Cabal: RFC: Tweak progress output for parallel builds in `new-build`

[hvr]

Currently we output Downloading/Configuring/Building lines (NB: the Installed event was lost in new-build).

This has the problem that sometimes cabal has no output for a few minutes on some tiresome packages, but you can't see from the log output easily which package is not done yet (since you only see when packages started building, but you don't know which ones are still in-flight).

Here's a simple strawman suggestion:

drop the uninteresting Configuring/Building distinction, and instead output when work on the package starts, and when it ends:

Downloading digest-0.0.1.2...
Starting work on extensible-exceptions-0.1.1.4 (lib)...
Starting work on hourglass-0.2.10 (lib)...
Starting work on fail-4.9.0.0 (lib)...
Downloading hslua-0.4.1...
Starting work on digest-0.0.1.2 (lib)...
Completed fail-4.9.0.0 (lib)
Completed extensible-exceptions-0.1.1.4 (lib)
Starting work on http-client-0.5.3.3 (lib)...
Downloading haddock-library-1.4.2...
Starting work on hslua-0.4.1 (lib)...
Downloading filemanip-0.3.6.3...
Starting work on haddock-library-1.4.2 (lib)...
Completed digest-0.0.1.2 (lib)
Starting work on pem-0.2.2 (lib)...
Downloading cmark-0.5.3.1...
Starting work on filemanip-0.3.6.3 (lib)...
Downloading highlighting-kate-0.6.3...
Starting work on cmark-0.5.3.1 (lib)...
Completed pem-0.2.2 (lib)
Starting work on socks-0.5.5 (lib)...
Downloading tagsoup-0.14...
Starting work on highlighting-kate-0.6.3 (lib)...
Downloading pandoc-types-1.16.1.1...
Downloading texmath-0.8.6.6...
Completed filemanip-0.3.6.3 (lib)
Starting work on tagsoup-0.14 (lib)...
Downloading zip-archive-0.3.0.5...
Completed hourglass-0.2.10 (lib)
Starting work on temporary-1.2.0.4 (lib)...
Completed socks-0.5.5 (lib)
Starting work on xml-1.3.14 (lib)...
Completed temporary-1.2.0.4 (lib)
Starting work on aeson-0.11.2.1 (lib)...
Completed http-client-0.5.3.3 (lib)
Starting work on zip-archive-0.3.0.5 (all, due to Custom setup)...
Completed haddock-library-1.4.2 (lib)
Starting work on asn1-types-0.3.2 (lib)...
Completed xml-1.3.14 (lib)
Completed hslua-0.4.1 (lib)
Completed asn1-types-0.3.2 (lib)
Starting work on asn1-encoding-0.9.4 (lib)...
Completed tagsoup-0.14 (lib)
Completed cmark-0.5.3.1 (lib)
Completed asn1-encoding-0.9.4 (lib)
Starting work on asn1-parse-0.9.4 (lib)...
Completed asn1-parse-0.9.4 (lib)
Starting work on x509-1.6.4 (lib)...
Completed zip-archive-0.3.0.5 (all, due to Custom setup)
Completed x509-1.6.4 (lib)
Starting work on x509-store-1.6.2 (lib)...
Completed x509-store-1.6.2 (lib)
Starting work on x509-system-1.6.4 (lib)...
Starting work on x509-validation-1.6.5 (lib)...
Completed x509-system-1.6.4 (lib)
Completed x509-validation-1.6.5 (lib)
Starting work on tls-1.3.8 (lib)...
Completed aeson-0.11.2.1 (lib)
Starting work on pandoc-types-1.16.1.1 (lib)...
Starting work on yaml-0.8.20 (lib)...
Completed tls-1.3.8 (lib)
Starting work on connection-0.2.6 (lib)...
Completed connection-0.2.6 (lib)
Starting work on http-client-tls-0.3.3 (lib)...
Completed http-client-tls-0.3.3 (lib)
Completed yaml-0.8.20 (lib)
Completed pandoc-types-1.16.1.1 (lib)
Starting work on texmath-0.8.6.6 (lib)...
Completed highlighting-kate-0.6.3 (lib)
...

Expressed as patch:

--- a/cabal-install/Distribution/Client/ProjectBuilding.hs
+++ b/cabal-install/Distribution/Client/ProjectBuilding.hs
@@ -876,15 +876,14 @@ buildAndInstallUnpackedPackage verbosity
             ElabComponent comp -> display pkgid
                 ++ " (" ++ maybe "custom" display (compComponentName comp) ++ ")"

-    -- Configure phase
     when isParallelBuild $
-      notice verbosity $ "Configuring " ++ dispname ++ "..."
+      notice verbosity $ "Starting work on " ++ dispname ++ "..."
+
+    -- Configure phase
     annotateFailure mlogFile ConfigureFailed $
       setup' configureCommand configureFlags configureArgs

     -- Build phase
-    when isParallelBuild $
-      notice verbosity $ "Building " ++ dispname ++ "..."
     annotateFailure mlogFile BuildFailed $
       setup buildCommand buildFlags

@@ -930,6 +929,9 @@ buildAndInstallUnpackedPackage verbosity
     let docsResult  = DocsNotTried
         testsResult = TestsNotTried

