GstShark - Processing Time tracer

GstShark
Getting Started
Getting the code Dependencies Building tracers Eclipse Plugin
Generating trace files
Tracer Parameters
Available Tracers
InterLatency Processing time Frame rate Schedule time CPU usage Graphic Bitrate Queue Level Buffer
Results
Common Trace Format Pipeline Diagram
Visualization Tools
gstshark-plot Eclipse plugin
Examples
CPU usage analysis Frame rate example Processing time example Scheduling time example Interlatency example
Contact Us

← {{{prev}}}

⌂ Home

→ {{{next}}}

Processing time was developed with the purpose of providing useful information to the user about the amount of time each element, of a given pipeline, is taking for processing each data buffer that goes through it, allowing the user to have knowledge about of how the performance of the pipeline is being affected by each element. This tracer corresponds to one of the tracers developed that are oriented to help the user to determine which element or process is increasing the general latency of the pipeline; in other words, it is a tool to check which element is taking too much time completing its tasks, causing a slow performance of the pipeline which can lead to a delay on the buffers and this being reflected on a wrong synchronization of the audio and video buffers, as an example.

The processing time tracer is designed for providing accurate data for the filter and filter-like elements of the pipeline. Based on the fact that the concept of the tracer is to measure the time an element takes to generate an output buffer when it receives a buffer on its sink pad, the source and sink elements are discarded since in order to the tracer to work properly it is needed that the element has both input and outputs pads. As it was mentioned previously the tracer supports the filter elements, in which an input buffer produces an output buffer, as a video converter; and the filter-like elements, more complex elements in which several input buffers combine to produce an output buffer, as an encoder or a muxer, or where a single input buffer produces several output buffers, as demuxer or a decoder; regardless of the amount of source and sink pads that the element has. However the tracer has the limitation that it only can report times for elements which process the inputs and outputs in the same thread, since the the idea of the tracer is to display a general measurement of the time elapsed processing a buffer without knowing the operation of element in detail.

At following there is an pipeline used as an example to demonstrate how to use the processing time tracer and the results obtained with it. The pipeline consists on 9 elements, numbered from left to right, connected as it is shown on the following graph; on the pipeline there are some elements that have a delay set, this with the purpose of increasing the time needed by that element to finish the processing of every buffer; this forced delay should be reflected on the measurements for every element on the output log of the tracer. Besides the graph of the pipeline used, at following is available the pipeline for testing along with the output log obtained.

Pipeline

GST_DEBUG="GST_TRACER:7" GST_TRACERS="proctime" gst-launch-1.0 videotestsrc ! identity sleep-time=8500 ! tee name=t t. ! queue ! identity sleep-time=50000 ! fakesink t. ! queue ! identity sleep-time=30000 ! fakesink

Sample diagram

Output

