SystemTap Beginners Guide 5.3と5.4のメモ
5.3 プロファイリング
以下のセクションでは、関数呼び出しの監視によりカーネルの活動状況を分析する方法を説明する。
5.3.1 関数呼び出しを数える
このセクションでは、カーネルが30秒間に何回カーネルの関数を呼び出すのか特定する方法について説明する。
functioncallcount.stp
#!/usr/bin/stap
# The following line command will probe all the functions
# in kernel's memory management code:
#
# stap functioncallcount.stp "*@mm/*.c"
probe kernel.function(@1).call { # probe functions listed on commandline
called[probefunc()] <<< 1 # add a count efficiently
}
global called
probe end {
foreach (fn in called-) # Sort by call count (in decreasing order)
# (fn+ in called) # Sort by function name
printf("%s %d\n", fn, @count(called[fn]))
exit()
}functioncallcount.stpは対象のカーネル関数を引数に取る。
ワイルドカードでも使えるので、別の環境でも確実に使えるはずである。
以下に、'stap functioncallcount.stp "*@mm/*.c"'を実行した結果を示す。
__vma_link 97 __vma_link_file 66 __vma_link_list 97 __vma_link_rb 97 __xchg 103 add_page_to_active_list 102 add_page_to_inactive_list 19 add_to_page_cache 19 add_to_page_cache_lru 7 all_vm_events 6 alloc_pages_node 4630 alloc_slabmgmt 67 anon_vma_alloc 62 anon_vma_free 62 anon_vma_lock 66 anon_vma_prepare 98 anon_vma_unlink 97 anon_vma_unlock 66 arch_get_unmapped_area_topdown 94 arch_get_unmapped_exec_area 3 arch_unmap_area_topdown 97 atomic_add 2 atomic_add_negative 97 atomic_dec_and_test 5153 atomic_inc 470 atomic_inc_and_test 1
5.3.2 コールグラフのトレース
このセクションでは、関数呼び出しにおける関数に入る箇所と出る箇所をトレースする。
#!/usr/bin/stap
function trace(entry_p, extra) {
%( $# > 1 %? if (tid() in trace) %)
printf("%s%s%s %s\n",
thread_indent (entry_p),
(entry_p>0?"->":"<-"),
probefunc (),
extra)
}
%( $# > 1 %?
global trace
probe $2.call {
trace[tid()] = 1
}
probe $2.return {
delete trace[tid()]
}
%)
probe $1.call { trace(1, $$parms) }
probe $1.return { trace(-1, $$return) }
para-callgraph.stp は２つのコマンドライン引数をとる。
- トレースしたい関数 ($1)
- ２つ目はオプションのトリガー関数($2)。トリガー関数が指定されている場合、この関数に入った後から、この関数から出るまでの間でトレースを実行する。
以下に、"stap para-callgraph.stp 'kernel.function("*@fs/*.c")' 'kernel.function("sys_read")'"の実行例を示す。
... 267 gnome-terminal(2921): <-do_sync_read return=0xfffffffffffffff5 269 gnome-terminal(2921):<-vfs_read return=0xfffffffffffffff5 0 gnome-terminal(2921):->fput file=0xffff880111eebbc0 2 gnome-terminal(2921):<-fput 0 gnome-terminal(2921):->fget_light fd=0x3 fput_needed=0xffff88010544df54 3 gnome-terminal(2921):<-fget_light return=0xffff8801116ce980 0 gnome-terminal(2921):->vfs_read file=0xffff8801116ce980 buf=0xc86504 count=0x1000 pos=0xffff88010544df48 4 gnome-terminal(2921): ->rw_verify_area read_write=0x0 file=0xffff8801116ce980 ppos=0xffff88010544df48 count=0x1000 7 gnome-terminal(2921): <-rw_verify_area return=0x1000 12 gnome-terminal(2921): ->do_sync_read filp=0xffff8801116ce980 buf=0xc86504 len=0x1000 ppos=0xffff88010544df48 15 gnome-terminal(2921): <-do_sync_read return=0xfffffffffffffff5 18 gnome-terminal(2921):<-vfs_read return=0xfffffffffffffff5 0 gnome-terminal(2921):->fput file=0xffff8801116ce980
5.3.3 カーネル空間とユーザ空間での消費時間の決定
このセクションでは、スレッドに与えられた時間がどのくらいカーネルで消費されたか、
またはユーザー空間で消費されたか決定する方法について説明する。
#!/usr/bin/stap
probe perf.sw.cpu_clock!, timer.profile {
// NB: To avoid contention on SMP machines, no global scalars/arrays used,
// only contention-free statistics aggregates.
tid=tid(); e=execname()
if (!user_mode())
kticks[e,tid] <<< 1
else
uticks[e,tid] <<< 1
ticks <<< 1
tids[e,tid] <<< 1
}
global uticks, kticks, ticks
global tids
probe timer.s(5), end {
allticks = @count(ticks)
printf ("%16s %5s %7s %7s (of %d ticks)\n",
"comm", "tid", "%user", "%kernel", allticks)
foreach ([e,tid] in tids- limit 20) {
uscaled = @count(uticks[e,tid])*10000/allticks
kscaled = @count(kticks[e,tid])*10000/allticks
printf ("%16s %5d %3d.%02d%% %3d.%02d%%\n",
e, tid, uscaled/100, uscaled%100, kscaled/100, kscaled%100)
}
printf("\n")
delete uticks
delete kticks
delete ticks
delete tids
}thread-times.stpは5秒間にCPUを最も消費した上位20プロセスを列挙する。
また、CPUの消費時間をユーザー空間とカーネル空間に分けて、パーセント表示する。
このスクリプトの実行にかかる時間も計測結果に含まれてしまっている。
以下に実行例を示す。
comm tid %user %kernel (of 9999 ticks)
swapper/1 0 0.00% 45.17%
swapper/0 0 0.00% 44.32%
gedit 1709 1.87% 0.10%
gnome-shell 1133 1.18% 0.26%
Xorg 823 0.75% 0.68%
gdbus 1566 1.10% 0.22%
mozc_server 1744 1.23% 0.04%
ibus-daemon 1475 0.59% 0.05%
ibus-engine-moz 1738 0.25% 0.25%
gdbus 1713 0.34% 0.06%
mozc_renderer 1748 0.27% 0.01%
gdbus 1740 0.22% 0.04%
ibus-ui-gtk3 1568 0.23% 0.01%
kworker/0:2 2344 0.00% 0.12%
kworker/1:1 2182 0.00% 0.10%
gdbus 1574 0.06% 0.02%
kworker/u:0 5 0.00% 0.07%
gnome-terminal 1780 0.04% 0.02%
gdbus 1579 0.06% 0.00%
ibus-engine-sim 1578 0.05% 0.00%
5.3.4 ポーリング中のアプリケーションの監視
このセクションでは、ポーリング中のアプリケーションの監視と特定について説明する。
不要であったり高価であったりするポーリングを追跡できるので、性能改善に役立つだろう。
#!/usr/bin/stap
# Copyright (C) 2009 Red Hat, Inc.
# Written by Ulrich Drepper <drepper@redhat.com>
# Modified by William Cohen <wcohen@redhat.com>
global process, timeout_count, to
global poll_timeout, epoll_timeout, select_timeout, itimer_timeout
global nanosleep_timeout, futex_timeout, signal_timeout
probe syscall.poll, syscall.epoll_wait {
if (timeout) to[pid()]=timeout
}
probe syscall.poll.return {
p = pid()
if ($return == 0 && to[p] > 0 ) {
poll_timeout[p]++
timeout_count[p]++
process[p] = execname()
delete to[p]
}
}
probe syscall.epoll_wait.return {
p = pid()
if ($return == 0 && to[p] > 0 ) {
epoll_timeout[p]++
timeout_count[p]++
process[p] = execname()
delete to[p]
}
}
probe syscall.select.return {
if ($return == 0) {
p = pid()
select_timeout[p]++
timeout_count[p]++
process[p] = execname()
}
}
probe syscall.futex.return {
if (errno_str($return) == "ETIMEDOUT") {
p = pid()
futex_timeout[p]++
timeout_count[p]++
process[p] = execname()
}
}
probe syscall.nanosleep.return {
if ($return == 0) {
p = pid()
nanosleep_timeout[p]++
timeout_count[p]++
process[p] = execname()
}
}
probe kernel.function("it_real_fn") {
p = pid()
itimer_timeout[p]++
timeout_count[p]++
process[p] = execname()
}
probe syscall.rt_sigtimedwait.return {
if (errno_str($return) == "EAGAIN") {
p = pid()
signal_timeout[p]++
timeout_count[p]++
process[p] = execname()
}
}
probe syscall.exit {
p = pid()
if (p in process) {
delete process[p]
delete timeout_count[p]
delete poll_timeout[p]
delete epoll_timeout[p]
delete select_timeout[p]
delete itimer_timeout[p]
delete futex_timeout[p]
delete nanosleep_timeout[p]
delete signal_timeout[p]
}
}
probe timer.s(1) {
ansi_clear_screen()
printf (" pid | poll select epoll itimer futex nanosle signal| process\n")
foreach (p in timeout_count- limit 20) {
printf ("%5d |%7d %7d %7d %7d %7d %7d %7d| %-.38s\n", p,
poll_timeout[p], select_timeout[p],
epoll_timeout[p], itimer_timeout[p],
futex_timeout[p], nanosleep_timeout[p],
signal_timeout[p], process[p])
}
}timeout.stpでは、以下のシステムコールが、実イベントの発生ではなく時間経過によって完了した回数を追跡する。
- poll
- select
- epoll
- itimer
- futex
- nanosleep
- signal
サンプル時間を増やしたい場合には、timer.s(1)の引数を増やせばよい。
timeout.stpの出力結果には、ポーリングシステムコールを実行して時間超過した数の順番に、上位の20個ポーリング中のアプリケーションのUIDと名前が表示される。
以下に実行例を示す。
pid | poll select epoll itimer futex nanosle signal| process
3397 | 3 0 0 0 156 0 0| firefox
1748 | 0 0 0 0 0 143 0| mozc_renderer
1780 | 120 0 0 0 0 3 0| gnome-terminal
822 | 0 64 0 0 0 0 0| wpa_supplicant
823 | 0 55 0 0 0 0 0| Xorg
1133 | 46 0 0 0 0 0 0| gnome-shell
697 | 10 0 0 0 0 0 0| NetworkManager
805 | 0 6 0 0 0 0 0| sendmail
1092 | 4 0 0 0 0 0 0| gnome-settings-
909 | 3 0 0 0 0 0 0| rtkit-daemon
670 | 0 0 0 0 0 3 0| abrt-watch-log
862 | 1 0 0 0 0 0 0| upowerd
0 | 0 0 0 1 0 0 0| swapper/0
1475 | 1 0 0 0 0 0 0| gdbus
1144 | 0 1 0 0 0 0 0| syndaemon
741 | 0 1 0 0 0 0 0| crond
1111 | 0 0 1 0 0 0 0| cupsd
5.3.5 最高頻度で使われるシステムコールの追跡
timeout.stpは、一部のシステムコール(poll等)を実行してポーリングしているアプリケーションを特定した。
しかし、その一部のシステムコール以外のシステムコールがカーネル内で時間を消費しているケースもあり得る。
もし、あるアプリケーションが無駄にシステムコールを使っていると考えているのであれば、
最高頻度で使われるシステムコールを特定する必要がある。そして、それにはtopsys.stpを使うことが出来る。
#!/usr/bin/stap
#
# This script continuously lists the top 20 systemcalls in the interval
# 5 seconds
#
global syscalls_count
probe syscall.* {
syscalls_count[name]++
}
function print_systop () {
printf ("%25s %10s\n", "SYSCALL", "COUNT")
foreach (syscall in syscalls_count- limit 20) {
printf("%25s %10d\n", syscall, syscalls_count[syscall])
}
delete syscalls_count
}
probe timer.s(5) {
print_systop ()
printf("--------------------------------------------------------------\n")
}
topsys.stpは5秒間隔にシステムコールが使われた回数を数えて、上位20のシステムコールを列挙する。
以下に実行例を示す。
SYSCALL COUNT
ioctl 904
write 593
poll 574
sendmsg 478
read 450
recvmsg 398
recvfrom 260
select 152
setitimer 128
writev 102
lseek 90
rt_sigprocmask 82
close 53
munmap 51
mmap2 50
fstat 50
open 49
ppoll 25
nanosleep 22
epoll_wait 7
5.3.6 プロセス毎のシステコールの総量の追跡
このセクションでは、システムコールを元も実行しているプロセスを特定する方法を説明する。
前節では、ある時間で最も呼ばれるシステムコールを関しする方法について説明した。
また、どのアプリケーションがポーリング関連のシステムコールを最も呼び出しているのか特定する方法も説明した。
それぞれのプロセスがシステムコールを呼ぶ量を監視することで、ポーリング中のプロセスやリソース喰いを調査するのに役立つ情報を、さらに提供することが出来る。
syscalls_by_proc.stp
#!/usr/bin/stap
# Copyright (C) 2006 IBM Corp.
#
# This file is part of systemtap, and is free software. You can
# redistribute it and/or modify it under the terms of the GNU General
# Public License (GPL); either version 2, or (at your option) any
# later version.
#
# Print the system call count by process name in descending order.
#
global syscalls
probe begin {
print ("Collecting data... Type Ctrl-C to exit and display results\n")
}
probe syscall.* {
syscalls[execname()]++
}
probe end {
printf ("%-10s %-s\n", "#SysCalls", "Process Name")
foreach (proc in syscalls-)
printf("%-10d %-s\n", syscalls[proc], proc)
}syscalls_by_proc.stpは、システムコールを呼び出した回数が多いプロセスの上位20を表示する。
また、システムコールを呼び出した回数も同時に表示する。
以下に実行例を示す。
SysCalls Process Name 30120 Xorg 5405 gnome-shell 3957 evince 1742 gnome-terminal 1412 gdbus 1188 NetworkManager 985 gnome-settings- 493 dbus-daemon 433 stapio 278 wpa_supplicant 183 upowerd 168 mozc_renderer 151 nm-applet 148 mission-control 123 ibus-ui-gtk3 116 ibus-daemon 109 systemd-journal 64 firefox 60 pool 56 sendmail 46 gnome-session 37 syndaemon 36 mozc_server 35 tracker-miner-f 31 systemd 24 rtkit-daemon 24 crond 20 modem-manager 20 gdm-binary 18 ibus-engine-sim 18 avahi-daemon 15 abrt-watch-log 7 cupsd 7 sudo 5 gnome-screensav 5 stap 4 fprintd 4 polkitd 4 gnome-shell-cal 4 evolution-alarm 4 gedit 3 rsyslogd 3 rs:main Q:Reg 2 audispd 1 kthreadd 1 gconfd-2
プロセス名の代わりにプロセスIDを表示する場合には以下のスクリプトを使用する。
#!/usr/bin/stap
# Copyright (C) 2006 IBM Corp.
#
# This file is part of systemtap, and is free software. You can
# redistribute it and/or modify it under the terms of the GNU General
# Public License (GPL); either version 2, or (at your option) any
# later version.
#
# Print the system call count by process ID in descending order.
#
global syscalls
probe begin {
print ("Collecting data... Type Ctrl-C to exit and display results\n")
}
probe syscall.* {
syscalls[pid()]++
}
probe end {
printf ("%-10s %-s\n", "#SysCalls", "PID")
foreach (pid in syscalls-)
printf("%-10d %-d\n", syscalls[pid], pid)
}
時間経過で終了させたい場合には、timer.s()を追加してexit関数を実行せよ。
5.4 競合したユーザー空間のロックを特定する
このセクションでは、ある期間にシステム全体に渡って、競合したユーザー空間のロックを特定する方法について説明する。
これはfutexの競合を原因とする貧弱な性能のプログラムを改善するのに役立つだろう。
単純に言って、futexの競合は複数のプロセスが同じ時期に同じロックにアクセスしようとするために発生する。
このためロック機構による並列実行は貧弱な性能の原因となる。
ロック機構の並列実行とは、あるプロセスがロックを得ると、他のプロセスはロックを使えるようになるまで待つといったものである。
futexes.stpスクリプトはfutexシステムコールをプローブして、ロックの競合を表示する。
#!/usr/bin/stap
# This script tries to identify contended user-space locks by hooking
# into the futex system call.
global FUTEX_WAIT = 0 /*, FUTEX_WAKE = 1 */
global FUTEX_PRIVATE_FLAG = 128 /* linux 2.6.22+ */
global FUTEX_CLOCK_REALTIME = 256 /* linux 2.6.29+ */
global lock_waits # long-lived stats on (tid,lock) blockage elapsed time
global process_names # long-lived pid-to-execname mapping
probe syscall.futex.return {
if (($op & ~(FUTEX_PRIVATE_FLAG|FUTEX_CLOCK_REALTIME)) != FUTEX_WAIT) next
process_names[pid()] = execname()
elapsed = gettimeofday_us() - @entry(gettimeofday_us())
lock_waits[pid(), $uaddr] <<< elapsed
}
probe end {
foreach ([pid+, lock] in lock_waits)
printf ("%s[%d] lock %p contended %d times, %d avg us\n",
process_names[pid], pid, lock, @count(lock_waits[pid,lock]),
@avg(lock_waits[pid,lock]))
}
futexes.stp は手動で停止させる必要がある。exitすると、以下の情報を出力する。
- ある競合に関して責任を持つプロセスIDと名前
- 対象となるロック変数の位置
- ロック変数が競合された回数
- プローブ中の競合に関する時間の平均
以下に実行例を示す。
rs:main Q:Reg[694] lock 0x7f6489d2ff04 contended 1 times, 25790639 avg us pool[1120] lock 0x14f59f0 contended 1 times, 595 avg us gnome-shell[1133] lock 0x1d86b50 contended 1 times, 252 avg us gnome-shell[1133] lock 0x1d97bb0 contended 1 times, 9 avg us gnome-shell[1133] lock 0x2c2af1c contended 1 times, 29665866 avg us ibus-daemon[1475] lock 0x25ef7d0 contended 3 times, 23 avg us gdbus[1780] lock 0x7f22e400a1d0 contended 2 times, 13 avg us gdbus[1780] lock 0x19762f0 contended 2 times, 11 avg us gdbus[1780] lock 0x7f22e4009560 contended 2 times, 22 avg us
