Stream: t-compiler/wg-nll

Topic: profiling-rustc


nikomatsakis (Jun 05 2018 at 14:41, on Zulip):

So @pnkfelix suggested that it'd be helpful for me to teach someone else how I do profiles of rustc. To use my setup, you do need to be using linux; he suggested I do a pairing session with @Santiago Pastorino or @qmx and make a video

nikomatsakis (Jun 05 2018 at 14:41, on Zulip):

I'd be up for that if either of you are down

nikomatsakis (Jun 05 2018 at 14:41, on Zulip):

that said, I could also try to just write the instructions out, it ain't that complex

nikomatsakis (Jun 05 2018 at 14:41, on Zulip):

maybe both is good :)

qmx (Jun 05 2018 at 14:42, on Zulip):

I'm up for it, we just need to find a time that works for us both :)

nikomatsakis (Jun 05 2018 at 14:44, on Zulip):

that's the trick I suppose

nikomatsakis (Jun 05 2018 at 14:44, on Zulip):

the first thing in any case is to prep a build of rust-lang/master with the right config.toml :)

nikomatsakis (Jun 05 2018 at 14:45, on Zulip):

that alone takes a good 30 minutes...

nikomatsakis (Jun 05 2018 at 14:45, on Zulip):

...or longer I suppose :)

nikomatsakis (Jun 05 2018 at 14:45, on Zulip):

let me try to make a gist in any case

Jake Goulding (Jun 05 2018 at 14:54, on Zulip):

Any idea if a Linux VM or Docker container works? For those of us not on Linux ;-)

nikomatsakis (Jun 05 2018 at 14:56, on Zulip):

I guess maybe

lqd (Jun 05 2018 at 14:58, on Zulip):

this is probably gonna use perf + some of niko's focus scripts, but in general valgrind/callgrind also work on osx (not High Sierra IIRC), and ofc Instruments

nikomatsakis (Jun 05 2018 at 14:59, on Zulip):

yeah so my setup is not the only one :)

nikomatsakis (Jun 05 2018 at 14:59, on Zulip):

valgrind etc is also fine

nikomatsakis (Jun 05 2018 at 14:59, on Zulip):

I'm just .. prone to use the tools I wrote, since naturally they work the way my mind works ;)

Jake Goulding (Jun 05 2018 at 15:00, on Zulip):

@lqd Oh, I use Instruments, but sometimes switching between tools gets you different info to lead to new places to explore, which is my interest. And yeah, Valgrind always lags behind, sadly.

Jake Goulding (Jun 05 2018 at 15:02, on Zulip):

but CPU counting profilers seem like they would be ok in VMs, but wallclock-based would be less so.

nikomatsakis (Jun 05 2018 at 15:19, on Zulip):

here is a gist where I am writing up my procedure:

nikomatsakis (Jun 05 2018 at 15:19, on Zulip):

naturally i've found there is more to write than I thought

nikomatsakis (Jun 05 2018 at 15:19, on Zulip):

seems like good material for the rustc-guide

nikomatsakis (Jun 05 2018 at 15:20, on Zulip):

gist url: https://gist.github.com/nikomatsakis/45e81ac4cfcf21c665176e3e2907f40e

lqd (Jun 05 2018 at 15:21, on Zulip):

(needs to lose the /edit at the end)

nikomatsakis (Jun 05 2018 at 15:21, on Zulip):

I hate that

Jake Goulding (Jun 05 2018 at 15:24, on Zulip):

I've always enjoyed the rationale behind 99Hz

qmx (Jun 05 2018 at 15:40, on Zulip):

@Jake Goulding I work from a container - even on linux - it works

Jake Goulding (Jun 05 2018 at 15:42, on Zulip):

@qmx there's "works" and then there's "produces correct / useful output" :stuck_out_tongue_winking_eye:. A wallclock-based / sampling profiler works in a VM, but may overinflate IO timings, virtualized syscalls, etc.

qmx (Jun 05 2018 at 15:44, on Zulip):

you're totally right

nikomatsakis (Jun 05 2018 at 15:45, on Zulip):

ok, updated the gist with more details

qmx (Jun 05 2018 at 15:45, on Zulip):

what I do is run a single container on a big machine, so the overhead should be minimal (I just want to have a turn-key dev env)

Santiago Pastorino (Jun 05 2018 at 15:46, on Zulip):

So @pnkfelix suggested that it'd be helpful for me to teach someone else how I do profiles of rustc. To use my setup, you do need to be using linux; he suggested I do a pairing session with @Santiago Pastorino or @qmx and make a video

@nikomatsakis let me know if you need something from me :)

nikomatsakis (Jun 05 2018 at 15:46, on Zulip):

@Santiago Pastorino well, so I wrote this gist that contains the directions for how to analyze performance

nikomatsakis (Jun 05 2018 at 15:46, on Zulip):

a good first step would be:

nikomatsakis (Jun 05 2018 at 15:47, on Zulip):

try to follow it and use it to analyze the inflate test

nikomatsakis (Jun 05 2018 at 15:47, on Zulip):

this will let me know what steps I've forgotten to document ;)

nikomatsakis (Jun 05 2018 at 15:47, on Zulip):

but also will give us some info on what that test is so ridiculously slow

Santiago Pastorino (Jun 05 2018 at 15:48, on Zulip):

ok

lqd (Jun 05 2018 at 15:49, on Zulip):

(another polonius datapoint, leapfrog is actually a bit slower than datafrog_opt on inflate)

Jake Goulding (Jun 05 2018 at 15:55, on Zulip):

Clearly you have to race all the algorithms in parallel, taking the first to finish.

Santiago Pastorino (Jun 05 2018 at 16:47, on Zulip):

@nikomatsakis starting to follow your gist :), debuginfo-lines = true and debuginfo = false?

nikomatsakis (Jun 05 2018 at 16:48, on Zulip):

yes

Santiago Pastorino (Jun 05 2018 at 16:49, on Zulip):

ok, building the thing

