Subpar performance when running gvim or emacs #670

totaam · 2014-09-04T21:02:08Z

Issue migrated from trac ticket # 670

component: core | priority: critical | resolution: fixed | keywords: performance paint gvim emacs damage storm

2014-09-04 21:02:08: cesarkawakami created the issue

Reproduction steps:

start server:
xpra start :100 --start-child='executable' --no-speaker -d encoding
where executable might be gvim or emacs when configured for GUI use

attach client in rgb mode:
xpra attach :100 --encoding=rgb -z 0
simply hold j/k in gvim (to move the cursor around across lines) or do a page scroll in emacs (Ctrl-v / Alt-v)

see general slowness and damage storm in the xpra server log

I've talked to totaam on #winswitch and we agreed this looks like a real problem, so he recommended me to open this ticket here.

The text was updated successfully, but these errors were encountered:

totaam · 2014-09-05T06:14:16Z

On a 1080p screen with a gvim window taking up half the screen, with a fairly large file open, a single click on the scrollbar causes 320 damage events!
All but 5 of those repaints are exactly 1 line in height (15 pixels high), many are one or two characters wide.. The 5 odd ones do contain an almost-full window repaint, right at the beginning.
69 repaints are a single character wide (8x15)

What a really odd way of painting the screen!

So the good news is that I have a workaround:

XPRA_FORCE_BATCH=1 xpra start ...

Will start the server with force-batch mode, which means that even when things are going well (no pixel backlog or network congestion) we will wait before encoding the pixels, which allows us to batch them up together.
On my system, it makes things usable again.

cesarkawakami: does that improve things for you?

As for a more proper fix for this: I'm not too sure how to go about it.
Should we always enable batching by default? (vnc does) We would lose a tiny bit of latency in some cases (well behaved applications) just to workaround applications with pathological behaviour...

Another approach would be to enable batching when we detect a damage storm like this one. Which is probably the better option, but may not be suitable for a 0.14.x backport.

totaam · 2014-09-05T06:39:15Z

The slightly better solution implemented in r7516 is to turn on damage batching if we find more than 5 damage events in the last 10 milliseconds.
The downside is that those 5 events will still get sent unbatched before the rest, but at least we don't penalize well behaved application too much (well, doing the checking has its own cost... but hopefully not too bad)

cesarkawakami: do both solutions work for you? Any other ideas?

FYI: using other encodings, even video encodings, seems to work just as well: the small updates get sent as rgb anyway.

Note: emacs just sitting idle will repaint the cursor even when it isn't focused or blinking, causing 4 damage events as it repaints each line around the hollow cursor individually!

totaam · 2014-09-05T18:41:58Z

2014-09-05 18:41:58: cesarkawakami2 commented

[For some reason I can neither login with my previous account nor get my username/email combination accepted in the "reset password" screen. Weird.]

Unfortunately, I just now noticed my xpra server was already batching updates, so none of the workarounds above work in my case.

totaam · 2014-09-06T05:04:56Z

For some reason I can neither login with my previous account..

Sorry about that, there were many spam accounts created yesterday, and I must have deleted your account by mistake.

my xpra server was already batching updates, so none of the workarounds above work in my case

That's odd, they make a very noticeable difference on my test setup.
How did you verify this?
Can you post xpra info of when things are bad and the server's -d encoding log?

totaam · 2014-09-08T04:38:39Z

2014-09-08 04:38:39: totaam commented

Many problems identified:

