How to profile video framerate
This article aims to debug & profile framerate performances of any GStreamer video use-case, including camera preview or video playback use-cases.
目录
Debugging framerate issues
A variety of symptoms related to framerate issues may be observed such as:
- Jerky video
- Video freeze
- Excessively slow Video framerate (typically one frame per second, see below)
- Too slow or too fast video motion
- Audio & video not synchronized
- ...
When such symptoms are observed, one can check below chapters to ease investigations and analysis of the problems.
Framerate of played content
Before investigating possible framerate issues, check the expected multimedia content framerate.
For a video, refer to gst-discoverer to get the video file framerate:
Board $> gst-discoverer-1.0 <my video> -v | grep -i "Frame rate"
Frame rate: 30/1
For this video, the framerate is 30 fps (frames per second).
For a camera preview use-case, the framerate is set in the pipeline:
Board $> gst-launch-1.0 v4l2src ! "video/x-raw, width=1280, Height=720, framerate=(fraction)15/1" ! queue ! autovideosink -e
Here the expected framerate is 15 fps.
Display framerate
当动画在显示器上运行时，可以从 显示驱动器级的命令：
Board $> (while true; do export fps=`cat /sys/kernel/debug/dri/0/state | grep fps -m1 | grep -o '[0-9]\+'`; echo display ${fps}fps; sleep 4; done) &
然后，在用户控制台中以“ fps”（f框persecond）定期输出显示帧率：
display 50fps display 50fps display 50fps
注意事项:
- 使用“ kill -9`ps -o ppid = -C sleep`”命令停止监视帧速率。
- 通过修改“睡眠”值（示例中为4秒）来调整帧速率更新时间。
- 使用命令“ dmesg -n8”来混合用户和内核控制台输出。
- 需要启用调试文件系统(debugfs)配置。
It should conform to the expected framerate for the played content. If it is not the case, continue investigations with next chapters.
Check default traces
By default, the traces show Warnings when the GStreamer video sink receives a lot of late buffers:
WARNING: from element /GstPipeline:pipeline0/[...] A lot of buffers are being dropped.
In that case, GStreamer falls into a recovery mode consisting into displaying one frame every second.
If such warning is displayed, it means that some elements before the video sink are not fast enough to sustain the targeted framerate.
Here is a test pipeline illustrating this behaviour:
Board $> gst-launch-1.0 videotestsrc ! "video/x-raw, framerate=(fraction)200/1" ! autovideosink
Setting pipeline to PAUSED ... Pipeline is PREROLLING ... Pipeline is PREROLLED ... Setting pipeline to PLAYING ... New clock: GstSystemClock WARNING: from element /GstPipeline:pipeline0/GstWaylandSink:waylandsink0: A lot of buffers are being dropped. Additional debug info: ../../../../git/libs/gst/base/gstbasesink.c(2901): gst_base_sink_is_too_late (): /GstPipeline:pipeline0/GstWaylandSink:waylandsink0: There may be a timestamping problem, or this computer is too slow. WARNING: from element /GstPipeline:pipeline0/GstWaylandSink:waylandsink0: A lot of buffers are being dropped. Additional debug info: ../../../../git/libs/gst/base/gstbasesink.c(2901): gst_base_sink_is_too_late (): /GstPipeline:pipeline0/GstWaylandSink:waylandsink0: There may be a timestamping problem, or this computer is too slow. WARNING: from element /GstPipeline:pipeline0/GstWaylandSink:waylandsink0: A lot of buffers are being dropped.
This test pipeline generates a pattern at 200fps which is not sustainable by the overall system, leading to frames coming to the video sink very late.
 |
