Large window size makes the UI slow and choppy

[karlc1]

I'm not sure if this is known, but something is up with the rendering. If I use a maximized window of onivim, the cursor moves super slow and choppy, skipping rows and continue registering key presses after hold and release of any navigation key. The performance seem to be directly correlated with the size of the window. At full screen on 3440x1440 resolution, the UI is more or less unusable.

I am not sure if this is related, but from what I can see in htop is, as I move the cursor, one of the eight threads of my CPU spikes immediately to 100% while the others remain largely unaffected. This is however the case regardless of client size, so it might be a separate issue. I'm not sure weather performance is single threaded by design or if it would benefit from multi threading more, but regardless it seems excessive that moving the cursor would use up an entire cpu thread.

I'm using Ubuntu 18.04 and has experienced this with every build I've tried, including one I downloaded today.

[szbergeron]

This is possibly related to perf limits in revery. May be significantly helped by the skia integration at #1206

Would you be able to test using that PR and see if the perf issues are improved? It may have other bugs but that would at least help see if that's the issue

[karlc1]

I tried to build from source, but I'm getting the error Unix.Unix_error(Unix.ENOTEMPTY, "rename", "/home/karlc/code/oni2/_esy/default/tmp/esy-a78e58") using esy 0.6.0 when running esy install

Edit: Seems like there is a revery dependency that requires Ubuntu 18.10 (im on 18.04). I am not sure if that is the problem, but I cannot really add packages to my sources since this is a work computer. I guess I will have to wait until the PR is merged and released to try it out.

[szbergeron]

Weird, I'd think we'd support at least latest Ubuntu LTS. What package does it require?

[CrossR]

I'd think we'd support at least latest Ubuntu LTS.

CI is done on 16.04, but there is some packages required on Ubuntu (both for revery, and libvim). Both are outlined in the install steps: https://onivim.github.io/docs/for-developers/building#linux. This includes the dependency on harfbuzz that Ubuntu 18.10+ has, which isn't in 18.04.

[bryphe]

For this error:

Unix.Unix_error(Unix.ENOTEMPTY, "rename", "/home/karlc/code/oni2/_esy/default/tmp/esy-a78e58")

might be worth git clean -dxf or just delete the _esy directory - seems like that got into a bad state (and esy install + esy build again).