Santiago Pastorino (Jun 05 2018 at 17:55, on Zulip):
   Compiling rustc_asan v0.0.0 (file:///home/santiago/src/oss/rust-perf/src/librustc_asan)
error: failed to run custom build command for `compiler_builtins v0.0.0 (file:///home/santiago/src/oss/rust-perf/src/rustc/compiler_builtins_shim)`
process didn't exit successfully: `/home/santiago/src/oss/rust-perf/build/x86_64-unknown-linux-gnu/stage0-std/release/build/compiler_builtins-c62c02041b0ab233/build-script-build` (exit code: 101)
--- stdout
cargo:rerun-if-changed=build.rs
cargo:rerun-if-changed=../../libcompiler_builtins/compiler-rt/lib/builtins/absvdi2.c
cargo:rerun-if-changed=../../libcompiler_builtins/compiler-rt/lib/builtins/absvsi2.c
cargo:rerun-if-changed=../../libcompiler_builtins/compiler-rt/lib/builtins/absvti2.c
cargo:rerun-if-changed=../../libcompiler_builtins/compiler-rt/lib/builtins/addvdi3.c
cargo:rerun-if-changed=../../libcompiler_builtins/compiler-rt/lib/builtins/addvsi3.c
cargo:rerun-if-changed=../../libcompiler_builtins/compiler-rt/lib/builtins/addvti3.c
cargo:rerun-if-changed=../../libcompiler_builtins/compiler-rt/lib/builtins/apple_versioning.c
cargo:rerun-if-changed=../../libcompiler_builtins/compiler-rt/lib/builtins/clzdi2.c
cargo:rerun-if-changed=../../libcompiler_builtins/compiler-rt/lib/builtins/clzsi2.c
cargo:rerun-if-changed=../../libcompiler_builtins/compiler-rt/lib/builtins/clzti2.c
cargo:rerun-if-changed=../../libcompiler_builtins/compiler-rt/lib/builtins/cmpdi2.c
cargo:rerun-if-changed=../../libcompiler_builtins/compiler-rt/lib/builtins/cmpti2.c
cargo:rerun-if-changed=../../libcompiler_builtins/compiler-rt/lib/builtins/ctzdi2.c
cargo:rerun-if-changed=../../libcompiler_builtins/compiler-rt/lib/builtins/ctzsi2.c
cargo:rerun-if-changed=../../libcompiler_builtins/compiler-rt/lib/builtins/ctzti2.c
cargo:rerun-if-changed=../../libcompiler_builtins/compiler-rt/lib/builtins/divdc3.c
cargo:rerun-if-changed=../../libcompiler_builtins/compiler-rt/lib/builtins/divsc3.c
cargo:rerun-if-changed=../../libcompiler_builtins/compiler-rt/lib/builtins/divxc3.c
cargo:rerun-if-changed=../../libcompiler_builtins/compiler-rt/lib/builtins/extendhfsf2.c
cargo:rerun-if-changed=../../libcompiler_builtins/compiler-rt/lib/builtins/ffsdi2.c
cargo:rerun-if-changed=../../libcompiler_builtins/compiler-rt/lib/builtins/ffsti2.c
cargo:rerun-if-changed=../../libcompiler_builtins/compiler-rt/lib/builtins/x86_64/floatdisf.c
cargo:rerun-if-changed=../../libcompiler_builtins/compiler-rt/lib/builtins/x86_64/floatdixf.c
cargo:rerun-if-changed=../../libcompiler_builtins/compiler-rt/lib/builtins/x86_64/floatundidf.S
cargo:rerun-if-changed=../../libcompiler_builtins/compiler-rt/lib/builtins/x86_64/floatundisf.S
cargo:rerun-if-changed=../../libcompiler_builtins/compiler-rt/lib/builtins/x86_64/floatundixf.S
cargo:rerun-if-changed=../../libcompiler_builtins/compiler-rt/lib/builtins/int_util.c
cargo:rerun-if-changed=../../libcompiler_builtins/compiler-rt/lib/builtins/muldc3.c
cargo:rerun-if-changed=../../libcompiler_builtins/compiler-rt/lib/builtins/mulsc3.c
cargo:rerun-if-changed=../../libcompiler_builtins/compiler-rt/lib/builtins/mulvdi3.c
cargo:rerun-if-changed=../../libcompiler_builtins/compiler-rt/lib/builtins/mulvsi3.c
cargo:rerun-if-changed=../../libcompiler_builtins/compiler-rt/lib/builtins/mulvti3.c
cargo:rerun-if-changed=../../libcompiler_builtins/compiler-rt/lib/builtins/mulxc3.c
cargo:rerun-if-changed=../../libcompiler_builtins/compiler-rt/lib/builtins/negdf2.c
cargo:rerun-if-changed=../../libcompiler_builtins/compiler-rt/lib/builtins/negdi2.c
cargo:rerun-if-changed=../../libcompiler_builtins/compiler-rt/lib/builtins/negsf2.c
cargo:rerun-if-changed=../../libcompiler_builtins/compiler-rt/lib/builtins/negti2.c
cargo:rerun-if-changed=../../libcompiler_builtins/compiler-rt/lib/builtins/negvdi2.c
cargo:rerun-if-changed=../../libcompiler_builtins/compiler-rt/lib/builtins/negvsi2.c
cargo:rerun-if-changed=../../libcompiler_builtins/compiler-rt/lib/builtins/negvti2.c
cargo:rerun-if-changed=../../libcompiler_builtins/compiler-rt/lib/builtins/paritydi2.c
cargo:rerun-if-changed=../../libcompiler_builtins/compiler-rt/lib/builtins/paritysi2.c
cargo:rerun-if-changed=../../libcompiler_builtins/compiler-rt/lib/builtins/parityti2.c
cargo:rerun-if-changed=../../libcompiler_builtins/compiler-rt/lib/builtins/popcountdi2.c
cargo:rerun-if-changed=../../libcompiler_builtins/compiler-rt/lib/builtins/popcountsi2.c
cargo:rerun-if-changed=../../libcompiler_builtins/compiler-rt/lib/builtins/popcountti2.c
cargo:rerun-if-changed=../../libcompiler_builtins/compiler-rt/lib/builtins/powixf2.c
cargo:rerun-if-changed=../../libcompiler_builtins/compiler-rt/lib/builtins/subvdi3.c
cargo:rerun-if-changed=../../libcompiler_builtins/compiler-rt/lib/builtins/subvsi3.c
cargo:rerun-if-changed=../../libcompiler_builtins/compiler-rt/lib/builtins/subvti3.c
cargo:rerun-if-changed=../../libcompiler_builtins/compiler-rt/lib/builtins/truncdfhf2.c
cargo:rerun-if-changed=../../libcompiler_builtins/compiler-rt/lib/builtins/truncdfsf2.c
cargo:rerun-if-changed=../../libcompiler_builtins/compiler-rt/lib/builtins/truncsfhf2.c
cargo:rerun-if-changed=../../libcompiler_builtins/compiler-rt/lib/builtins/ucmpdi2.c
cargo:rerun-if-changed=../../libcompiler_builtins/compiler-rt/lib/builtins/ucmpti2.c
TARGET = Some("x86_64-unknown-linux-gnu")
OPT_LEVEL = Some("2")
TARGET = Some("x86_64-unknown-linux-gnu")
HOST = Some("x86_64-unknown-linux-gnu")
TARGET = Some("x86_64-unknown-linux-gnu")
TARGET = Some("x86_64-unknown-linux-gnu")
HOST = Some("x86_64-unknown-linux-gnu")
CC_x86_64-unknown-linux-gnu = Some("cc")
TARGET = Some("x86_64-unknown-linux-gnu")
HOST = Some("x86_64-unknown-linux-gnu")
CFLAGS_x86_64-unknown-linux-gnu = Some("-ffunction-sections -fdata-sections -fPIC -m64")
DEBUG = Some("false")
TARGET = Some("x86_64-unknown-linux-gnu")
CC_x86_64-unknown-linux-gnu = Some("cc")
CFLAGS_x86_64-unknown-linux-gnu = Some("-ffunction-sections -fdata-sections -fPIC -m64")
running: "cc" "-O2" "-ffunction-sections" "-fdata-sections" "-fPIC" "-ffunction-sections" "-fdata-sections" "-fPIC" "-m64" "-m64" "-fno-builtin" "-fvisibility=hidden" "-ffreestanding" "-fomit-frame-pointer" "-DVISIBILITY_HIDDEN" "-o" "/home/santiago/src/oss/rust-perf/build/x86_64-unknown-linux-gnu/stage0-std/x86_64-unknown-linux-gnu/release/build/compiler_builtins-ffd422941bf53e42/out/../../libcompiler_builtins/compiler-rt/lib/builtins/absvdi2.o" "-c" "../../libcompiler_builtins/compiler-rt/lib/builtins/absvdi2.c"
cargo:warning=cc: error: ../../libcompiler_builtins/compiler-rt/lib/builtins/absvdi2.c: No such file or directory
cargo:warning=cc: fatal error: no input files
cargo:warning=compilation terminated.
exit code: 1

--- stderr
thread 'main' panicked at '

Internal error occurred: Command "cc" "-O2" "-ffunction-sections" "-fdata-sections" "-fPIC" "-ffunction-sections" "-fdata-sections" "-fPIC" "-m64" "-m64" "-fno-builtin" "-fvisibility=hidden" "-ffreestanding" "-fomit-frame-pointer" "-DVISIBILITY_HIDDEN" "-o" "/home/santiago/src/oss/rust-perf/build/x86_64-unknown-linux-gnu/stage0-std/x86_64-unknown-linux-gnu/release/build/compiler_builtins-ffd422941bf53e42/out/../../libcompiler_builtins/compiler-rt/lib/builtins/absvdi2.o" "-c" "../../libcompiler_builtins/compiler-rt/lib/builtins/absvdi2.c" with args "cc" did not execute successfully (status code exit code: 1).

', /home/santiago/.cargo/registry/src/github.com-1ecc6299db9ec823/cc-1.0.15/src/lib.rs:2158:5
note: Run with `RUST_BACKTRACE=1` for a backtrace.

warning: build failed, waiting for other jobs to finish...
error: build failed
command did not execute successfully: "/home/santiago/src/oss/rust-perf/build/x86_64-unknown-linux-gnu/stage0/bin/cargo" "build" "--target" "x86_64-unknown-linux-gnu" "-j" "4" "--release" "--features" "panic-unwind backtrace" "--manifest-path" "/home/santiago/src/oss/rust-perf/src/libstd/Cargo.toml" "--message-format" "json"
expected success, got: exit code: 101
thread 'main' panicked at 'cargo must succeed', bootstrap/compile.rs:1091:9
note: Run with `RUST_BACKTRACE=1` for a backtrace.
failed to run: /home/santiago/src/oss/rust-perf/build/bootstrap/debug/bootstrap build
Build completed unsuccessfully in 0:02:16
Santiago Pastorino (Jun 05 2018 at 17:55, on Zulip):

@nikomatsakis it's always failing here

simulacrum (Jun 05 2018 at 17:57, on Zulip):

Have you tried something like git submodule update --init?

nikomatsakis (Jun 05 2018 at 17:57, on Zulip):

uh...

simulacrum (Jun 05 2018 at 17:57, on Zulip):

Generally speaking that type of error comes from stale submodules

nikomatsakis (Jun 05 2018 at 17:57, on Zulip):

/me glad @Mark Simulacrum is here

nikomatsakis (Jun 05 2018 at 17:58, on Zulip):

...what Mark said :)

