Skip to content

Count and report time taken by MIR passes #36296

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Merged
merged 1 commit into from
Sep 7, 2016
Merged

Conversation

nagisa
Copy link
Member

@nagisa nagisa commented Sep 6, 2016

There’s some desire for deeper introspectability into what MIR passes cost us.

-Z time-passes after this PR:

   Compiling test_shim v0.1.0 (file:///home/nagisa/Documents/rust/rust/src/rustc/test_shim)
time: 0.000; rss: 29MB  parsing
time: 0.000; rss: 29MB  configuration
time: 0.000; rss: 29MB  recursion limit
time: 0.000; rss: 29MB  crate injection
time: 0.000; rss: 29MB  plugin loading
time: 0.000; rss: 29MB  plugin registration
time: 0.032; rss: 54MB  expansion
time: 0.000; rss: 54MB  maybe building test harness
time: 0.000; rss: 54MB  assigning node ids
time: 0.000; rss: 54MB  checking for inline asm in case the target doesn't support it
time: 0.000; rss: 54MB  complete gated feature checking
time: 0.000; rss: 54MB  collecting defs
time: 0.004; rss: 54MB  external crate/lib resolution
time: 0.000; rss: 54MB  early lint checks
time: 0.000; rss: 54MB  AST validation
time: 0.001; rss: 54MB  name resolution
time: 0.000; rss: 54MB  lowering ast -> hir
time: 0.000; rss: 56MB  indexing hir
time: 0.000; rss: 56MB  attribute checking
time: 0.000; rss: 56MB  language item collection
time: 0.000; rss: 56MB  lifetime resolution
time: 0.000; rss: 56MB  looking for entry point
time: 0.000; rss: 56MB  looking for plugin registrar
time: 0.000; rss: 56MB  region resolution
time: 0.000; rss: 56MB  loop checking
time: 0.000; rss: 56MB  static item recursion checking
time: 0.000; rss: 56MB  compute_incremental_hashes_map
time: 0.000; rss: 56MB  load_dep_graph
time: 0.000; rss: 56MB  type collecting
time: 0.000; rss: 56MB  variance inference
time: 0.011; rss: 59MB  coherence checking
time: 0.000; rss: 59MB  wf checking
time: 0.000; rss: 59MB  item-types checking
time: 0.000; rss: 59MB  item-bodies checking
time: 0.000; rss: 59MB  drop-impl checking
time: 0.000; rss: 59MB  const checking
time: 0.000; rss: 59MB  privacy checking
time: 0.000; rss: 59MB  stability index
time: 0.000; rss: 59MB  intrinsic checking
time: 0.000; rss: 59MB  effect checking
time: 0.000; rss: 59MB  match checking
time: 0.000; rss: 59MB  liveness checking
time: 0.000; rss: 59MB  rvalue checking
time: 0.000; rss: 59MB  MIR dump
  time: 0.000; rss: 59MB    SimplifyCfg
  time: 0.000; rss: 59MB    QualifyAndPromoteConstants
  time: 0.000; rss: 59MB    TypeckMir
  time: 0.000; rss: 59MB    SimplifyBranches
  time: 0.000; rss: 59MB    SimplifyCfg
time: 0.000; rss: 59MB  MIR passes
time: 0.000; rss: 59MB  borrow checking
time: 0.000; rss: 59MB  reachability checking
time: 0.000; rss: 59MB  death checking
time: 0.000; rss: 59MB  stability checking
time: 0.000; rss: 59MB  unused lib feature checking
time: 0.000; rss: 59MB  lint checking
time: 0.000; rss: 59MB  resolving dependency formats
  time: 0.000; rss: 59MB    NoLandingPads
  time: 0.000; rss: 59MB    SimplifyCfg
  time: 0.000; rss: 59MB    EraseRegions
  time: 0.000; rss: 59MB    AddCallGuards
  time: 0.000; rss: 59MB    ElaborateDrops
  time: 0.000; rss: 59MB    NoLandingPads
  time: 0.000; rss: 59MB    SimplifyCfg
  time: 0.000; rss: 59MB    Deaggregator
  time: 0.000; rss: 59MB    AddCallGuards
  time: 0.000; rss: 59MB    PreTrans
time: 0.000; rss: 59MB  Prepare MIR codegen passes
  time: 0.000; rss: 59MB    write metadata
  time: 0.000; rss: 61MB    translation item collection
  time: 0.000; rss: 61MB    codegen unit partitioning
  time: 0.000; rss: 61MB    internalize symbols
time: 0.007; rss: 61MB  translation
time: 0.000; rss: 61MB  assert dep graph
time: 0.000; rss: 61MB  serialize dep graph
time: 0.000; rss: 61MB  llvm function passes [2]
time: 0.000; rss: 61MB  llvm function passes [3]
time: 0.000; rss: 61MB  llvm function passes [1]
time: 0.000; rss: 61MB  llvm function passes [0]
time: 0.000; rss: 61MB  llvm module passes [2]
time: 0.000; rss: 61MB  llvm module passes [1]
time: 0.000; rss: 61MB  llvm module passes [0]
time: 0.000; rss: 61MB  llvm module passes [3]
time: 0.001; rss: 62MB  codegen passes [1]
time: 0.001; rss: 62MB  codegen passes [2]
time: 0.001; rss: 62MB  codegen passes [0]
time: 0.001; rss: 62MB  codegen passes [3]
time: 0.001; rss: 63MB  codegen passes [1]
time: 0.005; rss: 63MB  LLVM passes
time: 0.000; rss: 63MB  serialize work products
time: 0.001; rss: 63MB  linking

r? @eddyb or @nikomatsakis

cc @nrc, @Mark-Simulacrum

@Mark-Simulacrum
Copy link
Member

@nagisa Can we get a -Z time-passes log without this PR; for clarity as to what has changed?

Looks great otherwise, thanks! (From a performance monitoring perspective, anyway, I'm not qualified to review the code).

@nagisa
Copy link
Member Author

nagisa commented Sep 6, 2016

@Mark-Simulacrum This PR outputs more information under the MIR passes and Prepare MIR codegen passes steps. Namely all the slightly indented lines in these two sections are new:

  time: 0.000; rss: 59MB    SimplifyCfg
  time: 0.000; rss: 59MB    QualifyAndPromoteConstants
  time: 0.000; rss: 59MB    TypeckMir
  time: 0.000; rss: 59MB    SimplifyBranches
  time: 0.000; rss: 59MB    SimplifyCfg
time: 0.000; rss: 59MB  MIR passes
  time: 0.000; rss: 59MB    NoLandingPads
  time: 0.000; rss: 59MB    SimplifyCfg
  time: 0.000; rss: 59MB    EraseRegions
  time: 0.000; rss: 59MB    AddCallGuards
  time: 0.000; rss: 59MB    ElaborateDrops
  time: 0.000; rss: 59MB    NoLandingPads
  time: 0.000; rss: 59MB    SimplifyCfg
  time: 0.000; rss: 59MB    Deaggregator
  time: 0.000; rss: 59MB    AddCallGuards
  time: 0.000; rss: 59MB    PreTrans
time: 0.000; rss: 59MB  Prepare MIR codegen passes

@Mark-Simulacrum
Copy link
Member

I'm thinking it might be a good idea to make it an expectation that major additions to the codebase (e.g. new passes) require additions to time passes.

Should I write an RFC/Pre-RFC/irlo post for this, or is this a change/requirement that is just "we should start doing this"?

@eddyb
Copy link
Member

eddyb commented Sep 6, 2016

@bors r+

@bors
Copy link
Collaborator

bors commented Sep 6, 2016

📌 Commit 0520698 has been approved by eddyb

@nagisa
Copy link
Member Author

nagisa commented Sep 6, 2016

@Mark-Simulacrum I feel like status quo is quite all right. As far as MIR passes are concerned, this PR will make them appear automatically as they are registered. As far as other things go, addition to top-level pipeline gets a timing entry by convention and when there’s some interest in more detailed data, the measurements can be introduced in a similar manner to this PR.

@bors
Copy link
Collaborator

bors commented Sep 7, 2016

⌛ Testing commit 0520698 with merge 2819eca...

bors added a commit that referenced this pull request Sep 7, 2016
Count and report time taken by MIR passes

There’s some desire for deeper introspectability into what MIR passes cost us.

-Z time-passes after this PR:

```
   Compiling test_shim v0.1.0 (file:///home/nagisa/Documents/rust/rust/src/rustc/test_shim)
time: 0.000; rss: 29MB	parsing
time: 0.000; rss: 29MB	configuration
time: 0.000; rss: 29MB	recursion limit
time: 0.000; rss: 29MB	crate injection
time: 0.000; rss: 29MB	plugin loading
time: 0.000; rss: 29MB	plugin registration
time: 0.032; rss: 54MB	expansion
time: 0.000; rss: 54MB	maybe building test harness
time: 0.000; rss: 54MB	assigning node ids
time: 0.000; rss: 54MB	checking for inline asm in case the target doesn't support it
time: 0.000; rss: 54MB	complete gated feature checking
time: 0.000; rss: 54MB	collecting defs
time: 0.004; rss: 54MB	external crate/lib resolution
time: 0.000; rss: 54MB	early lint checks
time: 0.000; rss: 54MB	AST validation
time: 0.001; rss: 54MB	name resolution
time: 0.000; rss: 54MB	lowering ast -> hir
time: 0.000; rss: 56MB	indexing hir
time: 0.000; rss: 56MB	attribute checking
time: 0.000; rss: 56MB	language item collection
time: 0.000; rss: 56MB	lifetime resolution
time: 0.000; rss: 56MB	looking for entry point
time: 0.000; rss: 56MB	looking for plugin registrar
time: 0.000; rss: 56MB	region resolution
time: 0.000; rss: 56MB	loop checking
time: 0.000; rss: 56MB	static item recursion checking
time: 0.000; rss: 56MB	compute_incremental_hashes_map
time: 0.000; rss: 56MB	load_dep_graph
time: 0.000; rss: 56MB	type collecting
time: 0.000; rss: 56MB	variance inference
time: 0.011; rss: 59MB	coherence checking
time: 0.000; rss: 59MB	wf checking
time: 0.000; rss: 59MB	item-types checking
time: 0.000; rss: 59MB	item-bodies checking
time: 0.000; rss: 59MB	drop-impl checking
time: 0.000; rss: 59MB	const checking
time: 0.000; rss: 59MB	privacy checking
time: 0.000; rss: 59MB	stability index
time: 0.000; rss: 59MB	intrinsic checking
time: 0.000; rss: 59MB	effect checking
time: 0.000; rss: 59MB	match checking
time: 0.000; rss: 59MB	liveness checking
time: 0.000; rss: 59MB	rvalue checking
time: 0.000; rss: 59MB	MIR dump
  time: 0.000; rss: 59MB	SimplifyCfg
  time: 0.000; rss: 59MB	QualifyAndPromoteConstants
  time: 0.000; rss: 59MB	TypeckMir
  time: 0.000; rss: 59MB	SimplifyBranches
  time: 0.000; rss: 59MB	SimplifyCfg
time: 0.000; rss: 59MB	MIR passes
time: 0.000; rss: 59MB	borrow checking
time: 0.000; rss: 59MB	reachability checking
time: 0.000; rss: 59MB	death checking
time: 0.000; rss: 59MB	stability checking
time: 0.000; rss: 59MB	unused lib feature checking
time: 0.000; rss: 59MB	lint checking
time: 0.000; rss: 59MB	resolving dependency formats
  time: 0.000; rss: 59MB	NoLandingPads
  time: 0.000; rss: 59MB	SimplifyCfg
  time: 0.000; rss: 59MB	EraseRegions
  time: 0.000; rss: 59MB	AddCallGuards
  time: 0.000; rss: 59MB	ElaborateDrops
  time: 0.000; rss: 59MB	NoLandingPads
  time: 0.000; rss: 59MB	SimplifyCfg
  time: 0.000; rss: 59MB	Deaggregator
  time: 0.000; rss: 59MB	AddCallGuards
  time: 0.000; rss: 59MB	PreTrans
time: 0.000; rss: 59MB	Prepare MIR codegen passes
  time: 0.000; rss: 59MB	write metadata
  time: 0.000; rss: 61MB	translation item collection
  time: 0.000; rss: 61MB	codegen unit partitioning
  time: 0.000; rss: 61MB	internalize symbols
time: 0.007; rss: 61MB	translation
time: 0.000; rss: 61MB	assert dep graph
time: 0.000; rss: 61MB	serialize dep graph
time: 0.000; rss: 61MB	llvm function passes [2]
time: 0.000; rss: 61MB	llvm function passes [3]
time: 0.000; rss: 61MB	llvm function passes [1]
time: 0.000; rss: 61MB	llvm function passes [0]
time: 0.000; rss: 61MB	llvm module passes [2]
time: 0.000; rss: 61MB	llvm module passes [1]
time: 0.000; rss: 61MB	llvm module passes [0]
time: 0.000; rss: 61MB	llvm module passes [3]
time: 0.001; rss: 62MB	codegen passes [1]
time: 0.001; rss: 62MB	codegen passes [2]
time: 0.001; rss: 62MB	codegen passes [0]
time: 0.001; rss: 62MB	codegen passes [3]
time: 0.001; rss: 63MB	codegen passes [1]
time: 0.005; rss: 63MB	LLVM passes
time: 0.000; rss: 63MB	serialize work products
time: 0.001; rss: 63MB	linking
```

r? @eddyb or @nikomatsakis

cc @nrc, @Mark-Simulacrum
@bors bors merged commit 0520698 into rust-lang:master Sep 7, 2016
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

4 participants