[cpu-profiler] Log code events for bytecode flushing

Since the finalizer-based CodeEntry deallocation tracking can't
intercept flushed bytecode, implement monitoring for this via code
events.

Bug: v8:11054
Change-Id: I9557b4777fe0d0963309bd8134c57928e0aa3e08
Reviewed-on: https://chromium-review.googlesource.com/c/v8/v8/+/2686907
Commit-Queue: Andrew Comminos <acomminos@fb.com>
Reviewed-by: Ulan Degenbaev <ulan@chromium.org>
Reviewed-by: Peter Marshall <petermarshall@chromium.org>
Cr-Commit-Position: refs/heads/master@{#72639}

src/heap/mark-compact.cc

@@ -2207,6 +2207,8 @@ void MarkCompactCollector::FlushBytecodeFromSFI(
   // performing the unusual task of decompiling.
   shared_info.set_function_data(uncompiled_data, kReleaseStore);
   DCHECK(!shared_info.is_compiled());
+
+  PROFILE(heap()->isolate(), BytecodeFlushEvent(compiled_data_start));
 }
 
 void MarkCompactCollector::ClearOldBytecodeCandidates() {

src/logging/code-events.h

@@ -28,6 +28,7 @@ class WasmCode;
 using WasmName = Vector<const char>;
 }  // namespace wasm
 
+// clang-format off
 #define LOG_EVENTS_LIST(V)                             \
   V(CODE_CREATION_EVENT, code-creation)                \
   V(CODE_DISABLE_OPT_EVENT, code-disable-optimization) \
@@ -36,7 +37,9 @@ using WasmName = Vector<const char>;
   V(CODE_MOVING_GC, code-moving-gc)                    \
   V(SHARED_FUNC_MOVE_EVENT, sfi-move)                  \
   V(SNAPSHOT_CODE_NAME_EVENT, snapshot-code-name)      \
-  V(TICK_EVENT, tick)
+  V(TICK_EVENT, tick)                                  \
+  V(BYTECODE_FLUSH_EVENT, bytecode-flush)
+// clang-format on
 
 #define TAGS_LIST(V)                               \
   V(BUILTIN_TAG, Builtin)                          \
@@ -106,6 +109,8 @@ class CodeEventListener {
   virtual void CodeDependencyChangeEvent(Handle<Code> code,
                                          Handle<SharedFunctionInfo> shared,
                                          const char* reason) = 0;
+  // Invoked during GC. No allocation allowed.
+  virtual void BytecodeFlushEvent(Address compiled_data_start) = 0;
 
   virtual bool is_listening_to_code_events() { return false; }
 };
@@ -232,6 +237,11 @@ class CodeEventDispatcher : public CodeEventListener {
       listener->CodeDependencyChangeEvent(code, sfi, reason);
     });
   }
+  void BytecodeFlushEvent(Address compiled_data_start) override {
+    DispatchEventToListeners([=](CodeEventListener* listener) {
+      listener->BytecodeFlushEvent(compiled_data_start);
+    });
+  }
 
  private:
   std::unordered_set<CodeEventListener*> listeners_;

src/logging/log.h

