> On 14 Jun 2017, at 17:06, Christophe Fergeau <cfergeau@xxxxxxxxxx> 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@xxxxxxxxxx> 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@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”). _______________________________________________ Spice-devel mailing list Spice-devel@xxxxxxxxxxxxxxxxxxxxx https://lists.freedesktop.org/mailman/listinfo/spice-devel