Borrow checking time regression from stable to nightly #43018

jonhoo · 2017-07-02T22:02:04Z

The compile time for the following code has increased significantly since the last stable:

extern crate futures;
use futures::{future, IntoFuture, Future};
fn main() {
    let t: std::result::Result<(), ()> = Ok(());
    let f = t
            .into_future()
            .and_then(|_| future::ok(()))
            .and_then(|_| future::ok(()))
            .and_then(|_| future::ok(()))
            .and_then(|_| future::ok(()))
            .and_then(|_| future::ok(()))
            .and_then(|_| future::ok(()))
            .and_then(|_| future::ok(()))
            .and_then(|_| future::ok(()))
            .and_then(|_| future::ok(()))
            .and_then(|_| future::ok(()))
            .and_then(|_| future::ok(()))
            .and_then(|_| future::ok(()))
            .and_then(|_| future::ok(()))
            .and_then(|_| future::ok(()));
    f.wait();
}

Ignoring the fact that the translationphase takes forever (tracked in #38528), the borrow checking phase now takes orders of magnitude longer than on the last stable:

$ cargo +stable rustc -- -Z time-passes | grep "borrow checking"
time: 0.000; rss: 88MB  borrow checking                                                                                                                                                                                                                                      $ cargo +nightly rustc -- -Z time-passes | grep "borrow checking"
time: 1.173; rss: 101MB borrow checking

The text was updated successfully, but these errors were encountered:

arielb1 · 2017-07-03T12:30:34Z

I think MIR construction had just been merged into borrow checking, so that new borrow checking time = old MIR construction + old borrow checking time.

alexcrichton · 2017-07-23T15:35:52Z

Looks like this regression has snuck into 1.19.0 by accident :(

Mark-Simulacrum · 2017-07-27T16:29:02Z

Nominating for compiler team for prioritization. Possibly not a bug (just passes merging).

alexcrichton · 2017-07-27T16:29:30Z

cc @rust-lang/compiler

eddyb · 2017-07-27T16:50:43Z

Hmm, was MIR construction after borrow-checking? I thought borrow-checking, followed by lints, were supposed to be the very last two passes before trans (and let's say MIR optimizations could be after lints - but certainly not MIR construction!).
Also, -Z time-passes will start being more and more useless, see e.g. #43345 for a better approach.

nikomatsakis · 2017-07-27T20:57:32Z

@jonhoo can you measure the overall build times too?

I'm going to close the issue in the meantime, but if you find a discrepancy, please feel free to re-open. =)

jonhoo · 2017-07-27T21:10:57Z

Seems like a regression to me:

$ cargo +stable build
   Compiling rust-issue-43018 v0.1.0 (file:///home/jon/tmp/rust-issue-43018)
    Finished dev [unoptimized + debuginfo] target(s) in 40.72 secs
$ cargo +beta build
   Compiling rust-issue-43018 v0.1.0 (file:///home/jon/tmp/rust-issue-43018)
    Finished dev [unoptimized + debuginfo] target(s) in 49.18 secs
$ cargo +nightly build
   Compiling rust-issue-43018 v0.1.0 (file:///home/jon/tmp/rust-issue-43018)
    Finished dev [unoptimized + debuginfo] target(s) in 47.14 secs

With incremental compilation enabled it gets worse, but that may be expected?

$ env CARGO_INCREMENTAL=1 cargo +nightly build
   Compiling rust-issue-43018 v0.1.0 (file:///home/jon/tmp/rust-issue-43018)
    Finished dev [unoptimized + debuginfo] target(s) in 58.71 secs

arielb1 · 2017-07-27T21:24:04Z

@jonhoo

Can you provide -Z time-passes output?

jonhoo · 2017-07-27T21:49:18Z

@arielb1 only for nightly unfortunately, since -Z has now been disabled for stable:

$ env CARGO_INCREMENTAL= cargo +nightly rustc -- -Z time-passes
   Compiling rust-issue-43018 v0.1.0 (file:///home/jon/tmp/rust-issue-43018)
time: 0.000; rss: 53MB  parsing
time: 0.000; rss: 53MB  recursion limit
time: 0.000; rss: 53MB  crate injection
time: 0.000; rss: 53MB  plugin loading
time: 0.000; rss: 53MB  plugin registration
time: 0.020; rss: 75MB  expansion
time: 0.000; rss: 75MB  maybe building test harness
time: 0.000; rss: 75MB  maybe creating a macro crate
time: 0.000; rss: 80MB  creating allocators
time: 0.000; rss: 80MB  checking for inline asm in case the target doesn't support it
time: 0.000; rss: 80MB  early lint checks
time: 0.000; rss: 80MB  AST validation
time: 0.001; rss: 80MB  name resolution
time: 0.000; rss: 80MB  complete gated feature checking
time: 0.000; rss: 80MB  lowering ast -> hir
time: 0.000; rss: 80MB  indexing hir
time: 0.000; rss: 80MB  attribute checking
time: 0.000; rss: 80MB  language item collection
time: 0.000; rss: 80MB  lifetime resolution
time: 0.000; rss: 80MB  looking for entry point
time: 0.000; rss: 80MB  looking for plugin registrar
time: 0.000; rss: 80MB  loop checking
time: 0.000; rss: 80MB  static item recursion checking
time: 0.000; rss: 80MB  compute_incremental_hashes_map
time: 0.000; rss: 80MB  load_dep_graph
time: 0.000; rss: 80MB  stability index
time: 0.000; rss: 80MB  stability checking
time: 0.000; rss: 80MB  type collecting
time: 0.000; rss: 80MB  impl wf inference
time: 0.000; rss: 80MB  coherence checking
time: 0.000; rss: 80MB  variance testing
time: 0.000; rss: 80MB  wf checking
time: 0.000; rss: 80MB  item-types checking
time: 0.031; rss: 106MB item-bodies checking
time: 0.001; rss: 106MB const checking
time: 0.001; rss: 106MB privacy checking
time: 0.000; rss: 106MB intrinsic checking
time: 0.000; rss: 106MB effect checking
time: 0.000; rss: 106MB match checking
time: 0.000; rss: 106MB liveness checking
time: 1.008; rss: 106MB borrow checking
time: 0.000; rss: 106MB reachability checking
time: 0.000; rss: 106MB death checking
time: 0.000; rss: 106MB unused lib feature checking
time: 0.000; rss: 106MB lint checking
time: 0.000; rss: 106MB resolving dependency formats
  time: 0.000; rss: 106MB       write metadata
  time: 16.024; rss: 123MB      translation item collection
  time: 0.001; rss: 123MB       codegen unit partitioning
  time: 0.000; rss: 129MB       write allocator module
time: 46.324; rss: 129MB        translation
time: 0.000; rss: 129MB assert dep graph
time: 0.000; rss: 129MB serialize dep graph
  time: 0.000; rss: 147MB       codegen passes [0]
  time: 0.005; rss: 145MB       codegen passes [1]
  time: 0.014; rss: 147MB       llvm function passes [2]
  time: 0.004; rss: 147MB       llvm module passes [2]
  time: 0.240; rss: 152MB       codegen passes [2]
time: 0.260; rss: 146MB LLVM passes
time: 0.000; rss: 146MB serialize work products
  time: 0.102; rss: 141MB       running linker
time: 0.103; rss: 141MB linking
    Finished dev [unoptimized + debuginfo] target(s) in 47.87 secs

Mark-Simulacrum · 2017-07-27T21:51:10Z

You can pass RUSTC_BOOTSTRAP=1 to get around -Z being disabled. It does look like most of the time is spent in translation, though, so I'm not sure the issue title is valid...

jonhoo · 2017-07-27T22:01:14Z

From the original post:

Ignoring the fact that the translationphase takes forever (tracked in #38528)

The speed of translation has changed somewhat too (note that this issue was originally filed with 1.18.0 as stable), but that doesn't explain the shift in borrow checking time:

$ env CARGO_INCREMENTAL= RUSTC_BOOTSTRAP=1 cargo +stable rustc -- -Z time-passes
   Compiling rust-issue-43018 v0.1.0 (file:///home/jon/tmp/rust-issue-43018)
time: 0.000; rss: 44MB  parsing
time: 0.000; rss: 44MB  recursion limit
time: 0.000; rss: 44MB  crate injection
time: 0.000; rss: 44MB  plugin loading
time: 0.000; rss: 44MB  plugin registration
time: 0.028; rss: 73MB  expansion
time: 0.000; rss: 73MB  maybe building test harness
time: 0.000; rss: 73MB  maybe creating a macro crate
time: 0.000; rss: 73MB  checking for inline asm in case the target doesn't support it
time: 0.000; rss: 73MB  early lint checks
time: 0.000; rss: 73MB  AST validation
time: 0.002; rss: 77MB  name resolution
time: 0.000; rss: 77MB  complete gated feature checking
time: 0.000; rss: 77MB  lowering ast -> hir
time: 0.000; rss: 77MB  indexing hir
time: 0.000; rss: 77MB  attribute checking
time: 0.000; rss: 77MB  language item collection
time: 0.000; rss: 77MB  lifetime resolution
time: 0.000; rss: 77MB  looking for entry point
time: 0.000; rss: 77MB  looking for plugin registrar
time: 0.000; rss: 77MB  loop checking
time: 0.000; rss: 77MB  static item recursion checking
time: 0.000; rss: 77MB  compute_incremental_hashes_map
time: 0.000; rss: 77MB  load_dep_graph
time: 0.000; rss: 77MB  stability index
time: 0.001; rss: 77MB  stability checking
time: 0.000; rss: 77MB  type collecting
time: 0.000; rss: 77MB  impl wf inference
time: 0.000; rss: 77MB  coherence checking
time: 0.000; rss: 77MB  variance testing
time: 0.000; rss: 77MB  wf checking
time: 0.000; rss: 77MB  item-types checking
time: 0.030; rss: 99MB  item-bodies checking
time: 0.001; rss: 99MB  const checking
time: 0.000; rss: 99MB  privacy checking
time: 0.000; rss: 99MB  intrinsic checking
time: 0.000; rss: 99MB  effect checking
time: 0.000; rss: 99MB  match checking
time: 0.000; rss: 99MB  liveness checking
time: 1.107; rss: 99MB  borrow checking
time: 0.000; rss: 99MB  reachability checking
time: 0.000; rss: 99MB  death checking
time: 0.000; rss: 99MB  unused lib feature checking
time: 0.000; rss: 99MB  lint checking
time: 0.000; rss: 99MB  resolving dependency formats
  time: 0.000; rss: 99MB        write metadata
  time: 26.469; rss: 107MB      translation item collection
  time: 0.001; rss: 107MB       codegen unit partitioning
  time: 0.000; rss: 122MB       internalize symbols
time: 40.250; rss: 122MB        translation
time: 0.000; rss: 122MB assert dep graph
time: 0.000; rss: 122MB serialize dep graph
  time: 0.010; rss: 124MB       llvm function passes [0]
  time: 0.004; rss: 124MB       llvm module passes [0]
  time: 0.215; rss: 129MB       codegen passes [0]
  time: 0.000; rss: 129MB       codegen passes [0]
time: 0.231; rss: 129MB LLVM passes
time: 0.000; rss: 129MB serialize work products
  time: 0.099; rss: 125MB       running linker
time: 0.100; rss: 125MB linking
    Finished dev [unoptimized + debuginfo] target(s) in 41.83 secs
$ env CARGO_INCREMENTAL= RUSTC_BOOTSTRAP=1 cargo +1.18.0 rustc -- -Z time-passes
   Compiling futures v0.1.14
   Compiling rust-issue-43018 v0.1.0 (file:///home/jon/tmp/rust-issue-43018)
time: 0.000; rss: 36MB  parsing
time: 0.000; rss: 40MB  recursion limit
time: 0.000; rss: 40MB  crate injection
time: 0.000; rss: 40MB  plugin loading
time: 0.000; rss: 40MB  plugin registration
time: 0.027; rss: 73MB  expansion
time: 0.000; rss: 73MB  maybe building test harness
time: 0.000; rss: 73MB  maybe creating a macro crate
time: 0.000; rss: 73MB  checking for inline asm in case the target doesn't support it
time: 0.000; rss: 73MB  early lint checks
time: 0.000; rss: 73MB  AST validation
time: 0.001; rss: 73MB  name resolution
time: 0.000; rss: 73MB  complete gated feature checking
time: 0.000; rss: 73MB  lowering ast -> hir
time: 0.000; rss: 73MB  indexing hir
time: 0.000; rss: 73MB  attribute checking
time: 0.000; rss: 73MB  language item collection
time: 0.000; rss: 73MB  lifetime resolution
time: 0.000; rss: 73MB  looking for entry point
time: 0.000; rss: 73MB  looking for plugin registrar
time: 0.000; rss: 73MB  region resolution
time: 0.000; rss: 73MB  loop checking
time: 0.000; rss: 73MB  static item recursion checking
time: 0.000; rss: 73MB  compute_incremental_hashes_map
time: 0.000; rss: 73MB  load_dep_graph
time: 0.000; rss: 73MB  stability index
time: 0.000; rss: 73MB  stability checking
time: 0.000; rss: 77MB  type collecting
time: 0.000; rss: 77MB  variance inference
time: 0.000; rss: 77MB  impl wf inference
time: 0.000; rss: 77MB  coherence checking
time: 0.000; rss: 77MB  wf checking
time: 0.000; rss: 77MB  item-types checking
time: 0.031; rss: 95MB  item-bodies checking
time: 0.000; rss: 95MB  const checking
time: 0.000; rss: 95MB  privacy checking
time: 0.000; rss: 95MB  intrinsic checking
time: 0.000; rss: 95MB  effect checking
time: 0.000; rss: 95MB  match checking
time: 0.000; rss: 95MB  liveness checking
time: 0.001; rss: 95MB  MIR dump
  time: 0.000; rss: 95MB        SimplifyCfg
  time: 0.000; rss: 95MB        TypeckMir
  time: 0.000; rss: 95MB        QualifyAndPromoteConstants
  time: 0.000; rss: 95MB        SimplifyBranches
  time: 0.000; rss: 95MB        SimplifyCfg
time: 0.001; rss: 95MB  MIR cleanup and validation
time: 0.000; rss: 95MB  borrow checking
time: 0.000; rss: 95MB  reachability checking
time: 0.000; rss: 95MB  death checking
time: 0.000; rss: 95MB  unused lib feature checking
time: 0.000; rss: 95MB  lint checking
time: 0.000; rss: 95MB  resolving dependency formats
  time: 0.000; rss: 95MB        NoLandingPads
  time: 0.000; rss: 95MB        SimplifyCfg
  time: 0.000; rss: 95MB        EraseRegions
  time: 0.000; rss: 95MB        AddCallGuards
  time: 0.000; rss: 95MB        ElaborateDrops
  time: 0.000; rss: 95MB        NoLandingPads
  time: 0.000; rss: 95MB        SimplifyCfg
  time: 0.000; rss: 95MB        Inline
  time: 0.000; rss: 95MB        InstCombine
  time: 0.000; rss: 95MB        Deaggregator
  time: 0.000; rss: 95MB        CopyPropagation
  time: 0.000; rss: 95MB        SimplifyLocals
  time: 0.000; rss: 95MB        AddCallGuards
  time: 0.000; rss: 95MB        PreTrans
time: 0.001; rss: 95MB  MIR optimisations
  time: 0.000; rss: 95MB        write metadata
  time: 22.824; rss: 101MB      translation item collection
  time: 0.001; rss: 101MB       codegen unit partitioning
  time: 0.000; rss: 120MB       internalize symbols
time: 37.191; rss: 120MB        translation
time: 0.000; rss: 120MB assert dep graph
time: 0.000; rss: 120MB serialize dep graph
  time: 0.009; rss: 120MB       llvm function passes [0]
  time: 0.003; rss: 120MB       llvm module passes [0]
  time: 0.200; rss: 126MB       codegen passes [0]
  time: 0.000; rss: 126MB       codegen passes [0]
time: 0.214; rss: 125MB LLVM passes
time: 0.000; rss: 125MB serialize work products
  time: 0.109; rss: 118MB       running linker
time: 0.110; rss: 118MB linking
    Finished dev [unoptimized + debuginfo] target(s) in 39.68 secs

arielb1 · 2017-07-27T22:06:19Z

I'll look into it. I don't see any slow pass before TIC on old rustc and that's odd.

nikomatsakis · 2017-07-29T19:31:02Z

@jonhoo thanks for investigating, sorry for premature closure :)

jonhoo · 2017-07-29T19:41:08Z

No worries at all — it's worthwhile to check it's not a duplicate/non-bug!

nikomatsakis · 2017-08-24T20:50:35Z

triage: P-medium

Possibly related to #38528

steveklabnik · 2018-12-10T18:41:07Z

This now compiles in 0.7 seconds, with

  time: 0.039; rss: 54MB        borrow checking
  time: 0.000; rss: 54MB        MIR borrow checking

can this be closed?

jonhoo mentioned this issue Jul 2, 2017

Long compile time due to excessively long translation passes #42941

Closed

Mark-Simulacrum added the regression-from-stable-to-nightly Performance or correctness regression from stable to nightly. label Jul 19, 2017

alexcrichton added regression-from-stable-to-stable Performance or correctness regression from one stable version to another. and removed regression-from-stable-to-nightly Performance or correctness regression from stable to nightly. labels Jul 23, 2017

Mark-Simulacrum added I-nominated T-compiler Relevant to the compiler team, which will review and decide on the PR/issue. labels Jul 27, 2017

nikomatsakis closed this as completed Jul 27, 2017

arielb1 reopened this Jul 27, 2017

Mark-Simulacrum added the C-enhancement Category: An issue proposing an enhancement or a PR with one. label Jul 28, 2017

rust-highfive added P-medium Medium priority and removed I-nominated labels Aug 24, 2017

Mark-Simulacrum closed this as completed Dec 10, 2018

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Borrow checking time regression from stable to nightly #43018

Borrow checking time regression from stable to nightly #43018

jonhoo commented Jul 2, 2017

arielb1 commented Jul 3, 2017 •

edited

Loading

alexcrichton commented Jul 23, 2017

Mark-Simulacrum commented Jul 27, 2017

alexcrichton commented Jul 27, 2017

eddyb commented Jul 27, 2017 •

edited

Loading

nikomatsakis commented Jul 27, 2017

jonhoo commented Jul 27, 2017 •

edited

Loading

arielb1 commented Jul 27, 2017

jonhoo commented Jul 27, 2017

Mark-Simulacrum commented Jul 27, 2017

jonhoo commented Jul 27, 2017 •

edited

Loading

arielb1 commented Jul 27, 2017 •

edited

Loading

nikomatsakis commented Jul 29, 2017

jonhoo commented Jul 29, 2017

nikomatsakis commented Aug 24, 2017

steveklabnik commented Dec 10, 2018

Borrow checking time regression from stable to nightly #43018

Borrow checking time regression from stable to nightly #43018

Comments

jonhoo commented Jul 2, 2017

arielb1 commented Jul 3, 2017 • edited Loading

alexcrichton commented Jul 23, 2017

Mark-Simulacrum commented Jul 27, 2017

alexcrichton commented Jul 27, 2017

eddyb commented Jul 27, 2017 • edited Loading

nikomatsakis commented Jul 27, 2017

jonhoo commented Jul 27, 2017 • edited Loading

arielb1 commented Jul 27, 2017

jonhoo commented Jul 27, 2017

Mark-Simulacrum commented Jul 27, 2017

jonhoo commented Jul 27, 2017 • edited Loading

arielb1 commented Jul 27, 2017 • edited Loading

nikomatsakis commented Jul 29, 2017

jonhoo commented Jul 29, 2017

nikomatsakis commented Aug 24, 2017

steveklabnik commented Dec 10, 2018

arielb1 commented Jul 3, 2017 •

edited

Loading

eddyb commented Jul 27, 2017 •

edited

Loading

jonhoo commented Jul 27, 2017 •

edited

Loading

jonhoo commented Jul 27, 2017 •

edited

Loading

arielb1 commented Jul 27, 2017 •

edited

Loading