| OLD | NEW |
| 1 // Copyright (c) 2015, the Dart project authors. Please see the AUTHORS file | 1 // Copyright (c) 2015, the Dart project authors. Please see the AUTHORS file |
| 2 // for details. All rights reserved. Use of this source code is governed by a | 2 // for details. All rights reserved. Use of this source code is governed by a |
| 3 // BSD-style license that can be found in the LICENSE file. | 3 // BSD-style license that can be found in the LICENSE file. |
| 4 | 4 |
| 5 #include "vm/timeline_analysis.h" | 5 #include "vm/timeline_analysis.h" |
| 6 | 6 |
| 7 #include "vm/flags.h" | 7 #include "vm/flags.h" |
| 8 #include "vm/log.h" | 8 #include "vm/log.h" |
| 9 #include "vm/os_thread.h" | 9 #include "vm/os_thread.h" |
| 10 | 10 |
| 11 namespace dart { | 11 namespace dart { |
| 12 | 12 |
| 13 #ifndef PRODUCT | 13 #ifndef PRODUCT |
| 14 | 14 |
| 15 DECLARE_FLAG(bool, trace_timeline_analysis); | 15 DECLARE_FLAG(bool, trace_timeline_analysis); |
| 16 DECLARE_FLAG(bool, timing); | 16 DECLARE_FLAG(bool, timing); |
| 17 | 17 |
| 18 TimelineAnalysisThread::TimelineAnalysisThread(ThreadId id) | 18 TimelineAnalysisThread::TimelineAnalysisThread(ThreadId id) : id_(id) {} |
| 19 : id_(id) { | |
| 20 } | |
| 21 | 19 |
| 22 | 20 |
| 23 TimelineAnalysisThread::~TimelineAnalysisThread() { | 21 TimelineAnalysisThread::~TimelineAnalysisThread() {} |
| 24 } | |
| 25 | 22 |
| 26 | 23 |
| 27 void TimelineAnalysisThread::AddBlock(TimelineEventBlock* block) { | 24 void TimelineAnalysisThread::AddBlock(TimelineEventBlock* block) { |
| 28 blocks_.Add(block); | 25 blocks_.Add(block); |
| 29 } | 26 } |
| 30 | 27 |
| 31 | 28 |
| 32 static int CompareBlocksLowerTimeBound(TimelineEventBlock* const* a, | 29 static int CompareBlocksLowerTimeBound(TimelineEventBlock* const* a, |
| 33 TimelineEventBlock* const* b) { | 30 TimelineEventBlock* const* b) { |
| 34 ASSERT(a != NULL); | 31 ASSERT(a != NULL); |
| 35 ASSERT(*a != NULL); | 32 ASSERT(*a != NULL); |
| 36 ASSERT(b != NULL); | 33 ASSERT(b != NULL); |
| 37 ASSERT(*b != NULL); | 34 ASSERT(*b != NULL); |
| 38 return (*a)->LowerTimeBound() - (*b)->LowerTimeBound(); | 35 return (*a)->LowerTimeBound() - (*b)->LowerTimeBound(); |
| 39 } | 36 } |
| 40 | 37 |
| 41 | 38 |
| 42 void TimelineAnalysisThread::Finalize() { | 39 void TimelineAnalysisThread::Finalize() { |
| 43 blocks_.Sort(CompareBlocksLowerTimeBound); | 40 blocks_.Sort(CompareBlocksLowerTimeBound); |
| 44 if (FLAG_trace_timeline_analysis) { | 41 if (FLAG_trace_timeline_analysis) { |
| 45 THR_Print("Thread %" Px " has %" Pd " blocks\n", | 42 THR_Print("Thread %" Px " has %" Pd " blocks\n", |
| 46 OSThread::ThreadIdToIntPtr(id_), | 43 OSThread::ThreadIdToIntPtr(id_), blocks_.length()); |
| 47 blocks_.length()); | |
| 48 } | 44 } |
| 49 } | 45 } |
| 50 | 46 |
| 51 | 47 |
| 52 TimelineAnalysisThreadEventIterator::TimelineAnalysisThreadEventIterator( | 48 TimelineAnalysisThreadEventIterator::TimelineAnalysisThreadEventIterator( |
| 53 TimelineAnalysisThread* thread) { | 49 TimelineAnalysisThread* thread) { |
| 54 Reset(thread); | 50 Reset(thread); |
| 55 } | 51 } |
| 56 | 52 |
| 57 | 53 |
| (...skipping 55 matching lines...) Expand 10 before | Expand all | Expand 10 after Loading... |
| 113 isolate_(isolate), | 109 isolate_(isolate), |
| 114 recorder_(recorder), | 110 recorder_(recorder), |
| 115 has_error_(false), | 111 has_error_(false), |
| 116 error_msg_(NULL) { | 112 error_msg_(NULL) { |
| 117 ASSERT(zone_ != NULL); | 113 ASSERT(zone_ != NULL); |
| 118 ASSERT(isolate_ != NULL); | 114 ASSERT(isolate_ != NULL); |
| 119 ASSERT(recorder_ != NULL); | 115 ASSERT(recorder_ != NULL); |
| 120 } | 116 } |
| 121 | 117 |
| 122 | 118 |
| 123 TimelineAnalysis::~TimelineAnalysis() { | 119 TimelineAnalysis::~TimelineAnalysis() {} |
| 124 } | |
| 125 | 120 |
| 126 | 121 |
| 127 void TimelineAnalysis::BuildThreads() { | 122 void TimelineAnalysis::BuildThreads() { |
| 128 DiscoverThreads(); | 123 DiscoverThreads(); |
| 129 FinalizeThreads(); | 124 FinalizeThreads(); |
| 130 } | 125 } |
| 131 | 126 |
| 132 | 127 |
| 133 TimelineAnalysisThread* TimelineAnalysis::GetThread(ThreadId tid) { | 128 TimelineAnalysisThread* TimelineAnalysis::GetThread(ThreadId tid) { |
| 134 // Linear lookup because we expect N (# of threads in an isolate) to be small. | 129 // Linear lookup because we expect N (# of threads in an isolate) to be small. |
| (...skipping 24 matching lines...) Expand all Loading... |
| 159 TimelineEventBlockIterator it(recorder_); | 154 TimelineEventBlockIterator it(recorder_); |
| 160 while (it.HasNext()) { | 155 while (it.HasNext()) { |
| 161 TimelineEventBlock* block = it.Next(); | 156 TimelineEventBlock* block = it.Next(); |
| 162 ASSERT(block != NULL); | 157 ASSERT(block != NULL); |
| 163 if (block->IsEmpty()) { | 158 if (block->IsEmpty()) { |
| 164 // Skip empty blocks. | 159 // Skip empty blocks. |
| 165 continue; | 160 continue; |
| 166 } | 161 } |
| 167 if (!block->CheckBlock()) { | 162 if (!block->CheckBlock()) { |
| 168 if (FLAG_trace_timeline_analysis) { | 163 if (FLAG_trace_timeline_analysis) { |
| 169 THR_Print("DiscoverThreads block %" Pd " " | 164 THR_Print("DiscoverThreads block %" Pd |
| 170 "violates invariants.\n", block->block_index()); | 165 " " |
| 166 "violates invariants.\n", |
| 167 block->block_index()); |
| 171 } | 168 } |
| 172 SetError("Block %" Pd " violates invariants. See " | 169 SetError("Block %" Pd |
| 173 "TimelineEventBlock::CheckBlock", block->block_index()); | 170 " violates invariants. See " |
| 171 "TimelineEventBlock::CheckBlock", |
| 172 block->block_index()); |
| 174 return; | 173 return; |
| 175 } | 174 } |
| 176 TimelineAnalysisThread* thread = GetOrAddThread(block->thread_id()); | 175 TimelineAnalysisThread* thread = GetOrAddThread(block->thread_id()); |
| 177 ASSERT(thread != NULL); | 176 ASSERT(thread != NULL); |
| 178 thread->AddBlock(block); | 177 thread->AddBlock(block); |
| 179 } | 178 } |
| 180 } | 179 } |
| 181 | 180 |
| 182 | 181 |
| 183 void TimelineAnalysis::FinalizeThreads() { | 182 void TimelineAnalysis::FinalizeThreads() { |
| (...skipping 77 matching lines...) Expand 10 before | Expand all | Expand 10 after Loading... |
| 261 } | 260 } |
| 262 if (max_exclusive_micros_ < thread_pause_info->max_exclusive_micros_) { | 261 if (max_exclusive_micros_ < thread_pause_info->max_exclusive_micros_) { |
| 263 max_exclusive_micros_ = thread_pause_info->max_exclusive_micros_; | 262 max_exclusive_micros_ = thread_pause_info->max_exclusive_micros_; |
| 264 } | 263 } |
| 265 } | 264 } |
| 266 | 265 |
| 267 | 266 |
| 268 TimelinePauses::TimelinePauses(Zone* zone, | 267 TimelinePauses::TimelinePauses(Zone* zone, |
| 269 Isolate* isolate, | 268 Isolate* isolate, |
| 270 TimelineEventRecorder* recorder) | 269 TimelineEventRecorder* recorder) |
| 271 : TimelineAnalysis(zone, isolate, recorder) { | 270 : TimelineAnalysis(zone, isolate, recorder) {} |
| 272 } | |
| 273 | 271 |
| 274 | 272 |
| 275 void TimelinePauses::Setup() { | 273 void TimelinePauses::Setup() { |
| 276 BuildThreads(); | 274 BuildThreads(); |
| 277 } | 275 } |
| 278 | 276 |
| 279 | 277 |
| 280 void TimelinePauses::CalculatePauseTimesForThread(ThreadId tid) { | 278 void TimelinePauses::CalculatePauseTimesForThread(ThreadId tid) { |
| 281 if (has_error()) { | 279 if (has_error()) { |
| 282 return; | 280 return; |
| (...skipping 86 matching lines...) Expand 10 before | Expand all | Expand 10 after Loading... |
| 369 PopBegin(event->label(), event->TimeOrigin()); | 367 PopBegin(event->label(), event->TimeOrigin()); |
| 370 } | 368 } |
| 371 } else { | 369 } else { |
| 372 // Skip other event kinds. | 370 // Skip other event kinds. |
| 373 } | 371 } |
| 374 } | 372 } |
| 375 // Pop remaining duration stack. | 373 // Pop remaining duration stack. |
| 376 PopFinishedDurations(kMaxInt64); | 374 PopFinishedDurations(kMaxInt64); |
| 377 if (FLAG_trace_timeline_analysis) { | 375 if (FLAG_trace_timeline_analysis) { |
| 378 THR_Print("<<< TimelinePauses::ProcessThread %" Px " had %" Pd " events\n", | 376 THR_Print("<<< TimelinePauses::ProcessThread %" Px " had %" Pd " events\n", |
| 379 OSThread::ThreadIdToIntPtr(thread->id()), | 377 OSThread::ThreadIdToIntPtr(thread->id()), event_count); |
| 380 event_count); | |
| 381 } | 378 } |
| 382 } | 379 } |
| 383 | 380 |
| 384 | 381 |
| 385 // Verify that |event| is contained within all parent events on the stack. | 382 // Verify that |event| is contained within all parent events on the stack. |
| 386 bool TimelinePauses::CheckStack(TimelineEvent* event) { | 383 bool TimelinePauses::CheckStack(TimelineEvent* event) { |
| 387 ASSERT(event != NULL); | 384 ASSERT(event != NULL); |
| 388 for (intptr_t i = 0; i < stack_.length(); i++) { | 385 for (intptr_t i = 0; i < stack_.length(); i++) { |
| 389 const StackItem& slot = stack_.At(i); | 386 const StackItem& slot = stack_.At(i); |
| 390 if (slot.event->IsDuration()) { | 387 if (slot.event->IsDuration()) { |
| (...skipping 12 matching lines...) Expand all Loading... |
| 403 | 400 |
| 404 | 401 |
| 405 void TimelinePauses::PopFinishedDurations(int64_t start) { | 402 void TimelinePauses::PopFinishedDurations(int64_t start) { |
| 406 while (stack_.length() > 0) { | 403 while (stack_.length() > 0) { |
| 407 const StackItem& top = stack_.Last(); | 404 const StackItem& top = stack_.Last(); |
| 408 if (top.event->IsDuration() && top.event->DurationFinishedBefore(start)) { | 405 if (top.event->IsDuration() && top.event->DurationFinishedBefore(start)) { |
| 409 top.pause_info->OnPop(top.exclusive_micros); | 406 top.pause_info->OnPop(top.exclusive_micros); |
| 410 // Top of stack completes before |start|. | 407 // Top of stack completes before |start|. |
| 411 stack_.RemoveLast(); | 408 stack_.RemoveLast(); |
| 412 if (FLAG_trace_timeline_analysis) { | 409 if (FLAG_trace_timeline_analysis) { |
| 413 THR_Print("Popping %s (%" Pd64 " <= %" Pd64 ")\n", | 410 THR_Print("Popping %s (%" Pd64 " <= %" Pd64 ")\n", top.event->label(), |
| 414 top.event->label(), | 411 top.event->TimeEnd(), start); |
| 415 top.event->TimeEnd(), | |
| 416 start); | |
| 417 } | 412 } |
| 418 } else { | 413 } else { |
| 419 return; | 414 return; |
| 420 } | 415 } |
| 421 } | 416 } |
| 422 } | 417 } |
| 423 | 418 |
| 424 | 419 |
| 425 void TimelinePauses::PopBegin(const char* label, int64_t end) { | 420 void TimelinePauses::PopBegin(const char* label, int64_t end) { |
| 426 if (stack_.length() == 0) { | 421 if (stack_.length() == 0) { |
| 427 SetError("PopBegin(%s, ...) called with empty stack.", label); | 422 SetError("PopBegin(%s, ...) called with empty stack.", label); |
| 428 return; | 423 return; |
| 429 } | 424 } |
| 430 ASSERT(stack_.length() > 0); | 425 ASSERT(stack_.length() > 0); |
| 431 const StackItem& top = stack_.Last(); | 426 const StackItem& top = stack_.Last(); |
| 432 const char* top_label = top.event->label(); | 427 const char* top_label = top.event->label(); |
| 433 const bool top_is_begin = top.event->IsBegin(); | 428 const bool top_is_begin = top.event->IsBegin(); |
| 434 const int64_t start = top.event->TimeOrigin(); | 429 const int64_t start = top.event->TimeOrigin(); |
| 435 if (start > end) { | 430 if (start > end) { |
| 436 SetError("Bad time stamps for PopBegin(%s, ...) %" Pd64 " > %" Pd64 "", | 431 SetError("Bad time stamps for PopBegin(%s, ...) %" Pd64 " > %" Pd64 "", |
| 437 label, start, end); | 432 label, start, end); |
| 438 return; | 433 return; |
| 439 } | 434 } |
| 440 const int64_t duration = end - start; | 435 const int64_t duration = end - start; |
| 441 // Sanity checks. | 436 // Sanity checks. |
| 442 if (strcmp(top_label, label) != 0) { | 437 if (strcmp(top_label, label) != 0) { |
| 443 SetError("PopBegin(%s, ...) called with %s at the top of stack", | 438 SetError("PopBegin(%s, ...) called with %s at the top of stack", label, |
| 444 label, top.event->label()); | 439 top.event->label()); |
| 445 return; | 440 return; |
| 446 } | 441 } |
| 447 if (!top_is_begin) { | 442 if (!top_is_begin) { |
| 448 SetError("kEnd event not paired with kBegin event for label %s", | 443 SetError("kEnd event not paired with kBegin event for label %s", label); |
| 449 label); | |
| 450 return; | 444 return; |
| 451 } | 445 } |
| 452 // Pop this event. | 446 // Pop this event. |
| 453 // Add duration to exclusive micros. | 447 // Add duration to exclusive micros. |
| 454 if (FLAG_trace_timeline_analysis) { | 448 if (FLAG_trace_timeline_analysis) { |
| 455 THR_Print("Popping %s (%" Pd64 ")\n", | 449 THR_Print("Popping %s (%" Pd64 ")\n", top.event->label(), duration); |
| 456 top.event->label(), | |
| 457 duration); | |
| 458 } | 450 } |
| 459 const int64_t exclusive_micros = top.exclusive_micros + duration; | 451 const int64_t exclusive_micros = top.exclusive_micros + duration; |
| 460 stack_.RemoveLast(); | 452 stack_.RemoveLast(); |
| 461 top.pause_info->OnBeginPop(duration, | 453 top.pause_info->OnBeginPop(duration, exclusive_micros, |
| 462 exclusive_micros, | |
| 463 IsLabelOnStack(top_label)); | 454 IsLabelOnStack(top_label)); |
| 464 if (StackDepth() > 0) { | 455 if (StackDepth() > 0) { |
| 465 StackItem& top = GetStackTop(); | 456 StackItem& top = GetStackTop(); |
| 466 // |top| is under the popped |event|'s shadow, adjust the exclusive micros. | 457 // |top| is under the popped |event|'s shadow, adjust the exclusive micros. |
| 467 top.exclusive_micros -= duration; | 458 top.exclusive_micros -= duration; |
| 468 } | 459 } |
| 469 } | 460 } |
| 470 | 461 |
| 471 | 462 |
| 472 void TimelinePauses::Push(TimelineEvent* event) { | 463 void TimelinePauses::Push(TimelineEvent* event) { |
| 473 TimelineLabelPauseInfo* pause_info = GetOrAddLabelPauseInfo(event->label()); | 464 TimelineLabelPauseInfo* pause_info = GetOrAddLabelPauseInfo(event->label()); |
| 474 ASSERT(pause_info != NULL); | 465 ASSERT(pause_info != NULL); |
| 475 // |pause_info| will be running for |event->TimeDuration()|. | 466 // |pause_info| will be running for |event->TimeDuration()|. |
| 476 if (FLAG_trace_timeline_analysis) { | 467 if (FLAG_trace_timeline_analysis) { |
| 477 THR_Print("Pushing %s %" Pd64 " us\n", | 468 THR_Print("Pushing %s %" Pd64 " us\n", pause_info->name(), |
| 478 pause_info->name(), | |
| 479 event->TimeDuration()); | 469 event->TimeDuration()); |
| 480 } | 470 } |
| 481 if (event->IsDuration()) { | 471 if (event->IsDuration()) { |
| 482 pause_info->OnPush(event->TimeDuration(), IsLabelOnStack(event->label())); | 472 pause_info->OnPush(event->TimeDuration(), IsLabelOnStack(event->label())); |
| 483 if (StackDepth() > 0) { | 473 if (StackDepth() > 0) { |
| 484 StackItem& top = GetStackTop(); | 474 StackItem& top = GetStackTop(); |
| 485 // |top| is under |event|'s shadow, adjust the exclusive micros. | 475 // |top| is under |event|'s shadow, adjust the exclusive micros. |
| 486 top.exclusive_micros -= event->TimeDuration(); | 476 top.exclusive_micros -= event->TimeDuration(); |
| 487 } | 477 } |
| 488 // Push onto the stack. | 478 // Push onto the stack. |
| (...skipping 45 matching lines...) Expand 10 before | Expand all | Expand 10 after Loading... |
| 534 if (pause_info != NULL) { | 524 if (pause_info != NULL) { |
| 535 return pause_info; | 525 return pause_info; |
| 536 } | 526 } |
| 537 // New label. | 527 // New label. |
| 538 pause_info = new TimelineLabelPauseInfo(name); | 528 pause_info = new TimelineLabelPauseInfo(name); |
| 539 labels_.Add(pause_info); | 529 labels_.Add(pause_info); |
| 540 return pause_info; | 530 return pause_info; |
| 541 } | 531 } |
| 542 | 532 |
| 543 | 533 |
| 544 TimelinePauseTrace::TimelinePauseTrace() { | 534 TimelinePauseTrace::TimelinePauseTrace() {} |
| 545 } | |
| 546 | 535 |
| 547 | 536 |
| 548 TimelinePauseTrace::~TimelinePauseTrace() { | 537 TimelinePauseTrace::~TimelinePauseTrace() {} |
| 549 } | |
| 550 | 538 |
| 551 | 539 |
| 552 void TimelinePauseTrace::Print() { | 540 void TimelinePauseTrace::Print() { |
| 553 Thread* thread = Thread::Current(); | 541 Thread* thread = Thread::Current(); |
| 554 ASSERT(thread != NULL); | 542 ASSERT(thread != NULL); |
| 555 Isolate* isolate = thread->isolate(); | 543 Isolate* isolate = thread->isolate(); |
| 556 ASSERT(isolate != NULL); | 544 ASSERT(isolate != NULL); |
| 557 Zone* zone = thread->zone(); | 545 Zone* zone = thread->zone(); |
| 558 ASSERT(zone != NULL); | 546 ASSERT(zone != NULL); |
| 559 TimelineEventRecorder* recorder = Timeline::recorder(); | 547 TimelineEventRecorder* recorder = Timeline::recorder(); |
| 560 ASSERT(recorder != NULL); | 548 ASSERT(recorder != NULL); |
| 561 TimelinePauses pauses(zone, isolate, recorder); | 549 TimelinePauses pauses(zone, isolate, recorder); |
| 562 pauses.Setup(); | 550 pauses.Setup(); |
| 563 | 551 |
| 564 THR_Print("Timing for isolate %s (from %" Pd " threads)\n", | 552 THR_Print("Timing for isolate %s (from %" Pd " threads)\n", isolate->name(), |
| 565 isolate->name(), | |
| 566 pauses.NumThreads()); | 553 pauses.NumThreads()); |
| 567 THR_Print("\n"); | 554 THR_Print("\n"); |
| 568 for (intptr_t t_idx = 0; t_idx < pauses.NumThreads(); t_idx++) { | 555 for (intptr_t t_idx = 0; t_idx < pauses.NumThreads(); t_idx++) { |
| 569 TimelineAnalysisThread* tat = pauses.At(t_idx); | 556 TimelineAnalysisThread* tat = pauses.At(t_idx); |
| 570 ASSERT(tat != NULL); | 557 ASSERT(tat != NULL); |
| 571 pauses.CalculatePauseTimesForThread(tat->id()); | 558 pauses.CalculatePauseTimesForThread(tat->id()); |
| 572 THR_Print("Thread %" Pd " (%" Px "):\n", | 559 THR_Print("Thread %" Pd " (%" Px "):\n", t_idx, |
| 573 t_idx, | |
| 574 OSThread::ThreadIdToIntPtr(tat->id())); | 560 OSThread::ThreadIdToIntPtr(tat->id())); |
| 575 for (intptr_t j = 0; j < pauses.NumPauseInfos(); j++) { | 561 for (intptr_t j = 0; j < pauses.NumPauseInfos(); j++) { |
| 576 const TimelineLabelPauseInfo* pause_info = pauses.PauseInfoAt(j); | 562 const TimelineLabelPauseInfo* pause_info = pauses.PauseInfoAt(j); |
| 577 ASSERT(pause_info != NULL); | 563 ASSERT(pause_info != NULL); |
| 578 Aggregate(pause_info); | 564 Aggregate(pause_info); |
| 579 PrintPauseInfo(pause_info); | 565 PrintPauseInfo(pause_info); |
| 580 } | 566 } |
| 581 THR_Print("\n"); | 567 THR_Print("\n"); |
| 582 } | 568 } |
| 583 THR_Print("Totals:\n"); | 569 THR_Print("Totals:\n"); |
| (...skipping 43 matching lines...) Expand 10 before | Expand all | Expand 10 after Loading... |
| 627 MicrosecondsToMilliseconds(pause_info->exclusive_micros())); | 613 MicrosecondsToMilliseconds(pause_info->exclusive_micros())); |
| 628 THR_Print("%.3f ms max on stack; ", | 614 THR_Print("%.3f ms max on stack; ", |
| 629 MicrosecondsToMilliseconds(pause_info->max_inclusive_micros())); | 615 MicrosecondsToMilliseconds(pause_info->max_inclusive_micros())); |
| 630 THR_Print("%.3f ms max executing.\n", | 616 THR_Print("%.3f ms max executing.\n", |
| 631 MicrosecondsToMilliseconds(pause_info->max_exclusive_micros())); | 617 MicrosecondsToMilliseconds(pause_info->max_exclusive_micros())); |
| 632 } | 618 } |
| 633 | 619 |
| 634 #endif // !PRODUCT | 620 #endif // !PRODUCT |
| 635 | 621 |
| 636 } // namespace dart | 622 } // namespace dart |
| OLD | NEW |