Switch to a VM wide timeline recorder

runtime/vm/timeline.cc

Index: runtime/vm/timeline.cc
diff --git a/runtime/vm/timeline.cc b/runtime/vm/timeline.cc
index 833d1f8b6199403df773689eb24ca4412abd70b5..7e36a26979345bcd84fd0ba89748f7eb2e699b4b 100644
--- a/runtime/vm/timeline.cc
+++ b/runtime/vm/timeline.cc
@@ -4,6 +4,7 @@
 
 #include <cstdlib>
 
+#include "vm/atomic.h"
 #include "vm/isolate.h"
 #include "vm/json_stream.h"
 #include "vm/lockers.h"
@@ -16,6 +17,58 @@ namespace dart {
 DEFINE_FLAG(bool, trace_timeline, false, "Trace timeline backend");
 DEFINE_FLAG(bool, complete_timeline, false, "Record the complete timeline");
 
+DEFINE_FLAG(charp, timeline_dir, NULL,
+            "Enable all timeline trace streams and output VM global trace "
+            "into specified directory.");
+
+void Timeline::InitOnce() {
+  ASSERT(recorder_ == NULL);
+  // Default to ring recorder being enabled.
+  const bool use_ring_recorder = true;
+  // Some flags require that we use the endless recorder.
+  const bool use_endless_recorder = (FLAG_timeline_dir != NULL);
+  if (use_endless_recorder) {
+    recorder_ = new TimelineEventEndlessRecorder();
+  } else if (use_ring_recorder) {
+    recorder_ = new TimelineEventRingRecorder();
+  }
+  vm_stream_ = new TimelineStream();
+  vm_stream_->Init("VM", EnableStreamByDefault("VM"));
+}
+
+
+void Timeline::Shutdown() {
+  ASSERT(recorder_ != NULL);
+  if (FLAG_timeline_dir != NULL) {
+    recorder_->WriteTo(FLAG_timeline_dir);
+  }
+  delete recorder_;
+  recorder_ = NULL;
+  delete vm_stream_;
+  vm_stream_ = NULL;
+}
+
+
+TimelineEventRecorder* Timeline::recorder() {
+  return recorder_;
+}
+
+
+bool Timeline::EnableStreamByDefault(const char* stream_name) {
+  // TODO(johnmccutchan): Allow for command line control over streams.
+  return FLAG_timeline_dir != NULL;
+}
+
+
+TimelineStream* Timeline::GetVMStream() {
+  ASSERT(vm_stream_ != NULL);
+  return vm_stream_;
+}
+
+
+TimelineEventRecorder* Timeline::recorder_ = NULL;
+TimelineStream* Timeline::vm_stream_ = NULL;
+
 TimelineEvent::TimelineEvent()
     : timestamp0_(0),
       timestamp1_(0),
@@ -23,7 +76,7 @@ TimelineEvent::TimelineEvent()
       arguments_length_(0),
       state_(0),
       label_(NULL),
-      stream_(NULL),
+      category_(""),
       thread_(OSThread::kInvalidThreadId) {
 }
 
@@ -36,20 +89,18 @@ TimelineEvent::~TimelineEvent() {
 void TimelineEvent::Reset() {
   set_event_type(kNone);
   thread_ = OSThread::kInvalidThreadId;
-  stream_ = NULL;
+  isolate_ = NULL;
+  category_ = "";
   label_ = NULL;
   FreeArguments();
 }
 
 
-int64_t TimelineEvent::AsyncBegin(const char* label) {
+void TimelineEvent::AsyncBegin(const char* label, int64_t async_id) {
   Init(kAsyncBegin, label);
   timestamp0_ = OS::GetCurrentTimeMicros();
-  ASSERT(stream_ != NULL);
-  int64_t async_id = stream_->GetNextSeq();
   // Overload timestamp1_ with the async_id.
-  timestamp1_ = async_id;
-  return async_id;
+  timestamp1_ = static_cast<int64_t>(async_id);

[rmacnak, 2015/08/18 21:09:00]

Unnecessary cast

[Cutch, 2015/08/18 21:50:18]

Done.

 }
 
 
@@ -58,7 +109,7 @@ void TimelineEvent::AsyncInstant(const char* label,
   Init(kAsyncInstant, label);
   timestamp0_ = OS::GetCurrentTimeMicros();
   // Overload timestamp1_ with the async_id.
-  timestamp1_ = async_id;
+  timestamp1_ = static_cast<int64_t>(async_id);;

[rmacnak, 2015/08/18 21:09:00]

"

[Cutch, 2015/08/18 21:50:18]

Done.

 }
 
 
@@ -67,7 +118,7 @@ void TimelineEvent::AsyncEnd(const char* label,
   Init(kAsyncEnd, label);
   timestamp0_ = OS::GetCurrentTimeMicros();
   // Overload timestamp1_ with the async_id.
-  timestamp1_ = async_id;
+  timestamp1_ = static_cast<int64_t>(async_id);;

[rmacnak, 2015/08/18 21:09:00]

"

[Cutch, 2015/08/18 21:50:18]

Done.

 }
 
 
@@ -142,7 +193,10 @@ void TimelineEvent::CopyArgument(intptr_t i,
 
 
 void TimelineEvent::Complete() {
-  stream_->CompleteEvent(this);
+  TimelineEventRecorder* recorder = Timeline::recorder();
+  if (recorder != NULL) {
+    recorder->CompleteEvent(this);
+  }
 }
 
 
@@ -160,8 +214,11 @@ void TimelineEvent::FreeArguments() {
 
 
 void TimelineEvent::StreamInit(TimelineStream* stream) {
-  ASSERT(stream != NULL);
-  stream_ = stream;
+  if (stream != NULL) {
+    category_ = stream->name();
+  } else {
+    category_ = "";
+  }
 }
 
 
@@ -172,6 +229,7 @@ void TimelineEvent::Init(EventType event_type,
   timestamp0_ = 0;
   timestamp1_ = 0;
   thread_ = OSThread::GetCurrentThreadId();
+  isolate_ = Isolate::Current();
   label_ = label;
   FreeArguments();
 }
@@ -182,7 +240,7 @@ void TimelineEvent::PrintJSON(JSONStream* stream) const {
   int64_t pid = OS::ProcessId();
   int64_t tid = OSThread::ThreadIdToIntPtr(thread_);
   obj.AddProperty("name", label_);
-  obj.AddProperty("cat", stream_->name());
+  obj.AddProperty("cat", category_);
   obj.AddProperty64("tid", tid);
   obj.AddProperty64("pid", pid);
   obj.AddPropertyTimeMillis("ts", TimeOrigin());
@@ -246,10 +304,8 @@ int64_t TimelineEvent::TimeDuration() const {
 
 
 TimelineStream::TimelineStream()
-    : recorder_(NULL),
-      name_(NULL),
-      enabled_(false),
-      seq_(0) {
+    : name_(NULL),
+      enabled_(false) {
 }
 
 
@@ -260,11 +316,12 @@ void TimelineStream::Init(const char* name, bool enabled) {
 
 
 TimelineEvent* TimelineStream::StartEvent() {
-  if (!enabled_ || (recorder_ == NULL)) {
+  TimelineEventRecorder* recorder = Timeline::recorder();
+  if (!enabled_ || (recorder == NULL)) {
     return NULL;
   }
   ASSERT(name_ != NULL);
-  TimelineEvent* event = recorder_->StartEvent();
+  TimelineEvent* event = recorder->StartEvent();
   if (event != NULL) {
     event->StreamInit(this);
   }
@@ -272,23 +329,6 @@ TimelineEvent* TimelineStream::StartEvent() {
 }
 
 
-void TimelineStream::CompleteEvent(TimelineEvent* event) {
-  if (!enabled_ || (recorder_ == NULL)) {
-    return;
-  }
-  recorder_->CompleteEvent(event);
-}
-
-
-int64_t TimelineStream::GetNextSeq() {
-  seq_++;
-  if (seq_ < 0) {
-    seq_ = 0;
-  }
-  return seq_;
-}
-
-
 void TimelineDurationScope::FormatArgument(intptr_t i,
                                            const char* name,
                                            const char* fmt, ...) {
@@ -310,7 +350,22 @@ void TimelineDurationScope::FormatArgument(intptr_t i,
 }
 
 
-TimelineEventRecorder::TimelineEventRecorder() {
+TimelineEventFilter::TimelineEventFilter() {
+}
+
+
+TimelineEventFilter::~TimelineEventFilter() {
+}
+
+
+IsolateTimelineEventFilter::IsolateTimelineEventFilter(Isolate* isolate)
+    : isolate_(isolate) {
+}
+
+
+TimelineEventRecorder::TimelineEventRecorder()
+    : global_block_(NULL),
+      async_id_(0) {
 }
 
 
@@ -321,25 +376,58 @@ void TimelineEventRecorder::PrintJSONMeta(JSONArray* events) const {
 TimelineEvent* TimelineEventRecorder::ThreadBlockStartEvent() {
   // Grab the thread's timeline event block.
   Thread* thread = Thread::Current();
+  ASSERT(thread != NULL);
+
+  if (thread->isolate() == NULL) {
+    // Non-isolate thread case. This should be infrequent.
+    return GlobalBlockStartEvent();
+  }
+
   TimelineEventBlock* thread_block = thread->timeline_block();
-  if ((thread_block == NULL) || thread_block->IsFull()) {
-    // If it is full, request a new block.
-    thread_block = GetNewBlock();
+
+  if ((thread_block != NULL) && thread_block->IsFull()) {
+    MutexLocker ml(&lock_);
+    // Thread has a block and it is full:
+    // 1) Mark it as finished.
+    thread_block->Finish();
+    // 2) Allocate a new block.
+    thread_block = GetNewBlockLocked(thread->isolate());
+    thread->set_timeline_block(thread_block);
+  } else if (thread_block == NULL) {
+    MutexLocker ml(&lock_);
+    // Thread has no block. Attempt to allocate one.
+    thread_block = GetNewBlockLocked(thread->isolate());
     thread->set_timeline_block(thread_block);
   }
-  if (thread_block == NULL) {
-    // Could not allocate block.
-    return NULL;
+  if (thread_block != NULL) {
+    ASSERT(!thread_block->IsFull());
+    return thread_block->StartEvent();
   }
-  ASSERT(thread_block != NULL);
-  ASSERT(!thread_block->IsFull());
-  return thread_block->StartEvent();
+  return NULL;
 }
 
 
-void TimelineEventRecorder::WriteTo(const char* directory) {
-  Isolate* isolate = Isolate::Current();
 
+TimelineEvent* TimelineEventRecorder::GlobalBlockStartEvent() {
+  MutexLocker ml(&lock_);
+  if ((global_block_ != NULL) && global_block_->IsFull()) {
+    // Global block is full.
+    global_block_->Finish();
+    global_block_ = NULL;
+  }
+  if (global_block_ == NULL) {
+    // Allocate a new block.
+    global_block_ = GetNewBlockLocked(NULL);
+  }
+  if (global_block_ != NULL) {
+    ASSERT(!global_block_->IsFull());
+    return global_block_->StartEvent();
+  }
+  return NULL;
+}
+
+
+void TimelineEventRecorder::WriteTo(const char* directory) {
   Dart_FileOpenCallback file_open = Isolate::file_open_callback();
   Dart_FileWriteCallback file_write = Isolate::file_write_callback();
   Dart_FileCloseCallback file_close = Isolate::file_close_callback();
@@ -348,29 +436,42 @@ void TimelineEventRecorder::WriteTo(const char* directory) {
   }
 
   JSONStream js;
-  PrintJSON(&js);
+  TimelineEventFilter filter;
+  PrintJSON(&js, &filter);
 
-  const char* format = "%s/dart-timeline-%" Pd "-%" Pd ".json";
+  const char* format = "%s/dart-timeline-%" Pd ".json";
   intptr_t pid = OS::ProcessId();
-  intptr_t len = OS::SNPrint(NULL, 0, format,
-                             directory, pid, isolate->main_port());
-  char* filename = Thread::Current()->zone()->Alloc<char>(len + 1);
-  OS::SNPrint(filename, len + 1, format,
-              directory, pid, isolate->main_port());
+  intptr_t len = OS::SNPrint(NULL, 0, format, directory, pid);
+  char* filename = reinterpret_cast<char*>(malloc(len + 1));
+  OS::SNPrint(filename, len + 1, format, directory, pid);
   void* file = (*file_open)(filename, true);
   if (file == NULL) {
     OS::Print("Failed to write timeline file: %s\n", filename);
+    free(filename);
     return;
   }
+  free(filename);
   (*file_write)(js.buffer()->buf(), js.buffer()->length(), file);
   (*file_close)(file);
 }
 
 
+int64_t TimelineEventRecorder::GetNextAsyncId() {
+  // TODO(johnmccutchan): Gracefully handle wrap around.
+  uint32_t next = static_cast<uint32_t>(
+      AtomicOperations::FetchAndIncrement(&async_id_));
+  return static_cast<int64_t>(next);
+}
+
+
+TimelineEventBlock* TimelineEventRecorder::GetNewBlock() {
+  MutexLocker ml(&lock_);
+  return GetNewBlockLocked(Isolate::Current());
+}
+
 
 TimelineEventRingRecorder::TimelineEventRingRecorder(intptr_t capacity)
     : blocks_(NULL),
-      event_objects_(Array::null()),
       capacity_(capacity),
       num_blocks_(0),
       block_cursor_(0) {
@@ -389,8 +490,6 @@ TimelineEventRingRecorder::TimelineEventRingRecorder(intptr_t capacity)
   for (intptr_t i = 0; i < num_blocks_ - 1; i++) {
     blocks_[i]->set_next(blocks_[i + 1]);
   }
-  const Array& array = Array::Handle(Array::New(capacity, Heap::kOld));
-  event_objects_ = array.raw();
 }
 
 
@@ -401,11 +500,12 @@ TimelineEventRingRecorder::~TimelineEventRingRecorder() {
     delete block;
   }
   free(blocks_);
-  event_objects_ = Array::null();
 }
 
 
-void TimelineEventRingRecorder::PrintJSONEvents(JSONArray* events) const {
+void TimelineEventRingRecorder::PrintJSONEvents(
+    JSONArray* events,
+    TimelineEventFilter* filter) const {
   intptr_t block_offset = FindOldestBlockIndex();
   if (block_offset == -1) {
     // All blocks are empty.
@@ -428,35 +528,34 @@ void TimelineEventRingRecorder::PrintJSONEvents(JSONArray* events) const {
 }
 
 
-void TimelineEventRingRecorder::PrintJSON(JSONStream* js) {
+void TimelineEventRingRecorder::PrintJSON(JSONStream* js,
+                                          TimelineEventFilter* filter) {
   MutexLocker ml(&lock_);
   JSONObject topLevel(js);
   topLevel.AddProperty("type", "_Timeline");
   {
     JSONArray events(&topLevel, "traceEvents");
     PrintJSONMeta(&events);
-    PrintJSONEvents(&events);
+    PrintJSONEvents(&events, filter);
   }
 }
 
 
-TimelineEventBlock* TimelineEventRingRecorder::GetNewBlock() {
-  MutexLocker ml(&lock_);
-  return GetNewBlockLocked();
-}
-
-
-TimelineEventBlock* TimelineEventRingRecorder::GetHeadBlock() {
+TimelineEventBlock* TimelineEventRingRecorder::GetHeadBlockLocked() {
   return blocks_[0];
 }
 
 
-TimelineEventBlock* TimelineEventRingRecorder::GetNewBlockLocked() {
+TimelineEventBlock* TimelineEventRingRecorder::GetNewBlockLocked(
+    Isolate* isolate) {
+  // TODO(johnmccutchan): This function should only hand out blocks
+  // which have been marked as finished.
   if (block_cursor_ == num_blocks_) {
     block_cursor_ = 0;
   }
   TimelineEventBlock* block = blocks_[block_cursor_++];
   block->Reset();
+  block->Open(isolate);
   return block;
 }
 
@@ -497,7 +596,8 @@ TimelineEventStreamingRecorder::~TimelineEventStreamingRecorder() {
 }
 
 
-void TimelineEventStreamingRecorder::PrintJSON(JSONStream* js) {
+void TimelineEventStreamingRecorder::PrintJSON(JSONStream* js,
+                                               TimelineEventFilter* filter) {
   JSONObject topLevel(js);
   topLevel.AddProperty("type", "_Timeline");
   {
@@ -526,25 +626,20 @@ TimelineEventEndlessRecorder::TimelineEventEndlessRecorder()
 }
 
 
-void TimelineEventEndlessRecorder::PrintJSON(JSONStream* js) {
+void TimelineEventEndlessRecorder::PrintJSON(JSONStream* js,
+                                             TimelineEventFilter* filter) {
   MutexLocker ml(&lock_);
   JSONObject topLevel(js);
   topLevel.AddProperty("type", "_Timeline");
   {
     JSONArray events(&topLevel, "traceEvents");
     PrintJSONMeta(&events);
-    PrintJSONEvents(&events);
+    PrintJSONEvents(&events, filter);
   }
 }
 
 
-TimelineEventBlock* TimelineEventEndlessRecorder::GetNewBlock() {
-  MutexLocker ml(&lock_);
-  return GetNewBlockLocked();
-}
-
-
-TimelineEventBlock* TimelineEventEndlessRecorder::GetHeadBlock() {
+TimelineEventBlock* TimelineEventEndlessRecorder::GetHeadBlockLocked() {
   return head_;
 }
 
@@ -559,16 +654,21 @@ void TimelineEventEndlessRecorder::CompleteEvent(TimelineEvent* event) {
 }
 
 
-TimelineEventBlock* TimelineEventEndlessRecorder::GetNewBlockLocked() {
+TimelineEventBlock* TimelineEventEndlessRecorder::GetNewBlockLocked(
+    Isolate* isolate) {
   TimelineEventBlock* block = new TimelineEventBlock(block_index_++);
   block->set_next(head_);
+  block->Open(isolate);
   head_ = block;
   return head_;
 }
 
 
-void TimelineEventEndlessRecorder::PrintJSONEvents(JSONArray* events) const {
+void TimelineEventEndlessRecorder::PrintJSONEvents(
+    JSONArray* events,
+    TimelineEventFilter* filter) const {
   TimelineEventBlock* current = head_;
+
   while (current != NULL) {
     intptr_t length = current->length();
     for (intptr_t i = 0; i < length; i++) {
@@ -659,6 +759,19 @@ void TimelineEventBlock::Reset() {
     events_[i].Reset();
   }
   length_ = 0;
+  isolate_ = NULL;
+  open_ = false;
+}
+
+
+void TimelineEventBlock::Open(Isolate* isolate) {
+  isolate_ = isolate;
+  open_ = true;
+}
+
+
+void TimelineEventBlock::Finish() {
+  open_ = false;
 }
 
 
@@ -689,7 +802,7 @@ void TimelineEventBlockIterator::Reset(TimelineEventRecorder* recorder) {
   // Lock new recorder.
   recorder_->lock_.Lock();
   // Queue up first block.
-  current_ = recorder_->GetHeadBlock();
+  current_ = recorder_->GetHeadBlockLocked();
 }