Add timing information to filter traces

This commit is contained in:
Jeremy Ruston
2025-05-08 15:32:45 +01:00
parent 728243a66a
commit 4351a3d906
7 changed files with 40 additions and 12 deletions

View File

@@ -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);

View File

@@ -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

View File

@@ -0,0 +1,5 @@
title: $:/plugins/tiddlywiki/internals/filterinspection/InspectFilterProcedures/Filters/SlowFilter
tags: $:/tags/Filter
filter: [all[tiddlers+shadows]limit[500]] :filter[<currentTiddler>length[]reverse[]multiply[3.14]]
description: [Internals Plugin] A filter that takes a long time to process

View File

@@ -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
</$list>
</div>
<div class="tc-box-content">
Evaluation time <span class="tc-pill"><$text text={{{ [<jsonOperator>jsonget[evaluationTime]fixed[8]] }}}/></span> milliseconds
</div>
</div>
\end inspect-operator
@@ -102,6 +103,7 @@ tags: $:/tags/Macro
<div class="tc-box-header">
<span class="">Evaluation</span>
<span class="tc-pill"><$text text=<<indexOperation>> /></span>
Evaluation time <span class="tc-pill"><$text text={{{ [<jsonOperation>jsonget[evaluationTime]fixed[8]] }}}/></span> milliseconds
</div>
<div class="tc-box-content">
<$list filter="[<jsonOperation>jsonindexes[operators]nsort[]]" variable="indexOperator">
@@ -145,6 +147,7 @@ tags: $:/tags/Macro
</span>
</$list>
<%endif%>
Evaluation time <span class="tc-pill"><$text text={{{ [<jsonRun>jsonget[evaluationTime]fixed[8]] }}}/></span> milliseconds
</div>
<div class="tc-box-content">
<div class="tc-inspect-operations-wrapper">
@@ -178,6 +181,7 @@ tags: $:/tags/Macro
<div class="tc-box-header">
Filter
<span class="tc-pill"><$text text={{{ [<jsonOutput>jsonget[inputFilter]] }}}/></span>
Evaluation time <span class="tc-pill"><$text text={{{ [<jsonOutput>jsonget[evaluationTime]fixed[8]] }}}/></span> milliseconds
</div>
<div class="tc-box-content">
<$list filter="[<jsonOutput>jsonindexes[runs]nsort[]]" variable="indexRun">

View File

@@ -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)}`);

View File

@@ -1,3 +0,0 @@
title: $:/temp/advancedsearch
[all[shadows+tiddlers]tag[HelloThere]] -[all[shadows+tiddlers]prefix[A]] :filter[<currentTiddler>tag[Community]]

View File

@@ -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 `<<inspect-filter>>` 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