Add a flag for printf debugging the compiler dispatcher

BUG=v8:5215
R=vogelheim@chromium.org,marja@chromium.org

Review-Url: https://codereview.chromium.org/2618503002
Cr-Commit-Position: refs/heads/master@{#42091}

src/compiler-dispatcher/compiler-dispatcher-job.cc

@@ -8,6 +8,7 @@
 #include "src/compilation-info.h"
 #include "src/compiler-dispatcher/compiler-dispatcher-tracer.h"
 #include "src/compiler.h"
+#include "src/flags.h"
 #include "src/global-handles.h"
 #include "src/isolate.h"
 #include "src/objects-inl.h"
@@ -15,6 +16,7 @@
 #include "src/parsing/parser.h"
 #include "src/parsing/scanner-character-streams.h"
 #include "src/unicode-cache.h"
+#include "src/utils.h"
 #include "src/zone/zone.h"
 
 namespace v8 {
@@ -29,13 +31,19 @@ CompilerDispatcherJob::CompilerDispatcherJob(Isolate* isolate,
       shared_(Handle<SharedFunctionInfo>::cast(
           isolate_->global_handles()->Create(*shared))),
       max_stack_size_(max_stack_size),
-      can_compile_on_background_thread_(false) {
+      can_compile_on_background_thread_(false),
+      trace_compiler_dispatcher_jobs_(FLAG_trace_compiler_dispatcher_jobs) {
   HandleScope scope(isolate_);
   DCHECK(!shared_->outer_scope_info()->IsTheHole(isolate_));
   Handle<Script> script(Script::cast(shared_->script()), isolate_);
   Handle<String> source(String::cast(script->source()), isolate_);
   can_parse_on_background_thread_ =
       source->IsExternalTwoByteString() || source->IsExternalOneByteString();
+  if (trace_compiler_dispatcher_jobs_) {
+    PrintF("CompilerDispatcherJob[%p] created for ", static_cast<void*>(this));
+    shared_->ShortPrint();
+    PrintF("\n");
+  }
 }
 
 CompilerDispatcherJob::~CompilerDispatcherJob() {
@@ -54,6 +62,10 @@ void CompilerDispatcherJob::PrepareToParseOnMainThread() {
   DCHECK(ThreadId::Current().Equals(isolate_->thread_id()));
   DCHECK(status() == CompileJobStatus::kInitial);
   COMPILER_DISPATCHER_TRACE_SCOPE(tracer_, kPrepareToParse);
+  if (trace_compiler_dispatcher_jobs_) {
+    PrintF("CompilerDispatcherJob[%p]: Preparing to parse\n",
+           static_cast<void*>(this));
+  }
   HandleScope scope(isolate_);
   unicode_cache_.reset(new UnicodeCache());
   zone_.reset(new Zone(isolate_->allocator(), ZONE_NAME));
@@ -105,6 +117,9 @@ void CompilerDispatcherJob::Parse() {
   COMPILER_DISPATCHER_TRACE_SCOPE_WITH_NUM(
       tracer_, kParse,
       parse_info_->end_position() - parse_info_->start_position());
+  if (trace_compiler_dispatcher_jobs_) {
+    PrintF("CompilerDispatcherJob[%p]: Parsing\n", static_cast<void*>(this));
+  }
 
   DisallowHeapAllocation no_allocation;
   DisallowHandleAllocation no_handles;
@@ -133,6 +148,10 @@ bool CompilerDispatcherJob::FinalizeParsingOnMainThread() {
   DCHECK(ThreadId::Current().Equals(isolate_->thread_id()));
   DCHECK(status() == CompileJobStatus::kParsed);
   COMPILER_DISPATCHER_TRACE_SCOPE(tracer_, kFinalizeParsing);
+  if (trace_compiler_dispatcher_jobs_) {
+    PrintF("CompilerDispatcherJob[%p]: Finalizing parsing\n",
+           static_cast<void*>(this));
+  }
 
   if (!source_.is_null()) {
     i::GlobalHandles::Destroy(Handle<Object>::cast(source_).location());
@@ -177,6 +196,10 @@ bool CompilerDispatcherJob::PrepareToCompileOnMainThread() {
   DCHECK(ThreadId::Current().Equals(isolate_->thread_id()));
   DCHECK(status() == CompileJobStatus::kReadyToAnalyse);
   COMPILER_DISPATCHER_TRACE_SCOPE(tracer_, kPrepareToCompile);
+  if (trace_compiler_dispatcher_jobs_) {
+    PrintF("CompilerDispatcherJob[%p]: Preparing to compile\n",
+           static_cast<void*>(this));
+  }
 
   compile_info_.reset(
       new CompilationInfo(parse_info_.get(), Handle<JSFunction>::null()));
@@ -206,6 +229,9 @@ void CompilerDispatcherJob::Compile() {
          ThreadId::Current().Equals(isolate_->thread_id()));
   COMPILER_DISPATCHER_TRACE_SCOPE_WITH_NUM(
       tracer_, kCompile, parse_info_->literal()->ast_node_count());
+  if (trace_compiler_dispatcher_jobs_) {
+    PrintF("CompilerDispatcherJob[%p]: Compiling\n", static_cast<void*>(this));
+  }
 
   // Disallowing of handle dereference and heap access dealt with in
   // CompilationJob::ExecuteJob.
@@ -225,6 +251,10 @@ bool CompilerDispatcherJob::FinalizeCompilingOnMainThread() {
   DCHECK(ThreadId::Current().Equals(isolate_->thread_id()));
   DCHECK(status() == CompileJobStatus::kCompiled);
   COMPILER_DISPATCHER_TRACE_SCOPE(tracer_, kFinalizeCompiling);
+  if (trace_compiler_dispatcher_jobs_) {
+    PrintF("CompilerDispatcherJob[%p]: Finalizing compiling\n",
+           static_cast<void*>(this));
+  }
 
   if (compile_job_->state() == CompilationJob::State::kFailed ||
       !Compiler::FinalizeCompilationJob(compile_job_.release())) {
@@ -246,6 +276,10 @@ bool CompilerDispatcherJob::FinalizeCompilingOnMainThread() {
 void CompilerDispatcherJob::ResetOnMainThread() {
   DCHECK(ThreadId::Current().Equals(isolate_->thread_id()));
 
+  if (trace_compiler_dispatcher_jobs_) {
+    PrintF("CompilerDispatcherJob[%p]: Resetting\n", static_cast<void*>(this));
+  }
+
   parser_.reset();
   unicode_cache_.reset();
   character_stream_.reset();
@@ -294,5 +328,10 @@ double CompilerDispatcherJob::EstimateRuntimeOfNextStepInMs() const {
   return 0.0;
 }
 
+void CompilerDispatcherJob::ShortPrint() {
+  DCHECK(ThreadId::Current().Equals(isolate_->thread_id()));
+  shared_->ShortPrint();
+}
+
 }  // namespace internal
 }  // namespace v8

src/compiler-dispatcher/compiler-dispatcher-job.h

@@ -86,6 +86,10 @@ class V8_EXPORT_PRIVATE CompilerDispatcherJob {
   // Estimate how long the next step will take using the tracer.
   double EstimateRuntimeOfNextStepInMs() const;
 
+  // Even though the name does not imply this, ShortPrint() must only be invoked
+  // on the main thread.
+  void ShortPrint();
+
  private:
   FRIEND_TEST(CompilerDispatcherJobTest, ScopeChain);
 
@@ -111,6 +115,8 @@ class V8_EXPORT_PRIVATE CompilerDispatcherJob {
   bool can_parse_on_background_thread_;
   bool can_compile_on_background_thread_;
 
+  bool trace_compiler_dispatcher_jobs_;
+
   DISALLOW_COPY_AND_ASSIGN(CompilerDispatcherJob);
 };
 

src/compiler-dispatcher/compiler-dispatcher-tracer.cc

@@ -5,6 +5,7 @@
 #include "src/compiler-dispatcher/compiler-dispatcher-tracer.h"
 
 #include "src/isolate.h"
+#include "src/utils.h"
 
 namespace v8 {
 namespace internal {
@@ -143,6 +144,17 @@ double CompilerDispatcherTracer::EstimateFinalizeCompilingInMs() const {
   return Average(finalize_compiling_events_);
 }
 
+void CompilerDispatcherTracer::DumpStatistics() const {
+  PrintF(
+      "CompilerDispatcherTracer: "
+      "prepare_parsing=%.2lfms parsing=%.2lfms/kb finalize_parsing=%.2lfms "
+      "prepare_compiling=%.2lfms compiling=%.2lfms/kb "
+      "finalize_compilig=%.2lfms\n",
+      EstimatePrepareToParseInMs(), EstimateParseInMs(1 * KB),
+      EstimateFinalizeParsingInMs(), EstimatePrepareToCompileInMs(),
+      EstimateCompileInMs(1 * KB), EstimateFinalizeCompilingInMs());
+}
+
 double CompilerDispatcherTracer::Average(
     const base::RingBuffer<double>& buffer) {
   if (buffer.Count() == 0) return 0.0;

src/compiler-dispatcher/compiler-dispatcher-tracer.h

@@ -73,6 +73,8 @@ class V8_EXPORT_PRIVATE CompilerDispatcherTracer {
   double EstimateCompileInMs(size_t ast_size_in_bytes) const;
   double EstimateFinalizeCompilingInMs() const;
 
+  void DumpStatistics() const;
+
  private:
   static double Average(const base::RingBuffer<double>& buffer);
   static double Estimate(

src/compiler-dispatcher/compiler-dispatcher.cc

@@ -10,6 +10,7 @@
 #include "src/cancelable-task.h"
 #include "src/compiler-dispatcher/compiler-dispatcher-job.h"
 #include "src/compiler-dispatcher/compiler-dispatcher-tracer.h"
+#include "src/flags.h"
 #include "src/objects-inl.h"
 
 namespace v8 {
@@ -204,6 +205,7 @@ CompilerDispatcher::CompilerDispatcher(Isolate* isolate, Platform* platform,
     : isolate_(isolate),
       platform_(platform),
       max_stack_size_(max_stack_size),
+      trace_compiler_dispatcher_(FLAG_trace_compiler_dispatcher),
       tracer_(new CompilerDispatcherTracer(isolate_)),
       task_manager_(new CancelableTaskManager()),
       memory_pressure_level_(MemoryPressureLevel::kNone),
@@ -212,7 +214,11 @@ CompilerDispatcher::CompilerDispatcher(Isolate* isolate, Platform* platform,
       num_scheduled_background_tasks_(0),
       main_thread_blocking_on_job_(nullptr),
       block_for_testing_(false),
-      semaphore_for_testing_(0) {}
+      semaphore_for_testing_(0) {
+  if (trace_compiler_dispatcher_ && !IsEnabled()) {
+    PrintF("CompilerDispatcher: dispatcher is disabled\n");
+  }
+}
 
 CompilerDispatcher::~CompilerDispatcher() {
   // To avoid crashing in unit tests due to unfished jobs.
@@ -240,6 +246,13 @@ bool CompilerDispatcher::Enqueue(Handle<SharedFunctionInfo> function) {
   }
 
   if (IsEnqueued(function)) return true;
+
+  if (trace_compiler_dispatcher_) {
+    PrintF("CompilerDispatcher: enqueuing ");
+    function->ShortPrint();
+    PrintF("\n");
+  }
+
   std::unique_ptr<CompilerDispatcherJob> job(new CompilerDispatcherJob(
       isolate_, tracer_.get(), function, max_stack_size_));
   std::pair<int, int> key(Script::cast(function->script())->id(),
@@ -278,12 +291,26 @@ bool CompilerDispatcher::FinishNow(Handle<SharedFunctionInfo> function) {
   JobMap::const_iterator job = GetJobFor(function);
   CHECK(job != jobs_.end());
 
+  if (trace_compiler_dispatcher_) {
+    PrintF("CompilerDispatcher: finishing ");
+    function->ShortPrint();
+    PrintF(" now\n");
+  }
+
   WaitForJobIfRunningOnBackground(job->second.get());
   while (!IsFinished(job->second.get())) {
     DoNextStepOnMainThread(isolate_, job->second.get(),
                            ExceptionHandling::kThrow);
   }
   bool result = job->second->status() != CompileJobStatus::kFailed;
+
+  if (trace_compiler_dispatcher_) {
+    PrintF("CompilerDispatcher: finished working on ");
+    function->ShortPrint();
+    PrintF(": %s\n", result ? "success" : "failure");
+    tracer_->DumpStatistics();
+  }
+
   job->second->ResetOnMainThread();
   jobs_.erase(job);
   if (jobs_.empty()) {
@@ -299,6 +326,11 @@ void CompilerDispatcher::AbortAll(BlockingBehavior blocking) {
   if (!background_tasks_running || blocking == BlockingBehavior::kBlock) {
     for (auto& it : jobs_) {
       WaitForJobIfRunningOnBackground(it.second.get());
+      if (trace_compiler_dispatcher_) {
+        PrintF("CompilerDispatcher: aborted ");
+        it.second->ShortPrint();
+        PrintF("\n");
+      }
       it.second->ResetOnMainThread();
     }
     jobs_.clear();
@@ -341,6 +373,11 @@ void CompilerDispatcher::AbortInactiveJobs() {
         continue;
       }
     }
+    if (trace_compiler_dispatcher_) {
+      PrintF("CompilerDispatcher: aborted ");
+      job->second->ShortPrint();
+      PrintF("\n");
+    }
     job->second->ResetOnMainThread();
     jobs_.erase(job);
   }
@@ -360,6 +397,9 @@ void CompilerDispatcher::MemoryPressureNotification(
       level == MemoryPressureLevel::kNone) {
     return;
   }
+  if (trace_compiler_dispatcher_) {
+    PrintF("CompilerDispatcher: received memory pressure notification\n");
+  }
   if (is_isolate_locked) {
     AbortAll(BlockingBehavior::kDontBlock);
   } else {
@@ -458,6 +498,10 @@ void CompilerDispatcher::DoBackgroundWork() {
     semaphore_for_testing_.Wait();
   }
 
+  if (trace_compiler_dispatcher_) {
+    PrintF("CompilerDispatcher: doing background work\n");
+  }
+
   DoNextStepOnBackgroundThread(job);
 
   ScheduleMoreBackgroundTasksIfNeeded();
@@ -507,6 +551,12 @@ void CompilerDispatcher::DoIdleWork(double deadline_in_seconds) {
   // finished), or 3) make progress on it.
   double idle_time_in_seconds =
       deadline_in_seconds - platform_->MonotonicallyIncreasingTime();
+
+  if (trace_compiler_dispatcher_) {
+    PrintF("CompilerDispatcher: received %0.1lfms of idle time\n",
+           idle_time_in_seconds *
+               static_cast<double>(base::Time::kMillisecondsPerSecond));
+  }
   for (auto job = jobs_.begin();
        job != jobs_.end() && idle_time_in_seconds > 0.0;
        idle_time_in_seconds =
@@ -537,6 +587,14 @@ void CompilerDispatcher::DoIdleWork(double deadline_in_seconds) {
       ++job;
     } else if (IsFinished(job->second.get())) {
       DCHECK(it == pending_background_jobs_.end());
+      if (trace_compiler_dispatcher_) {
+        PrintF("CompilerDispatcher: finished working on ");
+        job->second->ShortPrint();
+        PrintF(": %s\n", job->second->status() == CompileJobStatus::kDone
+                             ? "success"
+                             : "failure");
+        tracer_->DumpStatistics();
+      }
       job->second->ResetOnMainThread();
       job = jobs_.erase(job);
       continue;

src/compiler-dispatcher/compiler-dispatcher.h

@@ -120,6 +120,10 @@ class V8_EXPORT_PRIVATE CompilerDispatcher {
   Isolate* isolate_;
   Platform* platform_;
   size_t max_stack_size_;
+
+  // Copy of FLAG_trace_compiler_dispatcher to allow for access from any thread.
+  bool trace_compiler_dispatcher_;
+
   std::unique_ptr<CompilerDispatcherTracer> tracer_;
 
   std::unique_ptr<CancelableTaskManager> task_manager_;

src/flag-definitions.h

@@ -669,6 +669,13 @@ DEFINE_BOOL(cache_prototype_transitions, true, "cache prototype transitions")
 
 // compiler-dispatcher.cc
 DEFINE_BOOL(compiler_dispatcher, false, "enable compiler dispatcher")
+DEFINE_BOOL(trace_compiler_dispatcher, false,
+            "trace compiler dispatcher activity")
+
+// compiler-dispatcher-job.cc
+DEFINE_BOOL(
+    trace_compiler_dispatcher_jobs, false,
+    "trace progress of individual jobs managed by the compiler dispatcher")
 
 // cpu-profiler.cc
 DEFINE_INT(cpu_profiler_sampling_interval, 1000,