@@ -214,6 +214,7 @@ class Logger : public CodeEventListener {
   void CodeDependencyChangeEvent(Handle<Code> code,
                                  Handle<SharedFunctionInfo> sfi,
                                  const char* reason) override;
+  void BytecodeFlushEvent(Address compiled_data_start) override {}
 
   void ProcessDeoptEvent(Handle<Code> code, SourcePosition position,
                          const char* kind, const char* reason);
@@ -411,6 +412,7 @@ class V8_EXPORT_PRIVATE CodeEventLogger : public CodeEventListener {
   void CodeDependencyChangeEvent(Handle<Code> code,
                                  Handle<SharedFunctionInfo> sfi,
                                  const char* reason) override {}
+  void BytecodeFlushEvent(Address compiled_data_start) override {}
 
  protected:
   Isolate* isolate_;
@@ -474,6 +476,7 @@ class ExternalCodeEventListener : public CodeEventListener {
   void CodeDependencyChangeEvent(Handle<Code> code,
                                  Handle<SharedFunctionInfo> sfi,
                                  const char* reason) override {}
+  void BytecodeFlushEvent(Address compiled_data_start) override {}
 
   void StartListening(v8::CodeEventHandler* code_event_handler);
   void StopListening();

src/profiler/profile-generator.cc

@@ -335,6 +335,7 @@ CpuProfileNode::SourceType ProfileNode::source_type() const {
     case CodeEventListener::SHARED_FUNC_MOVE_EVENT:
     case CodeEventListener::SNAPSHOT_CODE_NAME_EVENT:
     case CodeEventListener::TICK_EVENT:
+    case CodeEventListener::BYTECODE_FLUSH_EVENT:
     case CodeEventListener::NUMBER_OF_LOG_EVENTS:
       return CpuProfileNode::kInternal;
   }

src/profiler/profiler-listener.cc

@@ -299,6 +299,10 @@ void ProfilerListener::CodeDeoptEvent(Handle<Code> code, DeoptimizeKind kind,
   DispatchCodeEvent(evt_rec);
 }
 
+void ProfilerListener::BytecodeFlushEvent(Address compiled_data_start) {
+  // TODO(acomminos): Post flush event to profiler thread.
+}
+
 const char* ProfilerListener::GetName(Vector<const char> name) {
   // TODO(all): Change {StringsStorage} to accept non-null-terminated strings.
   OwnedVector<char> null_terminated = OwnedVector<char>::New(name.size() + 1);

src/profiler/profiler-listener.h

@@ -62,6 +62,7 @@ class V8_EXPORT_PRIVATE ProfilerListener : public CodeEventListener {
   void CodeDependencyChangeEvent(Handle<Code> code,
                                  Handle<SharedFunctionInfo> sfi,
                                  const char* reason) override {}
+  void BytecodeFlushEvent(Address compiled_data_start) override;
 
   const char* GetName(Name name) {
     return function_and_resource_names_.GetName(name);

src/runtime/runtime-test.cc

@@ -1667,6 +1667,7 @@ RUNTIME_FUNCTION(Runtime_EnableCodeLoggingForTesting) {
     void CodeDependencyChangeEvent(Handle<Code> code,
                                    Handle<SharedFunctionInfo> shared,
                                    const char* reason) final {}
+    void BytecodeFlushEvent(Address compiled_data_start) final {}
 
     bool is_listening_to_code_events() final { return true; }
   };

test/cctest/test-log.cc

@@ -1192,3 +1192,101 @@ UNINITIALIZED_TEST(BuiltinsNotLoggedAsLazyCompile) {
   }
   isolate->Dispose();
 }
+
+TEST(BytecodeFlushEvents) {
+  SETUP_FLAGS();
+
+#ifndef V8_LITE_MODE
+  i::FLAG_opt = false;
+  i::FLAG_always_opt = false;
+  i::FLAG_optimize_for_size = false;
+#endif  // V8_LITE_MODE
+  i::FLAG_flush_bytecode = true;
+  i::FLAG_allow_natives_syntax = true;
+
+  ManualGCScope manual_gc_scope;
+
+  v8::Isolate* isolate = CcTest::isolate();
+  i::Isolate* i_isolate = CcTest::i_isolate();
+  i::Factory* factory = i_isolate->factory();
+
+  struct FakeCodeEventLogger : public i::CodeEventLogger {
+    explicit FakeCodeEventLogger(i::Isolate* isolate)
+        : CodeEventLogger(isolate) {}
+
+    void CodeMoveEvent(i::AbstractCode from, i::AbstractCode to) override {}
+    void CodeDisableOptEvent(i::Handle<i::AbstractCode> code,
+                             i::Handle<i::SharedFunctionInfo> shared) override {
+    }
+
+    void BytecodeFlushEvent(Address compiled_data_start) override {
+      // We only expect a single flush.
+      CHECK_EQ(flushed_compiled_data_start, i::kNullAddress);
+      flushed_compiled_data_start = compiled_data_start;
+    }
+
+    void LogRecordedBuffer(i::Handle<i::AbstractCode> code,
+                           i::MaybeHandle<i::SharedFunctionInfo> maybe_shared,
+                           const char* name, int length) override {}
+    void LogRecordedBuffer(const i::wasm::WasmCode* code, const char* name,
+                           int length) override {}
+
+    i::Address flushed_compiled_data_start = i::kNullAddress;
+  };
+
+  FakeCodeEventLogger code_event_logger(i_isolate);
+
+  {
+    ScopedLoggerInitializer logger(isolate);
+    logger.logger()->AddCodeEventListener(&code_event_logger);
+
+    const char* source =
+        "function foo() {"
+        "  var x = 42;"
+        "  var y = 42;"
+        "  var z = x + y;"
+        "};"
+        "foo()";
+    i::Handle<i::String> foo_name = factory->InternalizeUtf8String("foo");
+
+    // This compile will add the code to the compilation cache.
+    {
+      v8::HandleScope scope(isolate);
+      CompileRun(source);
+    }
+
+    // Check function is compiled.
+    i::Handle<i::Object> func_value =
+        i::Object::GetProperty(i_isolate, i_isolate->global_object(), foo_name)
+            .ToHandleChecked();
+    CHECK(func_value->IsJSFunction());
+    i::Handle<i::JSFunction> function =
+        i::Handle<i::JSFunction>::cast(func_value);
+    CHECK(function->shared().is_compiled());
+
+    // The code will survive at least two GCs.
+    CcTest::CollectAllGarbage();
+    CcTest::CollectAllGarbage();
+    CHECK(function->shared().is_compiled());
+    CHECK_EQ(code_event_logger.flushed_compiled_data_start, i::kNullAddress);
+
+    // Get the start address of the compiled data before flushing.
+    i::HeapObject compiled_data =
+        function->shared().GetBytecodeArray(i_isolate);
+    i::Address compiled_data_start = compiled_data.address();
+
+    // Simulate several GCs that use full marking.
+    const int kAgingThreshold = 6;
+    for (int i = 0; i < kAgingThreshold; i++) {
+      CcTest::CollectAllGarbage();
+    }
+
+    // foo should no longer be in the compilation cache
+    CHECK(!function->shared().is_compiled());
+    CHECK(!function->is_compiled());
+
+    // Verify that foo() was in fact flushed.
+    CHECK_EQ(code_event_logger.flushed_compiled_data_start,
+             compiled_data_start);
+  }
+}