[logging] Make Logger::SetUp and TearDownAndGetLogFile thread-safe

While so far this should only happen in tests in test-log.cc, it can
happen that background threads using Logger::is_logging() race with
Logger::TearDownAndGetLogFile().

Fix the race by protecting is_logging_ with the mutex that is also used
for writing log messages. Logger::is_logging_ now becomes relaxed
atomic, such that code for logging isn't required to lock the mutex
to check whether logging is enabled.

Also remove Log::IsEnabled() in favor of Logger::is_logging() to avoid
checking both flags since both are the same.

Bug: v8:10315
Change-Id: Ic14e7f74334eb8a8438abad82ad227d1e6752bb8
Reviewed-on: https://chromium-review.googlesource.com/c/v8/v8/+/2416488
Commit-Queue: Dominik Inführ <dinfuehr@chromium.org>
Reviewed-by: Ulan Degenbaev <ulan@chromium.org>
Cr-Commit-Position: refs/heads/master@{#69973}

src/logging/log-utils.cc

@@ -46,20 +46,17 @@ bool Log::IsLoggingToTemporaryFile(std::string file_name) {
   return file_name.compare(Log::kLogToTemporaryFile) == 0;
 }
 
-Log::Log(std::string file_name)
-    : file_name_(file_name),
+Log::Log(Logger* logger, std::string file_name)
+    : logger_(logger),
+      file_name_(file_name),
       output_handle_(Log::CreateOutputHandle(file_name)),
       os_(output_handle_ == nullptr ? stdout : output_handle_),
-      is_enabled_(output_handle_ != nullptr),
       format_buffer_(NewArray<char>(kMessageBufferSize)) {
-  if (output_handle_ == nullptr) return;
-  WriteLogHeader();
+  if (output_handle_) WriteLogHeader();
 }
 
 void Log::WriteLogHeader() {
-  std::unique_ptr<Log::MessageBuilder> msg_ptr = NewMessageBuilder();
-  if (!msg_ptr) return;
-  Log::MessageBuilder& msg = *msg_ptr.get();
+  Log::MessageBuilder msg(this);
   LogSeparator kNext = LogSeparator::kSeparator;
   msg << "v8-version" << kNext << Version::GetMajor() << kNext
       << Version::GetMinor() << kNext << Version::GetBuild() << kNext
@@ -72,22 +69,21 @@ void Log::WriteLogHeader() {
 }
 
 std::unique_ptr<Log::MessageBuilder> Log::NewMessageBuilder() {
-  // Fast check of IsEnabled() without taking the lock. Bail out immediately if
+  // Fast check of is_logging() without taking the lock. Bail out immediately if
   // logging isn't enabled.
-  if (!IsEnabled()) return {};
+  if (!logger_->is_logging()) return {};
 
   std::unique_ptr<Log::MessageBuilder> result(new Log::MessageBuilder(this));
 
-  // The first invocation of IsEnabled() might still read an old value. It is
+  // The first invocation of is_logging() might still read an old value. It is
   // fine if a background thread starts logging a bit later, but we want to
-  // avoid background threads continue logging after logging was closed.
-  if (!IsEnabled()) return {};
+  // avoid background threads continue logging after logging was already closed.
+  if (!logger_->is_logging()) return {};
 
   return result;
 }
 
 FILE* Log::Close() {
-  base::MutexGuard guard(&mutex_);
   FILE* result = nullptr;
   if (output_handle_ != nullptr) {
     fflush(output_handle_);
@@ -95,7 +91,6 @@ FILE* Log::Close() {
   }
   output_handle_ = nullptr;
   format_buffer_.reset();
-  is_enabled_.store(false, std::memory_order_relaxed);
   return result;
 }
 
@@ -227,7 +222,6 @@ void Log::MessageBuilder::AppendRawFormatString(const char* format, ...) {
 void Log::MessageBuilder::AppendRawCharacter(char c) { log_->os_ << c; }
 
 void Log::MessageBuilder::WriteToLogFile() {
-  DCHECK(log_->IsEnabled());
   log_->os_ << std::endl;
 }
 

src/logging/log-utils.h

@@ -30,7 +30,7 @@ enum class LogSeparator { kSeparator };
 // Functions and data for performing output of log messages.
 class Log {
  public:
-  explicit Log(std::string log_file_name);
+  explicit Log(Logger* logger, std::string log_file_name);
 
   static bool InitLogAtStart() {
     return FLAG_log || FLAG_log_all || FLAG_log_api || FLAG_log_code ||
@@ -51,9 +51,6 @@ class Log {
 
   std::string file_name() const;
 
-  // Returns whether logging is enabled.
-  bool IsEnabled() { return is_enabled_.load(std::memory_order_relaxed); }
-
   // Size of buffer used for formatting log messages.
   static const int kMessageBufferSize = 2048;
 
@@ -115,19 +112,20 @@ class Log {
 
  private:
   static FILE* CreateOutputHandle(std::string file_name);
+  base::Mutex* mutex() { return &mutex_; }
 
   void WriteLogHeader();
 
+  Logger* logger_;
+
   std::string file_name_;
+
   // When logging is active output_handle_ is used to store a pointer to log
   // destination.  mutex_ should be acquired before using output_handle_.
   FILE* output_handle_;
 
   OFStream os_;
 
-  // Stores whether logging is enabled.
-  std::atomic<bool> is_enabled_;
-
   // mutex_ is a Mutex used for enforcing exclusive
   // access to the formatting buffer and the log file or log memory buffer.
   base::Mutex mutex_;
@@ -135,6 +133,8 @@ class Log {
   // Buffer used for formatting log messages. This is a singleton buffer and
   // mutex_ should be acquired before using it.
   std::unique_ptr<char[]> format_buffer_;
+
+  friend class Logger;
 };
 
 template <>

src/logging/log.cc

@@ -4,11 +4,13 @@
 
 #include "src/logging/log.h"
 
+#include <atomic>
 #include <cstdarg>
 #include <memory>
 #include <sstream>
 
 #include "src/api/api-inl.h"
+#include "src/base/platform/mutex.h"
 #include "src/base/platform/platform.h"
 #include "src/builtins/profile-data-reader.h"
 #include "src/codegen/bailout-reason.h"
@@ -1113,7 +1115,7 @@ void Logger::BuiltinHashEvent(const char* name, int hash) {
 bool Logger::is_logging() {
   // Disable logging while the CPU profiler is running.
   if (isolate_->is_profiling()) return false;
-  return is_logging_;
+  return is_logging_.load(std::memory_order_relaxed);
 }
 
 // Instantiate template methods.
@@ -1429,7 +1431,7 @@ void Logger::SharedFunctionInfoMoveEvent(Address from, Address to) {
 
 void Logger::CodeMovingGCEvent() {
   if (!is_listening_to_code_events()) return;
-  if (!log_->IsEnabled() || !FLAG_ll_prof) return;
+  if (!FLAG_ll_prof) return;
   base::OS::SignalCodeMovingGC();
 }
 
@@ -1473,7 +1475,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 (!log_->IsEnabled()) return;
+  if (!is_logging()) return;
   Deoptimizer::DeoptInfo info = Deoptimizer::GetDeoptInfo(*code, pc);
   ProcessDeoptEvent(code, info.position,
                     Deoptimizer::MessageFor(kind, reuse_code),
@@ -1483,7 +1485,7 @@ void Logger::CodeDeoptEvent(Handle<Code> code, DeoptimizeKind kind, Address pc,
 void Logger::CodeDependencyChangeEvent(Handle<Code> code,
                                        Handle<SharedFunctionInfo> sfi,
                                        const char* reason) {
-  if (!log_->IsEnabled()) return;
+  if (!is_logging()) return;
   SourcePosition position(sfi->StartPosition(), -1);
   ProcessDeoptEvent(code, position, "dependency-change", reason);
 }
@@ -2030,7 +2032,7 @@ bool Logger::SetUp(Isolate* isolate) {
 
   std::ostringstream log_file_name;
   PrepareLogFileName(log_file_name, isolate, FLAG_logfile);
-  log_ = std::make_unique<Log>(log_file_name.str());
+  log_ = std::make_unique<Log>(this, log_file_name.str());
 
 #if V8_OS_LINUX
   if (FLAG_perf_basic_prof) {
@@ -2059,17 +2061,22 @@ bool Logger::SetUp(Isolate* isolate) {
 
   ticker_ = std::make_unique<Ticker>(isolate, FLAG_prof_sampling_interval);
 
-  if (Log::InitLogAtStart()) is_logging_ = true;
+  bool activate_logging = false;
+
+  if (Log::InitLogAtStart()) activate_logging = true;
 
   timer_.Start();
 
   if (FLAG_prof_cpp) {
     profiler_ = std::make_unique<Profiler>(isolate);
-    is_logging_ = true;
+    activate_logging = true;
     profiler_->Engage();
   }
 
-  if (is_logging_) AddCodeEventListener(this);
+  if (activate_logging) {
+    AddCodeEventListener(this);
+    UpdateIsLogging(true);
+  }
 
   return true;
 }
@@ -2108,7 +2115,7 @@ void Logger::StopProfilerThread() {
 FILE* Logger::TearDownAndGetLogFile() {
   if (!is_initialized_) return nullptr;
   is_initialized_ = false;
-  is_logging_ = false;
+  UpdateIsLogging(false);
 
   // Stop the profiler thread before closing the file.
   StopProfilerThread();
@@ -2141,6 +2148,13 @@ FILE* Logger::TearDownAndGetLogFile() {
   return log_->Close();
 }
 
+void Logger::UpdateIsLogging(bool value) {
+  base::MutexGuard guard(log_->mutex());
+  // Relaxed atomic to avoid locking the mutex for the most common case: when
+  // logging is disabled.
+  is_logging_.store(value, std::memory_order_relaxed);
+}
+
 void ExistingCodeLogger::LogCodeObject(Object object) {
   HandleScope scope(isolate_);
   Handle<AbstractCode> abstract_code(AbstractCode::cast(object), isolate_);

src/logging/log.h

@@ -5,6 +5,7 @@
 #ifndef V8_LOGGING_LOG_H_
 #define V8_LOGGING_LOG_H_
 
+#include <atomic>
 #include <memory>
 #include <set>
 #include <string>
@@ -283,6 +284,8 @@ class Logger : public CodeEventListener {
   void LogCodeObject(Object code_object);
 
  private:
+  void UpdateIsLogging(bool value);
+
   // Emits the profiler's first message.
   void ProfilerBeginEvent();
 
@@ -324,7 +327,7 @@ class Logger : public CodeEventListener {
   // Internal implementation classes with access to private members.
   friend class Profiler;
 
-  bool is_logging_;
+  std::atomic<bool> is_logging_;
   std::unique_ptr<Log> log_;
 #if V8_OS_LINUX
   std::unique_ptr<PerfBasicLogger> perf_basic_logger_;