Jake Goulding (Jun 05 2018 at 18:02, on Zulip):

and updating is on by default, IIRC, so you probably turned it off?

nikomatsakis (Jun 05 2018 at 18:03, on Zulip):

that is confusing yes -- I feel like @Santiago Pastorino you've hit problems with this before?

nikomatsakis (Jun 05 2018 at 18:03, on Zulip):

I rarely do

nikomatsakis (Jun 05 2018 at 18:03, on Zulip):

or never

simulacrum (Jun 05 2018 at 18:05, on Zulip):

I think this periodically happens when submodules change... but I've never narrowed it down

simulacrum (Jun 05 2018 at 18:05, on Zulip):

We've "optimized" the submodule code to do less work, primarily because of Windows where that's super slow

simulacrum (Jun 05 2018 at 18:05, on Zulip):

That leads to this sort of problem

Santiago Pastorino (Jun 05 2018 at 18:07, on Zulip):

Have you tried something like git submodule update --init?

yes, it's not that

Santiago Pastorino (Jun 05 2018 at 18:07, on Zulip):

just cloned the thing

Santiago Pastorino (Jun 05 2018 at 18:07, on Zulip):

ran git submodule update --init

Santiago Pastorino (Jun 05 2018 at 18:08, on Zulip):

changed the config.toml to what @nikomatsakis suggested and ran ./x.py build

Santiago Pastorino (Jun 05 2018 at 18:10, on Zulip):

in particular

Santiago Pastorino (Jun 05 2018 at 18:10, on Zulip):
cargo:warning=cc: error: ../../libcompiler_builtins/compiler-rt/lib/builtins/absvdi2.c: No such file or directory
cargo:warning=cc: fatal error: no input files
cargo:warning=compilation terminated.
exit code: 1
nikomatsakis (Jun 05 2018 at 18:12, on Zulip):

what on earth

Santiago Pastorino (Jun 05 2018 at 18:12, on Zulip):

starting fresh again just in case

nikomatsakis (Jun 05 2018 at 18:13, on Zulip):

ok

Santiago Pastorino (Jun 05 2018 at 18:27, on Zulip):

I think I've found the issue

Santiago Pastorino (Jun 05 2018 at 18:27, on Zulip):

git submodule update --init --recursive

Santiago Pastorino (Jun 05 2018 at 18:27, on Zulip):

the recursive bit is important

Santiago Pastorino (Jun 05 2018 at 18:28, on Zulip):
[santiago@archlinux rust-perf (master)]$ git submodule update --init --recursive
Submodule 'compiler-rt' (https://github.com/rust-lang/compiler-rt) registered for path 'src/libcompiler_builtins/compiler-rt'
Cloning into '/home/santiago/src/oss/rust-perf/src/libcompiler_builtins/compiler-rt'...
Submodule path 'src/libcompiler_builtins/compiler-rt': checked out 'dfd960b5f1a1751b22738fa34fd27b583f4618db'
nikomatsakis (Jun 05 2018 at 18:31, on Zulip):

I don't get why you have to do this manually

nikomatsakis (Jun 05 2018 at 18:31, on Zulip):

I never do this kind of stuff :)

nikomatsakis (Jun 05 2018 at 18:31, on Zulip):

at most I occasionally run rm -rf build

Santiago Pastorino (Jun 05 2018 at 18:33, on Zulip):

I don't need to do this manually I guess

Santiago Pastorino (Jun 05 2018 at 18:33, on Zulip):

the thing is that I was already bitten by this

Santiago Pastorino (Jun 05 2018 at 18:33, on Zulip):

so I just did it

Santiago Pastorino (Jun 05 2018 at 18:34, on Zulip):

I don't know exactly the steps you need to follow to end in a state where you really need to run git submodule update --init

simulacrum (Jun 05 2018 at 18:37, on Zulip):

ah, yeah, recursive

Santiago Pastorino (Jun 05 2018 at 18:39, on Zulip):

I guess x.py doesn't do the right thing? or need to be fixed in some way?

simulacrum (Jun 05 2018 at 18:41, on Zulip):

I think I mentioned above -- x.py tries to be smart to do less filesystem operations because those are slow on Windows; that means that I think it doesn't detect stale submodules quite as well. Perhaps that's especially true when they're nested.

lqd (Jun 06 2018 at 09:13, on Zulip):

during the night I compiled a rustc like Niko's gist as well (it takes a while on a 7y old macbook air :3) and cargo checked inflate. it took a long time and I think segfaulted in the end, but there is some data — mainly, I think it's the liveness in the MIR typechecking

lqd (Jun 06 2018 at 09:15, on Zulip):

if the callgrind profile can be useful I can upload it, otherwise the liveness::generate is https://i.imgur.com/sDqi9X1.png

nikomatsakis (Jun 06 2018 at 09:19, on Zulip):

Interesting. I should drill in a bit more with my instrumented build then.

lqd (Jun 06 2018 at 09:24, on Zulip):

hopefully this profile isn't messed up and isn't a goose chase...

nikomatsakis (Jun 06 2018 at 09:30, on Zulip):

it sounds reasonable

lqd (Jun 06 2018 at 09:59, on Zulip):

I'm collecting a profile on clap now, which is the 2nd worst after inflate

lqd (Jun 06 2018 at 10:18, on Zulip):

a bit more muddy (and unfamiliar to me): 4% in liveness, 4% in the mysterious visit_mir, 3% in visit_place, 16% in ena's SnapshotVec::set_all -- it'd probably be interesting to compare to a non-NLL profile, so I'll do that

lqd (Jun 06 2018 at 12:12, on Zulip):

(I was mostly trying to compare these profiles using callgrind, to the ones w/ perf linked in the Paper doc)

nikomatsakis (Jun 06 2018 at 12:31, on Zulip):

both the liveness and set_all costs are things i'm trying to address

nikomatsakis (Jun 06 2018 at 12:31, on Zulip):

basically by doing smart (chalk-like, in fact) memoization

lqd (Jun 06 2018 at 12:44, on Zulip):

and I'm guessing we can't easily help ?

nikomatsakis (Jun 06 2018 at 12:48, on Zulip):

not sure how yet

