From 2c715a6b02f2a21fc67fa47e620ad22ffa47fbbe Mon Sep 17 00:00:00 2001 From: Trevor Norris Date: Thu, 14 May 2015 11:46:54 -0600 Subject: [PATCH] core: implement runtime flag to trace sync io Use the --trace-sync-io flag to print a stack trace whenever a sync method is used after the first tick, excluding during the process exit event. (e.g. fs.readFileSync()) It does not track if the warning has occurred at a specific location in the past and so will print the warning every time. Reason for not printing during the first tick of the appication is so all necessary resources can be required. Also by excluding synchronous calls during exit is necessary in case any data needs to be logged out by the application before it shuts down. Fixes: https://github.com/nodejs/io.js/issues/1674 PR-URL: https://github.com/nodejs/io.js/pull/1707 Reviewed-By: Ben Noordhuis Reviewed-By: Fedor Indutny Reviewed-By: Jeremiah Senkpiel Reviewed-By: Petka Antonov --- node.gyp | 1 + src/env-inl.h | 5 ++++ src/env.cc | 58 ++++++++++++++++++++++++++++++++++++++++++++++ src/env.h | 4 ++++ src/node.cc | 18 ++++++++++++++ src/node_crypto.cc | 2 ++ src/node_file.cc | 1 + src/node_zlib.cc | 1 + src/spawn_sync.cc | 4 +++- 9 files changed, 93 insertions(+), 1 deletion(-) create mode 100644 src/env.cc diff --git a/node.gyp b/node.gyp index c72b93b13868f4..70c9841a89a176 100644 --- a/node.gyp +++ b/node.gyp @@ -99,6 +99,7 @@ 'sources': [ 'src/debug-agent.cc', 'src/async-wrap.cc', + 'src/env.cc', 'src/fs_event_wrap.cc', 'src/cares_wrap.cc', 'src/handle_wrap.cc', diff --git a/src/env-inl.h b/src/env-inl.h index a0815acaccb926..0feefdb1e454c0 100644 --- a/src/env-inl.h +++ b/src/env-inl.h @@ -176,6 +176,7 @@ inline Environment::Environment(v8::Local context, using_abort_on_uncaught_exc_(false), using_asyncwrap_(false), printed_error_(false), + trace_sync_io_(false), debugger_agent_(this), context_(context->GetIsolate(), context) { // We'll be creating new objects so make sure we've entered the context. @@ -325,6 +326,10 @@ inline void Environment::set_printed_error(bool value) { printed_error_ = value; } +inline void Environment::set_trace_sync_io(bool value) { + trace_sync_io_ = value; +} + inline Environment* Environment::from_cares_timer_handle(uv_timer_t* handle) { return ContainerOf(&Environment::cares_timer_handle_, handle); } diff --git a/src/env.cc b/src/env.cc new file mode 100644 index 00000000000000..bc1ae36e5a3509 --- /dev/null +++ b/src/env.cc @@ -0,0 +1,58 @@ +#include "env.h" +#include "env-inl.h" +#include "v8.h" +#include + +namespace node { + +using v8::HandleScope; +using v8::Local; +using v8::Message; +using v8::StackFrame; +using v8::StackTrace; + +void Environment::PrintSyncWarn() const { + if (!trace_sync_io_) + return; + + HandleScope handle_scope(isolate()); + Local stack = + StackTrace::CurrentStackTrace(isolate(), 10, StackTrace::kDetailed); + + fprintf(stderr, "WARNING: Detected use of sync API\n"); + + for (int i = 0; i < stack->GetFrameCount() - 1; i++) { + Local stack_frame = stack->GetFrame(i); + node::Utf8Value fn_name_s(isolate(), stack_frame->GetFunctionName()); + node::Utf8Value script_name(isolate(), stack_frame->GetScriptName()); + const int line_number = stack_frame->GetLineNumber(); + const int column = stack_frame->GetColumn(); + + if (stack_frame->IsEval()) { + if (stack_frame->GetScriptId() == Message::kNoScriptIdInfo) { + fprintf(stderr, " at [eval]:%i:%i\n", line_number, column); + } else { + fprintf(stderr, + " at [eval] (%s:%i:%i)\n", + *script_name, + line_number, + column); + } + break; + } + + if (strcmp(*fn_name_s, "") == 0) { + fprintf(stderr, " at %s:%i:%i\n", *script_name, line_number, column); + } else { + fprintf(stderr, + " at %s (%s:%i:%i)\n", + *fn_name_s, + *script_name, + line_number, + column); + } + } + fflush(stderr); +} + +} // namespace node diff --git a/src/env.h b/src/env.h index e327786e36b907..265ef337fe4f8a 100644 --- a/src/env.h +++ b/src/env.h @@ -420,6 +420,9 @@ class Environment { inline bool printed_error() const; inline void set_printed_error(bool value); + void PrintSyncWarn() const; + inline void set_trace_sync_io(bool value); + inline void ThrowError(const char* errmsg); inline void ThrowTypeError(const char* errmsg); inline void ThrowRangeError(const char* errmsg); @@ -506,6 +509,7 @@ class Environment { bool using_abort_on_uncaught_exc_; bool using_asyncwrap_; bool printed_error_; + bool trace_sync_io_; debugger::Agent debugger_agent_; HandleWrapQueue handle_wrap_queue_; diff --git a/src/node.cc b/src/node.cc index 4cafe96f445dd1..16ea82b7964e66 100644 --- a/src/node.cc +++ b/src/node.cc @@ -102,6 +102,8 @@ using v8::Promise; using v8::PromiseRejectMessage; using v8::PropertyCallbackInfo; using v8::SealHandleScope; +using v8::StackFrame; +using v8::StackTrace; using v8::String; using v8::TryCatch; using v8::Uint32; @@ -114,6 +116,7 @@ static bool force_repl = false; static bool trace_deprecation = false; static bool throw_deprecation = false; static bool abort_on_uncaught_exception = false; +static bool trace_sync_io = false; static const char* eval_string = nullptr; static unsigned int preload_module_count = 0; static const char** preload_modules = nullptr; @@ -2834,6 +2837,13 @@ void SetupProcessObject(Environment* env, READONLY_PROPERTY(process, "traceDeprecation", True(env->isolate())); } + // --trace-sync-io + if (trace_sync_io) { + READONLY_PROPERTY(process, "traceSyncIO", True(env->isolate())); + // Don't env->set_trace_sync_io(true) because it will be enabled + // after LoadEnvironment() has run. + } + size_t exec_path_len = 2 * PATH_MAX; char* exec_path = new char[exec_path_len]; Local exec_path_value; @@ -3060,6 +3070,8 @@ static void PrintHelp() { " --throw-deprecation throw an exception anytime a deprecated " "function is used\n" " --trace-deprecation show stack traces on deprecations\n" + " --trace-sync-io show stack trace when use of sync IO\n" + " is detected after the first tick\n" " --v8-options print v8 command line options\n" #if defined(NODE_HAVE_I18N_SUPPORT) " --icu-data-dir=dir set ICU data load path to dir\n" @@ -3180,6 +3192,8 @@ static void ParseArgs(int* argc, no_deprecation = true; } else if (strcmp(arg, "--trace-deprecation") == 0) { trace_deprecation = true; + } else if (strcmp(arg, "--trace-sync-io") == 0) { + trace_sync_io = true; } else if (strcmp(arg, "--throw-deprecation") == 0) { throw_deprecation = true; } else if (strcmp(arg, "--abort-on-uncaught-exception") == 0 || @@ -3887,6 +3901,8 @@ static void StartNodeInstance(void* arg) { LoadEnvironment(env); + env->set_trace_sync_io(trace_sync_io); + // Enable debugger if (instance_data->use_debug_agent()) EnableDebug(env); @@ -3911,6 +3927,8 @@ static void StartNodeInstance(void* arg) { } while (more == true); } + env->set_trace_sync_io(false); + int exit_code = EmitExit(env); if (instance_data->is_main()) instance_data->set_exit_code(exit_code); diff --git a/src/node_crypto.cc b/src/node_crypto.cc index e49545810d3f78..f0bb1d35c9a8bf 100644 --- a/src/node_crypto.cc +++ b/src/node_crypto.cc @@ -4630,6 +4630,7 @@ void PBKDF2(const FunctionCallbackInfo& args) { EIO_PBKDF2, EIO_PBKDF2After); } else { + env->PrintSyncWarn(); Local argv[2]; EIO_PBKDF2(req); EIO_PBKDF2After(req, argv); @@ -4786,6 +4787,7 @@ void RandomBytes(const FunctionCallbackInfo& args) { RandomBytesAfter); args.GetReturnValue().Set(obj); } else { + env->PrintSyncWarn(); Local argv[2]; RandomBytesWork(req->work_req()); RandomBytesCheck(req, argv); diff --git a/src/node_file.cc b/src/node_file.cc index 095710ef37e32b..fb3bf00164acdf 100644 --- a/src/node_file.cc +++ b/src/node_file.cc @@ -280,6 +280,7 @@ struct fs_req_wrap { #define SYNC_DEST_CALL(func, path, dest, ...) \ fs_req_wrap req_wrap; \ + env->PrintSyncWarn(); \ int err = uv_fs_ ## func(env->event_loop(), \ &req_wrap.req, \ __VA_ARGS__, \ diff --git a/src/node_zlib.cc b/src/node_zlib.cc index 884c244f9f0afc..fa79afb5a9bac4 100644 --- a/src/node_zlib.cc +++ b/src/node_zlib.cc @@ -180,6 +180,7 @@ class ZCtx : public AsyncWrap { ctx->chunk_size_ = out_len; if (!async) { + ctx->env()->PrintSyncWarn(); // sync version Process(work_req); if (CheckError(ctx)) diff --git a/src/spawn_sync.cc b/src/spawn_sync.cc index 15e4fe8b103b0d..8804b36258016c 100644 --- a/src/spawn_sync.cc +++ b/src/spawn_sync.cc @@ -349,7 +349,9 @@ void SyncProcessRunner::Initialize(Handle target, void SyncProcessRunner::Spawn(const FunctionCallbackInfo& args) { - SyncProcessRunner p(Environment::GetCurrent(args)); + Environment* env = Environment::GetCurrent(args); + env->PrintSyncWarn(); + SyncProcessRunner p(env); Local result = p.Run(args[0]); args.GetReturnValue().Set(result); }