[TurboFan] Redirect --trace-opt, --trace-deopt, --trace-osr to a file

With the current flow, it is difficult to easily get the output
of --trace-opt, --trace-deopt and --trace-osr from Android devices.
These flags log to stdout and on Android it is difficult to get this
output that preserves the formatting. This cl redirects them to a file
when --redirect-code-traces is specified.

Change-Id: I8ea1f083d0ee4577f9d70cfd2d7cb2823fd1a6c4
Reviewed-on: https://chromium-review.googlesource.com/c/v8/v8/+/2089931
Commit-Queue: Mythri Alle <mythria@chromium.org>
Reviewed-by: Ross McIlroy <rmcilroy@chromium.org>
Reviewed-by: Georg Neis <neis@chromium.org>
Cr-Commit-Position: refs/heads/master@{#66722}

src/codegen/compiler.cc

@@ -26,6 +26,7 @@
 #include "src/compiler/pipeline.h"
 #include "src/debug/debug.h"
 #include "src/debug/liveedit.h"
+#include "src/diagnostics/code-tracer.h"
 #include "src/execution/frames-inl.h"
 #include "src/execution/isolate-inl.h"
 #include "src/execution/isolate.h"
@@ -224,7 +225,8 @@ CompilationJob::Status OptimizedCompilationJob::PrepareJob(Isolate* isolate) {
   DisallowJavascriptExecution no_js(isolate);
 
   if (FLAG_trace_opt && compilation_info()->IsOptimizing()) {
-    StdoutStream os;
+    CodeTracer::Scope scope(isolate->GetCodeTracer());
+    OFStream os(scope.file());
     os << "[compiling method " << Brief(*compilation_info()->closure())
        << " using " << compiler_name_;
     if (compilation_info()->is_osr()) os << " OSR";
@@ -278,10 +280,11 @@ void OptimizedCompilationJob::RecordCompilationStats(CompilationMode mode,
   double ms_optimize = time_taken_to_execute_.InMillisecondsF();
   double ms_codegen = time_taken_to_finalize_.InMillisecondsF();
   if (FLAG_trace_opt) {
-    PrintF("[optimizing ");
-    function->ShortPrint();
-    PrintF(" - took %0.3f, %0.3f, %0.3f ms]\n", ms_creategraph, ms_optimize,
-           ms_codegen);
+    CodeTracer::Scope scope(isolate->GetCodeTracer());
+    PrintF(scope.file(), "[optimizing ");
+    function->ShortPrint(scope.file());
+    PrintF(scope.file(), " - took %0.3f, %0.3f, %0.3f ms]\n", ms_creategraph,
+           ms_optimize, ms_codegen);
   }
   if (FLAG_trace_opt_stats) {
     static double compilation_time = 0.0;
@@ -824,9 +827,10 @@ bool GetOptimizedCodeNow(OptimizedCompilationJob* job, Isolate* isolate) {
           CompilationJob::SUCCEEDED ||
       job->FinalizeJob(isolate) != CompilationJob::SUCCEEDED) {
     if (FLAG_trace_opt) {
-      PrintF("[aborted optimizing ");
-      compilation_info->closure()->ShortPrint();
-      PrintF(" because: %s]\n",
+      CodeTracer::Scope scope(isolate->GetCodeTracer());
+      PrintF(scope.file(), "[aborted optimizing ");
+      compilation_info->closure()->ShortPrint(scope.file());
+      PrintF(scope.file(), " because: %s]\n",
              GetBailoutReason(compilation_info->bailout_reason()));
     }
     return false;
@@ -910,12 +914,13 @@ MaybeHandle<Code> GetOptimizedCode(Handle<JSFunction> function,
   if (GetCodeFromOptimizedCodeCache(function, osr_offset)
           .ToHandle(&cached_code)) {
     if (FLAG_trace_opt) {
-      PrintF("[found optimized code for ");
-      function->ShortPrint();
+      CodeTracer::Scope scope(isolate->GetCodeTracer());
+      PrintF(scope.file(), "[found optimized code for ");
+      function->ShortPrint(scope.file());
       if (!osr_offset.IsNone()) {
-        PrintF(" at OSR AST id %d", osr_offset.ToInt());
+        PrintF(scope.file(), " at OSR AST id %d", osr_offset.ToInt());
       }
-      PrintF("]\n");
+      PrintF(scope.file(), "]\n");
     }
     return cached_code;
   }
@@ -1556,9 +1561,10 @@ bool Compiler::Compile(Handle<JSFunction> function, ClearExceptionFlag flag,
   // Optimize now if --always-opt is enabled.
   if (FLAG_always_opt && !function->shared().HasAsmWasmData()) {
     if (FLAG_trace_opt) {
-      PrintF("[optimizing ");
-      function->ShortPrint();
-      PrintF(" because --always-opt]\n");
+      CodeTracer::Scope scope(isolate->GetCodeTracer());
+      PrintF(scope.file(), "[optimizing ");
+      function->ShortPrint(scope.file());
+      PrintF(scope.file(), " because --always-opt]\n");
     }
     Handle<Code> opt_code;
     if (GetOptimizedCode(function, ConcurrencyMode::kNotConcurrent)
@@ -2558,9 +2564,10 @@ bool Compiler::FinalizeOptimizedCompilationJob(OptimizedCompilationJob* job,
                                      isolate);
       InsertCodeIntoOptimizedCodeCache(compilation_info);
       if (FLAG_trace_opt) {
-        PrintF("[completed optimizing ");
-        compilation_info->closure()->ShortPrint();
-        PrintF("]\n");
+        CodeTracer::Scope scope(isolate->GetCodeTracer());
+        PrintF(scope.file(), "[completed optimizing ");
+        compilation_info->closure()->ShortPrint(scope.file());
+        PrintF(scope.file(), "]\n");
       }
       compilation_info->closure()->set_code(*compilation_info->code());
       return CompilationJob::SUCCEEDED;
@@ -2569,9 +2576,10 @@ bool Compiler::FinalizeOptimizedCompilationJob(OptimizedCompilationJob* job,
 
   DCHECK_EQ(job->state(), CompilationJob::State::kFailed);
   if (FLAG_trace_opt) {
-    PrintF("[aborted optimizing ");
-    compilation_info->closure()->ShortPrint();
-    PrintF(" because: %s]\n",
+    CodeTracer::Scope scope(isolate->GetCodeTracer());
+    PrintF(scope.file(), "[aborted optimizing ");
+    compilation_info->closure()->ShortPrint(scope.file());
+    PrintF(scope.file(), " because: %s]\n",
            GetBailoutReason(compilation_info->bailout_reason()));
   }
   compilation_info->closure()->set_code(shared->GetCode());

src/deoptimizer/deoptimizer.cc

@@ -123,7 +123,8 @@ class FrameWriter {
       PrintF(trace_scope_->file(), "    " V8PRIxPTR_FMT ": [top + %3d] <- ",
              output_address(output_offset), output_offset);
       if (obj.IsSmi()) {
-        PrintF(V8PRIxPTR_FMT " <Smi %d>", obj.ptr(), Smi::cast(obj).value());
+        PrintF(trace_scope_->file(), V8PRIxPTR_FMT " <Smi %d>", obj.ptr(),
+               Smi::cast(obj).value());
       } else {
         obj.ShortPrint(trace_scope_->file());
       }
@@ -1728,7 +1729,8 @@ void Deoptimizer::MaterializeHeapObjects() {
     Handle<Object> value = materialization.value_->GetValue();
 
     if (trace_scope_ != nullptr) {
-      PrintF("Materialization [" V8PRIxPTR_FMT "] <- " V8PRIxPTR_FMT " ;  ",
+      PrintF(trace_scope_->file(),
+             "Materialization [" V8PRIxPTR_FMT "] <- " V8PRIxPTR_FMT " ;  ",
              static_cast<intptr_t>(materialization.output_slot_address_),
              value->ptr());
       value->ShortPrint(trace_scope_->file());

src/diagnostics/code-tracer.h

@@ -52,6 +52,9 @@ class CodeTracer final : public Malloced {
 
     if (file_ == nullptr) {
       file_ = base::OS::FOpen(filename_.begin(), "ab");
+      CHECK_WITH_MSG(file_ != nullptr,
+                     "could not open file. If on Android, try passing "
+                     "--redirect-code-traces-to=/sdcard/Download/<file-name>");
     }
 
     scope_depth_++;
@@ -63,6 +66,7 @@ class CodeTracer final : public Malloced {
     }
 
     if (--scope_depth_ == 0) {
+      DCHECK_NOT_NULL(file_);
       fclose(file_);
       file_ = nullptr;
     }

src/execution/runtime-profiler.cc

@@ -9,6 +9,7 @@
 #include "src/codegen/compilation-cache.h"
 #include "src/codegen/compiler.h"
 #include "src/codegen/pending-optimization-table.h"
+#include "src/diagnostics/code-tracer.h"
 #include "src/execution/execution.h"
 #include "src/execution/frames-inl.h"
 #include "src/handles/global-handles.h"
@@ -69,18 +70,20 @@ RuntimeProfiler::RuntimeProfiler(Isolate* isolate)
     : isolate_(isolate), any_ic_changed_(false) {}
 
 static void TraceRecompile(JSFunction function, const char* reason,
-                           const char* type) {
+                           const char* type, Isolate* isolate) {
   if (FLAG_trace_opt) {
-    PrintF("[marking ");
-    function.ShortPrint();
-    PrintF(" for %s recompilation, reason: %s", type, reason);
-    PrintF("]\n");
+    CodeTracer::Scope scope(isolate->GetCodeTracer());
+    PrintF(scope.file(), "[marking ");
+    function.ShortPrint(scope.file());
+    PrintF(scope.file(), " for %s recompilation, reason: %s", type, reason);
+    PrintF(scope.file(), "]\n");
   }
 }
 
 void RuntimeProfiler::Optimize(JSFunction function, OptimizationReason reason) {
   DCHECK_NE(reason, OptimizationReason::kDoNotOptimize);
-  TraceRecompile(function, OptimizationReasonToString(reason), "optimized");
+  TraceRecompile(function, OptimizationReasonToString(reason), "optimized",
+                 isolate_);
   function.MarkForOptimization(ConcurrencyMode::kConcurrent);
 }
 
@@ -99,9 +102,10 @@ void RuntimeProfiler::AttemptOnStackReplacement(InterpretedFrame* frame,
   // BytecodeArray header so that certain back edges in any interpreter frame
   // for this bytecode will trigger on-stack replacement for that frame.
   if (FLAG_trace_osr) {
-    PrintF("[OSR - arming back edges in ");
-    function.PrintName();
-    PrintF("]\n");
+    CodeTracer::Scope scope(isolate_->GetCodeTracer());
+    PrintF(scope.file(), "[OSR - arming back edges in ");
+    function.PrintName(scope.file());
+    PrintF(scope.file(), "]\n");
   }
 
   DCHECK_EQ(StackFrame::INTERPRETED, frame->type());

src/objects/feedback-vector.cc

@@ -3,6 +3,7 @@
 // found in the LICENSE file.
 
 #include "src/objects/feedback-vector.h"
+#include "src/diagnostics/code-tracer.h"
 #include "src/heap/off-thread-factory-inl.h"
 #include "src/ic/handler-configuration-inl.h"
 #include "src/ic/ic-inl.h"
@@ -367,10 +368,12 @@ void FeedbackVector::EvictOptimizedCodeMarkedForDeoptimization(
   Code code = Code::cast(slot->GetHeapObject());
   if (code.marked_for_deoptimization()) {
     if (FLAG_trace_deopt) {
-      PrintF("[evicting optimizing code marked for deoptimization (%s) for ",
+      CodeTracer::Scope scope(GetIsolate()->GetCodeTracer());
+      PrintF(scope.file(),
+             "[evicting optimizing code marked for deoptimization (%s) for ",
              reason);
-      shared.ShortPrint();
-      PrintF("]\n");
+      shared.ShortPrint(scope.file());
+      PrintF(scope.file(), "]\n");
     }
     if (!code.deopt_already_counted()) {
       code.set_deopt_already_counted(true);

src/objects/js-objects-inl.h

@@ -7,6 +7,7 @@
 
 #include "src/objects/js-objects.h"
 
+#include "src/diagnostics/code-tracer.h"
 #include "src/heap/heap-write-barrier.h"
 #include "src/objects/elements.h"
 #include "src/objects/embedder-data-slot-inl.h"
@@ -573,10 +574,12 @@ void JSFunction::set_shared(SharedFunctionInfo value, WriteBarrierMode mode) {
 void JSFunction::ClearOptimizedCodeSlot(const char* reason) {
   if (has_feedback_vector() && feedback_vector().has_optimized_code()) {
     if (FLAG_trace_opt) {
-      PrintF("[evicting entry from optimizing code feedback slot (%s) for ",
+      CodeTracer::Scope scope(GetIsolate()->GetCodeTracer());
+      PrintF(scope.file(),
+             "[evicting entry from optimizing code feedback slot (%s) for ",
              reason);
-      ShortPrint();
-      PrintF("]\n");
+      ShortPrint(scope.file());
+      PrintF(scope.file(), "]\n");
     }
     feedback_vector().ClearOptimizedCode();
   }

src/objects/objects.cc

@@ -28,6 +28,7 @@
 #include "src/common/message-template.h"
 #include "src/date/date.h"
 #include "src/debug/debug.h"
+#include "src/diagnostics/code-tracer.h"
 #include "src/execution/arguments.h"
 #include "src/execution/execution.h"
 #include "src/execution/frames-inl.h"
@@ -5356,9 +5357,10 @@ void SharedFunctionInfo::DisableOptimization(BailoutReason reason) {
           CodeDisableOptEvent(handle(abstract_code(), GetIsolate()),
                               handle(*this, GetIsolate())));
   if (FLAG_trace_opt) {
-    PrintF("[disabled optimization for ");
-    ShortPrint();
-    PrintF(", reason: %s]\n", GetBailoutReason(reason));
+    CodeTracer::Scope scope(GetIsolate()->GetCodeTracer());
+    PrintF(scope.file(), "[disabled optimization for ");
+    ShortPrint(scope.file());
+    PrintF(scope.file(), ", reason: %s]\n", GetBailoutReason(reason));
   }
 }
 

src/runtime/runtime-compiler.cc

@@ -252,9 +252,10 @@ RUNTIME_FUNCTION(Runtime_CompileForOnStackReplacement) {
   Handle<JSFunction> function(frame->function(), isolate);
   if (IsSuitableForOnStackReplacement(isolate, function)) {
     if (FLAG_trace_osr) {
-      PrintF("[OSR - Compiling: ");
-      function->PrintName();
-      PrintF(" at AST id %d]\n", ast_id.ToInt());
+      CodeTracer::Scope scope(isolate->GetCodeTracer());
+      PrintF(scope.file(), "[OSR - Compiling: ");
+      function->PrintName(scope.file());
+      PrintF(scope.file(), " at AST id %d]\n", ast_id.ToInt());
     }
     maybe_result = Compiler::GetOptimizedCodeForOSR(function, ast_id, frame);
   }
@@ -269,7 +270,9 @@ RUNTIME_FUNCTION(Runtime_CompileForOnStackReplacement) {
     if (data.OsrPcOffset().value() >= 0) {
       DCHECK(BailoutId(data.OsrBytecodeOffset().value()) == ast_id);
       if (FLAG_trace_osr) {
-        PrintF("[OSR - Entry at AST id %d, offset %d in optimized code]\n",
+        CodeTracer::Scope scope(isolate->GetCodeTracer());
+        PrintF(scope.file(),
+               "[OSR - Entry at AST id %d, offset %d in optimized code]\n",
                ast_id.ToInt(), data.OsrPcOffset().value());
       }
 
@@ -298,9 +301,10 @@ RUNTIME_FUNCTION(Runtime_CompileForOnStackReplacement) {
         // the next call, otherwise we'd run unoptimized once more and
         // potentially compile for OSR again.
         if (FLAG_trace_osr) {
-          PrintF("[OSR - Re-marking ");
-          function->PrintName();
-          PrintF(" for non-concurrent optimization]\n");
+          CodeTracer::Scope scope(isolate->GetCodeTracer());
+          PrintF(scope.file(), "[OSR - Re-marking ");
+          function->PrintName(scope.file());
+          PrintF(scope.file(), " for non-concurrent optimization]\n");
         }
         function->SetOptimizationMarker(OptimizationMarker::kCompileOptimized);
       }
@@ -310,9 +314,10 @@ RUNTIME_FUNCTION(Runtime_CompileForOnStackReplacement) {
 
   // Failed.
   if (FLAG_trace_osr) {
-    PrintF("[OSR - Failed: ");
-    function->PrintName();
-    PrintF(" at AST id %d]\n", ast_id.ToInt());
+    CodeTracer::Scope scope(isolate->GetCodeTracer());
+    PrintF(scope.file(), "[OSR - Failed: ");
+    function->PrintName(scope.file());
+    PrintF(scope.file(), " at AST id %d]\n", ast_id.ToInt());
   }
 
   if (!function->IsOptimized()) {

src/runtime/runtime-test.cc

@@ -448,9 +448,10 @@ RUNTIME_FUNCTION(Runtime_OptimizeOsr) {
   // Ensure that the function is marked for non-concurrent optimization, so that
   // subsequent runs don't also optimize.
   if (FLAG_trace_osr) {
-    PrintF("[OSR - OptimizeOsr marking ");
-    function->ShortPrint();
-    PrintF(" for non-concurrent optimization]\n");
+    CodeTracer::Scope scope(isolate->GetCodeTracer());
+    PrintF(scope.file(), "[OSR - OptimizeOsr marking ");
+    function->ShortPrint(scope.file());
+    PrintF(scope.file(), " for non-concurrent optimization]\n");
   }
   JSFunction::EnsureFeedbackVector(function);
   function->MarkForOptimization(ConcurrencyMode::kNotConcurrent);