Report approximated duration in milliseconds for profile nodes.

src/profile-generator.cc

 // Copyright 2010 the V8 project authors. All rights reserved.
 // Redistribution and use in source and binary forms, with or without
 // modification, are permitted provided that the following conditions are
 // met:
 //
 //     * Redistributions of source code must retain the above copyright
 //       notice, this list of conditions and the following disclaimer.
 //     * Redistributions in binary form must reproduce the above
 //       copyright notice, this list of conditions and the following
 //       disclaimer in the documentation and/or other materials provided
@@ skipping 36 matching lines @@
   return map_entry != NULL ?
       reinterpret_cast<ProfileNode*>(map_entry->value) : NULL;
 }
 
 
 ProfileNode* ProfileNode::FindOrAddChild(CodeEntry* entry) {
   HashMap::Entry* map_entry =
       children_.Lookup(entry, CodeEntryHash(entry), true);
   if (map_entry->value == NULL) {
     // New node added.
-    ProfileNode* new_node = new ProfileNode(entry);
+    ProfileNode* new_node = new ProfileNode(tree_, entry);
     map_entry->value = new_node;
     children_list_.Add(new_node);
   }
   return reinterpret_cast<ProfileNode*>(map_entry->value);
 }
 
 
+double ProfileNode::GetSelfMillis() const {
+  return tree_->TicksToMillis(self_ticks_);
+}
+
+
+double ProfileNode::GetTotalMillis() const {
+  return tree_->TicksToMillis(total_ticks_);
+}
+
+
 void ProfileNode::Print(int indent) {
   OS::Print("%5u %5u %*c %s%s",
             total_ticks_, self_ticks_,
             indent, ' ',
             entry_->name_prefix(),
             entry_->name());
   if (entry_->resource_name()[0] != '\0')
     OS::Print(" %s:%d", entry_->resource_name(), entry_->line_number());
   OS::Print("\n");
   for (HashMap::Entry* p = children_.Start();
@@ skipping 13 matching lines @@
   }
 
   void AfterChildTraversed(ProfileNode*, ProfileNode*) { }
 };
 
 }  // namespace
 
 
 ProfileTree::ProfileTree()
     : root_entry_(Logger::FUNCTION_TAG, "", "(root)", "", 0),
