Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

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

Closed
totaam opened this issue Jun 19, 2020 · 10 comments
Closed

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

totaam opened this issue Jun 19, 2020 · 10 comments
Labels
v4.0.x

Comments

@totaam
Copy link
Collaborator

totaam commented Jun 19, 2020

Issue migrated from trac ticket # 2812

component: network | priority: major | resolution: worksforme

2020-06-19 03:35:37: afarr created the issue

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?
@totaam
Copy link
Collaborator Author

totaam commented Jun 29, 2020

2020-06-29 07:04:05: antoine commented

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.

@totaam
Copy link
Collaborator Author

totaam commented Jul 2, 2020

2020-07-02 20:55:12: afarr commented

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.

@totaam
Copy link
Collaborator Author

totaam commented Jul 2, 2020

2020-07-02 21:39:20: afarr uploaded file ticket2812_server-logs_-d-stats_for recovery.txt (190.0 KiB)

Some more logs - from congested network to less-congested

@totaam
Copy link
Collaborator Author

totaam commented Jul 2, 2020

2020-07-02 21:40:58: afarr commented

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

@totaam
Copy link
Collaborator Author

totaam commented Dec 10, 2020 •
edited
Loading

I can reproduce problems by starting a connection, then introducing extra latency with tc, then removing the latency: the performance should go back to what it was before, but it doesn't.

ie, from #999:

  • add latency:
tc qdisc add dev eth1 root netem delay 100ms 50ms 25%
  • removing it:
tc qdisc del dev eth1 root netem

If the rule is already present when the client connects, then there is no problem and the performance is very good.

It seems that we underestimate the bandwidth limit, then a single screen update takes us over the quota:

14:52:33,643 may_send_delayed() wid=  2 : bandwidth limit=1187126, used=0 : 0%
14:52:33,664 may_send_delayed() wid=  2 : bandwidth limit=1187126, used=12464789 : 1049%

Then we just throttle too much.

With --bandwidth-detection=no, the problem is less severe and recovery is quick once the limit is removed, but the performance could still be better.

When things are going well - testing with glxgears, I see (summary):

batch delay=8, last actual=16
update_quality() quality=78 (target=80)
update_speed() speed=44 (target=52, max=100)
do_damage: batching expiry in 8ms
compress: 1.6ms for 300x300 pixels at 0,0 for wid=2 using h264...
packet decoding: 300x300 took 2.0ms

So, that's doing 60fps video, which is decoded super-fast, so we are hitting vsync.

Then when I add the delay with tc, we detect the change in latency pretty quickly:

update_batch_delay: client-latency               : 3.22,0.59  {'avg': 56, 'recent': 335, 'target': 6, 'aim': 800, 'aimed_avg': 10336, 'div': 1000, 'smoothing': 'sqrt', 'weight_multiplier': 393}
..
update_batch_delay: client-latency               : 4.03,0.68  {'avg': 568, 'recent': 847, 'target': 6, 'aim': 800, 'aimed_avg': 16254, 'div': 1000, 'smoothing': 'sqrt', 'weight_multiplier': 392}

And things adapt:

  • the batch delay goes up, though maybe not as quickly as it should? no very important since we wait for acks to send more updates: the actual batch delay should rise more quickly as needed:
update_batch_delay: delay=38 (last actual delay: 16)
  • the quality drops:
update_quality() quality=30 (target=19) for wid=2, info={'compression-ratio': (44, 50), 'min-quality': 30, 'min-speed': 30, 'backlog': (2, 180000, 90000, 200), 'limits': {'backlog': 41, 'bandwidth': 89400, 'congestion': 100, 'batch': 341, 'latency': 21, 'boost': -4}}

One of the problems is that the batch delay keeps going up because the minimum latency value which drives the heuristics becomes a complete outlier.
We should use the latency hint as a safety net, not a deciding factor.

@totaam
Copy link
Collaborator Author

totaam commented Dec 20, 2020 •
edited
Loading

OK, got a handle on the bursty behaviour, we wait for pending acks longer and longer and then:

send_delayed for wid 2, sequence 23207, delaying again because of backlog:
 batch delay is 25, elapsed time is 596ms
 2 packets
