Stream: t-compiler/wg-polonius

Topic: profiling


lokalmatador (Apr 23 2019 at 19:45, on Zulip):

Q/A for @lokalmatador

nikomatsakis (Apr 23 2019 at 19:45, on Zulip):

OK, I've got to run but I can give one very quick tip =)

lokalmatador (Apr 23 2019 at 19:47, on Zulip):

nah it's fine, I got a pile to work off now (better read) - I'll drop a line as soon as I start doing some actual work with rustc - I thin by then the first questions will arise

lokalmatador (Apr 23 2019 at 19:47, on Zulip):

but thanks!

nikomatsakis (Apr 24 2019 at 18:45, on Zulip):

So what I was going to suggest @lokalmatador is that the time function can be used to "drop-in" timing measurements. Here is an example where we invoke it

nikomatsakis (Apr 24 2019 at 18:45, on Zulip):

If I recall, I inserted some calls to this before to dump out timing measurements for how long it takes to borrow check each function

nikomatsakis (Apr 24 2019 at 18:47, on Zulip):

Specifically, I think I replaced this line with something like this:

time(tcx.sess(), format!("borrow_check({:?})", def_id), || do_mir_borrowck(...));
nikomatsakis (Apr 24 2019 at 18:47, on Zulip):

and then you can run the compiler with (I think) -Ztime-passes -- this is a kind of deprecated profiler, but sufficient I think for this purpose

nikomatsakis (Apr 24 2019 at 18:47, on Zulip):

@Wesley Wiser is working on a nice replacement and may have some suggestions

nikomatsakis (Apr 24 2019 at 18:48, on Zulip):

maybe that new infrastructure can be used very easily here too, not sure

nikomatsakis (Apr 24 2019 at 18:48, on Zulip):

of course you could always write your own profiler too -- we just need to take start/stop measurements dump the elapsed time, along with the def_id

nikomatsakis (Apr 24 2019 at 18:48, on Zulip):

we can then run this on some tests and we'll see how long each fn took

nikomatsakis (Apr 24 2019 at 18:49, on Zulip):

one complication is that the do_mir_borrowck function sometimes recurses, specifically around closures...

nikomatsakis (Apr 24 2019 at 18:49, on Zulip):

inserting that call there will measure the standard NLL borrow check, of course, not polonius -- we can then measure twice, once with polonius enabled, and compare the difference

nikomatsakis (Apr 24 2019 at 18:49, on Zulip):

in fact, I wonder if it's easier to just insert some eprintln! calls (or perhaps info! or something so they don't print by default) and post-process the data with a quick script

nikomatsakis (Apr 24 2019 at 18:49, on Zulip):

that would let us readily handle the recursive case

nikomatsakis (Apr 24 2019 at 18:50, on Zulip):

e.g., print out a start stamp / end stamp

lokalmatador (Apr 24 2019 at 19:04, on Zulip):

ok, thanks for elaborating

nikomatsakis (Apr 24 2019 at 19:06, on Zulip):

I suppose it'd be nice if we could have some kind of code that we can check-in, such that we can readily generate spreadsheets etc in the future

lokalmatador (Apr 24 2019 at 19:06, on Zulip):

yup

nikomatsakis (Apr 24 2019 at 19:06, on Zulip):

(one easy way to do this would be to have the compiler self-profile and to generate debug! statements that we can grep for)

nikomatsakis (Apr 24 2019 at 19:06, on Zulip):

although hmm

nikomatsakis (Apr 24 2019 at 19:07, on Zulip):

so if it just generates debug! statements at specific points

nikomatsakis (Apr 24 2019 at 19:07, on Zulip):

we can check-in the scripts to post-process that output into the polonius repo

nikomatsakis (Apr 24 2019 at 19:07, on Zulip):

that seems like a good enough setup too

Wesley Wiser (Apr 24 2019 at 19:15, on Zulip):

If you want to use -Z self-profile, the easiest thing to do would be to call the start_activity() and end_activity() methods on the SelfProfiler which can take arbitrary strings. Here's an example:

https://github.com/rust-lang/rust/blob/31f5d69ba4f4d78740190a08ea097b41b00d96cb/src/librustc_interface/passes.rs#L72-L80

Wesley Wiser (Apr 24 2019 at 19:17, on Zulip):

The tooling here is currently kind of basic but after you've made that change, you'll need to build rustc, then run it with the -Z self-profile flag. You'll get three output files in your working directory. From there, you can use the tool in this PR to get timing data out of those binary files

