userspace_debugging_guide.rst 10 KB

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