[api] Use FLAG_log to check whether logging is enabled

Doing a function call into the logger to decide whether logging is enabled or not is more costly than necessary. This CL changes logging to take FLAG_log as main signal whether logging could be active. If FLAG_log == false, logging cannot be active. In that case we always call into the logger and perform detailed checks there. This CL changes flag-definitions to set FLAG_log if they need logging. Change-Id: Ia51ed9fb7128451bf1dcf345fab257547aab4a47 Reviewed-on: https://chromium-review.googlesource.com/c/v8/v8/+/2602461 Reviewed-by: Dominik Inführ <[email protected]> Reviewed-by: Jakob Gruber <[email protected]> Commit-Queue: Camillo Bruni <[email protected]> Cr-Commit-Position: refs/heads/master@{#72186}
zhaoleipeng · Jan 20, 2021 · 1dd3e29 · 1dd3e29
1 parent 73c399b
commit 1dd3e29
Show file tree

Hide file tree

Showing 18 changed files with 119 additions and 100 deletions.
diff --git a/src/deoptimizer/deoptimizer.cc b/src/deoptimizer/deoptimizer.cc
@@ -528,7 +528,7 @@ Deoptimizer::Deoptimizer(Isolate* isolate, JSFunction function,
       input_frame_context_(0),
       actual_argument_count_(0),
       stack_fp_(0),
-      trace_scope_(FLAG_trace_deopt
+      trace_scope_(FLAG_trace_deopt || FLAG_log_deopt
                        ? new CodeTracer::Scope(isolate->GetCodeTracer())
                        : nullptr) {
   if (isolate->deoptimizer_lazy_throw()) {
@@ -783,7 +783,7 @@ void Deoptimizer::TraceDeoptEnd(double deopt_duration) {
 
 // static
 void Deoptimizer::TraceMarkForDeoptimization(Code code, const char* reason) {
-  if (!FLAG_trace_deopt) return;
+  if (!FLAG_trace_deopt && !FLAG_log_deopt) return;
 
   DisallowGarbageCollection no_gc;
   Isolate* isolate = code.GetIsolate();
@@ -792,12 +792,14 @@ void Deoptimizer::TraceMarkForDeoptimization(Code code, const char* reason) {
 
   DeoptimizationData deopt_data = DeoptimizationData::cast(maybe_data);
   CodeTracer::Scope scope(isolate->GetCodeTracer());
-  PrintF(scope.file(), "[marking dependent code " V8PRIxPTR_FMT " (",
-         code.ptr());
-  deopt_data.SharedFunctionInfo().ShortPrint(scope.file());
-  PrintF(") (opt id %d) for deoptimization, reason: %s]\n",
-         deopt_data.OptimizationId().value(), reason);
-
+  if (FLAG_trace_deopt) {
+    PrintF(scope.file(), "[marking dependent code " V8PRIxPTR_FMT " (",
+           code.ptr());
+    deopt_data.SharedFunctionInfo().ShortPrint(scope.file());
+    PrintF(") (opt id %d) for deoptimization, reason: %s]\n",
+           deopt_data.OptimizationId().value(), reason);
+  }
+  if (!FLAG_log_deopt) return;
   no_gc.Release();
   {
     HandleScope scope(isolate);

diff --git a/src/execution/isolate.cc b/src/execution/isolate.cc
@@ -3885,7 +3885,8 @@ bool Isolate::NeedsDetailedOptimizedCodeLineInfo() const {
 bool Isolate::NeedsSourcePositionsForProfiling() const {
   return FLAG_trace_deopt || FLAG_trace_turbo || FLAG_trace_turbo_graph ||
          FLAG_turbo_profiling || FLAG_perf_prof || is_profiling() ||
-         debug_->is_active() || logger_->is_logging() || FLAG_trace_maps;
+         debug_->is_active() || logger_->is_logging() || FLAG_log_maps ||
+         FLAG_log_ic;
 }
 
 void Isolate::SetFeedbackVectorsForProfilingTools(Object value) {

diff --git a/src/flags/flag-definitions.h b/src/flags/flag-definitions.h
@@ -844,9 +844,9 @@ DEFINE_INT(wasm_tier_mask_for_testing, 0,
 DEFINE_BOOL(validate_asm, true, "validate asm.js modules before compiling")
 DEFINE_BOOL(suppress_asm_messages, false,
             "don't emit asm.js related messages (for golden file testing)")
-DEFINE_BOOL(trace_asm_time, false, "log asm.js timing info to the console")
+DEFINE_BOOL(trace_asm_time, false, "print asm.js timing info to the console")
 DEFINE_BOOL(trace_asm_scanner, false,
-            "log tokens encountered by asm.js scanner")
+            "print tokens encountered by asm.js scanner")
 DEFINE_BOOL(trace_asm_parser, false, "verbose logging of asm.js parse failures")
 DEFINE_BOOL(stress_validate_asm, false, "try to validate everything as asm.js")
 
@@ -1290,6 +1290,7 @@ DEFINE_BOOL(trace_opt_verbose, false,
 DEFINE_IMPLICATION(trace_opt_verbose, trace_opt)
 DEFINE_BOOL(trace_opt_stats, false, "trace optimized compilation statistics")
 DEFINE_BOOL(trace_deopt, false, "trace deoptimization")
+DEFINE_BOOL(log_deopt, false, "log deoptimization")
 DEFINE_BOOL(trace_deopt_verbose, false, "extra verbose deoptimization tracing")
 DEFINE_IMPLICATION(trace_deopt_verbose, trace_deopt)
 DEFINE_BOOL(trace_file_names, false,
@@ -1365,9 +1366,11 @@ DEFINE_BOOL(sampling_heap_profiler_suppress_randomness, false,
 DEFINE_BOOL(use_idle_notification, true,
             "Use idle notification to reduce memory footprint.")
 // ic.cc
-DEFINE_BOOL(trace_ic, false,
-            "trace inline cache state transitions for tools/ic-processor")
-DEFINE_IMPLICATION(trace_ic, log_code)
+DEFINE_BOOL(log_ic, false,
+            "Log inline cache state transitions for tools/ic-processor")
+DEFINE_BOOL(trace_ic, false, "See --log-ic")
+DEFINE_IMPLICATION(trace_ic, log_ic)
+DEFINE_IMPLICATION(log_ic, log_code)
 DEFINE_GENERIC_IMPLICATION(
     trace_ic, TracingFlags::ic_stats.store(
                   v8::tracing::TracingCategoryObserver::ENABLED_BY_NATIVE))
@@ -1386,9 +1389,9 @@ DEFINE_BOOL(thin_strings, true, "Enable ThinString support")
 DEFINE_BOOL(trace_prototype_users, false,
             "Trace updates to prototype user tracking")
 DEFINE_BOOL(trace_for_in_enumerate, false, "Trace for-in enumerate slow-paths")
-DEFINE_BOOL(trace_maps, false, "trace map creation")
-DEFINE_BOOL(trace_maps_details, true, "also log map details")
-DEFINE_IMPLICATION(trace_maps, log_code)
+DEFINE_BOOL(log_maps, false, "Log map creation")
+DEFINE_BOOL(log_maps_details, true, "Also log map details")
+DEFINE_IMPLICATION(log_maps, log_code)
 
 // parser.cc
 DEFINE_BOOL(allow_natives_syntax, false, "allow natives syntax")
@@ -1710,6 +1713,10 @@ DEFINE_BOOL(trace_wasm_gdb_remote, false, "trace Webassembly GDB-remote server")
 //
 // Logging and profiling flags
 //
+// Logging flag dependencies are are also set separately in
+// V8::InitializeOncePerProcessImpl. Please add your flag to the log_all_flags
+// list in v8.cc to properly set FLAG_log and automatically enable it with
+// --log-all.
 #undef FLAG
 #define FLAG FLAG_FULL
 
@@ -1722,6 +1729,7 @@ DEFINE_BOOL(logfile_per_isolate, true, "Separate log files for each isolate.")
 DEFINE_BOOL(log, false,
             "Minimal logging (no API, code, GC, suspect, or handles samples).")
 DEFINE_BOOL(log_all, false, "Log all events to the log file.")
+
 DEFINE_BOOL(log_api, false, "Log API events to the log file.")
 DEFINE_BOOL(log_code, false,
             "Log code events to the log file without profiling.")
@@ -1735,14 +1743,6 @@ DEFINE_BOOL(log_function_events, false,
             "Log function events "
             "(parse, compile, execute) separately.")
 
-DEFINE_IMPLICATION(log_all, log_api)
-DEFINE_IMPLICATION(log_all, log_code)
-DEFINE_IMPLICATION(log_all, log_code_disassemble)
-DEFINE_IMPLICATION(log_all, log_suspect)
-DEFINE_IMPLICATION(log_all, log_handles)
-DEFINE_IMPLICATION(log_all, log_internal_timer_events)
-DEFINE_IMPLICATION(log_all, log_function_events)
-
 DEFINE_BOOL(detailed_line_info, false,
             "Always generate detailed line information for CPU profiling.")
 

diff --git a/src/heap/factory.cc b/src/heap/factory.cc
@@ -1482,7 +1482,7 @@ Map Factory::InitializeMap(Map map, InstanceType type, int instance_size,
   map.clear_padding();
   map.set_elements_kind(elements_kind);
   isolate()->counters()->maps_created()->Increment();
-  if (FLAG_trace_maps) LOG(isolate(), MapCreate(map));
+  if (FLAG_log_maps) LOG(isolate(), MapCreate(map));
   return map;
 }
 

diff --git a/src/init/bootstrapper.cc b/src/init/bootstrapper.cc
@@ -346,7 +346,7 @@ Handle<JSGlobalProxy> Bootstrapper::NewRemoteContext(
 }
 
 void Bootstrapper::LogAllMaps() {
-  if (!FLAG_trace_maps || isolate_->initialized_from_snapshot()) return;
+  if (!FLAG_log_maps || isolate_->initialized_from_snapshot()) return;
   // Log all created Map objects that are on the heap. For snapshots the Map
   // logging happens during deserialization in order to avoid printing Maps
   // multiple times during partial deserialization.

diff --git a/src/init/v8.cc b/src/init/v8.cc
@@ -57,6 +57,36 @@ void V8::TearDown() {
 }
 
 void V8::InitializeOncePerProcessImpl() {
+  // Update logging information before enforcing flag implications.
+  bool* log_all_flags[] = {&FLAG_turbo_profiling_log_builtins,
+                           &FLAG_log_all,
+                           &FLAG_log_api,
+                           &FLAG_log_code,
+                           &FLAG_log_code_disassemble,
+                           &FLAG_log_handles,
+                           &FLAG_log_suspect,
+                           &FLAG_log_source_code,
+                           &FLAG_log_function_events,
+                           &FLAG_log_internal_timer_events,
+                           &FLAG_log_deopt,
+                           &FLAG_log_ic,
+                           &FLAG_log_maps};
+  if (FLAG_log_all) {
+    // Enable all logging flags
+    for (auto* flag : log_all_flags) {
+      *flag = true;
+    }
+    FLAG_log = true;
+  } else if (!FLAG_log) {
+    // Enable --log if any log flag is set.
+    for (const auto* flag : log_all_flags) {
+      if (!*flag) continue;
+      FLAG_log = true;
+      break;
+    }
+    FLAG_log |= FLAG_perf_basic_prof || FLAG_prof || FLAG_prof_cpp;
+  }
+
   FlagList::EnforceFlagImplications();
 
   if (FLAG_predictable && FLAG_random_seed == 0) {

diff --git a/src/logging/log-utils.cc b/src/logging/log-utils.cc
@@ -25,7 +25,7 @@ const char* const Log::kLogToConsole = "-";
 // static
 FILE* Log::CreateOutputHandle(std::string file_name) {
   // If we're logging anything, we need to open the log file.
-  if (!Log::InitLogAtStart()) {
+  if (!FLAG_log) {
     return nullptr;
   } else if (Log::IsLoggingToConsole(file_name)) {
     return stdout;

diff --git a/src/logging/log-utils.h b/src/logging/log-utils.h
@@ -32,15 +32,6 @@ class Log {
  public:
   explicit Log(Logger* logger, std::string log_file_name);
 
-  static bool InitLogAtStart() {
-    return FLAG_log || FLAG_log_all || FLAG_log_api || FLAG_log_code ||
-           FLAG_log_handles || FLAG_log_suspect || FLAG_ll_prof ||
-           FLAG_perf_basic_prof || FLAG_perf_prof || FLAG_log_source_code ||
-           FLAG_gdbjit || FLAG_log_internal_timer_events || FLAG_prof_cpp ||
-           FLAG_trace_ic || FLAG_log_function_events || FLAG_trace_zone_stats ||
-           FLAG_turbo_profiling_log_builtins;
-  }
-
   V8_EXPORT_PRIVATE static bool IsLoggingToConsole(std::string file_name);
   V8_EXPORT_PRIVATE static bool IsLoggingToTemporaryFile(std::string file_name);
 

diff --git a/src/logging/log.cc b/src/logging/log.cc
@@ -1030,10 +1030,7 @@ void Logger::UncheckedStringEvent(const char* name, const char* value) {
 }
 
 void Logger::IntPtrTEvent(const char* name, intptr_t value) {
-  if (FLAG_log) UncheckedIntPtrTEvent(name, value);
-}
-
-void Logger::UncheckedIntPtrTEvent(const char* name, intptr_t value) {
+  if (!FLAG_log) return;
   MSG_BUILDER();
   msg << name << kNext;
   msg.AppendFormatString("%" V8PRIdPTR, value);
@@ -1470,7 +1467,7 @@ void Logger::ProcessDeoptEvent(Handle<Code> code, SourcePosition position,
 
 void Logger::CodeDeoptEvent(Handle<Code> code, DeoptimizeKind kind, Address pc,
                             int fp_to_sp_delta, bool reuse_code) {
-  if (!is_logging()) return;
+  if (!is_logging() || !FLAG_log_deopt) return;
   Deoptimizer::DeoptInfo info = Deoptimizer::GetDeoptInfo(*code, pc);
   ProcessDeoptEvent(code, info.position,
                     Deoptimizer::MessageFor(kind, reuse_code),
@@ -1480,49 +1477,49 @@ void Logger::CodeDeoptEvent(Handle<Code> code, DeoptimizeKind kind, Address pc,
 void Logger::CodeDependencyChangeEvent(Handle<Code> code,
                                        Handle<SharedFunctionInfo> sfi,
                                        const char* reason) {
-  if (!is_logging()) return;
+  if (!is_logging() || !FLAG_log_deopt) return;
   SourcePosition position(sfi->StartPosition(), -1);
   ProcessDeoptEvent(code, position, "dependency-change", reason);
 }
 
 namespace {
 
 void CodeLinePosEvent(
-    JitLogger* jit_logger, Address code_start,
+    JitLogger& jit_logger, Address code_start,
     SourcePositionTableIterator& iter) {  // NOLINT(runtime/references)
-  if (jit_logger) {
-    void* jit_handler_data = jit_logger->StartCodePosInfoEvent();
-    for (; !iter.done(); iter.Advance()) {
-      if (iter.is_statement()) {
-        jit_logger->AddCodeLinePosInfoEvent(
-            jit_handler_data, iter.code_offset(),
-            iter.source_position().ScriptOffset(),
-            JitCodeEvent::STATEMENT_POSITION);
-      }
-      jit_logger->AddCodeLinePosInfoEvent(jit_handler_data, iter.code_offset(),
-                                          iter.source_position().ScriptOffset(),
-                                          JitCodeEvent::POSITION);
+  void* jit_handler_data = jit_logger.StartCodePosInfoEvent();
+  for (; !iter.done(); iter.Advance()) {
+    if (iter.is_statement()) {
+      jit_logger.AddCodeLinePosInfoEvent(jit_handler_data, iter.code_offset(),
+                                         iter.source_position().ScriptOffset(),
+                                         JitCodeEvent::STATEMENT_POSITION);
     }
-    jit_logger->EndCodePosInfoEvent(code_start, jit_handler_data);
+    jit_logger.AddCodeLinePosInfoEvent(jit_handler_data, iter.code_offset(),
+                                       iter.source_position().ScriptOffset(),
+                                       JitCodeEvent::POSITION);
   }
+  jit_logger.EndCodePosInfoEvent(code_start, jit_handler_data);
 }
 
 }  // namespace
 
 void Logger::CodeLinePosInfoRecordEvent(Address code_start,
                                         ByteArray source_position_table) {
+  if (!jit_logger_) return;
   SourcePositionTableIterator iter(source_position_table);
-  CodeLinePosEvent(jit_logger_.get(), code_start, iter);
+  CodeLinePosEvent(*jit_logger_, code_start, iter);
 }
 
 void Logger::CodeLinePosInfoRecordEvent(
     Address code_start, Vector<const byte> source_position_table) {
+  if (!jit_logger_) return;
   SourcePositionTableIterator iter(source_position_table);
-  CodeLinePosEvent(jit_logger_.get(), code_start, iter);
+  CodeLinePosEvent(*jit_logger_, code_start, iter);
 }
 
 void Logger::CodeNameEvent(Address addr, int pos, const char* code_name) {
   if (code_name == nullptr) return;  // Not a code object.
+  if (!is_listening_to_code_events()) return;
   MSG_BUILDER();
   msg << kLogEventsNames[CodeEventListener::SNAPSHOT_CODE_NAME_EVENT] << kNext
       << pos << kNext << code_name;
@@ -1727,7 +1724,7 @@ void Logger::TickEvent(TickSample* sample, bool overflow) {
 void Logger::ICEvent(const char* type, bool keyed, Handle<Map> map,
                      Handle<Object> key, char old_state, char new_state,
                      const char* modifier, const char* slow_stub_reason) {
-  if (!FLAG_trace_ic) return;
+  if (!FLAG_log_ic) return;
   MSG_BUILDER();
   if (keyed) msg << "Keyed";
   int line;
@@ -1753,7 +1750,7 @@ void Logger::ICEvent(const char* type, bool keyed, Handle<Map> map,
 
 void Logger::MapEvent(const char* type, Handle<Map> from, Handle<Map> to,
                       const char* reason, Handle<HeapObject> name_or_sfi) {
-  if (!FLAG_trace_maps) return;
+  if (!FLAG_log_maps) return;
   if (!to.is_null()) MapDetails(*to);
   int line = -1;
   int column = -1;
@@ -1784,20 +1781,20 @@ void Logger::MapEvent(const char* type, Handle<Map> from, Handle<Map> to,
 }
 
 void Logger::MapCreate(Map map) {
-  if (!FLAG_trace_maps) return;
+  if (!FLAG_log_maps) return;
   DisallowGarbageCollection no_gc;
   MSG_BUILDER();
   msg << "map-create" << kNext << Time() << kNext << AsHex::Address(map.ptr());
   msg.WriteToLogFile();
 }
 
 void Logger::MapDetails(Map map) {
-  if (!FLAG_trace_maps) return;
+  if (!FLAG_log_maps) return;
   DisallowGarbageCollection no_gc;
   MSG_BUILDER();
   msg << "map-details" << kNext << Time() << kNext << AsHex::Address(map.ptr())
       << kNext;
-  if (FLAG_trace_maps_details) {
+  if (FLAG_log_maps_details) {
     std::ostringstream buffer;
     map.PrintMapDetails(buffer);
     msg << buffer.str().c_str();
@@ -2008,21 +2005,16 @@ bool Logger::SetUp(Isolate* isolate) {
         std::make_unique<LowLevelLogger>(isolate, log_file_name.str().c_str());
     AddCodeEventListener(ll_logger_.get());
   }
-
   ticker_ = std::make_unique<Ticker>(isolate, FLAG_prof_sampling_interval);
-
-  if (Log::InitLogAtStart()) UpdateIsLogging(true);
-
+  if (FLAG_log) UpdateIsLogging(true);
   timer_.Start();
-
   if (FLAG_prof_cpp) {
-    UpdateIsLogging(true);
+    CHECK(FLAG_log);
+    CHECK(is_logging());
     profiler_ = std::make_unique<Profiler>(isolate);
     profiler_->Engage();
   }
-
   if (is_logging_) AddCodeEventListener(this);
-
   return true;
 }
 

diff --git a/src/logging/log.h b/src/logging/log.h
@@ -72,10 +72,9 @@ class SourcePosition;
 class Ticker;
 
 #undef LOG
-#define LOG(isolate, Call)                  \
-  do {                                      \
-    auto&& logger = (isolate)->logger();    \
-    if (logger->is_logging()) logger->Call; \
+#define LOG(isolate, Call)                                 \
+  do {                                                     \
+    if (v8::internal::FLAG_log) (isolate)->logger()->Call; \
   } while (false)
 
 #define LOG_CODE_EVENT(isolate, Call)                        \
@@ -305,9 +304,6 @@ class Logger : public CodeEventListener {
   // Logs a StringEvent regardless of whether FLAG_log is true.
   void UncheckedStringEvent(const char* name, const char* value);
 
-  // Logs an IntPtrTEvent regardless of whether FLAG_log is true.
-  void UncheckedIntPtrTEvent(const char* name, intptr_t value);
-
   // Logs a scripts sources. Keeps track of all logged scripts to ensure that
   // each script is logged only once.
   bool EnsureLogScriptSource(Script script);

diff --git a/src/objects/js-function.cc b/src/objects/js-function.cc
@@ -450,7 +450,7 @@ void JSFunction::SetInitialMap(Handle<JSFunction> function, Handle<Map> map,
   }
   function->set_prototype_or_initial_map(*map);
   map->SetConstructor(*function);
-  if (FLAG_trace_maps) {
+  if (FLAG_log_maps) {
     LOG(isolate, MapEvent("InitialMap", Handle<Map>(), map, "",
                           SharedFunctionInfo::DebugName(
                               handle(function->shared(), isolate))));