Performance regression reported from v5.1.23 #6042

Jermolene · 2021-09-17T09:35:53Z

From https://talk.tiddlywiki.org/t/tw-5-2-0-prerelease-significantly-slower-than-tw-5-1-23-instrumentation-data-included/776:

I’ve tested the 5.2.0-prerelease over the past few days both on mobile and on desktop.

I’ve noticed significantly degraded performance on mobile and did some performance instrumentation tests on my desktop. Results below.

I’ve primarily tested the basic TW operations such as navigating links (opening, closing tiddlers), selecting checkboxes, radio buttons, clicking buttons etc.

The overall performance is significantly slower in 5.2.0 compared to the same wiki running on 5.1.23. It appears that mainRenderer and mainRefresh see the biggest slowdowns.

Here’s some data from the two identical wikis running side by side, the figures on the left correspond to the 5.1.23 version and the ones on the right are from the 5.2.0-prerelease. In each “test run” I had all tiddlers closed beforehand and then performed identical navigation:

mainRenderer values

Opening tiddlers (variable levels of complexity)
151 ms vs 276ms
149 ms vs 230ms
242 ms vs 302ms
105 ms vs 196ms
398 ms vs 503ms

Opening Control Panel
90ms vs 190ms

Opening Advanced Search
83ms vs 195ms

Clicking on a checkbox that sets a value in a data tiddler
67ms vs 160ms

Pressing a button that sets a value in a data tiddler
175mm vs 278ms

Entering a password in an encrypted wiki, upon pressing enter:
mainRender (v5.1.23): 226.00m vs mainRender (v.5.2.0-prerelease): 350.00ms
mainRefresh (v5.1.23): 74.00ms vs mainRefresh (v.5.2.0-prerelease): 192.00ms

I’ve performed these tests on my desktop with an 8-Core Ryzen CPU clocked at 3.60 GHz and 32GB RAM. The performance on my midrange Motorola is at least 5 times slower. While desktop performance slowdowns on this system are negligible, mobile performance introduces major usability issues.

The values above are obviously system dependent and wiki dependent but the point I’m trying to make is that in relative terms, 5.2.0-prerelease is significantly slower than 5.1.23. I’ve made these tests on the same system, the same identical wiki, with the only difference being the TiddlyWiki version.

I’d like to hear your thoughts about this and also if there’s anything you could suggest. Could anyone perhaps perform similar tests on their end?

One point to note is that the wiki I used was password protected, which means that the new json parsing probably does not affect it yet (unless I misunderstood). However, the core render modules are still slower to render the wiki and it would be interesting to learn why it should be the case.

Jermolene · 2021-09-17T15:50:55Z

I've now setup a very basic performance testing framework. It consists of:

A test wiki (a snapshot of editions/tw5.com)
A script to build the wiki with a specific Git commit of TiddlyWiki
A script to open a wiki under Puppeteer and extract the performance timings

The repository is here:

https://github.com/Jermolene/tiddlywiki-performance-test-rig

At the moment, after running the tests several times I'm not seeing any performance regression between v5.1.23 and master:

./build-tiddlywiki-at-version.sh v5.1.23 ./tmp/v5.1.23 && ./build-tiddlywiki-at-version.sh master ./tmp/master
node ./index.js ./tmp/v5.1.23/index.html && node ./index.js ./tmp/master/index.html

Output:

file:///xxx/git/Jermolene/tiddlywiki-performance-test-rig/tmp/v5.1.23/index.html
2021 9 17 16:43:12.200: Execute $tw.perf.log(); to see filter execution timings
2021 9 17 16:43:24.666: mainRender: 12301.70ms
2021 9 17 16:43:25.340: styleRefresh: 2.70ms
2021 9 17 16:43:26.465: mainRefresh: 1125.20ms

