Investigating frames pile-up

Thursday, July 13, 2017

Investigating the frames pile-up in the spice client. With the help of Pavel, I added some code that clears the queue above a given size. And I can see that the queue fills up to 100 pretty quickly, then clears it.

There are also really long pauses sometimes, and that occasionally leads the server to drop the connection.

Investigating black screen

Investigating the black screen at startup on macOS. I see issues with the way the code compares multimedia times. For example, in channel-display-gst.c function schedule_frame, there is:

if (now < gstframe->frame->mm_time) {
    decoder->timer_id = g_timeout_add(gstframe->frame->mm_time - now,
                                      display_frame, decoder);
}

I would rather have a test that works OK when mm_time wraps around.

But this does not appear to be the root cause for my problem. After adding some instrumentation, I see this: 

channel-display-gst.c:170: [1551 4.170746] gst_schedule_frame: Schedule frame now=3534 timer_id=0
channel-display-gst.c:188: [1553 4.170969] frame_timer: Id 345 scheduled display in 764218667 ms
channel-display-gst.c:170: [1579 4.248549] gst_schedule_frame: Schedule frame now=3612 timer_id=345
channel-display-gst.c:170: [1591 4.295388] gst_schedule_frame: Schedule frame now=3659 timer_id=345
channel-display-gst.c:170: [1600 4.337092] gst_schedule_frame: Schedule frame no

In the working case, the base stream time used for now is correctly initialized: 

channel-display-gst.c:170: [1226 4.217059] gst_schedule_frame: Schedule frame now=764809994 timer_id=0
channel-display-gst.c:182: [1227 4.217165] gst_schedule_frame_time: Got frame 0x7fd8e0e60020 time=764806684 now=764809994 queue length=1
channel-display-gst.c:195: [1228 4.217195] frame_timer: Id 324 scheduled immediate display
channel-display-gst.c:170: [1230 4.221323] gst_schedule_frame: Schedule frame now=764809999 timer_id=0
channel-display-gst.c:170: [1240 4.308875] gst_schedule_frame: Schedule frame now=764810086 timer_id=0
channel-display-gst.c:182: [1241 4.308926] gst_schedule_frame_time: Got frame 0x7fd8e0e61ca0 time=764806697 now=764810086 queue length=1
channel-display-gst.c:195: [1242 4.308960] frame_timer: Id 327 scheduled immediate display

Instrumented the multimedia time, and it looks like there is a problem with the time being artificially reset: 

spice-session.c:2326: [151 2.031737] mm_time: Get mm_time=95269027, time_at_clock=0, delta=95269027
spice-session.c:2326: [152 2.032402] mm_time: Get mm_time=778414140, time_at_clock=95269028576, delta=0
spice-session.c:2347: [153 2.032424] mm_time: Set mm_time: 778414140, time_at_clock=95269028576, returned=778414140
spice-session.c:2350: [154 2.032440] mm_time: reset, new 778414140, old 95269027
spice-session.c:2326: [363 2.995109] mm_time: Get mm_time=778415102, time_at_clock=95269028576, delta=962
spice-session.c:2326: [364 2.995171] mm_time: Get mm_time=0, time_at_clock=95269991384, delta=0
spice-session.c:2347: [365 2.995190] mm_time: Set mm_time: 0, time_at_clock=95269991384, returned=0
spice-session.c:2350: [366 2.995204] mm_time: reset, new 0, old 778415102
spice-session.c:2326: [802 9.866806] mm_time: Get mm_time=6871, time_at_clock=95269991384, delta=6871
spice-session.c:2326: [811 9.867432] mm_time: Get mm_time=6872, time_at_clock=95269991384, delta=6872
spice-session.c:2326: [820 9.868415] mm_time: Get mm_time=6873, time_at_clock=95269991384, delta=6873
spice-session.c:2326: [829 9.868613] mm_time: Get mm_time=6873, time_at_clock=95269991384, delta=6873
spice-session.c:2326: [838 9.868968] mm_time: Get mm_time=6874,
time_at_clock=9526

The part that looks suspicious to me is: 

spice-session.c:2326: [363 2.995109] mm_time: Get mm_time=778415102, time_at_clock=95269028576, delta=962
spice-session.c:2326: [364 2.995171] mm_time: Get mm_time=0, time_at_clock=95269991384, delta=0
spice-session.c:2347: [365 2.995190] mm_time: Set mm_time: 0, time_at_clock=95269991384, returned=0

The time was good, and we overwrite it with 0. Printed the session in case we are getting the time from a different session. That's not the case. Added more instrumentation, notably with a record at the call sites for spice_session_set_mm_time. Of course, the problem becomes much harder to reproduce as soon as you want to see it.

The culprit appears to be spice_playback_channel_set_delay: 

channel-main.c:1644: [151 0.766052] mm_time: Init 780764832
spice-session.c:2326: [152 0.766164] mm_time: Get mm_time=97619656, time_at_clock=0, delta=97619656
spice-session.c:2346: [153 0.766181] mm_time: Set mm_time: 780764832, time_at_clock=97619656485
spice-session.c:2349: [154 0.766193] mm_time: reset, new 780764832, old 97619656
channel-playback.c:475: [363 0.941538] mm_time: Delay set to 0 last=0 delay=0
spice-session.c:2326: [364 0.941586] mm_time: Get mm_time=780765007, time_at_clock=97619656485, delta=175

Next problem: delays during playback

The next problem coming up is delays during playback. Apparently, there is another problem with multimedia time: 