Santiago Pastorino (Jun 06 2018 at 14:51, on Zulip):

how does https://perf.rust-lang.org/nll-dashboard.html works?

Santiago Pastorino (Jun 06 2018 at 14:52, on Zulip):

I mean, what's in each column, and what's being compared exactly?

simulacrum (Jun 06 2018 at 14:56, on Zulip):

We're comparing the equivalent of cargo check with cargo check --with-nll (if that was a flag); within one commit

simulacrum (Jun 06 2018 at 14:56, on Zulip):

just the leaf crate is being built

lqd (Jun 06 2018 at 14:57, on Zulip):

those are the -check benchmarks ?

lqd (Jun 06 2018 at 14:58, on Zulip):

from the numbers it seems like so indeed :)

simulacrum (Jun 06 2018 at 15:03, on Zulip):

Yeah, Niko said that there's no real point in having non-check benchmarks -- this should be illustrative of the difference

Santiago Pastorino (Jun 06 2018 at 17:46, on Zulip):
[santiago@archlinux inflate (master)]$ perf focus '{do_mir_borrowck}' --tree-callees --tree-min-percent 3
Matcher    : {do_mir_borrowck}
Matches    : 2290
Not Matches: 331
Percentage : 87%

Tree
| matched `{do_mir_borrowck}` (87% total, 0% self)
: | rustc_mir::borrow_check::nll::compute_regions (72% total, 0% self)
: : | rustc_mir::borrow_check::nll::type_check::type_check_internal (64% total, 0% self)
: : : | rustc_mir::borrow_check::nll::type_check::type_check::_$u7b$$u7b$closure$u7d$$u7d$::h5e644cf9693979bb (63% total, 0% self)
: : : : | rustc_mir::borrow_check::nll::type_check::liveness::generate (63% total, 59% self)
: : | rustc_mir::borrow_check::nll::region_infer::RegionInferenceContext::solve (6% total, 0% self)
: : : | rustc::util::common::time (6% total, 0% self)
: : : : | rustc_mir::borrow_check::nll::region_infer::RegionInferenceContext::solve_inner (6% total, 0% self)
: : : : : | rustc_mir::borrow_check::nll::region_infer::RegionInferenceContext::compute_region_values (6% total, 0% self)
: : : : : : | <rustc_data_structures::bitvec::SparseBitMatrix<R, C>>::merge (6% total, 0% self)
: : : : : : : | <alloc::btree::map::BTreeMap<K, V>>::entry (5% total, 1% self)
: : : : : : : : | alloc::btree::search::search_tree (3% total, 0% self)
: : : : : : : : : | alloc::btree::search::search_tree (3% total, 3% self)
: | rustc::mir::visit::Visitor::visit_mir (5% total, 3% self)
: | <rustc_mir::borrow_check::MirBorrowckCtxt<'cx, 'gcx, 'tcx> as rustc_mir::dataflow::DataflowResultsConsumer<'cx, 'tcx>>::visit_statement_entry (4% total, 0% self)
: | rustc_mir::dataflow::do_dataflow (3% total, 0% self)
Santiago Pastorino (Jun 06 2018 at 17:47, on Zulip):

@nikomatsakis :point_up:

Santiago Pastorino (Jun 06 2018 at 17:47, on Zulip):

72% spent on compute_regions

Santiago Pastorino (Jun 06 2018 at 17:47, on Zulip):

most of the time is in rustc_mir::borrow_check::nll::type_check::liveness::generate 63%

nikomatsakis (Jun 06 2018 at 18:03, on Zulip):

rustc_mir::borrow_check::nll::region_infer::RegionInferenceContext::solve (6% total, 0% self) that is sort of interesting

nikomatsakis (Jun 06 2018 at 18:03, on Zulip):

I have an ongoing branch that I hope will improve the liveness::generate results

nikomatsakis (Jun 06 2018 at 18:03, on Zulip):

but I didn't have any plans to improve RegionInferenceContext::solve

Santiago Pastorino (Jun 06 2018 at 18:06, on Zulip):

hehe

nikomatsakis (Jun 06 2018 at 18:45, on Zulip):

@Santiago Pastorino I've not looked at anything after sentry-cli

nikomatsakis (Jun 06 2018 at 18:45, on Zulip):

so if you wanted to do some measurements of some of those, seems like it could be useful

nikomatsakis (Jun 06 2018 at 18:48, on Zulip):

(ok, back)

nikomatsakis (Jun 06 2018 at 18:48, on Zulip):

I don't think we have to look at them all

nikomatsakis (Jun 06 2018 at 18:48, on Zulip):

but it'd be nice to make sure there is not some strikingly different pattern out there

Santiago Pastorino (Jun 06 2018 at 18:58, on Zulip):

ok

Santiago Pastorino (Jun 06 2018 at 18:58, on Zulip):

maybe I should start a document or something with the results?

nikomatsakis (Jun 06 2018 at 19:01, on Zulip):

@Santiago Pastorino let's use this one that I just made

Santiago Pastorino (Jun 06 2018 at 19:02, on Zulip):

was creating this https://paper.dropbox.com/doc/Profiling-of-rustc-perfs-benchmark-examples--AEcIIlo6J0xqvFBQ78VwegH_AQ-M6IR7tbGRqmRg8cwKZin2

Santiago Pastorino (Jun 06 2018 at 19:02, on Zulip):

but ok

Santiago Pastorino (Jun 06 2018 at 19:02, on Zulip):

let me paste that there

Santiago Pastorino (Jun 06 2018 at 19:03, on Zulip):

or well you can decide what to do with the clap part :)

nikomatsakis (Jun 06 2018 at 19:05, on Zulip):

@Santiago Pastorino take a look, do you think the tables are worth it? I'm not sure :)

nikomatsakis (Jun 06 2018 at 19:05, on Zulip):

maybe just an indented list is fine...

nikomatsakis (Jun 06 2018 at 19:09, on Zulip):

ok, I updated the template

nikomatsakis (Jun 06 2018 at 19:11, on Zulip):

gonna have to step out for a bit soon

Santiago Pastorino (Jun 06 2018 at 19:34, on Zulip):

let me check

Santiago Pastorino (Jun 06 2018 at 19:34, on Zulip):

I think it's fine :)

Santiago Pastorino (Jun 06 2018 at 21:05, on Zulip):
[santiago@archlinux sentry-cli (master)]$ perf focus '{do_mir_borrowck}' --tree-callees --relative --tree-max-depth 1 --tree-min-percent 5
Matcher    : {do_mir_borrowck}
Matches    : 0
Not Matches: 42
Percentage : 0%

Tree
Santiago Pastorino (Jun 06 2018 at 21:05, on Zulip):

hmm

davidtwco (Jun 06 2018 at 21:05, on Zulip):

@nikomatsakis when running the profile on clap-rs to confirm the visit_mir observation - is there anything other than these steps that I need to do? I'm not seeing any mentions of visit_mir but I may have messed up in the profiling (here's what I'm seeing from perf-focus)

nikomatsakis (Jun 06 2018 at 21:06, on Zulip):

hmm, no that should be it

nikomatsakis (Jun 06 2018 at 21:06, on Zulip):

interesting, because everybody else seemed to see it

simulacrum (Jun 06 2018 at 21:06, on Zulip):

Just to check, you did enable MIR borrowck?

nikomatsakis (Jun 06 2018 at 21:06, on Zulip):

also interesting because you have a missing %

nikomatsakis (Jun 06 2018 at 21:07, on Zulip):

43% total, but 32% and 3%

Santiago Pastorino (Jun 06 2018 at 21:07, on Zulip):

not sure if you guys are talking about @David Wood case or mine ::P

nikomatsakis (Jun 06 2018 at 21:07, on Zulip):

leaving around 7% :)

Santiago Pastorino (Jun 06 2018 at 21:07, on Zulip):

I have enabled MIR borrowck, yeah

nikomatsakis (Jun 06 2018 at 21:07, on Zulip):