+    when isParallelBuild $
+      notice verbosity $ "Completed " ++ dispname
+
     return BuildResult {
        buildResultDocs    = docsResult,
        buildResultTests   = testsResult,

[phadej]

I somehow like granular reporting of every state.

• Download
• Configure
• Build
• Register (to store) _this is missing_!

[hvr]

Alternatively, to make it visually easier to parse align so that the pkg name starts in the same column

Downloading  digest-0.0.1.2...
Starting on  extensible-exceptions-0.1.1.4 (lib)...
Starting on  hourglass-0.2.10 (lib)...
Starting on  fail-4.9.0.0 (lib)...
Downloading  hslua-0.4.1...
Starting on  digest-0.0.1.2 (lib)...
Completed    fail-4.9.0.0 (lib)
Completed    extensible-exceptions-0.1.1.4 (lib)
Starting on  http-client-0.5.3.3 (lib)...
Downloading  haddock-library-1.4.2...
Starting on  hslua-0.4.1 (lib)...
Downloading  filemanip-0.3.6.3...
Starting on  haddock-library-1.4.2 (lib)...
Completed    digest-0.0.1.2 (lib)
Starting on  pem-0.2.2 (lib)...
Downloading  cmark-0.5.3.1...
Starting on  filemanip-0.3.6.3 (lib)...
...

Another thing that would be quite useful for build logs (and for post-analysing with e.g. https://hackage.haskell.org/package/splot): prefix with timestamps

[hvr]

@phadej having each state printed at default verbosity is quite noisy though, and if you print register the most important events (being imho download-start(net-io-bound)/configure-start(cpu-bound-ish)/completion) still require also emitting a line for when the work on that particular package is really completed (i.e. post-copy/register).

That being said, I don't mind having the granularity you suggest (it may actually be interesting for splot), as long as I also get a completion event (& timestamps). :-)

Also, for interactive terminals, we may do some fancy eye-candy stuff. The output change I'm suggesting above is a first step aimed at non-interactive terminals and build logs.

[ezyang]

So, the root problem is that you're getting no output for a while as some big packages are built. So, here is a crazy suggestion: what if we just spewed all of the logs to stderr, locking on a line-by-line basis (GHC is line buffered anyway), adding some prefix to let people know where the line was coming from.

[phadej]

My opinions are biased by stack usage, I kind of like it's output:

avatar-app-0: build
favicon-app-0: configure
favicon-app-0: build
favicon-app-0: copy/register
avatar-app-0: haddock
futurice-foundation-0: configure
futurice-foundation-0: build
futurice-foundation-0: haddock
avatar-app-0: copy/register
planmill-proxy-0: configure
planmill-proxy-0: build
futurice-foundation-0: copy/register
futurice-reports-0: configure
futurice-reports-0: build
futurice-reports-0: haddock
planmill-proxy-0: haddock
futurice-reports-0: copy/register
futurice-integrations-0: configure
futurice-integrations-0: build
planmill-proxy-0: copy/register
proxy-mgmt-app-0: configure
proxy-mgmt-app-0: build
futurice-integrations-0: haddock

though action first, and tabular would be even cooler. copy/register is so fast it kind of acts as "done" event, but it won't hurt to be explicit.

[23Skidoo]

+1 on aligning and (optional) prefixing with timestamps. +0.5 on configure/build/haddock/copy+register vs started/completed.

[ezyang]

@hvr BE BOLD

[hvr]

Here's another example: https://gist.github.com/ba3918a1742d22492a99d4623632ab92

and this can easily transformed into input for splot which then may look like below
(the colors represent the different phases; note that we don't emit a download-completed event)

[hvr]

Here's another example (click on the image to enlarge), this time with download-finished events recorded and with a cleaned package cache & store where one can see how cabal new-build schedules the I/O & compilation workload:

(See ed4fbdf for proof-of-concept implementation)

https://gist.github.com/fe86b73df37123c8d7f63608aadaaf59

• red: download phase
• lightgray: after download complete, before configuring
• yellow: configuring phase
• green: build phase
• blue: install phase

[dcoutts]

I like the suggestions.

Can I suggest as an implementation technique that we pass the build phase a "progress" interface of some kind (i.e. set of callbacks/events for the begin/end of the various phases), and then it's easy externally to pick different renderings, e.g. fancy concurrent-output for terminals, something sensible for logs, optional timestamps.

Said progress interface should also control whether the build phase should redirect everything to log files / pipes / inherited stdio.

[dcoutts]

Straw man:

data BuildProgressActions m = BuildProgressActions {
       reportPhaseStart :: PackageId -> Maybe ComponentName -> Phase -> m (),
       reportPhaseEnd   :: PackageId -> Maybe ComponentName -> Phase -> m (),

       -- stuff for info/debug too

       useProcessOutputMethod :: ProcessOutputMethod m
     }

data ProcessOutputMethod m =
       ProcessOutputInherit {
         reportProcessStartOutputInherit :: m (),
         reportProcessEnd   :: m ()
       }

     | ProcessOutputToFile {
         reportProcessStartOutputToFile :: FilePath -> m (),
         reportProcessEnd   :: m ()
       }

     | ProcessOutputRedirect {
         reportProcessStartOutputRedirect :: Handle -> m (),
         reportProcessEnd   :: m ()
       }

[hvr]

@dcoutts I was just pointed to #1940 by @23Skidoo which seems quite relevant, as we'd like to avoid having to thread through the logging/event hooks manually to each use-sites

PS: Related: #4103 now provides timestamps via a new verbosity flag; we could also attach the logging/progress output hooks to Verbose and avoid requiring a refactoring to a "Shell" monad