AuroraMiddleware/v8
1
0
Fork 0
Code Issues 2 Pull Requests Releases Wiki Activity

[cpu-profile] Timestamps in tracing events args stay in monotonic time

Browse Source 
On Linux, Perfetto translates the builtin "ts" timestamp in trace event
from CLOCK_MONOTONIC to CLOCK_BOOTTIME, before passing them to devtools.
Devtools therefore implicitly operates on timestamps that are in
CLOCK_BOOTTIME.

However, additional timestamps sent in trace event payload arguments
will not be converted to CLOCK_BOOTTIME by Perfetto, raising the
possibility of devtools using timestamps from multiple clock domains
incorrectly.

Since trace events sent by CpuProfile also include the builtin "ts"
trace timestamp (sampled from CLOCK_MONOTONIC nearly at the same time by
the tracing framework), sending "data.startTime" and "data.endTime" is
essentially redundant. devtools-frontend:2113957 stops the use of the
value of these timestamps in the payload of Profile and ProfileChunk
events. Devtools continue to use the presence of these arguments to
indentify start and end profile events.

ProfileChunk events also include "timeDeltas" which are relative
timestamps. They are also in CLOCK_MONOTONIC and are not translated by
Perfetto. devtools-frontend:2113957 computes absolute CLOCK_BOOTTIME
timestamps from timeDeltas by adding them to "ts" in the "Profile" event
(previously, "data.startTime" was used). This is only valid if the
system is not suspended/resumed during profiling. Providing support for
suspend/resume in the middle of profiling will likely involve having
Perfetto convert "timeDeltas" directly to CLOCK_BOOTTIME.

This CL introduces no code changes and only adds comments to explain
the above.

BUG=chromium:1055871

Change-Id: I649dfcce8ea1a100c0ecfe03f843c7cb1fdd6f33
Reviewed-on: https://chromium-review.googlesource.com/c/v8/v8/+/2114001
Commit-Queue: Peter Marshall <petermarshall@chromium.org>
Reviewed-by: Peter Marshall <petermarshall@chromium.org>
Cr-Commit-Position: refs/heads/master@{#66820}
This commit is contained in:
Eric Rannaud 2020-03-20 23:49:03 -07:00 committed by Commit Bot
parent 2d8ca349f8
commit 668aafb56c
2 changed files with 22 additions and 0 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

1
AUTHORS
View File

@ -83,6 +83,7 @@ Deon Dior <diaoyuanjie@gmail.com>
Dominic Farolini <domfarolino@gmail.com>
Douglas Crosher <dtc-v8@scieneer.com>
Dusan Milosavljevic <dusan.m.milosavljevic@gmail.com>
Eric Rannaud <eric.rannaud@gmail.com>
Erich Ocean <erich.ocean@me.com>
Evan Lucas <evan.lucas@help.com>
Fedor Indutny <fedor@indutny.com>

21
src/profiler/profile-generator.cc
View File

@ -492,6 +492,11 @@ CpuProfile::CpuProfile(CpuProfiler* profiler, const char* title,
profiler_(profiler),
streaming_next_sample_(0),
id_(++last_id_) {
// The startTime timestamp is not converted to Perfetto's clock domain and
// will get out of sync with other timestamps Perfetto knows about, including
// the automatic trace event "ts" timestamp. startTime is included for
// backward compatibility with the tracing protocol but the value of "ts"
// should be used instead (it is recorded nearly immediately after).
auto value = TracedValue::Create();
value->SetDouble("startTime", start_time_.since_origin().InMicroseconds());
TRACE_EVENT_SAMPLE_WITH_ID1(TRACE_DISABLED_BY_DEFAULT("v8.cpu_profiler"),
@ -601,6 +606,16 @@ void CpuProfile::StreamPendingTraceEvents() {
value->EndDictionary();
}
if (streaming_next_sample_ != samples_.size()) {
// timeDeltas are computed within CLOCK_MONOTONIC. However, trace event
// "ts" timestamps are converted to CLOCK_BOOTTIME by Perfetto. To get
// absolute timestamps in CLOCK_BOOTTIME from timeDeltas, add them to
// the "ts" timestamp from the initial "Profile" trace event sent by
// CpuProfile::CpuProfile().
//
// Note that if the system is suspended and resumed while samples_ is
// captured, timeDeltas derived after resume will not be convertible to
// correct CLOCK_BOOTTIME time values (for instance, producing
// CLOCK_BOOTTIME time values in the middle of the suspended period).
value->BeginArray("timeDeltas");
base::TimeTicks lastTimestamp =
streaming_next_sample_ ? samples_[streaming_next_sample_ - 1].timestamp
@ -634,6 +649,12 @@ void CpuProfile::FinishProfile() {
context_filter_ = nullptr;
StreamPendingTraceEvents();
auto value = TracedValue::Create();
// The endTime timestamp is not converted to Perfetto's clock domain and will
// get out of sync with other timestamps Perfetto knows about, including the
// automatic trace event "ts" timestamp. endTime is included for backward
// compatibility with the tracing protocol: its presence in "data" is used by
// devtools to identify the last ProfileChunk but the value of "ts" should be
// used instead (it is recorded nearly immediately after).
value->SetDouble("endTime", end_time_.since_origin().InMicroseconds());
TRACE_EVENT_SAMPLE_WITH_ID1(TRACE_DISABLED_BY_DEFAULT("v8.cpu_profiler"),
"ProfileChunk", id_, "data", std::move(value));