hana_shinのLinux技術ブログ

Linuxの技術情報を掲載しています。特にネットワークをメインに掲載していきます。

trace-cmdコマンドの使い方

1 trace-cmdコマンドとは?

trace-cmdコマンドは、ftrace(カーネルの各種処理を追跡するためのツール)のフロントエンドのコマンドです。Linuxカーネルの障害調査に使います。

2 検証環境

CentOS版数は以下のとおりです。

[root@server ~]# cat /etc/redhat-release
CentOS Linux release 7.9.2009 (Core)

カーネル版数は以下のとおりです。

[root@server ~]# uname -r
3.10.0-1160.el7.x86_64

3 インストール方法

trace-cmdパッケージをインストールします。

[root@server ~]# yum -y install trace-cmd

trace-cmdの版数を確認します。

[root@server ~]# trace-cmd -h

trace-cmd version 2.7.

4 コマンド、オプション一覧

trace-cmdのコマンド一覧を以下に示します。

[root@server ~]# trace-cmd -h

trace-cmd version 2.7.

usage:
  trace-cmd [COMMAND] ...

  commands:
     record - record a trace into a trace.dat file
     start - start tracing without recording into a file
     extract - extract a trace from the kernel
     stop - stop the kernel from recording trace data
     restart - restart the kernel trace data recording
     show - show the contents of the kernel tracing buffer
     reset - disable all kernel tracing and clear the trace buffers
     clear - clear the trace buffers
     report - read out the trace stored in a trace.dat file
     stream - Start tracing and read the output directly
     profile - Start profiling and read the output directly
     hist - show a historgram of the trace.dat information
     stat - show the status of the running tracing (ftrace) system
     split - parse a trace.dat file into smaller file(s)
     options - list the plugin options available for trace-cmd report
     listen - listen on a network socket for trace clients
     list - list the available events, plugins or options
     restore - restore a crashed record
     snapshot - take snapshot of running trace
     stack - output, enable or disable kernel stack tracing
     check-events - parse trace event formats

各コマンドのオプションは、"trace-cmd"に続けて、ハイフン、"コマンド"を連結したものをmanで確認することができます。たとえば、recordコマンドのオプションは、man trace-cmd-recordと実行すると、オプションを確認することができます。

[root@server ~]# man trace-cmd-record

コマンドの概要を以下に示します。

コマンド 概要
record トレースを開始します。トレースデータはファイル(trace.dat)に保存されます
report ファイル(trace.dat)に保存されているトレースデータをテキストファイルに変換します
start トレースを開始します。トレースデータはメモリに保存されます
stop トレースを停止します。トレースデータのメモリへの保存を停止します
extract メモリに保存されているトレースデータをファイル(trace.dat)に保存します
reset メモリに保存されているトレースデータを消去します
show メモリに保存されているトレースデータを表示します
listen 採取したトレースデータを別ホストに転送します

5 listコマンドの使い方

利用可能なplugins, events,Ftraceオプションを表示するコマンドです。

5.1 トレーサを表示する方法(-t)

[root@server ~]# trace-cmd list -t
hwlat blk function_graph wakeup_dl wakeup_rt wakeup function nop
トレーサ 概要
function 関数の呼び出しを記録する
function_graph 基本的にfunctionと同じ。関数の呼び出しに加え、関数から戻るときも記録する
blk ブロックI/Oの関数呼び出しを記録する
wakeup スケジューリング遅延の大きいプロセスを記録する
wakeup_rt スケジューリング遅延の大きいリアルタイムプロセスを記録する

5.2 イベントを表示する方法(-e)

-eはイベントを表示するオプションです。イベントのフォーマットは、subsystem:event-nameになります。

[root@server ~]# trace-cmd list -e
hda_intel:azx_suspend
hda_intel:azx_resume
hda_intel:azx_runtime_suspend
-snip-

サブシステム名は、以下のようにして確認することができます。block,bridge,compactionがサブシステム名になります。

[root@server ~]# trace-cmd list -e|cut -d ":" -f1|sort|uniq
block
bridge
compaction
-snip-

次にnetサブシステムに所属するイベント名を表示してみます。

[root@server ~]# trace-cmd list -e net 
net:netif_rx_ni_entry
net:netif_rx_entry
net:netif_receive_skb_entry
-snip-

5.3 利用可能な関数名を表示する方法(-f)

[root@server ~]# trace-cmd list -f ip_rcv
ip_rcv_finish
ip_rcv

なお、-fオプションは、下記ファイルの中身を読み出しています。

