xpra icon
Bug tracker and wiki

Opened 4 years ago

Closed 3 years ago

#670 closed defect (fixed)

Subpar performance when running gvim or emacs

Reported by: cesarkawakami Owned by: cesarkawakami
Priority: critical Milestone:
Component: core Version: 0.14.x
Keywords: performance paint gvim emacs damage storm Cc: Antoine Martin

Description (last modified by Antoine Martin)

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.

Attachments (3)

output.log.tar.gz (269.0 KB) - added by cesarkawakami2 4 years ago.
-d encoding, large screen
xprainfo (75.7 KB) - added by cesarkawakami2 4 years ago.
xpra info
gvim-repaints.png (386.7 KB) - added by Antoine Martin 3 years ago.
shows gvim repainting using rgb24 (orange colour)

Download all attachments as: .zip

Change History (16)

comment:1 Changed 4 years ago by Antoine Martin

Description: modified (diff)
Owner: changed from Antoine Martin to Antoine Martin
Status: newassigned

comment:2 Changed 4 years ago by Antoine Martin

Description: modified (diff)

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.

Last edited 4 years ago by Antoine Martin (previous) (diff)

comment:3 Changed 4 years ago by Antoine Martin

Owner: changed from Antoine Martin to cesarkawakami
Status: assignednew

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!

comment:4 Changed 4 years ago by cesarkawakami2

[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.

comment:5 Changed 4 years ago by Antoine Martin

Owner: changed from cesarkawakami to cesarkawakami2

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?

comment:6 Changed 4 years ago by Antoine Martin

Many problems identified:

  • rgb formats are missing for an osx client because opengl is disabled on Intel 3000 (see #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 #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)

Last edited 4 years ago by Antoine Martin (previous) (diff)

Changed 4 years ago by cesarkawakami2

Attachment: output.log.tar.gz added

-d encoding, large screen

comment:7 Changed 4 years ago by cesarkawakami2

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.

Changed 4 years ago by cesarkawakami2

Attachment: xprainfo added

xpra info

comment:8 Changed 4 years ago by cesarkawakami2

I've also attached xpra info for this session.

comment:9 Changed 4 years ago by Antoine Martin

Can you please try to see how much difference the patch in ticket: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.

comment:10 Changed 4 years ago by Antoine Martin

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.

comment:11 Changed 3 years ago by Antoine Martin

FYI:

  • it should now be slightly easier to see what is going on with repaints, see #760
  • we now have support for "multi-delta" which should improve things with mostly useless unnecessary repaints, see #756

Changed 3 years ago by Antoine Martin

Attachment: gvim-repaints.png added

shows gvim repainting using rgb24 (orange colour)

comment:12 Changed 3 years ago by Antoine Martin

Owner: changed from cesarkawakami2 to cesarkawakami

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

The repaints now look like this:
shows gvim repainting using rgb24 (orange colour)

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.

comment:13 Changed 3 years ago by Antoine Martin

Resolution: fixed
Status: newclosed

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

Note: See TracTickets for help on using tickets.