Indicate both start and end of pass RSS in time-passes output

[tgnottingham]

Previously, only the end of pass RSS was indicated. This could easily
lead one to believe that the change in RSS from one pass to the next was
attributable to the second pass, when in fact it occurred between the
end of the first pass and the start of the second.

Also, improve alignment of columns.

Sample of output:

time:   0.739; rss:   607MB ->   637MB	item_types_checking
time:   8.429; rss:   637MB ->   775MB	item_bodies_checking
time:  11.063; rss:   470MB ->   775MB	type_check_crate
time:   0.232; rss:   775MB ->   777MB	match_checking
time:   0.139; rss:   777MB ->   779MB	liveness_and_intrinsic_checking
time:   0.372; rss:   775MB ->   779MB	misc_checking_2
time:   8.188; rss:   779MB ->  1019MB	MIR_borrow_checking
time:   0.062; rss:  1019MB ->  1021MB	MIR_effect_checking

[rust-highfive]

r? @oli-obk

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

[tgnottingham]

@rustbot label T-compiler

[rust-log-analyzer]

The job mingw-check failed! Check out the build log: (web) (plain)

Click to see the possible cause of the failure (guessed by this bot)

    Checking rustc_codegen_cranelift v0.1.0 (/checkout/compiler/rustc_codegen_cranelift)
error[E0061]: this function takes 4 arguments but 3 arguments were supplied
  --> src/bin/cg_clif.rs:65:5
   |
65 |     print_time_passes_entry(callbacks.time_passes, "\ttotal", start.elapsed());
   |     |
   |     expected 4 arguments

error: aborting due to previous error

[tgnottingham]

This is a small change, but it's turned out to be a huge help in seeing where actual memory usage increases are occurring.

For example, consider the before and after here:

Before:

time:   0.000; rss: 1756MB	find_cgu_reuse
time:   0.667; rss: 3300MB	LLVM_module_optimize_function_passes(2goq7lwe3l6np96t)

After:

time:   0.000; rss:  1756MB ->  1756MB	find_cgu_reuse
time:   0.667; rss:  3261MB ->  3300MB	LLVM_module_optimize_function_passes(2goq7lwe3l6np96t)

Before, the output suggests that LLVM optimizations were causing a huge memory increase. After, it shows that it's actually something between find_cgu_reuse and LLVM optimizations that's causing it.

With a little additional instrumentation, the culprit is revealed:

time:   0.000; rss:  1756MB ->  1756MB	find_cgu_reuse
time:   2.810; rss:  1756MB ->  1921MB	compile_codegen_unit(47luyf1dq9ttmk2y)
time:   3.587; rss:  1921MB ->  2204MB	compile_codegen_unit(5banyx1ghjvcxyne)
time:   4.355; rss:  2204MB ->  2482MB	compile_codegen_unit(2goq7lwe3l6np96t)
time:   3.161; rss:  2482MB ->  2712MB	compile_codegen_unit(qpagbtzbgw0u8oj)
time:   3.477; rss:  2712MB ->  2948MB	compile_codegen_unit(3mkkqle0ppntfa3i)
time:   1.266; rss:  2948MB ->  3057MB	compile_codegen_unit(47cjpiuhvj52boxv)
time:   0.680; rss:  3057MB ->  3114MB	compile_codegen_unit(4nihpc2q9xthln9l)
time:   1.846; rss:  3114MB ->  3261MB	compile_codegen_unit(z93ybhzpgfz689e)
time:   0.667; rss:  3261MB ->  3300MB  LLVM_module_optimize_function_passes(2goq7lwe3l6np96t)

[oli-obk]

I like this change. We can merge it as is, or tune it a little further with a diff-style printing. Please let me know what you prefer

[oli-obk]

@bors r+

[bors]

📌 Commit 849dc1a has been approved by oli-obk