src: add more debug logs and comments in NodePlatform

PR-URL: #58047
Refs: #47452
Refs: #54918
Reviewed-By: Stephen Belanger <admin@stephenbelanger.com>

Author: joyeecheung

src/debug_utils.h

@@ -55,6 +55,8 @@ void NODE_EXTERN_PRIVATE FWrite(FILE* file, const std::string& str);
   V(MKSNAPSHOT)                                                                \
   V(SNAPSHOT_SERDES)                                                           \
   V(PERMISSION_MODEL)                                                          \
+  V(PLATFORM_MINIMAL)                                                          \
+  V(PLATFORM_VERBOSE)                                                          \
   V(QUIC)
 
 enum class DebugCategory : unsigned int {

src/node_platform.cc

@@ -13,6 +13,7 @@ using v8::Isolate;
 using v8::Object;
 using v8::Platform;
 using v8::Task;
+using v8::TaskPriority;
 
 namespace {
 
@@ -22,8 +23,31 @@ struct PlatformWorkerData {
   ConditionVariable* platform_workers_ready;
   int* pending_platform_workers;
   int id;
+  PlatformDebugLogLevel debug_log_level;
 };
 
+const char* GetTaskPriorityName(TaskPriority priority) {
+  switch (priority) {
+    case TaskPriority::kUserBlocking:
+      return "UserBlocking";
+    case TaskPriority::kUserVisible:
+      return "UserVisible";
+    case TaskPriority::kBestEffort:
+      return "BestEffort";
+    default:
+      return "Unknown";
+  }
+}
+
+static void PrintSourceLocation(const v8::SourceLocation& location) {
+  auto loc = location.ToString();
+  if (!loc.empty()) {
+    fprintf(stderr, " %s\n", loc.c_str());
+  } else {
+    fprintf(stderr, " <no location>\n");
+  }
+}
+
 static void PlatformWorkerThread(void* data) {
   std::unique_ptr<PlatformWorkerData>
       worker_data(static_cast<PlatformWorkerData*>(data));
@@ -39,8 +63,18 @@ static void PlatformWorkerThread(void* data) {
     worker_data->platform_workers_ready->Signal(lock);
   }
 
+  bool debug_log_enabled =
+      worker_data->debug_log_level != PlatformDebugLogLevel::kNone;
+  int id = worker_data->id;
   while (std::unique_ptr<Task> task =
              pending_worker_tasks->Lock().BlockingPop()) {
+    if (debug_log_enabled) {
+      fprintf(stderr,
+              "\nPlatformWorkerThread %d running task %p\n",
+              id,
+              task.get());
+      fflush(stderr);
+    }
     task->Run();
     pending_worker_tasks->Lock().NotifyOfCompletion();
   }
@@ -74,6 +108,12 @@ class WorkerThreadsTaskRunner::DelayedTaskScheduler {
 
   void PostDelayedTask(std::unique_ptr<Task> task, double delay_in_seconds) {
     auto locked = tasks_.Lock();
+
+    // The delayed task scheuler is on is own thread with its own loop that
+    // runs the timers for the scheduled tasks to pop the original task back
+    // into the the worker task queue. This first pushes the tasks that
+    // schedules the timers into the local task queue that will be flushed
+    // by the local event loop.
     locked.Push(std::make_unique<ScheduleTask>(
         this, std::move(task), delay_in_seconds));
     uv_async_send(&flush_tasks_);
@@ -108,6 +148,9 @@ class WorkerThreadsTaskRunner::DelayedTaskScheduler {
     while (!tasks_to_run.empty()) {
       std::unique_ptr<Task> task = std::move(tasks_to_run.front());
       tasks_to_run.pop();
+      // This runs either the ScheduleTasks that scheduels the timers to
+      // pop the tasks back into the worker task runner queue, or the
+      // or the StopTasks to stop the timers and drop all the pending tasks.
       task->Run();
     }
   }
@@ -135,9 +178,9 @@ class WorkerThreadsTaskRunner::DelayedTaskScheduler {
     ScheduleTask(DelayedTaskScheduler* scheduler,
                  std::unique_ptr<Task> task,
                  double delay_in_seconds)
-      : scheduler_(scheduler),
-        task_(std::move(task)),
-        delay_in_seconds_(delay_in_seconds) {}
+        : scheduler_(scheduler),
+          task_(std::move(task)),
+          delay_in_seconds_(delay_in_seconds) {}
 
     void Run() override {
       uint64_t delay_millis = llround(delay_in_seconds_ * 1000);
@@ -172,15 +215,21 @@ class WorkerThreadsTaskRunner::DelayedTaskScheduler {
   }
 
   uv_sem_t ready_;
+  // Task queue in the worker thread task runner, we push the delayed task back
+  // to it when the timer expires.
   TaskQueue<Task>* pending_worker_tasks_;
 
+  // Locally scheduled tasks to be poped into the worker task runner queue.
+  // It is flushed whenever the next closest timer expires.
   TaskQueue<Task> tasks_;
   uv_loop_t loop_;
   uv_async_t flush_tasks_;
   std::unordered_set<uv_timer_t*> timers_;
 };
 
-WorkerThreadsTaskRunner::WorkerThreadsTaskRunner(int thread_pool_size) {
+WorkerThreadsTaskRunner::WorkerThreadsTaskRunner(
+    int thread_pool_size, PlatformDebugLogLevel debug_log_level)
+    : debug_log_level_(debug_log_level) {
   Mutex platform_workers_mutex;
   ConditionVariable platform_workers_ready;
 
@@ -192,10 +241,13 @@ WorkerThreadsTaskRunner::WorkerThreadsTaskRunner(int thread_pool_size) {
   threads_.push_back(delayed_task_scheduler_->Start());
 
   for (int i = 0; i < thread_pool_size; i++) {
-    PlatformWorkerData* worker_data = new PlatformWorkerData{
-      &pending_worker_tasks_, &platform_workers_mutex,
-      &platform_workers_ready, &pending_platform_workers, i
-    };
+    PlatformWorkerData* worker_data =
+        new PlatformWorkerData{&pending_worker_tasks_,
+                               &platform_workers_mutex,
+                               &platform_workers_ready,
+                               &pending_platform_workers,
+                               i,
+                               debug_log_level_};
     std::unique_ptr<uv_thread_t> t { new uv_thread_t() };
     if (uv_thread_create(t.get(), PlatformWorkerThread,
                          worker_data) != 0) {
@@ -237,8 +289,8 @@ int WorkerThreadsTaskRunner::NumberOfWorkerThreads() const {
 }
 
 PerIsolatePlatformData::PerIsolatePlatformData(
-    Isolate* isolate, uv_loop_t* loop)
-  : isolate_(isolate), loop_(loop) {
+    Isolate* isolate, uv_loop_t* loop, PlatformDebugLogLevel debug_log_level)
+    : isolate_(isolate), loop_(loop), debug_log_level_(debug_log_level) {
   flush_tasks_ = new uv_async_t();
   CHECK_EQ(0, uv_async_init(loop, flush_tasks_, FlushTasks));
   flush_tasks_->data = static_cast<void*>(this);
@@ -264,6 +316,14 @@ void PerIsolatePlatformData::PostTask(std::unique_ptr<Task> task) {
   // the foreground task runner is being cleaned up by Shutdown(). In that
   // case, make sure we wait until the shutdown is completed (which leads
   // to flush_tasks_ == nullptr, and the task will be discarded).
+  if (debug_log_level_ != PlatformDebugLogLevel::kNone) {
+    fprintf(stderr, "\nPerIsolatePlatformData::PostTaskImpl %p", task.get());
+    if (debug_log_level_ == PlatformDebugLogLevel::kVerbose) {
+      DumpNativeBacktrace(stderr);
+    }
+    fflush(stderr);
+  }
+
   auto locked = foreground_tasks_.Lock();
   if (flush_tasks_ == nullptr) return;
   locked.Push(std::move(task));
@@ -272,6 +332,17 @@ void PerIsolatePlatformData::PostTask(std::unique_ptr<Task> task) {
 
 void PerIsolatePlatformData::PostDelayedTask(
     std::unique_ptr<Task> task, double delay_in_seconds) {
+  if (debug_log_level_ != PlatformDebugLogLevel::kNone) {
+    fprintf(stderr,
+            "\nPerIsolatePlatformData::PostDelayedTaskImpl %p %f",
+            task.get(),
+            delay_in_seconds);
+    if (debug_log_level_ == PlatformDebugLogLevel::kVerbose) {
+      DumpNativeBacktrace(stderr);
+    }
+    fflush(stderr);
+  }
+
   auto locked = foreground_delayed_tasks_.Lock();
   if (flush_tasks_ == nullptr) return;
   std::unique_ptr<DelayedTask> delayed(new DelayedTask());
@@ -339,6 +410,16 @@ void PerIsolatePlatformData::DecreaseHandleCount() {
 NodePlatform::NodePlatform(int thread_pool_size,
                            v8::TracingController* tracing_controller,
                            v8::PageAllocator* page_allocator) {
+  if (per_process::enabled_debug_list.enabled(
+          DebugCategory::PLATFORM_VERBOSE)) {
+    debug_log_level_ = PlatformDebugLogLevel::kVerbose;
+  } else if (per_process::enabled_debug_list.enabled(
+                 DebugCategory::PLATFORM_MINIMAL)) {
+    debug_log_level_ = PlatformDebugLogLevel::kMinimal;
+  } else {
+    debug_log_level_ = PlatformDebugLogLevel::kNone;
+  }
+
   if (tracing_controller != nullptr) {
     tracing_controller_ = tracing_controller;
   } else {
@@ -355,8 +436,8 @@ NodePlatform::NodePlatform(int thread_pool_size,
   DCHECK_EQ(GetTracingController(), tracing_controller_);
 
   thread_pool_size = GetActualThreadPoolSize(thread_pool_size);
-  worker_thread_task_runner_ =
-      std::make_shared<WorkerThreadsTaskRunner>(thread_pool_size);
+  worker_thread_task_runner_ = std::make_shared<WorkerThreadsTaskRunner>(
+      thread_pool_size, debug_log_level_);
 }
 
 NodePlatform::~NodePlatform() {
@@ -365,7 +446,8 @@ NodePlatform::~NodePlatform() {
 
 void NodePlatform::RegisterIsolate(Isolate* isolate, uv_loop_t* loop) {
   Mutex::ScopedLock lock(per_isolate_mutex_);
-  auto delegate = std::make_shared<PerIsolatePlatformData>(isolate, loop);
+  auto delegate =
+      std::make_shared<PerIsolatePlatformData>(isolate, loop, debug_log_level_);
   IsolatePlatformDelegate* ptr = delegate.get();
   auto insertion = per_isolate_.emplace(
     isolate,
@@ -520,6 +602,17 @@ void NodePlatform::PostTaskOnWorkerThreadImpl(
     v8::TaskPriority priority,
     std::unique_ptr<v8::Task> task,
     const v8::SourceLocation& location) {
+  if (debug_log_level_ != PlatformDebugLogLevel::kNone) {
+    fprintf(stderr,
+            "\nNodePlatform::PostTaskOnWorkerThreadImpl %s %p",
+            GetTaskPriorityName(priority),
+            task.get());
+    PrintSourceLocation(location);
+    if (debug_log_level_ == PlatformDebugLogLevel::kVerbose) {
+      DumpNativeBacktrace(stderr);
+    }
+    fflush(stderr);
+  }
   worker_thread_task_runner_->PostTask(std::move(task));
 }
 
@@ -528,6 +621,18 @@ void NodePlatform::PostDelayedTaskOnWorkerThreadImpl(
     std::unique_ptr<v8::Task> task,
     double delay_in_seconds,
     const v8::SourceLocation& location) {
+  if (debug_log_level_ != PlatformDebugLogLevel::kNone) {
+    fprintf(stderr,
+            "\nNodePlatform::PostDelayedTaskOnWorkerThreadImpl %s %p %f",
+            GetTaskPriorityName(priority),
+            task.get(),
+            delay_in_seconds);
+    PrintSourceLocation(location);
+    if (debug_log_level_ == PlatformDebugLogLevel::kVerbose) {
+      DumpNativeBacktrace(stderr);
+    }
+    fflush(stderr);
+  }
   worker_thread_task_runner_->PostDelayedTask(std::move(task),
                                               delay_in_seconds);
 }
@@ -557,6 +662,17 @@ std::unique_ptr<v8::JobHandle> NodePlatform::CreateJobImpl(
     v8::TaskPriority priority,
     std::unique_ptr<v8::JobTask> job_task,
     const v8::SourceLocation& location) {
+  if (debug_log_level_ != PlatformDebugLogLevel::kNone) {
+    fprintf(stderr,
+            "\nNodePlatform::CreateJobImpl %s %p",
+            GetTaskPriorityName(priority),
+            job_task.get());
+    PrintSourceLocation(location);
+    if (debug_log_level_ == PlatformDebugLogLevel::kVerbose) {
+      DumpNativeBacktrace(stderr);
+    }
+    fflush(stderr);
+  }
   return v8::platform::NewDefaultJobHandle(
       this, priority, std::move(job_task), NumberOfWorkerThreads());
 }

src/node_platform.h

@@ -61,13 +61,22 @@ struct DelayedTask {
   std::shared_ptr<PerIsolatePlatformData> platform_data;
 };
 
+enum class PlatformDebugLogLevel {
+  kNone = 0,
+  kMinimal = 1,
+  kVerbose = 2,
+};
+
 // This acts as the foreground task runner for a given Isolate.
 class PerIsolatePlatformData :
     public IsolatePlatformDelegate,
     public v8::TaskRunner,
     public std::enable_shared_from_this<PerIsolatePlatformData> {
  public:
-  PerIsolatePlatformData(v8::Isolate* isolate, uv_loop_t* loop);
+  PerIsolatePlatformData(
+      v8::Isolate* isolate,
+      uv_loop_t* loop,
+      PlatformDebugLogLevel debug_log_level = PlatformDebugLogLevel::kNone);
   ~PerIsolatePlatformData() override;
 
   std::shared_ptr<v8::TaskRunner> GetForegroundTaskRunner() override;
@@ -126,12 +135,14 @@ class PerIsolatePlatformData :
   typedef std::unique_ptr<DelayedTask, void(*)(DelayedTask*)>
       DelayedTaskPointer;
   std::vector<DelayedTaskPointer> scheduled_delayed_tasks_;
+  PlatformDebugLogLevel debug_log_level_ = PlatformDebugLogLevel::kNone;
 };
 
 // This acts as the single worker thread task runner for all Isolates.
 class WorkerThreadsTaskRunner {
  public:
-  explicit WorkerThreadsTaskRunner(int thread_pool_size);
+  explicit WorkerThreadsTaskRunner(int thread_pool_size,
+                                   PlatformDebugLogLevel debug_log_level);
 
   void PostTask(std::unique_ptr<v8::Task> task);
   void PostDelayedTask(std::unique_ptr<v8::Task> task,
@@ -143,12 +154,21 @@ class WorkerThreadsTaskRunner {
   int NumberOfWorkerThreads() const;
 
  private:
+  // A queue shared by all threads. The consumers are the worker threads which
+  // take tasks from it to run in PlatformWorkerThread(). The producers can be
+  // any thread. Both the foreground thread and the worker threads can push
+  // tasks into the queue via v8::Platform::PostTaskOnWorkerThread() which
+  // eventually calls PostTask() on this class. When any thread calls
+  // v8::Platform::PostDelayedTaskOnWorkerThread(), the DelayedTaskScheduler
+  // thread will schedule a timer that pushes the delayed tasks back into this
+  // queue when the timer expires.
   TaskQueue<v8::Task> pending_worker_tasks_;
 
   class DelayedTaskScheduler;
   std::unique_ptr<DelayedTaskScheduler> delayed_task_scheduler_;
 
   std::vector<std::unique_ptr<uv_thread_t>> threads_;
+  PlatformDebugLogLevel debug_log_level_ = PlatformDebugLogLevel::kNone;
 };
 
 class NodePlatform : public MultiIsolatePlatform {
@@ -208,6 +228,7 @@ class NodePlatform : public MultiIsolatePlatform {
   v8::PageAllocator* page_allocator_;
   std::shared_ptr<WorkerThreadsTaskRunner> worker_thread_task_runner_;
   bool has_shut_down_ = false;
+  PlatformDebugLogLevel debug_log_level_ = PlatformDebugLogLevel::kNone;
 };
 
 }  // namespace node