Less verbose logs from `make` by xavierleroy · Pull Request #11844 · ocaml/ocaml

xavierleroy · 2022-12-30T17:23:07Z

It's still time to make small wishes for 2022. One of mine is less verbose build logs.

The output of make looks almost decent when each command fits on one line, as Stuart Feldman envisioned it, and looks like complete gobbledygook otherwise. Unfortunately, OCaml, like all serious projects, has very long build commands, what with all these -I and -w options.

But there's a trick! The Makefile can run commands silently after printing a short meaningful summary:

    @echo "Linking foo"
    @gcc bla bla bla bla bla -o foo

I think the Linux kernel build does this (or did it 25 years ago when I last built my own kernels). I learned this trick from Coq, and use it with pleasure in CompCert.

This draft PR applies this trick to (parts of most of) the Makefiles of OCaml. For example, it prints
OCAMLC lambda/switch.ml
instead of
./boot/ocamlrun ./boot/ocamlc -nostdlib -I ./boot -use-prims runtime/primitives -g -strict-sequence -principal -absname -w +a-4-9-40-41-42-44-45-48 -warn-error +a -bin-annot -strict-formats -I lambda -I utils -I parsing -I typing -I bytecomp -I file_formats -I lambda -I middle_end -I middle_end/closure -I middle_end/flambda -I middle_end/flambda/base_types -I asmcomp -I driver -I toplevel -I tools -c lambda/switch.ml
and
CC runtime/addrmap.c -> runtime/addrmap.b.o
instead of
gcc -c -O2 -fno-strict-aliasing -fwrapv -pthread -g -Wall -Werror -fno-common -fexcess-precision=standard -fno-tree-vrp -ffunction-sections -I./runtime -D_FILE_OFFSET_BITS=64 -DCAMLDLLIMPORT= -DIN_CAML_RUNTIME -o runtime/addrmap.b.o runtime/addrmap.c

The general format is COMMAND inputfile if there's no ambiguity about the output file, or COMMAND inputfile -> outputfile otherwise. The format is open to discussions; my only demand is that every output fits on a single line.

I attach a full build log for reference: log4.gz

Currently, only the generic compile rules are modified; other rules such as linking steps still print in full. And some Makefiles remain to be adjusted. Yet, the log file is already 3 times shorter (340 k instead of 1M).

As usual, I'll now switch to Q&A mode to speed up discussions.

Q: But if a command fails, I may need to see it in full!

A: Most of the time, we look at the error messages from the compiler, not at the command itself. But in the rare case where you need to see the command in full, there's a simple trick. After the failure, just do make -n | head. With the -n option, commands are printed in full even when preceded by @. If you're in a sequential build, the command that failed is the first command to re-execute, so it should be the first line of the make -n output. If you're in a parallel build, you can reproduce the failure with make, then see the command with make -n | head.

It would also possible to have a make variable that controls whether to abbreviate commands or leave them printed in full. But I don't know how to do this without some duplication and extra if...else...endif in the Makefiles.

Q: Why do you care? Do you really read the build logs?

A: I too often have to search through build logs from CI, yes. Smaller logs will be a relief for all our CI systems. Apart from this, the fast scrolling of huge build commands in a terminal or Emacs buffer does make me uncomfortable, indeed.

xavierleroy · 2022-12-30T17:28:27Z

@shindere needs to know about this proposal.

shindere · 2022-12-30T19:39:23Z

Yes, thanks! In short: I am fully in favour of this proposal. Actually, I had the smae idea, with the very same source of inspiration (Linux Kernel), but my plan was to propose it after the makefiles had been merged to minimize the number of changes. I am supposed to be on vacation until January 9th and I would like to be given an opportunity to review this before it gets merged so can this please wait until I'm back? Thanks!

gasche · 2022-12-30T21:21:37Z

Two questions:

The "how to see the full command for reproducing a failure?" question is important. You answer in this PR, but could you put the answer in HACKING.adoc as well to make it easy to find again in the future?
This approach doubles the number of "commands" run in each build, is there a noticeable slowdown on Windows? (This is probably a question for @nojb or @dra27.)

nojb · 2022-12-31T01:34:21Z

