gstreamer debug tracer使用概览

最新推荐文章于 2024-06-18 13:41:49 发布

Aero Auto

最新推荐文章于 2024-06-18 13:41:49 发布

阅读量1.9k

点赞数 2

分类专栏： gstreamer 文章标签： linux

本文链接：https://blog.csdn.net/yuangc/article/details/120442503

版权

gstreamer 专栏收录该内容

14 篇文章 16 订阅

订阅专栏

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', \

Aero Auto

关注

2
点赞
踩
12

收藏

觉得还不错? 一键收藏
4
评论
gstreamer debug tracer使用概览

gstreamr traces提供了延时、内存泄露等配置，可以直接通过环境变量来控制相关信息输出。1. 延时统计延时主要计算元件中，从src到sink的时间。使用 GST_TRACERS="latency(flags=element)"来使能log：GST_TRACERS="latency(flags=element)" GST_DEBUG=GST_TRACER:7 ./filter_test0:00:04.662245924 14152 0x5555750b4120 TRACE
复制链接

扫一扫