Revision as of 19:20, 17 August 2017

⌂
Home

The schedule time tracer is very similar to the processing time tracer. The processing time is focused on measuring the time that an element takes to completely process a given buffer and that is why it is measured on the source pad of that element, because when the buffer gets to that point is when the element has finished its process and the buffer is ready to be pushed to next element. On the other side, what the scheduling time tracer does is measuring the elapsed time since one buffer arrived to the sink pad of the element with the immediate consecutive one, without taking in consideration the time needed for the element to compute the arrived data buffer.

In the same way than the processing time tracer and the inter latency tracer, the schedule time tracer was developed to providing precise data to the user about the time needed by the pipeline to process a given data buffer completely and, with this, the performance of the pipeline. This tracer is not focused on the performance of the pipeline itself, like the processing time tracer and the inter latency tracer, instead it helps the user detect when and where data is being lost. In pipelines where live sources are present for audio and video and the outcome has several issues with synchronization or with frozen images, this tracer proves very useful. The schedule time tracer is useful for detecting bottle necks on the pipeline, buffer drops, inter-clock differences, and others.

This tracer does not have any limitation of the type of element that is being measured, the only requirement is that it has to have a sink pad because of the nature of the tracer.

The schedule time tracer measures the difference between the arrival of a data buffer on the sink pad of an element and the arrival of the following buffer. So, under normal operation, these values remain constant for the same element once the pipeline is stable. However, when buffer drops or other issues happen, the tracer measures an increased delay between two immediate buffers.

Pipeline

The following pipeline demonstrates the use of the scheduletime tracer and the results obtained.

GST_DEBUG="GST_TRACER:7" GST_TRACERS="scheduletime" gst-launch-1.0 v4l2src device=/dev/video0 do-timestamp=true ! 'video/x-raw, format=(string)YUY2, width=(int)1280, height=(int)720, framerate=(fraction)10/1' ! videoconvert ! queue ! avenc_h263p ! fakesink sync=true

Sample diagram

Output

0:00:01.696032908 13338 0x16532d0 TRACE GST_TRACER :0:: scheduletime, pad=(string)capsfilter0_sink, time=(string)0:00:00.099998663;
0:00:01.696074070 13338 0x16532d0 TRACE GST_TRACER :0:: scheduletime, pad=(string)videoconvert0_sink, time=(string)0:00:00.100000780;
0:00:01.706234597 13338 0x16532d0 TRACE GST_TRACER :0:: scheduletime, pad=(string)queue0_sink, time=(string)0:00:00.100140205;
0:00:01.706300516 13338 0x1653400 TRACE GST_TRACER :0:: scheduletime, pad=(string)avenc_h263p0_sink, time=(string)0:00:00.100140252;
0:00:01.711455532 13338 0x1653400 TRACE GST_TRACER :0:: scheduletime, pad=(string)fakesink0_sink, time=(string)0:00:00.088935196;

Each line of the log output contains a pad field that identifies the element being measured and a time field that shows the measured delay between consecutive buffers.

←
Framerate tracer

⌂
Home

→
CPU usage tracer

@@ Line 3: / Line 3: @@
 |next=[[GstShark - CPU usage tracer|CPU usage tracer]]
 |name=ScheduleTime
-|description=The schedule time tracer is very similar to the processing time tracer, and specially on the output logs. The processing time is focused on measuring the time that an element takes to completely process a given buffer and that is why it is measured on the source pad of that element, because when the buffer gets to that point is when the element has finished its process and the buffer is ready to be pushed to next element; on the other side, what the scheduling time tracer does is measuring the elapsed time since one buffer arrived to the sink pad of the element with the immediate consecutive one, without taking in consideration the time needed for the element to compute the arrived data buffer.
+|description=The schedule time tracer is very similar to the processing time tracer. The processing time is focused on measuring the time that an element takes to completely process a given buffer and that is why it is measured on the source pad of that element, because when the buffer gets to that point is when the element has finished its process and the buffer is ready to be pushed to next element. On the other side, what the scheduling time tracer does is measuring the elapsed time since one buffer arrived to the sink pad of the element with the immediate consecutive one, without taking in consideration the time needed for the element to compute the arrived data buffer.
-In the same way than the processing time tracer and the inter latency tracer, the schedule time tracer was developed with the purpose of providing precise data to the user about the amount of time needed by the pipeline to process a given data buffer completely and with this giving an idea of the performance of the pipeline. In difference with the processing time tracer and the inter latency tracer this tracer is not focused on the performance of the pipeline, instead it is oriented to help the user to detect when and where is occurring a lost of information; specially in pipelines where live sources are present for audio and video and the outcome has several issues with synchronization or with frozen images. The schedule time tracer is specially useful for detecting bottle necks on the pipeline, buffer drops, inter-clock differences, among others.
+In the same way than the processing time tracer and the inter latency tracer, the schedule time tracer was developed to providing precise data to the user about the time needed by the pipeline to process a given data buffer completely and, with this, the performance of the pipeline. This tracer is not focused on the performance of the pipeline itself, like the processing time tracer and the inter latency tracer, instead it helps the user detect when and where data is being lost. In pipelines where live sources are present for audio and video and the outcome has several issues with synchronization or with frozen images, this tracer proves very useful. The schedule time tracer is useful for detecting bottle necks on the pipeline, buffer drops, inter-clock differences, and others.
+This tracer does not have any limitation of the type of element that is being measured, the only requirement is that it has to have a sink pad because of the nature of the tracer.
+The schedule time tracer measures the difference between the arrival of a data buffer on the sink pad of an element and the arrival of the following buffer. So, under normal operation, these values remain constant for the same element once the pipeline is stable. However, when buffer drops or other issues happen, the tracer measures an increased delay between two immediate buffers.
-In order to demonstrate the operation of the schedule time tracer the following pipeline was used for testing; this pipeline has six elements, numbered from left to right, connected as the following graph shows. This tracer does not have any limitation with category of the element that is being measured, the only requirement is that it has to have a sink pad because of the nature of the tracer, which is why the source element are not analyzed with this 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_scheduletime.png|1000px|center]]
 |pipeline=