This trace only appears if lot of frames are dropped, see following chapters for finer grain analysis. |
Frame drop traces
Fine grain information can be provided around frame drops by enabling video sink traces:
--gst-debug=basesink:6 2>&1 | grep drop
One trace message will be output for each frame dropped.
With the test pipeline:
Board $> gst-launch-1.0 -e videotestsrc ! "video/x-raw, framerate=(fraction)100/1" ! autovideosink --gst-debug=basesink:6 2>&1 | grep drop
0:00:01.135448709 585 0x1a5a60 DEBUG basesink gstbasesink.c:3626:gst_base_sink_chain_unlocked:<autovideosink0-actual-sink-wayland> buffer late, dropping 0:00:01.147437126 585 0x1a5a60 DEBUG basesink gstbasesink.c:3626:gst_base_sink_chain_unlocked:<autovideosink0-actual-sink-wayland> buffer late, dropping 0:00:01.157521667 585 0x1a5a60 DEBUG basesink gstbasesink.c:3626:gst_base_sink_chain_unlocked:<autovideosink0-actual-sink-wayland> buffer late, dropping 0:00:01.168611
If no traces are observed, the GStreamer synchronisation system has not dropped any frame.
|
Even if no drop is observed with this trace, frames could nevertheless be dropped by the video sink GStreamer element because of the display subsystem, see next chapter for more details. |
.
Frame drop due to display subsytem
Frames could also be dropped by the video sink GStreamer element because of the display subsystem not being fast enough to sustain the incoming framerate.
This frame dropping strategy is specific to the selected video sink GStreamer element.
Here is a trace that can be enabled to show when wayland subsystem cannot sustain the incoming framerate, and consequently, drop frames:
--gst-debug=waylandsink:6 2>&1 | grep -i "redraw pending"
Here is an example:
Board $> gst-launch-1.0 -v -e videotestsrc ! video/x-raw, format=I420, framerate=100/1 ! queue ! fpsdisplaysink sync=false video-sink=waylandsink -v --gst-debug=waylandsink:6 2>&1 | grep -e "redraw pending" -e "dropped"
0:00:00.392392792 1020 0x19dd50 LOG waylandsink gstwaylandsink.c:822:gst_wayland_sink_show_frame:<waylandsink0> buffer 0xb510d860 dropped (redraw pending) 0:00:00.392863376 1020 0x19dd50 LOG waylandsink gstwaylandsink.c:822:gst_wayland_sink_show_frame:<waylandsink0> buffer 0xb510d900 dropped (redraw pending) 0:00:00.394748751 1020 0x19dd50 LOG waylandsink gstwaylandsink.c:822:gst_wayland_sink_show_frame:<waylandsink0> buffer 0xb510d9a0 dropped (redraw pending) 0:00:00.422420584 1020 0x19dd50 LOG waylandsink gstwaylandsink.c:822:gst_wayland_sink_show_frame:<waylandsink0> buffer 0xb510d900 dropped (redraw pending) /GstPipeline:pipeline0/GstFPSDisplaySink:fpsdisplaysink0/GstTextOverlay:fps-display-text-overlay: text = rendered: 132, dropped: 0, current: 76.90, average: 87.14 /GstPipeline:pipeline0/GstFPSDisplaySink:fpsdisplaysink0: last-message = rendered: 132, dropped: 0, current: 76.90, average: 87.14
In this example, the frames are generated fast enough to not be dropped because of their lateness, see trace message "dropped: 0". This is the display subsystem that is responsible of not rendering frames fast enough, see trace message "dropped (redraw pending)".
Profiling framerate: fpsdisplaysink
The framerate measurement can be done using fpsdisplaysink GStreamer element.
The measure is shown directly on the screen on a display overlay:
Available information:
- the number of rendered frames
- the number of dropped frames
- the current framerate
- the average framerate
fpsdisplaysink can replace any existing video sink into a GStreamer pipeline. To do so, replace:
gst-launch-1.0 [...] ! <current video sink>
with:
gst-launch-1.0 [...] ! fpsdisplaysink video-sink=<current video sink>
This could also be done with high level GStreamer bins such as playbin. To do so, replace:
gst-launch-1.0 playbin [...] video-sink=<current video sink>
with:
gst-launch-1.0 playbin [...] video-sink="fpsdisplaysink video-sink=<current video sink>"
Same can be done for high level GStreamer utility such as gst-play. To do so, replace:
gst-play-1.0 [...]
with:
gst-play-1.0 [...] --videosink="fpsdisplaysink video-sink=autovideosink"
Information could also be displayed in the console using the GStreamer "-v" verbose option.
Here is a test pipeline illustrating this behaviour:
Board $> gst-launch-1.0 videotestsrc ! "video/x-raw, width=640, height=480, framerate=(fraction)30/1" ! fpsdisplaysink video-sink=autovideosink -v
/GstPipeline:pipeline0/GstFPSDisplaySink:fpsdisplaysink0/GstTextOverlay:fps-display-text-overlay: text = rendered: 618, dropped: 3, fps: 25.04, drop rate: 1.93 /GstPipeline:pipeline0/GstFPSDisplaySink:fpsdisplaysink0: last-message = rendered: 618, dropped: 3, fps: 25.04, drop rate: 1.93 /GstPipeline:pipeline0/GstFPSDisplaySink:fpsdisplaysink0/GstTextOverlay:fps-display-text-overlay: text = rendered: 629, dropped: 10, fps: 20.52, drop rate: 13.06 /GstPipeline:pipeline0/GstFPSDisplaySink:fpsdisplaysink0: last-message = rendered: 629, dropped: 10, fps: 20.52, drop rate: 13.06 /GstPipeline:pipeline0/GstFPSDisplaySink:fpsdisplaysink0/GstTextOverlay:fps-display-text-overlay: text = rendered: 644, dropped: 10, current: 29.75, average: 29.55 /GstPipeline:pipeline0/GstFPSDisplaySink:fpsdisplaysink0: last-message = rendered: 644, dropped: 10, current: 29.75, average: 29.55 /GstPipeline:pipeline0/GstFPSDisplaySink:fpsdisplaysink0/GstTextOverlay:fps-display-text-overlay: text = rendered: 660, dropped: 10, current: 30.19, average: 29.57 /GstPipeline:pipeline0/GstFPSDisplaySink:fpsdisplaysink0: last-message = rendered: 660, dropped: 10, current: 30.19, average: 29.57
More options are also available on fpsdisplaysink, refer to the help:
Board $> gst-inspect-1.0 fpsdisplaysink
Factory Details:
Rank none (0)
Long-name Measure and show framerate on videosink
Klass Sink/Video
Description Shows the current frame-rate and drop-rate of the videosink as overlay or text on stdout
Author Zeeshan Ali <zeeshan.ali@nokia.com>, Stefan Kost <stefan.kost@nokia.com>
Plugin Details:
Name debugutilsbad
Description Collection of elements that may or may not be useful for debugging
Filename /usr/lib/gstreamer-1.0/libgstdebugutilsbad.so
Version 1.12.3
License LGPL
Source module gst-plugins-bad
Source release date 2017-09-18
Binary package GStreamer Bad Plug-ins source release
Origin URL Unknown package origin
GObject
+----GInitiallyUnowned
+----GstObject
+----GstElement
+----GstBin
+----GstFPSDisplaySink
Implemented Interfaces:
GstChildProxy
Pad Templates:
SINK template: 'sink'
Availability: Always
Capabilities:
ANY
Element Flags:
no flags set
Bin Flags:
no flags set
Element Implementation:
Has change_state() function: 0xb6a63d60
Element has no clocking capabilities.
Element has no URI handling capabilities.
Pads:
SINK: 'sink'
Element Properties:
name : The name of the object
flags: readable, writable
String. Default: "fpsdisplaysink0"
parent : The parent of the object
flags: readable, writable
Object of type "GstObject"
async-handling : The bin will handle Asynchronous state changes
flags: readable, writable
Boolean. Default: false
message-forward : Forwards all children messages
flags: readable, writable
Boolean. Default: false
sync : Sync on the clock (if the internally used sink doesn't have this property it will be ignored
flags: readable, writable
Boolean. Default: true
text-overlay : Whether to use text-overlay
flags: readable, writable
Boolean. Default: true
video-sink : Video sink to use (Must only be called on NULL state)
flags: readable, writable
Object of type "GstElement"
fps-update-interval : Time between consecutive frames per second measures and update (in ms). Should be set on NULL state
flags: readable, writable
Integer. Range: 1 - 2147483647 Default: 500
max-fps : Maximum fps rate measured. Reset when going from NULL to READY.-1 means no measurement has yet been done
flags: readable
Double. Range: -1 - 1.797693e+308 Default: -1
min-fps : Minimum fps rate measured. Reset when going from NULL to READY.-1 means no measurement has yet been done
flags: readable
Double. Range: -1 - 1.797693e+308 Default: -1
signal-fps-measurements: If the fps-measurements signal should be emited.
flags: readable, writable
Boolean. Default: false
frames-dropped : Number of frames dropped by the sink
flags: readable
Unsigned Integer. Range: 0 - 4294967295 Default: 0
frames-rendered : Number of frames rendered
flags: readable
Unsigned Integer. Range: 0 - 4294967295 Default: 0
silent : Don't produce last_message events
flags: readable, writable
Boolean. Default: false
last-message : The message describing current status
flags: readable
String. Default: null
Element Signals:
"fps-measurements" : void user_function (GstElement* object,
gdouble arg0,
gdouble arg1,
gdouble arg2,
gpointer user_data);
Disabling frame synchronisation
The GStreamer frame dropping mechanism (due to frame lateness) can be disabled using option "sync=false" applied on the video sink.
When frame dropping is disabled, all frames received by the video sink are sent to the display subsystem without any timestamp check.
In this case, the maximum framerate sustainable by the system can be reached.
Here are some typical GStreamer pipelines where video frame synchronization has been disabled:
Board $> gst-play-1.0 --videosink="autovideosink sync=false"
Board $> gst-play-1.0 --videosink="waylandsink sync=false"
Board $> gst-launch-1.0 playbin ... video-sink="waylandsink sync=false"
Board $> gst-launch-1.0 filesrc ... ! waylandsink sync=false
Board $> gst-launch-1.0 filesrc ... ! kmsssink sync=false
Using fpsdisplaysink with "sync=false" option allows to get the maximum sustainable framerate value.
Here is an example:
Board $> gst-launch-1.0 videotestsrc ! "video/x-raw, width=640, height=480, framerate=(fraction)100/1" ! fpsdisplaysink sync=false video-sink="autovideosink" -v
/GstPipeline:pipeline0/GstFPSDisplaySink:fpsdisplaysink0/GstTextOverlay:fps-display-text-overlay: text = rendered: 51, dropped: 0, current: 22.33, average: 24.67 /GstPipeline:pipeline0/GstFPSDisplaySink:fpsdisplaysink0: last-message = rendered: 51, dropped: 0, current: 22.33, average: 24.67 /GstPipeline:pipeline0/GstFPSDisplaySink:fpsdisplaysink0/GstTextOverlay:fps-display-text-overlay: text = rendered: 63, dropped: 0, current: 22.83, average: 24.30 /GstPipeline:pipeline0/GstFPSDisplaySink:fpsdisplaysink0: last-message = rendered: 63, dropped: 0, current: 22.83, average: 24.30 /GstPipeline:pipeline0/GstFPSDisplaySink:fpsdisplaysink0/GstTextOverlay:fps-display-text-overlay: text = rendered: 75, dropped: 0, current: 22.93, average: 24.07 /GstPipeline:pipeline0/GstFPSDisplaySink:fpsdisplaysink0: last-message = rendered: 75, dropped: 0, current: 22.93, average: 24.07
In the above example, the maximum framerate is around 23fps while target is 100fps.
<securetransclude src="ProtectedTemplate:PublicationRequestId" params="9900 | 2018-12-04 | BrunoB"></securetransclude>
