[cpu-profiler] Add logging to flaky tests

These flakes can't be reproduced locally so we need more information
when they fail. Add some logging so that we can figure out why they
are breaking.

Bug: v8:8649, v8:8648
Change-Id: I2fb1384bb7592c6fc68c08952505e79329f00bec
Reviewed-on: https://chromium-review.googlesource.com/c/1400418
Commit-Queue: Peter Marshall <petermarshall@chromium.org>
Reviewed-by: Yang Guo <yangguo@chromium.org>
Cr-Commit-Position: refs/heads/master@{#58641}

src/flag-definitions.h

@@ -934,6 +934,8 @@ DEFINE_BOOL(trace_compiler_dispatcher, false,
 // cpu-profiler.cc
 DEFINE_INT(cpu_profiler_sampling_interval, 1000,
            "CPU profiler sampling interval in microseconds")
+DEFINE_BOOL(cpu_profiler_logging, false,
+            "Detailed logging from the CPU profiler to help find bugs")
 
 // Array abuse tracing
 DEFINE_BOOL(trace_js_array_abuse, false,

src/profiler/profile-generator.cc

@@ -780,6 +780,11 @@ void ProfileGenerator::RecordTickSample(const TickSample& sample) {
   int src_line = no_line_info;
   bool src_line_not_found = true;
 
+  if (FLAG_cpu_profiler_logging) {
+    PrintF("RecordTickSample: ");
+    sample.print();
+  }
+
   if (sample.pc != nullptr) {
     if (sample.has_external_callback && sample.state == EXTERNAL) {
       // Don't use PC when in external callback code, as it can point
@@ -890,6 +895,18 @@ void ProfileGenerator::RecordTickSample(const TickSample& sample) {
     }
   }
 
+  if (FLAG_cpu_profiler_logging) {
+    PrintF("stack_trace:\n");
+    for (const CodeEntryAndLineNumber& pair : stack_trace) {
+      if (pair.code_entry) {
+        PrintF("  %s at %d\n", pair.code_entry->name(), pair.line_number);
+      } else {
+        PrintF("  null code entry\n");
+      }
+    }
+    PrintF("\n");
+  }
+
   profiles_->AddPathToCurrentProfiles(sample.timestamp, stack_trace, src_line,
                                       sample.update_stats);
 }

src/profiler/profiler-listener.cc

@@ -177,6 +177,11 @@ void ProfilerListener::CodeCreateEvent(CodeEventListener::LogEventsAndTags tag,
   }
 
   rec->entry->FillFunctionInfo(shared);
+
+  if (FLAG_cpu_profiler_logging) {
+    PrintF("CodeCreateEvent: ");
+    rec->entry->print();
+  }
   rec->instruction_size = abstract_code->InstructionSize();
   DispatchCodeEvent(evt_rec);
 }

src/profiler/tick-sample.cc

@@ -286,5 +286,20 @@ void TickSample::Init(Isolate* isolate, const v8::RegisterState& state,
   timestamp = base::TimeTicks::HighResolutionNow();
 }
 
+void TickSample::print() const {
+  PrintF("TickSample: at %p\n", this);
+  PrintF(" - state: %s\n", StateToString(state));
+  PrintF(" - pc: %p\n", pc);
+  PrintF(" - stack: (%u frames)\n", frames_count);
+  for (unsigned i = 0; i < frames_count; i++) {
+    PrintF("    %p\n", stack[i]);
+  }
+  PrintF(" - has_external_callback: %d\n", has_external_callback);
+  PrintF(" - %s: %p\n",
+         has_external_callback ? "external_callback_entry" : "tos", tos);
+  PrintF(" - update_stats: %d\n", update_stats);
+  PrintF("\n");
+}
+
 }  // namespace internal
 }  // namespace v8

src/profiler/tick-sample.h

@@ -19,6 +19,8 @@ struct TickSample : public v8::TickSample {
             RecordCEntryFrame record_c_entry_frame, bool update_stats,
             bool use_simulator_reg_state = true);
   base::TimeTicks timestamp;
+
+  void print() const;
 };
 
 }  // namespace internal

src/vm-state-inl.h

@@ -34,8 +34,8 @@ inline const char* StateToString(StateTag state) {
       return "OTHER";
     case EXTERNAL:
       return "EXTERNAL";
-    default:
-      UNREACHABLE();
+    case IDLE:
+      return "IDLE";
   }
 }
 

test/cctest/cctest.cc

@@ -95,6 +95,7 @@ void CcTest::Run() {
     }
     isolate_->Enter();
   }
+  i::FLAG_cpu_profiler_logging = true;
 #ifdef DEBUG
   const size_t active_isolates = i::Isolate::non_disposed_isolates();
 #endif  // DEBUG

test/cctest/test-cpu-profiler.cc

@@ -1772,7 +1772,7 @@ const double load_factor = 1.0;
 //                        bailed out due to 'Optimization is always disabled'
 //     2    (program):0 0 #2
 TEST(Inlining2) {
-  i::FLAG_allow_natives_syntax = true;
+  FLAG_allow_natives_syntax = true;
   v8::HandleScope scope(CcTest::isolate());
   v8::Local<v8::Context> env = CcTest::NewContext(PROFILER_EXTENSION);
   v8::Context::Scope context_scope(env);