rgb formats are missing for an osx client because opengl is disabled on Intel 3000 (see OSX client crashes with Intel opengl driver #563), so rgb encoding ends up byteswapping the data from BGRX to RGBX server-side (which slows it down a lot)
profiling output shows we spend too much time in intersect_rect (was discussed in performance optimizations from profiling #620 already and wrongly discarded):

SERVER COMMAND LINE:
XPRA_FORCE_BATCH=1 ./xpra-profile start :100 --start-child='gvim /home/cesarkawakami/repo/swag/geekie/swag/models/user.py' --no-speaker --no-daemon
 
CLIENT COMMAND LINE:
xpra attach ssh:pndev5:100 --no-swap-keys --encoding=rgb -z 0
 
Basic info:
    Sampling interval: 0.010 s
    Number of samples: 12483
    Overhead per sample: 0.0005 s
    Overhead percentage: 4.9%
    Thread IDs:
        140217407133440
        140217423451904
        140217436587776
        140217444980480
        140217453373184
        140217461765888
        140217543464704
        140218011969280
        140218046990144
    Total CPU time in samples: 22.6587 s
|- ./xpra-profile:57:<module> (12.82, 56.6%)
| \- /usr/lib/python2.7/dist-packages/xpra/scripts/main.py:103:main (12.82, 56.6%)
|   \- /usr/lib/python2.7/dist-packages/xpra/scripts/main.py:761:run_mode (12.82, 56.6%)
|     \- /usr/lib/python2.7/dist-packages/xpra/scripts/server.py:997:run_server (12.82, 56.6%)
|       \- /usr/lib/python2.7/dist-packages/xpra/server/server_base.py:403:run (12.82, 56.6%)
|         \- /usr/lib/python2.7/dist-packages/xpra/server/server_core.py:290:run (12.82, 56.6%)
|           \- /usr/lib/python2.7/dist-packages/xpra/server/gtk_server_base.py:51:do_run (12.82, 56.6%)
|             \- /usr/lib/python2.7/dist-packages/xpra/gtk_common/gtk2common.py:15:gtk2main (12.82, 56.6%)
|               |- /usr/lib/python2.7/dist-packages/xpra/x11/gtk_x11/composite.py:229:do_xpra_damage_event (6.07, 26.8%)
|               | \- /usr/lib/python2.7/dist-packages/xpra/x11/gtk_x11/window.py:395:_forward_contents_changed (5.85, 25.8%)
|               |   \- /usr/lib/python2.7/dist-packages/xpra/x11/server.py:614:_contents_changed (5.33, 23.5%)
|               |     \- /usr/lib/python2.7/dist-packages/xpra/server/server_base.py:1625:_damage (5.28, 23.3%)
|               |       \- /usr/lib/python2.7/dist-packages/xpra/server/source.py:1557:damage (5.28, 23.3%)
|               |         \- /usr/lib/python2.7/dist-packages/xpra/server/window_source.py:671:damage (4.99, 22.0%)
|               |           \- /usr/lib/python2.7/dist-packages/xpra/server/region.py:148:add_rectangle (4.80, 21.2%)
|               |             \- /usr/lib/python2.7/dist-packages/xpra/server/region.py:54:intersects_rect (4.21, 18.6%)
|               \- /usr/lib/python2.7/dist-packages/xpra/log.py:160:__call__ (1.62, 7.1%)
\- /usr/lib/python2.7/threading.py:783:__bootstrap (9.84, 43.4%)
  \- /usr/lib/python2.7/threading.py:810:__bootstrap_inner (9.84, 43.4%)
    \- /usr/lib/python2.7/threading.py:763:run (9.76, 43.1%)
      |- /usr/lib/python2.7/dist-packages/xpra/server/source.py:1615:encode_loop (7.15, 31.6%)
      | \- /usr/lib/python2.7/dist-packages/xpra/server/window_source.py:1057:make_data_packet_cb (6.46, 28.5%)
      |   \- /usr/lib/python2.7/dist-packages/xpra/server/window_source.py:1333:make_data_packet (6.11, 27.0%)
      |     \- /usr/lib/python2.7/dist-packages/xpra/server/window_source.py:1344:rgb_encode (6.07, 26.8%)
      |       \- /usr/lib/python2.7/dist-packages/xpra/server/picture_encode.py:164:rgb_encode (6.07, 26.8%)
      |         \- /usr/lib/python2.7/dist-packages/xpra/server/picture_encode.py:353:rgb_reformat (4.92, 21.7%)
      |           \- /usr/lib/python2.7/dist-packages/PIL/Image.py:573:tostring (2.03, 9.0%)
      |             \- /usr/lib/python2.7/dist-packages/PIL/Image.py:564:tobytes (1.77, 7.8%)
      \- /usr/lib/python2.7/dist-packages/xpra/server/source.py:1619:encode_loop (1.59, 7.0%)

That's twice as much time figuring out what to do (rectangles calculations) than actually doing it! (encode loop)

totaam · 2014-09-08T18:15:12Z

2014-09-08 18:15:12: cesarkawakami2 uploaded file `output.log.tar.gz` (269.0 KiB)

-d encoding, large screen

totaam · 2014-09-08T18:30:45Z

2014-09-08 18:30:45: cesarkawakami2 commented

With large screen, the rectangles computation issue is more pronounced:

Basic info:
    Sampling interval: 0.010 s
    Number of samples: 8208
    Overhead per sample: 0.0001 s
    Overhead percentage: 1.3%
    Thread IDs:
        140326658230016
        140326680794880
        140326693930752
        140326706603776
        140326714996480
        140326792697600
        140326801352448
        140327269771008
        140327304787776
    Total CPU time in samples: 14.4418 s
|- ./xpra-profile:66:<module> (10.99, 76.1%)
| \- /usr/lib/python2.7/dist-packages/xpra/scripts/main.py:103:main (10.99, 76.1%)
|   \- /usr/lib/python2.7/dist-packages/xpra/scripts/main.py:761:run_mode (10.99, 76.1%)
|     \- /usr/lib/python2.7/dist-packages/xpra/scripts/server.py:997:run_server (10.99, 76.1%)
|       \- /usr/lib/python2.7/dist-packages/xpra/server/server_base.py:403:run (10.99, 76.1%)
|         \- /usr/lib/python2.7/dist-packages/xpra/server/server_core.py:290:run (10.99, 76.1%)
|           \- /usr/lib/python2.7/dist-packages/xpra/server/gtk_server_base.py:51:do_run (10.99, 76.1%)
|             \- /usr/lib/python2.7/dist-packages/xpra/gtk_common/gtk2common.py:15:gtk2main (10.99, 76.1%)
|               |- /usr/lib/python2.7/dist-packages/xpra/x11/gtk_x11/composite.py:229:do_xpra_damage_event (6.89, 47.7%)
|               | \- /usr/lib/python2.7/dist-packages/xpra/x11/gtk_x11/window.py:395:_forward_contents_changed (6.56, 45.4%)
|               |   \- /usr/lib/python2.7/dist-packages/xpra/x11/server.py:614:_contents_changed (6.18, 42.8%)
|               |     \- /usr/lib/python2.7/dist-packages/xpra/server/server_base.py:1625:_damage (6.13, 42.5%)
|               |       \- /usr/lib/python2.7/dist-packages/xpra/server/source.py:1557:damage (6.13, 42.5%)
|               |         \- /usr/lib/python2.7/dist-packages/xpra/server/window_source.py:671:damage (5.96, 41.3%)
|               |           \- /usr/lib/python2.7/dist-packages/xpra/server/region.py:157:add_rectangle (5.83, 40.4%)
|               |             \- /usr/lib/python2.7/dist-packages/xpra/server/region.py:60:intersects_rect (4.98, 34.5%)
|               |               |- /usr/lib/python2.7/dist-packages/xpra/server/region.py:49:intersects (1.32, 9.2%)
|               |               \- /usr/lib/python2.7/dist-packages/xpra/server/region.py:53:intersects (0.83, 5.8%)
|               |- /usr/lib/python2.7/dist-packages/xpra/x11/gtk_x11/composite.py:226:do_xpra_damage_event (1.21, 8.4%)
|               \- /usr/lib/python2.7/dist-packages/xpra/log.py:160:__call__ (0.84, 5.8%)
\- /usr/lib/python2.7/threading.py:783:__bootstrap (3.46, 23.9%)
  \- /usr/lib/python2.7/threading.py:810:__bootstrap_inner (3.46, 23.9%)
    \- /usr/lib/python2.7/threading.py:763:run (3.42, 23.7%)
      \- /usr/lib/python2.7/dist-packages/xpra/server/source.py:1615:encode_loop (2.91, 20.1%)
        \- /usr/lib/python2.7/dist-packages/xpra/server/window_source.py:1057:make_data_packet_cb (2.42, 16.7%)
          \- /usr/lib/python2.7/dist-packages/xpra/server/window_source.py:1333:make_data_packet (2.33, 16.1%)
            \- /usr/lib/python2.7/dist-packages/xpra/server/window_source.py:1344:rgb_encode (2.33, 16.1%)
              \- /usr/lib/python2.7/dist-packages/xpra/server/picture_encode.py:164:rgb_encode (2.33, 16.1%)
                \- /usr/lib/python2.7/dist-packages/xpra/net/compression.py:195:compressed_wrapper (0.82, 5.7%)

Attached, the {-d encoding} log of my server.

Also, I've extracted a damage log from output.log and updated test_region.py with it. It seems that even though we have less rectangles, add_rectangle is having a harder time with them:

$ python test_region.py  # the original
created 365 rectangles in 0.23ms
add_rectangle 365 rectangles in 1.09ms
created 142 rectangles in 0.09ms
add_rectangle 142 rectangles in 0.50ms

$ python test_region_2.py  # modified with the new damage log from the larger screen
created 135 rectangles in 0.08ms
add_rectangle 135 rectangles in 2.02ms

Interesting.

totaam · 2014-09-08T18:33:13Z

2014-09-08 18:33:13: cesarkawakami2 uploaded file `xprainfo` (75.7 KiB)

xpra info

totaam · 2014-09-08T18:33:30Z

2014-09-08 18:33:30: cesarkawakami2 commented

I've also attached xpra info for this session.

totaam · 2014-09-08T19:52:23Z

2014-09-08 19:52:23: totaam commented

Can you please try to see how much difference the patch in #620#comment:18 makes? I haven't merged it because it didn't make enough of a difference.. but I've been proven wrong already.

totaam · 2014-09-09T17:51:26Z

The patch breaks "video regions" (which needs to modify the region), and cesarkawakami also reported "random spinfreezes"... so I think we should forget about this one.
It's just not worth the trouble.

totaam · 2014-12-26T08:10:15Z

FYI:

it should now be slightly easier to see what is going on with repaints, see debug option for subregion color coding according to encodings, quality, speed, etc? #760
we now have support for "multi-delta" which should improve things with mostly useless unnecessary repaints, see multi delta #756

totaam · 2015-01-06T06:47:54Z

2015-01-06 06:47:54: antoine uploaded file `gvim-repaints.png` (386.7 KiB)

shows gvim repainting using rgb24 (orange colour)

totaam · 2015-01-06T06:50:20Z

Thanks to the work on #760, I fixed a bug in the damage region merging code (fixed in 8374). This is included in the upcoming 0.14.16

The repaints now look like this gvim-repaints.png

If you can reproduce the problem, please include a screenshot using:

XPRA_OPENGL_PAINT_BOX=1 xpra attach ...

As per #760. This may show us what is going on in more detail.

totaam · 2015-01-24T07:23:38Z

Not heard back, I assume this is fixed. Closing.

totaam closed this as completed Jan 24, 2015

totaam added the v0.14.x label Jan 22, 2021

This was referenced Jan 22, 2021

lossless element re-painting seems to be overlooked when latency gets high #750

Closed

multi delta #756

Closed

Slow update when editing #2545

Closed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Subpar performance when running gvim or emacs #670

Subpar performance when running gvim or emacs #670

totaam commented Sep 4, 2014

totaam commented Sep 5, 2014 •

edited

Loading

totaam commented Sep 5, 2014 •

edited

Loading

totaam commented Sep 5, 2014

totaam commented Sep 6, 2014 •

edited

Loading

totaam commented Sep 8, 2014

totaam commented Sep 8, 2014

totaam commented Sep 8, 2014

totaam commented Sep 8, 2014

totaam commented Sep 8, 2014

totaam commented Sep 8, 2014

totaam commented Sep 9, 2014 •

edited

Loading

totaam commented Dec 26, 2014 •

edited

Loading

totaam commented Jan 6, 2015

totaam commented Jan 6, 2015 •

edited

Loading

totaam commented Jan 24, 2015 •

edited

Loading

Subpar performance when running gvim or emacs #670

Subpar performance when running gvim or emacs #670

Comments

totaam commented Sep 4, 2014

2014-09-04 21:02:08: cesarkawakami created the issue

totaam commented Sep 5, 2014 • edited Loading

totaam commented Sep 5, 2014 • edited Loading

totaam commented Sep 5, 2014

2014-09-05 18:41:58: cesarkawakami2 commented

totaam commented Sep 6, 2014 • edited Loading

totaam commented Sep 8, 2014

2014-09-08 04:38:39: totaam commented

totaam commented Sep 8, 2014

2014-09-08 18:15:12: cesarkawakami2 uploaded file output.log.tar.gz (269.0 KiB)

totaam commented Sep 8, 2014

2014-09-08 18:30:45: cesarkawakami2 commented

totaam commented Sep 8, 2014

2014-09-08 18:33:13: cesarkawakami2 uploaded file xprainfo (75.7 KiB)

totaam commented Sep 8, 2014

2014-09-08 18:33:30: cesarkawakami2 commented

totaam commented Sep 8, 2014

2014-09-08 19:52:23: totaam commented

totaam commented Sep 9, 2014 • edited Loading

totaam commented Dec 26, 2014 • edited Loading

totaam commented Jan 6, 2015

2015-01-06 06:47:54: antoine uploaded file gvim-repaints.png (386.7 KiB)

totaam commented Jan 6, 2015 • edited Loading

totaam commented Jan 24, 2015 • edited Loading

totaam commented Sep 5, 2014 •

edited

Loading

totaam commented Sep 5, 2014 •

edited

Loading

totaam commented Sep 6, 2014 •

edited

Loading

2014-09-08 18:15:12: cesarkawakami2 uploaded file `output.log.tar.gz` (269.0 KiB)

2014-09-08 18:33:13: cesarkawakami2 uploaded file `xprainfo` (75.7 KiB)

totaam commented Sep 9, 2014 •

edited

Loading

totaam commented Dec 26, 2014 •

edited

Loading

2015-01-06 06:47:54: antoine uploaded file `gvim-repaints.png` (386.7 KiB)

totaam commented Jan 6, 2015 •

edited

Loading

totaam commented Jan 24, 2015 •

edited

Loading