[TimeProfiler] Emit clock synchronization point

Time profiler 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. If such a compiler supports generating time traces
  of its own events, it could merge those events with LLVM-specific
  events received from llc/opt, and produce a more complete time trace.

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

Differential Revision: https://reviews.llvm.org/D78030

diff --git a/clang/test/Driver/check-time-trace-sections.py b/clang/test/Driver/check-time-trace-sections.py
index 7b59853..7551e5c 100644 (file)
--- a/clang/test/Driver/check-time-trace-sections.py
+++ b/clang/test/Driver/check-time-trace-sections.py
@@ -1,6 +1,6 @@
 #!/usr/bin/env python
 
-import json, sys
+import json, sys, time
 
 def is_inside(range1, range2):
     a = range1["ts"]; b = a + range1["dur"]
@@ -11,11 +11,22 @@ 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
+# and not later than now.
+if beginning_of_time > seconds_since_epoch or \
+        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!")

diff --git a/clang/test/Driver/check-time-trace.cpp b/clang/test/Driver/check-time-trace.cpp
index 1484462..1d80748 100644 (file)
--- a/clang/test/Driver/check-time-trace.cpp
+++ b/clang/test/Driver/check-time-trace.cpp
@@ -3,18 +3,19 @@
 // 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 {

diff --git a/lld/test/ELF/time-trace.s b/lld/test/ELF/time-trace.s
index 8085a25..e1da4c4 100644 (file)
--- a/lld/test/ELF/time-trace.s
+++ b/lld/test/ELF/time-trace.s
@@ -18,7 +18,8 @@
 # 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":

diff --git a/llvm/lib/Support/TimeProfiler.cpp b/llvm/lib/Support/TimeProfiler.cpp
index c907c1a..93bf6f5 100644 (file)
--- a/llvm/lib/Support/TimeProfiler.cpp
+++ b/llvm/lib/Support/TimeProfiler.cpp
@@ -75,9 +75,9 @@ struct Entry {
 
 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);
   }
 
@@ -234,12 +234,22 @@ struct llvm::TimeTraceProfiler {
 
     J.arrayEnd();
     J.attributeEnd();
+
+    // Emit the absolute time when this TimeProfiler started.
+    // 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;