Skip to content

Commit 08634ec

Browse files
rmacnak-googleCommit Queue
rmacnak-google
authored and
Commit Queue
committed
[vm] Remove thread time from the VM-internal recorders.
Querying the thread clock takes the overwhelming majority of time when using the VM-internal recorders (ring, startup, endless, file). Including the thread clocks in the timeline allowed visualizing roughly how much an event got scheduled out, but not when. This is a high price to pay for such fuzzy information. Precise scheduling information is available from Fuchsia tracing, systrace or Signposts. ``` import "dart:developer"; main() { var n = 1000000; var watch = new Stopwatch()..start(); for (var i = 0; i < n; i++) { Timeline.timeSync("EventName", () {}); } print("${watch.elapsedMicroseconds.toDouble() / n} us/event"); } ``` --timeline_recorder=ring 2.751822 -> 0.487936 us/event (5.64x) --timeline_recorder=systrace 0.440439 -> 0.435997 us/event TEST=ci Bug: flutter/flutter#121372 Change-Id: Ib6d625f28384a4e87df2a3305483f0f6facd08ff Reviewed-on: https://dart-review.googlesource.com/c/sdk/+/286661 Commit-Queue: Ryan Macnak <[email protected]> Reviewed-by: Ben Konyi <[email protected]> Reviewed-by: Siva Annamalai <[email protected]>
1 parent cbb4881 commit 08634ec

9 files changed

Lines changed: 15 additions & 131 deletions

File tree

‎runtime/vm/os.h‎