file:///xxx/git/Jermolene/tiddlywiki-performance-test-rig/tmp/master/index.html
2021 9 17 16:43:33.039: Execute $tw.perf.log(); to see filter execution timings
2021 9 17 16:43:45.018: mainRender: 11793.60ms
2021 9 17 16:43:45.680: styleRefresh: 2.60ms
2021 9 17 16:43:46.811: mainRefresh: 1130.20ms

The inconsistency may be because the test rig isn't measuring the correct thing. It would be helpful to dig into your wiki – would you be prepared to share it privately?

sobjornstad · 2021-09-18T13:05:52Z

If you aren't able to get a copy of Hubert's wiki or you want another test case, you could try my public Zettelkasten...should be able to just hit the download button and then run it through the upgrader. It has 2400 tiddlers and quite a complicated view template. I don't have time to try turning on the instrumentation and looking for numbers at the moment, but it does feel just a wee bit slower after doing an upgrade. The machine I'm on is so fast that it's hard to tell the difference sometimes.

Jermolene · 2021-09-18T14:24:30Z

Thanks @sobjornstad. For your wiki, I'm seeing slightly slower timings on the prerelease than v5.1.23. To emphasise that this might be a limitation of the test rig; all it does at the moment is take the timings that are enabled by $:/config/Performance/Instrumentation.

file:///xxx/git/Jermolene/tiddlywiki-performance-test-rig/tmp/v5.1.23/index.html
2021 9 18 15:16:14.434: Execute $tw.perf.log(); to see filter execution timings
2021 9 18 15:16:15.297: mainRender: 399.20ms
2021 9 18 15:16:15.402: styleRefresh: 15.70ms
2021 9 18 15:16:15.435: mainRefresh: 32.70ms

file:///xxx/git/Jermolene/tiddlywiki-performance-test-rig/tmp/master/index.html
2021 9 18 15:16:16.498: Execute $tw.perf.log(); to see filter execution timings
2021 9 18 15:16:17.366: mainRender: 408.10ms
2021 9 18 15:16:17.481: styleRefresh: 16.40ms
2021 9 18 15:16:17.518: mainRefresh: 36.80ms

Changing $:/DefaultTiddlers to [all[tiddlers]sort[]limit[300]] is interesting: the prerelease is 10% faster. It seems like the more tiddlers that are displayed, the faster the prerelease is compared to v5.1.23:


file:///xxx/git/Jermolene/tiddlywiki-performance-test-rig/tmp/v5.1.23/index.html
2021 9 18 15:21:18.462: Execute $tw.perf.log(); to see filter execution timings
2021 9 18 15:21:25.504: mainRender: 6551.40ms
2021 9 18 15:21:27.229: styleRefresh: 13.70ms
2021 9 18 15:21:28.014: mainRefresh: 784.60ms
2021 9 18 15:21:28.746: styleRefresh: 5.70ms
2021 9 18 15:21:29.188: mainRefresh: 441.50ms
2021 9 18 15:21:29.214: styleRefresh: 5.80ms
2021 9 18 15:21:29.615: mainRefresh: 400.60ms
2021 9 18 15:21:35.516: styleRefresh: 6.50ms
2021 9 18 15:21:35.914: mainRefresh: 397.30ms

file:///xxx/git/Jermolene/tiddlywiki-performance-test-rig/tmp/master/index.html
2021 9 18 15:21:36.943: Execute $tw.perf.log(); to see filter execution timings
2021 9 18 15:21:43.339: mainRender: 5920.60ms
2021 9 18 15:21:44.860: styleRefresh: 13.50ms
2021 9 18 15:21:45.647: mainRefresh: 786.50ms
2021 9 18 15:21:46.350: styleRefresh: 7.30ms
2021 9 18 15:21:46.810: mainRefresh: 459.20ms
2021 9 18 15:21:52.019: styleRefresh: 6.10ms
2021 9 18 15:21:52.452: mainRefresh: 433.10ms
2021 9 18 15:21:52.476: styleRefresh: 6.30ms
2021 9 18 15:21:52.904: mainRefresh: 427.30ms