-      root_(new ProfileNode(&root_entry_)) {
+      root_(new ProfileNode(this, &root_entry_)) {
 }
 
 
 ProfileTree::~ProfileTree() {
   DeleteNodesCallback cb;
-  TraverseBreadthFirstPostOrder(&cb);
+  TraverseDepthFirstPostOrder(&cb);
 }
 
 
 void ProfileTree::AddPathFromEnd(const Vector<CodeEntry*>& path) {
   ProfileNode* node = root_;
   for (CodeEntry** entry = path.start() + path.length() - 1;
        entry != path.start() - 1;
        --entry) {
     if (*entry != NULL) {
       node = node->FindOrAddChild(*entry);
     }
   }
   node->IncrementSelfTicks();
 }
 
 
 void ProfileTree::AddPathFromStart(const Vector<CodeEntry*>& path) {
   ProfileNode* node = root_;
   for (CodeEntry** entry = path.start();
        entry != path.start() + path.length();
        ++entry) {
     if (*entry != NULL) {
       node = node->FindOrAddChild(*entry);
     }
   }
   node->IncrementSelfTicks();
 }
 
 
+void ProfileTree::SetTickRatePerMs(double ticks_per_ms) {
+  ms_to_ticks_scale_ = ticks_per_ms > 0 ? 1.0 / ticks_per_ms : 1.0;
+}
+
+
 namespace {
 
 class Position {
  public:
   explicit Position(ProfileNode* node)
       : node(node), child_idx_(0) { }
   INLINE(ProfileNode* current_child()) {
     return node->children()->at(child_idx_);
   }
   INLINE(bool has_current_child()) {
     return child_idx_ < node->children()->length();
   }
   INLINE(void next_child()) { ++child_idx_; }
 
   ProfileNode* node;
  private:
   int child_idx_;
 };
 
 }  // namespace
 
 
-// Non-recursive implementation of breadth-first post-order tree traversal.
+// Non-recursive implementation of a depth-first post-order tree traversal.
 template <typename Callback>
-void ProfileTree::TraverseBreadthFirstPostOrder(Callback* callback) {
+void ProfileTree::TraverseDepthFirstPostOrder(Callback* callback) {
   List<Position> stack(10);
   stack.Add(Position(root_));
   do {
     Position& current = stack.last();
     if (current.has_current_child()) {
       stack.Add(Position(current.current_child()));
     } else {
       callback->AfterAllChildrenTraversed(current.node);
       if (stack.length() > 1) {
         Position& parent = stack[stack.length() - 2];
@@ skipping 18 matching lines @@
   void AfterChildTraversed(ProfileNode* parent, ProfileNode* child) {
     parent->IncreaseTotalTicks(child->total_ticks());
   }
 };
 
 }  // namespace
 
 
 void ProfileTree::CalculateTotalTicks() {
   CalculateTotalTicksCallback cb;
-  TraverseBreadthFirstPostOrder(&cb);
+  TraverseDepthFirstPostOrder(&cb);
 }
 
 
 void ProfileTree::ShortPrint() {
-  OS::Print("root: %u %u\n", root_->total_ticks(), root_->self_ticks());
+  OS::Print("root: %u %u %.2fms %.2fms\n",
+            root_->total_ticks(), root_->self_ticks(),
+            root_->GetTotalMillis(), root_->GetSelfMillis());
 }
 
 
 void CpuProfile::AddPath(const Vector<CodeEntry*>& path) {
   top_down_.AddPathFromEnd(path);
   bottom_up_.AddPathFromStart(path);
 }
 
 
 void CpuProfile::CalculateTotalTicks() {
   top_down_.CalculateTotalTicks();
   bottom_up_.CalculateTotalTicks();
 }
 
 
+void CpuProfile::SetActualSamplingRate(double actual_sampling_rate) {
+  top_down_.SetTickRatePerMs(actual_sampling_rate);
+  bottom_up_.SetTickRatePerMs(actual_sampling_rate);
+}
+
+
 void CpuProfile::ShortPrint() {
   OS::Print("top down ");
   top_down_.ShortPrint();
   OS::Print("bottom up ");
   bottom_up_.ShortPrint();
 }
 
 
 void CpuProfile::Print() {
   OS::Print("[Top down]:\n");
@@ skipping 91 matching lines @@
   current_profiles_semaphore_->Signal();
   return true;
 }
 
 
 bool CpuProfilesCollection::StartProfiling(String* title, unsigned uid) {
   return StartProfiling(GetName(title), uid);
 }
 
 
-CpuProfile* CpuProfilesCollection::StopProfiling(const char* title) {
+CpuProfile* CpuProfilesCollection::StopProfiling(const char* title,
+                                                 double actual_sampling_rate) {
   const int title_len = StrLength(title);
   CpuProfile* profile = NULL;
   current_profiles_semaphore_->Wait();
   for (int i = current_profiles_.length() - 1; i >= 0; --i) {
     if (title_len == 0 || strcmp(current_profiles_[i]->title(), title) == 0) {
       profile = current_profiles_.Remove(i);
       break;
     }
   }
   current_profiles_semaphore_->Signal();
 
   if (profile != NULL) {
     profile->CalculateTotalTicks();
+    profile->SetActualSamplingRate(actual_sampling_rate);
     profiles_.Add(profile);
     HashMap::Entry* entry =
         profiles_uids_.Lookup(reinterpret_cast<void*>(profile->uid()),
                               static_cast<uint32_t>(profile->uid()),
                               true);
     ASSERT(entry->value == NULL);
     entry->value = profile;
   }
   return profile;
 }
 
 
-CpuProfile* CpuProfilesCollection::StopProfiling(String* title) {
-  return StopProfiling(GetName(title));
+CpuProfile* CpuProfilesCollection::StopProfiling(String* title,
+                                                 double actual_sampling_rate) {
+  return StopProfiling(GetName(title), actual_sampling_rate);
 }
 
 
 CpuProfile* CpuProfilesCollection::GetProfile(unsigned uid) {
   HashMap::Entry* entry = profiles_uids_.Lookup(reinterpret_cast<void*>(uid),
                                                 static_cast<uint32_t>(uid),
                                                 false);
   return entry != NULL ? reinterpret_cast<CpuProfile*>(entry->value) : NULL;
 }
 
@@ skipping 92 matching lines @@
   // 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_semaphore_->Signal();
 }
 
 
+void SampleRateCalculator::Tick() {
+  if (--wall_time_query_countdown_ == 0)
+    UpdateMeasurements(OS::TimeCurrentMillis());
+}
+
+
+void SampleRateCalculator::UpdateMeasurements(double current_time) {
+  if (measurements_count_++ != 0) {
+    const double measured_ticks_per_ms =
+        (kWallTimeQueryIntervalMs * ticks_per_ms_) /
+        (current_time - last_wall_time_);
+    // Update the average value.
+    ticks_per_ms_ +=
+        (measured_ticks_per_ms - ticks_per_ms_) / measurements_count_;
+    // Update the externally accessible result.
+    result_ = static_cast<AtomicWord>(ticks_per_ms_ * kResultScale);
+  }
+  last_wall_time_ = current_time;
+  wall_time_query_countdown_ =
+      static_cast<unsigned>(kWallTimeQueryIntervalMs * ticks_per_ms_);
+}
+
+
 const char* ProfileGenerator::kAnonymousFunctionName = "(anonymous function)";
 const char* ProfileGenerator::kProgramEntryName = "(program)";
 const char* ProfileGenerator::kGarbageCollectorEntryName =
   "(garbage collector)";
 
 
 ProfileGenerator::ProfileGenerator(CpuProfilesCollection* profiles)
     : profiles_(profiles),
       program_entry_(
           profiles->NewCodeEntry(Logger::FUNCTION_TAG, kProgramEntryName)),
@@ skipping 37 matching lines @@
     // Put VM state as the topmost entry.
     *entry++ = EntryForVMState(sample.state);
   }
 
   profiles_->AddPathToCurrentProfiles(entries);
 }
 
 } }  // namespace v8::internal
 
 #endif  // ENABLE_LOGGING_AND_PROFILING