Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

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

Closed
ChALkeR opened this issue Jul 31, 2019 · 3 comments
Closed

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

ChALkeR opened this issue Jul 31, 2019 · 3 comments
Labels
lib / src Issues and PRs related to general changes in the lib or src directory. regression Issues related to regressions.

Comments

@ChALkeR
Copy link
Member

ChALkeR commented Jul 31, 2019 •
edited
Loading

  • Version: 10.11, 10.16.0, 12.7.0, v13.0.0-pre (master)
  • Platform: Darwin MacBook-ChALkeR.local 18.5.0 Darwin Kernel Version 18.5.0: Mon Mar 11 20:40:32 PDT 2019; root:xnu-4903.251.3~3/RELEASE_X86_64 x86_64
  • Subsystem: lib/src

--trace-sync-io is not expected to produce output before the first tick, and is not expected to print things when the source file does not trigger sync io. Both expectations fail now.

Examples:

Nothing

// Nothing

Expected, v10.10.0: nothing, .

Obtained (v10.11.0, v12.7.0 is almost equivalent with trace differences):

Click to expand
(node:18126) WARNING: Detected use of sync API
    at realpathSync (fs.js:1434:29)
    at toRealPath (internal/modules/cjs/loader.js:202:13)
    at Module._findPath (internal/modules/cjs/loader.js:268:22)
    at Module._resolveFilename (internal/modules/cjs/loader.js:578:25)
    at Module._load (internal/modules/cjs/loader.js:507:25)
    at Module.runMain (internal/modules/cjs/loader.js:742:12)
    at startup (internal/bootstrap/node.js:279:19)
(node:18126) WARNING: Detected use of sync API
    at realpathSync (fs.js:1434:29)
    at toRealPath (internal/modules/cjs/loader.js:202:13)
    at Module._findPath (internal/modules/cjs/loader.js:268:22)
    at Module._resolveFilename (internal/modules/cjs/loader.js:578:25)
    at Module._load (internal/modules/cjs/loader.js:507:25)
    at Module.runMain (internal/modules/cjs/loader.js:742:12)
    at startup (internal/bootstrap/node.js:279:19)
(node:18126) WARNING: Detected use of sync API
    at realpathSync (fs.js:1434:29)
    at toRealPath (internal/modules/cjs/loader.js:202:13)
    at Module._findPath (internal/modules/cjs/loader.js:268:22)
    at Module._resolveFilename (internal/modules/cjs/loader.js:578:25)
    at Module._load (internal/modules/cjs/loader.js:507:25)
    at Module.runMain (internal/modules/cjs/loader.js:742:12)
    at startup (internal/bootstrap/node.js:279:19)
(node:18126) WARNING: Detected use of sync API
    at realpathSync (fs.js:1434:29)
    at toRealPath (internal/modules/cjs/loader.js:202:13)
    at Module._findPath (internal/modules/cjs/loader.js:268:22)
    at Module._resolveFilename (internal/modules/cjs/loader.js:578:25)
    at Module._load (internal/modules/cjs/loader.js:507:25)
    at Module.runMain (internal/modules/cjs/loader.js:742:12)
    at startup (internal/bootstrap/node.js:279:19)
(node:18126) WARNING: Detected use of sync API
    at realpathSync (fs.js:1434:29)
    at toRealPath (internal/modules/cjs/loader.js:202:13)
    at Module._findPath (internal/modules/cjs/loader.js:268:22)
    at Module._resolveFilename (internal/modules/cjs/loader.js:578:25)
    at Module._load (internal/modules/cjs/loader.js:507:25)
    at Module.runMain (internal/modules/cjs/loader.js:742:12)
    at startup (internal/bootstrap/node.js:279:19)
(node:18126) WARNING: Detected use of sync API
    at openSync (fs.js:433:26)
    at readFileSync (fs.js:341:35)
    at Module._extensions..js (internal/modules/cjs/loader.js:699:20)
    at Module.load (internal/modules/cjs/loader.js:599:32)
    at tryModuleLoad (internal/modules/cjs/loader.js:538:12)
    at Module._load (internal/modules/cjs/loader.js:530:3)
    at Module.runMain (internal/modules/cjs/loader.js:742:12)
    at startup (internal/bootstrap/node.js:279:19)
