Make `-Z time-passes` less noisy #81284

jyn514 · 2021-01-22T19:44:29Z

Add the module name to pre_AST_expansion_passes and don't make it a
verbose event (since it normally doesn't take very long, and it's
emitted many times)
Don't make the following rustdoc events verbose; they're emitted many times.
- build_extern_trait_impl
- build_local_trait_impl
- build_primitive_trait_impl
- get_auto_trait_impls
- get_blanket_trait_impls
Remove the get_auto_trait_and_blanket_synthetic_impls rustdoc event; it's wholly
covered by get_{auto,blanket}_trait_impls and not very useful.

I found this while working on #81275 but it's independent of those changes.

rust-highfive · 2021-01-22T19:44:33Z

r? @estebank

(rust-highfive has picked a reviewer for you, use r? to override)

jyn514 · 2021-01-22T19:48:16Z

Before: time-passes.log (60k lines)

After:

Documenting cargo v0.48.0 (/home/joshua/test-rustdoc/cargo)
time: 0.001; rss: 62MB	parse_crate
time: 0.000; rss: 62MB	attributes_injection
time: 0.000; rss: 62MB	recursion_limit
time: 0.000; rss: 64MB	plugin_loading
time: 0.000; rss: 64MB	plugin_registration
time: 0.000; rss: 64MB	crate_injection
time: 1.244; rss: 217MB	expand_crate
time: 0.000; rss: 217MB	check_unused_macros
time: 1.244; rss: 217MB	macro_expand_crate
time: 0.000; rss: 217MB	maybe_building_test_harness
time: 0.013; rss: 217MB	AST_validation
time: 0.000; rss: 217MB	maybe_create_a_macro_crate
time: 0.015; rss: 246MB	complete_gated_feature_checking
time: 1.544; rss: 246MB	configure_and_expand
time: 0.008; rss: 247MB	load_extern_crates
time: 0.000; rss: 247MB	prepare_outputs
time: 0.160; rss: 297MB	hir_lowering
time: 0.039; rss: 297MB	early_lint_checks
time: 0.003; rss: 301MB	setup_global_ctxt
time: 0.003; rss: 301MB	create_global_ctxt
time: 0.484; rss: 396MB	item_types_checking
time: 0.101; rss: 401MB	crate_lints
time: 0.000; rss: 401MB	module_lints
time: 0.101; rss: 401MB	missing_docs
time: 0.023; rss: 401MB	check_mod_attrs
time: 0.149; rss: 510MB	clean_crate
time: 1.368; rss: 545MB	collect_synthetic_impls
time: 0.001; rss: 546MB	collect_items_for_trait_impls
time: 2.361; rss: 705MB	collect-trait-impls
time: 0.008; rss: 705MB	unindent-comments
time: 0.014; rss: 705MB	check-private-items-doc-tests
time: 0.009; rss: 705MB	strip-hidden
time: 0.011; rss: 705MB	strip-private
time: 0.032; rss: 706MB	collect-intra-doc-links
time: 0.021; rss: 706MB	check-code-block-syntax
time: 0.004; rss: 706MB	check-invalid-html-tags
time: 0.002; rss: 706MB	propagate-doc-cfg
time: 0.006; rss: 706MB	check-non-autolinks
time: 3.460; rss: 690MB	run_global_ctxt
time: 0.381; rss: 695MB	render_html
time: 0.060; rss: 565MB	free_global_ctxt

compiler/rustc_expand/src/base.rs

- Add the module name to `pre_AST_expansion_passes` and don't make it a verbose event (since it normally doesn't take very long, and it's emitted many times) - Don't make the following rustdoc events verbose; they're emitted many times. + build_extern_trait_impl + build_local_trait_impl + build_primitive_trait_impl + get_auto_trait_impls + get_blanket_trait_impls - Remove `get_auto_trait_and_blanket_synthetic_impls`; it's wholly covered by get_{auto,blanket}_trait_impls and not very useful.

jyn514 · 2021-01-23T16:46:21Z

r? @tgnottingham

tgnottingham · 2021-01-24T07:30:20Z

I have no power here, but have a symbolic r=me. :)

FWIW, I've noticed that pre_AST_expansion_lint_checks can cause big jumps in RSS. If you don't run them, the RSS still increases to the same level by the end of expand_crate, though, at least in the testing I've done. So it's not important to me that we log those events, but they do contain some non-trivial data.

jyn514 · 2021-01-24T15:12:29Z

FWIW, I've noticed that pre_AST_expansion_lint_checks can cause big jumps in RSS. If you don't run them, the RSS still increases to the same level by the end of expand_crate, though, at least in the testing I've done. So it's not important to me that we log those events, but they do contain some non-trivial data.

