Xpra: Ticket #1300: initial lossless packets are too expensive with html5 client

Thinking of the html5 client... we've been running with only jpeg enabled, just to keep the packets the client has to process as lean as possible - but we're also getting a lot of blurriness (unsurprisingly) as a result.

It would be nice to also allow a lossless encoding, like rgb, but when we try we end up with so much lossless information initially that the client is very slow to connect.

If we could maybe start the server with a flag to force an encoding, like jpeg, for the initial connection, but then let the heuristics take back over to determine when/where/if to use other encodings (rgb, whatever)... then the html5 client might be a lot more flexible.

I'll attach an info log for what our server looks like at the initial connection (my best guess, not a lot of visibility into which moment of initial connection is best to capture), and another info from a session after things have "settled down".

As you can probably tell from the info logs, in both cases we're using only jpeg (let me know if you need info with other encodings enabled or anything).

Hopefully my capture timing was enlightening.



Wed, 07 Sep 2016 22:30:05 GMT - alas: attachment set

my best guess of moment of initial connection, xpra info


Wed, 07 Sep 2016 22:30:26 GMT - alas: attachment set

info after the page elements loaded


Fri, 09 Sep 2016 09:10:49 GMT - Antoine Martin: owner, summary changed

(changed ticket title: let's focus on identifying the problem before deciding on a solution)

I need the logs with rgb and png, since that's what shows the problem and also what I have when I run the current html5 client code. Is the problem only with rgb? What about png? How do you quantify it?

I am tempted to wait for the new client code to land before making any changes.


Fri, 09 Sep 2016 16:33:16 GMT - alas:

All things considered, I may have to wait until new client code lands before I can get logs with rgb & png as well. I'll see what I can do though, maybe get some logs for you to look at and consider while examining the new code coming in for a landing.


Thu, 03 Nov 2016 14:17:00 GMT - Antoine Martin:

I have seen this, even with the python client, r14355 should fix that. It ensures we don't use plain rgb until we have enough packets to tune the heuristics.


Wed, 23 Nov 2016 22:56:53 GMT - J. Max Mena: status changed; resolution set

tl;dr: r14355 did it, that works great, closing. Thanks!


EDIT: Setting up a r14479 trunk server, and connecting with an html5 client and a Python client of the same revision, we can do some testing and get some relevant logs:

Right, so running with -d compress,paint,encoding on the server, and looking at the paint prints upon connecting, here's what the server prints when an html5 client connects:

2016-11-23 14:41:26,215 send_delayed_regions: using full window update 499x316 with jpeg
2016-11-23 14:41:26,216 process_damage_region: wid=1, adding pixel data to encode queue ( 499x316  -  jpeg), elapsed time: 51.9 ms, request time: 0.7 ms, frame delay=0ms
2016-11-23 14:41:26,216 make_data_packet: image=XShmImageWrapper(BGRX: 0, 0, 499, 316), damage data: (1, 0, 0, 499, 316, 'jpeg')
2016-11-23 14:41:26,218 compress:   1.6ms for  499x316  pixels at    0,0    for wid=1     using   jpeg with ratio   7.4%  (  615KB to    45KB), sequence     1, client_options={'quality': 99}
2016-11-23 14:41:26,249 send_delayed for wid 2, batch delay is 52ms, elapsed time is 77ms
2016-11-23 14:41:26,250 send_delayed_regions: bytes_cost=1083040, bytes_threshold=649209, pixel_count=1082016
2016-11-23 14:41:26,250 send_delayed_regions: using full window update 1248x867 with jpeg
2016-11-23 14:41:26,251 process_damage_region: wid=2, adding pixel data to encode queue (1248x867  -  jpeg), elapsed time: 79.1 ms, request time: 1.3 ms, frame delay=0ms
2016-11-23 14:41:26,251 make_data_packet: image=XShmImageWrapper(BGRX: 0, 0, 1248, 867), damage data: (2, 0, 0, 1248, 867, 'jpeg')
2016-11-23 14:41:26,264 compress:  12.8ms for 1248x867  pixels at    0,0    for wid=2     using   jpeg with ratio   9.3%  ( 4226KB to   391KB), sequence     1, client_options={'quality': 99}
2016-11-23 14:41:26,266 update_encoding_options(False) auto_refresh_encodings=['png', 'rgb32']
2016-11-23 14:41:26,267 update_encoding_options(False) want_alpha=False, lossless threshold: 74 / 6, small_as_rgb=6082, get_best_encoding=<bound method WindowVideoSource.get_best_encoding_video of WindowVideoSource(1 : (499, 316))>
2016-11-23 14:41:26,267 update_encoding_options(False) csc_encoder=None, video_encoder=None
2016-11-23 14:41:26,344 send_delayed for wid 2, batch delay is 52ms, elapsed time is 77ms
2016-11-23 14:41:26,344 send_delayed_regions: bytes_cost=175872, bytes_threshold=649209, pixel_count=172800
2016-11-23 14:41:26,344 send_delayed_regions: merged=[R(164, 126, 480, 360)], merged_bytes_cost=173824, bytes_cost=175872, merged_pixel_count=172800, pixel_count=172800
2016-11-23 14:41:26,345 process_damage_region: wid=2, adding pixel data to encode queue ( 480x360  -  jpeg), elapsed time: 79.2 ms, request time: 0.9 ms, frame delay=0ms
2016-11-23 14:41:26,345 send_delayed_regions: sent 1 regions using ['jpeg']

Looks straightforward, it's printing using jpeg - what we want.

And, here again with the Python client:

2016-11-23 14:44:06,561 send_delayed_regions: using full window update 499x316 with jpeg
2016-11-23 14:44:06,561 process_damage_region: wid=1, adding pixel data to encode queue ( 499x316  -  jpeg), elapsed time: 51.6 ms, request time: 0.5 ms, frame delay=0ms
2016-11-23 14:44:06,561 make_data_packet: image=XShmImageWrapper(BGRX: 0, 0, 499, 316), damage data: (1, 0, 0, 499, 316, 'jpeg')
2016-11-23 14:44:06,563 compress:   1.6ms for  499x316  pixels at    0,0    for wid=1     using   jpeg with ratio   7.4%  (  615KB to    45KB), sequence     1, client_options={'quality': 99}
2016-11-23 14:44:06,573 update_encoding_options(False) auto_refresh_encodings=['png', 'rgb24', 'rgb32']
2016-11-23 14:44:06,574 update_encoding_options(False) want_alpha=False, lossless threshold: 74 / 6, small_as_rgb=6082, get_best_encoding=<bound method WindowVideoSource.get_best_encoding_video of WindowVideoSource(1 : (499, 316))>
2016-11-23 14:44:06,574 update_encoding_options(False) csc_encoder=None, video_encoder=None
2016-11-23 14:44:06,596 send_delayed for wid 2, batch delay is 52ms, elapsed time is 77ms
2016-11-23 14:44:06,596 send_delayed_regions: bytes_cost=1083040, bytes_threshold=649209, pixel_count=1082016
2016-11-23 14:44:06,596 send_delayed_regions: using full window update 1248x867 with jpeg
2016-11-23 14:44:06,598 process_damage_region: wid=2, adding pixel data to encode queue (1248x867  -  jpeg), elapsed time: 79.3 ms, request time: 1.5 ms, frame delay=0ms
2016-11-23 14:44:06,598 make_data_packet: image=XShmImageWrapper(BGRX: 0, 0, 1248, 867), damage data: (2, 0, 0, 1248, 867, 'jpeg')
2016-11-23 14:44:06,611 compress:  12.8ms for 1248x867  pixels at    0,0    for wid=2     using   jpeg with ratio   9.3%  ( 4226KB to   391KB), sequence     1, client_options={'quality': 99}
2016-11-23 14:44:06,703 send_delayed for wid 2, batch delay is 52ms, elapsed time is 77ms
2016-11-23 14:44:06,703 send_delayed_regions: bytes_cost=175872, bytes_threshold=649209, pixel_count=172800
2016-11-23 14:44:06,704 send_delayed_regions: merged=[R(164, 126, 480, 360)], merged_bytes_cost=173824, bytes_cost=175872, merged_pixel_count=172800, pixel_count=172800
2016-11-23 14:44:06,705 process_damage_region: wid=2, adding pixel data to encode queue ( 480x360  -  jpeg), elapsed time: 79.1 ms, request time: 1.1 ms, frame delay=0ms
2016-11-23 14:44:06,705 send_delayed_regions: sent 1 regions using ['jpeg']

Slightly different, but again, only painting with jpeg upon initial connection.

After the connection settles, the html5 client gets the server to print:

2016-11-23 14:41:26,603 compress:  16.4ms for  480x360  pixels at  164,126  for wid=2     using    png with ratio  37.0%  (  675KB to   249KB), sequence     5, client_options={'compress_level': 1}
2016-11-23 14:41:26,652 send_delayed for wid 2, batch delay is 52ms, elapsed time is 52ms
2016-11-23 14:41:26,652 send_delayed_regions: bytes_cost=175872, bytes_threshold=649209, pixel_count=172800
2016-11-23 14:41:26,652 send_delayed_regions: merged=[R(164, 126, 480, 360)], merged_bytes_cost=173824, bytes_cost=175872, merged_pixel_count=172800, pixel_count=172800
2016-11-23 14:41:26,653 process_damage_region: wid=2, adding pixel data to encode queue ( 480x360  -  auto), elapsed time: 54.3 ms, request time: 0.9 ms, frame delay=0ms
2016-11-23 14:41:26,653 send_delayed_regions: sent 1 regions using ['auto']
2016-11-23 14:41:26,653 make_data_packet: image=XShmImageWrapper(BGRX: 164, 126, 480, 360), damage data: (2, 164, 126, 480, 360, 'auto')
2016-11-23 14:41:26,654 <bound method WindowVideoSource.video_encode of WindowVideoSource(2 : (1248, 867))>('auto', XShmImageWrapper(BGRX: 164, 126, 480, 360), {'scroll': True}) returned None
2016-11-23 14:41:26,718 send_delayed for wid 2, batch delay is 52ms, elapsed time is 52ms
2016-11-23 14:41:26,719 send_delayed_regions: bytes_cost=175872, bytes_threshold=649209, pixel_count=172800
2016-11-23 14:41:26,719 send_delayed_regions: merged=[R(164, 126, 480, 360)], merged_bytes_cost=173824, bytes_cost=175872, merged_pixel_count=172800, pixel_count=172800
2016-11-23 14:41:26,720 process_damage_region: wid=2, adding pixel data to encode queue ( 480x360  -  auto), elapsed time: 54.0 ms, request time: 0.9 ms, frame delay=0ms
2016-11-23 14:41:26,720 send_delayed_regions: sent 1 regions using ['auto']

Looks like we switched to PNG, expected - not a whole lot going on, only got Chrome open and not even interacting.

And, the same with a Python client connected:

2016-11-23 14:44:06,857 send_delayed_regions: using full window update 499x316 with png
2016-11-23 14:44:06,857 process_damage_region: wid=1, adding pixel data to encode queue ( 499x316  -   png), elapsed time: 0.4 ms, request time: 0.1 ms, frame delay=0ms
2016-11-23 14:44:06,857 make_data_packet: image=XShmImageWrapper(BGRX: 0, 0, 499, 316), damage data: (1, 0, 0, 499, 316, 'png')
2016-11-23 14:44:06,865 compress:   7.2ms for  499x316  pixels at    0,0    for wid=1     using    png with ratio   1.1%  (  615KB to     7KB), sequence     2, client_options={'compress_level': 3}
2016-11-23 14:44:06,906 send_delayed for wid 2, batch delay is 52ms, elapsed time is 52ms
2016-11-23 14:44:06,906 send_delayed_regions: bytes_cost=175872, bytes_threshold=649209, pixel_count=172800
2016-11-23 14:44:06,906 send_delayed_regions: merged=[R(164, 126, 480, 360)], merged_bytes_cost=173824, bytes_cost=175872, merged_pixel_count=172800, pixel_count=172800
2016-11-23 14:44:06,907 process_damage_region: wid=2, adding pixel data to encode queue ( 480x360  -  auto), elapsed time: 54.5 ms, request time: 1.3 ms, frame delay=0ms
2016-11-23 14:44:06,908 send_delayed_regions: sent 1 regions using ['auto']
2016-11-23 14:44:06,908 make_data_packet: image=XShmImageWrapper(BGRX: 164, 126, 480, 360), damage data: (2, 164, 126, 480, 360, 'auto')
2016-11-23 14:44:06,928 compress:  20.2ms for  480x360  pixels at  164,126  for wid=2     using   h264 with ratio  35.4%  (  675KB to   239KB), sequence     4, client_options={'pts': 0, 'frame': 0, 'csc': 'YUV444P', 'type': 'IDR', 'quality': 99, 'speed': 85}
2016-11-23 14:44:06,979 send_delayed for wid 2, batch delay is 52ms, elapsed time is 52ms
2016-11-23 14:44:06,979 send_delayed_regions: bytes_cost=175872, bytes_threshold=649209, pixel_count=172800
2016-11-23 14:44:06,979 send_delayed_regions: merged=[R(164, 126, 480, 360)], merged_bytes_cost=173824, bytes_cost=175872, merged_pixel_count=172800, pixel_count=172800
2016-11-23 14:44:06,981 process_damage_region: wid=2, adding pixel data to encode queue ( 480x360  -  auto), elapsed time: 54.8 ms, request time: 1.3 ms, frame delay=0ms
2016-11-23 14:44:06,981 send_delayed_regions: sent 1 regions using ['auto']

Also, expected - so it is switching eventually (both go on to use rgb eventually), which is good.

And, rolling the server back to r14350:

016-11-23 14:48:36,905 send_delayed for wid 1, batch delay is 19ms, elapsed time is 50ms
2016-11-23 14:48:36,905 send_delayed_regions: bytes_cost=158708, bytes_threshold=94610, pixel_count=157684
2016-11-23 14:48:36,905 get_best_encoding_video(..) temporarily switching to lossless mode for   157684 pixels: low pixel count
2016-11-23 14:48:36,905 send_delayed_regions: using full window update 499x316 with rgb24
2016-11-23 14:48:36,906 process_damage_region: wid=1, adding pixel data to encode queue ( 499x316  - rgb24), elapsed time: 51.2 ms, request time: 0.6 ms, frame delay=0ms
2016-11-23 14:48:36,906 make_data_packet: image=XShmImageWrapper(BGRX: 0, 0, 499, 316), damage data: (1, 0, 0, 499, 316, 'rgb24')
2016-11-23 14:48:36,906 rgb_encode reformatting because BGRX not in ['RGB', 'RGBX']
2016-11-23 14:48:36,906 rgb_reformat: converting XShmImageWrapper(BGRX: 0, 0, 499, 316) from BGRX to RGB using PIL
2016-11-23 14:48:36,907 rgb_reformat(XShmImageWrapper(RGB: 0, 0, 499, 316), ['RGB', 'RGBX'], False) converted from BGRX (630736 bytes) to RGB (473052 bytes) in 1.3ms, rowstride=1497
2016-11-23 14:48:36,908 rgb_encode using level=1, lz4 compressed 499x316 in rgb24/RGB: 473052 bytes down to 6217
2016-11-23 14:48:36,908 compress:   1.6ms for  499x316  pixels at    0,0    for wid=1     using rgb24 with ratio   1.0% (  615KB to     6KB), sequence     1, client_options={'lz4': 1, 'rgb_format': 'RGB'}
2

Is what I get upon connecting an html5 client - there we go, that was a clear indicator of the issue we were seeing, so the changes in r14355 is what did it.

Closing.


Sat, 23 Jan 2021 05:20:30 GMT - migration script:

this ticket has been moved to: https://github.com/Xpra-org/xpra/issues/1300