Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Add timings to verbose output #1105

Merged
merged 2 commits into from
Oct 24, 2023
Merged

Add timings to verbose output #1105

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
2 commits
Select commit Hold shift + click to select a range
9b4f8c3
Add timings to verbose output
f-f Oct 23, 2023
fc83b4d
Merge branch 'master' into add-timings
f-f Oct 24, 2023
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
40 changes: 21 additions & 19 deletions bin/src/Main.purs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -14,6 +14,7 @@ import Data.Map as Map
import Data.Maybe as Maybe
import Data.String as String
import Effect.Aff as Aff
import Effect.Now as Now
import Effect.Ref as Ref
import Node.FS.Stats (Stats(..))
import Node.Path as Path
Expand Down Expand Up @@ -474,11 +475,17 @@ parseArgs = do
)

main :: Effect Unit
main =
main = do
startingTime <- Now.now
let
printVersion = do
logOptions <- mkLogOptions startingTime { noColor: false, quiet: false, verbose: false, offline: Offline }
runSpago { logOptions } do
logInfo BuildInfo.buildInfo.spagoVersion
parseArgs >>=
\c -> Aff.launchAff_ case c of
Cmd'SpagoCmd (SpagoCmd globalArgs@{ offline } command) -> do
logOptions <- mkLogOptions globalArgs
logOptions <- mkLogOptions startingTime globalArgs
runSpago { logOptions } case command of
Sources args -> do
{ env } <- mkFetchEnv
Expand Down Expand Up @@ -645,23 +652,18 @@ main =

Cmd'VersionCmd v -> do when v printVersion
where
printVersion = do
logOptions <- mkLogOptions { noColor: false, quiet: false, verbose: false, offline: Offline }
runSpago { logOptions } do
logInfo BuildInfo.buildInfo.spagoVersion

mkLogOptions :: GlobalArgs -> Aff LogOptions
mkLogOptions { noColor, quiet, verbose } = do
supports <- liftEffect supportsColor
let color = and [ supports, not noColor ]
let
verbosity =
if quiet then
LogQuiet
else if verbose then
LogVerbose
else LogNormal
pure { color, verbosity }
mkLogOptions :: Instant -> GlobalArgs -> Aff LogOptions
mkLogOptions startingTime { noColor, quiet, verbose } = do
supports <- liftEffect supportsColor
let color = and [ supports, not noColor ]
let
verbosity =
if quiet then
LogQuiet
else if verbose then
LogVerbose
else LogNormal
pure { color, verbosity, startingTime }

mkBundleEnv :: forall a. BundleArgs -> Spago (Fetch.FetchEnv a) (Bundle.BundleEnv ())
mkBundleEnv bundleArgs = do
Expand Down
20 changes: 19 additions & 1 deletion core/src/Log.purs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -32,9 +32,15 @@ import Data.Array as Array
import Data.Array.NonEmpty (NonEmptyArray)
import Data.Array.NonEmpty (toArray) as NEA
import Data.Codec.Argonaut (JsonCodec)
import Data.DateTime.Instant (Instant)
import Data.DateTime.Instant as Instant
import Data.Either (Either(..))
import Data.Int as Int
import Data.Maybe (Maybe(..), fromMaybe)
import Data.Newtype (unwrap)
import Data.String as String
import Data.String.Utils as Strings
import Data.Time.Duration (Milliseconds)
import Data.Traversable (traverse)
import Dodo (Doc, print, twoSpaces)
import Dodo (indent, break) as DodoExport
Expand All @@ -48,6 +54,7 @@ import Dodo.Box as Box
import Effect.Class (class MonadEffect)
import Effect.Class as Effect
import Effect.Class.Console as Console
import Effect.Now as Now
import Node.Process as Process
import Registry.PackageName (PackageName)
import Registry.PackageName as PackageName
Expand All @@ -56,7 +63,11 @@ import Spago.Yaml as Yaml

type LogEnv a = { logOptions :: LogOptions | a }

type LogOptions = { color :: Boolean, verbosity :: LogVerbosity }
type LogOptions =
{ color :: Boolean
, verbosity :: LogVerbosity
, startingTime :: Instant
}

data LogVerbosity
= LogQuiet
Expand Down Expand Up @@ -100,6 +111,13 @@ log { content, level } = do
case logOptions.verbosity, level of
LogQuiet, _ -> pure unit
LogNormal, LogDebug -> pure unit
LogVerbose, _ -> do
now <- Effect.liftEffect $ Now.now
let
(timeDiff :: Milliseconds) = Instant.diff now logOptions.startingTime
millisDoc = Ansi.foreground Ansi.White $ Ansi.bold $ Log.text $ Strings.padStart 8 $ show $ Int.round $ unwrap timeDiff
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This is so much nicer than the million time/timeEnds I was dropping in before!

