[cpu-profiler] Add stats to track missing or unnattributed frames

This adds a global counter for the various reasons we might fail to
attribute a tick.

The counters are cleared and printed when Profile::Print() is called,
which we call in our tests, so flaky test output will now contain these
stats along with the printed profile tree.

Drive-by cleanup some print functions and make them const.

Change-Id: Ia3a27405f5b5346adfdbb32afc7e414857969cc5
Reviewed-on: https://chromium-review.googlesource.com/c/v8/v8/+/1550406
Commit-Queue: Peter Marshall <petermarshall@chromium.org>
Reviewed-by: Clemens Backes <clemensb@chromium.org>
Cr-Commit-Position: refs/heads/master@{#69647}

BUILD.gn

@@ -3059,6 +3059,8 @@ v8_source_set("v8_base_without_compiler") {
     "src/profiler/profile-generator.h",
     "src/profiler/profiler-listener.cc",
     "src/profiler/profiler-listener.h",
+    "src/profiler/profiler-stats.cc",
+    "src/profiler/profiler-stats.h",
     "src/profiler/sampling-heap-profiler.cc",
     "src/profiler/sampling-heap-profiler.h",
     "src/profiler/strings-storage.cc",

src/libsampler/sampler.cc

@@ -227,6 +227,7 @@ void SamplerManager::RemoveSampler(Sampler* sampler) {
 
 void SamplerManager::DoSample(const v8::RegisterState& state) {
   AtomicGuard atomic_guard(&samplers_access_counter_, false);
+  // TODO(petermarshall): Add stat counters for the bailouts here.
   if (!atomic_guard.is_success()) return;
   pthread_t thread_id = pthread_self();
   auto it = sampler_map_.find(thread_id);

src/profiler/cpu-profiler.cc

@@ -16,6 +16,7 @@
 #include "src/logging/counters.h"
 #include "src/logging/log.h"
 #include "src/profiler/cpu-profiler-inl.h"
+#include "src/profiler/profiler-stats.h"
 #include "src/utils/locked-queue-inl.h"
 #include "src/wasm/wasm-engine.h"
 
@@ -32,7 +33,13 @@ class CpuSampler : public sampler::Sampler {
 
   void SampleStack(const v8::RegisterState& regs) override {
     TickSample* sample = processor_->StartTickSample();
-    if (sample == nullptr) return;
+    if (sample == nullptr) {
+      ProfilerStats::Instance()->AddReason(
+          ProfilerStats::Reason::kTickBufferFull);
+      return;
+    }
+    // Every bailout up until here resulted in a dropped sample. From now on,
+    // the sample is created in the buffer.
     Isolate* isolate = reinterpret_cast<Isolate*>(this->isolate());
     sample->Init(isolate, regs, TickSample::kIncludeCEntryFrame,
                  /* update_stats */ true,

src/profiler/profile-generator.cc

@@ -10,6 +10,7 @@
 #include "src/objects/shared-function-info-inl.h"
 #include "src/profiler/cpu-profiler.h"
 #include "src/profiler/profile-generator-inl.h"
+#include "src/profiler/profiler-stats.h"
 #include "src/tracing/trace-event.h"
 #include "src/tracing/traced-value.h"
 
@@ -331,8 +332,7 @@ void ProfileNode::Print(int indent) const {
   if (entry_->resource_name()[0] != '\0')
     base::OS::Print(" %s:%d", entry_->resource_name(), entry_->line_number());
   base::OS::Print("\n");
-  for (size_t i = 0; i < deopt_infos_.size(); ++i) {
-    const CpuProfileDeoptInfo& info = deopt_infos_[i];
+  for (const CpuProfileDeoptInfo& info : deopt_infos_) {
     base::OS::Print(
         "%*s;;; deopted at script_id: %d position: %zu with reason '%s'.\n",
         indent + 10, "", info.stack[0].script_id, info.stack[0].position,
@@ -661,9 +661,11 @@ void CpuProfile::FinishProfile() {
                               "ProfileChunk", id_, "data", std::move(value));
 }
 
-void CpuProfile::Print() {
+void CpuProfile::Print() const {
   base::OS::Print("[Top down]:\n");
   top_down_.Print();
+  ProfilerStats::Instance()->Print();
+  ProfilerStats::Instance()->Clear();
 }
 
 CodeMap::CodeMap() = default;
@@ -935,6 +937,8 @@ void ProfileGenerator::SymbolizeTickSample(const TickSample& sample) {
           // former case we don't so we simply replace the frame with
           // 'unresolved' entry.
           if (!sample.has_external_callback) {
+            ProfilerStats::Instance()->AddReason(
+                ProfilerStats::Reason::kInCallOrApply);
             stack_trace.push_back(
                 {{CodeEntry::unresolved_entry(), no_line_info},
                  kNullAddress,
@@ -1007,6 +1011,12 @@ void ProfileGenerator::SymbolizeTickSample(const TickSample& sample) {
     }
     // If no frames were symbolized, put the VM state entry in.
     if (no_symbolized_entries) {
+      if (sample.pc == nullptr) {
+        ProfilerStats::Instance()->AddReason(ProfilerStats::Reason::kNullPC);
+      } else {
+        ProfilerStats::Instance()->AddReason(
+            ProfilerStats::Reason::kNoSymbolizedFrames);
+      }
       stack_trace.push_back(
           {{EntryForVMState(sample.state), no_line_info}, kNullAddress, false});
     }

src/profiler/profile-generator.h

@@ -348,9 +348,7 @@ class V8_EXPORT_PRIVATE ProfileTree {
   ProfileNode* root() const { return root_; }
   unsigned next_node_id() { return next_node_id_++; }
 
-  void Print() {
-    root_->Print(0);
-  }
+  void Print() const { root_->Print(0); }
 
   Isolate* isolate() const { return isolate_; }
 
@@ -412,7 +410,7 @@ class CpuProfile {
 
   void UpdateTicksScale();
 
-  V8_EXPORT_PRIVATE void Print();
+  V8_EXPORT_PRIVATE void Print() const;
 
  private:
   void StreamPendingTraceEvents();

src/profiler/profiler-stats.cc

+// Copyright 2020 the V8 project authors. All rights reserved.
+// Use of this source code is governed by a BSD-style license that can be
+// found in the LICENSE file.
+
+#include "src/profiler/profiler-stats.h"
+
+#include <algorithm>
+
+#include "src/base/platform/platform.h"
+
+namespace v8 {
+namespace internal {
+
+void ProfilerStats::AddReason(Reason reason) {
+  counts_[reason].fetch_add(1, std::memory_order_relaxed);
+}
+
+void ProfilerStats::Clear() {
+  for (int i = 0; i < Reason::kNumberOfReasons; i++) {
+    counts_[i].store(0, std::memory_order_relaxed);
+  }
+}
+
+void ProfilerStats::Print() const {
+  base::OS::Print("ProfilerStats:\n");
+  for (int i = 0; i < Reason::kNumberOfReasons; i++) {
+    base::OS::Print("  %-30s\t\t %d\n", ReasonToString(static_cast<Reason>(i)),
+                    counts_[i].load(std::memory_order_relaxed));
+  }
+}
+
+// static
+const char* ProfilerStats::ReasonToString(Reason reason) {
+  switch (reason) {
+    case kTickBufferFull:
+      return "kTickBufferFull";
+    case kSimulatorFillRegistersFailed:
+      return "kSimulatorFillRegistersFailed";
+    case kNoFrameRegion:
+      return "kNoFrameRegion";
+    case kInCallOrApply:
+      return "kInCallOrApply";
+    case kNoSymbolizedFrames:
+      return "kNoSymbolizedFrames";
+    case kNullPC:
+      return "kNullPC";
+    case kNumberOfReasons:
+      return "kNumberOfReasons";
+  }
+}
+
+}  // namespace internal
+}  // namespace v8

src/profiler/profiler-stats.h

+// Copyright 2020 the V8 project authors. All rights reserved.
+// Use of this source code is governed by a BSD-style license that can be
+// found in the LICENSE file.
+
+#ifndef V8_PROFILER_PROFILER_STATS_H_
+#define V8_PROFILER_PROFILER_STATS_H_
+
+#include <atomic>
+
+namespace v8 {
+namespace internal {
+
+// Stats are used to diagnose the reasons for dropped or unnattributed frames.
+class ProfilerStats {
+ public:
+  enum Reason {
+    // Reasons we fail to record a TickSample.
+    kTickBufferFull,
+    // These all generate a TickSample.
+    kSimulatorFillRegistersFailed,
+    kNoFrameRegion,
+    kInCallOrApply,
+    kNoSymbolizedFrames,
+    kNullPC,
+
+    kNumberOfReasons,
+  };
+
+  static ProfilerStats* Instance() {
+    static ProfilerStats stats;
+    return &stats;
+  }
+
+  void AddReason(Reason reason);
+  void Clear();
+  void Print() const;
+
+ private:
+  ProfilerStats() = default;
+  static const char* ReasonToString(Reason reason);
+
+  std::atomic_int counts_[Reason::kNumberOfReasons] = {};
+};
+
+}  // namespace internal
+}  // namespace v8
+
+#endif  // V8_PROFILER_PROFILER_STATS_H_

src/profiler/tick-sample.cc

@@ -12,6 +12,7 @@
 #include "src/execution/vm-state-inl.h"
 #include "src/heap/heap-inl.h"  // For Heap::code_range.
 #include "src/logging/counters.h"
+#include "src/profiler/profiler-stats.h"
 #include "src/sanitizer/asan.h"
 #include "src/sanitizer/msan.h"
 
@@ -223,7 +224,11 @@ bool TickSample::GetStackSample(Isolate* v8_isolate, RegisterState* regs,
 
 #if defined(USE_SIMULATOR)
   if (use_simulator_reg_state) {
-    if (!i::SimulatorHelper::FillRegisters(isolate, regs)) return false;
+    if (!i::SimulatorHelper::FillRegisters(isolate, regs)) {
+      i::ProfilerStats::Instance()->AddReason(
+          i::ProfilerStats::Reason::kSimulatorFillRegistersFailed);
+      return false;
+    }
   }
 #else
   USE(use_simulator_reg_state);
@@ -232,11 +237,15 @@ bool TickSample::GetStackSample(Isolate* v8_isolate, RegisterState* regs,
 
   // Check whether we interrupted setup/teardown of a stack frame in JS code.
   // Avoid this check for C++ code, as that would trigger false positives.
+  // TODO(petermarshall): Code range is always null on ia32 so this check for
+  // IsNoFrameRegion will never actually run there.
   if (regs->pc &&
       isolate->heap()->memory_allocator()->code_range().contains(
           reinterpret_cast<i::Address>(regs->pc)) &&
       IsNoFrameRegion(reinterpret_cast<i::Address>(regs->pc))) {
     // The frame is not setup, so it'd be hard to iterate the stack. Bailout.
+    i::ProfilerStats::Instance()->AddReason(
+        i::ProfilerStats::Reason::kNoFrameRegion);
     return false;
   }
 

test/cctest/test-cpu-profiler.cc

@@ -2111,9 +2111,7 @@ TEST(FunctionDetails) {
       "script_b", true);
   script_b->Run(env).ToLocalChecked();
   const v8::CpuProfile* profile = i::ProfilerExtension::last_profile;
-  const v8::CpuProfileNode* current = profile->GetTopDownRoot();
-  reinterpret_cast<ProfileNode*>(const_cast<v8::CpuProfileNode*>(current))
-      ->Print(0);
+  reinterpret_cast<const i::CpuProfile*>(profile)->Print();
   // The tree should look like this:
   //  0   (root) 0 #1
   //  0    "" 19 #2 no reason script_b:1
@@ -2189,9 +2187,7 @@ TEST(FunctionDetailsInlining) {
   script_a->Run(env).ToLocalChecked();
 
   const v8::CpuProfile* profile = i::ProfilerExtension::last_profile;
-  const v8::CpuProfileNode* current = profile->GetTopDownRoot();
-  reinterpret_cast<ProfileNode*>(const_cast<v8::CpuProfileNode*>(current))
-      ->Print(0);
+  reinterpret_cast<const i::CpuProfile*>(profile)->Print();
   //   The tree should look like this:
   //  0  (root) 0 #1
   //  5    (program) 0 #6