- 1 trace-cmdコマンドとは?
- 2 検証環境
- 3 インストール方法
- 4 コマンド、オプション一覧
- 5 listコマンドの使い方
- 6 record/reportコマンドの使い方
- 7 start/show/stop/resetコマンドの使い方
- 8 listenコマンドの使い方
- Z 参考情報
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_schedrcu_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はトレースデータの受信用に使います。なお、firewall-cmdの使い方は、firewall-cmdの使い方 - hana_shinのLinux技術ブログを参照してください。
[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技術ブログ
