xpra icon
Bug tracker and wiki

Opened 6 months ago

Last modified 2 weeks ago

#2812 assigned defect

Cluttered network doesn't seem to get detected quickly enough for batch delay to compensate.

Reported by: alas Owned by: Antoine Martin
Priority: major Milestone: 4.2
Component: network Version: 4.0.x
Keywords: Cc:

Description

Not sure the versions matter, but testing with stable (4.0.1) Windows python client and Fedora 30 server... when I started a download on the network which cluttered the bandwidth so badly that my ping between client and server jumped from the 30-50ms range to the 1200-2100ms range... the batch delay didn't seem to react quickly enough to keep the client from being disconnected.

Turning on the stats logging (xpra control :13 debug enable stats) I was able to get these logs as the download/cluttered network was restarted.

2020-06-11 14:04:22,238 packet decoding sequence 302 for window 10: 1036x466 took 3.0ms
2020-06-11 14:04:22,239 may_recalculate(10, 482776) total 482776 pixels, scheduling recalculate work item
2020-06-11 14:04:22,241 calculate_batch_delay for wid=10 current batch delay=76, last update 49.1 seconds ago
2020-06-11 14:04:22,242 update_batch_delay: damage-network-delay         : 1.00,0.50  {'avg': 40, 'recent': 40}
2020-06-11 14:04:22,242 packet decoding sequence 303 for window 10: 1036x18 took 2.0ms
2020-06-11 14:04:22,242 update_batch_delay: client-latency               : 2.90,2.23  {'avg': 322, 'recent': 1249, 'target': 41, 'aim': 800, 'aimed_avg': 8423, 'div': 1000, 'smoothing': 'sqrt', 'weight_multiplier': 1619}
2020-06-11 14:04:22,242 may_recalculate(10, 18648) total 18648 pixels, scheduling recalculate work item
2020-06-11 14:04:22,242 update_batch_delay: client-ping-latency          : 1.63,0.66  {'avg': 787, 'recent': 1135, 'target': 38, 'aim': 949, 'aimed_avg': 2656, 'div': 1000, 'smoothing': 'sqrt', 'weight_multiplier': 828}
2020-06-11 14:04:22,242 packet decoding sequence 304 for window 10: 1036x27 took 1.0ms
2020-06-11 14:04:22,243 update_batch_delay: server-ping-latency          : 0.40,0.11  {'avg': 1, 'recent': 1, 'target': 4, 'aim': 949, 'aimed_avg': 163, 'div': 1000, 'smoothing': 'sqrt', 'weight_multiplier': 137}
2020-06-11 14:04:22,243 packet decoding sequence 305 for window 10: 1036x2 took 6.0ms
2020-06-11 14:04:22,243 update_batch_delay: packet-queue-size            : 0.61,0.51  {'avg': 462, 'recent': 674, 'target': 1000, 'aim': 250, 'aimed_avg': 368, 'div': 1000, 'smoothing': 'sqrt', 'weight_multiplier': 821}
2020-06-11 14:04:22,243 update_batch_delay: packet-queue-pixels          : 0.35,0.29  {'avg': 54012710, 'recent': 79036640, 'target': 1000, 'aim': 250, 'aimed_avg': 123, 'div': 625356000, 'smoothing': 'sqrt', 'weight_multiplier': 355}
2020-06-11 14:04:22,244 update_batch_delay: compression-work-queue       : 0.00,0.13  {'avg': 18, 'recent': 0, 'target': 1000, 'aim': 250, 'aimed_avg': 0, 'div': 1000, 'smoothing': 'logp', 'weight_multiplier': 134}
2020-06-11 14:04:22,244 update_batch_delay: damage-packet-queue-pixels   : 0.35,0.29  {'avg': 58080742, 'recent': 79102406, 'target': 1000, 'aim': 250, 'aimed_avg': 123, 'div': 625356000, 'smoothing': 'sqrt', 'weight_multiplier': 355}
2020-06-11 14:04:22,244 update_batch_delay: focus                        : 0.00,1.00  {'has_focus': True}
2020-06-11 14:04:22,244 update_batch_delay: delay=88 (last actual delay: 50)
2020-06-11 14:04:22,244 update_quality() suspended=False, mmap=False, current=85, hint=-1, fixed=-1, encoding=auto, sequence=267
2020-06-11 14:04:22,244 get_client_backlog missing acks: []
2020-06-11 14:04:22,245 get_target_quality: target=  2% (window 1044x599 ) pctpixdamaged=254%, dpc=((1, 142560), (2, 1448328), (3, 0), (4, 0), (5, 0), (6, 0), (7, 0), (8, 0), (9, 0), (10, 0))
2020-06-11 14:04:22,245 update_quality() quality=31 (target=31) for wid=10, info={'compression-ratio': (126, 131), 'min-quality': 30, 'min-speed': 30, 'backlog': (9, 646464, 625356, 103), 'limits': {'backlog': 66, 'bandwidth': 4700, 'congestion': 100, 'batch': 174, 'latency': 21, 'boost': -2}}
2020-06-11 14:04:22,245 update_speed() suspended=False, mmap=False, current=34, hint=-1, fixed=-1, encoding=auto, sequence=267
2020-06-11 14:04:22,245 get_client_backlog missing acks: []
2020-06-11 14:04:22,246 packet decoding sequence 306 for window 10: 1036x12 took 3.0ms
2020-06-11 14:04:22,246 update_speed() speed=33 (target=33, max=47) for wid=10, info={'low-limit': 625356, 'max-speed': 47, 'min-speed': 30, 'factors': {'damage-latency-abs': 0, 'damage-latency-rel': 4, 'decoding-latency': 0, 'pixel-rate': 0}, 'limits': {'backlog': 67, 'damage-latency': 100, 'pixel-rate': 100, 'bandwidth-limit': 47, 'congestion': 100}}
2020-06-11 14:04:22,435 packet decoding sequence 307 for window 10: 1036x18 took 6.0ms
2020-06-11 14:04:22,435 packet decoding sequence 308 for window 10: 1036x466 took 5.0ms
2020-06-11 14:04:22,446 packet decoding sequence 309 for window 10: 1036x10 took 12.0ms
2020-06-11 14:04:22,446 packet decoding sequence 310 for window 10: 1036x7 took 13.0ms
2020-06-11 14:04:22,562 packet decoding sequence 311 for window 10: 1036x29 took 1.0ms
2020-06-11 14:04:22,613 packet decoding sequence 312 for window 10: 1036x4 took 0.0ms
2020-06-11 14:04:22,869 packet decoding sequence 313 for window 10: 1036x34 took 1.0ms
2020-06-11 14:04:23,159 packet decoding sequence 314 for window 10: 1036x44 took 2.0ms
2020-06-11 14:04:23,240 calculate_batch_delay for wid=10 current batch delay=88, last update 1.0 seconds ago
2020-06-11 14:04:23,241 update_batch_delay: damage-network-delay         : 1.00,0.50  {'avg': 40, 'recent': 41}
2020-06-11 14:04:23,241 update_batch_delay: bandwidth-limit              : 1.11,0.67  {'budget': 3039559, 'used': 3066032}
2020-06-11 14:04:23,241 update_batch_delay: client-latency               : 2.98,2.28  {'avg': 902, 'recent': 1711, 'target': 41, 'aim': 800, 'aimed_avg': 8877, 'div': 1000, 'smoothing': 'sqrt', 'weight_multiplier': 1619}
2020-06-11 14:04:23,241 update_batch_delay: client-ping-latency          : 1.59,0.64  {'avg': 771, 'recent': 1074, 'target': 38, 'aim': 949, 'aimed_avg': 2541, 'div': 1000, 'smoothing': 'sqrt', 'weight_multiplier': 828}
2020-06-11 14:04:23,241 update_batch_delay: server-ping-latency          : 0.40,0.11  {'avg': 1, 'recent': 1, 'target': 4, 'aim': 949, 'aimed_avg': 163, 'div': 1000, 'smoothing': 'sqrt', 'weight_multiplier': 137}
2020-06-11 14:04:23,241 update_batch_delay: packet-queue-size            : 0.20,0.52  {'avg': 341, 'recent': 69, 'target': 1000, 'aim': 250, 'aimed_avg': 38, 'div': 1000, 'smoothing': 'sqrt', 'weight_multiplier': 584}
2020-06-11 14:04:23,241 update_batch_delay: packet-queue-pixels          : 0.11,0.24  {'avg': 39684140, 'recent': 8237381, 'target': 1000, 'aim': 250, 'aimed_avg': 12, 'div': 625356000, 'smoothing': 'sqrt', 'weight_multiplier': 251}
2020-06-11 14:04:23,242 update_batch_delay: compression-work-queue       : 0.00,0.11  {'avg': 12, 'recent': 0, 'target': 1000, 'aim': 250, 'aimed_avg': 0, 'div': 1000, 'smoothing': 'logp', 'weight_multiplier': 109}
2020-06-11 14:04:23,242 update_batch_delay: congestion                   : 4.50,34.96  {}
2020-06-11 14:04:23,242 update_batch_delay: damage-packet-queue-pixels   : 0.12,0.25  {'avg': 44772253, 'recent': 9448811, 'target': 1000, 'aim': 250, 'aimed_avg': 14, 'div': 625356000, 'smoothing': 'sqrt', 'weight_multiplier': 267}
2020-06-11 14:04:23,242 update_batch_delay: focus                        : 0.00,1.00  {'has_focus': True}
2020-06-11 14:04:23,242 update_batch_delay: delay=281 (last actual delay: 35)
2020-06-11 14:04:23,242 update_quality() suspended=False, mmap=False, current=31, hint=-1, fixed=-1, encoding=auto, sequence=271
2020-06-11 14:04:23,242 get_client_backlog missing acks: []
2020-06-11 14:04:23,243 get_target_quality: target=  0% (window 1044x599 ) pctpixdamaged=408%, dpc=((1, 965552), (2, 142560), (3, 1448328), (4, 0), (5, 0), (6, 0), (7, 0), (8, 0), (9, 0), (10, 0))
2020-06-11 14:04:23,243 update_quality() quality=30 (target=30) for wid=10, info={'compression-ratio': (296, 343), 'min-quality': 30, 'min-speed': 30, 'backlog': (0, 0, 625356, 0), 'limits': {'backlog': 100, 'bandwidth': 5500, 'congestion': -3396, 'batch': 54, 'latency': 15, 'boost': -12}}
2020-06-11 14:04:23,243 update_speed() suspended=False, mmap=False, current=33, hint=-1, fixed=-1, encoding=auto, sequence=271
2020-06-11 14:04:23,243 get_client_backlog missing acks: []
2020-06-11 14:04:23,243 update_speed() speed=30 (target=30, max=30) for wid=10, info={'low-limit': 625356, 'max-speed': 30, 'min-speed': 30, 'factors': {'damage-latency-abs': 0, 'damage-latency-rel': 1, 'decoding-latency': 0, 'pixel-rate': 0}, 'limits': {'backlog': 100, 'damage-latency': 10, 'pixel-rate': 100, 'bandwidth-limit': 55, 'congestion': 0}}
2020-06-11 14:04:24,041 packet decoding sequence 110 for window 2: 499x316 took 2.0ms
2020-06-11 14:04:24,041 may_recalculate(2, 157684) total 157684 pixels, scheduling recalculate work item
2020-06-11 14:04:24,240 calculate_batch_delay for wid=2 current batch delay=12, last update 73.5 seconds ago
2020-06-11 14:04:24,241 update_batch_delay: damage-network-delay         : 1.00,0.50  {'avg': 40, 'recent': 40}
2020-06-11 14:04:24,241 update_batch_delay: damage-rate                  : 0.00,1.13  {'elapsed': 1472, 'max_latency': 100}
2020-06-11 14:04:24,241 update_batch_delay: client-latency               : 2.68,2.10  {'avg': 781, 'recent': 1351, 'target': 41, 'aim': 800, 'aimed_avg': 7192, 'div': 1000, 'smoothing': 'sqrt', 'weight_multiplier': 1619}
2020-06-11 14:04:24,241 update_batch_delay: client-ping-latency          : 2.05,0.85  {'avg': 1028, 'recent': 2038, 'target': 38, 'aim': 949, 'aimed_avg': 4201, 'div': 1000, 'smoothing': 'sqrt', 'weight_multiplier': 828}
2020-06-11 14:04:24,241 update_batch_delay: server-ping-latency          : 0.40,0.11  {'avg': 1, 'recent': 1, 'target': 4, 'aim': 949, 'aimed_avg': 163, 'div': 1000, 'smoothing': 'sqrt', 'weight_multiplier': 137}
2020-06-11 14:04:24,242 update_batch_delay: packet-queue-size            : 0.37,0.47  {'avg': 350, 'recent': 249, 'target': 1000, 'aim': 250, 'aimed_avg': 139, 'div': 1000, 'smoothing': 'sqrt', 'weight_multiplier': 592}
2020-06-11 14:04:24,242 update_batch_delay: packet-queue-pixels          : 0.42,0.39  {'avg': 40562789, 'recent': 29675099, 'target': 1000, 'aim': 250, 'aimed_avg': 178, 'div': 157684000, 'smoothing': 'sqrt', 'weight_multiplier': 507}
2020-06-11 14:04:24,242 update_batch_delay: compression-work-queue       : 0.00,0.12  {'avg': 15, 'recent': 0, 'target': 1000, 'aim': 250, 'aimed_avg': 0, 'div': 1000, 'smoothing': 'logp', 'weight_multiplier': 122}
2020-06-11 14:04:24,242 update_batch_delay: congestion                   : 1.32,3.18  {}
2020-06-11 14:04:24,242 update_batch_delay: delay=17 (last actual delay: 20)
2020-06-11 14:04:24,243 update_quality() suspended=False, mmap=False, current=62, hint=-1, fixed=-1, encoding=auto, sequence=221
2020-06-11 14:04:24,243 get_target_quality: target=  0% (window  499x316 ) pctpixdamaged= 95%, dpc=((1, 0), (2, 149892), (3, 0), (4, 0), (5, 0), (6, 0), (7, 0), (8, 0), (9, 0), (10, 0))
2020-06-11 14:04:24,243 update_quality() quality=50 (target=50) for wid=2, info={'compression-ratio': (21, 21), 'min-quality': 30, 'min-speed': 30, 'backlog': (0, 0, 157684, 0), 'limits': {'backlog': 100, 'bandwidth': 2200, 'congestion': -217, 'batch': 768, 'latency': 19, 'boost': 0}}
2020-06-11 14:04:24,243 update_speed() suspended=False, mmap=False, current=30, hint=-1, fixed=-1, encoding=auto, sequence=221
2020-06-11 14:04:24,243 update_speed() speed=30 (target=30, max=30) for wid=2, info={'low-limit': 157684, 'max-speed': 30, 'min-speed': 30, 'factors': {'damage-latency-abs': 0, 'damage-latency-rel': 1, 'decoding-latency': 1, 'pixel-rate': 0}, 'limits': {'backlog': 100, 'damage-latency': 388, 'pixel-rate': 100, 'bandwidth-limit': 22, 'congestion': 0}}
2020-06-11 14:04:26,122 packet decoding sequence 315 for window 10: 1044x599 took 44.0ms
2020-06-11 14:04:26,123 may_recalculate(10, 625356) total 625356 pixels, scheduling recalculate work item
2020-06-11 14:04:26,125 calculate_batch_delay for wid=10 current batch delay=281, last update 2.9 seconds ago
2020-06-11 14:04:26,125 update_batch_delay: damage-network-delay         : 1.01,0.51  {'avg': 40, 'recent': 41}
2020-06-11 14:04:26,126 update_batch_delay: client-decode-speed          : 2.25,0.33  {'avg': 18, 'recent': 68}
2020-06-11 14:04:26,126 update_batch_delay: damage-rate                  : 0.00,1.63  {'elapsed': 2862, 'max_latency': 100}
2020-06-11 14:04:26,126 update_batch_delay: client-latency               : 3.77,2.70  {'avg': 854, 'recent': 2714, 'target': 41, 'aim': 800, 'aimed_avg': 14215, 'div': 1000, 'smoothing': 'sqrt', 'weight_multiplier': 1619}
2020-06-11 14:04:26,126 update_batch_delay: client-ping-latency          : 1.92,0.80  {'avg': 906, 'recent': 1693, 'target': 38, 'aim': 949, 'aimed_avg': 3697, 'div': 1000, 'smoothing': 'sqrt', 'weight_multiplier': 828}
2020-06-11 14:04:26,126 update_batch_delay: server-ping-latency          : 0.40,0.11  {'avg': 1, 'recent': 1, 'target': 4, 'aim': 949, 'aimed_avg': 163, 'div': 1000, 'smoothing': 'sqrt', 'weight_multiplier': 137}
2020-06-11 14:04:26,126 update_batch_delay: packet-queue-size            : 0.48,0.46  {'avg': 341, 'recent': 404, 'target': 1000, 'aim': 250, 'aimed_avg': 226, 'div': 1000, 'smoothing': 'sqrt', 'weight_multiplier': 635}
2020-06-11 14:04:26,126 update_batch_delay: packet-queue-pixels          : 0.28,0.24  {'avg': 39260933, 'recent': 48146285, 'target': 1000, 'aim': 250, 'aimed_avg': 75, 'div': 625356000, 'smoothing': 'sqrt', 'weight_multiplier': 277}
2020-06-11 14:04:26,126 update_batch_delay: compression-work-queue       : 0.00,0.13  {'avg': 17, 'recent': 0, 'target': 1000, 'aim': 250, 'aimed_avg': 0, 'div': 1000, 'smoothing': 'logp', 'weight_multiplier': 133}
2020-06-11 14:04:26,126 update_batch_delay: congestion                   : 1.04,0.38  {}
2020-06-11 14:04:26,126 update_batch_delay: damage-packet-queue-pixels   : 0.29,0.25  {'avg': 44229316, 'recent': 53683406, 'target': 1000, 'aim': 250, 'aimed_avg': 84, 'div': 625356000, 'smoothing': 'sqrt', 'weight_multiplier': 292}
2020-06-11 14:04:26,127 update_batch_delay: focus                        : 0.00,1.00  {'has_focus': True}
2020-06-11 14:04:26,127 update_batch_delay: delay=246 (last actual delay: 35)
2020-06-11 14:04:26,127 update_quality() suspended=False, mmap=False, current=30, hint=-1, fixed=-1, encoding=auto, sequence=271
2020-06-11 14:04:26,127 get_client_backlog missing acks: []
2020-06-11 14:04:26,128 get_target_quality: target=  0% (window 1044x599 ) pctpixdamaged=177%, dpc=((1, 0), (2, 0), (3, 967055), (4, 142560), (5, 0), (6, 1448328), (7, 0), (8, 0), (9, 0), (10, 0))
2020-06-11 14:04:26,128 update_quality() quality=30 (target=30) for wid=10, info={'compression-ratio': (234, 336), 'min-quality': 30, 'min-speed': 30, 'backlog': (1, 482776, 625356, 77), 'limits': {'backlog': 74, 'bandwidth': 4400, 'congestion': 61, 'batch': 62, 'latency': 9, 'boost': -29}}
2020-06-11 14:04:26,128 update_speed() suspended=False, mmap=False, current=30, hint=-1, fixed=-1, encoding=auto, sequence=271
2020-06-11 14:04:26,128 get_client_backlog missing acks: []
2020-06-11 14:04:26,129 update_speed() speed=30 (target=30, max=30) for wid=10, info={'low-limit': 625356, 'max-speed': 30, 'min-speed': 30, 'factors': {'damage-latency-abs': 0, 'damage-latency-rel': 1, 'decoding-latency': 1, 'pixel-rate': 0}, 'limits': {'backlog': 75, 'damage-latency': 13, 'pixel-rate': 100, 'bandwidth-limit': 44, 'congestion': 61}}
2020-06-11 14:04:27,351 packet decoding sequence 316 for window 10: 1036x466 took 76.0ms
2020-06-11 14:04:27,351 may_recalculate(10, 482776) total 482776 pixels, scheduling recalculate work item
2020-06-11 14:04:27,353 calculate_batch_delay for wid=10 current batch delay=246, last update 1.2 seconds ago
2020-06-11 14:04:27,354 update_batch_delay: damage-network-delay         : 1.01,0.51  {'avg': 40, 'recent': 41}
2020-06-11 14:04:27,354 update_batch_delay: client-decode-speed          : 2.77,0.89  {'avg': 22, 'recent': 132}
2020-06-11 14:04:27,354 update_batch_delay: damage-rate                  : 0.00,1.97  {'elapsed': 4090, 'max_latency': 100}
2020-06-11 14:04:27,354 update_batch_delay: client-latency               : 4.39,2.98  {'avg': 1051, 'recent': 3811, 'target': 41, 'aim': 800, 'aimed_avg': 19297, 'div': 1000, 'smoothing': 'sqrt', 'weight_multiplier': 1619}
2020-06-11 14:04:27,354 update_batch_delay: client-ping-latency          : 2.44,0.99  {'avg': 1691, 'recent': 3485, 'target': 38, 'aim': 949, 'aimed_avg': 5929, 'div': 1000, 'smoothing': 'sqrt', 'weight_multiplier': 828}
2020-06-11 14:04:27,355 update_batch_delay: server-ping-latency          : 0.40,0.11  {'avg': 1, 'recent': 1, 'target': 4, 'aim': 949, 'aimed_avg': 163, 'div': 1000, 'smoothing': 'sqrt', 'weight_multiplier': 137}
2020-06-11 14:04:27,355 update_batch_delay: packet-queue-size            : 0.49,0.47  {'avg': 334, 'recent': 430, 'target': 1000, 'aim': 250, 'aimed_avg': 242, 'div': 1000, 'smoothing': 'sqrt', 'weight_multiplier': 656}
2020-06-11 14:04:27,355 update_batch_delay: packet-queue-pixels          : 0.28,0.24  {'avg': 38323847, 'recent': 51194000, 'target': 1000, 'aim': 250, 'aimed_avg': 80, 'div': 625356000, 'smoothing': 'sqrt', 'weight_multiplier': 286}
2020-06-11 14:04:27,355 update_batch_delay: compression-work-queue       : 0.00,0.14  {'avg': 18, 'recent': 1, 'target': 1000, 'aim': 250, 'aimed_avg': 0, 'div': 1000, 'smoothing': 'logp', 'weight_multiplier': 137}
2020-06-11 14:04:27,355 update_batch_delay: congestion                   : 1.02,0.20  {}
2020-06-11 14:04:27,355 update_batch_delay: damage-packet-queue-pixels   : 0.30,0.25  {'avg': 43234339, 'recent': 56354007, 'target': 1000, 'aim': 250, 'aimed_avg': 88, 'div': 625356000, 'smoothing': 'sqrt', 'weight_multiplier': 300}
2020-06-11 14:04:27,356 update_batch_delay: focus                        : 0.00,1.00  {'has_focus': True}
2020-06-11 14:04:27,357 update_batch_delay: delay=261 (last actual delay: 4140)
2020-06-11 14:04:27,357 update_quality() suspended=False, mmap=False, current=30, hint=-1, fixed=-1, encoding=auto, sequence=272
2020-06-11 14:04:27,357 get_target_quality: target=  0% (window 1044x599 ) pctpixdamaged=154%, dpc=((1, 0), (2, 0), (3, 0), (4, 0), (5, 967055), (6, 142560), (7, 1448328), (8, 0), (9, 0), (10, 0))
2020-06-11 14:04:27,357 update_quality() quality=30 (target=30) for wid=10, info={'compression-ratio': (220, 330), 'min-quality': 30, 'min-speed': 30, 'backlog': (0, 0, 625356, 0), 'limits': {'backlog': 100, 'bandwidth': 4400, 'congestion': 80, 'batch': 58, 'latency': 6, 'boost': -32}}
2020-06-11 14:04:27,358 update_speed() suspended=False, mmap=False, current=30, hint=-1, fixed=-1, encoding=auto, sequence=272
2020-06-11 14:04:27,358 update_speed() speed=30 (target=30, max=30) for wid=10, info={'low-limit': 625356, 'max-speed': 30, 'min-speed': 30, 'factors': {'damage-latency-abs': 0, 'damage-latency-rel': 0, 'decoding-latency': 2, 'pixel-rate': 0}, 'limits': {'backlog': 100, 'damage-latency': 3, 'pixel-rate': 100, 'bandwidth-limit': 44, 'congestion': 80}}
2020-06-11 14:04:41,837 packet decoding sequence 317 for window 10: 1044x599 took 16.0ms
2020-06-11 14:04:41,838 may_recalculate(10, 625356) total 625356 pixels, scheduling recalculate work item
2020-06-11 14:04:41,839 calculate_batch_delay for wid=10 current batch delay=261, last update 14.5 seconds ago
2020-06-11 14:04:41,840 update_batch_delay: damage-network-delay         : 1.00,0.50  {'avg': 40, 'recent': 40}
2020-06-11 14:04:41,841 update_batch_delay: client-decode-speed          : 1.24,0.02  {'avg': 19, 'recent': 26}
2020-06-11 14:04:41,841 update_batch_delay: damage-rate                  : 0.00,3.41  {'elapsed': 11848, 'max_latency': 100}
2020-06-11 14:04:41,841 update_batch_delay: client-latency               : 8.11,4.32  {'avg': 2701, 'recent': 14305, 'target': 41, 'aim': 800, 'aimed_avg': 65815, 'div': 1000, 'smoothing': 'sqrt', 'weight_multiplier': 1619}
2020-06-11 14:04:41,841 update_batch_delay: client-ping-latency          : 1.68,0.69  {'avg': 910, 'recent': 1302, 'target': 38, 'aim': 949, 'aimed_avg': 2837, 'div': 1000, 'smoothing': 'sqrt', 'weight_multiplier': 828}
2020-06-11 14:04:41,842 update_batch_delay: server-ping-latency          : 0.40,0.11  {'avg': 1, 'recent': 1, 'target': 4, 'aim': 949, 'aimed_avg': 163, 'div': 1000, 'smoothing': 'sqrt', 'weight_multiplier': 137}
2020-06-11 14:04:41,843 update_batch_delay: packet-queue-size            : 0.46,0.45  {'avg': 291, 'recent': 367, 'target': 1000, 'aim': 250, 'aimed_avg': 209, 'div': 1000, 'smoothing': 'sqrt', 'weight_multiplier': 606}
2020-06-11 14:04:41,843 update_batch_delay: packet-queue-pixels          : 0.26,0.22  {'avg': 32786390, 'recent': 42250601, 'target': 1000, 'aim': 250, 'aimed_avg': 66, 'div': 625356000, 'smoothing': 'sqrt', 'weight_multiplier': 259}
2020-06-11 14:04:41,844 update_batch_delay: compression-work-queue       : 0.01,0.15  {'avg': 23, 'recent': 7, 'target': 1000, 'aim': 250, 'aimed_avg': 4, 'div': 1000, 'smoothing': 'logp', 'weight_multiplier': 151}
2020-06-11 14:04:41,844 update_batch_delay: damage-packet-queue-pixels   : 0.27,0.23  {'avg': 37480675, 'recent': 45299851, 'target': 1000, 'aim': 250, 'aimed_avg': 71, 'div': 625356000, 'smoothing': 'sqrt', 'weight_multiplier': 269}
2020-06-11 14:04:41,844 update_batch_delay: focus                        : 0.00,1.00  {'has_focus': True}
2020-06-11 14:04:41,845 update_batch_delay: delay=241 (last actual delay: 12143)
2020-06-11 14:04:41,845 update_quality() suspended=False, mmap=False, current=30, hint=-1, fixed=-1, encoding=auto, sequence=277
2020-06-11 14:04:41,845 get_client_backlog missing acks: []
2020-06-11 14:04:41,846 get_target_quality: target=  0% (window 1044x599 ) pctpixdamaged=  0%, dpc=((1, 0), (2, 0), (3, 0), (4, 0), (5, 0), (6, 0), (7, 0), (8, 0), (9, 0), (10, 0))
2020-06-11 14:04:41,846 update_quality() quality=30 (target=30) for wid=10, info={'compression-ratio': (161, 130), 'min-quality': 30, 'min-speed': 30, 'backlog': (0, 0, 625356, 0), 'limits': {'backlog': 100, 'bandwidth': 4400, 'congestion': 100, 'batch': 63, 'latency': 1, 'boost': 7}}
2020-06-11 14:04:41,846 update_speed() suspended=False, mmap=False, current=30, hint=-1, fixed=-1, encoding=auto, sequence=277
2020-06-11 14:04:41,847 get_client_backlog missing acks: []
2020-06-11 14:04:41,847 update_speed() speed=30 (target=30, max=30) for wid=10, info={'low-limit': 625356, 'max-speed': 30, 'min-speed': 30, 'factors': {'damage-latency-abs': 0, 'damage-latency-rel': 0, 'decoding-latency': 1, 'pixel-rate': 0}, 'limits': {'backlog': 100, 'damage-latency': 1, 'pixel-rate': 100, 'bandwidth-limit': 44, 'congestion': 100}}
2020-06-11 14:04:43,266 client   1 ping timeout - reconnecting
2020-06-11 14:04:44,317 client   1 close_audio_mediasource: audio_source_buffer=[object SourceBuffer], media_source=[object MediaSource], audio=[object HTMLAudioElement]
2020-06-11 14:04:44,318 client   1 audio-state: stopped
2020-06-11 14:04:44,319 sound source stopping
2020-06-11 14:04:44,331 xpra client 1 disconnected.

