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.

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

perf: Buffer stderr when writing json errors/warnings #69227

Merged
merged 2 commits into from
Feb 29, 2020

Conversation

Marwes
Copy link
Contributor

@Marwes Marwes commented Feb 17, 2020

Since stderr is unbuffered, writing out json messages actually take up
about ~10%/0.1s of the runtime of the inflate benchmark as it generates a fair number of warnings.

cc #64413

@rust-highfive
Copy link
Collaborator

r? @varkor

(rust_highfive has picked a reviewer for you, use r? to override)

@rust-highfive rust-highfive added the S-waiting-on-review Status: Awaiting review from the assignee but also interested parties. label Feb 17, 2020
@rust-highfive
Copy link
Collaborator

The job x86_64-gnu-llvm-7 of your PR failed (pretty log, raw log). Through arcane magic we have determined that the following fragments from the build log may contain information about the problem.

Click to expand the log.
2020-02-17T07:13:11.7713571Z ========================== Starting Command Output ===========================
2020-02-17T07:13:11.7716490Z [command]/bin/bash --noprofile --norc /home/vsts/work/_temp/cf25030b-1175-4e12-a72b-8850ef5f347f.sh
2020-02-17T07:13:11.7716558Z 
2020-02-17T07:13:11.7720775Z ##[section]Finishing: Disable git automatic line ending conversion
2020-02-17T07:13:11.7727347Z ##[section]Starting: Checkout rust-lang/rust@refs/pull/69227/merge to s
2020-02-17T07:13:11.7729117Z Task         : Get sources
2020-02-17T07:13:11.7729148Z Description  : Get sources from a repository. Supports Git, TfsVC, and SVN repositories.
2020-02-17T07:13:11.7729179Z Version      : 1.0.0
2020-02-17T07:13:11.7729228Z Author       : Microsoft
---
2020-02-17T07:13:12.6542690Z ##[command]git remote add origin https://github.com/rust-lang/rust
2020-02-17T07:13:12.6628831Z ##[command]git config gc.auto 0
2020-02-17T07:13:12.6708195Z ##[command]git config --get-all http.https://github.com/rust-lang/rust.extraheader
2020-02-17T07:13:12.6763478Z ##[command]git config --get-all http.proxy
2020-02-17T07:13:12.6912707Z ##[command]git -c http.extraheader="AUTHORIZATION: basic ***" fetch --force --tags --prune --progress --no-recurse-submodules --depth=2 origin +refs/heads/*:refs/remotes/origin/* +refs/pull/69227/merge:refs/remotes/pull/69227/merge
---
2020-02-17T08:14:59.7613931Z .................................................................................................... 1700/9650
2020-02-17T08:15:04.6064228Z ...........................................FF....................................................... 1800/9650
2020-02-17T08:15:16.8020464Z ..................................i................................................................. 1900/9650
2020-02-17T08:15:24.6200244Z .................................................................................................... 2000/9650
2020-02-17T08:15:39.4075463Z ........................iiiii....................................................................... 2100/9650
2020-02-17T08:15:49.3000593Z .................................................................................................... 2300/9650
2020-02-17T08:15:51.6904351Z .................................................................................................... 2400/9650
2020-02-17T08:15:56.3324062Z .................................................................................................... 2500/9650
2020-02-17T08:16:17.7497594Z .................................................................................................... 2600/9650
---
2020-02-17T08:19:45.1845267Z .................................................................................................... 5600/9650
2020-02-17T08:19:56.0868874Z .......................................................................................i............ 5700/9650
2020-02-17T08:20:04.2353288Z .................................................................................................... 5800/9650
2020-02-17T08:20:09.6031101Z .....................................................................................i.............. 5900/9650
2020-02-17T08:20:19.7622974Z ...............................................................................ii...i..ii........... 6000/9650
2020-02-17T08:20:32.5791458Z i................................................................................................... 6100/9650
2020-02-17T08:20:49.3424031Z .................................................................................................... 6300/9650
2020-02-17T08:20:57.1950847Z .................................................................................................... 6400/9650
2020-02-17T08:20:57.1950847Z .................................................................................................... 6400/9650
2020-02-17T08:21:13.3347252Z .......i..ii........................................................................................ 6500/9650
2020-02-17T08:21:33.9166739Z ...............................................................................................i.... 6700/9650
2020-02-17T08:21:36.1438885Z .................................................................................................... 6800/9650
2020-02-17T08:21:38.3379074Z .................................................................................................... 6900/9650
2020-02-17T08:21:40.7666183Z .....i.............................................................................................. 7000/9650
---
2020-02-17T08:23:20.0980065Z .................................................................................................... 7600/9650
2020-02-17T08:23:24.7497705Z .................................................................................................... 7700/9650
2020-02-17T08:23:30.9091214Z .................................................................................................... 7800/9650
2020-02-17T08:23:37.5756926Z .................................................................................................... 7900/9650
2020-02-17T08:23:47.3892685Z .......................................................................................iiiiiii.i.... 8000/9650
2020-02-17T08:24:03.8082551Z ...........................i......i................................................................. 8200/9650
2020-02-17T08:24:08.8176892Z .................................................................................................... 8300/9650
2020-02-17T08:24:20.6106662Z .................................................................................................... 8400/9650
2020-02-17T08:24:32.7587583Z .................................................................................................... 8500/9650
---
2020-02-17T08:26:34.9216027Z 
2020-02-17T08:26:34.9216236Z - warning: skipping const checks
2020-02-17T08:26:34.9216549Z -   --> $DIR/mutable_const2.rs:15:38
2020-02-17T08:26:34.9216707Z -    |
2020-02-17T08:26:34.9216945Z - LL | const MUTABLE_BEHIND_RAW: *mut i32 = &UnsafeCell::new(42) as *const _ as *mut _;
2020-02-17T08:26:34.9217314Z - 
2020-02-17T08:26:34.9217528Z - error: internal compiler error: mutable allocation in constant
2020-02-17T08:26:34.9217715Z -   --> $DIR/mutable_const2.rs:15:1
2020-02-17T08:26:34.9217865Z -    |
2020-02-17T08:26:34.9217865Z -    |
2020-02-17T08:26:34.9218331Z - LL | const MUTABLE_BEHIND_RAW: *mut i32 = &UnsafeCell::new(42) as *const _ as *mut _;
2020-02-17T08:26:34.9218933Z - 
2020-02-17T08:26:34.9218933Z - 
2020-02-17T08:26:34.9219385Z 13 thread 'rustc' panicked at 'no errors encountered even though `delay_span_bug` issued', src/librustc_errors/lib.rs:355:17
2020-02-17T08:26:34.9219516Z 15 
2020-02-17T08:26:34.9219541Z 
2020-02-17T08:26:34.9219599Z 22 note: rustc VERSION running on TARGET
2020-02-17T08:26:34.9219637Z 23 
2020-02-17T08:26:34.9219637Z 23 
2020-02-17T08:26:34.9219675Z 24 note: compiler flags: FLAGS
2020-02-17T08:26:34.9220251Z + 
2020-02-17T08:26:34.9220297Z + warning: skipping const checks
2020-02-17T08:26:34.9220531Z +   --> $DIR/mutable_const2.rs:15:38
2020-02-17T08:26:34.9220579Z +    |
2020-02-17T08:26:34.9220733Z + LL | const MUTABLE_BEHIND_RAW: *mut i32 = &UnsafeCell::new(42) as *const _ as *mut _;
2020-02-17T08:26:34.9220848Z + 
2020-02-17T08:26:34.9220911Z + error: internal compiler error: mutable allocation in constant
2020-02-17T08:26:34.9221138Z +   --> $DIR/mutable_const2.rs:15:1
2020-02-17T08:26:34.9221186Z +    |
2020-02-17T08:26:34.9221186Z +    |
2020-02-17T08:26:34.9221349Z + LL | const MUTABLE_BEHIND_RAW: *mut i32 = &UnsafeCell::new(42) as *const _ as *mut _;
2020-02-17T08:26:34.9221452Z 25 
2020-02-17T08:26:34.9221510Z 26 
2020-02-17T08:26:34.9221538Z 
2020-02-17T08:26:34.9221565Z 
2020-02-17T08:26:34.9221565Z 
2020-02-17T08:26:34.9221612Z The actual stderr differed from the expected stderr.
2020-02-17T08:26:34.9221961Z Actual stderr saved to /checkout/obj/build/x86_64-unknown-linux-gnu/test/ui/consts/miri_unleashed/mutable_const2/mutable_const2.stderr
2020-02-17T08:26:34.9222223Z To update references, rerun the tests and pass the `--bless` flag
2020-02-17T08:26:34.9222776Z To only update this specific test, also pass `--test-args consts/miri_unleashed/mutable_const2.rs`
2020-02-17T08:26:34.9222989Z error: 1 errors occurred comparing output.
2020-02-17T08:26:34.9223035Z status: exit code: 101
2020-02-17T08:26:34.9223035Z status: exit code: 101
2020-02-17T08:26:34.9223983Z command: "/checkout/obj/build/x86_64-unknown-linux-gnu/stage2/bin/rustc" "/checkout/src/test/ui/consts/miri_unleashed/mutable_const2.rs" "-Zthreads=1" "--target=x86_64-unknown-linux-gnu" "--error-format" "json" "-Zui-testing" "-Zdeduplicate-diagnostics=no" "--emit" "metadata" "-C" "prefer-dynamic" "--out-dir" "/checkout/obj/build/x86_64-unknown-linux-gnu/test/ui/consts/miri_unleashed/mutable_const2" "-Crpath" "-O" "-Cdebuginfo=0" "-Zunstable-options" "-Lnative=/checkout/obj/build/x86_64-unknown-linux-gnu/native/rust-test-helpers" "-A" "unused" "-Zunleash-the-miri-inside-of-you" "-L" "/checkout/obj/build/x86_64-unknown-linux-gnu/test/ui/consts/miri_unleashed/mutable_const2/auxiliary"
2020-02-17T08:26:34.9224344Z ------------------------------------------
2020-02-17T08:26:34.9224379Z 
2020-02-17T08:26:34.9224616Z ------------------------------------------
2020-02-17T08:26:34.9224665Z stderr:
2020-02-17T08:26:34.9224665Z stderr:
2020-02-17T08:26:34.9224904Z ------------------------------------------
2020-02-17T08:26:34.9225216Z thread 'rustc' panicked at 'no errors encountered even though `delay_span_bug` issued', src/librustc_errors/lib.rs:355:17
2020-02-17T08:26:34.9225337Z 
2020-02-17T08:26:34.9225382Z error: internal compiler error: unexpected panic
2020-02-17T08:26:34.9225412Z 
2020-02-17T08:26:34.9225458Z note: the compiler unexpectedly panicked. this is a bug.
2020-02-17T08:26:34.9225458Z note: the compiler unexpectedly panicked. this is a bug.
2020-02-17T08:26:34.9225507Z 
2020-02-17T08:26:34.9225902Z note: we would appreciate a bug report: ***/blob/master/CONTRIBUTING.md#bug-reports
2020-02-17T08:26:34.9225942Z 
2020-02-17T08:26:34.9226246Z note: rustc 1.43.0-nightly (a027f5f92 2020-02-17) running on x86_64-unknown-linux-gnu
2020-02-17T08:26:34.9226292Z 
2020-02-17T08:26:34.9226651Z note: compiler flags: -Z threads=1 -Z ui-testing -Z deduplicate-diagnostics=no -Z unstable-options -Z unleash-the-miri-inside-of-you -C prefer-dynamic -C rpath -C debuginfo=0
2020-02-17T08:26:34.9226768Z warning: skipping const checks
2020-02-17T08:26:34.9227028Z   --> /checkout/src/test/ui/consts/miri_unleashed/mutable_const2.rs:15:38
2020-02-17T08:26:34.9227077Z    |
2020-02-17T08:26:34.9227077Z    |
2020-02-17T08:26:34.9227149Z LL | const MUTABLE_BEHIND_RAW: *mut i32 = &UnsafeCell::new(42) as *const _ as *mut _;
2020-02-17T08:26:34.9227235Z 
2020-02-17T08:26:34.9227302Z error: internal compiler error: mutable allocation in constant
2020-02-17T08:26:34.9227562Z   --> /checkout/src/test/ui/consts/miri_unleashed/mutable_const2.rs:15:1
2020-02-17T08:26:34.9227611Z    |
2020-02-17T08:26:34.9227611Z    |
2020-02-17T08:26:34.9227689Z LL | const MUTABLE_BEHIND_RAW: *mut i32 = &UnsafeCell::new(42) as *const _ as *mut _;
2020-02-17T08:26:34.9227787Z 
2020-02-17T08:26:34.9227814Z 
2020-02-17T08:26:34.9228057Z ------------------------------------------
2020-02-17T08:26:34.9228090Z 
---
2020-02-17T08:26:34.9229597Z -    |        ^^^^^^^^^^^^^^^^^^^^
2020-02-17T08:26:34.9229790Z - 
2020-02-17T08:26:34.9230035Z 7 thread 'rustc' panicked at 'assertion failed: `(left != right)`
2020-02-17T08:26:34.9230086Z 8   left: `Const`,
2020-02-17T08:26:34.9230706Z 9  right: `Const`: UnsafeCells are not allowed behind references in constants. This should have been prevented statically by const qualification. If this were allowed one would be able to change a constant at one use site and other use sites could observe that mutation.', src/librustc_mir/interpret/intern.rs:LL:CC
2020-02-17T08:26:34.9230876Z 18 note: rustc VERSION running on TARGET
2020-02-17T08:26:34.9230939Z 19 
2020-02-17T08:26:34.9230987Z 20 note: compiler flags: FLAGS
2020-02-17T08:26:34.9231029Z + 
---
2020-02-17T08:26:34.9231665Z 22 
2020-02-17T08:26:34.9231692Z 
2020-02-17T08:26:34.9231737Z 
2020-02-17T08:26:34.9231785Z The actual stderr differed from the expected stderr.
2020-02-17T08:26:34.9232137Z Actual stderr saved to /checkout/obj/build/x86_64-unknown-linux-gnu/test/ui/consts/miri_unleashed/mutable_references_ice/mutable_references_ice.stderr
2020-02-17T08:26:34.9232419Z To update references, rerun the tests and pass the `--bless` flag
2020-02-17T08:26:34.9232713Z To only update this specific test, also pass `--test-args consts/miri_unleashed/mutable_references_ice.rs`
2020-02-17T08:26:34.9232812Z error: 1 errors occurred comparing output.
2020-02-17T08:26:34.9232859Z status: exit code: 101
2020-02-17T08:26:34.9232859Z status: exit code: 101
2020-02-17T08:26:34.9233836Z command: "/checkout/obj/build/x86_64-unknown-linux-gnu/stage2/bin/rustc" "/checkout/src/test/ui/consts/miri_unleashed/mutable_references_ice.rs" "-Zthreads=1" "--target=x86_64-unknown-linux-gnu" "--error-format" "json" "-Zui-testing" "-Zdeduplicate-diagnostics=no" "--emit" "metadata" "-C" "prefer-dynamic" "--out-dir" "/checkout/obj/build/x86_64-unknown-linux-gnu/test/ui/consts/miri_unleashed/mutable_references_ice" "-Crpath" "-O" "-Cdebuginfo=0" "-Zunstable-options" "-Lnative=/checkout/obj/build/x86_64-unknown-linux-gnu/native/rust-test-helpers" "-A" "unused" "-Zunleash-the-miri-inside-of-you" "-L" "/checkout/obj/build/x86_64-unknown-linux-gnu/test/ui/consts/miri_unleashed/mutable_references_ice/auxiliary"
2020-02-17T08:26:34.9234192Z ------------------------------------------
2020-02-17T08:26:34.9234243Z 
2020-02-17T08:26:34.9234465Z ------------------------------------------
2020-02-17T08:26:34.9234513Z stderr:
2020-02-17T08:26:34.9234513Z stderr:
2020-02-17T08:26:34.9234725Z ------------------------------------------
2020-02-17T08:26:34.9234988Z thread 'rustc' panicked at 'assertion failed: `(left != right)`
2020-02-17T08:26:34.9235042Z   left: `Const`,
2020-02-17T08:26:34.9235568Z  right: `Const`: UnsafeCells are not allowed behind references in constants. This should have been prevented statically by const qualification. If this were allowed one would be able to change a constant at one use site and other use sites could observe that mutation.', src/librustc_mir/interpret/intern.rs:173:21
2020-02-17T08:26:34.9235692Z 
2020-02-17T08:26:34.9235757Z error: internal compiler error: unexpected panic
2020-02-17T08:26:34.9235787Z 
2020-02-17T08:26:34.9235834Z note: the compiler unexpectedly panicked. this is a bug.
2020-02-17T08:26:34.9235834Z note: the compiler unexpectedly panicked. this is a bug.
2020-02-17T08:26:34.9235864Z 
2020-02-17T08:26:34.9236211Z note: we would appreciate a bug report: ***/blob/master/CONTRIBUTING.md#bug-reports
2020-02-17T08:26:34.9236249Z 
2020-02-17T08:26:34.9236532Z note: rustc 1.43.0-nightly (a027f5f92 2020-02-17) running on x86_64-unknown-linux-gnu
2020-02-17T08:26:34.9236585Z 
2020-02-17T08:26:34.9236942Z note: compiler flags: -Z threads=1 -Z ui-testing -Z deduplicate-diagnostics=no -Z unstable-options -Z unleash-the-miri-inside-of-you -C prefer-dynamic -C rpath -C debuginfo=0
2020-02-17T08:26:34.9237182Z warning: skipping const checks
2020-02-17T08:26:34.9237872Z   --> /checkout/src/test/ui/consts/miri_unleashed/mutable_references_ice.rs:22:8
2020-02-17T08:26:34.9237972Z    |
2020-02-17T08:26:34.9237972Z    |
2020-02-17T08:26:34.9238015Z LL |     x: &UnsafeCell::new(42), //~ WARN: skipping const checks
2020-02-17T08:26:34.9238102Z 
2020-02-17T08:26:34.9238126Z 
2020-02-17T08:26:34.9238516Z ------------------------------------------
2020-02-17T08:26:34.9238562Z 
---
2020-02-17T08:26:34.9242684Z thread 'main' panicked at 'Some tests failed', src/tools/compiletest/src/main.rs:348:22
2020-02-17T08:26:34.9242789Z note: run with `RUST_BACKTRACE=1` environment variable to display a backtrace
2020-02-17T08:26:34.9253951Z 
2020-02-17T08:26:34.9254028Z 
2020-02-17T08:26:34.9260128Z command did not execute successfully: "/checkout/obj/build/x86_64-unknown-linux-gnu/stage0-tools-bin/compiletest" "--compile-lib-path" "/checkout/obj/build/x86_64-unknown-linux-gnu/stage2/lib" "--run-lib-path" "/checkout/obj/build/x86_64-unknown-linux-gnu/stage2/lib/rustlib/x86_64-unknown-linux-gnu/lib" "--rustc-path" "/checkout/obj/build/x86_64-unknown-linux-gnu/stage2/bin/rustc" "--src-base" "/checkout/src/test/ui" "--build-base" "/checkout/obj/build/x86_64-unknown-linux-gnu/test/ui" "--stage-id" "stage2-x86_64-unknown-linux-gnu" "--mode" "ui" "--target" "x86_64-unknown-linux-gnu" "--host" "x86_64-unknown-linux-gnu" "--llvm-filecheck" "/usr/lib/llvm-7/bin/FileCheck" "--host-rustcflags" "-Crpath -O -Cdebuginfo=0 -Zunstable-options  -Lnative=/checkout/obj/build/x86_64-unknown-linux-gnu/native/rust-test-helpers" "--target-rustcflags" "-Crpath -O -Cdebuginfo=0 -Zunstable-options  -Lnative=/checkout/obj/build/x86_64-unknown-linux-gnu/native/rust-test-helpers" "--docck-python" "/usr/bin/python2.7" "--lldb-python" "/usr/bin/python2.7" "--gdb" "/usr/bin/gdb" "--quiet" "--llvm-version" "7.0.0\n" "--system-llvm" "--cc" "" "--cxx" "" "--cflags" "" "--llvm-components" "" "--adb-path" "adb" "--adb-test-dir" "/data/tmp/work" "--android-cross-path" "" "--color" "always"
2020-02-17T08:26:34.9260466Z 
2020-02-17T08:26:34.9260493Z 
2020-02-17T08:26:34.9270980Z failed to run: /checkout/obj/build/bootstrap/debug/bootstrap test
2020-02-17T08:26:34.9271082Z Build completed unsuccessfully in 1:07:08
2020-02-17T08:26:34.9271082Z Build completed unsuccessfully in 1:07:08
2020-02-17T08:26:34.9410735Z == clock drift check ==
2020-02-17T08:26:34.9431091Z   local time: Mon Feb 17 08:26:34 UTC 2020
2020-02-17T08:26:35.2382407Z   network time: Mon, 17 Feb 2020 08:26:35 GMT
2020-02-17T08:26:35.2388799Z == end clock drift check ==
2020-02-17T08:26:35.6650845Z 
2020-02-17T08:26:35.6748817Z ##[error]Bash exited with code '1'.
2020-02-17T08:26:35.6761284Z ##[section]Finishing: Run build
2020-02-17T08:26:35.6783154Z ##[section]Starting: Checkout rust-lang/rust@refs/pull/69227/merge to s
2020-02-17T08:26:35.6784879Z Task         : Get sources
2020-02-17T08:26:35.6784923Z Description  : Get sources from a repository. Supports Git, TfsVC, and SVN repositories.
2020-02-17T08:26:35.6784966Z Version      : 1.0.0
2020-02-17T08:26:35.6785022Z Author       : Microsoft
2020-02-17T08:26:35.6785022Z Author       : Microsoft
2020-02-17T08:26:35.6785067Z Help         : [More Information](https://go.microsoft.com/fwlink/?LinkId=798199)
2020-02-17T08:26:35.6785114Z ==============================================================================
2020-02-17T08:26:36.1406694Z Cleaning any cached credential from repository: rust-lang/rust (GitHub)
2020-02-17T08:26:36.1450993Z ##[section]Finishing: Checkout rust-lang/rust@refs/pull/69227/merge to s
2020-02-17T08:26:36.1562204Z Cleaning up task key
2020-02-17T08:26:36.1562967Z Start cleaning up orphan processes.
2020-02-17T08:26:36.1693585Z Terminate orphan process: pid (4567) (python)
2020-02-17T08:26:36.1926380Z ##[section]Finishing: Finalize Job

I'm a bot! I can only do what humans tell me to, so if this was not helpful or you have suggestions for improvements, please ping or otherwise contact @TimNN. (Feature Requests)

Markus Westerlind added 2 commits February 17, 2020 15:35
Since `stderr` is unbuffered, writing out json messages actually take up
about ~10%/0.1s of the runtime of the `inflate` benchmark.

cc rust-lang#64413
Even when buffered. Ideally we would flush only when the emitter is
done, but that requires larger changes. This gives most of the benefit
of buffering in any case.
@ecstatic-morse
Copy link
Contributor

Is this ready for a perf run @Marwes?

@Marwes
Copy link
Contributor Author

Marwes commented Feb 21, 2020

Yep

@varkor
Copy link
Member

varkor commented Feb 21, 2020

@bors try @rust-timer queue

@rust-timer
Copy link
Collaborator

Awaiting bors try build completion

@bors
Copy link
Contributor

bors commented Feb 21, 2020

⌛ Trying commit ee064be with merge 168259ddefb401a797c91e7d1720602a4c140f07...

@bors
Copy link
Contributor

bors commented Feb 21, 2020

☀️ Try build successful - checks-azure
Build commit: 168259ddefb401a797c91e7d1720602a4c140f07 (168259ddefb401a797c91e7d1720602a4c140f07)

@rust-timer
Copy link
Collaborator

Queued 168259ddefb401a797c91e7d1720602a4c140f07 with parent 01a8b5f, future comparison URL.

@rust-timer
Copy link
Collaborator

Finished benchmarking try commit 168259ddefb401a797c91e7d1720602a4c140f07, comparison URL.

@ecstatic-morse
Copy link
Contributor

Awesome! cc #69227

@Marwes
Copy link
Contributor Author

Marwes commented Feb 21, 2020

No improvement in benchmarks, yet it was a clear when I ran inflate manually (cargo check). Maybe warnings are ignored when benchmarks are ran so nothing is emitted? Couldn't find anything about it though.

@ecstatic-morse
Copy link
Contributor

ecstatic-morse commented Feb 21, 2020

@Marwes syscall only counts as one instruction. Have a look at the task-clock measurements.

@Marwes
Copy link
Contributor Author

Marwes commented Feb 25, 2020

Perf looks good (looking at task-clock). Should be good to merge?

@ecstatic-morse
Copy link
Contributor

ecstatic-morse commented Feb 25, 2020

I don't think we should merge this as-is. Wouldn't this decouple error messages from other output such as RUSTC_LOG thus making debugging harder? Instead, we should use either line- or block-buffering for io::Stderr if it is not a TTY (this is basically #64413).

@Marwes
Copy link
Contributor Author

Marwes commented Feb 25, 2020

Isn't it already decoupled and susceptible to races though? This change does mean that there is a race between writeln! and the flush. But since stderr isn't locked before passing it to writeln! then each segment written to stderr is already susceptible races with RUSTC_LOG.

@ecstatic-morse
Copy link
Contributor

ecstatic-morse commented Feb 25, 2020

@Marwes In a single-threaded context, what happens if I emit then call warn! then emit again? I want to see the following:

ERROR 1
warning
ERROR 2

Are we flushing the emitter buffer in such a way that the relative order is preserved?

@Marwes
Copy link
Contributor Author

Marwes commented Feb 26, 2020

The buffer is flushed immediately after each emit, so effectively it only buffers each warning written. Without that tests indeed showed interleaved messages like you pointed out.

@ecstatic-morse
Copy link
Contributor

Ah, my bad. I withdraw my objection.

@varkor
Copy link
Member

varkor commented Feb 27, 2020

@bors r+

@bors
Copy link
Contributor

bors commented Feb 27, 2020

📌 Commit ee064be has been approved by varkor

@bors bors added S-waiting-on-bors Status: Waiting on bors to run and complete tests. Bors will change the label on completion. and removed S-waiting-on-review Status: Awaiting review from the assignee but also interested parties. labels Feb 27, 2020
@bors
Copy link
Contributor

bors commented Feb 29, 2020

⌛ Testing commit ee064be with merge 04e7f96...

@bors
Copy link
Contributor

bors commented Feb 29, 2020

☀️ Test successful - checks-azure
Approved by: varkor
Pushing 04e7f96 to master...

@bors bors added the merged-by-bors This PR was explicitly merged by bors. label Feb 29, 2020
@bors bors merged commit 04e7f96 into rust-lang:master Feb 29, 2020
@Marwes Marwes deleted the buffer_stderr branch February 29, 2020 15:14
@tamird
Copy link
Contributor

tamird commented Mar 6, 2020

Doesn't it negate the effect of buffering, if you're immediately flushing after every write?

@Marwes
Copy link
Contributor Author

Marwes commented Mar 6, 2020

Each write! involves multiple syscalls since writing out JSON performs no buffering (each {, [ is a separate syscall). With this it is once per warning (or more if a warning fills the buffer)

So there is a still a good amount of benefit.

@jonas-schievink jonas-schievink added relnotes Marks issues that should be documented in the release notes of the next release. relnotes-perf Performance improvements that should be mentioned in the release notes. labels Mar 13, 2020
@jonas-schievink jonas-schievink modified the milestones: 1.44, 1.43 Mar 13, 2020
netbsd-srcmastr pushed a commit to NetBSD/pkgsrc that referenced this pull request May 16, 2020
Pkgsrc changes:
 * Bump rust bootstrap version to 1.42.0, except for Darwin/i686 where the
   bootstrap is not (yet?) available.

Upstream changes:

Version 1.43.0 (2020-04-23)
==========================

Language
--------
- [Fixed using binary operations with `&{number}` (e.g. `&1.0`) not having
  the type inferred correctly.][68129]
- [Attributes such as `#[cfg()]` can now be used on `if` expressions.][69201]

**Syntax only changes**
- [Allow `type Foo: Ord` syntactically.][69361]
- [Fuse associated and extern items up to defaultness.][69194]
- [Syntactically allow `self` in all `fn` contexts.][68764]
- [Merge `fn` syntax + cleanup item parsing.][68728]
- [`item` macro fragments can be interpolated into `trait`s, `impl`s,
  and `extern` blocks.][69366]
  For example, you may now write:
  ```rust
  macro_rules! mac_trait {
      ($i:item) => {
          trait T { $i }
      }
  }
  mac_trait! {
      fn foo() {}
  }
  ```
These are still rejected *semantically*, so you will likely receive an error but
these changes can be seen and parsed by macros and
conditional compilation.


Compiler
--------
- [You can now pass multiple lint flags to rustc to override the previous
  flags.][67885] For example; `rustc -D unused -A unused-variables` denies
  everything in the `unused` lint group except `unused-variables` which
  is explicitly allowed. However, passing `rustc -A unused-variables -D unused` denies
  everything in the `unused` lint group **including** `unused-variables` since
  the allow flag is specified before the deny flag (and therefore overridden).
- [rustc will now prefer your system MinGW libraries over its bundled libraries
  if they are available on `windows-gnu`.][67429]
- [rustc now buffers errors/warnings printed in JSON.][69227]

Libraries
---------
- [`Arc<[T; N]>`, `Box<[T; N]>`, and `Rc<[T; N]>`, now implement
  `TryFrom<Arc<[T]>>`,`TryFrom<Box<[T]>>`, and `TryFrom<Rc<[T]>>`
  respectively.][69538] **Note** These conversions are only available when `N`
  is `0..=32`.
- [You can now use associated constants on floats and integers directly, rather
  than having to import the module.][68952] e.g. You can now write `u32::MAX` or
  `f32::NAN` with no imports.
- [`u8::is_ascii` is now `const`.][68984]
- [`String` now implements `AsMut<str>`.][68742]
- [Added the `primitive` module to `std` and `core`.][67637] This module
  reexports Rust's primitive types. This is mainly useful in macros
  where you want avoid these types being shadowed.
- [Relaxed some of the trait bounds on `HashMap` and `HashSet`.][67642]
- [`string::FromUtf8Error` now implements `Clone + Eq`.][68738]

Stabilized APIs
---------------
- [`Once::is_completed`]
- [`f32::LOG10_2`]
- [`f32::LOG2_10`]
- [`f64::LOG10_2`]
- [`f64::LOG2_10`]
- [`iter::once_with`]

Cargo
-----
- [You can now set config `[profile]`s in your `.cargo/config`, or through
  your environment.][cargo/7823]
- [Cargo will now set `CARGO_BIN_EXE_<name>` pointing to a binary's
  executable path when running integration tests or benchmarks.][cargo/7697]
  `<name>` is the name of your binary as-is e.g. If you wanted the executable
  path for a binary named `my-program`you would use
  `env!("CARGO_BIN_EXE_my-program")`.

Misc
----
- [Certain checks in the `const_err` lint were deemed unrelated to const
  evaluation][69185], and have been moved to the `unconditional_panic` and
  `arithmetic_overflow` lints.

Compatibility Notes
-------------------

- [Having trailing syntax in the `assert!` macro is now a hard error.][69548]
  This has been a warning since 1.36.0.
- [Fixed `Self` not having the correctly inferred type.][69340] This incorrectly
  led to some instances being accepted, and now correctly emits a hard error.

[69340]: rust-lang/rust#69340

Internal Only
-------------
These changes provide no direct user facing benefits, but represent significant
improvements to the internals and overall performance of `rustc` and
related tools.

- [All components are now built with `opt-level=3` instead of `2`.][67878]
- [Improved how rustc generates drop code.][67332]
- [Improved performance from `#[inline]`-ing certain hot functions.][69256]
- [traits: preallocate 2 Vecs of known initial size][69022]
- [Avoid exponential behaviour when relating types][68772]
- [Skip `Drop` terminators for enum variants without drop glue][68943]
- [Improve performance of coherence checks][68966]
- [Deduplicate types in the generator witness][68672]
- [Invert control in struct_lint_level.][68725]

[67332]: rust-lang/rust#67332
[67429]: rust-lang/rust#67429
[67637]: rust-lang/rust#67637
[67642]: rust-lang/rust#67642
[67878]: rust-lang/rust#67878
[67885]: rust-lang/rust#67885
[68129]: rust-lang/rust#68129
[68672]: rust-lang/rust#68672
[68725]: rust-lang/rust#68725
[68728]: rust-lang/rust#68728
[68738]: rust-lang/rust#68738
[68742]: rust-lang/rust#68742
[68764]: rust-lang/rust#68764
[68772]: rust-lang/rust#68772
[68943]: rust-lang/rust#68943
[68952]: rust-lang/rust#68952
[68966]: rust-lang/rust#68966
[68984]: rust-lang/rust#68984
[69022]: rust-lang/rust#69022
[69185]: rust-lang/rust#69185
[69194]: rust-lang/rust#69194
[69201]: rust-lang/rust#69201
[69227]: rust-lang/rust#69227
[69548]: rust-lang/rust#69548
[69256]: rust-lang/rust#69256
[69361]: rust-lang/rust#69361
[69366]: rust-lang/rust#69366
[69538]: rust-lang/rust#69538
[cargo/7823]: rust-lang/cargo#7823
[cargo/7697]: rust-lang/cargo#7697
[`Once::is_completed`]: https://doc.rust-lang.org/std/sync/struct.Once.html#method.is_completed
[`f32::LOG10_2`]: https://doc.rust-lang.org/std/f32/consts/constant.LOG10_2.html
[`f32::LOG2_10`]: https://doc.rust-lang.org/std/f32/consts/constant.LOG2_10.html
[`f64::LOG10_2`]: https://doc.rust-lang.org/std/f64/consts/constant.LOG10_2.html
[`f64::LOG2_10`]: https://doc.rust-lang.org/std/f64/consts/constant.LOG2_10.html
[`iter::once_with`]: https://doc.rust-lang.org/std/iter/fn.once_with.html
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
merged-by-bors This PR was explicitly merged by bors. relnotes Marks issues that should be documented in the release notes of the next release. relnotes-perf Performance improvements that should be mentioned in the release notes. S-waiting-on-bors Status: Waiting on bors to run and complete tests. Bors will change the label on completion.
Projects
None yet
Development

Successfully merging this pull request may close these issues.

8 participants