Sampling profiler

runtime/vm/profiler.cc

+// Copyright (c) 2013, 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 <cstdio>
+
+#include "platform/utils.h"
+
+#include "vm/isolate.h"
+#include "vm/json_stream.h"
+#include "vm/native_symbol.h"
+#include "vm/object.h"
+#include "vm/os.h"
+#include "vm/profiler.h"
+
+namespace dart {
+
+DEFINE_FLAG(bool, profile, true, "Enable Sampling Profiler");
+
+bool ProfilerManager::initialized_ = false;
+bool ProfilerManager::shutdown_ = false;
+Monitor* ProfilerManager::monitor_ = NULL;
+Isolate** ProfilerManager::isolates_ = NULL;
+intptr_t ProfilerManager::isolates_capacity_ = 0;
+intptr_t ProfilerManager::isolates_size_ = 0;
+
+
+void ProfilerManager::InitOnce() {
+  if (!FLAG_profile) {
+    return;
+  }
+  NativeSymbolResolver::InitOnce();
+  ASSERT(!initialized_);
+  monitor_ = new Monitor();
+  initialized_ = true;
+  ResizeIsolates(16);
+  Thread::Start(ThreadMain, 0);
+}
+
+
+void ProfilerManager::Shutdown() {
+  if (!FLAG_profile) {
+    return;
+  }
+  ScopedMonitorLock lock(monitor_);
+  shutdown_ = true;
+  for (intptr_t i = 0; i < isolates_size_; i++) {
+    Isolate* isolate = isolates_[i];
+    ASSERT(isolate != NULL);
+    ScopedMutexLock profiler_data_lock(isolate->profiler_data_mutex());
+    FreeIsolateProfilingData(isolate);
+  }
+  isolates_size_ = 0;

[siva, 2013/11/11 03:51:54]

a free of isolates_ also needs to be done here?

[Cutch, 2013/11/18 20:48:54]

Done.

+  lock.Notify();
+  NativeSymbolResolver::ShutdownOnce();
+}
+
+
+void ProfilerManager::SetupIsolateForProfiling(Isolate* isolate) {
+  if (!FLAG_profile) {
+    return;
+  }
+  ASSERT(isolate != NULL);
+  ScopedMutexLock profiler_data_lock(isolate->profiler_data_mutex());
+  SampleBuffer* sample_buffer = new SampleBuffer();
+  IsolateProfilerData* profiler_data =
+      new IsolateProfilerData(isolate, sample_buffer);
+  profiler_data->set_sample_interval(1000);
+  isolate->set_profiler_data(profiler_data);
+}
+
+
+void ProfilerManager::FreeIsolateProfilingData(Isolate* isolate) {
+  // TODO(johnmccutchan): Move ScopedMutexLock here and remove from
+  // two call sites.
+  IsolateProfilerData* profiler_data = isolate->profiler_data();
+  if (profiler_data == NULL) {
+    // Already freed.
+    return;
+  }
+  isolate->set_profiler_data(NULL);
+  SampleBuffer* sample_buffer = profiler_data->sample_buffer();
+  ASSERT(sample_buffer != NULL);
+  delete sample_buffer;
+  delete profiler_data;
+}
+
+
+void ProfilerManager::ShutdownIsolateForProfiling(Isolate* isolate) {
+  ASSERT(isolate != NULL);
+  if (!FLAG_profile) {
+    return;
+  }
+  ScopedMutexLock profiler_data_lock(isolate->profiler_data_mutex());
+  FreeIsolateProfilingData(isolate);
+}
+
+
+void ProfilerManager::ScheduleIsolate(Isolate* isolate) {
+  if (!FLAG_profile) {
+    return;
+  }
+  ASSERT(initialized_);
+  ASSERT(isolate != NULL);
+  ScopedMonitorLock lock(monitor_);
+  ScopedMutexLock profiler_data_lock(isolate->profiler_data_mutex());

[siva, 2013/11/11 03:51:54]

Maybe later you should consider adding a locking order value to the mutexes and
ensure that this locking order is always maintained.

+  IsolateProfilerData* profiler_data = isolate->profiler_data();
+  if (profiler_data == NULL) {
+    return;
+  }
+  profiler_data->Scheduled(OS::GetCurrentTimeMicros(),
+                           Thread::GetCurrentThreadId());
+  AddIsolate(isolate);
+  lock.Notify();
+}
+
+
+void ProfilerManager::DescheduleIsolate(Isolate* isolate) {
+  if (!FLAG_profile) {
+    return;
+  }
+  ASSERT(initialized_);
+  ASSERT(isolate != NULL);
+  ScopedMonitorLock lock(monitor_);
+  intptr_t i = FindIsolate(isolate);
+  if (i < 0) {
+    // Not scheduled.
+    return;
+  }
+  {
+    ScopedMutexLock profiler_data_lock(isolate->profiler_data_mutex());
+    IsolateProfilerData* profiler_data = isolate->profiler_data();
+    ASSERT(profiler_data != NULL);
+    profiler_data->Descheduled();
+  }
+  RemoveIsolate(i);
+  lock.Notify();
+}
+
+
+void PrintToJSONStream(Isolate* isolate, JSONStream* stream) {
+  ASSERT(isolate == Isolate::Current());
+  {
+    // We can't get signals here.
+  }
+  UNIMPLEMENTED();
+}
+
+
+void ProfilerManager::ResizeIsolates(intptr_t new_capacity) {
+  ASSERT(new_capacity > isolates_capacity_);
+  Isolate* isolate = NULL;
+  isolates_ = reinterpret_cast<Isolate**>(
+      realloc(isolates_, sizeof(isolate) * new_capacity));

[siva, 2013/11/11 03:51:54]

we need to ensure that this does not overflow, maybe we need a limit for the
number of isolates we will support.

[Cutch, 2013/11/18 20:48:54]

Done. For now I just assert we aren't monitoring more than 4K isolates. In the
future we may need to spin up a new ProfilerManager to spread the load.

+  isolates_capacity_ = new_capacity;
+}
+
+
+void ProfilerManager::AddIsolate(Isolate* isolate) {

[siva, 2013/11/11 03:51:54]

you should add a comment here and in FindIsolate, RemoveIsolate that the
monitor_ lock needs to be held when these functions are called.

[Cutch, 2013/11/18 20:48:54]

Done.

+  if (isolates_size_ == isolates_capacity_) {
+    ResizeIsolates(isolates_capacity_ == 0 ? 16 : isolates_capacity_ * 2);
+  }
+  isolates_[isolates_size_] = isolate;
+  isolates_size_++;
+}
+
+
+intptr_t ProfilerManager::FindIsolate(Isolate* isolate) {
+  for (intptr_t i = 0; i < isolates_size_; i++) {
+    if (isolates_[i] == isolate) {
+      return i;
+    }
+  }
+  return -1;
+}
+
+
+void ProfilerManager::RemoveIsolate(intptr_t i) {
+  ASSERT(i < isolates_size_);
+  intptr_t last = isolates_size_ - 1;
+  if (i != last) {
+    isolates_[i] = isolates_[last];
+  }
+  // Mark last as NULL.
+  isolates_[last] = NULL;
+  // Pop.
+  isolates_size_--;
+}
+
+
+static char* FindSymbolName(uintptr_t pc, bool* native_symbol) {
+  // TODO(johnmccutchan): Differentiate between symbols which can't be found
+  // and symbols which were GCed. (Heap::CodeContains).
+  ASSERT(native_symbol != NULL);
+  const char* symbol_name = "Unknown";
+  *native_symbol = false;
+  const Code& code = Code::Handle(Code::LookupCode(pc));
+  if (code.IsNull()) {
+    // Possibly a native symbol.
+    char* native_name = NativeSymbolResolver::LookupSymbolName(pc);
+    if (native_name != NULL) {
+      symbol_name = native_name;
+      *native_symbol = true;
+    }
+  } else {
+    const Function& function = Function::Handle(code.function());
+    if (!function.IsNull()) {
+      const String& name = String::Handle(function.QualifiedUserVisibleName());
+      if (!name.IsNull()) {
+        symbol_name = name.ToCString();
+      }
+    }
+  }
+  return const_cast<char*>(symbol_name);
+}
+
+
+void ProfilerManager::WriteTracing(Isolate* isolate, const char* name,
+                                   Dart_Port port) {
+  ASSERT(isolate == Isolate::Current());
+  ScopedMutexLock profiler_data_lock(isolate->profiler_data_mutex());
+  IsolateProfilerData* profiler_data = isolate->profiler_data();
+  if (profiler_data == NULL) {
+    return;
+  }
+  SampleBuffer* sample_buffer = profiler_data->sample_buffer();
+  ASSERT(sample_buffer != NULL);
+  JSONStream stream(10 * MB);
+  intptr_t tid = reinterpret_cast<intptr_t>(sample_buffer);
+  intptr_t pid = 1;
+  {
+    JSONArray events(&stream);
+    {
+      JSONObject thread_name(&events);
+      thread_name.AddProperty("name", "thread_name");
+      thread_name.AddProperty("ph", "M");
+      thread_name.AddProperty("tid", tid);
+      thread_name.AddProperty("pid", pid);
+      {
+        JSONObject args(&thread_name, "args");
+        args.AddProperty("name", name);
+      }
+    }
+    {
+      JSONObject process_name(&events);
+      process_name.AddProperty("name", "process_name");
+      process_name.AddProperty("ph", "M");
+      process_name.AddProperty("tid", tid);
+      process_name.AddProperty("pid", pid);
+      {
+        JSONObject args(&process_name, "args");
+        args.AddProperty("name", "Dart VM");
+      }
+    }
+    uint64_t last_time = 0;
+    for (Sample* i = sample_buffer->FirstSample();
+         i != sample_buffer->LastSample();
+         i = sample_buffer->NextSample(i)) {
+      if (last_time == 0) {
+        last_time = i->timestamp;
+      }
+      intptr_t delta = i->timestamp - last_time;
+      {
+        double percentage = static_cast<double>(i->cpu_usage) /
+                            static_cast<double>(delta) * 100.0;
+        if (percentage != percentage) {
+          percentage = 0.0;
+        }
+        percentage = percentage < 0.0 ? 0.0 : percentage;
+        percentage = percentage > 100.0 ? 100.0 : percentage;
+        {
+          JSONObject cpu_usage(&events);
+          cpu_usage.AddProperty("name", "CPU Usage");
+          cpu_usage.AddProperty("ph", "C");
+          cpu_usage.AddProperty("tid", tid);
+          cpu_usage.AddProperty("pid", pid);
+          cpu_usage.AddProperty("ts", static_cast<double>(last_time));
+          {
+            JSONObject args(&cpu_usage, "args");
+            args.AddProperty("CPU", percentage);
+          }
+        }
+        {
+          JSONObject cpu_usage(&events);
+          cpu_usage.AddProperty("name", "CPU Usage");
+          cpu_usage.AddProperty("ph", "C");
+          cpu_usage.AddProperty("tid", tid);
+          cpu_usage.AddProperty("pid", pid);
+          cpu_usage.AddProperty("ts", static_cast<double>(i->timestamp));
+          {
+            JSONObject args(&cpu_usage, "args");
+            args.AddProperty("CPU", percentage);
+          }
+        }
+      }
+      for (int j = 0; j < Sample::kNumStackFrames; j++) {
+        if (i->pcs[j] == 0) {
+          continue;
+        }
+        bool native_symbol = false;
+        char* symbol_name = FindSymbolName(i->pcs[j], &native_symbol);
+        {
+          JSONObject begin(&events);
+          begin.AddProperty("ph", "B");
+          begin.AddProperty("tid", tid);
+          begin.AddProperty("pid", pid);
+          begin.AddProperty("name", symbol_name);
+          begin.AddProperty("ts", static_cast<double>(last_time));
+        }
+        if (native_symbol) {
+          NativeSymbolResolver::FreeSymbolName(symbol_name);
+        }
+      }
+      for (int j = Sample::kNumStackFrames-1; j >= 0; j--) {
+        if (i->pcs[j] == 0) {
+          continue;
+        }
+        bool native_symbol = false;
+        char* symbol_name = FindSymbolName(i->pcs[j], &native_symbol);
+        {
+          JSONObject end(&events);
+          end.AddProperty("ph", "E");
+          end.AddProperty("tid", tid);
+          end.AddProperty("pid", pid);
+          end.AddProperty("name", symbol_name);
+          end.AddProperty("ts", static_cast<double>(i->timestamp));
+        }
+        if (native_symbol) {
+          NativeSymbolResolver::FreeSymbolName(symbol_name);
+        }
+      }
+      last_time = i->timestamp;
+    }
+  }
+  char fname[1024];
+#if defined(TARGET_OS_WINDOWS)
+  snprintf(fname, sizeof(fname)-1, "c:\\tmp\\isolate-%d.prof",
+           static_cast<int>(port));
+#else
+  snprintf(fname, sizeof(fname)-1, "/tmp/isolate-%d.prof",
+           static_cast<int>(port));
+#endif
+  printf("%s\n", fname);
+  FILE* f = fopen(fname, "wb");
+  ASSERT(f != NULL);
+  fputs(stream.ToCString(), f);
+  fclose(f);
+}
+
+
+
+
+
+IsolateProfilerData::IsolateProfilerData(Isolate* isolate,
+                                         SampleBuffer* sample_buffer) {
+  isolate_ = isolate;
+  sample_buffer_ = sample_buffer;
+  timer_expiration_micros_ = kNoExpirationTime;
+  last_sampled_micros_ = 0;
+  thread_id_ = 0;
+}
+
+
+IsolateProfilerData::~IsolateProfilerData() {
+}
+
+
+void IsolateProfilerData::SampledAt(int64_t current_time) {
+  last_sampled_micros_ = current_time;
+}
+
+
+void IsolateProfilerData::Scheduled(int64_t current_time, ThreadId thread_id) {
+  timer_expiration_micros_ = current_time + sample_interval_micros_;
+  Thread::GetThreadCpuUsage(thread_id, &cpu_usage_);
+  thread_id_ = thread_id;
+}
+
+
+void IsolateProfilerData::Descheduled() {
+  cpu_usage_ = kDescheduledCpuUsage;
+  timer_expiration_micros_ = kNoExpirationTime;
+  thread_id_ = 0;
+  Sample* sample = sample_buffer_->ReserveSample();
+  ASSERT(sample != NULL);
+  sample->timestamp = OS::GetCurrentTimeMicros();
+  sample->cpu_usage = 0;
+  sample->vm_tags = Sample::kIdle;
+}
+
+
+const char* Sample::kLookupSymbol = "Symbol Not Looked Up";
+const char* Sample::kNoSymbol = "No Symbol Found";
+
+Sample::Sample()  {
+  timestamp = 0;
+  cpu_usage = 0;
+  for (int i = 0; i < kNumStackFrames; i++) {
+    pcs[i] = 0;
+  }
+  vm_tags = kIdle;
+  runtime_tags = 0;
+}
+
+
+SampleBuffer::SampleBuffer(intptr_t capacity) {
+  start_ = 0;
+  end_ = 0;
+  capacity_ = capacity;
+  samples_ = reinterpret_cast<Sample*>(calloc(capacity, sizeof(Sample)));
+}
+
+
+SampleBuffer::~SampleBuffer() {
+  if (samples_ != NULL) {
+    free(samples_);
+    samples_ = NULL;
+  }
+}
+
+
+Sample* SampleBuffer::ReserveSample() {
+  intptr_t index = end_;
+  end_ = WrapIncrement(end_);
+  if (end_ == start_) {
+    start_ = WrapIncrement(start_);
+  }
+  // Reset.
+  samples_[index] = Sample();
+  return &samples_[index];
+}
+
+
+Sample* SampleBuffer::FirstSample() const {
+  return &samples_[start_];
+}
+
+
+Sample* SampleBuffer::NextSample(Sample* sample) const {
+  ASSERT(sample >= &samples_[0]);
+  ASSERT(sample < &samples_[capacity_]);
+  intptr_t index = sample - samples_;
+  index = WrapIncrement(index);
+  return &samples_[index];
+}
+
+
+Sample* SampleBuffer::LastSample() const {
+  return &samples_[end_];
+}
+
+
+intptr_t SampleBuffer::WrapIncrement(intptr_t i) const {
+  return (i + 1) % capacity_;
+}
+
+
+ProfilerSampleStackWalker::ProfilerSampleStackWalker(Sample* sample,
+                                                     uintptr_t stack_lower,
+                                                     uintptr_t stack_upper,
+                                                     uintptr_t pc,
+                                                     uintptr_t fp,
+                                                     uintptr_t sp) :
+    sample_(sample),
+    stack_lower_(stack_lower),
+    stack_upper_(stack_upper),
+    original_pc_(pc),
+    original_fp_(fp),
+    original_sp_(sp) {
+  ASSERT(sample_ != NULL);
+}
+
+
+int ProfilerSampleStackWalker::walk() {
+  uword* pc = reinterpret_cast<uword*>(original_pc_);
+  uword* fp = reinterpret_cast<uword*>(original_fp_);
+  int i = 0;
+  for (; i < Sample::kNumStackFrames; i++) {
+    sample_->pcs[i] = reinterpret_cast<uintptr_t>(pc);
+    if (!ValidInstructionPointer(pc) || !ValidFramePointer(fp)) {
+      break;
+    }
+    pc = CallerPC(fp);
+    uword* previous_fp = fp;
+    fp = CallerFP(fp);
+    if (fp <= previous_fp) {
+      // Frame pointers should only move to higher addresses.
+      break;
+    }
+  }
+  return i;
+}
+
+
+uword* ProfilerSampleStackWalker::CallerPC(uword* fp) {
+  ASSERT(fp != NULL);
+  return reinterpret_cast<uword*>(*(fp+1));
+}
+
+
+uword* ProfilerSampleStackWalker::CallerFP(uword* fp) {
+  ASSERT(fp != NULL);
+  return reinterpret_cast<uword*>(*fp);
+}
+
+
+bool ProfilerSampleStackWalker::ValidInstructionPointer(uword* pc) {
+  uintptr_t cursor = reinterpret_cast<uintptr_t>(pc);
+  return cursor != 0;

[siva, 2013/11/11 03:51:54]

Seems simplistic...

[Cutch, 2013/11/18 20:48:54]

Done.

+}
+
+
+bool ProfilerSampleStackWalker::ValidFramePointer(uword* fp) {
+  uintptr_t cursor = reinterpret_cast<uintptr_t>(fp);
+  cursor += sizeof(fp);
+  bool r = cursor >= stack_lower_ && cursor <= stack_upper_;
+  return r;
+}
+
+
+}  // namespace dart