From 45eeea4330fd97720efe7d34a52a8a3e9181632f Mon Sep 17 00:00:00 2001 From: Anna Henningsen Date: Sun, 27 May 2018 16:37:30 +0200 Subject: [PATCH] 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: https://github.com/nodejs/node/pull/20987 Reviewed-By: Daniel Bevenius Reviewed-By: Joyee Cheung Reviewed-By: Minwoo Jung Reviewed-By: James M Snell --- node.gyp | 1 + src/async_wrap.cc | 5 +++ src/async_wrap.h | 1 + src/debug_utils.h | 92 +++++++++++++++++++++++++++++++++++++++++++++++ src/env-inl.h | 18 ++++++++++ src/env.cc | 26 ++++++++++++++ src/env.h | 19 ++++++++++ src/node.cc | 3 ++ src/util-inl.h | 7 ++++ src/util.h | 2 ++ 10 files changed, 174 insertions(+) create mode 100644 src/debug_utils.h diff --git a/node.gyp b/node.gyp index 48945acaca831e..10b818e683f1fc 100644 --- a/node.gyp +++ b/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', diff --git a/src/async_wrap.cc b/src/async_wrap.cc index 51db615f703f85..11ce5a387a950c 100644 --- a/src/async_wrap.cc +++ b/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(async_id_)) + ")"; +} + } // namespace node NODE_BUILTIN_MODULE_CONTEXT_AWARE(async_wrap, node::AsyncWrap::Initialize) diff --git a/src/async_wrap.h b/src/async_wrap.h index 17017ab602c84a..451bcfe12e6717 100644 --- a/src/async_wrap.h +++ b/src/async_wrap.h @@ -167,6 +167,7 @@ class AsyncWrap : public BaseObject { v8::Local* argv); virtual size_t self_size() const = 0; + virtual std::string diagnostic_name() const; static void WeakCallback(const v8::WeakCallbackInfo &info); diff --git a/src/debug_utils.h b/src/debug_utils.h new file mode 100644 index 00000000000000..f10342c79d35be --- /dev/null +++ b/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 + +// 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 +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)...); +} + +inline void FORCE_INLINE Debug(Environment* env, + DebugCategory cat, + const char* message) { + if (!UNLIKELY(env->debug_enabled(cat))) + return; + fprintf(stderr, "%s", message); +} + +template +inline void Debug(Environment* env, + DebugCategory cat, + const std::string& format, + Args&&... args) { + Debug(env, cat, format.c_str(), std::forward(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 +void COLD_NOINLINE UnconditionalAsyncWrapDebug(AsyncWrap* async_wrap, + const char* format, + Args&&... args) { + Debug(async_wrap->env(), + static_cast(async_wrap->provider_type()), + async_wrap->diagnostic_name() + " " + format + "\n", + std::forward(args)...); +} + +template +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(async_wrap->provider_type()); + if (!UNLIKELY(async_wrap->env()->debug_enabled(cat))) + return; + UnconditionalAsyncWrapDebug(async_wrap, format, std::forward(args)...); +} + +template +inline void FORCE_INLINE Debug(AsyncWrap* async_wrap, + const std::string& format, + Args&&... args) { + Debug(async_wrap, format.c_str(), std::forward(args)...); +} + + +} // namespace node + +#endif // defined(NODE_WANT_INTERNALS) && NODE_WANT_INTERNALS + +#endif // SRC_DEBUG_UTILS_H_ diff --git a/src/env-inl.h b/src/env-inl.h index a965bd195ef850..cb8d0c4efe0405 100644 --- a/src/env-inl.h +++ b/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(category), 0); + CHECK_LT(static_cast(category), + static_cast(DebugCategory::CATEGORY_COUNT)); +#endif + return debug_enabled_[static_cast(category)]; +} + +void Environment::set_debug_enabled(DebugCategory category, bool enabled) { +#ifdef DEBUG + CHECK_GE(static_cast(category), 0); + CHECK_LT(static_cast(category), + static_cast(DebugCategory::CATEGORY_COUNT)); +#endif + debug_enabled_[static_cast(category)] = enabled; +} + inline AliasedBuffer* Environment::fs_stats_field_array() { return &fs_stats_field_array_; diff --git a/src/env.cc b/src/env.cc index 2fa4432c54d4e9..f6303e6011f54c 100644 --- a/src/env.cc +++ b/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 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 obj, int errorno, diff --git a/src/env.h b/src/env.h index 15d417ba606860..c17cc59b5b5ccd 100644 --- a/src/env.h +++ b/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 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* 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_state_; + bool debug_enabled_[static_cast(DebugCategory::CATEGORY_COUNT)] = {0}; + AliasedBuffer fs_stats_field_array_; std::vector> diff --git a/src/node.cc b/src/node.cc index e464a44e461f84..e5d43a965882b5 100644 --- a/src/node.cc +++ b/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" diff --git a/src/util-inl.h b/src/util-inl.h index ff0d47c078815a..90c7447f7e105f 100644 --- a/src/util-inl.h +++ b/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') diff --git a/src/util.h b/src/util.h index 069f6d428e7751..e272286d3e4b96 100644 --- a/src/util.h +++ b/src/util.h @@ -34,6 +34,7 @@ #include #include +#include #include // 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);