degrading video quality more than the rest

Issue migrated from trac ticket # 1135

component: encodings | priority: critical | resolution: fixed

2016-02-24 05:43:18: antoine created the issue

Similar and related to #1130 and #967: we want to ensure that when we need to make sacrifices to cope with the amount of pixels that need to be encoded we sacrifice the video area picture quality (if there is video), before we degrade the rest of the window. And also make sure that we only use a video encoder when it is the right choice for the content.

We already have hooks for this: [/browser/xpra/tags/v0.16.x/src/xpra/server/window/window_video_source.py#L441 WindowVideoSource get_speed / get_quality]: the non-video areas get a huge speed and quality boost.

Other things we could / should be doing:

maybe the boost code above should be replaced by more aggressive speed and quality mappings in the video codecs themselves? Changing the tuning code to give higher values for quality and speed by default and/or use non-video lossless at a lower threshold (currently between 75 to 100 depending on the size of the area to encode)

more aggressively switch to YUV420P: if we are using a video encoder, we are very likely to be sending the data losslessly already (unless the quality is set to 100), so using a subsampled colourspace probably does not matter much and will save a lot of CPU / bandwidth which we can use for other things - can be tested using XPRA_FORCE_CSC_MODE=YUV420P xpra start ... - I believe newer versions already do this

automatic video scaling: this is probably OK as it is (we have a command line switch to control how aggressive it is: #692), can easily be tested and verified

more stringent video detection: only using video if we are absolutely certain that we are dealing with a video area (see #967#comment:11)

when the picture compression ratio is very high (#967 pages that repaint for no reason: successive frames are identical), we should automatically raise the quality

2016-02-24 09:35:15: antoine changed owner from antoine to afarr

2016-02-24 09:35:15: antoine edited the issue description

2016-02-24 09:35:15: antoine commented

r12028 tries to make the video region detection more strict, which may help

r12029 lowers the threshold for lossless updates (both for the case where we have video on screen and when we don't)

r12030 fixes a bug (oops) - backport makes me a bit nervous since no-one noticed this until now: this fix could make things worse

r12031 takes the compression ratio into account to update the quality setting (ie: better compression ratios should make us increase the quality, worse -> decrease)

You can see the server quality settings getting updated with -d stats by looking for update_quality in the output, or with:
xpra info | grep "encoding.quality"
The "backlog_factor" is new and takes the form: backlog_factor=(PACKETS, PIXELS, TARGET_QUALITY). When the recent compression ratio is better than average, the delta should increase the target quality. (and conversely, it should show a negative delta value to lower the quality when the recent is worse than average)

There are some new environment variables which can be used to tune the video region detection code (maybe this can be tuned better so as to exclude problematic cases like #967):

XPRA_VIDEO_DETECT_MAX_TIME - how far back we look for screen updates, defaults to 5 (in seconds)

XPRA_VIDEO_DETECT_MIN_EVENTS - within this timeframe, how many events we require to start looking for a video region, defaults to 20

@afarr: do you have reliable test cases to verify that this improves the corner cases we want to deal with?

2016-07-20 20:39:59: antoine commented

See also: #1257#comment:3 and #1257#comment:4.

2016-09-02 23:51:42: afarr commented

Testing with 1.0 r13520, both win32 client and fedora 23 server, I'm almost never seeing any change in the backlog_factor (I saw one instance where it was different, but otherwise the only value I've seen is 'backlog_factor': (0, 0, 100) with -d stats running).

I was so fixated on the backlog_factor (thinking this was an indicator of the compression ration you mentioned) that I almost missed that there is another value "two doors over" called - 'compression-ratio'. Nearly oops.

Using the awful site from #967 (http://www.msn.com/en-us/money) I'm finding that the quality, even when I am just looking at a static page, seems to be in the 30s regularly, even when the compression-ratio values are (0, 0, 0) (I am tempted to presume it also uses an (AVERAGE, RECENT, DELTA) format, but in that case the DELTA would often be 0... which I would think would indicate a likelihood that the successive frames are identical, in which case I would presume the quality would want to increase drastically, rather than remain in the 30s?).

Since I'm not entirely sure what to make of the compression-ratio values, I'll add some logs gathered with stats debugging enabled (I set up the pages, started the logging, behaved as the logs are named, then turned off the logging), but a couple quick excerpts for glancing at:
msn-money static.
update_quality() info={'batch-delay-ratio': 39, 'backlog_factor': (0, 0, 100), 'latency': 36101, 'compression-ratio': (1, 0, 13), 'min_quality': 30, 'min_speed': 30}, quality=44
update_speed() info={'frame_delay': 27, 'mpixels': 3, 'low_limit': 1154248, 'min_speed': 30, 'damage_latency': {'abs_factor': 0, 'rel_factor': 10, 'avg': 9, 'ref': 37, 'target': 37}, 'decoding_latency': {'target': 8000000, 'factor': 3}}, speed=44
packet decoding sequence 2969 for window 2: 1024x764 took 5.0ms
record_latency: took    6.9 ms round trip,    6.9 for echo,    5.0 for decoding of   782336 pixels,      192 bytes sent over the network in    1.9 ms,    1.9 ms for echo
may_recalculate(2, 782336) total 782336 pixels, scheduling recalculate work item
...

calculate_batch_delay for wid=2 current batch delay=26, last update 2 seconds ago calculate_batch_delay for wid=2, 35273880 pixels updated since the last update calculate_batch_delay for wid=2, skipping - only 10308 bytes sent since the last update update_quality() suspended=False, mmap=None, encoding=h264 update_quality() info={'batch-delay-ratio': 39, 'backlog_factor': (0, 0, 100), 'latency': 33582, 'compression-ratio': (0, 0, 0), 'min_quality': 30, 'min_speed': 30}, quality=39 update_speed() info={'frame_delay': 26, 'mpixels': 3, 'low_limit': 1154248, 'min_speed': 30, 'damage_latency': {'abs_factor': 0, 'rel_factor': 9, 'avg': 8, 'ref': 37, 'target': 37}, 'decoding_latency': {'target': 8000000, 'factor': 3}}, speed=44 packet decoding sequence 3012 for window 2: 1x764 took 1.0ms

...

calculate_batch_delay for wid=2 current batch delay=26, last update 5 seconds ago calculate_batch_delay for wid=2, 38706008 pixels updated since the last update calculate_batch_delay for wid=2, 204576 bytes sent since the last update update_batch_delay: damage-network-delay : 1.00,0.50 {'avg': 41, 'recent': 41} update_batch_delay: network-send-speed : 0.89,0.10 {'avg': 4, 'recent': 3} update_batch_delay: client-decode-speed : 1.04,0.00 {'avg': 4, 'recent': 5} update_batch_delay: damage-rate : 1.00,0.00 {'max_latency': 100, 'elapsed': 32} update_batch_delay: client-latency : 0.54,0.23 {'target': 5, 'weight_multiplier': 332, 'smoothing': 'sqrt', 'aim': 800, 'aimed_avg': 289, 'div': 1000, 'avg': 1, 'recent': 2} update_batch_delay: client-ping-latency : 0.50,0.12 {'target': 6, 'weight_multiplier': 168, 'smoothing': 'sqrt', 'aim': 949, 'aimed_avg': 249, 'div': 1000, 'avg': 2, 'recent': 1} update_batch_delay: server-ping-latency : 0.39,0.11 {'target': 4, 'weight_multiplier': 137, 'smoothing': 'sqrt', 'aim': 949, 'aimed_avg': 151, 'div': 1000, 'avg': 1, 'recent': 0} update_batch_delay: packet-queue-size : 0.12,0.14 {'target': 1000, 'weight_multiplier': 147, 'smoothing': 'sqrt', 'aim': 250, 'aimed_avg': 13, 'div': 1000, 'avg': 10, 'recent': 21} update_batch_delay: packet-queue-pixels : 0.12,0.11 {'target': 1000, 'weight_multiplier': 120, 'smoothing': 'sqrt', 'aim': 250, 'aimed_avg': 14, 'div': 1154248000, 'avg': 6275158, 'recent': 16845001} update_batch_delay: compression-work-queue : 0.29,0.53 {'target': 1000, 'weight_multiplier': 682, 'smoothing': 'logp', 'aim': 250, 'aimed_avg': 222, 'div': 1000, 'avg': 465, 'recent': 408} update_batch_delay: damage-packet-queue-pixels : 0.12,0.11 {'target': 1000, 'weight_multiplier': 120, 'smoothing': 'sqrt', 'aim': 250, 'aimed_avg': 14, 'div': 1154248000, 'avg': 6274879, 'recent': 16842001} update_batch_delay: focus : 1.00,0.00 {'has_focus': False} update_batch_delay: override-redirect : 1.00,0.00 {'is_OR': False} update_batch_delay: fullscreen : 0.00,0.00 {'other_is_fullscreen': False} update_batch_delay: maximized : 0.00,0.00 {'other_is_maximized': False} update_batch_delay: soft-expired : 0.00,0.00 {'count': 0} update_batch_delay: delay=28 update_quality() suspended=False, mmap=None, encoding=h264 update_quality() info={'batch-delay-ratio': 36, 'backlog_factor': (0, 0, 100), 'latency': 31695, 'compression-ratio': (2, 4, -11), 'min_quality': 30, 'min_speed': 30}, quality=34 update_speed() info={'frame_delay': 42, 'mpixels': 7, 'low_limit': 1154248, 'min_speed': 30, 'damage_latency': {'abs_factor': 0, 'rel_factor': 9, 'avg': 9, 'ref': 37, 'target': 42}, 'decoding_latency': {'target': 8000000, 'factor': 3}}, speed=44 packet decoding sequence 3151 for window 2: 1024x764 took 3.0ms record_latency: took 7.3 ms round trip, 7.3 for echo, 3.0 for decoding of 782336 pixels, 257 bytes sent over the network in 4.3 ms, 4.3 ms for echo may_recalculate(2, 782336) total 782336 pixels, scheduling recalculate work item
- msn-money with lots of mousing over the plentitude of widgets and ads.
calculate_batch_delay for wid=2 update_batch_delay: damage-network-delay update_batch_delay: network-send-speed update_batch_delay: client-decode-speed update_batch_delay: damage-rate update_batch_delay: client-latency update_batch_delay: client-ping-latency update_batch_delay: server-ping-latency update_batch_delay: packet-queue-size update_batch_delay: packet-queue-pixels update_batch_delay: compression-work-queue update_batch_delay: damage-packet-queue-pixels update_batch_delay: focus update_batch_delay: override-redirect update_batch_delay: fullscreen update_batch_delay: maximized update_batch_delay: soft-expired update_batch_delay: delay=126 update_quality() suspended=False, update_quality() info={'batch-delay-ratio': update_speed() info={'frame_delay': packet decoding sequence 1208 current batch delay=127, last update 1 seconds ago : 1.00,0.50 {'avg': 41, 'recent': 41} : 1.09,0.10 {'avg': 3, 'recent': 4} : 1.05,0.00 {'avg': 19, 'recent': 20} : 1.00,0.00 {'max_latency': 100, 'elapsed': 35} : 0.70,0.19 {'target': 5, 'weight_multiplier': 349, 'smoothing': 'sqrt', 'aim': 800, 'aimed_avg': 487, 'div': 1000, 'avg': 5, 'recent': 5} : 0.55,0.12 {'target': 6, 'weight_multiplier': 172, 'smoothing': 'sqrt', 'aim': 949, 'aimed_avg': 300, 'div': 1000, 'avg': 2, 'recent': 2} : 0.62,0.12 {'target': 7, 'weight_multiplier': 189, 'smoothing': 'sqrt', 'aim': 949, 'aimed_avg': 378, 'div': 1000, 'avg': 5, 'recent': 4} : 0.39,0.41 {'target': 1000, 'weight_multiplier': 521, 'smoothing': 'sqrt', 'aim': 250, 'aimed_avg': 155, 'div': 1000, 'avg': 265, 'recent': 271} : 0.09,0.08 {'target': 1000, 'weight_multiplier': 86, 'smoothing': 'sqrt', 'aim': 250, 'aimed_avg': 7, 'div': 1154248000, 'avg': 6125406, 'recent': 8574857} : 2.20,3.39 {'target': 1000, 'weight_multiplier': 2987, 'smoothing': 'logp', 'aim': 250, 'aimed_avg': 3579, 'div': 1000, 'avg': 8628, 'recent': 8927} : 0.09,0.08 {'target': 1000, 'weight_multiplier': 86, 'smoothing': 'sqrt', 'aim': 250, 'aimed_avg': 7, 'div': 1154248000, 'avg': 6125266, 'recent': 8574706} : 1.00,0.00 {'has_focus': False} : 1.00,0.00 {'is_OR': False} : 0.00,0.00 {'other_is_fullscreen': False} : 0.00,0.00 {'other_is_maximized': False} : 0.00,0.00 {'count': 0} mmap=None, encoding=h264 8, 'backlog_factor': (0, 0, 100), 'latency': 3863, 'compression-ratio': (112, 122, -6), 'min_quality': 30, 'min_speed': 30}, quality=32 81, 'mpixels': 15, 'low_limit': 1154248, 'min_speed': 30, 'damage_latency': {'abs_factor': 15, 'rel_factor': 39, 'avg': 60, 'ref': 37, 'target': 81}, 'decoding_latency': {'target': 8000000, 'factor': 14}}, speed=56 for window 2: 317x253 took 3.0ms

...

calculate_batch_delay for wid=2 current batch delay=126, last update 0 seconds ago update_batch_delay: damage-network-delay : 1.00,0.50 {'avg': 41, 'recent': 41} update_batch_delay: network-send-speed : 1.07,0.10 {'avg': 5, 'recent': 5} update_batch_delay: client-decode-speed : 1.18,0.03 {'avg': 31, 'recent': 40} update_batch_delay: damage-rate : 1.00,0.00 {'max_latency': 100, 'elapsed': 52} update_batch_delay: client-latency : 0.75,0.18 {'target': 5, 'weight_multiplier': 353, 'smoothing': 'sqrt', 'aim': 800, 'aimed_avg': 563, 'div': 1000, 'avg': 5, 'recent': 6} update_batch_delay: client-ping-latency : 0.55,0.12 {'target': 6, 'weight_multiplier': 172, 'smoothing': 'sqrt', 'aim': 949, 'aimed_avg': 301, 'div': 1000, 'avg': 2, 'recent': 2} update_batch_delay: server-ping-latency : 0.63,0.12 {'target': 7, 'weight_multiplier': 189, 'smoothing': 'sqrt', 'aim': 949, 'aimed_avg': 396, 'div': 1000, 'avg': 5, 'recent': 4} update_batch_delay: packet-queue-size : 0.50,0.47 {'target': 1000, 'weight_multiplier': 668, 'smoothing': 'sqrt', 'aim': 250, 'aimed_avg': 252, 'div': 1000, 'avg': 321, 'recent': 447} update_batch_delay: packet-queue-pixels : 0.10,0.09 {'target': 1000, 'weight_multiplier': 99, 'smoothing': 'sqrt', 'aim': 250, 'aimed_avg': 9, 'div': 1154248000, 'avg': 7493121, 'recent': 11494687} update_batch_delay: compression-work-queue : 2.27,3.67 {'target': 1000, 'weight_multiplier': 3094, 'smoothing': 'logp', 'aim': 250, 'aimed_avg': 3834, 'div': 1000, 'avg': 8788, 'recent': 9573} update_batch_delay: damage-packet-queue-pixels : 0.10,0.09 {'target': 1000, 'weight_multiplier': 99, 'smoothing': 'sqrt', 'aim': 250, 'aimed_avg': 9, 'div': 1154248000, 'avg': 7493019, 'recent': 11494919} update_batch_delay: focus : 1.00,0.00 {'has_focus': False} update_batch_delay: override-redirect : 1.00,0.00 {'is_OR': False} update_batch_delay: fullscreen : 0.00,0.00 {'other_is_fullscreen': False} update_batch_delay: maximized : 0.00,0.00 {'other_is_maximized': False} update_batch_delay: soft-expired : 0.00,0.00 {'count': 0} packet decoding sequence 1260 for window 2: 1294x50 took 3.0ms update_batch_delay: delay=140 record_latency: took 8.5 ms round trip, 8.3 for echo, 3.0 for decoding of 64700 pixels, 9402 bytes sent over the network in 5.5 ms, 5.3 ms for echo update_quality() suspended=False, mmap=None, encoding=h264 get_client_backlog missing acks: [] may_recalculate(2, 64700) total 64700 pixels, scheduling recalculate work item update_quality() info={'batch-delay-ratio': 7, 'backlog_factor': (0, 0, 100), 'latency': 2193, 'compression-ratio': (202, 203, 0), 'min_quality': 30, 'min_speed': 30}, quality=32 packet decoding sequence 1261 for window 2: 22x5 took 3.0ms

...

calculate_batch_delay for wid=2 current batch delay=140, last update 1 seconds ago update_batch_delay: damage-network-delay : 1.00,0.50 {'avg': 42, 'recent': 42} update_batch_delay: network-send-speed : 1.03,0.09 {'avg': 3, 'recent': 3} update_batch_delay: client-decode-speed : 1.00,0.00 {'avg': 22, 'recent': 22} update_batch_delay: damage-rate : 1.00,0.00 {'max_latency': 100, 'elapsed': 68} update_batch_delay: client-latency : 0.76,0.17 {'target': 5, 'weight_multiplier': 352, 'smoothing': 'sqrt', 'aim': 800, 'aimed_avg': 580, 'div': 1000, 'avg': 5, 'recent': 6} update_batch_delay: client-ping-latency : 0.55,0.12 {'target': 6, 'weight_multiplier': 172, 'smoothing': 'sqrt', 'aim': 949, 'aimed_avg': 302, 'div': 1000, 'avg': 2, 'recent': 2} packet decoding sequence 1381 for window 2: 1294x50 took 5.0ms update_batch_delay: server-ping-latency : 0.64,0.11 {'target': 7, 'weight_multiplier': 189, 'smoothing': 'sqrt', 'aim': 949, 'aimed_avg': 411, 'div': 1000, 'avg': 6, 'recent': 4} record_latency: took 11.1 ms round trip, 10.5 for echo, 5.0 for decoding of 64700 pixels, 7674 bytes sent over the network in 6.1 ms, 5.5 ms for echo update_batch_delay: packet-queue-size : 0.63,0.52 {'target': 1000, 'weight_multiplier': 848, 'smoothing': 'sqrt', 'aim': 250, 'aimed_avg': 390, 'div': 1000, 'avg': 493, 'recent': 720} may_recalculate(2, 64700) total 64700 pixels, scheduling recalculate work item update_batch_delay: packet-queue-pixels : 0.08,0.08 {'target': 1000, 'weight_multiplier': 82, 'smoothing': 'sqrt', 'aim': 250, 'aimed_avg': 6, 'div': 1154248000, 'avg': 7854624, 'recent': 7765988} update_batch_delay: compression-work-queue : 2.53,4.63 {'target': 1000, 'weight_multiplier': 3460, 'smoothing': 'logp', 'aim': 250, 'aimed_avg': 4763, 'div': 1000, 'avg': 10040, 'recent': 11978} update_batch_delay: damage-packet-queue-pixels : 0.08,0.08 {'target': 1000, 'weight_multiplier': 82, 'smoothing': 'sqrt', 'aim': 250, 'aimed_avg': 6, 'div': 1154248000, 'avg': 7854592, 'recent': 7765677} update_batch_delay: focus : 1.00,0.00 {'has_focus': False} update_batch_delay: override-redirect : 1.00,0.00 {'is_OR': False} update_batch_delay: fullscreen : 0.00,0.00 {'other_is_fullscreen': False} update_batch_delay: maximized : 0.00,0.00 {'other_is_maximized': False} update_batch_delay: soft-expired : 0.00,0.00 {'count': 0} update_batch_delay: delay=181 update_quality() suspended=False, mmap=None, encoding=h264 update_quality() info={'batch-delay-ratio': 5, 'backlog_factor': (0, 0, 100), 'latency': 2807, 'compression-ratio': (143, 150, -3), 'min_quality': 30, 'min_speed': 30}, quality=31 update_speed() info={'frame_delay': 125, 'mpixels': 4, 'low_limit': 1154248, 'min_speed': 30, 'damage_latency': {'abs_factor': 0, 'rel_factor': 16, 'avg': 38, 'ref': 37, 'target': 125}, 'decoding_latency': {'target': 8000000, 'factor': 17}}, speed=51 packet decoding sequence 1382 for window 2: 510x510 took 3.0ms
- msn-money with mousing and scrolling.
calculate_batch_delay for wid=2 current batch delay=34, last update 1 seconds ago calculate_batch_delay for wid=2, 3699672 pixels updated since the last update calculate_batch_delay for wid=2, 534882 bytes sent since the last update update_batch_delay: damage-network-delay : 1.00,0.50 {'avg': 41, 'recent': 41} update_batch_delay: network-send-speed : 1.64,0.16 {'avg': 2, 'recent': 5} update_batch_delay: client-decode-speed : 1.15,0.01 {'avg': 11, 'recent': 14} update_batch_delay: damage-rate : 1.00,0.00 {'max_latency': 100, 'elapsed': 19} update_batch_delay: client-latency : 0.67,0.21 {'target': 5, 'weight_multiplier': 359, 'smoothing': 'sqrt', 'aim': 800, 'aimed_avg': 448, 'div': 1000, 'avg': 5, 'recent': 4} update_batch_delay: client-ping-latency : 0.76,0.09 {'target': 6, 'weight_multiplier': 182, 'smoothing': 'sqrt', 'aim': 949, 'aimed_avg': 573, 'div': 1000, 'avg': 3, 'recent': 5} update_batch_delay: server-ping-latency : 0.29,0.12 {'target': 4, 'weight_multiplier': 137, 'smoothing': 'sqrt', 'aim': 949, 'aimed_avg': 81, 'div': 1000, 'avg': 1, 'recent': 0} update_batch_delay: packet-queue-size : 0.23,0.32 {'target': 1000, 'weight_multiplier': 368, 'smoothing': 'sqrt', 'aim': 250, 'aimed_avg': 53, 'div': 1000, 'avg': 136, 'recent': 89} update_batch_delay: packet-queue-pixels : 0.04,0.06 {'target': 1000, 'weight_multiplier': 65, 'smoothing': 'sqrt', 'aim': 250, 'aimed_avg': 1, 'div': 1154248000, 'avg': 5007000, 'recent': 2096269} update_batch_delay: compression-work-queue : 1.79,2.03 {'target': 1000, 'weight_multiplier': 2425, 'smoothing': 'logp', 'aim': 250, 'aimed_avg': 2449, 'div': 1000, 'avg': 5064, 'recent': 5884} update_batch_delay: damage-packet-queue-pixels : 0.04,0.06 {'target': 1000, 'weight_multiplier': 65, 'smoothing': 'sqrt', 'aim': 250, 'aimed_avg': 1, 'div': 1154248000, 'avg': 5007178, 'recent': 2096332} update_batch_delay: focus : 0.00,1.00 {'has_focus': True} update_batch_delay: override-redirect : 1.00,0.00 {'is_OR': False} update_batch_delay: fullscreen : 0.00,0.00 {'other_is_fullscreen': False} update_batch_delay: maximized : 0.00,0.00 {'other_is_maximized': False} update_batch_delay: soft-expired : 0.00,0.00 {'count': 0} update_batch_delay: delay=48 update_quality() suspended=False, mmap=None, encoding=h264 update_quality() info={'batch-delay-ratio': 21, 'backlog_factor': (0, 0, 100), 'latency': 6308, 'compression-ratio': (119, 57, 94), 'min_quality': 30, 'min_speed': 30}, quality=87 update_speed() info={'frame_delay': 54, 'mpixels': 6, 'low_limit': 1154248, 'min_speed': 30, 'damage_latency': {'abs_factor': 0, 'rel_factor': 38, 'avg': 36, 'ref': 37, 'target': 54}, 'decoding_latency': {'target': 8000000, 'factor': 9}}, speed=60 packet decoding sequence 702 for window 2: 764x510 took 6.0ms

... (lots and lots of pixel packets)

calculate_batch_delay for wid=2 current batch delay=48, last update 1 seconds ago calculate_batch_delay for wid=2, 9367476 pixels updated since the last update calculate_batch_delay for wid=2, 1816517 bytes sent since the last update update_batch_delay: damage-network-delay : 1.01,0.51 {'avg': 43, 'recent': 44} update_batch_delay: network-send-speed : 0.97,0.10 {'avg': 5, 'recent': 4} update_batch_delay: client-decode-speed : 1.03,0.00 {'avg': 15, 'recent': 16} update_batch_delay: damage-rate : 1.00,0.00 {'max_latency': 100, 'elapsed': 2} update_batch_delay: client-latency : 0.82,0.15 {'target': 5, 'weight_multiplier': 359, 'smoothing': 'sqrt', 'aim': 800, 'aimed_avg': 679, 'div': 1000, 'avg': 8, 'recent': 8} update_batch_delay: client-ping-latency : 0.74,0.09 {'target': 6, 'weight_multiplier': 182, 'smoothing': 'sqrt', 'aim': 949, 'aimed_avg': 550, 'div': 1000, 'avg': 3, 'recent': 4} update_batch_delay: server-ping-latency : 0.32,0.11 {'target': 4, 'weight_multiplier': 137, 'smoothing': 'sqrt', 'aim': 949, 'aimed_avg': 104, 'div': 1000, 'avg': 2, 'recent': 0} update_batch_delay: packet-queue-size : 0.72,0.53 {'target': 1000, 'weight_multiplier': 1009, 'smoothing': 'sqrt', 'aim': 250, 'aimed_avg': 525, 'div': 1000, 'avg': 782, 'recent': 1019} update_batch_delay: packet-queue-pixels : 0.15,0.14 {'target': 1000, 'weight_multiplier': 152, 'smoothing': 'sqrt', 'aim': 250, 'aimed_avg': 23, 'div': 1154248000, 'avg': 17436751, 'recent': 26762638} update_batch_delay: compression-work-queue : 2.20,3.40 {'target': 1000, 'weight_multiplier': 2990, 'smoothing': 'logp', 'aim': 250, 'aimed_avg': 3591, 'div': 1000, 'avg': 8429, 'recent': 8945} update_batch_delay: damage-packet-queue-pixels : 0.15,0.14 {'target': 1000, 'weight_multiplier': 152, 'smoothing': 'sqrt', 'aim': 250, 'aimed_avg': 23, 'div': 1154248000, 'avg': 17436455, 'recent': 26761968} update_batch_delay: focus : 0.00,1.00 {'has_focus': True} update_batch_delay: override-redirect : 1.00,0.00 {'is_OR': False} update_batch_delay: fullscreen : 0.00,0.00 {'other_is_fullscreen': False} update_batch_delay: maximized : 0.00,0.00 {'other_is_maximized': False} update_batch_delay: soft-expired : 0.00,0.00 {'count': 0} update_batch_delay: delay=55 update_quality() suspended=False, mmap=None, encoding=h264 update_quality() info={'batch-delay-ratio': 18, 'backlog_factor': (0, 0, 100), 'latency': 2739, 'compression-ratio': (59, 54, 10), 'min_quality': 30, 'min_speed': 30}, quality=40 update_speed() info={'frame_delay': 50, 'mpixels': 22, 'low_limit': 1154248, 'min_speed': 30, 'damage_latency': {'abs_factor': 13, 'rel_factor': 69, 'avg': 58, 'ref': 37, 'target': 50}, 'decoding_latency': {'target': 8000000, 'factor': 11}}, speed=66 packet decoding sequence 863 for window 2: 1294x50 took 4.0ms

... (not so many separate pixel packets)

may_recalculate(2, 1037788) total 1037788 pixels, scheduling recalculate work item update_batch_delay: damage-rate : 1.00,0.00 {'max_latency': 100, 'elapsed': 3} update_batch_delay: client-latency : 0.73,0.19 {'target': 5, 'weight_multiplier': 359, 'smoothing': 'sqrt', 'aim': 800, 'aimed_avg': 537, 'div': 1000, 'avg': 8, 'recent': 6} update_batch_delay: client-ping-latency : 0.54,0.12 {'target': 6, 'weight_multiplier': 182, 'smoothing': 'sqrt', 'aim': 949, 'aimed_avg': 291, 'div': 1000, 'avg': 2, 'recent': 2} update_batch_delay: server-ping-latency : 0.04,0.13 {'target': 4, 'weight_multiplier': 137, 'smoothing': 'sqrt', 'aim': 949, 'aimed_avg': 1, 'div': 1000, 'avg': 0, 'recent': 0} update_batch_delay: packet-queue-size : 0.48,0.57 {'target': 1000, 'weight_multiplier': 789, 'smoothing': 'sqrt', 'aim': 250, 'aimed_avg': 229, 'div': 1000, 'avg': 622, 'recent': 433} update_batch_delay: packet-queue-pixels : 0.18,0.16 {'target': 1000, 'weight_multiplier': 177, 'smoothing': 'sqrt', 'aim': 250, 'aimed_avg': 31, 'div': 1154248000, 'avg': 20022476, 'recent': 36203894} update_batch_delay: compression-work-queue : 1.45,1.41 {'target': 1000, 'weight_multiplier': 2645, 'smoothing': 'logp', 'aim': 250, 'aimed_avg': 1727, 'div': 1000, 'avg': 6999, 'recent': 4252} update_batch_delay: damage-packet-queue-pixels : 0.18,0.16 {'target': 1000, 'weight_multiplier': 177, 'smoothing': 'sqrt', 'aim': 250, 'aimed_avg': 31, 'div': 1154248000, 'avg': 20022101, 'recent': 36197714} update_batch_delay: focus : 0.00,1.00 {'has_focus': True} update_batch_delay: override-redirect : 1.00,0.00 {'is_OR': False} update_batch_delay: fullscreen : 0.00,0.00 {'other_is_fullscreen': False} update_batch_delay: maximized : 0.00,0.00 {'other_is_maximized': False} update_batch_delay: soft-expired : 1.00,1.00 {'count': 1} update_batch_delay: delay=51 update_quality() suspended=False, mmap=None, encoding=h264 get_client_backlog missing acks: [] update_quality() info={'batch-delay-ratio': 20, 'backlog_factor': (0, 0, 100), 'latency': 3636, 'compression-ratio': (46, 40, 16), 'min_quality': 30, 'min_speed': 30}, quality=40 update_speed() info={'frame_delay': 59, 'mpixels': 17, 'low_limit': 1154248, 'min_speed': 30, 'damage_latency': {'abs_factor': 13, 'rel_factor': 61, 'avg': 58, 'ref': 37, 'target': 59}, 'decoding_latency': {'target': 8000000, 'factor': 11}}, speed=65 packet decoding sequence 903 for window 2: 1294x83 took 6.0ms
In every case, the video region detection is very often off (as indicated by opengl paint boxes), which I'll investigate further with both the environment variables in this ticket and #1060 and comment further in one of those, or #967...

I am also, in many cases, seeing that mousing around pages like cnn while video is playing will trigger jpeg encoding, often over most of the rest of the window, which will also degrade quality visibly (not sure how to tell whether the quality value listed in the stats logs corresponds to video regions vs. non-video regions that might be getting painted with jpeg).

2016-09-02 23:52:20: afarr uploaded file `backlog-test8_static-msn-com-money.txt` (281.7 KiB)

msn-money stats without any interaction

2016-09-02 23:53:01: afarr uploaded file `backlog-test9_msn-com-money_lots-of-mousing.txt` (303.5 KiB)

msn-money with a lot of mousing over regions & widgets

2016-09-02 23:53:29: afarr uploaded file `backlog-test10_msn-com-money_lots-of-mousing-and-scrolling.txt` (341.6 KiB)

msn-money with both mousing and scrolling

2016-09-06 16:51:08: antoine commented

the "backlog-factor" measures how many pixels and packets should have been ACKed by the client but haven't - this should almost never happen and we have code that takes immediate action for this particular problem, the "backlog-factor" just exposes it in the more usual place (I have edited comment:1 to fix the documentation of the data format)

the "compression-ratio" uses the format AVERAGE, RECENT, DELTA - the delta value tells you in which direction we adjust the quality (ie: -10 means we drop the quality by 10 points). If things are better recently then we raise the quality, but if they're worse then we lower it.

Based on the data above, and some quick tests, I have tweaked the heuristics a bit:

r13589 changes in compression ratio should not sway the quality quite so much

r13590 allow the quality to go higher for "reasonable" values of the batch delay

This ticket is being hampered by the issues with video region detection (#967), hopefully r13587 fixes some of those problematic cases.

The value for the quality setting shown in this ticket is the baseline, video encoders should lower the quality and non-video encoders should increase it. You can see the quality actually used for each screen update with "-d compress". And just as important is the CSC mode: video areas should be using "YUV420P" and "film" tuning (#1257).

2016-09-27 10:51:18: antoine changed priority from major to critical

2016-10-05 02:22:25: afarr changed owner from afarr to antoine

2016-10-05 02:22:25: afarr commented

Testing some more with 1.0 r13977 osx client against 1.0 r13979 fedora 23 server... after checking on the x264 logging expected from #1257, and looking at that last comment... I'm now running the server with -d stats,x264,compress.

Playing around with a number of sites with and without video, with or without scrolling, I think I might have a bit of a handle on this.

It looks like the "compression-ratio" deltas are informing adjustments for quality in the right direction, though not nearly as directly as "-10 means drop quality by 10 points"... and poring over some logs until my eyes begin to cross, it looks like growth/shrinkage of 'latency' seems to influence the magnitude of the quality adjustments that seem to be informed by the "compression-ratio" (or maybe that's just an anecdotal trend I noticed... if you're expecting an exact mapping of compression-ration delta to quality adjustments, then some work will be needed).

Here's sample (from watching a youtube video) of the correlation I'm seeing between the "compression-ratio" delta and the quality settings after update_quality() calls... which seems to also be affected by 'latency' (which I assume is really just a factor in the heuristics which happens to be noticeably related to the changes seen).

2016-10-03 18:17:28,197 update_quality() info={'batch-delay-ratio': 159, 'backlog_factor': (0, 0, 100), 'latency': 4457, 'compression-ratio': (130, 119, 2), 'min_quality': 30, 'min_speed': 30}, quality=99
…
2016-10-03 18:17:29,198 update_quality() info={'batch-delay-ratio': 42, 'backlog_factor': (0, 0, 100), 'latency': 3271, 'compression-ratio': (163, 156, 1), 'min_quality': 30, 'min_speed': 30}, quality=49
…
2016-10-03 18:17:30,195 update_quality() info={'batch-delay-ratio': 42, 'backlog_factor': (0, 0, 100), 'latency': 3859, 'compression-ratio': (163, 161, 0), 'min_quality': 30, 'min_speed': 30}, quality=45
…
2016-10-03 18:17:31,198 update_quality() info={'batch-delay-ratio': 46, 'backlog_factor': (0, 0, 100), 'latency': 9654, 'compression-ratio': (104, 36, 24), 'min_quality': 30, 'min_speed': 30}, quality=62
…
2016-10-03 18:17:32,200 update_quality() info={'batch-delay-ratio': 47, 'backlog_factor': (0, 0, 100), 'latency': 17305, 'compression-ratio': (52, 13, 16), 'min_quality': 30, 'min_speed': 30}, quality=57
…
2016-10-03 18:17:33,200 update_quality() info={'batch-delay-ratio': 42, 'backlog_factor': (0, 0, 100), 'latency': 21425, 'compression-ratio': (55, 26, 11), 'min_quality': 30, 'min_speed': 30}, quality=50
…
2016-10-03 18:17:34,200 update_quality() info={'batch-delay-ratio': 52, 'backlog_factor': (0, 0, 100), 'latency': 3523, 'compression-ratio': (83, 132, -25), 'min_quality': 30, 'min_speed': 30}, quality=38

It took a while to find an example, but I did see a portion of logs in which the pixels being encoded in h264 are being encoded at a significantly lower quality than the pixels being encoded with jpeg (meanwhile, the rgb and png encoded bits have no quality to increase. However, it looks like I'm getting all "YUV444P" & "zerolatency" x264 encoding - whether I'm looking at a youtube page with video, or if I've scrolled the video region off-frame and I'm just looking at the list of comments on the video. Here's a nice "brief" log sample from a youtube video (shortly on the heels of the above log snippet) showing the different qualities for the h264 and jpeg (which I think is the main thrust of this ticket)... but also showing the h264 encoder to be using the "YUV444P" & "zerolatency".

2016-10-03 18:17:34,264 x264 context=0x7fa9453e4e20,    BGRX  854x480  quality=38, speed=83, source=unknown
2016-10-03 18:17:34,265  preset=veryfast, profile=high444, tune=zerolatency
2016-10-03 18:17:34,265  me=DIA, me_range=16, mv_range=-1, b-frames=0, max delayed frames=0
2016-10-03 18:17:34,265  vfr-input=0, lookahead=-1, sync-lookahead=0, mb-tree=0, bframe-adaptive=FAST
2016-10-03 18:17:34,265  threads=auto, sliced-threads=True
2016-10-03 18:17:34,266 x264 close context 0x0
2016-10-03 18:17:34,272 x264 encode frame     0 as  IDR slice with 7 nals, total   11846 bytes, keyframe=True , delayed=0
2016-10-03 18:17:34,272 compress:  15.1ms for  854x480  pixels at  195,150  for wid=2     using  h264 with ratio   0.7% ( 1601KB to    11KB), client_options={'pts': 0, 'frame': 0L, 'flush': 0, 'csc': 'YUV444P', 'type': 'IDR', 'quality': 38, 'speed': 83}
2016-10-03 18:17:34,284 packet decoding sequence 79 for window 2: 854x480 took 9.0ms
2016-10-03 18:17:34,284 record_latency: took   10.6 ms round trip,   10.5 for echo,    9.0 for decoding of   409920 pixels,    11944 bytes sent over the network in    1.6 ms,    1.5 ms for echo
2016-10-03 18:17:34,332 x264 encode frame     1 as    P slice with 4 nals, total     139 bytes, keyframe=False, delayed=0
2016-10-03 18:17:34,332 compress:   9.0ms for  854x480  pixels at  195,150  for wid=2     using  h264 with ratio   0.0% ( 1601KB to     0KB), client_options={'pts': 67, 'frame': 1L, 'flush': 0, 'csc': 'YUV444P', 'type': 'P', 'quality': 38, 'speed': 83}
2016-10-03 18:17:34,340 packet decoding sequence 80 for window 2: 854x480 took 3.2ms
2016-10-03 18:17:34,341 record_latency: took    7.3 ms round trip,    7.2 for echo,    3.0 for decoding of   409920 pixels,      236 bytes sent over the network in    4.1 ms,    4.1 ms for echo
2016-10-03 18:17:34,342 rgb_encode using level=1, lz4 compressed 855x3 in rgb24/BGRX: 10260 bytes down to 58
2016-10-03 18:17:34,342 compress:   0.4ms for  855x3    pixels at  194,630  for wid=2     using rgb24 with ratio   0.6% (   10KB to     0KB), client_options={'flush': 1, 'bucket': 3, 'lz4': 1, 'store': 161, 'rgb_format': 'BGRX'}
2016-10-03 18:17:34,343 rgb_encode using level=1, lz4 compressed 1x480 in rgb24/BGRX: 1920 bytes down to 25
2016-10-03 18:17:34,344 compress:   0.5ms for    1x480  pixels at  194,150  for wid=2     using rgb24 with ratio   1.3% (    1KB to     0KB), client_options={'flush': 0, 'lz4': 1, 'rgb_format': 'BGRX'}
2016-10-03 18:17:34,347 packet decoding sequence 81 for window 2: 855x3 took 0.8ms
2016-10-03 18:17:34,347 record_latency: took    2.8 ms round trip,    2.7 for echo,    0.0 for decoding of     2565 pixels,      137 bytes sent over the network in    2.0 ms,    2.0 ms for echo
2016-10-03 18:17:34,348 packet decoding sequence 82 for window 2: 1x480 took 1.4ms
2016-10-03 18:17:34,349 record_latency: took    3.9 ms round trip,    3.8 for echo,    1.0 for decoding of      480 pixels,       85 bytes sent over the network in    2.5 ms,    2.5 ms for echo
2016-10-03 18:17:34,391 x264 encode frame     2 as    P slice with 4 nals, total    2045 bytes, keyframe=False, delayed=0
2016-10-03 18:17:34,391 compress:  10.2ms for  854x480  pixels at  195,150  for wid=2     using  h264 with ratio   0.1% ( 1601KB to     1KB), client_options={'pts': 126, 'frame': 2L, 'flush': 0, 'csc': 'YUV444P', 'type': 'P', 'quality': 38, 'speed': 83}
2016-10-03 18:17:34,398 packet decoding sequence 83 for window 2: 854x480 took 3.4ms
2016-10-03 18:17:34,398 record_latency: took    5.9 ms round trip,    5.8 for echo,    3.0 for decoding of   409920 pixels,     2142 bytes sent over the network in    2.5 ms,    2.4 ms for echo
2016-10-03 18:17:34,408 compress:   4.8ms for 1684x162  pixels at    0,630  for wid=2     using  jpeg with ratio   2.6% ( 1065KB to    27KB), client_options={'quality': 78, 'flush': 3}
2016-10-03 18:17:34,418 compress:   9.2ms for  635x480  pixels at 1049,150  for wid=2     using  jpeg with ratio   3.3% ( 1190KB to    39KB), client_options={'quality': 78, 'flush': 2}
2016-10-03 18:17:34,421 packet decoding sequence 84 for window 2: 1684x162 took 5.1ms
2016-10-03 18:17:34,423 rgb_encode using level=1, lz4 compressed 195x480 in rgb24/BGRX: 374400 bytes down to 1486
2016-10-03 18:17:34,423 record_latency: took   12.3 ms round trip,   12.2 for echo,    5.0 for decoding of   272808 pixels,    28395 bytes sent over the network in    7.2 ms,    7.1 ms for echo
2016-10-03 18:17:34,424 compress:   1.6ms for  195x480  pixels at    0,150  for wid=2     using rgb24 with ratio   0.4% (  365KB to     1KB), client_options={'flush': 1, 'lz4': 1, 'rgb_format': 'BGRX'}
2016-10-03 18:17:34,428 compress:   3.4ms for 1684x150  pixels at    0,0    for wid=2     using  jpeg with ratio   3.3% (  986KB to    32KB), client_options={'quality': 78, 'flush': 0}
2016-10-03 18:17:34,433 packet decoding sequence 85 for window 2: 635x480 took 8.7ms
2016-10-03 18:17:34,434 record_latency: took   10.6 ms round trip,   10.3 for echo,    8.0 for decoding of   304800 pixels,    40785 bytes sent over the network in    1.9 ms,    1.5 ms for echo
2016-10-03 18:17:34,435 packet decoding sequence 86 for window 2: 195x480 took 4.5ms
2016-10-03 18:17:34,436 record_latency: took   10.5 ms round trip,   10.4 for echo,    4.0 for decoding of    93600 pixels,     1552 bytes sent over the network in    5.9 ms,    5.8 ms for echo
2016-10-03 18:17:34,450 x264 encode frame     3 as    P slice with 4 nals, total    3050 bytes, keyframe=False, delayed=0
2016-10-03 18:17:34,450 compress:   8.5ms for  854x480  pixels at  195,150  for wid=2     using  h264 with ratio   0.2% ( 1601KB to     2KB), client_options={'pts': 186, 'frame': 3L, 'flush': 0, 'csc': 'YUV444P', 'type': 'P', 'quality': 38, 'speed': 83}
2016-10-03 18:17:34,452 packet decoding sequence 87 for window 2: 1684x150 took 15.6ms
2016-10-03 18:17:34,452 record_latency: took   23.6 ms round trip,   23.5 for echo,   15.0 for decoding of   252600 pixels,    33590 bytes sent over the network in    8.1 ms,    7.9 ms for echo

Likewise, even when the "YUV420P" csc mode is being selected, I'm still seeing "zerolatency" tuning. (I thought the use of "film" for YUV420P was default and I needed to use an environment variable to disable b-frames, and potentially also "film" tuning - have I gotten something reversed?). Here's a sample, found poring over logs while scrolling on arsetechnica.com (which tends to have a long home page to scroll up and down) with no video playing at all.

2016-10-04 14:30:41,115 x264 context=0x7f4ce0007dc0, YUV420P 1122x528  quality=36, speed=94, source=unknown
2016-10-04 14:30:41,115  preset=superfast, profile=high10, tune=zerolatency
2016-10-04 14:30:41,115  me=DIA, me_range=16, mv_range=-1, b-frames=0, max delayed frames=0
2016-10-04 14:30:41,117  vfr-input=0, lookahead=-1, sync-lookahead=0, mb-tree=0, bframe-adaptive=FAST
2016-10-04 14:30:41,117  threads=auto, sliced-threads=True
2016-10-04 14:30:41,118 x264 close context 0x0
2016-10-04 14:30:41,138 x264 encode frame     0 as  IDR slice with 7 nals, total   28899 bytes, keyframe=True , delayed=0
2016-10-04 14:30:41,139 compress:  41.2ms for 1684x792  pixels at    0,0    for wid=2     using  h264 with ratio   0.5% ( 5209KB to    28KB), client_options={'pts': 0, 'frame': 0L, 'flush': 0, 'csc': 'YUV420P', 'scaled_size': (1122, 528), 'type': 'IDR', 'quality': 36, 'speed': 94}
2016-10-04 14:30:41,150 packet decoding sequence 135 for window 2: 1684x792 took 8.8ms
2016-10-04 14:30:41,150 record_latency: took   10.7 ms round trip,   10.5 for echo,    8.0 for decoding of  1333728 pixels,    29013 bytes sent over the network in    1.9 ms,    1.7 ms for echo
2016-10-04 14:30:41,249 x264 close context 0x7f4ce0007dc0

... of course, I'm not sure if the "YUV420P" and "zerolatency" combo should be moved (or duplicated) to #1257.

In any case, I'll pass this back to you to decide - I feel like this ticket is working as hoped/expected, but perhaps #1257 needs more work(?).

2016-10-06 10:24:55: antoine changed owner from antoine to afarr

2016-10-06 10:24:55: antoine commented

It looks like the "compression-ratio" deltas are informing adjustments for quality in the right direction, though not nearly as directly as "-10 means drop quality by 10 points"... and poring over some logs until my eyes begin to cross, it looks like growth/shrinkage of 'latency' seems to influence the magnitude of the quality adjustments that seem to be informed by the "compression-ratio" [[BR]] That's some very good observation right there: the latency value gives us a cap on the calculated quality, if the latency is too high (at least 3 times higher than our target value), then we always discount the quality value calculated using the other heuristics.

Here's a nice "brief" log sample from a youtube video [[BR]] The quality used in this sample is exactly what we want to see (~40 for h264 and ~80 for jpeg). (the value of 80 may even be high enough that we'll often use RGB or PNG for the non-video region, which saves us doing an auto-refresh later)

However, it looks like I'm getting all "YUV444P" & "zerolatency" x264 encoding - whether I'm looking at a youtube page with video, or if I've scrolled the video region off-frame and I'm just looking at the list of comments on the video Likewise, even when the "YUV420P" csc mode is being selected, I'm still seeing "zerolatency" tuning. [[BR]] Hmm. Looks like a bug. Scrolling is bursty by nature, so it may not have time to trigger "real video" (YUV420P, b-frames and "film" tuning). Youtube on the other hand... should be using it.

Relevant comments (including information on what we need for debugging these kinds of problems):

1257#comment:8

1257#comment:9

1232#comment:16

1232#comment:17

r14015 adjusts the scoring a little bit, keeping it as simple as I can this late in the release cycle.. it should now select YUV420P more often when the quality is low. (even when close to or lower than the min-quality)

2016-11-12 00:52:08: afarr changed owner from afarr to antoine

2016-11-12 00:52:08: afarr commented

Testing some more with 1.0 r14404 fedora 23 server and 1.0 r14397 win client (without forcing opengl on, after running into the errors noted in #1111).

Looks like scrolling is leading to "zerolatency" tuning, whether it is using "YUV420P" or "BGRX"... but I'm seeing the "film" tuning when I leave a video playing without going crazy and also scrolling the page.

In a short while of testing I didn't see any more examples of jpeg and h264 occurring within close proximity, to compare the relative qualities... but I am often seeing the h264 interspersed with rgb and png (which sounds like what we were hoping for in order to avoid the lossless auto-refreshes).

I did run into a patch of odd heuristics though when I left the client connected after a video had stopped on a page, while poring over the logs. I noticed, with an essentially static page... other than clicking to give it focus and a moment of mousing across... that the page went blurry.

Looking at the server logs, I see that there is indeed still h264 interspersed with rgb and png... and the h264 quality is low - but it looks like it has remained low and there has been no auto-refresh.

Pasting in another patch of logs... but these are the latest logs of a static youtube page that has blurry text around the video frame (which is not playing anything at present)... I'll try to also get a screenshot.

2016-11-11 16:31:50,248 x264 close context 0x0
2016-11-11 16:31:50,256 x264 encode YUV420P frame     0 as  IDR slice with 5 nals, tune=zerolatency, total    6876 bytes, keyframe=True , delayed=0
2016-11-11 16:31:50,256 compress:  13.7ms for 1870x138  pixels at    0,908  for wid=2     using  h264 with ratio   0.7% ( 1015KB to     6KB), sequence   263, client_options={'pts': 0, 'frame': 0, 'csc': 'YUV420P', 'type': 'IDR', 'quality': 30, 'speed': 93}
2016-11-11 16:31:50,290 packet decoding sequence 262 for window 2: 1870x1046 took 47.0ms
2016-11-11 16:31:50,290 record_latency: took   75.9 ms round trip,   75.8 for echo,   47.0 for decoding of  1956020 pixels,    34993 bytes sent over the network in   28.9 ms,   28.8 ms for echo
2016-11-11 16:31:50,301 packet decoding sequence 263 for window 2: 1870x138 took 15.0ms
2016-11-11 16:31:50,302 record_latency: took   45.1 ms round trip,   45.1 for echo,   15.0 for decoding of   258060 pixels,     6966 bytes sent over the network in   30.1 ms,   30.1 ms for echo
2016-11-11 16:31:50,890 compress: 167.5ms for 1871x1047 pixels at    0,0    for wid=2     using   png with ratio  10.9% ( 7652KB to   834KB), sequence   264, client_options={'compress_level': 3}
2016-11-11 16:31:51,011 packet decoding sequence 264 for window 2: 1871x1047 took 109.0ms
2016-11-11 16:31:51,012 record_latency: took  120.9 ms round trip,  120.4 for echo,  109.0 for decoding of  1958937 pixels,   854205 bytes sent over the network in   11.9 ms,   11.4 ms for echo
2016-11-11 16:31:51,057 calculate_batch_delay for wid=2 current batch delay=58, last update 0 seconds ago
2016-11-11 16:31:51,057 calculate_batch_delay for wid=2, skipping - only 4 events since the last update
2016-11-11 16:31:51,058 update_quality() suspended=False, mmap=None, encoding=auto
2016-11-11 16:31:51,058 update_quality() info={'batch-delay-ratio': 35, 'backlog_factor': (0, 0, 100), 'latency': 1419, 'compression-ratio': (244, 377, -37), 'min_quality': 30, 'min_speed': 30}, quality=30
2016-11-11 16:31:51,058 update_speed() info={'frame_delay': 64, 'mpixels': 1, 'low_limit': 1958937, 'min_speed': 30, 'damage_latency': {'abs_factor': 24, 'rel_factor': 143, 'avg': 99, 'ref': 50, 'target': 64}, 'decoding_latency': {'target': 8000000, 'factor': 26}}, speed=97
2016-11-11 16:31:58,964 rgb_encode reformatting because BGRX not in ['RGB', 'RGBX']
2016-11-11 16:31:58,966 rgb_reformat: converting XShmImageWrapper(BGRX: 254, 852, 256, 195) from BGRX to RGB using PIL
2016-11-11 16:31:58,967 rgb_reformat(XShmImageWrapper(RGB: 254, 852, 256, 195), ['RGB', 'RGBX'], False) converted from BGRX (1459380 bytes) to RGB (149760 bytes) in 1.0ms, rowstride=768
2016-11-11 16:31:58,967 rgb_encode using level=0, not compressed 256x195 in rgb24/RGB: 149760 bytes down to 149760
2016-11-11 16:31:58,968 compress:   3.4ms for  256x195  pixels at  254,852  for wid=2     using rgb24 with ratio  75.0% (  195KB to   146KB), sequence   265, client_options={'rgb_format': 'RGB'}
2016-11-11 16:31:58,979 packet decoding sequence 265 for window 2: 256x195 took 0.0ms
2016-11-11 16:31:58,979 may_recalculate(2, 49920) total 49920 pixels, scheduling recalculate work item
2016-11-11 16:31:58,980 calculate_batch_delay for wid=2 current batch delay=58, last update 8 seconds ago
2016-11-11 16:31:58,980 calculate_batch_delay for wid=2, skipping - only 5 events since the last update
2016-11-11 16:31:58,980 update_quality() suspended=False, mmap=None, encoding=auto
2016-11-11 16:31:58,981 update_quality() info={'batch-delay-ratio': 35, 'backlog_factor': (0, 0, 100), 'latency': 1001, 'compression-ratio': (153, 747, -172), 'min_quality': 30, 'min_speed': 30}, quality=30
2016-11-11 16:31:58,981 update_speed() info={'frame_delay': 58, 'mpixels': 0, 'low_limit': 1958937, 'min_speed': 30, 'damage_latency': {'abs_factor': 15, 'rel_factor': 132, 'avg': 81, 'ref': 50, 'target': 58}, 'decoding_latency': {'target': 8000000, 'factor': 17}}, speed=98
2016-11-11 16:32:15,915 x264 close context 0x7f4d1000abe0
2016-11-11 16:32:15,924 x264 context=0x7f4d1000abe0, YUV420P 1246x696  quality=30, speed=98, source=unknown
2016-11-11 16:32:15,924  preset=superfast, profile=high10, tune=zerolatency
2016-11-11 16:32:15,925  me=DIA, me_range=16, mv_range=-1, b-frames=0, max delayed frames=0
2016-11-11 16:32:15,925  vfr-input=0, lookahead=-1, sync-lookahead=0, mb-tree=0, bframe-adaptive=FAST
2016-11-11 16:32:15,925  threads=auto, sliced-threads=True
2016-11-11 16:32:15,925 x264 close context 0x0
2016-11-11 16:32:15,944 x264 encode YUV420P frame     0 as  IDR slice with 7 nals, tune=zerolatency, total   34880 bytes, keyframe=True , delayed=0
2016-11-11 16:32:15,944 compress:  30.1ms for 1870x1046 pixels at    0,0    for wid=2     using  h264 with ratio   0.4% ( 7652KB to    34KB), sequence   266, client_options={'pts': 0, 'frame': 0, 'csc': 'YUV420P', 'scaled_size': (1246, 696), 'type': 'IDR', 'quality': 30, 'speed': 98}
2016-11-11 16:32:16,006 packet decoding sequence 266 for window 2: 1870x1046 took 47.0ms
2016-11-11 16:32:16,006 record_latency: took   60.9 ms round trip,   60.8 for echo,   47.0 for decoding of  1956020 pixels,    34987 bytes sent over the network in   13.9 ms,   13.8 ms for echo
2016-11-11 16:32:16,006 may_recalculate(2, 1956020) total 1956020 pixels, scheduling recalculate work item
2016-11-11 16:32:16,008 calculate_batch_delay for wid=2 current batch delay=58, last update 25 seconds ago
2016-11-11 16:32:16,008 calculate_batch_delay for wid=2, 6189360 pixels updated since the last update
2016-11-11 16:32:16,008 calculate_batch_delay for wid=2, 1082024 bytes sent since the last update
2016-11-11 16:32:16,011 update_batch_delay: damage-network-delay         : 0.99,0.51  {'avg': 41, 'recent': 40}
2016-11-11 16:32:16,011 update_batch_delay: network-send-speed           : 1.35,0.11  {'avg': 1, 'recent': 2}
2016-11-11 16:32:16,011 update_batch_delay: client-decode-speed          : 1.04,0.00  {'avg': 23, 'recent': 25}
2016-11-11 16:32:16,011 update_batch_delay: damage-rate                  : 1.00,0.00  {'max_latency': 100, 'elapsed': 167}
2016-11-11 16:32:16,011 update_batch_delay: client-latency               : 0.92,0.09  {'target': 4, 'weight_multiplier': 321, 'smoothing': 'sqrt', 'aim': 800, 'aimed_avg': 837, 'div': 1000, 'avg': 14, 'recent': 13}
2016-11-11 16:32:16,011 update_batch_delay: client-ping-latency          : 0.51,0.12  {'target': 6, 'weight_multiplier': 170, 'smoothing': 'sqrt', 'aim': 949, 'aimed_avg': 257, 'div': 1000, 'avg': 2, 'recent': 1}
2016-11-11 16:32:16,012 update_batch_delay: server-ping-latency          : 0.04,0.13  {'target': 4, 'weight_multiplier': 137, 'smoothing': 'sqrt', 'aim': 949, 'aimed_avg': 1, 'div': 1000, 'avg': 0, 'recent': 0}
2016-11-11 16:32:16,012 update_batch_delay: packet-queue-size            : 0.00,0.00  {'target': 1000, 'weight_multiplier': 0, 'smoothing': 'sqrt', 'aim': 250, 'aimed_avg': 0, 'div': 1000, 'avg': 0, 'recent': 0}
2016-11-11 16:32:16,012 update_batch_delay: packet-queue-pixels          : 0.00,0.00  {'target': 1000, 'weight_multiplier': 0, 'smoothing': 'sqrt', 'aim': 250, 'aimed_avg': 0, 'div': 1958937000, 'avg': 0, 'recent': 0}
2016-11-11 16:32:16,012 update_batch_delay: compression-work-queue       : 0.00,1.23  {'target': 1000, 'weight_multiplier': 1233, 'smoothing': 'logp', 'aim': 250, 'aimed_avg': 0, 'div': 1000, 'avg': 1520, 'recent': 0}
2016-11-11 16:32:16,012 update_batch_delay: damage-packet-queue-pixels   : 0.00,0.00  {'target': 1000, 'weight_multiplier': 0, 'smoothing': 'sqrt', 'aim': 250, 'aimed_avg': 0, 'div': 1958937000, 'avg': 0, 'recent': 0}
2016-11-11 16:32:16,013 update_batch_delay: focus                        : 0.00,1.00  {'has_focus': True}
2016-11-11 16:32:16,013 update_batch_delay: override-redirect            : 1.00,0.00  {'is_OR': False}
2016-11-11 16:32:16,013 update_batch_delay: fullscreen                   : 0.00,0.00  {'other_is_fullscreen': False}
2016-11-11 16:32:16,013 update_batch_delay: maximized                    : 0.00,0.00  {'other_is_maximized': False}
2016-11-11 16:32:16,013 update_batch_delay: soft-expired                 : 0.00,0.00  {'count': 0}
2016-11-11 16:32:16,014 update_batch_delay: delay=36
2016-11-11 16:32:16,014 update_quality() suspended=False, mmap=None, encoding=auto
2016-11-11 16:32:16,014 update_quality() info={'batch-delay-ratio': 56, 'backlog_factor': (0, 0, 100), 'latency': 1243, 'compression-ratio': (31, 13, 7), 'min_quality': 30, 'min_speed': 30}, quality=56
2016-11-11 16:32:16,015 update_speed() info={'frame_delay': 47, 'mpixels': 1, 'low_limit': 1958937, 'min_speed': 30, 'damage_latency': {'abs_factor': 24, 'rel_factor': 189, 'avg': 99, 'ref': 50, 'target': 50}, 'decoding_latency': {'target': 8000000, 'factor': 18}}, speed=98
2016-11-11 16:32:16,633 compress: 166.6ms for 1871x1047 pixels at    0,0    for wid=2     using   png with ratio  10.9% ( 7652KB to   834KB), sequence   267, client_options={'compress_level': 3}
2016-11-11 16:32:16,748 packet decoding sequence 267 for window 2: 1871x1047 took 93.0ms
2016-11-11 16:32:16,748 record_latency: took  115.0 ms round trip,  114.4 for echo,   93.0 for decoding of  1958937 pixels,   854186 bytes sent over the network in   22.0 ms,   21.4 ms for echo
2016-11-11 16:32:16,748 may_recalculate(2, 1958937) total 1958937 pixels, scheduling recalculate work item
2016-11-11 16:32:17,009 calculate_batch_delay for wid=2 current batch delay=36, last update 1 seconds ago
2016-11-11 16:32:17,010 calculate_batch_delay for wid=2, skipping - only 1 events since the last update
2016-11-11 16:32:17,011 update_quality() suspended=False, mmap=None, encoding=auto
2016-11-11 16:32:17,011 update_quality() info={'batch-delay-ratio': 56, 'backlog_factor': (0, 0, 100), 'latency': 823, 'compression-ratio': (239, 366, -35), 'min_quality': 30, 'min_speed': 30}, quality=34
2016-11-11 16:32:17,012 update_speed() info={'frame_delay': 47, 'mpixels': 0, 'low_limit': 1958937, 'min_speed': 30, 'damage_latency': {'abs_factor': 49, 'rel_factor': 292, 'avg': 151, 'ref': 50, 'target': 50}, 'decoding_latency': {'target': 8000000, 'factor': 24}}, speed=98
2016-11-11 16:32:20,461 x264 encode YUV420P frame     1 as    P slice with 4 nals, tune=zerolatency, total     443 bytes, keyframe=False, delayed=0
2016-11-11 16:32:20,462 compress:  19.8ms for 1870x1046 pixels at    0,0    for wid=2     using  h264 with ratio   0.0% ( 7652KB to     0KB), sequence   268, client_options={'pts': 4517, 'frame': 1, 'csc': 'YUV420P', 'scaled_size': (1246, 696), 'type': 'P', 'quality': 34, 'speed': 98}
2016-11-11 16:32:20,495 packet decoding sequence 268 for window 2: 1870x1046 took 31.0ms
2016-11-11 16:32:20,496 record_latency: took   32.5 ms round trip,   32.5 for echo,   31.0 for decoding of  1956020 pixels,      550 bytes sent over the network in    1.5 ms,    1.5 ms for echo
2016-11-11 16:32:20,496 may_recalculate(2, 1956020) total 1956020 pixels, scheduling recalculate work item
2016-11-11 16:32:20,497 calculate_batch_delay for wid=2 current batch delay=36, last update 4 seconds ago
2016-11-11 16:32:20,497 calculate_batch_delay for wid=2, skipping - only 2 events since the last update
2016-11-11 16:32:20,498 update_quality() suspended=False, mmap=None, encoding=auto
2016-11-11 16:32:20,498 update_quality() info={'batch-delay-ratio': 56, 'backlog_factor': (0, 0, 100), 'latency': 9911, 'compression-ratio': (72, 3, 29), 'min_quality': 30, 'min_speed': 30}, quality=78
2016-11-11 16:32:20,499 update_speed() info={'frame_delay': 36, 'mpixels': 1, 'low_limit': 1958937, 'min_speed': 30, 'damage_latency': {'abs_factor': 23, 'rel_factor': 189, 'avg': 98, 'ref': 50, 'target': 50}, 'decoding_latency': {'target': 8000000, 'factor': 14}}, speed=98

2016-11-12 00:53:54: afarr uploaded file `ticket1135_static-rgb-and-h264-encoded-page_gone-very-blurry.PNG` (465.2 KiB)

page static for a number of minutes & still blurry, despite apparent mix of rgb and png with h264 encodings... ticket1135_static-rgb-and-h264-encoded-page_gone-very-blurry.PNG

2016-11-12 00:57:38: afarr commented

Oddly, the clip of the logs top-ish left indicates the final encoding for this completely static page... h264 P slice with "zerolatency" tuning... at quality "34" ... and there has been no auto-refresh in the entire time of my composing these comments... leaving it blurry (don't usually catch corner cases so perfectly!).

[[Image(ticket1135_static-rgb-and-h264-encoded-page_gone-very-blurry.PNG)]]

2016-11-13 14:05:30: antoine changed owner from antoine to afarr

2016-11-13 14:05:30: antoine commented

Fixes and tweaks:
r14408: better lz4 compression tuning, so this should no longer happen:
rgb_encode using level=0, not compressed 256x195 in rgb24/RGB: 149760 bytes down to 149760
we should end up using level=1 or higher to actually compress things now
r14409: raise the quality quickly when there are not many screen updates
As for the lack for auto-refresh, we need "-d refresh" (or even "-d refresh,regionrefresh" if a video region was active). I hope you can trigger it again with the same concise logging.

2016-11-18 02:04:34: afarr changed owner from afarr to antoine

2016-11-18 02:04:34: afarr commented

Tested a little more with a 1.0 r14430 fedora 23 server and a 1.0 14416 win32 client.

Not seeing any more of the rgb_encode using level=0 (all at level=1).

Also not stumbling across the lack of auto-refresh... not sure if it was a fluke or something to do with the change to raise quality quickly when there aren't many screen updates... but my attempts to repro are now regularly auto-refreshing with rgb (and someteims also some png) after an initial x264 paint when mousing over a recently ended video region.

I'll test a bit more to be sure, but passing this back to you as looking ready to be closed for now.

2016-11-18 05:41:51: antoine changed owner from antoine to afarr

2016-11-18 05:41:51: antoine commented

Note: we probably should not be refreshing very large areas with rgb. If it does refresh something bigger than ~720p with rgb, can you please include the "quality", "speed" and "rgb_threshold" from xpra info, as well as the corresponding compress log message. (if not, please just close the ticket)

2016-11-18 18:23:25: afarr changed owner from afarr to antoine

2016-11-18 18:23:25: afarr commented

It looks to me, doing a little more testing, like it is doing some of the updates with rgb (probably corresponding to me mousing over the window after a video has stopped, trying to induce another auto-refresh failure) and is then following that up with a png paint, which I presume is a more full auto-refresh.

Here's a clip of some of some sample logs that I'm seeing now while trying to repro, for you to confirm my interpretation.

2016-11-18 09:48:42,952 x264 encode    BGRX frame     0 as  IDR slice with 7 nals, tune=zerolatency, total  232695 bytes, keyframe=True , delayed=0
2016-11-18 09:48:42,954 compress:  66.6ms for 1182x682  pixels at    0,0    for wid=2     using  h264 with ratio   7.2% ( 3148KB to   227KB), sequence 21460, client_options={'pts': 0, 'frame': 0, 'csc': 'YUV444P', 'type': 'IDR', 'quality': 60, 'speed': 55}
2016-11-18 09:48:43,380 compress:  79.1ms for 1182x682  pixels at    0,0    for wid=2     using   png with ratio  14.7% ( 3148KB to   463KB), sequence 21465, client_options={'compress_level': 3}
2016-11-18 09:48:48,526 compress:   4.0ms for  405x84   pixels at  762,598  for wid=2     using   png with ratio  14.2% (  132KB to    18KB), sequence 21466, client_options={'compress_level': 1}
2016-11-18 09:48:48,668 compress:   9.0ms for  382x128  pixels at   83,175  for wid=2     using   png with ratio  46.3% (  191KB to    88KB), sequence 21469, client_options={'compress_level': 1}
2016-11-18 09:48:51,441 rgb_encode using level=1 for 97280 pixels at  63 speed, lz4 compressed  190x128  in rgb24/BGRX: 97280 bytes down to 80655
2016-11-18 09:48:51,442 compress:   1.1ms for  190x128  pixels at  469,175  for wid=2     using rgb24 with ratio  82.9% (   95KB to    78KB), sequence 21587, client_options={'bucket': 2, 'lz4': 1, 'store': 38117, 'rgb_format': 'BGRX'}
2016-11-18 09:48:52,094 compress:  13.3ms for  405x338  pixels at  762,344  for wid=2     using   png with ratio  16.8% (  534KB to    89KB), sequence 21608, client_options={'compress_level': 1}
2016-11-18 09:48:52,249 x264 close context 0x7f8330bc2320
2016-11-18 09:48:52,279 x264 close context 0x0
2016-11-18 09:48:52,283 using default profile=high444
2016-11-18 09:48:52,299 x264 context=0x7f833003ac60,    BGRX 1166x592  quality=35, speed=72, source=unknown
2016-11-18 09:48:52,299  preset=faster, profile=high444, tune=zerolatency
2016-11-18 09:48:52,300  me=DIA, me_range=16, mv_range=-1, weighted-pred=1
2016-11-18 09:48:52,301  b-frames=0, max delayed frames=0
2016-11-18 09:48:52,304  vfr-input=False, lookahead=-1, sync-lookahead=0, mb-tree=False, bframe-adaptive=FAST
2016-11-18 09:48:52,305  open-gop=True, bluray-compat=False, cabac=True, deblocking-filter=True
2016-11-18 09:48:52,308  intra-refresh=False, interlaced=False, constrained_intra=False
2016-11-18 09:48:52,309  threads=auto, sliced-threads=True
2016-11-18 09:48:52,347 x264 encode    BGRX frame     0 as  IDR slice with 7 nals, tune=zerolatency, total   93950 bytes, keyframe=True , delayed=0
2016-11-18 09:48:52,347 compress:  66.4ms for 1166x592  pixels at    0,90   for wid=2     using  h264 with ratio   3.4% ( 2698KB to    91KB), sequence 21613, client_options={'pts': 0, 'frame': 0, 'csc': 'YUV444P', 'type': 'IDR', 'quality': 35, 'speed': 72}
2016-11-18 09:48:52,565 rgb_encode using level=1 for 36156 pixels at  72 speed, lz4 compressed  393x23   in rgb24/BGRX: 36156 bytes down to  4534
2016-11-18 09:48:52,566 compress:   0.7ms for  393x23   pixels at    0,659  for wid=2     using rgb24 with ratio  12.5% (   35KB to     4KB), sequence 21619, client_options={'flush': 1, 'bucket': 0, 'lz4': 1, 'store': 38141, 'rgb_format': 'BGRX'}
2016-11-18 09:48:52,567 rgb_encode using level=1 for 35520 pixels at  72 speed, lz4 compressed   15x592  in rgb24/BGRX: 35520 bytes down to   265
2016-11-18 09:48:52,567 compress:   0.4ms for   15x592  pixels at 1167,90   for wid=2     using rgb24 with ratio   0.7% (   34KB to     0KB), sequence 21620, client_options={'bucket': 4, 'lz4': 1, 'store': 38143, 'rgb_format': 'BGRX'}
2016-11-18 09:48:52,654 rgb_encode using level=1 for 36156 pixels at  72 speed, lz4 compressed  393x23   in rgb24/BGRX: 36156 bytes down to  4516
2016-11-18 09:48:52,655 compress:   1.7ms for  393x23   pixels at    0,659  for wid=2     using rgb24 with ratio  12.5% (   35KB to     4KB), sequence 21621, client_options={'delta': 38141, 'bucket': 0, 'lz4': 1, 'store': 38145, 'rgb_format': 'BGRX'}
2016-11-18 09:48:53,045 compress:  74.1ms for 1182x682  pixels at    0,0    for wid=2     using   png with ratio  14.7% ( 3148KB to   463KB), sequence 21622, client_options={'compress_level': 3}
2016-11-18 09:48:54,557 compress:   3.1ms for  405x95   pixels at  762,251  for wid=2     using   png with ratio  13.7% (  150KB to    20KB), sequence 21623, client_options={'compress_level': 1, 'flush': 2}
2016-11-18 09:48:54,562 compress:   4.4ms for  405x161  pixels at  762,90   for wid=2     using   png with ratio  10.3% (  254KB to    26KB), sequence 21624, client_options={'compress_level': 1, 'flush': 1}
2016-11-18 09:48:54,563 rgb_encode using level=1 for 35520 pixels at  71 speed, lz4 compressed   15x592  in rgb24/BGRX: 35520 bytes down to   178
2016-11-18 09:48:54,563 compress:   0.4ms for   15x592  pixels at 1167,90   for wid=2     using rgb24 with ratio   0.5% (   34KB to     0KB), sequence 21625, client_options={'delta': 38143, 'bucket': 4, 'lz4': 1, 'store': 38153, 'rgb_format': 'BGRX'}
2016-11-18 09:48:54,718 rgb_encode using level=1 for 97524 pixels at  73 speed, lz4 compressed  189x129  in rgb24/BGRX: 97524 bytes down to 90219
2016-11-18 09:48:54,719 compress:   0.6ms for  189x129  pixels at  276,307  for wid=2     using rgb24 with ratio  92.5% (   95KB to    88KB), sequence 21627, client_options={'bucket': 3, 'lz4': 1, 'store': 38159, 'rgb_format': 'BGRX'}
2016-11-18 09:48:54,789 compress:  17.0ms for  383x129  pixels at  276,307  for wid=2     using   png with ratio  42.7% (  192KB to    82KB), sequence 21628, client_options={'compress_level': 1}

I would also mention that as I was doing a couple of last stabs at testing this, I somehow managed to trigger a strange behavior where whenever I moused over the window, the mouse seemed to do a grab and move the window... making it impossible to mouse to any buttons or anything else. I wasn't able to repro at all, so it was probably just a missed un-click event... though subsequent clicks didn't fix it - only disconnecting then re-connecting. I have some logs and xpra info, but I suspect they'll just indicate that the window was being moved. I'll make a ticket if I can repro.

As for this, I'll hand it back to you to glance at the logs then most likely just close this one.

2016-11-19 06:02:03: antoine changed status from new to closed

2016-11-19 06:02:03: antoine set resolution to fixed

2016-11-19 06:02:03: antoine commented

The rgb updates are for smaller regions than the png ones, which is what we want. (the exact "rgb_threshold" varies)

The rgb ones tend to compress a lot less but almost always take under 1 ms to do so! png uses a lot more CPU time.

The grab-the-window bug sounds like a real problem for another ticket. What application was this? (you should always be able to get out of grabs using the escape key - assuming that it is xpra that triggered the grab)

Xpra-org / xpra