On Wed, 23 Oct 2024 at 13:37, Hans Verkuil <hverkuil-cisco@xxxxxxxxx> wrote:
>
> On 23/10/2024 14:29, Laurent Pinchart wrote:
> > On Wed, Oct 23, 2024 at 01:43:34PM +0200, Hans Verkuil wrote:
> >> On 24/09/2024 10:45, Sebastian Fricke 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@xxxxxxxxxxxxx>
> >>> ---
> >>> 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 */
> >>> +
> >>> +DebugFS
> >>> +-------
> >>> +
> >>> +For general advice see the `driver-development-debugging-guide <../../debugging/driver_development_debugging_guide.html>`__.
> >>> +
> >>> +Perf & alternatives
> >>> +-------------------
> >>> +
> >>> +For general advice see the `userspace-debugging-guide <../../debugging/userspace_debugging_guide.html>`__.
> >>> +
> >>> +Example for media devices:
> >>> +
> >>> +Gather statistics data for a decoding job: (This example is on a RK3399 SoC with the rkvdec codec driver using the `fluster test suite <https://github.com/fluendo/fluster>`__)
> >>> +::
> >>> +
> >>> + perf stat -d python3 fluster.py run -d GStreamer-H.264-V4L2SL-Gst1.0 -ts JVT-AVC_V1 -tv AUD_MW_E -j1
> >>> + ...
> >>> + Performance counter stats for 'python3 fluster.py run -d GStreamer-H.264-V4L2SL-Gst1.0 -ts JVT-AVC_V1 -tv AUD_MW_E -j1 -v':
> >>> +
> >>> + 7794.23 msec task-clock:u # 0.697 CPUs utilized
> >>> + 0 context-switches:u # 0.000 /sec
> >>> + 0 cpu-migrations:u # 0.000 /sec
> >>> + 11901 page-faults:u # 1.527 K/sec
> >>> + 882671556 cycles:u # 0.113 GHz (95.79%)
> >>> + 711708695 instructions:u # 0.81 insn per cycle (95.79%)
> >>> + 10581935 branches:u # 1.358 M/sec (15.13%)
> >>> + 6871144 branch-misses:u # 64.93% of all branches (95.79%)
> >>> + 281716547 L1-dcache-loads:u # 36.144 M/sec (95.79%)
> >>> + 9019581 L1-dcache-load-misses:u # 3.20% of all L1-dcache accesses (95.79%)
> >>> + <not supported> LLC-loads:u
> >>> + <not supported> LLC-load-misses:u
> >>> +
> >>> + 11.180830431 seconds time elapsed
> >>> +
> >>> + 1.502318000 seconds user
> >>> + 6.377221000 seconds sys
> >>> +
> >>> +The availability of events and metrics depends on the system you are running.
> >>> +
> >>> +Error checking & panic analysis
> >>> +-------------------------------
> >>> +
> >>> +For general advice see the `driver-development-debugging-guide <../../debugging/driver_development_debugging_guide.html>`__.
> >>> +
> >>> +**Copyright** |copy| 2024 : Collabora
> >>
> >> I would add a few more:
> >>
> >> - Implementing vidioc_log_status in the driver: this can log the current status to the kernel log.
> >> It's called by v4l2-ctl --log-status. Very useful for debugging problems with receiving video
> >> (TV/S-Video/HDMI/etc) since the video signal is external (so unpredictable). Less useful with
> >> camera sensor inputs since you have control over what the camera sensor does.
> >
> > To avoid unnecessary complexity in drivers, should we encourage
> > implementing log_status for receivers but discourage it for camera
> > sensors ? I haven't seen many people attempting to do so, but I have
> > pushed back against the debug read/write register ops in sensor drivers.
>
> I'm fine with that.
>
> Logging the current status is particularly useful if you have no control over
> what you receive, so anything can happen. But for camera sensors it is typically
> not needed.
>
> The register debug ops I haven't used in a very long time, and I wonder if it
> shouldn't be deprecated.
For most things I'll agree that you can use "i2ctransfer -f" to send
I2C commands independent of the driver, so implementing it has limited
gain.
However with adv7180 (and potentially others) the driver caches a page
register for accessing different pages of registers.
