Profiler fixes for 1.9

runtime/vm/profiler_service.cc

 // Copyright (c) 2015, 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 "vm/profiler_service.h"
 
 #include "vm/growable_array.h"
 #include "vm/native_symbol.h"
 #include "vm/object.h"
 #include "vm/os.h"
@@ skipping 156 matching lines @@
       if ((*code_objects_)[i] == index) {
         return;
       }
     }
     code_objects_->Add(index);
   }
 
   intptr_t inclusive_ticks() const {
     return inclusive_ticks_;
   }
-
+  void inc_inclusive_ticks() {
+    inclusive_ticks_++;
+  }
   intptr_t exclusive_ticks() const {
     return exclusive_ticks_;
   }
 
   void Tick(bool exclusive, intptr_t serial) {
     // Assert that exclusive ticks are never passed a valid serial number.
     ASSERT((exclusive && (serial == -1)) || (!exclusive && (serial != -1)));
     if (!exclusive && (inclusive_tick_serial_ == serial)) {
       // We've already given this object an inclusive tick for this sample.
       return;
@@ skipping 241 matching lines @@
   }
   int64_t compile_timestamp() const { return compile_timestamp_; }
   void set_compile_timestamp(int64_t timestamp) {
     compile_timestamp_ = timestamp;
   }
 
   intptr_t inclusive_ticks() const { return inclusive_ticks_; }
   void set_inclusive_ticks(intptr_t inclusive_ticks) {
     inclusive_ticks_ = inclusive_ticks;
   }
+  void inc_inclusive_ticks() {
+    inclusive_ticks_++;
+  }
 
   intptr_t exclusive_ticks() const { return exclusive_ticks_; }
   void set_exclusive_ticks(intptr_t exclusive_ticks) {
     exclusive_ticks_ = exclusive_ticks;
   }
 
   const char* name() const { return name_; }
   void SetName(const char* name) {
     if (name == NULL) {
       name_ = NULL;
@@ skipping 956 matching lines @@
   ProfileFunctionTrieBuilder(Isolate* isolate,
                              CodeRegionTable* live_code_table,
                              CodeRegionTable* dead_code_table,
                              CodeRegionTable* tag_code_table,
                              ProfileFunctionTable* function_table)
       : SampleVisitor(isolate),
         live_code_table_(live_code_table),
         dead_code_table_(dead_code_table),
         tag_code_table_(tag_code_table),
         function_table_(function_table),
-        inclusive_(false),
+        inclusive_tree_(false),
         trace_(false),
         trace_code_filter_(NULL) {
     ASSERT(live_code_table_ != NULL);
     ASSERT(dead_code_table_ != NULL);
     ASSERT(tag_code_table_ != NULL);
     ASSERT(function_table_ != NULL);
     set_tag_order(ProfilerService::kUserVM);
 
     // Verify that the truncated tag exists.
     ASSERT(tag_code_table_->FindIndex(VMTag::kTruncatedTagId) >= 0);
 
     // Verify that the root tag exists.
     intptr_t root_index = tag_code_table_->FindIndex(VMTag::kRootTagId);
     ASSERT(root_index >= 0);
 
     // Setup root.
     CodeRegion* region = tag_code_table_->At(root_index);
     ASSERT(region != NULL);
     ProfileFunction* function = region->function();
     ASSERT(function != NULL);
 
     exclusive_root_ = new ProfileFunctionTrieNode(function->index());
     inclusive_root_ = new ProfileFunctionTrieNode(function->index());
   }
 
   void VisitSample(Sample* sample) {
-    inclusive_ = false;
+    inclusive_tree_ = false;
     ProcessSampleExclusive(sample);
-    inclusive_ = true;
+    inclusive_tree_ = true;
     ProcessSampleInclusive(sample);
   }
 
   ProfileFunctionTrieNode* exclusive_root() const {
     return exclusive_root_;
   }
 
   ProfileFunctionTrieNode* inclusive_root() const {
     return inclusive_root_;
   }
 
   ProfilerService::TagOrder tag_order() const {
     return tag_order_;
   }
 
+  bool vm_tags_emitted() const {
+    return (tag_order_ == ProfilerService::kUserVM) ||
+           (tag_order_ == ProfilerService::kVMUser) ||
+           (tag_order_ == ProfilerService::kVM);
+  }
+
   void set_tag_order(ProfilerService::TagOrder tag_order) {
     tag_order_ = tag_order;
   }
 
  private:
   void ProcessSampleInclusive(Sample* sample) {
     // Give the root a tick.
     inclusive_root_->Tick();
     ProfileFunctionTrieNode* current = inclusive_root_;
     current = AppendTags(sample, current);
     if (sample->truncated_trace()) {
+      InclusiveTickTruncatedTag();
       current = AppendTruncatedTag(current);
     }
     // Walk the sampled PCs.
     for (intptr_t i = FLAG_profile_depth - 1; i >= 0; i--) {
       if (sample->At(i) == 0) {
         continue;
       }
-      // If we aren't sampled out of an exit frame and this is the top
-      // frame.
-      bool exclusive_tick = (i == 0) && !sample->exit_frame_sample();
-      current = ProcessPC(sample->At(i), sample->timestamp(), current,
-                          visited(), exclusive_tick,
+      current = ProcessPC(sample->At(i),
+                          sample->timestamp(),
+                          current,
+                          visited(),
+                          (i == 0),
+                          sample->exit_frame_sample() && (i == 0),
                           sample->missing_frame_inserted());
     }
   }
 
   void ProcessSampleExclusive(Sample* sample) {
     // Give the root a tick.
     exclusive_root_->Tick();
     ProfileFunctionTrieNode* current = exclusive_root_;
     current = AppendTags(sample, current);
     // Walk the sampled PCs.
     for (intptr_t i = 0; i < FLAG_profile_depth; i++) {
       if (sample->At(i) == 0) {
         break;
       }
-      // If we aren't sampled out of an exit frame and this is the top
-      // frame.
-      bool exclusive_tick = (i == 0) && !sample->exit_frame_sample();
-      current = ProcessPC(sample->At(i), sample->timestamp(), current,
-                          visited(), exclusive_tick,
+      current = ProcessPC(sample->At(i),
+                          sample->timestamp(),
+                          current,
+                          visited(),
+                          (i == 0),
+                          sample->exit_frame_sample() && (i == 0),
                           sample->missing_frame_inserted());
     }
     if (sample->truncated_trace()) {
       current = AppendTruncatedTag(current);
     }
   }
 
   ProfileFunctionTrieNode* AppendUserTag(Sample* sample,
                                          ProfileFunctionTrieNode* current) {
     intptr_t user_tag_index = FindTagIndex(sample->user_tag());
     if (user_tag_index >= 0) {
       current = current->GetChild(user_tag_index);
       // Give the tag a tick.
       current->Tick();
     }
     return current;
   }
 
 
   ProfileFunctionTrieNode* AppendTruncatedTag(
       ProfileFunctionTrieNode* current) {
     intptr_t truncated_tag_index = FindTagIndex(VMTag::kTruncatedTagId);
     ASSERT(truncated_tag_index >= 0);
     current = current->GetChild(truncated_tag_index);
     current->Tick();
     return current;
   }
 
+  void InclusiveTickTruncatedTag() {
+    intptr_t index = tag_code_table_->FindIndex(VMTag::kTruncatedTagId);
+    CodeRegion* region = tag_code_table_->At(index);

[Ivan Posva, 2015/03/16 22:17:37]

I am wondering whether some of this information could and should be cached.

+    ProfileFunction* function = region->function();
+    function->inc_inclusive_ticks();
+  }
 
   ProfileFunctionTrieNode* AppendVMTag(Sample* sample,
                                        ProfileFunctionTrieNode* current) {
     if (VMTag::IsNativeEntryTag(sample->vm_tag())) {
       // Insert a dummy kNativeTagId node.
       intptr_t tag_index = FindTagIndex(VMTag::kNativeTagId);
       current = current->GetChild(tag_index);
       // Give the tag a tick.
       current->Tick();
     } else if (VMTag::IsRuntimeEntryTag(sample->vm_tag())) {
@@ skipping 77 matching lines @@
     return function->index();
   }
 
   void Dump(ProfileFunctionTrieNode* current) {
     int current_index = current->profile_function_table_index();
     ProfileFunction* function = function_table_->At(current_index);
     function->Dump();
     OS::Print("\n");
   }
 
-  ProfileFunctionTrieNode* ProcessPC(uword pc, int64_t timestamp,
+  ProfileFunctionTrieNode* ProcessPC(uword pc,
+                                     int64_t timestamp,
                                      ProfileFunctionTrieNode* current,
                                      intptr_t inclusive_serial,
-                                     bool exclusive,
+                                     bool exclusive_frame,
+                                     bool exit_frame,
                                      bool missing_frame_inserted) {
     CodeRegion* region = FindCodeObject(pc, timestamp);
     if (region == NULL) {
       return current;
     }
     const char* region_name = region->name();
     if (region_name == NULL) {
       region_name = "";
     }
     intptr_t code_index = region->code_table_index();
     const Code& code = Code::ZoneHandle(region->code());
     GrowableArray<Function*> inlined_functions;
     if (!code.IsNull()) {
       intptr_t offset = pc - code.EntryPoint();
       code.GetInlinedFunctionsAt(offset, &inlined_functions);
     }
     if (code.IsNull() || (inlined_functions.length() == 0)) {
       // No inlined functions.
       ProfileFunction* function = region->function();
       ASSERT(function != NULL);
       if (trace_) {
         OS::Print("[%" Px "] X - %s (%s)\n",
                   pc, function->name(), region_name);
       }
-      if (!inclusive_) {
-        function->Tick(exclusive, exclusive ? -1 : inclusive_serial);
-      }
-      current = current->GetChild(function->index());
-      current->AddCodeObjectIndex(code_index);
-      current->Tick();
+      current = ProcessFunction(function,
+                                current,
+                                inclusive_serial,
+                                exclusive_frame,
+                                exit_frame,
+                                code_index);
       if ((trace_code_filter_ != NULL) &&
           (strstr(region_name, trace_code_filter_) != NULL)) {
         trace_ = true;
         OS::Print("Tracing from: %" Px " [%s] ", pc,
                   missing_frame_inserted ? "INSERTED" : "");
         Dump(current);
       }
       return current;
     }
 
-    if (inclusive_) {
+    if (inclusive_tree_) {
       for (intptr_t i = inlined_functions.length() - 1; i >= 0; i--) {
         Function* inlined_function = inlined_functions[i];
         ASSERT(inlined_function != NULL);
         ASSERT(!inlined_function->IsNull());
-        current = ProcessInlinedFunction(
-            inlined_function, current, inclusive_serial, exclusive, code_index);
-        exclusive = false;
+        current = ProcessInlinedFunction(inlined_function,
+                                         current,
+                                         inclusive_serial,
+                                         exclusive_frame,
+                                         exit_frame,
+                                         code_index);
+        exclusive_frame = false;
       }
     } else {
       for (intptr_t i = 0; i < inlined_functions.length(); i++) {
         Function* inlined_function = inlined_functions[i];
         ASSERT(inlined_function != NULL);
         ASSERT(!inlined_function->IsNull());
         const char* inline_name = inlined_function->ToQualifiedCString();
         if (trace_) {
           OS::Print("[%" Px "] %" Pd " - %s (%s)\n",
                   pc, i, inline_name, region_name);
         }
-        current = ProcessInlinedFunction(
-            inlined_function, current, inclusive_serial, exclusive, code_index);
-        exclusive = false;
+        current = ProcessInlinedFunction(inlined_function,
+                                         current,
+                                         inclusive_serial,
+                                         exclusive_frame,
+                                         exit_frame,
+                                         code_index);
+        exclusive_frame = false;
         if ((trace_code_filter_ != NULL) &&
             (strstr(region_name, trace_code_filter_) != NULL)) {
           trace_ = true;
           OS::Print("Tracing from: %" Px " [%s] ",
                     pc, missing_frame_inserted ? "INSERTED" : "");
           Dump(current);
         }
       }
     }
 
     return current;
   }
 
   ProfileFunctionTrieNode* ProcessInlinedFunction(
       Function* inlined_function,
       ProfileFunctionTrieNode* current,
       intptr_t inclusive_serial,
-      bool exclusive,
+      bool exclusive_frame,

[Ivan Posva, 2015/03/16 22:17:37]

exclusive_frame really means the top frame.

+      bool exit_frame,
       intptr_t code_index) {
     ProfileFunction* function =
         function_table_->LookupOrAdd(*inlined_function);
     ASSERT(function != NULL);
+    return ProcessFunction(function,
+                           current,
+                           inclusive_serial,
+                           exclusive_frame,
+                           exit_frame,
+                           code_index);
+  }
+
+  ProfileFunctionTrieNode* ProcessFunction(ProfileFunction* function,
+                                           ProfileFunctionTrieNode* current,
+                                           intptr_t inclusive_serial,
+                                           bool exclusive_frame,
+                                           bool exit_frame,
+                                           intptr_t code_index) {
+    const bool exclusive = exclusive_frame && !exit_frame;
+    if (!inclusive_tree_) {
+      // We process functions for the inclusive and exclusive trees.
+      // Only tick the function for the exclusive tree.
+      function->Tick(exclusive, exclusive ? -1 : inclusive_serial);
+    }
     function->AddCodeObjectIndex(code_index);
-    function->Tick(exclusive, exclusive ? -1 : inclusive_serial);
+
     current = current->GetChild(function->index());
     current->AddCodeObjectIndex(code_index);
-    current->Tick();
+    if (exclusive_frame) {
+      if (!exit_frame || vm_tags_emitted()) {
+        // Only tick if this isn't an exit frame or VM tags are emitted.
+        current->Tick();
+      }
+    } else {
+      current->Tick();
+    }
     return current;
   }
 
   CodeRegion* FindCodeObject(uword pc, int64_t timestamp) const {
     intptr_t index = live_code_table_->FindIndex(pc);
     if (index < 0) {
       return NULL;
     }
     CodeRegion* region = live_code_table_->At(index);
     ASSERT(region->contains(pc));
@@ skipping 12 matching lines @@
     return region;
   }
 
   ProfilerService::TagOrder tag_order_;
   ProfileFunctionTrieNode* exclusive_root_;
   ProfileFunctionTrieNode* inclusive_root_;
   CodeRegionTable* live_code_table_;
   CodeRegionTable* dead_code_table_;
   CodeRegionTable* tag_code_table_;
   ProfileFunctionTable* function_table_;
-  bool inclusive_;
+  bool inclusive_tree_;
   bool trace_;
   const char* trace_code_filter_;
 };
 
 
 class CodeRegionTrieNode : public ZoneAllocated {
  public:
   explicit CodeRegionTrieNode(intptr_t code_region_index)
       : code_region_index_(code_region_index),
         count_(0),
@@ skipping 122 matching lines @@
   }
 
   CodeRegionTrieNode* exclusive_root() const {
     return exclusive_root_;
   }
 
   ProfilerService::TagOrder tag_order() const {
     return tag_order_;
   }
 
+  bool vm_tags_emitted() const {
+    return (tag_order_ == ProfilerService::kUserVM) ||
+           (tag_order_ == ProfilerService::kVMUser) ||
+           (tag_order_ == ProfilerService::kVM);
+  }
+
   void set_tag_order(ProfilerService::TagOrder tag_order) {
     tag_order_ = tag_order;
   }
 
  private:
   void ProcessSampleInclusive(Sample* sample) {
     // Give the root a tick.
     inclusive_root_->Tick();
     CodeRegionTrieNode* current = inclusive_root_;
     current = AppendTags(sample, current);
@@ skipping 22 matching lines @@
     // Walk the sampled PCs.
     for (intptr_t i = 0; i < FLAG_profile_depth; i++) {
       if (sample->At(i) == 0) {
         break;
       }
       intptr_t index = FindFinalIndex(sample->At(i), sample->timestamp());
       if (index < 0) {
         continue;
       }
       current = current->GetChild(index);
-      current->Tick();
+      if (i == 0) {
+        // Executing PC.
+        if (!sample->exit_frame_sample() || vm_tags_emitted()) {
+          // Only tick if this isn't an exit frame or VM tags are emitted.
+          current->Tick();
+        }
+      } else {
+        // Caller PCs.
+        current->Tick();
+      }
     }
     if (sample->truncated_trace()) {
       current = AppendTruncatedTag(current);
     }
   }
 
   CodeRegionTrieNode* AppendUserTag(Sample* sample,
                                     CodeRegionTrieNode* current) {
     intptr_t user_tag_index = FindTagIndex(sample->user_tag());
     if (user_tag_index >= 0) {
@@ skipping 178 matching lines @@
                                      &dead_code_table,
                                      &tag_code_table,
                                      deoptimized_code);
       {
         ScopeTimer sw("CodeRegionTableBuilder", FLAG_trace_profiler);
         sample_buffer->VisitSamples(&builder);
       }
       intptr_t samples = builder.visited();
       intptr_t frames = builder.frames();
       if (FLAG_trace_profiler) {
+        OS::Print(
+            "Processed %" Pd " samples with %" Pd " frames\n", samples, frames);
+      }

[Ivan Posva, 2015/03/16 22:17:37]

if (x) {
}
if (x) {
}

???

+      if (FLAG_trace_profiler) {
         intptr_t total_live_code_objects = live_code_table.Length();
         intptr_t total_dead_code_objects = dead_code_table.Length();
         intptr_t total_tag_code_objects = tag_code_table.Length();
-        OS::Print("Processed %" Pd " frames\n", frames);
+
         OS::Print("CodeTables: live=%" Pd " dead=%" Pd " tag=%" Pd "\n",
                   total_live_code_objects,
                   total_dead_code_objects,
                   total_tag_code_objects);
       }
 
       if (FLAG_trace_profiler) {
         ScopeTimer sw("CodeRegionTableVerify", FLAG_trace_profiler);
         live_code_table.Verify();
         dead_code_table.Verify();
@@ skipping 17 matching lines @@
                                               &dead_code_table,
                                               &tag_code_table);
       code_trie_builder.set_tag_order(tag_order);
       {
         // Build CodeRegion trie.
         ScopeTimer sw("CodeRegionTrieBuilder", FLAG_trace_profiler);
         sample_buffer->VisitSamples(&code_trie_builder);
         code_trie_builder.exclusive_root()->SortByCount();
         code_trie_builder.inclusive_root()->SortByCount();
       }
+      if (FLAG_trace_profiler) {
+        OS::Print("Code Trie Root Count: E: %" Pd " I: %" Pd "\n",
+                  code_trie_builder.exclusive_root()->count(),
+                  code_trie_builder.inclusive_root()->count());
+      }
       ProfileFunctionTrieBuilder function_trie_builder(isolate,
                                                        &live_code_table,
                                                        &dead_code_table,
                                                        &tag_code_table,
                                                        &function_table);
       function_trie_builder.set_tag_order(tag_order);
       {
         // Build ProfileFunction trie.
         ScopeTimer sw("ProfileFunctionTrieBuilder",
                       FLAG_trace_profiler);
         sample_buffer->VisitSamples(&function_trie_builder);
         function_trie_builder.exclusive_root()->SortByCount();
         function_trie_builder.inclusive_root()->SortByCount();
       }
+      if (FLAG_trace_profiler) {
+        OS::Print("Function Trie Root Count: E: %" Pd " I: %" Pd "\n",
+                  function_trie_builder.exclusive_root()->count(),
+                  function_trie_builder.inclusive_root()->count());
+      }
       {
         ScopeTimer sw("CpuProfileJSONStream", FLAG_trace_profiler);
         // Serialize to JSON.
         JSONObject obj(stream);
         obj.AddProperty("type", "_CpuProfile");
         obj.AddProperty("sampleCount", samples);
         obj.AddProperty("samplePeriod",
                         static_cast<intptr_t>(FLAG_profile_period));
         obj.AddProperty("stackDepth",
                         static_cast<intptr_t>(FLAG_profile_depth));
@@ skipping 76 matching lines @@
   ASSERT(sample_buffer != NULL);
 
   ClearProfileVisitor clear_profile(isolate);
   sample_buffer->VisitSamples(&clear_profile);
 
   // Enable profile interrupts.
   Profiler::BeginExecution(isolate);
 }
 
 }  // namespace dart