How to display or retrieve ftrace data from the kernel crash dump?

Resolution

• If ftrace functionality was enabled on the system while collecting the kernel crash dump then the crash extension trace can be used to display or retrieve ftrace data from the kernel crash dump.

crash> help trace
NAME
  trace - show or dump the tracing info

SYNOPSIS
  trace [ <show [-c <cpulist>] [-f [no]<flagname>]> | <dump [-sm] <dest-dir>> ]

DESCRIPTION
trace
    shows the current tracer and other information.

trace show [ -c <cpulist> ] [ -f [no]<flagname> ]
    shows all events with readability text(sorted by timestamp)
    -c: only shows specified CPUs' events.
        ex. trace show -c 1,2    - only shows cpu#1 and cpu#2 's events.
            trace show -c 0,2-7  - only shows cpu#0, cpu#2...cpu#7's events.
    -f: set or clear a flag
        available flags            default
        context_info               true
        sym_offset                 false
        sym_addr                   false
        graph_print_duration       true
        graph_print_overhead       true
        graph_print_abstime        false
        graph_print_cpu            true
        graph_print_proc           false
        graph_print_overrun        false

trace dump [-sm] <dest-dir>
    dump ring_buffers to dest-dir. Then you can parse it
    by other tracing tools. The dirs and files are generated
    the same as debugfs/tracing.
    -m: also dump metadata of ftrace.
    -s: also dump symbols of the kernel <not implemented>.

Steps to display ftrace data from the kernel crash dump:

• Install the crash and crash-trace-command packages.

Eg:

# yum install crash crash-trace-command

• Determine the kernel version from the kernel crash dump.

Eg:

# crash --osrelease vmcore
4.18.0-32.el8.x86_64

• Install the corresponding kernel-debuginfo package of the kernel version from which the kernel crash dump was collected.

Eg:

# yum install kernel-debuginfo-4.18.0-32.el8.x86_64

• Open the kernel crash dump using the crash utility.

Eg:

# crash vmcore /usr/lib/debug/lib/modules/4.18.0-32.el8.x86_64/vmlinux

• Load the crash extension trace.so.

Eg:

crash> extend /usr/lib64/crash/extensions/trace.so
/usr/lib64/crash/extensions/trace.so: shared object loaded

crash> extend
SHARED OBJECT                         COMMANDS
/usr/lib64/crash/extensions/trace.so  trace 

• Check the current tracer.

Eg:

crash> trace
current tracer is function_graph

• Execute trace show or trace report command to show the tracing info of all cpu.

Eg:

crash> trace show   
...
cpus=4
                     <idle>-0     [001]   738.580871: funcgraph_exit:         0.059 us   |        }
                     <idle>-0     [001]   738.580871: funcgraph_exit:         5.112 us   |      }
                     <idle>-0     [001]   738.580871: funcgraph_entry:        0.106 us   |      tick_nohz_stop_tick();
                     <idle>-0     [001]   738.580872: funcgraph_exit:         6.666 us   |    }
                     <idle>-0     [001]   738.580872: funcgraph_entry:                   |    rcu_idle_enter() {
                     <idle>-0     [001]   738.580872: funcgraph_entry:        0.069 us   |      rcu_eqs_enter.constprop.61();
                     <idle>-0     [001]   738.580873: funcgraph_exit:         0.527 us   |    }
                     <idle>-0     [001]   738.580873: funcgraph_entry:                   |    default_idle_call() {
                     <idle>-0     [001]   738.580873: funcgraph_entry:                   |      arch_cpu_idle() {
                     <idle>-0     [001]   738.580874: funcgraph_entry:                   |        __cpuidle_text_start() {
                     <idle>-0     [001]   738.582813: funcgraph_entry:                   |          smp_reschedule_interrupt() {
                     <idle>-0     [001]   738.582814: funcgraph_entry:                   |            scheduler_ipi() {
                     <idle>-0     [001]   738.582814: funcgraph_entry:                   |              irq_enter() {
                     <idle>-0     [001]   738.582814: funcgraph_entry:                   |                rcu_irq_enter() {
                     <idle>-0     [001]   738.582815: funcgraph_entry:        0.057 us   |                  rcu_dynticks_eqs_exit();
                     <idle>-0     [001]   738.582815: funcgraph_exit:         0.644 us   |                }
                     <idle>-0     [001]   738.582815: funcgraph_entry:                   |                tick_irq_enter() {
                     <idle>-0     [001]   738.582816: funcgraph_entry:        0.067 us   |                  tick_check_oneshot_broadcast_this_cpu();
                     <idle>-0     [001]   738.582816: funcgraph_entry:        0.118 us   |                  ktime_get();
                     <idle>-0     [001]   738.582817: funcgraph_entry:                   |                  update_ts_time_stats() {
                     <idle>-0     [001]   738.582817: funcgraph_entry:        0.054 us   |                    nr_iowait_cpu();
                     <idle>-0     [001]   738.582818: funcgraph_exit:         0.598 us   |                  }
                     <idle>-0     [001]   738.582818: funcgraph_entry:        0.056 us   |                  touch_softlockup_watchdog_sched();
                     <idle>-0     [001]   738.582818: funcgraph_exit:         2.735 us   |                }
                     <idle>-0     [001]   738.582819: funcgraph_entry:        0.050 us   |                _local_bh_enable();
                     <idle>-0     [001]   738.582819: funcgraph_entry:        0.163 us   |                irqtime_account_irq();
                     <idle>-0     [001]   738.582820: funcgraph_exit:         5.427 us   |              }
                     <idle>-0     [001]   738.582820: funcgraph_entry:        0.092 us   |              sched_ttwu_pending();

crash> trace report
cpus=4
                     <idle>-0     [001]   738.580871: funcgraph_exit:         0.059 us   |        }
                     <idle>-0     [001]   738.580871: funcgraph_exit:         5.112 us   |      }
                     <idle>-0     [001]   738.580871: funcgraph_entry:        0.106 us   |      tick_nohz_stop_tick();
                     <idle>-0     [001]   738.580872: funcgraph_exit:         6.666 us   |    }
                     <idle>-0     [001]   738.580872: funcgraph_entry:                   |    rcu_idle_enter() {
                     <idle>-0     [001]   738.580872: funcgraph_entry:        0.069 us   |      rcu_eqs_enter.constprop.61();
                     <idle>-0     [001]   738.580873: funcgraph_exit:         0.527 us   |    }
                     <idle>-0     [001]   738.580873: funcgraph_entry:                   |    default_idle_call() {
                     <idle>-0     [001]   738.580873: funcgraph_entry:                   |      arch_cpu_idle() {
                     <idle>-0     [001]   738.580874: funcgraph_entry:                   |        __cpuidle_text_start() {
                     <idle>-0     [001]   738.582813: funcgraph_entry:                   |          smp_reschedule_interrupt() {
                     <idle>-0     [001]   738.582814: funcgraph_entry:                   |            scheduler_ipi() {
                     <idle>-0     [001]   738.582814: funcgraph_entry:                   |              irq_enter() {
                     <idle>-0     [001]   738.582814: funcgraph_entry:                   |                rcu_irq_enter() {
                     <idle>-0     [001]   738.582815: funcgraph_entry:        0.057 us   |                  rcu_dynticks_eqs_exit();
                     <idle>-0     [001]   738.582815: funcgraph_exit:         0.644 us   |                }
                     <idle>-0     [001]   738.582815: funcgraph_entry:                   |                tick_irq_enter() {
                     <idle>-0     [001]   738.582816: funcgraph_entry:        0.067 us   |                  tick_check_oneshot_broadcast_this_cpu();
                     <idle>-0     [001]   738.582816: funcgraph_entry:        0.118 us   |                  ktime_get();
                     <idle>-0     [001]   738.582817: funcgraph_entry:                   |                  update_ts_time_stats() {
                     <idle>-0     [001]   738.582817: funcgraph_entry:        0.054 us   |                    nr_iowait_cpu();
                     <idle>-0     [001]   738.582818: funcgraph_exit:         0.598 us   |                  }
                     <idle>-0     [001]   738.582818: funcgraph_entry:        0.056 us   |                  touch_softlockup_watchdog_sched();
                     <idle>-0     [001]   738.582818: funcgraph_exit:         2.735 us   |                }
                     <idle>-0     [001]   738.582819: funcgraph_entry:        0.050 us   |                _local_bh_enable();
                     <idle>-0     [001]   738.582819: funcgraph_entry:        0.163 us   |                irqtime_account_irq();
                     <idle>-0     [001]   738.582820: funcgraph_exit:         5.427 us   |              }
                     <idle>-0     [001]   738.582820: funcgraph_entry:        0.092 us   |              sched_ttwu_pending();

Note: It is also possible to dump the ftrace ring buffer content into the directory that can be parse by other tracing tools.

Steps to retrieveftrace data from the kernel crash dump:

• Execute trace dump -t [output-file-name] command to dump ring_buffers and all meta data to a file that can be parsed by trace-cmd.

crash> trace dump -t trace.dat

crash> !ls -l trace.dat 
-rw-r--r-- 1 root root 14413824 Apr 29 10:05 trace.dat

OR

• Execute trace dump -m -s command to dump ftrace ring_buffers to default directory dump_tracing_dir. Then you can parse it by other tracing tools.

Eg:

crash> trace dump -m -s

Where;
-m: also dump metadata of ftrace.
-s: also dump symbols of the kernel.

crash> ls
dump_tracing_dir  vmcore  vmcore-dmesg.txt

Note: The above command will save the ftrace ring_buffers inside the default directory dump_tracing_dir. The directories and files are generated the same as debugfs/tracing.

• Execute trace dump -m -s <dest-dir> command to dump ftrace ring_buffers to a different directory .

Eg:

crash> trace dump -m -s ftrace-dump

crash> ls
ftrace-dump  vmcore  vmcore-dmesg.txt

crash> sym -l > kallsyms

crash> ! sed -ne 's/(\(.*\))/\1/p' < kallsyms > dump_tracing_dir/functions

Note: The above command will save the ftrace ring_buffers inside the directory ftrace-dump.

Analyze the ftrace data using the trace-cmd utility:

RHEL-8 and RHEL-9:

• Install trace-cmd package:

Eg:

# yum install trace-cmd

• Analyze the ftrace data using the trace-cmd utility.

# trace-cmd report -i  trace.dat 

OR

Eg:

# trace-cmd restore -c -k dump_tracing_dir/functions -o head.dat

# trace-cmd restore -i head.dat -o trace.dat dump_tracing_dir/per_cpu/cpu*/trace_pipe_raw 2> /dev/null
first = 6 dump_tracing_dir/per_cpu/cpu0/trace_pipe_raw args=4

# trace-cmd report 2> /dev/null | head
cpus=4
          <idle>-0     [001]   738.580871: funcgraph_exit:         0.059 us   |        }
          <idle>-0     [001]   738.580871: funcgraph_exit:         5.112 us   |      }
          <idle>-0     [001]   738.580871: funcgraph_entry:        0.106 us   |      tick_nohz_stop_tick();
          <idle>-0     [001]   738.580872: funcgraph_exit:         6.666 us   |    }
          <idle>-0     [001]   738.580872: funcgraph_entry:                   |    rcu_idle_enter() {
          <idle>-0     [001]   738.580872: funcgraph_entry:        0.069 us   |      rcu_eqs_enter.constprop.61();
          <idle>-0     [001]   738.580873: funcgraph_exit:         0.527 us   |    }
          <idle>-0     [001]   738.580873: funcgraph_entry:                   |    default_idle_call() {
          <idle>-0     [001]   738.580873: funcgraph_entry:                   |      arch_cpu_idle() {

# trace-cmd report -f 2> /dev/null  | tail
ffffffffc0848240 nft_rbtree_get
ffffffffc0848344 cleanup_module
ffffffffc0848344 nf_tables_set_module_exit
ffffffffc084ac14 .LC0
ffffffffc084b020 nft_set_hash_fast_type
ffffffffc084b0c0 nft_set_hash_type
ffffffffc084b160 nft_set_rhash_type
ffffffffc084b200 nft_set_bitmap_type
ffffffffc084b2a0 nft_set_rbtree_type
ffffffffc084b340 __this_module

# trace-cmd report --profile 2> /dev/null | head
cpus=4

task: <idle>-0
  Event: func: default_idle_call() (116) Total: 58318689307 Avg: 502747321 Max: 57189176127(ts:796.204406) Min:252(ts:796.239976)
  Event: func: arch_cpu_idle() (114) Total: 58318534999 Avg: 511566096 Max: 57189175067(ts:796.204405) Min:1438(ts:796.244920)
  Event: func: __cpuidle_text_start() (114) Total: 58318408508 Avg: 511564986 Max: 57189174021(ts:796.204404) Min:1093(ts:796.244920)
  Event: func: do_idle() (63) Total: 57413808652 Avg: 911330296 Max: 56454506919(ts:795.469728) Min:39796(ts:796.240079)
  Event: func: schedule_idle() (60) Total: 48749625 Avg: 812493 Max: 12203564(ts:796.176429) Min:7365(ts:796.239910)
  Event: func: smp_apic_timer_interrupt() (91) Total: 12381809 Avg: 136063 Max: 523639(ts:795.578415) Min:4087(ts:796.238827)
  Event: func: irq_exit() (119) Total: 7249148 Avg: 60917 Max: 563067(ts:796.422528) Min:1079(ts:796.240606)

# trace-cmd report --profile 2> /dev/null | grep task: -A 1 | head
task: <idle>-0
  Event: func: default_idle_call() (116) Total: 58318689307 Avg: 502747321 Max: 57189176127(ts:796.204406) Min:252(ts:796.239976)
--
task: <...>-5
  Event: func: process_one_work() (1) Total: 55713 Avg: 55713 Max: 55713(ts:796.237367) Min:55713(ts:796.237367)
--
task: <...>-7
  Event: func: process_one_work() (1) Total: 15344 Avg: 15344 Max: 15344(ts:796.239930) Min:15344(ts:796.239930)
--
task: <...>-10

RHEL-6:

• RHEL6 ships trace-cmd as a command line tool to collect and report the output. Unfortunately, it is missing one feature (restore).
• You need to use upstream trace-cmd by pulling it from the git to see the output of the dumped raw file,

Eg:

$ git clone git://git.kernel.org/pub/scm/linux/kernel/git/rostedt/trace-cmd.git
$ cd trace-cmd ; make gui
$ cd ..
$ ./trace-cmd/trace-cmd restore -c -k dump_tracing_dir/functions -o head.dat
$ ./trace-cmd/trace-cmd restore -i head.dat -o trace.dat dump_tracing_dir/per_cpu/cpu*/trace_pipe_raw
$ ./trace-cmd/trace-cmd report