Re: [PATCH RFC v2 3/3] docs: media: Debugging guide for the media subsystem

[Daniel Almeida <daniel.almeida@collabora.com>]

Hi Sebastian,

> On 24 Sep 2024, at 05:45, Sebastian Fricke <sebastian.fricke@collabora.com> wrote:
> 
> Create a guides section for all documentation material, that isn't
> strictly related to a specific piece of code.
> 
> Provide a guide for developers on how to debug code with a focus on the
> media subsystem. This document aims to provide a rough overview over the
> possibilities and a rational to help choosing the right tool for the
> given circumstances.
> 
> Signed-off-by: Sebastian Fricke <sebastian.fricke@collabora.com>
> ---
> Documentation/media/guides/debugging_issues.rst | 174 ++++++++++++++++++++++++
> Documentation/media/guides/index.rst            |  11 ++
> Documentation/media/index.rst                   |   1 +
> 3 files changed, 186 insertions(+)
> 
> diff --git a/Documentation/media/guides/debugging_issues.rst b/Documentation/media/guides/debugging_issues.rst
> new file mode 100644
> index 000000000000..5f37801dd4ba
> --- /dev/null
> +++ b/Documentation/media/guides/debugging_issues.rst
> @@ -0,0 +1,174 @@
> +.. SPDX-License-Identifier: GPL-2.0
> +.. include:: <isonum.txt>
> +
> +============================================
> +Debugging and tracing in the media subsystem
> +============================================
> +
> +This document serves as a starting point and lookup for debugging device
> +drivers in the media subsystem.
> +
> +.. contents::
> +    :depth: 3
> +
> +General debugging advice
> +========================
> +
> +For general advice see the `general-debugging-guide <../../debugging/index.html>`__.
> +
> +Available tools
> +===============
> +
> +dev_debug module parameter
> +--------------------------
> +
> +For a general overview please see the `driver-development-debugging-guide <../../debugging/driver_development_debugging_guide.html>`__.
> +
> +Every video device provides a `dev_debug` parameter, which allows to get further insights into the IOCTLs in the background.
> +::
> +
> +  # cat /sys/class/video4linux/video3/name
> +  rkvdec
> +  # echo 0xff > /sys/class/video4linux/video3/dev_debug
> +  # dmesg -wH
> +  [...] videodev: v4l2_open: video3: open (0)
> +  [  +0.000036] video3: VIDIOC_QUERYCAP: driver=rkvdec, card=rkvdec, bus=platform:rkvdec, version=0x00060900, capabilities=0x84204000, device_caps=0x04204000
> +
> +`Full documentation <../../driver-api/media/v4l2-dev.html#video-device-debugging>`__
> +
> +dev_dbg / v4l2_dbg
> +------------------
> +
> +- Difference between both?
> +
> +  - v4l2_dbg utilizes v4l2_printk under the hood, which further uses printk directly, thus it cannot be targeted by dynamic debug
> +  - dev_dbg can be targeted by dynamic debug
> +  - v4l2_dbg has a more specific prefix format for the media subsystem, while dev_dbg only highlights the driver name and the location of the log
> +
> +Dynamic debug
> +-------------
> +
> +For general advice see the `userspace-debugging-guide <../../debugging/userspace_debugging_guide.html>`__.
> +
> +Here is one example, that enables all available `pr_debug()`'s within the file:
> +::
> +
> +  $ alias ddcmd='echo $* > /proc/dynamic_debug/control'
> +  $ ddcmd '-p; file v4l2-h264.c +p'
> +  $ grep =p /proc/dynamic_debug/control
> +   drivers/media/v4l2-core/v4l2-h264.c:372 [v4l2_h264]print_ref_list_b =p "ref_pic_list_b%u (cur_poc %u%c) %s"
> +   drivers/media/v4l2-core/v4l2-h264.c:333 [v4l2_h264]print_ref_list_p =p "ref_pic_list_p (cur_poc %u%c) %s\n"
> +
> +Ftrace
> +------
> +
> +For general advice see the `userspace-debugging-guide <../../debugging/userspace_debugging_guide.html>`__.
> +
> +Trace whenever the `rkvdec_try_ctrl` function is called
> +::
> +
> +  $ cd /sys/kernel/tracing
> +  $ echo function > /sys/kernel/tracing/current_tracer
> +  $ echo rkvdec_try_ctrl > set_ftrace_filter
> +  $ echo 1 > tracing_on
> +  $ cat trace
> +   h264parse0:sink-6359    [001] ...1. 172714.547523: rkvdec_try_ctrl <-try_or_set_cluster
> +   h264parse0:sink-6359    [005] ...1. 172714.567386: rkvdec_try_ctrl <-try_or_set_cluster
> +
> +Find out from where the calls originate
> +::
> +
> +  $ echo 1 > options/func_stack_trace
> +   h264parse0:sink-6715    [002] ..... 172837.967762: rkvdec_try_ctrl <-try_or_set_cluster
> +   h264parse0:sink-6715    [002] ..... 172837.967773: <stack trace>
> +   => rkvdec_try_ctrl
> +   => try_or_set_cluster
> +   => try_set_ext_ctrls_common
> +   => try_set_ext_ctrls
> +   => v4l2_s_ext_ctrls
> +   => v4l_s_ext_ctrls
> +   ...
> +   h264parse0:sink-6715    [004] ..... 172837.985747: rkvdec_try_ctrl <-try_or_set_cluster
> +   h264parse0:sink-6715    [004] ..... 172837.985750: <stack trace>
> +   => rkvdec_try_ctrl
> +   => try_or_set_cluster
> +   => v4l2_ctrl_request_setup
> +   => rkvdec_run_preamble
> +   => rkvdec_h264_run
> +   => rkvdec_device_run
> +   ...
> +
> +Trace the children of a function call and show the return values (requires config `FUNCTION_GRAPH_RETVAL`)
> +::
> +
> +  echo function_graph > current_tracer
> +  echo rkvdec_h264_run > set_graph_function
> +  echo 4 > max_graph_depth
> +  echo do_interrupt_handler mutex_* > set_graph_notrace
> +  echo 1 > options/funcgraph-retval
> +   ...
> +   4)               |  rkvdec_h264_run [rockchip_vdec]() {
> +   4)               |    v4l2_ctrl_find [videodev]() {
> +   ...
> +   4)               |    rkvdec_run_preamble [rockchip_vdec]() {
> +   4)   4.666 us    |      v4l2_m2m_next_buf [v4l2_mem2mem](); /* = 0xffff000005782000 */
> +   ...
> +   4)               |      v4l2_ctrl_request_setup [videodev]() {
> +   4)   4.667 us    |        media_request_object_find [mc](); /* = 0xffff000005e3aa98 */
> +   4)   1.750 us    |        find_ref [videodev](); /* = 0xffff00000833b2a0 */
> +   ...
> +   4)   1.750 us    |      v4l2_m2m_buf_copy_metadata [v4l2_mem2mem](); /* = 0x0 */
> +   4) ! 114.333 us  |    } /* rkvdec_run_preamble [rockchip_vdec] = 0x0 */
> +   4)   2.334 us    |    v4l2_h264_init_reflist_builder [v4l2_h264](); /* = 0x3e */
> +   ...
> +   4)               |    v4l2_h264_build_b_ref_lists [v4l2_h264]() {
> +   ...
> +   4)               |    rkvdec_run_postamble [rockchip_vdec]() {
> +   ...
> +   4) ! 444.208 us  |  } /* rkvdec_h264_run [rockchip_vdec] = 0x0 */

Maybe have a look at retsnoop? 

To me, a very frustrating and very common issue is having to figure out where
exactly an error code was generated. Ftrace helps a great deal, but I feel that
retsnoop just takes it a step further. On top of that, you can retrace the
execution on a statement level.  

That is, with the right options, it can tell you exactly what statements
executed, which then lets you get very precise without any extra prints.

See [0]. There’s a talk on KR2024 about it too [1].


[0]: https://github.com/anakryiko/retsnoop

[1]: https://www.youtube.com/watch?v=NvTBrx6EdF8 

— Daniel