feat: logbypass on worker threads

PR-URL: #154

src/commands/dump.cc

@@ -8,6 +8,7 @@
 #include "heapprofiler/sampling_heap_profiler.h"
 #include "logger.h"
 #include "platform/platform.h"
+#include "process_data.h"
 #include "report/node_report.h"
 #include "uv.h"
 #include "v8.h"
@@ -273,7 +274,9 @@ void StopProfiling(EnvironmentData* env_data, void* data,
 
 static void ProfilingWatchDog(void* data) {
   // TODO(legendecas): environment data selector
-  EnvironmentData* env_data = EnvironmentData::GetCurrent();
+  EnvironmentRegistry* registry = ProcessData::Get()->environment_registry();
+  EnvironmentRegistry::NoExitScope scope(registry);
+  EnvironmentData* env_data = registry->GetMainThread();
   BaseDumpData* dump_data = static_cast<BaseDumpData*>(data);
   string traceid = dump_data->traceid;
   DumpAction action = dump_data->action;
@@ -325,7 +328,9 @@ static json DoDumpAction(json command, DumpAction action, string prefix,
   action_map.insert(make_pair(action, true));
 
   // TODO(legendecas): environment data selector
-  EnvironmentData* env_data = EnvironmentData::GetCurrent();
+  EnvironmentRegistry* registry = ProcessData::Get()->environment_registry();
+  EnvironmentRegistry::NoExitScope scope(registry);
+  EnvironmentData* env_data = registry->GetMainThread();
 
   // get file name
   switch (action) {

src/environment_data.cc

@@ -9,21 +9,13 @@
 #include "xpf_v8.h"
 
 namespace xprofiler {
+using v8::Boolean;
 using v8::Context;
 using v8::Isolate;
 using v8::Local;
 using v8::Number;
 using v8::Object;
 
-// static
-EnvironmentData* EnvironmentData::GetCurrent() {
-  EnvironmentRegistry* registry = ProcessData::Get()->environment_registry();
-  EnvironmentRegistry::NoExitScope scope(registry);
-
-  CHECK_NE(registry->begin(), registry->end());
-  return *registry->begin();
-}
-
 // static
 EnvironmentData* EnvironmentData::GetCurrent(v8::Isolate* isolate) {
   EnvironmentRegistry* registry = ProcessData::Get()->environment_registry();
@@ -131,7 +123,9 @@ void EnvironmentData::CollectStatistics(uv_async_t* handle) {
 }
 
 // javascript accessible
-void JsSetupEnvironmentData(const Nan::FunctionCallbackInfo<v8::Value>& info) {
+// static
+void EnvironmentData::JsSetupEnvironmentData(
+    const Nan::FunctionCallbackInfo<v8::Value>& info) {
   Isolate* isolate = info.GetIsolate();
   EnvironmentData* env_data = EnvironmentData::GetCurrent(isolate);
   HandleScope scope(isolate);
@@ -142,7 +136,13 @@ void JsSetupEnvironmentData(const Nan::FunctionCallbackInfo<v8::Value>& info) {
       data->Get(context, OneByteString(isolate, "threadId"))
           .ToLocalChecked()
           .As<Number>();
-  env_data->set_thread_id(thread_id->Value());
+  Local<Boolean> is_main_thread =
+      data->Get(context, OneByteString(isolate, "isMainThread"))
+          .ToLocalChecked()
+          .As<Boolean>();
+
+  env_data->thread_id_ = thread_id->Value();
+  env_data->is_main_thread_ = is_main_thread->Value();
 }
 
 }  // namespace xprofiler

src/environment_data.h

@@ -6,6 +6,7 @@
 
 #include "commands/cpuprofiler/cpu_profiler.h"
 #include "commands/gcprofiler/gc_profiler.h"
+#include "library/common.h"
 #include "logbypass/gc.h"
 #include "logbypass/heap.h"
 #include "logbypass/http.h"
@@ -24,21 +25,23 @@ using InterruptCallback = std::function<void(EnvironmentData*, InterruptKind)>;
 
 class EnvironmentData {
  public:
-  // TODO(legendecas): remove this no-args GetCurrent.
-  static EnvironmentData* GetCurrent();
   static EnvironmentData* GetCurrent(v8::Isolate* isolate);
   static EnvironmentData* GetCurrent(
       const Nan::FunctionCallbackInfo<v8::Value>& info);
   static void Create(v8::Isolate* isolate);
 
+  static void JsSetupEnvironmentData(
+      const Nan::FunctionCallbackInfo<v8::Value>& info);
+
   void SendCollectStatistics();
 
   void RequestInterrupt(InterruptCallback interrupt);
 
   inline v8::Isolate* isolate() { return isolate_; }
   inline uv_loop_t* loop() { return loop_; }
-  inline double thread_id() { return thread_id_; }
-  inline void set_thread_id(double thread_id) { thread_id_ = thread_id; }
+
+  inline bool is_main_thread() { return is_main_thread_; }
+  inline ThreadId thread_id() { return thread_id_; }
 
   inline GcStatistics* gc_statistics() { return &gc_statistics_; }
   inline HttpStatistics* http_statistics() { return &http_statistics_; }
@@ -62,10 +65,12 @@ class EnvironmentData {
   v8::Isolate* isolate_;
   uv_loop_t* loop_;
   uv_async_t statistics_async_;
+
+  bool is_main_thread_ = false;
   /* We don't have a native method to get the uint64_t thread id.
    * Use the JavaScript number representation.
    */
-  double thread_id_ = -1;
+  ThreadId thread_id_ = ThreadId(-1);
 
   Mutex interrupt_mutex_;
   std::list<InterruptCallback> interrupt_requests_;
@@ -77,9 +82,6 @@ class EnvironmentData {
   UvHandleStatistics uv_handle_statistics_;
 };
 
-// javascript accessible
-void JsSetupEnvironmentData(const Nan::FunctionCallbackInfo<v8::Value>& info);
-
 }  // namespace xprofiler
 
 #endif /* XPROFILER_SRC_ENVIRONMENT_DATA_H */

src/environment_registry.cc

@@ -36,6 +36,18 @@ EnvironmentData* EnvironmentRegistry::Get(v8::Isolate* isolate) {
   return it->second.get();
 }
 
+EnvironmentData* EnvironmentRegistry::GetMainThread() {
+  CHECK(disallow_exit_);
+
+  for (auto it : *this) {
+    if (it->is_main_thread()) {
+      return it;
+    }
+  }
+
+  return nullptr;
+}
+
 EnvironmentRegistry::Iterator EnvironmentRegistry::begin() {
   CHECK(disallow_exit_);
   return Iterator(map_.begin());

src/environment_registry.h

@@ -49,6 +49,7 @@ class EnvironmentRegistry {
   void Register(v8::Isolate* isolate, std::unique_ptr<EnvironmentData> env);
   std::unique_ptr<EnvironmentData> Unregister(v8::Isolate* isolate);
   EnvironmentData* Get(v8::Isolate* isolate);
+  EnvironmentData* GetMainThread();
 
   Iterator begin();
   Iterator end();

src/library/common.h

@@ -11,6 +11,11 @@ unsigned long GetUptime();
 std::string GetStartTime(std::string format);
 size_t GetNextDiagFileId();
 
+/**
+ * Update the type when we can get integer thread_id from Node.js
+ */
+using ThreadId = double;
+
 // commands
 #define COMMAND_CALLBACK(cb)                                               \
   void cb(nlohmann::json command, std::string (*format)(const char*, ...), \

src/logbypass/gc.cc

@@ -105,28 +105,28 @@ void WriteGcStatusToLog(EnvironmentData* env_data, bool log_format_alinode) {
          gc_statistics->scavange_duration_last_record,
          gc_statistics->marksweep_duration_last_record);
   else
-    Info("gc",
-         "uptime: %lu, "
-         "total_gc_times: %u, "
-         "total_gc_duration: %lu, "
-         "total_scavange_duration: %lu, "
-         "total_marksweep_duration: %lu, "
-         "total_incremental_marking_duration: %lu, "
-         "gc_time_during_last_record: %lu, "
-         "scavange_duration_last_record: %lu, "
-         "marksweep_duration_last_record: %lu, "
-         "incremental_marking_duration_last_record: %lu",
-         GetUptime(),  // uptime, s
-         // total
-         gc_statistics->total_gc_times, gc_statistics->total_gc_duration,
-         gc_statistics->total_scavange_duration,
-         gc_statistics->total_marksweep_duration,
-         gc_statistics->total_incremental_marking_duration,
-         // last record
-         gc_statistics->gc_time_during_last_record,
-         gc_statistics->scavange_duration_last_record,
-         gc_statistics->marksweep_duration_last_record,
-         gc_statistics->incremental_marking_duration_last_record);
+    InfoT("gc", env_data->thread_id(),
+          "uptime: %lu, "
+          "total_gc_times: %u, "
+          "total_gc_duration: %lu, "
+          "total_scavange_duration: %lu, "
+          "total_marksweep_duration: %lu, "
+          "total_incremental_marking_duration: %lu, "
+          "gc_time_during_last_record: %lu, "
+          "scavange_duration_last_record: %lu, "
+          "marksweep_duration_last_record: %lu, "
+          "incremental_marking_duration_last_record: %lu",
+          GetUptime(),  // uptime, s
+          // total
+          gc_statistics->total_gc_times, gc_statistics->total_gc_duration,
+          gc_statistics->total_scavange_duration,
+          gc_statistics->total_marksweep_duration,
+          gc_statistics->total_incremental_marking_duration,
+          // last record
+          gc_statistics->gc_time_during_last_record,
+          gc_statistics->scavange_duration_last_record,
+          gc_statistics->marksweep_duration_last_record,
+          gc_statistics->incremental_marking_duration_last_record);
   // reset last record
   gc_statistics->reset();
 }

src/logbypass/heap.cc

@@ -112,25 +112,27 @@ void WriteMemoryInfoToLog(EnvironmentData* env_data, bool log_format_alinode) {
          LOG_SPACE_INFO(read_only), LOG_SPACE_INFO(new_large_object),
          LOG_SPACE_INFO(code_large_object));
   } else {
-    Info("memory",
-         COMMON_INFO_FORMATTERX SPACE_INFO_FORMATTER(new) SPACE_INFO_FORMATTER(
-             old) SPACE_INFO_FORMATTER(code) SPACE_INFO_FORMATTER(map)
-             SPACE_INFO_FORMATTER(lo) SPACE_INFO_FORMATTER(read_only)
-                 SPACE_INFO_FORMATTER(new_lo) SPACE_INFO_FORMATTER(code_lo),
-         // rss
-         rss,
-         // heap statistics
-         heap_statistics->used_heap_size(),
-         heap_statistics->total_available_size(),
-         heap_statistics->total_heap_size(), heap_statistics->heap_size_limit(),
-         heap_statistics->total_heap_size_executable(),
-         heap_statistics->total_physical_size(),
-         heap_statistics->malloced_memory(), heap_statistics->external_memory(),
-         // space statistics
-         LOG_SPACE_INFO(new), LOG_SPACE_INFO(old), LOG_SPACE_INFO(code),
-         LOG_SPACE_INFO(map), LOG_SPACE_INFO(large_object),
-         LOG_SPACE_INFO(read_only), LOG_SPACE_INFO(new_large_object),
-         LOG_SPACE_INFO(code_large_object));
+    InfoT(
+        "memory", env_data->thread_id(),
+        COMMON_INFO_FORMATTERX SPACE_INFO_FORMATTER(new)
+            SPACE_INFO_FORMATTER(old) SPACE_INFO_FORMATTER(code)
+                SPACE_INFO_FORMATTER(map) SPACE_INFO_FORMATTER(lo)
+                    SPACE_INFO_FORMATTER(read_only) SPACE_INFO_FORMATTER(new_lo)
+                        SPACE_INFO_FORMATTER(code_lo),
+        // rss
+        rss,
+        // heap statistics
+        heap_statistics->used_heap_size(),
+        heap_statistics->total_available_size(),
+        heap_statistics->total_heap_size(), heap_statistics->heap_size_limit(),
+        heap_statistics->total_heap_size_executable(),
+        heap_statistics->total_physical_size(),
+        heap_statistics->malloced_memory(), heap_statistics->external_memory(),
+        // space statistics
+        LOG_SPACE_INFO(new), LOG_SPACE_INFO(old), LOG_SPACE_INFO(code),
+        LOG_SPACE_INFO(map), LOG_SPACE_INFO(large_object),
+        LOG_SPACE_INFO(read_only), LOG_SPACE_INFO(new_large_object),
+        LOG_SPACE_INFO(code_large_object));
   }
 }
 }  // namespace xprofiler

src/logbypass/http.cc

@@ -109,18 +109,18 @@ void WriteHttpStatus(EnvironmentData* env_data, bool log_format_alinode,
       }
     }
 
-    Info("http",
-         "%s"
-         "live_http_request: %d, "
-         "http_response_close: %d, "
-         "http_response_sent: %d, "
-         "http_request_timeout: %d, "
-         "http_patch_timeout: %d, "
-         "http_rt: %.2lf",
-         format.c_str(), http_statistics->live_http_request,
-         http_statistics->http_response_close,
-         http_statistics->http_response_sent,
-         http_statistics->http_request_timeout, http_patch_timeout, rt);
+    InfoT("http", env_data->thread_id(),
+          "%s"
+          "live_http_request: %d, "
+          "http_response_close: %d, "
+          "http_response_sent: %d, "
+          "http_request_timeout: %d, "
+          "http_patch_timeout: %d, "
+          "http_rt: %.2lf",
+          format.c_str(), http_statistics->live_http_request,
+          http_statistics->http_response_close,
+          http_statistics->http_response_sent,
+          http_statistics->http_request_timeout, http_patch_timeout, rt);
   }
 
   // reset

src/logbypass/libuv.cc

@@ -83,27 +83,28 @@ void WriteLibuvHandleInfoToLog(EnvironmentData* env_data,
          uv_handle_statistics->active_timer_handles,
          uv_handle_statistics->active_handles);
   } else if (enable_log_uv_handles) {
-    Info("uv",
-         "active_handles: %d, "
-         "active_file_handles: %d, "
-         "active_and_ref_file_handles: %d, "
-         "active_tcp_handles: %d, "
-         "active_and_ref_tcp_handles: %d, "
-         "active_udp_handles: %d, "
-         "active_and_ref_udp_handles: %d, "
-         "active_timer_handles: %d, "
-         "active_and_ref_timer_handles: %d",
-         uv_handle_statistics->active_handles,
-         uv_handle_statistics->active_file_handles,
-         uv_handle_statistics->active_and_ref_file_handles,
-         uv_handle_statistics->active_tcp_handles,
-         uv_handle_statistics->active_and_ref_tcp_handles,
-         uv_handle_statistics->active_udp_handles,
-         uv_handle_statistics->active_and_ref_udp_handles,
-         uv_handle_statistics->active_timer_handles,
-         uv_handle_statistics->active_and_ref_timer_handles);
+    InfoT("uv", env_data->thread_id(),
+          "active_handles: %d, "
+          "active_file_handles: %d, "
+          "active_and_ref_file_handles: %d, "
+          "active_tcp_handles: %d, "
+          "active_and_ref_tcp_handles: %d, "
+          "active_udp_handles: %d, "
+          "active_and_ref_udp_handles: %d, "
+          "active_timer_handles: %d, "
+          "active_and_ref_timer_handles: %d",
+          uv_handle_statistics->active_handles,
+          uv_handle_statistics->active_file_handles,
+          uv_handle_statistics->active_and_ref_file_handles,
+          uv_handle_statistics->active_tcp_handles,
+          uv_handle_statistics->active_and_ref_tcp_handles,
+          uv_handle_statistics->active_udp_handles,
+          uv_handle_statistics->active_and_ref_udp_handles,
+          uv_handle_statistics->active_timer_handles,
+          uv_handle_statistics->active_and_ref_timer_handles);
   } else {
-    Info("uv", "active_handles: %d", uv_handle_statistics->active_handles);
+    InfoT("uv", env_data->thread_id(), "[%ld] active_handles: %d",
+          uv_handle_statistics->active_handles);
   }
 }
 }  // namespace xprofiler