(node:18126) WARNING: Detected use of sync API
    at tryStatSync (fs.js:303:25)
    at readFileSync (fs.js:343:17)
    at Module._extensions..js (internal/modules/cjs/loader.js:699:20)
    at Module.load (internal/modules/cjs/loader.js:599:32)
    at tryModuleLoad (internal/modules/cjs/loader.js:538:12)
    at Module._load (internal/modules/cjs/loader.js:530:3)
    at Module.runMain (internal/modules/cjs/loader.js:742:12)
    at startup (internal/bootstrap/node.js:279:19)
(node:18126) WARNING: Detected use of sync API
    at readSync (fs.js:489:26)
    at tryReadSync (fs.js:330:20)
    at readFileSync (fs.js:367:19)
    at Module._extensions..js (internal/modules/cjs/loader.js:699:20)
    at Module.load (internal/modules/cjs/loader.js:599:32)
    at tryModuleLoad (internal/modules/cjs/loader.js:538:12)
    at Module._load (internal/modules/cjs/loader.js:530:3)
    at Module.runMain (internal/modules/cjs/loader.js:742:12)
    at startup (internal/bootstrap/node.js:279:19)
(node:18126) WARNING: Detected use of sync API
    at closeSync (fs.js:400:11)
    at readFileSync (fs.js:376:8)
    at Module._extensions..js (internal/modules/cjs/loader.js:699:20)
    at Module.load (internal/modules/cjs/loader.js:599:32)
    at tryModuleLoad (internal/modules/cjs/loader.js:538:12)
    at Module._load (internal/modules/cjs/loader.js:530:3)
    at Module.runMain (internal/modules/cjs/loader.js:742:12)
    at startup (internal/bootstrap/node.js:279:19)

No output expected

const fs = require('fs');
fs.statSync(process.argv[0])

Expected, v10.10: nothing, .

Obtained (v10.11.0, v12.7.0 is almost equivalent with trace differences):

Click to expand
(node:18792) WARNING: Detected use of sync API
    at realpathSync (fs.js:1434:29)
    at toRealPath (internal/modules/cjs/loader.js:202:13)
    at Module._findPath (internal/modules/cjs/loader.js:268:22)
    at Module._resolveFilename (internal/modules/cjs/loader.js:578:25)
    at Module._load (internal/modules/cjs/loader.js:507:25)
    at Module.runMain (internal/modules/cjs/loader.js:742:12)
    at startup (internal/bootstrap/node.js:279:19)
(node:18792) WARNING: Detected use of sync API
    at realpathSync (fs.js:1434:29)
    at toRealPath (internal/modules/cjs/loader.js:202:13)
    at Module._findPath (internal/modules/cjs/loader.js:268:22)
    at Module._resolveFilename (internal/modules/cjs/loader.js:578:25)
    at Module._load (internal/modules/cjs/loader.js:507:25)
    at Module.runMain (internal/modules/cjs/loader.js:742:12)
    at startup (internal/bootstrap/node.js:279:19)
(node:18792) WARNING: Detected use of sync API
    at realpathSync (fs.js:1434:29)
    at toRealPath (internal/modules/cjs/loader.js:202:13)
    at Module._findPath (internal/modules/cjs/loader.js:268:22)
    at Module._resolveFilename (internal/modules/cjs/loader.js:578:25)
    at Module._load (internal/modules/cjs/loader.js:507:25)
    at Module.runMain (internal/modules/cjs/loader.js:742:12)
    at startup (internal/bootstrap/node.js:279:19)
(node:18792) WARNING: Detected use of sync API
    at realpathSync (fs.js:1434:29)
    at toRealPath (internal/modules/cjs/loader.js:202:13)
    at Module._findPath (internal/modules/cjs/loader.js:268:22)
    at Module._resolveFilename (internal/modules/cjs/loader.js:578:25)
    at Module._load (internal/modules/cjs/loader.js:507:25)
    at Module.runMain (internal/modules/cjs/loader.js:742:12)
    at startup (internal/bootstrap/node.js:279:19)
(node:18792) WARNING: Detected use of sync API
    at realpathSync (fs.js:1434:29)
    at toRealPath (internal/modules/cjs/loader.js:202:13)
    at Module._findPath (internal/modules/cjs/loader.js:268:22)
    at Module._resolveFilename (internal/modules/cjs/loader.js:578:25)
    at Module._load (internal/modules/cjs/loader.js:507:25)
    at Module.runMain (internal/modules/cjs/loader.js:742:12)
    at startup (internal/bootstrap/node.js:279:19)
