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

[Sergej Jaskiewicz via Phabricator via cfe-commits]

This revision was automatically updated to reflect the committed changes.
Closed by commit rG2899103108d3: [TimeProfiler] Emit clock synchronization 
point (authored by broadwaylamb).

Changed prior to commit:
  https://reviews.llvm.org/D78030?vs=258061=259413#toc

Repository:
  rG LLVM Github Monorepo

CHANGES SINCE LAST ACTION
  https://reviews.llvm.org/D78030/new/

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
@@ -75,9 +75,9 @@
 
 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 @@
 
 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;
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,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 {
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,22 @@
 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"] / 100
+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!")

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

[Sergej Jaskiewicz via Phabricator via cfe-commits]

broadwaylamb added a comment.

@russell.gallop thanks! I'll address your comments and commit the change.


CHANGES SINCE LAST ACTION
  https://reviews.llvm.org/D78030/new/

https://reviews.llvm.org/D78030



___
cfe-commits mailing list
cfe-commits@lists.llvm.org
https://lists.llvm.org/cgi-bin/mailman/listinfo/cfe-commits

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

[Russell Gallop via Phabricator via cfe-commits]

russell.gallop accepted this revision.
russell.gallop added a comment.

LGTM, with a few small comments.

For the record, I wondered whether the time profiler could emit all ts as 
absolute, so I tried it out. This has two problems. 1). The "Total" numbers 
also need adjusting to be at the beginning of the trace time rather than zero, 
which feels a little odd, and it hard to see how long things are on the time 
scale. 2). All of the times end up being very large numbers so this bloats 
traces considerably.




Comment at: clang/test/Driver/check-time-trace-sections.py:23
+
+# Make sure that the 'beginningOfTime' is not earlier than 10 seconds ago.
+if seconds_since_epoch - beginning_of_time > 10:

Could also check that beginningOfTime isn't after seconds_since_epoch.



Comment at: llvm/lib/Support/TimeProfiler.cpp:78
   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()),

Note that this will record BeginningOfTime for each TimeTraceProfiler started 
on a thread, but that won't be used. This shouldn't cause any harm  and I don't 
think that is very frequent so I think that this is okay.



Comment at: llvm/lib/Support/TimeProfiler.cpp:238
+
+// Emit the absolute time of the moment when this TimeProfiler started
+// measurements. This can be used to combine the profiling data from

Nit. This is a bit wordy. How about "Emit the absolute time when this 
TimeProfiler started."?


CHANGES SINCE LAST ACTION
  https://reviews.llvm.org/D78030/new/

https://reviews.llvm.org/D78030



___
cfe-commits mailing list
cfe-commits@lists.llvm.org
https://lists.llvm.org/cgi-bin/mailman/listinfo/cfe-commits

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

[Sergej Jaskiewicz via Phabricator via cfe-commits]

broadwaylamb added a comment.

ping


CHANGES SINCE LAST ACTION
  https://reviews.llvm.org/D78030/new/

https://reviews.llvm.org/D78030



___
cfe-commits mailing list
cfe-commits@lists.llvm.org
https://lists.llvm.org/cgi-bin/mailman/listinfo/cfe-commits

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

[Sergej Jaskiewicz via Phabricator via cfe-commits]

broadwaylamb added a comment.

Since we're adding a new attribute here that we won't ever be able to remove in 
the future, I'd still like to get a LGTM from some of the folks that are 
familiar with the time profiler. @russell.gallop @anton-afanasyev?


CHANGES SINCE LAST ACTION
  https://reviews.llvm.org/D78030/new/

https://reviews.llvm.org/D78030



___
cfe-commits mailing list
cfe-commits@lists.llvm.org
https://lists.llvm.org/cgi-bin/mailman/listinfo/cfe-commits

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

[Sergej Jaskiewicz via Phabricator via cfe-commits]

broadwaylamb updated this revision to Diff 258061.
broadwaylamb added a comment.

A simpler generation of the beginning of time.


CHANGES SINCE LAST ACTION
  https://reviews.llvm.org/D78030/new/

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
@@ -75,9 +75,9 @@
 
 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 @@
 
 J.arrayEnd();
 J.attributeEnd();
