GstShark - Processing Time tracer: Difference between revisions

From RidgeRun Developer Wiki
No edit summary
No edit summary
(3 intermediate revisions by the same user not shown)
Line 3: Line 3:
|next=[[GstShark - Framerate tracer|Framerate tracer]]
|next=[[GstShark - Framerate tracer|Framerate tracer]]
|name=ProcTime
|name=ProcTime
|description=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.
|description=Processing time was developed with the purpose of providing useful information to the user about the time each element of a given pipeline takes processing each data buffer that goes through it. This allows the user to measure the performance of each element of the pipeline. This tracer was developed to help the user determine which element or process is increasing the general latency of the pipeline. It is a tool to check which element takes too much time completing its tasks, causing a slow performance of the pipeline which can lead to a delay on the buffers. This kind of delay can affect audio-video synchronization, for 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.
The processing time tracer is designed to providing accurate data for the filter and filter-like elements of the pipeline. The tracer measures the time an element takes to generate an output buffer when it receives a buffer on its sink pad. Only elements that have both input and outputs pads are measured. Thus, the source and sink elements are not measured by this tracer.
 
In the filter elements, supported by this tracer, an input buffer produces an output buffer, as a video converter. The filter-like elements are more complex elements in which several input buffers combine to produce an output buffer (like an encoder or a muxer) or where a single input buffer produces several output buffers (like a 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 tracer displays 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.


|graph=[[File:test_proctime.png|1000px|center]]
|graph=[[File:test_proctime.png|1000px|center]]


|pipeline=
|pipeline=
<pre style="white-space:pre-wrap; width:100%;">
The following pipeline demonstrates how to use the processing time tracer and the results obtained with it. Identity elements with a delay set are used to simulate an increased processing time by an element. This forced delay should be reflected on the measurements for every element on the output log of the tracer.
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
 
</pre>
<syntaxhighlight lang=bash>
$ 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
</syntaxhighlight>


|output=
|output=
<font size=1>
<font size=2>
<pre>
<pre>0:00:03.064150969 13190      0x1511720 TRACE             GST_TRACER :0:: proctime, element=(string)identity0, time=(string)0:00:00.008593923;
0:00:00.030766061 12926 0x248bf20 TRACE GST_TRACER :0:: proctime, element=(string)identity0, time=(string)0:00:00.008613006;
0:00:03.085515606 13190      0x165f680 TRACE             GST_TRACER :0:: proctime, element=(string)identity2, time=(string)0:00:00.030146650;
0:00:00.040429334 12926 0x248bf20 TRACE GST_TRACER :0:: proctime, element=(string)identity0, time=(string)0:00:00.008651178;
0:00:03.105485969 13190      0x165f4a0 TRACE             GST_TRACER :0:: proctime, element=(string)identity1, time=(string)0:00:00.050150374;</pre>
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;
</pre>
</font>
</font>


|closing=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.
Each line of the log includes an {{code|1=element}} field identifying the element and the {{code|1=time}} field with the processing time it took to run a buffer through the element. The output log only shows the identity elements. This is because, as it was mentioned before, the processing time only works for filter and filter-like elements. There are no results for the videotestsrc, the tee or the fakesinks. The queue element is a filter element as well, but it processes the buffers in different threads, so it is not supported by the processing time tracer.  
 
|plot=[[File:test_proctime_plot.png|1000px|center]]
}}
}}

Revision as of 04:18, 18 August 2017

GstShark
GstShark
Getting Started
Generating trace files
Tracer Parameters
Available Tracers
Results
Visualization Tools
Examples
Contact Us
←
InterLatency tracer 		⌂
Home 		→
Framerate tracer

Processing time was developed with the purpose of providing useful information to the user about the time each element of a given pipeline takes processing each data buffer that goes through it. This allows the user to measure the performance of each element of the pipeline. This tracer was developed to help the user determine which element or process is increasing the general latency of the pipeline. It is a tool to check which element takes too much time completing its tasks, causing a slow performance of the pipeline which can lead to a delay on the buffers. This kind of delay can affect audio-video synchronization, for example.

The processing time tracer is designed to providing accurate data for the filter and filter-like elements of the pipeline. The tracer measures the time an element takes to generate an output buffer when it receives a buffer on its sink pad. Only elements that have both input and outputs pads are measured. Thus, the source and sink elements are not measured by this tracer.

In the filter elements, supported by this tracer, an input buffer produces an output buffer, as a video converter. The filter-like elements are more complex elements in which several input buffers combine to produce an output buffer (like an encoder or a muxer) or where a single input buffer produces several output buffers (like a 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 tracer displays a general measurement of the time elapsed processing a buffer without knowing the operation of element in detail.

Pipeline

The following pipeline demonstrates how to use the processing time tracer and the results obtained with it. Identity elements with a delay set are used to simulate an increased processing time by an element. This forced delay should be reflected on the measurements for every element on the output log of the tracer. 

$ 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:03.064150969 13190      0x1511720 TRACE             GST_TRACER :0:: proctime, element=(string)identity0, time=(string)0:00:00.008593923;
0:00:03.085515606 13190      0x165f680 TRACE             GST_TRACER :0:: proctime, element=(string)identity2, time=(string)0:00:00.030146650;
0:00:03.105485969 13190      0x165f4a0 TRACE             GST_TRACER :0:: proctime, element=(string)identity1, time=(string)0:00:00.050150374;

Each line of the log includes an element field identifying the element and the time field with the processing time it took to run a buffer through the element. The output log only shows the identity elements. This is because, as it was mentioned before, the processing time only works for filter and filter-like elements. There are no results for the videotestsrc, the tee or the fakesinks. The queue element is a filter element as well, but it processes the buffers in different threads, so it is not supported by the processing time tracer.

Plot

←
InterLatency tracer 		⌂
Home 		→
Framerate tracer
Retrieved from "http://developer.ridgerun.com/wiki/index.php?title=GstShark_-_Processing_Time_tracer&oldid=14316"