@Santiago Pastorino that was a case where you don't want --lib iirc

nikomatsakis (Jun 06 2018 at 21:07, on Zulip):

could that be it?

nikomatsakis (Jun 06 2018 at 21:07, on Zulip):

I did profile that one

Santiago Pastorino (Jun 06 2018 at 21:07, on Zulip):

ahh

Santiago Pastorino (Jun 06 2018 at 21:07, on Zulip):

could be

nikomatsakis (Jun 06 2018 at 21:07, on Zulip):

or you want to touch src/main.rs

simulacrum (Jun 06 2018 at 21:07, on Zulip):

You can see what args perf passes from perf-config.json in the directory

nikomatsakis (Jun 06 2018 at 21:08, on Zulip):

oh, good to know

nikomatsakis (Jun 06 2018 at 21:08, on Zulip):

I could never figure out where those were

simulacrum (Jun 06 2018 at 21:08, on Zulip):

perf will also touch all files in the dir (find . -name '*.rs' | xargs touch)

lqd (Jun 06 2018 at 21:10, on Zulip):

which case are we talking about ? IIRC there is no main.rs for clap right ? (Ok David is talking about clap, and Santiago about sentry-cli)

Jake Goulding (Jun 06 2018 at 21:10, on Zulip):

(shocked face) not find -print0 | xargs -0? how irresponsible ;-)

davidtwco (Jun 06 2018 at 21:13, on Zulip):

I ran CARGO_INCREMENTAL=0 perf record -F99 --call-graph dwarf cargo +rust0-perf rustc --profile check --lib -- -Zborrowck=mir to generate the perf data for my run.

nikomatsakis (Jun 06 2018 at 21:18, on Zulip):

that seems like it should work

nikomatsakis (Jun 06 2018 at 21:18, on Zulip):

what perf focus command did you use?

Santiago Pastorino (Jun 06 2018 at 21:19, on Zulip):
[santiago@archlinux sentry-cli (master)]$ perf focus '{do_mir_borrowck}' --tree-callees --tree-min-percent 3
Matcher    : {do_mir_borrowck}
Matches    : 256
Not Matches: 430
Percentage : 37%

Tree
| matched `{do_mir_borrowck}` (37% total, 0% self)
: | rustc_mir::borrow_check::nll::compute_regions (26% total, 0% self)
: : | rustc_mir::borrow_check::nll::type_check::type_check_internal (22% total, 0% self)
: : : | rustc_mir::borrow_check::nll::type_check::type_check::_$u7b$$u7b$closure$u7d$$u7d$::h5e644cf9693979bb (16% total, 0% self)
: : : : | rustc_mir::borrow_check::nll::type_check::liveness::generate (16% total, 2% self)
: : : : : | rustc_mir::borrow_check::nll::type_check::TypeChecker::fully_perform_op (11% total, 0% self)
: : : : : : | rustc::infer::InferCtxt::commit_if_ok (5% total, 0% self)
: : : : : : : | rustc::traits::query::dropck_outlives::<impl rustc::infer::at::At<'cx, 'gcx, 'tcx>>::dropck_outlives (4% total, 0% self)
: : : : : : | rustc::infer::InferCtxt::take_and_reset_region_constraints (4% total, 0% self)
: : : : : : : | rustc::infer::region_constraints::RegionConstraintCollector::take_and_reset_data (4% total, 0% self)
: : : : : : : : | <ena::snapshot_vec::SnapshotVec<D>>::set_all (4% total, 4% self)
: | <rustc_mir::borrow_check::MirBorrowckCtxt<'cx, 'gcx, 'tcx> as rustc_mir::dataflow::DataflowResultsConsumer<'cx, 'tcx>>::visit_terminator_entry (3% total, 0% self)
: : | rustc_mir::borrow_check::MirBorrowckCtxt::visit_terminator_drop (3% total, 0% self)
davidtwco (Jun 06 2018 at 21:19, on Zulip):

I used the same command as in Santiago's snippet there, doesn't show up in perf report either though.

lqd (Jun 06 2018 at 21:20, on Zulip):

could visit_mir be less than 3% and filtered out ?

nikomatsakis (Jun 06 2018 at 21:21, on Zulip):

could be, maybe try --tree-max-depth 1

davidtwco (Jun 06 2018 at 21:21, on Zulip):

If I don't add in --tree-min-percent and grep for it then I still don't see it.

nikomatsakis (Jun 06 2018 at 21:22, on Zulip):

I'm wondered where that "lost" percentage has gone

davidtwco (Jun 06 2018 at 21:22, on Zulip):
❯ ~/.cargo/bin/perf-focus '{do_mir_borrowck}' --tree-callees --tree-max-depth 1
Matcher    : {do_mir_borrowck}
Matches    : 2184
Not Matches: 4383
Percentage : 33%

Tree
| matched `{do_mir_borrowck}` (33% total, 0% self)
: | rustc_mir::borrow_check::nll::compute_regions (24% total, 0% self) [...]
: | rustc_mir::dataflow::DataflowResultsConsumer::analyze_results (2% total, 0% self) [...]
: | rustc_mir::dataflow::do_dataflow (2% total, 0% self) [...]
: | <rustc::mir::Mir<'tcx> as rustc_mir::util::collect_writes::FindAssignments>::find_assignments (1% total, 0% self) [...]
: | rustc_mir::borrow_check::nll::replace_regions_in_mir (0% total, 0% self) [...]
: | rustc_mir::dataflow::impls::borrows::Borrows::new (0% total, 0% self) [...]
: | <alloc::rc::Rc<T> as core::ops::drop::Drop>::drop (0% total, 0% self) [...]
: | rustc_mir::dataflow::move_paths::MoveData::gather_moves (0% total, 0% self) [...]
: | rustc_mir::borrow_check::borrow_set::BorrowSet::build (0% total, 0% self) [...]
: | core::ptr::drop_in_place (0% total, 0% self) [...]
: | <rustc::mir::Mir<'tcx> as core::clone::Clone>::clone (0% total, 0% self) [...]
: | _init (0% total, 0% self)
: | rustc_mir::borrow_check::location::LocationTable::new (0% total, 0% self) [...]
: | rustc::ty::maps::<impl rustc::ty::context::TyCtxt<'a, 'tcx, 'lcx>>::param_env (0% total, 0% self) [...]
: | rustc_data_structures::control_flow_graph::dominators::dominators (0% total, 0% self) [...]
nikomatsakis (Jun 06 2018 at 21:22, on Zulip):

because it comes to 7% or 8%

nikomatsakis (Jun 06 2018 at 21:22, on Zulip):

which is exactly what we saw

nikomatsakis (Jun 06 2018 at 21:22, on Zulip):

find_assignments .. interesting

Santiago Pastorino (Jun 06 2018 at 21:23, on Zulip):

could visit_mir be less than 3% and filtered out ?

in my case it was

lqd (Jun 06 2018 at 21:23, on Zulip):

where are the last 4% ? :)

davidtwco (Jun 06 2018 at 21:24, on Zulip):

Well, it was 7% in niko's profiling of clap-rs, not inflate, so it might only be < 3% for inflate.

davidtwco (Jun 06 2018 at 21:24, on Zulip):