(node:18792) WARNING: Detected use of sync API
    at openSync (fs.js:433:26)
    at readFileSync (fs.js:341:35)
    at Module._extensions..js (internal/modules/cjs/loader.js:699:20)
    at Module.load (internal/modules/cjs/loader.js:599:32)
    at tryModuleLoad (internal/modules/cjs/loader.js:538:12)
    at Module._load (internal/modules/cjs/loader.js:530:3)
    at Module.runMain (internal/modules/cjs/loader.js:742:12)
    at startup (internal/bootstrap/node.js:279:19)
(node:18792) WARNING: Detected use of sync API
    at tryStatSync (fs.js:303:25)
    at readFileSync (fs.js:343:17)
    at Module._extensions..js (internal/modules/cjs/loader.js:699:20)
    at Module.load (internal/modules/cjs/loader.js:599:32)
    at tryModuleLoad (internal/modules/cjs/loader.js:538:12)
    at Module._load (internal/modules/cjs/loader.js:530:3)
    at Module.runMain (internal/modules/cjs/loader.js:742:12)
    at startup (internal/bootstrap/node.js:279:19)
(node:18792) WARNING: Detected use of sync API
    at readSync (fs.js:489:26)
    at tryReadSync (fs.js:330:20)
    at readFileSync (fs.js:359:19)
    at Module._extensions..js (internal/modules/cjs/loader.js:699:20)
    at Module.load (internal/modules/cjs/loader.js:599:32)
    at tryModuleLoad (internal/modules/cjs/loader.js:538:12)
    at Module._load (internal/modules/cjs/loader.js:530:3)
    at Module.runMain (internal/modules/cjs/loader.js:742:12)
    at startup (internal/bootstrap/node.js:279:19)
(node:18792) WARNING: Detected use of sync API
    at closeSync (fs.js:400:11)
    at readFileSync (fs.js:376:8)
    at Module._extensions..js (internal/modules/cjs/loader.js:699:20)
    at Module.load (internal/modules/cjs/loader.js:599:32)
    at tryModuleLoad (internal/modules/cjs/loader.js:538:12)
    at Module._load (internal/modules/cjs/loader.js:530:3)
    at Module.runMain (internal/modules/cjs/loader.js:742:12)
    at startup (internal/bootstrap/node.js:279:19)
(node:18792) WARNING: Detected use of sync API
    at statSync (fs.js:827:25)
    at /Users/chalker/repo/node/4.js:2:4
    at Module._compile (internal/modules/cjs/loader.js:689:30)
    at Module._extensions..js (internal/modules/cjs/loader.js:700:10)
    at Module.load (internal/modules/cjs/loader.js:599:32)
    at tryModuleLoad (internal/modules/cjs/loader.js:538:12)
    at Module._load (internal/modules/cjs/loader.js:530:3)
    at Module.runMain (internal/modules/cjs/loader.js:742:12)
    at startup (internal/bootstrap/node.js:279:19)

