Add timestamps to ninja output

[Marc-Antoine Ruel]

Hi

Would our benevolent dictator(s) accept a patch to change ninja to show the relative timestamp + duration of each commands like run_test_cases does? The benefits are:

- Quickly determine the slowest operations, like linking.

- Quickly find when the build process was effectively hung with the help of the relative timestamp of each output, for example by disk I/O contention.

The output could be controlled by either:

- output is redirected to a file/pipe instead of a console

- with a new flag

- just enable the new format all the time

I don't know which you would prefer so that's why I'm asking before any implementation.

Faked example of the proposed output:

[   1/2686]   0.97s CXX obj/base/base.hi_res_timer_manager_posix.o (0.97s)

[   2/2686]   2.36s CXX obj/base/json/base.json_file_value_serializer.o (1.39s)

[   3/2686]   2.46s CXX obj/base/json/base.json_parser.o (2.45s)

[   4/2686]   2.46s CXX obj/base/json/base.json_writer.o (2.45s)

[   5/2686]   2.46s CXX obj/base/base.lazy_instance.o (2.45s)

[   6/2686]   4.08s CXX obj/base/base.location.o (1.63s)

[   7/2686]   4.25s CXX obj/base/base.logging.o (1.89s)

[   8/2686]   4.35s CXX obj/base/memory/base.ref_counted.o (1.90s)

First timestamp column is the relative timestamp at which the message was printed, the last number is the duration of this single step.

Thanks,

M-A

[Evan Martin]

I like this idea.

Ninja already tracks the start/end times of all commands, so if you wanted to extract this sort of info without making any changes to Ninja you can look at out/Debug/.ninja_log : the first column is the start time (in ms, since the start of the build) and second is the end time.

Otherwise, you probably can extend FormatProgressStatus() to let you add this info to the NINJA_STATUS env variable. http://martine.github.com/ninja/manual.html#_environment_variables

You can make up a new format parameter in the code here, and to take additional info:

  https://github.com/martine/ninja/blob/master/src/build.cc#L177

then adjust the place where it's called

  https://github.com/martine/ninja/blob/master/src/build.cc#L253

see also BuildEdgeFinished() in the same file -- that's what's called when a subcommand completes and it has the timing info.

Two caveats:

1) this code has no tests, which is a recurring annoyance.  I'm sorry.

2) when run on a dumb terminal (like the build bot), Ninja goes into dumb terminal mode where it only prints each built edge once, when the edge starts.  But what you want is for Ninja to print when the edge finishes (as that's the only point you'll know how long it took).  One idea for how to work around this is to scan NINJA_STATUS at startup and say "if it references the time the edge finished, then it should only print after the edge completes".  Not sure how unpredictable that is, though.  It may also be weird as the bot won't print anything while running a long command, only after it finishes.

--
You received this message because you are subscribed to the Google Groups "ninja-build" group.
To unsubscribe from this group and stop receiving emails from it, send an email to ninja-build...@googlegroups.com.
For more options, visit https://groups.google.com/groups/opt_out.
 
 

[Gavin Peters (蓋文彼德斯)]

Why not store this information in the log, and provide a tool to extract it?

- Gavin

[Allan Odgaard]

On Feb 8, 2013, at 6:19 PM, Gavin Peters (蓋文彼德斯) <gav...@google.com> wrote:

> Why not store this information in the log, and provide a tool to extract it?

Agree, I think this belongs as a tool. When used for analysis purposes, the information should be stored somewhere, not be intermixed with regular output, and it solves the problem that the per-node build time is not known at the time ninja writes out its activity line.

[Nico Weber]

Hi maruel,

On Fri, Feb 8, 2013 at 9:02 AM, Marc-Antoine Ruel <mar...@chromium.org> wrote:

> Would our benevolent dictator(s) accept a patch to change ninja to show the
> relative timestamp + duration of each commands like run_test_cases does? The
> benefits are:
> - Quickly determine the slowest operations, like linking.
> - Quickly find when the build process was effectively hung with the help of
> the relative timestamp of each output, for example by disk I/O contention.

I wrote a prototype of something similar a while ago:
https://github.com/nico/ninja/tree/display This shows all currently
running commands and their runtime. I wrote it for the same reasons
you mention above, but I didn't find it all that useful in practice.
(Check out that branch and build chromium with it yourself to give it
a try. It assumes that there is no output from subprocesses, but
that's true in chromium.)

Nico

[Marc-Antoine Ruel]

Thanks all!

Thanks for the pointers Evan. I like the idea of using the environment variable, I didn't know about it, a classic case of RTFM. :) That makes it easy to enable it on the build slaves but not annoy users, all without having to add any kind of flag. It fits my intended use case particularly well. 

I see the caveat and I'm fine with the second one. As a first step, there's no variable for "build rule". So I'd like to propose first to change the NINJA_STATUS behavior to add an explicit "build rule" variable. I quickly wrote something at https://github.com/maruel/ninja/compare/status but it's not completely working. I'd like to know if you like the idea before investing more time on that route. I'll happily write a unit test for it before sending a pull request, I got ninja_test to run green here.

Gavin and Allan, I don't want to add any new build steps, I just want minimal new information from the already available build log files. More importantly, we'd lose the streaming property of the compile stdio.

Thanks,

M-A

2013/2/8 Nico Weber <tha...@chromium.org>

[Evan Martin]

Yeah, that patch looks great.  It's clever to switch the behavior on whether you're using the before or after format character, that's much better than what I was thinking.

It's probably worth thinking about what to do when neither %b nor %B are present, for people who've already set this variable using an older Ninja version.  Maybe we should just warn in that case.

I wrote some small comments on the review.

[Frank Miller]

Marc-Antonie,

Have you done any more work on this? I hacked on your branch a bit and I think I got it where you wanted.

    https://github.com/frankmiller/ninja/compare/master...status

I can get something similar to the output you proposed in the first email in this thread by setting the following environment variables.

    NINJA_STATUS='[%s/%t] %es %b (%ds)'
    TERM='dumb'

What do you think?

Frank

[Marc-Antoine Ruel]

Hi!

Thanks for looking into it. I've been slacking on it because I really wanted to write a thorough test first, and a test that would work on all OSes. You can see my diff of the feature without the test at:

https://github.com/maruel/ninja/compare/master...status

or the commit itself:

https://github.com/maruel/ninja/commit/dce1ea3e359e38f911d6355a2cb2f31da6290357

The reason for a test is that this new support creates a new code paths that may never get used in the common flow, potentially causing broken behaviour to go unnoticed before release that would use optional features, e.g. (%b vs %B) on (pty vs redirected).

You can look if there's anything interesting in my branch (probably not) and get yours merged if you can. That would be appreciated.

Thanks,

M-A

2013/5/29 Frank Miller <christopher...@gmail.com>