1.0 r14155 osx client and 1.0 r14282 fedora 23 server.
While playing video (html5 and flash, in case that might make a difference) I'm regularly seeing an avcodec error (starts usually within 1-2 minutes of the video starting (though it sometimes feels like 5 long minutes).
Client-side:
2016-10-25 17:15:30,108 Error: avcodec error -35 decoding 7928 bytes of h264 data: 2016-10-25 17:15:30,109 'Resource temporarily unavailable' 2016-10-25 17:15:30,109 frame 0 2016-10-25 17:15:30,109 options={'pts': 0, 'encoding': 'h264', 'type': 'IDR', 'frame': 0, 'delayed': 1, 'csc': 'YUV420P', 'paint': False, 'flush': 0, 'quality': 60, 'speed': 73} 2016-10-25 17:15:30,110 decoder state: 2016-10-25 17:15:30,110 decoder_height = 360 2016-10-25 17:15:30,110 encoding = h264 2016-10-25 17:15:30,110 colorspace = YUV420P 2016-10-25 17:15:30,110 actual_colorspace = YUV420P 2016-10-25 17:15:30,111 height = 360 2016-10-25 17:15:30,111 decoder_width = 640 2016-10-25 17:15:30,111 width = 640 2016-10-25 17:15:30,112 version = (57, 48, 101) 2016-10-25 17:15:30,112 formats = ['YUV422P', 'BGRX', 'GBRP', 'RGB', 'YUV420P', 'BGRA', 'ARGB', 'XRGB', 'YUV444P'] 2016-10-25 17:15:30,114 frames = 0 2016-10-25 17:15:30,114 type = avcodec
Testing for #1135, with -d stats,x264,compress
on the server, I think I've spotted the cause of this being the initialization of an x264 context encoding YUV420P frames (or it's just a coincidence?).
Doing a short test, I see two x264 contexts initialized, one encoding BGRX frames, the other YUV420P. Immediately after the intitialization of the YUV 420P context, I see the above error.
2016-10-25 18:02:49,513 x264 close context 0x7fbd700671c0 2016-10-25 18:02:49,530 x264 close context 0x0 2016-10-25 18:02:49,531 using default profile=high444 2016-10-25 18:02:49,539 x264 context=0x7fbd700671c0, BGRX 768x432 quality=59, speed=94, source=unknown 2016-10-25 18:02:49,539 preset=superfast, profile=high444, tune=zerolatency 2016-10-25 18:02:49,540 me=DIA, me_range=16, mv_range=-1, b-frames=0, max delayed frames=0 2016-10-25 18:02:49,540 vfr-input=0, lookahead=-1, sync-lookahead=0, mb-tree=0, bframe-adaptive=FAST 2016-10-25 18:02:49,540 threads=auto, sliced-threads=True 2016-10-25 18:02:49,553 x264 encode BGRX frame 0 as IDR slice with 7 nals, tune=zerolatency, total 50431 bytes, keyframe=True , delayed=0 2016-10-25 18:02:49,554 compress: 23.3ms for 768x432 pixels at 69,320 for wid=3 using h264 with ratio 3.8% ( 1296KB to 49KB), client_options={'pts': 0, 'frame': 0L, 'flush': 0, 'csc': 'YUV444P', 'type': 'IDR', 'quality': 59, 'speed': 94} 2016-10-25 18:02:49,561 client 1: process_draw: 50431 bytes for window 3 using h264 encoding with options={'speed': 94, 'type': 'IDR', 'flush': 0, 'pts': 0, 'frame': 0, 'quality': 59, 'csc': 'YUV444P'} 2016-10-25 18:02:49,574 packet decoding sequence 690 for window 3: 768x432 took 13.4ms 2016-10-25 18:02:49,575 record_latency: took 20.6 ms round trip, 20.4 for echo, 13.0 for decoding of 331776 pixels, 50530 bytes sent over the network in 7.2 ms, 7.1 ms for echo 2016-10-25 18:02:49,575 may_recalculate(3, 331776) total 331776 pixels, scheduling recalculate work item ... 2016-10-25 18:02:50,554 x264 close context 0x0 2016-10-25 18:02:50,565 x264 context=0x7fbd700671c0, YUV420P 768x432 quality=55, speed=94, source=video 2016-10-25 18:02:50,566 preset=superfast, profile=high10, tune=film 2016-10-25 18:02:50,566 me=DIA, me_range=16, mv_range=-1, b-frames=1, max delayed frames=1 2016-10-25 18:02:50,566 vfr-input=0, lookahead=0, sync-lookahead=-1, mb-tree=0, bframe-adaptive=FAST 2016-10-25 18:02:50,566 threads=auto, sliced-threads=True 2016-10-25 18:02:50,573 x264 encode 1 delayed frames after 0 2016-10-25 18:02:50,579 compress: 24.3ms for 768x432 pixels at 69,320 for wid=3 using jpeg with ratio 4.8% ( 1296KB to 61KB), client_options={'quality': 95, 'flush': 0} 2016-10-25 18:02:50,588 client 1: process_draw: 63444 bytes for window 3 using jpeg encoding with options={'quality': 95, 'flush': 0} 2016-10-25 18:02:50,595 packet decoding sequence 713 for window 3: 768x432 took 7.0ms 2016-10-25 18:02:50,596 record_latency: took 16.6 ms round trip, 16.5 for echo, 6.0 for decoding of 331776 pixels, 63502 bytes sent over the network in 9.6 ms, 9.5 ms for echo 2016-10-25 18:02:50,614 x264 encode YUV420P frame 0 as IDR slice with 7 nals, tune=film, total 23083 bytes, keyframe=True , delayed=1 2016-10-25 18:02:50,615 compress: 13.6ms for 768x432 pixels at 69,320 for wid=3 using h264 with ratio 1.7% ( 1296KB to 22KB), client_options={'pts': 0, 'frame': 0L, 'flush': 0, 'delayed': 1, 'csc': 'YUV420P', 'paint': False, 'type': 'IDR', 'quality': 55, 'speed': 94} 2016-10-25 18:02:50,625 client 1: process_draw: 23083 bytes for window 3 using h264 encoding with options={'pts': 0, 'type': 'IDR', 'frame': 0, 'delayed': 1, 'csc': 'YUV420P', 'paint': False, 'flush': 0, 'quality': 55, 'speed': 94} 2016-10-25 18:02:50,627 client 1: Error: avcodec error -35 decoding 23083 bytes of h264 data: 2016-10-25 18:02:50,627 client 1: 'Resource temporarily unavailable' 2016-10-25 18:02:50,628 client 1: frame 0 2016-10-25 18:02:50,629 client 1: options={'pts': 0, 'encoding': 'h264', 'type': 'IDR', 'frame': 0, 'delayed': 1, 'csc': 'YUV420P', 'paint': False, 'flush': 0, 'quality': 55, 'speed': 94} 2016-10-25 18:02:50,629 client 1: decoder state: 2016-10-25 18:02:50,629 client 1: decoder_height = 432 2016-10-25 18:02:50,630 client 1: encoding = h264 2016-10-25 18:02:50,630 client 1: colorspace = YUV420P 2016-10-25 18:02:50,631 client 1: actual_colorspace = YUV420P 2016-10-25 18:02:50,632 client 1: height = 432 2016-10-25 18:02:50,633 client 1: decoder_width = 768 2016-10-25 18:02:50,633 packet decoding sequence 714 for window 3: 768x432 took 11.1ms 2016-10-25 18:02:50,634 record_latency: took 18.7 ms round trip, 18.6 for echo, 11.0 for decoding of 331776 pixels, 23198 bytes sent over the network in 7.6 ms, 7.5 ms for echo 2016-10-25 18:02:50,634 client 1: width = 768 2016-10-25 18:02:50,635 client 1: version = (57, 48, 101) 2016-10-25 18:02:50,635 client 1: formats = ['YUV422P', 'BGRX', 'GBRP', 'RGB', 'YUV420P', 'BGRA', 'ARGB', 'XRGB', 'YUV444P'] 2016-10-25 18:02:50,636 client 1: frames = 0 2016-10-25 18:02:50,636 client 1: type = avcodec 2016-10-25 18:02:50,667 x264 encode YUV420P frame 1 as P slice with 4 nals, tune=film, total 4626 bytes, keyframe=False, delayed=1
I don't suppose there's much point in posting this to #1135 though.
I'm not sure what's happening here, I cannot reproduce it.
The YUV420P context replaces the BGRX one when the heuristics have decided that this is "real video" and therefore should be encoded as such. (#800, #1135)
I suspect that the problem may well go away if you run with XPRA_B_FRAMES=0
.
It could be related to the client's capabilities, in particular how many CPU / threads are available.
Does it help if you run the server with: XPRA_X264_THREADS=1
and XPRA_X264_SLICED_THREADS=0
? (and keeping b-frames enabled)
The short answer is no. Nothing seems to be making a difference. Maybe it's just my client?
I tried with XPRA_B_FRAMES=0
, with XPRA_X264_THREADS=1
and XPRA_X264_SLICED_THREADS=0
, with and without forcing opengl, with video, and with just scrolling text. In every case, it looks like I'm seeing this issue corresponding with an x264 context being created with tune=film
.
In the case of trying with XPRA_X264_THREADS=1
and XPRA_X264_SLICED_THREADS=0
, I'm also seeing a new error... which is far more regular than this avcodec error, but does still coexist.
2016-10-26 13:51:12,719 error processing encode queue at index 0 2016-10-26 13:51:12,719 item=(1310, 777, 1477515072.592879, 1477515072.690525, XShmImageWrapper(BGRX: 0, 0, 1310, 777), 'auto', 47, {}, 0) Traceback (most recent call last): File "/usr/lib64/python2.7/site-packages/xpra/server/window/window_video_source.py", line 823, in encode_from_queue self.make_data_packet_cb(*item) File "/usr/lib64/python2.7/site-packages/xpra/server/window/window_source.py", line 1448, in make_data_packet_cb packet = self.make_data_packet(damage_time, process_damage_time, image, coding, sequence, options, flush) File "/usr/lib64/python2.7/site-packages/xpra/server/window/window_source.py", line 1794, in make_data_packet ret = encoder(coding, image, options) File "/usr/lib64/python2.7/site-packages/xpra/server/window/window_video_source.py", line 1467, in video_encode return self.do_video_encode(encoding, image, options) File "/usr/lib64/python2.7/site-packages/xpra/server/window/window_video_source.py", line 1568, in do_video_encode ret = ve.compress_image(csc_image, quality, speed, options) File "xpra/codecs/enc_x264/encoder.pyx", line 717, in xpra.codecs.enc_x264.encoder.Encoder.compress_image (xpra/codecs/enc_x264/encoder.c:7846) File "xpra/codecs/enc_x264/encoder.pyx", line 750, in xpra.codecs.enc_x264.encoder.Encoder.do_compress_image (xpra/codecs/enc_x264/encoder.c:8408) Exception: x264_encoder_encode produced no data! 2016-10-26 13:51:55,572 client 1: UI thread is now blocked 2016-10-26 13:51:55,576 client 1: UI thread is running again, resuming 2016-10-26 13:51:55,729 Error during encoding: Traceback (most recent call last): File "/usr/lib64/python2.7/site-packages/xpra/server/source.py", line 2185, in encode_loop fn_and_args[1](*fn_and_args[2:]) File "/usr/lib64/python2.7/site-packages/xpra/server/window/window_source.py", line 1448, in make_data_packet_cb packet = self.make_data_packet(damage_time, process_damage_time, image, coding, sequence, options, flush) File "/usr/lib64/python2.7/site-packages/xpra/server/window/window_source.py", line 1794, in make_data_packet ret = encoder(coding, image, options) File "/usr/lib64/python2.7/site-packages/xpra/server/window/window_video_source.py", line 1467, in video_encode return self.do_video_encode(encoding, image, options) File "/usr/lib64/python2.7/site-packages/xpra/server/window/window_video_source.py", line 1568, in do_video_encode ret = ve.compress_image(csc_image, quality, speed, options) File "xpra/codecs/enc_x264/encoder.pyx", line 717, in xpra.codecs.enc_x264.encoder.Encoder.compress_image (xpra/codecs/enc_x264/encoder.c:7846) File "xpra/codecs/enc_x264/encoder.pyx", line 750, in xpra.codecs.enc_x264.encoder.Encoder.do_compress_image (xpra/codecs/enc_x264/encoder.c:8408) Exception: x264_encoder_encode produced no data!
I can attach some clips of logs but the short bit is that it looks like whenever the x264 is tune=zerolatency
I'm not seeing the avcodec error, whether it is YUV444, YUV420, or BGRX, but when I triggered tune=film
(just by pasting a pile of logs into a gedit window and then scrolling a lot), then I see the error logs:
2016-10-26 16:18:00,837 x264 context=0x7f3d98015e80, YUV420P 762x460 quality=44, speed=74, source=video 2016-10-26 16:18:00,837 preset=faster, profile=high10, tune=film 2016-10-26 16:18:00,838 me=HEX, me_range=16, mv_range=-1, b-frames=1, max delayed frames=1 2016-10-26 16:18:00,838 vfr-input=0, lookahead=0, sync-lookahead=-1, mb-tree=1, bframe-adaptive=FAST 2016-10-26 16:18:00,839 threads=auto, sliced-threads=True 2016-10-26 16:18:00,849 x264 encode 1 delayed frames after 0 2016-10-26 16:18:00,862 compress: 36.2ms for 1145x690 pixels at 5,5 for wid=3 using jpeg with ratio 6.9% ( 3086KB to 211KB), client_options={'quality': 84, 'flush': 0} 2016-10-26 16:18:00,912 x264 encode YUV420P frame 0 as IDR slice with 7 nals, tune=film, total 33747 bytes, keyframe=True , delayed=1 2016-10-26 16:18:00,913 compress: 22.5ms for 1144x690 pixels at 5,5 for wid=3 using h264 with ratio 1.1% ( 3086KB to 32KB), client_options={'scaled_size': (762, 460), 'pts': 0, 'frame': 0L, 'flush': 0, 'delayed': 1, 'csc': 'YUV420P', 'paint': False, 'type': 'IDR', 'quality': 44, 'speed': 74} 2016-10-26 16:18:00,919 packet decoding sequence 230 for window 3: 1145x690 took 21.4ms 2016-10-26 16:18:00,920 record_latency: took 54.9 ms round trip, 54.7 for echo, 21.0 for decoding of 790050 pixels, 216985 bytes sent over the network in 33.5 ms, 33.4 ms for echo 2016-10-26 16:18:00,920 may_recalculate(3, 790050) total 790050 pixels, scheduling recalculate work item 2016-10-26 16:18:00,928 client 1: Error: avcodec error -35 decoding 33747 bytes of h264 data: 2016-10-26 16:18:00,928 client 1: 'Resource temporarily unavailable' 2016-10-26 16:18:00,928 client 1: frame 0 2016-10-26 16:18:00,929 client 1: options={'pts': 0, 'scaled_size': (762, 460), 'type': 'IDR', 'frame': 0, 'encoding': 'h264', 'delayed': 1, 'csc': 'YUV420P', 'paint': False, 'flush': 0, 'quality': 44, 'speed': 74} 2016-10-26 16:18:00,931 client 1: decoder state: 2016-10-26 16:18:00,931 client 1: decoder_height = 460 2016-10-26 16:18:00,932 packet decoding sequence 231 for window 3: 1144x690 took 9.7ms 2016-10-26 16:18:00,932 record_latency: took 17.7 ms round trip, 17.6 for echo, 9.0 for decoding of 789360 pixels, 33878 bytes sent over the network in 8.1 ms, 8.0 ms for echo 2016-10-26 16:18:00,932 client 1: encoding = h264 2016-10-26 16:18:00,933 client 1: colorspace = YUV420P 2016-10-26 16:18:00,933 client 1: actual_colorspace = YUV420P 2016-10-26 16:18:00,933 client 1: height = 460 2016-10-26 16:18:00,934 client 1: decoder_width = 762 2016-10-26 16:18:00,934 client 1: width = 762 2016-10-26 16:18:00,934 client 1: version = (57, 48, 101) 2016-10-26 16:18:00,935 client 1: formats = ['YUV422P', 'BGRX', 'GBRP', 'RGB', 'YUV420P', 'BGRA', 'ARGB', 'XRGB', 'YUV444P'] 2016-10-26 16:18:00,935 client 1: frames = 0 2016-10-26 16:18:00,935 client 1: type = avcodec
I think I can reproduce it, but not very reliably.
Adding better debug logging in r14295 + r14296 and running the server with "-d compress,x264" the client with "-d avcodec", it seems that we're cleaning the video context before the last frame is received:
compress: 16.3ms for 1236x612 pixels at 5,53 for wid=2 using h264 with ratio 1.2% ( 2957KB to 36KB), sequence= 2372, client_options=\ {'pts': 1896, 'frame': 33L, 'flush': 0, 'csc': 'YUV420P', 'scaled_size': (824, 408), 'type': 'P', 'quality': 87, 'speed': 86} compress: 41.4ms for 1236x612 pixels at 5,53 for wid=2 using h264 with ratio 1.1% ( 2957KB to 33KB), sequence= 2373, client_options=\ {'pts': 1937, 'frame': 34L, 'flush': 0, 'csc': 'YUV420P', 'type': 'P', 'quality': 86, 'speed': 86} setup_pipeline: trying (82, (1, 3), (1, 3), 1236, 612, video_spec(libyuv), 'YUV420P', (1, 1), 412, 204, video_spec(x264))
decompress_image(<type 'str'>:37088, \ {'pts': 1896, 'encoding': 'h264', 'type': 'P', 'frame': 33, 'csc': 'YUV420P', \ 'scaled_size': (824, 408), 'flush': 0, 'quality': 87, 'speed': 86} )=AVImageWrapper-AVFrameWrapper(0x7fc844006e00)(YUV420P:(0, 0, 824, 408, 24):3_PLANES) (..) clean_decoder() freeing AVCodecContext: 0x7fc844001b00 (..) Error: avcodec error -1094995529 decoding 33842 bytes of h264 data: (..) frame options={'speed': 86, 'type': 'P', 'flush': 0, 'pts': 1937, 'frame': 34, 'encoding': 'h264', 'quality': 86, 'csc': 'YUV420P'}
Frame 34 should have been decoded with the same context as 33.
The bad news is that I have no idea why this happens. The good news is that the decoder just drops this "corrupt" frame and carries on.
Logging the client with "-d paint,-opengl", I can see:
draw_region(5, 53, 1236, 612, h264, 43416 bytes, 0, \ {'pts': 939, 'type': 'P', 'frame': 45, 'delayed': 1, 'csc': 'YUV420P', \ 'scaled_size': (824, 408), 'flush': 0, 'quality': 93, 'speed': 78}, \ [<function record_decode_time at 0x7fcaaf1cf050>, <function after_draw_refresh at 0x7fcaac24db90>]) paint_with_video_decoder: window dimensions have changed from (824, 408) to (1236, 612) draw_region(5, 53, 1236, 612, h264, 35868 bytes, 0, \ {'type': 'B', 'pts': 922, 'frame': 46, 'delayed': 1, 'csc': 'YUV420P', \ 'flush': 0, 'quality': 93, 'speed': 78}, \ [<function record_decode_time at 0x7fcaaf1cf050>, <function after_draw_refresh at 0x7fcaac24db90>])
Just before the error, we are changing from scaled to unscaled video and so the client will re-create the context for the new dimensions received. After a lot of digging, I fixed the following issues and I seem to be unable to reproduce the problem anymore:
The problem is that these bugs are quite hard to trigger as they require very specific circumstances to fire, so I am not 100% sure that this fixed in all cases.
If you still see the Exception: x264_encoder_encode produced no data
bug with XPRA_X264_THREADS=1
and XPRA_X264_SLICED_THREADS=0
, please file a separate ticket for that - I'm not seeing this one at all. (but then again, I'm notoriously bad at reproducing bugs..)
The error message should be improved for that one too now.
It is a lot harder to induce testing with 1.0 r14304 fedora 23 server, but ... just as I was about to give up on it... I found it again (with either 1.0 r13977 or r14155 osx clients).
I'm not seeing the 'scaled_size' window dimensions changing issues you mentioned (which suggests that was probably causing most of those previously ubiquitous errors, and is fixed), but I do notice in the cases I spotted, the errors followed closely after a paint_with_video_decoder: colorspace changed from YUV444P to YUV420P
message (perhaps more than coincidence?).
With the r13977 client (not that it probably matters what client, but I saw it with both, so its two samples of logs to compare)... running with -d stat,compress,x264
server side and -d paint,opengl
client side (which seem to be getting passed through to the server, so I'll just paste server log bits). ... Note, to repro I just start some video and then mouse around & maybe scroll up and down for a minute or two... maybe three... and watch for red in the log output.
2016-11-01 17:12:12,593 x264 encode YUV420P frame 0 as IDR slice with 7 nals, tune=film, total 6905 bytes, keyframe=True , delayed=1 2016-11-01 17:12:12,594 compress: 22.0ms for 854x480 pixels at 146,150 for wid=3 using h264 with ratio 0.4% ( 1601KB to 6KB), sequence 220, client_options={'pts': 0, 'frame': 0, 'delayed': 1, 'csc': 'YUV420P', 'paint': False, 'type': 'IDR', 'quality': 42, 'speed': 81} 2016-11-01 17:12:12,641 client 4: process_draw 6905 bytes for window 3 using h264 encoding with options={'pts': 0, 'type': 'IDR', 'frame': 0, 'delayed': 1, 'csc': 'YUV420P', 'paint': False, 'quality': 42, 'speed': 81} 2016-11-01 17:12:12,642 client 4: draw_region(146, 150, 854, 480, h264, 6905 bytes, 0, {'pts': 0, 'type': 'IDR', 'frame': 0, 'delayed': 1, 'csc': 'YUV420P', 'paint': False, 'quality': 42, 'speed': 81}, [<function record_decode_time at 0x116dfef0>, <function after_draw_refresh at 0x116dfe70>]) 2016-11-01 17:12:12,642 client 4: paint_with_video_decoder: colorspace changed from YUV444P to YUV420P 2016-11-01 17:12:12,642 client 4: paint_with_video_decoder: new <type 'xpra.codecs.dec_avcodec2.decoder.Decoder'>(854,480,YUV420P) 2016-11-01 17:12:12,646 client 4: paint_with_video_decoder: info={'decoder_height': 480, 'encoding': 'h264', 'colorspace': 'YUV420P', 'actual_colorspace': 'YUV420P', 'height': 480, 'decoder_width': 854, 'width': 854, 'version': (57, 48, 101), 'formats': ['YUV422P', 'BGRX', 'GBRP', 'RGB', 'YUV420P', 'BGRA', 'ARGB', 'XRGB', 'YUV444P'], 'frames': 0L, 'type': 'avcodec'} 2016-11-01 17:12:12,647 client 4: Error: avcodec error -35 decoding 6905 bytes of h264 data: 2016-11-01 17:12:12,647 client 4: 'Resource temporarily unavailable' 2016-11-01 17:12:12,647 client 4: frame 0 2016-11-01 17:12:12,648 client 4: options={'pts': 0, 'encoding': 'h264', 'type': 'IDR', 'frame': 0, 'delayed': 1, 'csc': 'YUV420P', 'paint': False, 'quality': 42, 'speed': 81} 2016-11-01 17:12:12,649 client 4: decoder state: 2016-11-01 17:12:12,649 client 4: decoder_height = 480 2016-11-01 17:12:12,650 client 4: encoding = h264 2016-11-01 17:12:12,650 client 4: colorspace = YUV420P 2016-11-01 17:12:12,650 packet decoding sequence 220 for window 3: 854x480 took 8.4ms 2016-11-01 17:12:12,650 record_latency: took 55.4 ms round trip, 55.3 for echo, 8.0 for decoding of 409920 pixels, 7013 bytes sent over the network in 46.9 ms, 46.8 ms for echo 2016-11-01 17:12:12,651 client 4: actual_colorspace = YUV420P 2016-11-01 17:12:12,651 client 4: height = 480 2016-11-01 17:12:12,651 client 4: decoder_width = 854 2016-11-01 17:12:12,651 client 4: width = 854 2016-11-01 17:12:12,651 client 4: version = (57, 48, 101) 2016-11-01 17:12:12,652 client 4: formats = ['YUV422P', 'BGRX', 'GBRP', 'RGB', 'YUV420P', 'BGRA', 'ARGB', 'XRGB', 'YUV444P'] 2016-11-01 17:12:12,652 client 4: frames = 0 2016-11-01 17:12:12,653 client 4: type = avcodec 2016-11-01 17:12:12,653 client 4: record_decode_time(True, ) wid=3, h264: 854x480, 8.4ms 2016-11-01 17:12:12,653 client 4: after_draw_refresh(True, ) 854x480 at 146x150 encoding=h264, options={'pts': 0, 'encoding': 'h264', 'type': 'IDR', 'frame': 0, 'delayed': 1, 'csc': 'YUV420P', 'paint': False, 'quality': 42, 'speed': 81} 2016-11-01 17:12:12,662 x264 encode YUV420P frame 1 as P slice with 4 nals, tune=film, total 1206 bytes, keyframe=False, delayed=1 2016-11-01 17:12:12,662 compress: 16.1ms for 854x480 pixels at 146,150 for wid=3 using h264 with ratio 0.1% ( 1601KB to 1KB), sequence 221, client_options={'pts': 144, 'frame': 1, 'delayed': 1, 'csc': 'YUV420P', 'type': 'P', 'quality': 42, 'speed': 81} 2016-11-01 17:12:12,700 client 4: process_draw 1206 bytes for window 3 using h264 encoding with options={'speed': 81, 'type': 'P', 'pts': 144, 'frame': 1, 'quality': 42, 'delayed': 1, 'csc': 'YUV420P'} 2016-11-01 17:12:12,702 client 4: draw_region(146, 150, 854, 480, h264, 1206 bytes, 0, {'speed': 81, 'type': 'P', 'pts': 144, 'frame': 1, 'quality': 42, 'delayed': 1, 'csc': 'YUV420P'}, [<function record_decode_time at 0x116dfef0>, <function after_draw_refresh at 0x116dfe70>]) 2016-11-01 17:12:12,703 client 4: gl_paint_planar(0, 'h264', AVImageWrapper-None(YUV420P:(0, 0, 854, 480, 24):3_PLANES), 146, 150, 854, 480, 854, 480, [<function record_decode_time at 0x116dfef0>, <function after_draw_refresh at 0x116dfe70>]) 2016-11-01 17:12:12,703 client 4: gtk2.GLWindowBacking(3, (1587, 749), GBRP).gl_context() GL Pixmap backing size: 1587 x 749, context=gtk2.GLContextManager(<gtk.DrawingArea object at 0x9f444b8 (GtkDrawingArea at 0x41b2bd8)>) 2016-11-01 17:12:12,705 client 4: gtk2.GLWindowBacking(3, (1587, 749), GBRP).update_planar_textures(146, 150, 854, 480, AVImageWrapper-None(YUV420P:(0, 0, 854, 480, 24):3_PLANES), 'YUV420P') 2016-11-01 17:12:12,705 client 4: Creating new planar textures, pixel format YUV420P 2016-11-01 17:12:12,706 client 4: updating planar textures: 854x480 YUV420P 2016-11-01 17:12:12,706 client 4: texture 0: div=(1, 1), rowstride=896, 854x480, data=430080 bytes, upload=zerocopy:buffer-as-memoryview 2016-11-01 17:12:12,706 client 4: texture 1: div=(2, 2), rowstride=448, 427x240, data=107520 bytes, upload=zerocopy:buffer-as-memoryview 2016-11-01 17:12:12,707 client 4: texture 2: div=(2, 2), rowstride=448, 427x240, data=107520 bytes, upload=zerocopy:buffer-as-memoryview 2016-11-01 17:12:12,707 client 4: gtk2.GLWindowBacking(3, (1587, 749), YUV420P).render_planar_update(146, 150, 854, 480, 1, 1) pixel_format=YUV420P 2016-11-01 17:12:12,707 client 4: painting planar update, format YUV420P 2016-11-01 17:12:12,708 client 4: gtk2.GLWindowBacking(3, (1587, 749), YUV420P).render_planar_update(..) texture_size=(854, 480), size=(1587, 749) 2016-11-01 17:12:12,708 client 4: present_fbo: adding (146, 150, 854, 480) to pending paint list (size=0), flush=0, paint_screen=True 2016-11-01 17:12:12,711 client 4: Presenting FBO on screen 2016-11-01 17:12:12,711 client 4: Switching to RGB paint state 2016-11-01 17:12:12,711 client 4: do_present_fbo: painting [(146, 150, 854, 480)] 2016-11-01 17:12:12,712 client 4: gtk2.GLWindowBacking(3, (1587, 749), YUV420P).gl_show() flushing 2016-11-01 17:12:12,712 client 4: gl_show after 125ms took 1ms, 1 updates 2016-11-01 17:12:12,713 client 4: gtk2.GLWindowBacking(3, (1587, 749), YUV420P).gl_frame_terminator() 2016-11-01 17:12:12,713 client 4: Switching back to YUV paint state 2016-11-01 17:12:12,714 client 4: <OpenGL.platform.baseplatform.glBindFramebuffer object at 0xa4d8530>(GL_FRAMEBUFFER (36160), c_ulong(1L)) 2016-11-01 17:12:12,715 client 4: gtk2.GLWindowBacking(3, (1587, 749), YUV420P).do_present_fbo() done 2016-11-01 17:12:12,716 client 4: record_decode_time(True, ) wid=3, h264: 854x480, 12.2ms 2016-11-01 17:12:12,716 packet decoding sequence 221 for window 3: 854x480 took 12.2ms 2016-11-01 17:12:12,716 record_latency: took 53.3 ms round trip, 53.2 for echo, 12.0 for decoding of 409920 pixels, 1307 bytes sent over the network in 41.1 ms, 41.0 ms for echo 2016-11-01 17:12:12,717 client 4: after_draw_refresh(True, ) 854x480 at 146x150 encoding=h264, options={'speed': 81, 'type': 'P', 'pts': 144, 'frame': 1, 'encoding': 'h264', 'quality': 42, 'delayed': 1, 'csc': 'YUV420P'}
And more of nearly the same with the r14155 client:
2016-11-01 17:22:16,566 x264 close context 0x7f22bc01c520 2016-11-01 17:22:16,592 x264 close context 0x0 2016-11-01 17:22:16,603 x264 context=0x7f22bc01c520, YUV420P 764x482 quality=52, speed=62, source=video 2016-11-01 17:22:16,604 preset=faster, profile=high10, tune=film 2016-11-01 17:22:16,604 me=HEX, me_range=16, mv_range=-1, b-frames=1, max delayed frames=1 2016-11-01 17:22:16,604 vfr-input=0, lookahead=0, sync-lookahead=-1, mb-tree=1, bframe-adaptive=FAST 2016-11-01 17:22:16,604 threads=auto, sliced-threads=True 2016-11-01 17:22:16,606 client 6: draw_region(146, 150, 764, 482, h264, 4075 bytes, 0, {'speed': 63, 'csc': 'YUV444P', 'type': 'P', 'frame': 31, 'quality': 50, 'pts': 1908}, [<function record_decode_time at 0x11738770>, <function after_draw_refresh at 0x9f1ea70>]) 2016-11-01 17:22:16,607 client 6: gl_paint_planar(0, 'h264', AVImageWrapper-None(GBRP:(0, 0, 764, 482, 24):3_PLANES), 146, 150, 764, 482, 764, 482, [<function record_decode_time at 0x11738770>, <function after_draw_refresh at 0x9f1ea70>]) 2016-11-01 17:22:16,608 client 6: gtk2.GLWindowBacking(3, (1587, 749), GBRP).gl_context() GL Pixmap backing size: 1587 x 749, context=gtk2.GLContextManager(<gtk.DrawingArea object at 0xa84e328 (GtkDrawingArea at 0xc48bd8)>) 2016-11-01 17:22:16,608 client 6: gtk2.GLWindowBacking(3, (1587, 749), GBRP).update_planar_textures(146, 150, 764, 482, AVImageWrapper-None(GBRP:(0, 0, 764, 482, 24):3_PLANES), 'GBRP') 2016-11-01 17:22:16,609 client 6: updating planar textures: 764x482 GBRP 2016-11-01 17:22:16,610 client 6: texture 0: div=(1, 1), rowstride=768, 764x482, data=370176 bytes, upload=zerocopy:buffer-as-memoryview 2016-11-01 17:22:16,610 client 6: texture 1: div=(1, 1), rowstride=768, 764x482, data=370176 bytes, upload=zerocopy:buffer-as-memoryview 2016-11-01 17:22:16,610 client 6: texture 2: div=(1, 1), rowstride=768, 764x482, data=370176 bytes, upload=zerocopy:buffer-as-memoryview 2016-11-01 17:22:16,611 client 6: gtk2.GLWindowBacking(3, (1587, 749), GBRP).render_planar_update(146, 150, 764, 482, 1, 1) pixel_format=GBRP 2016-11-01 17:22:16,612 client 6: painting planar update, format GBRP 2016-11-01 17:22:16,612 x264 encode 1 delayed frames after 0 2016-11-01 17:22:16,618 client 6: gtk2.GLWindowBacking(3, (1587, 749), GBRP).render_planar_update(..) texture_size=(764, 482), size=(1587, 749) 2016-11-01 17:22:16,619 client 6: present_fbo: adding (146, 150, 764, 482) to pending paint list (size=0), flush=0, paint_screen=True 2016-11-01 17:22:16,619 client 6: Presenting FBO on screen 2016-11-01 17:22:16,619 client 6: Switching to RGB paint state 2016-11-01 17:22:16,619 client 6: do_present_fbo: painting [(146, 150, 764, 482)] 2016-11-01 17:22:16,620 client 6: gtk2.GLWindowBacking(3, (1587, 749), GBRP).gl_show() flushing 2016-11-01 17:22:16,619 compress: 26.1ms for 764x483 pixels at 146,150 for wid=3 using jpeg with ratio 2.5% ( 1441KB to 36KB), sequence 916, client_options={'quality': 92} 2016-11-01 17:22:16,621 client 6: gl_show after 64ms took 0ms, 1 updates 2016-11-01 17:22:16,621 client 6: gtk2.GLWindowBacking(3, (1587, 749), GBRP).gl_frame_terminator() 2016-11-01 17:22:16,631 client 6: Switching back to YUV paint state 2016-11-01 17:22:16,631 client 6: <OpenGL.platform.baseplatform.glBindFramebuffer object at 0xadf74f0>(GL_FRAMEBUFFER (36160), c_ulong(1L)) 2016-11-01 17:22:16,632 packet decoding sequence 915 for window 3: 764x482 took 11.2ms 2016-11-01 17:22:16,632 record_latency: took 73.9 ms round trip, 73.8 for echo, 11.0 for decoding of 368248 pixels, 4168 bytes sent over the network in 62.7 ms, 62.6 ms for echo 2016-11-01 17:22:16,633 client 6: gtk2.GLWindowBacking(3, (1587, 749), GBRP).do_present_fbo() done 2016-11-01 17:22:16,633 client 6: record_decode_time(True, ) wid=3, h264: 764x482, 11.2ms 2016-11-01 17:22:16,633 client 6: after_draw_refresh(True, ) 764x482 at 146x150 encoding=h264, options={'speed': 63, 'csc': 'YUV444P', 'encoding': 'h264', 'type': 'P', 'frame': 31, 'quality': 50, 'pts': 1908} 2016-11-01 17:22:16,672 x264 encode YUV420P frame 0 as IDR slice with 7 nals, tune=film, total 7021 bytes, keyframe=True , delayed=1 2016-11-01 17:22:16,674 compress: 21.1ms for 764x482 pixels at 146,150 for wid=3 using h264 with ratio 0.5% ( 1441KB to 6KB), sequence 917, client_options={'pts': 0, 'frame': 0, 'delayed': 1, 'csc': 'YUV420P', 'paint': False, 'type': 'IDR', 'quality': 52, 'speed': 62} 2016-11-01 17:22:16,685 client 6: draw_region(146, 150, 764, 483, jpeg, 37034 bytes, 0, {'quality': 92}, [<function record_decode_time at 0x9f1ea70>, <function after_draw_refresh at 0x9f1e330>]) 2016-11-01 17:22:16,690 client 6: gtk2.GLWindowBacking(3, (1587, 749), GBRP).do_paint_rgb(RGB, 1107036 bytes, x=146, y=150, width=764, height=483, rowstride=2292, options={'rgb_format': 'RGB', 'quality': 92, 'encoding': 'jpeg'}) 2016-11-01 17:22:16,692 client 6: gtk2.GLWindowBacking(3, (1587, 749), GBRP).gl_context() GL Pixmap backing size: 1587 x 749, context=gtk2.GLContextManager(<gtk.DrawingArea object at 0xa84e328 (GtkDrawingArea at 0xc48bd8)>) 2016-11-01 17:22:16,692 client 6: Switching to RGB paint state 2016-11-01 17:22:16,693 client 6: RGB update at (146,150) size 764x483 (1107036 bytes), stride=2292, row length 0, alignment 4, using GL zerocopy:buffer-as-memoryview format=RGB 2016-11-01 17:22:16,693 client 6: present_fbo: adding (146, 150, 764, 483) to pending paint list (size=0), flush=0, paint_screen=True 2016-11-01 17:22:16,694 client 6: Presenting FBO on screen 2016-11-01 17:22:16,694 client 6: Switching to RGB paint state 2016-11-01 17:22:16,694 client 6: do_present_fbo: painting [(146, 150, 764, 483)] 2016-11-01 17:22:16,695 client 6: gtk2.GLWindowBacking(3, (1587, 749), GBRP).gl_show() flushing 2016-11-01 17:22:16,698 client 6: gl_show after 84ms took 0ms, 1 updates 2016-11-01 17:22:16,698 client 6: gtk2.GLWindowBacking(3, (1587, 749), GBRP).gl_frame_terminator() 2016-11-01 17:22:16,699 packet decoding sequence 916 for window 3: 764x483 took 11.9ms 2016-11-01 17:22:16,699 record_latency: took 79.1 ms round trip, 79.0 for echo, 11.0 for decoding of 369012 pixels, 37086 bytes sent over the network in 67.2 ms, 67.1 ms for echo 2016-11-01 17:22:16,700 client 6: Switching back to YUV paint state 2016-11-01 17:22:16,700 client 6: <OpenGL.platform.baseplatform.glBindFramebuffer object at 0xadf74f0>(GL_FRAMEBUFFER (36160), c_ulong(1L)) 2016-11-01 17:22:16,703 client 6: gtk2.GLWindowBacking(3, (1587, 749), GBRP).do_present_fbo() done 2016-11-01 17:22:16,703 client 6: record_decode_time(True, ) wid=3, jpeg: 764x483, 11.8ms 2016-11-01 17:22:16,704 client 6: after_draw_refresh(True, ) 764x483 at 146x150 encoding=jpeg, options={'quality': 92, 'encoding': 'jpeg'} 2016-11-01 17:22:16,719 client 6: draw_region(146, 150, 764, 482, h264, 7021 bytes, 0, {'pts': 0, 'type': 'IDR', 'frame': 0, 'delayed': 1, 'csc': 'YUV420P', 'paint': False, 'quality': 52, 'speed': 62}, [<function record_decode_time at 0x11738770>, <function after_draw_refresh at 0x9f1ea70>]) 2016-11-01 17:22:16,720 client 6: paint_with_video_decoder: colorspace changed from YUV444P to YUV420P 2016-11-01 17:22:16,722 client 6: paint_with_video_decoder: new <type 'xpra.codecs.dec_avcodec2.decoder.Decoder'>(764,482,YUV420P) 2016-11-01 17:22:16,723 client 6: paint_with_video_decoder: info={'decoder_height': 482, 'encoding': 'h264', 'colorspace': 'YUV420P', 'actual_colorspace': 'YUV420P', 'height': 482, 'decoder_width': 764, 'width': 764, 'version': (57, 48, 101), 'formats': ['YUV422P', 'BGRX', 'GBRP', 'RGB', 'YUV420P', 'BGRA', 'ARGB', 'XRGB', 'YUV444P'], 'frames': 0L, 'type': 'avcodec'} 2016-11-01 17:22:16,726 client 6: Error: avcodec error -35 decoding 7021 bytes of h264 data: 2016-11-01 17:22:16,726 client 6: 'Resource temporarily unavailable' 2016-11-01 17:22:16,726 client 6: frame 0 2016-11-01 17:22:16,727 client 6: options={'pts': 0, 'encoding': 'h264', 'type': 'IDR', 'frame': 0, 'delayed': 1, 'csc': 'YUV420P', 'paint': False, 'quality': 52, 'speed': 62} 2016-11-01 17:22:16,728 packet decoding sequence 917 for window 3: 764x482 took 9.1ms 2016-11-01 17:22:16,728 record_latency: took 54.0 ms round trip, 53.9 for echo, 9.0 for decoding of 368248 pixels, 7130 bytes sent over the network in 44.9 ms, 44.8 ms for echo 2016-11-01 17:22:16,728 client 6: decoder state: 2016-11-01 17:22:16,729 client 6: decoder_height = 482 2016-11-01 17:22:16,729 client 6: encoding = h264 2016-11-01 17:22:16,732 client 6: colorspace = YUV420P 2016-11-01 17:22:16,732 client 6: actual_colorspace = YUV420P 2016-11-01 17:22:16,732 client 6: height = 482 2016-11-01 17:22:16,733 client 6: decoder_width = 764 2016-11-01 17:22:16,733 client 6: width = 764 2016-11-01 17:22:16,733 client 6: version = (57, 48, 101) 2016-11-01 17:22:16,733 client 6: formats = ['YUV422P', 'BGRX', 'GBRP', 'RGB', 'YUV420P', 'BGRA', 'ARGB', 'XRGB', 'YUV444P'] 2016-11-01 17:22:16,733 client 6: frames = 0 2016-11-01 17:22:16,733 client 6: type = avcodec 2016-11-01 17:22:16,734 client 6: record_decode_time(True, ) wid=3, h264: 764x482, 9.1ms 2016-11-01 17:22:16,734 client 6: after_draw_refresh(True, ) 764x482 at 146x150 encoding=h264, options={'pts': 0, 'encoding': 'h264', 'type': 'IDR', 'frame': 0, 'delayed': 1, 'csc': 'YUV420P', 'paint': False, 'quality': 52, 'speed': 62} 2016-11-01 17:22:16,735 x264 encode YUV420P frame 1 as P slice with 4 nals, tune=film, total 1643 bytes, keyframe=False, delayed=1 2016-11-01 17:22:16,735 compress: 23.3ms for 764x482 pixels at 146,150 for wid=3 using h264 with ratio 0.1% ( 1441KB to 1KB), sequence 918, client_options={'pts': 112, 'frame': 1, 'delayed': 1, 'csc': 'YUV420P', 'type': 'P', 'quality': 52, 'speed': 62} 2016-11-01 17:22:16,775 x264 encode YUV420P frame 2 as B slice with 4 nals, tune=film, total 740 bytes, keyframe=False, delayed=1 2016-11-01 17:22:16,775 compress: 12.9ms for 764x482 pixels at 146,150 for wid=3 using h264 with ratio 0.1% ( 1441KB to 0KB), sequence 919, client_options={'pts': 48, 'frame': 2, 'delayed': 1, 'csc': 'YUV420P', 'type': 'B', 'quality': 52, 'speed': 62} 2016-11-01 17:22:16,781 client 6: draw_region(146, 150, 764, 482, h264, 1643 bytes, 0, {'speed': 62, 'type': 'P', 'pts': 112, 'frame': 1, 'quality': 52, 'delayed': 1, 'csc': 'YUV420P'}, [<function record_decode_time at 0x11738770>, <function after_draw_refresh at 0x9f1ea70>]) 2016-11-01 17:22:16,782 client 6: gl_paint_planar(0, 'h264', AVImageWrapper-None(YUV420P:(0, 0, 764, 482, 24):3_PLANES), 146, 150, 764, 482, 764, 482, [<function record_decode_time at 0x11738770>, <function after_draw_refresh at 0x9f1ea70>]) 2016-11-01 17:22:16,783 client 6: gtk2.GLWindowBacking(3, (1587, 749), GBRP).gl_context() GL Pixmap backing size: 1587 x 749, context=gtk2.GLContextManager(<gtk.DrawingArea object at 0xa84e328 (GtkDrawingArea at 0xc48bd8)>) 2016-11-01 17:22:16,783 client 6: gtk2.GLWindowBacking(3, (1587, 749), GBRP).update_planar_textures(146, 150, 764, 482, AVImageWrapper-None(YUV420P:(0, 0, 764, 482, 24):3_PLANES), 'YUV420P') 2016-11-01 17:22:16,784 client 6: Creating new planar textures, pixel format YUV420P 2016-11-01 17:22:16,784 client 6: updating planar textures: 764x482 YUV420P 2016-11-01 17:22:16,785 client 6: texture 0: div=(1, 1), rowstride=768, 764x482, data=370176 bytes, upload=zerocopy:buffer-as-memoryview 2016-11-01 17:22:16,786 client 6: texture 1: div=(2, 2), rowstride=384, 382x241, data=92544 bytes, upload=zerocopy:buffer-as-memoryview 2016-11-01 17:22:16,787 client 6: texture 2: div=(2, 2), rowstride=384, 382x241, data=92544 bytes, upload=zerocopy:buffer-as-memoryview 2016-11-01 17:22:16,787 client 6: gtk2.GLWindowBacking(3, (1587, 749), YUV420P).render_planar_update(146, 150, 764, 482, 1, 1) pixel_format=YUV420P 2016-11-01 17:22:16,788 client 6: painting planar update, format YUV420P 2016-11-01 17:22:16,788 client 6: gtk2.GLWindowBacking(3, (1587, 749), YUV420P).render_planar_update(..) texture_size=(764, 482), size=(1587, 749) 2016-11-01 17:22:16,788 client 6: present_fbo: adding (146, 150, 764, 482) to pending paint list (size=0), flush=0, paint_screen=True 2016-11-01 17:22:16,790 client 6: Presenting FBO on screen 2016-11-01 17:22:16,790 client 6: Switching to RGB paint state 2016-11-01 17:22:16,790 client 6: do_present_fbo: painting [(146, 150, 764, 482)] 2016-11-01 17:22:16,791 client 6: gtk2.GLWindowBacking(3, (1587, 749), YUV420P).gl_show() flushing 2016-11-01 17:22:16,793 client 6: gl_show after 95ms took 1ms, 1 updates 2016-11-01 17:22:16,794 client 6: gtk2.GLWindowBacking(3, (1587, 749), YUV420P).gl_frame_terminator() 2016-11-01 17:22:16,795 client 6: Switching back to YUV paint state 2016-11-01 17:22:16,796 packet decoding sequence 918 for window 3: 764x482 took 13.3ms 2016-11-01 17:22:16,796 record_latency: took 59.8 ms round trip, 59.7 for echo, 13.0 for decoding of 368248 pixels, 1744 bytes sent over the network in 46.5 ms, 46.4 ms for echo 2016-11-01 17:22:16,796 client 6: <OpenGL.platform.baseplatform.glBindFramebuffer object at 0xadf74f0>(GL_FRAMEBUFFER (36160), c_ulong(1L)) 2016-11-01 17:22:16,797 client 6: gtk2.GLWindowBacking(3, (1587, 749), YUV420P).do_present_fbo() done 2016-11-01 17:22:16,797 client 6: record_decode_time(True, ) wid=3, h264: 764x482, 13.3ms 2016-11-01 17:22:16,797 client 6: after_draw_refresh(True, ) 764x482 at 146x150 encoding=h264, options={'speed': 62, 'type': 'P', 'pts': 112, 'frame': 1, 'encoding': 'h264', 'quality': 52, 'delayed': 1, 'csc': 'YUV420P'} 2016-11-01 17:22:16,814 client 6: draw_region(146, 150, 764, 482, h264, 740 bytes, 0, {'speed': 62, 'type': 'B', 'pts': 48, 'frame': 2, 'quality': 52, 'delayed': 1, 'csc': 'YUV420P'}, [<function record_decode_time at 0x11738770>, <function after_draw_refresh at 0x9f1e330>]) 2016-11-01 17:22:16,820 client 6: gl_paint_planar(0, 'h264', AVImageWrapper-None(YUV420P:(0, 0, 764, 482, 24):3_PLANES), 146, 150, 764, 482, 764, 482, [<function record_decode_time at 0x11738770>, <function after_draw_refresh at 0x9f1e330>]) 2016-11-01 17:22:16,822 client 6: gtk2.GLWindowBacking(3, (1587, 749), YUV420P).gl_context() GL Pixmap backing size: 1587 x 749, context=gtk2.GLContextManager(<gtk.DrawingArea object at 0xa84e328 (GtkDrawingArea at 0xc48bd8)>) 2016-11-01 17:22:16,824 client 6: gtk2.GLWindowBacking(3, (1587, 749), YUV420P).update_planar_textures(146, 150, 764, 482, AVImageWrapper-None(YUV420P:(0, 0, 764, 482, 24):3_PLANES), 'YUV420P') 2016-11-01 17:22:16,825 client 6: updating planar textures: 764x482 YUV420P 2016-11-01 17:22:16,834 client 6: texture 0: div=(1, 1), rowstride=768, 764x482, data=370176 bytes, upload=zerocopy:buffer-as-memoryview 2016-11-01 17:22:16,834 packet decoding sequence 919 for window 3: 764x482 took 11.4ms 2016-11-01 17:22:16,835 record_latency: took 58.2 ms round trip, 58.0 for echo, 11.0 for decoding of 368248 pixels, 841 bytes sent over the network in 46.7 ms, 46.6 ms for echo 2016-11-01 17:22:16,835 client 6: texture 1: div=(2, 2), rowstride=384, 382x241, data=92544 bytes, upload=zerocopy:buffer-as-memoryview 2016-11-01 17:22:16,835 client 6: texture 2: div=(2, 2), rowstride=384, 382x241, data=92544 bytes, upload=zerocopy:buffer-as-memoryview 2016-11-01 17:22:16,835 client 6: gtk2.GLWindowBacking(3, (1587, 749), YUV420P).render_planar_update(146, 150, 764, 482, 1, 1) pixel_format=YUV420P 2016-11-01 17:22:16,835 client 6: painting planar update, format YUV420P 2016-11-01 17:22:16,835 client 6: gtk2.GLWindowBacking(3, (1587, 749), YUV420P).render_planar_update(..) texture_size=(764, 482), size=(1587, 749) 2016-11-01 17:22:16,835 client 6: present_fbo: adding (146, 150, 764, 482) to pending paint list (size=0), flush=0, paint_screen=True 2016-11-01 17:22:16,835 client 6: Presenting FBO on screen 2016-11-01 17:22:16,836 client 6: Switching to RGB paint state 2016-11-01 17:22:16,836 client 6: do_present_fbo: painting [(146, 150, 764, 482)] 2016-11-01 17:22:16,836 client 6: gtk2.GLWindowBacking(3, (1587, 749), YUV420P).gl_show() flushing 2016-11-01 17:22:16,836 client 6: gl_show after 30ms took 1ms, 1 updates 2016-11-01 17:22:16,836 client 6: gtk2.GLWindowBacking(3, (1587, 749), YUV420P).gl_frame_terminator() 2016-11-01 17:22:16,836 client 6: Switching back to YUV paint state 2016-11-01 17:22:16,836 client 6: <OpenGL.platform.baseplatform.glBindFramebuffer object at 0xadf74f0>(GL_FRAMEBUFFER (36160), c_ulong(1L)) 2016-11-01 17:22:16,837 client 6: gtk2.GLWindowBacking(3, (1587, 749), YUV420P).do_present_fbo() done 2016-11-01 17:22:16,837 client 6: record_decode_time(True, ) wid=3, h264: 764x482, 11.4ms 2016-11-01 17:22:16,837 client 6: after_draw_refresh(True, ) 764x482 at 146x150 encoding=h264, options={'speed': 62, 'type': 'B', 'pts': 48, 'frame': 2, 'encoding': 'h264', 'quality': 52, 'delayed': 1, 'csc': 'YUV420P'} 2016-11-01 17:22:16,840 x264 encode YUV420P frame 3 as P slice with 4 nals, tune=film, total 1842 bytes, keyframe=False, delayed=1 2016-11-01 17:22:16,844 compress: 25.4ms for 764x482 pixels at 146,150 for wid=3 using h264 with ratio 0.1% ( 1441KB to 1KB), sequence 920, client_options={'pts': 212, 'frame': 3, 'delayed': 1, 'csc': 'YUV420P', 'type': 'P', 'quality': 52, 'speed': 62} 2016-11-01 17:22:16,855 x264 encode YUV420P frame 4 as B slice with 4 nals, tune=film, total 739 bytes, keyframe=False, delayed=1 2016-11-01 17:22:16,855 compress: 10.8ms for 764x482 pixels at 146,150 for wid=3 using h264 with ratio 0.1% ( 1441KB to 0KB), sequence 921, client_options={'pts': 157, 'frame': 4, 'delayed': 1, 'csc': 'YUV420P', 'type': 'B', 'quality': 52, 'speed': 62} 2016-11-01 17:22:16,886 client 6: draw_region(146, 150, 764, 482, h264, 1842 bytes, 0, {'speed': 62, 'type': 'P', 'pts': 212, 'frame': 3, 'quality': 52, 'delayed': 1, 'csc': 'YUV420P'}, [<function record_decode_time at 0x11738770>, <function after_draw_refresh at 0x9f1e970>]) 2016-11-01 17:22:16,887 client 6: gl_paint_planar(0, 'h264', AVImageWrapper-None(YUV420P:(0, 0, 764, 482, 24):3_PLANES), 146, 150, 764, 482, 764, 482, [<function record_decode_time at 0x11738770>, <function after_draw_refresh at 0x9f1e970>]) 2016-11-01 17:22:16,888 client 6: gtk2.GLWindowBacking(3, (1587, 749), YUV420P).gl_context() GL Pixmap backing size: 1587 x 749, context=gtk2.GLContextManager(<gtk.DrawingArea object at 0xa84e328 (GtkDrawingArea at 0xc48bd8)>) 2016-11-01 17:22:16,889 client 6: gtk2.GLWindowBacking(3, (1587, 749), YUV420P).update_planar_textures(146, 150, 764, 482, AVImageWrapper-None(YUV420P:(0, 0, 764, 482, 24):3_PLANES), 'YUV420P') 2016-11-01 17:22:16,890 client 6: updating planar textures: 764x482 YUV420P 2016-11-01 17:22:16,890 client 6: texture 0: div=(1, 1), rowstride=768, 764x482, data=370176 bytes, upload=zerocopy:buffer-as-memoryview 2016-11-01 17:22:16,891 client 6: texture 1: div=(2, 2), rowstride=384, 382x241, data=92544 bytes, upload=zerocopy:buffer-as-memoryview 2016-11-01 17:22:16,891 client 6: texture 2: div=(2, 2), rowstride=384, 382x241, data=92544 bytes, upload=zerocopy:buffer-as-memoryview 2016-11-01 17:22:16,891 client 6: gtk2.GLWindowBacking(3, (1587, 749), YUV420P).render_planar_update(146, 150, 764, 482, 1, 1) pixel_format=YUV420P 2016-11-01 17:22:16,892 client 6: painting planar update, format YUV420P 2016-11-01 17:22:16,893 client 6: gtk2.GLWindowBacking(3, (1587, 749), YUV420P).render_planar_update(..) texture_size=(764, 482), size=(1587, 749) 2016-11-01 17:22:16,893 client 6: present_fbo: adding (146, 150, 764, 482) to pending paint list (size=0), flush=0, paint_screen=True 2016-11-01 17:22:16,893 client 6: Presenting FBO on screen 2016-11-01 17:22:16,894 client 6: Switching to RGB paint state 2016-11-01 17:22:16,895 client 6: do_present_fbo: painting [(146, 150, 764, 482)] 2016-11-01 17:22:16,896 client 6: gtk2.GLWindowBacking(3, (1587, 749), YUV420P).gl_show() flushing 2016-11-01 17:22:16,898 client 6: gl_show after 77ms took 3ms, 1 updates 2016-11-01 17:22:16,902 client 6: gtk2.GLWindowBacking(3, (1587, 749), YUV420P).gl_frame_terminator() 2016-11-01 17:22:16,902 client 6: Switching back to YUV paint state 2016-11-01 17:22:16,903 client 6: <OpenGL.platform.baseplatform.glBindFramebuffer object at 0xadf74f0>(GL_FRAMEBUFFER (36160), c_ulong(1L)) 2016-11-01 17:22:16,903 packet decoding sequence 920 for window 3: 764x482 took 17.0ms 2016-11-01 17:22:16,903 record_latency: took 57.7 ms round trip, 57.7 for echo, 17.0 for decoding of 368248 pixels, 1944 bytes sent over the network in 40.7 ms, 40.6 ms for echo 2016-11-01 17:22:16,907 client 6: gtk2.GLWindowBacking(3, (1587, 749), YUV420P).do_present_fbo() done 2016-11-01 17:22:16,907 client 6: record_decode_time(True, ) wid=3, h264: 764x482, 17.0ms 2016-11-01 17:22:16,907 client 6: after_draw_refresh(True, ) 764x482 at 146x150 encoding=h264, options={'speed': 62, 'type': 'P', 'pts': 212, 'frame': 3, 'encoding': 'h264', 'quality': 52, 'delayed': 1, 'csc': 'YUV420P'} 2016-11-01 17:22:16,908 client 6: draw_region(146, 150, 764, 482, h264, 739 bytes, 0, {'speed': 62, 'type': 'B', 'pts': 157, 'frame': 4, 'quality': 52, 'delayed': 1, 'csc': 'YUV420P'}, [<function record_decode_time at 0x11738770>, <function after_draw_refresh at 0x9f1e970>]) 2016-11-01 17:22:16,909 client 6: gl_paint_planar(0, 'h264', AVImageWrapper-None(YUV420P:(0, 0, 764, 482, 24):3_PLANES), 146, 150, 764, 482, 764, 482, [<function record_decode_time at 0x11738770>, <function after_draw_refresh at 0x9f1e970>]) 2016-11-01 17:22:16,910 client 6: gtk2.GLWindowBacking(3, (1587, 749), YUV420P).gl_context() GL Pixmap backing size: 1587 x 749, context=gtk2.GLContextManager(<gtk.DrawingArea object at 0xa84e328 (GtkDrawingArea at 0xc48bd8)>) 2016-11-01 17:22:16,912 client 6: gtk2.GLWindowBacking(3, (1587, 749), YUV420P).update_planar_textures(146, 150, 764, 482, AVImageWrapper-None(YUV420P:(0, 0, 764, 482, 24):3_PLANES), 'YUV420P') 2016-11-01 17:22:16,913 client 6: updating planar textures: 764x482 YUV420P 2016-11-01 17:22:16,913 client 6: texture 0: div=(1, 1), rowstride=768, 764x482, data=370176 bytes, upload=zerocopy:buffer-as-memoryview 2016-11-01 17:22:16,913 client 6: texture 1: div=(2, 2), rowstride=384, 382x241, data=92544 bytes, upload=zerocopy:buffer-as-memoryview 2016-11-01 17:22:16,913 client 6: texture 2: div=(2, 2), rowstride=384, 382x241, data=92544 bytes, upload=zerocopy:buffer-as-memoryview 2016-11-01 17:22:16,914 client 6: gtk2.GLWindowBacking(3, (1587, 749), YUV420P).render_planar_update(146, 150, 764, 482, 1, 1) pixel_format=YUV420P 2016-11-01 17:22:16,914 client 6: painting planar update, format YUV420P 2016-11-01 17:22:16,914 client 6: gtk2.GLWindowBacking(3, (1587, 749), YUV420P).render_planar_update(..) texture_size=(764, 482), size=(1587, 749) 2016-11-01 17:22:16,914 client 6: present_fbo: adding (146, 150, 764, 482) to pending paint list (size=0), flush=0, paint_screen=True 2016-11-01 17:22:16,914 client 6: Presenting FBO on screen 2016-11-01 17:22:16,915 client 6: Switching to RGB paint state 2016-11-01 17:22:16,915 client 6: do_present_fbo: painting [(146, 150, 764, 482)] 2016-11-01 17:22:16,915 client 6: gtk2.GLWindowBacking(3, (1587, 749), YUV420P).gl_show() flushing 2016-11-01 17:22:16,916 client 6: gl_show after 16ms took 1ms, 1 updates 2016-11-01 17:22:16,916 client 6: gtk2.GLWindowBacking(3, (1587, 749), YUV420P).gl_frame_terminator() 2016-11-01 17:22:16,918 packet decoding sequence 921 for window 3: 764x482 took 13.6ms 2016-11-01 17:22:16,918 record_latency: took 62.2 ms round trip, 62.2 for echo, 13.0 for decoding of 368248 pixels, 841 bytes sent over the network in 48.6 ms, 48.5 ms for echo 2016-11-01 17:22:16,918 client 6: Switching back to YUV paint state 2016-11-01 17:22:16,919 client 6: <OpenGL.platform.baseplatform.glBindFramebuffer object at 0xadf74f0>(GL_FRAMEBUFFER (36160), c_ulong(1L)) 2016-11-01 17:22:16,919 client 6: gtk2.GLWindowBacking(3, (1587, 749), YUV420P).do_present_fbo() done 2016-11-01 17:22:16,920 client 6: record_decode_time(True, ) wid=3, h264: 764x482, 13.6ms 2016-11-01 17:22:16,921 client 6: after_draw_refresh(True, ) 764x482 at 146x150 encoding=h264, options={'speed': 62, 'type': 'B', 'pts': 157, 'frame': 4, 'encoding': 'h264', 'quality': 52, 'delayed': 1, 'csc': 'YUV420P'}
Ohh... and as for the errors I was seeing with XPRA_X264_THREADS=1
and XPRA_X264_SLICED_THREADS=0
... I've figured out why you're not seeing them.
Somehow, rather than XPRA_X264_THREADS=1
, I managed to try to test using XPRA_CPU_THREADS=1
- which I'm not even sure is a real property, but using it seems to trigger a lot of errors.
While figuring out where I'd gone wrong (I've no idea still quite how), I did notice that testing with the correct variables (XPRA_X264_THREADS=1
and XPRA_X264_SLICED_THREADS=0
), I am in fact not able to repro... as you'd expected previously. (At least that's one mystery solved, and a far less nerve wracking mystery substituted in its place.)
Replying to comment:7 : do we need to change the defaults settings for x264 threads? Do you get errors with the default settings but not if you disable sliced threads? (do you need both environment variables to get rid of the problem?) Note: this code has been present for a very long time, maybe the error is only triggering now because of b-frames.
Can you reproduce the error from comment:6 with a more up to date server? If so, does it go away (or become harder to hit?) if you turn off b-frames on the server?
There were some important fixes in this area recently:
You already had:
... I am able to still reproduce the error from comment:6 ... using fedora 23 server 1.0 r14390 (just built it, as up to date as I know how to get)... though I'm still using a 1.0 r14155 osx client (shouldn't be an issue, but just sayin').
With the same -d stat,x264,compress
flags, server side:
2016-11-03 18:08:04,309 x264 close context 0x0 2016-11-03 18:08:04,317 x264 context=0x7f46a11e3160, YUV420P 854x480 quality=62, speed=96, source=video 2016-11-03 18:08:04,317 preset=superfast, profile=high10, tune=film 2016-11-03 18:08:04,317 me=DIA, me_range=16, mv_range=-1, b-frames=1, max delayed frames=1 2016-11-03 18:08:04,318 vfr-input=0, lookahead=0, sync-lookahead=-1, mb-tree=0, bframe-adaptive=FAST 2016-11-03 18:08:04,319 threads=auto, sliced-threads=True 2016-11-03 18:08:04,326 x264 encode 1 delayed frames after 0 2016-11-03 18:08:04,334 compress: 24.4ms for 854x480 pixels at 146,150 for wid=2 using jpeg with ratio 4.3% ( 1601KB to 69KB), sequence 8546, client_options={'quality': 99} 2016-11-03 18:08:04,344 client 1: draw_region(146, 150, 854, 480, jpeg, 70809 bytes, 0, {'quality': 99}, [<function record_decode_time at 0x69097f0>, <function after_draw_refresh at 0x6b87fb0>]) 2016-11-03 18:08:04,355 client 1: gtk2.GLWindowBacking(2, (1587, 749), GBRP).do_paint_rgb(RGB, 1229760 bytes, x=146, y=150, width=854, height=480, rowstride=2562, options={'rgb_format': 'RGB', 'quality': 99, 'encoding': 'jpeg'}) 2016-11-03 18:08:04,355 client 1: gtk2.GLWindowBacking(2, (1587, 749), GBRP).gl_context() GL Pixmap backing size: 1587 x 749, context=gtk2.GLContextManager(<gtk.DrawingArea object at 0x87776e8 (GtkDrawingArea at 0x2ad6b58)>) 2016-11-03 18:08:04,357 client 1: Switching to RGB paint state 2016-11-03 18:08:04,357 client 1: RGB update at (146,150) size 854x480 (1229760 bytes), stride=2562, row length 0, alignment 2, using GL zerocopy:buffer-as-memoryview format=RGB 2016-11-03 18:08:04,357 client 1: present_fbo: adding (146, 150, 854, 480) to pending paint list (size=0), flush=0, paint_screen=True 2016-11-03 18:08:04,357 client 1: Presenting FBO on screen 2016-11-03 18:08:04,359 client 1: Switching to RGB paint state 2016-11-03 18:08:04,359 client 1: do_present_fbo: painting [(146, 150, 854, 480)] 2016-11-03 18:08:04,359 client 1: gtk2.GLWindowBacking(2, (1587, 749), GBRP).gl_show() flushing 2016-11-03 18:08:04,360 client 1: gl_show after 85ms took 3ms, 1 updates 2016-11-03 18:08:04,360 client 1: gtk2.GLWindowBacking(2, (1587, 749), GBRP).gl_frame_terminator() 2016-11-03 18:08:04,360 client 1: Switching back to YUV paint state 2016-11-03 18:08:04,360 client 1: <OpenGL.platform.baseplatform.glBindFramebuffer object at 0xbd1d4f0>(GL_FRAMEBUFFER (36160), c_ulong(2L)) 2016-11-03 18:08:04,360 client 1: gtk2.GLWindowBacking(2, (1587, 749), GBRP).do_present_fbo() done 2016-11-03 18:08:04,362 client 1: record_decode_time(True, ) wid=2, jpeg: 854x480, 16.6ms 2016-11-03 18:08:04,363 client 1: after_draw_refresh(True, ) 854x480 at 146x150 encoding=jpeg, options={'quality': 99, 'encoding': 'jpeg'} 2016-11-03 18:08:04,366 x264 encode YUV420P frame 0 as IDR slice with 7 nals, tune=film, total 23122 bytes, keyframe=True , delayed=1 2016-11-03 18:08:04,366 compress: 12.9ms for 854x480 pixels at 146,150 for wid=2 using h264 with ratio 1.4% ( 1601KB to 22KB), sequence 8547, client_options={'pts': 0, 'frame': 0, 'delayed': 1, 'csc': 'YUV420P', 'paint': False, 'type': 'IDR', 'quality': 62, 'speed': 96} 2016-11-03 18:08:04,372 client 1: draw_region(146, 150, 854, 480, h264, 23122 bytes, 0, {'pts': 0, 'type': 'IDR', 'frame': 0, 'delayed': 1, 'csc': 'YUV420P', 'paint': False, 'quality': 62, 'speed': 96}, [<function record_decode_time at 0x69097f0>, <function after_draw_refresh at 0x6b87fb0>]) 2016-11-03 18:08:04,374 client 1: paint_with_video_decoder: colorspace changed from YUV444P to YUV420P 2016-11-03 18:08:04,374 client 1: paint_with_video_decoder: new <type 'xpra.codecs.dec_avcodec2.decoder.Decoder'>(854,480,YUV420P) 2016-11-03 18:08:04,374 client 1: paint_with_video_decoder: info={'decoder_height': 480, 'encoding': 'h264', 'colorspace': 'YUV420P', 'actual_colorspace': 'YUV420P', 'height': 480, 'decoder_width': 854, 'width': 854, 'version': (57, 48, 101), 'formats': ['YUV422P', 'BGRX', 'GBRP', 'RGB', 'YUV420P', 'BGRA', 'ARGB', 'XRGB', 'YUV444P'], 'frames': 0L, 'type': 'avcodec'} 2016-11-03 18:08:04,378 client 1: Error: avcodec error -35 decoding 23122 bytes of h264 data: 2016-11-03 18:08:04,378 client 1: 'Resource temporarily unavailable' 2016-11-03 18:08:04,380 client 1: frame 0 2016-11-03 18:08:04,380 client 1: options={'pts': 0, 'encoding': 'h264', 'type': 'IDR', 'frame': 0, 'delayed': 1, 'csc': 'YUV420P', 'paint': False, 'quality': 62, 'speed': 96} 2016-11-03 18:08:04,381 client 1: decoder state: 2016-11-03 18:08:04,381 client 1: decoder_height = 480 2016-11-03 18:08:04,382 client 1: encoding = h264 2016-11-03 18:08:04,382 client 1: colorspace = YUV420P 2016-11-03 18:08:04,382 client 1: actual_colorspace = YUV420P 2016-11-03 18:08:04,383 client 1: height = 480 2016-11-03 18:08:04,383 client 1: decoder_width = 854 2016-11-03 18:08:04,384 client 1: width = 854 2016-11-03 18:08:04,385 client 1: version = (57, 48, 101) 2016-11-03 18:08:04,385 client 1: formats = ['YUV422P', 'BGRX', 'GBRP', 'RGB', 'YUV420P', 'BGRA', 'ARGB', 'XRGB', 'YUV444P'] 2016-11-03 18:08:04,386 client 1: frames = 0 2016-11-03 18:08:04,386 client 1: type = avcodec 2016-11-03 18:08:04,386 client 1: record_decode_time(True, ) wid=2, h264: 854x480, 12.3ms 2016-11-03 18:08:04,386 client 1: after_draw_refresh(True, ) 854x480 at 146x150 encoding=h264, options={'pts': 0, 'encoding': 'h264', 'type': 'IDR', 'frame': 0, 'delayed': 1, 'csc': 'YUV420P', 'paint': False, 'quality': 62, 'speed': 96} 2016-11-03 18:08:04,449 x264 encode YUV420P frame 1 as P slice with 4 nals, tune=film, total 7900 bytes, keyframe=False, delayed=1 2016-11-03 18:08:04,450 compress: 12.5ms for 854x480 pixels at 146,150 for wid=2 using h264 with ratio 0.5% ( 1601KB to 7KB), sequence 8548, client_options={'pts': 117, 'frame': 1, 'delayed': 1, 'csc': 'YUV420P', 'type': 'P', 'quality': 62, 'speed': 96} 2016-11-03 18:08:04,453 client 1: draw_region(146, 150, 854, 480, h264, 7900 bytes, 0, {'speed': 96, 'type': 'P', 'pts': 117, 'frame': 1, 'quality': 62, 'delayed': 1, 'csc': 'YUV420P'}, [<function record_decode_time at 0x69097f0>, <function after_draw_refresh at 0x6b87fb0>]) 2016-11-03 18:08:04,456 client 1: gl_paint_planar(0, 'h264', AVImageWrapper-None(YUV420P:(0, 0, 854, 480, 24):3_PLANES), 146, 150, 854, 480, 854, 480, [<function record_decode_time at 0x69097f0>, <function after_draw_refresh at 0x6b87fb0>]) 2016-11-03 18:08:04,457 client 1: gtk2.GLWindowBacking(2, (1587, 749), GBRP).gl_context() GL Pixmap backing size: 1587 x 749, context=gtk2.GLContextManager(<gtk.DrawingArea object at 0x87776e8 (GtkDrawingArea at 0x2ad6b58)>) 2016-11-03 18:08:04,458 client 1: gtk2.GLWindowBacking(2, (1587, 749), GBRP).update_planar_textures(146, 150, 854, 480, AVImageWrapper-None(YUV420P:(0, 0, 854, 480, 24):3_PLANES), 'YUV420P') 2016-11-03 18:08:04,458 client 1: Creating new planar textures, pixel format YUV420P 2016-11-03 18:08:04,458 client 1: updating planar textures: 854x480 YUV420P 2016-11-03 18:08:04,459 client 1: texture 0: div=(1, 1), rowstride=896, 854x480, data=430080 bytes, upload=zerocopy:buffer-as-memoryview 2016-11-03 18:08:04,459 client 1: texture 1: div=(2, 2), rowstride=448, 427x240, data=107520 bytes, upload=zerocopy:buffer-as-memoryview 2016-11-03 18:08:04,460 client 1: texture 2: div=(2, 2), rowstride=448, 427x240, data=107520 bytes, upload=zerocopy:buffer-as-memoryview 2016-11-03 18:08:04,461 client 1: gtk2.GLWindowBacking(2, (1587, 749), YUV420P).render_planar_update(146, 150, 854, 480, 1, 1) pixel_format=YUV420P 2016-11-03 18:08:04,461 client 1: painting planar update, format YUV420P 2016-11-03 18:08:04,462 client 1: gtk2.GLWindowBacking(2, (1587, 749), YUV420P).render_planar_update(..) texture_size=(854, 480), size=(1587, 749) 2016-11-03 18:08:04,462 client 1: present_fbo: adding (146, 150, 854, 480) to pending paint list (size=0), flush=0, paint_screen=True 2016-11-03 18:08:04,463 client 1: Presenting FBO on screen 2016-11-03 18:08:04,463 client 1: Switching to RGB paint state 2016-11-03 18:08:04,463 client 1: do_present_fbo: painting [(146, 150, 854, 480)] 2016-11-03 18:08:04,463 client 1: gtk2.GLWindowBacking(2, (1587, 749), YUV420P).gl_show() flushing 2016-11-03 18:08:04,466 client 1: gl_show after 108ms took 4ms, 1 updates 2016-11-03 18:08:04,469 client 1: gtk2.GLWindowBacking(2, (1587, 749), YUV420P).gl_frame_terminator() 2016-11-03 18:08:04,470 client 1: Switching back to YUV paint state 2016-11-03 18:08:04,471 client 1: <OpenGL.platform.baseplatform.glBindFramebuffer object at 0xbd1d4f0>(GL_FRAMEBUFFER (36160), c_ulong(2L)) 2016-11-03 18:08:04,471 client 1: gtk2.GLWindowBacking(2, (1587, 749), YUV420P).do_present_fbo() done 2016-11-03 18:08:04,471 client 1: record_decode_time(True, ) wid=2, h264: 854x480, 13.7ms 2016-11-03 18:08:04,471 client 1: after_draw_refresh(True, ) 854x480 at 146x150 encoding=h264, options={'speed': 96, 'type': 'P', 'pts': 117, 'frame': 1, 'encoding': 'h264', 'quality': 62, 'delayed': 1, 'csc': 'YUV420P'} 2016-11-03 18:08:04,511 x264 encode YUV420P frame 2 as B slice with 4 nals, tune=film, total 1857 bytes, keyframe=False, delayed=1 2016-11-03 18:08:04,511 compress: 8.5ms for 854x480 pixels at 146,150 for wid=2 using h264 with ratio 0.1% ( 1601KB to 1KB), sequence 8549, client_options={'pts': 36, 'frame': 2, 'delayed': 1, 'csc': 'YUV420P', 'type': 'B', 'quality': 62, 'speed': 96} 2016-11-03 18:08:04,515 client 1: draw_region(146, 150, 854, 480, h264, 1857 bytes, 0, {'speed': 96, 'type': 'B', 'pts': 36, 'frame': 2, 'quality': 62, 'delayed': 1, 'csc': 'YUV420P'}, [<function record_decode_time at 0x69097f0>, <function after_draw_refresh at 0x6b87fb0>]) 2016-11-03 18:08:04,520 client 1: gl_paint_planar(0, 'h264', AVImageWrapper-None(YUV420P:(0, 0, 854, 480, 24):3_PLANES), 146, 150, 854, 480, 854, 480, [<function record_decode_time at 0x69097f0>, <function after_draw_refresh at 0x6b87fb0>]) 2016-11-03 18:08:04,521 client 1: gtk2.GLWindowBacking(2, (1587, 749), YUV420P).gl_context() GL Pixmap backing size: 1587 x 749, context=gtk2.GLContextManager(<gtk.DrawingArea object at 0x87776e8 (GtkDrawingArea at 0x2ad6b58)>) 2016-11-03 18:08:04,522 client 1: gtk2.GLWindowBacking(2, (1587, 749), YUV420P).update_planar_textures(146, 150, 854, 480, AVImageWrapper-None(YUV420P:(0, 0, 854, 480, 24):3_PLANES), 'YUV420P') 2016-11-03 18:08:04,522 client 1: updating planar textures: 854x480 YUV420P 2016-11-03 18:08:04,523 client 1: texture 0: div=(1, 1), rowstride=896, 854x480, data=430080 bytes, upload=zerocopy:buffer-as-memoryview 2016-11-03 18:08:04,523 client 1: texture 1: div=(2, 2), rowstride=448, 427x240, data=107520 bytes, upload=zerocopy:buffer-as-memoryview 2016-11-03 18:08:04,523 client 1: texture 2: div=(2, 2), rowstride=448, 427x240, data=107520 bytes, upload=zerocopy:buffer-as-memoryview 2016-11-03 18:08:04,524 client 1: gtk2.GLWindowBacking(2, (1587, 749), YUV420P).render_planar_update(146, 150, 854, 480, 1, 1) pixel_format=YUV420P 2016-11-03 18:08:04,527 client 1: painting planar update, format YUV420P 2016-11-03 18:08:04,527 client 1: gtk2.GLWindowBacking(2, (1587, 749), YUV420P).render_planar_update(..) texture_size=(854, 480), size=(1587, 749) 2016-11-03 18:08:04,528 client 1: present_fbo: adding (146, 150, 854, 480) to pending paint list (size=0), flush=0, paint_screen=True 2016-11-03 18:08:04,528 client 1: Presenting FBO on screen 2016-11-03 18:08:04,530 client 1: Switching to RGB paint state 2016-11-03 18:08:04,530 client 1: do_present_fbo: painting [(146, 150, 854, 480)] 2016-11-03 18:08:04,530 client 1: gtk2.GLWindowBacking(2, (1587, 749), YUV420P).gl_show() flushing 2016-11-03 18:08:04,530 client 1: gl_show after 60ms took 0ms, 1 updates 2016-11-03 18:08:04,530 client 1: gtk2.GLWindowBacking(2, (1587, 749), YUV420P).gl_frame_terminator() 2016-11-03 18:08:04,531 client 1: Switching back to YUV paint state 2016-11-03 18:08:04,531 client 1: <OpenGL.platform.baseplatform.glBindFramebuffer object at 0xbd1d4f0>(GL_FRAMEBUFFER (36160), c_ulong(2L)) 2016-11-03 18:08:04,531 client 1: gtk2.GLWindowBacking(2, (1587, 749), YUV420P).do_present_fbo() done 2016-11-03 18:08:04,531 client 1: record_decode_time(True, ) wid=2, h264: 854x480, 12.1ms 2016-11-03 18:08:04,531 client 1: after_draw_refresh(True, ) 854x480 at 146x150 encoding=h264, options={'speed': 96, 'type': 'B', 'pts': 36, 'frame': 2, 'encoding': 'h264', 'quality': 62, 'delayed': 1, 'csc': 'YUV420P'}
XPRA_B_FRAMES=0
... and was indeed able to produce the message again (not much more difficult to trigger... though neither is simple to trigger... require nearly a minute of dedicated patience).
2016-11-03 18:21:20,475 x264 close context 0x0 2016-11-03 18:21:20,483 x264 context=0x7f8788733640, YUV420P 854x480 quality=58, speed=95, source=video 2016-11-03 18:21:20,483 preset=superfast, profile=high10, tune=film 2016-11-03 18:21:20,483 me=DIA, me_range=16, mv_range=-1, b-frames=1, max delayed frames=1 2016-11-03 18:21:20,484 vfr-input=0, lookahead=0, sync-lookahead=-1, mb-tree=0, bframe-adaptive=FAST 2016-11-03 18:21:20,484 threads=auto, sliced-threads=True 2016-11-03 18:21:20,492 x264 encode 1 delayed frames after 0 2016-11-03 18:21:20,502 compress: 26.2ms for 854x480 pixels at 147,150 for wid=2 using jpeg with ratio 4.8% ( 1601KB to 76KB), sequence 1771, client_options={'quality': 98} 2016-11-03 18:21:20,514 client 1: draw_region(147, 150, 854, 480, jpeg, 78036 bytes, 0, {'quality': 98}, [<function record_decode_time at 0x10861ab0>, <function after_draw_refresh at 0x10861cb0>]) 2016-11-03 18:21:20,521 client 1: gtk2.GLWindowBacking(2, (1589, 1026), GBRP).do_paint_rgb(RGB, 1229760 bytes, x=147, y=150, width=854, height=480, rowstride=2562, options={'rgb_format': 'RGB', 'quality': 98, 'encoding': 'jpeg'}) 2016-11-03 18:21:20,521 client 1: gtk2.GLWindowBacking(2, (1589, 1026), GBRP).gl_context() GL Pixmap backing size: 1589 x 1026, context=gtk2.GLContextManager(<gtk.DrawingArea object at 0xb85d418 (GtkDrawingArea at 0x49ffb58)>) 2016-11-03 18:21:20,522 client 1: Switching to RGB paint state 2016-11-03 18:21:20,523 client 1: RGB update at (147,150) size 854x480 (1229760 bytes), stride=2562, row length 0, alignment 2, using GL zerocopy:buffer-as-memoryview format=RGB 2016-11-03 18:21:20,526 client 1: present_fbo: adding (147, 150, 854, 480) to pending paint list (size=0), flush=0, paint_screen=True 2016-11-03 18:21:20,527 client 1: Presenting FBO on screen 2016-11-03 18:21:20,527 client 1: Switching to RGB paint state 2016-11-03 18:21:20,527 client 1: do_present_fbo: painting [(147, 150, 854, 480)] 2016-11-03 18:21:20,528 client 1: gtk2.GLWindowBacking(2, (1589, 1026), GBRP).gl_show() flushing 2016-11-03 18:21:20,529 client 1: gl_show after 81ms took 4ms, 1 updates 2016-11-03 18:21:20,532 client 1: gtk2.GLWindowBacking(2, (1589, 1026), GBRP).gl_frame_terminator() 2016-11-03 18:21:20,532 client 1: Switching back to YUV paint state 2016-11-03 18:21:20,532 client 1: <OpenGL.platform.baseplatform.glBindFramebuffer object at 0xbf374f0>(GL_FRAMEBUFFER (36160), c_ulong(1L)) 2016-11-03 18:21:20,533 client 1: gtk2.GLWindowBacking(2, (1589, 1026), GBRP).do_present_fbo() done 2016-11-03 18:21:20,533 client 1: record_decode_time(True, ) wid=2, jpeg: 854x480, 15.2ms 2016-11-03 18:21:20,533 client 1: after_draw_refresh(True, ) 854x480 at 147x150 encoding=jpeg, options={'quality': 98, 'encoding': 'jpeg'} 2016-11-03 18:21:20,543 x264 encode YUV420P frame 0 as IDR slice with 7 nals, tune=film, total 23145 bytes, keyframe=True , delayed=1 2016-11-03 18:21:20,543 compress: 16.8ms for 854x480 pixels at 147,150 for wid=2 using h264 with ratio 1.4% ( 1601KB to 22KB), sequence 1772, client_options={'pts': 0, 'frame': 0, 'delayed': 1, 'csc': 'YUV420P', 'paint': False, 'type': 'IDR', 'quality': 58, 'speed': 95} 2016-11-03 18:21:20,554 client 1: draw_region(147, 150, 854, 480, h264, 23145 bytes, 0, {'pts': 0, 'type': 'IDR', 'frame': 0, 'delayed': 1, 'csc': 'YUV420P', 'paint': False, 'quality': 58, 'speed': 95}, [<function record_decode_time at 0x10861df0>, <function after_draw_refresh at 0x10861870>]) 2016-11-03 18:21:20,555 client 1: paint_with_video_decoder: colorspace changed from YUV444P to YUV420P 2016-11-03 18:21:20,555 client 1: paint_with_video_decoder: new <type 'xpra.codecs.dec_avcodec2.decoder.Decoder'>(854,480,YUV420P) 2016-11-03 18:21:20,555 client 1: paint_with_video_decoder: info={'decoder_height': 480, 'encoding': 'h264', 'colorspace': 'YUV420P', 'actual_colorspace': 'YUV420P', 'height': 480, 'decoder_width': 854, 'width': 854, 'version': (57, 48, 101), 'formats': ['YUV422P', 'BGRX', 'GBRP', 'RGB', 'YUV420P', 'BGRA', 'ARGB', 'XRGB', 'YUV444P'], 'frames': 0L, 'type': 'avcodec'} 2016-11-03 18:21:20,557 client 1: Error: avcodec error -35 decoding 23145 bytes of h264 data: 2016-11-03 18:21:20,558 client 1: 'Resource temporarily unavailable' 2016-11-03 18:21:20,558 client 1: frame 0 2016-11-03 18:21:20,559 client 1: options={'pts': 0, 'encoding': 'h264', 'type': 'IDR', 'frame': 0, 'delayed': 1, 'csc': 'YUV420P', 'paint': False, 'quality': 58, 'speed': 95} 2016-11-03 18:21:20,559 client 1: decoder state: 2016-11-03 18:21:20,560 client 1: decoder_height = 480 2016-11-03 18:21:20,561 client 1: encoding = h264 2016-11-03 18:21:20,562 client 1: colorspace = YUV420P 2016-11-03 18:21:20,563 client 1: actual_colorspace = YUV420P 2016-11-03 18:21:20,563 client 1: height = 480 2016-11-03 18:21:20,563 client 1: decoder_width = 854 2016-11-03 18:21:20,563 client 1: width = 854 2016-11-03 18:21:20,563 client 1: version = (57, 48, 101) 2016-11-03 18:21:20,564 client 1: formats = ['YUV422P', 'BGRX', 'GBRP', 'RGB', 'YUV420P', 'BGRA', 'ARGB', 'XRGB', 'YUV444P'] 2016-11-03 18:21:20,564 client 1: frames = 0 2016-11-03 18:21:20,564 client 1: type = avcodec 2016-11-03 18:21:20,565 client 1: record_decode_time(True, ) wid=2, h264: 854x480, 12.1ms 2016-11-03 18:21:20,565 client 1: after_draw_refresh(True, ) 854x480 at 147x150 encoding=h264, options={'pts': 0, 'encoding': 'h264', 'type': 'IDR', 'frame': 0, 'delayed': 1, 'csc': 'YUV420P', 'paint': False, 'quality': 58, 'speed': 95} 2016-11-03 18:21:20,632 x264 encode YUV420P frame 1 as P slice with 4 nals, tune=film, total 6796 bytes, keyframe=False, delayed=1 2016-11-03 18:21:20,633 compress: 22.2ms for 854x480 pixels at 147,150 for wid=2 using h264 with ratio 0.4% ( 1601KB to 6KB), sequence 1773, client_options={'pts': 41, 'frame': 1, 'delayed': 1, 'csc': 'YUV420P', 'type': 'P', 'quality': 58, 'speed': 95} 2016-11-03 18:21:20,637 client 1: draw_region(147, 150, 854, 480, h264, 6796 bytes, 0, {'speed': 95, 'type': 'P', 'pts': 41, 'frame': 1, 'quality': 58, 'delayed': 1, 'csc': 'YUV420P'}, [<function record_decode_time at 0x10861df0>, <function after_draw_refresh at 0x10861870>]) 2016-11-03 18:21:20,639 client 1: gl_paint_planar(0, 'h264', AVImageWrapper-None(YUV420P:(0, 0, 854, 480, 24):3_PLANES), 147, 150, 854, 480, 854, 480, [<function record_decode_time at 0x10861df0>, <function after_draw_refresh at 0x10861870>]) 2016-11-03 18:21:20,641 client 1: gtk2.GLWindowBacking(2, (1589, 1026), GBRP).gl_context() GL Pixmap backing size: 1589 x 1026, context=gtk2.GLContextManager(<gtk.DrawingArea object at 0xb85d418 (GtkDrawingArea at 0x49ffb58)>) 2016-11-03 18:21:20,641 client 1: gtk2.GLWindowBacking(2, (1589, 1026), GBRP).update_planar_textures(147, 150, 854, 480, AVImageWrapper-None(YUV420P:(0, 0, 854, 480, 24):3_PLANES), 'YUV420P') 2016-11-03 18:21:20,642 client 1: Creating new planar textures, pixel format YUV420P 2016-11-03 18:21:20,642 client 1: updating planar textures: 854x480 YUV420P 2016-11-03 18:21:20,642 client 1: texture 0: div=(1, 1), rowstride=896, 854x480, data=430080 bytes, upload=zerocopy:buffer-as-memoryview 2016-11-03 18:21:20,642 client 1: texture 1: div=(2, 2), rowstride=448, 427x240, data=107520 bytes, upload=zerocopy:buffer-as-memoryview 2016-11-03 18:21:20,643 client 1: texture 2: div=(2, 2), rowstride=448, 427x240, data=107520 bytes, upload=zerocopy:buffer-as-memoryview 2016-11-03 18:21:20,644 client 1: gtk2.GLWindowBacking(2, (1589, 1026), YUV420P).render_planar_update(147, 150, 854, 480, 1, 1) pixel_format=YUV420P 2016-11-03 18:21:20,645 client 1: painting planar update, format YUV420P 2016-11-03 18:21:20,646 client 1: gtk2.GLWindowBacking(2, (1589, 1026), YUV420P).render_planar_update(..) texture_size=(854, 480), size=(1589, 1026) 2016-11-03 18:21:20,647 client 1: present_fbo: adding (147, 150, 854, 480) to pending paint list (size=0), flush=0, paint_screen=True 2016-11-03 18:21:20,647 client 1: Presenting FBO on screen 2016-11-03 18:21:20,647 client 1: Switching to RGB paint state 2016-11-03 18:21:20,650 client 1: do_present_fbo: painting [(147, 150, 854, 480)] 2016-11-03 18:21:20,651 client 1: gtk2.GLWindowBacking(2, (1589, 1026), YUV420P).gl_show() flushing 2016-11-03 18:21:20,651 client 1: gl_show after 118ms took 0ms, 1 updates 2016-11-03 18:21:20,651 client 1: gtk2.GLWindowBacking(2, (1589, 1026), YUV420P).gl_frame_terminator() 2016-11-03 18:21:20,652 client 1: Switching back to YUV paint state 2016-11-03 18:21:20,652 client 1: <OpenGL.platform.baseplatform.glBindFramebuffer object at 0xbf374f0>(GL_FRAMEBUFFER (36160), c_ulong(1L)) 2016-11-03 18:21:20,652 client 1: gtk2.GLWindowBacking(2, (1589, 1026), YUV420P).do_present_fbo() done 2016-11-03 18:21:20,652 client 1: record_decode_time(True, ) wid=2, h264: 854x480, 11.1ms 2016-11-03 18:21:20,653 client 1: after_draw_refresh(True, ) 854x480 at 147x150 encoding=h264, options={'speed': 95, 'type': 'P', 'pts': 41, 'frame': 1, 'encoding': 'h264', 'quality': 58, 'delayed': 1, 'csc': 'YUV420P'}
XPRA_X264_SLICED_THREADS=0
as a sole environment variable, which produced a different error entirely...
2016-11-03 18:42:57,239 compress: 0.8ms for 1589x150 pixels at 0,0 for wid=2 using rgb24 with ratio 2.6% ( 931KB to 23KB), sequence 295, client_options={'lz4': 1, 'rgb_format': 'BGRX'} 2016-11-03 18:42:57,259 client 1: draw_region(0, 633, 1589, 393, rgb24, 258285 bytes, 6356, {'flush': 3, 'lz4': 1, 'rgb_format': 'BGRX'}, [<function record_decode_time at 0x85f04b0>, <function after_draw_refresh at 0x85f0670>]) 2016-11-03 18:42:57,265 client 1: draw_region(147, 340, 854, 4, png, 435 bytes, 0, {'av-sync': True}, [<function record_decode_time at 0x85f0530>, <function after_draw_refresh at 0x85f08f0>]) 2016-11-03 18:42:57,266 client 1: gtk2.GLWindowBacking(2, (1589, 1026), None).do_paint_rgb(BGRX, 2497908 bytes, x=0, y=633, width=1589, height=393, rowstride=6356, options={'encoding': 'rgb24', 'flush': 3, 'lz4': 1, 'rgb_format': 'BGRX'}) 2016-11-03 18:42:57,266 client 1: gtk2.GLWindowBacking(2, (1589, 1026), None).gl_context() GL Pixmap backing size: 1589 x 1026, context=gtk2.GLContextManager(<gtk.DrawingArea object at 0x8676418 (GtkDrawingArea at 0x916b58)>) 2016-11-03 18:42:57,267 client 1: Switching to RGB paint state 2016-11-03 18:42:57,268 client 1: BGRX update at (0,633) size 1589x393 (2497908 bytes), stride=6356, row length 0, alignment 4, using GL zerocopy:buffer-as-memoryview format=BGRA 2016-11-03 18:42:57,268 client 1: present_fbo: adding (0, 633, 1589, 393) to pending paint list (size=0), flush=3, paint_screen=True 2016-11-03 18:42:57,269 client 1: record_decode_time(True, ) wid=2, rgb24: 1589x393, 7.3ms 2016-11-03 18:42:57,270 client 1: after_draw_refresh(True, ) 1589x393 at 0x633 encoding=rgb24, options={'encoding': 'rgb24', 'flush': 3, 'lz4': 1, 'rgb_format': 'BGRX'} 2016-11-03 18:42:57,270 client 1: gtk2.GLWindowBacking(2, (1589, 1026), None).do_paint_rgb(RGB, 10248 bytes, x=147, y=340, width=854, height=4, rowstride=2562, options={'av-sync': True, 'rgb_format': 'RGB', 'encoding': 'png'}) 2016-11-03 18:42:57,271 client 1: gtk2.GLWindowBacking(2, (1589, 1026), None).gl_context() GL Pixmap backing size: 1589 x 1026, context=gtk2.GLContextManager(<gtk.DrawingArea object at 0x8676418 (GtkDrawingArea at 0x916b58)>) 2016-11-03 18:42:57,278 client 1: Switching to RGB paint state 2016-11-03 18:42:57,279 client 1: RGB update at (147,340) size 854x4 (10248 bytes), stride=2562, row length 0, alignment 2, using GL zerocopy:buffer-as-memoryview format=RGB 2016-11-03 18:42:57,280 client 1: present_fbo: adding (147, 340, 854, 4) to pending paint list (size=1), flush=0, paint_screen=True 2016-11-03 18:42:57,281 client 1: Presenting FBO on screen 2016-11-03 18:42:57,282 client 1: Switching to RGB paint state 2016-11-03 18:42:57,282 client 1: do_present_fbo: painting [(0, 633, 1589, 393), (147, 340, 854, 4)] 2016-11-03 18:42:57,283 client 1: gtk2.GLWindowBacking(2, (1589, 1026), None).gl_show() flushing 2016-11-03 18:42:57,284 client 1: gl_show after 68ms took 1ms, 2 updates 2016-11-03 18:42:57,284 client 1: gtk2.GLWindowBacking(2, (1589, 1026), None).gl_frame_terminator() 2016-11-03 18:42:57,285 client 1: Switching back to YUV paint state 2016-11-03 18:42:57,285 client 1: <OpenGL.platform.baseplatform.glBindFramebuffer object at 0xb6554f0>(GL_FRAMEBUFFER (36160), c_ulong(2L)) 2016-11-03 18:42:57,286 client 1: gtk2.GLWindowBacking(2, (1589, 1026), None).do_present_fbo() done 2016-11-03 18:42:57,286 client 1: record_decode_time(True, ) wid=2, png: 854x4, 18.5ms 2016-11-03 18:42:57,287 client 1: after_draw_refresh(True, ) 854x4 at 147x340 encoding=png, options={'av-sync': True, 'encoding': 'png'} 2016-11-03 18:42:57,290 client 1: draw_region(1001, 150, 588, 483, rgb24, 200853 bytes, 2352, {'flush': 2, 'lz4': 1, 'rgb_format': 'BGRX'}, [<function record_decode_time at 0x85f0530>, <function after_draw_refresh at 0x85f08f0>]) 2016-11-03 18:42:57,291 client 1: draw_region(0, 150, 147, 483, rgb24, 1131 bytes, 588, {'flush': 1, 'lz4': 1, 'rgb_format': 'BGRX'}, [<function record_decode_time at 0x85f0670>, <function after_draw_refresh at 0x85f0a70>]) 2016-11-03 18:42:57,292 client 1: gtk2.GLWindowBacking(2, (1589, 1026), None).do_paint_rgb(BGRX, 1136016 bytes, x=1001, y=150, width=588, height=483, rowstride=2352, options={'encoding': 'rgb24', 'flush': 2, 'lz4': 1, 'rgb_format': 'BGRX'}) 2016-11-03 18:42:57,292 client 1: gtk2.GLWindowBacking(2, (1589, 1026), None).gl_context() GL Pixmap backing size: 1589 x 1026, context=gtk2.GLContextManager(<gtk.DrawingArea object at 0x8676418 (GtkDrawingArea at 0x916b58)>) 2016-11-03 18:42:57,293 client 1: Switching to RGB paint state 2016-11-03 18:42:57,294 client 1: BGRX update at (1001,150) size 588x483 (1136016 bytes), stride=2352, row length 0, alignment 8, using GL zerocopy:buffer-as-memoryview format=BGRA 2016-11-03 18:42:57,295 client 1: present_fbo: adding (1001, 150, 588, 483) to pending paint list (size=0), flush=2, paint_screen=True 2016-11-03 18:42:57,296 client 1: record_decode_time(True, ) wid=2, rgb24: 588x483, 3.4ms 2016-11-03 18:42:57,297 client 1: after_draw_refresh(True, ) 588x483 at 1001x150 encoding=rgb24, options={'encoding': 'rgb24', 'flush': 2, 'lz4': 1, 'rgb_format': 'BGRX'} 2016-11-03 18:42:57,298 client 1: gtk2.GLWindowBacking(2, (1589, 1026), None).do_paint_rgb(BGRX, 284004 bytes, x=0, y=150, width=147, height=483, rowstride=588, options={'encoding': 'rgb24', 'flush': 1, 'lz4': 1, 'rgb_format': 'BGRX'}) 2016-11-03 18:42:57,298 client 1: gtk2.GLWindowBacking(2, (1589, 1026), None).gl_context() GL Pixmap backing size: 1589 x 1026, context=gtk2.GLContextManager(<gtk.DrawingArea object at 0x8676418 (GtkDrawingArea at 0x916b58)>) 2016-11-03 18:42:57,299 client 1: Switching to RGB paint state 2016-11-03 18:42:57,299 client 1: BGRX update at (0,150) size 147x483 (284004 bytes), stride=588, row length 0, alignment 4, using GL zerocopy:buffer-as-memoryview format=BGRA 2016-11-03 18:42:57,299 client 1: present_fbo: adding (0, 150, 147, 483) to pending paint list (size=1), flush=1, paint_screen=True 2016-11-03 18:42:57,299 client 1: record_decode_time(True, ) wid=2, rgb24: 147x483, 5.9ms 2016-11-03 18:42:57,300 client 1: after_draw_refresh(True, ) 147x483 at 0x150 encoding=rgb24, options={'encoding': 'rgb24', 'flush': 1, 'lz4': 1, 'rgb_format': 'BGRX'} 2016-11-03 18:42:57,300 client 1: draw_region(0, 0, 1589, 150, rgb24, 24319 bytes, 6356, {'lz4': 1, 'rgb_format': 'BGRX'}, [<function record_decode_time at 0x85f0670>, <function after_draw_refresh at 0x85f0a70>]) 2016-11-03 18:42:57,300 client 1: gtk2.GLWindowBacking(2, (1589, 1026), None).do_paint_rgb(BGRX, 953400 bytes, x=0, y=0, width=1589, height=150, rowstride=6356, options={'encoding': 'rgb24', 'lz4': 1, 'rgb_format': 'BGRX'}) 2016-11-03 18:42:57,300 client 1: gtk2.GLWindowBacking(2, (1589, 1026), None).gl_context() GL Pixmap backing size: 1589 x 1026, context=gtk2.GLContextManager(<gtk.DrawingArea object at 0x8676418 (GtkDrawingArea at 0x916b58)>) 2016-11-03 18:42:57,301 client 1: Switching to RGB paint state 2016-11-03 18:42:57,301 client 1: BGRX update at (0,0) size 1589x150 (953400 bytes), stride=6356, row length 0, alignment 4, using GL zerocopy:buffer-as-memoryview format=BGRA 2016-11-03 18:42:57,302 client 1: present_fbo: adding (0, 0, 1589, 150) to pending paint list (size=2), flush=0, paint_screen=True 2016-11-03 18:42:57,302 client 1: Presenting FBO on screen 2016-11-03 18:42:57,304 client 1: Switching to RGB paint state 2016-11-03 18:42:57,307 client 1: do_present_fbo: painting [(1001, 150, 588, 483), (0, 150, 147, 483), (0, 0, 1589, 150)] 2016-11-03 18:42:57,308 client 1: gtk2.GLWindowBacking(2, (1589, 1026), None).gl_show() flushing 2016-11-03 18:42:57,309 client 1: gl_show after 31ms took 3ms, 3 updates 2016-11-03 18:42:57,310 client 1: gtk2.GLWindowBacking(2, (1589, 1026), None).gl_frame_terminator() 2016-11-03 18:42:57,311 client 1: Switching back to YUV paint state 2016-11-03 18:42:57,312 client 1: <OpenGL.platform.baseplatform.glBindFramebuffer object at 0xb6554f0>(GL_FRAMEBUFFER (36160), c_ulong(2L)) 2016-11-03 18:42:57,313 client 1: gtk2.GLWindowBacking(2, (1589, 1026), None).do_present_fbo() done 2016-11-03 18:42:57,314 client 1: record_decode_time(True, ) wid=2, rgb24: 1589x150, 11.0ms 2016-11-03 18:42:57,314 client 1: after_draw_refresh(True, ) 1589x150 at 0x0 encoding=rgb24, options={'encoding': 'rgb24', 'lz4': 1, 'rgb_format': 'BGRX'} 2016-11-03 18:42:57,888 Error: failed to encode x264 video frame: 2016-11-03 18:42:57,889 x264_encoder_encode produced no data (frame=0, frame-size=0, b-frames=0, delayed-frames=2) 2016-11-03 18:42:57,889 source: XShmImageWrapper(BGRX: 147, 150, 854, 483) 2016-11-03 18:42:57,889 options: {'av-sync': True} 2016-11-03 18:42:57,889 encoder: 2016-11-03 18:42:57,889 profile : high444 2016-11-03 18:42:57,890 generation : 12 2016-11-03 18:42:57,890 delayed : 2 2016-11-03 18:42:57,890 height : 482 2016-11-03 18:42:57,890 max-size : (8192, 4096) 2016-11-03 18:42:57,890 preset : superfast 2016-11-03 18:42:57,890 frames : 0 2016-11-03 18:42:57,891 quality : 50 2016-11-03 18:42:57,891 lossless : False 2016-11-03 18:42:57,891 frame-types : {} 2016-11-03 18:42:57,891 width : 854 2016-11-03 18:42:57,892 speed : 93 2016-11-03 18:42:57,892 source : unknown 2016-11-03 18:42:57,892 version : 148 2016-11-03 18:42:57,893 tune : zerolatency 2016-11-03 18:42:57,893 src_format : BGRX 2016-11-03 18:42:57,893 formats : ['YUV422P', 'RGB', 'BGRX', 'BGR', 'YUV420P', 'BGRA', 'YUV444P'] 2016-11-03 18:42:57,893 b-frames : 0 2016-11-03 18:42:57,893 buffer_api : 1 2016-11-03 18:42:57,954 Error: failed to encode x264 video frame: 2016-11-03 18:42:57,954 x264_encoder_encode produced no data (frame=0, frame-size=0, b-frames=0, delayed-frames=3) 2016-11-03 18:42:57,954 source: XShmImageWrapper(BGRX: 147, 150, 854, 483) 2016-11-03 18:42:57,954 options: {'av-sync': True} 2016-11-03 18:42:57,955 encoder: 2016-11-03 18:42:57,955 profile : high444 2016-11-03 18:42:57,955 generation : 12 2016-11-03 18:42:57,955 delayed : 3 2016-11-03 18:42:57,956 height : 482 2016-11-03 18:42:57,956 max-size : (8192, 4096) 2016-11-03 18:42:57,956 preset : superfast 2016-11-03 18:42:57,957 frames : 0 2016-11-03 18:42:57,957 quality : 50 2016-11-03 18:42:57,957 lossless : False 2016-11-03 18:42:57,957 frame-types : {} 2016-11-03 18:42:57,957 width : 854 2016-11-03 18:42:57,958 speed : 93 2016-11-03 18:42:57,958 source : unknown 2016-11-03 18:42:57,958 version : 148 2016-11-03 18:42:57,958 tune : zerolatency 2016-11-03 18:42:57,958 src_format : BGRX 2016-11-03 18:42:57,958 formats : ['YUV422P', 'RGB', 'BGRX', 'BGR', 'YUV420P', 'BGRA', 'YUV444P'] 2016-11-03 18:42:57,959 b-frames : 0 2016-11-03 18:42:57,959 buffer_api : 1 2016-11-03 18:42:58,009 Error: failed to encode x264 video frame: 2016-11-03 18:42:58,009 x264_encoder_encode produced no data (frame=0, frame-size=0, b-frames=0, delayed-frames=4) 2016-11-03 18:42:58,009 source: XShmImageWrapper(BGRX: 147, 150, 854, 483) 2016-11-03 18:42:58,010 options: {'av-sync': True} 2016-11-03 18:42:58,010 encoder: 2016-11-03 18:42:58,010 profile : high444 2016-11-03 18:42:58,010 generation : 12 2016-11-03 18:42:58,010 delayed : 4 2016-11-03 18:42:58,011 height : 482 2016-11-03 18:42:58,011 max-size : (8192, 4096) 2016-11-03 18:42:58,011 preset : superfast 2016-11-03 18:42:58,011 frames : 0 2016-11-03 18:42:58,011 quality : 50 2016-11-03 18:42:58,011 lossless : False 2016-11-03 18:42:58,012 frame-types : {} 2016-11-03 18:42:58,013 width : 854 2016-11-03 18:42:58,014 speed : 93 2016-11-03 18:42:58,014 source : unknown 2016-11-03 18:42:58,014 version : 148 2016-11-03 18:42:58,015 tune : zerolatency 2016-11-03 18:42:58,015 src_format : BGRX 2016-11-03 18:42:58,015 formats : ['YUV422P', 'RGB', 'BGRX', 'BGR', 'YUV420P', 'BGRA', 'YUV444P'] 2016-11-03 18:42:58,015 b-frames : 0 2016-11-03 18:42:58,016 buffer_api : 1 2016-11-03 18:42:58,091 Error: failed to encode x264 video frame: 2016-11-03 18:42:58,092 x264_encoder_encode produced no data (frame=0, frame-size=0, b-frames=0, delayed-frames=5) 2016-11-03 18:42:58,092 source: XShmImageWrapper(BGRX: 147, 150, 854, 483) 2016-11-03 18:42:58,092 options: {'av-sync': True} 2016-11-03 18:42:58,092 encoder: 2016-11-03 18:42:58,092 profile : high444 2016-11-03 18:42:58,092 generation : 12 2016-11-03 18:42:58,092 delayed : 5 2016-11-03 18:42:58,092 height : 482 2016-11-03 18:42:58,093 max-size : (8192, 4096) 2016-11-03 18:42:58,093 preset : superfast 2016-11-03 18:42:58,093 frames : 0 2016-11-03 18:42:58,093 quality : 50 2016-11-03 18:42:58,093 lossless : False 2016-11-03 18:42:58,093 frame-types : {} 2016-11-03 18:42:58,093 width : 854 2016-11-03 18:42:58,093 speed : 93 2016-11-03 18:42:58,093 source : unknown 2016-11-03 18:42:58,093 version : 148 2016-11-03 18:42:58,093 tune : zerolatency 2016-11-03 18:42:58,093 src_format : BGRX 2016-11-03 18:42:58,094 formats : ['YUV422P', 'RGB', 'BGRX', 'BGR', 'YUV420P', 'BGRA', 'YUV444P'] 2016-11-03 18:42:58,094 b-frames : 0 2016-11-03 18:42:58,094 buffer_api : 1 2016-11-03 18:42:58,155 x264 encode BGRX frame 0 as IDR slice with 4 nals, tune=zerolatency, total 11851 bytes, keyframe=True , delayed=5 2016-11-03 18:42:58,156 compress: 9.9ms for 854x482 pixels at 147,150 for wid=2 using h264 with ratio 0.7% ( 1611KB to 11KB), sequence 296, client_options={'pts': 0, 'frame': 0, 'delayed': 5, 'csc': 'YUV444P', 'type': 'IDR', 'quality': 50, 'speed': 94}
... which makes me suspect that both of those environment variables are required to deal with the errors... though I haven't yet tested with just the other disabled.
Sorry about that, it's all quite embarrassing:
XPRA_B_FRAMES=0
was not being honoured (quickly spotted because your output had b-frames=1
for the x264 encoder, that's fixed in r14392
XPRA_X264_SLICED_THREADS=0
errors I can reproduce very easily - I'm not sure why that breaks (maybe we just can't use frame threading without b-frames?), and we don't care - let's just avoid changing this setting for now
I believe those errors should now all be gone - though I don't doubt for one second your ability to turn up some more.
Well... re-tested with 1.0 r14155 osx client (again... might check into our capability to build for ourselves soon) against a newly built 1.0 r14399 fedora 23 server.
The good news is that, with XPRA_B_FRAMES=0
... I'm no longer seeing any sign of the avcodec errors.
The (possibly equally good?) other news is that, without that environment variable I am still... eventually... able to repro (usually by scrolling and mousing madly over a browser tab playing video, then getting up to get a snack or beverage... by the time I'm back, I've got an error in logs, though obviously haven't seen anything).
Server-side, without disabling B-Frames... with -d stat,x264,compress
...
... 2016-11-07 17:36:54,679 x264 close context 0x0 2016-11-07 17:36:54,686 x264 encode 1 delayed frames after 0 2016-11-07 17:36:54,692 compress: 26.0ms for 854x480 pixels at 147,150 for wid=2 using jpeg with ratio 1.2% ( 1601KB to 19KB), sequence 8335, client_options={'quality': 70} 2016-11-07 17:36:54,702 x264 encode YUV420P frame 0 as IDR slice with 7 nals, tune=film, total 6772 bytes, keyframe=True , delayed=1 2016-11-07 17:36:54,702 compress: 10.2ms for 854x480 pixels at 147,150 for wid=2 using h264 with ratio 0.4% ( 1601KB to 6KB), sequence 8336, client_options={'pts': 0, 'frame': 0, 'delayed': 1, 'csc': 'YUV420P', 'paint': False, 'type': 'IDR', 'quality': 30, 'speed': 96} 2016-11-07 17:36:54,716 x264 encode YUV420P frame 1 as P slice with 4 nals, tune=film, total 497 bytes, keyframe=False, delayed=1 2016-11-07 17:36:54,717 compress: 13.9ms for 854x480 pixels at 147,150 for wid=2 using h264 with ratio 0.0% ( 1601KB to 0KB), sequence 8337, client_options={'pts': 23, 'frame': 1, 'delayed': 1, 'csc': 'YUV420P', 'type': 'P', 'quality': 30, 'speed': 96} 2016-11-07 17:36:54,717 rgb_encode using level=0, not compressed 256x174 in rgb24/BGRX: 178176 bytes down to 178176 2016-11-07 17:36:54,718 compress: 0.9ms for 256x174 pixels at 508,852 for wid=2 using rgb24 with ratio 100.0% ( 174KB to 174KB), sequence 8338, client_options={'rgb_format': 'BGRX'} 2016-11-07 17:36:54,728 x264 encode YUV420P frame 2 as B slice with 4 nals, tune=film, total 105 bytes, keyframe=False, delayed=1 2016-11-07 17:36:54,728 compress: 9.9ms for 854x480 pixels at 147,150 for wid=2 using h264 with ratio 0.0% ( 1601KB to 0KB), sequence 8339, client_options={'pts': 12, 'frame': 2, 'delayed': 1, 'csc': 'YUV420P', 'type': 'B', 'quality': 30, 'speed': 96} 2016-11-07 17:36:54,739 client 1: Error: avcodec error -35 decoding 6772 bytes of h264 data: 2016-11-07 17:36:54,740 client 1: 'Resource temporarily unavailable' 2016-11-07 17:36:54,740 client 1: frame 0 2016-11-07 17:36:54,741 client 1: options={'pts': 0, 'encoding': 'h264', 'type': 'IDR', 'frame': 0, 'delayed': 1, 'csc': 'YUV420P', 'paint': False, 'quality': 30, 'speed': 96} 2016-11-07 17:36:54,741 client 1: decoder state: 2016-11-07 17:36:54,741 client 1: decoder_height = 480 2016-11-07 17:36:54,742 client 1: encoding = h264 2016-11-07 17:36:54,742 client 1: colorspace = YUV420P 2016-11-07 17:36:54,743 client 1: actual_colorspace = YUV420P 2016-11-07 17:36:54,743 client 1: height = 480 2016-11-07 17:36:54,743 client 1: decoder_width = 854 2016-11-07 17:36:54,744 x264 encode YUV420P frame 3 as P slice with 4 nals, tune=film, total 947 bytes, keyframe=False, delayed=1 2016-11-07 17:36:54,744 client 1: width = 854 2016-11-07 17:36:54,745 compress: 16.0ms for 854x480 pixels at 147,150 for wid=2 using h264 with ratio 0.1% ( 1601KB to 0KB), sequence 8340, client_options={'pts': 53, 'frame': 3, 'delayed': 1, 'csc': 'YUV420P', 'type': 'P', 'quality': 30, 'speed': 96} 2016-11-07 17:36:54,745 client 1: version = (57, 48, 101) 2016-11-07 17:36:54,746 client 1: formats = ['YUV422P', 'BGRX', 'GBRP', 'RGB', 'YUV420P', 'BGRA', 'ARGB', 'XRGB', 'YUV444P'] 2016-11-07 17:36:54,746 client 1: frames = 0 2016-11-07 17:36:54,747 client 1: type = avcodec 2016-11-07 17:36:54,755 x264 encode YUV420P frame 4 as B slice with 4 nals, tune=film, total 76 bytes, keyframe=False, delayed=1 2016-11-07 17:36:54,755 compress: 9.4ms for 854x480 pixels at 147,150 for wid=2 using h264 with ratio 0.0% ( 1601KB to 0KB), sequence 8341, client_options={'pts': 39, 'frame': 4, 'delayed': 1, 'csc': 'YUV420P', 'type': 'B', 'quality': 30, 'speed': 96} 2016-11-07 17:36:54,766 x264 encode YUV420P frame 5 as P slice with 4 nals, tune=film, total 1849 bytes, keyframe=False, delayed=1 2016-11-07 17:36:54,767 compress: 11.1ms for 854x480 pixels at 147,150 for wid=2 using h264 with ratio 0.1% ( 1601KB to 1KB), sequence 8342, client_options={'pts': 76, 'frame': 5, 'delayed': 1, 'csc': 'YUV420P', 'type': 'P', 'quality': 30, 'speed': 96} 2016-11-07 17:36:54,774 x264 encode YUV420P frame 6 as B slice with 4 nals, tune=film, total 115 bytes, keyframe=False, delayed=1 2016-11-07 17:36:54,775 compress: 7.7ms for 854x480 pixels at 147,150 for wid=2 using h264 with ratio 0.0% ( 1601KB to 0KB), sequence 8343, client_options={'pts': 66, 'frame': 6, 'delayed': 1, 'csc': 'YUV420P', 'type': 'B', 'quality': 30, 'speed': 96} 2016-11-07 17:36:54,785 x264 encode YUV420P frame 7 as P slice with 4 nals, tune=film, total 1255 bytes, keyframe=False, delayed=1 2016-11-07 17:36:54,786 compress: 10.4ms for 854x480 pixels at 147,150 for wid=2 using h264 with ratio 0.1% ( 1601KB to 1KB), sequence 8344, client_options={'pts': 95, 'frame': 7, 'delayed': 1, 'csc': 'YUV420P', 'type': 'P', 'quality': 30, 'speed': 96} 2016-11-07 17:36:54,796 x264 encode YUV420P frame 8 as B slice with 4 nals, tune=film, total 79 bytes, keyframe=False, delayed=1 ...
I assume having the error show up whenever b-frames are enabled isn't a place to close this, so I'll hand it back to you.
Please re-test with an up to date client, the client 1: Error: avcodec error -35 decoding 6772 bytes of h264 data..
error was fixed in r14393.
Tried to re-test with 1.0 r14397 osx client, against 1.0 r14404 fedora 23 server... but client wouldn't launch (#1355 missing dyld library).
Tried to re-retest with 1.0 r14397 win client, with intel 4000 graphics and --opengl=on
forced... added some new opengl error messages to the end of #1111.
Testing with 1.0 r14397 win client without OpenGL... I no longer see any avcodec errors.
I'll pass this back to help ensure you glance at the errors added to #1111 to be sure there's nothing new there... and if the opengl isn't liable to impact the avcodec potential issues, then this can probably be closed.
opengl or not shouldn't make any difference, so closing.
this ticket has been moved to: https://github.com/Xpra-org/xpra/issues/1346