[root@server ~]# cat /sys/kernel/debug/tracing/available_filter_functions|grep ip_rcv
ip_rcv_finish
ip_rcv

5.4 利用可能なオプションを表示する方法(-t)

[root@server ~]# trace-cmd list -o
print-parent
nosym-offset
nosym-addr
-snip-

5.5 イベントフォーマットを表示する方法(-F -e)

[root@server ~]# trace-cmd list -F -e net:netif_receive_skb_entry
system: net
name: netif_receive_skb_entry
ID: 1017
format:
        field:unsigned short common_type;       offset:0;       size:2; signed:0;
        field:unsigned char common_flags;       offset:2;       size:1; signed:0;
        field:unsigned char common_preempt_count;       offset:3;       size:1; signed:0;
        field:int common_pid;   offset:4;       size:4; signed:1;

        field:__data_loc char[] name;   offset:8;       size:4; signed:1;
        field:unsigned int napi_id;     offset:12;      size:4; signed:0;
        field:u16 queue_mapping;        offset:16;      size:2; signed:0;
        field:const void * skbaddr;     offset:24;      size:8; signed:0;
        field:bool vlan_tagged; offset:32;      size:1; signed:0;
        field:u16 vlan_proto;   offset:34;      size:2; signed:0;
        field:u16 vlan_tci;     offset:36;      size:2; signed:0;
        field:u16 protocol;     offset:38;      size:2; signed:0;
        field:u8 ip_summed;     offset:40;      size:1; signed:0;
        field:u32 hash; offset:44;      size:4; signed:0;
        field:bool l4_hash;     offset:48;      size:1; signed:0;
        field:unsigned int len; offset:52;      size:4; signed:0;
        field:unsigned int data_len;    offset:56;      size:4; signed:0;
        field:unsigned int truesize;    offset:60;      size:4; signed:0;
        field:bool mac_header_valid;    offset:64;      size:1; signed:0;
        field:int mac_header;   offset:68;      size:4; signed:1;
        field:unsigned char nr_frags;   offset:72;      size:1; signed:0;
        field:u16 gso_size;     offset:74;      size:2; signed:0;
        field:u16 gso_type;     offset:76;      size:2; signed:0;

6 record/reportコマンドの使い方

6.1 プロセスのトレースデータを採取する方法(-P)

-PはPID(プロセスID)を指定するオプションです。指定したプロセスのトレースデータを採取することができます。ここでは、rcu_schedというカーネルスレッドのトレースデータを採取してみます。なお、-Pを指定しないと全てのプロセスのトレースを採取します。

rcu_schedのPIDを確認します。rcu_schedのPIDは9であることがわかります。

[root@server ~]# ps -C rcu_sched
  PID TTY          TIME CMD
    9 ?        00:00:00 rcu_sched

rcu_schedのPIDを指定してtrace-cmdコマンドを実行します。適当な時間が経過したら、Ctrl+Cを押下して、trace-cmdコマンドを終了します。

[root@server ~]# trace-cmd record -p function_graph -P 9
  plugin 'function_graph'
Hit Ctrl^C to stop recording
^CCPU0 data recorded at offset=0x465000
    20480 bytes in size
CPU1 data recorded at offset=0x46a000
    24576 bytes in size
CPU2 data recorded at offset=0x470000
    8192 bytes in size
CPU3 data recorded at offset=0x472000
    0 bytes in size

採取したトレースデータを確認します。

[root@server ~]# ls -l trace.dat
-rw-r--r--. 1 root root 4661248  5月  7 08:48 trace.dat

トレースデータをテキストファイルに変換します。

[root@server ~]# trace-cmd report trace.dat > trace.txt

変換したテキストファイルの中身を確認します。rcu_schedのトレースデータを確認することができます。finish_task_switch関数の実行に0.496μ秒かかっていることがわかります。また、del_timer_sync関数はtry_to_del_timer_sync関数を呼び出しており、さらにtry_to_del_timer_sync関数はlock_timer_base関数を呼び出していることがわかります。

