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!")
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!")
_______________________________________________
cfe-commits mailing list
cfe-commits@lists.llvm.org
https://lists.llvm.org/cgi-bin/mailman/listinfo/cfe-commits