The session seemed to be running rather smoothly, then it obviously quickly became non-responsive, then dropped.

Not that there's much to be done if the network becomes so bad that pings break the 2000 ms mark, but maybe something in case of less extreme problems?

Attachments (1)

ticket2812_server-logs_-d-stats_for recovery.txt (190.0 KB) - added by alas 5 months ago.
Some more logs - from congested network to less-congested

Download all attachments as: .zip

Change History (5)

comment:1 Changed 5 months ago by Antoine Martin

Status: newassigned

Interesting. The first sign is client-latency : 2.90,2.23, then we get a congestion event: congestion : 4.50,34.96 {} and raise the batch delay: delay=281 (last actual delay: 35).
Shortly after, things go bad: delay=261 (last actual delay: 4140)...
And quickly become unusable (12 seconds delay!): delay=241 (last actual delay: 12143).

#2421 may help with this, as it should help us notice that the connection is saturated whilst sending, without having to wait for the echo packets - by which point it is often too late.
Though this may not help if the delays are caused by bufferbloat, because the OS won't be notified of what's being delayed down the line.

comment:2 Changed 5 months ago by alas

I didn't see any sign that you'd gotten a chance to pursue #2421, but I found some available time to try the same tricks with a 4.1 server (4.1-r26759) and a 4.1 Windows client (on Windows 7): Xpra-Python3-x86_64_Setup_4.1-r26851 .

