[TimeProfiler] Emit clock synchronization point

[broadwaylamb]

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:

[MaskRay]

lld/test/ELF/time-trace.s

21–22

Add 5 spaces after : so that the key is aligned

[broadwaylamb]

Indent patterns in tests

[broadwaylamb]

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

[MaskRay]

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.

[broadwaylamb]

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]

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]

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]

llvm/lib/Support/TimeProfiler.cpp

248

Exactly, yes.

[broadwaylamb]

A simpler generation of the beginning of time.

[broadwaylamb]

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?

[broadwaylamb]

ping

[russell.gallop]

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."?

[broadwaylamb]

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

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

 #!/usr/bin/env python
 
-import json, sys
+import json, sys, time
 
 def is_inside(range1, range2):
     a = range1["ts"]; b = a + range1["dur"]
     c = range2["ts"]; d = c + range2["dur"]
     return (a >= c and a <= d) and (b >= c and b <= d)
 
 def is_before(range1, range2):
     b = range1["ts"] + range1["dur"]; c = range2["ts"]
     return b <= c
 
-events = json.loads(sys.stdin.read())["traceEvents"]
+log_contents = json.loads(sys.stdin.read())
+events = log_contents["traceEvents"]
 codegens = [event for event in events if event["name"] == "CodeGen Function"]
 frontends = [event for event in events if event["name"] == "Frontend"]
 backends = [event for event in events if event["name"] == "Backend"]
 
+beginning_of_time = log_contents["beginningOfTime"] / 1000000
+seconds_since_epoch = time.time()
+
+# Make sure that the 'beginningOfTime' is not earlier than 10 seconds ago.
+if seconds_since_epoch - beginning_of_time > 10:
+    sys.exit("'beginningOfTime' should represent the absolute time when the "
+             "process has started")
+
 if not all([any([is_inside(codegen, frontend) for frontend in frontends])
                         for codegen in codegens]):
     sys.exit("Not all CodeGen sections are inside any Frontend section!")
 
 if not all([all([is_before(frontend, backend) for frontend in frontends])
                         for backend in backends]):
     sys.exit("Not all Frontend section are before all Backend sections!")

clang/test/Driver/check-time-trace.cpp

 // RUN: %clangxx -S -ftime-trace -ftime-trace-granularity=0 -o %T/check-time-trace %s
 // RUN: cat %T/check-time-trace.json \
 // RUN:   | %python -c 'import json, sys; json.dump(json.loads(sys.stdin.read()), sys.stdout, sort_keys=True, indent=2)' \
 // RUN:   | FileCheck %s
 
-// CHECK: "traceEvents": [
-// CHECK: "args":
-// CHECK: "detail":
-// CHECK: "dur":
-// CHECK: "name":
+// CHECK:      "beginningOfTime": {{[0-9]{16},}}
+// CHECK-NEXT: "traceEvents": [
+// CHECK:      "args":
+// CHECK:      "detail":
+// CHECK:      "dur":
+// CHECK:      "name":
 // CHECK-NEXT: "ph":
 // CHECK-NEXT: "pid":
 // CHECK-NEXT: "tid":
 // CHECK-NEXT: "ts":
-// CHECK: "name": "clang{{.*}}"
-// CHECK: "name": "process_name"
-// CHECK: "name": "thread_name"
+// CHECK:      "name": "clang{{.*}}"
+// CHECK:      "name": "process_name"
+// CHECK:      "name": "thread_name"
 
 template <typename T>
 struct Struct {
   T Num;
 };
 
 int main() {
   Struct<int> S;
 
   return 0;
 }

lld/test/ELF/time-trace.s

 # RUN:   | %python -c 'import json, sys; json.dump(json.loads(sys.stdin.read()), sys.stdout, sort_keys=True, indent=2)' \
 # RUN:   | FileCheck %s
 
 # Test trace requested to stdout
 # RUN: ld.lld -time-trace -time-trace-file=- -time-trace-granularity=0 -o %t3.elf %t.o \
 # RUN:   | %python -c 'import json, sys; json.dump(json.loads(sys.stdin.read()), sys.stdout, sort_keys=True, indent=2)' \
 # RUN:   | FileCheck %s
 
-# CHECK: "traceEvents": [
+# CHECK:      "beginningOfTime": {{[0-9]{16},}}
+# CHECK-NEXT: "traceEvents": [
 
 # Check one event has correct fields
 # CHECK:      "dur":
 # CHECK-NEXT: "name":
 # CHECK-NEXT: "ph":
 # CHECK-NEXT: "pid":
 # CHECK-NEXT: "tid":
 # CHECK-NEXT: "ts":

llvm/lib/Support/TimeProfiler.cpp

return (time_point_cast<microseconds>(End) -
             time_point_cast<microseconds>(Start))
         .count();
   }
 };
 } // namespace
 
 struct llvm::TimeTraceProfiler {
   TimeTraceProfiler(unsigned TimeTraceGranularity = 0, StringRef ProcName = "")
-      : StartTime(steady_clock::now()), ProcName(ProcName),
-        Pid(sys::Process::getProcessId()), Tid(llvm::get_threadid()),
-        TimeTraceGranularity(TimeTraceGranularity) {
+      : BeginningOfTime(system_clock::now()), StartTime(steady_clock::now()),
+        ProcName(ProcName), Pid(sys::Process::getProcessId()),
+        Tid(llvm::get_threadid()), TimeTraceGranularity(TimeTraceGranularity) {
     llvm::get_thread_name(ThreadName);
   }
 
   void begin(std::string Name, llvm::function_ref<std::string()> Detail) {
     Stack.emplace_back(steady_clock::now(), TimePointType(), std::move(Name),
                        Detail());
   }
 
void write(raw_pwrite_stream &OS) {
 
     writeMetadataEvent("process_name", Tid, ProcName);
     writeMetadataEvent("thread_name", Tid, ThreadName);
     for (const TimeTraceProfiler *TTP : ThreadTimeTraceProfilerInstances)
       writeMetadataEvent("thread_name", TTP->Tid, TTP->ThreadName);
 
     J.arrayEnd();
     J.attributeEnd();
+
+    // Emit the absolute time of the moment when this TimeProfiler started
+    // measurements. This can be used to combine the profiling data from
+    // multiple processes and preserve actual time intervals.
+    J.attribute("beginningOfTime",
+                time_point_cast<microseconds>(BeginningOfTime)
+                    .time_since_epoch()
+                    .count());
+
     J.objectEnd();
   }
 
   SmallVector<Entry, 16> Stack;
   SmallVector<Entry, 128> Entries;
   StringMap<CountAndDurationType> CountAndTotalPerName;
+  const time_point<system_clock> BeginningOfTime;
   const TimePointType StartTime;
   const std::string ProcName;
   const sys::Process::Pid Pid;
   SmallString<0> ThreadName;
   const uint64_t Tid;
 
   // Minimum time granularity (in microseconds)
   const unsigned TimeTraceGranularity;