+The following pipeline demonstrates the use of the scheduletime tracer and the results obtained.
 <pre style="white-space:pre-wrap; width:100%;">
 GST_DEBUG="GST_TRACER:7" GST_TRACERS="scheduletime" gst-launch-1.0 v4l2src device=/dev/video0 do-timestamp=true ! 'video/x-raw, format=(string)YUY2, width=(int)1280, height=(int)720, framerate=(fraction)10/1' ! videoconvert ! queue ! avenc_h263p ! fakesink sync=true
 </pre>
 |output=
-<font size=1>
+<font size=2>
-<pre>
+<pre>0:00:01.696032908 13338 0x16532d0 TRACE GST_TRACER :0:: scheduletime, pad=(string)capsfilter0_sink, time=(string)0:00:00.099998663;
-:00:01.100036113 13338 0x16532d0 TRACE GST_TRACER :0:: scheduletime, pad=(string)capsfilter0_sink, time=(string)0:00:00.099975209;
-:00:01.100077742 13338 0x16532d0 TRACE GST_TRACER :0:: scheduletime, pad=(string)videoconvert0_sink, time=(string)0:00:00.100006848;
-:00:01.110098321 13338 0x16532d0 TRACE GST_TRACER :0:: scheduletime, pad=(string)queue0_sink, time=(string)0:00:00.095063097;
-:00:01.110171350 13338 0x1653400 TRACE GST_TRACER :0:: scheduletime, pad=(string)avenc_h263p0_sink, time=(string)0:00:00.095097492;
-:00:01.144021899 13338 0x1653400 TRACE GST_TRACER :0:: scheduletime, pad=(string)fakesink0_sink, time=(string)0:00:00.106929909;
-:00:01.196037609 13338 0x16532d0 TRACE GST_TRACER :0:: scheduletime, pad=(string)capsfilter0_sink, time=(string)0:00:00.096002535;
-:00:01.196077429 13338 0x16532d0 TRACE GST_TRACER :0:: scheduletime, pad=(string)videoconvert0_sink, time=(string)0:00:00.096000107;
-:00:01.205692317 13338 0x16532d0 TRACE GST_TRACER :0:: scheduletime, pad=(string)queue0_sink, time=(string)0:00:00.095595742;
-:00:01.205761485 13338 0x1653400 TRACE GST_TRACER :0:: scheduletime, pad=(string)avenc_h263p0_sink, time=(string)0:00:00.095590914;
-:00:01.230904816 13338 0x1653400 TRACE GST_TRACER :0:: scheduletime, pad=(string)fakesink0_sink, time=(string)0:00:00.086886102;
-:00:01.296035071 13338 0x16532d0 TRACE GST_TRACER :0:: scheduletime, pad=(string)capsfilter0_sink, time=(string)0:00:00.099998787;
-:00:01.296076145 13338 0x16532d0 TRACE GST_TRACER :0:: scheduletime, pad=(string)videoconvert0_sink, time=(string)0:00:00.099998340;
-:00:01.305749996 13338 0x16532d0 TRACE GST_TRACER :0:: scheduletime, pad=(string)queue0_sink, time=(string)0:00:00.100057851;
-:00:01.305831402 13338 0x1653400 TRACE GST_TRACER :0:: scheduletime, pad=(string)avenc_h263p0_sink, time=(string)0:00:00.100059523;
-:00:01.338188493 13338 0x1653400 TRACE GST_TRACER :0:: scheduletime, pad=(string)fakesink0_sink, time=(string)0:00:00.107283618;
-:00:01.396034758 13338 0x16532d0 TRACE GST_TRACER :0:: scheduletime, pad=(string)capsfilter0_sink, time=(string)0:00:00.099999355;
-:00:01.396074586 13338 0x16532d0 TRACE GST_TRACER :0:: scheduletime, pad=(string)videoconvert0_sink, time=(string)0:00:00.099998790;
-:00:01.406017644 13338 0x16532d0 TRACE GST_TRACER :0:: scheduletime, pad=(string)queue0_sink, time=(string)0:00:00.100268044;
-:00:01.406085333 13338 0x1653400 TRACE GST_TRACER :0:: scheduletime, pad=(string)avenc_h263p0_sink, time=(string)0:00:00.100264111;
-:00:01.422747303 13338 0x1653400 TRACE GST_TRACER :0:: scheduletime, pad=(string)fakesink0_sink, time=(string)0:00:00.084559137;
-:00:01.496031029 13338 0x16532d0 TRACE GST_TRACER :0:: scheduletime, pad=(string)capsfilter0_sink, time=(string)0:00:00.099996185;
-:00:01.496071205 13338 0x16532d0 TRACE GST_TRACER :0:: scheduletime, pad=(string)videoconvert0_sink, time=(string)0:00:00.099996202;
-:00:01.505720264 13338 0x16532d0 TRACE GST_TRACER :0:: scheduletime, pad=(string)queue0_sink, time=(string)0:00:00.099703471;
-:00:01.505797802 13338 0x1653400 TRACE GST_TRACER :0:: scheduletime, pad=(string)avenc_h263p0_sink, time=(string)0:00:00.099702877;
-:00:01.518303910 13338 0x1653400 TRACE GST_TRACER :0:: scheduletime, pad=(string)fakesink0_sink, time=(string)0:00:00.095557221;
-:00:01.596034015 13338 0x16532d0 TRACE GST_TRACER :0:: scheduletime, pad=(string)capsfilter0_sink, time=(string)0:00:00.100002760;
-:00:01.596073322 13338 0x16532d0 TRACE GST_TRACER :0:: scheduletime, pad=(string)videoconvert0_sink, time=(string)0:00:00.100002398;
-:00:01.606089673 13338 0x16532d0 TRACE GST_TRACER :0:: scheduletime, pad=(string)queue0_sink, time=(string)0:00:00.100368610;
-:00:01.606159476 13338 0x1653400 TRACE GST_TRACER :0:: scheduletime, pad=(string)avenc_h263p0_sink, time=(string)0:00:00.100371629;
-:00:01.622523839 13338 0x1653400 TRACE GST_TRACER :0:: scheduletime, pad=(string)fakesink0_sink, time=(string)0:00:00.104218242;
-:00:01.696032908 13338 0x16532d0 TRACE GST_TRACER :0:: scheduletime, pad=(string)capsfilter0_sink, time=(string)0:00:00.099998663;
 :00:01.696074070 13338 0x16532d0 TRACE GST_TRACER :0:: scheduletime, pad=(string)videoconvert0_sink, time=(string)0:00:00.100000780;
 :00:01.706234597 13338 0x16532d0 TRACE GST_TRACER :0:: scheduletime, pad=(string)queue0_sink, time=(string)0:00:00.100140205;
 :00:01.706300516 13338 0x1653400 TRACE GST_TRACER :0:: scheduletime, pad=(string)avenc_h263p0_sink, time=(string)0:00:00.100140252;
-:00:01.711455532 13338 0x1653400 TRACE GST_TRACER :0:: scheduletime, pad=(string)fakesink0_sink, time=(string)0:00:00.088935196;
+:00:01.711455532 13338 0x1653400 TRACE GST_TRACER :0:: scheduletime, pad=(string)fakesink0_sink, time=(string)0:00:00.088935196;</pre>
-</pre>
 </font>
-|closing=The measurements done by the schedule time tracer correspond to the difference between the arrival of a data buffer on the sink pad of an element and the arrival of the following buffer; normally when the behavior of the pipeline is the expected one, and and as it can be seen on the output log above, these values measured tend to maintain constant for the same element once the pipeline is stable, which is related to the frame rate and the processing time of the element but that it can be appreciated by using the schedule time tracer as the previous example and with that verify that there are not buffer drops or any other possible issue that could cause a delay, higher than the expected one, between two immediate buffers.
+Each line of the log output contains a {{code|pad}} field that identifies the element being measured and a {{code|time}} field that shows the measured delay between consecutive buffers.
 }}