From 2899103108d38215af8aae377cd0e54794278209 Mon Sep 17 00:00:00 2001 From: Sergej Jaskiewicz Date: Thu, 16 Apr 2020 17:37:25 +0300 Subject: [PATCH] [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 --- clang/test/Driver/check-time-trace-sections.py | 15 +++++++++++++-- clang/test/Driver/check-time-trace.cpp | 17 +++++++++-------- lld/test/ELF/time-trace.s | 3 ++- llvm/lib/Support/TimeProfiler.cpp | 16 +++++++++++++--- 4 files changed, 37 insertions(+), 14 deletions(-) diff --git a/clang/test/Driver/check-time-trace-sections.py b/clang/test/Driver/check-time-trace-sections.py index 7b59853..7551e5c 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 1484462..1d80748 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 struct Struct { diff --git a/lld/test/ELF/time-trace.s b/lld/test/ELF/time-trace.s index 8085a25..e1da4c4 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 c907c1a..93bf6f5 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(BeginningOfTime) + .time_since_epoch() + .count()); + J.objectEnd(); } SmallVector Stack; SmallVector Entries; StringMap CountAndTotalPerName; + const time_point BeginningOfTime; const TimePointType StartTime; const std::string ProcName; const sys::Process::Pid Pid; -- 2.7.4