hubertgk · 2021-09-18T15:21:08Z

Thanks for looking into this further @Jermolene and apologies for responding late.

Unfortunetely, I cannot share my main wiki but could replicate my initial findings with a test pair of empty wikis, one running 5.1.23 and the other one being the empty 5.2.0-prerelease:

TiddlyWiki test pair.zip

In each wiki, I've created 5000 dummy tiddlers that only contain some lorem ipsum plaintext (no wikitext, widgets or custom macros).

Overall, each wiki has 5003 ordinary tiddlers and is just over 17 megabytes in size. They should be identical in terms of user content.

By running performance instrumentation manually like before with my own wiki, I've found the results to be consistent with my initial fidings (5.1.23 is on the left, 5.2.0-prerelease on the right):

Saving a new tiddler

1357ms vs 1661ms

Clicking on the Recent tab

951ms vs 1233ms
975ms vs 1290ms
913ms vs 1253ms

Opening Control Panel

371ms vs 528ms

Opening a tiddler by clicking its title as a search result (sidebar)

266ms vs 535ms

Clicking to edit a tiddler called "Startpage"

141ms vs 174ms
139ms vs 179ms
145ms vs 176ms

Opening default tiddlers (clicking the home button)

10ms vs 14ms

Creating a tiddler (clicking the + button on the sidebar) so that it goes into edit mode

138ms vs 161ms

Deleting an open tiddler in draft mode

12ms vs 18ms

Jermolene · 2021-09-18T15:45:33Z

Thanks @hubertgk

I used the --savewikifolder command to unpack your example wiki into a wikifolder for use with the test rig. As before, I got similar timings with the single entry in $:/DefaultTiddlers. When I changed it to [all[tiddlers]sort[]limit[1000]], I see an improvement in the initial render: 2.313s for master vs. 2.698s for v5.1.23.

I assume the inconsistency is because your tests are all interactive, whereas the test rig is just measuring the initial rendering. I'll look at extending the test rig, but in the meantime it might be helpful if you could report the startup render times your seeing with the updated $:/DefaultTiddlers.

saqimtiaz · 2021-09-18T16:07:57Z

@hubertgk I tried some of your tests using your test wikis and I don't see a significant performance difference. Also worth nothing that having the zoomin story view active can confound testing as the number of open tiddlers can vary without one realizing it.

Clicking on the Recent tab
369ms vs 424ms
371ms vs 331ms
317ms vs 315ms

Opening Control Panel
47ms vs 50ms
47ms vs 46ms
52ms vs 47ms

Opening a tiddler by clicking its title as a search result (sidebar)
47ms vs 41ms
41ms vs 46ms

Clicking to edit a tiddler called "Startpage"
106ms vs 99ms
82ms vs 88ms
80ms vs 75ms

Opening default tiddlers (clicking the home button)
15 vs 18
16 vs 18

Creating a tiddler (clicking the + button on the sidebar) so that it goes into edit mode
65 vs 63

hubertgk · 2021-09-18T16:09:26Z

With [all[tiddlers]sort[]limit[1000]] in $:/DefaultTiddlers I get the folllowing:

5.1.23

Startup:

<empty string> performance: mainRender: 2530.00ms <empty string> $:/core/modules/utils/logger.js:52:26
<empty string> performance: styleRefresh: 5.00ms <empty string> $:/core/modules/utils/logger.js:52:26
<empty string> performance: mainRefresh: 496.00ms <empty string> $:/core/modules/utils/logger.js:52:26

Clicking the Home button (opening default tiddlers):

<empty string> performance: styleRefresh: 9.00ms <empty string> $:/core/modules/utils/logger.js:52:26
<empty string> performance: mainRefresh: 1921.00ms <empty string> $:/core/modules/utils/logger.js:52:26

Clicking the plus button (new tiddler):

<empty string> performance: styleRefresh: 7.00ms <empty string> $:/core/modules/utils/logger.js:52:26
<empty string> performance: mainRefresh: 2130.00ms <empty string> $:/core/modules/utils/logger.js:52:26

