tp: fix the ninja log visualization, read v6 and v7 - #7249
Conversation
|
Fwiw I tried moden ninja logs as well but I was disappointed in the visualization compared to ninjatracing. It would be nice if, as part of this change, we also make the visualization closer to what ninjatracing produces. |
|
Agreed that the visualization is the weaker half of the story, and I'd like to fix it — but as a separate change on top of this one. This PR is a pure gate fix: no ninja in use writes v5, so the importer currently rejects every real Making the track layout closer to ninjatracing changes what the importer emits rather than what it accepts — different code, different tests, and a design question of its own (ninjatracing packs concurrent jobs onto synthetic tracks by start/end overlap and derives names from the output path; the current importer does neither). Folding that in here would bury the gate fix under it and make both harder to review. If that split works for you I'll open the visualization PR against this one once it lands. If you'd rather see them together, say so and I'll fold it in. |
|
Correction to my previous comment: I described the current importer from memory and got it wrong. It does pack concurrent jobs onto synthetic worker tracks by timestamp overlap — with a documented heuristic that picks the worker whose The split I'm proposing stands, but on the honest version of the argument: the gate fix in this PR is about what the importer accepts, and any visualization change is about what it emits, with its own tests. I'll go and characterise the actual gap against ninjatracing on a real build log before saying anything more about it. One thing already visible in the code: every worker thread is named the literal |
|
The reason I want it as part of this change is that I'd rather say "unsupported" than show a poor visualization. So I think it's a prerequisite for landing this change. |
The .ninja_log importer accepts only `# ninja log v5`, a version no ninja in use writes any more: 1.12 bumped the format to v6 and 1.13 to v7, and ninja's own reader has kOldestSupportedVersion == kCurrentVersion == 7, so it neither writes nor reads v5. Feeding trace_processor the .ninja_log of a Perfetto build made by ninja 1.13.2 fails outright with "Unsupported ninja log version". Neither bump changed the layout of a log line: v6 (ninja c266b21, first released in 1.12) only dropped ninja's own support for reading v4 entries, and v7 (32e7e23, released in 1.13) switched the command hash from MurmurHash2 to rapidhash. Perfetto never interprets that hash, it only compares it for equality when merging the outputs of a multi-output rule, so v5, v6 and v7 all parse identically here. Widen the gate to 5..7. Anything outside the range is still rejected rather than guessed at, and the error now names the version it saw. Add diff tests over v6 and v7 fixtures whose job lines are six real lines of a ninja 1.13.2 build log; v5 stays covered by the existing TraceProcessorIntegrationTest.NinjaLog. .ninja_log is tab separated by definition, so the presubmit tab check skips that extension.
A .ninja_log accumulates the log of every build run in that output directory, and each build restarts its timestamps from zero. The importer infers parallelism from overlapping timestamps, so builds laid on top of each other look like one build with several times the real number of workers. On the ninja_log in test/data, which holds two builds, this synthesizes 28 worker tracks for a build that ran with far fewer; on a .ninja_log from a real perfetto checkout with 64 builds in it, 50 tracks for a `-j10` build, with up to 140 jobs drawn as concurrent. Detect the build boundary again - within an invocation ninja appends lines as jobs complete, so an end timestamp going backwards starts a new build - and shift each build past the end of the previous one, which is what ninjatracing does with --showall. No job is dropped and the packing heuristic is untouched; workers are simply reused across builds instead of being duplicated. Boundary detection was removed in bec39a8 to avoid an explosion in the number of tracks, by merging all builds into one process the way ninjatracing was believed to. ninjatracing does not superimpose builds: it keeps only the last one by default and lays them end to end with --showall. Merging them onto one timeline produces the very explosion that commit set out to avoid. After this change trace_processor matches `ninjatracing --showall` on test/data/ninja_log exactly: 14 workers, 57556 ms span, 837192 ms of total job duration over 681 slices. Two smaller fixes to the same output, each with its own test: - worker threads are numbered again ("Worker 1", "Worker 2", ...). The numbering was lost in the same commit, so every track was labelled "Worker". - the outputs of a multi-output rule are joined with ", " rather than " ", so a slice reads "gen/foo.pb.h, gen/foo.pb.cc" instead of running the paths together. The class comment described the removed per-invocation behaviour and has been updated to what the code does.
99ef907 to
0221d5d
Compare
|
Folded in — this now fixes the visualization first and widens the gate second. The visualization was poor for one concrete reason: a Boundary detection existed until bec39a8, which removed it to avoid exactly that explosion, on the understanding that ninjatracing merges all builds into one process. It doesn't: So this restores the detection and does the If you would rather have ninjatracing's default — keep only the last build — say so and I'll switch. It gives the same track count, but it throws away 89% of that log, which is why I didn't pick it. I also tried deriving each build's real wall-clock start from the mtime field so the builds could sit where they actually happened; it doesn't hold up, because on small incremental builds many outputs keep an older mtime, so the derived starts come out non-monotonic and most builds still overlap. Two smaller things in the same commit, each with a test: worker tracks are numbered again (the Unrelated, noticed while reading: the |
Two commits: the first lets a modern
.ninja_login at all, the secondfixes what the importer draws once it is in. Per review, the
visualization is a prerequisite for the version bump rather than a
follow-up.
Read v6 and v7
The
.ninja_logimporter accepts only# ninja log v5, a version noninja in use writes any more. ninja 1.12 bumped the format to v6 and
1.13 to v7, and ninja's own reader has
kOldestSupportedVersion == kCurrentVersion == 7, so it neither writesnor reads v5. Feeding trace_processor the
.ninja_logof a Perfettobuild made by ninja 1.13.2 fails outright with
Unsupported ninja log version, even though.ninja_logis one of theformats the docs advertise.
Neither bump changed the layout of a log line:
first released in 1.12) only dropped ninja's own support for reading
v4 entries.
first released in 1.13) switched the command hash from MurmurHash2 to
rapidhash.
Perfetto never interprets that hash, it only compares it for equality
when merging the outputs of a multi-output rule, so v5, v6 and v7 parse
identically here. The gate is widened to 5..7; anything outside that is
still rejected rather than guessed at, and the error now names the
version it saw.
Stop drawing builds on top of each other
A
.ninja_logaccumulates the log of every build run in that outputdirectory, and each build restarts its timestamps from zero. The
importer infers parallelism from overlapping timestamps, so builds laid
on top of each other look like one build with several times the real
number of workers.
The effect is not marginal.
test/data/ninja_log, this repo's own testasset, holds two builds and gets 28 worker tracks. The
.ninja_logof aPerfetto checkout here has 64 builds in it and gets 50 tracks for a
-j10build, with up to 140 jobs drawn as concurrent. One stale buildof 32 lines in front of a real one is enough to double the track count.
Boundary detection used to exist and was removed in bec39a8, to avoid
"an explosion in the number of tracks", by merging all builds into one
process the way ninjatracing was believed to work. ninjatracing does not
superimpose builds:
read_targets()treats an end timestamp that goesbackwards as a new build and, by default, throws away everything before
it, keeping only the last build;
--showallinstead lays the builds endto end. Merging them onto one timeline produces the very explosion that
commit set out to avoid.
This restores the boundary detection (within an invocation ninja appends
lines as jobs complete, so an end timestamp going backwards starts a new
build) and shifts each build past the end of the previous one, which is
what ninjatracing does with
--showall. No job is dropped and thepacking heuristic is untouched; workers are reused across builds instead
of being duplicated. On the numbers above: 28 tracks become 14, and 50
become 10, with all 5735 slices still present. A log holding a single
build is unaffected.
The alternative of keeping only the last build was measured too. It
gives the same track count and throws away 89% of that log, so it did
not seem worth the loss. Deriving each build's real wall-clock start
from the mtime field was also tried and does not hold up: on small
incremental builds many outputs keep an older mtime, the derived starts
come out non-monotonic and most builds still overlap.
After this change trace_processor matches
ninjatracing --showallontest/data/ninja_logexactly: 14 workers, 57556 ms span, 837192 ms oftotal job duration over 681 slices, same last slice.
Two smaller fixes to the same output, each with its own test:
Worker 1,Worker 2, ...). The%zuwas dropped in the same commit, so every track was labelledWorker.", "rather than" ", so a slice readsgen/foo.pb.h, gen/foo.pb.ccinstead ofrunning the paths together.
The class comment described the per-invocation behaviour that
bec39a8 removed and has been updated to what the code does.
Tests
of a ninja 1.13.2 build log;
fail against an unpatched trace_processor and pass with this change;
TraceProcessorIntegrationTest.NinjaLogupdated for the new workercount and span, with its cross-check against ninjatracing noted in the
comment;
Unrelated to this change, noticed while reading the docs: the
.ninja_logsection describes the third field as "the restat mtime (inmilliseconds)". It is seconds in the v5 logs and nanoseconds in the v7
logs I looked at, never milliseconds. Left alone here.