+
+// Emit the absolute time of the moment when this TimeProfiler started
+// measurements. 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;
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,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 {
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"] / 100
+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

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

[Sergej Jaskiewicz via Phabricator via cfe-commits]

broadwaylamb marked an inline comment as done.
broadwaylamb added inline comments.



Comment at: llvm/lib/Support/TimeProfiler.cpp:266
+  const auto BeginningOfTimeUs = SystemTime - ProcessLocalTime;
+  J.attribute("beginningOfTime",
+  BeginningOfTimeUs.time_since_epoch().count());

MaskRay wrote:
> broadwaylamb wrote:
> > broadwaylamb wrote:
> > > MaskRay wrote:
> > > > What is the logic here?
> > > > 
> > > > Two events in the same process may have different `beginningOfTime`. Is 
> > > > that intended?
> > > > 
> > > > Noe that `system_clock::now()` and `steady_clock::now()` are not 
> > > > measured at the same time.
> > > >Two events in the same process may have different beginningOfTime. Is 
> > > >that intended?
> > > 
> > > How would that be possible? We only compute `beginningOfTime` when 
> > > writing the data of the time profiler to a JSON file. AFAICT it happens 
> > > only once. So, this code is only called once.
> > > 
> > > >Noe that system_clock::now() and steady_clock::now() are not measured at 
> > > >the same time.
> > > I understand. But the difference should be very small (certainly less 
> > > than a microsecond), since there are only a few arithmetic operations in 
> > > between.
> > Although we could set the beginning of time in `TimeProfiler`'s constructor 
> > and assign it to a field. That would be a lot simpler, I guess. What do you 
> > think?
> OK, but I am still confused by the logic and the comment. Does the code just 
> want to compute the start time in system_clock?
Exactly, yes.


Repository:
  rG LLVM Github Monorepo

CHANGES SINCE LAST ACTION
  https://reviews.llvm.org/D78030/new/

https://reviews.llvm.org/D78030



___
cfe-commits mailing list
cfe-commits@lists.llvm.org
https://lists.llvm.org/cgi-bin/mailman/listinfo/cfe-commits

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

[Fangrui Song via Phabricator via cfe-commits]

MaskRay added inline comments.



Comment at: llvm/lib/Support/TimeProfiler.cpp:266
+  const auto BeginningOfTimeUs = SystemTime - ProcessLocalTime;
+  J.attribute("beginningOfTime",
+  BeginningOfTimeUs.time_since_epoch().count());

broadwaylamb wrote:
> broadwaylamb wrote:
> > MaskRay wrote:
> > > What is the logic here?
> > > 
> > > Two events in the same process may have different `beginningOfTime`. Is 
> > > that intended?
> > > 
> > > Noe that `system_clock::now()` and `steady_clock::now()` are not measured 
> > > at the same time.
> > >Two events in the same process may have different beginningOfTime. Is that 
> > >intended?
> > 
> > How would that be possible? We only compute `beginningOfTime` when writing 
> > the data of the time profiler to a JSON file. AFAICT it happens only once. 
> > So, this code is only called once.
> > 
> > >Noe that system_clock::now() and steady_clock::now() are not measured at 
> > >the same time.
> > I understand. But the difference should be very small (certainly less than 
> > a microsecond), since there are only a few arithmetic operations in between.
> Although we could set the beginning of time in `TimeProfiler`'s constructor 
> and assign it to a field. That would be a lot simpler, I guess. What do you 
> think?
OK, but I am still confused by the logic and the comment. Does the code just 
want to compute the start time in system_clock?


Repository:
  rG LLVM Github Monorepo

CHANGES SINCE LAST ACTION
  https://reviews.llvm.org/D78030/new/

https://reviews.llvm.org/D78030



___
cfe-commits mailing list
cfe-commits@lists.llvm.org
https://lists.llvm.org/cgi-bin/mailman/listinfo/cfe-commits

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

[Sergej Jaskiewicz via Phabricator via cfe-commits]

broadwaylamb marked an inline comment as done.
broadwaylamb added inline comments.



Comment at: llvm/lib/Support/TimeProfiler.cpp:266
+  const auto BeginningOfTimeUs = SystemTime - ProcessLocalTime;
+  J.attribute("beginningOfTime",
+  BeginningOfTimeUs.time_since_epoch().count());

broadwaylamb wrote:
> MaskRay wrote:
> > What is the logic here?
> > 
> > Two events in the same process may have different `beginningOfTime`. Is 
> > that intended?
> > 
> > Noe that `system_clock::now()` and `steady_clock::now()` are not measured 
> > at the same time.
> >Two events in the same process may have different beginningOfTime. Is that 
> >intended?
> 
> How would that be possible? We only compute `beginningOfTime` when writing 
> the data of the time profiler to a JSON file. AFAICT it happens only once. 
> So, this code is only called once.
> 
> >Noe that system_clock::now() and steady_clock::now() are not measured at the 
> >same time.
> I understand. But the difference should be very small (certainly less than a 
> microsecond), since there are only a few arithmetic operations in between.
Although we could set the beginning of time in `TimeProfiler`'s constructor and 
assign it to a field. That would be a lot simpler, I guess. What do you think?


Repository:
  rG LLVM Github Monorepo

CHANGES SINCE LAST ACTION
  https://reviews.llvm.org/D78030/new/

https://reviews.llvm.org/D78030



___
cfe-commits mailing list
cfe-commits@lists.llvm.org
https://lists.llvm.org/cgi-bin/mailman/listinfo/cfe-commits

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

[Sergej Jaskiewicz via Phabricator via cfe-commits]

broadwaylamb marked an inline comment as done.
broadwaylamb added inline comments.



Comment at: llvm/lib/Support/TimeProfiler.cpp:266
+  const auto BeginningOfTimeUs = SystemTime - ProcessLocalTime;
+  J.attribute("beginningOfTime",
+  BeginningOfTimeUs.time_since_epoch().count());

MaskRay wrote:
> What is the logic here?
> 
> Two events in the same process may have different `beginningOfTime`. Is that 
> intended?
> 
> Noe that `system_clock::now()` and `steady_clock::now()` are not measured at 
> the same time.
>Two events in the same process may have different beginningOfTime. Is that 
>intended?

How would that be possible? We only compute `beginningOfTime` when writing the 
data of the time profiler to a JSON file. AFAICT it happens only once. So, this 
code is only called once.

>Noe that system_clock::now() and steady_clock::now() are not measured at the 
>same time.
I understand. But the difference should be very small (certainly less than a 
microsecond), since there are only a few arithmetic operations in between.


Repository:
  rG LLVM Github Monorepo

CHANGES SINCE LAST ACTION
  https://reviews.llvm.org/D78030/new/

https://reviews.llvm.org/D78030



___
cfe-commits mailing list
cfe-commits@lists.llvm.org
https://lists.llvm.org/cgi-bin/mailman/listinfo/cfe-commits

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

[Fangrui Song via Phabricator via cfe-commits]

MaskRay added inline comments.



Comment at: llvm/lib/Support/TimeProfiler.cpp:266
+  const auto BeginningOfTimeUs = SystemTime - ProcessLocalTime;
+  J.attribute("beginningOfTime",
+  BeginningOfTimeUs.time_since_epoch().count());

What is the logic here?

Two events in the same process may have different `beginningOfTime`. Is that 
intended?

Noe that `system_clock::now()` and `steady_clock::now()` are not measured at 
the same time.


Repository:
  rG LLVM Github Monorepo

CHANGES SINCE LAST ACTION
  https://reviews.llvm.org/D78030/new/

https://reviews.llvm.org/D78030



___
cfe-commits mailing list
cfe-commits@lists.llvm.org
https://lists.llvm.org/cgi-bin/mailman/listinfo/cfe-commits

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

[Sergej Jaskiewicz via Phabricator via cfe-commits]

broadwaylamb marked an inline comment as done.
broadwaylamb added a comment.

It'd be good if I had one more LGTM.


Repository:
  rG LLVM Github Monorepo

CHANGES SINCE LAST ACTION
  https://reviews.llvm.org/D78030/new/

https://reviews.llvm.org/D78030



___
cfe-commits mailing list
cfe-commits@lists.llvm.org
https://lists.llvm.org/cgi-bin/mailman/listinfo/cfe-commits

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

[Sergej Jaskiewicz via Phabricator via cfe-commits]

broadwaylamb updated this revision to Diff 257340.
broadwaylamb added a comment.

Indent patterns in tests


Repository:
  rG LLVM Github Monorepo

CHANGES SINCE LAST ACTION
  https://reviews.llvm.org/D78030/new/

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
@@ -252,6 +252,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(system_clock::now());
+  const microseconds ProcessLocalTime =
+  time_point_cast(steady_clock::now()) -
+  time_point_cast(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,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 {
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"] / 100
+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

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

[Fangrui Song via Phabricator via cfe-commits]

MaskRay added inline comments.



Comment at: lld/test/ELF/time-trace.s:21
 
-# CHECK: "traceEvents": [
+# CHECK: "beginningOfTime": {{[0-9]{16},}}
+# CHECK-NEXT: "traceEvents": [

Add 5 spaces after `:` so that the key is aligned


Repository:
  rG LLVM Github Monorepo

CHANGES SINCE LAST ACTION
  https://reviews.llvm.org/D78030/new/

https://reviews.llvm.org/D78030



___
cfe-commits mailing list
cfe-commits@lists.llvm.org
https://lists.llvm.org/cgi-bin/mailman/listinfo/cfe-commits

[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  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 



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(system_clock::now());
+  const microseconds ProcessLocalTime =
+  time_point_cast(steady_clock::now()) -
+  time_point_cast(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"] / 100
+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])