Print status when edge finishes on dumb terminals #999
Conversation
On smart terminals ninja prints the status line both before and after running a command, reusing the same line if possible. On a dumb terminal that doesn't support reusing the line, it only prints the status before starting the command, but prints the output of the command when the command finishes, by which point other commands may have started and printed their status line. This makes it impossible to determine what command produced a line of output. Modify BuildEdgeStarted to only print the status line if the command is going to lock the console, or if ninja is running on a smart terminal. Modify BuildEdgeFinished to always print the status line unless the command locked the console, in which case the status was already printed and no other command can have printed any lines. The end result will be dumb terminal output that much more closely matches smart terminal output. One disadvantage is that dumb terminals won't show anything when starting a command, making it harder to tell what commands are currently running, but I expect most interactive uses of ninja will use a smart terminal.
|
I'm tentatively merging this as discussed on the "[rfc] changing ninja's progress output order when writing to a file?" thread. |
Print status when edge finishes on dumb terminals
PR ninja-build#999 changed the status line to be printed when edges finish on dumb teerminals, but the default status message includes the number of started edges, resulting in sequential status lines with identical edge counts. Change the default status to show the number of finished edges, which will keep the count incrementing on every line. This will slightly change the output on smart terminals. Previously a build that was just starting would show a count equal to the number of concurrent jobs, and a build waiting for the final jobs to finish would show a count equal to the total number of edges. Now a starting build will show 0, and build waiting for the final jobs will show a count less than the total number of edges by the number of remaining jobs. Fixes: ninja-build#1142
PR ninja-build#999 changed the status line to be printed when edges finish on dumb teerminals, but the default status message includes the number of started edges, resulting in sequential status lines with identical edge counts. Change the default status to show the number of finished edges, which will keep the count incrementing on every line. This will slightly change the output on smart terminals. Previously a build that was just starting would show a count equal to the number of concurrent jobs, and a build waiting for the final jobs to finish would show a count equal to the total number of edges. Now a starting build will show 0, and build waiting for the final jobs will show a count less than the total number of edges by the number of remaining jobs. Fixes: ninja-build#1142
PR ninja-build#999 made dumb terminals only output when edges finish. BuildStatus::overall_rate_ stopwatch is only initialized to the current time when PrintStatus is called with finished_edges_ == 0, but on a dumb terminal it will be called for the first time when finished_edge_ = 1, which results in very long elapsed times: NINJA_STATUS="[%r processes, %f/%t @ %o/s : %es ] " [0 processes, 2/2 @ 0.0/s : 1461869902.367s ] Reset the stopwatches in BuildEdgeFinished before finshed_edges_ is incremented instead.
PR ninja-build#999 made dumb terminals only output when edges finish. PrintStatus is called after finished_edges_ is incremented, which means the calculation for running edges will always return 1 less than the real number of running processes. This happens on smart terminals too, but ninja will immediately print the status for the next edge with starting_edges_ incremented, so the incorrect value is never visible. Pass a boolean specifying whether the status is being printed on an edge finishing, and if so count the edge that just finished as being running.
|
I think this might have regressed output on the Chrome bots. Dirk noticed un-nice output on https://build.chromium.org/p/chromium.linux/builders/Linux%20Builder%20%28dbg%29%2832%29/builds/52253/steps/compile/logs/stdio Maybe because the jobs are finishing at that point? Seems like we might need a special case for failure if we want to keep this ordering of output. |
|
(Should have been @dpranke above.) |
|
Before this patch output from commands that were running concurrently with failed command would appear after the output of the failed command, with no status line to separate the outputs of the different commands. Chromium probably never ran into this issue since your rules generally have no output. After this patch every command output is preceded by its status line, but that means that failures are followed by status lines for all concurrent commands. Hiding the status lines for concurrent commands that have no output doesn't seem right, since those rules ran and completed. We could delay printing the error until all concurrent commands have finished, but then if you had an error concurrent with a long command you might get the error much later than you otherwise could have seen it. On Android our commands are so noisy that identifying the build output from a failing command is impossible without this patch. |
|
I think delaying the error is probably okay; I don't know how often you really need to see the failures in real time or the delay would be long enough to matter. I agree that the change is generally an improvement and I would like to avoid hiding the output from completed edges as well. |
|
I think it'd be OK to delay the error, but only in dumb-mode; that would be annoying locally in smart-terminal mode where there's often a long unrelated link finishing. |
|
sure, only in not-a-tty-mode is fine by me. |
PR ninja-build#999 made dumb terminals only output when edges finish. PrintStatus is called after finished_edges_ is incremented, which means the calculation for running edges will always return 1 less than the real number of running processes. This happens on smart terminals too, but ninja will immediately print the status for the next edge with starting_edges_ incremented, so the incorrect value is never visible. Pass a boolean specifying whether the status is being printed on an edge finishing, and if so count the edge that just finished as being running.
|
I just ran into this when 'ninja -v' did not print started jobs anymore (which run for many minutes, so there is basically no output at all). This is pretty annoying -- are there any plans to offer to revert to the previous behavior as an option? |
|
FWIW I find this annoying in -v mode too, so I agree it'd be nice to do something there. |
On smart terminals ninja prints the status line both before
and after running a command, reusing the same line if possible.
On a dumb terminal that doesn't support reusing the line, it
only prints the status before starting the command, but prints
the output of the command when the command finishes, by which
point other commands may have started and printed their status
line. This makes it impossible to determine what command
produced a line of output.
Modify BuildEdgeStarted to only print the status line if the
command is going to lock the console, or if ninja is running
on a smart terminal. Modify BuildEdgeFinished to always
print the status line unless the command locked the console,
in which case the status was already printed and no other
command can have printed any lines.
The end result will be dumb terminal output that much more
closely matches smart terminal output. One disadvantage is
that dumb terminals won't show anything when starting a
command, making it harder to tell what commands are currently
running, but I expect most interactive uses of ninja will use
a smart terminal.