From 08634ec4ee3efb2b574d8da22bae58ead0d5be62 Mon Sep 17 00:00:00 2001 From: Ryan Macnak Date: Fri, 3 Mar 2023 19:05:28 +0000 Subject: [PATCH] [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: https://github.com/flutter/flutter/issues/121372 Change-Id: Ib6d625f28384a4e87df2a3305483f0f6facd08ff Reviewed-on: https://dart-review.googlesource.com/c/sdk/+/286661 Commit-Queue: Ryan Macnak Reviewed-by: Ben Konyi Reviewed-by: Siva Annamalai --- runtime/vm/os.h | 4 --- runtime/vm/os_android.cc | 9 ------ runtime/vm/os_fuchsia.cc | 7 ----- runtime/vm/os_linux.cc | 8 ----- runtime/vm/os_macos.cc | 9 ------ runtime/vm/os_win.cc | 8 ----- runtime/vm/timeline.cc | 59 +++++-------------------------------- runtime/vm/timeline.h | 40 +++++-------------------- runtime/vm/timeline_test.cc | 2 +- 9 files changed, 15 insertions(+), 131 deletions(-) diff --git a/runtime/vm/os.h b/runtime/vm/os.h index c77425412a6..c1653b350a7 100644 --- a/runtime/vm/os.h +++ b/runtime/vm/os.h @@ -61,10 +61,6 @@ class OS { // If the tracing/timeline configuration on takes timestamps as input, returns // the same value as |GetCurrentMonotonicMicros|. Otherwise, returns -1. static int64_t GetCurrentMonotonicMicrosForTimeline(); - // If the tracing/timeline configuration on the current OS supports thread - // timestamps, returns the same value as |GetCurrentThreadCPUMicros|. - // Otherwise, returns -1. - static int64_t GetCurrentThreadCPUMicrosForTimeline(); // Returns the activation frame alignment constraint or one if // the platform doesn't care. Guaranteed to be a power of two. diff --git a/runtime/vm/os_android.cc b/runtime/vm/os_android.cc index 6ee9cd4738a..564e68ec5ec 100644 --- a/runtime/vm/os_android.cc +++ b/runtime/vm/os_android.cc @@ -175,15 +175,6 @@ int64_t OS::GetCurrentMonotonicMicrosForTimeline() { #endif } -int64_t OS::GetCurrentThreadCPUMicrosForTimeline() { -#if defined(SUPPORT_TIMELINE) - if (Timeline::recorder_discards_clock_values()) return -1; - return OS::GetCurrentThreadCPUMicros(); -#else - return -1; -#endif -} - // TODO(5411554): May need to hoist these architecture dependent code // into a architecture specific file e.g: os_ia32_linux.cc intptr_t OS::ActivationFrameAlignment() { diff --git a/runtime/vm/os_fuchsia.cc b/runtime/vm/os_fuchsia.cc index 74191efd2d3..f5b7eff989a 100644 --- a/runtime/vm/os_fuchsia.cc +++ b/runtime/vm/os_fuchsia.cc @@ -449,13 +449,6 @@ int64_t OS::GetCurrentMonotonicMicrosForTimeline() { #endif } -// On Fuchsia, thread timestamp values are not used in the tracing/timeline -// integration. Because of this, we try to avoid querying them, since doing so -// has both a runtime and trace buffer storage cost. -int64_t OS::GetCurrentThreadCPUMicrosForTimeline() { - return -1; -} - // TODO(5411554): May need to hoist these architecture dependent code // into a architecture specific file e.g: os_ia32_fuchsia.cc intptr_t OS::ActivationFrameAlignment() { diff --git a/runtime/vm/os_linux.cc b/runtime/vm/os_linux.cc index 8cb55b7c0cf..ff590cee58a 100644 --- a/runtime/vm/os_linux.cc +++ b/runtime/vm/os_linux.cc @@ -494,14 +494,6 @@ int64_t OS::GetCurrentMonotonicMicrosForTimeline() { #endif } -int64_t OS::GetCurrentThreadCPUMicrosForTimeline() { -#if defined(SUPPORT_TIMELINE) - if (Timeline::recorder_discards_clock_values()) return -1; - return OS::GetCurrentThreadCPUMicros(); -#else - return -1; -#endif -} // TODO(5411554): May need to hoist these architecture dependent code // into a architecture specific file e.g: os_ia32_linux.cc intptr_t OS::ActivationFrameAlignment() { diff --git a/runtime/vm/os_macos.cc b/runtime/vm/os_macos.cc index 390805d9f1d..0dabcc0775c 100644 --- a/runtime/vm/os_macos.cc +++ b/runtime/vm/os_macos.cc @@ -121,15 +121,6 @@ int64_t OS::GetCurrentMonotonicMicrosForTimeline() { #endif } -int64_t OS::GetCurrentThreadCPUMicrosForTimeline() { -#if defined(SUPPORT_TIMELINE) - if (Timeline::recorder_discards_clock_values()) return -1; - return OS::GetCurrentThreadCPUMicros(); -#else - return -1; -#endif -} - intptr_t OS::ActivationFrameAlignment() { #if DART_HOST_OS_IOS #if TARGET_ARCH_ARM diff --git a/runtime/vm/os_win.cc b/runtime/vm/os_win.cc index b6fed58d9c9..9756d91af5a 100644 --- a/runtime/vm/os_win.cc +++ b/runtime/vm/os_win.cc @@ -171,14 +171,6 @@ int64_t OS::GetCurrentMonotonicMicrosForTimeline() { #endif } -int64_t OS::GetCurrentThreadCPUMicrosForTimeline() { -#if defined(SUPPORT_TIMELINE) - return OS::GetCurrentThreadCPUMicros(); -#else - return -1; -#endif -} - intptr_t OS::ActivationFrameAlignment() { #if defined(TARGET_ARCH_ARM64) return 16; diff --git a/runtime/vm/timeline.cc b/runtime/vm/timeline.cc index 11bc2216b0e..dfe58fd14be 100644 --- a/runtime/vm/timeline.cc +++ b/runtime/vm/timeline.cc @@ -465,8 +465,6 @@ TIMELINE_STREAM_LIST(TIMELINE_STREAM_DEFINE) TimelineEvent::TimelineEvent() : timestamp0_(0), timestamp1_(0), - thread_timestamp0_(-1), - thread_timestamp1_(-1), state_(0), label_(NULL), stream_(NULL), @@ -521,18 +519,14 @@ void TimelineEvent::AsyncEnd(const char* label, set_timestamp1(async_id); } -void TimelineEvent::DurationBegin(const char* label, - int64_t micros, - int64_t thread_micros) { +void TimelineEvent::DurationBegin(const char* label, int64_t micros) { Init(kDuration, label); set_timestamp0(micros); - set_thread_timestamp0(thread_micros); } -void TimelineEvent::DurationEnd(int64_t micros, int64_t thread_micros) { +void TimelineEvent::DurationEnd(int64_t micros) { ASSERT(timestamp1_ == 0); set_timestamp1(micros); - set_thread_timestamp1(thread_micros); } void TimelineEvent::Instant(const char* label, int64_t micros) { @@ -542,34 +536,22 @@ void TimelineEvent::Instant(const char* label, int64_t micros) { void TimelineEvent::Duration(const char* label, int64_t start_micros, - int64_t end_micros, - int64_t thread_start_micros, - int64_t thread_end_micros) { + int64_t end_micros) { Init(kDuration, label); set_timestamp0(start_micros); set_timestamp1(end_micros); - set_thread_timestamp0(thread_start_micros); - set_thread_timestamp1(thread_end_micros); } -void TimelineEvent::Begin(const char* label, - int64_t id, - int64_t micros, - int64_t thread_micros) { +void TimelineEvent::Begin(const char* label, int64_t id, int64_t micros) { Init(kBegin, label); set_timestamp0(micros); - set_thread_timestamp0(thread_micros); // Overload timestamp1_ with the async_id. set_timestamp1(id); } -void TimelineEvent::End(const char* label, - int64_t id, - int64_t micros, - int64_t thread_micros) { +void TimelineEvent::End(const char* label, int64_t id, int64_t micros) { Init(kEnd, label); set_timestamp0(micros); - set_thread_timestamp0(thread_micros); // Overload timestamp1_ with the async_id. set_timestamp1(id); } @@ -641,8 +623,6 @@ void TimelineEvent::Init(EventType event_type, const char* label) { state_ = 0; timestamp0_ = 0; timestamp1_ = 0; - thread_timestamp0_ = -1; - thread_timestamp1_ = -1; OSThread* os_thread = OSThread::Current(); ASSERT(os_thread != NULL); thread_ = os_thread->trace_id(); @@ -694,9 +674,6 @@ void TimelineEvent::PrintJSON(JSONWriter* writer) const { writer->PrintProperty64("tid", tid); writer->PrintProperty64("pid", pid); writer->PrintProperty64("ts", TimeOrigin()); - if (HasThreadCPUTime()) { - writer->PrintProperty64("tts", ThreadCPUTimeOrigin()); - } switch (event_type()) { case kBegin: { writer->PrintProperty("ph", "B"); @@ -707,9 +684,6 @@ void TimelineEvent::PrintJSON(JSONWriter* writer) const { case kDuration: { writer->PrintProperty("ph", "X"); writer->PrintProperty64("dur", TimeDuration()); - if (HasThreadCPUTime()) { - writer->PrintProperty64("tdur", ThreadCPUTimeDuration()); - } } break; case kInstant: { writer->PrintProperty("ph", "i"); @@ -810,24 +784,6 @@ int64_t TimelineEvent::TimeDuration() const { return timestamp1_ - timestamp0_; } -bool TimelineEvent::HasThreadCPUTime() const { - return (thread_timestamp0_ != -1); -} - -int64_t TimelineEvent::ThreadCPUTimeOrigin() const { - ASSERT(HasThreadCPUTime()); - return thread_timestamp0_; -} - -int64_t TimelineEvent::ThreadCPUTimeDuration() const { - ASSERT(HasThreadCPUTime()); - if (thread_timestamp1_ == -1) { - // This duration is still open, use current time as end. - return OS::GetCurrentThreadCPUMicros() - thread_timestamp0_; - } - return thread_timestamp1_ - thread_timestamp0_; -} - bool TimelineEvent::HasIsolateId() const { return isolate_id_ != ILLEGAL_ISOLATE_ID; } @@ -1907,7 +1863,6 @@ void DartTimelineEventHelpers::ReportTaskEvent(TimelineEvent* event, char* name, char* args) { const int64_t start = OS::GetCurrentMonotonicMicrosForTimeline(); - const int64_t start_cpu = OS::GetCurrentThreadCPUMicrosForTimeline(); switch (static_cast(type)) { case TimelineEvent::kAsyncInstant: event->AsyncInstant(name, id, start); @@ -1919,10 +1874,10 @@ void DartTimelineEventHelpers::ReportTaskEvent(TimelineEvent* event, event->AsyncEnd(name, id, start); break; case TimelineEvent::kBegin: - event->Begin(name, id, start, start_cpu); + event->Begin(name, id, start); break; case TimelineEvent::kEnd: - event->End(name, id, start, start_cpu); + event->End(name, id, start); break; case TimelineEvent::kFlowBegin: event->FlowBegin(name, id, start); diff --git a/runtime/vm/timeline.h b/runtime/vm/timeline.h index c8945215a7c..2ea818b91a5 100644 --- a/runtime/vm/timeline.h +++ b/runtime/vm/timeline.h @@ -341,31 +341,21 @@ class TimelineEvent { void DurationBegin( const char* label, - int64_t micros = OS::GetCurrentMonotonicMicrosForTimeline(), - int64_t thread_micros = OS::GetCurrentThreadCPUMicrosForTimeline()); - void DurationEnd( - int64_t micros = OS::GetCurrentMonotonicMicrosForTimeline(), - int64_t thread_micros = OS::GetCurrentThreadCPUMicrosForTimeline()); + int64_t micros = OS::GetCurrentMonotonicMicrosForTimeline()); + void DurationEnd(int64_t micros = OS::GetCurrentMonotonicMicrosForTimeline()); void Instant(const char* label, int64_t micros = OS::GetCurrentMonotonicMicrosForTimeline()); - void Duration(const char* label, - int64_t start_micros, - int64_t end_micros, - int64_t thread_start_micros = -1, - int64_t thread_end_micros = -1); + void Duration(const char* label, int64_t start_micros, int64_t end_micros); - void Begin( - const char* label, - int64_t id, - int64_t micros = OS::GetCurrentMonotonicMicrosForTimeline(), - int64_t thread_micros = OS::GetCurrentThreadCPUMicrosForTimeline()); + void Begin(const char* label, + int64_t id, + int64_t micros = OS::GetCurrentMonotonicMicrosForTimeline()); void End(const char* label, int64_t id, - int64_t micros = OS::GetCurrentMonotonicMicrosForTimeline(), - int64_t thread_micros = OS::GetCurrentThreadCPUMicrosForTimeline()); + int64_t micros = OS::GetCurrentMonotonicMicrosForTimeline()); void Counter(const char* label, int64_t micros = OS::GetCurrentMonotonicMicrosForTimeline()); @@ -414,10 +404,6 @@ class TimelineEvent { return (event_type() == kDuration) && (timestamp1_ > timestamp0_); } - bool HasThreadCPUTime() const; - int64_t ThreadCPUTimeDuration() const; - int64_t ThreadCPUTimeOrigin() const; - int64_t TimeOrigin() const { return timestamp0_; } int64_t Id() const { ASSERT(event_type() != kDuration); @@ -536,16 +522,6 @@ class TimelineEvent { timestamp1_ = value; } - void set_thread_timestamp0(int64_t value) { - ASSERT(thread_timestamp0_ == -1); - thread_timestamp0_ = value; - } - - void set_thread_timestamp1(int64_t value) { - ASSERT(thread_timestamp1_ == -1); - thread_timestamp1_ = value; - } - bool pre_serialized_args() const { return PreSerializedArgsBit::decode(state_); } @@ -570,8 +546,6 @@ class TimelineEvent { int64_t timestamp0_; int64_t timestamp1_; - int64_t thread_timestamp0_; - int64_t thread_timestamp1_; TimelineEventArguments arguments_; uword state_; const char* label_; diff --git a/runtime/vm/timeline_test.cc b/runtime/vm/timeline_test.cc index 69a55c9661e..4d0b5ad0c8a 100644 --- a/runtime/vm/timeline_test.cc +++ b/runtime/vm/timeline_test.cc @@ -205,7 +205,7 @@ TEST_CASE(TimelineEventPrintSystrace) { // Test a duration event. This event kind is not supported so we should // serialize it to an empty string. - event.Duration("DUR", 0, 1, 2, 3); + event.Duration("DUR", 0, 1); TimelineEventSystraceRecorder::PrintSystrace(&event, &buffer[0], kBufferLength); EXPECT_STREQ("", buffer);