1*a037699dSSebastian Fricke.. SPDX-License-Identifier: GPL-2.0 2*a037699dSSebastian Fricke 3*a037699dSSebastian Fricke========================== 4*a037699dSSebastian FrickeUserspace debugging advice 5*a037699dSSebastian Fricke========================== 6*a037699dSSebastian Fricke 7*a037699dSSebastian FrickeThis document provides a brief overview of common tools to debug the Linux 8*a037699dSSebastian FrickeKernel from userspace. 9*a037699dSSebastian FrickeFor debugging advice aimed at driver developers go :doc:`here 10*a037699dSSebastian Fricke</process/debugging/driver_development_debugging_guide>`. 11*a037699dSSebastian FrickeFor general debugging advice, see :doc:`general advice document 12*a037699dSSebastian Fricke</process/debugging/index>`. 13*a037699dSSebastian Fricke 14*a037699dSSebastian Fricke.. contents:: 15*a037699dSSebastian Fricke :depth: 3 16*a037699dSSebastian Fricke 17*a037699dSSebastian FrickeThe following sections show you the available tools. 18*a037699dSSebastian Fricke 19*a037699dSSebastian FrickeDynamic debug 20*a037699dSSebastian Fricke------------- 21*a037699dSSebastian Fricke 22*a037699dSSebastian FrickeMechanism to filter what ends up in the kernel log by dis-/en-abling log 23*a037699dSSebastian Frickemessages. 24*a037699dSSebastian Fricke 25*a037699dSSebastian FrickePrerequisite: ``CONFIG_DYNAMIC_DEBUG`` 26*a037699dSSebastian Fricke 27*a037699dSSebastian FrickeDynamic debug is only able to target: 28*a037699dSSebastian Fricke 29*a037699dSSebastian Fricke- pr_debug() 30*a037699dSSebastian Fricke- dev_dbg() 31*a037699dSSebastian Fricke- print_hex_dump_debug() 32*a037699dSSebastian Fricke- print_hex_dump_bytes() 33*a037699dSSebastian Fricke 34*a037699dSSebastian FrickeTherefore the usability of this tool is, as of now, quite limited as there is 35*a037699dSSebastian Frickeno uniform rule for adding debug prints to the codebase, resulting in a variety 36*a037699dSSebastian Frickeof ways these prints are implemented. 37*a037699dSSebastian Fricke 38*a037699dSSebastian FrickeAlso, note that most debug statements are implemented as a variation of 39*a037699dSSebastian Frickedprintk(), which have to be activated via a parameter in respective module, 40*a037699dSSebastian Frickedynamic debug is unable to do that step for you. 41*a037699dSSebastian Fricke 42*a037699dSSebastian FrickeHere is one example, that enables all available pr_debug()'s within the file:: 43*a037699dSSebastian Fricke 44*a037699dSSebastian Fricke $ alias ddcmd='echo $* > /proc/dynamic_debug/control' 45*a037699dSSebastian Fricke $ ddcmd '-p; file v4l2-h264.c +p' 46*a037699dSSebastian Fricke $ grep =p /proc/dynamic_debug/control 47*a037699dSSebastian Fricke drivers/media/v4l2-core/v4l2-h264.c:372 [v4l2_h264]print_ref_list_b =p 48*a037699dSSebastian Fricke "ref_pic_list_b%u (cur_poc %u%c) %s" 49*a037699dSSebastian Fricke drivers/media/v4l2-core/v4l2-h264.c:333 [v4l2_h264]print_ref_list_p =p 50*a037699dSSebastian Fricke "ref_pic_list_p (cur_poc %u%c) %s\n" 51*a037699dSSebastian Fricke 52*a037699dSSebastian Fricke**When should you use this over Ftrace ?** 53*a037699dSSebastian Fricke 54*a037699dSSebastian Fricke- When the code contains one of the valid print statements (see above) or when 55*a037699dSSebastian Fricke you have added multiple pr_debug() statements during development 56*a037699dSSebastian Fricke- When timing is not an issue, meaning if multiple pr_debug() statements in 57*a037699dSSebastian Fricke the code won't cause delays 58*a037699dSSebastian Fricke- When you care more about receiving specific log messages than tracing the 59*a037699dSSebastian Fricke pattern of how a function is called 60*a037699dSSebastian Fricke 61*a037699dSSebastian FrickeFor the full documentation see :doc:`/admin-guide/dynamic-debug-howto` 62*a037699dSSebastian Fricke 63*a037699dSSebastian FrickeFtrace 64*a037699dSSebastian Fricke------ 65*a037699dSSebastian Fricke 66*a037699dSSebastian FrickePrerequisite: ``CONFIG_DYNAMIC_FTRACE`` 67*a037699dSSebastian Fricke 68*a037699dSSebastian FrickeThis tool uses the tracefs file system for the control files and output files. 69*a037699dSSebastian FrickeThat file system will be mounted as a ``tracing`` directory, which can be found 70*a037699dSSebastian Frickein either ``/sys/kernel/`` or ``/sys/debug/kernel/``. 71*a037699dSSebastian Fricke 72*a037699dSSebastian FrickeSome of the most important operations for debugging are: 73*a037699dSSebastian Fricke 74*a037699dSSebastian Fricke- You can perform a function trace by adding a function name to the 75*a037699dSSebastian Fricke ``set_ftrace_filter`` file (which accepts any function name found within the 76*a037699dSSebastian Fricke ``available_filter_functions`` file) or you can specifically disable certain 77*a037699dSSebastian Fricke functions by adding their names to the ``set_ftrace_notrace`` file (more info 78*a037699dSSebastian Fricke at: :ref:`trace/ftrace:dynamic ftrace`). 79*a037699dSSebastian Fricke- In order to find out where calls originate from you can activate the 80*a037699dSSebastian Fricke ``func_stack_trace`` option under ``options/func_stack_trace``. 81*a037699dSSebastian Fricke- Tracing the children of a function call and showing the return values are 82*a037699dSSebastian Fricke possible by adding the desired function in the ``set_graph_function`` file 83*a037699dSSebastian Fricke (requires config ``FUNCTION_GRAPH_RETVAL``); more info at 84*a037699dSSebastian Fricke :ref:`trace/ftrace:dynamic ftrace with the function graph tracer`. 85*a037699dSSebastian Fricke 86*a037699dSSebastian FrickeFor the full Ftrace documentation see :doc:`/trace/ftrace` 87*a037699dSSebastian Fricke 88*a037699dSSebastian FrickeOr you could also trace for specific events by :ref:`using event tracing 89*a037699dSSebastian Fricke<trace/events:2. using event tracing>`, which can be defined as described here: 90*a037699dSSebastian Fricke:ref:`Creating a custom Ftrace tracepoint 91*a037699dSSebastian Fricke<process/debugging/driver_development_debugging_guide:ftrace>`. 92*a037699dSSebastian Fricke 93*a037699dSSebastian FrickeFor the full Ftrace event tracing documentation see :doc:`/trace/events` 94*a037699dSSebastian Fricke 95*a037699dSSebastian Fricke.. _read_ftrace_log: 96*a037699dSSebastian Fricke 97*a037699dSSebastian FrickeReading the ftrace log 98*a037699dSSebastian Fricke~~~~~~~~~~~~~~~~~~~~~~ 99*a037699dSSebastian Fricke 100*a037699dSSebastian FrickeThe ``trace`` file can be read just like any other file (``cat``, ``tail``, 101*a037699dSSebastian Fricke``head``, ``vim``, etc.), the size of the file is limited by the 102*a037699dSSebastian Fricke``buffer_size_kb`` (``echo 1000 > buffer_size_kb``). The 103*a037699dSSebastian Fricke:ref:`trace/ftrace:trace_pipe` will behave similarly to the ``trace`` file, but 104*a037699dSSebastian Frickewhenever you read from the file the content is consumed. 105*a037699dSSebastian Fricke 106*a037699dSSebastian FrickeKernelshark 107*a037699dSSebastian Fricke~~~~~~~~~~~ 108*a037699dSSebastian Fricke 109*a037699dSSebastian FrickeA GUI interface to visualize the traces as a graph and list view from the 110*a037699dSSebastian Frickeoutput of the `trace-cmd 111*a037699dSSebastian Fricke<https://git.kernel.org/pub/scm/utils/trace-cmd/trace-cmd.git/>`__ application. 112*a037699dSSebastian Fricke 113*a037699dSSebastian FrickeFor the full documentation see `<https://kernelshark.org/Documentation.html>`__ 114*a037699dSSebastian Fricke 115*a037699dSSebastian FrickePerf & alternatives 116*a037699dSSebastian Fricke------------------- 117*a037699dSSebastian Fricke 118*a037699dSSebastian FrickeThe tools mentioned above provide ways to inspect kernel code, results, 119*a037699dSSebastian Frickevariable values, etc. Sometimes you have to find out first where to look and 120*a037699dSSebastian Frickefor those cases, a box of performance tracking tools can help you to frame the 121*a037699dSSebastian Frickeissue. 122*a037699dSSebastian Fricke 123*a037699dSSebastian FrickeWhy should you do a performance analysis? 124*a037699dSSebastian Fricke~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~ 125*a037699dSSebastian Fricke 126*a037699dSSebastian FrickeA performance analysis is a good first step when among other reasons: 127*a037699dSSebastian Fricke 128*a037699dSSebastian Fricke- you cannot define the issue 129*a037699dSSebastian Fricke- you do not know where it occurs 130*a037699dSSebastian Fricke- the running system should not be interrupted or it is a remote system, where 131*a037699dSSebastian Fricke you cannot install a new module/kernel 132*a037699dSSebastian Fricke 133*a037699dSSebastian FrickeHow to do a simple analysis with linux tools? 134*a037699dSSebastian Fricke~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~ 135*a037699dSSebastian Fricke 136*a037699dSSebastian FrickeFor the start of a performance analysis, you can start with the usual tools 137*a037699dSSebastian Frickelike: 138*a037699dSSebastian Fricke 139*a037699dSSebastian Fricke- ``top`` / ``htop`` / ``atop`` (*get an overview of the system load, see 140*a037699dSSebastian Fricke spikes on specific processes*) 141*a037699dSSebastian Fricke- ``mpstat -P ALL`` (*look at the load distribution among CPUs*) 142*a037699dSSebastian Fricke- ``iostat -x`` (*observe input and output devices utilization and performance*) 143*a037699dSSebastian Fricke- ``vmstat`` (*overview of memory usage on the system*) 144*a037699dSSebastian Fricke- ``pidstat`` (*similar to* ``vmstat`` *but per process, to dial it down to the 145*a037699dSSebastian Fricke target*) 146*a037699dSSebastian Fricke- ``strace -tp $PID`` (*once you know the process, you can figure out how it 147*a037699dSSebastian Fricke communicates with the Kernel*) 148*a037699dSSebastian Fricke 149*a037699dSSebastian FrickeThese should help to narrow down the areas to look at sufficiently. 150*a037699dSSebastian Fricke 151*a037699dSSebastian FrickeDiving deeper with perf 152*a037699dSSebastian Fricke~~~~~~~~~~~~~~~~~~~~~~~ 153*a037699dSSebastian Fricke 154*a037699dSSebastian FrickeThe **perf** tool provides a series of metrics and events to further dial down 155*a037699dSSebastian Frickeon issues. 156*a037699dSSebastian Fricke 157*a037699dSSebastian FrickePrerequisite: build or install perf on your system 158*a037699dSSebastian Fricke 159*a037699dSSebastian FrickeGather statistics data for finding all files starting with ``gcc`` in ``/usr``:: 160*a037699dSSebastian Fricke 161*a037699dSSebastian Fricke # perf stat -d find /usr -name 'gcc*' | wc -l 162*a037699dSSebastian Fricke 163*a037699dSSebastian Fricke Performance counter stats for 'find /usr -name gcc*': 164*a037699dSSebastian Fricke 165*a037699dSSebastian Fricke 1277.81 msec task-clock # 0.997 CPUs utilized 166*a037699dSSebastian Fricke 9 context-switches # 7.043 /sec 167*a037699dSSebastian Fricke 1 cpu-migrations # 0.783 /sec 168*a037699dSSebastian Fricke 704 page-faults # 550.943 /sec 169*a037699dSSebastian Fricke 766548897 cycles # 0.600 GHz (97.15%) 170*a037699dSSebastian Fricke 798285467 instructions # 1.04 insn per cycle (97.15%) 171*a037699dSSebastian Fricke 57582731 branches # 45.064 M/sec (2.85%) 172*a037699dSSebastian Fricke 3842573 branch-misses # 6.67% of all branches (97.15%) 173*a037699dSSebastian Fricke 281616097 L1-dcache-loads # 220.390 M/sec (97.15%) 174*a037699dSSebastian Fricke 4220975 L1-dcache-load-misses # 1.50% of all L1-dcache accesses (97.15%) 175*a037699dSSebastian Fricke <not supported> LLC-loads 176*a037699dSSebastian Fricke <not supported> LLC-load-misses 177*a037699dSSebastian Fricke 178*a037699dSSebastian Fricke 1.281746009 seconds time elapsed 179*a037699dSSebastian Fricke 180*a037699dSSebastian Fricke 0.508796000 seconds user 181*a037699dSSebastian Fricke 0.773209000 seconds sys 182*a037699dSSebastian Fricke 183*a037699dSSebastian Fricke 184*a037699dSSebastian Fricke 52 185*a037699dSSebastian Fricke 186*a037699dSSebastian FrickeThe availability of events and metrics depends on the system you are running. 187*a037699dSSebastian Fricke 188*a037699dSSebastian FrickeFor the full documentation see 189*a037699dSSebastian Fricke`<https://perf.wiki.kernel.org/index.php/Main_Page>`__ 190*a037699dSSebastian Fricke 191*a037699dSSebastian FrickePerfetto 192*a037699dSSebastian Fricke~~~~~~~~ 193*a037699dSSebastian Fricke 194*a037699dSSebastian FrickeA set of tools to measure and analyze how well applications and systems perform. 195*a037699dSSebastian FrickeYou can use it to: 196*a037699dSSebastian Fricke 197*a037699dSSebastian Fricke* identify bottlenecks 198*a037699dSSebastian Fricke* optimize code 199*a037699dSSebastian Fricke* make software run faster and more efficiently. 200*a037699dSSebastian Fricke 201*a037699dSSebastian Fricke**What is the difference between perfetto and perf?** 202*a037699dSSebastian Fricke 203*a037699dSSebastian Fricke* perf is tool as part of and specialized for the Linux Kernel and has CLI user 204*a037699dSSebastian Fricke interface. 205*a037699dSSebastian Fricke* perfetto cross-platform performance analysis stack, has extended 206*a037699dSSebastian Fricke functionality into userspace and provides a WEB user interface. 207*a037699dSSebastian Fricke 208*a037699dSSebastian FrickeFor the full documentation see `<https://perfetto.dev/docs/>`__ 209*a037699dSSebastian Fricke 210*a037699dSSebastian FrickeKernel panic analysis tools 211*a037699dSSebastian Fricke--------------------------- 212*a037699dSSebastian Fricke 213*a037699dSSebastian Fricke To capture the crash dump please use ``Kdump`` & ``Kexec``. Below you can find 214*a037699dSSebastian Fricke some advice for analysing the data. 215*a037699dSSebastian Fricke 216*a037699dSSebastian Fricke For the full documentation see the :doc:`/admin-guide/kdump/kdump` 217*a037699dSSebastian Fricke 218*a037699dSSebastian Fricke In order to find the corresponding line in the code you can use `faddr2line 219*a037699dSSebastian Fricke <https://elixir.bootlin.com/linux/v6.11.6/source/scripts/faddr2line>`__; note 220*a037699dSSebastian Fricke that you need to enable ``CONFIG_DEBUG_INFO`` for that to work. 221*a037699dSSebastian Fricke 222*a037699dSSebastian Fricke An alternative to using ``faddr2line`` is the use of ``objdump`` (and its 223*a037699dSSebastian Fricke derivatives for the different platforms like ``aarch64-linux-gnu-objdump``). 224*a037699dSSebastian Fricke Take this line as an example: 225*a037699dSSebastian Fricke 226*a037699dSSebastian Fricke ``[ +0.000240] rkvdec_device_run+0x50/0x138 [rockchip_vdec]``. 227*a037699dSSebastian Fricke 228*a037699dSSebastian Fricke We can find the corresponding line of code by executing:: 229*a037699dSSebastian Fricke 230*a037699dSSebastian Fricke aarch64-linux-gnu-objdump -dS drivers/staging/media/rkvdec/rockchip-vdec.ko | grep rkvdec_device_run\>: -A 40 231*a037699dSSebastian Fricke 0000000000000ac8 <rkvdec_device_run>: 232*a037699dSSebastian Fricke ac8: d503201f nop 233*a037699dSSebastian Fricke acc: d503201f nop 234*a037699dSSebastian Fricke { 235*a037699dSSebastian Fricke ad0: d503233f paciasp 236*a037699dSSebastian Fricke ad4: a9bd7bfd stp x29, x30, [sp, #-48]! 237*a037699dSSebastian Fricke ad8: 910003fd mov x29, sp 238*a037699dSSebastian Fricke adc: a90153f3 stp x19, x20, [sp, #16] 239*a037699dSSebastian Fricke ae0: a9025bf5 stp x21, x22, [sp, #32] 240*a037699dSSebastian Fricke const struct rkvdec_coded_fmt_desc *desc = ctx->coded_fmt_desc; 241*a037699dSSebastian Fricke ae4: f9411814 ldr x20, [x0, #560] 242*a037699dSSebastian Fricke struct rkvdec_dev *rkvdec = ctx->dev; 243*a037699dSSebastian Fricke ae8: f9418015 ldr x21, [x0, #768] 244*a037699dSSebastian Fricke if (WARN_ON(!desc)) 245*a037699dSSebastian Fricke aec: b4000654 cbz x20, bb4 <rkvdec_device_run+0xec> 246*a037699dSSebastian Fricke ret = pm_runtime_resume_and_get(rkvdec->dev); 247*a037699dSSebastian Fricke af0: f943d2b6 ldr x22, [x21, #1952] 248*a037699dSSebastian Fricke ret = __pm_runtime_resume(dev, RPM_GET_PUT); 249*a037699dSSebastian Fricke af4: aa0003f3 mov x19, x0 250*a037699dSSebastian Fricke af8: 52800081 mov w1, #0x4 // #4 251*a037699dSSebastian Fricke afc: aa1603e0 mov x0, x22 252*a037699dSSebastian Fricke b00: 94000000 bl 0 <__pm_runtime_resume> 253*a037699dSSebastian Fricke if (ret < 0) { 254*a037699dSSebastian Fricke b04: 37f80340 tbnz w0, #31, b6c <rkvdec_device_run+0xa4> 255*a037699dSSebastian Fricke dev_warn(rkvdec->dev, "Not good\n"); 256*a037699dSSebastian Fricke b08: f943d2a0 ldr x0, [x21, #1952] 257*a037699dSSebastian Fricke b0c: 90000001 adrp x1, 0 <rkvdec_try_ctrl-0x8> 258*a037699dSSebastian Fricke b10: 91000021 add x1, x1, #0x0 259*a037699dSSebastian Fricke b14: 94000000 bl 0 <_dev_warn> 260*a037699dSSebastian Fricke *bad = 1; 261*a037699dSSebastian Fricke b18: d2800001 mov x1, #0x0 // #0 262*a037699dSSebastian Fricke ... 263*a037699dSSebastian Fricke 264*a037699dSSebastian Fricke Meaning, in this line from the crash dump:: 265*a037699dSSebastian Fricke 266*a037699dSSebastian Fricke [ +0.000240] rkvdec_device_run+0x50/0x138 [rockchip_vdec] 267*a037699dSSebastian Fricke 268*a037699dSSebastian Fricke I can take the ``0x50`` as offset, which I have to add to the base address 269*a037699dSSebastian Fricke of the corresponding function, which I find in this line:: 270*a037699dSSebastian Fricke 271*a037699dSSebastian Fricke 0000000000000ac8 <rkvdec_device_run>: 272*a037699dSSebastian Fricke 273*a037699dSSebastian Fricke The result of ``0xac8 + 0x50 = 0xb18`` 274*a037699dSSebastian Fricke And when I search for that address within the function I get the 275*a037699dSSebastian Fricke following line:: 276*a037699dSSebastian Fricke 277*a037699dSSebastian Fricke *bad = 1; 278*a037699dSSebastian Fricke b18: d2800001 mov x1, #0x0 279*a037699dSSebastian Fricke 280*a037699dSSebastian Fricke**Copyright** ©2024 : Collabora 281