core: implement runtime flag to print warn on sync #1707

trevnorris · 2015-05-14T22:30:19Z

Use the --warn-on-sync flag to print a stack trace whenever a sync
method is used. (e.g. fs.readFileSync()) It does not track if the
warning has occurred as a specific location in the past and so will
print the warning every time the function is used.

This does not print the warning for the first synchronous execution of
the script. This will allow all the require(), etc. statements to run
that are necessary to prepare the environment.

NOTE: I believe I've addressed all applicable sync calls that should warn the user. I will not be enabling the warning for the 'net' module's .listen() calls that exclude the callback. Because the calls are actually synchronous under the hood and we simply queue the callback asynchronously to be run. It also appears to be the same for http.{get,request}(). Also calls to any stream's .write() are still async even if the callback is excluded.

Opening this up now so we can have further discussion.

trevnorris · 2015-05-14T22:30:58Z

src/node.h

@@ -335,6 +335,9 @@ NODE_DEPRECATED("Use DecodeWrite(isolate, ...)",
  return DecodeWrite(v8::Isolate::GetCurrent(), buf, buflen, val, encoding);
 })

+
+void PrintSyncWarning(Environment* env);


@bnoordhuis I'm pretty sure node.h isn't the correct place for this, but wasn't sure where else to place it.

ChALkeR · 2015-05-14T23:21:03Z

Does this handle Zlib.writeSync (https://github.com/iojs/io.js/blob/v2.0.1/src/node_zlib.cc#L182)?

trevnorris · 2015-05-15T01:53:30Z

@ChALkeR Thanks. Figured I'd missed some. I'll add that.

trevnorris · 2015-05-15T02:19:38Z

@ChALkeR Added.

@iojs/tc I've updated the implementation to store the needed value on Environment to avoid exposing it through node.h. I believe all sync methods have been dealt with. The implementation to pass a callback to JS to enable warnings in nextTick() was the only way I could figure to enable it directly after the synchronous section of code ran. Thoughts on adding this flag?

Fishrock123 · 2015-05-15T02:44:18Z

I think this could be useful. 👍
No comment on impl details.

petkaantonov · 2015-05-15T06:01:15Z

src/env-inl.h

+      isolate_, 10, v8::StackTrace::kDetailed);
+
+  fprintf(stderr, "WARNING: Detected use of sync API\n");
+  for (int i = 0; i < stack->GetFrameCount() - 1; i++) {


Could we use Message::PrintCurrentStackTrace(isolate_, stderr) so that v8 does the formatting? Since it's pretty complicated when you start to handle evals, constructors etc.

That would make things much easier. Though there's a slight style issue that doesn't sit well with me. Here's an example output:

WARNING: Detected use of sync API pbkdf2 (crypto.js:592:20) Object.exports.pbkdf2Sync (crypto.js:583:10) null._onTimeout (/tmp/x.js:8:10) Timer.listOnTimeout (timers.js:89:15)

I would prefer the stack trace to look more like an error's stack trace with at at the beginning of each line. But reimplementing the entire formatting would be a pain. I have the change ready and waiting but would like your thoughts on this before I push it up.

oh I expected it to be in same format as you would get when doing new Error().stack or Error.captureStackTrace in javascript. Another option would be to call into javascript to get a formatted stack trace.

Yeah. I see how complex the formatting is for the stack trace in CallSiteToString() in deps/v8/src/message.js.

@bnoordhuis If we were to call to JS, what would be the best way to do that from an env function?

petkaantonov · 2015-05-15T06:11:39Z

The implementation to pass a callback to JS to enable warnings in nextTick() was the only way I could figure to enable it directly after the synchronous section of code ran

The synchronous code has been run after LoadEnvironment so you could do this instead:

diff --git a/src/node.cc b/src/node.cc
index 4cafe96..8dec8da 100644
--- a/src/node.cc
+++ b/src/node.cc
@@ -3887,6 +3887,9 @@ static void StartNodeInstance(void* arg) {

     LoadEnvironment(env);

+    if (warn_on_sync)
+      env->set_warn_on_sync(true);
+
     // Enable debugger
     if (instance_data->use_debug_agent())
       EnableDebug(env);

trevnorris · 2015-05-15T08:32:59Z

@petkaantonov

The synchronous code has been run after LoadEnvironment

Great idea. Implemented that change.

petkaantonov · 2015-05-15T08:41:00Z

src/node.cc

@@ -2834,6 +2837,13 @@ void SetupProcessObject(Environment* env,
    READONLY_PROPERTY(process, "traceDeprecation", True(env->isolate()));
  }

+  // --warn-on-sync
+  if (warn_on_sync) {
+    READONLY_PROPERTY(process, "warnOnSync", True(env->isolate()));


It seems weird that this property is always either true or doesn't exist, should it just always be defined as either true or false?

I'm just following the current implementation for all other properties of this type, e.g. process.traceDeprecation.

though you're right. a PR to conditionally set those would be fairly trivial. i'll put that on my list, unless you get to it first. :)

petkaantonov · 2015-05-15T08:42:30Z

LGTM with comments

ChALkeR · 2015-05-15T09:11:54Z

Cross-linking: #1674

petkaantonov · 2015-05-15T09:48:24Z

Almost forgot, there should be env->set_warn_on_sync(false) before the EmitExit line so that using synchronous code doesn't emit a warning when done inside "exit" event (async code doesn't run at that point)

trevnorris · 2015-05-15T10:02:00Z

@petkaantonov Good call. Also I analyzed the stack trace formatting that V8 uses and matched it as closely as possible using the available C++ API. I think that will be good enough for now.

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: nodejs#1674 PR-URL: nodejs#1707 Reviewed-By: Ben Noordhuis <[email protected]> Reviewed-By: Fedor Indutny <[email protected]> Reviewed-By: Jeremiah Senkpiel <[email protected]> Reviewed-By: Petka Antonov <[email protected]>

indutny · 2015-05-18T16:02:09Z

src/env.cc

+      break;
+    }
+
+    if (strcmp(*fn_name_s, "") == 0) {


I wonder if we could use fn_name_s.length() here ;)

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: nodejs#1674 PR-URL: nodejs#1707 Reviewed-By: Ben Noordhuis <[email protected]> Reviewed-By: Fedor Indutny <[email protected]> Reviewed-By: Jeremiah Senkpiel <[email protected]> Reviewed-By: Petka Antonov <[email protected]>