0:00:00.030766061 12926 0x248bf20 TRACE GST_TRACER :0:: proctime, element=(string)identity0, time=(string)0:00:00.008613006;
0:00:00.040429334 12926 0x248bf20 TRACE GST_TRACER :0:: proctime, element=(string)identity0, time=(string)0:00:00.008651178;
0:00:00.050182040 12926 0x248bf20 TRACE GST_TRACER :0:: proctime, element=(string)identity0, time=(string)0:00:00.008657576;
0:00:00.059830835 12926 0x248bf20 TRACE GST_TRACER :0:: proctime, element=(string)identity0, time=(string)0:00:00.008609986;
0:00:00.060992920 12926 0x24c68a0 TRACE GST_TRACER :0:: proctime, element=(string)identity2, time=(string)0:00:00.030099057;
0:00:00.069503703 12926 0x248bf20 TRACE GST_TRACER :0:: proctime, element=(string)identity0, time=(string)0:00:00.008655531;
0:00:00.079200604 12926 0x248bf20 TRACE GST_TRACER :0:: proctime, element=(string)identity0, time=(string)0:00:00.008655985;
0:00:00.081049528 12926 0x24c6a80 TRACE GST_TRACER :0:: proctime, element=(string)identity1, time=(string)0:00:00.050154409;
0:00:00.088951094 12926 0x248bf20 TRACE GST_TRACER :0:: proctime, element=(string)identity0, time=(string)0:00:00.008593832;
0:00:00.099182356 12926 0x248bf20 TRACE GST_TRACER :0:: proctime, element=(string)identity0, time=(string)0:00:00.008612803;
0:00:00.108961732 12926 0x248bf20 TRACE GST_TRACER :0:: proctime, element=(string)identity0, time=(string)0:00:00.008589039;
0:00:00.112001889 12926 0x24c68a0 TRACE GST_TRACER :0:: proctime, element=(string)identity2, time=(string)0:00:00.030088968;
0:00:00.117951345 12926 0x248bf20 TRACE GST_TRACER :0:: proctime, element=(string)identity0, time=(string)0:00:00.008585748;
0:00:00.126983880 12926 0x248bf20 TRACE GST_TRACER :0:: proctime, element=(string)identity0, time=(string)0:00:00.008579732;
0:00:00.132033587 12926 0x24c6a80 TRACE GST_TRACER :0:: proctime, element=(string)identity1, time=(string)0:00:00.050077050;
0:00:00.136588166 12926 0x248bf20 TRACE GST_TRACER :0:: proctime, element=(string)identity0, time=(string)0:00:00.008574922;
0:00:00.142125118 12926 0x24c68a0 TRACE GST_TRACER :0:: proctime, element=(string)identity2, time=(string)0:00:00.030071961;
0:00:00.145779940 12926 0x248bf20 TRACE GST_TRACER :0:: proctime, element=(string)identity0, time=(string)0:00:00.008578415;
0:00:00.155090678 12926 0x248bf20 TRACE GST_TRACER :0:: proctime, element=(string)identity0, time=(string)0:00:00.008583098;
0:00:00.164369513 12926 0x248bf20 TRACE GST_TRACER :0:: proctime, element=(string)identity0, time=(string)0:00:00.008598880;
0:00:00.172292595 12926 0x24c68a0 TRACE GST_TRACER :0:: proctime, element=(string)identity2, time=(string)0:00:00.030082726;
0:00:00.173588683 12926 0x248bf20 TRACE GST_TRACER :0:: proctime, element=(string)identity0, time=(string)0:00:00.008585821;
0:00:00.182214111 12926 0x24c6a80 TRACE GST_TRACER :0:: proctime, element=(string)identity1, time=(string)0:00:00.050107075;
0:00:00.182807057 12926 0x248bf20 TRACE GST_TRACER :0:: proctime, element=(string)identity0, time=(string)0:00:00.008586735;
0:00:00.191972095 12926 0x248bf20 TRACE GST_TRACER :0:: proctime, element=(string)identity0, time=(string)0:00:00.008602782;
0:00:00.201634649 12926 0x248bf20 TRACE GST_TRACER :0:: proctime, element=(string)identity0, time=(string)0:00:00.008626978;
0:00:00.202440357 12926 0x24c68a0 TRACE GST_TRACER :0:: proctime, element=(string)identity2, time=(string)0:00:00.030097713;
0:00:00.211297237 12926 0x248bf20 TRACE GST_TRACER :0:: proctime, element=(string)identity0, time=(string)0:00:00.008590217;
0:00:00.220964963 12926 0x248bf20 TRACE GST_TRACER :0:: proctime, element=(string)identity0, time=(string)0:00:00.008653206;
0:00:00.230604043 12926 0x248bf20 TRACE GST_TRACER :0:: proctime, element=(string)identity0, time=(string)0:00:00.008602488;

Additional notes

As it is shown on the output log of the pipeline run the results displayed correspond only to the identity elements, this is because as it was mentioned before the processing time only works for filter and filter-like elements, which is why there are no results for the videotestsrc, the tee and neither for the fakesink; on the other side, the queue element is a filter element and it is not being measured by the processing time tracer and this is why the queue element processes the buffers in different threads, therefore it is not possible to be measured by the processing time tracer. Regarding the results of the identity elements, verifying that the time needed by each element to process its incoming buffer matches the delay set previously on the pipeline is straightforward, which exemplifies the operation of the tracer and what can be expected from it.

← {{{prev}}}

⌂ Home

→ {{{next}}}