From b12ac18481356313cf834a5509e271cd7c7de4e5 Mon Sep 17 00:00:00 2001 From: Jeremy Wall Date: Mon, 2 Jul 2018 18:30:17 -0500 Subject: [PATCH] FEATURE: Benchmarking and tracing Benchmarks and tracing as a compile time feature. This should help while tracking down performance bottlenecks. --- Cargo.toml | 28 +++++++- examples/test.ucg | 5 ++ src/benches/parse.rs | 125 ++++++++++++++++++++++++++++++++++++ src/parse/mod.rs | 148 +++++++++++++++++++++++++++---------------- 4 files changed, 251 insertions(+), 55 deletions(-) create mode 100644 src/benches/parse.rs diff --git a/Cargo.toml b/Cargo.toml index 71d3c99..e568b48 100644 --- a/Cargo.toml +++ b/Cargo.toml @@ -15,12 +15,38 @@ version = "^3.2" [dependencies] nom_locate = "^0.1.1" clap = "~2.26.0" -serde_json = "~1.0.9" +serde_json = "~1.0.9" + +[dev-dependencies] +bencher = "~0.1.5" +cpuprofiler = "0.0.3" + +[[bench]] +name = "parse" +harness = false +path = "src/benches/parse.rs" + +[profile.bench] +opt-level = 0 +debug = true +rpath = false +lto = false +debug-assertions = false +codegen-units = 16 +incremental = false +overflow-checks = false + +[profile.release] +debug = true [lib] name = "ucglib" path = "src/lib.rs" +bench = false [[bin]] name = "ucg" path = "src/main.rs" + +[features] +tracing = [] \ No newline at end of file diff --git a/examples/test.ucg b/examples/test.ucg index 32999b7..1d1bdc8 100644 --- a/examples/test.ucg +++ b/examples/test.ucg @@ -23,6 +23,11 @@ let connstr_mapper = macro (item) => { let db_conns = map connstr_mapper.str [db_conn1, db_conn2]; +let cplx_list = [ + {foo = 1}, + {bar = {foo=1}}, +]; + // Our server configuration. let server_config = { db_conn1 = db_conns.0, // connection one diff --git a/src/benches/parse.rs b/src/benches/parse.rs new file mode 100644 index 0000000..56ccf61 --- /dev/null +++ b/src/benches/parse.rs @@ -0,0 +1,125 @@ +#![allow(unused_must_use)] + +#[macro_use] +extern crate bencher; +extern crate cpuprofiler; +extern crate nom_locate; +extern crate ucglib; + +use bencher::Bencher; +//use cpuprofiler::PROFILER; + +macro_rules! bench_parse { + ($parsemac:ident($i:expr), $b:expr) => { + bench_parse!($i, $parsemac, $b) + }; + ($i:expr, $f:expr, $b:expr) => { + let input = nom_locate::LocatedSpan::new($i); + let val = tokenize(input).unwrap(); + $b.iter(|| { + $f(TokenIter { + source: val.as_slice(), + }) + }); + }; +} + +use ucglib::parse::*; +use ucglib::tokenizer::*; + +fn do_parse(i: &str) { + parse(nom_locate::LocatedSpan::new(i)); +} + +fn parse_int(b: &mut Bencher) { + b.iter(|| do_parse("1;")); +} + +fn parse_whole_float(b: &mut Bencher) { + b.iter(|| do_parse("1.0;")); +} + +fn parse_pre_partial_float(b: &mut Bencher) { + b.iter(|| do_parse("1.;")); +} + +fn parse_post_partial_float(b: &mut Bencher) { + b.iter(|| do_parse(".0;")); +} + +fn parse_bareword(b: &mut Bencher) { + b.iter(|| do_parse("foo;")); +} + +fn parse_string(b: &mut Bencher) { + b.iter(|| do_parse("\"foo\";")); +} + +fn parse_simple_tuple(b: &mut Bencher) { + b.iter(|| do_parse("{foo = 1, bar = \"2\",};")); +} + +fn parse_complex_tuple(b: &mut Bencher) { + b.iter(|| do_parse("{foo = 1, { bar = \"2\",}};")); +} + +fn parse_simple_list(b: &mut Bencher) { + //PROFILER + // .lock() + // .unwrap() + // .start("./my-parse_list.profile") + // .unwrap(); + b.iter(|| do_parse("[1, 2, 3];")); + //PROFILER.lock().unwrap().stop().unwrap(); +} + +fn parse_complex_tuple_list(b: &mut Bencher) { + //PROFILER + // .lock() + // .unwrap() + // .start("./my-parse_list.profile") + // .unwrap(); + let input = "[{foo=1}, {bar=2}, {quux=4}];"; + b.iter(|| do_parse(input)); + //bench_parse!(non_op_expression(input), b); + //PROFILER.lock().unwrap().stop().unwrap(); +} + +fn parse_complex_nested_list(b: &mut Bencher) { + //PROFILER + // .lock() + // .unwrap() + // .start("./my-parse_list.profile") + // .unwrap(); + let input = "[[1,2], [3,4], [4,5]];"; + b.iter(|| do_parse(input)); + //bench_parse!(non_op_expression(input), b); + //PROFILER.lock().unwrap().stop().unwrap(); +} + +fn parse_selector_tuple_head(b: &mut Bencher) { + b.iter(|| do_parse("{foo=1}.foo;")); +} + +fn parse_selector_symbol_head(b: &mut Bencher) { + b.iter(|| do_parse("bar.foo;")); +} + +benchmark_group!( + benches, + parse_int, + parse_whole_float, + parse_pre_partial_float, + parse_post_partial_float, + parse_bareword, + parse_string, + parse_simple_tuple, + parse_complex_tuple, + parse_simple_list, + parse_complex_tuple_list, + parse_complex_nested_list, + parse_selector_tuple_head, + parse_selector_symbol_head, +); + +benchmark_main!(benches); diff --git a/src/parse/mod.rs b/src/parse/mod.rs index 14be443..ce36089 100644 --- a/src/parse/mod.rs +++ b/src/parse/mod.rs @@ -27,8 +27,39 @@ use tokenizer::*; type NomResult<'a, O> = nom::IResult, O, error::Error>; -type ParseResult = Result; +#[cfg(feature = "tracing")] +const ENABLE_TRACE: bool = true; +#[cfg(not(feature = "tracing"))] +const ENABLE_TRACE: bool = false; +type ParseResult = Result; +macro_rules! trace_nom { + ($i:expr, $rule:ident!( $($args:tt)* )) => { + { + if ENABLE_TRACE { + eprintln!("Entering Rule: {:?} {:?}", stringify!($rule), $i); + } + let result = $rule($i, $($args)* ); + if ENABLE_TRACE { + eprintln!("Exiting Rule: {:?}", stringify!($rule)); + } + result + } + }; + + ($i:expr, $rule:ident) => { + { + if ENABLE_TRACE { + eprintln!("Entering Rule: {:?} {:?}", stringify!($rule), $i); + } + let result = call!($i, $rule); + if ENABLE_TRACE { + eprintln!("Exiting Rule: {:?}", stringify!($rule)); + } + result + } + }; +} fn symbol_to_value(s: &Token) -> ParseResult { Ok(Value::Symbol(value_node!( s.fragment.to_string(), @@ -300,24 +331,27 @@ named!(empty_value, ) ); -named!(compound_value, - alt!(list_value | tuple) +named!(pub compound_value, + alt_peek!( + punct!("[") => trace_nom!(list_value) | + punct!("{") => trace_nom!(tuple) + ) ); named!(scalar_value, alt!( - boolean_value | - empty_value | - number | - quoted_value + trace_nom!(boolean_value) | + trace_nom!(empty_value) | + trace_nom!(number) | + trace_nom!(quoted_value) ) ); -named!(value, +named!(pub value, alt!( - selector_value - | compound_value - | scalar_value + trace_nom!(selector_value) + | trace_nom!(compound_value) + | trace_nom!(scalar_value) ) ); @@ -327,7 +361,7 @@ fn value_to_expression(v: Value) -> ParseResult { named!(simple_expression, map_res!( - value, + trace_nom!(value), value_to_expression ) ); @@ -343,9 +377,9 @@ fn tuple_to_binary_expression( })) } -/// do_binary_expr implements precedence based parsing where the more tightly bound parsers -/// are passed in as lowerrule parsers. We default to grouped_expression and simple_expression as -/// the most tightly bound expressions. +/// do_binary_expr implements precedence based parsing where the more tightly bound +/// parsers are passed in as lowerrule parsers. We default to any non_op_expression +/// as the most tightly bound expressions. macro_rules! do_binary_expr { ($i:expr, $oprule:ident!( $($args:tt)* )) => { do_binary_expr!($i, $oprule!($($args)*), non_op_expression) @@ -385,7 +419,7 @@ named!(sum_expression, alt_peek!( punct!("+") => math_op_type | punct!("-") => math_op_type), - alt!(product_expression | simple_expression | grouped_expression)) + alt!(trace_nom!(product_expression) | trace_nom!(simple_expression) | trace_nom!(grouped_expression))) ); named!(product_expression, @@ -397,7 +431,7 @@ named!(product_expression, ); named!(math_expression, - alt!(sum_expression | product_expression) + alt!(trace_nom!(sum_expression) | trace_nom!(product_expression)) ); // TODO(jwall): Change comparison operators to use the do_binary_expr! with precedence? @@ -427,9 +461,9 @@ named!(compare_expression, map_res!( do_parse!( pos: pos >> - left: alt!(math_expression | non_op_expression) >> + left: alt!(trace_nom!(math_expression) | trace_nom!(non_op_expression)) >> typ: compare_op_type >> - right: alt!(math_expression | non_op_expression) >> + right: alt!(trace_nom!(math_expression) | trace_nom!(non_op_expression)) >> (pos, typ, left, right) ), tuple_to_compare_expression @@ -438,7 +472,7 @@ named!(compare_expression, // FIXME(jwall): This is really *really* slow. named!(op_expression, - alt!(math_expression | compare_expression) + alt!(trace_nom!(math_expression) | trace_nom!(compare_expression)) ); fn expression_to_grouped_expression(e: Expression) -> ParseResult { @@ -447,7 +481,7 @@ fn expression_to_grouped_expression(e: Expression) -> ParseResult { named!(grouped_expression, map_res!( - preceded!(punct!("("), terminated!(expression, punct!(")"))), + preceded!(punct!("("), terminated!(trace_nom!(expression), punct!(")"))), expression_to_grouped_expression ) ); @@ -557,9 +591,9 @@ named!(copy_expression, map_res!( do_parse!( pos: pos >> - selector: selector_list >> + selector: trace_nom!(selector_list) >> punct!("{") >> - fields: field_list >> + fields: trace_nom!(field_list) >> opt_res!(punct!(",")) >> // noms opt! macro does not preserve error types properly but this one does. punct!("}") >> (SelectorDef::new(selector, pos.line, pos.column as usize), fields) @@ -597,10 +631,10 @@ named!(macro_expression, pos: pos >> word!("macro") >> punct!("(") >> - arglist: arglist >> + arglist: trace_nom!(arglist) >> punct!(")") >> punct!("=>") >> - map: tuple >> + map: trace_nom!(tuple) >> (pos, arglist, map) ), tuple_to_macro @@ -627,9 +661,9 @@ named!(select_expression, map_res!( do_parse!( start: word!("select") >> - val: terminated!(expression, punct!(",")) >> - default: terminated!(expression, punct!(",")) >> - map: tuple >> + val: terminated!(trace_nom!(expression), punct!(",")) >> + default: terminated!(trace_nom!(expression), punct!(",")) >> + map: trace_nom!(tuple) >> (start.pos.clone(), val, default, map) ), tuple_to_select @@ -650,7 +684,7 @@ named!(format_expression, tmpl: match_type!(STR) >> punct!("%") >> punct!("(") >> - args: separated_list!(punct!(","), expression) >> + args: separated_list!(punct!(","), trace_nom!(expression)) >> punct!(")") >> (tmpl, args) ), @@ -685,7 +719,7 @@ fn vec_to_selector_value(t: (Position, SelectorList)) -> ParseResult { named!(selector_value, map_res!( do_parse!( - sl: selector_list >> + sl: trace_nom!(selector_list) >> (sl.head.pos().clone(), sl) ), vec_to_selector_value @@ -695,9 +729,9 @@ named!(selector_value, named!(call_expression, map_res!( do_parse!( - macroname: selector_value >> + macroname: trace_nom!(selector_value) >> punct!("(") >> - args: separated_list!(punct!(","), expression) >> + args: separated_list!(punct!(","), trace_nom!(expression)) >> punct!(")") >> (macroname.pos().clone(), macroname, args) ), @@ -797,36 +831,41 @@ named!(list_op_expression, do_parse!( pos: pos >> optype: alt!(word!("map") | word!("filter")) >> - macroname: selector_value >> - list: symbol_or_list >> + macroname: trace_nom!(selector_value) >> + list: trace_nom!(symbol_or_list) >> (pos, optype, macroname, list) ), tuple_to_list_op ) ); -named!(non_op_expression, - alt!(list_op_expression | - macro_expression | - format_expression | - select_expression | - call_expression | - copy_expression | - grouped_expression | - simple_expression) +named!(pub non_op_expression, + alt!(trace_nom!(list_op_expression) | + trace_nom!(macro_expression) | + trace_nom!(format_expression) | + trace_nom!(select_expression) | + trace_nom!(grouped_expression) | + trace_nom!(call_expression) | + trace_nom!(copy_expression) | + trace_nom!(simple_expression)) ); -named!(expression, - alt_complete!(op_expression | non_op_expression) +// TODO(jwall): Because we have to parse an op_expression before a non_op_expression +// this parser is really slow. The reason is that the op_expression is unable to fail +// quickly enough and wastes a lot of parsing time before it realizes that this is not +// an operator expression. Fixing this probably means hand rolling this parsing +// function so we can identify early whether this is an op_expression or not. +named!(pub expression, + alt_complete!(trace_nom!(op_expression) | trace_nom!(non_op_expression)) ); fn expression_to_statement(v: Expression) -> ParseResult { Ok(Statement::Expression(v)) } -named!(expression_statement, +named!(pub expression_statement, map_res!( - terminated!(expression, punct!(";")), + terminated!(trace_nom!(expression), punct!(";")), expression_to_statement ) ); @@ -843,7 +882,7 @@ named!(let_stmt_body, do_parse!( name: match_type!(BAREWORD) >> punct!("=") >> - val: expression >> + val: trace_nom!(expression) >> punct!(";") >> (name, val)), tuple_to_let @@ -859,7 +898,7 @@ named!(let_statement, error::Error::new( "Invalid syntax for let binding", error::ErrorType::ParseError, pos)), - let_stmt_body) >> + trace_nom!(let_stmt_body)) >> (stmt) ) ); @@ -893,7 +932,7 @@ named!(import_statement, error::Error::new( "Invalid syntax for import", error::ErrorType::ParseError, pos)), - import_stmt_body) >> + trace_nom!(import_stmt_body)) >> (stmt) ) ); @@ -916,10 +955,11 @@ named!(assert_statement, //trace_macros!(true); fn statement(i: TokenIter) -> nom::IResult { return alt_peek!(i, - word!("assert") => assert_statement | - word!("import") => import_statement | - word!("let") => let_statement | - expression_statement); + word!("assert") => trace_nom!(assert_statement) | + word!("import") => trace_nom!(import_statement) | + word!("let") => trace_nom!(let_statement) | + trace_nom!(expression_statement) + ); } //trace_macros!(false);