5.2.0-prerelease

Startup:

<empty string> performance: mainRender: 2574.00ms <empty string> $:/core/modules/utils/logger.js:52:26
<empty string> performance: styleRefresh: 10.00ms <empty string> $:/core/modules/utils/logger.js:52:26
<empty string> performance: mainRefresh: 1885.00ms <empty string> $:/core/modules/utils/logger.js:52:26

Clicking the Home button (opening default tiddlers):


<empty string> performance: styleRefresh: 10.00ms <empty string> $:/core/modules/utils/logger.js:52:26
<empty string> performance: mainRefresh: 1873.00ms <empty string> $:/core/modules/utils/logger.js:52:26

Clicking the plus button (new tiddler):

<empty string> performance: styleRefresh: 7.00ms <empty string> $:/core/modules/utils/logger.js:52:26
<empty string> performance: mainRefresh: 2076.00ms <empty string> $:/core/modules/utils/logger.js:52:26

Is it then recommended to open as many tiddlers as possible at startup to improve overal performance (at the cost of the longer startup time)?

Jermolene · 2021-09-18T16:11:02Z

Is it then recommended to open as many tiddlers as possible at startup to improve overal performance (at the cost of the longer startup time)?

No, not at all. I'm just opening lots of tiddlers to make the startup time longer, and hence easier to measure.

hubertgk · 2021-09-18T16:18:54Z

Thanks @saqimtiaz

having the zoomin story view active can confound testing as the number of open tiddlers can vary without one realizing it

Fair point, however I'm aware of this. In my tests, I performed the exact same clicks on both test wikis so that the same tiddlers remain open, the same tabs are selected etc.

Again, not really an issue on desktop but the lag is becoming a UX problem on mobile (it's there that I've first noticed it).

I'm not quite sure why we're getting inconsistent readings.

pmario · 2021-09-18T16:34:38Z

I think it may be also important to check the browser vendors. It seems Hubert uses FF which I also use. I can confirm that there are differences:

Switch between Open and Recent tab

5.1.23 vs 5.2.0
450ms vs 620ms
(variation from 440ms to 490ms) vs (variation from 540ms to 650ms)

Jermolene · 2021-09-18T16:44:52Z

Thanks @pmario. Puppeteer supports Firefox now so I'll have a look at adding it to the rig.

pmario · 2021-09-18T16:45:11Z

Reload page with Recent tab selected:

Filters seem to be much less performant

v5.1.23

v5.2.0

saqimtiaz · 2021-09-18T17:43:29Z

@pmario if you get the chance, could you compare before and after this commit:
dbd3f83

I can't reproduce the problem so can't test myself but I have a hunch...

saqimtiaz · 2021-09-18T18:04:57Z

@pmario @hubertgk here is a patched 5.2.0 file for testing: https://saqimtiaz.github.io/sq-tw/temp/5.2.0-prerelease-patched.html

Can you please confirm if the performance issue persists here, especially with filter execution?

pmario · 2021-09-18T18:06:38Z

@saqimtiaz
5.2.0-prerelease-master - That's the version with the new sort code

5.2.0-prerelease - old sort code prior to #dbd3f83

saqimtiaz · 2021-09-18T18:33:36Z

@pmario thank you. So that change to the sorting is definitely the major contributor to the slowdown in filter evaluation.

The question remains whether that resolves all performance issues or whether there might be other changes that are also contributing.

hoelzro · 2021-09-18T21:18:25Z

I don't know how feasible this would be, but would it make sense to track global/per-tiddler cache hit/miss ratios, or somehow reflect how long potentially cached operations are taking during each step? I imagine that might influence timings from startup vs timings from after the wiki has had a chance to warm up a bit!

hoelzro · 2021-09-18T21:26:26Z