We just recently (yesterday) merged in Skia (#1206), which is basically a total revamp of our rendering pipeline - it'll be interesting to see how it works in this scenario. Hopefully improved!

[CrossR]

As just some additional data points, here is what I get on the latest build from the Early Access portal (#0c4cddea), at 4K (no scaling) on Windows in full screen, and I am just holding j:

• Fill the screen with letters in a txt file and make 10000 lines : 30 FPS (from Afterburner, so not sure how reliable that is, but it matches up to my feeling of "okay but not smooth").
• Worst case scenario - Giant JSON file so full screen of text with syntax HL : 10FPS (visible stutters and jumps. I don't know the best approach here as in giant JSON files I notice vim stuttering once they get too big, but still).
• More realistic file (VimStoreConnector) is hovering around but just under 60 (55-57). I can see that moving the window to half my monitor (no text is cut off, I just lose some of the empty space between the buffer and the minimap) nets me about 20FPS, which seems interesting.
• Empty buffer (just as an optimisation note really) 150FPS.

I can at least see that in a realistic example, having a larger window, even if no extra text is shown, we do lose performance. I can also see that if I drop to a smaller window with an empty buffer I get like 700 FPS and a bunch of CPU/GPU usage, so I'm guessing we have no detection around "probably don't need to repaint now".

[bryphe]

Thanks for the great benchmarks, @CrossR !

Still some work to do - these cases should all be 60 FPS.

I measured with the latest, and it turns out, the next bottlenecks are actually not rendering - but expensive text manipulation we're doing every render frame. The two biggest culprits I see are:

• IndentLineRenderer- the indent line calculation is expensive. There are some non-optimal things, like a String.trim call that is allocating every query.
• BufferViewTokenizer - this takes a visible buffer line, syntax tokens, and gives the renderer a list of colorized tokens to draw. This again requires several allocations, and we call it for every minimap line.

@glennsl is currently working on some EditorSurface improvements - once those are in, I'll focus on these as next pieces to optimize.

With skia, now, we can also have a benchmark around the EditorSurface rendering, which will be very helpful to track the performance profile as we make changes. For both the IndentLineRenderer and BufferViewTokenizer - there really is no need to calculate either of these every frame. We should be able to calculate these just on buffer updates (and syntax highlight updates, in the case of the BufferViewTokenizer).

[karlc1]

So I tested the latest build on my work computer today, and while it does seem to distribute workload much more evenly across cpu threads, the issue with poor visual performance at large screen size remains. I don't have any hard numbers, but cpu and memory usage seems to be extremely similar at a small window size that runs smoothly and a large one that runs terribly, so to me it seems like inefficiencies of memory allocations between frame renders is perhaps not the real issue. By the way, I notice no difference when disabling the mini map in config.

[bryphe]

I don't have any hard numbers, but cpu and memory usage seems to be extremely similar at a small window size that runs smoothly and a large one that runs terribly, so to me it seems like inefficiencies of memory allocations between frame renders is perhaps not the real issue. By the way, I notice no difference when disabling the mini map in config.

Thanks for the details, @karlc1 ! Indeed, it does sound like a different issue based on your description.

One other issue that can occur is if we happen to be using software rendering instead of leveraging the GPU - you said you're running Ubuntu 18.04, what kind of GPU do you use? And any window manager?

If you wouldn't mind grabbing some logs - running with -f --trace --log-filter=Revery will output some OpenGL info at the beginning:

[INFO]    +78ms Revery.Core.Window : Creating window Oni2 width: 800 height: 600
[INFO]    +28ms Revery.Core.Window : Window created successfully.
[INFO]    +17ms Revery.Core.Window : OpenGL hardware info:
[INFO]     +0ms Revery.Core.Window :   version: 2.1 INTEL-12.10.14
[INFO]     +0ms Revery.Core.Window :   vendor: Intel Inc.
[INFO]     +0ms Revery.Core.Window :   shadingLanguageVersion: 1.20

I'd be curious what we're picking up for the OpenGL version/vendor. I wonder if we're hitting the software renderer by chance.

Another piece of logging that would be useful is to run with -f --trace and REVERY_PERF=1 - this gives us some detailed performance measurements:

[TRACE]    +0ms Revery.UI.Render : BEGIN: Render frame
[TRACE]    +0ms Revery.Core.Performance : --[BEGIN: reconcile]
[TRACE]    +1ms Revery.Core.Performance : --[END: reconcile] Time: 0.916004ms Memory: | minor: 74422 | major: 0 | promoted: 0 |
[TRACE]    +0ms Revery.Core.Performance : --[BEGIN: layout]
[TRACE]    +0ms Revery.Core.Performance : --[END: layout] Time: 0.012159ms Memory: | minor: 1182 | major: 0 | promoted: 0 |
[TRACE]    +0ms Revery.Core.Performance : --[BEGIN: recalculate]
[TRACE]    +0ms Revery.Core.Performance : --[END: recalculate] Time: 0.276804ms Memory: | minor: 26523 | major: 0 | promoted: 0 |
[TRACE]    +0ms Revery.Core.Performance : --[BEGIN: flush]
[TRACE]    +0ms Revery.Core.Performance : --[END: flush] Time: 0.020027ms Memory: | minor: 1180 | major: 0 | promoted: 0 |
[TRACE]    +0ms Revery.Core.Performance : --[BEGIN: draw]
[TRACE]    +1ms Revery.Core.Performance : --[END: draw] Time: 0.699997ms Memory: | minor: 22377 | major: 0 | promoted: 0 |
[TRACE]    +0ms Revery.UI.Render : END: Render frame
[TRACE]    +0ms Revery.Core.Performance : --[BEGIN: swapWindow]
[TRACE]    +1ms Revery.Core.Performance : --[END: swapWindow] Time: 0.576973ms Memory: | minor: 1180 | major: 0 | promoted: 0 |
[TRACE]    +0ms Revery.Core.Performance : -[END: renderWindows] Time: 2.729893ms Memory: | minor: 138695 | major: 0 | promoted: 0 |

Might give us some clues on where the bottleneck is.

[karlc1]

-f --trace --log-filter=Revery outputs:

[INFO]     +0ms Revery.Core.Window : OpenGL hardware info:
[INFO]     +0ms Revery.Core.Window :   version: 3.0 Mesa 19.2.8
[INFO]     +0ms Revery.Core.Window :   vendor: Intel Open Source Technology Center
[INFO]     +0ms Revery.Core.Window :   shadingLanguageVersion: 1.30

-f --trace and REVERY_PERF=1 with large window:

[TRACE]    +0ms Revery.UI.Render : BEGIN: Render frame                                                         
[TRACE]    +0ms Revery.Core.Performance : --[BEGIN: reconcile]                                                 
[TRACE]   +37ms Revery.Core.Performance : --[END: reconcile] Time: 36.502123ms Memory: | minor: 445124 | major:
 174200 | promoted: 85894 |                                                                                    
[TRACE]    +0ms Revery.Core.Performance : --[BEGIN: layout]                                                    
[TRACE]    +0ms Revery.Core.Performance : --[END: layout] Time: 0.025988ms Memory: | minor: 1182 | major: 0 | p
romoted: 0 |                                                                                                   
[TRACE]    +0ms Revery.Core.Performance : --[BEGIN: recalculate]                                               
[TRACE]    +1ms Revery.Core.Performance : --[END: recalculate] Time: 0.827074ms Memory: | minor: 36681 | major:
 17961 | promoted: 17961 |                                                                                     
[TRACE]    +0ms Revery.Core.Performance : --[BEGIN: flush]                                                     
[TRACE]    +0ms Revery.Core.Performance : --[END: flush] Time: 0.047922ms Memory: | minor: 1180 | major: 0 | pr
omoted: 0 |                                                                                                    
[TRACE]    +0ms Revery.Core.Performance : --[BEGIN: draw]                                                      
[TRACE]    +5ms Revery.Core.Performance : --[END: draw] Time: 5.213976ms Memory: | minor: 111621 | major: 35772

with small window:

[TRACE]    +0ms Revery.UI.Render : BEGIN: Render frame                                                         
[TRACE]    +0ms Revery.Core.Performance : --[BEGIN: reconcile]                                                 
[TRACE]    +3ms Revery.Core.Performance : --[END: reconcile] Time: 3.386974ms Memory: | minor: 99616 | major: 0
 | promoted: 0 |                                                                                               
[TRACE]    +0ms Revery.Core.Performance : --[BEGIN: layout]                                                    
[TRACE]    +0ms Revery.Core.Performance : --[END: layout] Time: 0.065088ms Memory: | minor: 1182 | major: 0 | p
romoted: 0 |                                                                                                   
[TRACE]    +0ms Revery.Core.Performance : --[BEGIN: recalculate]                                               
[TRACE]    +4ms Revery.Core.Performance : --[END: recalculate] Time: 3.813028ms Memory: | minor: 34065 | major:
 0 | promoted: 0 |                                                                                             
[TRACE]    +0ms Revery.Core.Performance : --[BEGIN: flush]                                                     
[TRACE]    +1ms Revery.Core.Performance : --[END: flush] Time: 0.643015ms Memory: | minor: 1180 | major: 0 | pr
omoted: 0 |                                                                                                    
[TRACE]    +0ms Revery.Core.Performance : --[BEGIN: draw]                                                      
[TRACE]   +10ms Revery.Core.Performance : --[END: draw] Time: 10.412216ms Memory: | minor: 94261 | major: 13909
 | promoted: 13909 |                                                                                           
[TRACE]    +0ms Revery.UI.Render : END: Render frame                                                           
[TRACE]    +0ms Revery.Core.Performance : --[BEGIN: swapWindow]                                                
[TRACE]    +1ms Revery.Core.Performance : --[END: swapWindow] Time: 0.503063ms Memory: | minor: 1180 | major: 0
 | promoted: 0 |                                                                                               
[TRACE]    +0ms Revery.Core.Performance : -[END: renderWindows] Time: 20.737171ms Memory: | minor: 251978 | maj
or: 13909 | promoted: 13909 |                                                                                  
[DEBUG]   +11ms Revery.App : Upshifting into active state.                                                     
[TRACE]    +0ms Revery.Core.Performance : -[BEGIN: _doPendingMainThreadJobs]                                   
[TRACE]    +0ms Revery.Core.Performance : -[END: _doPendingMainThreadJobs] Time: 0.065088ms Memory: | minor: 11
82 | major: 0 | promoted: 0 |                                                                                  
[TRACE]    +0ms Revery.Core.Performance : -[BEGIN: renderWindows]                                              
[TRACE]    +0ms Revery.Core.Window : _getScaleFactor - Linux - inferring from DPI: 1.000000                    
[TRACE]    +0ms Revery.Core.Window : _updateMetrics - new metrics: DevicePixelRatio: 1.000000 ScaleFactor: 1.00
0000 Zoom: 1.000000 Raw Dimensions: 800x980px Framebuffer: 800x980px                                           

I got these logs using Ubuntu on Wayland, but I have had the same experience with Xorg

[bryphe]

Thanks for the help with the logs, @karlc1 !

It's actually very helpful.

It seems like the bottleneck we're seeing is in the reconcile phase of our rendering:

[TRACE]    +0ms Revery.Core.Performance : --[BEGIN: reconcile]                                                 
[TRACE]   +37ms Revery.Core.Performance : --[END: reconcile] Time: 36.502123ms Memory: | minor: 445124 | major:
 174200 | promoted: 85894 |          

So actually not related to OpenGL / Skia / or the memory issue I mentioned before. The draw time for the small window is still higher than I'd like to see (we'd prefer that to be under 8ms), but the main bottleneck for the large window is that reconcile step at 36ms.

We expect this to be ~1-2ms to be within the 60 FPS goals, but 36ms exceeds that by a wide, wide margin.

I suspect this could be related to the file explorer - it's the heaviest 'reconcile' path today. I wonder if we're hitting some degenerate case that is causing the reconciler to spend a lot of time in the file explorer - perhaps a deeply nested path.

We might want to consider an 'immediate-mode' rendering for the file explorer, like we do for the editor surface / minimap today - so that we can avoid any reconciler cost there.

[lessp]

Also experience quite a lot of staggering (holding J/K in the editor) in fullscreen on a 27":

With small window-size: