Caps negotiation analysis with GstTracer

GstTracer

GstTracer is an yet to be merged (post 1.6) new feature to GStreamer core to expose events happening in the pipeline to tracer plugins. Examples of such events are:

  • Events/buffers/queries being pushed on pads
  • Elements/pads being created
  • Messages posted on the bus

The notification for those events happens live during the pipeline execution and the plugins can react to it. GstTracer discussion is happening at bugzilla and the latest version, while not merged, can be found here.

stats, for example, is a tracer plugin that logs to GST_DEBUG all those notifications using a structured output. This output can be very useful to do post-analysis of a pipeline execution.

Analyzing caps negotiation

By using the stats output it was possible to analyze the caps related queries performed in the pipeline and organize this information for 2 purposes:

  • Create caps query calls tree: the sequence of caps and accept-caps queries can be put up together in a tree of calls and it is possible to check how a caps query travels and transforms itself from element to element in the pipeline.
  • Count the number of repeated caps queries: Queries have a filter caps and a result caps, it is possible to identify how many of those are repeated on the pads.

The results:

The caps queries trees are printed to stdout and, while still not beautiful, already depict the sequence of queries made:

To help understanding the output, the caps strings were replaced in the following piece of output. Notice that the lines contain the timestamp when the query happened, the type of query, the pad that received the query and then the query parameters and result. Indented lines mean the inner query was a result of the outer query.

0:00:00.136669408 : accept-caps : avdec_aac0(15):sink(26) - caps: A : res: True  
    0:00:00.136730979 : query-caps : avdec_aac0(15):sink(26) - filter: A : res: A
        0:00:00.136789273 : query-caps : --4294967295--(4294967295):proxypad3(21) - filter: B
            0:00:00.136834046 : query-caps : pulsesink0(13):sink(23) - filter: B
            0:00:00.137330967
        0:00:00.137414549
    0:00:00.137490063
0:00:00.137559348  

If you want to see how it really looks, here it is:

0:00:00.136669408 : accept-caps : avdec_aac0(15):sink(26) - caps: audio/mpeg, mpegversion=(int)4, framed=(boolean)true, stream-format=(string)raw, level=(string)4, base-profile=(string)lc, profile=(string)lc, codec_data=(buffer)11b0, rate=(int)48000, channels=(int)6, channel-mask=(bitmask)0x0000000000000000 : res: True  
    0:00:00.136730979 : query-caps : avdec_aac0(15):sink(26) - filter: audio/mpeg, mpegversion=(int)4, framed=(boolean)true, stream-format=(string)raw, level=(string)4, base-profile=(string)lc, profile=(string)lc, codec_data=(buffer)11b0, rate=(int)48000, channels=(int)6, channel-mask=(bitmask)0x0000000000000000 : res: audio/mpeg, rate=(int)48000, channels=(int)6, mpegversion=(int)4, stream-format=(string)raw, framed=(boolean)true, level=(string)4, base-profile=(string)lc, profile=(string)lc, codec_data=(buffer)11b0, channel-mask=(bitmask)0x0000000000000000
        0:00:00.136789273 : query-caps : --4294967295--(4294967295):proxypad3(21) - filter: audio/x-raw, rate=(int)48000, channels=(int)6 : res: audio/x-raw, rate=(int)48000, channels=(int)6, format=(string){ S16LE, S16BE, F32LE, F32BE, S32LE, S32BE, S24LE, S24BE, S24_32LE, S24_32BE, U8 }, layout=(string)interleaved
            0:00:00.136834046 : query-caps : pulsesink0(13):sink(23) - filter: audio/x-raw, rate=(int)48000, channels=(int)6 : res: audio/x-raw, rate=(int)48000, channels=(int)6, format=(string){ S16LE, S16BE, F32LE, F32BE, S32LE, S32BE, S24LE, S24BE, S24_32LE, S24_32BE, U8 }, layout=(string)interleaved
            0:00:00.137330967
        0:00:00.137414549
    0:00:00.137490063
0:00:00.137559348  

All the caps query call trees are output as a result of the analysis tool. The second part of the result is the count of the repeated caps queries per pad and looks like this:

pulsesink0(13):sink(23)  
    filter: NULL
    caps: audio/x-raw, format=(string){ S16LE, S16BE, F32LE, F32BE, S32LE, S32BE, S24LE, S24BE, S24_32LE, S24_32BE, U8 }, layout=(string)interleaved, rate=(int)[ 1, 2147483647 ], channels=(int)[ 1, 32 ]; audio/x
-alaw, rate=(int)[ 1, 2147483647 ], channels=(int)[ 1, 32 ]; audio/x-mulaw, rate=(int)[ 1, 2147483647 ], channels=(int)[ 1, 32 ]
    res: True
    Repeated: 11 (total time: 21341790ns)

So pulsesink received 11 times the same caps query with filter=NULL and returned the same caps as a result. Even though the total time is of 21ms it is a bit concerning that the same operation was repeated 11 times. Those tests were run on a Samsung Series 5 Ultra, this time might have a greater impact on slower devices.

How to use it

Step 1: getting a trace: First of all, let's get a tracer stats log out of a pipeline run.

GST_TRACE="stats" GST_DEBUG=GST_TRACER:9 gst-launch-1.0 playbin uri=<someuri> > gsttracer_stats.log 2>&1

This will run playbin enabling the tracer stats and will dump it to GST_DEBUG output (that is only enabled for the tracer logs). The result will be in the gsttracer_stats.log file.

Step 2: parsing the trace: For that, a python script was written and can be found here. The script is named gsttracer-negotiation-analyzer.py. This code is still under development but is already useful to generate the above results.

More work

One thing still not solved is how to track the caps event. The caps and accept-caps queries are not serialized with the data flow so they are always on the same thread, making it easy to track those. The caps event is serialized and will change threads with the data flow. How to track it? Another good addition would be to analyze cases of not-negotiated failure and point exactly the caps query tree that failed.

Feel free to stop at github or talk to me on IRC (thiagoss in #gstreamer @ freenode) if you have any comments or suggestions.