I was looking at https://github.com/Jermolene/TiddlyWiki5/blob/1ddc3ab037bab8cefa0b0173367335ea31d665a5/core/modules/startup/render.js#L80-L104 and I think I found a bug - if only throttled tiddlers have changed, the actual refresh will happen in another execution of the event loop, but the function provided to $tw.perf.report will have returned after setting up that deferred refresh and $tw.perf.report will report a shorter time, right? I doubt this influences much in practice (especially regarding timings for initial loads and switching sidebar tabs), but I just thought I'd mention it.

pmario · 2021-09-19T10:46:26Z

and I think I found a bug - if only throttled tiddlers have changed, the actual refresh will happen in another execution of the event loop, but the function provided to $tw.perf.report will have returned after setting up that deferred refresh and $tw.perf.report will report a shorter time, right?

Right. But I think that isn't a big problem. The mainRefresh time has its own line in the log, every time it is measured.. So it isn't used to calculate an average value, where it would have a negative impact.

pmario · 2021-09-19T10:47:29Z

I don't know how feasible this would be, but would it make sense to track global/per-tiddler cache hit/miss ratios, or somehow reflect how long potentially cached operations are taking during each step?

I think, this would be interesting. ... Especially since the global cache is destroyed whenever any tiddler is changed. And this basically happens with every user interaction.

…TiddlyWiki5#6042

Jermolene · 2021-09-19T11:43:38Z

Thanks @saqimtiaz @pmario @hoelzro

I've updated the test rig to properly measure sorting by introducing the following test tiddler:

<$list filter="[range[0:50]]" variable="count">
<$list filter="[all[tiddlers]sort[modified]sort[title]sort[modifier]]">
<$text text=<<currentTiddler>>/>
</$list>
</$list>

Using the data from Soren's wiki, I get the following timings:

v5.1.23 – 3314.00ms
master – 5373.30ms
master with dbd3f83 reverted – 1844.70ms

So, it would appear that dbd3f83 is masking what would otherwise be a doubling in performance on this test. I will now use the test rig to investigate alternative fixes to #5701

and I think I found a bug

Thanks @hoelzro I think you're correct, would you mind opening a separate issue?

Jermolene · 2021-09-19T12:30:54Z

I've just pushed a simple fix that brings the master execution time into line with v5.1.23 – the test rig gives roughly the same timings for each now.

master with dbd3f83 reverted – 1844.70ms

I can't duplicate that result now, I think that I was testing the wrong wiki in that instance.

pmario · 2021-09-19T13:03:24Z

@Jermolene .. This function is used very often in the core. .. So if we can make it faster, it would be an improvement. right?

I saw inNaN checks at https://github.com/Jermolene/TiddlyWiki5/blob/fb4d77ef46e23c23f4e46c13f4a529aa29a27dcd/core/modules/wiki.js#L393 and again at: https://github.com/Jermolene/TiddlyWiki5/blob/fb4d77ef46e23c23f4e46c13f4a529aa29a27dcd/core/modules/wiki.js#L372

So I think they are redundant. ... Just a thought

Jermolene · 2021-09-19T13:04:15Z

That's right, I'm investigating some simple optimisations now

pmario · 2021-09-19T14:28:23Z

I think titles.sort() .. could start like this:

Init from x and y moved up from the middle of the code to the init area.
a and b initialized with empty string.

	titles.sort(function(a,b) {
		var x = Number(a),
			y = Number(b),
			a = b = "";

The else path isn't needed, since a and b are initialized already.
tiddlerA.getFieldString() does always return a string, so the || "" is redundant

		if(sortField !== "title") {
			var tiddlerA = self.getTiddler(a),
				tiddlerB = self.getTiddler(b);
			if(tiddlerA) {
				a = tiddlerA.getFieldString(sortField);
			}
			if(tiddlerB) {
				b = tiddlerB.getFieldString(sortField);
			}
		}
/*snip*/

Jermolene · 2021-09-19T17:37:04Z

I'm preparing a PR with some simple optimisations and unrolling of the sort function. The timings for Soren's wiki are promising:

v5.1.23 mainRender: 5412.20ms
575c233 mainRender: 11221.60ms
with the pending PR mainRender: 3862.00ms

(575c233 is the last commit before reverting the problematic commit dbd3f83)

Jermolene · 2021-09-19T18:17:39Z

The PR for optimising tiddler sorting is #6053.

hoelzro · 2021-09-19T20:00:56Z

@Jermolene Done: #6054

Jermolene added a commit to TiddlyWiki/tiddlywiki5-performance-test-rig that referenced this issue Sep 19, 2021

A better test for the performance regression discussed in TiddlyWiki/…

6795c9f

…TiddlyWiki5#6042

Jermolene closed this as completed in fb4d77e Sep 19, 2021

Jermolene mentioned this issue Sep 19, 2021

Optimise wiki.sortTiddlers() #6053

Merged

hoelzro mentioned this issue Sep 19, 2021

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

Open

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Performance regression reported from v5.1.23 #6042

Performance regression reported from v5.1.23 #6042

Jermolene commented Sep 17, 2021

Jermolene commented Sep 17, 2021

sobjornstad commented Sep 18, 2021 •

edited

Loading

Jermolene commented Sep 18, 2021

hubertgk commented Sep 18, 2021

Jermolene commented Sep 18, 2021

saqimtiaz commented Sep 18, 2021

hubertgk commented Sep 18, 2021

Jermolene commented Sep 18, 2021

hubertgk commented Sep 18, 2021

pmario commented Sep 18, 2021 •

edited

Loading

Jermolene commented Sep 18, 2021

pmario commented Sep 18, 2021 •

edited

Loading

saqimtiaz commented Sep 18, 2021

saqimtiaz commented Sep 18, 2021

pmario commented Sep 18, 2021

saqimtiaz commented Sep 18, 2021

hoelzro commented Sep 18, 2021

hoelzro commented Sep 18, 2021

pmario commented Sep 19, 2021

pmario commented Sep 19, 2021

Jermolene commented Sep 19, 2021

Jermolene commented Sep 19, 2021

pmario commented Sep 19, 2021

Jermolene commented Sep 19, 2021

pmario commented Sep 19, 2021

Jermolene commented Sep 19, 2021

Jermolene commented Sep 19, 2021

hoelzro commented Sep 19, 2021

Performance regression reported from v5.1.23 #6042

Performance regression reported from v5.1.23 #6042

Comments

Jermolene commented Sep 17, 2021

Jermolene commented Sep 17, 2021

sobjornstad commented Sep 18, 2021 • edited Loading

Jermolene commented Sep 18, 2021

hubertgk commented Sep 18, 2021

Jermolene commented Sep 18, 2021

saqimtiaz commented Sep 18, 2021

hubertgk commented Sep 18, 2021

5.1.23

5.2.0-prerelease

Jermolene commented Sep 18, 2021

hubertgk commented Sep 18, 2021

pmario commented Sep 18, 2021 • edited Loading

Jermolene commented Sep 18, 2021

pmario commented Sep 18, 2021 • edited Loading

saqimtiaz commented Sep 18, 2021

saqimtiaz commented Sep 18, 2021

pmario commented Sep 18, 2021

saqimtiaz commented Sep 18, 2021

hoelzro commented Sep 18, 2021

hoelzro commented Sep 18, 2021

pmario commented Sep 19, 2021

pmario commented Sep 19, 2021

Jermolene commented Sep 19, 2021

Jermolene commented Sep 19, 2021

pmario commented Sep 19, 2021

Jermolene commented Sep 19, 2021

pmario commented Sep 19, 2021

Jermolene commented Sep 19, 2021

Jermolene commented Sep 19, 2021

hoelzro commented Sep 19, 2021

sobjornstad commented Sep 18, 2021 •

edited

Loading

pmario commented Sep 18, 2021 •

edited

Loading

pmario commented Sep 18, 2021 •

edited

Loading