src: implement debug output utilities

Implement utilities for easier debugging of Node.js core code,
inspired by the HTTP/2 debugging code. Debugging is, however,
implemented at runtime rather than at compile time, controlled
through a new `NODE_DEBUG_NATIVE=categories` environment variable.

The runtime overhead in the debugging-disabled case amounts to
1 well-cachable one-byte read per debug call.

PR-URL: #20987
Reviewed-By: Daniel Bevenius <[email protected]>
Reviewed-By: Joyee Cheung <[email protected]>
Reviewed-By: Minwoo Jung <[email protected]>
Reviewed-By: James M Snell <[email protected]>

node.gyp

@@ -367,6 +367,7 @@
         'src/base_object-inl.h',
         'src/connection_wrap.h',
         'src/connect_wrap.h',
+        'src/debug_utils.h',
         'src/env.h',
         'src/env-inl.h',
         'src/handle_wrap.h',

src/async_wrap.cc

@@ -769,6 +769,11 @@ void EmitAsyncDestroy(Isolate* isolate, async_context asyncContext) {
       Environment::GetCurrent(isolate), asyncContext.async_id);
 }
 
+std::string AsyncWrap::diagnostic_name() const {
+  return std::string(provider_names[provider_type()]) +
+      " (" + std::to_string(static_cast<int64_t>(async_id_)) + ")";
+}
+
 }  // namespace node
 
 NODE_BUILTIN_MODULE_CONTEXT_AWARE(async_wrap, node::AsyncWrap::Initialize)

src/async_wrap.h

@@ -167,6 +167,7 @@ class AsyncWrap : public BaseObject {
                                                 v8::Local<v8::Value>* argv);
 
   virtual size_t self_size() const = 0;
+  virtual std::string diagnostic_name() const;
 
   static void WeakCallback(const v8::WeakCallbackInfo<DestroyParam> &info);
 

src/debug_utils.h

@@ -0,0 +1,92 @@
+#ifndef SRC_DEBUG_UTILS_H_
+#define SRC_DEBUG_UTILS_H_
+
+#if defined(NODE_WANT_INTERNALS) && NODE_WANT_INTERNALS
+
+#include "async_wrap.h"
+#include "env.h"
+#include <string>
+
+// Use FORCE_INLINE on functions that have a debug-category-enabled check first
+// and then ideally only a single function call following it, to maintain
+// performance for the common case (no debugging used).
+#ifdef __GNUC__
+#define FORCE_INLINE __attribute__((always_inline))
+#define COLD_NOINLINE __attribute__((cold, noinline))
+#else
+#define FORCE_INLINE
+#define COLD_NOINLINE
+#endif
+
+namespace node {
+
+template <typename... Args>
+inline void FORCE_INLINE Debug(Environment* env,
+                               DebugCategory cat,
+                               const char* format,
+                               Args&&... args) {
+  if (!UNLIKELY(env->debug_enabled(cat)))
+    return;
+  fprintf(stderr, format, std::forward<Args>(args)...);
+}
+
+inline void FORCE_INLINE Debug(Environment* env,
+                               DebugCategory cat,
+                               const char* message) {
+  if (!UNLIKELY(env->debug_enabled(cat)))
+    return;
+  fprintf(stderr, "%s", message);
+}
+
+template <typename... Args>
+inline void Debug(Environment* env,
+                  DebugCategory cat,
+                  const std::string& format,
+                  Args&&... args) {
+  Debug(env, cat, format.c_str(), std::forward<Args>(args)...);
+}
+
+// Used internally by the 'real' Debug(AsyncWrap*, ...) functions below, so that
+// the FORCE_INLINE flag on them doesn't apply to the contents of this function
+// as well.
+// We apply COLD_NOINLINE to tell the compiler that it's not worth optimizing
+// this function for speed and it should rather focus on keeping it out of
+// hot code paths. In particular, we want to keep the string concatenating code
+// out of the function containing the original `Debug()` call.
+template <typename... Args>
+void COLD_NOINLINE UnconditionalAsyncWrapDebug(AsyncWrap* async_wrap,
+                                               const char* format,
+                                               Args&&... args) {
+  Debug(async_wrap->env(),
+        static_cast<DebugCategory>(async_wrap->provider_type()),
+        async_wrap->diagnostic_name() + " " + format + "\n",
+        std::forward<Args>(args)...);
+}
+
+template <typename... Args>
+inline void FORCE_INLINE Debug(AsyncWrap* async_wrap,
+                               const char* format,
+                               Args&&... args) {
+#ifdef DEBUG
+  CHECK_NOT_NULL(async_wrap);
+#endif
+  DebugCategory cat =
+      static_cast<DebugCategory>(async_wrap->provider_type());
+  if (!UNLIKELY(async_wrap->env()->debug_enabled(cat)))
+    return;
+  UnconditionalAsyncWrapDebug(async_wrap, format, std::forward<Args>(args)...);
+}
+
+template <typename... Args>
+inline void FORCE_INLINE Debug(AsyncWrap* async_wrap,
+                               const std::string& format,
+                               Args&&... args) {
+  Debug(async_wrap, format.c_str(), std::forward<Args>(args)...);
+}
+
+
+}  // namespace node
+
+#endif  // defined(NODE_WANT_INTERNALS) && NODE_WANT_INTERNALS
+
+#endif  // SRC_DEBUG_UTILS_H_

src/env-inl.h

@@ -519,6 +519,24 @@ inline void Environment::set_http2_state(
   http2_state_ = std::move(buffer);
 }
 