benjamingr · 2015-05-18T16:17:37Z

Related to the code conversation - I think the performance of printing the trace is mostly irrelevant anyway @trevnorris - we expect this to log very rarely and never in production anyway. I'm not even sure that it's a bad idea to flush it at every iteration. Don't be so hard on yourself :)

Related to the name - are we OK with --trace-sync-io? I might be not understanding the test in the PR but didn't we only want to log IO after the first iteration?

On an unrelated hook - it might be interesting to find out if there is a need to expose sync io detected events on process, but I haven't come up with a convincing use case yet (well, tools that monitor your app in general and give you feedback on it could use it, but that's about it). I'll open a separate issue after this PR is merged so it can be discussed.

Good work by the way.

indutny · 2015-05-18T16:19:04Z

LGTM

trevnorris · 2015-05-18T16:24:26Z

@benjamingr What I was taking about is that I return if one of the stack trace lines was ever an [eval]. Which would only have ever left a partial stack trace. That was just a plainly stupid oversight on my part.

It does only print after the first "phase" (not "tick" as in nextTick() as explained above) but it also won't print during the process 'exit' event. Thus getting a name to fully explain what was happening was complicated. Instead we opted for the shorter name and a better description.

@indutny thanks!

trevnorris · 2015-05-18T16:25:28Z

Thanks all. Landed in c1de6d2.

benjamingr · 2015-05-18T16:45:32Z

Nice work, and thanks :)

silverwind · 2015-05-19T12:24:19Z

@trevnorris seems the new test added here fails on a few platforms:

https://jenkins-iojs.nodesource.com/view/iojs/job/iojs+any-pr+multi/686/

not ok 637 - test-sync-io-option.js
# 
# assert.js:88
# throw new assert.AssertionError({
# ^
# AssertionError: 0 == 2
# at ChildProcess.<anonymous> (/home/iojs/build/workspace/iojs+any-pr+multi/nodes/ubuntu1404-64/test/parallel/test-sync-io-option.js:33:16)
# at emitTwo (events.js:87:13)
# at ChildProcess.emit (events.js:172:7)
# at Process.ChildProcess._handle.onexit (child_process.js:1009:12)

santigimeno · 2015-05-19T12:38:11Z

Tentative fix @ #1734

