[Spice-devel] [PATCH spice-common 0/4] RFC: add structured logging and log category
Christophe de Dinechin
cdupontd at redhat.com
Wed Jun 14 17:21:21 UTC 2017
> On 14 Jun 2017, at 17:06, Christophe Fergeau <cfergeau at redhat.com> wrote:
>
> On Wed, Jun 14, 2017 at 10:44:49AM +0200, Christophe de Dinechin wrote:
>>
>>> On 13 Jun 2017, at 12:17, Marc-André Lureau <marcandre.lureau at redhat.com> wrote:
>>>
>>
>>>> - Better memory locality (not wasting a whole cache line for a single flag)
>>>
>>> minor, because log is not for hot traces.
>>
>> My experience differs from yours, and as a result, the idea that “log is not for hot traces" seems particularly wrong to me. In a real-time system, if your logging system cannot properly instrument the hot paths, then your logging system is at fault, not the idea of instrumenting the hot paths, and even less the idea of designing a mechanism capable of efficiently instrumenting hot paths.
>>
>> Since Spice is a real-time system, it would have expected (and I really want, sooner better than later):
>>
>> a) a logging system that knows how to record stuff and print it out efficiently.
>> b) a tracing system that lets me view selected things as they happen, including in hot paths
>> c) a flight-recorder recording information continuously and dumping useful data after specific events, e.g. crash, signal, assert, etc.
>> d) performance probes, to continuously measure key things and report them
>> e) a tuning / tweaking system, to adjust internal parameters, ideally on a running system, and observe the effect
>>
>> As far as I can tell, only (a) logging exists today. Why don’t we have the rest? And why is there such a strong push-back from you when I suggest we add it?
>>
>> If you really believe this is useless, then I have to disagree with you. To support my opinion for each category above:
>>
>> a) Being able to improve logging is obviously a hot topic, meaning the current state is not considered satisfactory.
>> b) commented-out calls to spice_msg_in_hexdump. Ask yourself, why is this code commented out?
>
> I would blame that on the lack of an easy way to hide at runtime this
> verbose dump by default, and reenable it when needed. Which both your
> proposal and Marc André's solve.
>
>> c) Bugs which we have to be able to reproduce, because there is no
>> useful information in the debug log, e.g.
>> https://bugzilla.redhat.com/show_bug.cgi?id=1017261. Here, we know an
>> assertion failed, but nothing about what happened to get there, so you
>> can only guess and try to reproduce. Reported in 2013, not solved, and
>> probably not much progress made since then.
>
> We can switch to Marc-André's suggestion, or we can switch to yours,
> none of them will help us to solve this bug ;)
> More/better logs is what _may_ help, which we could even have with the
> current logging system..
In the message above, part c) is having a flight recorder that, AFTER we crash, dumps something that was recorded BEFORE the crash. Below is an example output from my current experimental branch (https://github.com/c3d/spice-gtk/compare/master...c3d:recorder). What I did is send a SIGBUS to the process with killall while it was running (please check if you can figure that out from the dump :-), but of course the same thing would happen with a real crash.
The key point I was making with my example for (c) is is that if we had this amount of information in case of crash, in many cases we would not need to re-do a run with some debug option, or reproduce the problem. The information would already be right there. And I would like you to compare the amount of available information available today (the lines beginning with (spicy:78043) with the amount of information the recorder dump gives me (the rest).
ddd at ptitpuce[recorder] spice-gtk> spicy -h turbo -p 5901
(process:78043): Gtk-WARNING **: Locale not supported by C library.
Using the fallback 'C' locale.
2017-06-14 18:57:01.165 spicy[78043:24824016] *** WARNING: Method userSpaceScaleFactor in class NSView is deprecated on 10.7 and later. It should not be used in new applications. Use convertRectToBacking: instead.
** Message: main channel: opened
(spicy:78043): GSpice-CRITICAL **: spice_playback_channel_set_delay: assertion 'SPICE_IS_PLAYBACK_CHANNEL(channel)' failed
(spicy:78043): GLib-GObject-CRITICAL **: g_object_get: assertion 'G_IS_OBJECT (object)' failed
(spicy:78043): GLib-GObject-CRITICAL **: g_object_unref: assertion 'G_IS_OBJECT (object)' failed
(spicy:78043): GLib-GObject-CRITICAL **: g_object_get: assertion 'G_IS_OBJECT (object)' failed
(spicy:78043): GLib-GObject-CRITICAL **: g_object_unref: assertion 'G_IS_OBJECT (object)' failed
(spicy:78043): Spice-WARNING **: channel-display-gst.c:339:create_pipeline: GStreamer error: pas d??l?ment ??vp8dec??
(spicy:78043): Spice-WARNING **: channel-display-gst.c:339:create_pipeline: GStreamer error: pas d??l?ment ??vp9dec??
(spicy:78043): Spice-WARNING **: channel-display-gst.c:339:create_pipeline: GStreamer error: pas d??l?ment ??vp8dec??
(spicy:78043): Spice-WARNING **: channel-display-gst.c:339:create_pipeline: GStreamer error: pas d??l?ment ??vp9dec??
(spicy:78043): Gdk-WARNING **: GdkQuartzDisplay does not implement the monitor vfuncs
Received signal 10, dumping recorder
0 [0.000000:0x103efd9ec] MAIN: spicy starts with 5 args
1 [0.000011:0x103efda17] MAIN: Installing signal handlers
2 [0.003671:0x103efdb21] MAIN: Configuration file /Users/ddd/.config/spicy/settings
3 [0.176761:0x103efdd14] MAIN: Created main loop 0x7fc2b1d1ae90
8 [0.223439:0x103efddc6] MAIN: Initial connection path <NULL> host turbo port 5901 tls-port <NULL>
9 [0.223440:0x103efde3f] MAIN: Connect 0x7fc2b1d1ba40
419 [1.280683:0x103f2158c] DISPLAY: 0:0recalc geom monitor: 0:0
420 [1.280688:0x103f2158c] DISPLAY: 0:0recalc geom monitor: 0:0
421 [1.280691:0x103f2158c] DISPLAY: 0:0recalc geom monitor: 0:0
422 [1.280693:0x103f2158c] DISPLAY: 0:0recalc geom monitor: 0:0
423 [1.280694:0x103f2158c] DISPLAY: 0:0recalc geom monitor: 0:0
424 [1.280697:0x103f211a4] DISPLAY: 0:0keypress-delay is set to 100 ms
425 [1.280704:0x103f2158c] DISPLAY: 0:0recalc geom monitor: 0:0
426 [1.280705:0x103f2158c] DISPLAY: 0:0recalc geom monitor: 0:0
427 [1.280748:0x103f1fea9] DISPLAY: 0:0mouse mode 2 (client
429 [1.280862:0x103f1966c] DISPLAY: 0:0update monitor area
430 [1.280867:0x103f19cbd] DISPLAY: 0:0update area +0+0
431 [1.280867:0x103f19e3b] DISPLAY: 0:0primary: 720x400
432 [1.280878:0x103f2158c] DISPLAY: 0:0recalc geom monitor: 0:0
433 [1.280879:0x103f20396] DISPLAY: 0:0widget mark: 0, display 0x7fc2b2980460
434 [1.282159:0x103f2158c] DISPLAY: 0:0recalc geom monitor: 0:0
435 [1.282164:0x103f2158c] DISPLAY: 0:0recalc geom monitor: 0:0
436 [1.282192:0x103f2158c] DISPLAY: 0:0recalc geom monitor: 0:0
440 [1.282334:0x103f2158c] DISPLAY: 0:0recalc geom monitor: 0:0
444 [2.276572:0x103f2158c] DISPLAY: 0:0recalc geom monitor: 0:0
445 [2.377078:0x103f22232] VNC: Using OS-X virtual keycode mapping
463 [2.448142:0x103f20396] DISPLAY: 0:0widget mark: 1, display 0x7fc2b2980460
485 [2.484121:0x103f2158c] DISPLAY: 1:0recalc geom monitor: 1:0
486 [2.484123:0x103f2158c] DISPLAY: 1:0recalc geom monitor: 1:0
487 [2.484125:0x103f2158c] DISPLAY: 1:0recalc geom monitor: 1:0
488 [2.484126:0x103f2158c] DISPLAY: 1:0recalc geom monitor: 1:0
489 [2.484127:0x103f2158c] DISPLAY: 1:0recalc geom monitor: 1:0
490 [2.484129:0x103f211a4] DISPLAY: 1:0keypress-delay is set to 100 ms
491 [2.484132:0x103f2158c] DISPLAY: 1:0recalc geom monitor: 1:0
492 [2.484134:0x103f2158c] DISPLAY: 1:0recalc geom monitor: 1:0
493 [2.484160:0x103f1fea9] DISPLAY: 1:0mouse mode 2 (client
495 [2.484196:0x103f1966c] DISPLAY: 1:0update monitor area
496 [2.484199:0x103f19cbd] DISPLAY: 1:0update area +0+0
497 [2.484200:0x103f19e3b] DISPLAY: 1:0primary: 1600x1200
498 [2.484202:0x103f2158c] DISPLAY: 1:0recalc geom monitor: 1:0
499 [2.484202:0x103f20396] DISPLAY: 1:0widget mark: 0, display 0x7fc2b2980760
500 [2.484833:0x103f2158c] DISPLAY: 1:0recalc geom monitor: 1:0
501 [2.484836:0x103f2158c] DISPLAY: 1:0recalc geom monitor: 1:0
502 [2.484897:0x103f2158c] DISPLAY: 1:0recalc geom monitor: 1:0
506 [2.485042:0x103f2158c] DISPLAY: 1:0recalc geom monitor: 1:0
510 [2.490692:0x103f2158c] DISPLAY: 1:0recalc geom monitor: 1:0
511 [2.502822:0x103f22232] VNC: Using OS-X virtual keycode mapping
527 [2.548646:0x103f20396] DISPLAY: 1:0widget mark: 1, display 0x7fc2b2980760
3866 [10.139954:0x103f94e5f] DEBUG: schedule_frame: rendering too late by 2726 ms (ts: 700192745, mmtime: 700195471
3877 [10.196200:0x103f443c7] DEBUG: spice_session_sync_playback_latency: not implemented when there isn't audio playback
3883 [10.198341:0x103f94e5f] DEBUG: schedule_frame: rendering too late by 2734 ms (ts: 700192795, mmtime: 700195529
3899 [10.314015:0x103f94e5f] DEBUG: schedule_frame: rendering too late by 2767 ms (ts: 700192878, mmtime: 700195645
3905 [10.314311:0x103f443c7] DEBUG: spice_session_sync_playback_latency: not implemented when there isn't audio playback
3931 [10.376283:0x103f443c7] DEBUG: spice_session_sync_playback_latency: not implemented when there isn't audio playback
3942 [10.378533:0x103f94e5f] DEBUG: schedule_frame: rendering too late by 2764 ms (ts: 700192945, mmtime: 700195709
3943 [10.435039:0x103f94e5f] DEBUG: schedule_frame: rendering too late by 2771 ms (ts: 700192995, mmtime: 700195766
3959 [10.435383:0x103f443c7] DEBUG: spice_session_sync_playback_latency: not implemented when there isn't audio playback
3960 [10.492842:0x103f94e5f] DEBUG: schedule_frame: rendering too late by 2778 ms (ts: 700193045, mmtime: 700195823
3989 [10.557610:0x103f443c7] DEBUG: spice_session_sync_playback_latency: not implemented when there isn't audio playback
4000 [10.559919:0x103f94e5f] DEBUG: schedule_frame: rendering too late by 2779 ms (ts: 700193112, mmtime: 700195891
4006 [10.612549:0x103f94e5f] DEBUG: schedule_frame: rendering too late by 2781 ms (ts: 700193162, mmtime: 700195943
4017 [10.612796:0x103f443c7] DEBUG: spice_session_sync_playback_latency: not implemented when there isn't audio playback
4023 [10.676239:0x103f94e5f] DEBUG: schedule_frame: rendering too late by 2796 ms (ts: 700193211, mmtime: 700196007
4039 [10.743125:0x103f94e5f] DEBUG: schedule_frame: rendering too late by 2812 ms (ts: 700193262, mmtime: 700196074
4040 [10.743132:0x103f94e5f] DEBUG: schedule_frame: rendering too late by 2796 ms (ts: 700193278, mmtime: 700196074
4046 [10.743401:0x103f443c7] DEBUG: spice_session_sync_playback_latency: not implemented when there isn't audio playback
4072 [10.792143:0x103f443c7] DEBUG: spice_session_sync_playback_latency: not implemented when there isn't audio playback
4073 [10.794589:0x103f94e5f] DEBUG: schedule_frame: rendering too late by 2794 ms (ts: 700193331, mmtime: 700196125
4082 [10.859181:0x103f94e5f] DEBUG: schedule_frame: rendering too late by 2811 ms (ts: 700193379, mmtime: 700196190
4103 [10.920043:0x103f443c7] DEBUG: spice_session_sync_playback_latency: not implemented when there isn't audio playback
4114 [10.922512:0x103f94e5f] DEBUG: schedule_frame: rendering too late by 2809 ms (ts: 700193444, mmtime: 700196253
4125 [10.976031:0x103f94e5f] DEBUG: schedule_frame: rendering too late by 2813 ms (ts: 700193494, mmtime: 700196307
4131 [11.033579:0x103f443c7] DEBUG: spice_session_sync_playback_latency: not implemented when there isn't audio playback
4142 [11.035771:0x103f94e5f] DEBUG: schedule_frame: rendering too late by 2822 ms (ts: 700193544, mmtime: 700196366
4158 [11.086797:0x103f443c7] DEBUG: spice_session_sync_playback_latency: not implemented when there isn't audio playback
4164 [11.100126:0x103f952de] DEBUG: the GStreamer pipeline dropped a frame
4165 [11.100130:0x103f952de] DEBUG: the GStreamer pipeline dropped a frame
4166 [11.100132:0x103f952de] DEBUG: the GStreamer pipeline dropped a frame
4167 [11.100133:0x103f952de] DEBUG: the GStreamer pipeline dropped a frame
4168 [11.100134:0x103f952de] DEBUG: the GStreamer pipeline dropped a frame
4169 [11.100135:0x103f952de] DEBUG: the GStreamer pipeline dropped a frame
4170 [11.100137:0x103f952de] DEBUG: the GStreamer pipeline dropped a frame
4171 [11.100138:0x103f952de] DEBUG: the GStreamer pipeline dropped a frame
4172 [11.100139:0x103f952de] DEBUG: the GStreamer pipeline dropped a frame
4173 [11.100140:0x103f952de] DEBUG: the GStreamer pipeline dropped a frame
4174 [11.136929:0x103f94e5f] DEBUG: schedule_frame: rendering too late by 2857 ms (ts: 700193611, mmtime: 700196468
4195 [11.187694:0x103f443c7] DEBUG: spice_session_sync_playback_latency: not implemented when there isn't audio playback
4204 [11.190392:0x103f94e5f] DEBUG: schedule_frame: rendering too late by 2860 ms (ts: 700193661, mmtime: 700196521
4225 [11.250175:0x103f443c7] DEBUG: spice_session_sync_playback_latency: not implemented when there isn't audio playback
4226 [11.252384:0x103f94e5f] DEBUG: schedule_frame: rendering too late by 2873 ms (ts: 700193710, mmtime: 700196583
4227 [11.314175:0x103f94e5f] DEBUG: schedule_frame: rendering too late by 2884 ms (ts: 700193761, mmtime: 700196645
4253 [11.367777:0x103f443c7] DEBUG: spice_session_sync_playback_latency: not implemented when there isn't audio playback
4279 [11.432352:0x103f443c7] DEBUG: spice_session_sync_playback_latency: not implemented when there isn't audio playback
4290 [11.486026:0x103f94e5f] DEBUG: schedule_frame: rendering too late by 2890 ms (ts: 700193927, mmtime: 700196817
4306 [11.536308:0x103f443c7] DEBUG: spice_session_sync_playback_latency: not implemented when there isn't audio playback
4335 [11.536620:0x103f443c7] DEBUG: spice_session_sync_playback_latency: not implemented when there isn't audio playback
4361 [11.542264:0x103f443c7] DEBUG: spice_session_sync_playback_latency: not implemented when there isn't audio playback
4382 [11.602006:0x103f94e5f] DEBUG: schedule_frame: rendering too late by 2878 ms (ts: 700194055, mmtime: 700196933
4388 [11.657611:0x103f443c7] DEBUG: spice_session_sync_playback_latency: not implemented when there isn't audio playback
4404 [11.660352:0x103f94e5f] DEBUG: schedule_frame: rendering too late by 2887 ms (ts: 700194104, mmtime: 700196991
4415 [11.723945:0x103f443c7] DEBUG: spice_session_sync_playback_latency: not implemented when there isn't audio playback
4434 [11.725460:0x103f94e5f] DEBUG: schedule_frame: rendering too late by 2886 ms (ts: 700194170, mmtime: 700197056
4440 [11.780996:0x103f94e5f] DEBUG: schedule_frame: rendering too late by 2891 ms (ts: 700194221, mmtime: 700197112
4446 [11.781248:0x103f443c7] DEBUG: spice_session_sync_playback_latency: not implemented when there isn't audio playback
4457 [11.835121:0x103f94e5f] DEBUG: schedule_frame: rendering too late by 2894 ms (ts: 700194272, mmtime: 700197166
4473 [11.886566:0x103f443c7] DEBUG: spice_session_sync_playback_latency: not implemented when there isn't audio playback
4479 [11.888996:0x103f94e5f] DEBUG: schedule_frame: rendering too late by 2898 ms (ts: 700194322, mmtime: 700197220
4485 [11.951404:0x103f94e5f] DEBUG: schedule_frame: rendering too late by 2910 ms (ts: 700194372, mmtime: 700197282
4501 [11.951668:0x103f443c7] DEBUG: spice_session_sync_playback_latency: not implemented when there isn't audio playback
4502 [12.009728:0x103f94e5f] DEBUG: schedule_frame: rendering too late by 2918 ms (ts: 700194422, mmtime: 700197340
4518 [12.061073:0x103f94e5f] DEBUG: schedule_frame: rendering too late by 2920 ms (ts: 700194472, mmtime: 700197392
4529 [12.061275:0x103f443c7] DEBUG: spice_session_sync_playback_latency: not implemented when there isn't audio playback
4553 [12.117087:0x103f94e5f] DEBUG: schedule_frame: rendering too late by 2912 ms (ts: 700194536, mmtime: 700197448
4559 [12.117277:0x103f443c7] DEBUG: spice_session_sync_playback_latency: not implemented when there isn't audio playback
4560 [12.171818:0x103f94e5f] DEBUG: schedule_frame: rendering too late by 2910 ms (ts: 700194592, mmtime: 700197502
4586 [12.224257:0x103f443c7] DEBUG: spice_session_sync_playback_latency: not implemented when there isn't audio playback
4612 [12.298773:0x103f443c7] DEBUG: spice_session_sync_playback_latency: not implemented when there isn't audio playback
4638 [12.364066:0x103f443c7] DEBUG: spice_session_sync_playback_latency: not implemented when there isn't audio playback
4667 [12.433021:0x103f443c7] DEBUG: spice_session_sync_playback_latency: not implemented when there isn't audio playback
4673 [12.500909:0x103f94e5f] DEBUG: schedule_frame: rendering too late by 3007 ms (ts: 700194825, mmtime: 700197832
4694 [12.501311:0x103f443c7] DEBUG: spice_session_sync_playback_latency: not implemented when there isn't audio playback
4710 [12.562036:0x103f94e5f] DEBUG: schedule_frame: rendering too late by 3014 ms (ts: 700194879, mmtime: 700197893
4721 [12.623093:0x103f443c7] DEBUG: spice_session_sync_playback_latency: not implemented when there isn't audio playback
4747 [12.684742:0x103f443c7] DEBUG: spice_session_sync_playback_latency: not implemented when there isn't audio playback
4756 [12.687283:0x103f94e5f] DEBUG: schedule_frame: rendering too late by 3030 ms (ts: 700194988, mmtime: 700198018
4777 [12.752582:0x103f443c7] DEBUG: spice_session_sync_playback_latency: not implemented when there isn't audio playback
4778 [12.755142:0x103f94e5f] DEBUG: schedule_frame: rendering too late by 3044 ms (ts: 700195042, mmtime: 700198086
4779 [12.818669:0x103f94e5f] DEBUG: schedule_frame: rendering too late by 3043 ms (ts: 700195106, mmtime: 700198149
4805 [12.874040:0x103f443c7] DEBUG: spice_session_sync_playback_latency: not implemented when there isn't audio playback
4831 [12.925201:0x103f443c7] DEBUG: spice_session_sync_playback_latency: not implemented when there isn't audio playback
4852 [13.048325:0x103f94e5f] DEBUG: schedule_frame: rendering too late by 3096 ms (ts: 700195283, mmtime: 700198379
4858 [13.048619:0x103f443c7] DEBUG: spice_session_sync_playback_latency: not implemented when there isn't audio playback
4887 [13.114876:0x103f443c7] DEBUG: spice_session_sync_playback_latency: not implemented when there isn't audio playback
4913 [13.181775:0x103f443c7] DEBUG: spice_session_sync_playback_latency: not implemented when there isn't audio playback
4919 [13.201578:0x103f952de] DEBUG: the GStreamer pipeline dropped a frame
4920 [13.201582:0x103f952de] DEBUG: the GStreamer pipeline dropped a frame
4921 [13.201584:0x103f952de] DEBUG: the GStreamer pipeline dropped a frame
4922 [13.201586:0x103f952de] DEBUG: the GStreamer pipeline dropped a frame
4923 [13.201587:0x103f952de] DEBUG: the GStreamer pipeline dropped a frame
4924 [13.201588:0x103f952de] DEBUG: the GStreamer pipeline dropped a frame
4925 [13.201590:0x103f952de] DEBUG: the GStreamer pipeline dropped a frame
4926 [13.201591:0x103f952de] DEBUG: the GStreamer pipeline dropped a frame
4927 [13.201592:0x103f952de] DEBUG: the GStreamer pipeline dropped a frame
4928 [13.201594:0x103f952de] DEBUG: the GStreamer pipeline dropped a frame
4949 [13.241937:0x103f443c7] DEBUG: spice_session_sync_playback_latency: not implemented when there isn't audio playback
4975 [13.242305:0x103f443c7] DEBUG: spice_session_sync_playback_latency: not implemented when there isn't audio playback
5004 [13.242681:0x103f443c7] DEBUG: spice_session_sync_playback_latency: not implemented when there isn't audio playback
5005 [13.245110:0x103f94e5f] DEBUG: schedule_frame: rendering too late by 3197 ms (ts: 700195379, mmtime: 700198576
5011 [13.304590:0x103f94e5f] DEBUG: schedule_frame: rendering too late by 3206 ms (ts: 700195429, mmtime: 700198635
5027 [13.359873:0x103f94e5f] DEBUG: schedule_frame: rendering too late by 3213 ms (ts: 700195478, mmtime: 700198691
5028 [13.359877:0x103f94e5f] DEBUG: schedule_frame: rendering too late by 3195 ms (ts: 700195496, mmtime: 700198691
5034 [13.360132:0x103f443c7] DEBUG: spice_session_sync_playback_latency: not implemented when there isn't audio playback
5060 [13.411310:0x103f443c7] DEBUG: spice_session_sync_playback_latency: not implemented when there isn't audio playback
5061 [13.413551:0x103f94e5f] DEBUG: schedule_frame: rendering too late by 3199 ms (ts: 700195545, mmtime: 700198744
5067 [13.474287:0x103f94e5f] DEBUG: schedule_frame: rendering too late by 3209 ms (ts: 700195596, mmtime: 700198805
5088 [13.524053:0x103f443c7] DEBUG: spice_session_sync_playback_latency: not implemented when there isn't audio playback
5102 [13.526362:0x103f94e5f] DEBUG: schedule_frame: rendering too late by 3211 ms (ts: 700195646, mmtime: 700198857
5118 [13.576343:0x103f443c7] DEBUG: spice_session_sync_playback_latency: not implemented when there isn't audio playback
5119 [13.578549:0x103f94e5f] DEBUG: schedule_frame: rendering too late by 3213 ms (ts: 700195696, mmtime: 700198909
5125 [13.638006:0x103f94e5f] DEBUG: schedule_frame: rendering too late by 3223 ms (ts: 700195746, mmtime: 700198969
5141 [13.694672:0x103f94e5f] DEBUG: schedule_frame: rendering too late by 3230 ms (ts: 700195795, mmtime: 700199025
5147 [13.694976:0x103f443c7] DEBUG: spice_session_sync_playback_latency: not implemented when there isn't audio playback
5158 [13.757530:0x103f94e5f] DEBUG: schedule_frame: rendering too late by 3225 ms (ts: 700195863, mmtime: 700199088
5174 [13.757876:0x103f443c7] DEBUG: spice_session_sync_playback_latency: not implemented when there isn't audio playback
5175 [13.811424:0x103f94e5f] DEBUG: schedule_frame: rendering too late by 3230 ms (ts: 700195912, mmtime: 700199142
5201 [13.876596:0x103f443c7] DEBUG: spice_session_sync_playback_latency: not implemented when there isn't audio playback
5215 [13.879003:0x103f94e5f] DEBUG: schedule_frame: rendering too late by 3231 ms (ts: 700195979, mmtime: 700199210
5221 [13.946506:0x103f94e5f] DEBUG: schedule_frame: rendering too late by 3248 ms (ts: 700196029, mmtime: 700199277
5232 [13.946815:0x103f443c7] DEBUG: spice_session_sync_playback_latency: not implemented when there isn't audio playback
5243 [14.013706:0x103f94e5f] DEBUG: schedule_frame: rendering too late by 3265 ms (ts: 700196079, mmtime: 700199344
5259 [14.014033:0x103f443c7] DEBUG: spice_session_sync_playback_latency: not implemented when there isn't audio playback
5285 [14.074874:0x103f443c7] DEBUG: spice_session_sync_playback_latency: not implemented when there isn't audio playback
5286 [14.077072:0x103f94e5f] DEBUG: schedule_frame: rendering too late by 3262 ms (ts: 700196146, mmtime: 700199408
5302 [14.188170:0x103f94e5f] DEBUG: schedule_frame: rendering too late by 3274 ms (ts: 700196245, mmtime: 700199519
5313 [14.188524:0x103f443c7] DEBUG: spice_session_sync_playback_latency: not implemented when there isn't audio playback
5322 [14.236088:0x103f94e5f] DEBUG: schedule_frame: rendering too late by 3271 ms (ts: 700196296, mmtime: 700199567
5343 [14.289459:0x103f443c7] DEBUG: spice_session_sync_playback_latency: not implemented when there isn't audio playback
5359 [14.351307:0x103f94e5f] DEBUG: schedule_frame: rendering too late by 3303 ms (ts: 700196379, mmtime: 700199682
5370 [14.351650:0x103f443c7] DEBUG: spice_session_sync_playback_latency: not implemented when there isn't audio playback
5396 [14.412102:0x103f443c7] DEBUG: spice_session_sync_playback_latency: not implemented when there isn't audio playback
5402 [14.412908:0x103f94e5f] DEBUG: schedule_frame: rendering too late by 3298 ms (ts: 700196446, mmtime: 700199744
5418 [14.469854:0x103f94e5f] DEBUG: schedule_frame: rendering too late by 3305 ms (ts: 700196496, mmtime: 700199801
5424 [14.516795:0x103f443c7] DEBUG: spice_session_sync_playback_latency: not implemented when there isn't audio playback
5453 [14.568322:0x103f443c7] DEBUG: spice_session_sync_playback_latency: not implemented when there isn't audio playback
5479 [14.670504:0x103f443c7] DEBUG: spice_session_sync_playback_latency: not implemented when there isn't audio playback
5500 [14.719494:0x103f94e5f] DEBUG: schedule_frame: rendering too late by 3321 ms (ts: 700196729, mmtime: 700200050
5506 [14.769062:0x103f443c7] DEBUG: spice_session_sync_playback_latency: not implemented when there isn't audio playback
5517 [14.769794:0x103f94e5f] DEBUG: schedule_frame: rendering too late by 3305 ms (ts: 700196796, mmtime: 700200101
5533 [14.815054:0x103f443c7] DEBUG: spice_session_sync_playback_latency: not implemented when there isn't audio playback
5562 [14.867306:0x103f443c7] DEBUG: spice_session_sync_playback_latency: not implemented when there isn't audio playback
5566 [14.869547:0x103f94e5f] DEBUG: schedule_frame: rendering too late by 3304 ms (ts: 700196896, mmtime: 700200200
5589 [14.916232:0x103f443c7] DEBUG: spice_session_sync_playback_latency: not implemented when there isn't audio playback
5353 [14.289571:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1541 ms (ts: 700198079, mmtime: 700199620
5358 [14.289617:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1525 ms (ts: 700198095, mmtime: 700199620
5364 [14.351596:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1570 ms (ts: 700198112, mmtime: 700199682
5369 [14.351644:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1553 ms (ts: 700198129, mmtime: 700199682
5375 [14.351674:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1536 ms (ts: 700198146, mmtime: 700199682
5380 [14.411955:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1581 ms (ts: 700198162, mmtime: 700199743
5385 [14.412023:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1565 ms (ts: 700198178, mmtime: 700199743
5390 [14.412061:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1547 ms (ts: 700198196, mmtime: 700199743
5395 [14.412096:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1530 ms (ts: 700198213, mmtime: 700199743
5401 [14.412135:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1515 ms (ts: 700198228, mmtime: 700199743
5407 [14.469440:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1554 ms (ts: 700198246, mmtime: 700199800
5412 [14.469573:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1537 ms (ts: 700198263, mmtime: 700199800
5417 [14.469648:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1522 ms (ts: 700198278, mmtime: 700199800
5423 [14.516779:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1552 ms (ts: 700198296, mmtime: 700199848
5432 [14.516866:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1536 ms (ts: 700198312, mmtime: 700199848
5437 [14.516898:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1519 ms (ts: 700198329, mmtime: 700199848
5442 [14.568246:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1554 ms (ts: 700198345, mmtime: 700199899
5447 [14.568292:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1537 ms (ts: 700198362, mmtime: 700199899
5452 [14.568317:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1520 ms (ts: 700198379, mmtime: 700199899
5458 [14.620146:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1556 ms (ts: 700198395, mmtime: 700199951
5463 [14.620193:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1539 ms (ts: 700198412, mmtime: 700199951
5468 [14.620217:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1522 ms (ts: 700198429, mmtime: 700199951
5473 [14.670458:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1556 ms (ts: 700198445, mmtime: 700200001
5478 [14.670499:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1539 ms (ts: 700198462, mmtime: 700200001
5484 [14.670532:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1522 ms (ts: 700198479, mmtime: 700200001
5489 [14.717331:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1553 ms (ts: 700198495, mmtime: 700200048
5494 [14.717383:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1536 ms (ts: 700198512, mmtime: 700200048
5499 [14.717412:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1519 ms (ts: 700198529, mmtime: 700200048
5505 [14.769046:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1554 ms (ts: 700198546, mmtime: 700200100
5511 [14.769089:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1538 ms (ts: 700198562, mmtime: 700200100
5516 [14.769119:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1521 ms (ts: 700198579, mmtime: 700200100
5522 [14.812661:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1548 ms (ts: 700198595, mmtime: 700200143
5527 [14.812700:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1531 ms (ts: 700198612, mmtime: 700200143
5532 [14.815042:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1517 ms (ts: 700198629, mmtime: 700200146
5541 [14.867139:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1553 ms (ts: 700198645, mmtime: 700200198
5546 [14.867182:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1536 ms (ts: 700198662, mmtime: 700200198
5551 [14.867228:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1519 ms (ts: 700198679, mmtime: 700200198
5556 [14.867267:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1519 ms (ts: 700198679, mmtime: 700200198
5561 [14.867301:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1519 ms (ts: 700198679, mmtime: 700200198
5568 [14.869772:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1522 ms (ts: 700198679, mmtime: 700200201
5573 [14.869825:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1522 ms (ts: 700198679, mmtime: 700200201
5578 [14.872212:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1524 ms (ts: 700198679, mmtime: 700200203
5583 [14.916054:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1568 ms (ts: 700198679, mmtime: 700200247
5588 [14.916226:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1568 ms (ts: 700198679, mmtime: 700200247
5594 [14.916299:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1567 ms (ts: 700198680, mmtime: 700200247
5599 [14.916360:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1567 ms (ts: 700198680, mmtime: 700200247
5604 [14.916442:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1567 ms (ts: 700198680, mmtime: 700200247
5609 [14.916472:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1552 ms (ts: 700198695, mmtime: 700200247
5614 [14.916495:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1535 ms (ts: 700198712, mmtime: 700200247
5615 [14.916498:0x103f443c7] DEBUG: spice_session_sync_playback_latency: not implemented when there isn't audio playback
5620 [14.916542:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1518 ms (ts: 700198729, mmtime: 700200247
5621 [14.918808:0x103f94e5f] DEBUG: schedule_frame: rendering too late by 3304 ms (ts: 700196946, mmtime: 700200250
5626 [14.965089:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1551 ms (ts: 700198745, mmtime: 700200296
5631 [14.965127:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1534 ms (ts: 700198762, mmtime: 700200296
5636 [14.965153:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1517 ms (ts: 700198779, mmtime: 700200296
5637 [14.993420:0x103f952de] DEBUG: the GStreamer pipeline dropped a frame
5638 [14.993424:0x103f952de] DEBUG: the GStreamer pipeline dropped a frame
5639 [14.993425:0x103f952de] DEBUG: the GStreamer pipeline dropped a frame
5640 [14.993426:0x103f952de] DEBUG: the GStreamer pipeline dropped a frame
5641 [14.993427:0x103f952de] DEBUG: the GStreamer pipeline dropped a frame
5642 [14.993428:0x103f952de] DEBUG: the GStreamer pipeline dropped a frame
5643 [14.993428:0x103f952de] DEBUG: the GStreamer pipeline dropped a frame
5644 [14.993429:0x103f952de] DEBUG: the GStreamer pipeline dropped a frame
5645 [14.993430:0x103f952de] DEBUG: the GStreamer pipeline dropped a frame
5646 [14.993431:0x103f952de] DEBUG: the GStreamer pipeline dropped a frame
5647 [14.993432:0x103f952de] DEBUG: the GStreamer pipeline dropped a frame
5648 [15.014347:0x103f94e5f] DEBUG: schedule_frame: rendering too late by 3316 ms (ts: 700197029, mmtime: 700200345
5653 [15.014549:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1550 ms (ts: 700198795, mmtime: 700200345
5654 [15.014562:0x103f443c7] DEBUG: spice_session_sync_playback_latency: not implemented when there isn't audio playback
5662 [15.014621:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1533 ms (ts: 700198812, mmtime: 700200345
5667 [15.014650:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1516 ms (ts: 700198829, mmtime: 700200345
5672 [15.063820:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1549 ms (ts: 700198846, mmtime: 700200395
5677 [15.063913:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1533 ms (ts: 700198862, mmtime: 700200395
5682 [15.063958:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1516 ms (ts: 700198879, mmtime: 700200395
5683 [15.063964:0x103f443c7] DEBUG: spice_session_sync_playback_latency: not implemented when there isn't audio playback
5684 [15.064379:0x103f94e5f] DEBUG: schedule_frame: rendering too late by 3299 ms (ts: 700197096, mmtime: 700200395
5685 [15.114778:0x103f94e5f] DEBUG: schedule_frame: rendering too late by 3300 ms (ts: 700197146, mmtime: 700200446
5690 [15.115010:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1551 ms (ts: 700198895, mmtime: 700200446
5695 [15.115049:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1534 ms (ts: 700198912, mmtime: 700200446
5700 [15.115074:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1517 ms (ts: 700198929, mmtime: 700200446
5701 [15.162880:0x103f94e5f] DEBUG: schedule_frame: rendering too late by 3282 ms (ts: 700197212, mmtime: 700200494
5706 [15.163094:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1548 ms (ts: 700198946, mmtime: 700200494
5711 [15.163131:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1532 ms (ts: 700198962, mmtime: 700200494
5712 [15.163138:0x103f443c7] DEBUG: spice_session_sync_playback_latency: not implemented when there isn't audio playback
5717 [15.163162:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1515 ms (ts: 700198979, mmtime: 700200494
5722 [15.213686:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1549 ms (ts: 700198995, mmtime: 700200544
5727 [15.213727:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1533 ms (ts: 700199012, mmtime: 700200545
5728 [15.215832:0x103f94e5f] DEBUG: schedule_frame: rendering too late by 3269 ms (ts: 700197278, mmtime: 700200547
5733 [15.216054:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1518 ms (ts: 700199029, mmtime: 700200547
5734 [15.263152:0x103f94e5f] DEBUG: schedule_frame: rendering too late by 3265 ms (ts: 700197329, mmtime: 700200594
5739 [15.263389:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1547 ms (ts: 700199047, mmtime: 700200594
5740 [15.263403:0x103f443c7] DEBUG: spice_session_sync_playback_latency: not implemented when there isn't audio playback
5745 [15.263431:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1531 ms (ts: 700199063, mmtime: 700200594
5750 [15.265589:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1517 ms (ts: 700199079, mmtime: 700200596
5755 [15.313032:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1548 ms (ts: 700199096, mmtime: 700200644
5760 [15.313073:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1532 ms (ts: 700199112, mmtime: 700200644
5765 [15.313097:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1515 ms (ts: 700199129, mmtime: 700200644
5766 [15.313101:0x103f443c7] DEBUG: spice_session_sync_playback_latency: not implemented when there isn't audio playback
5767 [15.315211:0x103f94e5f] DEBUG: schedule_frame: rendering too late by 3250 ms (ts: 700197396, mmtime: 700200646
5768 [15.363424:0x103f94e5f] DEBUG: schedule_frame: rendering too late by 3249 ms (ts: 700197445, mmtime: 700200694
224 [0.990287:0x103f4dcf2] WRITE: Wrote 38 bytes on usbredir-9:0
228 [0.990356:0x103f4dca4] WRITE: Write 38 bytes on usbredir-9:1
229 [0.990384:0x103f4dcf2] WRITE: Wrote 38 bytes on usbredir-9:1
233 [0.990518:0x103f4dca4] WRITE: Write 42 bytes on record-6:0
234 [0.990546:0x103f4dcf2] WRITE: Wrote 42 bytes on record-6:0
238 [0.992593:0x103f4dca4] WRITE: Write 42 bytes on display-2:1
239 [0.992636:0x103f4dcf2] WRITE: Wrote 42 bytes on display-2:1
243 [0.992720:0x103f4dca4] WRITE: Write 42 bytes on playback-5:0
244 [0.992748:0x103f4dcf2] WRITE: Wrote 42 bytes on playback-5:0
255 [1.032802:0x103f4dca4] WRITE: Write 4 bytes on record-6:0
256 [1.032846:0x103f4dcf2] WRITE: Wrote 4 bytes on record-6:0
257 [1.032980:0x103f4dca4] WRITE: Write 128 bytes on record-6:0
258 [1.033009:0x103f4dcf2] WRITE: Wrote 128 bytes on record-6:0
271 [1.045159:0x103f4dca4] WRITE: Write 4 bytes on usbredir-9:0
272 [1.045207:0x103f4dcf2] WRITE: Wrote 4 bytes on usbredir-9:0
273 [1.045339:0x103f4dca4] WRITE: Write 128 bytes on usbredir-9:0
274 [1.045380:0x103f4dcf2] WRITE: Wrote 128 bytes on usbredir-9:0
287 [1.072463:0x103f4dca4] WRITE: Write 4 bytes on usbredir-9:1
288 [1.072507:0x103f4dcf2] WRITE: Wrote 4 bytes on usbredir-9:1
289 [1.072641:0x103f4dca4] WRITE: Write 128 bytes on usbredir-9:1
290 [1.072681:0x103f4dcf2] WRITE: Wrote 128 bytes on usbredir-9:1
303 [1.104316:0x103f4dca4] WRITE: Write 4 bytes on display-2:0
304 [1.104357:0x103f4dcf2] WRITE: Wrote 4 bytes on display-2:0
305 [1.104506:0x103f4dca4] WRITE: Write 128 bytes on display-2:0
306 [1.104553:0x103f4dcf2] WRITE: Wrote 128 bytes on display-2:0
312 [1.104798:0x103f49898] WRITE: Message 0x7fc2b1e196b0 on usbredir-9:1
313 [1.104800:0x103f4dca4] WRITE: Write 86 bytes on usbredir-9:1
314 [1.104829:0x103f4dcf2] WRITE: Wrote 86 bytes on usbredir-9:1
324 [1.106844:0x103f49898] WRITE: Message 0x7fc2b1f93f50 on usbredir-9:0
325 [1.106846:0x103f4dca4] WRITE: Write 86 bytes on usbredir-9:0
326 [1.106885:0x103f4dcf2] WRITE: Wrote 86 bytes on usbredir-9:0
341 [1.113002:0x103f4dca4] WRITE: Write 4 bytes on display-2:1
342 [1.113046:0x103f4dcf2] WRITE: Wrote 4 bytes on display-2:1
343 [1.113166:0x103f4dca4] WRITE: Write 128 bytes on display-2:1
344 [1.113209:0x103f4dcf2] WRITE: Wrote 128 bytes on display-2:1
351 [1.113969:0x103f49898] WRITE: Message 0x7fc2b1e02b20 on display-2:0
352 [1.113970:0x103f4dca4] WRITE: Write 20 bytes on display-2:0
353 [1.114010:0x103f4dcf2] WRITE: Wrote 20 bytes on display-2:0
358 [1.125632:0x103f49898] WRITE: Message 0x7fc2b3013fd0 on display-2:0
359 [1.125633:0x103f4dca4] WRITE: Write 10 bytes on display-2:0
360 [1.125681:0x103f4dcf2] WRITE: Wrote 10 bytes on display-2:0
384 [1.141089:0x103f4dca4] WRITE: Write 4 bytes on playback-5:0
385 [1.141124:0x103f4dcf2] WRITE: Wrote 4 bytes on playback-5:0
386 [1.141254:0x103f4dca4] WRITE: Write 128 bytes on playback-5:0
387 [1.141290:0x103f4dcf2] WRITE: Wrote 128 bytes on playback-5:0
394 [1.141532:0x103f49898] WRITE: Message 0x7fc2b1d39dd0 on display-2:1
395 [1.141533:0x103f4dca4] WRITE: Write 20 bytes on display-2:1
396 [1.141566:0x103f4dcf2] WRITE: Wrote 20 bytes on display-2:1
401 [1.141744:0x103f49898] WRITE: Message 0x7fc2b1d39dd0 on display-2:1
402 [1.141745:0x103f4dca4] WRITE: Write 10 bytes on display-2:1
403 [1.141776:0x103f4dcf2] WRITE: Wrote 10 bytes on display-2:1
468 [2.448196:0x103f49898] WRITE: Message 0x7fc2b32f16f0 on display-2:0
469 [2.448197:0x103f4dca4] WRITE: Write 18 bytes on display-2:0
470 [2.448255:0x103f4dcf2] WRITE: Wrote 18 bytes on display-2:0
475 [2.448270:0x103f49898] WRITE: Message 0x7fc2b32f16f0 on display-2:0
476 [2.448270:0x103f4dca4] WRITE: Write 18 bytes on display-2:0
477 [2.448294:0x103f4dcf2] WRITE: Wrote 18 bytes on display-2:0
519 [2.546461:0x103f4dca4] WRITE: Write 38 bytes on inputs-3:0
520 [2.546503:0x103f4dcf2] WRITE: Wrote 38 bytes on inputs-3:0
524 [2.546572:0x103f4dca4] WRITE: Write 38 bytes on cursor-4:0
525 [2.546594:0x103f4dcf2] WRITE: Wrote 38 bytes on cursor-4:0
616 [2.553766:0x103f49898] WRITE: Message 0x7fc2b1d4f460 on display-2:1
617 [2.553767:0x103f4dca4] WRITE: Write 6 bytes on display-2:1
618 [2.553786:0x103f4dcf2] WRITE: Wrote 6 bytes on display-2:1
653 [2.599932:0x103f4dca4] WRITE: Write 4 bytes on inputs-3:0
654 [2.599965:0x103f4dcf2] WRITE: Wrote 4 bytes on inputs-3:0
655 [2.600076:0x103f4dca4] WRITE: Write 128 bytes on inputs-3:0
656 [2.600116:0x103f4dcf2] WRITE: Wrote 128 bytes on inputs-3:0
668 [2.600159:0x103f4dca4] WRITE: Write 4 bytes on cursor-4:0
669 [2.600177:0x103f4dcf2] WRITE: Wrote 4 bytes on cursor-4:0
670 [2.600235:0x103f4dca4] WRITE: Write 128 bytes on cursor-4:0
671 [2.600253:0x103f4dcf2] WRITE: Wrote 128 bytes on cursor-4:0
754 [2.600860:0x103f49898] WRITE: Message 0x7fc2b32f4dd0 on display-2:1
755 [2.600861:0x103f4dca4] WRITE: Write 6 bytes on display-2:1
756 [2.600889:0x103f4dcf2] WRITE: Wrote 6 bytes on display-2:1
871 [2.649251:0x103f49898] WRITE: Message 0x7fc2b345c260 on inputs-3:0
872 [2.649253:0x103f4dca4] WRITE: Write 8 bytes on inputs-3:0
873 [2.649292:0x103f4dcf2] WRITE: Wrote 8 bytes on inputs-3:0
876 [2.649440:0x103f49898] WRITE: Message 0x7fc2b1cf7e20 on display-2:1
877 [2.649440:0x103f4dca4] WRITE: Write 6 bytes on display-2:1
878 [2.649479:0x103f4dcf2] WRITE: Wrote 6 bytes on display-2:1
983 [2.649938:0x103f49898] WRITE: Message 0x7fc2b1cf7e20 on display-2:1
984 [2.649939:0x103f4dca4] WRITE: Write 6 bytes on display-2:1
985 [2.649953:0x103f4dcf2] WRITE: Wrote 6 bytes on display-2:1
995 [2.651558:0x103f49898] WRITE: Message 0x7fc2b1c399d0 on cursor-4:0
996 [2.651559:0x103f4dca4] WRITE: Write 10 bytes on cursor-4:0
997 [2.651584:0x103f4dcf2] WRITE: Wrote 10 bytes on cursor-4:0
1111 [2.956160:0x103f49898] WRITE: Message 0x7fc2b3539ac0 on display-2:1
1112 [2.956161:0x103f4dca4] WRITE: Write 6 bytes on display-2:1
1113 [2.956193:0x103f4dcf2] WRITE: Wrote 6 bytes on display-2:1
1222 [3.221988:0x103f49898] WRITE: Message 0x7fc2b34d1630 on display-2:1
1223 [3.221989:0x103f4dca4] WRITE: Write 6 bytes on display-2:1
1224 [3.222008:0x103f4dcf2] WRITE: Wrote 6 bytes on display-2:1
1296 [3.346758:0x103f49898] WRITE: Message 0x7fc2b1e2e4f0 on main-1:0
1297 [3.346760:0x103f4dca4] WRITE: Write 354 bytes on main-1:0
1298 [3.346836:0x103f4dcf2] WRITE: Wrote 354 bytes on main-1:0
1346 [3.470138:0x103f49898] WRITE: Message 0x7fc2b1df3e30 on display-2:1
1347 [3.470140:0x103f4dca4] WRITE: Write 6 bytes on display-2:1
1348 [3.470161:0x103f4dcf2] WRITE: Wrote 6 bytes on display-2:1
1455 [3.779985:0x103f49898] WRITE: Message 0x7fc2b1e28890 on display-2:1
1456 [3.779987:0x103f4dca4] WRITE: Write 6 bytes on display-2:1
1457 [3.780036:0x103f4dcf2] WRITE: Wrote 6 bytes on display-2:1
1565 [4.103440:0x103f49898] WRITE: Message 0x7fc2b33488a0 on display-2:1
1566 [4.103442:0x103f4dca4] WRITE: Write 6 bytes on display-2:1
1567 [4.103475:0x103f4dcf2] WRITE: Wrote 6 bytes on display-2:1
1686 [4.469279:0x103f49898] WRITE: Message 0x7fc2b3522230 on display-2:1
1687 [4.469280:0x103f4dca4] WRITE: Write 6 bytes on display-2:1
1688 [4.469322:0x103f4dcf2] WRITE: Wrote 6 bytes on display-2:1
1805 [4.803259:0x103f49898] WRITE: Message 0x7fc2b1d477c0 on display-2:1
1806 [4.803260:0x103f4dca4] WRITE: Write 6 bytes on display-2:1
1807 [4.803303:0x103f4dcf2] WRITE: Wrote 6 bytes on display-2:1
1915 [4.961993:0x103f49898] WRITE: Message 0x7fc2b3114450 on display-2:1
1916 [4.961995:0x103f4dca4] WRITE: Write 6 bytes on display-2:1
1917 [4.962050:0x103f4dcf2] WRITE: Wrote 6 bytes on display-2:1
2027 [5.270678:0x103f49898] WRITE: Message 0x7fc2b1cc8b40 on display-2:1
2028 [5.270679:0x103f4dca4] WRITE: Write 6 bytes on display-2:1
2029 [5.270711:0x103f4dcf2] WRITE: Wrote 6 bytes on display-2:1
2143 [5.613394:0x103f49898] WRITE: Message 0x7fc2b344b2b0 on display-2:1
2144 [5.613395:0x103f4dca4] WRITE: Write 6 bytes on display-2:1
2145 [5.613438:0x103f4dcf2] WRITE: Wrote 6 bytes on display-2:1
2266 [5.954250:0x103f49898] WRITE: Message 0x7fc2b34ba7c0 on display-2:1
2267 [5.954251:0x103f4dca4] WRITE: Write 6 bytes on display-2:1
2268 [5.954298:0x103f4dcf2] WRITE: Wrote 6 bytes on display-2:1
2381 [6.291216:0x103f49898] WRITE: Message 0x7fc2b324a150 on display-2:1
2382 [6.291218:0x103f4dca4] WRITE: Write 6 bytes on display-2:1
2383 [6.291244:0x103f4dcf2] WRITE: Wrote 6 bytes on display-2:1
2492 [6.470406:0x103f49898] WRITE: Message 0x7fc2b1c485d0 on display-2:1
2493 [6.470407:0x103f4dca4] WRITE: Write 6 bytes on display-2:1
2494 [6.470443:0x103f4dcf2] WRITE: Wrote 6 bytes on display-2:1
2604 [6.774430:0x103f49898] WRITE: Message 0x7fc2b3525200 on display-2:1
2605 [6.774431:0x103f4dca4] WRITE: Write 6 bytes on display-2:1
2606 [6.774454:0x103f4dcf2] WRITE: Wrote 6 bytes on display-2:1
2715 [7.106043:0x103f49898] WRITE: Message 0x7fc2b352e320 on display-2:1
2716 [7.106044:0x103f4dca4] WRITE: Write 6 bytes on display-2:1
2717 [7.106069:0x103f4dcf2] WRITE: Wrote 6 bytes on display-2:1
2836 [7.441284:0x103f49898] WRITE: Message 0x7fc2b3519770 on display-2:1
2837 [7.441285:0x103f4dca4] WRITE: Write 6 bytes on display-2:1
2838 [7.441319:0x103f4dcf2] WRITE: Wrote 6 bytes on display-2:1
2946 [7.789700:0x103f49898] WRITE: Message 0x7fc2b1c517d0 on display-2:1
2947 [7.789701:0x103f4dca4] WRITE: Write 6 bytes on display-2:1
2948 [7.789759:0x103f4dcf2] WRITE: Wrote 6 bytes on display-2:1
3059 [8.082194:0x103f49898] WRITE: Message 0x7fc2b34ba710 on display-2:1
3060 [8.082195:0x103f4dca4] WRITE: Write 6 bytes on display-2:1
3061 [8.082230:0x103f4dcf2] WRITE: Wrote 6 bytes on display-2:1
3169 [8.245573:0x103f49898] WRITE: Message 0x7fc2b1e2b790 on display-2:1
3170 [8.245575:0x103f4dca4] WRITE: Write 6 bytes on display-2:1
3171 [8.245609:0x103f4dcf2] WRITE: Wrote 6 bytes on display-2:1
3284 [8.603149:0x103f49898] WRITE: Message 0x7fc2b1c2a7f0 on display-2:1
3285 [8.603151:0x103f4dca4] WRITE: Write 6 bytes on display-2:1
3286 [8.603184:0x103f4dcf2] WRITE: Wrote 6 bytes on display-2:1
3399 [8.951145:0x103f49898] WRITE: Message 0x7fc2b320e160 on display-2:1
3400 [8.951146:0x103f4dca4] WRITE: Write 6 bytes on display-2:1
3401 [8.951171:0x103f4dcf2] WRITE: Wrote 6 bytes on display-2:1
3521 [9.247733:0x103f49898] WRITE: Message 0x7fc2b300d5c0 on display-2:1
3522 [9.247735:0x103f4dca4] WRITE: Write 6 bytes on display-2:1
3523 [9.247773:0x103f4dcf2] WRITE: Wrote 6 bytes on display-2:1
3631 [9.584480:0x103f49898] WRITE: Message 0x7fc2b3344df0 on display-2:1
3632 [9.584481:0x103f4dca4] WRITE: Write 6 bytes on display-2:1
3633 [9.584517:0x103f4dcf2] WRITE: Wrote 6 bytes on display-2:1
3741 [9.789140:0x103f49898] WRITE: Message 0x7fc2b3013bf0 on display-2:1
3742 [9.789142:0x103f4dca4] WRITE: Write 6 bytes on display-2:1
3743 [9.789174:0x103f4dcf2] WRITE: Wrote 6 bytes on display-2:1
3852 [10.139374:0x103f49898] WRITE: Message 0x7fc2b3522230 on display-2:1
3853 [10.139376:0x103f4dca4] WRITE: Write 6 bytes on display-2:1
3854 [10.139411:0x103f4dcf2] WRITE: Wrote 6 bytes on display-2:1
3965 [10.493063:0x103f49898] WRITE: Message 0x7fc2b363e4c0 on display-2:1
3966 [10.493065:0x103f4dca4] WRITE: Write 6 bytes on display-2:1
3967 [10.493123:0x103f4dcf2] WRITE: Wrote 6 bytes on display-2:1
4078 [10.802130:0x103f49898] WRITE: Message 0x7fc2b344cf90 on display-2:1
4079 [10.802131:0x103f4dca4] WRITE: Write 6 bytes on display-2:1
4080 [10.802172:0x103f4dcf2] WRITE: Wrote 6 bytes on display-2:1
4200 [11.187740:0x103f49898] WRITE: Message 0x7fc2b1cc8a30 on display-2:1
4201 [11.187743:0x103f4dca4] WRITE: Write 6 bytes on display-2:1
4202 [11.187801:0x103f4dcf2] WRITE: Wrote 6 bytes on display-2:1
4311 [11.536329:0x103f49898] WRITE: Message 0x7fc2b1cc36d0 on display-2:1
4312 [11.536331:0x103f4dca4] WRITE: Write 6 bytes on display-2:1
4313 [11.536394:0x103f4dcf2] WRITE: Wrote 6 bytes on display-2:1
4420 [11.723970:0x103f49898] WRITE: Message 0x7fc2b1c54330 on display-2:1
4421 [11.723972:0x103f4dca4] WRITE: Write 6 bytes on display-2:1
4422 [11.724018:0x103f4dcf2] WRITE: Wrote 6 bytes on display-2:1
4534 [12.061289:0x103f49898] WRITE: Message 0x7fc2b363e4c0 on display-2:1
4535 [12.061291:0x103f4dca4] WRITE: Write 6 bytes on display-2:1
4536 [12.061344:0x103f4dcf2] WRITE: Wrote 6 bytes on display-2:1
4643 [12.364088:0x103f49898] WRITE: Message 0x7fc2b1cbc920 on display-2:1
4644 [12.364090:0x103f4dca4] WRITE: Write 6 bytes on display-2:1
4645 [12.364133:0x103f4dcf2] WRITE: Wrote 6 bytes on display-2:1
4752 [12.684779:0x103f49898] WRITE: Message 0x7fc2b34ba7c0 on display-2:1
4753 [12.684781:0x103f4dca4] WRITE: Write 6 bytes on display-2:1
4754 [12.684817:0x103f4dcf2] WRITE: Wrote 6 bytes on display-2:1
4863 [13.048645:0x103f49898] WRITE: Message 0x7fc2b3029c90 on display-2:1
4864 [13.048647:0x103f4dca4] WRITE: Write 6 bytes on display-2:1
4865 [13.048690:0x103f4dcf2] WRITE: Wrote 6 bytes on display-2:1
4980 [13.242380:0x103f49898] WRITE: Message 0x7fc2b1de8bd0 on display-2:1
4981 [13.242381:0x103f4dca4] WRITE: Write 6 bytes on display-2:1
4982 [13.242425:0x103f4dcf2] WRITE: Wrote 6 bytes on display-2:1
5093 [13.524090:0x103f49898] WRITE: Message 0x7fc2b3478200 on display-2:1
5094 [13.524092:0x103f4dca4] WRITE: Write 6 bytes on display-2:1
5095 [13.524120:0x103f4dcf2] WRITE: Wrote 6 bytes on display-2:1
5206 [13.876639:0x103f49898] WRITE: Message 0x7fc2b3482470 on display-2:1
5207 [13.876641:0x103f4dca4] WRITE: Write 6 bytes on display-2:1
5208 [13.876676:0x103f4dcf2] WRITE: Wrote 6 bytes on display-2:1
5318 [14.188572:0x103f49898] WRITE: Message 0x7fc2b3109640 on display-2:1
5319 [14.188574:0x103f4dca4] WRITE: Write 6 bytes on display-2:1
5320 [14.188602:0x103f4dcf2] WRITE: Wrote 6 bytes on display-2:1
5429 [14.516826:0x103f49898] WRITE: Message 0x7fc2b34db8b0 on display-2:1
5430 [14.516827:0x103f4dca4] WRITE: Write 6 bytes on display-2:1
5431 [14.516861:0x103f4dcf2] WRITE: Wrote 6 bytes on display-2:1
5538 [14.867105:0x103f49898] WRITE: Message 0x7fc2b1cc5530 on display-2:1
5539 [14.867106:0x103f4dca4] WRITE: Write 6 bytes on display-2:1
5540 [14.867131:0x103f4dcf2] WRITE: Wrote 6 bytes on display-2:1
5659 [15.014588:0x103f49898] WRITE: Message 0x7fc2b1cc3de0 on display-2:1
5660 [15.014590:0x103f4dca4] WRITE: Write 6 bytes on display-2:1
5661 [15.014616:0x103f4dcf2] WRITE: Wrote 6 bytes on display-2:1
5773 [15.363673:0x103f49898] WRITE: Message 0x7fc2b3543010 on display-2:1
5774 [15.363674:0x103f4dca4] WRITE: Write 6 bytes on display-2:1
5775 [15.363735:0x103f4dcf2] WRITE: Wrote 6 bytes on display-2:1
5776 [15.363743:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1550 ms (ts: 700199145, mmtime: 700200695
5781 [15.363783:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1533 ms (ts: 700199162, mmtime: 700200695
5786 [15.363814:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1517 ms (ts: 700199178, mmtime: 700200695
5791 [15.411214:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1546 ms (ts: 700199196, mmtime: 700200742
5796 [15.411257:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1530 ms (ts: 700199212, mmtime: 700200742
5797 [15.411261:0x103f443c7] DEBUG: spice_session_sync_playback_latency: not implemented when there isn't audio playback
5798 [15.411543:0x103f94e5f] DEBUG: schedule_frame: rendering too late by 3230 ms (ts: 700197512, mmtime: 700200742
5803 [15.415781:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1518 ms (ts: 700199229, mmtime: 700200747
5804 [15.464122:0x103f94e5f] DEBUG: schedule_frame: rendering too late by 3228 ms (ts: 700197567, mmtime: 700200795
5809 [15.464339:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1549 ms (ts: 700199246, mmtime: 700200795
5814 [15.464382:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1533 ms (ts: 700199262, mmtime: 700200795
5819 [15.464416:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1516 ms (ts: 700199279, mmtime: 700200795
5820 [15.514345:0x103f94e5f] DEBUG: schedule_frame: rendering too late by 3213 ms (ts: 700197632, mmtime: 700200845
5825 [15.514532:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1549 ms (ts: 700199296, mmtime: 700200845
5826 [15.514546:0x103f443c7] DEBUG: spice_session_sync_playback_latency: not implemented when there isn't audio playback
5831 [15.514586:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1533 ms (ts: 700199312, mmtime: 700200845
5836 [15.514617:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1516 ms (ts: 700199329, mmtime: 700200845
5841 [15.561751:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1548 ms (ts: 700199345, mmtime: 700200893
5846 [15.561791:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1532 ms (ts: 700199361, mmtime: 700200893
5851 [15.561818:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1515 ms (ts: 700199378, mmtime: 700200893
5852 [15.561822:0x103f443c7] DEBUG: spice_session_sync_playback_latency: not implemented when there isn't audio playback
5853 [15.563314:0x103f94e5f] DEBUG: schedule_frame: rendering too late by 3198 ms (ts: 700197696, mmtime: 700200894
5854 [15.626031:0x103f94e5f] DEBUG: schedule_frame: rendering too late by 3211 ms (ts: 700197746, mmtime: 700200957
5859 [15.626296:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1563 ms (ts: 700199394, mmtime: 700200957
5864 [15.626353:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1547 ms (ts: 700199410, mmtime: 700200957
5869 [15.626396:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1530 ms (ts: 700199427, mmtime: 700200957
5874 [15.687521:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1574 ms (ts: 700199444, mmtime: 700201018
5879 [15.687597:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1557 ms (ts: 700199461, mmtime: 700201018
5880 [15.687609:0x103f443c7] DEBUG: spice_session_sync_playback_latency: not implemented when there isn't audio playback
5885 [15.687659:0x103f49898] WRITE: Message 0x7fc2b300f1e0 on display-2:1
5886 [15.687661:0x103f4dca4] WRITE: Write 6 bytes on display-2:1
5887 [15.687700:0x103f4dcf2] WRITE: Wrote 6 bytes on display-2:1
5888 [15.687707:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1540 ms (ts: 700199478, mmtime: 700201018
5893 [15.687761:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1525 ms (ts: 700199494, mmtime: 700201019
5898 [15.752204:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1572 ms (ts: 700199511, mmtime: 700201083
5903 [15.752269:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1555 ms (ts: 700199528, mmtime: 700201083
5908 [15.752312:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1538 ms (ts: 700199545, mmtime: 700201083
5909 [15.752318:0x103f443c7] DEBUG: spice_session_sync_playback_latency: not implemented when there isn't audio playback
5914 [15.752359:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1522 ms (ts: 700199561, mmtime: 700201083
5915 [15.754692:0x103f94e5f] DEBUG: schedule_frame: rendering too late by 3256 ms (ts: 700197829, mmtime: 700201085
5920 [15.816428:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1569 ms (ts: 700199578, mmtime: 700201147
5925 [15.816498:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1553 ms (ts: 700199594, mmtime: 700201147
5930 [15.816539:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1536 ms (ts: 700199611, mmtime: 700201147
5935 [15.816580:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1519 ms (ts: 700199628, mmtime: 700201147
5936 [15.816587:0x103f443c7] DEBUG: spice_session_sync_playback_latency: not implemented when there isn't audio playback
5937 [15.819190:0x103f94e5f] DEBUG: schedule_frame: rendering too late by 3271 ms (ts: 700197879, mmtime: 700201150
5942 [15.882718:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1569 ms (ts: 700199645, mmtime: 700201214
5947 [15.882806:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1553 ms (ts: 700199661, mmtime: 700201214
5952 [15.882881:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1536 ms (ts: 700199678, mmtime: 700201214
5957 [15.882935:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1520 ms (ts: 700199694, mmtime: 700201214
5962 [15.949206:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1569 ms (ts: 700199711, mmtime: 700201280
5963 [15.949225:0x103f443c7] DEBUG: spice_session_sync_playback_latency: not implemented when there isn't audio playback
5968 [15.949263:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1552 ms (ts: 700199728, mmtime: 700201280
5973 [15.949304:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1536 ms (ts: 700199744, mmtime: 700201280
5978 [15.949345:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1519 ms (ts: 700199761, mmtime: 700201280
5979 [15.951561:0x103f94e5f] DEBUG: schedule_frame: rendering too late by 3319 ms (ts: 700197963, mmtime: 700201282
5984 [15.951762:0x103f49898] WRITE: Message 0x7fc2b363e4c0 on main-1:0
5985 [15.951763:0x103f4dca4] WRITE: Write 18 bytes on main-1:0
5986 [15.951845:0x103f4dcf2] WRITE: Wrote 18 bytes on main-1:0
5991 [15.951870:0x103f49898] WRITE: Message 0x7fc2b363e4c0 on main-1:0
5992 [15.951870:0x103f4dca4] WRITE: Write 18 bytes on main-1:0
5993 [15.951894:0x103f4dcf2] WRITE: Wrote 18 bytes on main-1:0
5998 [16.014855:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1568 ms (ts: 700199778, mmtime: 700201346
6003 [16.014919:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1551 ms (ts: 700199795, mmtime: 700201346
6004 [16.014926:0x103f443c7] DEBUG: spice_session_sync_playback_latency: not implemented when there isn't audio playback
6009 [16.014968:0x103f49898] WRITE: Message 0x7fc2b34ca110 on display-2:1
6010 [16.014970:0x103f4dca4] WRITE: Write 6 bytes on display-2:1
6011 [16.015009:0x103f4dcf2] WRITE: Wrote 6 bytes on display-2:1
6012 [16.015014:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1535 ms (ts: 700199811, mmtime: 700201346
6017 [16.015060:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1519 ms (ts: 700199827, mmtime: 700201346
6018 [16.018298:0x103f94e5f] DEBUG: schedule_frame: rendering too late by 3337 ms (ts: 700198012, mmtime: 700201349
6019 [16.082571:0x103f94e5f] DEBUG: schedule_frame: rendering too late by 3351 ms (ts: 700198062, mmtime: 700201413
6024 [16.082838:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1570 ms (ts: 700199844, mmtime: 700201414
6029 [16.082893:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1553 ms (ts: 700199861, mmtime: 700201414
6034 [16.082935:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1536 ms (ts: 700199878, mmtime: 700201414
6035 [16.082942:0x103f443c7] DEBUG: spice_session_sync_playback_latency: not implemented when there isn't audio playback
6040 [16.082977:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1519 ms (ts: 700199895, mmtime: 700201414
6045 [16.143436:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1563 ms (ts: 700199911, mmtime: 700201474
6050 [16.143646:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1547 ms (ts: 700199927, mmtime: 700201474
6055 [16.143704:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1531 ms (ts: 700199944, mmtime: 700201475
6060 [16.143741:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1514 ms (ts: 700199961, mmtime: 700201475
6061 [16.143749:0x103f443c7] DEBUG: spice_session_sync_playback_latency: not implemented when there isn't audio playback
6062 [16.146222:0x103f94e5f] DEBUG: schedule_frame: rendering too late by 3348 ms (ts: 700198129, mmtime: 700201477
6067 [16.214875:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1569 ms (ts: 700199977, mmtime: 700201546
6072 [16.214968:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1551 ms (ts: 700199995, mmtime: 700201546
6077 [16.215047:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1535 ms (ts: 700200011, mmtime: 700201546
6082 [16.215123:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1520 ms (ts: 700200026, mmtime: 700201546
6083 [16.217415:0x103f94e5f] DEBUG: schedule_frame: rendering too late by 3370 ms (ts: 700198178, mmtime: 700201548
6088 [16.273880:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1562 ms (ts: 700200043, mmtime: 700201605
6089 [16.273894:0x103f443c7] DEBUG: spice_session_sync_playback_latency: not implemented when there isn't audio playback
6094 [16.273929:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1541 ms (ts: 700200064, mmtime: 700201605
6099 [16.273956:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1524 ms (ts: 700200081, mmtime: 700201605
6100 [16.276059:0x103f94e5f] DEBUG: schedule_frame: rendering too late by 3379 ms (ts: 700198228, mmtime: 700201607
6105 [16.329095:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1563 ms (ts: 700200097, mmtime: 700201660
6110 [16.329157:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1544 ms (ts: 700200116, mmtime: 700201660
6115 [16.329212:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1528 ms (ts: 700200132, mmtime: 700201660
6116 [16.329219:0x103f443c7] DEBUG: spice_session_sync_playback_latency: not implemented when there isn't audio playback
6117 [16.330583:0x103f94e5f] DEBUG: schedule_frame: rendering too late by 3383 ms (ts: 700198278, mmtime: 700201661
6122 [16.331933:0x103f49898] WRITE: Message 0x7fc2b344b550 on display-2:1
6123 [16.331935:0x103f4dca4] WRITE: Write 6 bytes on display-2:1
6124 [16.331974:0x103f4dcf2] WRITE: Wrote 6 bytes on display-2:1
6125 [16.331984:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1515 ms (ts: 700200148, mmtime: 700201663
6130 [16.386511:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1552 ms (ts: 700200165, mmtime: 700201717
6135 [16.386595:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1536 ms (ts: 700200181, mmtime: 700201717
6140 [16.386660:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1520 ms (ts: 700200197, mmtime: 700201717
6141 [16.390003:0x103f94e5f] DEBUG: schedule_frame: rendering too late by 3392 ms (ts: 700198329, mmtime: 700201721
6146 [16.448928:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1565 ms (ts: 700200215, mmtime: 700201780
6147 [16.448945:0x103f443c7] DEBUG: spice_session_sync_playback_latency: not implemented when there isn't audio playback
6152 [16.448983:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1550 ms (ts: 700200230, mmtime: 700201780
6157 [16.449020:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1533 ms (ts: 700200247, mmtime: 700201780
6162 [16.449060:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1517 ms (ts: 700200263, mmtime: 700201780
6163 [16.451342:0x103f94e5f] DEBUG: schedule_frame: rendering too late by 3403 ms (ts: 700198379, mmtime: 700201782
6168 [16.503188:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1555 ms (ts: 700200279, mmtime: 700201834
6173 [16.503242:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1539 ms (ts: 700200295, mmtime: 700201834
6174 [16.503248:0x103f443c7] DEBUG: spice_session_sync_playback_latency: not implemented when there isn't audio playback
6179 [16.503284:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1522 ms (ts: 700200312, mmtime: 700201834
6184 [16.550776:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1555 ms (ts: 700200327, mmtime: 700201882
6189 [16.550975:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1539 ms (ts: 700200343, mmtime: 700201882
6194 [16.551056:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1539 ms (ts: 700200343, mmtime: 700201882
6199 [16.551132:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1539 ms (ts: 700200343, mmtime: 700201882
6200 [16.551140:0x103f443c7] DEBUG: spice_session_sync_playback_latency: not implemented when there isn't audio playback
6205 [16.551204:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1539 ms (ts: 700200343, mmtime: 700201882
6210 [16.551332:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1539 ms (ts: 700200343, mmtime: 700201882
6215 [16.551403:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1539 ms (ts: 700200343, mmtime: 700201882
6220 [16.551459:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1539 ms (ts: 700200343, mmtime: 700201882
6225 [16.551595:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1539 ms (ts: 700200343, mmtime: 700201882
6226 [16.551681:0x103f443c7] DEBUG: spice_session_sync_playback_latency: not implemented when there isn't audio playback
6231 [16.551775:0x103f49898] WRITE: Message 0x7fc2b345aaf0 on display-2:1
6232 [16.551777:0x103f4dca4] WRITE: Write 6 bytes on display-2:1
6233 [16.551869:0x103f4dcf2] WRITE: Wrote 6 bytes on display-2:1
6234 [16.551884:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1540 ms (ts: 700200343, mmtime: 700201883
6239 [16.551946:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1540 ms (ts: 700200343, mmtime: 700201883
6244 [16.551987:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1539 ms (ts: 700200344, mmtime: 700201883
6248 [16.554537:0x103f94e5f] DEBUG: schedule_frame: rendering too late by 3406 ms (ts: 700198479, mmtime: 700201885
6250 [16.554763:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1527 ms (ts: 700200359, mmtime: 700201886
6255 [16.604956:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1561 ms (ts: 700200375, mmtime: 700201936
6256 [16.604975:0x103f443c7] DEBUG: spice_session_sync_playback_latency: not implemented when there isn't audio playback
6261 [16.605000:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1526 ms (ts: 700200410, mmtime: 700201936
6262 [16.607411:0x103f94e5f] DEBUG: schedule_frame: rendering too late by 3409 ms (ts: 700198529, mmtime: 700201938
6267 [16.610243:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1513 ms (ts: 700200428, mmtime: 700201941
6268 [16.656586:0x103f94e5f] DEBUG: schedule_frame: rendering too late by 3408 ms (ts: 700198579, mmtime: 700201987
6273 [16.656793:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1543 ms (ts: 700200445, mmtime: 700201988
6278 [16.656894:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1527 ms (ts: 700200461, mmtime: 700201988
6283 [16.704076:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1557 ms (ts: 700200478, mmtime: 700202035
6284 [16.704093:0x103f443c7] DEBUG: spice_session_sync_playback_latency: not implemented when there isn't audio playback
6289 [16.704175:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1540 ms (ts: 700200495, mmtime: 700202035
6294 [16.704206:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1523 ms (ts: 700200512, mmtime: 700202035
6295 [16.706440:0x103f94e5f] DEBUG: schedule_frame: rendering too late by 3408 ms (ts: 700198629, mmtime: 700202037
6300 [16.756232:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1559 ms (ts: 700200528, mmtime: 700202087
6305 [16.756307:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1542 ms (ts: 700200545, mmtime: 700202087
6310 [16.756325:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1525 ms (ts: 700200562, mmtime: 700202087
6311 [16.756328:0x103f443c7] DEBUG: spice_session_sync_playback_latency: not implemented when there isn't audio playback
6312 [16.778735:0x103f952de] DEBUG: the GStreamer pipeline dropped a frame
6313 [16.778739:0x103f952de] DEBUG: the GStreamer pipeline dropped a frame
6314 [16.778741:0x103f952de] DEBUG: the GStreamer pipeline dropped a frame
6315 [16.778742:0x103f952de] DEBUG: the GStreamer pipeline dropped a frame
6316 [16.778743:0x103f952de] DEBUG: the GStreamer pipeline dropped a frame
6317 [16.778746:0x103f952de] DEBUG: the GStreamer pipeline dropped a frame
6318 [16.778747:0x103f952de] DEBUG: the GStreamer pipeline dropped a frame
6319 [16.778748:0x103f952de] DEBUG: the GStreamer pipeline dropped a frame
6320 [16.778749:0x103f952de] DEBUG: the GStreamer pipeline dropped a frame
6321 [16.778751:0x103f952de] DEBUG: the GStreamer pipeline dropped a frame
6326 [16.798403:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1550 ms (ts: 700200579, mmtime: 700202129
6331 [16.798476:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1534 ms (ts: 700200595, mmtime: 700202129
6336 [16.798494:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1516 ms (ts: 700200613, mmtime: 700202129
6337 [16.800659:0x103f94e5f] DEBUG: schedule_frame: rendering too late by 3436 ms (ts: 700198695, mmtime: 700202131
6338 [16.850862:0x103f94e5f] DEBUG: schedule_frame: rendering too late by 3437 ms (ts: 700198745, mmtime: 700202182
6343 [16.851043:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1552 ms (ts: 700200630, mmtime: 700202182
6348 [16.851114:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1536 ms (ts: 700200646, mmtime: 700202182
6349 [16.851122:0x103f443c7] DEBUG: spice_session_sync_playback_latency: not implemented when there isn't audio playback
6354 [16.851137:0x103f49898] WRITE: Message 0x7fc2b3625570 on display-2:1
6355 [16.851138:0x103f4dca4] WRITE: Write 6 bytes on display-2:1
6356 [16.851168:0x103f4dcf2] WRITE: Wrote 6 bytes on display-2:1
6357 [16.851171:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1519 ms (ts: 700200663, mmtime: 700202182
6362 [16.901611:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1552 ms (ts: 700200680, mmtime: 700202232
6367 [16.901673:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1537 ms (ts: 700200696, mmtime: 700202233
6372 [16.901692:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1520 ms (ts: 700200713, mmtime: 700202233
6373 [16.903054:0x103f94e5f] DEBUG: schedule_frame: rendering too late by 3422 ms (ts: 700198812, mmtime: 700202234
6378 [16.949273:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1551 ms (ts: 700200729, mmtime: 700202280
6379 [16.949288:0x103f443c7] DEBUG: spice_session_sync_playback_latency: not implemented when there isn't audio playback
6384 [16.949346:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1533 ms (ts: 700200747, mmtime: 700202280
6389 [16.949363:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1518 ms (ts: 700200762, mmtime: 700202280
6390 [16.949716:0x103f94e5f] DEBUG: schedule_frame: rendering too late by 3419 ms (ts: 700198862, mmtime: 700202281
6395 [17.004732:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1556 ms (ts: 700200780, mmtime: 700202336
6400 [17.004784:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1539 ms (ts: 700200797, mmtime: 700202336
6405 [17.004801:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1523 ms (ts: 700200813, mmtime: 700202336
6406 [17.004806:0x103f443c7] DEBUG: spice_session_sync_playback_latency: not implemented when there isn't audio playback
6407 [17.006907:0x103f94e5f] DEBUG: schedule_frame: rendering too late by 3426 ms (ts: 700198912, mmtime: 700202338
6412 [17.053816:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1555 ms (ts: 700200830, mmtime: 700202385
6417 [17.053877:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1538 ms (ts: 700200847, mmtime: 700202385
6422 [17.053908:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1521 ms (ts: 700200864, mmtime: 700202385
6427 [17.104800:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1556 ms (ts: 700200880, mmtime: 700202436
6432 [17.104868:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1538 ms (ts: 700200898, mmtime: 700202436
6433 [17.104873:0x103f443c7] DEBUG: spice_session_sync_playback_latency: not implemented when there isn't audio playback
6438 [17.104886:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1521 ms (ts: 700200915, mmtime: 700202436
6439 [17.151794:0x103f94e5f] DEBUG: schedule_frame: rendering too late by 3436 ms (ts: 700199047, mmtime: 700202483
6440 [17.151821:0x103f94e5f] DEBUG: schedule_frame: rendering too late by 3420 ms (ts: 700199063, mmtime: 700202483
6445 [17.152284:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1552 ms (ts: 700200931, mmtime: 700202483
6450 [17.152326:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1535 ms (ts: 700200948, mmtime: 700202483
6455 [17.202828:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1569 ms (ts: 700200965, mmtime: 700202534
6460 [17.202906:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1553 ms (ts: 700200981, mmtime: 700202534
6461 [17.202910:0x103f443c7] DEBUG: spice_session_sync_playback_latency: not implemented when there isn't audio playback
6466 [17.202925:0x103f49898] WRITE: Message 0x7fc2b3519d80 on display-2:1
6467 [17.202926:0x103f4dca4] WRITE: Write 6 bytes on display-2:1
6468 [17.202952:0x103f4dcf2] WRITE: Wrote 6 bytes on display-2:1
6469 [17.202955:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1536 ms (ts: 700200998, mmtime: 700202534
6470 [17.205245:0x103f94e5f] DEBUG: schedule_frame: rendering too late by 3424 ms (ts: 700199112, mmtime: 700202536
6471 [17.260636:0x103f94e5f] DEBUG: schedule_frame: rendering too late by 3430 ms (ts: 700199162, mmtime: 700202592
6476 [17.260840:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1578 ms (ts: 700201014, mmtime: 700202592
6481 [17.260892:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1561 ms (ts: 700201031, mmtime: 700202592
6486 [17.260910:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1544 ms (ts: 700201048, mmtime: 700202592
6491 [17.265116:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1532 ms (ts: 700201064, mmtime: 700202596
6492 [17.265130:0x103f443c7] DEBUG: spice_session_sync_playback_latency: not implemented when there isn't audio playback
6497 [17.316287:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1566 ms (ts: 700201081, mmtime: 700202647
6457 [17.202849:0x103f4a5d1] READ: Read 6 bytes from display-2:1, total 4410605
6458 [17.202850:0x103f4a4c4] READ: Reading 2123 bytes from display-2:1
6459 [17.202903:0x103f4a5d1] READ: Read 2123 bytes from display-2:1, total 4412728
6462 [17.202915:0x103f4a4c4] READ: Reading 6 bytes from display-2:1
6463 [17.202918:0x103f4a5d1] READ: Read 6 bytes from display-2:1, total 4412734
6464 [17.202919:0x103f4a4c4] READ: Reading 1996 bytes from display-2:1
6465 [17.202923:0x103f4a5d1] READ: Read 1996 bytes from display-2:1, total 4414730
6472 [17.260817:0x103f4a4c4] READ: Reading 6 bytes from display-2:1
6473 [17.260827:0x103f4a5d1] READ: Read 6 bytes from display-2:1, total 4414736
6474 [17.260829:0x103f4a4c4] READ: Reading 1893 bytes from display-2:1
6475 [17.260833:0x103f4a5d1] READ: Read 1893 bytes from display-2:1, total 4416629
6477 [17.260860:0x103f4a4c4] READ: Reading 6 bytes from display-2:1
6478 [17.260864:0x103f4a5d1] READ: Read 6 bytes from display-2:1, total 4416635
6479 [17.260864:0x103f4a4c4] READ: Reading 1912 bytes from display-2:1
6480 [17.260890:0x103f4a5d1] READ: Read 1912 bytes from display-2:1, total 4418547
6482 [17.260900:0x103f4a4c4] READ: Reading 6 bytes from display-2:1
6483 [17.260903:0x103f4a5d1] READ: Read 6 bytes from display-2:1, total 4418553
6484 [17.260904:0x103f4a4c4] READ: Reading 2647 bytes from display-2:1
6485 [17.260908:0x103f4a5d1] READ: Read 2647 bytes from display-2:1, total 4421200
6487 [17.265079:0x103f4a4c4] READ: Reading 6 bytes from display-2:1
6488 [17.265090:0x103f4a5d1] READ: Read 6 bytes from display-2:1, total 4421206
6489 [17.265092:0x103f4a4c4] READ: Reading 1859 bytes from display-2:1
6490 [17.265095:0x103f4a5d1] READ: Read 1859 bytes from display-2:1, total 4423065
6493 [17.316261:0x103f4a4c4] READ: Reading 6 bytes from display-2:1
6494 [17.316275:0x103f4a5d1] READ: Read 6 bytes from display-2:1, total 4423071
6495 [17.316276:0x103f4a4c4] READ: Reading 1892 bytes from display-2:1
6496 [17.316281:0x103f4a5d1] READ: Read 1892 bytes from display-2:1, total 4424963
6498 [17.316306:0x103f4a4c4] READ: Reading 6 bytes from display-2:1
6499 [17.316308:0x103f4a5d1] READ: Read 6 bytes from display-2:1, total 4424969
6500 [17.316309:0x103f4a4c4] READ: Reading 1842 bytes from display-2:1
6501 [17.316353:0x103f4a5d1] READ: Read 1842 bytes from display-2:1, total 4426811
6502 [17.316355:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1550 ms (ts: 700201097, mmtime: 700202647
6503 [17.316363:0x103f4a4c4] READ: Reading 6 bytes from display-2:1
6504 [17.316367:0x103f4a5d1] READ: Read 6 bytes from display-2:1, total 4426817
6505 [17.316368:0x103f4a4c4] READ: Reading 1868 bytes from display-2:1
6506 [17.316371:0x103f4a5d1] READ: Read 1868 bytes from display-2:1, total 4428685
6507 [17.316372:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1533 ms (ts: 700201114, mmtime: 700202647
6508 [17.316379:0x103f4a4c4] READ: Reading 6 bytes from display-2:1
6509 [17.316382:0x103f4a5d1] READ: Read 6 bytes from display-2:1, total 4428691
6510 [17.316382:0x103f4a4c4] READ: Reading 1702 bytes from display-2:1
6511 [17.316394:0x103f4a5d1] READ: Read 1702 bytes from display-2:1, total 4430393
6512 [17.316395:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1517 ms (ts: 700201130, mmtime: 700202647
6513 [17.369460:0x103f4a4c4] READ: Reading 6 bytes from display-2:1
6514 [17.369471:0x103f4a5d1] READ: Read 6 bytes from display-2:1, total 4430399
6515 [17.369473:0x103f4a4c4] READ: Reading 1662 bytes from display-2:1
6516 [17.369477:0x103f4a5d1] READ: Read 1662 bytes from display-2:1, total 4432061
6517 [17.369483:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1553 ms (ts: 700201147, mmtime: 700202700
6518 [17.369497:0x103f443c7] DEBUG: spice_session_sync_playback_latency: not implemented when there isn't audio playback
6519 [17.369502:0x103f4a4c4] READ: Reading 6 bytes from display-2:1
6520 [17.369505:0x103f4a5d1] READ: Read 6 bytes from display-2:1, total 4432067
6521 [17.369505:0x103f4a4c4] READ: Reading 2550 bytes from display-2:1
6522 [17.369531:0x103f4a5d1] READ: Read 2550 bytes from display-2:1, total 4434617
6523 [17.369534:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1537 ms (ts: 700201163, mmtime: 700202700
6524 [17.421632:0x103f4a4c4] READ: Reading 6 bytes from display-2:1
6525 [17.421644:0x103f4a5d1] READ: Read 6 bytes from display-2:1, total 4434623
6526 [17.421646:0x103f4a4c4] READ: Reading 1742 bytes from display-2:1
6527 [17.421650:0x103f4a5d1] READ: Read 1742 bytes from display-2:1, total 4436365
6528 [17.421656:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1573 ms (ts: 700201180, mmtime: 700202753
6529 [17.421673:0x103f4a4c4] READ: Reading 6 bytes from display-2:1
6530 [17.421676:0x103f4a5d1] READ: Read 6 bytes from display-2:1, total 4436371
6531 [17.421677:0x103f4a4c4] READ: Reading 1748 bytes from display-2:1
6532 [17.421702:0x103f4a5d1] READ: Read 1748 bytes from display-2:1, total 4438119
6533 [17.421704:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1557 ms (ts: 700201196, mmtime: 700202753
6534 [17.421713:0x103f4a4c4] READ: Reading 6 bytes from display-2:1
6535 [17.421716:0x103f4a5d1] READ: Read 6 bytes from display-2:1, total 4438125
6536 [17.421717:0x103f4a4c4] READ: Reading 1858 bytes from display-2:1
6537 [17.421721:0x103f4a5d1] READ: Read 1858 bytes from display-2:1, total 4439983
6538 [17.421722:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1540 ms (ts: 700201213, mmtime: 700202753
6539 [17.472558:0x103f4a4c4] READ: Reading 6 bytes from display-2:1
6540 [17.472575:0x103f4a5d1] READ: Read 6 bytes from display-2:1, total 4439989
6541 [17.472576:0x103f4a4c4] READ: Reading 1936 bytes from display-2:1
6542 [17.472584:0x103f4a5d1] READ: Read 1936 bytes from display-2:1, total 4441925
6543 [17.472592:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1573 ms (ts: 700201230, mmtime: 700202803
6544 [17.472608:0x103f443c7] DEBUG: spice_session_sync_playback_latency: not implemented when there isn't audio playback
6545 [17.472615:0x103f4a4c4] READ: Reading 6 bytes from display-2:1
6546 [17.472619:0x103f4a5d1] READ: Read 6 bytes from display-2:1, total 4441931
6547 [17.472620:0x103f4a4c4] READ: Reading 1897 bytes from display-2:1
6548 [17.472658:0x103f4a5d1] READ: Read 1897 bytes from display-2:1, total 4443828
6549 [17.472661:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1558 ms (ts: 700201246, mmtime: 700202804
6550 [17.472672:0x103f4a4c4] READ: Reading 6 bytes from display-2:1
6551 [17.472677:0x103f4a5d1] READ: Read 6 bytes from display-2:1, total 4443834
6552 [17.472678:0x103f4a4c4] READ: Reading 1713 bytes from display-2:1
6553 [17.472682:0x103f4a5d1] READ: Read 1713 bytes from display-2:1, total 4445547
6554 [17.472684:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1541 ms (ts: 700201263, mmtime: 700202804
6555 [17.472692:0x103f4a4c4] READ: Reading 6 bytes from display-2:1
6556 [17.472694:0x103f4a5d1] READ: Read 6 bytes from display-2:1, total 4445553
6557 [17.472695:0x103f4a4c4] READ: Reading 2651 bytes from display-2:1
6558 [17.472710:0x103f4a5d1] READ: Read 2651 bytes from display-2:1, total 4448204
6559 [17.472711:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1525 ms (ts: 700201279, mmtime: 700202804
6560 [17.474860:0x103f4a4c4] READ: Reading 6 bytes from display-2:0
6561 [17.474872:0x103f4a5d1] READ: Read 6 bytes from display-2:0, total 1152437
6562 [17.474873:0x103f4a4c4] READ: Reading 12 bytes from display-2:0
6563 [17.474875:0x103f4a5d1] READ: Read 12 bytes from display-2:0, total 1152449
6564 [17.474880:0x103f49898] WRITE: Message 0x7fc2b3533830 on display-2:0
6565 [17.474881:0x103f4dca4] WRITE: Write 18 bytes on display-2:0
6566 [17.474937:0x103f4dcf2] WRITE: Wrote 18 bytes on display-2:0
6567 [17.474944:0x103f4a4c4] READ: Reading 6 bytes from display-2:0
6568 [17.474947:0x103f4a5d1] READ: Read 6 bytes from display-2:0, total 1152455
6569 [17.474947:0x103f4a4c4] READ: Reading 12 bytes from display-2:0
6570 [17.474950:0x103f4a5d1] READ: Read 12 bytes from display-2:0, total 1152467
6571 [17.474952:0x103f49898] WRITE: Message 0x7fc2b3533830 on display-2:0
6572 [17.474952:0x103f4dca4] WRITE: Write 18 bytes on display-2:0
6573 [17.474966:0x103f4dcf2] WRITE: Wrote 18 bytes on display-2:0
6574 [17.479691:0x103f4a4c4] READ: Reading 6 bytes from display-2:1
6575 [17.479707:0x103f4a5d1] READ: Read 6 bytes from display-2:1, total 4448210
6576 [17.479710:0x103f4a4c4] READ: Reading 1825 bytes from display-2:1
6577 [17.479715:0x103f4a5d1] READ: Read 1825 bytes from display-2:1, total 4450035
6578 [17.479722:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1515 ms (ts: 700201296, mmtime: 700202811
6579 [17.527369:0x103f4a4c4] READ: Reading 6 bytes from display-2:1
6580 [17.527390:0x103f4a5d1] READ: Read 6 bytes from display-2:1, total 4450041
6581 [17.527391:0x103f4a4c4] READ: Reading 1893 bytes from display-2:1
6582 [17.527399:0x103f4a5d1] READ: Read 1893 bytes from display-2:1, total 4451934
6583 [17.527406:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1546 ms (ts: 700201312, mmtime: 700202858
6584 [17.527423:0x103f443c7] DEBUG: spice_session_sync_playback_latency: not implemented when there isn't audio playback
6585 [17.527430:0x103f4a4c4] READ: Reading 6 bytes from display-2:1
6586 [17.527434:0x103f4a5d1] READ: Read 6 bytes from display-2:1, total 4451940
6587 [17.527436:0x103f4a4c4] READ: Reading 1841 bytes from display-2:1
6588 [17.527495:0x103f4a5d1] READ: Read 1841 bytes from display-2:1, total 4453781
6589 [17.527500:0x103f49898] WRITE: Message 0x7fc2b362b8c0 on display-2:1
6590 [17.527502:0x103f4dca4] WRITE: Write 6 bytes on display-2:1
6591 [17.527541:0x103f4dcf2] WRITE: Wrote 6 bytes on display-2:1
6592 [17.527548:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1529 ms (ts: 700201329, mmtime: 700202858
6593 [17.530100:0x103f4a4c4] READ: Reading 6 bytes from display-2:1
6594 [17.530118:0x103f4a5d1] READ: Read 6 bytes from display-2:1, total 4453787
6595 [17.530120:0x103f4a4c4] READ: Reading 1806 bytes from display-2:1
6596 [17.530128:0x103f4a5d1] READ: Read 1806 bytes from display-2:1, total 4455593
6597 [17.530135:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1515 ms (ts: 700201346, mmtime: 700202861
6598 [17.590360:0x103f94e5f] DEBUG: schedule_frame: rendering too late by 3443 ms (ts: 700199478, mmtime: 700202921
6599 [17.590372:0x103f94e5f] DEBUG: schedule_frame: rendering too late by 3427 ms (ts: 700199494, mmtime: 700202921
6600 [17.591261:0x103f4a4c4] READ: Reading 6 bytes from display-2:1
6601 [17.591276:0x103f4a5d1] READ: Read 6 bytes from display-2:1, total 4455599
6602 [17.591278:0x103f4a4c4] READ: Reading 2055 bytes from display-2:1
6603 [17.591285:0x103f4a5d1] READ: Read 2055 bytes from display-2:1, total 4457654
6604 [17.591291:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1560 ms (ts: 700201362, mmtime: 700202922
6605 [17.591310:0x103f4a4c4] READ: Reading 6 bytes from display-2:1
6606 [17.591314:0x103f4a5d1] READ: Read 6 bytes from display-2:1, total 4457660
6607 [17.591316:0x103f4a4c4] READ: Reading 1744 bytes from display-2:1
6608 [17.591346:0x103f4a5d1] READ: Read 1744 bytes from display-2:1, total 4459404
6609 [17.591349:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1543 ms (ts: 700201379, mmtime: 700202922
6610 [17.635393:0x103f4a4c4] READ: Reading 6 bytes from display-2:1
6611 [17.635412:0x103f4a5d1] READ: Read 6 bytes from display-2:1, total 4459410
6612 [17.635414:0x103f4a4c4] READ: Reading 1782 bytes from display-2:1
6613 [17.635422:0x103f4a5d1] READ: Read 1782 bytes from display-2:1, total 4461192
6614 [17.635431:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1571 ms (ts: 700201395, mmtime: 700202966
6615 [17.635447:0x103f443c7] DEBUG: spice_session_sync_playback_latency: not implemented when there isn't audio playback
6616 [17.635455:0x103f4a4c4] READ: Reading 6 bytes from display-2:1
6617 [17.635461:0x103f4a5d1] READ: Read 6 bytes from display-2:1, total 4461198
6618 [17.635462:0x103f4a4c4] READ: Reading 1760 bytes from display-2:1
6619 [17.635517:0x103f4a5d1] READ: Read 1760 bytes from display-2:1, total 4462958
6620 [17.635522:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1555 ms (ts: 700201411, mmtime: 700202966
6621 [17.635541:0x103f4a4c4] READ: Reading 6 bytes from display-2:1
6622 [17.635548:0x103f4a5d1] READ: Read 6 bytes from display-2:1, total 4462964
6623 [17.635549:0x103f4a4c4] READ: Reading 1677 bytes from display-2:1
6624 [17.635555:0x103f4a5d1] READ: Read 1677 bytes from display-2:1, total 4464641
6625 [17.635557:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1538 ms (ts: 700201428, mmtime: 700202966
6626 [17.635566:0x103f4a4c4] READ: Reading 6 bytes from display-2:1
6627 [17.635571:0x103f4a5d1] READ: Read 6 bytes from display-2:1, total 4464647
6628 [17.635572:0x103f4a4c4] READ: Reading 2486 bytes from display-2:1
6629 [17.635602:0x103f4a5d1] READ: Read 2486 bytes from display-2:1, total 4467133
6630 [17.635605:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1521 ms (ts: 700201445, mmtime: 700202966
6631 [17.679067:0x103f4a4c4] READ: Reading 6 bytes from display-2:1
6632 [17.679081:0x103f4a5d1] READ: Read 6 bytes from display-2:1, total 4467139
6633 [17.679082:0x103f4a4c4] READ: Reading 1698 bytes from display-2:1
6634 [17.679087:0x103f4a5d1] READ: Read 1698 bytes from display-2:1, total 4468837
6635 [17.679094:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1549 ms (ts: 700201461, mmtime: 700203010
6636 [17.679113:0x103f4a4c4] READ: Reading 6 bytes from display-2:1
6637 [17.679117:0x103f4a5d1] READ: Read 6 bytes from display-2:1, total 4468843
6638 [17.679118:0x103f4a4c4] READ: Reading 2072 bytes from display-2:1
6639 [17.679162:0x103f4a5d1] READ: Read 2072 bytes from display-2:1, total 4470915
6640 [17.679165:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1532 ms (ts: 700201478, mmtime: 700203010
6641 [17.679172:0x103f443c7] DEBUG: spice_session_sync_playback_latency: not implemented when there isn't audio playback
6642 [17.679599:0x103f94e5f] DEBUG: schedule_frame: rendering too late by 3432 ms (ts: 700199578, mmtime: 700203010
6643 [17.681564:0x103f4a4c4] READ: Reading 6 bytes from display-2:1
6644 [17.681579:0x103f4a5d1] READ: Read 6 bytes from display-2:1, total 4470921
6645 [17.681581:0x103f4a4c4] READ: Reading 1654 bytes from display-2:1
6646 [17.681587:0x103f4a5d1] READ: Read 1654 bytes from display-2:1, total 4472575
6647 [17.681594:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1517 ms (ts: 700201495, mmtime: 700203012
6648 [17.740345:0x103f94e5f] DEBUG: schedule_frame: rendering too late by 3443 ms (ts: 700199628, mmtime: 700203071
6649 [17.740525:0x103f4a4c4] READ: Reading 6 bytes from display-2:1
6650 [17.740539:0x103f4a5d1] READ: Read 6 bytes from display-2:1, total 4472581
6651 [17.740541:0x103f4a4c4] READ: Reading 1597 bytes from display-2:1
6652 [17.740548:0x103f4a5d1] READ: Read 1597 bytes from display-2:1, total 4474178
6653 [17.740555:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1560 ms (ts: 700201511, mmtime: 700203071
6654 [17.740577:0x103f4a4c4] READ: Reading 6 bytes from display-2:1
6655 [17.740581:0x103f4a5d1] READ: Read 6 bytes from display-2:1, total 4474184
6656 [17.740583:0x103f4a4c4] READ: Reading 1535 bytes from display-2:1
6657 [17.740624:0x103f4a5d1] READ: Read 1535 bytes from display-2:1, total 4475719
6658 [17.740628:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1544 ms (ts: 700201528, mmtime: 700203072
6659 [17.740643:0x103f4a4c4] READ: Reading 6 bytes from display-2:1
6660 [17.740648:0x103f4a5d1] READ: Read 6 bytes from display-2:1, total 4475725
6661 [17.740649:0x103f4a4c4] READ: Reading 1544 bytes from display-2:1
6662 [17.740655:0x103f4a5d1] READ: Read 1544 bytes from display-2:1, total 4477269
6663 [17.740658:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1527 ms (ts: 700201545, mmtime: 700203072
6664 [17.787660:0x103f4a4c4] READ: Reading 6 bytes from display-2:1
6665 [17.787672:0x103f4a5d1] READ: Read 6 bytes from display-2:1, total 4477275
6666 [17.787675:0x103f4a4c4] READ: Reading 2463 bytes from display-2:1
6667 [17.787683:0x103f4a5d1] READ: Read 2463 bytes from display-2:1, total 4479738
6668 [17.787689:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1558 ms (ts: 700201561, mmtime: 700203119
6669 [17.787706:0x103f443c7] DEBUG: spice_session_sync_playback_latency: not implemented when there isn't audio playback
6670 [17.787713:0x103f4a4c4] READ: Reading 6 bytes from display-2:1
6671 [17.787718:0x103f4a5d1] READ: Read 6 bytes from display-2:1, total 4479744
6672 [17.787719:0x103f4a4c4] READ: Reading 1566 bytes from display-2:1
6673 [17.787766:0x103f4a5d1] READ: Read 1566 bytes from display-2:1, total 4481310
6674 [17.787770:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1541 ms (ts: 700201578, mmtime: 700203119
6675 [17.787781:0x103f4a4c4] READ: Reading 6 bytes from display-2:1
6676 [17.787787:0x103f4a5d1] READ: Read 6 bytes from display-2:1, total 4481316
6677 [17.787788:0x103f4a4c4] READ: Reading 1558 bytes from display-2:1
6678 [17.787792:0x103f4a5d1] READ: Read 1558 bytes from display-2:1, total 4482874
6679 [17.787794:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1525 ms (ts: 700201594, mmtime: 700203119
6680 [17.831364:0x103f4a4c4] READ: Reading 6 bytes from display-2:1
6681 [17.831384:0x103f4a5d1] READ: Read 6 bytes from display-2:1, total 4482880
6682 [17.831386:0x103f4a4c4] READ: Reading 1526 bytes from display-2:1
6683 [17.831393:0x103f4a5d1] READ: Read 1526 bytes from display-2:1, total 4484406
6684 [17.831400:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1551 ms (ts: 700201611, mmtime: 700203162
6685 [17.831420:0x103f4a4c4] READ: Reading 6 bytes from display-2:1
6686 [17.831424:0x103f4a5d1] READ: Read 6 bytes from display-2:1, total 4484412
6687 [17.831426:0x103f4a4c4] READ: Reading 1553 bytes from display-2:1
6688 [17.831485:0x103f4a5d1] READ: Read 1553 bytes from display-2:1, total 4485965
6689 [17.831488:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1534 ms (ts: 700201628, mmtime: 700203162
6690 [17.831498:0x103f4a4c4] READ: Reading 6 bytes from display-2:1
6691 [17.831503:0x103f4a5d1] READ: Read 6 bytes from display-2:1, total 4485971
6692 [17.831504:0x103f4a4c4] READ: Reading 1653 bytes from display-2:1
6693 [17.831509:0x103f4a5d1] READ: Read 1653 bytes from display-2:1, total 4487624
6694 [17.831510:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1517 ms (ts: 700201645, mmtime: 700203162
6695 [17.831515:0x103f443c7] DEBUG: spice_session_sync_playback_latency: not implemented when there isn't audio playback
6696 [17.879476:0x103f4a4c4] READ: Reading 6 bytes from display-2:1
6697 [17.879489:0x103f4a5d1] READ: Read 6 bytes from display-2:1, total 4487630
6698 [17.879490:0x103f4a4c4] READ: Reading 1539 bytes from display-2:1
6699 [17.879495:0x103f4a5d1] READ: Read 1539 bytes from display-2:1, total 4489169
6700 [17.879498:0x103f49898] WRITE: Message 0x7fc2b3718030 on display-2:1
6701 [17.879499:0x103f4dca4] WRITE: Write 6 bytes on display-2:1
6702 [17.879585:0x103f4dcf2] WRITE: Wrote 6 bytes on display-2:1
6703 [17.879599:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1549 ms (ts: 700201661, mmtime: 700203210
6704 [17.879630:0x103f4a4c4] READ: Reading 6 bytes from display-2:1
6705 [17.879641:0x103f4a5d1] READ: Read 6 bytes from display-2:1, total 4489175
6706 [17.879643:0x103f4a4c4] READ: Reading 2363 bytes from display-2:1
6707 [17.879649:0x103f4a5d1] READ: Read 2363 bytes from display-2:1, total 4491538
6708 [17.879652:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1533 ms (ts: 700201678, mmtime: 700203211
6709 [17.885723:0x103f4a4c4] READ: Reading 6 bytes from display-2:1
6710 [17.885732:0x103f4a5d1] READ: Read 6 bytes from display-2:1, total 4491544
6711 [17.885733:0x103f4a4c4] READ: Reading 1631 bytes from display-2:1
6712 [17.885737:0x103f4a5d1] READ: Read 1631 bytes from display-2:1, total 4493175
6713 [17.885746:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1523 ms (ts: 700201694, mmtime: 700203217
6714 [17.940159:0x103f4a4c4] READ: Reading 6 bytes from display-2:1
6715 [17.940169:0x103f4a5d1] READ: Read 6 bytes from display-2:1, total 4493181
6716 [17.940171:0x103f4a4c4] READ: Reading 1561 bytes from display-2:1
6717 [17.940175:0x103f4a5d1] READ: Read 1561 bytes from display-2:1, total 4494742
6718 [17.940182:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1560 ms (ts: 700201711, mmtime: 700203271
6719 [17.940199:0x103f4a4c4] READ: Reading 6 bytes from display-2:1
6720 [17.940202:0x103f4a5d1] READ: Read 6 bytes from display-2:1, total 4494748
6721 [17.940203:0x103f4a4c4] READ: Reading 1544 bytes from display-2:1
6722 [17.940238:0x103f4a5d1] READ: Read 1544 bytes from display-2:1, total 4496292
6723 [17.940246:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1543 ms (ts: 700201728, mmtime: 700203271
6724 [17.940261:0x103f443c7] DEBUG: spice_session_sync_playback_latency: not implemented when there isn't audio playback
6725 [17.942690:0x103f94e5f] DEBUG: schedule_frame: rendering too late by 3447 ms (ts: 700199827, mmtime: 700203274
6726 [17.942884:0x103f4a4c4] READ: Reading 6 bytes from display-2:1
6727 [17.942900:0x103f4a5d1] READ: Read 6 bytes from display-2:1, total 4496298
6728 [17.942902:0x103f4a4c4] READ: Reading 1479 bytes from display-2:1
6729 [17.942908:0x103f4a5d1] READ: Read 1479 bytes from display-2:1, total 4497777
6730 [17.942915:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1529 ms (ts: 700201745, mmtime: 700203274
6731 [17.996313:0x103f4a4c4] READ: Reading 6 bytes from display-2:1
6732 [17.996327:0x103f4a5d1] READ: Read 6 bytes from display-2:1, total 4497783
6733 [17.996329:0x103f4a4c4] READ: Reading 2437 bytes from display-2:1
6734 [17.996335:0x103f4a5d1] READ: Read 2437 bytes from display-2:1, total 4500220
6735 [17.996342:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1566 ms (ts: 700201761, mmtime: 700203327
6736 [17.996360:0x103f4a4c4] READ: Reading 6 bytes from display-2:1
6737 [17.996363:0x103f4a5d1] READ: Read 6 bytes from display-2:1, total 4500226
6738 [17.996363:0x103f4a4c4] READ: Reading 1586 bytes from display-2:1
6739 [17.996486:0x103f4a5d1] READ: Read 1586 bytes from display-2:1, total 4501812
6740 [17.996489:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1549 ms (ts: 700201778, mmtime: 700203327
6741 [17.996499:0x103f4a4c4] READ: Reading 6 bytes from display-2:1
6742 [17.996504:0x103f4a5d1] READ: Read 6 bytes from display-2:1, total 4501818
6743 [17.996505:0x103f4a4c4] READ: Reading 1557 bytes from display-2:1
6744 [17.996508:0x103f4a5d1] READ: Read 1557 bytes from display-2:1, total 4503375
6745 [17.996509:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1532 ms (ts: 700201795, mmtime: 700203327
6746 [17.996515:0x103f4a4c4] READ: Reading 6 bytes from display-2:1
6747 [17.996518:0x103f4a5d1] READ: Read 6 bytes from display-2:1, total 4503381
6748 [17.996518:0x103f4a4c4] READ: Reading 1520 bytes from display-2:1
6749 [17.996586:0x103f4a5d1] READ: Read 1520 bytes from display-2:1, total 4504901
6750 [17.996589:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1516 ms (ts: 700201811, mmtime: 700203327
6751 [17.996596:0x103f443c7] DEBUG: spice_session_sync_playback_latency: not implemented when there isn't audio playback
6752 [17.998758:0x103f94e5f] DEBUG: schedule_frame: rendering too late by 3452 ms (ts: 700199878, mmtime: 700203330
6753 [18.051859:0x103f4a4c4] READ: Reading 6 bytes from display-2:1
6754 [18.051869:0x103f4a5d1] READ: Read 6 bytes from display-2:1, total 4504907
6755 [18.051871:0x103f4a4c4] READ: Reading 1421 bytes from display-2:1
6756 [18.051875:0x103f4a5d1] READ: Read 1421 bytes from display-2:1, total 4506328
6757 [18.051881:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1555 ms (ts: 700201828, mmtime: 700203383
6758 [18.051901:0x103f4a4c4] READ: Reading 6 bytes from display-2:1
6759 [18.051907:0x103f4a5d1] READ: Read 6 bytes from display-2:1, total 4506334
6760 [18.051908:0x103f4a4c4] READ: Reading 2353 bytes from display-2:1
6761 [18.051944:0x103f4a5d1] READ: Read 2353 bytes from display-2:1, total 4508687
6762 [18.051947:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1538 ms (ts: 700201845, mmtime: 700203383
6763 [18.054221:0x103f94e5f] DEBUG: schedule_frame: rendering too late by 3441 ms (ts: 700199944, mmtime: 700203385
6764 [18.054412:0x103f4a4c4] READ: Reading 6 bytes from display-2:1
6765 [18.054428:0x103f4a5d1] READ: Read 6 bytes from display-2:1, total 4508693
6766 [18.054430:0x103f4a4c4] READ: Reading 1420 bytes from display-2:1
6767 [18.054436:0x103f4a5d1] READ: Read 1420 bytes from display-2:1, total 4510113
6768 [18.054442:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1524 ms (ts: 700201861, mmtime: 700203385
6769 [18.106165:0x103f94e5f] DEBUG: schedule_frame: rendering too late by 3442 ms (ts: 700199995, mmtime: 700203437
6770 [18.106312:0x103f4a4c4] READ: Reading 6 bytes from display-2:1
6771 [18.106324:0x103f4a5d1] READ: Read 6 bytes from display-2:1, total 4510119
6772 [18.106325:0x103f4a4c4] READ: Reading 1861 bytes from display-2:1
6773 [18.106329:0x103f4a5d1] READ: Read 1861 bytes from display-2:1, total 4511980
6774 [18.106334:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1559 ms (ts: 700201878, mmtime: 700203437
6775 [18.106348:0x103f4a4c4] READ: Reading 6 bytes from display-2:1
6776 [18.106351:0x103f4a5d1] READ: Read 6 bytes from display-2:1, total 4511986
6777 [18.106352:0x103f4a4c4] READ: Reading 1358 bytes from display-2:1
6778 [18.106378:0x103f4a5d1] READ: Read 1358 bytes from display-2:1, total 4513344
6779 [18.106380:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1543 ms (ts: 700201894, mmtime: 700203437
6780 [18.106385:0x103f443c7] DEBUG: spice_session_sync_playback_latency: not implemented when there isn't audio playback
6781 [18.154665:0x103f4a4c4] READ: Reading 6 bytes from display-2:1
6782 [18.154686:0x103f4a5d1] READ: Read 6 bytes from display-2:1, total 4513350
6783 [18.154688:0x103f4a4c4] READ: Reading 1399 bytes from display-2:1
6784 [18.154696:0x103f4a5d1] READ: Read 1399 bytes from display-2:1, total 4514749
6785 [18.154705:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1575 ms (ts: 700201911, mmtime: 700203486
6786 [18.154731:0x103f4a4c4] READ: Reading 6 bytes from display-2:1
6787 [18.154736:0x103f4a5d1] READ: Read 6 bytes from display-2:1, total 4514755
6788 [18.154738:0x103f4a4c4] READ: Reading 1343 bytes from display-2:1
6789 [18.154743:0x103f4a5d1] READ: Read 1343 bytes from display-2:1, total 4516098
6790 [18.154745:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1558 ms (ts: 700201928, mmtime: 700203486
6791 [18.154756:0x103f4a4c4] READ: Reading 6 bytes from display-2:1
6792 [18.154761:0x103f4a5d1] READ: Read 6 bytes from display-2:1, total 4516104
6793 [18.154763:0x103f4a4c4] READ: Reading 1384 bytes from display-2:1
6794 [18.154823:0x103f4a5d1] READ: Read 1384 bytes from display-2:1, total 4517488
6795 [18.154828:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1541 ms (ts: 700201945, mmtime: 700203486
6796 [18.154841:0x103f4a4c4] READ: Reading 6 bytes from display-2:1
6797 [18.154846:0x103f4a5d1] READ: Read 6 bytes from display-2:1, total 4517494
6798 [18.154848:0x103f4a4c4] READ: Reading 2466 bytes from display-2:1
6799 [18.154855:0x103f4a5d1] READ: Read 2466 bytes from display-2:1, total 4519960
6800 [18.154858:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1522 ms (ts: 700201964, mmtime: 700203486
6801 [18.156999:0x103f94e5f] DEBUG: schedule_frame: rendering too late by 3445 ms (ts: 700200043, mmtime: 700203488
6802 [18.201765:0x103f4a4c4] READ: Reading 6 bytes from display-2:1
6803 [18.201776:0x103f4a5d1] READ: Read 6 bytes from display-2:1, total 4519966
6804 [18.201777:0x103f4a4c4] READ: Reading 1461 bytes from display-2:1
6805 [18.201782:0x103f4a5d1] READ: Read 1461 bytes from display-2:1, total 4521427
6806 [18.201788:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1552 ms (ts: 700201981, mmtime: 700203533
6807 [18.201801:0x103f443c7] DEBUG: spice_session_sync_playback_latency: not implemented when there isn't audio playback
6808 [18.201806:0x103f4a4c4] READ: Reading 6 bytes from display-2:1
6809 [18.201809:0x103f4a5d1] READ: Read 6 bytes from display-2:1, total 4521433
6810 [18.201810:0x103f4a4c4] READ: Reading 1425 bytes from display-2:1
6811 [18.201833:0x103f4a5d1] READ: Read 1425 bytes from display-2:1, total 4522858
6812 [18.201836:0x103f49898] WRITE: Message 0x7fc2b363e4c0 on display-2:1
6813 [18.201837:0x103f4dca4] WRITE: Write 6 bytes on display-2:1
6814 [18.201885:0x103f4dcf2] WRITE: Wrote 6 bytes on display-2:1
6815 [18.201897:0x103f5b39a] CHANNEL: display-2:1: stream data too late by 1536 ms (ts: 700201997, mmtime: 700203533
6816 [18.204676:0x103f94e5f] DEBUG: schedule_frame: rendering too late by 3439 ms (ts: 700200097, mmtime: 700203536
6817 [18.245537:0x103f8ffbe] MAIN: Received signal 10, dumping recorder
>
>> d) Performance bugs, e.g.
>> https://beta-bugzilla.redhat.com/show_bug.cgi?id=1363940#c1 states
>> “please provide supporting data”, but there is no easy way for the
>> customer to collect objective data
>> e) Frediano having to commit code adding a magic 2000 in the server to
>> “try to reduce lag”, see
>> https://cgit.freedesktop.org/~fziglio/spice-server/commit/?h=nvidia&id=855849d7a2b8e1968a14dcce3dd84d05f25bc702.
>>
>> All these examples (only a sample, I can easily find dozen more) show
>> that the need for the tools I am talking about exist.
>
> I mostly read these examples as "our debug logs are bad", and most of
> these would be helped by more logs, which filtered output facilitates
> as you are not overwhelmed with too much stuff.
I’m sorry if I’m being dense here, but I insist, there are 5 different things, only one of them is logs:
a) logs
b) trace selection
c) flight recorder
d) performance probes
e) tweaks
Of these, my RFC addresses b and e, the “recorder” branch is WIP to address c, and I have yet-unpublished work for d.
>
>>
>>>
>>> This argument is probably only valid if you have a mix of categories in a very tiny context. If you switch to a single category, there shouldn't be much performance difference locally and globally.
>>
>> Actually, this argument is valid for any mechanism designed to also
>> instrument hot paths. The first level cache is a very precious
>> commodity. Say we have 50 categories in the normal run path. With your
>> approche, we use 50 unrelated cache lines with nothing else of
>> interest in them (the name and description of the category being
>> largely uninteresting at run time). With mine, it’s one cache line,
>> with the first category test priming the cache for subsequent category
>> tests, ensuring they don’t stall.
>>
>> Let’s design a tracing selection mechanism that can instrument hot
>> paths at minimal cost, rather than rationalize why we don’t need to
>> instrument hot paths.
>
> If it's a hot path, then the needed flag will be in a cache-line
> regardless of the approach taken.
You are reasoning on one flag, the only case where it’s the same. If your hot path tests N categories, then it’s N cache lines versus something like N/512.
> If it's an actual issue, then we can
> always move from one approach to the other.
Yes.
>
> At this point, I would say that any of the 2 approaches are an
> improvement over the current code. I'm also unconvinced that we have to
> have support for tweaks,
But do you have any good argument for depriving me from having tweaks if I want them? Would you nack tweaks, and if so, why?
> and Marc-André's approach has the advantage
> (to me) of not needing #define MAGIC_FOO(x) ... #include "foo.defs"
> which I'm not a big fan of.
That’s the trade-off for DRY (don’t repeat yourself) vs. WET (write everything twice, or we enjoy typing).
I agree this is a bit hacky, though in my opinion less complex than, say, the python marshalling generators, which play a similar role of automating some code generation.
> Once again, any of the 2 approaches would allow you to add the logs you
> need with the filtering you need. And not getting tweaks/centralized
> categories now does not prevent that from changing later when a concrete
> compelling use case shows up ("This patch is adding XXX which we really
> want to have, this cannot be done with the current infrastructure, so
> this other patch is changing that", or "While debugging YYY, I needed
> the logs but performance was not appropriate, this patch fixes it”).
More information about the Spice-devel
mailing list