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
3// BSD-style license that can be found in the LICENSE file.
4
5#include "vm/timeline_analysis.h"
6
7#include "vm/flags.h"
8#include "vm/isolate.h"
9#include "vm/log.h"
10#include "vm/os_thread.h"
11
12namespace dart {
13
14#ifndef PRODUCT
15
16DECLARE_FLAG(bool, trace_timeline_analysis);
17DECLARE_FLAG(bool, timing);
18
19TimelineAnalysisThread::TimelineAnalysisThread(ThreadId id) : id_(id) {}
20
21TimelineAnalysisThread::~TimelineAnalysisThread() {}
22
23void TimelineAnalysisThread::AddBlock(TimelineEventBlock* block) {
24 blocks_.Add(block);
25}
26
27static int CompareBlocksLowerTimeBound(TimelineEventBlock* const* a,
28 TimelineEventBlock* const* b) {
29 ASSERT(a != NULL);
30 ASSERT(*a != NULL);
31 ASSERT(b != NULL);
32 ASSERT(*b != NULL);
33 return (*a)->LowerTimeBound() - (*b)->LowerTimeBound();
34}
35
36void TimelineAnalysisThread::Finalize() {
37 blocks_.Sort(CompareBlocksLowerTimeBound);
38 if (FLAG_trace_timeline_analysis) {
39 THR_Print("Thread %" Pd " has %" Pd " blocks\n",
40 OSThread::ThreadIdToIntPtr(id_), blocks_.length());
41 }
42}
43
44TimelineAnalysisThreadEventIterator::TimelineAnalysisThreadEventIterator(
45 TimelineAnalysisThread* thread) {
46 Reset(thread);
47}
48
49TimelineAnalysisThreadEventIterator::~TimelineAnalysisThreadEventIterator() {
50 Reset(NULL);
51}
52
53void TimelineAnalysisThreadEventIterator::Reset(
54 TimelineAnalysisThread* thread) {
55 current_ = NULL;
56 thread_ = thread;
57 block_cursor_ = 0;
58 event_cursor_ = 0;
59 if (thread_ == NULL) {
60 return;
61 }
62 if (thread_->NumBlocks() == 0) {
63 return;
64 }
65 TimelineEventBlock* block = thread_->At(block_cursor_);
66 ASSERT(!block->IsEmpty());
67 current_ = block->At(event_cursor_++);
68}
69
70bool TimelineAnalysisThreadEventIterator::HasNext() const {
71 return current_ != NULL;
72}
73
74TimelineEvent* TimelineAnalysisThreadEventIterator::Next() {
75 ASSERT(current_ != NULL);
76 TimelineEvent* r = current_;
77 current_ = NULL;
78
79 TimelineEventBlock* block = thread_->At(block_cursor_);
80 if (event_cursor_ == block->length()) {
81 // Reached the end of this block, move to the next.
82 block_cursor_++;
83 if (block_cursor_ == thread_->NumBlocks()) {
84 // Exhausted our supply of blocks.
85 return r;
86 }
87 // Grab next block.
88 block = thread_->At(block_cursor_);
89 event_cursor_ = 0;
90 ASSERT(!block->IsEmpty());
91 }
92 current_ = block->At(event_cursor_++);
93 return r;
94}
95
96TimelineAnalysis::TimelineAnalysis(Zone* zone,
97 Isolate* isolate,
98 TimelineEventRecorder* recorder)
99 : zone_(zone),
100 isolate_(isolate),
101 recorder_(recorder),
102 has_error_(false),
103 error_msg_(NULL) {
104 ASSERT(zone_ != NULL);
105 ASSERT(isolate_ != NULL);
106 ASSERT(recorder_ != NULL);
107}
108
109TimelineAnalysis::~TimelineAnalysis() {}
110
111void TimelineAnalysis::BuildThreads() {
112 DiscoverThreads();
113 FinalizeThreads();
114}
115
116TimelineAnalysisThread* TimelineAnalysis::GetThread(ThreadId tid) {
117 // Linear lookup because we expect N (# of threads in an isolate) to be small.
118 for (intptr_t i = 0; i < threads_.length(); i++) {
119 TimelineAnalysisThread* thread = threads_.At(i);
120 ASSERT(thread != NULL);
121 if (thread->id() == tid) {
122 return thread;
123 }
124 }
125 return NULL;
126}
127
128TimelineAnalysisThread* TimelineAnalysis::GetOrAddThread(ThreadId tid) {
129 TimelineAnalysisThread* thread = GetThread(tid);
130 if (thread != NULL) {
131 return thread;
132 }
133 // New thread.
134 thread = new TimelineAnalysisThread(tid);
135 threads_.Add(thread);
136 return thread;
137}
138
139void TimelineAnalysis::DiscoverThreads() {
140 TimelineEventBlockIterator it(recorder_);
141 while (it.HasNext()) {
142 TimelineEventBlock* block = it.Next();
143 ASSERT(block != NULL);
144 if (block->IsEmpty()) {
145 // Skip empty blocks.
146 continue;
147 }
148 if (!block->CheckBlock()) {
149 if (FLAG_trace_timeline_analysis) {
150 THR_Print("DiscoverThreads block %" Pd
151 " "
152 "violates invariants.\n",
153 block->block_index());
154 }
155 SetError("Block %" Pd
156 " violates invariants. See "
157 "TimelineEventBlock::CheckBlock",
158 block->block_index());
159 return;
160 }
161 TimelineAnalysisThread* thread = GetOrAddThread(block->thread_id());
162 ASSERT(thread != NULL);
163 thread->AddBlock(block);
164 }
165}
166
167void TimelineAnalysis::FinalizeThreads() {
168 for (intptr_t i = 0; i < threads_.length(); i++) {
169 TimelineAnalysisThread* thread = threads_.At(i);
170 ASSERT(thread != NULL);
171 thread->Finalize();
172 }
173}
174
175void TimelineAnalysis::SetError(const char* format, ...) {
176 ASSERT(!has_error_);
177 ASSERT(error_msg_ == NULL);
178 has_error_ = true;
179 va_list args;
180 va_start(args, format);
181 error_msg_ = zone_->VPrint(format, args);
182 ASSERT(error_msg_ != NULL);
183 if (FLAG_trace_timeline_analysis) {
184 OS::PrintErr("TimelineAnalysis error = %s\n", error_msg_);
185 }
186}
187
188TimelineLabelPauseInfo::TimelineLabelPauseInfo(const char* name)
189 : name_(name),
190 inclusive_micros_(0),
191 exclusive_micros_(0),
192 max_inclusive_micros_(0),
193 max_exclusive_micros_(0) {
194 ASSERT(name_ != NULL);
195}
196
197void TimelineLabelPauseInfo::OnPush(int64_t micros, bool already_on_stack) {
198 UpdateInclusiveMicros(micros, already_on_stack);
199}
200
201void TimelineLabelPauseInfo::OnPop(int64_t exclusive_micros) {
202 UpdateExclusiveMicros(exclusive_micros);
203}
204
205void TimelineLabelPauseInfo::OnBeginPop(int64_t inclusive_micros,
206 int64_t exclusive_micros,
207 bool already_on_stack) {
208 UpdateInclusiveMicros(inclusive_micros, already_on_stack);
209 UpdateExclusiveMicros(exclusive_micros);
210}
211
212void TimelineLabelPauseInfo::UpdateInclusiveMicros(int64_t inclusive_micros,
213 bool already_on_stack) {
214 if (!already_on_stack) {
215 // Only adjust inclusive counts if we aren't already on the stack.
216 add_inclusive_micros(inclusive_micros);
217 if (inclusive_micros > max_inclusive_micros_) {
218 max_inclusive_micros_ = inclusive_micros;
219 }
220 }
221}
222
223void TimelineLabelPauseInfo::UpdateExclusiveMicros(int64_t exclusive_micros) {
224 add_exclusive_micros(exclusive_micros);
225 if (exclusive_micros > max_exclusive_micros_) {
226 max_exclusive_micros_ = exclusive_micros;
227 }
228}
229
230void TimelineLabelPauseInfo::Aggregate(
231 const TimelineLabelPauseInfo* thread_pause_info) {
232 ASSERT(thread_pause_info != NULL);
233 inclusive_micros_ += thread_pause_info->inclusive_micros_;
234 exclusive_micros_ += thread_pause_info->exclusive_micros_;
235 if (max_inclusive_micros_ < thread_pause_info->max_inclusive_micros_) {
236 max_inclusive_micros_ = thread_pause_info->max_inclusive_micros_;
237 }
238 if (max_exclusive_micros_ < thread_pause_info->max_exclusive_micros_) {
239 max_exclusive_micros_ = thread_pause_info->max_exclusive_micros_;
240 }
241}
242
243TimelinePauses::TimelinePauses(Zone* zone,
244 Isolate* isolate,
245 TimelineEventRecorder* recorder)
246 : TimelineAnalysis(zone, isolate, recorder) {}
247
248void TimelinePauses::Setup() {
249 BuildThreads();
250}
251
252void TimelinePauses::CalculatePauseTimesForThread(ThreadId tid) {
253 if (has_error()) {
254 return;
255 }
256 TimelineAnalysisThread* thread = GetThread(tid);
257 if (thread == NULL) {
258 SetError("Thread %" Pd " does not exist.", OSThread::ThreadIdToIntPtr(tid));
259 return;
260 }
261 ProcessThread(thread);
262}
263
264TimelineLabelPauseInfo* TimelinePauses::GetLabelPauseInfo(
265 const char* name) const {
266 ASSERT(name != NULL);
267 // Linear lookup because we expect N (# of labels in an isolate) to be small.
268 for (intptr_t i = 0; i < labels_.length(); i++) {
269 TimelineLabelPauseInfo* label = labels_.At(i);
270 if (strcmp(label->name(), name) == 0) {
271 return label;
272 }
273 }
274 return NULL;
275}
276
277int64_t TimelinePauses::InclusiveTime(const char* name) const {
278 TimelineLabelPauseInfo* pause_info = GetLabelPauseInfo(name);
279 ASSERT(pause_info != NULL);
280 return pause_info->inclusive_micros();
281}
282
283int64_t TimelinePauses::ExclusiveTime(const char* name) const {
284 TimelineLabelPauseInfo* pause_info = GetLabelPauseInfo(name);
285 ASSERT(pause_info != NULL);
286 return pause_info->exclusive_micros();
287}
288
289int64_t TimelinePauses::MaxInclusiveTime(const char* name) const {
290 TimelineLabelPauseInfo* pause_info = GetLabelPauseInfo(name);
291 ASSERT(pause_info != NULL);
292 return pause_info->max_inclusive_micros();
293}
294
295int64_t TimelinePauses::MaxExclusiveTime(const char* name) const {
296 TimelineLabelPauseInfo* pause_info = GetLabelPauseInfo(name);
297 ASSERT(pause_info != NULL);
298 return pause_info->max_exclusive_micros();
299}
300
301void TimelinePauses::ProcessThread(TimelineAnalysisThread* thread) {
302 ASSERT(thread != NULL);
303 stack_.Clear();
304 labels_.Clear();
305
306 TimelineAnalysisThreadEventIterator it(thread);
307 if (FLAG_trace_timeline_analysis) {
308 THR_Print(">>> TimelinePauses::ProcessThread %" Pd "\n",
309 OSThread::ThreadIdToIntPtr(thread->id()));
310 }
311 intptr_t event_count = 0;
312 while (!has_error() && it.HasNext()) {
313 TimelineEvent* event = it.Next();
314 if (event->isolate_id() != isolate_->main_port()) {
315 // Skip events that do not belong to the isolate.
316 continue;
317 }
318 if (event->IsFinishedDuration()) {
319 int64_t start = event->TimeOrigin();
320 PopFinishedDurations(start);
321 if (!CheckStack(event)) {
322 SetError("Duration check fail.");
323 return;
324 }
325 event_count++;
326 Push(event);
327 } else if (event->IsBeginOrEnd()) {
328 event_count++;
329 if (event->IsBegin()) {
330 PopFinishedDurations(event->TimeOrigin());
331 Push(event);
332 } else {
333 ASSERT(event->IsEnd());
334 PopFinishedDurations(event->TimeOrigin());
335 PopBegin(event->label(), event->TimeOrigin());
336 }
337 } else {
338 // Skip other event kinds.
339 }
340 }
341 // Pop remaining duration stack.
342 PopFinishedDurations(kMaxInt64);
343 if (FLAG_trace_timeline_analysis) {
344 THR_Print("<<< TimelinePauses::ProcessThread %" Pd " had %" Pd " events\n",
345 OSThread::ThreadIdToIntPtr(thread->id()), event_count);
346 }
347}
348
349// Verify that |event| is contained within all parent events on the stack.
350bool TimelinePauses::CheckStack(TimelineEvent* event) {
351 ASSERT(event != NULL);
352 for (intptr_t i = 0; i < stack_.length(); i++) {
353 const StackItem& slot = stack_.At(i);
354 if (slot.event->IsDuration()) {
355 if (!slot.event->DurationContains(event)) {
356 return false;
357 }
358 } else {
359 ASSERT(slot.event->IsBegin());
360 if (slot.event->TimeOrigin() > event->TimeOrigin()) {
361 return false;
362 }
363 }
364 }
365 return true;
366}
367
368void TimelinePauses::PopFinishedDurations(int64_t start) {
369 while (stack_.length() > 0) {
370 const StackItem& top = stack_.Last();
371 if (top.event->IsDuration() && top.event->DurationFinishedBefore(start)) {
372 top.pause_info->OnPop(top.exclusive_micros);
373 // Top of stack completes before |start|.
374 stack_.RemoveLast();
375 if (FLAG_trace_timeline_analysis) {
376 THR_Print("Popping %s (%" Pd64 " <= %" Pd64 ")\n", top.event->label(),
377 top.event->TimeEnd(), start);
378 }
379 } else {
380 return;
381 }
382 }
383}
384
385void TimelinePauses::PopBegin(const char* label, int64_t end) {
386 if (stack_.length() == 0) {
387 SetError("PopBegin(%s, ...) called with empty stack.", label);
388 return;
389 }
390 ASSERT(stack_.length() > 0);
391 const StackItem& top = stack_.Last();
392 const char* top_label = top.event->label();
393 const bool top_is_begin = top.event->IsBegin();
394 const int64_t start = top.event->TimeOrigin();
395 if (start > end) {
396 SetError("Bad time stamps for PopBegin(%s, ...) %" Pd64 " > %" Pd64 "",
397 label, start, end);
398 return;
399 }
400 const int64_t duration = end - start;
401 // Sanity checks.
402 if (strcmp(top_label, label) != 0) {
403 SetError("PopBegin(%s, ...) called with %s at the top of stack", label,
404 top.event->label());
405 return;
406 }
407 if (!top_is_begin) {
408 SetError("kEnd event not paired with kBegin event for label %s", label);
409 return;
410 }
411 // Pop this event.
412 // Add duration to exclusive micros.
413 if (FLAG_trace_timeline_analysis) {
414 THR_Print("Popping %s (%" Pd64 ")\n", top.event->label(), duration);
415 }
416 const int64_t exclusive_micros = top.exclusive_micros + duration;
417 stack_.RemoveLast();
418 top.pause_info->OnBeginPop(duration, exclusive_micros,
419 IsLabelOnStack(top_label));
420 if (StackDepth() > 0) {
421 StackItem& top = GetStackTop();
422 // |top| is under the popped |event|'s shadow, adjust the exclusive micros.
423 top.exclusive_micros -= duration;
424 }
425}
426
427void TimelinePauses::Push(TimelineEvent* event) {
428 TimelineLabelPauseInfo* pause_info = GetOrAddLabelPauseInfo(event->label());
429 ASSERT(pause_info != NULL);
430 // |pause_info| will be running for |event->TimeDuration()|.
431 if (FLAG_trace_timeline_analysis) {
432 THR_Print("Pushing %s %" Pd64 " us\n", pause_info->name(),
433 event->TimeDuration());
434 }
435 if (event->IsDuration()) {
436 pause_info->OnPush(event->TimeDuration(), IsLabelOnStack(event->label()));
437 if (StackDepth() > 0) {
438 StackItem& top = GetStackTop();
439 // |top| is under |event|'s shadow, adjust the exclusive micros.
440 top.exclusive_micros -= event->TimeDuration();
441 }
442 // Push onto the stack.
443 StackItem item;
444 item.event = event;
445 item.pause_info = pause_info;
446 item.exclusive_micros = event->TimeDuration();
447 stack_.Add(item);
448 } else {
449 ASSERT(event->IsBegin());
450 pause_info->OnPush(0, IsLabelOnStack(event->label()));
451 // Push onto the stack.
452 StackItem item;
453 item.event = event;
454 item.pause_info = pause_info;
455 item.exclusive_micros = 0;
456 stack_.Add(item);
457 }
458}
459
460bool TimelinePauses::IsLabelOnStack(const char* label) const {
461 ASSERT(label != NULL);
462 for (intptr_t i = 0; i < stack_.length(); i++) {
463 const StackItem& slot = stack_.At(i);
464 if (strcmp(slot.event->label(), label) == 0) {
465 return true;
466 }
467 }
468 return false;
469}
470
471intptr_t TimelinePauses::StackDepth() const {
472 return stack_.length();
473}
474
475TimelinePauses::StackItem& TimelinePauses::GetStackTop() {
476 ASSERT(stack_.length() > 0);
477 return stack_.Last();
478}
479
480TimelineLabelPauseInfo* TimelinePauses::GetOrAddLabelPauseInfo(
481 const char* name) {
482 ASSERT(name != NULL);
483 TimelineLabelPauseInfo* pause_info = GetLabelPauseInfo(name);
484 if (pause_info != NULL) {
485 return pause_info;
486 }
487 // New label.
488 pause_info = new TimelineLabelPauseInfo(name);
489 labels_.Add(pause_info);
490 return pause_info;
491}
492
493TimelinePauseTrace::TimelinePauseTrace() {}
494
495TimelinePauseTrace::~TimelinePauseTrace() {}
496
497void TimelinePauseTrace::Print() {
498 Thread* thread = Thread::Current();
499 ASSERT(thread != NULL);
500 Isolate* isolate = thread->isolate();
501 ASSERT(isolate != NULL);
502 Zone* zone = thread->zone();
503 ASSERT(zone != NULL);
504 TimelineEventRecorder* recorder = Timeline::recorder();
505 ASSERT(recorder != NULL);
506 TimelinePauses pauses(zone, isolate, recorder);
507 pauses.Setup();
508
509 THR_Print("Timing for isolate (%" Pd64 ") '%s' (from %" Pd " threads)\n",
510 static_cast<int64_t>(isolate->main_port()), isolate->name(),
511 pauses.NumThreads());
512 THR_Print("\n");
513 for (intptr_t t_idx = 0; t_idx < pauses.NumThreads(); t_idx++) {
514 TimelineAnalysisThread* tat = pauses.At(t_idx);
515 ASSERT(tat != NULL);
516 pauses.CalculatePauseTimesForThread(tat->id());
517 THR_Print("Thread %" Pd " (%" Pd "):\n", t_idx,
518 OSThread::ThreadIdToIntPtr(tat->id()));
519 for (intptr_t j = 0; j < pauses.NumPauseInfos(); j++) {
520 const TimelineLabelPauseInfo* pause_info = pauses.PauseInfoAt(j);
521 ASSERT(pause_info != NULL);
522 Aggregate(pause_info);
523 PrintPauseInfo(pause_info);
524 }
525 THR_Print("\n");
526 }
527 THR_Print("Totals:\n");
528 for (intptr_t i = 0; i < isolate_labels_.length(); i++) {
529 TimelineLabelPauseInfo* pause_info = isolate_labels_.At(i);
530 ASSERT(pause_info != NULL);
531 PrintPauseInfo(pause_info);
532 }
533 THR_Print("\n");
534}
535
536TimelineLabelPauseInfo* TimelinePauseTrace::GetOrAddLabelPauseInfo(
537 const char* name) {
538 ASSERT(name != NULL);
539 // Linear lookup because we expect N (# of labels in an isolate) to be small.
540 for (intptr_t i = 0; i < isolate_labels_.length(); i++) {
541 TimelineLabelPauseInfo* label = isolate_labels_.At(i);
542 if (strcmp(label->name(), name) == 0) {
543 return label;
544 }
545 }
546 // New label.
547 TimelineLabelPauseInfo* pause_info = new TimelineLabelPauseInfo(name);
548 isolate_labels_.Add(pause_info);
549 return pause_info;
550}
551
552void TimelinePauseTrace::Aggregate(
553 const TimelineLabelPauseInfo* thread_pause_info) {
554 ASSERT(thread_pause_info != NULL);
555 TimelineLabelPauseInfo* isolate_pause_info =
556 GetOrAddLabelPauseInfo(thread_pause_info->name());
557 ASSERT(isolate_pause_info != NULL);
558 isolate_pause_info->Aggregate(thread_pause_info);
559}
560
561void TimelinePauseTrace::PrintPauseInfo(
562 const TimelineLabelPauseInfo* pause_info) {
563 ASSERT(pause_info != NULL);
564 THR_Print("%s : ", pause_info->name());
565 THR_Print("%.3f ms total on stack; ",
566 MicrosecondsToMilliseconds(pause_info->inclusive_micros()));
567 THR_Print("%.3f ms total executing; ",
568 MicrosecondsToMilliseconds(pause_info->exclusive_micros()));
569 THR_Print("%.3f ms max on stack; ",
570 MicrosecondsToMilliseconds(pause_info->max_inclusive_micros()));
571 THR_Print("%.3f ms max executing.\n",
572 MicrosecondsToMilliseconds(pause_info->max_exclusive_micros()));
573}
574
575#endif // !PRODUCT
576
577} // namespace dart
578