[BUG] mainRefresh reports incorrect timings if only throttled tiddlers have changed

[hoelzro]

Describe the bug

See https://github.com/Jermolene/TiddlyWiki5/issues/6042#issuecomment-922376116

If only throttled tiddlers change, no actual refreshing occurs - it gets deferred until a future event loop execution. However, the refresh function called by $tw.perf.report does return, so the performance report outputs a short duration which doesn't reflect how long the refresh actually takes.

To Reproduce Steps to reproduce the behavior:

1. Enable performance monitoring
2. Change a tiddler that doesn't get throttled
3. Change a tiddler that does get throttled
4. Observe that the logged duration for mainRefresh is quite small

Expected behavior

I would expect TiddlyWiki to report the refresh time from when the deferred refresh runs.

Screenshots

(none)

TiddlyWiki Configuration (please complete the following information):

• Version: 5.1.23
• Saving mechanism: Node
• Plugins installed: None

Desktop (please complete the following information):

• OS: Arch Linux
• Browser: Firefox
• Version: 92

Additional context

@pmario points out that this probably isn't an issue as long as people aren't doing things like aggregating mainRefresh numbers and calculating averages. I agree, but I also think the resulting numbers could confuse users trying to diagnose slow refreshes.

[hoelzro]

I was thinking about this again today while trying to get some timings on a particularly slow parse/render I ran into while editing a tiddler - if we don't mind having throttled refresh times logged under throttledRefresh rather than mainRefresh, I was able to effect a pretty simple fix with this change:

diff --git core/modules/startup/render.js core/modules/startup/render.js
index e50512463..caa8db2ef 100644
--- core/modules/startup/render.js
+++ core/modules/startup/render.js
@@ -81,6 +81,8 @@ exports.startup = function() {
                deferredChanges = Object.create(null);
                $tw.hooks.invokeHook("th-page-refreshed");
        }
+       var throttledRefresh = $tw.perf.report("throttledRefresh",refresh);
+
        // Add the change event handler
        $tw.wiki.addEventListener("change",$tw.perf.report("mainRefresh",function(changes) {
                // Check if only tiddlers that are throttled have changed
@@ -101,7 +103,7 @@ exports.startup = function() {
                        if(isNaN(timeout)) {
                                timeout = THROTTLE_REFRESH_TIMEOUT;
                        }
-                       timerId = setTimeout(refresh,timeout);
+                       timerId = setTimeout(throttledRefresh,timeout);
                        $tw.utils.extend(deferredChanges,changes);
                } else {
                        $tw.utils.extend(deferredChanges,changes);

[pmario]

I would be OK with a new parameter. It only shows up, if there are "throttled tiddlers" - right?

[hoelzro]

Yes - in the little bit of testing I did just now, I only saw throttledRefresh in the logs when I was actually editing a tiddler.