[root@server ~]# head -n 10 trace.txt
CPU 3 is empty
cpus=4
       rcu_sched-9     [001]  2871.249522: funcgraph_entry:        0.496 us   |  finish_task_switch();
       rcu_sched-9     [001]  2871.249525: funcgraph_entry:                   |  del_timer_sync() {
       rcu_sched-9     [001]  2871.249526: funcgraph_entry:                   |    try_to_del_timer_sync() {
       rcu_sched-9     [001]  2871.249526: funcgraph_entry:                   |      lock_timer_base.isra.38() {
       rcu_sched-9     [001]  2871.249526: funcgraph_entry:        0.088 us   |        _raw_spin_lock_irqsave();
       rcu_sched-9     [001]  2871.249527: funcgraph_exit:         0.836 us   |      }
       rcu_sched-9     [001]  2871.249528: funcgraph_entry:        0.095 us   |      detach_if_pending();
       rcu_sched-9     [001]  2871.249528: funcgraph_entry:        0.113 us   |      _raw_spin_unlock_irqrestore();

6.2 コマンドのトレースデータを採取する方法(-F)

-Fはコマンドを指定するオプションです。指定したコマンドのトレースデータを採取することができます。ここでは、pingコマンドのトレースデータを採取してみます。なお、pingコマンドは、pingコマンドの使い方 - hana_shinのLinux技術ブログを参照してください。

[root@server ~]# trace-cmd record -p function_graph -F ping -c 1 192.168.122.1
  plugin 'function_graph'
PING 192.168.122.1 (192.168.122.1) 56(84) bytes of data.
64 bytes from 192.168.122.1: icmp_seq=1 ttl=64 time=0.586 ms

--- 192.168.122.1 ping statistics ---
1 packets transmitted, 1 received, 0% packet loss, time 0ms
rtt min/avg/max/mdev = 0.586/0.586/0.586/0.000 ms
CPU 1: 38293 events lost
CPU0 data recorded at offset=0x465000
    61440 bytes in size
CPU1 data recorded at offset=0x474000
    1449984 bytes in size
CPU2 data recorded at offset=0x5d6000
    0 bytes in size
CPU3 data recorded at offset=0x5d6000
    0 bytes in size

トレースデータをテキストファイルに変換します。

[root@server ~]# trace-cmd report trace.dat > trace.txt

変換したテキストファイルの中身を確認します。pingコマンドのトレースデータを確認することができます。

[root@server ~]# head -n 10 trace.txt
CPU 2 is empty
CPU 3 is empty
cpus=4
            ping-1805  [000]  4543.480824: funcgraph_entry:        0.213 us   |  mutex_unlock();
            ping-1805  [000]  4543.480826: funcgraph_entry:        0.068 us   |  __fsnotify_parent();
            ping-1805  [000]  4543.480827: funcgraph_entry:        0.119 us   |  fsnotify();
            ping-1805  [000]  4543.480827: funcgraph_entry:        0.072 us   |  __sb_end_write();
            ping-1805  [000]  4543.480828: funcgraph_entry:        0.059 us   |  mutex_unlock();
            ping-1805  [000]  4543.480829: funcgraph_entry:                   |  __audit_syscall_exit() {
            ping-1805  [000]  4543.480829: funcgraph_entry:                   |    path_put() {

6.3 指定した関数のトレースデータを表示する方法(-l)

-lは指定した関数のトレースデータを採取するオプションです。ここでは、カーネル関数のip_outputとudp_sendmsgのトレースデータを採取してみます。

[root@server ~]# trace-cmd record -p function_graph -l ip_output -l udp_sendmsg dig ntp.nict.jp +short
  plugin 'function_graph'
133.243.238.244
133.243.238.163
61.205.120.130
133.243.238.243
133.243.238.164
CPU0 data recorded at offset=0x465000
    0 bytes in size
CPU1 data recorded at offset=0x465000
    0 bytes in size
CPU2 data recorded at offset=0x465000
    4096 bytes in size
CPU3 data recorded at offset=0x466000
    4096 bytes in size

トレースデータをテキストファイルに変換します。

[root@server ~]# trace-cmd report trace.dat > trace.txt

トレースデータを確認します。

[root@server ~]# cat trace.txt
CPU 0 is empty
CPU 1 is empty
cpus=4
  isc-worker0000-3163  [003] 18345.435442: funcgraph_entry:        1.132 us   |  udp_sendmsg();
  isc-worker0000-3163  [003] 18345.436783: funcgraph_entry:                   |  udp_sendmsg() {
  isc-worker0000-3163  [003] 18345.436806: funcgraph_entry:      ! 109.944 us |    ip_output();
  isc-worker0000-3163  [003] 18345.436918: funcgraph_exit:       ! 133.693 us |  }
            sshd-1568  [002] 18345.449867: funcgraph_entry:      + 38.199 us  |  ip_output();

6.4 指定したコマンドが実行する関数を表示する方法(-F,-l)

digコマンドを実行すると、カーネル関数のip_outputとudp_sendmsgが呼び出されます。ここでは、digコマンドを実行時、ip_outputとudp_sendmsgだけが表示されることを確認してみます。

[root@server ~]# trace-cmd record -p function_graph -l ip_output -l udp_sendmsg -F dig ntp.nict.jp +short
  plugin 'function_graph'
133.243.238.244
133.243.238.164
133.243.238.243
61.205.120.130
133.243.238.163
CPU0 data recorded at offset=0x465000
    4096 bytes in size
CPU1 data recorded at offset=0x466000
    0 bytes in size
CPU2 data recorded at offset=0x466000
    0 bytes in size
CPU3 data recorded at offset=0x466000
    0 bytes in size

トレースデータをテキストに変換します。

[root@server ~]# trace-cmd report trace.dat > trace.txt

変換したテキストファイルの中身を確認します。udp_sendmsgとip_outputだけが表示されていることがわかります。

[root@server ~]# head -n 10 trace.txt
CPU 1 is empty
CPU 2 is empty
CPU 3 is empty
cpus=4
  isc-worker0000-3226  [000] 19593.471563: funcgraph_entry:        0.820 us   |  udp_sendmsg();
  isc-worker0000-3226  [000] 19593.472417: funcgraph_entry:                   |  udp_sendmsg() {
  isc-worker0000-3226  [000] 19593.472438: funcgraph_entry:      + 45.339 us  |    ip_output();
  isc-worker0000-3226  [000] 19593.472485: funcgraph_exit:       + 67.245 us  |  }

6.5 サブシステムのトレースデータを採取する方法(-e)

イベントは、サブシステムとイベント名から構成されます。特定のサブシステムに所属するイベントをトレースしてみます。ここでは、サブシステムとしてnetを指定します。

[root@server ~]# trace-cmd record -e net ping -c 1 192.168.122.1
PING 192.168.122.1 (192.168.122.1) 56(84) bytes of data.
64 bytes from 192.168.122.1: icmp_seq=1 ttl=64 time=0.436 ms

--- 192.168.122.1 ping statistics ---
1 packets transmitted, 1 received, 0% packet loss, time 0ms
rtt min/avg/max/mdev = 0.436/0.436/0.436/0.000 ms
CPU0 data recorded at offset=0x468000
    0 bytes in size
CPU1 data recorded at offset=0x468000
    0 bytes in size
CPU2 data recorded at offset=0x468000
    4096 bytes in size
CPU3 data recorded at offset=0x469000
    0 bytes in size

トレースデータをテキストファイルに変換します。

[root@server ~]# trace-cmd report trace.dat > trace.txt

トレースデータを確認します。

[root@server ~]# head -n 10 trace.txt
CPU 0 is empty
CPU 1 is empty
CPU 3 is empty
cpus=4
            ping-3290  [002] 21531.058020: net_dev_queue:        dev=eth0 skbaddr=0xffff8ecb36217f00 len=98
            ping-3290  [002] 21531.058188: net_dev_xmit:         dev=eth0 skbaddr=0xffff8ecb36217f00 len=98 rc=0
            sshd-1568  [002] 21531.058355: napi_gro_receive_entry: dev=eth0 napi_id=0 queue_mapping=0 skbaddr=0xffff8ecb36217100 vlan_tagged=0 vlan_proto=0x0000 vlan_tci=0x0000 protocol=0x0800 ip_summed=0 hash=0x00000000 l4_hash=0 len=84 data_len=0 truesize=768 mac_header_valid=1 mac_header=-14 nr_frags=0 gso_size=0 gso_type=0
            sshd-1568  [002] 21531.058360: netif_receive_skb:    dev=eth0 skbaddr=0xffff8ecb36217100 len=84
            sshd-1568  [002] 21531.058422: net_dev_queue:        dev=eth0 skbaddr=0xffff8ecb8ccfb4f8 len=158
            sshd-1568  [002] 21531.058496: net_dev_xmit:         dev=eth0 skbaddr=0xffff8ecb8ccfb4f8 len=158 rc=0

6.6 特定のイベントのトレースデータを表示する方法

[root@server ~]# trace-cmd record -e net:net_dev_queue ping -c 1 192.168.122.1
PING 192.168.122.1 (192.168.122.1) 56(84) bytes of data.
64 bytes from 192.168.122.1: icmp_seq=1 ttl=64 time=0.936 ms

--- 192.168.122.1 ping statistics ---
1 packets transmitted, 1 received, 0% packet loss, time 0ms
rtt min/avg/max/mdev = 0.936/0.936/0.936/0.000 ms
CPU0 data recorded at offset=0x465000
    4096 bytes in size
CPU1 data recorded at offset=0x466000
    0 bytes in size
CPU2 data recorded at offset=0x466000
    4096 bytes in size
CPU3 data recorded at offset=0x467000
    0 bytes in size

トレースデータをテキストファイルに変換します。

[root@server ~]# trace-cmd report trace.dat > trace.txt

トレースデータを確認します。

[root@server ~]# head -n 10 trace.txt
CPU 1 is empty
CPU 3 is empty
cpus=4
            ping-3307  [000] 21695.788235: net_dev_queue:        dev=eth0 skbaddr=0xffff8ecbb2122400 len=98
            sshd-1568  [002] 21695.788907: net_dev_queue:        dev=eth0 skbaddr=0xffff8ecb8ccfbef8 len=158

6.7 スタックのトレースデータを表示する方法(-T)

[root@server ~]# trace-cmd record -e net -T ping -c 1 192.168.122.1
PING 192.168.122.1 (192.168.122.1) 56(84) bytes of data.
64 bytes from 192.168.122.1: icmp_seq=1 ttl=64 time=0.465 ms

--- 192.168.122.1 ping statistics ---
1 packets transmitted, 1 received, 0% packet loss, time 0ms
rtt min/avg/max/mdev = 0.465/0.465/0.465/0.000 ms
CPU0 data recorded at offset=0x468000
    0 bytes in size
CPU1 data recorded at offset=0x468000
    4096 bytes in size
CPU2 data recorded at offset=0x469000
    4096 bytes in size
CPU3 data recorded at offset=0x46a000
    0 bytes in size

トレースデータをテキストに変換します。

[root@server ~]# trace-cmd report trace.dat > trace.txt

トレースデータを確認します。system_call_fastpathからip_outputを呼び出すまでのスタックトレースが表示されていることがわかります。

[root@server ~]# head -n 15 trace.txt
CPU 0 is empty
CPU 3 is empty
cpus=4
            ping-1661  [001]   938.434436: net_dev_queue:        dev=eth0 skbaddr=0xffff8ecc30027500 len=98
            ping-1661  [001]   938.434443: kernel_stack:         <stack trace>
=> ip_output (ffffffffab4a59db)
=> ip_local_out_sk (ffffffffab4a3407)
=> ip_send_skb (ffffffffab4a6446)
=> ip_push_pending_frames (ffffffffab4a64b3)
=> raw_sendmsg (ffffffffab4cdb74)
=> inet_sendmsg (ffffffffab4dd589)
=> sock_sendmsg (ffffffffab4343a6)
=> SYSC_sendto (ffffffffab434ad1)
=> SyS_sendto (ffffffffab4365ee)
=> system_call_fastpath (ffffffffab593f92)

6.8 表示関数の深さを指定する方法(--max-graph-depth)

--max-graph-depthは、関数呼び出しの深さを指定するオプションです。たとえば、関数A->関数B->関数Cというように関数呼び出しがあった場合、本オプションを指定しないと、関数A,B,Cが表示されます。しかし、本オプションに1を指定すると、関数Aだけが表示されるようになります。

まず、深さを1に指定した場合のトレースデータを確認してみます。

[root@server ~]# trace-cmd record -p function_graph --max-graph-depth=1 -F ping -c 1 192.168.122.1

トレースデータをテキストに変換します。

[root@server ~]#  trace-cmd report trace.dat > trace.txt

トレースデータを確認します。深さが1だと、最上位の関数だけが表示され、そこから呼び出す関数は表示されないことがわかります。

[root@server ~]# head -n 15 trace.txt
CPU 0 is empty
CPU 3 is empty
cpus=4
            ping-2783  [001]  9687.052709: funcgraph_entry:        0.133 us   |  mutex_unlock();
            ping-2783  [001]  9687.052711: funcgraph_entry:        0.079 us   |  __fsnotify_parent();
            ping-2783  [001]  9687.052712: funcgraph_entry:        0.130 us   |  fsnotify();
            ping-2783  [001]  9687.052712: funcgraph_entry:        0.068 us   |  __sb_end_write();
            ping-2783  [001]  9687.052713: funcgraph_entry:        0.056 us   |  mutex_unlock();
            ping-2783  [001]  9687.052714: funcgraph_entry:        0.380 us   |  __audit_syscall_exit();
            ping-2783  [001]  9687.052717: funcgraph_entry:        2.386 us   |  do_async_page_fault();
            ping-2783  [001]  9687.052721: funcgraph_entry:        1.699 us   |  do_async_page_fault();
            ping-2783  [001]  9687.052725: funcgraph_entry:        1.608 us   |  do_async_page_fault();
            ping-2783  [001]  9687.052729: funcgraph_entry:        1.644 us   |  do_async_page_fault();
            ping-2783  [001]  9687.052733: funcgraph_entry:        1.554 us   |  do_async_page_fault();
            ping-2783  [001]  9687.052736: funcgraph_entry:        1.743 us   |  do_async_page_fault();

次に、深さを2に指定した場合のトレースデータを確認してみます。

[root@server ~]# trace-cmd record -p function_graph --max-graph-depth=2 -F ping -c 1 192.168.122.1

トレースデータをテキストに変換します。

[root@server ~]#  trace-cmd report trace.dat > trace.txt

トレースデータを確認します。深さを2にすると、__audit_syscall_exit関数からpath_put関数等が呼び出されていることがわかります。

[root@server ~]# head -n 15 trace.txt
CPU 1 is empty
CPU 3 is empty
cpus=4
            ping-2773  [002]  9581.645902: funcgraph_entry:        0.127 us   |  mutex_unlock();
            ping-2773  [002]  9581.645905: funcgraph_entry:        0.091 us   |  __fsnotify_parent();
            ping-2773  [002]  9581.645906: funcgraph_entry:        0.151 us   |  fsnotify();
            ping-2773  [002]  9581.645907: funcgraph_entry:        0.101 us   |  __sb_end_write();
            ping-2773  [002]  9581.645907: funcgraph_entry:        0.089 us   |  mutex_unlock();
            ping-2773  [002]  9581.645908: funcgraph_entry:                   |  __audit_syscall_exit() {
            ping-2773  [002]  9581.645909: funcgraph_entry:        0.315 us   |    path_put();
            ping-2773  [002]  9581.645910: funcgraph_entry:        0.092 us   |    unroll_tree_refs();
            ping-2773  [002]  9581.645910: funcgraph_entry:        0.080 us   |    kfree();
            ping-2773  [002]  9581.645911: funcgraph_exit:         2.598 us   |  }
            ping-2773  [002]  9581.645915: funcgraph_entry:                   |  do_async_page_fault() {
            ping-2773  [002]  9581.645916: funcgraph_entry:        3.428 us   |    trace_do_page_fault();

7 start/show/stop/resetコマンドの使い方

recordコマンドはトレースデータをファイルに保存しますが、startコマンドはトレースデータをファイルではなくメモリに保存します。なお、startコマンドで使用できるオプションは、-s, -o, -F, -N, -t以外はrecordコマンドと同じです。

トレースが動作していると不要なトーレスデータがメモリに保存されてしまうので、stopコマンドを実行してトレースを停止します。

[root@server ~]# trace-cmd stop

メモリに保存されているトレースデータを消去します。

[root@server ~]# trace-cmd reset

トレースデータを表示します。トレースデータが何も保存されていないことがわかります。

[root@server ~]# trace-cmd show
# tracer: nop
#
# entries-in-buffer/entries-written: 0/0   #P:4
#
#                              _-----=> irqs-off
#                             / _----=> need-resched
#                            | / _---=> hardirq/softirq
#                            || / _--=> preempt-depth
#                            ||| /     delay
#           TASK-PID   CPU#  ||||    TIMESTAMP  FUNCTION
#              | |       |   ||||       |         |

irq番号が10以上のイベントを採取してみます。

[root@server ~]# trace-cmd start -e irq_handler_entry -f "irq>=10"

トレースを停止します。

[root@server ~]# trace-cmd stop

メモリに保存したトレースデータをファイル(trace.dat)に保存します。

[root@server ~]# trace-cmd extract
CPU0 data recorded at offset=0x574000
    4096 bytes in size
CPU1 data recorded at offset=0x575000
    0 bytes in size
CPU2 data recorded at offset=0x575000
    4096 bytes in size
CPU3 data recorded at offset=0x576000
    0 bytes in size

トレースデータを保存したファイルを確認します。

[root@server ~]# ls -lh trace.dat
-rw-r--r--. 1 root root 5.5M  5月  7 17:07 trace.dat

トレースデータをテキストファイルに変換します。

[root@server ~]# trace-cmd report trace.dat > trace.txt

トレースデータを確認します。

[root@server ~]# cat trace.txt
CPU 1 is empty
CPU 3 is empty
cpus=4
          <idle>-0     [002]  3703.138985: irq_handler_entry:    irq=27 name=virtio0-input.0
          <idle>-0     [000]  3703.941317: irq_handler_entry:    irq=14 name=ata_piix
          <idle>-0     [000]  3703.941937: irq_handler_entry:    irq=14 name=ata_piix
          <idle>-0     [002]  3704.681327: irq_handler_entry:    irq=27 name=virtio0-input.0
          <idle>-0     [002]  3705.784634: irq_handler_entry:    irq=27 name=virtio0-input.0
          <idle>-0     [002]  3705.786180: irq_handler_entry:    irq=27 name=virtio0-input.0
          <idle>-0     [002]  3705.957495: irq_handler_entry:    irq=27 name=virtio0-input.0
-snip-

8 listenコマンドの使い方

listenコマンドを使うと、あるホストで採取したトレースデータを別ホストに転送することができます。 listenコマンドは、トレースデータを受信する側で使用します。

8.1 検証環境

クライアントでトレースデータを採取します。採取したトレースデータをサーバに転送します。サーバはlsitenコマンドを使って、トレースデータを受信します。

client ----------------------(UDP/TCP)-------------------> server
trace-cmd record                                   trace-cmd listen

8.2 トレースデータの送信にTCPを使う方法(-t)

トレースデータの送信にTCPを使ってみます。
以下のポート番号を解放します。TCPの11111番ポートは制御用、TCPの1500,1501はトレースデータの受信用に使います。

[root@server ~]#  firewall-cmd --add-port=11111/tcp
success
[root@server ~]# firewall-cmd --add-port=1500/tcp
success
[root@server ~]# firewall-cmd --add-port=1501/tcp
success

開放したポート番号を確認します。

[root@server ~]#  firewall-cmd --list-ports
11111/tcp 1500/tcp 1501/tcp

trace-cmdコマンドを実行します。このとき、TCPの11111番ポートでListenするようにします。

[root@server ~]# trace-cmd listen -p 11111

trace-cmdプロセスがListenしているポート番号を確認します。TCPの11111番ポートでListenしていることがわかります。なお、lsofコマンドのインストール方法、使い方は、lsofコマンドの使い方 - hana_shinのLinux技術ブログを参照してください。

[root@server ~]# lsof -c trace-cmd -a -i -a -nP
COMMAND    PID USER   FD   TYPE DEVICE SIZE/OFF NODE NAME
trace-cmd 1727 root    3u  IPv4  34662      0t0  TCP *:11111 (LISTEN)

クライアントでtrace-cmdコマンドを実行します。このとき、pingコマンドのトーレスを取得して、それをサーバに送信するようにしてみます。"192.168.122.216:11111"はサーバのIPアドレスとtrace-cmdプロセスがListenしているポート番号です。

[root@client ~]# trace-cmd record -N 192.168.122.216:11111 -t -p function_graph -F ping -c 1 192.168.122.1
  plugin 'function_graph'
trace-cmd: No route to host
  Can not connect to TCP server 192.168.122.216:1502
trace-cmd: No route to host
  Can not connect to TCP server 192.168.122.216:1503
PING 192.168.122.1 (192.168.122.1) 56(84) bytes of data.
64 bytes from 192.168.122.1: icmp_seq=1 ttl=64 time=0.595 ms

--- 192.168.122.1 ping statistics ---
1 packets transmitted, 1 received, 0% packet loss, time 0ms
rtt min/avg/max/mdev = 0.595/0.595/0.595/0.000 ms

Ctrl+Cを押下して、trace-cmdコマンドを終了します。

[root@server ~]# trace-cmd listen -p 11111
Connected with client:39772
cpus=4
pagesize=4096
Using TCP for live connection
CPU0 data recorded at offset=0x465000
    61440 bytes in size
CPU1 data recorded at offset=0x474000
    1449984 bytes in size
CPU2 data recorded at offset=0x5d6000
    0 bytes in size
CPU3 data recorded at offset=0x5d6000
    0 bytes in size

クライアントから受信したトレースデータを確認します。

[root@server ~]# ls -lh trace.client\:39772.dat
-rw-r--r--. 1 root root 5.9M  5月  8 09:32 trace.client:39772.dat

トレースデータをテキストに変換します。

[root@server ~]# trace-cmd report trace.client:39772.dat > trace.txt

トレースデータを確認します。pingコマンド実行時のカーネル関数が出力されていることがわかります。

[root@server ~]# less trace.txt
-snip-
           <...>-1626  [001]   921.203375: funcgraph_entry:        0.373 us   |        ping_init_sock();
           <...>-1626  [001]   921.203376: funcgraph_entry:                   |        sk_common_release() {
           <...>-1626  [001]   921.203377: funcgraph_entry:                   |          ping_v4_unhash() {
           <...>-1626  [001]   921.203377: funcgraph_entry:        0.356 us   |            _raw_write_lock_bh();
           <...>-1626  [001]   921.203378: funcgraph_entry:                   |            _raw_write_unlock_bh() {
           <...>-1626  [001]   921.203379: funcgraph_entry:        0.124 us   |              __local_bh_enable_ip();
           <...>-1626  [001]   921.203379: funcgraph_exit:         0.653 us   |            }
           <...>-1626  [001]   921.203379: funcgraph_exit:         2.359 us   |          }
-snip-

8.3 トレースデータの送信にUDPを使う方法

トレースデータの送信にUDPを使ってみます。
以下のポート番号を解放します。TCPの11111番ポートは制御用、UDPの1500,1501はトレースデータの受信用に使います。

[root@server ~]# firewall-cmd --add-port=11111/tcp
success
[root@server ~]# firewall-cmd --add-port=1500/udp
success
[root@server ~]# firewall-cmd --add-port=1501/udp
success

開放したポート番号を確認します。

[root@server ~]# firewall-cmd --list-ports
11111/tcp 1500/udp 1501/udp

trace-cmdコマンドを実行します。このとき、TCPの11111番ポートでListenするようにします。

[root@server ~]# trace-cmd listen -p 11111

クライアントでtrace-cmdコマンドを実行します。このとき、pingコマンドのトーレスを取得して、それをサーバに送信するようにしてみます。"192.168.122.216:11111"はサーバのIPアドレスとtrace-cmdプロセスがListenしているポート番号です。

[root@client ~]# trace-cmd record -N 192.168.122.216:11111 -p function_graph -F ping -c 1 192.168.122.1
  plugin 'function_graph'
PING 192.168.122.1 (192.168.122.1) 56(84) bytes of data.
64 bytes from 192.168.122.1: icmp_seq=1 ttl=64 time=0.738 ms

--- 192.168.122.1 ping statistics ---
1 packets transmitted, 1 received, 0% packet loss, time 0ms
rtt min/avg/max/mdev = 0.738/0.738/0.738/0.000 ms

Ctrl+Cを押下して、trace-cmdコマンドを終了します。

[root@server ~]# trace-cmd listen -p 11111
Connected with client:39810
cpus=4
pagesize=4096
CPU0 data recorded at offset=0x465000
    1024000 bytes in size
CPU1 data recorded at offset=0x55f000
    40960 bytes in size
CPU2 data recorded at offset=0x569000
    0 bytes in size
CPU3 data recorded at offset=0x569000
    0 bytes in size

クライアントから受信したトレースデータを確認します。

[root@server ~]# ls -lh trace.client\:39810.dat
-rw-r--r--. 1 root root 5.5M  5月  8 11:04 trace.client:39810.dat

トレースデータをテキストに変換します。

[root@server ~]# trace-cmd report trace.client:39810.dat > trace.txt

トレースデータを確認します。pingコマンド実行時のカーネル関数が出力されていることがわかります。

[root@server ~]# less trace.txt
-snip-
           <...>-1896  [000]  6448.899304: funcgraph_entry:        0.337 us   |        ping_init_sock();
           <...>-1896  [000]  6448.899305: funcgraph_entry:                   |        sk_common_release() {
           <...>-1896  [000]  6448.899306: funcgraph_entry:                   |          ping_v4_unhash() {
           <...>-1896  [000]  6448.899306: funcgraph_entry:        0.196 us   |            _raw_write_lock_bh();
           <...>-1896  [000]  6448.899307: funcgraph_entry:                   |            _raw_write_unlock_bh() {
           <...>-1896  [000]  6448.899308: funcgraph_entry:        0.125 us   |              __local_bh_enable_ip();
           <...>-1896  [000]  6448.899308: funcgraph_exit:         0.726 us   |            }
           <...>-1896  [000]  6448.899309: funcgraph_exit:         2.322 us   |          }
-snip-

Z 参考情報

私が業務や記事執筆で参考にした書籍を以下のページに記載します。
Linux技術のスキルアップをしよう! - hana_shinのLinux技術ブログ