I am generally in favor, this makes the logs much more readable.

The format is open to discussions; my only demand is that every output fits on a single line.

At the moment, OCAMLC is used as a prefix both for ocamlc and ocamlc.opt (and similarly for ocamlopt). I think that showing OCAMLC.OPT for the second one would be slightly better. Is this doable without complicating things too much?

is there a noticeable slowdown on Windows?

I did a quick benchmark of make -j10, starting from a clean tree, with the mingw64 port, which shows a slowdown of ~7%. This is unfortunate, but I think it is still tolerable.

trunk

real    5m45.928s
user    8m46.635s
sys     5m49.594s

This PR

real    6m11.228s
user    9m23.653s
sys     7m9.884s

dra27 · 2022-12-31T09:44:30Z

I’m also for this! For the slowdown, I think it may be possible to avoid the call to echo by using $(info?

xavierleroy · 2023-01-02T08:54:43Z

I just pushed a version that uses $(info ...) instead of @echo "...", it should run faster. Thanks a lot @dra27 for the suggestion!

@shindere : glad you like the idea. My next wish is a less verbose output from ocamltest...

@nojb: the code that sets OCAMLC and OCAMLOPT could also set OCAMLC_NAME and OCAMLOPT_NAME variables (e.g. to OCAMLC or OCAMLC.OPT), which could then be used when printing the command.

shindere · 2023-01-02T09:19:27Z

Xavier Leroy (2023/01/02 00:54 -0800):

I just pushed a version that uses `$(info ...)` instead of ***@***.*** "..."`, it should run faster. Thanks a lot @dra27 for the suggestion! @shindere : glad you like the idea. My next wish is a less verbose output from ocamltest...

You mean all the time, or you mean when run by the CI? In the latter case I have a branch that suppresses the output of ocamltest whn run by the testsuite to just print the report, because I had the understanding that this was what you were actually looking for. It had a bug which I never understood so I never finished but if you like the idea I can definitely give it one more try next week.

@nojb: the code that sets OCAMLC and OCAMLOPT could also set OCAMLC_NAME and OCAMLOPT_NAME variables (e.g. to `OCAMLC` or `OCAMLC.OPT`), which could then be used when printing the command.

That looks cool. The variable could even be called `COMPILER_NAME` so that the same code could be used for printing, no matter which compiler. One other possibility would be to distinguish, in this variable, `boot/ocamlc` from `./ocamlc` to make it clear whether it's the boot compiler which is used, or not. One further generalisation step would be to use e.g. `COMMAND`, `INPUT_FILE` and `OUTPUT_FILE`, although the two last ones could also be just `$<` and `$@` and in this case we would use the same display code for all the commmands, which would make it easier to get a by-construction guarantee that the printing format is consistent accross all the invoked commands.

nojb · 2023-01-03T06:53:38Z

I just pushed a version that uses $(info ...) instead of @echo "...", it should run faster. Thanks a lot @dra27 for the suggestion!

I played around with the PR and did what seems to me like some improvements (as well as adapting more of the build system), see xavierleroy#1.

xavierleroy · 2023-01-03T10:53:42Z

Thanks @nojb for the nice improvements, they are now merged in this PR.

Given that the initial feedback is positive and that it's starting to look really good, I'm removing the "Draft" status to show that this PR is ready for review. We will wait for @shindere's review.

xavierleroy · 2023-01-03T10:55:32Z

My next wish is a less verbose output from ocamltest...

You mean all the time, or you mean when run by the CI?

I mean when run by make -C testsuite. But I also think that the default output format for ocamltest should be a single line:

   name-of-test   (passed|skipped|failed)  [time taken]

and the current output should be explicitly requested with a -v option or something.

avsm · 2023-01-03T20:53:56Z

I don't have a development environment handy to test this at the moment, but if there are a lot of generated files then you may be able to speedup the Windows build by using the GNU Make $(file ) function to write outputs instead of indirecting the V_GEN calls through an echo/cat and shell redirect.

dra27 · 2023-01-03T21:11:33Z

There aren't too many generated files, fortunately (at least in the main build). Alas, $(file ...) is GNU make 4.0, so it's not at the moment available to us without considerable care to avoid it on macOS.

shindere · 2023-01-09T15:23:00Z

Just started to review this. Many thanks for the cool work. The result
looks much better than before, obviously.

Quick question: how important is the vertical alignment of filenames
to you (poor ;-) ) sighted people? I have two reasons to ask this question.

In braille it makes the text less compact than it could be, so I loose a little bit of effiency in reading.
More importantly: it may be nice at some point to e.g. distinguish
BOOT_OCAMLC from OCAMLC in the printed messages and it may then become
harder to maintain the vertical alignment, except of course if it is made
big enough but still, all this means that if we have vertical alignment
we will have to maintain it. Is the visual gain really worth it?
It's a genuine question.

Am I correct that, in its present state, the PR does not provide any way to
see the details of a command?

In the implementation I have in mind, we would have a V variable to
control the verbosity. Basically, make V=0 would be equivalent to make -s and would
let one verify that the build does not yield any unexpected message (the
output of Make V=0 should be empty), make V=1 would print the nice new
messages and make V=2 would print the commands in full details as before.

Is the idea okay and, if yes, shall I try to add it to the present PR or rather to
a separate one? If it's in a separate one then likely I'll wait until all
the makefiles have been merge because that will make the work easier. But in
workin on the makefiles it would be useful to have a way to see the
commands.

How about the mkdir command? Shoudln't it get a nice output, too?

xavierleroy · 2023-01-11T17:02:49Z

Quick question: how important is the vertical alignment of filenames to you (poor ;-) ) sighted people?

Not important to me.

How about the mkdir command? Shoudln't it get a nice output, too?

I think there will always be "raw" commands that occur too rarely to get a special output. It's OK, especially if they fit on one line, which is the case for mkdir commands. See also ln commands for which @nojb removed the nice output recently, as it was problematic (I guess).

Am I correct that, in its present state, the PR does not provide any way to
see the details of a command?

Correct. But there's always make -n.

In the implementation I have in mind, we would have a V variable to
control the verbosity. Basically, make V=0 would be equivalent to make -s and would
let one verify that the build does not yield any unexpected message (the
output of Make V=0 should be empty), make V=1 would print the nice new
messages and make V=2 would print the commands in full details as before.

Because there will always be "raw" commands, your "V=0" mode will not suppress all output, and it's better to rely on make -s. There's something similar to your "V=1" and "V=2" in the Coq makefiles, if I remember correctly.

nojb · 2023-01-11T17:14:01Z

See also ln commands for which @nojb removed the nice output recently, as it was problematic (I guess).

It wasn't problematic, but we were doing it for ln and not for mkdir, cp, etc; we should do it either for all of them or none of them, and it wasn't clear if it was worth doing it for these commands by the reasons mentioned.

shindere · 2023-01-11T19:27:54Z

Nicolás Ojeda Bär (2023/01/11 09:14 -0800):

> See also `ln` commands for which @nojb removed the nice output recently, as it was problematic (I guess). It wasn't problematic, but we were doing it for `ln` and not for `mkdir`, `cp`, etc; we should do it either for all of them or none of them, and it wasn't clear if it was worth doing it for these commands by the reasons mentioned.

To me, it wouldn't hurt to do it for such commands and would make things clearer. It's not a lot of noise and still it can be precious, whereas not having it can be problematic.

shindere · 2023-01-11T19:39:27Z

Xavier Leroy (2023/01/11 09:03 -0800):

> Quick question: how important is the vertical alignment of filenames to you (poor ;-) ) sighted people? Not important to me.

OK so if this is not retained in future changes you won't complain, IIUC.

> How about the mkdir command? Shoudln't it get a nice output, too? I think there will always be "raw" commands that occur too rarely to get a special output. It's OK, especially if they fit on one line, which is the case for `mkdir` commands. See also `ln` commands for which @nojb removed the nice output recently, as it was problematic (I guess).

My preference would be to have something homogenous but it does not need to happen in this PR.

> Am I correct that, in its present state, the PR does not provide any way to > see the details of a command? Correct. But there's always `make -n`.

Will that really produce the very same output as we got before? I'm indoubt but again, no problem, I'll reivew the current PR as it is and submit adjustements once it's merged.

> In the implementation I have in mind, we would have a V variable to > control the verbosity. Basically, make V=0 would be equivalent to make -s and would > let one verify that the build does not yield any unexpected message (the > output of Make V=0 should be empty), make V=1 would print the nice new > messages and make V=2 would print the commands in full details as before. Because there will always be "raw" commands,

I don't see this as a fatality. I do think it's possible to have control over all the commands, especially after the refactoring.

your "V=0" mode will not suppress all output,

Let's bet. :-)

and it's better to rely on `make -s`.

Incidnetally, here is the output of `make -s` on latest trunk: ``` File "../../stdlib/stdlib.mli", line 1500, characters 15-28: 1500 | module Stack = Stdlib__Stack ^^^^^^^^^^^^^ Alert unsynchronized_accesses: module Stdlib__Stack Unsynchronized accesses to stacks are a programming error. ```

There's something similar to your "V=1" and "V=2" in the Coq makefiles, if I remember correctly.

I am pretty sure all of us have the same source of inspiration, namely the Linux kernel, so what you write does not surprise me so much.

shindere · 2023-01-16T08:52:49Z

Xavier Leroy (2022/12/30 09:23 -0800):

Q: But if a command fails, I may need to see it in full! A: Most of the time, we look at the error messages from the compiler, not at the command itself. But in the rare case where you need to see the command in full, there's a simple trick. After the failure, just do `make -n | head`. With the `-n` option, commands are printed in full even when preceded by `@`. If you're in a sequential build, the command that failed is the first command to do again, so it should be the first line of the `make -n` output. If you're in a parallel build, you can reproduce the failure with `make`, then see the command with `make -n | head`.

The limit to this trick is that `-n` is dry-run so the commands are indeed printed, but not executed. So it may indeed work to run `make -n` just after having run `make`, but oneshould keep in mind that this can nnot be generalized, as sometimes executing a command really makes a difference for the rest of the build and which commands will be executed afterwards.

It would also possible to have a make variable that controls whether to abbreviate commands or leave them printed in full. But I don't know how to do this without some duplication and extra `if...else...endif` in the Makefiles.

This has been implemented at the top of the `less-verbose-logs` branch of `shindere/ocaml`: `make V=1` prints the commands the new way (default) whereas `make V=2` prints the commands as they were printed before this PR. Could this please be cherry-picked into this PR? With the above mentionned PR, I was able to get a diff of build logs before and after the PR (see attached - [buildlog-patch.patch](https://github.com/ocaml/ocaml/files/10424363/buildlog-patch.patch))

shindere · 2023-01-16T09:01:11Z

Gabriel Scherer (2022/12/30 13:21 -0800):

1. The "how to see the full command for reproducing a failure?" question is important. You answer in this PR, but could you put the answer in HACKING.adoc as well to make it easy to find again in the future?

This point from @gasche has not been addressed yet and, at the moment, thePR does not have a Changes entry.

xavierleroy · 2023-01-16T14:19:41Z

This has been implemented at the top of the less-verbose-logs branch
of shindere/ocaml: make V=1 prints the commands the new way
(default) whereas make V=2 prints the commands as they were printed
before this PR.

I'm a computer scientist: I don't know this "2" thing you're using, only "0" and "1" :-)

More seriously, according to Stackoverflow wisdom, CMake, uses make VERBOSE=1 and GNU autotools make V=1 to select verbose output. I strongly suggest we use one of these two conventions.

shindere · 2023-01-16T14:53:47Z

Xavier Leroy (2023/01/16 06:19 -0800):

> This has been implemented at the top of the `less-verbose-logs` branch > of `shindere/ocaml`: `make V=1` prints the commands the new way > (default) whereas `make V=2` prints the commands as they were printed > before this PR. I'm a computer scientist: I don't know this "2" thing you're using, only "0" and "1" :-)

I'll tell you about the wonders of Peano numbers next time we have a coffee together. You'll see, you're gonna be amazed!

More seriously, according to Stackoverflow wisdom, CMake, uses `make VERBOSE=1` and GNU autotools `make V=1` to select verbose output. I strongly suggest we use one of these two conventions.

Here is the relevant bit of output of Linux's `make help`: ``` make V=0|1 [targets] 0 => quiet build (default), 1 => verbose build make V=2 [targets] 2 => give reason for rebuild of target ``` My understanding of this is that it gives a point to each of us. One point to you because it distinguishes `V=0` from `make -s`. One point for me because they do use more than two values. I can just say that what I proposed seems the more coherent to me: it would make sense to me that `V=0` is an equivalent to `make -s` and it is actually very easy to implement by modifying `MAKEFLAGS`; `V=1` what we have and then we have 2 for all commands, why not 3 to mean `run the commands in verbose mode`. It may be interesting to hear the opinions of others. Finally between V and VERBOSE I'd go for the first one which is more concise. And please, fellfree to modify the commit directly and to take the authorship.

gasche · 2023-01-16T15:01:01Z

It may be interesting to hear the opinions of others.

My opinion: I haven't looked at this and don't plan to, but it looks like there is a general consensus in favor of the change as, broadly, originally proposed, and less consensus on the proposed addition of an explicit verbosity setting. My recommendation would be to first merge the change at the scope of the original proposal, and split the verbosity setting patches to a follow-up PR where you can discuss more if you want.

(Re. V versus VERBOSE: in general I'm in favor of longer options because they are nicer on the reader, and I read more than I write. This being said, I guess I'm the sort of people who does not mind seeing long commands in the build logs.)

damiendoligez · 2023-01-16T16:22:42Z

For the flag, my vote goes to V and I see a good use for relative integers here:
make V=-1 for a completely silent build
make V=0 (default) for printing abbreviated commands
make V=1 for printing full commands

shindere · 2023-01-16T16:45:27Z

Wouldn't it be nice, finally, to use floating pointnumbers? That way we would have a main verbosity number which would be the integral part, and then we could use the numbers after the dot to encode the verbosity of different components and subcommands, which would give us all the control and flexibility we can drema of. Plus, it would be future proof because, if real numbers turn out to not be enough to encode a verbosity setting, then we coudl very easily say that the numbers we use are actually complex numbers.

dra27 · 2023-01-16T16:45:48Z

Re. V versus VERBOSE: in general I'm in favor of longer options because they are nicer on the reader, and I read more than I write

There’s no major reason not to have both? I keep meaning to add that in testsuite/Makefile for KEEP_TEST_DIR_ON_SUCCESS as my usage of it always begins with grep KEEP Makefile to remind me what the full name of the variable is…

shindere · 2023-01-16T16:52:07Z

David Allsopp (2023/01/16 08:46 -0800):

> Re. V versus VERBOSE: in general I'm in favor of longer options because they are nicer on the reader, and I read more than I write There’s no major reason not to have both? I keep meaning to add that in testsuite/Makefile for `KEEP_TEST_DIR_ON_SUCCESS` as my usage of it always begins with `grep KEEP Makefile` to remind me what the full name of the variable is…

I really like the good intentions behind the proposal. No sarcasm intended, I do like that. I'm just not sure whether it's a wise way to go because it will likely create code duplication and/or questions about which varialbe has the priority if they happen to contradict each other...

Print concise summaries instead of full commands for some of the most verbose commands. For example, print ``` OCAMLC lambda/switch.ml ``` instead of ``` ./boot/ocamlrun ./boot/ocamlc -nostdlib -I ./boot -use-prims runtime/primitives -g -strict-sequence -principal -absname -w +a-4-9-40-41-42-44-45-48 -warn-error +a -bin-annot -strict-formats -I lambda -I utils -I parsing -I typing -I bytecomp -I file_formats -I lambda -I middle_end -I middle_end/closure -I middle_end/flambda -I middle_end/flambda/base_types -I asmcomp -I driver -I toplevel -I tools -c lambda/switch.ml ``` and ``` CC runtime/addrmap.c -> runtime/addrmap.b.o ``` instead of ``` gcc -c -O2 -fno-strict-aliasing -fwrapv -pthread -g -Wall -Werror -fno-common -fexcess-precision=standard -fno-tree-vrp -ffunction-sections -I./runtime -D_FILE_OFFSET_BITS=64 -DCAMLDLLIMPORT= -DIN_CAML_RUNTIME -o runtime/addrmap.b.o runtime/addrmap.c ``` This is work in progress; many Makefiles haven't been touched yet.

@dra27

This saves the cost of spawning a shell just to write a message, cost that is significant under Cygwin. Suggested by @dra27. This commit changes only the `@echo` introduced by the previous commit. The same trick is applicable to other `@echo` occurrences, however.

nojb · 2023-01-17T22:25:45Z

I rebased this patch on top of trunk, and:

Removed the extra whitespace between the command name and the target name (asked in Less verbose logs from make #11844 (comment));
Added a flag V=0 (default) and V=1 to control whether to use the new shorthand or the full command lines. Other variants can be added later; and
Added a Changes entry.

Planning to merge tomorrow...

shindere · 2023-01-17T23:03:37Z

Many thanks. I just find it very odd that `V=0` means something different from silence but AIUI I'm the only one seeing things that way.

xavierleroy · 2023-01-17T23:51:49Z

Planning to merge tomorrow...

Thanks!

xavierleroy marked this pull request as ready for review January 3, 2023 10:53

shindere mentioned this pull request Jan 11, 2023

Stricter C99 warnings, strict prototypes for primitives list #11861

Merged

shindere approved these changes Jan 16, 2023

View reviewed changes

xavierleroy and others added 2 commits January 17, 2023 23:01

Introduce $(V_XXX) variables, port rest of build system

228b288

nojb force-pushed the less-verbose-make branch from 868c09e to 228b288 Compare January 17, 2023 22:13

Changes

782f125

nojb merged commit 60260ec into ocaml:trunk Jan 18, 2023

xavierleroy deleted the less-verbose-make branch January 20, 2023 19:13

dra27 mentioned this pull request Feb 20, 2023

Fix undefined Makefile variables #12022

Merged

MisterDA mentioned this pull request Jun 7, 2024

Make the CI dump config.log and verbosely print failed commands #13223

Merged

Conversation

xavierleroy commented Dec 30, 2022 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

xavierleroy commented Dec 30, 2022

Uh oh!

shindere commented Dec 30, 2022 via email

Uh oh!

gasche commented Dec 30, 2022

Uh oh!

nojb commented Dec 31, 2022 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

dra27 commented Dec 31, 2022

Uh oh!

xavierleroy commented Jan 2, 2023

Uh oh!

shindere commented Jan 2, 2023 via email

Uh oh!

nojb commented Jan 3, 2023

Uh oh!

xavierleroy commented Jan 3, 2023

Uh oh!

xavierleroy commented Jan 3, 2023 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

avsm commented Jan 3, 2023 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

dra27 commented Jan 3, 2023

Uh oh!

shindere commented Jan 9, 2023

Uh oh!

xavierleroy commented Jan 11, 2023

Uh oh!

nojb commented Jan 11, 2023

Uh oh!

shindere commented Jan 11, 2023 via email

Uh oh!

shindere commented Jan 11, 2023 via email

Uh oh!

shindere commented Jan 16, 2023 via email • edited by dra27 Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

shindere commented Jan 16, 2023 via email

Uh oh!

xavierleroy commented Jan 16, 2023

Uh oh!

shindere commented Jan 16, 2023 via email

Uh oh!

gasche commented Jan 16, 2023

Uh oh!

damiendoligez commented Jan 16, 2023

Uh oh!

shindere commented Jan 16, 2023 via email

Uh oh!

dra27 commented Jan 16, 2023

Uh oh!

shindere commented Jan 16, 2023 via email

Uh oh!

nojb commented Jan 17, 2023

Uh oh!

shindere commented Jan 17, 2023 via email

Uh oh!

xavierleroy commented Jan 17, 2023

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

7 participants

xavierleroy commented Dec 30, 2022 •

edited

Loading

nojb commented Dec 31, 2022 •

edited

Loading

xavierleroy commented Jan 3, 2023 •

edited

Loading

avsm commented Jan 3, 2023 •

edited

Loading

shindere commented Jan 16, 2023 via email •

edited by dra27

Loading