Include self-profiler results

[wesleywiser]

rustc has the option to emit self-profiling data at the end of a compilation. It would be cool to include this data in the performance metrics which would allow us to see what parts of the compiler are broadly responsible for performance gains/regressions.

Running the compiler with rustc -Z self-profile -Z profile-json will cause a self_profiler_results.json file to be created in the working directory. The output looks like this:

[
  {
    "category": "Parsing",
    "time_ms": 1
  },
  {
    "category": "Expansion",
    "time_ms": 2
  },
  {
    "category": "TypeChecking",
    "time_ms": 3
  },
  {
    "category": "BorrowChecking",
    "time_ms": 4
  },
  {
    "category": "Codegen",
    "time_ms": 5
  },
  {
    "category": "Linking",
    "time_ms": 6
  },
  {
    "category": "Other",
    "time_ms": 7
  }
]

cc @nikomatsakis who's wanted this for a while and probably has ideas for what it should look like 😃

[Mark-Simulacrum]

I discussed this around a week ago with @nikomatsakis and we arrived at the conclusion that just collecting the data would be an excellent start; I hope to have some time this next week to do just that.

[Mark-Simulacrum]

I'm seeing the following results which are not valid JSON on a file just containing fn main() {}. Is it possible the support here isn't fully fleshed out yet? It would be good to eliminate the NaNs and make the JSON generated be valid I think before integration into perf is done. @wesleywiser would you perhaps know if I'm doing something wrong? I'm compiling with rustc -Zprofile-json -Zself-profile t.rs on rustc 1.32.0-nightly (13c943992 2018-11-18).

{ "category_data": [{ "category": Parsing, "time_ms": 0,
                            "query_count": 0, "query_hits": NaN }{ "category": Expansion, "time_ms": 10,
                            "query_count": 0, "query_hits": NaN }{ "category": TypeChecking, "time_ms": 1,
                            "query_count": 3444, "query_hits": 80.55 }{ "category": BorrowChecking, "time_ms": 0,
                            "query_count": 20, "query_hits": 40.00 }{ "category": Codegen, "time_ms": 3,
                            "query_count": 763, "query_hits": 65.27 }{ "category": Linking, "time_ms": 65,
                            "query_count": 64, "query_hits": 46.88 }{ "category": Other, "time_ms": 56,
                            "query_count": 13572, "query_hits": 38.73 }], "compilation_options": { "optimization_level": "No", "incremental": false } }

[wesleywiser]

@Mark-Simulacrum Nope, looks like you found a bug. I filed a fix here

[Mark-Simulacrum]

The category labels are not currently allowed per the JSON spec; they need to be strings. I'm working on a patch now.

[Mark-Simulacrum]

@wesleywiser Could we not print out the table if the -Zprofile-json is passed?

[wesleywiser]

@Mark-Simulacrum Absolutely!

[Mark-Simulacrum]

Empirically, I'm also seeing high Other counts -- could we somehow dig into those? I happened to run this on librustc in rustc and I see, which is quite ... unhelpful since the vast majority of the time (133 seconds) is in "other"

Self profiling results for rustc:

| Phase            | Time (ms)      | Queries        | Hits (%) |
| ---------------- | -------------- | -------------- | -------- |
| Parsing          | 419            |                |          |
| Expansion        | 1539           |                |          |
| TypeChecking     | 31186          | 147616813      | 96.87    |
| BorrowChecking   | 6976           | 556902         | 72.80    |
| Codegen          | 71564          | 7517292        | 95.36    |
| Linking          | 2785           | 1425238        | 97.82    |
| Other            | 133209         | 96020418       | 98.11    |

Optimization level: Default
Incremental: off

[wesleywiser]

I suspect this is because of the many queries tagged as Other. I tagged the stuff that was obvious to me with an appropriate category but I put everything else in Other so that at least the other categories wouldn't be erroneously inflated.

https://github.com/rust-lang/rust/blob/4988b096e673204b91683dc693fc3eb6b2323e97/src/librustc/ty/query/mod.rs#L106

[Mark-Simulacrum]

Okay, that would make sense -- would it be possible for the JSON to contain per-query counts perhaps (maybe summed up into categories, but with per-query counts also available?) I suspect that some of these queries are not strictly in any category (i.e., they're used throughout multiple)...

cc @nikomatsakis @michaelwoerister, perhaps you could help us decide if the "Other" being that large would help

[Mark-Simulacrum]

Data for self-profiling is now being collected -- e.g. https://raw.githubusercontent.com/rust-lang-nursery/rustc-timing/481d47377a20d85a676acebedd0a92e094c04a55/times/commit-14997d56a550f4aa99fe737593cd2758227afc56-x86_64-unknown-linux-gnu.json. I'm not quite sure how we want to visualize it yet, so would like some feedback on that bit. Maybe some graphs in e.g. Google spreadsheets or something along those lines. For now though we are at least collecting the data.

[nnethercote]

| Phase            | Time (ms)      | Queries        | Hits (%) |
| ---------------- | -------------- | -------------- | -------- |
| Parsing          | 419            |                |          |
| Expansion        | 1539           |                |          |
| TypeChecking     | 31186          | 147616813      | 96.87    |
| BorrowChecking   | 6976           | 556902         | 72.80    |
| Codegen          | 71564          | 7517292        | 95.36    |
| Linking          | 2785           | 1425238        | 97.82    |
| Other            | 133209         | 96020418       | 98.11    |

I haven't used this feature at all but I can't help but make the following observations.

• It would be extremely helpful if the "Time" and "Queries" columns had (a) a total at the bottom, and (b) for each value, its percentage of the total.
• All the number should be right-justified so the columns line up.
• When numbers get long its very nice to have separators in them. Unfortunately Rust doesn't have built-in support for doing that, as far as I know. You can roll it yourself with string manipulation. It's a pain, but typically worth it: "147,616,813" is much easier to read than "147616813".

[Mark-Simulacrum]

Okay, I think the next step here is to add measureme as a dependency of collector and likely restore something along the lines of 8ee44e1 to the codebase. @wesleywiser I can try to get more detailed directions but this seems like a good first step.

[Mark-Simulacrum]

Closing this as we now have an implementation that collects self-profiler results and displays them.