Lines changed: 0 additions & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -61,10 +61,6 @@ class OS {
6161
// If the tracing/timeline configuration on takes timestamps as input, returns
6262
// the same value as |GetCurrentMonotonicMicros|. Otherwise, returns -1.
6363
static int64_t GetCurrentMonotonicMicrosForTimeline();
64-
// If the tracing/timeline configuration on the current OS supports thread
65-
// timestamps, returns the same value as |GetCurrentThreadCPUMicros|.
66-
// Otherwise, returns -1.
67-
static int64_t GetCurrentThreadCPUMicrosForTimeline();
6864

6965
// Returns the activation frame alignment constraint or one if
7066
// the platform doesn't care. Guaranteed to be a power of two.

‎runtime/vm/os_android.cc‎

Lines changed: 0 additions & 9 deletions
Original file line numberDiff line numberDiff line change
@@ -175,15 +175,6 @@ int64_t OS::GetCurrentMonotonicMicrosForTimeline() {
175175
#endif
176176
}
177177

178-
int64_t OS::GetCurrentThreadCPUMicrosForTimeline() {
179-
#if defined(SUPPORT_TIMELINE)
180-
if (Timeline::recorder_discards_clock_values()) return -1;
181-
return OS::GetCurrentThreadCPUMicros();
182-
#else
183-
return -1;
184-
#endif
185-
}
186-
187178
// TODO(5411554): May need to hoist these architecture dependent code
188179
// into a architecture specific file e.g: os_ia32_linux.cc
189180
intptr_t OS::ActivationFrameAlignment() {

‎runtime/vm/os_fuchsia.cc‎

Lines changed: 0 additions & 7 deletions
Original file line numberDiff line numberDiff line change
@@ -449,13 +449,6 @@ int64_t OS::GetCurrentMonotonicMicrosForTimeline() {
449449
#endif
450450
}
451451

452-
// On Fuchsia, thread timestamp values are not used in the tracing/timeline
453-
// integration. Because of this, we try to avoid querying them, since doing so
454-
// has both a runtime and trace buffer storage cost.
455-
int64_t OS::GetCurrentThreadCPUMicrosForTimeline() {
456-
return -1;
457-
}
458-
459452
// TODO(5411554): May need to hoist these architecture dependent code
460453
// into a architecture specific file e.g: os_ia32_fuchsia.cc
461454
intptr_t OS::ActivationFrameAlignment() {

‎runtime/vm/os_linux.cc‎

Lines changed: 0 additions & 8 deletions
Original file line numberDiff line numberDiff line change
@@ -494,14 +494,6 @@ int64_t OS::GetCurrentMonotonicMicrosForTimeline() {
494494
#endif
495495
}
496496

497-
int64_t OS::GetCurrentThreadCPUMicrosForTimeline() {
498-
#if defined(SUPPORT_TIMELINE)
499-
if (Timeline::recorder_discards_clock_values()) return -1;
500-
return OS::GetCurrentThreadCPUMicros();
501-
#else
502-
return -1;
503-
#endif
504-
}
505497
// TODO(5411554): May need to hoist these architecture dependent code
506498
// into a architecture specific file e.g: os_ia32_linux.cc
507499
intptr_t OS::ActivationFrameAlignment() {

‎runtime/vm/os_macos.cc‎

Lines changed: 0 additions & 9 deletions
Original file line numberDiff line numberDiff line change
@@ -121,15 +121,6 @@ int64_t OS::GetCurrentMonotonicMicrosForTimeline() {
121121
#endif
122122
}
123123

124-
int64_t OS::GetCurrentThreadCPUMicrosForTimeline() {
125-
#if defined(SUPPORT_TIMELINE)
126-
if (Timeline::recorder_discards_clock_values()) return -1;
127-
return OS::GetCurrentThreadCPUMicros();
128-
#else
129-
return -1;
130-
#endif
131-
}
132-
133124
intptr_t OS::ActivationFrameAlignment() {
134125
#if DART_HOST_OS_IOS
135126
#if TARGET_ARCH_ARM

‎runtime/vm/os_win.cc‎

Lines changed: 0 additions & 8 deletions
Original file line numberDiff line numberDiff line change
@@ -171,14 +171,6 @@ int64_t OS::GetCurrentMonotonicMicrosForTimeline() {
171171
#endif
172172
}
173173

174-
int64_t OS::GetCurrentThreadCPUMicrosForTimeline() {
175-
#if defined(SUPPORT_TIMELINE)
176-
return OS::GetCurrentThreadCPUMicros();
177-
#else
178-
return -1;
179-
#endif
180-
}
181-
182174
intptr_t OS::ActivationFrameAlignment() {
183175
#if defined(TARGET_ARCH_ARM64)
184176
return 16;

‎runtime/vm/timeline.cc‎

Lines changed: 7 additions & 52 deletions
Original file line numberDiff line numberDiff line change
@@ -465,8 +465,6 @@ TIMELINE_STREAM_LIST(TIMELINE_STREAM_DEFINE)
465465
TimelineEvent::TimelineEvent()
466466
: timestamp0_(0),
467467
timestamp1_(0),
468-
thread_timestamp0_(-1),
469-
thread_timestamp1_(-1),
470468
state_(0),
471469
label_(NULL),
472470
stream_(NULL),
@@ -521,18 +519,14 @@ void TimelineEvent::AsyncEnd(const char* label,
521519
set_timestamp1(async_id);
522520
}
523521

524-
void TimelineEvent::DurationBegin(const char* label,
525-
int64_t micros,
526-
int64_t thread_micros) {
522+
void TimelineEvent::DurationBegin(const char* label, int64_t micros) {
527523
Init(kDuration, label);
528524
set_timestamp0(micros);
529-
set_thread_timestamp0(thread_micros);
530525
}
531526

532-
void TimelineEvent::DurationEnd(int64_t micros, int64_t thread_micros) {
527+
void TimelineEvent::DurationEnd(int64_t micros) {
533528
ASSERT(timestamp1_ == 0);
534529
set_timestamp1(micros);
535-
set_thread_timestamp1(thread_micros);
536530
}
537531

538532
void TimelineEvent::Instant(const char* label, int64_t micros) {
@@ -542,34 +536,22 @@ void TimelineEvent::Instant(const char* label, int64_t micros) {
542536

543537
void TimelineEvent::Duration(const char* label,
544538
int64_t start_micros,
545-
int64_t end_micros,
546-
int64_t thread_start_micros,
547-
int64_t thread_end_micros) {
539+
int64_t end_micros) {
548540
Init(kDuration, label);
549541
set_timestamp0(start_micros);
550542
set_timestamp1(end_micros);
551-
set_thread_timestamp0(thread_start_micros);
552-
set_thread_timestamp1(thread_end_micros);
553543
}
554544

555-
void TimelineEvent::Begin(const char* label,
556-
int64_t id,
557-
int64_t micros,
558-
int64_t thread_micros) {
545+
void TimelineEvent::Begin(const char* label, int64_t id, int64_t micros) {
559546
Init(kBegin, label);
560547
set_timestamp0(micros);
561-
set_thread_timestamp0(thread_micros);
562548
// Overload timestamp1_ with the async_id.
563549
set_timestamp1(id);
564550
}
565551

566-
void TimelineEvent::End(const char* label,
567-
int64_t id,
568-
int64_t micros,
569-
int64_t thread_micros) {
552+
void TimelineEvent::End(const char* label, int64_t id, int64_t micros) {
570553
Init(kEnd, label);
571554
set_timestamp0(micros);
572-
set_thread_timestamp0(thread_micros);
573555
// Overload timestamp1_ with the async_id.
574556
set_timestamp1(id);
575557
}
@@ -641,8 +623,6 @@ void TimelineEvent::Init(EventType event_type, const char* label) {
641623
state_ = 0;
642624
timestamp0_ = 0;
643625
timestamp1_ = 0;
644-
thread_timestamp0_ = -1;
645-
thread_timestamp1_ = -1;
646626
OSThread* os_thread = OSThread::Current();
647627
ASSERT(os_thread != NULL);
648628
thread_ = os_thread->trace_id();
@@ -694,9 +674,6 @@ void TimelineEvent::PrintJSON(JSONWriter* writer) const {
694674
writer->PrintProperty64("tid", tid);
695675
writer->PrintProperty64("pid", pid);
696676
writer->PrintProperty64("ts", TimeOrigin());
697-
if (HasThreadCPUTime()) {
698-
writer->PrintProperty64("tts", ThreadCPUTimeOrigin());
699-
}
700677
switch (event_type()) {
701678
case kBegin: {
702679
writer->PrintProperty("ph", "B");
@@ -707,9 +684,6 @@ void TimelineEvent::PrintJSON(JSONWriter* writer) const {
707684
case kDuration: {
708685
writer->PrintProperty("ph", "X");
709686
writer->PrintProperty64("dur", TimeDuration());
710-
if (HasThreadCPUTime()) {
711-
writer->PrintProperty64("tdur", ThreadCPUTimeDuration());
712-
}
713687
} break;
714688
case kInstant: {
715689
writer->PrintProperty("ph", "i");
@@ -810,24 +784,6 @@ int64_t TimelineEvent::TimeDuration() const {
810784
return timestamp1_ - timestamp0_;
811785
}
812786

813-
bool TimelineEvent::HasThreadCPUTime() const {
814-
return (thread_timestamp0_ != -1);
815-
}
816-
817-
int64_t TimelineEvent::ThreadCPUTimeOrigin() const {
818-
ASSERT(HasThreadCPUTime());
819-
return thread_timestamp0_;
820-
}
821-
822-
int64_t TimelineEvent::ThreadCPUTimeDuration() const {
823-
ASSERT(HasThreadCPUTime());
824-
if (thread_timestamp1_ == -1) {
825-
// This duration is still open, use current time as end.
826-
return OS::GetCurrentThreadCPUMicros() - thread_timestamp0_;
827-
}
828-
return thread_timestamp1_ - thread_timestamp0_;
829-
}
830-
831787
bool TimelineEvent::HasIsolateId() const {
832788
return isolate_id_ != ILLEGAL_ISOLATE_ID;
833789
}
@@ -1907,7 +1863,6 @@ void DartTimelineEventHelpers::ReportTaskEvent(TimelineEvent* event,
19071863
char* name,
19081864
char* args) {
19091865
const int64_t start = OS::GetCurrentMonotonicMicrosForTimeline();
1910-
const int64_t start_cpu = OS::GetCurrentThreadCPUMicrosForTimeline();
19111866
switch (static_cast<TimelineEvent::EventType>(type)) {
19121867
case TimelineEvent::kAsyncInstant:
19131868
event->AsyncInstant(name, id, start);
@@ -1919,10 +1874,10 @@ void DartTimelineEventHelpers::ReportTaskEvent(TimelineEvent* event,
19191874
event->AsyncEnd(name, id, start);
19201875
break;
19211876
case TimelineEvent::kBegin:
1922-
event->Begin(name, id, start, start_cpu);
1877+
event->Begin(name, id, start);
19231878
break;
19241879
case TimelineEvent::kEnd:
1925-
event->End(name, id, start, start_cpu);
1880+
event->End(name, id, start);
19261881
break;
19271882
case TimelineEvent::kFlowBegin:
19281883
event->FlowBegin(name, id, start);

‎runtime/vm/timeline.h‎

Lines changed: 7 additions & 33 deletions
Original file line numberDiff line numberDiff line change
@@ -341,31 +341,21 @@ class TimelineEvent {
341341

342342
void DurationBegin(
343343
const char* label,
344-
int64_t micros = OS::GetCurrentMonotonicMicrosForTimeline(),
345-
int64_t thread_micros = OS::GetCurrentThreadCPUMicrosForTimeline());
346-
void DurationEnd(
347-
int64_t micros = OS::GetCurrentMonotonicMicrosForTimeline(),
348-
int64_t thread_micros = OS::GetCurrentThreadCPUMicrosForTimeline());
344+
int64_t micros = OS::GetCurrentMonotonicMicrosForTimeline());
345+
void DurationEnd(int64_t micros = OS::GetCurrentMonotonicMicrosForTimeline());
349346

350347
void Instant(const char* label,
351348
int64_t micros = OS::GetCurrentMonotonicMicrosForTimeline());
352349

353-
void Duration(const char* label,
354-
int64_t start_micros,
355-
int64_t end_micros,
356-
int64_t thread_start_micros = -1,
357-
int64_t thread_end_micros = -1);
350+
void Duration(const char* label, int64_t start_micros, int64_t end_micros);
358351

359-
void Begin(
360-
const char* label,
361-
int64_t id,
362-
int64_t micros = OS::GetCurrentMonotonicMicrosForTimeline(),
363-
int64_t thread_micros = OS::GetCurrentThreadCPUMicrosForTimeline());
352+
void Begin(const char* label,
353+
int64_t id,
354+
int64_t micros = OS::GetCurrentMonotonicMicrosForTimeline());
364355

365356
void End(const char* label,
366357
int64_t id,
367-
int64_t micros = OS::GetCurrentMonotonicMicrosForTimeline(),
368-
int64_t thread_micros = OS::GetCurrentThreadCPUMicrosForTimeline());
358+
int64_t micros = OS::GetCurrentMonotonicMicrosForTimeline());
369359

370360
void Counter(const char* label,
371361
int64_t micros = OS::GetCurrentMonotonicMicrosForTimeline());
@@ -414,10 +404,6 @@ class TimelineEvent {
414404
return (event_type() == kDuration) && (timestamp1_ > timestamp0_);
415405
}
416406

417-
bool HasThreadCPUTime() const;
418-
int64_t ThreadCPUTimeDuration() const;
419-
int64_t ThreadCPUTimeOrigin() const;
420-
421407
int64_t TimeOrigin() const { return timestamp0_; }
422408
int64_t Id() const {
423409
ASSERT(event_type() != kDuration);
@@ -536,16 +522,6 @@ class TimelineEvent {
536522
timestamp1_ = value;
537523
}
538524

539-
void set_thread_timestamp0(int64_t value) {
540-
ASSERT(thread_timestamp0_ == -1);
541-
thread_timestamp0_ = value;
542-
}
543-
544-
void set_thread_timestamp1(int64_t value) {
545-
ASSERT(thread_timestamp1_ == -1);
546-
thread_timestamp1_ = value;
547-
}
548-
549525
bool pre_serialized_args() const {
550526
return PreSerializedArgsBit::decode(state_);
551527
}
@@ -570,8 +546,6 @@ class TimelineEvent {
570546

571547
int64_t timestamp0_;
572548
int64_t timestamp1_;
573-
int64_t thread_timestamp0_;
574-
int64_t thread_timestamp1_;
575549
TimelineEventArguments arguments_;
576550
uword state_;
577551
const char* label_;

‎runtime/vm/timeline_test.cc‎

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -205,7 +205,7 @@ TEST_CASE(TimelineEventPrintSystrace) {
205205

206206
// Test a duration event. This event kind is not supported so we should
207207
// serialize it to an empty string.
208-
event.Duration("DUR", 0, 1, 2, 3);
208+
event.Duration("DUR", 0, 1);
209209
TimelineEventSystraceRecorder::PrintSystrace(&event, &buffer[0],
210210
kBufferLength);
211211
EXPECT_STREQ("", buffer);

0 commit comments

Comments
 (0)