Solving parser bottleneck

[bvssvni]

Did some profiling with cmr's hprof library on a 582 loc file:

Timing information for root profiler:
  run - 1 * 1.1s = 1.1s @ 0.9hz
    lazy - 1 * 114ns = 114ns (0.0%)
    parse - 1 * 1.1s = 1.1s (98.3%)
    prelude - 1 * 577.6us = 577.6us (0.1%)
    check - 1 * 38.0us = 38.0us (0.0%)
    convert - 1 * 5.9ms = 5.9ms (0.5%)
    join - 1 * 1.6ms = 1.6ms (0.1%)
    ignored - 1 * 94ns = 94ns (0.0%)

Over 98% of the time is spent parsing.

lib.rs:

let parse_guard = enter("parse");
    let mut data = vec![];
    try!(parse_errstr(syntax_rules, &d, &mut data).map_err(
        |err| format!("In `{}:`\n{}", source, err)
    ));
    drop(parse_guard);

Could figure out what's taking so much time in Piston-Meta.

Develop binary format for Piston-Meta

The meta data is all you need, while the syntax is just to make it readable. Sometimes you reuse the same data over and over, but want to load it as fast as possible.

Could develop an efficient binary format for meta data that loads much quicker. This format can also save space by using a string table. Meta data conversion could happen directly from binary data (changes required in Piston-Meta).

The benefit with this direction is that all meta formats automatically gets a binary format.

Add a bin type to Dyon

Also been thinking about compression and privacy (simple encryption, for example for game content). Then it hit me that perhaps Dyon could get a built-in bin type. Could also use it as a bit vector.

[bvssvni]

Perhaps a better idea: Generate meta data in Rust code.

If you don't need the original source, you might as well include the meta data in the binary executable. This will skip the parsing step completely, while being compatible with all meta data converters in Rust.

[bvssvni]

Added new function for loading directly from meta data in https://github.com/PistonDevelopers/dyon/pull/432. Included an example that generates meta data in Rust code. It works!

Upside is that the binary becomes self contained, with no external code. Loads very fast, because there is no parsing. Skips lifetime and type checks by assuming the source already has been checked. This technique could be used when packaging apps.

Downside is that build times in release mode are scary: 1167.39 seconds for the n-body example. This should be straight forward code for the Rust compiler. I am wondering whether LLVM does some partial evaluation since it knows the input and this could be the reason it takes so long time.

$ time ./target/debug/examples/test
-0.16907514416856514
-0.16908671301860925

real	0m1.378s
user	0m1.368s
sys	0m0.009s

$ time ./target/release/examples/test
-0.16907514416856514
-0.16908671301860925

real	0m0.077s
user	0m0.069s
sys	0m0.006s

$ time ./target/debug/examples/test_compile
-0.16907514416856514
-0.16908671301860925

real	0m0.888s
user	0m0.827s
sys	0m0.014s

$ time ./target/release/examples/test_compile
-0.16907514416856514
-0.16908671301860925

real	0m0.051s
user	0m0.041s
sys	0m0.006s

[nagisa]

Try -Z time-passes flag for rustc to see where time is spent (e.g. export RUSTFLAGS="-Z time-passes"). Feel free to also open an issue on the rustc. I assume that by “meta data” you mean some generated rust code; it might be hitting some super-linear code path somewhere and ideally none would exist; getting rid of it is difficult sometimes.

[bvssvni]

@nagisa Thanks! Running it now.

[bvssvni]

Here is what I got:

$ cargo run --release --example test_compile
   Compiling dyon v0.16.0 (file:///Users/sven/rust/dyon)
time: 0.039	parsing
time: 0.000	recursion limit
time: 0.000	crate injection
time: 0.000	plugin loading
time: 0.000	plugin registration
time: 0.308	expansion
time: 0.000	maybe building test harness
time: 0.001	maybe creating a macro crate
time: 0.000	checking for inline asm in case the target doesn't support it
time: 0.001	complete gated feature checking
time: 0.005	early lint checks
time: 0.001	AST validation
time: 0.013	name resolution
time: 0.007	lowering ast -> hir
time: 0.001	indexing hir
time: 0.001	attribute checking
time: 0.000	language item collection
time: 0.001	lifetime resolution
time: 0.000	looking for entry point
time: 0.000	looking for plugin registrar
time: 0.003	region resolution
time: 0.001	loop checking
time: 0.000	static item recursion checking
time: 0.011	compute_incremental_hashes_map
time: 0.000	load_dep_graph
time: 0.001	stability index
time: 0.002	stability checking
time: 0.001	type collecting
time: 0.000	variance inference
time: 0.000	impl wf inference
time: 0.008	coherence checking
time: 0.000	wf checking
time: 0.001	item-types checking
time: 0.871	item-bodies checking
time: 0.000	drop-impl checking
time: 0.023	const checking
time: 0.002	privacy checking
time: 0.001	intrinsic checking
time: 0.001	effect checking
time: 0.001	match checking
time: 0.003	liveness checking
time: 0.020	rvalue checking
time: 0.498	MIR dump
  time: 0.015	SimplifyCfg
  time: 0.018	QualifyAndPromoteConstants
  time: 0.020	TypeckMir
  time: 0.000	SimplifyBranches
  time: 0.008	SimplifyCfg
time: 0.062	MIR cleanup and validation
time: 0.121	borrow checking
time: 0.000	reachability checking
time: 0.001	death checking
time: 0.000	unused lib feature checking
time: 0.030	lint checking
time: 0.003	resolving dependency formats
  time: 0.000	NoLandingPads
  time: 0.010	SimplifyCfg
  time: 0.010	EraseRegions
  time: 0.003	AddCallGuards
  time: 0.994	ElaborateDrops
  time: 0.000	NoLandingPads
  time: 0.023	SimplifyCfg
  time: 0.005	InstCombine
  time: 0.000	Deaggregator
  time: 0.000	CopyPropagation
  time: 0.006	SimplifyLocals
  time: 0.003	AddCallGuards
  time: 0.000	PreTrans
time: 1.054	MIR optimisations
  time: 0.000	write metadata
  time: 0.208	translation item collection
  time: 0.002	codegen unit partitioning
  time: 0.002	internalize symbols
time: 0.606	translation
time: 0.000	assert dep graph
time: 0.000	serialize dep graph
  time: 34.105	llvm function passes [0]
  time: 1215.066	llvm module passes [0]
  time: 6.071	codegen passes [0]
  time: 0.001	codegen passes [0]
time: 1255.267	LLVM passes
time: 0.000	serialize work products
  time: 0.432	running linker
time: 0.439	linking

The "llvm module passes" part takes most of the time.

One intriguing idea I have: Knowing the input could trigger some optimization in LLVM, where it attempts to evaluate things, thereby essentially doing what the Dyon run-time is supposed to be doing: Executing the program, but at a much slower speed.

[bvssvni]

Opened https://github.com/rust-lang/rust/issues/39082 with updated to latest nightly.