gstreamer tracer可以直接输出当前系统的开销、耗时、内存占用等状况。
使用tracer需要在debug中将tracer的打印开启。
GST_DEBUG=“GST_TRACER:7”
1. GST_DEBUG基础设定
设定打印等级
GST_DEBUG=2 //将log输出级别设定为2,WARNING
默认等级为0,即不输出任何信息。当我们需要输出log,通过设定GST_DEBUG变量的值来更改等级。对应等级参考下表
| # | Name | Description |
|---|---------|----------------------------------------------------------------|
| 0 | none | No debug information is output. |
| 1 | ERROR | Logs all fatal errors. These are errors that do not allow the |
| | | core or elements to perform the requested action. The |
| | | application can still recover if programmed to handle the |
| | | conditions that triggered the error. |
| 2 | WARNING | Logs all warnings. Typically these are non-fatal, but |
| | | user-visible problems are expected to happen. |
| 3 | FIXME | Logs all "fixme" messages. Those typically that a codepath that|
| | | is known to be incomplete has been triggered. It may work in |
| | | most cases, but may cause problems in specific instances. |
| 4 | INFO | Logs all informational messages. These are typically used for |
| | | events in the system that only happen once, or are important |
| | | and rare enough to be logged at this level. |
| 5 | DEBUG | Logs all debug messages. These are general debug messages for |
| | | events that happen only a limited number of times during an |
| | | object's lifetime; these include setup, teardown, change of |
| | | parameters, etc. |
| 6 | LOG | Logs all log messages. These are messages for events that |
| | | happen repeatedly during an object's lifetime; these include |
| | | streaming and steady-state conditions. This is used for log |
| | | messages that happen on every buffer in an element for example.|
| 7 | TRACE | Logs all trace messages. Those are message that happen very |
| | | very often. This is for example is each time the reference |
| | | count of a GstMiniObject, such as a GstBuffer or GstEvent, is |
| | | modified. |
| 9 | MEMDUMP | Logs all memory dump messages. This is the heaviest logging and|
| | | may include dumping the content of blocks of memory. |
+------------------------------------------------------------------------------+
单独设定某一元件等级
GST_DEBUG=2,audiotestsrc:6 //将audiotestsrc等级单独设定为6
以上支持通配符:
GST_DEBUG=2,audio*:6 //将所有audio开头的元件等级设定为6
将log输出到指定文件
GST_DEBUG_FILE=/home/gst/trace.log
更改输出通道
可以将log指定到某文件或者socket。
GST_TRACE_CHANNEL=stderr
输出管道图
GST_DEBUG_DUMP_DOT_DIR=/home/gst/
2. rusage
输出资源占用信息:
GST_TRACERS=“rusage”
$ GST_DEBUG="GST_TRACER:7" GST_TRACERS="rusage" /usr/bin/gst-play-1.0 ~/Videos/test1.mp4 ~/Videos/test1.mp4
...
0:00:00.109237154 15123 0x557d7cdac750 TRACE GST_TRACER :0:: thread-rusage, thread-id=(guint64)93997453985616, ts=(guint64)109234032, average-cpuload=(uint)151, current-cpuload=(uint)78, time=(guint64)16501669;
0:00:00.109243797 15123 0x557d7cdac750 TRACE GST_TRACER :0:: proc-rusage, process-id=(guint64)15123, ts=(guint64)109234032, average-cpuload=(uint)39, current-cpuload=(uint)32, time=(guint64)34465689;
0:00:00.109253587 15123 0x557d7cdac750 TRACE GST_TRACER :0:: thread-rusage, thread-id=(guint64)93997453985616, ts=(guint64)109250395, average-cpuload=(uint)151, current-cpuload=(uint)78, time=(guint64)16518019;
0:00:00.109260176 15123 0x557d7cdac750 TRACE GST_TRACER :0:: proc-rusage, process-id=(guint64)15123, ts=(guint64)109250395, average-cpuload=(uint)39, current-cpuload=(uint)32, time=(guint64)34482023;
使用定时器辅助监测:
GST_TRACE_TIMERS=“100ms,75ms”
原则上可以通过GST_TRACE_TIMERS=“100ms,75ms” ,然后设定GST_TRACERS=“rusage(timer=1000ms)” 来指定采集间隔,但实测无效,可能代码没有适配好。
GST_TRACE_TIMERS="100ms,75ms" GST_TRACERS="rusage(timer=1000ms)" gst-launch-1.0 videotestsrc num-buffers=10000 ! my_filter ! fakesink
3. leaks
检测GstObject 和 GstMiniObject的泄露:
GST_TRACERS=“leaks”
可以使用 GST_TRACERS="leaks"来检查在程序退出时会将未释放的内存打印出来。在程序执行中途强制退出也可以。
$GST_DEBUG="GST_TRACER:7" GST_TRACERS="leaks" gst-launch-1.0 videotestsrc num-buffers=10000 ! my_filter ! fakesink
...
0:00:07.270769896 22291 0x55942fe42d50 TRACE GST_TRACER :0:: object-alive, type-name=(string)GstMemory, address=(gpointer)0x7f398e2d1010, description=(string)0x7f398e2d1010, ref-count=(uint)1, trace=(string);
0:00:07.270773299 22291 0x55942fe42d50 TRACE GST_TRACER :0:: object-alive, type-name=(string)GstMemory, address=(gpointer)0x7f2aecf6b010, description=(string)0x7f2aecf6b010, ref-count=(uint)1, trace=(string);
0:00:07.270776878 22291 0x55942fe42d50 TRACE GST_TRACER :0:: object-alive, type-name=(string)GstMemory, address=(gpointer)0x7f28b3fdd010, description=(string)0x7f28b3fdd010, ref-count=(uint)1, trace=(string);
** (gst-launch-1.0:22291): WARNING **: 16:29:46.533: Leaks detected and logged under GST_DEBUG=GST_TRACER:7
指定检查对象:
GST_TRACERS=“leaks(GstEvent,GstMessage)”
4. latency
显示时间戳和花费:
GST_TRACERS=“latency(flags=element)”
延时主要计算元件中,从src到sink的时间统计,是在gst_pad_push或者gst_pad_pull_range函数中添加tracer来实现。
如果数据流有多个pad,比如tee或者mux,目前只会输出后面来的一组数据(前面的数据会被重写)。
$GST_TRACERS="latency(flags=element)" GST_DEBUG=GST_TRACER:7 ./filter_test
0:00:04.662245924 14152 0x5555750b4120 TRACE GST_TRACER :0:: element-latency, element-id=(string)0x5555750ae120, element=(string)videoscale, src=(string)src, time=(guint64)96957, ts=(guint64)4662173061;
0:00:04.662340868 14152 0x5555750b4120 TRACE GST_TRACER :0:: element-latency, element-id=(string)0x5555750ab070, element=(string)myfilterName, src=(string)src, time=(guint64)120781, ts=(guint64)4662293842;
0:00:04.662393369 14152 0x5555750b4120 TRACE GST_TRACER :0:: element-latency, element-id=(string)0x5555750ab1b0, element=(string)myfilterName2, src=(string)src, time=(guint64)61582, ts=(guint64)4662355424;
通过上述设定可以看到每个元件的时间统计,单位为微秒。
flags用于指定需要统计的object类型,支持pipeline,element,reported三种类型。如果没有指定flags,默认为piplline。也可以同时统计多种类型:GST_TRACERS=latency(flags=pipeline+element+reported)。
$GST_TRACERS="latency(flags=reported)" GST_DEBUG=GST_TRACER:7 ./filter_test
... ...
0:00:03.276968326 19234 0x7f3d24002980 TRACE GST_TRACER :0:: element-reported-latency, element-id=(string)0x561ccead85a0, element=(string)source, live=(boolean)0, min=(guint64)33333333, max=(guint64)18446744073709551615, ts=(guint64)3276956309;
0:00:03.276984393 19234 0x7f3d24002980 TRACE GST_TRACER :0:: element-reported-latency, element-id=(string)0x561cceaed120, element=(string)videoscale, live=(boolean)0, min=(guint64)0, max=(guint64)0, ts=(guint64)3276980931;
0:00:03.276992711 19234 0x7f3d24002980 TRACE GST_TRACER :0:: element-reported-latency, element-id=(string)0x561cceaea070, element=(string)myfilterName, live=(boolean)0, min=(guint64)18446744073676218283, max=(guint64)0, ts=(guint64)3276989093;
0:00:03.276998280 19234 0x7f3d24002980 TRACE GST_TRACER :0:: element-reported-latency, element-id=(string)0x561cceaea1b0, element=(string)myfilterName2, live=(boolean)0, min=(guint64)0, max=(guint64)0, ts=(guint64)3276996157;
$GST_TRACERS="latency(flags=element)" GST_DEBUG=GST_TRACER:7 ./filter_test
... ...
0:00:03.880613781 19834 0x5626b4ee6120 TRACE GST_TRACER :0:: element-latency, element-id=(string)0x5626b4edd070, element=(string)myfilterName, src=(string)src, time=(guint64)160478, ts=(guint64)3880522814;
0:00:03.880717967 19834 0x5626b4ee6120 TRACE GST_TRACER :0:: element-latency, element-id=(string)0x5626b4edd1b0, element=(string)myfilterName2, src=(string)src, time=(guint64)120145, ts=(guint64)3880642959;
0:00:03.880805603 19834 0x5626b4ee6120 TRACE GST_TRACER :0:: element-latency, element-id=(string)0x5626b4edd2f0, element=(string)myfilterName3, src=(string)src, time=(guint64)99418, ts=(guint64)3880742377;
5. stats
追溯buffer, event, message 和 query。
GST_TRACERS=“stats”
$ GST_DEBUG="GST_TRACER:7" GST_TRACERS="stats" gst-launch-1.0 videotestsrc num-buffers=10 ! my_filter ! fakesink
...
Setting pipeline to PLAYING ...
0:00:00.011970904 26716 0x555935117160 TRACE GST_TRACER :0:: message, thread-id=(guint64)93841630785888, ts=(guint64)11962673, element-ix=(uint)3, name=(string)new-clock, structure=(structure)"GstMessageNewClock\,\ clock\=\(GstClock\)\"\\\(GstSystemClock\\\)\\\ GstSystemClock\"\;";
0:00:00.011983251 26716 0x555935117160 TRACE GST_TRACER :0:: element-query, thread-id=(guint64)93841630785888, ts=(guint64)11980768, element-ix=(uint)3, name=(string)latency;
0:00:00.012004424 26716 0x555935117160 TRACE GST_TRACER :0:: query, thread-id=(guint64)93841630785888, ts=(guint64)11997035, pad-ix=(uint)2, element-ix=(uint)1, peer-pad-ix=(uint)3, peer-element-ix=(uint)2, name=(string)latency, structure=(structure)"GstQueryLatency\,\ live\=\(boolean\)false\,\ min-latency\=\(guint64\)0\,\ max-latency\=\(guint64\)18446744073709551615\;", have-res=(boolean)0, res=(boolean)0;
6. 多项输出
将需要输出的选项加上双引号,用分号隔开:
GST_TRACERS=“stats;rusage”
$GST_DEBUG="GST_TRACER:7" GST_TRACERS="stats;rusage" gst-launch-1.0 fakesrc num-buffers=10 sizetype=fixed ! queue ! fakesink
0:00:00.007896969 15529 0x563b6c84bd30 DEBUG GST_TRACER gsttracerrecord.c:125:gst_tracer_record_build_format: new format string: thread-rusage, thread-id=(guint64)%lu, ts=(guint64)%lu, average-cpuload=(uint)%u, current-cpuload=(uint)%u, time=(guint64)%lu;
0:00:00.007921621 15529 0x563b6c84bd30 TRACE GST_TRACER gsttracerrecord.c:111:gst_tracer_record_build_format: proc-rusage.class, process-id=(structure)"scope\,\ type\=\(type\)guint64\,\ related-to\=\(GstTracerValueScope\)GST_TRACER_VALUE_SCOPE_PROCESS\;", ts=(structure)"value\,\ type\=\(type\)guint64\,\ description\=\(string\)\"event\\\ ts\"\;", average-cpuload=(structure)"value\,\ type\=\(type\)guint\,\ description\=\(string\)\"average\\\ cpu\\\ usage\\\ per\\\ process\\\ in\\\ \\342\\200\\260\"\,\ flags\=\(GstTracerValueFlags\)GST_TRACER_VALUE_FLAGS_AGGREGATED\,\ min\=\(uint\)0\,\ max\=\(uint\)1000\;", current-cpuload=(structure)"value\,\ type\=\(type\)guint\,\ description\=\(string\)\"current\\\ cpu\\\ usage\\\ per\\\ process\\\ in\\\ \\342\\200\\260\"\,\ min\=\(uint\)0\,\ max\=\(uint\)1000\;", time=(structure)"value\,\ type\=\(type\)guint64\,\ description\=\(string\)\"time\\\ spent\\\ in\\\ process\\\ in\\\ ns\"\,\ flags\=\(GstTracerValueFlags\)GST_TRACER_VALUE_FLAGS_AGGREGATED\,\ min\=\(guint64\)0\,\ max\=\(guint64\)18446744073709551615\;";
0:00:00.007928798 15529 0x563b6c84bd30 DEBUG GST_TRACER gsttracerrecord.c:125:gst_tracer_record_build_format: new format string: proc-rusage, process-id=(guint64)%lu, ts=(guint64)%lu, average-cpuload=(uint)%u, current-cpuload=(uint)%u, time=(guint64)%lu;
0:00:00.008349489 15529 0x563b6c84bd30 TRACE GST_TRACER :0:: thread-rusage, thread-id=(guint64)94813223697712, ts=(guint64)8343995, average-cpuload=(uint)1000, current-cpuload=(uint)1000, time=(guint64)8345023;
0:00:00.008357952 15529 0x563b6c84bd30 TRACE GST_TRACER :0:: proc-rusage, process-id=(guint64)15529, ts=(guint64)8343995, average-cpuload=(uint)124, current-cpuload=(uint)124, time=(guint64)8343995;
7. 脚本工具
数据统计
gst-stats-1.0 trace.log
gst-stats可以用于统计log中的数据信息:
gst-stats-1.0 trace.log
Setting pipeline to PAUSED ...
Pipeline is PREROLLING ...
Pipeline is PREROLLED ...
Setting pipeline to PLAYING ...
New clock: GstSystemClock
Got EOS from element "pipeline0".
Execution ended after 0:00:00.001057097
Setting pipeline to NULL ...
Freeing pipeline ...
Overall Statistics:
Number of Threads: 3
Number of Elements: 3
Number of Bins: 1
Number of Pads: 4
Number of GhostPads: 0
Number of Buffers passed: 20
Number of Events sent: 8
Number of Message sent: 49
Number of Queries sent: 32
Time: 0:00:00.013837783
Avg CPU load: 13.9 %
Thread 0x55fa8908cd60 Statistics:
Time: 0:00:00.016669486
Avg CPU load: 100.0 %
Pad Statistics:
> fakesrc0.src : buffers 10 (live 0,dec 0,dis 1,res 0,cor 0,mar 0,hdr 0,gap 0,drop 0,dlt 0), size (min/avg/max) ......./ 4096/......., time 0:00:00.000471274, bytes/sec 86913345.527230
> queue0.src : buffers 10 (live 0,dec 0,dis 1,res 0,cor 0,mar 0,hdr 0,gap 0,drop 0,dlt 0), size (min/avg/max) ......./ 4096/......., time 0:00:00.001172691, bytes/sec 34928212.120669
Element Statistics:
GstFakeSrc:fakesrc0 : buffers in/out -/ 10 bytes in/out -/ 40960 first activity 0:00:00.011097270, ev/msg/qry sent 3/ 6/ 14
GstQueue:queue0 : buffers in/out 10/ 10 bytes in/out 40960/ 40960 first activity 0:00:00.011097271, ev/msg/qry sent 4/ 6/ 12
GstFakeSink:fakesink0 : buffers in/out 10/ - bytes in/out 40960/ - first activity 0:00:00.011176740, ev/msg/qry sent 1/ 10/ 6
Bin Statistics:
图形化输出
gst-plot-traces.sh --format=png | gnuplot eog trace.log.*.png
gst-plot-traces.sh可以用于输出图形化数据,经过gnuplot生成png图片。不过目前因为gnuplot配置问题,无法正常生成图像。
在生成tracer.log之后,直接运行gst-plot-traces脚本可以输出绘图内容:
gst-plot-traces.sh --format=png
set term png truecolor font "Sans,7" size 1600,1200
set output 'trace.cpu.png'
set xlabel "Time (ns)"
set ylabel "Per-Mille"
set grid
plot \
'/tmp/tmp.XzvO1WJYUP/cpu_proc.dat' using 1:2 with lines title 'avg cpu', \
'' using 1:3 with lines title 'cur cpu'
set output 'trace.thread.png'
set xlabel "Time (ns)"
set ylabel "Per-Mille"
set grid
plot \
'/tmp/tmp.XzvO1WJYUP/cpu_thread.139964729823632.dat' using 1:2 with lines title '139964729823632 avg cpu', \
'' using 1:3 with lines title '139964729823632 cur cpu', \
'/tmp/tmp.XzvO1WJYUP/cpu_thread.139967145783072.dat' using 1:2 with lines title '139967145783072 avg cpu', \
'' using 1:3 with lines title '139967145783072 cur cpu', \
'/tmp/tmp.XzvO1WJYUP/cpu_thread.139967145982512.dat' using 1:2 with lines title '139967145982512 avg cpu', \
'' using 1:3 with lines title '139967145982512 cur cpu', \
'/tmp/tmp.XzvO1WJYUP/cpu_thread.139967214918656.dat' using 1:2 with lines title '139967214918656 avg cpu', \
'' using 1:3 with lines title '139967214918656 cur cpu', \
'/tmp/tmp.XzvO1WJYUP/cpu_thread.139967215176320.dat' using 1:2 with lines title '139967215176320 avg cpu', \
'' using 1:3 with lines title '139967215176320 cur cpu', \
'/tmp/tmp.XzvO1WJYUP/cpu_thread.139967281669520.dat' using 1:2 with lines title '139967281669520 avg cpu', \
'' using 1:3 with lines title '139967281669520 cur cpu', \
'/tmp/tmp.XzvO1WJYUP/cpu_thread.94768975272240.dat' using 1:2 with lines title '94768975272240 avg cpu', \
'' using 1:3 with lines title '94768975272240 cur cpu', \
'/tmp/tmp.XzvO1WJYUP/cpu_thread.94768975415856.dat' using 1:2 with lines title '94768975415856 avg cpu', \
'' using 1:3 with lines title '94768975415856 cur cpu', \