"Total Time" is wrong for nested filters?

[yaisog]

It looks like "Total Time" is calculated as the sum of all individual entries in the filter list. This can be significantly off when filters are nested, I think. Take e.g. these definitions from a search tiddler:

\define suffix-regexp() .+?([\+|\*|\#]*)
\define suffix() [<termStore>get[text]search-replace:g:regexp<suffix-regexp>,[$1]]
\define journal-subfilter() [subfilter<suffix>search[+]] :then[[]] :else[tag[$:/tags/Journal]]
\define search-subfilter() [subfilter<suffix>search[*]] :then[search:*<searchTerm>] :else[search:title,caption<searchTerm>]
\define all-results() [all[tiddlers]!is[system]] -[tag[$:/tags/TiddlerTask]] -[subfilter<journal-subfilter>] +[subfilter<search-subfilter>]
\define filtered-results() [subfilter<all-results>] +[subfilter{$:/mwi/ui/GoTo/config/sort}]

Each usage of filtered-results will result in all the other filters being called. In the performance report it will show this (only a portion of the output is shown): (the third line is the contents of "$:/mwi/ui/GoTo/config/sort" in the second line, the fourth line is the chrono-subfilter called in the third line)

As far as I can tell, in this list, the runtime for each filter includes the runtime of its subfilters. So, if you just add them all up, you'll count the runtime of the subfilter twice – once its self time and once for the calling filter.

Since all of the above lines are subfilters of the first line, the total time would be 304 ms, not 1.3 s as reported in "Total Time".

I'm not sure this is something that can be fixed easily, but maybe you can add a note to the docs?

[EvidentlyCube]

@yaisog Oh wow, great catch! It should be simple to fix, I'll make it so that subfilters are still displayed but displayed slightly differently to make it obvious they were executed as a subfilter expression, then I'll make it so that they're not included in the summary in the first tab to avoid double counting them.

I'll take care of this in about a week or two.

[EvidentlyCube]

@yaisog I've addressed it in now released 1.1.3:

• The subfilter executions are now clearly marked with a tooltip-title explaining things.
• The subfilter execution is still counted in the main filter's run because A) it'd be a pain to do otherwise; B) It makes sense to include it there, since it's, after all, part of the filter's execution time
• Since refresh times are calculated separately there was no double counting there,