GNOME Bugzilla – Bug 771699
gst_clock_id_wait waits for too long
Last modified: 2016-09-26 06:06:41 UTC
I use gst_clock_new_single_shot_id + gst_clock_id_wait for synchronization (with system clock). Usually the target time is ~10 milliseconds in the future. When the application window is in background for some time, gst_clock_id_wait starts to block for 10 seconds. Printing gst_clock_get_time() shows 10 second difference too (and it is 10 seconds later than GstClockID's target time). But jitter value returned by gst_clock_id_wait is very small (microseconds). Activating the window immediately "fixes" the problem. And the problem doesn't occur when the window is in foreground. If I disable timer coalescing (sudo sysctl -w kern.timer.coalescing_enabled=0), the problem doesn't occur too. OS: macOS Sierra (probably happens on older versions too)
Can you check if mach_absolute_time() just stops increasing in this case, or if waiting for an fd with a timeout never wakes up (that's how internally the clock waiting is implemented)? From debug logs with GST_DEBUG=GST_CLOCK:6 this might already all be visible.
0:01:26.824546000 60523 0x7fc63497c4a0 DEBUG GST_CLOCK gstclock.c:253:GstClockID gst_clock_entry_new(GstClock *, GstClockTime, GstClockTime, GstClockEntryType):<GstSystemClock> created entry 0x7fc634983350, time 168:20:50.920845174 0:01:26.824577000 60523 0x7fc63497c4a0 DEBUG GST_CLOCK gstclock.c:542:GstClockReturn gst_clock_id_wait(GstClockID, GstClockTimeDiff *):<GstSystemClock> waiting on clock entry 0x7fc634983350 0:01:26.824586000 60523 0x7fc63497c4a0 DEBUG GST_CLOCK gstclock.c:1056:GstClockTime gst_clock_get_internal_time(GstClock *):<GstSystemClock> internal time 168:20:50.887313474 0:01:26.824596000 60523 0x7fc63497c4a0 DEBUG GST_CLOCK gstclock.c:1101:GstClockTime gst_clock_get_time(GstClock *):<GstSystemClock> adjusted time 168:20:50.887313474 0:01:26.824609000 60523 0x7fc63497c4a0 DEBUG GST_CLOCK gstsystemclock.c:727:GstClockReturn gst_system_clock_id_wait_jitter_unlocked(GstClock *, GstClockEntry *, GstClockTimeDiff *, gboolean): entry 0x7fc634983350 time 168:20:50.920845174 now 168:20:50.887313474 diff (time-now) 33531700 0:01:36.857627000 60523 0x7fc63497c4a0 DEBUG GST_CLOCK gstsystemclock.c:755:GstClockReturn gst_system_clock_id_wait_jitter_unlocked(GstClock *, GstClockEntry *, GstClockTimeDiff *, gboolean): entry 0x7fc634983350 unlocked, status 3, ret 0 0:01:36.857662000 60523 0x7fc63497c4a0 DEBUG GST_CLOCK gstsystemclock.c:779:GstClockReturn gst_system_clock_id_wait_jitter_unlocked(GstClock *, GstClockEntry *, GstClockTimeDiff *, gboolean): entry 0x7fc634983350 unlocked after timeout 0:01:36.857675000 60523 0x7fc63497c4a0 DEBUG GST_CLOCK gstclock.c:1056:GstClockTime gst_clock_get_internal_time(GstClock *):<GstSystemClock> internal time 168:21:00.920955318 0:01:36.857685000 60523 0x7fc63497c4a0 DEBUG GST_CLOCK gstclock.c:1101:GstClockTime gst_clock_get_time(GstClock *):<GstSystemClock> adjusted time 168:21:00.920955318 0:01:36.857692000 60523 0x7fc63497c4a0 DEBUG GST_CLOCK gstsystemclock.c:801:GstClockReturn gst_system_clock_id_wait_jitter_unlocked(GstClock *, GstClockEntry *, GstClockTimeDiff *, gboolean): entry 0x7fc634983350 finished, diff -10000110144 0:01:36.857728000 60523 0x7fc63497c4a0 DEBUG GST_CLOCK gstclock.c:552:GstClockReturn gst_clock_id_wait(GstClockID, GstClockTimeDiff *):<GstSystemClock> done waiting entry 0x7fc634983350, res: 0 (ok) 0:01:36.857738000 60523 0x7fc63497c4a0 DEBUG GST_CLOCK gstclock.c:356:void _gst_clock_id_free(GstClockID): freed entry 0x7fc634983350
0:01:26.824609000 60523 0x7fc63497c4a0 DEBUG GST_CLOCK gstsystemclock.c:727:GstClockReturn gst_system_clock_id_wait_jitter_unlocked(GstClock *, GstClockEntry *, GstClockTimeDiff *, gboolean): entry 0x7fc634983350 time 168:20:50.920845174 now 168:20:50.887313474 diff (time-now) 33531700 <<Long wait happens here>> 0:01:36.857627000 60523 0x7fc63497c4a0 DEBUG GST_CLOCK gstsystemclock.c:755:GstClockReturn gst_system_clock_id_wait_jitter_unlocked(GstClock *, GstClockEntry *, GstClockTimeDiff *, gboolean): entry 0x7fc634983350 unlocked, status 3, ret 0 Oops, status=GST_CLOCK_BUSY? What does it mean? 0:01:36.857662000 60523 0x7fc63497c4a0 DEBUG GST_CLOCK gstsystemclock.c:779:GstClockReturn gst_system_clock_id_wait_jitter_unlocked(GstClock *, GstClockEntry *, GstClockTimeDiff *, gboolean): entry 0x7fc634983350 unlocked after timeout 0:01:36.857675000 60523 0x7fc63497c4a0 DEBUG GST_CLOCK gstclock.c:1056:GstClockTime gst_clock_get_internal_time(GstClock *):<GstSystemClock> internal time 168:21:00.920955318 internal time 168:21:00.92, entry 0x7fc634983350 time 168:20:50.92
The problem doesn't occur on Linux with the same code and the same GStreamer version.
Can you please attach the debug log? That makes it possible to actually read it :) But this looks like it waits for 10 seconds, notices also that it waits for 10 seconds, but should've only waited for a couple of milliseconds. So it just didn't wake up in time, which hints at timeouts for select/poll on fds do not trigger properly in your situation. Can you try with a simple testcase that uses poll() or select() on a fd with a timeout to see if that guess is correct?
This seems to be not timer coalescing but "app nap". And this API has to be used *by the application* to disable it: https://developer.apple.com/reference/iokit/1659204-iopmlib.h and use the proper assertions (like beginActivity) Or [[NSProcessInfo processInfo] disableAutomaticTermination] See https://developer.apple.com/library/content/documentation/Performance/Conceptual/power_efficiency_guidelines_osx/AppNap.html
Thank you. Could you add it to GStreamer (GstSystemClock?) documentation somewhere? Because it's a bit unexpected.
It's not clear if that is the right place for documenting this. It will not affect only direct usage of GstSystemClock but really everything on macOS/iOS. Not sure where a good place to put this into the docs would be