+bool Environment::debug_enabled(DebugCategory category) const {
+#ifdef DEBUG
+  CHECK_GE(static_cast<int>(category), 0);
+  CHECK_LT(static_cast<int>(category),
+           static_cast<int>(DebugCategory::CATEGORY_COUNT));
+#endif
+  return debug_enabled_[static_cast<int>(category)];
+}
+
+void Environment::set_debug_enabled(DebugCategory category, bool enabled) {
+#ifdef DEBUG
+  CHECK_GE(static_cast<int>(category), 0);
+  CHECK_LT(static_cast<int>(category),
+           static_cast<int>(DebugCategory::CATEGORY_COUNT));
+#endif
+  debug_enabled_[static_cast<int>(category)] = enabled;
+}
+
 inline AliasedBuffer<double, v8::Float64Array>*
 Environment::fs_stats_field_array() {
   return &fs_stats_field_array_;

src/env.cc

@@ -130,6 +130,10 @@ Environment::Environment(IsolateData* isolate_data,
 
   // By default, always abort when --abort-on-uncaught-exception was passed.
   should_abort_on_uncaught_toggle_[0] = 1;
+
+  std::string debug_cats;
+  SafeGetenv("NODE_DEBUG_NATIVE", &debug_cats);
+  set_debug_categories(debug_cats, true);
 }
 
 Environment::~Environment() {
@@ -496,6 +500,28 @@ Local<Value> Environment::GetNow() {
 }
 
 
+void Environment::set_debug_categories(const std::string& cats, bool enabled) {
+  std::string debug_categories = cats;
+  while (!debug_categories.empty()) {
+    std::string::size_type comma_pos = debug_categories.find(',');
+    std::string wanted = ToLower(debug_categories.substr(0, comma_pos));
+
+#define V(name)                                                          \
+    {                                                                    \
+      static const std::string available_category = ToLower(#name);      \
+      if (available_category.find(wanted) != std::string::npos)          \
+        set_debug_enabled(DebugCategory::name, enabled);                 \
+    }
+
+    DEBUG_CATEGORY_NAMES(V)
+
+    if (comma_pos == std::string::npos)
+      break;
+    // Use everything after the `,` as the list for the next iteration.
+    debug_categories = debug_categories.substr(comma_pos);
+  }
+}
+
 void CollectExceptionInfo(Environment* env,
                           v8::Local<v8::Object> obj,
                           int errorno,

src/env.h

@@ -398,6 +398,19 @@ struct ContextInfo {
   bool is_default = false;
 };
 
+// Listing the AsyncWrap provider types first enables us to cast directly
+// from a provider type to a debug category. Currently no other debug
+// categories are available.
+#define DEBUG_CATEGORY_NAMES(V) \
+    NODE_ASYNC_PROVIDER_TYPES(V)
+
+enum class DebugCategory {
+#define V(name) name,
+  DEBUG_CATEGORY_NAMES(V)
+#undef V
+  CATEGORY_COUNT
+};
+
 class Environment {
  public:
   class AsyncHooks {
@@ -654,6 +667,10 @@ class Environment {
   inline http2::Http2State* http2_state() const;
   inline void set_http2_state(std::unique_ptr<http2::Http2State> state);
 
+  inline bool debug_enabled(DebugCategory category) const;
+  inline void set_debug_enabled(DebugCategory category, bool enabled);
+  void set_debug_categories(const std::string& cats, bool enabled);
+
   inline AliasedBuffer<double, v8::Float64Array>* fs_stats_field_array();
 
   // stat fields contains twice the number of entries because `fs.StatWatcher`
@@ -853,6 +870,8 @@ class Environment {
   bool http_parser_buffer_in_use_ = false;
   std::unique_ptr<http2::Http2State> http2_state_;
 
+  bool debug_enabled_[static_cast<int>(DebugCategory::CATEGORY_COUNT)] = {0};
+
   AliasedBuffer<double, v8::Float64Array> fs_stats_field_array_;
 
   std::vector<std::unique_ptr<fs::FileHandleReadWrap>>

src/node.cc

@@ -3302,6 +3302,9 @@ static void PrintHelp() {
          "Environment variables:\n"
          "NODE_DEBUG                   ','-separated list of core modules\n"
          "                             that should print debug information\n"
+         "NODE_DEBUG_NATIVE            ','-separated list of C++ core debug\n"
+         "                             categories that should print debug\n"
+         "                             output\n"
          "NODE_DISABLE_COLORS          set to 1 to disable colors in the REPL\n"
          "NODE_EXTRA_CA_CERTS          path to additional CA certificates\n"
          "                             file\n"

src/util-inl.h

@@ -293,6 +293,13 @@ char ToLower(char c) {
   return c >= 'A' && c <= 'Z' ? c + ('a' - 'A') : c;
 }
 
+std::string ToLower(const std::string& in) {
+  std::string out(in.size(), 0);
+  for (size_t i = 0; i < in.size(); ++i)
+    out[i] = ToLower(in[i]);
+  return out;
+}
+
 bool StringEqualNoCase(const char* a, const char* b) {
   do {
     if (*a == '\0')

src/util.h

@@ -34,6 +34,7 @@
 #include <stdlib.h>
 #include <string.h>
 
+#include <string>
 #include <functional>  // std::function
 
 namespace node {
@@ -250,6 +251,7 @@ inline void SwapBytes64(char* data, size_t nbytes);
 
 // tolower() is locale-sensitive.  Use ToLower() instead.
 inline char ToLower(char c);
+inline std::string ToLower(const std::string& in);
 
 // strcasecmp() is locale-sensitive.  Use StringEqualNoCase() instead.
 inline bool StringEqualNoCase(const char* a, const char* b);