PR-URL: nodejs#1532 Notable Changes: * crypto: Diffie-Hellman key exchange (DHE) parameters ('dhparams') must now be 1024 bits or longer or an error will be thrown. A warning will also be printed to the console if you supply less than 2048 bits. See https://weakdh.org/ for further context on this security concern. (Shigeki Ohtsu) nodejs#1739. * node: A new --trace-sync-io command line flag will print a warning and a stack trace whenever a synchronous API is used. This can be used to track down synchronous calls that may be slowing down an application. (Trevor Norris) nodejs#1707. * node: To allow for chaining of methods, the setTimeout(), setKeepAlive(), setNoDelay(), ref() and unref() methods used in 'net', 'dgram', 'http', 'https' and 'tls' now return the current instance instead of undefined (Roman Reiss) nodejs#1779. * util: A significant speed-up (in the order of 35%) for the common-case of a single string argument to util.format(), used by console.log() (Сковорода Никита Андреевич) nodejs#1749.

PR-URL: nodejs#1532 Notable Changes: * crypto: Diffie-Hellman key exchange (DHE) parameters ('dhparams') must now be 1024 bits or longer or an error will be thrown. A warning will also be printed to the console if you supply less than 2048 bits. See https://weakdh.org/ for further context on this security concern. (Shigeki Ohtsu) nodejs#1739. * node: A new --trace-sync-io command line flag will print a warning and a stack trace whenever a synchronous API is used. This can be used to track down synchronous calls that may be slowing down an application. (Trevor Norris) nodejs#1707. * node: To allow for chaining of methods, the setTimeout(), setKeepAlive(), setNoDelay(), ref() and unref() methods used in 'net', 'dgram', 'http', 'https' and 'tls' now return the current instance instead of undefined (Roman Reiss & Evan Lucas) nodejs#1699 nodejs#1768 nodejs#1779. * util: A significant speed-up (in the order of 35%) for the common-case of a single string argument to util.format(), used by console.log() (Сковорода Никита Андреевич) nodejs#1749.

PR-URL: nodejs#1532 Notable Changes: * crypto: Diffie-Hellman key exchange (DHE) parameters ('dhparams') must now be 1024 bits or longer or an error will be thrown. A warning will also be printed to the console if you supply less than 2048 bits. See https://weakdh.org/ for further context on this security concern. (Shigeki Ohtsu) nodejs#1739. * node: A new --trace-sync-io command line flag will print a warning and a stack trace whenever a synchronous API is used. This can be used to track down synchronous calls that may be slowing down an application. (Trevor Norris) nodejs#1707. * node: To allow for chaining of methods, the setTimeout(), setKeepAlive(), setNoDelay(), ref() and unref() methods used in 'net', 'dgram', 'http', 'https' and 'tls' now return the current instance instead of undefined (Roman Reiss & Evan Lucas) nodejs#1699 nodejs#1768 nodejs#1779. * npm: Upgraded to v2.10.1, release notes can be found in https://github.com/npm/npm/releases/tag/v2.10.1 and https://github.com/npm/npm/releases/tag/v2.10.0. * util: A significant speed-up (in the order of 35%) for the common-case of a single string argument to util.format(), used by console.log() (Сковорода Никита Андреевич) nodejs#1749.

PR-URL: #1777 Notable Changes: * crypto: Diffie-Hellman key exchange (DHE) parameters ('dhparams') must now be 1024 bits or longer or an error will be thrown. A warning will also be printed to the console if you supply less than 2048 bits. See https://weakdh.org/ for further context on this security concern. (Shigeki Ohtsu) #1739. * node: A new --trace-sync-io command line flag will print a warning and a stack trace whenever a synchronous API is used. This can be used to track down synchronous calls that may be slowing down an application. (Trevor Norris) #1707. * node: To allow for chaining of methods, the setTimeout(), setKeepAlive(), setNoDelay(), ref() and unref() methods used in 'net', 'dgram', 'http', 'https' and 'tls' now return the current instance instead of undefined (Roman Reiss & Evan Lucas) #1699 #1768 #1779. * npm: Upgraded to v2.10.1, release notes can be found in https://github.com/npm/npm/releases/tag/v2.10.1 and https://github.com/npm/npm/releases/tag/v2.10.0. * util: A significant speed-up (in the order of 35%) for the common-case of a single string argument to util.format(), used by console.log() (Сковорода Никита Андреевич) #1749.

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: nodejs/node#1674 PR-URL: nodejs/node#1707 Reviewed-By: Ben Noordhuis <[email protected]> Reviewed-By: Fedor Indutny <[email protected]> Reviewed-By: Jeremiah Senkpiel <[email protected]> Reviewed-By: Petka Antonov <[email protected]>

trevnorris reviewed May 14, 2015
View reviewed changes

trevnorris force-pushed the flag-sync-methods branch 2 times, most recently from 8743a9f to 19e77d3 Compare May 14, 2015 22:53

trevnorris force-pushed the flag-sync-methods branch 4 times, most recently from 80926f2 to 066f492 Compare May 15, 2015 02:19

trevnorris force-pushed the flag-sync-methods branch from 066f492 to d1e1744 Compare May 15, 2015 02:25

petkaantonov reviewed May 15, 2015
View reviewed changes

trevnorris force-pushed the flag-sync-methods branch from d1e1744 to 343fc0e Compare May 15, 2015 08:32

trevnorris changed the title ~~core: implement runtime flag to pring warn on sync~~ core: implement runtime flag to print warn on sync May 15, 2015

trevnorris force-pushed the flag-sync-methods branch 3 times, most recently from 8205884 to 347c94d Compare May 15, 2015 08:38

petkaantonov reviewed May 15, 2015
View reviewed changes

trevnorris force-pushed the flag-sync-methods branch from 347c94d to 7d1474e Compare May 15, 2015 08:44

This was referenced May 15, 2015

Put *Sync methods behind a flag in some future major version #1665

Closed

Provide a --warn-on-late-sync flag for tracing synchronous calls #1674

Closed

trevnorris force-pushed the flag-sync-methods branch from 7d1474e to c6ea43d Compare May 15, 2015 10:00

trevnorris force-pushed the flag-sync-methods branch from 2c715a6 to dd6f71a Compare May 18, 2015 15:58

indutny reviewed May 18, 2015
View reviewed changes

trevnorris force-pushed the flag-sync-methods branch from dd6f71a to c1de6d2 Compare May 18, 2015 16:05

trevnorris merged commit c1de6d2 into nodejs:master May 18, 2015

trevnorris deleted the flag-sync-methods branch May 18, 2015 23:12

silverwind mentioned this pull request May 19, 2015

test: enable linting for tests and fix tests #1721

Closed

rvagg mentioned this pull request May 23, 2015

Release proposal v2.1.0 #1777

Closed

This was referenced Feb 10, 2017

Cache file system operations browserslist/browserslist#116

Merged

FS caching improvements babel/babel-loader#375

Merged

Config caching babel/babel#5292

Closed

This was referenced Jul 31, 2019

buffer: add Buffer.harden() method #28439

Closed

--trace-sync-io regression between v10.10 and v10.11 #28913

Closed

snyk-bot mentioned this pull request Apr 2, 2021

[Snyk] Security upgrade snyk from 1.437.3 to 1.518.0 turkdevops/node#241

Closed

snyk-bot mentioned this pull request Aug 24, 2021

[Snyk] Security upgrade snyk from 1.437.3 to 1.518.0 turkdevops/node#317

Closed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

core: implement runtime flag to print warn on sync #1707

core: implement runtime flag to print warn on sync #1707

trevnorris commented May 14, 2015

trevnorris May 14, 2015

ChALkeR commented May 14, 2015

trevnorris commented May 15, 2015

trevnorris commented May 15, 2015

Fishrock123 commented May 15, 2015

petkaantonov May 15, 2015

trevnorris May 15, 2015

petkaantonov May 15, 2015

trevnorris May 15, 2015

petkaantonov commented May 15, 2015

trevnorris commented May 15, 2015

petkaantonov May 15, 2015

trevnorris May 15, 2015

petkaantonov May 15, 2015

trevnorris May 15, 2015

petkaantonov commented May 15, 2015

ChALkeR commented May 15, 2015

petkaantonov commented May 15, 2015

trevnorris commented May 15, 2015

indutny May 18, 2015

trevnorris May 18, 2015

benjamingr commented May 18, 2015

indutny commented May 18, 2015

trevnorris commented May 18, 2015

trevnorris commented May 18, 2015

benjamingr commented May 18, 2015

silverwind commented May 19, 2015

santigimeno commented May 19, 2015

core: implement runtime flag to print warn on sync #1707

core: implement runtime flag to print warn on sync #1707

Conversation

trevnorris commented May 14, 2015

Choose a reason for hiding this comment

ChALkeR commented May 14, 2015

trevnorris commented May 15, 2015

trevnorris commented May 15, 2015

Fishrock123 commented May 15, 2015

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

petkaantonov commented May 15, 2015

trevnorris commented May 15, 2015

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

petkaantonov commented May 15, 2015

ChALkeR commented May 15, 2015

petkaantonov commented May 15, 2015

trevnorris commented May 15, 2015

Choose a reason for hiding this comment

Choose a reason for hiding this comment

benjamingr commented May 18, 2015

indutny commented May 18, 2015

trevnorris commented May 18, 2015

trevnorris commented May 18, 2015

benjamingr commented May 18, 2015

silverwind commented May 19, 2015

santigimeno commented May 19, 2015