// Copyright (c) 2015, the Dart project authors. Please see the AUTHORS file // for details. All rights reserved. Use of this source code is governed by a // BSD-style license that can be found in the LICENSE file. #include "vm/timeline_analysis.h" #include "vm/flags.h" #include "vm/isolate.h" #include "vm/log.h" #include "vm/os_thread.h" namespace dart { #ifndef PRODUCT DECLARE_FLAG(bool, trace_timeline_analysis); DECLARE_FLAG(bool, timing); TimelineAnalysisThread::TimelineAnalysisThread(ThreadId id) : id_(id) {} TimelineAnalysisThread::~TimelineAnalysisThread() {} void TimelineAnalysisThread::AddBlock(TimelineEventBlock* block) { blocks_.Add(block); } static int CompareBlocksLowerTimeBound(TimelineEventBlock* const* a, TimelineEventBlock* const* b) { ASSERT(a != NULL); ASSERT(*a != NULL); ASSERT(b != NULL); ASSERT(*b != NULL); return (*a)->LowerTimeBound() - (*b)->LowerTimeBound(); } void TimelineAnalysisThread::Finalize() { blocks_.Sort(CompareBlocksLowerTimeBound); if (FLAG_trace_timeline_analysis) { THR_Print("Thread %" Pd " has %" Pd " blocks\n", OSThread::ThreadIdToIntPtr(id_), blocks_.length()); } } TimelineAnalysisThreadEventIterator::TimelineAnalysisThreadEventIterator( TimelineAnalysisThread* thread) { Reset(thread); } TimelineAnalysisThreadEventIterator::~TimelineAnalysisThreadEventIterator() { Reset(NULL); } void TimelineAnalysisThreadEventIterator::Reset( TimelineAnalysisThread* thread) { current_ = NULL; thread_ = thread; block_cursor_ = 0; event_cursor_ = 0; if (thread_ == NULL) { return; } if (thread_->NumBlocks() == 0) { return; } TimelineEventBlock* block = thread_->At(block_cursor_); ASSERT(!block->IsEmpty()); current_ = block->At(event_cursor_++); } bool TimelineAnalysisThreadEventIterator::HasNext() const { return current_ != NULL; } TimelineEvent* TimelineAnalysisThreadEventIterator::Next() { ASSERT(current_ != NULL); TimelineEvent* r = current_; current_ = NULL; TimelineEventBlock* block = thread_->At(block_cursor_); if (event_cursor_ == block->length()) { // Reached the end of this block, move to the next. block_cursor_++; if (block_cursor_ == thread_->NumBlocks()) { // Exhausted our supply of blocks. return r; } // Grab next block. block = thread_->At(block_cursor_); event_cursor_ = 0; ASSERT(!block->IsEmpty()); } current_ = block->At(event_cursor_++); return r; } TimelineAnalysis::TimelineAnalysis(Zone* zone, Isolate* isolate, TimelineEventRecorder* recorder) : zone_(zone), isolate_(isolate), recorder_(recorder), has_error_(false), error_msg_(NULL) { ASSERT(zone_ != NULL); ASSERT(isolate_ != NULL); ASSERT(recorder_ != NULL); } TimelineAnalysis::~TimelineAnalysis() {} void TimelineAnalysis::BuildThreads() { DiscoverThreads(); FinalizeThreads(); } TimelineAnalysisThread* TimelineAnalysis::GetThread(ThreadId tid) { // Linear lookup because we expect N (# of threads in an isolate) to be small. for (intptr_t i = 0; i < threads_.length(); i++) { TimelineAnalysisThread* thread = threads_.At(i); ASSERT(thread != NULL); if (thread->id() == tid) { return thread; } } return NULL; } TimelineAnalysisThread* TimelineAnalysis::GetOrAddThread(ThreadId tid) { TimelineAnalysisThread* thread = GetThread(tid); if (thread != NULL) { return thread; } // New thread. thread = new TimelineAnalysisThread(tid); threads_.Add(thread); return thread; } void TimelineAnalysis::DiscoverThreads() { TimelineEventBlockIterator it(recorder_); while (it.HasNext()) { TimelineEventBlock* block = it.Next(); ASSERT(block != NULL); if (block->IsEmpty()) { // Skip empty blocks. continue; } if (!block->CheckBlock()) { if (FLAG_trace_timeline_analysis) { THR_Print("DiscoverThreads block %" Pd " " "violates invariants.\n", block->block_index()); } SetError("Block %" Pd " violates invariants. See " "TimelineEventBlock::CheckBlock", block->block_index()); return; } TimelineAnalysisThread* thread = GetOrAddThread(block->thread_id()); ASSERT(thread != NULL); thread->AddBlock(block); } } void TimelineAnalysis::FinalizeThreads() { for (intptr_t i = 0; i < threads_.length(); i++) { TimelineAnalysisThread* thread = threads_.At(i); ASSERT(thread != NULL); thread->Finalize(); } } void TimelineAnalysis::SetError(const char* format, ...) { ASSERT(!has_error_); ASSERT(error_msg_ == NULL); has_error_ = true; va_list args; va_start(args, format); error_msg_ = zone_->VPrint(format, args); ASSERT(error_msg_ != NULL); if (FLAG_trace_timeline_analysis) { OS::PrintErr("TimelineAnalysis error = %s\n", error_msg_); } } TimelineLabelPauseInfo::TimelineLabelPauseInfo(const char* name) : name_(name), inclusive_micros_(0), exclusive_micros_(0), max_inclusive_micros_(0), max_exclusive_micros_(0) { ASSERT(name_ != NULL); } void TimelineLabelPauseInfo::OnPush(int64_t micros, bool already_on_stack) { UpdateInclusiveMicros(micros, already_on_stack); } void TimelineLabelPauseInfo::OnPop(int64_t exclusive_micros) { UpdateExclusiveMicros(exclusive_micros); } void TimelineLabelPauseInfo::OnBeginPop(int64_t inclusive_micros, int64_t exclusive_micros, bool already_on_stack) { UpdateInclusiveMicros(inclusive_micros, already_on_stack); UpdateExclusiveMicros(exclusive_micros); } void TimelineLabelPauseInfo::UpdateInclusiveMicros(int64_t inclusive_micros, bool already_on_stack) { if (!already_on_stack) { // Only adjust inclusive counts if we aren't already on the stack. add_inclusive_micros(inclusive_micros); if (inclusive_micros > max_inclusive_micros_) { max_inclusive_micros_ = inclusive_micros; } } } void TimelineLabelPauseInfo::UpdateExclusiveMicros(int64_t exclusive_micros) { add_exclusive_micros(exclusive_micros); if (exclusive_micros > max_exclusive_micros_) { max_exclusive_micros_ = exclusive_micros; } } void TimelineLabelPauseInfo::Aggregate( const TimelineLabelPauseInfo* thread_pause_info) { ASSERT(thread_pause_info != NULL); inclusive_micros_ += thread_pause_info->inclusive_micros_; exclusive_micros_ += thread_pause_info->exclusive_micros_; if (max_inclusive_micros_ < thread_pause_info->max_inclusive_micros_) { max_inclusive_micros_ = thread_pause_info->max_inclusive_micros_; } if (max_exclusive_micros_ < thread_pause_info->max_exclusive_micros_) { max_exclusive_micros_ = thread_pause_info->max_exclusive_micros_; } } TimelinePauses::TimelinePauses(Zone* zone, Isolate* isolate, TimelineEventRecorder* recorder) : TimelineAnalysis(zone, isolate, recorder) {} void TimelinePauses::Setup() { BuildThreads(); } void TimelinePauses::CalculatePauseTimesForThread(ThreadId tid) { if (has_error()) { return; } TimelineAnalysisThread* thread = GetThread(tid); if (thread == NULL) { SetError("Thread %" Pd " does not exist.", OSThread::ThreadIdToIntPtr(tid)); return; } ProcessThread(thread); } TimelineLabelPauseInfo* TimelinePauses::GetLabelPauseInfo( const char* name) const { ASSERT(name != NULL); // Linear lookup because we expect N (# of labels in an isolate) to be small. for (intptr_t i = 0; i < labels_.length(); i++) { TimelineLabelPauseInfo* label = labels_.At(i); if (strcmp(label->name(), name) == 0) { return label; } } return NULL; } int64_t TimelinePauses::InclusiveTime(const char* name) const { TimelineLabelPauseInfo* pause_info = GetLabelPauseInfo(name); ASSERT(pause_info != NULL); return pause_info->inclusive_micros(); } int64_t TimelinePauses::ExclusiveTime(const char* name) const { TimelineLabelPauseInfo* pause_info = GetLabelPauseInfo(name); ASSERT(pause_info != NULL); return pause_info->exclusive_micros(); } int64_t TimelinePauses::MaxInclusiveTime(const char* name) const { TimelineLabelPauseInfo* pause_info = GetLabelPauseInfo(name); ASSERT(pause_info != NULL); return pause_info->max_inclusive_micros(); } int64_t TimelinePauses::MaxExclusiveTime(const char* name) const { TimelineLabelPauseInfo* pause_info = GetLabelPauseInfo(name); ASSERT(pause_info != NULL); return pause_info->max_exclusive_micros(); } void TimelinePauses::ProcessThread(TimelineAnalysisThread* thread) { ASSERT(thread != NULL); stack_.Clear(); labels_.Clear(); TimelineAnalysisThreadEventIterator it(thread); if (FLAG_trace_timeline_analysis) { THR_Print(">>> TimelinePauses::ProcessThread %" Pd "\n", OSThread::ThreadIdToIntPtr(thread->id())); } intptr_t event_count = 0; while (!has_error() && it.HasNext()) { TimelineEvent* event = it.Next(); if (event->isolate_id() != isolate_->main_port()) { // Skip events that do not belong to the isolate. continue; } if (event->IsFinishedDuration()) { int64_t start = event->TimeOrigin(); PopFinishedDurations(start); if (!CheckStack(event)) { SetError("Duration check fail."); return; } event_count++; Push(event); } else if (event->IsBeginOrEnd()) { event_count++; if (event->IsBegin()) { PopFinishedDurations(event->TimeOrigin()); Push(event); } else { ASSERT(event->IsEnd()); PopFinishedDurations(event->TimeOrigin()); PopBegin(event->label(), event->TimeOrigin()); } } else { // Skip other event kinds. } } // Pop remaining duration stack. PopFinishedDurations(kMaxInt64); if (FLAG_trace_timeline_analysis) { THR_Print("<<< TimelinePauses::ProcessThread %" Pd " had %" Pd " events\n", OSThread::ThreadIdToIntPtr(thread->id()), event_count); } } // Verify that |event| is contained within all parent events on the stack. bool TimelinePauses::CheckStack(TimelineEvent* event) { ASSERT(event != NULL); for (intptr_t i = 0; i < stack_.length(); i++) { const StackItem& slot = stack_.At(i); if (slot.event->IsDuration()) { if (!slot.event->DurationContains(event)) { return false; } } else { ASSERT(slot.event->IsBegin()); if (slot.event->TimeOrigin() > event->TimeOrigin()) { return false; } } } return true; } void TimelinePauses::PopFinishedDurations(int64_t start) { while (stack_.length() > 0) { const StackItem& top = stack_.Last(); if (top.event->IsDuration() && top.event->DurationFinishedBefore(start)) { top.pause_info->OnPop(top.exclusive_micros); // Top of stack completes before |start|. stack_.RemoveLast(); if (FLAG_trace_timeline_analysis) { THR_Print("Popping %s (%" Pd64 " <= %" Pd64 ")\n", top.event->label(), top.event->TimeEnd(), start); } } else { return; } } } void TimelinePauses::PopBegin(const char* label, int64_t end) { if (stack_.length() == 0) { SetError("PopBegin(%s, ...) called with empty stack.", label); return; } ASSERT(stack_.length() > 0); const StackItem& top = stack_.Last(); const char* top_label = top.event->label(); const bool top_is_begin = top.event->IsBegin(); const int64_t start = top.event->TimeOrigin(); if (start > end) { SetError("Bad time stamps for PopBegin(%s, ...) %" Pd64 " > %" Pd64 "", label, start, end); return; } const int64_t duration = end - start; // Sanity checks. if (strcmp(top_label, label) != 0) { SetError("PopBegin(%s, ...) called with %s at the top of stack", label, top.event->label()); return; } if (!top_is_begin) { SetError("kEnd event not paired with kBegin event for label %s", label); return; } // Pop this event. // Add duration to exclusive micros. if (FLAG_trace_timeline_analysis) { THR_Print("Popping %s (%" Pd64 ")\n", top.event->label(), duration); } const int64_t exclusive_micros = top.exclusive_micros + duration; stack_.RemoveLast(); top.pause_info->OnBeginPop(duration, exclusive_micros, IsLabelOnStack(top_label)); if (StackDepth() > 0) { StackItem& top = GetStackTop(); // |top| is under the popped |event|'s shadow, adjust the exclusive micros. top.exclusive_micros -= duration; } } void TimelinePauses::Push(TimelineEvent* event) { TimelineLabelPauseInfo* pause_info = GetOrAddLabelPauseInfo(event->label()); ASSERT(pause_info != NULL); // |pause_info| will be running for |event->TimeDuration()|. if (FLAG_trace_timeline_analysis) { THR_Print("Pushing %s %" Pd64 " us\n", pause_info->name(), event->TimeDuration()); } if (event->IsDuration()) { pause_info->OnPush(event->TimeDuration(), IsLabelOnStack(event->label())); if (StackDepth() > 0) { StackItem& top = GetStackTop(); // |top| is under |event|'s shadow, adjust the exclusive micros. top.exclusive_micros -= event->TimeDuration(); } // Push onto the stack. StackItem item; item.event = event; item.pause_info = pause_info; item.exclusive_micros = event->TimeDuration(); stack_.Add(item); } else { ASSERT(event->IsBegin()); pause_info->OnPush(0, IsLabelOnStack(event->label())); // Push onto the stack. StackItem item; item.event = event; item.pause_info = pause_info; item.exclusive_micros = 0; stack_.Add(item); } } bool TimelinePauses::IsLabelOnStack(const char* label) const { ASSERT(label != NULL); for (intptr_t i = 0; i < stack_.length(); i++) { const StackItem& slot = stack_.At(i); if (strcmp(slot.event->label(), label) == 0) { return true; } } return false; } intptr_t TimelinePauses::StackDepth() const { return stack_.length(); } TimelinePauses::StackItem& TimelinePauses::GetStackTop() { ASSERT(stack_.length() > 0); return stack_.Last(); } TimelineLabelPauseInfo* TimelinePauses::GetOrAddLabelPauseInfo( const char* name) { ASSERT(name != NULL); TimelineLabelPauseInfo* pause_info = GetLabelPauseInfo(name); if (pause_info != NULL) { return pause_info; } // New label. pause_info = new TimelineLabelPauseInfo(name); labels_.Add(pause_info); return pause_info; } TimelinePauseTrace::TimelinePauseTrace() {} TimelinePauseTrace::~TimelinePauseTrace() {} void TimelinePauseTrace::Print() { Thread* thread = Thread::Current(); ASSERT(thread != NULL); Isolate* isolate = thread->isolate(); ASSERT(isolate != NULL); Zone* zone = thread->zone(); ASSERT(zone != NULL); TimelineEventRecorder* recorder = Timeline::recorder(); ASSERT(recorder != NULL); TimelinePauses pauses(zone, isolate, recorder); pauses.Setup(); THR_Print("Timing for isolate (%" Pd64 ") '%s' (from %" Pd " threads)\n", static_cast(isolate->main_port()), isolate->name(), pauses.NumThreads()); THR_Print("\n"); for (intptr_t t_idx = 0; t_idx < pauses.NumThreads(); t_idx++) { TimelineAnalysisThread* tat = pauses.At(t_idx); ASSERT(tat != NULL); pauses.CalculatePauseTimesForThread(tat->id()); THR_Print("Thread %" Pd " (%" Pd "):\n", t_idx, OSThread::ThreadIdToIntPtr(tat->id())); for (intptr_t j = 0; j < pauses.NumPauseInfos(); j++) { const TimelineLabelPauseInfo* pause_info = pauses.PauseInfoAt(j); ASSERT(pause_info != NULL); Aggregate(pause_info); PrintPauseInfo(pause_info); } THR_Print("\n"); } THR_Print("Totals:\n"); for (intptr_t i = 0; i < isolate_labels_.length(); i++) { TimelineLabelPauseInfo* pause_info = isolate_labels_.At(i); ASSERT(pause_info != NULL); PrintPauseInfo(pause_info); } THR_Print("\n"); } TimelineLabelPauseInfo* TimelinePauseTrace::GetOrAddLabelPauseInfo( const char* name) { ASSERT(name != NULL); // Linear lookup because we expect N (# of labels in an isolate) to be small. for (intptr_t i = 0; i < isolate_labels_.length(); i++) { TimelineLabelPauseInfo* label = isolate_labels_.At(i); if (strcmp(label->name(), name) == 0) { return label; } } // New label. TimelineLabelPauseInfo* pause_info = new TimelineLabelPauseInfo(name); isolate_labels_.Add(pause_info); return pause_info; } void TimelinePauseTrace::Aggregate( const TimelineLabelPauseInfo* thread_pause_info) { ASSERT(thread_pause_info != NULL); TimelineLabelPauseInfo* isolate_pause_info = GetOrAddLabelPauseInfo(thread_pause_info->name()); ASSERT(isolate_pause_info != NULL); isolate_pause_info->Aggregate(thread_pause_info); } void TimelinePauseTrace::PrintPauseInfo( const TimelineLabelPauseInfo* pause_info) { ASSERT(pause_info != NULL); THR_Print("%s : ", pause_info->name()); THR_Print("%.3f ms total on stack; ", MicrosecondsToMilliseconds(pause_info->inclusive_micros())); THR_Print("%.3f ms total executing; ", MicrosecondsToMilliseconds(pause_info->exclusive_micros())); THR_Print("%.3f ms max on stack; ", MicrosecondsToMilliseconds(pause_info->max_inclusive_micros())); THR_Print("%.3f ms max executing.\n", MicrosecondsToMilliseconds(pause_info->max_exclusive_micros())); } #endif // !PRODUCT } // namespace dart