GNOME Bugzilla – Bug 784382
Debug logging output on Windows sometimes hangs
Last modified: 2018-04-11 22:33:33 UTC
Problem occurs in 1.12.1, 1.12.0, 1.10.5 and also earlier versions. Steps to reproduce (on Windows): > set GST_DEBUG=*:1,GST_META*:9,GST_EVENT*:9,GST_DATAFLOW:9,videoencoder:9,bufferpool:9,videopool:9,basesink:9,fakesink:9,GST_BUFFER:9,qsH264enc:9,GST_TRACER*:7 > set GST_TRACERS=leaks > gst-launch-1.0.exe videotestsrc num-buffers=100 ! video/x-raw,format=I420,width=1920,height=1080,framerate=60/1 ! openh264enc ! h264parse ! mp4mux ! filesink location="abc.mov" This test run hangs on Windows, but it works on Linux (at least with version 1.11.1). On Windows it looks like (last relevant lines): … 0:00:01.129951470 4544 0000000002BCC280 LOG GST_BUFFER gstbuffer.c:1721:gst_buffer_map_range: buffer 0000000002C49920, idx 0, length -1, flags 0002 0:00:01.135682601 4544 0000000002BCC280 LOG GST_BUFFER gstbuffer.c:213:_get_merged_memory: buffer 0000000002C49920, idx 0, length 1 0:00:01.140517742 4544 0000000002BCC280 LOG GST_BUFFER gstbuffer.c:1876:gst_buffer_extract: buffer 0000000002C491B0, offset 0, size 16 0:00:01.145276302 4544 0000000002BCC280 LOG GST_BUFFER gstbuffer.c:1876:gst_buffer_extract: buffer 0000000002C495F0, offset 0, size 4 0:00:01.151505571 4544 0000000002BCC280 ERROR default gstevent.c:818:gst_event_new_caps:handling interrupt. Interrupt: Stopping pipeline ... ERROR: pipeline doesn't want to preroll. Setting pipeline to NULL ... ^CBatchvorgang abbrechen (J/N)? j Nothing printed after "gst_event_new_caps:". “handling interrupt” occurs when I press Ctrl-C to abort the test run. (I think when I enable more debug data or reach a certain point of num-buffers, I am even not more able to stop gst-launch anymore, I must kill it via task manager.) Added some general debug output in gstevent.c line 818 where debug output shall be printed. *caps point to address 0x0000000002BD36A0 I dumped first 4 bytes on this address: F0 F2 48 00 On Linux I see (filtered to file gstevent.c and line 808): # grep gst_event_new_caps abc.log 0:00:00.320152667 282 0x1577e00 INFO GST_EVENT gstevent.c:808:gst_event_new_caps: creating caps event video/x-raw, format=(string)I420, width=(int)1920, height=(int)1080, framerate=(fraction)60/1, pixel-aspect-ratio=(fraction)1/1, interlace-mode=(string)progressive 0:00:00.322927333 282 0x1577e00 INFO GST_EVENT gstevent.c:808:gst_event_new_caps: creating caps event video/x-raw, format=(string)I420, width=(int)1920, height=(int)1080, framerate=(fraction)60/1, pixel-aspect-ratio=(fraction)1/1, interlace-mode=(string)progressive 0:00:00.369638667 282 0x1577e00 INFO GST_EVENT gstevent.c:808:gst_event_new_caps: creating caps event video/x-h264, stream-format=(string)byte-stream, alignment=(string)au, profile=(string)baseline, width=(int)1920, height=(int)1080, pixel-aspect-ratio=(fraction)1/1, framerate=(fraction)60/1, interlace-mode=(string)progressive, colorimetry=(string)bt709, chroma-site=(string)mpeg2 0:00:00.702754000 282 0x1577e00 INFO GST_EVENT gstevent.c:808:gst_event_new_caps: creating caps event video/x-h264, stream-format=(string)avc, alignment=(string)au, profile=(string)constrained-baseline, width=(int)1920, height=(int)1080, pixel-aspect-ratio=(fraction)1/1, framerate=(fraction)60/1, interlace-mode=(string)progressive, colorimetry=(string)bt709, chroma-site=(string)mpeg2, parsed=(boolean)true, level=(string)4.2, codec_data=(buffer)0142c02affe100106742c02a8c8d403c0112f2c03c2211a801000468ce3c80 0:00:00.707792000 282 0x1577e00 INFO GST_EVENT gstevent.c:808:gst_event_new_caps: creating caps event video/quicktime, variant=(string)iso 0:00:18.299080335 282 0x1577e00 INFO GST_EVENT gstevent.c:808:gst_event_new_caps: creating caps event video/quicktime, variant=(string)iso, streamheader=(buffer)< 000005036d6f6f760000006c6d76686400000000d5325d03d5325d0300001770000027100001000001000000000000000000000000010000000000000000000000000000000100000000000000000000000000004000000000000000000000000000000000000000000000000000000000000002000004527472616b0000005c746b686400000007d5325d03d5325d0300000001000000000000271000000000000000000000000000000000000100000000000000000000000000000001000000000000000000000000000040000000001000000009000000000024656474730000001c656c737400000000000000010000271000000000000100000000038d6d646961000000206d64686400000000d5325d03d5325d030000177000002710000000000000002d68646c72000000000000000076696465000000000000000000000000566964656f48616e646c657200000003386d696e6600000014766d68640000000100000000000000000000002464696e660000001c6472656600000000000000010000000c75726c2000000001000002f87374626c000000c8737473640000000000000001000000b86176633100000000000000010000000000000000000000000000000007800438004800000048000000000000000100000000000000000000000000000000000000000000000000000000000000000018ffff00000027617663430142c02affe100106742c02a8c8d403c0112f2c03c2211a801000468ce3c8000000014627472740000000001b266410184c6b300000013636f6c726e636c7800010001000100000000107061737000000001000000010000000000000018737474730000000000000001000000640000006400000018737473730000000000000002000000010000005b00000028737473630000000000000002000000010000001000000001000000070000000400000001000001a47374737a0000000000000000000000640000e5460000df260000cd680000ccbb0000cc960000cc250000cc260000cbf40000cc380000cc8e0000cc000000cfcb0000cea90000ce210000ce630000cef00000d0c90000cee30000ce630000ce2e0000ce8c0000ce6f0000cec60000cf190000d13f0000ce740000ce950000ce400000ce770000cdbf0000ceef0000cecf0000d3e70000ceb00000ce930000ce610000cea30000ce260000cdef0000ce910000d44d0000ce320000cdef0000ce830000cea30000cdcc0000ce400000cf1e0000d3f70000ce1c0000ce970000ce690000ce490000ce630000ce3c0000ce0e0000d4080000ce100000ce060000ce5b0000ce760000ce690000ce2d0000cdc00000d4160000ce620000cebb0000ce270000ceae0000ce2d0000ce920000ced20000d3bd0000ce880000ce080000ce890000ce920000cee40000cea80000ce620000d43e0000cea10000ce6c0000ceae0000ce7f0000cdd30000ce210000ce720000d4010000ce8a0000e7ae0000cc300000cc010000cbe40000cb5e0000cbf00000cc4e0000cc280000cc4d0000cc420000002c7374636f000000000000000700000030000cfe420019ebd50026dd670033ccb50040bfa4004dbe1e0000003d75647461000000356d657461000000000000002168646c72000000006d686c726d6469720000000000000000000000000000000008696c73740000003d75647461000000356d657461000000000000002168646c72000000006d686c726d6469720000000000000000000000000000000008696c7374 > # I think it is some endless loop in debug output due to debug output in GstBuffer?
It is enough to set GST_DEBUG "default" to a value of at least 1 and "GST_BUFFER" to a value of at least 6. e.g. GST_DEBUG=default:1,GST_BUFFER:6 Cyclic call graph? Recursive locking of a mutex? This is the callstack (latest on bottom): gst_event.c: gst_event_new_caps ... gstinfo.c: gst_debug_print_object (GST_IS_CAPS) gstcaps.c: gst_caps_to_string gststructure.c: priv_gst_structure_append_to_gstring gstvalue.c: gst_value_serialize gstvalue.c: gst_value_serialize_buffer gstbuffer.c: gst_buffer_map gstbuffer.c: gst_buffer_map_range gst_buffer_map_range calls GST_CAT_LOG, where it does not return. This must be continued by someone with more knowledge in this area. I don't know how to solve it.
Does it also happen without GST_TRACERS=leaks ? If it only happens with the tracer enabled, does this commit help: commit cce18426f756c0a17410020b0e5db06e7546257c Author: Tim-Philipp Müller <tim@centricular.com> Date: Mon Jul 3 09:03:24 2017 +0100 miniobject: make refcount tracing and debug logging reliable Tracing of the refcounts wasn't thread-safe, and log output of the refcount values before/after wasn't reliable. https://bugzilla.gnome.org/show_bug.cgi?id=784383
This should fix it: commit ae612551fa0a2378bfb71eb03611dc6c0861ee7a Author: Tim-Philipp Müller <tim@centricular.com> Date: Wed Apr 11 19:56:01 2018 +0100 gstdebug: fix occasional deadlocks on windows when outputting debug logging When outputting debug logs on Windows, some sections are protected with a non-recursive lock. Turns out though that gst_debug_message_get() might indirectly, via our printf format extensions, call code which in turn would try to log something when it can't handle something. If that happens we end up in gst_debug_log_default() again recursively and try to again take the lock that's already taken, thus deadlocking. Format the debug message string outside of the critical section instead to avoid this. https://bugzilla.gnome.org/show_bug.cgi?id=784382