From 4351a3d906a89ee085b242d1fbdadf90ba2714dd Mon Sep 17 00:00:00 2001 From: Jeremy Ruston Date: Thu, 8 May 2025 15:32:45 +0100 Subject: [PATCH] Add timing information to filter traces --- core/modules/filters.js | 3 ++ .../docs/inspect Operator.tid | 1 + .../filterinspection/filters/SlowFilter.tid | 5 ++++ .../filterinspection/inspect-filter.tid | 8 ++++-- .../filterinspection/modules/startup.js | 28 ++++++++++++++----- .../not-to-be-merged/AdvancedSearch.tid | 3 -- plugins/tiddlywiki/internals/readme.tid | 4 +++ 7 files changed, 40 insertions(+), 12 deletions(-) create mode 100644 plugins/tiddlywiki/internals/filterinspection/filters/SlowFilter.tid delete mode 100644 plugins/tiddlywiki/internals/not-to-be-merged/AdvancedSearch.tid diff --git a/core/modules/filters.js b/core/modules/filters.js index f0e12e01c2..b7d3281ac4 100644 --- a/core/modules/filters.js +++ b/core/modules/filters.js @@ -247,6 +247,9 @@ exports.compileFilter = function(filterString,options) { } catch(e) { // We do not cache this result, so it adjusts along with localization changes return function(source,widget) { + if(wrappers.start) { + wrappers.start(source,widget); + } var resultsArray = [$tw.language.getString("Error/Filter") + ": " + e]; if(wrappers.done) { wrappers.done(resultsArray); diff --git a/plugins/tiddlywiki/internals/filterinspection/docs/inspect Operator.tid b/plugins/tiddlywiki/internals/filterinspection/docs/inspect Operator.tid index ea5a1a7931..fb6d9e6478 100644 --- a/plugins/tiddlywiki/internals/filterinspection/docs/inspect Operator.tid +++ b/plugins/tiddlywiki/internals/filterinspection/docs/inspect Operator.tid @@ -15,6 +15,7 @@ The output JSON object contains the following properties: * `input`: the input titles passed to the filter * `inputFilter`: the filter being inspected * `output`: the output titles resulting from evaluating the filter +* `evaluationTime`: the time taken to evaluate the filter, in milliseconds * `runs`: an array of objects, each of which represents a single run of the filter. Each object contains the following properties: ** `prefixName`: the name of the prefix operator that was used in this run. Shortcut prefixes like `+` and `-` are expanded to their full names, e.g. `and` and `except` ** `input`: the input titles passed to the prefix operator diff --git a/plugins/tiddlywiki/internals/filterinspection/filters/SlowFilter.tid b/plugins/tiddlywiki/internals/filterinspection/filters/SlowFilter.tid new file mode 100644 index 0000000000..025c565d78 --- /dev/null +++ b/plugins/tiddlywiki/internals/filterinspection/filters/SlowFilter.tid @@ -0,0 +1,5 @@ +title: $:/plugins/tiddlywiki/internals/filterinspection/InspectFilterProcedures/Filters/SlowFilter +tags: $:/tags/Filter +filter: [all[tiddlers+shadows]limit[500]] :filter[length[]reverse[]multiply[3.14]] +description: [Internals Plugin] A filter that takes a long time to process + diff --git a/plugins/tiddlywiki/internals/filterinspection/inspect-filter.tid b/plugins/tiddlywiki/internals/filterinspection/inspect-filter.tid index 22387b9eb2..619381c09d 100644 --- a/plugins/tiddlywiki/internals/filterinspection/inspect-filter.tid +++ b/plugins/tiddlywiki/internals/filterinspection/inspect-filter.tid @@ -1,5 +1,5 @@ -title: $:/plugins/tiddlywiki/internals/filterinspection/inspectfiltermacro -tags: $:/tags/Macro +title: $:/plugins/tiddlywiki/internals/filterinspection/InspectFilterProcedures +tags: $:/tags/Global \whitespace trim @@ -93,6 +93,7 @@ tags: $:/tags/Macro
+ Evaluation time <$text text={{{ [jsonget[evaluationTime]fixed[8]] }}}/> milliseconds
\end inspect-operator @@ -102,6 +103,7 @@ tags: $:/tags/Macro
Evaluation <$text text=<> /> + Evaluation time <$text text={{{ [jsonget[evaluationTime]fixed[8]] }}}/> milliseconds
<$list filter="[jsonindexes[operators]nsort[]]" variable="indexOperator"> @@ -145,6 +147,7 @@ tags: $:/tags/Macro <%endif%> + Evaluation time <$text text={{{ [jsonget[evaluationTime]fixed[8]] }}}/> milliseconds
@@ -178,6 +181,7 @@ tags: $:/tags/Macro
Filter <$text text={{{ [jsonget[inputFilter]] }}}/> + Evaluation time <$text text={{{ [jsonget[evaluationTime]fixed[8]] }}}/> milliseconds
<$list filter="[jsonindexes[runs]nsort[]]" variable="indexRun"> diff --git a/plugins/tiddlywiki/internals/filterinspection/modules/startup.js b/plugins/tiddlywiki/internals/filterinspection/modules/startup.js index 3e67778a74..528253c7f1 100644 --- a/plugins/tiddlywiki/internals/filterinspection/modules/startup.js +++ b/plugins/tiddlywiki/internals/filterinspection/modules/startup.js @@ -30,12 +30,7 @@ exports.startup = function() { return wrappers; } // Get the list of filters to be inspected - var inspectedFilters = []; - $tw.wiki.eachTiddlerPlusShadows(function(tiddler,title) { - if(tiddler.fields.tags && tiddler.fields.tags.indexOf("$:/tags/InspectableFilter") !== -1 && !tiddler.fields["draft.of"] && tiddler.fields.text) { - inspectedFilters.push(tiddler.fields.text); - } - }); + var inspectedFilters = $tw.wiki.getTiddlersWithTag("$:/tags/InspectableFilter"); // Check whether this is a filter we want to inspect if(inspectedFilters.indexOf(filterString) === -1) { return wrappers; @@ -111,6 +106,8 @@ function getWrappers(fnDone,inputFilter) { }; // Keep track of where the current run and the current operation are being written var currentRun,currentOperation; + // The starting evaluation time stamp + var filterStartTime; // Compile the filter with wrapper functions to log the details return { start: function(source) { @@ -118,6 +115,8 @@ function getWrappers(fnDone,inputFilter) { source(function(tiddler,title) { output.input.push(title); }); + // Start the timer + filterStartTime = $tw.utils.timer(); }, prefix: function(filterRunPrefixFunction,operationFunction,innerOptions) { // Function to be called at the start of each filter run @@ -132,10 +131,14 @@ function getWrappers(fnDone,inputFilter) { }; // Save the current run so that we can add operations to it currentRun = details.operations; + // Save the start time + var startTime = $tw.utils.timer(); // Get the filter run prefix function var innerResults = filterRunPrefixFunction.call(null,operationFunction,innerOptions); // Invoke the filter run innerResults(results,innerSource,innerWidget); + // Save the end time + details.evaluationTime = $tw.utils.timer(startTime); // Save the results of the filter run details.output = results.toArray(); output.runs.push(details); @@ -146,11 +149,16 @@ function getWrappers(fnDone,inputFilter) { var details = { operators: [] } + // Save the start time + var startTime = $tw.utils.timer(); // Keep track of where the current operation should be being written currentOperation = details.operators; - currentRun.push(details); // Invoke the operation operationFunction(); + // Save the end time + details.evaluationTime = $tw.utils.timer(startTime); + // Save the results of the operation + currentRun.push(details); }, operator: function(operatorFunction,innerSource,innerOperator,innerOptions) { // Record the operator @@ -170,8 +178,12 @@ function getWrappers(fnDone,inputFilter) { }); // Save this operation currentOperation.push(details); + // Save the start time + var startTime = $tw.utils.timer(); // Invoke the operator var innerResults = operatorFunction.apply(null,Array.prototype.slice.call(arguments,1)); + // Save the end time + details.evaluationTime = $tw.utils.timer(startTime); // Make sure the results are an array so that we can store them if(!$tw.utils.isArray(innerResults)) { var resultArray = []; @@ -186,6 +198,8 @@ function getWrappers(fnDone,inputFilter) { return innerResults; }, done: function(results) { + // Store evaluation time + output.evaluationTime = $tw.utils.timer(filterStartTime); // Save the results of the filter evaluation output.output = results; // console.log(`Inspected ${JSON.stringify(output,null,4)}`); diff --git a/plugins/tiddlywiki/internals/not-to-be-merged/AdvancedSearch.tid b/plugins/tiddlywiki/internals/not-to-be-merged/AdvancedSearch.tid deleted file mode 100644 index f7f2f1e264..0000000000 --- a/plugins/tiddlywiki/internals/not-to-be-merged/AdvancedSearch.tid +++ /dev/null @@ -1,3 +0,0 @@ -title: $:/temp/advancedsearch - -[all[shadows+tiddlers]tag[HelloThere]] -[all[shadows+tiddlers]prefix[A]] :filter[tag[Community]] \ No newline at end of file diff --git a/plugins/tiddlywiki/internals/readme.tid b/plugins/tiddlywiki/internals/readme.tid index 9072e3069b..f7b6ab9d06 100644 --- a/plugins/tiddlywiki/internals/readme.tid +++ b/plugins/tiddlywiki/internals/readme.tid @@ -11,6 +11,10 @@ Filter inspection is based on a schematic visualisation that traces all the step ** The ''Observe'' tab allows the current filter to be logged in the background. A new trace is generated every time the filter is evaluated, regardless of the context, if the results are different from previous evaluations * Directly using the `<>` procedure, or the underlying `inspect[]` operator +Note that observing a filter is not the same as logging it. Observing a filter means that the filter is evaluated in the background, and a new trace is generated every time the filter is evaluated, regardless of the context. Logging a filter means that the filter is evaluated in the background, but only if the results are different from previous evaluations. + +Filter observation has a performance impact, and disables certain optimisations such as caching of compiled filters. + !! Inspecting Parse Trees and Widget Trees New preview panes for the tiddler editor that show