[PATCH] D78030: [TimeProfiler] Emit clock synchronization point

[Sergej Jaskiewicz via Phabricator via cfe-commits]

broadwaylamb created this revision.
broadwaylamb added reviewers: anton-afanasyev, russell.gallop, espindola.
Herald added subscribers: cfe-commits, MaskRay, hiraditya, emaste.
Herald added a project: clang.
broadwaylamb added a parent revision: D78027: [TimeProfiler] Emit real process ID and thread names.

`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 <https://github.com/aras-p/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:

F11724922: 79080338-ad673580-7d1c-11ea-9e30-5e6f72e77555.png <https://reviews.llvm.org/F11724922>


Repository:
  rG LLVM Github Monorepo

https://reviews.llvm.org/D78030

Files:
  clang/test/Driver/check-time-trace-sections.py
  clang/test/Driver/check-time-trace.cpp
  lld/test/ELF/time-trace.s
  llvm/lib/Support/TimeProfiler.cpp


Index: llvm/lib/Support/TimeProfiler.cpp
===================================================================
--- llvm/lib/Support/TimeProfiler.cpp
+++ llvm/lib/Support/TimeProfiler.cpp
@@ -251,6 +251,21 @@
 
     J.arrayEnd();
     J.attributeEnd();
+
+    // Emit synchronization point, i. e. the absolute time of StartTime.
+    // When combining time profiler logs from different processes,
+    // this attribute helps preserve relative timing.
+    {
+      const auto SystemTime =
+          time_point_cast<microseconds>(system_clock::now());
+      const microseconds ProcessLocalTime =
+          time_point_cast<microseconds>(steady_clock::now()) -
+          time_point_cast<microseconds>(StartTime);
+      const auto BeginningOfTimeUs = SystemTime - ProcessLocalTime;
+      J.attribute("beginningOfTime",
+                  BeginningOfTimeUs.time_since_epoch().count());
+    }
+
     J.objectEnd();
   }
 
Index: lld/test/ELF/time-trace.s
===================================================================
--- lld/test/ELF/time-trace.s
+++ 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":
Index: clang/test/Driver/check-time-trace.cpp
===================================================================
--- clang/test/Driver/check-time-trace.cpp
+++ clang/test/Driver/check-time-trace.cpp
@@ -3,7 +3,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: "args":
 // CHECK: "detail":
 // CHECK: "dur":
Index: clang/test/Driver/check-time-trace-sections.py
===================================================================
--- clang/test/Driver/check-time-trace-sections.py
+++ 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,20 @@
     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!")


-------------- next part --------------
A non-text attachment was scrubbed...
Name: D78030.257002.patch
Type: text/x-patch
Size: 3336 bytes
Desc: not available
URL: <http://lists.llvm.org/pipermail/cfe-commits/attachments/20200413/84354c2f/attachment.bin>