Add timings to verbose output (#1105)

bin/src/Main.purs

@@ -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
@@ -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
@@ -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

core/src/Log.purs

@@ -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
@@ -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
@@ -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
@@ -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
+        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

spago.lock

@@ -138,6 +138,7 @@ workspace:
         - registry-lib
         - spago-core
         - strings
+        - stringutils
         - transformers
         - tuples
         - unsafe-coerce
@@ -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

spago.yaml

@@ -43,6 +43,7 @@ package:
     - registry-lib
     - spago-core
     - strings
+    - stringutils
     - transformers
     - tuples
     - unsafe-coerce

test/Spago/Install.purs

@@ -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
@@ -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

test/Spago/Upgrade.purs

@@ -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(..))
@@ -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