Hmm, maybe the memory usage comes from collecting the AST? The lint is called on each module so that at least seems plausible. Do you know if RSS is tracked with self-profile, or just instruction count and timings? If it's tracked with self-profile I'd prefer to leave this off by default.

tgnottingham · 2021-01-24T18:08:55Z

I'm not very familiar, but I don't think RSS is tracked. Quick scan of rustc and measureme codebases suggests not.

bjorn3 · 2021-01-24T18:15:22Z

RSS is tracked at

rust/compiler/rustc_data_structures/src/profiling.rs

Lines 587 to 593 in 4e208f6

    
           let mem_string = match get_resident() { 
        
               Some(n) => { 
        
                   let mb = n as f64 / 1_000_000.0; 
        
                   format!("; rss: {}MB", mb.round() as usize) 
        
               } 
        
               None => String::new(), 
        
           };

jyn514 · 2021-01-24T18:16:58Z

@bjorn3 that's for time-passes, not self-profile, right? The concern is that this loses info by only tracking it for self-profile.

bjorn3 · 2021-01-24T18:22:46Z

Yeah, that is only for time-passes.

jyn514 · 2021-01-24T18:33:48Z

r? @wesleywiser

Do you think making time-passes less noisy is worth losing the info about memory usage?

tgnottingham · 2021-01-25T21:54:13Z

While working on adding more RSS data to the time-passes output, I realized that the RSS increase I spoke of doesn't occur during pre_AST_expansion_lint_checks. That pass is called repeatedly during expand_crate. What looks like an increase during pre_AST_expansion_lint_checks is actually just a reflection of an increase that happened elsewhere during expand_crate.

So, no worries here. False alarm. :)

wesleywiser · 2021-01-26T01:11:58Z

Yeah, I agree this is more useful.

@bors r+

bors · 2021-01-26T01:12:00Z

📌 Commit 3b8f1b7 has been approved by wesleywiser

Make `-Z time-passes` less noisy - Add the module name to `pre_AST_expansion_passes` and don't make it a verbose event (since it normally doesn't take very long, and it's emitted many times) - Don't make the following rustdoc events verbose; they're emitted many times. + build_extern_trait_impl + build_local_trait_impl + build_primitive_trait_impl + get_auto_trait_impls + get_blanket_trait_impls - Remove the `get_auto_trait_and_blanket_synthetic_impls` rustdoc event; it's wholly covered by get_{auto,blanket}_trait_impls and not very useful. I found this while working on rust-lang#81275 but it's independent of those changes.

estebank · 2021-01-26T17:11:23Z

Do you think making time-passes less noisy is worth losing the info about memory usage?

Yeah, I agree this is more useful.

Would it be worth it to add a -Z flag to be able to expand the output for when it is needed? (In a separate PR.)

tgnottingham · 2021-01-26T20:15:34Z

Would it be worth it to add a -Z flag to be able to expand the output for when it is needed? (In a separate PR.)

We have -Z time and -Z time-passes, which are less and more verbose respectively. I believe the only difference is that -Z time-passes prints extra verbose activities (ones with text in parentheses).

Logging pre_AST_expansion_lint_checks for -Z time-passes only would fall out naturally from using extra_verbose_generic_activity instead of generic_activity_with_arg.

Only downside is that I think fewer people know about -Z time, but it seems to exist for exactly the purpose we want, so it makes sense to use it and spread the word.

tgnottingham · 2021-01-27T00:41:03Z

If -Z time and -Z time-passes are truly supposed to be non-verbose and verbose versions of pass info, as they seem to be now, we could also go the route of renaming -Z time to -Z time-passes, and -Z time-passes to -Z time-passes-verbose.

Make `-Z time-passes` less noisy - Add the module name to `pre_AST_expansion_passes` and don't make it a verbose event (since it normally doesn't take very long, and it's emitted many times) - Don't make the following rustdoc events verbose; they're emitted many times. + build_extern_trait_impl + build_local_trait_impl + build_primitive_trait_impl + get_auto_trait_impls + get_blanket_trait_impls - Remove the `get_auto_trait_and_blanket_synthetic_impls` rustdoc event; it's wholly covered by get_{auto,blanket}_trait_impls and not very useful. I found this while working on rust-lang#81275 but it's independent of those changes.

estebank · 2021-01-27T17:47:30Z

I would say that it might make sense to make this configurable instead: -Ztime-passes, -Ztime-passes=verbose.

