performance issue

[guiv42]

TuxGuitar 1.6.3beta1, on Linux openSuse tumbleweed

tab scrolling does not follow correctly when playing, see video:

https://github.com/helge17/tuxguitar/assets/129443524/05b9b7d8-39fd-49e5-9f76-828c60b89ea5

Even with option "Player / Highlight Played Beat" unchecked. Edit: it's not systematic... at least it's not always as severe as in this video

[guiv42]

I was expecting this issue to be a consequence of the new "highlight played beat" feature, but it seems not. I tried to git bisect this issue. It's not so easy, as the observed issue is not systematic, however it led me to this commit d4d2506602a0180196f45ab122516e97a1da57f7 Update SWT on Linux to 4.26

Just for testing I tried (from 1.6.3beta1) to downgrade SWT to 4.21: this solves the issue. Tested a few versions of SWT/Linux:

• 4.21, 4.25 : OK
• 4.26, 4.28, 4.29, 4.30 : KO

[guiv42]

technically, problem is solved by SWT downgrade. However I prefer to leave this issue open (bug -> enhancement). Analysis shall be more detailed : we will not be able to stick to an old version of SWT forever.

[guiv42]

Starting to profile app, with the objective to understand what's going on. I ran a test scenario with both versions 1.6.3beta1 and 1.6.3, and tried to profile different parts of the application. The culprit seems to be org.eclipse.swt.graphics.GC.drawImage : with this scenario, cpu time consumed by this function is

• 13788ms for 1.6.3beta1
• 750ms for 1.6.3

This SWT function is called by SWTPainter.drawImage, which itself is called by TGMeasureBuffer.paintBuffer Now... how to get further in the analysis??

[guiv42]

I confirm the performance issue of org.eclipse.swt.graphics.GC.drawImage. Use of GC.drawImage by TuxGuitar:

• when updating a measure, TuxGuitar creates an image buffer in memory
• then, it paints the content of the measure into that buffer
• when buffer is ready, it calls GC.drawImage to display the buffer

Profiling GC.drawImage: with 1.6.3beta1 (SWT 4.26)

• more than 13000ms cpu spent in GC.drawImage
• it spends almost all of its (long) execution time in org.eclipse.swt.graphics.Image.getImageDataAtCurrentZoom

with 1.6.3 (SWT 4.21)

• 829ms cpu spent in GC.drawImage (It's the same test scenario, and these figures are reproducible)

Note: the number of invocations of GC.drawImage significantly differs between the 2 versions, for the same test scenario. I assume it's a consequence of the profiler. When profiler is active, performance is significantly reduced. One measure is updated each time the played note changes. My test script is full of 16th, so it goes quite fast (see video in first post of this issue). With 1.6.3beta1 and profiler, scrolling is very very slow, many invocations are skipped. With 1.6.3, scrolling is almost fluid.

[guiv42]

After analyzing differences between SWT4.21 and SWT4.26 source code, it seems this line triggers the call to Image.getImageData which creates our perf issue.

It was introduced by this commit to fix this issue

[guiv42]

OK, so we have a performance impact when switching to SWT 4.26. Now, looking closer (see profiling screenshots above):

• almost 14s cpu spent in GC.drawImage
• yes, but this method is called about 28000 times
• so it's about 0.5ms per call (with profiler active). This should be affordable.

So, after looking at SWT, let's have a look at TuxGuitar. Two problems found

1. A significant amount of time is wasted in MidiPlayer.getInstance() Same test scenario as above, but different profiler configuration (significant impact, so don't compare figures):

• 28600ms cpu spent in TGLayoutHorizontal.paintSong
• among these, 7000ms are spent in MidiPlayer.getInstance (almost 25%, it's not negligible)

I don't see any reasonable reason for that. The calling stack is this one:

• TGLayoutHorizontal.paintSong 28600ms
  • TGMeasureImpl.registerSpacing 12200ms
  • TGLayout.hasLoopMarker 11000ms
    • Tablature.isLoopSHeader 5100ms
      • TuxGuitar.getPlayer 3900ms
        • MidiPlayer.getInstance 3500ms
    • Tablature.isLoopEHeader 5100ms
      • TuxGuitar.getPlayer 3900ms
        • MidiPlayer.getInstance 3500ms

To investigate: is it possible to cache player mode somewhere in this path, to avoid this? (and similar problem 5 lines below)

2. Processing of SWT events Why so many calls to GC.drawImage? I intrumented the number of calls to TGLayoutHorizontal.paintSong. There are very significant peaks: when page scrolls. This creates up to 60 calls per second, sometimes for several seconds. In this case it does not make sense to try re-painting full tablature 60 times per second. Apart this "page scroll" specific case, everything seems reasonable. See video (1.6.3beta1, SWT 4.26):

https://github.com/helge17/tuxguitar/assets/129443524/009c9b1f-b146-4e69-9f7c-adbda344775a

My interpretation: at each page scroll, a significant amount of paint SWT events is generated, meaning some objects need to be re-painted. All these events trigger a re-painting of the complete tab. Events are queued, and it takes some time to process them all. Once all are processed, it falls down to <10 re-paint actions per second, there it's reasonable.

To investigate:

• why so many events triggering full tablature re-painting?
• possibility to filter these events, to limit the frequency of re-painting actions?

[guiv42]

I think I understood the origin of the burst of Paint events. Page scrolling is not directly responsible: the problem is linked to the horizontal scrollbar. It seems there's a sort of recursive loop between paint tablature and update scrollbar. Most probably because scrollbar is transparent: when scrollbar is refreshed, swt identifies the tablature needs to be redrawn (visible through the scrollbar). And paintTablature refreshes the scrollbar. See video: just showing the scrollbar creates this throughput of 60 events/sec (leading to as many calls to paintTablature)

https://github.com/helge17/tuxguitar/assets/129443524/72f04f13-960e-4841-8827-f993f5c7f997

[guiv42]

Good news: I confirm it's a TuxGuitar issue, not SWT, so we can fix it. I also confirm the scrollbars are the problem: just open a tab with 1.6.3beta1, move slowly the mouse to make sure the scrollbars remain permanently visible, and monitor cpu load. In this situation TuxGuitar repaints full tablature about 60 times per second.

Several possible steps to optimize: Step 1 When painting tab, only update scrollbars if their attributes have changed. This breaks the loop [paintTablature -> update scrollbars -> paintTablature ->...] when scrollbars are stable, and solves the issue mentioned above. After this, peaks of 60 repaint per second persist, but only when scrollbars appear and fade away.

Step 2 Mask scrollbars when playing. In this situation they are useless: moving the scrollbar competes with the player to define which portion of the tab shall be displayed. And this allocates more screen space to display the useful information.

With these 2 steps, display when playing is fluid: formally this solves the perf issue. After profiling in my reference test case: number of invocations of GC.drawImage is divided by about 10. And it also solves first issue mentioned in this post: number of invocations to MidiPlayer.getInstance is also very significantly reduced. Further optimization here would be useless.

I'll probably create a PR with these 2 first steps soon (easy implementation, already prototyped in a test branch).

Step 3 When a Paint event is received from SWT, it seems it contains information about the area which needs to be repainted. Analysis to perform: is it possible for TuxGuitar to repaint only this area and not the full tablature? This would be cleaner, but also more complex to implement. Compatibility with JFX shall also be considered.

[guiv42]

Optimization step3 mentioned above is not feasible. Since there are both an horizontal and a vertical scrollbar in the tab area, when they appear or disappear the SWT Paint events define the full tab to be repainted.