Add timestamps to CPU profile samples.

BUG=363976
LOG=Y
R=bmeurer@chromium.org, yurys@chromium.org

Review URL: https://codereview.chromium.org/259803002

git-svn-id: http://v8.googlecode.com/svn/branches/bleeding_edge@20993 ce2b1a6d-e550-0410-aec6-3dcde31c8c00

include/v8-profiler.h

@@ -106,28 +106,35 @@ class V8_EXPORT CpuProfile {
   const CpuProfileNode* GetTopDownRoot() const;
 
   /**
-    * Returns number of samples recorded. The samples are not recorded unless
-    * |record_samples| parameter of CpuProfiler::StartCpuProfiling is true.
-    */
+   * Returns number of samples recorded. The samples are not recorded unless
+   * |record_samples| parameter of CpuProfiler::StartCpuProfiling is true.
+   */
   int GetSamplesCount() const;
 
   /**
-    * Returns profile node corresponding to the top frame the sample at
-    * the given index.
-    */
+   * Returns profile node corresponding to the top frame the sample at
+   * the given index.
+   */
   const CpuProfileNode* GetSample(int index) const;
 
   /**
-    * Returns time when the profile recording was started (in microseconds)
-    * since some unspecified starting point.
-    */
+   * Returns the timestamp of the sample. The timestamp is the number of
+   * microseconds since some unspecified starting point.
+   * The point is equal to the starting point used by GetStartTime.
+   */
+  int64_t GetSampleTimestamp(int index) const;
+
+  /**
+   * Returns time when the profile recording was started (in microseconds)
+   * since some unspecified starting point.
+   */
   int64_t GetStartTime() const;
 
   /**
-    * Returns time when the profile recording was stopped (in microseconds)
-    * since some unspecified starting point. The point is however equal to the
-    * starting point used by GetStartTime.
-    */
+   * Returns time when the profile recording was stopped (in microseconds)
+   * since some unspecified starting point.
+   * The point is equal to the starting point used by GetStartTime.
+   */
   int64_t GetEndTime() const;
 
   /**

src/api.cc

@@ -7067,6 +7067,12 @@ const CpuProfileNode* CpuProfile::GetSample(int index) const {
 }
 
 
+int64_t CpuProfile::GetSampleTimestamp(int index) const {
+  const i::CpuProfile* profile = reinterpret_cast<const i::CpuProfile*>(this);
+  return (profile->sample_timestamp(index) - i::TimeTicks()).InMicroseconds();
+}
+
+
 int64_t CpuProfile::GetStartTime() const {
   const i::CpuProfile* profile = reinterpret_cast<const i::CpuProfile*>(this);
   return (profile->start_time() - i::TimeTicks()).InMicroseconds();

src/cpu-profiler.cc

@@ -432,7 +432,6 @@ void CpuProfiler::StartProfiling(const char* title, bool record_samples) {
   if (profiles_->StartProfiling(title, record_samples)) {
     StartProcessorIfNotStarted();
   }
-  processor_->AddCurrentStack(isolate_);
 }
 
 
@@ -463,6 +462,7 @@ void CpuProfiler::StartProcessorIfNotStarted() {
     // Enable stack sampling.
     sampler->SetHasProcessingThread(true);
     sampler->IncreaseProfilingDepth();
+    processor_->AddCurrentStack(isolate_);
     processor_->StartSynchronously();
   }
 }

src/profile-generator.cc

@@ -359,9 +359,12 @@ CpuProfile::CpuProfile(const char* title, bool record_samples)
 }
 
 
-void CpuProfile::AddPath(const Vector<CodeEntry*>& path) {
+void CpuProfile::AddPath(TimeTicks timestamp, const Vector<CodeEntry*>& path) {
   ProfileNode* top_frame_node = top_down_.AddPathFromEnd(path);
-  if (record_samples_) samples_.Add(top_frame_node);
+  if (record_samples_) {
+    timestamps_.Add(timestamp);
+    samples_.Add(top_frame_node);
+  }
 }
 
 
@@ -545,13 +548,13 @@ void CpuProfilesCollection::RemoveProfile(CpuProfile* profile) {
 
 
 void CpuProfilesCollection::AddPathToCurrentProfiles(
-    const Vector<CodeEntry*>& path) {
+    TimeTicks timestamp, const Vector<CodeEntry*>& path) {
   // As starting / stopping profiles is rare relatively to this
   // method, we don't bother minimizing the duration of lock holding,
   // e.g. copying contents of the list to a local vector.
   current_profiles_semaphore_.Wait();
   for (int i = 0; i < current_profiles_.length(); ++i) {
-    current_profiles_[i]->AddPath(path);
+    current_profiles_[i]->AddPath(timestamp, path);
   }
   current_profiles_semaphore_.Signal();
 }
@@ -674,7 +677,7 @@ void ProfileGenerator::RecordTickSample(const TickSample& sample) {
     }
   }
 
-  profiles_->AddPathToCurrentProfiles(entries);
+  profiles_->AddPathToCurrentProfiles(sample.timestamp, entries);
 }
 
 

src/profile-generator.h

@@ -199,7 +199,7 @@ class CpuProfile {
   CpuProfile(const char* title, bool record_samples);
 
   // Add pc -> ... -> main() call path to the profile.
-  void AddPath(const Vector<CodeEntry*>& path);
+  void AddPath(TimeTicks timestamp, const Vector<CodeEntry*>& path);
   void CalculateTotalTicksAndSamplingRate();
 
   const char* title() const { return title_; }
@@ -207,6 +207,7 @@ class CpuProfile {
 
   int samples_count() const { return samples_.length(); }
   ProfileNode* sample(int index) const { return samples_.at(index); }
+  TimeTicks sample_timestamp(int index) const { return timestamps_.at(index); }
 
   TimeTicks start_time() const { return start_time_; }
   TimeTicks end_time() const { return end_time_; }
@@ -221,6 +222,7 @@ class CpuProfile {
   TimeTicks start_time_;
   TimeTicks end_time_;
   List<ProfileNode*> samples_;
+  List<TimeTicks> timestamps_;
   ProfileTree top_down_;
 
   DISALLOW_COPY_AND_ASSIGN(CpuProfile);
@@ -305,7 +307,8 @@ class CpuProfilesCollection {
       int column_number = v8::CpuProfileNode::kNoColumnNumberInfo);
 
   // Called from profile generator thread.
-  void AddPathToCurrentProfiles(const Vector<CodeEntry*>& path);
+  void AddPathToCurrentProfiles(
+      TimeTicks timestamp, const Vector<CodeEntry*>& path);
 
   // Limits the number of profiles that can be simultaneously collected.
   static const int kMaxSimultaneousProfiles = 100;

src/sampler.cc

@@ -589,6 +589,7 @@ SamplerThread* SamplerThread::instance_ = NULL;
 DISABLE_ASAN void TickSample::Init(Isolate* isolate,
                                    const RegisterState& regs) {
   ASSERT(isolate->IsInitialized());
+  timestamp = TimeTicks::HighResolutionNow();
   pc = regs.pc;
   state = isolate->current_vm_state();
 

src/sampler.h

@@ -69,6 +69,7 @@ struct TickSample {
   };
   static const int kMaxFramesCount = 64;
   Address stack[kMaxFramesCount];  // Call stack.
+  TimeTicks timestamp;
   int frames_count : 8;  // Number of captured frames.
   bool has_external_callback : 1;
   StackFrame::Type top_frame_type : 4;

test/cctest/test-cpu-profiler.cc

@@ -401,12 +401,12 @@ TEST(ProfileStartEndTime) {
 static v8::CpuProfile* RunProfiler(
     v8::Handle<v8::Context> env, v8::Handle<v8::Function> function,
     v8::Handle<v8::Value> argv[], int argc,
-    unsigned min_js_samples) {
+    unsigned min_js_samples, bool collect_samples = false) {
   v8::CpuProfiler* cpu_profiler = env->GetIsolate()->GetCpuProfiler();
   v8::Local<v8::String> profile_name =
       v8::String::NewFromUtf8(env->GetIsolate(), "my_profile");
 
-  cpu_profiler->StartProfiling(profile_name);
+  cpu_profiler->StartProfiling(profile_name, collect_samples);
 
   i::Sampler* sampler =
       reinterpret_cast<i::Isolate*>(env->GetIsolate())->logger()->sampler();
@@ -587,6 +587,37 @@ TEST(CollectCpuProfile) {
 }
 
 
+TEST(CollectCpuProfileSamples) {
+  LocalContext env;
+  v8::HandleScope scope(env->GetIsolate());
+
+  v8::Script::Compile(v8::String::NewFromUtf8(env->GetIsolate(),
+                                              cpu_profiler_test_source))->Run();
+  v8::Local<v8::Function> function = v8::Local<v8::Function>::Cast(
+      env->Global()->Get(v8::String::NewFromUtf8(env->GetIsolate(), "start")));
+
+  int32_t profiling_interval_ms = 200;
+  v8::Handle<v8::Value> args[] = {
+    v8::Integer::New(env->GetIsolate(), profiling_interval_ms)
+  };
+  v8::CpuProfile* profile =
+      RunProfiler(env.local(), function, args, ARRAY_SIZE(args), 200, true);
+
+  CHECK_LE(200, profile->GetSamplesCount());
+  uint64_t end_time = profile->GetEndTime();
+  uint64_t current_time = profile->GetStartTime();
+  CHECK_LE(current_time, end_time);
+  for (int i = 0; i < profile->GetSamplesCount(); i++) {
+    CHECK_NE(NULL, profile->GetSample(i));
+    uint64_t timestamp = profile->GetSampleTimestamp(i);
+    CHECK_LE(current_time, timestamp);
+    CHECK_LE(timestamp, end_time);
+    current_time = timestamp;
+  }
+
+  profile->Delete();
+}
+
 
 static const char* cpu_profiler_test_source2 = "function loop() {}\n"
 "function delay() { loop(); }\n"