(unless I'm mistaken)

nikomatsakis (Jun 06 2018 at 21:24, on Zulip):

oh, wait, is this inflate?

davidtwco (Jun 06 2018 at 21:24, on Zulip):

Mine isn't, I'm running it on clap-rs.

Santiago Pastorino (Jun 06 2018 at 21:25, on Zulip):

@nikomatsakis btw, I'm not able to see analyze_results in the results, the top level thing seems to be visit_terminator_entry, ... unsure

Santiago Pastorino (Jun 06 2018 at 21:26, on Zulip):

anyway, added entry-cli results here https://paper.dropbox.com/doc/NLL-Performance-Tracking-Doc-dRlUMiWT8eexf80FTrYj8

nikomatsakis (Jun 06 2018 at 21:35, on Zulip):

I'd say just put what you see

lqd (Jun 06 2018 at 22:12, on Zulip):

just looking at liveness and wondering: this part is not hot on the profiles we've seen, right ?

lqd (Jun 06 2018 at 22:42, on Zulip):

njn would be good at this, I'm not sure they've looked at NLL during their recent rustc optimization work

nikomatsakis (Jun 06 2018 at 22:58, on Zulip):

I believe that part is reasonably hot; that is part of what I am looking to memoize more.

Santiago Pastorino (Jun 06 2018 at 23:04, on Zulip):

@simulacrum was going to measure serde as next in the list

Santiago Pastorino (Jun 06 2018 at 23:04, on Zulip):
[santiago@archlinux serde (master)]$ ls
appveyor.yml  Cargo.toml       LICENSE-APACHE  perf-config.json  rustfmt.toml  serde_derive            serde_test  test_suite
Cargo.lock    CONTRIBUTING.md  LICENSE-MIT     README.md         serde         serde_derive_internals  target      travis.sh
Santiago Pastorino (Jun 06 2018 at 23:04, on Zulip):

I guess I should measure the internal serde crate, right?

Santiago Pastorino (Jun 06 2018 at 23:05, on Zulip):

is that what shows up https://perf.rust-lang.org/nll-dashboard.html ?

simulacrum (Jun 06 2018 at 23:51, on Zulip):

Yes, that's what's measured by the dashboard. You can look in perf-config for the specific invocation

Santiago Pastorino (Jun 07 2018 at 00:26, on Zulip):

:thumbs_up:

pnkfelix (Jun 07 2018 at 15:19, on Zulip):

@nikomatsakis are you familiar with perf probe? I am now learning about it and am wondering whether we might find it useful for instrumenting rustc binaries

pnkfelix (Jun 07 2018 at 15:22, on Zulip):

i suppose its probably not necessary for our use case...

nikomatsakis (Jun 08 2018 at 01:08, on Zulip):

I had heard of it. I wanted to try and setup something with that and/or dtrace or one of the various other mechanisms to use for query profiling at some point. I remembered @Reed Koser did some experimentation in this direction, right?

nikomatsakis (Jun 08 2018 at 01:08, on Zulip):

I don't think we need it for NLL in particular

Reed Koser (Jun 08 2018 at 01:25, on Zulip):

Yeah, I played with integrating LTTNG into the query system

Reed Koser (Jun 08 2018 at 01:25, on Zulip):

it went... OK. I think I've misplaced some of the code for that

davidtwco (Jun 12 2018 at 13:52, on Zulip):

@nikomatsakis I've not looked into the clap-rs strangeness since mid last week when I couldn't reproduce your measurement, is there anything I should be doing on that?

nikomatsakis (Jun 12 2018 at 13:54, on Zulip):

Hmm, if you can't reproduce, I don't see what — I've almost got my caching branch up and going — maybe we'll investigate again after that

nikomatsakis (Jun 12 2018 at 13:54, on Zulip):

it's interesting though that you can't reproduce, since @lqd and I both did (I can't remember if @Santiago Pastorino did)

nikomatsakis (Jun 12 2018 at 13:55, on Zulip):

one thing maybe worth looking at is the test case that @simulacrum added

nikomatsakis (Jun 12 2018 at 13:55, on Zulip):

"coercions"

nikomatsakis (Jun 12 2018 at 13:55, on Zulip):

2,273.06% slower :)

lqd (Jun 12 2018 at 13:59, on Zulip):

@nikomatsakis didn't you recently start measurements on coercions, or a bisect, which were literally in-flight ? :)

nikomatsakis (Jun 12 2018 at 14:02, on Zulip):

ah no I was bisecting the test failure on https://github.com/rust-lang/rust/pull/51460

nikomatsakis (Jun 12 2018 at 14:02, on Zulip):

which I did do

nikomatsakis (Jun 12 2018 at 14:02, on Zulip):

and am now looking at the best way to fix ;)

Santiago Pastorino (Jun 12 2018 at 14:09, on Zulip):

@nikomatsakis about clap-rs?

Santiago Pastorino (Jun 12 2018 at 14:09, on Zulip):

I can try again

nikomatsakis (Jun 12 2018 at 14:12, on Zulip):

not clap-rs

nikomatsakis (Jun 12 2018 at 14:12, on Zulip):

er, I don't quite know what you are asking :)

Santiago Pastorino (Jun 12 2018 at 14:14, on Zulip):

