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 |