This is an archive of the discontinued LLVM Phabricator instance.

[TimeProfiler] Emit clock synchronization point
ClosedPublic

Authored by broadwaylamb on Apr 13 2020, 9:29 AM.

Details

Summary

TimeProfiler emits relative timestamps for events (the number of microseconds passed since the start of the current process).

This patch allows combining events from different processes while preserving their relative timing by emitting a new attribute beginningOfTime. This attribute contains the system time that corresponds to the zero timestamp of the time profiler.

This has at least two use cases:

  • Build systems can use this to merge time traces from multiple compiler invocations and generate statistics for the whole build. Tools like ClangBuildAnalyzer could also leverage this feature.
  • Compilers that use LLVM as their backend by invoking llc/opt in a child process. I'm currently working on supporting the -ftime-trace functionality in GHC. A single GHC invocation can emit GHC-specific events, but with this patch it could also include LLVM-specific events in its log.

I wrote a proof-of-concept script that merges multiple logs that contain a synchronization point into one log: https://github.com/broadwaylamb/merge_trace_events

This is how the result looks like for GHC:

Diff Detail

Event Timeline

broadwaylamb created this revision.Apr 13 2020, 9:29 AM
MaskRay added inline comments.Apr 13 2020, 2:36 PM
lld/test/ELF/time-trace.s
21–22

Add 5 spaces after : so that the key is aligned

aras-p accepted this revision.Apr 14 2020, 12:36 AM
This revision is now accepted and ready to land.Apr 14 2020, 12:36 AM

Indent patterns in tests

broadwaylamb marked an inline comment as done.Apr 14 2020, 8:05 AM

It'd be good if I had one more LGTM.

MaskRay added inline comments.Apr 14 2020, 12:14 PM
llvm/lib/Support/TimeProfiler.cpp
248

What is the logic here?

Two events in the same process may have different beginningOfTime. Is that intended?

Noe that system_clock::now() and steady_clock::now() are not measured at the same time.

MaskRay requested changes to this revision.Apr 14 2020, 12:14 PM
This revision now requires changes to proceed.Apr 14 2020, 12:14 PM
broadwaylamb marked an inline comment as done.Apr 14 2020, 12:47 PM
broadwaylamb added inline comments.
llvm/lib/Support/TimeProfiler.cpp
248

Two events in the same process may have different beginningOfTime. Is that intended?

How would that be possible? We only compute beginningOfTime when writing the data of the time profiler to a JSON file. AFAICT it happens only once. So, this code is only called once.

Noe that system_clock::now() and steady_clock::now() are not measured at the same time.

I understand. But the difference should be very small (certainly less than a microsecond), since there are only a few arithmetic operations in between.

broadwaylamb marked an inline comment as done.Apr 14 2020, 12:58 PM
broadwaylamb added inline comments.
llvm/lib/Support/TimeProfiler.cpp
248

Although we could set the beginning of time in TimeProfiler's constructor and assign it to a field. That would be a lot simpler, I guess. What do you think?

MaskRay added inline comments.Apr 14 2020, 4:07 PM
llvm/lib/Support/TimeProfiler.cpp
248

OK, but I am still confused by the logic and the comment. Does the code just want to compute the start time in system_clock?

broadwaylamb marked an inline comment as done.Apr 16 2020, 7:38 AM
broadwaylamb added inline comments.
llvm/lib/Support/TimeProfiler.cpp
248

Exactly, yes.

A simpler generation of the beginning of time.

MaskRay accepted this revision.Apr 16 2020, 8:13 AM
This revision is now accepted and ready to land.Apr 16 2020, 8:13 AM

Since we're adding a new attribute here that we won't ever be able to remove in the future, I'd still like to get a LGTM from some of the folks that are familiar with the time profiler. @russell.gallop @anton-afanasyev?

russell.gallop accepted this revision.Apr 22 2020, 1:18 AM

LGTM, with a few small comments.

For the record, I wondered whether the time profiler could emit all ts as absolute, so I tried it out. This has two problems. 1). The "Total" numbers also need adjusting to be at the beginning of the trace time rather than zero, which feels a little odd, and it hard to see how long things are on the time scale. 2). All of the times end up being very large numbers so this bloats traces considerably.

clang/test/Driver/check-time-trace-sections.py
23

Could also check that beginningOfTime isn't after seconds_since_epoch.

llvm/lib/Support/TimeProfiler.cpp
78

Note that this will record BeginningOfTime for each TimeTraceProfiler started on a thread, but that won't be used. This shouldn't cause any harm and I don't think that is very frequent so I think that this is okay.

238

Nit. This is a bit wordy. How about "Emit the absolute time when this TimeProfiler started."?

@russell.gallop thanks! I'll address your comments and commit the change.

This revision was automatically updated to reflect the committed changes.