Wesley Wiser (Apr 24 2019 at 19:18, on Zulip):

The self-profiler should correctly handle the recursive case so you don't need to do anything there.

lokalmatador (Apr 24 2019 at 19:18, on Zulip):

I see. Thanks for the info!

Wesley Wiser (Apr 24 2019 at 19:19, on Zulip):

Let me know if you decide to go that route and have questions. I'd be happy to answer them or help you get unstuck.

nikomatsakis (Apr 24 2019 at 19:43, on Zulip):

That might be the right thing then

lokalmatador (May 23 2019 at 21:09, on Zulip):

alright

lokalmatador (May 23 2019 at 21:09, on Zulip):

so I dug around the last coupla days I think I found the locations where profiling for polonius should be done

lokalmatador (May 23 2019 at 21:11, on Zulip):

this is what I changed: https://github.com/lokalmatador/rust/commit/3953fa1a48e9bf08b9ee729a7d3d2dacee5ffd95

lokalmatador (May 23 2019 at 21:12, on Zulip):

everything compiles and using it seems to output some profiling data for the statements I added, but now I'm stuck with measureme

lokalmatador (May 23 2019 at 21:12, on Zulip):

cloned it (today) and compiled it and now I get that

lokalmatador (May 23 2019 at 21:12, on Zulip):

thread 'main' panicked at 'assertion failed: `(left == right)` left: `"GenericActivity"`, right: `"Query"`', summarize/src/analysis.rs:150:17

lokalmatador (May 23 2019 at 21:12, on Zulip):

maybe @Wesley Wiser has an idea why this happens?

lokalmatador (May 23 2019 at 21:13, on Zulip):

also, @nikomatsakis , is this what you inteded with profiling? and also, are the locations correct?

Wesley Wiser (May 23 2019 at 21:22, on Zulip):

I can tell you what's happening but I don't know why.

Profiler events get recorded as either a Start event or a Stop event and then an event type.

When the summarization tool runs, it keeps of stack of events that happen per thread. When a Stop event gets processed, we look at the previous event on the stack and make sure it matches the event we're currently processing.

In this case, that assertion is failing. Based on the message, the last Start event we saw on this thread was for a "GenericActivity" event type but now the Stop event we're processing is for a "Query" event type.

Wesley Wiser (May 23 2019 at 21:23, on Zulip):

It almost looks like there's event missing from the file but that shouldn't happen and I've never seen it

Wesley Wiser (May 23 2019 at 21:23, on Zulip):

How big is your .events file?

lokalmatador (May 23 2019 at 21:24, on Zulip):

308K

Wesley Wiser (May 23 2019 at 21:27, on Zulip):

Can you file a bug report on https://github.com/rust-lang/measureme ?

Wesley Wiser (May 23 2019 at 21:27, on Zulip):

And include all three files

Wesley Wiser (May 23 2019 at 21:28, on Zulip):

Thanks!

lokalmatador (May 23 2019 at 21:29, on Zulip):

sure

lokalmatador (May 23 2019 at 21:58, on Zulip):

Can you file a bug report on https://github.com/rust-lang/measureme ?

done - though I could not add a proper label...

nikomatsakis (May 28 2019 at 13:44, on Zulip):

@lokalmatador that looks like what I intended, yes. It's a bit of an underestimate in that it's only profiling the cost of "inner loop" of polonius and not the cost of generating the facts themselves, but it'd still be useful data.

nikomatsakis (May 28 2019 at 13:44, on Zulip):

Did you ever figure out what was going wrong with measureme?

lokalmatador (May 28 2019 at 15:54, on Zulip):

lokalmatador that looks like what I intended, yes. It's a bit of an underestimate in that it's only profiling the cost of "inner loop" of polonius and not the cost of generating the facts themselves, but it'd still be useful data.

I see. For my understanding: Polonius uses the same facts as NLL, right?

lokalmatador (May 28 2019 at 15:55, on Zulip):

so it boils down to also profile NLL's fact generation

Albin Stjerna (May 28 2019 at 18:43, on Zulip):

@lokalmatador More or less, there are some Polonius-specific fact generation steps, notably an entire MIR traversal to extract variable uses, but I can't remember if that's in the code you're profiling yet. I think I remember a nested loop doing some sort of Polonius-only work somewhere in trace::trace()as well.

Albin Stjerna (May 28 2019 at 18:44, on Zulip):

But it's heavily piggy-backing off of NLL's calculations as far as I can tell

