Add a flag for printf debugging the compiler dispatcher

src/compiler-dispatcher/compiler-dispatcher.cc

 // Copyright 2016 the V8 project authors. All rights reserved.
 // Use of this source code is governed by a BSD-style license that can be
 // found in the LICENSE file.
 
 #include "src/compiler-dispatcher/compiler-dispatcher.h"
 
 #include "include/v8-platform.h"
 #include "include/v8.h"
 #include "src/base/platform/time.h"
 #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 {
 namespace internal {
 
 namespace {
 
 enum class ExceptionHandling { kSwallow, kThrow };
 
 bool DoNextStepOnMainThread(Isolate* isolate, CompilerDispatcherJob* job,
@@ skipping 174 matching lines @@
 
 void CompilerDispatcher::IdleTask::RunInternal(double deadline_in_seconds) {
   dispatcher_->DoIdleWork(deadline_in_seconds);
 }
 
 CompilerDispatcher::CompilerDispatcher(Isolate* isolate, Platform* platform,
                                        size_t max_stack_size)
     : 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),
       abort_(false),
       idle_task_scheduled_(false),
       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.
   AbortAll(BlockingBehavior::kBlock);
   task_manager_->CancelAndWait();
 }
 
 bool CompilerDispatcher::Enqueue(Handle<SharedFunctionInfo> function) {
   if (!IsEnabled()) return false;
 
   if (memory_pressure_level_.Value() != MemoryPressureLevel::kNone) {
     return false;
   }
 
   {
     base::LockGuard<base::Mutex> lock(&mutex_);
     if (abort_) return false;
   }
 
   // We only handle functions (no eval / top-level code / wasm) that are
   // attached to a script.
   if (!function->script()->IsScript() || !function->is_function() ||
       function->asm_function() || function->native()) {
     return false;
   }
 
   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(),
                           function->function_literal_id());
   jobs_.insert(std::make_pair(key, std::move(job)));
   ScheduleIdleTaskIfNeeded();
   return true;
 }
 
 bool CompilerDispatcher::IsEnabled() const {
@@ skipping 18 matching lines @@
     main_thread_blocking_signal_.Wait(&mutex_);
   }
   DCHECK(pending_background_jobs_.find(job) == pending_background_jobs_.end());
   DCHECK(running_background_jobs_.find(job) == running_background_jobs_.end());
 }
 
 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()) {
     base::LockGuard<base::Mutex> lock(&mutex_);
     abort_ = false;
   }
   return result;
 }
 
 void CompilerDispatcher::AbortAll(BlockingBehavior blocking) {
   bool background_tasks_running =
       task_manager_->TryAbortAll() == CancelableTaskManager::kTaskRunning;
   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();
     {
       base::LockGuard<base::Mutex> lock(&mutex_);
       DCHECK(pending_background_jobs_.empty());
       DCHECK(running_background_jobs_.empty());
       abort_ = false;
     }
     return;
@@ skipping 22 matching lines @@
   for (auto it = jobs_.begin(); it != jobs_.end();) {
     auto job = it;
     ++it;
     {
       base::LockGuard<base::Mutex> lock(&mutex_);
       if (running_background_jobs_.find(job->second.get()) !=
           running_background_jobs_.end()) {
         continue;
       }
     }
+    if (trace_compiler_dispatcher_) {
+      PrintF("CompilerDispatcher: aborted ");
+      job->second->ShortPrint();
+      PrintF("\n");
+    }
     job->second->ResetOnMainThread();
     jobs_.erase(job);
   }
   if (jobs_.empty()) {
     base::LockGuard<base::Mutex> lock(&mutex_);
     abort_ = false;
   }
 }
 
 void CompilerDispatcher::MemoryPressureNotification(
     v8::MemoryPressureLevel level, bool is_isolate_locked) {
   MemoryPressureLevel previous = memory_pressure_level_.Value();
   memory_pressure_level_.SetValue(level);
   // If we're already under pressure, we haven't accepted new tasks meanwhile
   // and can just return. If we're no longer under pressure, we're also done.
   if (previous != MemoryPressureLevel::kNone ||
       level == MemoryPressureLevel::kNone) {
     return;
   }
+  if (trace_compiler_dispatcher_) {
+    PrintF("CompilerDispatcher: received memory pressure notification\n");
+  }
   if (is_isolate_locked) {
     AbortAll(BlockingBehavior::kDontBlock);
   } else {
     {
       base::LockGuard<base::Mutex> lock(&mutex_);
       if (abort_) return;
       // By going into abort mode here, and clearing the
       // pending_background_jobs_, we at keep existing background jobs from
       // picking up more work before the MemoryPressureTask gets executed.
       abort_ = true;
@@ skipping 78 matching lines @@
       running_background_jobs_.insert(job);
     }
   }
   if (job == nullptr) return;
 
   if (V8_UNLIKELY(block_for_testing_.Value())) {
     block_for_testing_.SetValue(false);
     semaphore_for_testing_.Wait();
   }
 
+  if (trace_compiler_dispatcher_) {
+    PrintF("CompilerDispatcher: doing background work\n");
+  }
+
   DoNextStepOnBackgroundThread(job);
 
   ScheduleMoreBackgroundTasksIfNeeded();
   // Unconditionally schedule an idle task, as all background steps have to be
   // followed by a main thread step.
   ScheduleIdleTaskFromAnyThread();
 
   {
     base::LockGuard<base::Mutex> lock(&mutex_);
     running_background_jobs_.erase(job);
@@ skipping 29 matching lines @@
 
   // Number of jobs that are unlikely to make progress during any idle callback
   // due to their estimated duration.
   size_t too_long_jobs = 0;
 
   // Iterate over all available jobs & remaining time. For each job, decide
   // whether to 1) skip it (if it would take too long), 2) erase it (if it's
   // 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 =
            deadline_in_seconds - platform_->MonotonicallyIncreasingTime()) {
     // Don't work on jobs that are being worked on by background tasks.
     // Similarly, remove jobs we work on from the set of available background
     // jobs.
     std::unique_ptr<base::LockGuard<base::Mutex>> lock(
         new base::LockGuard<base::Mutex>(&mutex_));
     if (running_background_jobs_.find(job->second.get()) !=
@@ skipping 10 matching lines @@
       // have managed to finish the job in a large idle task to assess
       // whether we should ask for another idle callback.
       if (estimate_in_ms > kMaxIdleTimeToExpectInMs) ++too_long_jobs;
       if (it == pending_background_jobs_.end()) {
         lock.reset();
         ConsiderJobForBackgroundProcessing(job->second.get());
       }
       ++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;
     } else {
       // Do one step, and keep processing the job (as we don't advance the
       // iterator).
       if (it != pending_background_jobs_.end()) {
         pending_background_jobs_.erase(it);
       }
       lock.reset();
       DoNextStepOnMainThread(isolate_, job->second.get(),
                              ExceptionHandling::kSwallow);
     }
   }
   if (jobs_.size() > too_long_jobs) ScheduleIdleTaskIfNeeded();
 }
 
 }  // namespace internal
 }  // namespace v8