Skip to content

Commit

Permalink
core: implement runtime flag to trace sync io
Browse files Browse the repository at this point in the history
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: #1674
PR-URL: #1707
Reviewed-By: Ben Noordhuis <info@bnoordhuis.nl>
Reviewed-By: Fedor Indutny <fedor@indutny.com>
Reviewed-By: Jeremiah Senkpiel <fishrock123@rocketmail.com>
Reviewed-By: Petka Antonov <petka_antonov@hotmail.com>
  • Loading branch information
trevnorris committed May 18, 2015
1 parent 0662747 commit c1de6d2
Show file tree
Hide file tree
Showing 10 changed files with 137 additions and 1 deletion.
1 change: 1 addition & 0 deletions node.gyp
Original file line number Diff line number Diff line change
Expand Up @@ -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',
Expand Down
5 changes: 5 additions & 0 deletions src/env-inl.h
Original file line number Diff line number Diff line change
Expand Up @@ -176,6 +176,7 @@ inline Environment::Environment(v8::Local<v8::Context> 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.
Expand Down Expand Up @@ -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);
}
Expand Down
58 changes: 58 additions & 0 deletions src/env.cc
Original file line number Diff line number Diff line change
@@ -0,0 +1,58 @@
#include "env.h"
#include "env-inl.h"
#include "v8.h"
#include <stdio.h>

namespace node {

using v8::HandleScope;
using v8::Local;
using v8::Message;
using v8::StackFrame;
using v8::StackTrace;

void Environment::PrintSyncTrace() const {
if (!trace_sync_io_)
return;

HandleScope handle_scope(isolate());
Local<v8::StackTrace> 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<StackFrame> 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 (fn_name_s.length() == 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
4 changes: 4 additions & 0 deletions src/env.h
Original file line number Diff line number Diff line change
Expand Up @@ -420,6 +420,9 @@ class Environment {
inline bool printed_error() const;
inline void set_printed_error(bool value);

void PrintSyncTrace() 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);
Expand Down Expand Up @@ -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_;
Expand Down
18 changes: 18 additions & 0 deletions src/node.cc
Original file line number Diff line number Diff line change
Expand Up @@ -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;
Expand All @@ -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;
Expand Down Expand Up @@ -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<String> exec_path_value;
Expand Down Expand Up @@ -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"
Expand Down Expand Up @@ -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 ||
Expand Down Expand Up @@ -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);
Expand All @@ -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);
Expand Down
2 changes: 2 additions & 0 deletions src/node_crypto.cc
Original file line number Diff line number Diff line change
Expand Up @@ -4630,6 +4630,7 @@ void PBKDF2(const FunctionCallbackInfo<Value>& args) {
EIO_PBKDF2,
EIO_PBKDF2After);
} else {
env->PrintSyncTrace();
Local<Value> argv[2];
EIO_PBKDF2(req);
EIO_PBKDF2After(req, argv);
Expand Down Expand Up @@ -4786,6 +4787,7 @@ void RandomBytes(const FunctionCallbackInfo<Value>& args) {
RandomBytesAfter);
args.GetReturnValue().Set(obj);
} else {
env->PrintSyncTrace();
Local<Value> argv[2];
RandomBytesWork(req->work_req());
RandomBytesCheck(req, argv);
Expand Down
1 change: 1 addition & 0 deletions src/node_file.cc
Original file line number Diff line number Diff line change
Expand Up @@ -280,6 +280,7 @@ struct fs_req_wrap {

#define SYNC_DEST_CALL(func, path, dest, ...) \
fs_req_wrap req_wrap; \
env->PrintSyncTrace(); \
int err = uv_fs_ ## func(env->event_loop(), \
&req_wrap.req, \
__VA_ARGS__, \
Expand Down
1 change: 1 addition & 0 deletions src/node_zlib.cc
Original file line number Diff line number Diff line change
Expand Up @@ -181,6 +181,7 @@ class ZCtx : public AsyncWrap {

if (!async) {
// sync version
ctx->env()->PrintSyncTrace();
Process(work_req);
if (CheckError(ctx))
AfterSync(ctx, args);
Expand Down
4 changes: 3 additions & 1 deletion src/spawn_sync.cc
Original file line number Diff line number Diff line change
Expand Up @@ -349,7 +349,9 @@ void SyncProcessRunner::Initialize(Handle<Object> target,


void SyncProcessRunner::Spawn(const FunctionCallbackInfo<Value>& args) {
SyncProcessRunner p(Environment::GetCurrent(args));
Environment* env = Environment::GetCurrent(args);
env->PrintSyncTrace();
SyncProcessRunner p(env);
Local<Value> result = p.Run(args[0]);
args.GetReturnValue().Set(result);
}
Expand Down
44 changes: 44 additions & 0 deletions test/parallel/test-sync-io-option.js
Original file line number Diff line number Diff line change
@@ -0,0 +1,44 @@
'use strict';

const assert = require('assert');
const spawn = require('child_process').spawn;


if (process.argv[2] === 'child') {
setImmediate(function() {
require('fs').readFileSync(__filename);
process.exit();
});

} else {
(function runTest(flags) {
var execArgv = [flags.pop()];
var args = [__filename, 'child'];
var child = spawn(process.execPath, execArgv.concat(args));
var cntr = 0;

child.stdout.on('data', function(chunk) {
throw new Error('UNREACHABLE');
});

child.stderr.on('data', function(chunk) {
// Prints twice for --trace-sync-io. First for the require() and second
// for the fs operation.
if (/^WARNING[\s\S]*fs\.readFileSync/.test(chunk.toString()))
cntr++;
});

child.on('exit', function() {
if (execArgv[0] === '--trace-sync-io')
assert.equal(cntr, 2);
else if (execArgv[0] === ' ')
assert.equal(cntr, 0);
else
throw new Error('UNREACHABLE');

if (flags.length > 0)
setImmediate(runTest, flags);
});
}(['--trace-sync-io', ' ']));
}

0 comments on commit c1de6d2

Please sign in to comment.