GStreamer unwanted startup delay and unit test crashes when Xcode debugging for iOS

Question

I have an iOS application that uses Gstreamer to stream live video from a source over UDP. When I run this app with the Xcode debugger attached, there is a 5-10 second delay before the video appears. Then it seems to quickly display all of the previous frames until it "catches up" to the current timestamp. At first I thought this was caused by my pipeline that was converted to dynamic code, however I have since isolated the problem to only when debugging:

If I stop the pipeline and recreate it, there is no noticeable delay.
If I stop debugging and use the app it is fine (killing from multitasking too).
The TestFlight version is also fine.

Here is my console output with some debug messages, GStreamer callbacks, and my comments in code comment syntax:

WARNING: no real random source present!
 GST_STATE_READY
playOrStopVideo
2019-09-26 15:45:19.442411-0400  pipeline is null
2019-09-26 15:45:19.502487-0400  pad_added_handler: tee
2019-09-26 15:45:19.534644-0400  Metal GPU Frame Capture Enabled
2019-09-26 15:45:19.535959-0400  Metal API Validation Enabled
[GStreamer check_initialization_complete]:[00m Initialization complete, notifying application.
ViewController gstreamerInitialized()
2019-09-26 15:45:19.646378-0400   message NEED_CONTEXT
2019-09-26 15:45:19.646436-0400   message HAVE_CONTEXT
2019-09-26 15:45:19.646465-0400   message NEED_CONTEXT
2019-09-26 15:45:19.646492-0400   message ELEMENT
2019-09-26 15:45:19.646547-0400   message NEED_CONTEXT
2019-09-26 15:45:19.646636-0400   message NEED_CONTEXT
2019-09-26 15:45:19.646685-0400   message NEED_CONTEXT
 GST_STATE_READY
2019-09-26 15:45:19.649381-0400   message STREAM_STATUS CREATE for src
2019-09-26 15:45:19.652090-0400   message STREAM_STATUS CREATE for src
2019-09-26 15:45:19.652148-0400   message STREAM_STATUS CREATE for src
 GST_STATE_PAUSED
2019-09-26 15:45:19.652808-0400   message STREAM_STATUS ENTER for src
2019-09-26 15:45:19.652926-0400   message NEW_CLOCK
2019-09-26 15:45:19.652980-0400   message STREAM_STATUS ENTER for src
2019-09-26 15:45:19.653166-0400   message STREAM_STATUS ENTER for src
2019-09-26 15:45:19.987250-0400  pad_added_handler: decodebin0
2019-09-26 15:45:19.999452-0400   message STREAM_START
2019-09-26 15:45:20.032557-0400   message TAG
=================================================================
Main Thread Checker: UI API called on a background thread: -[UIView frame]
PID: 3788, TID: 1475176, Thread name: (none), Queue name: org.freedesktop.gstreamer.glwindow, QoS: 0
Backtrace:
4   MyApp                               0x0000000105ef14f8 gst_gl_context_eagl_update_layer + 652
5   MyApp                               0x0000000105edd4b8 gst_gl_window_eagl_set_window_handle + 92
6   MyApp                               0x0000000105ef5f6c _set_window_handle_cb + 104
7   MyApp                               0x0000000105edd790 __gst_gl_window_eagl_send_message_async_block_invoke + 36
8   libdispatch.dylib                   0x00000001097e51dc _dispatch_call_block_and_release + 24
9   libdispatch.dylib                   0x00000001097e519c _dispatch_client_callout + 16
10  libdispatch.dylib                   0x00000001097f3dfc _dispatch_queue_serial_drain + 768
11  libdispatch.dylib                   0x00000001097e86ac _dispatch_queue_invoke + 328
12  libdispatch.dylib                   0x00000001097f4d54 _dispatch_root_queue_drain_deferred_wlh + 352
13  libdispatch.dylib                   0x00000001097fbe38 _dispatch_workloop_worker_thread + 676
14  libsystem_pthread.dylib             0x0000000184c83e70 _pthread_wqthread + 860
15  libsystem_pthread.dylib             0x0000000184c83b08 start_wqthread + 4
2019-09-26 15:45:20.049748-0400 MyApp[3788:1475176] [reports] Main Thread Checker: UI API called on a background thread: -[UIView frame]
PID: 3788, TID: 1475176, Thread name: (none), Queue name: org.freedesktop.gstreamer.glwindow, QoS: 0
Backtrace:
4   MyApp                               0x0000000105ef14f8 gst_gl_context_eagl_update_layer + 652
5   MyApp                               0x0000000105edd4b8 gst_gl_window_eagl_set_window_handle + 92
6   MyApp                               0x0000000105ef5f6c _set_window_handle_cb + 104
7   MyApp                               0x0000000105edd790 __gst_gl_window_eagl_send_message_async_block_invoke + 36
8   libdispatch.dylib                   0x00000001097e51dc _dispatch_call_block_and_release + 24
9   libdispatch.dylib                   0x00000001097e519c _dispatch_client_callout + 16
10  libdispatch.dylib                   0x00000001097f3dfc _dispatch_queue_serial_drain + 768
11  libdispatch.dylib                   0x00000001097e86ac _dispatch_queue_invoke + 328
12  libdispatch.dylib                   0x00000001097f4d54 _dispatch_root_queue_drain_deferred_wlh + 352
13  libdispatch.dylib                   0x00000001097fbe38 _dispatch_workloop_worker_thread + 676
14  libsystem_pthread.dylib             0x0000000184c83e70 _pthread_wqthread + 860
15  libsystem_pthread.dylib             0x0000000184c83b08 start_wqthread + 4
=================================================================
Main Thread Checker: UI API called on a background thread: -[UIView layer]
PID: 3788, TID: 1475176, Thread name: (none), Queue name: org.freedesktop.gstreamer.glwindow, QoS: 0
Backtrace:

4   MyApp                               0x0000000105ef1300 gst_gl_context_eagl_update_layer + 148
5   MyApp                               0x0000000105edd4b8 gst_gl_window_eagl_set_window_handle + 92
6   MyApp                               0x0000000105ef5f6c _set_window_handle_cb + 104
7   MyApp                               0x0000000105edd790 __gst_gl_window_eagl_send_message_async_block_invoke + 36
8   libdispatch.dylib                   0x00000001097e51dc _dispatch_call_block_and_release + 24
9   libdispatch.dylib                   0x00000001097e519c _dispatch_client_callout + 16
10  libdispatch.dylib                   0x00000001097f3dfc _dispatch_queue_serial_drain + 768
11  libdispatch.dylib                   0x00000001097e86ac _dispatch_queue_invoke + 328
12  libdispatch.dylib                   0x00000001097f4d54 _dispatch_root_queue_drain_deferred_wlh + 352
13  libdispatch.dylib                   0x00000001097fbe38 _dispatch_workloop_worker_thread + 676
14  libsystem_pthread.dylib             0x0000000184c83e70 _pthread_wqthread + 860
15  libsystem_pthread.dylib             0x0000000184c83b08 start_wqthread + 4
2019-09-26 15:45:27.554390-0400 MyApp[3788:1475176] [reports] Main Thread Checker: UI API called on a background thread: -[UIView layer]
PID: 3788, TID: 1475176, Thread name: (none), Queue name: org.freedesktop.gstreamer.glwindow, QoS: 0
Backtrace:
4   MyApp                               0x0000000105ef1300 gst_gl_context_eagl_update_layer + 148
5   MyApp                               0x0000000105edd4b8 gst_gl_window_eagl_set_window_handle + 92
6   MyApp                               0x0000000105ef5f6c _set_window_handle_cb + 104
7   MyApp                               0x0000000105edd790 __gst_gl_window_eagl_send_message_async_block_invoke + 36
8   libdispatch.dylib                   0x00000001097e51dc _dispatch_call_block_and_release + 24
9   libdispatch.dylib                   0x00000001097e519c _dispatch_client_callout + 16
10  libdispatch.dylib                   0x00000001097f3dfc _dispatch_queue_serial_drain + 768
11  libdispatch.dylib                   0x00000001097e86ac _dispatch_queue_invoke + 328
12  libdispatch.dylib                   0x00000001097f4d54 _dispatch_root_queue_drain_deferred_wlh + 352
13  libdispatch.dylib                   0x00000001097fbe38 _dispatch_workloop_worker_thread + 676
14  libsystem_pthread.dylib             0x0000000184c83e70 _pthread_wqthread + 860
15  libsystem_pthread.dylib             0x0000000184c83b08 start_wqthread + 4

//
// THIS IS WHERE IT HANGS (check the timestamps)
//

2019-09-26 15:45:27.692918-0400   message ASYNC_DONE
 GST_STATE_PLAYING
2019-09-26 15:45:28.023985-0400   message QOS
2019-09-26 15:45:28.190131-0400   message QOS
2019-09-26 15:45:28.418494-0400   message QOS
2019-09-26 15:45:28.657004-0400   message QOS
2019-09-26 15:45:28.665464-0400   message QOS
2019-09-26 15:45:28.668784-0400   message QOS
2019-09-26 15:45:28.672105-0400   message QOS
2019-09-26 15:45:28.675492-0400   message QOS

//
// Sometimes I see output with QoS about "a lot of buffers being dropped"
//

//
// STOPPING VIDEO VIA UI AND RESTARTING (plays immediately)
//
playOrStopVideo
2019-09-26 15:45:32.959316-0400   SENT EOS OK
2019-09-26 15:45:32.962257-0400   GST_MESSAGE_EOS
2019-09-26 15:45:32.969720-0400   Pipeline set to NULL
 GST_STATE_NULL
[GStreamer setupVideoWithRecording:]:[00m Exited main loop
2019-09-26 15:45:32.970650-0400   Exited main loop
2019-09-26 15:45:32.970712-0400   destroy()
playOrStopVideo
2019-09-26 15:45:35.330103-0400  pipeline is null
2019-09-26 15:45:35.369882-0400  pad_added_handler: tee
[GStreamer check_initialization_complete]:[00m Initialization complete, notifying application.
ViewController gstreamerInitialized()
2019-09-26 15:45:35.385008-0400   message NEED_CONTEXT
2019-09-26 15:45:35.385064-0400   message HAVE_CONTEXT
2019-09-26 15:45:35.385099-0400   message NEED_CONTEXT
2019-09-26 15:45:35.385134-0400   message ELEMENT
2019-09-26 15:45:35.385241-0400   message NEED_CONTEXT
2019-09-26 15:45:35.385305-0400   message NEED_CONTEXT
2019-09-26 15:45:35.385368-0400   message NEED_CONTEXT
 GST_STATE_READY
2019-09-26 15:45:35.389410-0400   message STREAM_STATUS CREATE for src
2019-09-26 15:45:35.389992-0400   message STREAM_STATUS CREATE for src
2019-09-26 15:45:35.390051-0400   message STREAM_STATUS CREATE for src
 GST_STATE_PAUSED
2019-09-26 15:45:35.390270-0400   message STREAM_STATUS ENTER for src
2019-09-26 15:45:35.390301-0400   message NEW_CLOCK
2019-09-26 15:45:35.390437-0400   message STREAM_STATUS ENTER for src
2019-09-26 15:45:35.390519-0400   message STREAM_STATUS ENTER for src
2019-09-26 15:45:35.659082-0400  pad_added_handler: decodebin1
2019-09-26 15:45:35.676625-0400   message STREAM_START
2019-09-26 15:45:35.682690-0400   message TAG
2019-09-26 15:45:35.693208-0400   message ASYNC_DONE
 GST_STATE_PLAYING

It's not that big of a deal since it is only when debugging, however that is a lot of unnecessary time added to my development. It seems to be related to the iOS Thread complaints. Those have been in GStreamer for as long as I've used it (may have even filed a bug) and I am not sure of a way around it since it's in the library itself. Ideas?

Edit

Reported here:

https://gitlab.freedesktop.org/gstreamer/gst-plugins-base/issues/568 https://www.bountysource.com/issues/48924739-glwindow-eagl-bug-with-ios11-and-xcode-9-0-beta-4 https://gitlab.freedesktop.org/gstreamer/gst-plugins-base/issues/372 https://gitlab.freedesktop.org/gstreamer/gstreamer/issues/394

Not sure what the proper fix is. I'm trying all sorts of combinations of dispatch queues.

Edit 2:

Using XCTWaiter to create some unit tests, but the running application dies at this same point. Assuming this is also related to threading, as in the test (main) thread is waiting for GStreamer who is modifying in the background what should be modified on the main thread (UIView properties view and frame).

score 0 · Accepted Answer · answered Nov 12 '19 at 06:36

I was able to solve this by recompiling GStreamer and adding some dispatch calls where [UIView layer] and [UIView frame] are used in gst_gl_context_eagl_update_layer and the window's draw_cb.

Used this commit as a reference, but you can look at your stack traces too, as I required fewer calls.
gstglcontext_eagl.m gstglwindow_eagl.m

Dispatching per: https://stackoverflow.com/a/5226271/890558

GStreamer unwanted startup delay and unit test crashes when Xcode debugging for iOS

1 Answers1