Why does wrappedGrammarRule and invokeRuleWithTry 10x the runtime in browser? #1731
-
Running chevrotain 9.1.0 I'm calling and profiling calling a rule 1000x in browser and getting weird results. I'm just evaluating 1 x 1000.So looking into it, I found this weirdness: formulaWithBinaryOp is a rule. What's going on and is there a way we can optimize this? |
Beta Was this translation helpful? Give feedback.
Replies: 5 comments 3 replies
-
|
moving to discussions |
Beta Was this translation helpful? Give feedback.
-
|
Hi @tyleradams Generally much of the CST building is done inside |
Beta Was this translation helpful? Give feedback.
-
|
Thanks for making it a discussion. I did some performance measuring by adding some performance.now() and log lines to defineRule: RecognizerEngine.prototype.defineRule = function (ruleName, impl, config) {
if (this.selfAnalysisDone) {
throw Error("Grammar rule <" + ruleName + "> may not be defined after the 'performSelfAnalysis' method has been called'\n" +
"Make sure that all grammar rule definitions are done before 'performSelfAnalysis' is called.");
}
var resyncEnabled = (0, utils_1.has)(config, "resyncEnabled")
? config.resyncEnabled
: parser_1.DEFAULT_RULE_CONFIG.resyncEnabled;
var recoveryValueFunc = (0, utils_1.has)(config, "recoveryValueFunc")
? config.recoveryValueFunc
: parser_1.DEFAULT_RULE_CONFIG.recoveryValueFunc;
// performance optimization: Use small integers as keys for the longer human readable "full" rule names.
// this greatly improves Map access time (as much as 8% for some performance benchmarks).
/* tslint:disable */
var shortName = this.ruleShortNameIdx << (keys_1.BITS_FOR_METHOD_TYPE + keys_1.BITS_FOR_OCCURRENCE_IDX);
/* tslint:enable */
this.ruleShortNameIdx++;
this.shortRuleNameToFull[shortName] = ruleName;
this.fullRuleNameToShort[ruleName] = shortName;
function invokeRuleWithTry(args) {
const times = [];
times.push(performance.now());
try {
if (this.outputCst === true) {
impl.apply(this, args);
var cst = this.CST_STACK[this.CST_STACK.length - 1];
this.cstPostRule(cst);
return cst;
}
else {
times.push(performance.now());
const v = impl.apply(this, args);
times.push(performance.now());
console.debug(JSON.stringify({S: "Profiling", id: "invokeRuleWithTry--apply", ruleName, actualDuration: times[times.length-1]-times[times.length - 2]}));
return v;
}
}
catch (e) {
return this.invokeRuleCatch(e, resyncEnabled, recoveryValueFunc);
}
finally {
this.ruleFinallyStateUpdate();
times.push(performance.now());
console.debug(JSON.stringify({S: "Profiling", id: "wrappedGrammarRule--invokeRuleWithTry", ruleName, actualDuration: times[times.length-1]-times[0]}));
}
}
var wrappedGrammarRule = function (idxInCallingRule, args) {
const times = [];
times.push(performance.now());
if (idxInCallingRule === void 0) { idxInCallingRule = 0; }
this.ruleInvocationStateUpdate(shortName, ruleName, idxInCallingRule);
const v = invokeRuleWithTry.call(this, args);
times.push(performance.now());
console.debug(JSON.stringify({S: "Profiling", id: "formulaWithBinaryOp--wrappedGrammarRule", ruleName, actualDuration: times[times.length-1]-times[times.length - 2]}));
return v;
};
var ruleNamePropName = "ruleName";
wrappedGrammarRule[ruleNamePropName] = ruleName;
wrappedGrammarRule["originalGrammarAction"] = impl;
return wrappedGrammarRule;
};which I then captured in tree form above. Does this help? |
Beta Was this translation helpful? Give feedback.
-
Yes, it does.
There may be another thing that could affect performance which is that increasing the size of functions over a certain number of characters |
Beta Was this translation helpful? Give feedback.
-
|
Thanks, so after I stripped out everything but the top and bottom level, I see it's closer to 40x, not 10x: [
{
"name": "apply",
"children": [
{
"name": "formulaWithBinaryOpInternal",
"time": 56.89999985694885,
"count": 3015,
"children": []
}
]
},
{
"name": "parser",
"children": [
{
"name": "parseAsyncWithType",
"time": 2335.0999999046326,
"count": 1,
"children": [
{
"name": "parseAsync",
"time": 2418.400001168251,
"count": 1001,
"children": [
{
"name": "checkFormulaResult",
"time": 13.100001096725464,
"count": 1001,
"children": []
},
{
"name": "formulaWithBinaryOp",
"time": 2375.8999987840652,
"count": 1001,
"children": []
},
{
"name": "lex",
"time": 2.5999999046325684,
"count": 1001,
"children": []
}
]
}
]
}
]
}
]
For reference: $.RULE('formulaWithBinaryOp', () => {
debugger;
console.log(JSON.stringify({S: "Trace", id: "formulaWithBinaryOp--formulaWithBinaryOpInternal--start", now: performance.now()}));
const times = [];
times.push(performance.now());
const infixes = [];
const values = [$.SUBRULE($.formulaWithPercentOp)];
$.MANY(() => {
// Caching Arrays of Alternatives
// https://sap.github.io/chevrotain/docs/guide/performance.html#caching-arrays-of-alternatives
infixes.push($.OR($.c1 ||
(
$.c1 = [
{ALT: () => $.CONSUME(GtOp).image},
{ALT: () => $.CONSUME(EqOp).image},
{ALT: () => $.CONSUME(LtOp).image},
{ALT: () => $.CONSUME(NeqOp).image},
{ALT: () => $.CONSUME(GteOp).image},
{ALT: () => $.CONSUME(LteOp).image},
{ALT: () => $.CONSUME(ConcatOp).image},
{ALT: () => $.CONSUME(PlusOp).image},
{ALT: () => $.CONSUME(MinOp).image},
{ALT: () => $.CONSUME(MulOp).image},
{ALT: () => $.CONSUME(DivOp).image},
{ALT: () => $.CONSUME(ExOp).image}
]
)));
values.push($.SUBRULE2($.formulaWithPercentOp));
});
$.ACTION(() => {
// evaluate
for (const ops of this.binaryOperatorsPrecedence) {
for (let index = 0, length = infixes.length; index < length; index++) {
const infix = infixes[index];
if (!ops.includes(infix)) continue;
infixes.splice(index, 1);
values.splice(index, 2, this.utils.applyInfix(values[index], infix, values[index + 1]));
index--;
length--;
}
}
});
const v = values[0];
times.push(performance.now());
console.log(JSON.stringify({S: "Profiling", id: "apply--formulaWithBinaryOpInternal", actualDuration: times[times.length-1] - times[times.length - 2]}));
console.log(JSON.stringify({S: "Trace", id: "apply--formulaWithBinaryOpInternal--end", now: performance.now()}));
return v;
} times.push(performance.now());
res = await this.parser.formulaWithBinaryOp();
times.push(performance.now());
console.log(JSON.stringify({S: "Profiling", id: "parseAsync--formulaWithBinaryOp", inputText, position, actualDuration: times[times.length-1] - times[times.length - 2]})); |
Beta Was this translation helpful? Give feedback.
-
|
Hello again @tyleradams I suspect the benchmark is still not fully precise. Anyhow I am not sure this is the best way to go about profiling the code, as the inspection itself can modify the performance. If you do stick to measuring via .now() calls I recommend you save the data to some global variable and |
Beta Was this translation helpful? Give feedback.
-
|
@bd82 Your suspicious were correct, thank you! I tried your technique and it showed us the bottleneck was thankfully in our code :). Somehow initial measurements missed this, I do apologize for wasting your time. |
Beta Was this translation helpful? Give feedback.
-
|
Also note there have been some performance upgrades to this wrapper on the master branch
|
Beta Was this translation helpful? Give feedback.
Hello again @tyleradams
I suspect the benchmark is still not fully precise.
Assuming these
JSON.stringifycalls are the culprit for the unexpected results theparseAsync--formulaWithBinaryOpwould then include the time of the last two console.logs and JSON.stringify calls from insideformulaWithBinaryOp.Anyhow I am not sure this is the best way to go about profiling the code, as the inspection itself can modify the performance.
Have you considered trying to use the Chrome Dev Tools profiler?
If you do stick to measuring via .now() calls I recommend you save the data to some global variable and
do all the printing and calculations afterwards...