docs/release/userguide/Ftrace.debugging.tool.userguide.rst

   1 .. This work is licensed under a Creative Commons Attribution 4.0 International License.
   2
   3 .. http://creativecommons.org/licenses/by/4.0
   4
   5 =====================
   6 FTrace Debugging Tool
   7 =====================
   8
   9 About Ftrace
  10 -------------
  11 Ftrace is an internal tracer designed to find what is going on inside the kernel. It can be used
  12 for debugging or analyzing latencies and performance related issues that take place outside of
  13 user-space. Although ftrace is typically considered the function tracer, it is really a frame
  14 work of several assorted tracing utilities.
  15
  16     One of the most common uses of ftrace is the event tracing.
  17
  18 **Note:**
  19 - For KVM4NFV, Ftrace is preferred as it is in-built kernel tool
  20 - More stable compared to other debugging tools
  21
  22 Version Features
  23 ----------------
  24
  25 +-----------------------------+-----------------------------------------------+
  26 |                             |                                               |
  27 |      **Release**            |               **Features**                    |
  28 |                             |                                               |
  29 +=============================+===============================================+
  30 |                             | - Ftrace Debugging tool is not implemented in |
  31 |       Colorado              |   Colorado release of KVM4NFV                 |
  32 |                             |                                               |
  33 +-----------------------------+-----------------------------------------------+
  34 |                             | - Ftrace aids in debugging the KVM4NFV        |
  35 |       Danube                |   4.4-linux-kernel level issues               |
  36 |                             | - Option to disable if not required           |
  37 +-----------------------------+-----------------------------------------------+
  38 |                             | - Breaktrace option is implemented.           |
  39 |       Euphrates             | - Implemented post-execute script option to   |
  40 |                             |   disable the ftrace when it is enabled.      |
  41 +-----------------------------+-----------------------------------------------+
  42
  43
  44 Implementation of Ftrace
  45 -------------------------
  46 Ftrace uses the debugfs file system to hold the control files as
  47 well as the files to display output.
  48
  49 When debugfs is configured into the kernel (which selecting any ftrace
  50 option will do) the directory /sys/kernel/debug will be created. To mount
  51 this directory, you can add to your /etc/fstab file:
  52
  53 .. code:: bash
  54
  55  debugfs       /sys/kernel/debug          debugfs defaults        0       0
  56
  57 Or you can mount it at run time with:
  58
  59 .. code:: bash
  60
  61  mount -t debugfs nodev /sys/kernel/debug
  62
  63 Some configurations for Ftrace are used for other purposes, like finding latency or analyzing the
  64 system. For the purpose of debugging, the kernel configuration parameters that should be enabled are:
  65
  66 .. code:: bash
  67
  68     CONFIG_FUNCTION_TRACER=y
  69     CONFIG_FUNCTION_GRAPH_TRACER=y
  70     CONFIG_STACK_TRACER=y
  71     CONFIG_DYNAMIC_FTRACE=y
  72
  73 The above parameters must be enabled in /boot/config-4.4.0-el7.x86_64 i.e., kernel config file for
  74 ftrace to work. If not enabled, change the parameter to ``y`` and run.,
  75
  76 .. code:: bash
  77
  78     On CentOS
  79     grub2-mkconfig -o /boot/grub2/grub.cfg
  80     sudo reboot
  81
  82 Re-check the parameters after reboot before running ftrace.
  83
  84 Files in Ftrace:
  85 ----------------
  86 The below is a list of few major files in Ftrace.
  87
  88   ``current_tracer:``
  89
  90         This is used to set or display the current tracer that is configured.
  91
  92   ``available_tracers:``
  93
  94         This holds the different types of tracers that have been compiled into the kernel.
  95         The tracers listed here can be configured by echoing their name into current_tracer.
  96
  97   ``tracing_on:``
  98
  99         This sets or displays whether writing to the tracering buffer is enabled. Echo 0 into this
 100         file to disable the tracer or 1 to enable it.
 101
 102   ``trace:``
 103
 104         This file holds the output of the trace in a human readable format.
 105
 106   ``tracing_cpumask:``
 107
 108         This is a mask that lets the user only trace on specified CPUs. The format is a hex string
 109         representing the CPUs.
 110
 111   ``events:``
 112
 113         It holds event tracepoints (also known as static tracepoints) that have been compiled into
 114         the kernel. It shows what event tracepoints exist and how they are grouped by system.
 115
 116
 117 Avaliable Tracers
 118 -----------------
 119
 120 Here is the list of current tracers that may be configured based on usage.
 121
 122 - function
 123 - function_graph
 124 - irqsoff
 125 - preemptoff
 126 - preemptirqsoff
 127 - wakeup
 128 - wakeup_rt
 129
 130 Brief about a few:
 131
 132   ``function:``
 133
 134         Function call tracer to trace all kernel functions.
 135
 136   ``function_graph:``
 137
 138         Similar to the function tracer except that the function tracer probes the functions on their
 139         entry whereas the function graph tracer traces on both entry and exit of the functions.
 140
 141   ``nop:``
 142
 143         This is the "trace nothing" tracer. To remove tracers from tracing simply echo "nop" into
 144         current_tracer.
 145
 146 Examples:
 147
 148 .. code:: bash
 149
 150
 151      To list available tracers:
 152      [tracing]# cat available_tracers
 153      function_graph function wakeup wakeup_rt preemptoff irqsoff preemptirqsoff nop
 154
 155      Usage:
 156      [tracing]# echo function > current_tracer
 157      [tracing]# cat current_tracer
 158      function
 159
 160      To view output:
 161      [tracing]# cat trace | head -10
 162
 163      To Stop tracing:
 164      [tracing]# echo 0 > tracing_on
 165
 166      To Start/restart tracing:
 167      [tracing]# echo 1 > tracing_on;
 168
 169
 170 Ftrace in KVM4NFV
 171 -----------------
 172 Ftrace is part of KVM4NFV D-Release. KVM4NFV built 4.4-linux-Kernel will be tested by
 173 executing cyclictest and analyzing the results/latency values (max, min, avg) generated.
 174 Ftrace (or) function tracer is a stable kernel inbuilt debugging tool which tests real time
 175 kernel and outputs a log as part of the code. These output logs are useful in following ways.
 176
 177     - Kernel Debugging.
 178     - Helps in Kernel code optimization and
 179     - Can be used to better understand the kernel level code flow
 180
 181 Ftrace logs for KVM4NFV can be found `here`_:
 182
 183
 184 .. _here: http://artifacts.opnfv.org/kvmfornfv.html
 185
 186 Ftrace Usage in KVM4NFV Kernel Debugging:
 187 -----------------------------------------
 188 Kvm4nfv has two scripts in /ci/envs to provide ftrace tool:
 189
 190     - enable_trace.sh
 191     - disable_trace.sh
 192
 193 .. code:: bash
 194
 195     Found at.,
 196     $ cd kvmfornfv/ci/envs
 197
 198 Enabling Ftrace in KVM4NFV
 199 --------------------------
 200
 201 The enable_trace.sh script is triggered by changing ftrace_enable value in test_kvmfornfv.sh
 202 script to 1 (which is zero by default). Change as below to enable Ftrace.
 203
 204 .. code:: bash
 205
 206     ftrace_enable=1
 207
 208 Note:
 209
 210 - Ftrace is enabled before
 211
 212 Details of enable_trace script
 213 ------------------------------
 214
 215 - CPU coremask is calculated using getcpumask()
 216 - All the required events are enabled by,
 217    echoing "1" to $TRACEDIR/events/event_name/enable file
 218
 219 Example,
 220
 221 .. code:: bash
 222
 223    $TRACEDIR = /sys/kernel/debug/tracing/
 224    sudo bash -c "echo 1 > $TRACEDIR/events/irq/enable"
 225    sudo bash -c "echo 1 > $TRACEDIR/events/task/enable"
 226    sudo bash -c "echo 1 > $TRACEDIR/events/syscalls/enable"
 227
 228 The set_event file contains all the enabled events list
 229
 230 - Function tracer is selected. May be changed to other avaliable tracers based on requirement
 231
 232 .. code:: bash
 233
 234    sudo bash -c "echo function > $TRACEDIR/current_tracer
 235
 236 - When tracing is turned ON by setting ``tracing_on=1``,  the ``trace`` file keeps getting append
 237 with the traced data until ``tracing_on=0`` and then ftrace_buffer gets cleared.
 238
 239 .. code:: bash
 240
 241     To Stop/Pause,
 242     echo 0 >tracing_on;
 243
 244     To Start/Restart,
 245     echo 1 >tracing_on;
 246
 247 - Once tracing is disabled, disable_trace.sh script is triggered.
 248
 249 BREAKTRACE
 250 ----------
 251 - Send break trace command when latency > USEC. This is a debugging option to control the latency
 252 tracer in the realtime preemption patch. It is useful to track down unexpected large latencies on a
 253 system. This option does only work with following kernel config options.
 254
 255 For kernel < 2.6.24:
 256 * CONFIG_PREEMPT_RT=y
 257 * CONFIG_WAKEUP_TIMING=y
 258 * CONFIG_LATENCY_TRACE=y
 259 * CONFIG_CRITICAL_PREEMPT_TIMING=y
 260 * CONFIG_CRITICAL_IRQSOFF_TIMING=y
 261
 262 For kernel >= 2.6.24:
 263 * CONFIG_PREEMPT_RT=y
 264 * CONFIG_FTRACE
 265 * CONFIG_IRQSOFF_TRACER=y
 266 * CONFIG_PREEMPT_TRACER=y
 267 * CONFIG_SCHED_TRACER=y
 268 * CONFIG_WAKEUP_LATENCY_HIST
 269
 270 - Kernel configuration options enabled. The USEC parameter to the -b option defines a maximum
 271 latency value, which is compared against the actual latencies of the test. Once the measured latency
 272 is higher than the given maximum, the kernel tracer and cyclictest is stopped. The trace can be read
 273 from /proc/latency_trace. Please be aware that the tracer adds significant overhead to the kernel,
 274 so the latencies will be much higher than on a kernel with latency tracing disabled.
 275
 276 - Breaktrace option will enable the trace by default, suppress the tracing by using --notrace option.
 277
 278 Post-execute scripts
 279 --------------------
 280 post-execute script to yardstick node context teardown is added to disable the ftrace soon after the
 281 completion of cyclictest execution throughyardstick. This option is implemented to collect only
 282 required ftrace logs for effective debugging if needed.
 283
 284 Details of disable_trace Script
 285 -------------------------------
 286 In disable trace script the following are done:
 287
 288 - The trace file is copied and moved to /tmp folder based on timestamp
 289 - The current tracer file is set to ``nop``
 290 - The set_event file is cleared i.e., all the enabled events are disabled
 291 - Kernel Ftrace is disabled/unmounted
 292
 293
 294 Publishing Ftrace logs:
 295 -----------------------
 296 The generated trace log is pushed to `artifacts`_ by kvmfornfv-upload-artifact.sh
 297 script available in releng which will be triggered as a part of kvm4nfv daily job.
 298 The `trigger`_ in the script is.,
 299
 300 .. code:: bash
 301
 302    echo "Uploading artifacts for future debugging needs...."
 303    gsutil cp -r $WORKSPACE/build_output/log-*.tar.gz $GS_LOG_LOCATION > $WORKSPACE/gsutil.log 2>&1
 304
 305 .. _artifacts: https://artifacts.opnfv.org/
 306
 307 .. _trigger: https://gerrit.opnfv.org/gerrit/gitweb?p=releng.git;a=blob;f=jjb/kvmfornfv/kvmfornfv-upload-artifact.sh;h=56fb4f9c18a83c689a916dc6c85f9e3ddf2479b2;hb=HEAD#l53