it's interesting though that you can't reproduce, since @lqd and I both did (I can't remember if @Santiago Pastorino did)

this ^^^

Santiago Pastorino (Jun 12 2018 at 14:14, on Zulip):

anyway in case you need my data ...

Santiago Pastorino (Jun 12 2018 at 14:14, on Zulip):
[santiago@archlinux clap-rs (master)]$ perf focus '{do_mir_borrowck}' --tree-callees --tree-min-percent 3
Matcher    : {do_mir_borrowck}
Matches    : 948
Not Matches: 793
Percentage : 54%

Tree
| matched `{do_mir_borrowck}` (54% total, 0% self)
: | rustc_mir::borrow_check::nll::compute_regions (33% total, 0% self)
: : | rustc_mir::borrow_check::nll::type_check::type_check (24% total, 0% self)
: : : | rustc_mir::borrow_check::nll::type_check::type_check_internal (24% total, 0% self)
: : : : | rustc_mir::borrow_check::nll::type_check::type_check::_$u7b$$u7b$closure$u7d$$u7d$::h2f6b8fe8a646401e (8% total, 0% self)
: : : : : | rustc_mir::borrow_check::nll::type_check::liveness::generate (8% total, 0% self)
: : : : : : | rustc_mir::borrow_check::nll::type_check::TypeChecker::fully_perform_op (7% total, 0% self)
: : : : : : : | rustc::infer::InferCtxt::take_and_reset_region_constraints (5% total, 0% self)
: : : : : : : : | rustc::infer::region_constraints::RegionConstraintCollector::take_and_reset_data (5% total, 0% self)
: : : : : : : : : | <ena::unify::UnificationTable<S>>::reset_unifications (5% total, 5% self)
: : : : | rustc_mir::borrow_check::nll::type_check::TypeChecker::sub_types (6% total, 0% self)
: : : : : | rustc::infer::InferCtxt::take_and_reset_region_constraints (5% total, 0% self)
: : : : : : | rustc::infer::region_constraints::RegionConstraintCollector::take_and_reset_data (5% total, 0% self)
: : : : : : : | <ena::unify::UnificationTable<S>>::reset_unifications (5% total, 5% self)
: : : : | <rustc_mir::borrow_check::nll::type_check::TypeVerifier<'a, 'b, 'gcx, 'tcx> as rustc::mir::visit::Visitor<'tcx>>::visit_mir (4% total, 0% self)
: : : : : | <rustc_mir::borrow_check::nll::type_check::TypeVerifier<'a, 'b, 'gcx, 'tcx> as rustc::mir::visit::Visitor<'tcx>>::visit_constant (3% total, 0% self)
: : | rustc_mir::util::liveness::liveness_of_locals (3% total, 0% self)
: | rustc::mir::visit::Visitor::visit_mir (6% total, 4% self)
: | <rustc_mir::borrow_check::MirBorrowckCtxt<'cx, 'gcx, 'tcx> as rustc_mir::dataflow::DataflowResultsConsumer<'cx, 'tcx>>::visit_statement_entry (5% total, 0% self)
: | rustc_mir::dataflow::do_dataflow (3% total, 0% self)
lqd (Jun 12 2018 at 14:15, on Zulip):

@Santiago Pastorino do you reproduce the NLL slowdown on clap-rs ?

Santiago Pastorino (Jun 12 2018 at 14:16, on Zulip):

now I'm not sure what you meant by the slowdown, maybe we are talking about different thing

Santiago Pastorino (Jun 12 2018 at 14:16, on Zulip):

thought Niko mentioned me here because of this data

lqd (Jun 12 2018 at 14:17, on Zulip):

cargo check on clap is 2-3x slower with NLL than without NLL

Santiago Pastorino (Jun 12 2018 at 14:17, on Zulip):

ok, I can just measure that

Santiago Pastorino (Jun 12 2018 at 14:18, on Zulip):

how are you measuring that?

Santiago Pastorino (Jun 12 2018 at 14:19, on Zulip):

using clap-rs on rustc-perf?

nikomatsakis (Jun 12 2018 at 14:19, on Zulip):

well what @David Wood failed to reproduce was not the slowdown

nikomatsakis (Jun 12 2018 at 14:19, on Zulip):

but rather the mysterios visit_mir calls`

nikomatsakis (Jun 12 2018 at 14:19, on Zulip):

I see them in @Santiago Pastorino's profile though

nikomatsakis (Jun 12 2018 at 14:19, on Zulip):
: | rustc::mir::visit::Visitor::visit_mir (6% total, 4% self)
lqd (Jun 12 2018 at 14:19, on Zulip):

so the "strangeness" is only those calls missing ?

nikomatsakis (Jun 12 2018 at 14:20, on Zulip):

well so we don't know who is making those calls

nikomatsakis (Jun 12 2018 at 14:20, on Zulip):

so what I had in mind was to try and instrument rustc very closely

lqd (Jun 12 2018 at 14:20, on Zulip):

if @David Wood has the slowdown, we're not sure either what is slow on their profile either then :)

nikomatsakis (Jun 12 2018 at 14:20, on Zulip):

and try to track down where they are coming from

nikomatsakis (Jun 12 2018 at 14:20, on Zulip):

I do recall that @David Wood's numbers seemed to be "missing" the same percentage

nikomatsakis (Jun 12 2018 at 14:21, on Zulip):

that is, about 7% of total MIR borrowck time was unaccounted for

Santiago Pastorino (Jun 12 2018 at 14:22, on Zulip):

and btw ...

Santiago Pastorino (Jun 12 2018 at 14:23, on Zulip):
[santiago@archlinux clap-rs (master)]$ touch src/lib.rs
[santiago@archlinux clap-rs (master)]$ time cargo +rust-prof build
warning: profile `doc` is deprecated and has no effect
   Compiling clap v2.29.0 (file:///home/santiago/src/oss/rustc-perf/collector/benchmarks/clap-rs)
warning: use of deprecated item 'std::ascii::AsciiExt': use inherent methods instead
 --> src/app/settings.rs:3:5
  |
3 | use std::ascii::AsciiExt;
  |     ^^^^^^^^^^^^^^^^^^^^
  |
  = note: #[warn(deprecated)] on by default

warning: use of deprecated item 'std::ascii::AsciiExt': use inherent methods instead
 --> src/app/validator.rs:4:5
  |
4 | use std::ascii::AsciiExt;
  |     ^^^^^^^^^^^^^^^^^^^^

warning: use of deprecated item 'std::ascii::AsciiExt': use inherent methods instead
 --> src/args/settings.rs:3:5
  |
3 | use std::ascii::AsciiExt;
  |     ^^^^^^^^^^^^^^^^^^^^

warning: use of deprecated item 'std::ascii::AsciiExt': use inherent methods instead
 --> src/completions/zsh.rs:4:5
  |
4 | use std::ascii::AsciiExt;
  |     ^^^^^^^^^^^^^^^^^^^^

warning: use of deprecated item 'std::ascii::AsciiExt': use inherent methods instead
 --> src/completions/shell.rs:2:5
  |
2 | use std::ascii::AsciiExt;
  |     ^^^^^^^^^^^^^^^^^^^^

    Finished dev [unoptimized + debuginfo] target(s) in 4.56s

real    0m4.577s
user    0m3.991s
sys 0m0.582s
[santiago@archlinux clap-rs (master)]$ touch src/lib.rs
[santiago@archlinux clap-rs (master)]$ time cargo +rust-prof rustc -- -Zborrowck=mir
warning: profile `doc` is deprecated and has no effect
   Compiling clap v2.29.0 (file:///home/santiago/src/oss/rustc-perf/collector/benchmarks/clap-rs)
warning: use of deprecated item 'std::ascii::AsciiExt': use inherent methods instead
 --> src/app/settings.rs:3:5
  |
3 | use std::ascii::AsciiExt;
  |     ^^^^^^^^^^^^^^^^^^^^
  |
  = note: #[warn(deprecated)] on by default

warning: use of deprecated item 'std::ascii::AsciiExt': use inherent methods instead
 --> src/app/validator.rs:4:5
  |
4 | use std::ascii::AsciiExt;
  |     ^^^^^^^^^^^^^^^^^^^^

warning: use of deprecated item 'std::ascii::AsciiExt': use inherent methods instead
 --> src/args/settings.rs:3:5
  |
3 | use std::ascii::AsciiExt;
  |     ^^^^^^^^^^^^^^^^^^^^

warning: use of deprecated item 'std::ascii::AsciiExt': use inherent methods instead
 --> src/completions/zsh.rs:4:5
  |
4 | use std::ascii::AsciiExt;
  |     ^^^^^^^^^^^^^^^^^^^^

warning: use of deprecated item 'std::ascii::AsciiExt': use inherent methods instead
 --> src/completions/shell.rs:2:5
  |
2 | use std::ascii::AsciiExt;
  |     ^^^^^^^^^^^^^^^^^^^^

    Finished dev [unoptimized + debuginfo] target(s) in 32.67s

real    0m32.700s
user    0m48.666s
sys 0m0.913s
Santiago Pastorino (Jun 12 2018 at 14:23, on Zulip):

4.577s vs 32.700s

lqd (Jun 12 2018 at 14:23, on Zulip):

@Santiago Pastorino since your profile has our weird visit_mir calls, you're in the same situation as we are :) but if you need it, the NLL slowdown can be seen comparing for example cargo +nightly clean && CARGO_INCREMENTAL=0 cargo +nightly check && touch src/lib.rs && time CARGO_INCREMENTAL=0 cargo +nightly rustc --profile check --lib vs cargo +nightly clean && CARGO_INCREMENTAL=0 cargo +nightly check && touch src/lib.rs && time CARGO_INCREMENTAL=0 cargo +nightly rustc --profile check --lib -- -Zborrowck=mir

davidtwco (Jun 12 2018 at 14:24, on Zulip):
❯ ~/.cargo/bin/perf-focus '{do_mir_borrowck}' --tree-callees --tree-max-depth 1
Matcher    : {do_mir_borrowck}
Matches    : 2184
Not Matches: 4383
Percentage : 33%

Tree
| matched `{do_mir_borrowck}` (33% total, 0% self)
: | rustc_mir::borrow_check::nll::compute_regions (24% total, 0% self) [...]
: | rustc_mir::dataflow::DataflowResultsConsumer::analyze_results (2% total, 0% self) [...]
: | rustc_mir::dataflow::do_dataflow (2% total, 0% self) [...]
: | <rustc::mir::Mir<'tcx> as rustc_mir::util::collect_writes::FindAssignments>::find_assignments (1% total, 0% self) [...]
: | rustc_mir::borrow_check::nll::replace_regions_in_mir (0% total, 0% self) [...]
: | rustc_mir::dataflow::impls::borrows::Borrows::new (0% total, 0% self) [...]
: | <alloc::rc::Rc<T> as core::ops::drop::Drop>::drop (0% total, 0% self) [...]
: | rustc_mir::dataflow::move_paths::MoveData::gather_moves (0% total, 0% self) [...]
: | rustc_mir::borrow_check::borrow_set::BorrowSet::build (0% total, 0% self) [...]
: | core::ptr::drop_in_place (0% total, 0% self) [...]
: | <rustc::mir::Mir<'tcx> as core::clone::Clone>::clone (0% total, 0% self) [...]
: | _init (0% total, 0% self)
: | rustc_mir::borrow_check::location::LocationTable::new (0% total, 0% self) [...]
: | rustc::ty::maps::<impl rustc::ty::context::TyCtxt<'a, 'tcx, 'lcx>>::param_env (0% total, 0% self) [...]
: | rustc_data_structures::control_flow_graph::dominators::dominators (0% total, 0% self) [...]

Here's my data from before.

davidtwco (Jun 12 2018 at 14:24, on Zulip):

Apparently Zulip doesn't like quoting code blocks.

Santiago Pastorino (Jun 12 2018 at 14:24, on Zulip):

@Santiago Pastorino since your profile has our weird visit_mir calls, you're in the same situation as we are :) but if you need it, the NLL slowdown can be seen comparing for example cargo +nightly clean && CARGO_INCREMENTAL=0 cargo +nightly check && touch src/lib.rs && time CARGO_INCREMENTAL=0 cargo +nightly rustc --profile check --lib vs cargo +nightly clean && CARGO_INCREMENTAL=0 cargo +nightly check && touch src/lib.rs && time CARGO_INCREMENTAL=0 cargo +nightly rustc --profile check --lib -- -Zborrowck=mir

:+1:

davidtwco (Jun 12 2018 at 14:25, on Zulip):

I've still got the build so when I get home I can run it again.

lqd (Jun 12 2018 at 14:46, on Zulip):

oh I hadn't noticed that the rustc-perf repo can't be cloned on windows (cc @simulacrum) but with this partial clone I can at least reproduce the coercions slowdown for sure (<1s vs 17s); I can't really profile on windows though so I'll try later tonight :)

lqd (Jun 12 2018 at 16:05, on Zulip):

oh but valgrind runs :3 this coercions profile might be trash but just in case: could "95% of the time is now spent in ena's UnificationTable::reset_unifications" make sense for a huge static array of strs @nikomatsakis ?

nikomatsakis (Jun 12 2018 at 16:42, on Zulip):

ah. yes.

nikomatsakis (Jun 12 2018 at 16:42, on Zulip):

I suspect my pending PR will make a huge difference here.

nikomatsakis (Jun 12 2018 at 16:42, on Zulip):

gotta fix those bugs.

nikomatsakis (Jun 12 2018 at 16:42, on Zulip):

I found the cause but I have to do a bit of refactoring to fix properly

simulacrum (Jun 12 2018 at 17:17, on Zulip):

I'll look into the windows issue, though I don't have access to windows so it might be somewhat hard to test. Should be able to figure something out though.

lqd (Jun 12 2018 at 20:04, on Zulip):

redoing the coercions profile on osx seems to still point at heavier usage of ena in RegionConstraintCollector::take_and_reset_data, but here/now it's 93% SnapshotVec::set_all... I'll be looking forward to the comparisons with profiles made by others

lqd (Jun 13 2018 at 07:09, on Zulip):

we're still unsure about where the visir_mircalls are coming from ? is there something I could do to help gather some information about that ?

lqd (Jun 13 2018 at 10:55, on Zulip):

@nikomatsakis is this how I should do it: set up a String global variable in librustc::mir::visit, which would be printed in the visitor super_mir, and update this string context in different parts of NLL's do_mir_borrowck to tally up the different calls ?

nikomatsakis (Jun 13 2018 at 12:11, on Zulip):

@lqd I would probably do something like. Or else, set the variable to TRUE for each path that we know of (and FALSE afterwards), and then assert that it is TRUE in the mysterious visit_mir?

nikomatsakis (Jun 13 2018 at 12:11, on Zulip):

basically looking to find the path that makes it assert

nikomatsakis (Jun 13 2018 at 12:11, on Zulip):

but I think the idea of recording "where each call comes from" is probably better

nikomatsakis (Jun 13 2018 at 12:12, on Zulip):

since there is a decent chance that this is indeed a profiler fail

nikomatsakis (Jun 13 2018 at 12:12, on Zulip):

and in fact the calls are coming from one of the places we know of

nikomatsakis (Jun 13 2018 at 12:12, on Zulip):

and the backtrace is just wrong

lqd (Jun 13 2018 at 12:12, on Zulip):

if I'm not sorely mistaken I think around half of the visit_mir calls come from parts of do_mir_borrowck

nikomatsakis (Jun 13 2018 at 12:13, on Zulip):

are you able to narrow down where from within do_mir_borrowck?

nikomatsakis (Jun 13 2018 at 12:13, on Zulip):

like, can you just update your variable at various points

nikomatsakis (Jun 13 2018 at 12:13, on Zulip):

and see what comes out?

nikomatsakis (Jun 13 2018 at 12:13, on Zulip):

(binary search-esque)

lqd (Jun 13 2018 at 12:14, on Zulip):

yeah I can update it at various points in the fn

lqd (Jun 13 2018 at 20:16, on Zulip):

@nikomatsakis update: callgrind reports around 8-8.1k calls to visit_mir, but a println in super_mir yields 31k results — and I'm now a bit more confused than I was when I started this; binary search-esque results are here where I moved the tracing between different "regions" of the code. I will need to recheck all of these tomorrow because of this confusing bit: mir_borrowck yields 4.9k super_mirtraces, while a part of do_mir_borrowck does 8.1k :/

lqd (Jun 14 2018 at 06:43, on Zulip):

... a night's sleep and it makes sense ... one last trace and this should be done

lqd (Jun 14 2018 at 12:57, on Zulip):

for those following at home my visit_mir / super_mir rollercoaster adventures, I'm back at "I'm missing something"

nikomatsakis (Jun 14 2018 at 12:59, on Zulip):

d'oh :)

lqd (Jun 14 2018 at 18:10, on Zulip):

oh but mir_borrowck is recursive, this seems a key fact to find out now :p

lqd (Jun 14 2018 at 18:40, on Zulip):

(something like maybe nll::compute_regions indirectly calling mir_borrowckagain — to the stack-of-traces mobile!)

nikomatsakis (Jun 14 2018 at 18:45, on Zulip):

hmm, that's a good point, I had sort of forgotten about that

lqd (Jun 14 2018 at 18:48, on Zulip):

good to remember if/when we parallelize one day :)

nikomatsakis (Jun 14 2018 at 18:51, on Zulip):

not really relevant

nikomatsakis (Jun 14 2018 at 18:51, on Zulip):

for that in particular

nikomatsakis (Jun 14 2018 at 18:51, on Zulip):

I mean, it recurses via a query basically

nikomatsakis (Jun 14 2018 at 18:51, on Zulip):

and that will "just work" with the parallelization work

nikomatsakis (Jun 14 2018 at 18:52, on Zulip):

(which is in progress btw...)

nikomatsakis (Jun 14 2018 at 18:52, on Zulip):

(specifically it recurses in the case of a fn analyzing the closures contained within)

lqd (Jun 14 2018 at 18:53, on Zulip):

good to know!

lqd (Jun 14 2018 at 18:53, on Zulip):

yeah zoxc's work IIRC

lqd (Jun 15 2018 at 15:17, on Zulip):

@nikomatsakis I finally managed to locate the origins of the MIR borrowck super_mir calls (which I assume would be related to the mysterious visit_mir calls), does this help ?

nikomatsakis (Jun 15 2018 at 21:36, on Zulip):

@lqd actually, yes it does =) I suspect that this is the mysterious source

lqd (Jun 15 2018 at 21:39, on Zulip):

callgrind reported around the same number of visit_mir calls

lqd (Jun 15 2018 at 21:40, on Zulip):

and hehe this is the part of the code where the non-recursive proof tracing behaviour was the most confusing :)

lqd (Jun 17 2018 at 10:48, on Zulip):

I forgot to mention I had already massaged this loop a little to confirm that the find_assignments call was the only source of mir visits in this part of the code indeed

Last update: Nov 21 2019 at 13:05UTC