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]>

Author: addaleax

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{
+returnstd::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);
 
 virtualsize_tself_size() const = 0;
+virtual std::string diagnostic_name() const;
 
 staticvoidWeakCallback(const v8::WeakCallbackInfo<DestroyParam> &info);
 

src/debug_utils.h

@@ -0,0 +1,92 @@
+#ifndef SRC_DEBUG_UTILS_H_
+#defineSRC_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__
+#defineFORCE_INLINE__attribute__((always_inline))
+#defineCOLD_NOINLINE__attribute__((cold, noinline))
+#else
+#defineFORCE_INLINE
+#defineCOLD_NOINLINE
+#endif
+
+namespacenode{
+
+template <typename... Args>
+inlinevoid FORCE_INLINE Debug(Environment* env,
+ DebugCategory cat,
+constchar* format,
+ Args&&... args){
+if (!UNLIKELY(env->debug_enabled(cat)))
+return;
+fprintf(stderr, format, std::forward<Args>(args)...);
+}
+
+inlinevoid FORCE_INLINE Debug(Environment* env,
+ DebugCategory cat,
+constchar* message){
+if (!UNLIKELY(env->debug_enabled(cat)))
+return;
+fprintf(stderr, "%s", message);
+}
+
+template <typename... Args>
+inlinevoidDebug(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,
+constchar* 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>
+inlinevoid FORCE_INLINE Debug(AsyncWrap* async_wrap,
+constchar* 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>
+inlinevoid 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);
 }
 
+boolEnvironment::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)];
+}
+
+voidEnvironment::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(){
 }
 
 
+voidEnvironment::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));
+
+#defineV(name) \
+{\
+staticconst 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);
+ }
+}
+
 voidCollectExceptionInfo(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.
+#defineDEBUG_CATEGORY_NAMES(V) \
+NODE_ASYNC_PROVIDER_TYPES(V)
+
+enumclassDebugCategory{
+#defineV(name) name,
+DEBUG_CATEGORY_NAMES(V)
+#undef V
+ CATEGORY_COUNT
+};
+
 classEnvironment{
 public:
 classAsyncHooks{
@@ -654,6 +667,10 @@ class Environment{
 inline http2::Http2State* http2_state() const;
 inlinevoidset_http2_state(std::unique_ptr<http2::Http2State> state);
 
+inlinebooldebug_enabled(DebugCategory category) const;
+inlinevoidset_debug_enabled(DebugCategory category, bool enabled);
+voidset_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;
+}
+
 boolStringEqualNoCase(constchar* a, constchar* b){
 do{
 if (*a == '\0')

src/util.h

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