[lld] 2899103 - [TimeProfiler] Emit clock synchronization point
Sergej Jaskiewicz via llvm-commits
llvm-commits at lists.llvm.org
Wed Apr 22 15:09:50 PDT 2020
Author: Sergej Jaskiewicz
Date: 2020-04-23T01:09:31+03:00
New Revision: 2899103108d38215af8aae377cd0e54794278209
URL: https://github.com/llvm/llvm-project/commit/2899103108d38215af8aae377cd0e54794278209
DIFF: https://github.com/llvm/llvm-project/commit/2899103108d38215af8aae377cd0e54794278209.diff
LOG: [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
Added:
Modified:
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
Removed:
################################################################################
diff --git a/clang/test/Driver/check-time-trace-sections.py b/clang/test/Driver/check-time-trace-sections.py
index 7b598537a5b0..7551e5c19be5 100644
--- 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 1484462b72bb..1d80748a5233 100644
--- 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 8085a256649e..e1da4c476f40 100644
--- 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 c907c1aaf983..93bf6f57e348 100644
--- 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;
More information about the llvm-commits
mailing list