Note how statSync call is also included (it shouldn't be), this is not just the garbage in the front.

Some output expected

const fs = require('fs');
setTimeout(() => {
  fs.statSync(process.argv[0])
}, 100)

Expected, v10.10:

(node:17902) WARNING: Detected use of sync API
    at statSync (fs.js:827:25)
    at setTimeout (/Users/chalker/repo/node/4.js:3:6)
    at ontimeout (timers.js:425:11)
    at tryOnTimeout (timers.js:289:5)
    at listOnTimeout (timers.js:252:5)

Obtained (v10.11.0, v12.7.0 is almost equivalent with trace differences):

Click to expand
(node:18815) WARNING: Detected use of sync API
    at realpathSync (fs.js:1434:29)
    at toRealPath (internal/modules/cjs/loader.js:202:13)
    at Module._findPath (internal/modules/cjs/loader.js:268:22)
    at Module._resolveFilename (internal/modules/cjs/loader.js:578:25)
    at Module._load (internal/modules/cjs/loader.js:507:25)
    at Module.runMain (internal/modules/cjs/loader.js:742:12)
    at startup (internal/bootstrap/node.js:279:19)
(node:18815) WARNING: Detected use of sync API
    at realpathSync (fs.js:1434:29)
    at toRealPath (internal/modules/cjs/loader.js:202:13)
    at Module._findPath (internal/modules/cjs/loader.js:268:22)
    at Module._resolveFilename (internal/modules/cjs/loader.js:578:25)
    at Module._load (internal/modules/cjs/loader.js:507:25)
    at Module.runMain (internal/modules/cjs/loader.js:742:12)
    at startup (internal/bootstrap/node.js:279:19)
(node:18815) WARNING: Detected use of sync API
    at realpathSync (fs.js:1434:29)
    at toRealPath (internal/modules/cjs/loader.js:202:13)
    at Module._findPath (internal/modules/cjs/loader.js:268:22)
    at Module._resolveFilename (internal/modules/cjs/loader.js:578:25)
    at Module._load (internal/modules/cjs/loader.js:507:25)
    at Module.runMain (internal/modules/cjs/loader.js:742:12)
    at startup (internal/bootstrap/node.js:279:19)
(node:18815) WARNING: Detected use of sync API
    at realpathSync (fs.js:1434:29)
    at toRealPath (internal/modules/cjs/loader.js:202:13)
    at Module._findPath (internal/modules/cjs/loader.js:268:22)
    at Module._resolveFilename (internal/modules/cjs/loader.js:578:25)
    at Module._load (internal/modules/cjs/loader.js:507:25)
    at Module.runMain (internal/modules/cjs/loader.js:742:12)
    at startup (internal/bootstrap/node.js:279:19)
(node:18815) WARNING: Detected use of sync API
    at realpathSync (fs.js:1434:29)
    at toRealPath (internal/modules/cjs/loader.js:202:13)
    at Module._findPath (internal/modules/cjs/loader.js:268:22)
    at Module._resolveFilename (internal/modules/cjs/loader.js:578:25)
    at Module._load (internal/modules/cjs/loader.js:507:25)
    at Module.runMain (internal/modules/cjs/loader.js:742:12)
    at startup (internal/bootstrap/node.js:279:19)
(node:18815) WARNING: Detected use of sync API
    at openSync (fs.js:433:26)
    at readFileSync (fs.js:341:35)
    at Module._extensions..js (internal/modules/cjs/loader.js:699:20)
    at Module.load (internal/modules/cjs/loader.js:599:32)
    at tryModuleLoad (internal/modules/cjs/loader.js:538:12)
    at Module._load (internal/modules/cjs/loader.js:530:3)
    at Module.runMain (internal/modules/cjs/loader.js:742:12)
    at startup (internal/bootstrap/node.js:279:19)
(node:18815) WARNING: Detected use of sync API
    at tryStatSync (fs.js:303:25)
    at readFileSync (fs.js:343:17)
    at Module._extensions..js (internal/modules/cjs/loader.js:699:20)
    at Module.load (internal/modules/cjs/loader.js:599:32)
    at tryModuleLoad (internal/modules/cjs/loader.js:538:12)
    at Module._load (internal/modules/cjs/loader.js:530:3)
    at Module.runMain (internal/modules/cjs/loader.js:742:12)
    at startup (internal/bootstrap/node.js:279:19)
(node:18815) WARNING: Detected use of sync API
    at readSync (fs.js:489:26)
    at tryReadSync (fs.js:330:20)
    at readFileSync (fs.js:359:19)
    at Module._extensions..js (internal/modules/cjs/loader.js:699:20)
    at Module.load (internal/modules/cjs/loader.js:599:32)
    at tryModuleLoad (internal/modules/cjs/loader.js:538:12)
    at Module._load (internal/modules/cjs/loader.js:530:3)
    at Module.runMain (internal/modules/cjs/loader.js:742:12)
    at startup (internal/bootstrap/node.js:279:19)
(node:18815) WARNING: Detected use of sync API
    at closeSync (fs.js:400:11)
    at readFileSync (fs.js:376:8)
    at Module._extensions..js (internal/modules/cjs/loader.js:699:20)
    at Module.load (internal/modules/cjs/loader.js:599:32)
    at tryModuleLoad (internal/modules/cjs/loader.js:538:12)
    at Module._load (internal/modules/cjs/loader.js:530:3)
    at Module.runMain (internal/modules/cjs/loader.js:742:12)
    at startup (internal/bootstrap/node.js:279:19)
(node:18815) WARNING: Detected use of sync API
    at statSync (fs.js:827:25)
    at setTimeout (/Users/chalker/repo/node/4.js:3:6)
    at ontimeout (timers.js:425:11)
    at tryOnTimeout (timers.js:289:5)
    at listOnTimeout (timers.js:252:5)

Refs: #1707
@ChALkeR ChALkeR added the lib / src Issues and PRs related to general changes in the lib or src directory. label Jul 31, 2019
@ChALkeR ChALkeR mentioned this issue Jul 31, 2019
Closed
4 tasks
@ChALkeR
Copy link
Member Author

ChALkeR commented Aug 1, 2019

I will take a closer look

@ChALkeR
Copy link
Member Author

ChALkeR commented Aug 1, 2019

Bisect shows that --trace-sync-io was broken by 7fa5f54, ref: #22726.

7fa5f54 is the first bad commit

/cc @danbev

@ChALkeR ChALkeR added the regression Issues related to regressions. label Aug 1, 2019
@ChALkeR
Copy link
Member Author

ChALkeR commented Aug 1, 2019 •
edited
Loading

This is caused by removal of env.set_trace_sync_io(env.options()->trace_sync_io).

7fa5f54 breaks the logic behind --trace-sync-io, it should be enabled only at a certain point in time, while that commit enables it from the very start.

Revert in progress. Upd: #28926

@ChALkeR ChALkeR mentioned this issue Aug 1, 2019
Closed
3 tasks
ChALkeR added a commit to ChALkeR/io.js that referenced this issue Aug 2, 2019
@ChALkeR
Revert "src: remove trace_sync_io_ from env"
31973cc 
This reverts commit 7fa5f54.

The reverted commit breaks the logic behind --trace-sync-io, it should
be enabled only at a certain point in time, while that commit enables
it from the very start, causing warnings be printed for all sync io
instead of sync io after the first tick of the event loop as documented.

Fixes: nodejs#28913
Refs: nodejs#22726
Refs: https://nodejs.org/api/cli.html#cli_trace_sync_io
PR-URL: nodejs#28926
@Trott Trott closed this as completed in aa252eb Aug 4, 2019
BridgeAR pushed a commit that referenced this issue Aug 6, 2019
@ChALkeR @BridgeAR
Revert "src: remove trace_sync_io_ from env"
4a747f6 
This reverts commit 7fa5f54.

The reverted commit breaks the logic behind --trace-sync-io, it should
be enabled only at a certain point in time, while that commit enables
it from the very start, causing warnings be printed for all sync io
instead of sync io after the first tick of the event loop as documented.

Fixes: #28913
Refs: #22726
Refs: https://nodejs.org/api/cli.html#cli_trace_sync_io
PR-URL: #28926
Reviewed-By: Anna Henningsen <anna@addaleax.net>
Reviewed-By: Rich Trott <rtrott@gmail.com>
Reviewed-By: Colin Ihrig <cjihrig@gmail.com>
Reviewed-By: James M Snell <jasnell@gmail.com>
addaleax added a commit to addaleax/node that referenced this issue Aug 6, 2019
@addaleax
test: refactor test-sync-io-option
77694f3 
Refactor `test/parallel/test-sync-io-option.js` to be simpler and cover
more cases (in particular, this adds a regression test for
nodejs#28913).

Refs: nodejs#28913
@addaleax addaleax mentioned this issue Aug 6, 2019
Closed
3 tasks
Trott pushed a commit to Trott/io.js that referenced this issue Aug 8, 2019
@addaleax @Trott
test: refactor test-sync-io-option
44f228c 
Refactor `test/parallel/test-sync-io-option.js` to be simpler and cover
more cases (in particular, this adds a regression test for
nodejs#28913).

Refs: nodejs#28913

PR-URL: nodejs#29020
Reviewed-By: Colin Ihrig <cjihrig@gmail.com>
Reviewed-By: Michaël Zasso <targos@protonmail.com>
Reviewed-By: Luigi Pinca <luigipinca@gmail.com>
Reviewed-By: James M Snell <jasnell@gmail.com>
Reviewed-By: Jiawen Geng <technicalcute@gmail.com>
Reviewed-By: Rich Trott <rtrott@gmail.com>
targos pushed a commit that referenced this issue Aug 19, 2019
@addaleax @targos
test: refactor test-sync-io-option
43e444b 
Refactor `test/parallel/test-sync-io-option.js` to be simpler and cover
more cases (in particular, this adds a regression test for
#28913).

Refs: #28913

PR-URL: #29020
Reviewed-By: Colin Ihrig <cjihrig@gmail.com>
Reviewed-By: Michaël Zasso <targos@protonmail.com>
Reviewed-By: Luigi Pinca <luigipinca@gmail.com>
Reviewed-By: James M Snell <jasnell@gmail.com>
Reviewed-By: Jiawen Geng <technicalcute@gmail.com>
Reviewed-By: Rich Trott <rtrott@gmail.com>
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
lib / src Issues and PRs related to general changes in the lib or src directory. regression Issues related to regressions.
Projects
None yet
Milestone
No milestone
Development

Successfully merging a pull request may close this issue.

Revert "src: remove trace_sync_io_ from env" ChALkeR/io.js
1 participant
@ChALkeR