I'm connecting over a VPN with what I've gotten used to as reasonable latency:

Reply from 10.0.3.148: bytes=32 time=25ms TTL=60
Reply from 10.0.3.148: bytes=32 time=26ms TTL=60
Reply from 10.0.3.148: bytes=32 time=29ms TTL=60
Reply from 10.0.3.148: bytes=32 time=26ms TTL=60

... with which I simply launched a gedit window with some logging from something or other, and started scrolling (relatively small gedit window, but on a 4K display, so "small" is relative here)... logs with -d stats look reasonable.

2020-07-02 12:03:38,806 may_recalculate(3, 687960) total 687960 pixels, scheduling recalculate work item
2020-07-02 12:03:38,812 packet decoding sequence 2 for window 3: 759x41 took 6.3ms
2020-07-02 12:03:38,860 packet decoding sequence 3 for window 3: 763x45 took 1.6ms
2020-07-02 12:03:38,869 packet decoding sequence 4 for window 3: 764x46 took 8.4ms
2020-07-02 12:03:38,886 packet decoding sequence 5 for window 3: 910x46 took 21.0ms
2020-07-02 12:03:38,886 packet decoding sequence 2 for window 1: 499x316 took 20.1ms
2020-07-02 12:03:38,886 may_recalculate(1, 157684) total 157684 pixels, scheduling recalculate work item
2020-07-02 12:03:38,886 packet decoding sequence 2 for window 2: 499x316 took 20.0ms
2020-07-02 12:03:39,173 calculate_batch_delay for wid=1 current batch delay=69, last update 1.0 seconds ago
2020-07-02 12:03:39,173 calculate_batch_delay for wid=1, skipping - only 1 events since the last update
2020-07-02 12:03:39,173 update_quality() suspended=False, mmap=None, current=100, hint=-1, fixed=-1, encoding=auto, sequence=5
2020-07-02 12:03:39,173 update_speed() suspended=False, mmap=False, current=80, hint=-1, fixed=-1, encoding=auto, sequence=5
2020-07-02 12:03:39,174 calculate_batch_delay for wid=2 current batch delay=50, last update 828158.9 seconds ago
2020-07-02 12:03:39,174 update_batch_delay: damage-network-delay         : 1.12,0.62  {'avg': 180, 'recent': 211}
2020-07-02 12:03:39,175 update_batch_delay: client-decode-speed          : 1.45,0.13  {'avg': 43, 'recent': 76}
2020-07-02 12:03:39,175 update_batch_delay: damage-rate                  : 0.17,0.91  {'elapsed': 1172, 'max_latency': 172}
2020-07-02 12:03:39,175 update_batch_delay: client-latency               : 1.05,0.90  {'avg': 491, 'recent': 502, 'target': 351, 'aim': 800, 'aimed_avg': 1092, 'div': 1000, 'smoothing': 'sqrt', 'weight_multiplier': 4214}
2020-07-02 12:03:39,175 update_batch_delay: client-ping-latency          : 0.92,0.20  {'avg': 25, 'recent': 25, 'target': 30, 'aim': 949, 'aimed_avg': 837, 'div': 1000, 'smoothing': 'sqrt', 'weight_multiplier': 679}
2020-07-02 12:03:39,175 update_batch_delay: server-ping-latency          : 0.96,0.24  {'avg': 59, 'recent': 59, 'target': 64, 'aim': 949, 'aimed_avg': 918, 'div': 1000, 'smoothing': 'sqrt', 'weight_multiplier': 1189}
2020-07-02 12:03:39,175 update_batch_delay: packet-queue-size            : 0.68,0.53  {'avg': 623, 'recent': 866, 'target': 1000, 'aim': 250, 'aimed_avg': 458, 'div': 1000, 'smoothing': 'sqrt', 'weight_multiplier': 930}
2020-07-02 12:03:39,176 update_batch_delay: packet-queue-pixels          : 0.17,0.15  {'avg': 4079701, 'recent': 4427589, 'target': 1000, 'aim': 250, 'aimed_avg': 27, 'div': 157684000, 'smoothing': 'sqrt', 'weight_multiplier': 167}
2020-07-02 12:03:39,176 update_batch_delay: congestion                   : 1.87,8.74  {}
2020-07-02 12:03:39,176 update_batch_delay: delay=88 (last actual delay: 178)
2020-07-02 12:03:39,176 update_quality() suspended=False, mmap=None, current=100, hint=-1, fixed=-1, encoding=auto, sequence=5
2020-07-02 12:03:39,176 update_speed() suspended=False, mmap=False, current=80, hint=-1, fixed=-1, encoding=auto, sequence=5
2020-07-02 12:03:39,177 calculate_batch_delay for wid=3 current batch delay=50, last update 828158.9 seconds ago
2020-07-02 12:03:39,177 update_batch_delay: damage-network-delay         : 1.00,0.50  {'avg': 544, 'recent': 544}
2020-07-02 12:03:39,177 update_batch_delay: damage-rate                  : 0.86,0.38  {'elapsed': 1172, 'max_latency': 513}
2020-07-02 12:03:39,178 update_batch_delay: client-latency               : 1.05,0.90  {'avg': 491, 'recent': 502, 'target': 351, 'aim': 800, 'aimed_avg': 1092, 'div': 1000, 'smoothing': 'sqrt', 'weight_multiplier': 4214}
2020-07-02 12:03:39,178 update_batch_delay: client-ping-latency          : 0.92,0.20  {'avg': 25, 'recent': 25, 'target': 30, 'aim': 949, 'aimed_avg': 837, 'div': 1000, 'smoothing': 'sqrt', 'weight_multiplier': 679}
2020-07-02 12:03:39,178 update_batch_delay: server-ping-latency          : 0.96,0.24  {'avg': 59, 'recent': 59, 'target': 64, 'aim': 949, 'aimed_avg': 918, 'div': 1000, 'smoothing': 'sqrt', 'weight_multiplier': 1189}
2020-07-02 12:03:39,178 update_batch_delay: packet-queue-size            : 0.68,0.53  {'avg': 623, 'recent': 865, 'target': 1000, 'aim': 250, 'aimed_avg': 458, 'div': 1000, 'smoothing': 'sqrt', 'weight_multiplier': 930}
2020-07-02 12:03:39,178 update_batch_delay: packet-queue-pixels          : 0.08,0.08  {'avg': 4079496, 'recent': 4426808, 'target': 1000, 'aim': 250, 'aimed_avg': 6, 'div': 687960000, 'smoothing': 'sqrt', 'weight_multiplier': 80}
2020-07-02 12:03:39,178 update_batch_delay: congestion                   : 1.87,8.74  {}
2020-07-02 12:03:39,179 update_batch_delay: damage-packet-queue-pixels   : 0.11,0.10  {'avg': 7438605, 'recent': 8479693, 'target': 1000, 'aim': 250, 'aimed_avg': 12, 'div': 687960000, 'smoothing': 'sqrt', 'weight_multiplier': 111}
2020-07-02 12:03:39,179 update_batch_delay: focus                        : 0.00,1.00  {'has_focus': True}
2020-07-02 12:03:39,179 update_batch_delay: delay=63 (last actual delay: 51)
2020-07-02 12:03:39,179 update_quality() suspended=False, mmap=None, current=100, hint=-1, fixed=-1, encoding=auto, sequence=11
2020-07-02 12:03:39,180 get_target_quality: target=  0% (window  910x756 ) pctpixdamaged= 27%, dpc=((1, 0), (2, 191564), (3, 0), (4, 0), (5, 0), (6, 0), (7, 0), (8, 0), (9, 0), (10, 0))
2020-07-02 12:03:39,180 update_quality() quality=50 (target=50) for wid=3, info={'compression-ratio': (261, 260), 'min-quality': 30, 'min-speed': 30, 'backlog': (0, 0, 687960, 0), 'limits': {'backlog': 100, 'bandwidth': 100, 'congestion': -774, 'batch': 430, 'latency': 269, 'boost': 0}}
2020-07-02 12:03:39,180 update_speed() suspended=False, mmap=False, current=80, hint=-1, fixed=-1, encoding=auto, sequence=11
2020-07-02 12:03:39,180 update_speed() speed=30 (target=30, max=30) for wid=3, info={'low-limit': 687960, 'max-speed': 30, 'min-speed': 30, 'factors': {'damage-latency-abs': 0, 'damage-latency-rel': 4, 'decoding-latency': 4, 'pixel-rate': 0}, 'limits': {'backlog': 100, 'damage-latency': 120, 'pixel-rate': 100, 'bandwidth-limit': 100, 'congestion': 0}}
2020-07-02 12:03:51,295 packet decoding sequence 6 for window 3: 910x7 took 1.3ms
2020-07-02 12:03:51,295 may_recalculate(3, 6370) total 6370 pixels, scheduling recalculate work item
2020-07-02 12:03:51,296 calculate_batch_delay for wid=3 current batch delay=63, last update 12.1 seconds ago
2020-07-02 12:03:51,296 calculate_batch_delay for wid=3, skipping - only 0 events since the last update
2020-07-02 12:03:51,297 update_quality() suspended=False, mmap=None, current=50, hint=-1, fixed=-1, encoding=auto, sequence=13
2020-07-02 12:03:51,297 get_client_backlog missing acks: []
2020-07-02 12:03:51,297 get_target_quality: target=100% (window  910x756 ) pctpixdamaged= 89%, dpc=((1, 614448), (2, 0), (3, 0), (4, 0), (5, 0), (6, 0), (7, 0), (8, 0), (9, 0), (10, 0))
2020-07-02 12:03:51,298 update_quality() quality=99 (target=100) for wid=3, info={'compression-ratio': (261, 261), 'min-quality': 30, 'min-speed': 30, 'backlog': (0, 0, 687960, 0), 'limits': {'backlog': 100, 'bandwidth': 100, 'congestion': 100, 'batch': 422, 'latency': 3042, 'boost': 0}}
2020-07-02 12:03:51,298 update_speed() suspended=False, mmap=False, current=30, hint=-1, fixed=-1, encoding=auto, sequence=13
2020-07-02 12:03:51,298 get_client_backlog missing acks: []
2020-07-02 12:03:51,299 update_speed() speed=32 (target=33, max=100) for wid=3, info={'low-limit': 687960, 'max-speed': 100, 'min-speed': 30, 'factors': {'damage-latency-abs': 0, 'damage-latency-rel': 5, 'decoding-latency': 4, 'pixel-rate': 0}, 'limits': {'backlog': 100, 'damage-latency': 125, 'pixel-rate': 100, 'bandwidth-limit': 100, 'congestion': 100}}
2020-07-02 12:03:51,346 packet decoding sequence 7 for window 3: 910x42 took 6.8ms
2020-07-02 12:03:51,346 may_recalculate(3, 38220) total 38220 pixels, scheduling recalculate work item
2020-07-02 12:03:51,346 packet decoding sequence 8 for window 3: 910x7 took 3.1ms
2020-07-02 12:03:51,352 packet decoding sequence 9 for window 3: 910x7 took 8.4ms
2020-07-02 12:03:51,352 packet decoding sequence 10 for window 3: 910x7 took 1.6ms
2020-07-02 12:03:51,352 packet decoding sequence 11 for window 3: 910x7 took 1.7ms
2020-07-02 12:03:51,353 packet decoding sequence 12 for window 3: 910x7 took 5.1ms
2020-07-02 12:03:51,353 packet decoding sequence 13 for window 3: 910x7 took 3.5ms
2020-07-02 12:03:51,360 packet decoding sequence 14 for window 3: 910x7 took 2.9ms
2020-07-02 12:03:51,364 packet decoding sequence 15 for window 3: 910x7 took 4.8ms
2020-07-02 12:03:51,387 packet decoding sequence 16 for window 3: 910x8 took 0.7ms
2020-07-02 12:03:51,388 packet decoding sequence 17 for window 3: 900x6 took 0.7ms
2020-07-02 12:03:51,396 packet decoding sequence 18 for window 3: 6x665 took 0.6ms
2020-07-02 12:03:51,397 packet decoding sequence 19 for window 3: 6x1 took 0.8ms
2020-07-02 12:03:51,397 packet decoding sequence 20 for window 3: 252x1 took 0.9ms
2020-07-02 12:03:51,417 packet decoding sequence 21 for window 3: 900x6 took 1.0ms
2020-07-02 12:03:51,417 packet decoding sequence 22 for window 3: 6x665 took 1.1ms
2020-07-02 12:03:51,417 packet decoding sequence 23 for window 3: 6x1 took 1.1ms
2020-07-02 12:03:51,418 packet decoding sequence 24 for window 3: 252x1 took 1.0ms
2020-07-02 12:03:51,483 packet decoding sequence 25 for window 3: 900x6 took 0.7ms
2020-07-02 12:03:51,484 packet decoding sequence 26 for window 3: 6x665 took 0.4ms
2020-07-02 12:03:51,484 packet decoding sequence 27 for window 3: 6x1 took 0.8ms
2020-07-02 12:03:51,484 packet decoding sequence 28 for window 3: 252x1 took 0.5ms
2020-07-02 12:03:51,556 packet decoding sequence 29 for window 3: 900x6 took 1.2ms
2020-07-02 12:03:51,557 packet decoding sequence 30 for window 3: 6x665 took 0.5ms
2020-07-02 12:03:51,557 packet decoding sequence 31 for window 3: 6x1 took 0.4ms
2020-07-02 12:03:51,557 packet decoding sequence 32 for window 3: 252x1 took 0.3ms
2020-07-02 12:03:51,611 packet decoding sequence 33 for window 3: 900x6 took 0.8ms
2020-07-02 12:03:51,612 packet decoding sequence 34 for window 3: 6x665 took 0.7ms
2020-07-02 12:03:51,613 packet decoding sequence 35 for window 3: 6x1 took 0.9ms
2020-07-02 12:03:51,613 packet decoding sequence 36 for window 3: 252x1 took 1.1ms
2020-07-02 12:03:51,690 packet decoding sequence 37 for window 3: 900x6 took 1.0ms
2020-07-02 12:03:51,690 packet decoding sequence 38 for window 3: 6x665 took 0.9ms
2020-07-02 12:03:51,691 packet decoding sequence 39 for window 3: 6x1 took 0.7ms
2020-07-02 12:03:51,691 packet decoding sequence 40 for window 3: 252x1 took 0.4ms
2020-07-02 12:03:51,748 packet decoding sequence 41 for window 3: 900x6 took 0.9ms
2020-07-02 12:03:51,748 packet decoding sequence 42 for window 3: 6x665 took 1.0ms
2020-07-02 12:03:51,755 packet decoding sequence 43 for window 3: 6x1 took 1.2ms
2020-07-02 12:03:51,755 packet decoding sequence 44 for window 3: 252x1 took 1.9ms
2020-07-02 12:03:51,814 packet decoding sequence 45 for window 3: 900x6 took 0.5ms
2020-07-02 12:03:51,815 packet decoding sequence 46 for window 3: 6x665 took 0.5ms
2020-07-02 12:03:51,824 packet decoding sequence 47 for window 3: 6x1 took 2.2ms
2020-07-02 12:03:51,824 packet decoding sequence 48 for window 3: 252x1 took 2.6ms
2020-07-02 12:03:51,834 packet decoding sequence 49 for window 3: 910x42 took 1.1ms
2020-07-02 12:03:51,879 packet decoding sequence 50 for window 3: 900x6 took 0.9ms
2020-07-02 12:03:51,900 packet decoding sequence 51 for window 3: 6x665 took 0.9ms
2020-07-02 12:03:51,901 packet decoding sequence 52 for window 3: 6x1 took 1.1ms
2020-07-02 12:03:51,901 packet decoding sequence 53 for window 3: 252x1 took 1.2ms
2020-07-02 12:03:51,951 packet decoding sequence 54 for window 3: 900x6 took 1.2ms
2020-07-02 12:03:51,981 packet decoding sequence 55 for window 3: 6x665 took 0.6ms
2020-07-02 12:03:51,981 packet decoding sequence 56 for window 3: 6x1 took 0.6ms
2020-07-02 12:03:51,981 packet decoding sequence 57 for window 3: 252x1 took 0.5ms
2020-07-02 12:03:52,027 packet decoding sequence 58 for window 3: 900x6 took 2.1ms
2020-07-02 12:03:52,028 packet decoding sequence 59 for window 3: 6x665 took 1.6ms
2020-07-02 12:03:52,028 packet decoding sequence 60 for window 3: 6x1 took 1.8ms
2020-07-02 12:03:52,028 packet decoding sequence 61 for window 3: 252x1 took 2.1ms
2020-07-02 12:03:52,085 packet decoding sequence 62 for window 3: 900x6 took 0.8ms
2020-07-02 12:03:52,086 packet decoding sequence 63 for window 3: 6x665 took 0.4ms
2020-07-02 12:03:52,087 packet decoding sequence 64 for window 3: 6x1 took 0.7ms
2020-07-02 12:03:52,087 packet decoding sequence 65 for window 3: 252x1 took 0.8ms
2020-07-02 12:03:52,145 packet decoding sequence 66 for window 3: 900x6 took 0.8ms
2020-07-02 12:03:52,147 packet decoding sequence 67 for window 3: 6x665 took 0.8ms
2020-07-02 12:03:52,165 packet decoding sequence 68 for window 3: 6x1 took 0.3ms
2020-07-02 12:03:52,165 packet decoding sequence 69 for window 3: 252x1 took 0.2ms
2020-07-02 12:03:52,219 packet decoding sequence 70 for window 3: 900x6 took 0.9ms
2020-07-02 12:03:52,219 packet decoding sequence 71 for window 3: 6x665 took 1.3ms
2020-07-02 12:03:52,220 packet decoding sequence 72 for window 3: 6x1 took 1.0ms
2020-07-02 12:03:52,226 packet decoding sequence 73 for window 3: 252x1 took 1.1ms
2020-07-02 12:03:52,297 calculate_batch_delay for wid=3 current batch delay=63, last update 13.1 seconds ago
2020-07-02 12:03:52,298 calculate_batch_delay for wid=3, 861252 pixels updated since the last update
2020-07-02 12:03:52,298 calculate_batch_delay for wid=3, skipping - only 100781 bytes sent since the last update
2020-07-02 12:03:52,298 update_quality() suspended=False, mmap=None, current=99, hint=-1, fixed=-1, encoding=auto, sequence=129
2020-07-02 12:03:52,299 get_client_backlog missing acks: []
2020-07-02 12:03:52,300 get_target_quality: target=108% (window  910x756 ) pctpixdamaged=198%, dpc=((1, 753624), (2, 614448), (3, 0), (4, 0), (5, 0), (6, 0), (7, 0), (8, 0), (9, 0), (10, 0))
2020-07-02 12:03:52,300 update_quality() quality=99 (target=100) for wid=3, info={'compression-ratio': (85, 73), 'min-quality': 30, 'min-speed': 30, 'backlog': (0, 0, 687960, 0), 'limits': {'backlog': 100, 'bandwidth': 100, 'congestion': 100, 'batch': 377, 'latency': 2885, 'boost': 3}}
2020-07-02 12:03:52,300 update_speed() suspended=False, mmap=False, current=32, hint=-1, fixed=-1, encoding=auto, sequence=129
2020-07-02 12:03:52,301 get_client_backlog missing acks: []
2020-07-02 12:03:52,301 update_speed() speed=32 (target=33, max=100) for wid=3, info={'low-limit': 687960, 'max-speed': 100, 'min-speed': 30, 'factors': {'damage-latency-abs': 0, 'damage-latency-rel': 1, 'decoding-latency': 5, 'pixel-rate': 0}, 'limits': {'backlog': 100, 'damage-latency': 125, 'pixel-rate': 100, 'bandwidth-limit': 100, 'congestion': 100}}
2020-07-02 12:03:52,377 packet decoding sequence 74 for window 3: 910x756 took 20.7ms
2020-07-02 12:03:52,377 may_recalculate(3, 687960) total 687960 pixels, scheduling recalculate work item
2020-07-02 12:03:52,680 packet decoding sequence 75 for window 3: 910x756 took 4.2ms
2020-07-02 12:03:53,082 packet decoding sequence 76 for window 3: 910x18 took 2.9ms
2020-07-02 12:03:53,297 calculate_batch_delay for wid=3 current batch delay=63, last update 14.1 seconds ago
2020-07-02 12:03:53,297 calculate_batch_delay for wid=3, 870900 pixels updated since the last update
2020-07-02 12:03:53,297 calculate_batch_delay for wid=3, skipping - only 102250 bytes sent since the last update
2020-07-02 12:03:53,298 update_quality() suspended=False, mmap=None, current=99, hint=-1, fixed=-1, encoding=auto, sequence=141
2020-07-02 12:03:53,298 get_client_backlog missing acks: []
2020-07-02 12:03:53,299 get_target_quality: target=114% (window  910x756 ) pctpixdamaged=374%, dpc=((1, 1209600), (2, 753624), (3, 614448), (4, 0), (5, 0), (6, 0), (7, 0), (8, 0), (9, 0), (10, 0))
2020-07-02 12:03:53,300 update_quality() quality=99 (target=100) for wid=3, info={'compression-ratio': (94, 74), 'min-quality': 30, 'min-speed': 30, 'backlog': (0, 0, 687960, 0), 'limits': {'backlog': 100, 'bandwidth': 100, 'congestion': 100, 'batch': 373, 'latency': 2680, 'boost': 6}}
2020-07-02 12:03:53,300 update_speed() suspended=False, mmap=False, current=32, hint=-1, fixed=-1, encoding=auto, sequence=141
2020-07-02 12:03:53,300 get_client_backlog missing acks: []
2020-07-02 12:03:53,301 update_speed() speed=36 (target=40, max=43) for wid=3, info={'low-limit': 687960, 'max-speed': 43, 'min-speed': 30, 'factors': {'damage-latency-abs': 0, 'damage-latency-rel': 1, 'decoding-latency': 1, 'pixel-rate': 15}, 'limits': {'backlog': 100, 'damage-latency': 125, 'pixel-rate': 43, 'bandwidth-limit': 100, 'congestion': 100}}
2020-07-02 12:03:53,302 packet decoding sequence 77 for window 3: 900x6 took 1.7ms
2020-07-02 12:03:53,302 may_recalculate(3, 5400) total 5400 pixels, scheduling recalculate work item
2020-07-02 12:03:53,309 packet decoding sequence 78 for window 3: 6x665 took 2.1ms
2020-07-02 12:03:53,310 packet decoding sequence 79 for window 3: 6x1 took 2.3ms
2020-07-02 12:03:53,310 packet decoding sequence 80 for window 3: 252x1 took 2.3ms
2020-07-02 12:03:53,368 packet decoding sequence 81 for window 3: 900x6 took 0.7ms
2020-07-02 12:03:53,376 packet decoding sequence 82 for window 3: 6x665 took 0.7ms
2020-07-02 12:03:53,376 packet decoding sequence 83 for window 3: 6x1 took 0.9ms
2020-07-02 12:03:53,377 packet decoding sequence 84 for window 3: 252x1 took 0.9ms
2020-07-02 12:03:53,449 packet decoding sequence 85 for window 3: 900x6 took 3.6ms
2020-07-02 12:03:53,450 packet decoding sequence 86 for window 3: 6x665 took 1.9ms
2020-07-02 12:03:53,450 packet decoding sequence 87 for window 3: 6x1 took 2.0ms
2020-07-02 12:03:53,450 packet decoding sequence 88 for window 3: 252x1 took 1.9ms
2020-07-02 12:03:53,760 packet decoding sequence 89 for window 3: 910x756 took 26.9ms
2020-07-02 12:03:53,775 packet decoding sequence 90 for window 3: 910x756 took 25.4ms
2020-07-02 12:03:53,792 packet decoding sequence 91 for window 3: 910x756 took 16.5ms
2020-07-02 12:03:53,792 packet decoding sequence 92 for window 3: 910x52 took 4.4ms
2020-07-02 12:03:53,792 packet decoding sequence 93 for window 3: 910x9 took 3.5ms
2020-07-02 12:03:53,793 packet decoding sequence 94 for window 3: 910x42 took 3.4ms
2020-07-02 12:03:53,793 packet decoding sequence 95 for window 3: 910x3 took 2.3ms
2020-07-02 12:03:53,801 packet decoding sequence 96 for window 3: 910x13 took 2.8ms
2020-07-02 12:03:53,802 packet decoding sequence 97 for window 3: 910x5 took 2.2ms
2020-07-02 12:03:53,813 packet decoding sequence 98 for window 3: 910x12 took 1.1ms
2020-07-02 12:03:53,814 packet decoding sequence 99 for window 3: 910x6 took 0.7ms
2020-07-02 12:03:53,830 packet decoding sequence 100 for window 3: 910x14 took 1.5ms
2020-07-02 12:03:53,830 packet decoding sequence 101 for window 3: 910x10 took 0.9ms
2020-07-02 12:03:53,830 packet decoding sequence 102 for window 3: 900x6 took 6.0ms
2020-07-02 12:03:53,831 packet decoding sequence 103 for window 3: 6x665 took 4.9ms
2020-07-02 12:03:53,831 packet decoding sequence 104 for window 3: 6x1 took 5.1ms
2020-07-02 12:03:53,837 packet decoding sequence 105 for window 3: 252x1 took 5.3ms
2020-07-02 12:03:53,837 packet decoding sequence 106 for window 3: 900x6 took 6.0ms
2020-07-02 12:03:53,839 packet decoding sequence 107 for window 3: 6x665 took 1.5ms
2020-07-02 12:03:53,839 packet decoding sequence 108 for window 3: 6x1 took 1.5ms
2020-07-02 12:03:53,839 packet decoding sequence 109 for window 3: 252x1 took 1.8ms
2020-07-02 12:03:53,857 packet decoding sequence 110 for window 3: 900x6 took 0.7ms
2020-07-02 12:03:53,865 packet decoding sequence 111 for window 3: 6x665 took 0.9ms
2020-07-02 12:03:53,865 packet decoding sequence 112 for window 3: 6x1 took 0.6ms
2020-07-02 12:03:53,865 packet decoding sequence 113 for window 3: 252x1 took 0.4ms
2020-07-02 12:03:54,065 packet decoding sequence 114 for window 3: 910x756 took 28.6ms
2020-07-02 12:03:54,066 packet decoding sequence 115 for window 3: 910x756 took 11.8ms
2020-07-02 12:03:54,066 packet decoding sequence 116 for window 3: 910x52 took 12.8ms
2020-07-02 12:03:54,067 packet decoding sequence 117 for window 3: 910x42 took 0.8ms
2020-07-02 12:03:54,090 packet decoding sequence 118 for window 3: 910x9 took 0.7ms
2020-07-02 12:03:54,189 packet decoding sequence 119 for window 3: 910x9 took 7.0ms
2020-07-02 12:03:54,189 packet decoding sequence 120 for window 3: 910x9 took 11.0ms
2020-07-02 12:03:54,197 packet decoding sequence 121 for window 3: 910x9 took 9.1ms
2020-07-02 12:03:54,198 packet decoding sequence 122 for window 3: 910x38 took 4.2ms
2020-07-02 12:03:54,198 packet decoding sequence 123 for window 3: 900x6 took 5.3ms
2020-07-02 12:03:54,198 packet decoding sequence 124 for window 3: 6x665 took 4.9ms
2020-07-02 12:03:54,199 packet decoding sequence 125 for window 3: 6x1 took 4.9ms
2020-07-02 12:03:54,199 packet decoding sequence 126 for window 3: 252x1 took 4.9ms
2020-07-02 12:03:54,199 packet decoding sequence 127 for window 3: 900x6 took 5.6ms
2020-07-02 12:03:54,199 packet decoding sequence 128 for window 3: 6x665 took 4.9ms
2020-07-02 12:03:54,200 packet decoding sequence 129 for window 3: 6x1 took 3.8ms
2020-07-02 12:03:54,200 packet decoding sequence 130 for window 3: 252x1 took 3.6ms
2020-07-02 12:03:54,200 packet decoding sequence 131 for window 3: 900x6 took 3.5ms
2020-07-02 12:03:54,200 packet decoding sequence 132 for window 3: 6x665 took 3.5ms
2020-07-02 12:03:54,201 packet decoding sequence 133 for window 3: 6x1 took 3.7ms
2020-07-02 12:03:54,201 packet decoding sequence 134 for window 3: 252x1 took 3.9ms
2020-07-02 12:03:54,305 calculate_batch_delay for wid=3 current batch delay=63, last update 15.1 seconds ago
2020-07-02 12:03:54,306 calculate_batch_delay for wid=3, 4387884 pixels updated since the last update
2020-07-02 12:03:54,306 calculate_batch_delay for wid=3, 444386 bytes sent since the last update
2020-07-02 12:03:54,307 update_batch_delay: damage-network-delay         : 0.99,0.51  {'avg': 41, 'recent': 40}
2020-07-02 12:03:54,307 update_batch_delay: client-decode-speed          : 1.13,0.01  {'avg': 22, 'recent': 26}
2020-07-02 12:03:54,307 update_batch_delay: client-latency               : 1.24,0.76  {'avg': 104, 'recent': 129, 'target': 39, 'aim': 800, 'aimed_avg': 1530, 'div': 1000, 'smoothing': 'sqrt', 'weight_multiplier': 1561}
2020-07-02 12:03:54,307 update_batch_delay: client-ping-latency          : 0.91,0.20  {'avg': 30, 'recent': 29, 'target': 30, 'aim': 949, 'aimed_avg': 827, 'div': 1000, 'smoothing': 'sqrt', 'weight_multiplier': 679}
2020-07-02 12:03:54,307 update_batch_delay: server-ping-latency          : 0.90,0.24  {'avg': 33, 'recent': 31, 'target': 35, 'aim': 949, 'aimed_avg': 811, 'div': 1000, 'smoothing': 'sqrt', 'weight_multiplier': 765}
2020-07-02 12:03:54,307 update_batch_delay: packet-queue-size            : 0.28,0.31  {'avg': 109, 'recent': 133, 'target': 1000, 'aim': 250, 'aimed_avg': 80, 'div': 1000, 'smoothing': 'sqrt', 'weight_multiplier': 365}
2020-07-02 12:03:54,308 update_batch_delay: packet-queue-pixels          : 0.23,0.20  {'avg': 24725701, 'recent': 36463304, 'target': 1000, 'aim': 250, 'aimed_avg': 52, 'div': 687960000, 'smoothing': 'sqrt', 'weight_multiplier': 230}
2020-07-02 12:03:54,308 update_batch_delay: compression-work-queue       : 0.34,0.51  {'avg': 449, 'recent': 490, 'target': 1000, 'aim': 250, 'aimed_avg': 268, 'div': 1000, 'smoothing': 'logp', 'weight_multiplier': 700}
2020-07-02 12:03:54,308 update_batch_delay: damage-packet-queue-pixels   : 0.23,0.20  {'avg': 24820548, 'recent': 36464667, 'target': 1000, 'aim': 250, 'aimed_avg': 52, 'div': 687960000, 'smoothing': 'sqrt', 'weight_multiplier': 230}
2020-07-02 12:03:54,308 update_batch_delay: focus                        : 0.00,1.00  {'has_focus': True}
2020-07-02 12:03:54,308 update_batch_delay: delay=44 (last actual delay: 51)
2020-07-02 12:03:54,308 update_quality() suspended=False, mmap=None, current=99, hint=-1, fixed=-1, encoding=auto, sequence=219
2020-07-02 12:03:54,309 get_client_backlog missing acks: []
2020-07-02 12:03:54,309 get_target_quality: target=100% (window  910x756 ) pctpixdamaged=1087%, dpc=((1, 4905432), (2, 1209600), (3, 753624), (4, 614448), (5, 0), (6, 0), (7, 0), (8, 0), (9, 0), (10, 0))
2020-07-02 12:03:54,309 update_quality() quality=99 (target=100) for wid=3, info={'compression-ratio': (73, 73), 'min-quality': 30, 'min-speed': 30, 'backlog': (0, 0, 687960, 0), 'limits': {'backlog': 100, 'bandwidth': 100, 'congestion': 100, 'batch': 512, 'latency': 151, 'boost': 0}}
2020-07-02 12:03:54,310 update_speed() suspended=False, mmap=False, current=36, hint=-1, fixed=-1, encoding=auto, sequence=219
2020-07-02 12:03:54,310 get_client_backlog missing acks: []
2020-07-02 12:03:54,310 update_speed() speed=41 (target=51, max=100) for wid=3, info={'low-limit': 687960, 'max-speed': 100, 'min-speed': 30, 'factors': {'damage-latency-abs': 0, 'damage-latency-rel': 2, 'decoding-latency': 2, 'pixel-rate': 30}, 'limits': {'backlog': 100, 'damage-latency': 148, 'pixel-rate': 113, 'bandwidth-limit': 100, 'congestion': 100}}
2020-07-02 12:03:54,406 packet decoding sequence 135 for window 3: 910x756 took 30.6ms
2020-07-02 12:03:54,406 may_recalculate(3, 687960) total 687960 pixels, scheduling recalculate work item
2020-07-02 12:03:54,627 packet decoding sequence 136 for window 3: 910x756 took 20.1ms
2020-07-02 12:03:54,846 packet decoding sequence 137 for window 3: 910x756 took 33.9ms
2020-07-02 12:03:54,847 packet decoding sequence 138 for window 3: 910x756 took 15.7ms
2020-07-02 12:03:54,863 packet decoding sequence 139 for window 3: 910x52 took 7.0ms
2020-07-02 12:03:54,863 packet decoding sequence 140 for window 3: 910x3 took 6.7ms
2020-07-02 12:03:54,864 packet decoding sequence 141 for window 3: 910x5 took 6.8ms
2020-07-02 12:03:54,866 packet decoding sequence 142 for window 3: 910x6 took 0.7ms
2020-07-02 12:03:54,866 packet decoding sequence 143 for window 3: 910x9 took 0.6ms
2020-07-02 12:03:54,882 packet decoding sequence 144 for window 3: 910x9 took 0.6ms
2020-07-02 12:03:54,898 packet decoding sequence 145 for window 3: 910x9 took 0.6ms
2020-07-02 12:03:54,913 packet decoding sequence 146 for window 3: 910x9 took 0.7ms
2020-07-02 12:03:54,939 packet decoding sequence 147 for window 3: 910x33 took 1.1ms
2020-07-02 12:03:54,940 packet decoding sequence 148 for window 3: 910x756 took 3.5ms
2020-07-02 12:03:54,968 packet decoding sequence 149 for window 3: 910x52 took 1.1ms
2020-07-02 12:03:54,977 packet decoding sequence 150 for window 3: 910x5 took 1.4ms
2020-07-02 12:03:54,977 packet decoding sequence 151 for window 3: 910x3 took 0.4ms
2020-07-02 12:03:55,001 packet decoding sequence 152 for window 3: 910x12 took 0.8ms
2020-07-02 12:03:55,016 packet decoding sequence 153 for window 3: 910x9 took 0.8ms
2020-07-02 12:03:55,017 packet decoding sequence 154 for window 3: 910x12 took 0.6ms
2020-07-02 12:03:55,034 packet decoding sequence 155 for window 3: 910x13 took 0.6ms
2020-07-02 12:03:55,047 packet decoding sequence 156 for window 3: 910x14 took 0.9ms
2020-07-02 12:03:55,064 packet decoding sequence 157 for window 3: 910x10 took 0.7ms
2020-07-02 12:03:55,305 calculate_batch_delay for wid=3 current batch delay=44, last update 1.0 seconds ago
2020-07-02 12:03:55,306 update_batch_delay: damage-network-delay         : 1.00,0.50  {'avg': 40, 'recent': 40}
2020-07-02 12:03:55,306 update_batch_delay: client-decode-speed          : 0.83,0.01  {'avg': 17, 'recent': 13}
2020-07-02 12:03:55,307 update_batch_delay: damage-rate                  : 0.85,0.38  {'elapsed': 347, 'max_latency': 100}
2020-07-02 12:03:55,307 update_batch_delay: client-latency               : 1.48,1.09  {'avg': 143, 'recent': 221, 'target': 39, 'aim': 800, 'aimed_avg': 2199, 'div': 1000, 'smoothing': 'sqrt', 'weight_multiplier': 1561}
2020-07-02 12:03:55,307 update_batch_delay: client-ping-latency          : 0.91,0.20  {'avg': 30, 'recent': 29, 'target': 30, 'aim': 949, 'aimed_avg': 832, 'div': 1000, 'smoothing': 'sqrt', 'weight_multiplier': 679}
2020-07-02 12:03:55,308 update_batch_delay: server-ping-latency          : 0.90,0.24  {'avg': 33, 'recent': 31, 'target': 35, 'aim': 949, 'aimed_avg': 811, 'div': 1000, 'smoothing': 'sqrt', 'weight_multiplier': 765}
2020-07-02 12:03:55,308 update_batch_delay: packet-queue-size            : 0.27,0.30  {'avg': 111, 'recent': 123, 'target': 1000, 'aim': 250, 'aimed_avg': 74, 'div': 1000, 'smoothing': 'sqrt', 'weight_multiplier': 351}
2020-07-02 12:03:55,308 update_batch_delay: packet-queue-pixels          : 0.26,0.22  {'avg': 32344093, 'recent': 46918964, 'target': 1000, 'aim': 250, 'aimed_avg': 67, 'div': 687960000, 'smoothing': 'sqrt', 'weight_multiplier': 261}
2020-07-02 12:03:55,308 update_batch_delay: compression-work-queue       : 0.23,0.52  {'avg': 405, 'recent': 313, 'target': 1000, 'aim': 250, 'aimed_avg': 173, 'div': 1000, 'smoothing': 'logp', 'weight_multiplier': 636}
2020-07-02 12:03:55,309 update_batch_delay: damage-packet-queue-pixels   : 0.26,0.22  {'avg': 32476136, 'recent': 46925750, 'target': 1000, 'aim': 250, 'aimed_avg': 67, 'div': 687960000, 'smoothing': 'sqrt', 'weight_multiplier': 261}
2020-07-02 12:03:55,309 update_batch_delay: focus                        : 0.00,1.00  {'has_focus': True}
2020-07-02 12:03:55,309 update_batch_delay: delay=48 (last actual delay: 107)
2020-07-02 12:03:55,309 update_quality() suspended=False, mmap=None, current=99, hint=-1, fixed=-1, encoding=auto, sequence=227
2020-07-02 12:03:55,310 get_client_backlog missing acks: []
2020-07-02 12:03:55,310 get_target_quality: target= 32% (window  910x756 ) pctpixdamaged=1351%, dpc=((1, 1813644), (2, 4905432), (3, 1209600), (4, 753624), (5, 614448), (6, 0), (7, 0), (8, 0), (9, 0), (10, 0))
2020-07-02 12:03:55,311 update_quality() quality=75 (target=72) for wid=3, info={'compression-ratio': (81, 95), 'min-quality': 30, 'min-speed': 30, 'backlog': (1, 687960, 687960, 100), 'limits': {'backlog': 67, 'bandwidth': 100, 'congestion': 100, 'batch': 464, 'latency': 103, 'boost': -8}}
2020-07-02 12:03:55,311 update_speed() suspended=False, mmap=False, current=41, hint=-1, fixed=-1, encoding=auto, sequence=227
2020-07-02 12:03:55,312 get_client_backlog missing acks: []
2020-07-02 12:03:55,312 update_speed() speed=39 (target=43, max=54) for wid=3, info={'low-limit': 687960, 'max-speed': 54, 'min-speed': 30, 'factors': {'damage-latency-abs': 0, 'damage-latency-rel': 2, 'decoding-latency': 1, 'pixel-rate': 18}, 'limits': {'backlog': 68, 'damage-latency': 106, 'pixel-rate': 54, 'bandwidth-limit': 100, 'congestion': 100}}
2020-07-02 12:03:55,375 packet decoding sequence 158 for window 3: 910x756 took 40.3ms
2020-07-02 12:03:55,375 may_recalculate(3, 687960) total 687960 pixels, scheduling recalculate work item
2020-07-02 12:03:55,432 packet decoding sequence 159 for window 3: 910x756 took 3.3ms
2020-07-02 12:03:55,433 packet decoding sequence 160 for window 3: 910x52 took 1.0ms
2020-07-02 12:03:55,433 packet decoding sequence 161 for window 3: 910x12 took 1.1ms
2020-07-02 12:03:55,441 packet decoding sequence 162 for window 3: 910x13 took 0.9ms
2020-07-02 12:03:55,441 packet decoding sequence 163 for window 3: 910x12 took 0.9ms
2020-07-02 12:03:55,450 packet decoding sequence 164 for window 3: 910x13 took 6.4ms
2020-07-02 12:03:55,450 packet decoding sequence 165 for window 3: 910x7 took 5.9ms
2020-07-02 12:03:55,458 packet decoding sequence 166 for window 3: 910x10 took 0.8ms
2020-07-02 12:03:55,466 packet decoding sequence 167 for window 3: 910x10 took 0.8ms
2020-07-02 12:03:55,481 packet decoding sequence 168 for window 3: 910x6 took 0.5ms
2020-07-02 12:03:55,489 packet decoding sequence 169 for window 3: 910x14 took 1.5ms
2020-07-02 12:03:55,497 packet decoding sequence 170 for window 3: 910x10 took 1.3ms
2020-07-02 12:03:55,770 packet decoding sequence 171 for window 3: 910x756 took 29.7ms
2020-07-02 12:03:55,839 packet decoding sequence 172 for window 3: 910x756 took 3.5ms
2020-07-02 12:03:55,840 packet decoding sequence 173 for window 3: 910x52 took 1.9ms
2020-07-02 12:03:55,848 packet decoding sequence 174 for window 3: 910x1 took 1.4ms
2020-07-02 12:03:55,848 packet decoding sequence 175 for window 3: 910x9 took 1.5ms
2020-07-02 12:03:55,848 packet decoding sequence 176 for window 3: 910x14 took 0.8ms
2020-07-02 12:03:55,849 packet decoding sequence 177 for window 3: 910x3 took 0.5ms
2020-07-02 12:03:55,849 packet decoding sequence 178 for window 3: 910x4 took 0.6ms
2020-07-02 12:03:55,849 packet decoding sequence 179 for window 3: 910x9 took 0.6ms
2020-07-02 12:03:55,877 packet decoding sequence 180 for window 3: 910x11 took 0.7ms
2020-07-02 12:03:55,887 packet decoding sequence 181 for window 3: 910x14 took 0.9ms
2020-07-02 12:03:55,888 packet decoding sequence 182 for window 3: 910x10 took 0.6ms
2020-07-02 12:03:56,107 packet decoding sequence 183 for window 3: 910x756 took 15.8ms

...

I then started a download on the server's network, which apparently takes up a still startlingly large portion of the bandwidth... and the ping times quickly escalate.

Reply from 10.0.3.148: bytes=32 time=359ms TTL=60
Reply from 10.0.3.148: bytes=32 time=407ms TTL=60
Reply from 10.0.3.148: bytes=32 time=466ms TTL=60
Reply from 10.0.3.148: bytes=32 time=510ms TTL=60

... from there very likely into the 12K ms to 18K ms range (which I routinely see, and which was seen in the previous logs).

The logs, which go longer than the last and might, hopefully, capture something interesting as things get bad.

2020-07-02 12:04:21,151 packet decoding sequence 452 for window 3: 900x6 took 1.6ms
2020-07-02 12:04:21,152 may_recalculate(3, 5400) total 5400 pixels, scheduling recalculate work item
2020-07-02 12:04:21,153 calculate_batch_delay for wid=3 current batch delay=23, last update 10.8 seconds ago
2020-07-02 12:04:21,153 calculate_batch_delay for wid=3, skipping - only 271419 pixels updated since the last update
2020-07-02 12:04:21,154 packet decoding sequence 453 for window 3: 6x665 took 1.7ms
2020-07-02 12:04:21,154 update_quality() suspended=False, mmap=None, current=99, hint=-1, fixed=-1, encoding=auto, sequence=637
2020-07-02 12:04:21,154 may_recalculate(3, 3990) total 3990 pixels, scheduling recalculate work item
2020-07-02 12:04:21,154 get_client_backlog missing acks: []
2020-07-02 12:04:21,155 packet decoding sequence 454 for window 3: 6x1 took 2.0ms
2020-07-02 12:04:21,155 get_target_quality: target=105% (window  910x756 ) pctpixdamaged= 40%, dpc=((1, 28944), (2, 173664), (3, 78459), (4, 0), (5, 0), (6, 0), (7, 0), (8, 0), (9, 0), (10, 0))
2020-07-02 12:04:21,156 packet decoding sequence 455 for window 3: 252x1 took 2.1ms
2020-07-02 12:04:21,156 update_quality() quality=99 (target=100) for wid=3, info={'compression-ratio': (76, 68), 'min-quality': 30, 'min-speed': 30, 'backlog': (0, 0, 687960, 0), 'limits': {'backlog': 100, 'bandwidth': 100, 'congestion': 100, 'batch': 661, 'latency': 345, 'boost': 2}}
2020-07-02 12:04:21,156 update_speed() suspended=False, mmap=False, current=34, hint=-1, fixed=-1, encoding=auto, sequence=637
2020-07-02 12:04:21,157 get_client_backlog missing acks: []
2020-07-02 12:04:21,157 update_speed() speed=34 (target=33, max=100) for wid=3, info={'low-limit': 687960, 'max-speed': 100, 'min-speed': 30, 'factors': {'damage-latency-abs': 0, 'damage-latency-rel': 1, 'decoding-latency': 4, 'pixel-rate': 0}, 'limits': {'backlog': 100, 'damage-latency': 250, 'pixel-rate': 100, 'bandwidth-limit': 100, 'congestion': 100}}
2020-07-02 12:04:21,190 packet decoding sequence 456 for window 3: 900x6 took 1.7ms
2020-07-02 12:04:21,190 packet decoding sequence 457 for window 3: 6x665 took 2.7ms
2020-07-02 12:04:21,191 packet decoding sequence 458 for window 3: 6x1 took 2.4ms
2020-07-02 12:04:21,191 packet decoding sequence 459 for window 3: 252x1 took 1.0ms
2020-07-02 12:04:21,229 packet decoding sequence 460 for window 3: 900x6 took 1.1ms
2020-07-02 12:04:21,229 packet decoding sequence 461 for window 3: 6x665 took 1.0ms
2020-07-02 12:04:21,229 packet decoding sequence 462 for window 3: 6x1 took 1.2ms
2020-07-02 12:04:21,237 packet decoding sequence 463 for window 3: 252x1 took 1.2ms
2020-07-02 12:04:21,274 packet decoding sequence 464 for window 3: 900x6 took 1.4ms
2020-07-02 12:04:21,274 packet decoding sequence 465 for window 3: 6x665 took 1.2ms
2020-07-02 12:04:21,274 packet decoding sequence 466 for window 3: 6x1 took 1.4ms
2020-07-02 12:04:21,275 packet decoding sequence 467 for window 3: 252x1 took 1.7ms
2020-07-02 12:04:21,313 packet decoding sequence 468 for window 3: 900x6 took 0.7ms
2020-07-02 12:04:21,319 packet decoding sequence 469 for window 3: 6x665 took 0.8ms
2020-07-02 12:04:21,319 packet decoding sequence 470 for window 3: 6x1 took 0.9ms
2020-07-02 12:04:21,320 packet decoding sequence 471 for window 3: 252x1 took 1.1ms
2020-07-02 12:04:21,372 packet decoding sequence 472 for window 3: 900x6 took 0.7ms
2020-07-02 12:04:21,372 packet decoding sequence 473 for window 3: 6x665 took 0.6ms
2020-07-02 12:04:21,373 packet decoding sequence 474 for window 3: 6x1 took 0.4ms
2020-07-02 12:04:21,373 packet decoding sequence 475 for window 3: 252x1 took 0.4ms
2020-07-02 12:04:21,418 packet decoding sequence 476 for window 3: 900x6 took 0.8ms
2020-07-02 12:04:21,418 packet decoding sequence 477 for window 3: 6x665 took 0.8ms
2020-07-02 12:04:21,419 packet decoding sequence 478 for window 3: 6x1 took 1.0ms
2020-07-02 12:04:21,419 packet decoding sequence 479 for window 3: 252x1 took 1.1ms
2020-07-02 12:04:21,474 packet decoding sequence 480 for window 3: 900x6 took 1.0ms
2020-07-02 12:04:21,491 packet decoding sequence 481 for window 3: 6x665 took 0.7ms
2020-07-02 12:04:21,491 packet decoding sequence 482 for window 3: 6x1 took 0.5ms
2020-07-02 12:04:21,491 packet decoding sequence 483 for window 3: 252x1 took 0.2ms
2020-07-02 12:04:21,536 packet decoding sequence 484 for window 3: 900x6 took 2.0ms
2020-07-02 12:04:21,537 packet decoding sequence 485 for window 3: 6x665 took 1.9ms
2020-07-02 12:04:21,537 packet decoding sequence 486 for window 3: 6x1 took 2.5ms
2020-07-02 12:04:21,537 packet decoding sequence 487 for window 3: 252x1 took 3.2ms
2020-07-02 12:04:21,577 packet decoding sequence 488 for window 3: 900x6 took 1.2ms
2020-07-02 12:04:21,584 packet decoding sequence 489 for window 3: 6x665 took 1.8ms
2020-07-02 12:04:21,584 packet decoding sequence 490 for window 3: 6x1 took 0.5ms
2020-07-02 12:04:21,585 packet decoding sequence 491 for window 3: 252x1 took 1.1ms
2020-07-02 12:04:21,620 packet decoding sequence 492 for window 3: 900x6 took 0.8ms
2020-07-02 12:04:21,633 packet decoding sequence 493 for window 3: 6x665 took 1.1ms
2020-07-02 12:04:21,633 packet decoding sequence 494 for window 3: 6x1 took 1.4ms
2020-07-02 12:04:21,633 packet decoding sequence 495 for window 3: 252x1 took 1.2ms
2020-07-02 12:04:21,671 packet decoding sequence 496 for window 3: 900x6 took 1.0ms
2020-07-02 12:04:21,671 packet decoding sequence 497 for window 3: 6x665 took 1.0ms
2020-07-02 12:04:21,672 packet decoding sequence 498 for window 3: 6x1 took 1.2ms
2020-07-02 12:04:21,672 packet decoding sequence 499 for window 3: 252x1 took 1.4ms
2020-07-02 12:04:21,719 packet decoding sequence 500 for window 3: 900x6 took 0.8ms
2020-07-02 12:04:21,720 packet decoding sequence 501 for window 3: 6x665 took 1.0ms
2020-07-02 12:04:21,720 packet decoding sequence 502 for window 3: 6x1 took 1.0ms
2020-07-02 12:04:21,720 packet decoding sequence 503 for window 3: 252x1 took 1.0ms
2020-07-02 12:04:21,776 packet decoding sequence 504 for window 3: 900x6 took 2.1ms
2020-07-02 12:04:21,777 packet decoding sequence 505 for window 3: 6x665 took 2.0ms
2020-07-02 12:04:21,777 packet decoding sequence 506 for window 3: 6x1 took 2.4ms
2020-07-02 12:04:21,777 packet decoding sequence 507 for window 3: 252x1 took 2.6ms
2020-07-02 12:04:21,822 packet decoding sequence 508 for window 3: 900x6 took 1.0ms
2020-07-02 12:04:21,823 packet decoding sequence 509 for window 3: 6x665 took 0.9ms
2020-07-02 12:04:21,823 packet decoding sequence 510 for window 3: 6x1 took 1.0ms
2020-07-02 12:04:21,823 packet decoding sequence 511 for window 3: 252x1 took 1.3ms
2020-07-02 12:04:21,872 packet decoding sequence 512 for window 3: 900x6 took 0.8ms
2020-07-02 12:04:21,873 packet decoding sequence 513 for window 3: 6x665 took 0.9ms
2020-07-02 12:04:21,873 packet decoding sequence 514 for window 3: 6x1 took 0.7ms
2020-07-02 12:04:21,873 packet decoding sequence 515 for window 3: 252x1 took 0.7ms
2020-07-02 12:04:21,917 packet decoding sequence 516 for window 3: 900x6 took 1.2ms
2020-07-02 12:04:21,924 packet decoding sequence 517 for window 3: 6x665 took 0.8ms
2020-07-02 12:04:21,925 packet decoding sequence 518 for window 3: 6x1 took 0.8ms
2020-07-02 12:04:21,925 packet decoding sequence 519 for window 3: 252x1 took 1.0ms
2020-07-02 12:04:21,985 packet decoding sequence 520 for window 3: 900x6 took 1.2ms
2020-07-02 12:04:22,001 packet decoding sequence 521 for window 3: 6x665 took 0.7ms
2020-07-02 12:04:22,002 packet decoding sequence 522 for window 3: 6x1 took 0.5ms
2020-07-02 12:04:22,002 packet decoding sequence 523 for window 3: 252x1 took 0.5ms
2020-07-02 12:04:22,029 packet decoding sequence 524 for window 3: 900x6 took 2.5ms
2020-07-02 12:04:22,032 packet decoding sequence 525 for window 3: 6x665 took 1.6ms
2020-07-02 12:04:22,032 packet decoding sequence 526 for window 3: 6x1 took 1.7ms
2020-07-02 12:04:22,033 packet decoding sequence 527 for window 3: 252x1 took 1.9ms
2020-07-02 12:04:22,083 packet decoding sequence 528 for window 3: 900x6 took 1.3ms
2020-07-02 12:04:22,083 packet decoding sequence 529 for window 3: 6x665 took 1.4ms
2020-07-02 12:04:22,083 packet decoding sequence 530 for window 3: 6x1 took 1.6ms
2020-07-02 12:04:22,084 packet decoding sequence 531 for window 3: 252x1 took 2.0ms
2020-07-02 12:04:22,154 calculate_batch_delay for wid=3 current batch delay=23, last update 11.8 seconds ago
2020-07-02 12:04:22,154 calculate_batch_delay for wid=3, 923760 pixels updated since the last update
2020-07-02 12:04:22,154 calculate_batch_delay for wid=3, skipping - only 129421 bytes sent since the last update
2020-07-02 12:04:22,154 update_quality() suspended=False, mmap=None, current=99, hint=-1, fixed=-1, encoding=auto, sequence=783
2020-07-02 12:04:22,155 get_client_backlog missing acks: []
2020-07-02 12:04:22,156 get_target_quality: target=100% (window  910x756 ) pctpixdamaged=152%, dpc=((1, 768564), (2, 28944), (3, 173664), (4, 78459), (5, 0), (6, 0), (7, 0), (8, 0), (9, 0), (10, 0))
2020-07-02 12:04:22,156 update_quality() quality=99 (target=100) for wid=3, info={'compression-ratio': (74, 74), 'min-quality': 30, 'min-speed': 30, 'backlog': (0, 0, 687960, 0), 'limits': {'backlog': 100, 'bandwidth': 100, 'congestion': 100, 'batch': 661, 'latency': 353, 'boost': 0}}
2020-07-02 12:04:22,156 update_speed() suspended=False, mmap=False, current=34, hint=-1, fixed=-1, encoding=auto, sequence=783
2020-07-02 12:04:22,156 get_client_backlog missing acks: []
2020-07-02 12:04:22,156 update_speed() speed=38 (target=45, max=100) for wid=3, info={'low-limit': 687960, 'max-speed': 100, 'min-speed': 30, 'factors': {'damage-latency-abs': 0, 'damage-latency-rel': 1, 'decoding-latency': 21, 'pixel-rate': 0}, 'limits': {'backlog': 100, 'damage-latency': 250, 'pixel-rate': 100, 'bandwidth-limit': 100, 'congestion': 100}}
2020-07-02 12:04:22,218 packet decoding sequence 532 for window 3: 910x756 took 31.2ms
2020-07-02 12:04:22,218 may_recalculate(3, 687960) total 687960 pixels, scheduling recalculate work item
2020-07-02 12:04:23,154 calculate_batch_delay for wid=3 current batch delay=23, last update 12.8 seconds ago
2020-07-02 12:04:23,155 calculate_batch_delay for wid=3, 923760 pixels updated since the last update
2020-07-02 12:04:23,155 calculate_batch_delay for wid=3, skipping - only 129421 bytes sent since the last update
2020-07-02 12:04:23,155 update_quality() suspended=False, mmap=None, current=99, hint=-1, fixed=-1, encoding=auto, sequence=783
2020-07-02 12:04:23,155 get_target_quality: target=100% (window  910x756 ) pctpixdamaged=152%, dpc=((1, 0), (2, 768564), (3, 28944), (4, 173664), (5, 78459), (6, 0), (7, 0), (8, 0), (9, 0), (10, 0))
2020-07-02 12:04:23,156 update_quality() quality=99 (target=100) for wid=3, info={'compression-ratio': (74, 74), 'min-quality': 30, 'min-speed': 30, 'backlog': (0, 0, 687960, 0), 'limits': {'backlog': 100, 'bandwidth': 100, 'congestion': 100, 'batch': 661, 'latency': 348, 'boost': 0}}
2020-07-02 12:04:23,156 update_speed() suspended=False, mmap=False, current=38, hint=-1, fixed=-1, encoding=auto, sequence=783
2020-07-02 12:04:23,156 update_speed() speed=35 (target=33, max=100) for wid=3, info={'low-limit': 687960, 'max-speed': 100, 'min-speed': 30, 'factors': {'damage-latency-abs': 0, 'damage-latency-rel': 1, 'decoding-latency': 4, 'pixel-rate': 0}, 'limits': {'backlog': 100, 'damage-latency': 250, 'pixel-rate': 100, 'bandwidth-limit': 100, 'congestion': 100}}
2020-07-02 12:04:46,517 packet decoding sequence 533 for window 3: 900x6 took 0.8ms
2020-07-02 12:04:46,518 may_recalculate(3, 5400) total 5400 pixels, scheduling recalculate work item
2020-07-02 12:04:46,518 packet decoding sequence 534 for window 3: 6x665 took 0.8ms
2020-07-02 12:04:46,519 calculate_batch_delay for wid=3 current batch delay=23, last update 36.2 seconds ago
2020-07-02 12:04:46,520 may_recalculate(3, 3990) total 3990 pixels, scheduling recalculate work item
2020-07-02 12:04:46,520 update_batch_delay: damage-network-delay         : 1.00,0.50  {'avg': 40, 'recent': 40}
2020-07-02 12:04:46,521 packet decoding sequence 535 for window 3: 6x1 took 1.4ms
2020-07-02 12:04:46,521 update_batch_delay: client-decode-speed          : 1.73,0.32  {'avg': 49, 'recent': 114}
2020-07-02 12:04:46,521 update_batch_delay: damage-rate                  : 0.73,0.52  {'elapsed': 468, 'max_latency': 100}
2020-07-02 12:04:46,521 packet decoding sequence 536 for window 3: 252x1 took 0.8ms
2020-07-02 12:04:46,521 update_batch_delay: client-latency               : 2.54,1.65  {'avg': 109, 'recent': 509, 'target': 30, 'aim': 800, 'aimed_avg': 6432, 'div': 1000, 'smoothing': 'sqrt', 'weight_multiplier': 1332}
2020-07-02 12:04:46,522 update_batch_delay: client-ping-latency          : 1.44,0.45  {'avg': 132, 'recent': 246, 'target': 30, 'aim': 949, 'aimed_avg': 2061, 'div': 1000, 'smoothing': 'sqrt', 'weight_multiplier': 679}
2020-07-02 12:04:46,522 update_batch_delay: server-ping-latency          : 1.40,0.46  {'avg': 104, 'recent': 196, 'target': 32, 'aim': 949, 'aimed_avg': 1952, 'div': 1000, 'smoothing': 'sqrt', 'weight_multiplier': 731}
2020-07-02 12:04:46,522 update_batch_delay: packet-queue-size            : 0.02,0.19  {'avg': 37, 'recent': 0, 'target': 1000, 'aim': 250, 'aimed_avg': 0, 'div': 1000, 'smoothing': 'sqrt', 'weight_multiplier': 193}
2020-07-02 12:04:46,522 update_batch_delay: packet-queue-pixels          : 0.01,0.11  {'avg': 8364401, 'recent': 140108, 'target': 1000, 'aim': 250, 'aimed_avg': 0, 'div': 687960000, 'smoothing': 'sqrt', 'weight_multiplier': 110}
2020-07-02 12:04:46,522 update_batch_delay: compression-work-queue       : 0.29,0.49  {'avg': 301, 'recent': 397, 'target': 1000, 'aim': 250, 'aimed_avg': 225, 'div': 1000, 'smoothing': 'logp', 'weight_multiplier': 630}
2020-07-02 12:04:46,523 update_batch_delay: damage-packet-queue-pixels   : 0.01,0.11  {'avg': 8364663, 'recent': 140171, 'target': 1000, 'aim': 250, 'aimed_avg': 0, 'div': 687960000, 'smoothing': 'sqrt', 'weight_multiplier': 110}
2020-07-02 12:04:46,523 update_batch_delay: focus                        : 0.00,1.00  {'has_focus': True}
2020-07-02 12:04:46,523 update_batch_delay: delay=29 (last actual delay: 34)
2020-07-02 12:04:46,523 update_quality() suspended=False, mmap=None, current=99, hint=-1, fixed=-1, encoding=auto, sequence=799
2020-07-02 12:04:46,523 get_client_backlog missing acks: []
2020-07-02 12:04:46,524 get_target_quality: target=  9% (window  910x756 ) pctpixdamaged=  4%, dpc=((1, 28944), (2, 0), (3, 0), (4, 0), (5, 0), (6, 0), (7, 0), (8, 0), (9, 0), (10, 0))
2020-07-02 12:04:46,524 update_quality() quality=60 (target=59) for wid=3, info={'compression-ratio': (74, 56), 'min-quality': 30, 'min-speed': 30, 'backlog': (4, 9648, 687960, 1), 'limits': {'backlog': 99, 'bandwidth': 100, 'congestion': 100, 'batch': 661, 'latency': 34, 'boost': 0}}
2020-07-02 12:04:46,524 update_speed() suspended=False, mmap=False, current=35, hint=-1, fixed=-1, encoding=auto, sequence=799
2020-07-02 12:04:46,524 get_client_backlog missing acks: []
2020-07-02 12:04:46,525 update_speed() speed=34 (target=33, max=100) for wid=3, info={'low-limit': 687960, 'max-speed': 100, 'min-speed': 30, 'factors': {'damage-latency-abs': 0, 'damage-latency-rel': 1, 'decoding-latency': 4, 'pixel-rate': 0}, 'limits': {'backlog': 100, 'damage-latency': 225, 'pixel-rate': 100, 'bandwidth-limit': 100, 'congestion': 100}}
2020-07-02 12:04:46,567 packet decoding sequence 537 for window 3: 900x6 took 0.9ms
2020-07-02 12:04:46,567 packet decoding sequence 538 for window 3: 6x665 took 0.6ms
2020-07-02 12:04:46,570 packet decoding sequence 539 for window 3: 6x1 took 0.8ms
2020-07-02 12:04:46,570 packet decoding sequence 540 for window 3: 252x1 took 0.9ms
2020-07-02 12:04:47,520 calculate_batch_delay for wid=3 current batch delay=29, last update 1.0 seconds ago
2020-07-02 12:04:47,521 update_batch_delay: damage-network-delay         : 1.00,0.50  {'avg': 40, 'recent': 40}
2020-07-02 12:04:47,521 update_batch_delay: client-decode-speed          : 1.45,0.15  {'avg': 49, 'recent': 86}
2020-07-02 12:04:47,521 update_batch_delay: damage-rate                  : 0.44,0.75  {'elapsed': 761, 'max_latency': 100}
2020-07-02 12:04:47,521 update_batch_delay: client-latency               : 2.23,1.48  {'avg': 187, 'recent': 506, 'target': 30, 'aim': 800, 'aimed_avg': 4973, 'div': 1000, 'smoothing': 'sqrt', 'weight_multiplier': 1332}
2020-07-02 12:04:47,522 update_batch_delay: client-ping-latency          : 1.41,0.44  {'avg': 124, 'recent': 227, 'target': 30, 'aim': 949, 'aimed_avg': 1992, 'div': 1000, 'smoothing': 'sqrt', 'weight_multiplier': 679}
2020-07-02 12:04:47,522 update_batch_delay: server-ping-latency          : 1.38,0.45  {'avg': 98, 'recent': 180, 'target': 32, 'aim': 949, 'aimed_avg': 1894, 'div': 1000, 'smoothing': 'sqrt', 'weight_multiplier': 731}
2020-07-02 12:04:47,522 update_batch_delay: packet-queue-size            : 0.05,0.20  {'avg': 41, 'recent': 3, 'target': 1000, 'aim': 250, 'aimed_avg': 2, 'div': 1000, 'smoothing': 'sqrt', 'weight_multiplier': 202}
2020-07-02 12:04:47,522 update_batch_delay: packet-queue-pixels          : 0.03,0.11  {'avg': 9193970, 'recent': 644612, 'target': 1000, 'aim': 250, 'aimed_avg': 0, 'div': 687960000, 'smoothing': 'sqrt', 'weight_multiplier': 115}
2020-07-02 12:04:47,522 update_batch_delay: compression-work-queue       : 0.22,0.45  {'avg': 279, 'recent': 295, 'target': 1000, 'aim': 250, 'aimed_avg': 168, 'div': 1000, 'smoothing': 'logp', 'weight_multiplier': 543}
2020-07-02 12:04:47,523 update_batch_delay: damage-packet-queue-pixels   : 0.03,0.11  {'avg': 9194143, 'recent': 644774, 'target': 1000, 'aim': 250, 'aimed_avg': 0, 'div': 687960000, 'smoothing': 'sqrt', 'weight_multiplier': 115}
2020-07-02 12:04:47,523 update_batch_delay: focus                        : 0.00,1.00  {'has_focus': True}
2020-07-02 12:04:47,523 update_batch_delay: delay=101 (last actual delay: 519)
2020-07-02 12:04:47,524 update_quality() suspended=False, mmap=None, current=60, hint=-1, fixed=-1, encoding=auto, sequence=801
2020-07-02 12:04:47,524 get_client_backlog missing acks: []
2020-07-02 12:04:47,525 get_target_quality: target= 10% (window  910x756 ) pctpixdamaged=190%, dpc=((1, 1283112), (2, 28944), (3, 0), (4, 0), (5, 0), (6, 0), (7, 0), (8, 0), (9, 0), (10, 0))
2020-07-02 12:04:47,525 update_quality() quality=58 (target=57) for wid=3, info={'compression-ratio': (74, 73), 'min-quality': 30, 'min-speed': 30, 'backlog': (1, 687960, 687960, 100), 'limits': {'backlog': 67, 'bandwidth': 100, 'congestion': 100, 'batch': 216, 'latency': 36, 'boost': 0}}
2020-07-02 12:04:47,526 update_speed() suspended=False, mmap=False, current=34, hint=-1, fixed=-1, encoding=auto, sequence=801
2020-07-02 12:04:47,526 get_client_backlog missing acks: []
2020-07-02 12:04:47,527 update_speed() speed=35 (target=36, max=36) for wid=3, info={'low-limit': 687960, 'max-speed': 36, 'min-speed': 30, 'factors': {'damage-latency-abs': 0, 'damage-latency-rel': 0, 'decoding-latency': 4, 'pixel-rate': 15}, 'limits': {'backlog': 68, 'damage-latency': 36, 'pixel-rate': 44, 'bandwidth-limit': 100, 'congestion': 100}}
2020-07-02 12:04:48,012 packet decoding sequence 541 for window 3: 910x756 took 31.7ms
2020-07-02 12:04:48,012 may_recalculate(3, 687960) total 687960 pixels, scheduling recalculate work item
2020-07-02 12:04:48,520 calculate_batch_delay for wid=3 current batch delay=101, last update 1.0 seconds ago
2020-07-02 12:04:48,521 update_batch_delay: damage-network-delay         : 1.00,0.50  {'avg': 40, 'recent': 40}
2020-07-02 12:04:48,521 update_batch_delay: damage-rate                  : 0.00,1.25  {'elapsed': 1761, 'max_latency': 100}
2020-07-02 12:04:48,521 update_batch_delay: client-latency               : 3.00,1.89  {'avg': 211, 'recent': 965, 'target': 30, 'aim': 800, 'aimed_avg': 9026, 'div': 1000, 'smoothing': 'sqrt', 'weight_multiplier': 1332}
2020-07-02 12:04:48,521 update_batch_delay: client-ping-latency          : 1.66,0.55  {'avg': 598, 'recent': 917, 'target': 30, 'aim': 949, 'aimed_avg': 2752, 'div': 1000, 'smoothing': 'sqrt', 'weight_multiplier': 679}
2020-07-02 12:04:48,521 update_batch_delay: server-ping-latency          : 1.44,0.49  {'avg': 348, 'recent': 521, 'target': 32, 'aim': 949, 'aimed_avg': 2086, 'div': 1000, 'smoothing': 'sqrt', 'weight_multiplier': 731}
2020-07-02 12:04:48,521 update_batch_delay: packet-queue-size            : 0.05,0.20  {'avg': 42, 'recent': 3, 'target': 1000, 'aim': 250, 'aimed_avg': 2, 'div': 1000, 'smoothing': 'sqrt', 'weight_multiplier': 205}
2020-07-02 12:04:48,521 update_batch_delay: packet-queue-pixels          : 0.03,0.12  {'avg': 9468452, 'recent': 627444, 'target': 1000, 'aim': 250, 'aimed_avg': 0, 'div': 687960000, 'smoothing': 'sqrt', 'weight_multiplier': 117}
2020-07-02 12:04:48,522 update_batch_delay: compression-work-queue       : 0.03,0.49  {'avg': 247, 'recent': 40, 'target': 1000, 'aim': 250, 'aimed_avg': 23, 'div': 1000, 'smoothing': 'logp', 'weight_multiplier': 497}
2020-07-02 12:04:48,522 update_batch_delay: damage-packet-queue-pixels   : 0.03,0.12  {'avg': 9468568, 'recent': 627634, 'target': 1000, 'aim': 250, 'aimed_avg': 0, 'div': 687960000, 'smoothing': 'sqrt', 'weight_multiplier': 117}
2020-07-02 12:04:48,522 update_batch_delay: focus                        : 0.00,1.00  {'has_focus': True}
2020-07-02 12:04:48,522 update_batch_delay: delay=224 (last actual delay: 1340)
2020-07-02 12:04:48,522 update_quality() suspended=False, mmap=None, current=58, hint=-1, fixed=-1, encoding=auto, sequence=805
2020-07-02 12:04:48,522 get_client_backlog missing acks: []
2020-07-02 12:04:48,523 get_target_quality: target=  0% (window  910x756 ) pctpixdamaged=190%, dpc=((1, 0), (2, 1283112), (3, 28944), (4, 0), (5, 0), (6, 0), (7, 0), (8, 0), (9, 0), (10, 0))
2020-07-02 12:04:48,523 update_quality() quality=52 (target=50) for wid=3, info={'compression-ratio': (126, 149), 'min-quality': 30, 'min-speed': 30, 'backlog': (1, 687960, 687960, 100), 'limits': {'backlog': 67, 'bandwidth': 100, 'congestion': 100, 'batch': 97, 'latency': 18, 'boost': -10}}
2020-07-02 12:04:48,523 update_speed() suspended=False, mmap=False, current=35, hint=-1, fixed=-1, encoding=auto, sequence=805
2020-07-02 12:04:48,523 get_client_backlog missing acks: []
2020-07-02 12:04:48,523 update_speed() speed=30 (target=30, max=30) for wid=3, info={'low-limit': 687960, 'max-speed': 30, 'min-speed': 30, 'factors': {'damage-latency-abs': 0, 'damage-latency-rel': 0, 'decoding-latency': 4, 'pixel-rate': 0}, 'limits': {'backlog': 68, 'damage-latency': 10, 'pixel-rate': 100, 'bandwidth-limit': 100, 'congestion': 100}}
2020-07-02 12:04:50,019 packet decoding sequence 542 for window 3: 910x756 took 27.4ms
2020-07-02 12:04:50,020 may_recalculate(3, 687960) total 687960 pixels, scheduling recalculate work item
2020-07-02 12:04:50,021 calculate_batch_delay for wid=3 current batch delay=224, last update 1.5 seconds ago
2020-07-02 12:04:50,022 update_batch_delay: damage-network-delay         : 1.00,0.50  {'avg': 40, 'recent': 40}
2020-07-02 12:04:50,022 update_batch_delay: damage-rate                  : 0.00,1.75  {'elapsed': 3262, 'max_latency': 100}
2020-07-02 12:04:50,022 update_batch_delay: client-latency               : 3.90,2.27  {'avg': 288, 'recent': 1819, 'target': 30, 'aim': 800, 'aimed_avg': 15247, 'div': 1000, 'smoothing': 'sqrt', 'weight_multiplier': 1332}
2020-07-02 12:04:50,022 update_batch_delay: client-ping-latency          : 1.73,0.58  {'avg': 455, 'recent': 856, 'target': 30, 'aim': 949, 'aimed_avg': 2987, 'div': 1000, 'smoothing': 'sqrt', 'weight_multiplier': 679}
2020-07-02 12:04:50,022 update_batch_delay: server-ping-latency          : 1.52,0.53  {'avg': 270, 'recent': 487, 'target': 32, 'aim': 949, 'aimed_avg': 2319, 'div': 1000, 'smoothing': 'sqrt', 'weight_multiplier': 731}
2020-07-02 12:04:50,022 update_batch_delay: packet-queue-size            : 0.09,0.20  {'avg': 45, 'recent': 13, 'target': 1000, 'aim': 250, 'aimed_avg': 8, 'div': 1000, 'smoothing': 'sqrt', 'weight_multiplier': 213}
2020-07-02 12:04:50,022 update_batch_delay: packet-queue-pixels          : 0.06,0.12  {'avg': 10262844, 'recent': 2436623, 'target': 1000, 'aim': 250, 'aimed_avg': 3, 'div': 687960000, 'smoothing': 'sqrt', 'weight_multiplier': 122}
2020-07-02 12:04:50,022 update_batch_delay: compression-work-queue       : 0.14,0.46  {'avg': 258, 'recent': 176, 'target': 1000, 'aim': 250, 'aimed_avg': 101, 'div': 1000, 'smoothing': 'logp', 'weight_multiplier': 508}
2020-07-02 12:04:50,023 update_batch_delay: damage-packet-queue-pixels   : 0.06,0.12  {'avg': 10262902, 'recent': 2436783, 'target': 1000, 'aim': 250, 'aimed_avg': 3, 'div': 687960000, 'smoothing': 'sqrt', 'weight_multiplier': 122}
2020-07-02 12:04:50,023 update_batch_delay: focus                        : 0.00,1.00  {'has_focus': True}
2020-07-02 12:04:50,023 update_batch_delay: delay=234 (last actual delay: 1340)
2020-07-02 12:04:50,023 update_quality() suspended=False, mmap=None, current=52, hint=-1, fixed=-1, encoding=auto, sequence=805
2020-07-02 12:04:50,024 get_target_quality: target=  0% (window  910x756 ) pctpixdamaged=190%, dpc=((1, 0), (2, 0), (3, 0), (4, 1292760), (5, 19296), (6, 0), (7, 0), (8, 0), (9, 0), (10, 0))
2020-07-02 12:04:50,024 update_quality() quality=51 (target=50) for wid=3, info={'compression-ratio': (120, 134), 'min-quality': 30, 'min-speed': 30, 'backlog': (0, 0, 687960, 0), 'limits': {'backlog': 100, 'bandwidth': 100, 'congestion': 100, 'batch': 93, 'latency': 10, 'boost': -6}}
2020-07-02 12:04:50,024 update_speed() suspended=False, mmap=False, current=30, hint=-1, fixed=-1, encoding=auto, sequence=805
2020-07-02 12:04:50,024 update_speed() speed=30 (target=30, max=30) for wid=3, info={'low-limit': 687960, 'max-speed': 30, 'min-speed': 30, 'factors': {'damage-latency-abs': 0, 'damage-latency-rel': 0, 'decoding-latency': 4, 'pixel-rate': 0}, 'limits': {'backlog': 100, 'damage-latency': 14, 'pixel-rate': 100, 'bandwidth-limit': 100, 'congestion': 100}}
2020-07-02 12:05:08,752 client   2 @38.460 server is not responding, drawing spinners over the windows
2020-07-02 12:05:08,944 packet decoding sequence 543 for window 3: 910x756 took 23.6ms
2020-07-02 12:05:08,944 may_recalculate(3, 687960) total 687960 pixels, scheduling recalculate work item
2020-07-02 12:05:08,946 calculate_batch_delay for wid=3 current batch delay=234, last update 18.9 seconds ago
2020-07-02 12:05:08,947 update_batch_delay: damage-network-delay         : 2.37,1.87  {'avg': 160, 'recent': 673}
2020-07-02 12:05:08,947 update_batch_delay: client-latency               : 5.17,2.72  {'avg': 504, 'recent': 3705, 'target': 30, 'aim': 800, 'aimed_avg': 26764, 'div': 1000, 'smoothing': 'sqrt', 'weight_multiplier': 1332}
2020-07-02 12:05:08,947 update_batch_delay: client-ping-latency          : 1.74,0.58  {'avg': 718, 'recent': 1105, 'target': 30, 'aim': 949, 'aimed_avg': 3026, 'div': 1000, 'smoothing': 'sqrt', 'weight_multiplier': 679}
2020-07-02 12:05:08,947 update_batch_delay: server-ping-latency          : 1.72,0.62  {'avg': 658, 'recent': 1074, 'target': 32, 'aim': 949, 'aimed_avg': 2952, 'div': 1000, 'smoothing': 'sqrt', 'weight_multiplier': 731}
2020-07-02 12:05:08,947 update_batch_delay: packet-queue-size            : 0.12,0.21  {'avg': 50, 'recent': 23, 'target': 1000, 'aim': 250, 'aimed_avg': 14, 'div': 1000, 'smoothing': 'sqrt', 'weight_multiplier': 225}
2020-07-02 12:05:08,948 update_batch_delay: packet-queue-pixels          : 0.09,0.13  {'avg': 12033762, 'recent': 5024040, 'target': 1000, 'aim': 250, 'aimed_avg': 7, 'div': 687960000, 'smoothing': 'sqrt', 'weight_multiplier': 132}
2020-07-02 12:05:08,948 update_batch_delay: compression-work-queue       : 0.05,0.47  {'avg': 236, 'recent': 56, 'target': 1000, 'aim': 250, 'aimed_avg': 32, 'div': 1000, 'smoothing': 'logp', 'weight_multiplier': 486}
2020-07-02 12:05:08,948 update_batch_delay: congestion                   : 1.02,0.21  {}
2020-07-02 12:05:08,948 update_batch_delay: damage-packet-queue-pixels   : 0.09,0.13  {'avg': 12033799, 'recent': 5024314, 'target': 1000, 'aim': 250, 'aimed_avg': 7, 'div': 687960000, 'smoothing': 'sqrt', 'weight_multiplier': 132}
2020-07-02 12:05:08,949 update_batch_delay: delay=362 (last actual delay: 50)
2020-07-02 12:05:08,949 update_quality() suspended=False, mmap=None, current=51, hint=-1, fixed=-1, encoding=auto, sequence=813
2020-07-02 12:05:08,949 get_client_backlog missing acks: []
2020-07-02 12:05:08,950 get_target_quality: target=  0% (window  910x756 ) pctpixdamaged=298%, dpc=((1, 0), (2, 595152), (3, 0), (4, 1461174), (5, 0), (6, 0), (7, 0), (8, 0), (9, 0), (10, 0))
2020-07-02 12:05:08,950 update_quality() quality=50 (target=50) for wid=3, info={'compression-ratio': (142, 150), 'min-quality': 30, 'min-speed': 30, 'backlog': (1, 687960, 687960, 100), 'limits': {'backlog': 67, 'bandwidth': 100, 'congestion': 78, 'batch': 60, 'latency': 4, 'boost': -3}}
2020-07-02 12:05:08,950 update_speed() suspended=False, mmap=False, current=30, hint=-1, fixed=-1, encoding=auto, sequence=813
2020-07-02 12:05:08,950 get_client_backlog missing acks: []
2020-07-02 12:05:08,950 update_speed() speed=32 (target=32, max=32) for wid=3, info={'low-limit': 687960, 'max-speed': 32, 'min-speed': 30, 'factors': {'damage-latency-abs': 0, 'damage-latency-rel': 0, 'decoding-latency': 3, 'pixel-rate': 0}, 'limits': {'backlog': 68, 'damage-latency': 32, 'pixel-rate': 100, 'bandwidth-limit': 100, 'congestion': 78}}
2020-07-02 12:05:08,997 client   2 @38.713 server is OK again
2020-07-02 12:05:11,398 packet decoding sequence 544 for window 3: 910x756 took 26.6ms
2020-07-02 12:05:11,398 may_recalculate(3, 687960) total 687960 pixels, scheduling recalculate work item
2020-07-02 12:05:11,400 calculate_batch_delay for wid=3 current batch delay=362, last update 2.5 seconds ago
2020-07-02 12:05:11,401 update_batch_delay: damage-network-delay         : 2.21,1.71  {'avg': 120, 'recent': 438}
2020-07-02 12:05:11,401 update_batch_delay: damage-rate                  : 0.00,1.67  {'elapsed': 3604, 'max_latency': 403}
2020-07-02 12:05:11,401 update_batch_delay: client-latency               : 6.29,3.07  {'avg': 873, 'recent': 6027, 'target': 30, 'aim': 800, 'aimed_avg': 39557, 'div': 1000, 'smoothing': 'sqrt', 'weight_multiplier': 1332}
2020-07-02 12:05:11,401 update_batch_delay: client-ping-latency          : 1.72,0.57  {'avg': 664, 'recent': 1034, 'target': 30, 'aim': 949, 'aimed_avg': 2943, 'div': 1000, 'smoothing': 'sqrt', 'weight_multiplier': 679}
2020-07-02 12:05:11,401 update_batch_delay: server-ping-latency          : 1.69,0.61  {'avg': 601, 'recent': 989, 'target': 32, 'aim': 949, 'aimed_avg': 2852, 'div': 1000, 'smoothing': 'sqrt', 'weight_multiplier': 731}
2020-07-02 12:05:11,402 update_batch_delay: packet-queue-size            : 0.14,0.21  {'avg': 51, 'recent': 33, 'target': 1000, 'aim': 250, 'aimed_avg': 20, 'div': 1000, 'smoothing': 'sqrt', 'weight_multiplier': 227}
2020-07-02 12:05:11,403 update_batch_delay: packet-queue-pixels          : 0.10,0.13  {'avg': 12339170, 'recent': 7189309, 'target': 1000, 'aim': 250, 'aimed_avg': 10, 'div': 687960000, 'smoothing': 'sqrt', 'weight_multiplier': 133}
2020-07-02 12:05:11,403 update_batch_delay: compression-work-queue       : 0.11,0.46  {'avg': 246, 'recent': 136, 'target': 1000, 'aim': 250, 'aimed_avg': 78, 'div': 1000, 'smoothing': 'logp', 'weight_multiplier': 496}
2020-07-02 12:05:11,405 update_batch_delay: congestion                   : 1.00,0.03  {}
2020-07-02 12:05:11,405 update_batch_delay: damage-packet-queue-pixels   : 0.10,0.13  {'avg': 12339193, 'recent': 7189452, 'target': 1000, 'aim': 250, 'aimed_avg': 10, 'div': 687960000, 'smoothing': 'sqrt', 'weight_multiplier': 133}
2020-07-02 12:05:11,405 update_batch_delay: delay=332 (last actual delay: 6177)
2020-07-02 12:05:11,406 update_quality() suspended=False, mmap=None, current=50, hint=-1, fixed=-1, encoding=auto, sequence=815
2020-07-02 12:05:11,407 get_target_quality: target=  0% (window  910x756 ) pctpixdamaged= 86%, dpc=((1, 0), (2, 0), (3, 0), (4, 595152), (5, 0), (6, 0), (7, 1461174), (8, 0), (9, 0), (10, 0))
2020-07-02 12:05:11,410 update_quality() quality=50 (target=50) for wid=3, info={'compression-ratio': (140, 149), 'min-quality': 30, 'min-speed': 30, 'backlog': (0, 0, 687960, 0), 'limits': {'backlog': 100, 'bandwidth': 100, 'congestion': 96, 'batch': 65, 'latency': 3, 'boost': -3}}
2020-07-02 12:05:11,410 update_speed() suspended=False, mmap=False, current=32, hint=-1, fixed=-1, encoding=auto, sequence=815
2020-07-02 12:05:11,410 get_client_backlog missing acks: []
2020-07-02 12:05:11,411 update_speed() speed=30 (target=30, max=30) for wid=3, info={'low-limit': 687960, 'max-speed': 30, 'min-speed': 30, 'factors': {'damage-latency-abs': 0, 'damage-latency-rel': 0, 'decoding-latency': 3, 'pixel-rate': 0}, 'limits': {'backlog': 100, 'damage-latency': 2, 'pixel-rate': 100, 'bandwidth-limit': 100, 'congestion': 96}}

At this point I stopped the logging because I wasn't sure if the connection was likely to survive much longer, with repeated appearance of spinners, and obviously scrolling the gedit window wasn't having any success.

Changed 5 months ago by alas

Some more logs - from congested network to less-congested

comment:3 Changed 5 months ago by alas

Attached a txt file with some more logs, this time watching behavior as the network congestion is "lifted", to see more about what the session does to try to compensate (as user continues to try to scroll a gedit window).

comment:4 Changed 2 weeks ago by Antoine Martin

Milestone: 4.14.2

I'm hoping we can do something with #2421, maybe for 4.2

Note: See TracTickets for help on using tickets.