(..)
send_delayed for wid 2, batch delay is 25ms, elapsed time is 534ms
22:54:41,040 process_damage_region: wid=2, sequence=23229, adding pixel data to encode queue ( 300x300  -  auto), elapsed time: 535.5 ms, request time: 0.5 ms, frame delay=0ms
22:54:41,067 process_damage_region: wid=2, sequence=23231, adding pixel data to encode queue ( 300x300  -  auto), elapsed time: 26.6 ms, request time: 0.3 ms, frame delay=0ms
22:54:41,073 process_damage_region: wid=2, sequence=23233, adding pixel data to encode queue ( 300x300  -  auto), elapsed time: 3.8 ms, request time: 0.3 ms, frame delay=0ms
22:54:41,079 process_damage_region: wid=2, sequence=23235, adding pixel data to encode queue ( 300x300  -  auto), elapsed time: 5.0 ms, request time: 0.7 ms, frame delay=0ms

That's 4 frames in just 40ms because the batch delay is actually very low before we start waiting, and then immediately after sending those 4 frames we start waiting again:

send_delayed for wid 2, sequence 23235, delaying again because of backlog:
 batch delay is 25, elapsed time is 0ms
 1 packets
(..)
send_delayed for wid 2, sequence 23263, delaying again because of backlog:
 batch delay is 36, elapsed time is 209ms
 1 packets

The latency is now so much higher that almost as soon as we send a packet then it registers as backlogged.
With r28208:

get_packets_backlog(100)=3 (sent less than 44ms ago, target latency=24)

(that's with 50-100ms delay added each way!)

We need to:

  • calculate the backlog better: don't use the absolute minimum latency as reference, more jitter tolerance and take into account the client's jitter value (derived from the adapter type)
  • following a long wait we should not immediately restart sending at the same rate as before, but only gradually faster from the last delay

@totaam
Copy link
Collaborator Author

totaam commented Dec 21, 2020 •
edited
Loading

Difficulty: increasing the target latency improves things when there's jitter but it also makes latency issues harder to spot and the speed / quality / batch delay are not adjusted as quickly.

Some updates:

  • debugging tweaks: r28209, r28215, r28217, r28208
  • better network adapter type detection for Linux: r28210 + r28212
  • expose client adapter type: r28211
  • latency / jitter changes: r28213, r28214
  • honour expire delay bug fixes: r28216, r28218, r28219, r28221
  • more dynamic batch delay: r28222
  • optimization was never firing: r28223
  • make it easier to tweak settings: r28226, ie: xpra attach "tcp://192.168.0.10:10000/?socket.nodelay=1&socket.jitter=99&socket.adapter-type=wan&socket.speed=8Mbps"

@totaam
Copy link
Collaborator Author

totaam commented Dec 22, 2020 •
edited
Loading

2020-12-22 18:33:19: antoine commented

With the fixes in comment:9 and now also:

  • r28227 minor optimization
  • r28228 honour XPRA_ACK_JITTER and only apply the latency tolerance percentage to that
  • r28229 bump default XPRA_ACK_JITTER to 100ms

With all those fixes accumulated, I am able to run glxgears at only slighly lower fps / quality, despite the roundtrip increasing from 40ms to 150ms!

@afarr / @stdedos: sorry it's taken so long.. I've made beta builds you can try, most distros and most branches are covered. (more coming later)
I would appreciate any feedback you may have.
This is the only ticket holding up releases for all active branches.
This solution is not perfect and I do intend to try to improve it later, but I have to stop at some point.

@totaam
Copy link
Collaborator Author

totaam commented Dec 23, 2020

2020-12-23 00:07:00: stdedos commented

Antoine, I am very glad you managed to fix it / found a way to accurately replicate this. It doesn't matter the least bit to me that "it took you so long" :-D

Sadly, I am almost positive that I will not able to test this right now, and for quite some time :/
Hopefully @alas is able to do such testing for a pre-!Christmas/New Year release.

Of course, if the release manager started talking in me ... he'd say it's a bit dangerous to go with a release on !Christmas/New Year anyway, unless you are so confident in it.

@totaam
Copy link
Collaborator Author

totaam commented Jan 13, 2021 •
edited
Loading

This will do for v4.1, will follow up in #3001

@totaam totaam closed this as completed Jan 13, 2021
@totaam totaam added the v4.0.x label Jan 22, 2021
This was referenced Jan 22, 2021
Closed
Closed
@totaam totaam mentioned this issue Mar 24, 2021
Open
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
v4.0.x
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
1 participant
@totaam