Given that the times just ascend is the padding necessary? I'd find this hard to parse:

[80ms] ...
[802323ms] ...
[802ms] ...

But not so much this:

[4ms] ...
[10ms] ...
[75ms] ...
[80ms] ...
[2000ms] ...
[32322ms] ...

Maybe it's more noticeably jumpy at the start. Could drop it down to 4 so the nudge only happens after longer intervals?

Suggested change
millisDoc = Ansi.foreground Ansi.White $ Ansi.bold $ Log.text $ Strings.padStart 8 $ show $ Int.round $ unwrap timeDiff
millisDoc = Ansi.foreground Ansi.White $ Ansi.bold $ Log.text $ Strings.padStart 4 $ show $ Int.round $ unwrap timeDiff

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

But not so much this

My eye finds that equally hard to parse, and I figured out because I started with what you're suggesting here, and ended up with the padding 😄

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I am unsure about the square brackets though. I just wanted some separation with the rest of the log line, I guess a dash or something could work as well

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I don't think I care one way or another whether there's brackets or hyphens used.

I do like the current padded usage.

contentWithTimeDiff = Log.text "[" <> millisDoc <> Log.text "ms]" <> Log.space <> content
Console.error $ printFn (Log.twoSpaces { pageWidth = 200 }) contentWithTimeDiff
_, _ -> Console.error $ printFn (Log.twoSpaces { pageWidth = 200 }) content

logInfo :: forall a b m. MonadEffect m => MonadAsk (LogEnv b) m => Loggable a => a -> m Unit
Expand Down
12 changes: 12 additions & 0 deletions spago.lock
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -138,6 +138,7 @@ workspace:
- registry-lib
- spago-core
- strings
- stringutils
- transformers
- tuples
- unsafe-coerce
Expand Down Expand Up @@ -1976,6 +1977,17 @@ packages:
- tuples
- unfoldable
- unsafe-coerce
stringutils:
type: registry
version: 0.0.12
integrity: sha256-t63QWBlp49U0nRqUcFryKflSJsNKGTQAHKjn24/+ooI=
dependencies:
- arrays
- integers
- maybe
- partial
- prelude
- strings
tailrec:
type: registry
version: 6.1.0
Expand Down
1 change: 1 addition & 0 deletions spago.yaml
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -43,6 +43,7 @@ package:
- registry-lib
- spago-core
- strings
- stringutils
- transformers
- tuples
- unsafe-coerce
Expand Down
4 changes: 3 additions & 1 deletion test/Spago/Install.purs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -4,6 +4,7 @@ import Test.Prelude

import Data.Array as Array
import Data.Map as Map
import Effect.Now as Now
import Node.FS.Aff as FSA
import Node.Path as Path
import Registry.Version as Version
Expand Down Expand Up @@ -238,7 +239,8 @@ spec = Spec.around withTempDir do

Spec.it "can build with a newer (but still compatible) compiler than the one in the package set" \{ spago } -> do
spago [ "init", "--package-set", "10.0.0" ] >>= shouldBeSuccess
purs <- runSpago { logOptions: { color: false, verbosity: LogQuiet } } Purs.getPurs
startingTime <- liftEffect $ Now.now
purs <- runSpago { logOptions: { color: false, verbosity: LogQuiet, startingTime } } Purs.getPurs
-- The package set 10.0.0 has purescript 0.15.4, so we check that we have a newer version
case purs.version > mkVersion "0.15.4" of
true -> pure unit
Expand Down
4 changes: 3 additions & 1 deletion test/Spago/Upgrade.purs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -2,6 +2,7 @@ module Test.Spago.Upgrade where

import Test.Prelude

import Effect.Now as Now
import Spago.Core.Config (SetAddress(..))
import Spago.Core.Config as Core
import Spago.Log (LogVerbosity(..))
Expand All @@ -19,7 +20,8 @@ spec = Spec.around withTempDir do
-- we can't just check a fixture here, as there are new package set versions all the time.
-- so we read the config file, and check that the package set version is more recent than the one we started with
let initialVersion = mkVersion "20.0.1"
maybeConfig <- runSpago { logOptions: { color: false, verbosity: LogQuiet } } (Core.readConfig "spago.yaml")
startingTime <- liftEffect $ Now.now
maybeConfig <- runSpago { logOptions: { color: false, verbosity: LogQuiet, startingTime } } (Core.readConfig "spago.yaml")
case maybeConfig of
Right { yaml: { workspace: Just { package_set: Just (SetFromRegistry { registry }) } } } | registry > initialVersion -> pure unit
Right { yaml: c } -> Assert.fail $ "Could not upgrade the package set, config: " <> printJson Core.configCodec c
Expand Down
Loading