Wesley Wiser (May 31 2019 at 11:48, on Zulip):

@lokalmatador The issue with measureme is that this line in your diff should use end_activity instead of start_activity.

lokalmatador (Jun 01 2019 at 06:56, on Zulip):

lokalmatador The issue with measureme is that this line in your diff should use end_activity instead of start_activity.

hey @Wesley Wiser, just saw it on github. Totally my bad, sorry for bothering with that stupid question :D I'll proof read my code thrice from now on ;) Anyways, thanks for clarifying!

Wesley Wiser (Jun 01 2019 at 11:59, on Zulip):

@lokalmatador No worries! I had to look through your diff twice before I spotted it myself :slight_smile:

lokalmatador (Jun 24 2019 at 16:16, on Zulip):

hm, to whoever stumbles upon this (but maybe @nikomatsakis wants to reply), at the beginning we at some point talked about also dumping tuple counts

lokalmatador (Jun 24 2019 at 16:18, on Zulip):

1. so do we still want to do this?
2. that seems a little trickier as I cannot reuse the profiling stuff which is there - well I could by dumping some string that contains the number of tuples if this is ok, but in an ideal world, we probably want something else; could the NLL fact dumping stuff be reused?

lokalmatador (Jun 24 2019 at 16:18, on Zulip):

just trying to avoid to introduce too much new stuff somehow...

lokalmatador (Jun 24 2019 at 16:19, on Zulip):

no need to discuss now, but tomorrow maybe

lokalmatador (Jun 24 2019 at 16:40, on Zulip):

in the meantime, I'll continue playing with rustc-perf and give some benchmarks a shot

nikomatsakis (Jun 24 2019 at 18:46, on Zulip):

well the tuple counts we can also get very easily just by inspecting the output

nikomatsakis (Jun 24 2019 at 18:46, on Zulip):

I guess I think we *may want to do it

nikomatsakis (Jun 24 2019 at 18:46, on Zulip):

I'm trying to remember

nikomatsakis (Jun 24 2019 at 18:47, on Zulip):

I think my main motivation was being able to correlate timing with tuple counts maybe?

nikomatsakis (Jun 24 2019 at 18:47, on Zulip):

starting with just timing seems ok

lokalmatador (Jun 24 2019 at 18:49, on Zulip):

I think my main motivation was being able to correlate timing with tuple counts maybe?

that sounds very reasonable

lokalmatador (Jun 24 2019 at 18:49, on Zulip):

ok, then I'll focus on the timing for now

Albin Stjerna (Jun 24 2019 at 19:40, on Zulip):

I don't think this is useful for you yet @lokalmatador, but as part of my work for my thesis, I have collected about 17 000 Git repositories containing Rust code that compiles with Nightly Rust (selected by number of Github stars and downloads on crates.io), and have now generated around 70 GB of Polonius inputs from them. I plan on doing a quick tuple count and run Polonius against them and see how the correlations look. :)

Albin Stjerna (Jun 24 2019 at 19:42, on Zulip):

(this is an excuse to have more colourful graphs in my report)

Albin Stjerna (Jun 24 2019 at 19:42, on Zulip):

Ah, apparently I have inputs from roughly 1700 repositories, or precisely 789 658 functions.

Albin Stjerna (Jun 24 2019 at 19:43, on Zulip):

(I do all of this from Python scripts like an animal)

lqd (Jun 24 2019 at 20:00, on Zulip):

(yeah we can always add these tuple counts/graph/correlate them later — interestingly enough, we might also be able to dump them with datafrog; it'll also dump the whole counts at each iteration of the computation, including outputs and intermediate relations, not just inputs, using this — but polonius doesn't use this rev of datafrog yet though IIRC)

lokalmatador (Jun 25 2019 at 07:06, on Zulip):

I don't think this is useful for you yet lokalmatador, but as part of my work for my thesis, I have collected about 17 000 Git repositories containing Rust code that compiles with Nightly Rust (selected by number of Github stars and downloads on crates.io), and have now generated around 70 GB of Polonius inputs from them. I plan on doing a quick tuple count and run Polonius against them and see how the correlations look. :)

wow, that's a lot :D
yeah maybe we can briefly talk about it tonite if it makes sense for me to reuse it

Albin Stjerna (Jul 01 2019 at 12:00, on Zulip):

Here's a heatmap of inputs affecting solve-time for rougly 789 000 functions from popular crates

Last update: Nov 15 2019 at 20:15UTC