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.

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

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

Closed
hvr opened this Issue Oct 26, 2016 · 12 comments

Comments

@hvr
Member

hvr commented Oct 26, 2016

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,

@hvr hvr changed the title from Tweak progress output for parallel builds in `new-build` to RFC: Tweak progress output for parallel builds in `new-build` Oct 26, 2016

@phadej

This comment has been minimized.

Show comment
Hide comment
@phadej

phadej Oct 26, 2016

Collaborator

I somehow like granular reporting of every state.

  • Download
  • Configure
  • Build
  • Register (to store) this is missing!
Collaborator

phadej commented Oct 26, 2016

I somehow like granular reporting of every state.

  • Download
  • Configure
  • Build
  • Register (to store) this is missing!
@hvr

This comment has been minimized.

Show comment
Hide comment
@hvr

hvr Oct 26, 2016

Member

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

Member

hvr commented Oct 26, 2016

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

This comment has been minimized.

Show comment
Hide comment
@hvr

hvr Oct 26, 2016

Member

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

Member

hvr commented Oct 26, 2016

@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

This comment has been minimized.

Show comment
Hide comment
@ezyang

ezyang Oct 26, 2016

Contributor

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.

Contributor

ezyang commented Oct 26, 2016

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

This comment has been minimized.

Show comment
Hide comment
@phadej

phadej Oct 26, 2016

Collaborator

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.

Collaborator

phadej commented Oct 26, 2016

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

This comment has been minimized.

Show comment
Hide comment
@23Skidoo

23Skidoo Oct 26, 2016

Member

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

Member

23Skidoo commented Oct 26, 2016

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

@ezyang ezyang added this to the milestone Oct 29, 2016

@ezyang

This comment has been minimized.

Show comment
Hide comment
@ezyang

ezyang Oct 29, 2016

Contributor

@hvr BE BOLD

Contributor

ezyang commented Oct 29, 2016

@hvr BE BOLD

@hvr

This comment has been minimized.

Show comment
Hide comment
@hvr

hvr Oct 29, 2016

Member

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)

example

Member

hvr commented Oct 29, 2016

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)

example

hvr added a commit that referenced this issue Oct 29, 2016

@hvr

This comment has been minimized.

Show comment
Hide comment
@hvr

hvr Oct 29, 2016

Member

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

stack-build

Member

hvr commented Oct 29, 2016

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

stack-build

@dcoutts

This comment has been minimized.

Show comment
Hide comment
@dcoutts

dcoutts Oct 29, 2016

Member

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.

Member

dcoutts commented Oct 29, 2016

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

This comment has been minimized.

Show comment
Hide comment
@dcoutts

dcoutts Oct 29, 2016

Member

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 ()
       }
Member

dcoutts commented Oct 29, 2016

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 added a commit to hvr/cabal that referenced this issue Oct 30, 2016

hvr added a commit to hvr/cabal that referenced this issue Nov 1, 2016

hvr added a commit to hvr/cabal that referenced this issue Nov 4, 2016

@hvr

This comment has been minimized.

Show comment
Hide comment
@hvr

hvr Nov 9, 2016

Member

@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

Member

hvr commented Nov 9, 2016

@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

hvr added a commit to hvr/cabal that referenced this issue May 16, 2017

hvr added a commit to hvr/cabal that referenced this issue May 18, 2017

hvr added a commit to hvr/cabal that referenced this issue May 19, 2017

@ChShersh ChShersh referenced this issue Jul 24, 2018

Merged

[#4040] Align output for parallel builds #5456

4 of 4 tasks complete

@hvr hvr closed this in #5456 Jul 29, 2018

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment