Skip to content

Conversation

@trevnorris
Copy link
Contributor

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.

src/node.h Outdated
Copy link
ContributorAuthor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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

@trevnorristrevnorrisforce-pushed the flag-sync-methods branch 2 times, most recently from 8743a9f to 19e77d3CompareMay 14, 2015 22:53
@ChALkeR
Copy link
Member

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

@trevnorris
Copy link
ContributorAuthor

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

@trevnorristrevnorrisforce-pushed the flag-sync-methods branch 4 times, most recently from 80926f2 to 066f492CompareMay 15, 2015 02:19
@trevnorris
Copy link
ContributorAuthor

@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
Copy link
Contributor

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

src/env-inl.h Outdated
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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.

Copy link
ContributorAuthor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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.

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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.

Copy link
ContributorAuthor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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
Copy link
Contributor

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
Copy link
ContributorAuthor

@petkaantonov

The synchronous code has been run after LoadEnvironment

Great idea. Implemented that change.

@trevnorristrevnorris changed the title core: implement runtime flag to pring warn on synccore: implement runtime flag to print warn on syncMay 15, 2015
@trevnorristrevnorrisforce-pushed the flag-sync-methods branch 3 times, most recently from 8205884 to 347c94dCompareMay 15, 2015 08:38
src/node.cc Outdated
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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?

Copy link
ContributorAuthor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

ok then

Copy link
ContributorAuthor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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
Copy link
Contributor

LGTM with comments

@ChALkeR
Copy link
Member

Cross-linking: #1674

@petkaantonov
Copy link
Contributor

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
Copy link
ContributorAuthor

@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.

trevnorris added a commit to trevnorris/node that referenced this pull request May 18, 2015
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]>
trevnorris added a commit to trevnorris/node that referenced this pull request May 18, 2015
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]>
src/env.cc Outdated
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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

Copy link
ContributorAuthor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

done.

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
Copy link
Member

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
Copy link
Member

LGTM

@trevnorris
Copy link
ContributorAuthor

@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!

@trevnorristrevnorris merged commit c1de6d2 into nodejs:masterMay 18, 2015
@trevnorris
Copy link
ContributorAuthor

Thanks all. Landed in c1de6d2.

@benjamingr
Copy link
Member

Nice work, and thanks :)

@trevnorristrevnorris deleted the flag-sync-methods branch May 18, 2015 23:12
@silverwind
Copy link
Contributor

@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
Copy link
Member

Tentative fix @ #1734

@rvaggrvagg mentioned this pull request May 23, 2015
rvagg added a commit to rvagg/io.js that referenced this pull request May 23, 2015
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.
rvagg added a commit to rvagg/io.js that referenced this pull request May 23, 2015
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#1699nodejs#1768nodejs#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.
rvagg added a commit to rvagg/io.js that referenced this pull request May 23, 2015
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#1699nodejs#1768nodejs#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.
rvagg added a commit to rvagg/io.js that referenced this pull request May 24, 2015
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#1699nodejs#1768nodejs#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.
rvagg added a commit that referenced this pull request May 24, 2015
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.
andrewdeandrade pushed a commit to andrewdeandrade/node that referenced this pull request Jun 3, 2015
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]>
Sign up for freeto join this conversation on GitHub. Already have an account? Sign in to comment

Labels

semver-minorPRs that contain new features and should be released in the next minor version.

Projects

None yet

Development

Successfully merging this pull request may close these issues.

11 participants

@trevnorris@ChALkeR@Fishrock123@petkaantonov@CrabDude@bnoordhuis@benjamingr@indutny@silverwind@santigimeno@rlidwka