channel-display-gst.c:195: [4111 46.753883] frame_timer: Id 1147 scheduled immediate display
spice-channel.c:1168: [4112 46.754073] channel_read: Read 6 bytes from display-2:1
spice-channel.c:1192: [4113 46.754098] channel_read: Read 6 bytes from display-2:1, total 817027
spice-channel.c:1168: [4114 46.754102] channel_read: Read 3275 bytes from display-2:1
spice-channel.c:1192: [4115 46.754188] channel_read: Read 3275 bytes from display-2:1, total 820302
spice-session.c:2326: [4116 46.754198] mm_time: Get mm_time=783843894, time_at_clock=100652774572, delta=45995
channel-display.c:1487: [4117 46.754199] channel: display-2:1: stream data too late by 1538 ms (ts: 783842356, mmtime: 783843894), dropping
channel-display-gst.c:577: [4118 46.754203] gst_queue_stats: Frame size 3263 length 92
spice-channel.c:1168: [4119 46.754232] channel_read: Read 6 bytes from display-2:1
spice-channel.c:1192: [4120 46.754241] channel_read: Read 6 bytes from display-2:1, total 820308
spice-channel.c:1168: [4121 46.754244] channel_read: Read 3631 bytes from display-2:1
spice-channel.c:1192: [4122 46.754282] channel_read: Read 3631 bytes from display-2:1, total 823939
spice-session.c:2326: [4123 46.754286] mm_time: Get mm_time=783843894, time_at_clock=100652774572, delta=45995
channel-display.c:1487: [4124 46.754287] channel: display-2:1: stream data too late by 1481 ms (ts: 783842413, mmtime: 783843894), dropping
channel-display-gst.c:577: [4125 46.754288] gst_queue_stats: Frame size 3619 length 93
channel-display-gst.c:150: [4126 46.754337] display_frame: Display 0x7f941a581740 ts 783838798 size 1600x1200
spice-session.c:2326: [4127 46.756853] mm_time: Get mm_time=783843897, time_at_clock=100652774572, delta=45998
channel-display-gst.c:170: [4128 46.756854] gst_schedule_frame: Schedule frame now=783843897 timer_id=0
channel-display-gst.c:240: [4129 46.788202] new_sample: Frame timestamp 39071
spice-session.c:2326: [4130 46.788207] mm_time: Get mm_time=783843928, time_at_clock=100652774572, delta=46029
channel-display-gst.c:170: [4131 46.788207] gst_schedule_frame: Schedule frame now=783843928 timer_id=0
channel-display-gst.c:182: [4132 46.788208] gst_schedule_frame_time: Got frame 0x7f941a7d9cd0 time=783838821 now=783843928 queue length=1
channel-display-gst.c:195: [4133 46.788228] frame_timer: Id 1149 scheduled immediate display
recorder/recorder.c:1472: [4134 46.851783] signals: Received signal Information request: 29 (29) si_addr=0x7fff79ef8856, dumping recorder
recorder/recorder.c:716: [4135 46.851795] recorders: Recorder dump
channel-display-gst.c:240: [4136 46.856843] new_sample: Frame timestamp 39072
spice-session.c:2326: [4137 46.856849] mm_time: Get mm_time=783843997, time_at_clock=100652774572, delta=46098
channel-display-gst.c:170: [4138 46.856849] gst_schedule_frame: Schedule frame now=783843997 timer_id=1149
channel-display-gst.c:200: [4250 47.198329] gst_schedule_frame_warning: Rendering too late by 5352 ms (ts: 783838986, mmtime: 783844338), dropping
channel-display-gst.c:200: [4288 47.380259] gst_schedule_frame_warning: Rendering too late by 5406 ms (ts: 783839114, mmtime: 783844520), dropping
channel-display-gst.c:200: [4290 47.380314] gst_schedule_frame_warning: Rendering too late by 5371 ms (ts: 783839149, mmtime: 783844520), dropping
channel-display-gst.c:200: [4376 47.515846] gst_schedule_frame_warning: Rendering too late by 5350 ms (ts: 783839306, mmtime: 783844656), dropping
channel-display-gst.c:200: [4525 47.924888] gst_schedule_frame_warning: Rendering too late by 5421 ms (ts: 783839644, mmtime: 783845065), dropping

Red Skin Cat

Daily rants and notes about my work on Spice at Red Hat

July 2017
Sun Mon Tue Wed Thu Fri Sat
1
2 3 4 5 6 7 8
9 10 11 12 13 14 15
16 17 18 19 20 21 22
23 24 25 26 27 28 29
30 31
Jun  Aug
RSS

Links

This is the work blog of Christophe de Dinechin for Red Hat. Think of it as a public lab book.

This should not be particularly interesting except to myself. It's really more intended as a set of personal notes, so there is no formatting whatsoever. I type tings as I go along during the day. All you'll find here are things like stack traces, Linux commands I want to remember or bugzilla links I want to be able to return to.

If you want to read stuff about my work at Red Hat that I believe is more interesting to the general public, you will find it on A Spice Odyssey. If you want to read my rants about everything else, go to Grenouille Bouillie. This is about as much advertisement as you will find on this site.

2016-2017 - Christophe de Dinechin

All views expressed on this blog are strictly personal. This blog does not represent the views of my employer, nor mine for that matter. This blog is provided as-is, without warrrany of any kind, express or implied, in particular regarding accuracy or interest of the content. The contents of this blog is distributed under a Creative Commons BY-SA 4.0 license .