fix(log): break timing-info message to multiple

[weihanglo]

What does this PR try to resolve?

Convert timing-info log messages from a single aggregated message per unit
to an event-based model that captures the build timings.

New events introduced:

• unit-started - compilation begins (full metadata + index)
• unit-rmeta-finished - .rmeta artifact generated (with unlocked units)
• unit-section-{started,finished} - compilation phases (with section name)
• unit-finished - completion (with unlocked units)
• All events use elapsed time instead of duration
• All events reference units by deterministic index from unit-started

Changes in old events:

• timing-info — split to five unit-* events
• rebuild — the target field now use a custom struct to show { name, kind }, which should be good enough to distinguish different units.

Part of #15844.

How to test and review this PR?

Test diffs should reflect the change.
A new test has bee added to showcase -Zsection-timings
(apparently we didn't have any test before).

[rustbot]

r? @epage

rustbot has assigned @epage.
They will have a look at your PR within the next two weeks and either review your PR or reassign to another reviewer.

Use r? to explicitly pick a reviewer

[epage]

Before I dig into this too much, do we need special messages for these or are there existing json messages from cargo we could use if we also log those? If not, are there existing rustc messages that we can translate into cargo messages to handle this?

[weihanglo]

What Cargo --message-format=json emits today:

• build-finished — for the entire build, not at per unit level
• build-script-exectued — emitted after build script execution
• compiler-artifact — emitted when a compiler artifact is produced for each rustc invocation.
• compiler-message — this is basically rustc diagonstics.
• timing-info — the unstable aggregated timing info. It is the same as the old timing-info log message before this PR.

None of them has any elapsed time information

What rustc has today:

• diagnostic — just diagnostics
• artifact — Notice when an artifact is written to disk. Contains file name and emit-type.
• future_incompat — for future incompat warnings
• section_timing — unstable section timing. Looks like

  {
      "event": "start", /* Marks the "start" or "end" of the compilation section */
      "name": "link",  /* The name of the compilation section */
      // Opaque timestamp when the message was emitted, in microseconds
      // The timestamp is currently relative to the beginning of the compilation session
      "time": 12345
  }

I don't feel like there is anything we can directly use. timing-info Cargo message is half-broken. compiler-artifact has too much of information timing tracking doesn't need (but perhaps we'd like to expand to that in the future). We might not want to rely on section_timing's time field, as it is unclear what "beginning of the compilation" refers to.

The current approach gives us a room to iterate on our own at least.

[epage]

If we view this as a hack and document that we need to consolidate our messages, I'm fine moving forward with this.

[weihanglo]

Yeah it is not the final version. I'd love to learn your thoughts on long-term consolidating our JSON messages and logging.

[epage]

I think we need to flesh out our json messages more

From #7614 (comment)

I think we should work to improve our json messages. The build analysis work is one area that will help shine a light on that. Another is the new cargo-fix architecture which would ideally have cargo check like progress while being a wrapper around cargo check, so we'll need json messages to support all of the progress reporting needs

If we log all json messages, we'll have redundancy with this.

From #t-cargo > build analysis log format @ 💬

would love for us to record all --message-format json messages

I also wonder if we should go with a full inverse, all logged messages are also json messages. Of course, we'll likely need to keep them distinct while the feature is unstable and we work through what we want the schema to be.

[epage]

While this reduces content, it does deviate from our normal structure of json messages

[weihanglo]

I am seeing timings message different from other messages. If users want details information, they should either inspect other messages or cargo metadata. Though if we want to be a bit consistent atm, fine with reusing the detailed Target struct.

[epage]

I think this ties into #16303 (comment)

[epage]

This also is being inconsistent

[epage]

I've noted schema questions in the tracking issue

View changes since this review