[utils] Synchronize across StdoutStream instances

We constantly fight against scrambled output with --print-wasm-code and
other flags. Passing --single-threaded only partially mitigates this,
because there could still be multiple isolates (e.g. Workers), and we
sometimes failed to really execute in a single thread if that flag was
set.
Hence this CL solves the problem in a more fundamental way: Whenever a
{StdoutStream} is constructed, it implicitly takes a global recursive
mutex. The recursive mutex is needed because we still have some printing
methods that don't take a stream as parameter, and instead create their
own instance of {StdoutStream}, which should not crash of course.

The overhead of taking a mutex should be acceptable, since output to
stdout mostly happens if special tracing flags have been passed, and is
slow anyway.

This CL ensures that the {StdoutStream} is used at least for
--print-code, --print-wasm-code, and --trace-turbo-graph.
More flags can later be ported on demand.

The {JSHeapBroker} class was modified to not contain a {StdoutStream},
but instead create one on demand.

R=mlippautz@chromium.org, tebbi@chromium.org
CC=ahaas@chromium.org

Bug: v8:10506
Change-Id: Ib9cf8d76aa79553b4215bb7775e6d47a8179aafa
Reviewed-on: https://chromium-review.googlesource.com/c/v8/v8/+/2201767Reviewed-by: Andreas Haas <ahaas@chromium.org>
Reviewed-by: Michael Lippautz <mlippautz@chromium.org>
Reviewed-by: Tobias Tebbi <tebbi@chromium.org>
Commit-Queue: Clemens Backes <clemensb@chromium.org>
Cr-Commit-Position: refs/heads/master@{#67855}

src/compiler/js-heap-broker.cc

@@ -2407,9 +2407,11 @@ JSHeapBroker::JSHeapBroker(Isolate* isolate, Zone* broker_zone,
   TRACE(this, "Constructing heap broker");
 }
 
-std::ostream& JSHeapBroker::Trace() const {
-  return trace_out_ << "[" << this << "] "
-                    << std::string(trace_indentation_ * 2, ' ');
+std::string JSHeapBroker::Trace() const {
+  std::ostringstream oss;
+  oss << "[" << this << "] ";
+  for (unsigned i = 0; i < trace_indentation_ * 2; ++i) oss.put(' ');
+  return oss.str();
 }
 
 void JSHeapBroker::StopSerializing() {

src/compiler/js-heap-broker.h

@@ -33,20 +33,20 @@ std::ostream& operator<<(std::ostream& os, const ObjectRef& ref);
 #define TRACE_BROKER(broker, x)                                      \
   do {                                                               \
     if (broker->tracing_enabled() && FLAG_trace_heap_broker_verbose) \
-      broker->Trace() << x << '\n';                                  \
+      StdoutStream{} << broker->Trace() << x << '\n';                \
   } while (false)
 
 #define TRACE_BROKER_MEMORY(broker, x)                              \
   do {                                                              \
     if (broker->tracing_enabled() && FLAG_trace_heap_broker_memory) \
-      broker->Trace() << x << std::endl;                            \
+      StdoutStream{} << broker->Trace() << x << std::endl;          \
   } while (false)
 
-#define TRACE_BROKER_MISSING(broker, x)                             \
-  do {                                                              \
-    if (broker->tracing_enabled())                                  \
-      broker->Trace() << "Missing " << x << " (" << __FILE__ << ":" \
-                      << __LINE__ << ")" << std::endl;              \
+#define TRACE_BROKER_MISSING(broker, x)                                        \
+  do {                                                                         \
+    if (broker->tracing_enabled())                                             \
+      StdoutStream{} << broker->Trace() << "Missing " << x << " (" << __FILE__ \
+                     << ":" << __LINE__ << ")" << std::endl;                   \
   } while (false)
 
 struct PropertyAccessTarget {
@@ -193,7 +193,7 @@ class V8_EXPORT_PRIVATE JSHeapBroker {
   bool IsSerializedForCompilation(const SharedFunctionInfoRef& shared,
                                   const FeedbackVectorRef& feedback) const;
 
-  std::ostream& Trace() const;
+  std::string Trace() const;
   void IncrementTracingIndentation();
   void DecrementTracingIndentation();
 
@@ -242,7 +242,6 @@ class V8_EXPORT_PRIVATE JSHeapBroker {
   BrokerMode mode_ = kDisabled;
   bool const tracing_enabled_;
   bool const is_concurrent_inlining_;
-  mutable StdoutStream trace_out_;
   unsigned trace_indentation_ = 0;
   PerIsolateCompilerCache* compiler_cache_ = nullptr;
   ZoneUnorderedMap<FeedbackSource, ProcessedFeedback const*,

src/compiler/pipeline.cc

@@ -680,9 +680,9 @@ void PrintFunctionSource(OptimizedCompilationInfo* info, Isolate* isolate,
     Handle<Script> script(Script::cast(shared->script()), isolate);
 
     if (!script->source().IsUndefined(isolate)) {
-      CodeTracer::Scope tracing_scope(isolate->GetCodeTracer());
+      CodeTracer::StreamScope tracing_scope(isolate->GetCodeTracer());
       Object source_name = script->name();
-      OFStream os(tracing_scope.file());
+      auto& os = tracing_scope.stream();
       os << "--- FUNCTION SOURCE (";
       if (source_name.IsString()) {
         os << String::cast(source_name).ToCString().get() << ":";
@@ -711,8 +711,8 @@ void PrintFunctionSource(OptimizedCompilationInfo* info, Isolate* isolate,
 void PrintInlinedFunctionInfo(
     OptimizedCompilationInfo* info, Isolate* isolate, int source_id,
     int inlining_id, const OptimizedCompilationInfo::InlinedFunctionHolder& h) {
-  CodeTracer::Scope tracing_scope(isolate->GetCodeTracer());
-  OFStream os(tracing_scope.file());
+  CodeTracer::StreamScope tracing_scope(isolate->GetCodeTracer());
+  auto& os = tracing_scope.stream();
   os << "INLINE (" << h.shared_info->DebugName().ToCString().get() << ") id{"
      << info->optimization_id() << "," << source_id << "} AS " << inlining_id
      << " AT ";
@@ -753,8 +753,8 @@ void PrintCode(Isolate* isolate, Handle<Code> code,
        info->shared_info()->PassesFilter(FLAG_print_opt_code_filter));
   if (print_code) {
     std::unique_ptr<char[]> debug_name = info->GetDebugName();
-    CodeTracer::Scope tracing_scope(isolate->GetCodeTracer());
-    OFStream os(tracing_scope.file());
+    CodeTracer::StreamScope tracing_scope(isolate->GetCodeTracer());
+    auto& os = tracing_scope.stream();
 
     // Print the source code if available.
     bool print_source = code->kind() == Code::OPTIMIZED_FUNCTION;
@@ -810,9 +810,10 @@ void TraceScheduleAndVerify(OptimizedCompilationInfo* info, PipelineData* data,
   }
   if (info->trace_turbo_graph_enabled() || FLAG_trace_turbo_scheduler) {
     AllowHandleDereference allow_deref;
-    CodeTracer::Scope tracing_scope(data->GetCodeTracer());
-    OFStream os(tracing_scope.file());
-    os << "-- Schedule --------------------------------------\n" << *schedule;
+    CodeTracer::StreamScope tracing_scope(data->GetCodeTracer());
+    tracing_scope.stream()
+        << "-- Schedule --------------------------------------\n"
+        << *schedule;
   }
 
   if (FLAG_turbo_verify) ScheduleVerifier::Run(schedule);
@@ -1270,11 +1271,11 @@ CompilationJob::Status WasmHeapStubCompilationJob::ExecuteJobImpl(
     pipeline_statistics->BeginPhaseKind("V8.WasmStubCodegen");
   }
   if (info_.trace_turbo_json_enabled() || info_.trace_turbo_graph_enabled()) {
-    CodeTracer::Scope tracing_scope(data_.GetCodeTracer());
-    OFStream os(tracing_scope.file());
-    os << "---------------------------------------------------\n"
-       << "Begin compiling method " << info_.GetDebugName().get()
-       << " using TurboFan" << std::endl;
+    CodeTracer::StreamScope tracing_scope(data_.GetCodeTracer());
+    tracing_scope.stream()
+        << "---------------------------------------------------\n"
+        << "Begin compiling method " << info_.GetDebugName().get()
+        << " using TurboFan" << std::endl;
   }
   if (info_.trace_turbo_graph_enabled()) {  // Simple textual RPO.
     StdoutStream{} << "-- wasm stub " << Code::Kind2String(info_.code_kind())
@@ -1306,9 +1307,9 @@ CompilationJob::Status WasmHeapStubCompilationJob::FinalizeJobImpl(
     info_.SetCode(code);
 #ifdef ENABLE_DISASSEMBLER
     if (FLAG_print_opt_code) {
-      CodeTracer::Scope tracing_scope(isolate->GetCodeTracer());
-      OFStream os(tracing_scope.file());
-      code->Disassemble(compilation_info()->GetDebugName().get(), os, isolate);
+      CodeTracer::StreamScope tracing_scope(isolate->GetCodeTracer());
+      code->Disassemble(compilation_info()->GetDebugName().get(),
+                        tracing_scope.stream(), isolate);
     }
 #endif
     return SUCCEEDED;
@@ -2302,16 +2303,16 @@ struct PrintGraphPhase {
       }
 
       AllowHandleDereference allow_deref;
-      CodeTracer::Scope tracing_scope(data->GetCodeTracer());
-      OFStream os(tracing_scope.file());
-      os << "-- Graph after " << phase << " -- " << std::endl;
-      os << AsScheduledGraph(schedule);
+      CodeTracer::StreamScope tracing_scope(data->GetCodeTracer());
+      tracing_scope.stream()
+          << "-- Graph after " << phase << " -- " << std::endl
+          << AsScheduledGraph(schedule);
     } else if (info->trace_turbo_graph_enabled()) {  // Simple textual RPO.
       AllowHandleDereference allow_deref;
-      CodeTracer::Scope tracing_scope(data->GetCodeTracer());
-      OFStream os(tracing_scope.file());
-      os << "-- Graph after " << phase << " -- " << std::endl;
-      os << AsRPO(*graph);
+      CodeTracer::StreamScope tracing_scope(data->GetCodeTracer());
+      tracing_scope.stream()
+          << "-- Graph after " << phase << " -- " << std::endl
+          << AsRPO(*graph);
     }
   }
 };
@@ -2361,11 +2362,11 @@ void PipelineImpl::Serialize() {
 
   if (info()->trace_turbo_json_enabled() ||
       info()->trace_turbo_graph_enabled()) {
-    CodeTracer::Scope tracing_scope(data->GetCodeTracer());
-    OFStream os(tracing_scope.file());
-    os << "---------------------------------------------------\n"
-       << "Begin compiling method " << info()->GetDebugName().get()
-       << " using TurboFan" << std::endl;
+    CodeTracer::StreamScope tracing_scope(data->GetCodeTracer());
+    tracing_scope.stream()
+        << "---------------------------------------------------\n"
+        << "Begin compiling method " << info()->GetDebugName().get()
+        << " using TurboFan" << std::endl;
   }
   if (info()->trace_turbo_json_enabled()) {
     TurboCfgFile tcf(isolate());
@@ -2640,10 +2641,10 @@ MaybeHandle<Code> Pipeline::GenerateCodeForCodeStub(
   PipelineImpl pipeline(&data);
 
   if (info.trace_turbo_json_enabled() || info.trace_turbo_graph_enabled()) {
-    CodeTracer::Scope tracing_scope(data.GetCodeTracer());
-    OFStream os(tracing_scope.file());
-    os << "---------------------------------------------------\n"
-       << "Begin compiling " << debug_name << " using TurboFan" << std::endl;
+    CodeTracer::StreamScope tracing_scope(data.GetCodeTracer());
+    tracing_scope.stream()
+        << "---------------------------------------------------\n"
+        << "Begin compiling " << debug_name << " using TurboFan" << std::endl;
     if (info.trace_turbo_json_enabled()) {
       TurboJsonFile json_of(&info, std::ios_base::trunc);
       json_of << "{\"function\" : ";
@@ -2742,11 +2743,11 @@ wasm::WasmCompilationResult Pipeline::GenerateCodeForWasmNativeStub(
   PipelineImpl pipeline(&data);
 
   if (info.trace_turbo_json_enabled() || info.trace_turbo_graph_enabled()) {
-    CodeTracer::Scope tracing_scope(data.GetCodeTracer());
-    OFStream os(tracing_scope.file());
-    os << "---------------------------------------------------\n"
-       << "Begin compiling method " << info.GetDebugName().get()
-       << " using TurboFan" << std::endl;
+    CodeTracer::StreamScope tracing_scope(data.GetCodeTracer());
+    tracing_scope.stream()
+        << "---------------------------------------------------\n"
+        << "Begin compiling method " << info.GetDebugName().get()
+        << " using TurboFan" << std::endl;
   }
 
   if (info.trace_turbo_graph_enabled()) {  // Simple textual RPO.
@@ -2803,11 +2804,11 @@ wasm::WasmCompilationResult Pipeline::GenerateCodeForWasmNativeStub(
   }
 
   if (info.trace_turbo_json_enabled() || info.trace_turbo_graph_enabled()) {
-    CodeTracer::Scope tracing_scope(data.GetCodeTracer());
-    OFStream os(tracing_scope.file());
-    os << "---------------------------------------------------\n"
-       << "Finished compiling method " << info.GetDebugName().get()
-       << " using TurboFan" << std::endl;
+    CodeTracer::StreamScope tracing_scope(data.GetCodeTracer());
+    tracing_scope.stream()
+        << "---------------------------------------------------\n"
+        << "Finished compiling method " << info.GetDebugName().get()
+        << " using TurboFan" << std::endl;
   }
 
   return result;
@@ -2917,11 +2918,11 @@ void Pipeline::GenerateCodeForWasmFunction(
 
   if (data.info()->trace_turbo_json_enabled() ||
       data.info()->trace_turbo_graph_enabled()) {
-    CodeTracer::Scope tracing_scope(data.GetCodeTracer());
-    OFStream os(tracing_scope.file());
-    os << "---------------------------------------------------\n"
-       << "Begin compiling method " << data.info()->GetDebugName().get()
-       << " using TurboFan" << std::endl;
+    CodeTracer::StreamScope tracing_scope(data.GetCodeTracer());
+    tracing_scope.stream()
+        << "---------------------------------------------------\n"
+        << "Begin compiling method " << data.info()->GetDebugName().get()
+        << " using TurboFan" << std::endl;
   }
 
   pipeline.RunPrintAndVerify("V8.WasmMachineCode", true);
@@ -3008,11 +3009,11 @@ void Pipeline::GenerateCodeForWasmFunction(
 
   if (data.info()->trace_turbo_json_enabled() ||
       data.info()->trace_turbo_graph_enabled()) {
-    CodeTracer::Scope tracing_scope(data.GetCodeTracer());
-    OFStream os(tracing_scope.file());
-    os << "---------------------------------------------------\n"
-       << "Finished compiling method " << data.info()->GetDebugName().get()
-       << " using TurboFan" << std::endl;
+    CodeTracer::StreamScope tracing_scope(data.GetCodeTracer());
+    tracing_scope.stream()
+        << "---------------------------------------------------\n"
+        << "Finished compiling method " << data.info()->GetDebugName().get()
+        << " using TurboFan" << std::endl;
   }
 
   DCHECK(result->succeeded());
@@ -3074,15 +3075,16 @@ bool PipelineImpl::SelectInstructions(Linkage* linkage) {
   if (verify_stub_graph) {
     if (FLAG_trace_verify_csa) {
       AllowHandleDereference allow_deref;
-      CodeTracer::Scope tracing_scope(data->GetCodeTracer());
-      OFStream os(tracing_scope.file());
-      os << "--------------------------------------------------\n"
-         << "--- Verifying " << data->debug_name() << " generated by TurboFan\n"
-         << "--------------------------------------------------\n"
-         << *data->schedule()
-         << "--------------------------------------------------\n"
-         << "--- End of " << data->debug_name() << " generated by TurboFan\n"
-         << "--------------------------------------------------\n";
+      CodeTracer::StreamScope tracing_scope(data->GetCodeTracer());
+      tracing_scope.stream()
+          << "--------------------------------------------------\n"
+          << "--- Verifying " << data->debug_name()
+          << " generated by TurboFan\n"
+          << "--------------------------------------------------\n"
+          << *data->schedule()
+          << "--------------------------------------------------\n"
+          << "--- End of " << data->debug_name() << " generated by TurboFan\n"
+          << "--------------------------------------------------\n";
     }
     Zone temp_zone(data->allocator(), kMachineGraphVerifierZoneName);
     MachineGraphVerifier::Run(
@@ -3304,11 +3306,11 @@ MaybeHandle<Code> PipelineImpl::FinalizeCode(bool retire_broker) {
   }
   if (info()->trace_turbo_json_enabled() ||
       info()->trace_turbo_graph_enabled()) {
-    CodeTracer::Scope tracing_scope(data->GetCodeTracer());
-    OFStream os(tracing_scope.file());
-    os << "---------------------------------------------------\n"
-       << "Finished compiling method " << info()->GetDebugName().get()
-       << " using TurboFan" << std::endl;
+    CodeTracer::StreamScope tracing_scope(data->GetCodeTracer());
+    tracing_scope.stream()
+        << "---------------------------------------------------\n"
+        << "Finished compiling method " << info()->GetDebugName().get()
+        << " using TurboFan" << std::endl;
   }
   data->EndPhaseKind();
   return code;
@@ -3351,10 +3353,10 @@ void TraceSequence(OptimizedCompilationInfo* info, PipelineData* data,
   }
   if (info->trace_turbo_graph_enabled()) {
     AllowHandleDereference allow_deref;
-    CodeTracer::Scope tracing_scope(data->GetCodeTracer());
-    OFStream os(tracing_scope.file());
-    os << "----- Instruction sequence " << phase_name << " -----\n"
-       << *data->sequence();
+    CodeTracer::StreamScope tracing_scope(data->GetCodeTracer());
+    tracing_scope.stream() << "----- Instruction sequence " << phase_name
+                           << " -----\n"
+                           << *data->sequence();
   }
 }
 

src/diagnostics/code-tracer.h

@@ -5,9 +5,11 @@
 #ifndef V8_DIAGNOSTICS_CODE_TRACER_H_
 #define V8_DIAGNOSTICS_CODE_TRACER_H_
 
+#include "src/base/optional.h"
 #include "src/common/globals.h"
 #include "src/flags/flags.h"
 #include "src/utils/allocation.h"
+#include "src/utils/ostreams.h"
 #include "src/utils/utils.h"
 #include "src/utils/vector.h"
 
@@ -45,6 +47,28 @@ class CodeTracer final : public Malloced {
     CodeTracer* tracer_;
   };
 
+  class StreamScope : public Scope {
+   public:
+    explicit StreamScope(CodeTracer* tracer) : Scope(tracer) {
+      FILE* file = this->file();
+      if (file == stdout) {
+        stdout_stream_.emplace();
+      } else {
+        file_stream_.emplace(file);
+      }
+    }
+
+    std::ostream& stream() {
+      if (stdout_stream_.has_value()) return stdout_stream_.value();
+      return file_stream_.value();
+    }
+
+   private:
+    // Exactly one of these two will be initialized.
+    base::Optional<StdoutStream> stdout_stream_;
+    base::Optional<OFStream> file_stream_;
+  };
+
   void OpenFile() {
     if (!ShouldRedirect()) {
       return;

src/flags/flag-definitions.h

@@ -783,7 +783,6 @@ DEFINE_BOOL(wasm_fuzzer_gen_test, false,
             "generate a test case when running a wasm fuzzer")
 DEFINE_IMPLICATION(wasm_fuzzer_gen_test, single_threaded)
 DEFINE_BOOL(print_wasm_code, false, "Print WebAssembly code")
-DEFINE_IMPLICATION(print_wasm_code, single_threaded)
 DEFINE_BOOL(print_wasm_stub_code, false, "Print WebAssembly stub code")
 DEFINE_BOOL(asm_wasm_lazy_compilation, false,
             "enable lazy compilation for asm-wasm modules")

src/utils/ostreams.cc

@@ -6,6 +6,7 @@
 
 #include <cinttypes>
 
+#include "src/base/lazy-instance.h"
 #include "src/objects/objects.h"
 #include "src/objects/string.h"
 
@@ -114,6 +115,9 @@ std::streamsize AndroidLogStream::xsputn(const char* s, std::streamsize n) {
 }
 #endif
 
+DEFINE_LAZY_LEAKY_OBJECT_GETTER(base::RecursiveMutex,
+                                StdoutStream::GetStdoutMutex)
+
 namespace {
 
 // Locale-independent predicates.

src/utils/ostreams.h

@@ -13,6 +13,7 @@
 
 #include "include/v8config.h"
 #include "src/base/macros.h"
+#include "src/base/platform/mutex.h"
 #include "src/common/globals.h"
 
 namespace v8 {
@@ -80,12 +81,20 @@ class StdoutStream : public std::ostream {
   StdoutStream() : std::ostream(&stream_) {}
 
  private:
+  static V8_EXPORT_PRIVATE base::RecursiveMutex* GetStdoutMutex();
+
   AndroidLogStream stream_;
+  base::RecursiveMutexGuard mutex_guard_{GetStdoutMutex()};
 };
 #else
 class StdoutStream : public OFStream {
  public:
   StdoutStream() : OFStream(stdout) {}
+
+ private:
+  static V8_EXPORT_PRIVATE base::RecursiveMutex* GetStdoutMutex();
+
+  base::RecursiveMutexGuard mutex_guard_{GetStdoutMutex()};
 };
 #endif