PTP: dump stats in either [Signal]Exit or Start

Problem: Apparently some uses of node go through Exit without fully cleaning up, so printing stats in the PartitionedNodeThreadpool d'tor was not giving us stats. This was true, for example, for 'npm install'. Solution: DrainAndPrintStats in both node.cc::Start and node.cc::Exit, and only keep the first one if we see it twice. This should not be merged. Just performance profiling. And dumping stats in SignalExit is unsafe.
davisjam · Aug 31, 2018 · Sep 3, 2018 · Sep 6, 2018 · Sep 6, 2018 · Sep 6, 2018
commit 003c147065f144de0e758e5bc83b567b1b146ea8
diff --git a/src/node.cc b/src/node.cc
@@ -306,10 +306,20 @@ static struct {
 
     libuv_executor_ = std::unique_ptr<threadpool::LibuvExecutor>(
       new threadpool::LibuvExecutor(tp_));
+    printed_stats = false;
+  }
+
+  void DrainAndPrintStats(void) {
+    if (!printed_stats) {
+      tp_->BlockingDrain();
+      tp_->PrintStats();
+      printed_stats = true;
+    }
   }
 
   std::shared_ptr<threadpool::NodeThreadpool> tp_;
   std::unique_ptr<threadpool::LibuvExecutor> libuv_executor_;
+  bool printed_stats;
 } node_threadpool;
 
 static struct {
@@ -1224,6 +1234,9 @@ static void Exit(const FunctionCallbackInfo<Value>& args) {
   Environment* env = Environment::GetCurrent(args);
   WaitForInspectorDisconnect(env);
   v8_platform.StopTracingAgent();
+
+  node_threadpool.DrainAndPrintStats();
+
   env->Exit(args[0]->Int32Value());
 }
 
@@ -2213,6 +2226,9 @@ void SetupProcessObject(Environment* env,
 
 
 void SignalExit(int signo) {
+  // Yeah, yeah, this is not signal safe.
+  node_threadpool.DrainAndPrintStats();
+
   uv_tty_reset_mode();
   v8_platform.StopTracingAgent();
 #ifdef __FreeBSD__
@@ -3377,6 +3393,7 @@ int Start(int argc, char** argv) {
   // Replace the default V8 platform with our implementation.
   // Use our threadpool.
   v8_platform.Initialize(node_threadpool.tp_);
+
   V8::Initialize();
   performance::performance_v8_start = PERFORMANCE_NOW();
   v8_initialized = true;
@@ -3394,6 +3411,8 @@ int Start(int argc, char** argv) {
   // will never be fully cleaned up.
   v8_platform.Dispose();
 
+  node_threadpool.DrainAndPrintStats();
+
   return exit_code;
 }
 

diff --git a/src/node_threadpool.cc b/src/node_threadpool.cc
@@ -88,6 +88,9 @@ int NodeThreadpool::NWorkers() const {
   return tp_->NWorkers();
 }
 
+void NodeThreadpool::PrintStats() const {
+}
+
 /**************
  * PartitionedNodeThreadpool
  ***************/
@@ -112,12 +115,17 @@ void PartitionedNodeThreadpool::Initialize(const std::vector<int>& tp_sizes) {
 }
 
 PartitionedNodeThreadpool::~PartitionedNodeThreadpool() {
+  LOG("PartitionedNodeThreadpool::~PartitionedNodeThreadpool: Goodbye\n");
+  fflush(stderr);
+
   // If we just return, the destructors of the tp's will drain them.
   // But if we want to report meaningful statistics we must drain them first.
   for (auto &tp : tps_) {
     tp->BlockingDrain();
   }
+}
 
+void PartitionedNodeThreadpool::PrintStats(void) const {
   // TODO(davisjam) Let's hope the application didn't make more than one of these :-D.
   char logFile[128];
   snprintf(logFile, sizeof(logFile), "/tmp/node-%d-PartitionedNodeThreadpool-result.log", getpid());
@@ -129,7 +137,7 @@ PartitionedNodeThreadpool::~PartitionedNodeThreadpool() {
   // so we can slice and dice quickly.
   LOG_TO_FILE(fd, "TP key format: TP,name,size\n");
   for (auto pair : tp_labels_) {
-    LOG_TO_FILE(fd, "TP key: %d,%s,%d\n", pair.first, tp_labels_[pair.first].c_str(), tp_sizes_[pair.first]);
+    LOG_TO_FILE(fd, "TP key: %d,%s,%d\n", pair.first, tp_labels_.at(pair.first).c_str(), tp_sizes_.at(pair.first));
   }
 
   LOG_TO_FILE(fd, "QueueLengths data format: TP,queue-length,n_cpu,n_io,time\n");

diff --git a/src/node_threadpool.h b/src/node_threadpool.h
@@ -395,6 +395,9 @@ class NodeThreadpool {
   // Attributes
   virtual int NWorkers() const;
 
+  // Does nothing. Subclasses can implement.
+  virtual void PrintStats() const;
+
  protected:
   int GoodCPUThreadpoolSize();
 
@@ -422,6 +425,8 @@ class PartitionedNodeThreadpool : public NodeThreadpool {
 
   virtual int NWorkers() const override;
 
+  virtual void PrintStats() const override;
+
  protected:
   // Sub-classes should call this after computing tp_sizes in their c'tors.
   void Initialize(const std::vector<int>& tp_sizes);