Rollup of 13 pull requests Successful merges: - rust-lang#70904 (Stabilize `Seek::stream_position` (feature `seek_convenience`)) - rust-lang#79951 (Refractor a few more types to `rustc_type_ir` ) - rust-lang#80868 (Print failure message on all tests that should panic, but don't) - rust-lang#81062 (Improve diagnostics for Precise Capture) - rust-lang#81277 (Make more traits of the From/Into family diagnostic items) - rust-lang#81284 (Make `-Z time-passes` less noisy) - rust-lang#81379 (Improve URLs handling) - rust-lang#81416 (Tweak suggestion for missing field in patterns) - rust-lang#81426 (const_evaluatable: expand abstract consts in try_unify) - rust-lang#81428 (compiletest: Add two more unit tests) - rust-lang#81430 (add const_evaluatable_checked test) - rust-lang#81433 (const_evaluatable: stop looking into type aliases) - rust-lang#81445 (Update cargo) Failed merges: r? `@ghost` `@rustbot` modify labels: rollup

jyn514 added T-compiler Relevant to the compiler team, which will review and decide on the PR/issue. A-self-profile Area: Self-profiling feature of the compiler labels Jan 22, 2021

rust-highfive assigned estebank Jan 22, 2021

rust-highfive added the S-waiting-on-review Status: Awaiting review from the assignee but also interested parties. label Jan 22, 2021

jyn514 mentioned this pull request Jan 22, 2021

Remove special casing of rustdoc in rustc_lint #81285

Merged

This comment has been minimized.

Sign in to view

jyn514 force-pushed the impl-times branch from 10daad9 to de7460c Compare January 22, 2021 19:59

bjorn3 reviewed Jan 23, 2021

View reviewed changes

compiler/rustc_expand/src/base.rs Outdated Show resolved Hide resolved

jyn514 force-pushed the impl-times branch from de7460c to 3b8f1b7 Compare January 23, 2021 17:03

jyn514 mentioned this pull request Jan 24, 2021

Track memory usage with -Z self-profile #81348

Open

rust-highfive assigned wesleywiser and unassigned estebank Jan 24, 2021

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 Jan 26, 2021

JohnTitor mentioned this pull request Jan 26, 2021

Rollup of 11 pull requests #81406

Closed

Dylan-DPC-zz mentioned this pull request Jan 27, 2021

Rollup of 11 pull requests #81424

Closed

This was referenced Jan 27, 2021

Rollup of 15 pull requests #81435

Closed

Rollup of 15 pull requests #81437

Closed

This was referenced Jan 27, 2021

Rollup of 19 pull requests #81449

Closed

Rollup of 18 pull requests #81450

Closed

JohnTitor mentioned this pull request Jan 28, 2021

Rollup of 13 pull requests #81461

Merged

bors merged commit bb6d1d3 into rust-lang:master Jan 28, 2021

rustbot added this to the 1.51.0 milestone Jan 28, 2021

jyn514 deleted the impl-times branch January 28, 2021 15:27

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Make `-Z time-passes` less noisy #81284

Make `-Z time-passes` less noisy #81284

jyn514 commented Jan 22, 2021

rust-highfive commented Jan 22, 2021

jyn514 commented Jan 22, 2021 •

edited

Loading

This comment has been minimized.

jyn514 commented Jan 23, 2021

tgnottingham commented Jan 24, 2021

jyn514 commented Jan 24, 2021

tgnottingham commented Jan 24, 2021

bjorn3 commented Jan 24, 2021

jyn514 commented Jan 24, 2021

bjorn3 commented Jan 24, 2021

jyn514 commented Jan 24, 2021

tgnottingham commented Jan 25, 2021

wesleywiser commented Jan 26, 2021

bors commented Jan 26, 2021

estebank commented Jan 26, 2021

tgnottingham commented Jan 26, 2021

tgnottingham commented Jan 27, 2021

estebank commented Jan 27, 2021

Make -Z time-passes less noisy #81284

Make -Z time-passes less noisy #81284

Conversation

jyn514 commented Jan 22, 2021

rust-highfive commented Jan 22, 2021

jyn514 commented Jan 22, 2021 • edited Loading

This comment has been minimized.

jyn514 commented Jan 23, 2021

tgnottingham commented Jan 24, 2021

jyn514 commented Jan 24, 2021

tgnottingham commented Jan 24, 2021

bjorn3 commented Jan 24, 2021

jyn514 commented Jan 24, 2021

bjorn3 commented Jan 24, 2021

jyn514 commented Jan 24, 2021

tgnottingham commented Jan 25, 2021

wesleywiser commented Jan 26, 2021

bors commented Jan 26, 2021

estebank commented Jan 26, 2021

tgnottingham commented Jan 26, 2021

tgnottingham commented Jan 27, 2021

estebank commented Jan 27, 2021

Make `-Z time-passes` less noisy #81284

Make `-Z time-passes` less noisy #81284

jyn514 commented Jan 22, 2021 •

edited

Loading