はじめに
本記事はFringe81 アドベントカレンダー2017の１１日目の投稿です。
5日目に紹介したdataflowで大幅コスト削減の開発で活用している開発環境でのパフォーマンスボトルネック発見のために活用しているトレースツールの簡単な使い方をまとめた記事になります。
本記事について
データ処理に代表する高負荷処理ではしばしばパフォーマンスのボトルネック問題に悩まされます。
問題に直面した際に、まず使うのはmpstatやiostatのようなstat系ツールが一般的ですが、
そこで見られる情報は、CPU負荷が高い、IO負荷が高いなどの大まかなリソース消費状況でした。
大まかな当たりからココラアタリが問題箇所だろうと推測して実装するのは、不発多くなかなか決め手に欠ける開発法と思われます。
特にdataflow開発のように様々なAPIが裏で動くフレームワークを使ったシステム開発ではソース追っても複雑で、効率的な開発はなかなか厳しいものがあると感じていました。
そんな折り、「詳解 システム・パフォーマンス」という本に出会い、動的トレーシングを使うと内部処理まで可視化できることを知りました。
本記事では、動的トレースツール(Dtrace)を活用して 「推測するな、計測せよ」を深掘る 方法を紹介します。
※開発環境はMacOSXです。本記事はその環境での実行した結果になります。
パフォーマンス計測におけるトレーシングとカウンタ
UNIX系システムでパフォーマンスを計測するには下記のように２つのタイプがあります。
-
トレーシング
分析のために、負荷をかけてイベントごとのデータを集める機能です。一般にデフォルトでは有効にされていません。本番環境で定常的に使うのもおすすめできません。
この機能を使うツールは、tcpdump, Dtraceが一般的です。 -
カウンタ
カーネルが継続的に書き出しているカウンタを読み出して情報を表示する機能です。カーネルの管理情報を使うため、オーバーヘッド極小で問題なく使えます。
この機能を使うツールは、vmstat, mpstat, iostat等のstat系ツール、sar、topが一般的です。
動的にトレーシングを行うことができるツールがDtraceです。
事前準備
トレーシングを実行するにはroot権限が必要です。
下記ページが参考になります
https://support.apple.com/ja-jp/HT204012
以上で使えます。OSX version 10.5 「Leopard」以降では標準で入っているようです。
IO系
iosnoop
diskI/Oのライブtraceです。
diskI/O実行が終わるたびにプロセス名とファイル名の詳細を記した情報が出ます。
実行すると以下のようにな出力になります。
UID=ユーザID, PID=プロセスID, D=direction(R = read, W = write), BLOCK=ディスク上の場所, SIZE=I/Oサイズ(bytes), COMM=プロセス名, PATHNAME=パス情報
出力はIO処理が終わるごとOS全体の情報が出力されてくるのでgrepとtailでよしなに整形すると処理状況を観察できます。
この処理では最初にmysqlのIOが発生し、tableデータへアクセスされて、メインロジックに移っていく様子がIOの視点から見れます。
tailで取得すると処理時間の感覚もつかめるので、どこでもたついているのか把握できます。
このツールからはが想定しない場所で発生していないか、もたつきはないかを見れます。
このツールから、不要なログ出力が思わぬ負荷となっていたことを発見できました。
iotop
上記iosnoopと同じdataを出力するツールです。
iosnoopに比べてサマられたデータを出力できます。
# 3秒ごとにサマられた%使用率を表示
iotop -CP 3
このツールからはiosnoopだと情報量が多すぎるところをサマって全体的なリソース状況が見れます。
ただ、詳細データが無くなってstat系と同じような結果になってしまいますね。
全体的な処理状況を俯瞰する場合に使えると思います。
全方位系
dtruss
dtrussはosカーネルのあらゆるシステムコールをトレースできるツールです。
広範囲のdebugツールとして使えます。特にマルチプロセスを一度に見れるところに特徴があります。
動作にそこそこ負荷がかかり情報量が多いので使いこなすの大変ですが、システムコールレベルの詳細が見れるので厄介なパフォーマンス問題の解決に繋がる可能性があります。
dtruss -a -e -d -n java 2>&1 |grep -v ".class"
で見るとヘッダは「PID/THRD RELATIVE ELAPSD CPU SYSCALL(args)」となって以下のような情報が見れます。
classごとに差が出ているのがわかります。まだこのツールで詳細見るほどのパフォーマンス問題には当たっていませんが、
イザとなったら詳細追えると思います(チト辛そうですが)
その他
下記のようにmanを参照するとたくさん出てきます(^^)
# man -k dtrace
Tcl_CommandTraceInfo(3tcl), Tcl_TraceCommand(3tcl), Tcl_UntraceCommand(3tcl) - monitor renames and deletes of a command
bitesize.d(1m) - analyse disk I/O size by process. Uses DTrace
cpuwalk.d(1m) - Measure which CPUs a process runs on. Uses DTrace
creatbyproc.d(1m) - snoop creat()s by process name. Uses DTrace
dappprof(1m) - profile user and lib function usage. Uses DTrace
dapptrace(1m) - trace user and library function usage. Uses DTrace
diskhits(1m) - disk access by file offset. Uses DTrace
dispqlen.d(1m) - dispatcher queue length by CPU. Uses DTrace
dtrace(1) - generic front-end to the DTrace facility
dtruss(1m) - process syscall details. Uses DTrace
errinfo(1m) - print errno for syscall fails. Uses DTrace
execsnoop(1m) - snoop new process execution. Uses DTrace
fddist(1m) - file descriptor usage distributions. Uses DTrace
filebyproc.d(1m) - snoop opens by process name. Uses DTrace
hotspot.d(1m) - print disk event by location. Uses DTrace
httpdstat.d(1m) - realtime httpd statistics. Uses DTrace
iofile.d(1m) - I/O wait time by file and process. Uses DTrace
iofileb.d(1m) - I/O bytes by file and process. Uses DTrace
iopattern(1m) - print disk I/O pattern. Uses DTrace
iopending(1m) - plot number of pending disk events. Uses DTrace
iosnoop(1m) - snoop I/O events as they occur. Uses DTrace
iotop(1m) - display top disk I/O events by process. Uses DTrace
kill.d(1m) - snoop process signals as they occur. Uses DTrace
lastwords(1m) - print syscalls before exit. Uses DTrace
loads.d(1m) - print load averages. Uses DTrace
newproc.d(1m) - snoop new processes. Uses DTrace
opensnoop(1m) - snoop file opens as they occur. Uses DTrace
pathopens.d(1m) - full pathnames opened ok count. Uses DTrace
perldtrace(1) - Perl's support for DTrace
pidpersec.d(1m) - print new PIDs per sec. Uses DTrace
plockstat(1) - front-end to DTrace to print statistics about POSIX mutexes and read/write locks
priclass.d(1m) - priority distribution by scheduling class. Uses DTrace
pridist.d(1m) - process priority distribution. Uses DTrace
procsystime(1m) - analyse system call times. Uses DTrace
runocc.d(1m) - run queue occupancy by CPU. Uses DTrace
rwbypid.d(1m) - read/write calls by PID. Uses DTrace
rwbytype.d(1m) - read/write bytes by vnode type. Uses DTrace
rwsnoop(1m) - snoop read/write events. Uses DTrace
sampleproc(1m) - sample processes on the CPUs. Uses DTrace
seeksize.d(1m) - print disk event seek report. Uses DTrace
setuids.d(1m) - snoop setuid calls as they occur. Uses DTrace
sigdist.d(1m) - signal distribution by process. Uses DTrace
syscallbypid.d(1m) - syscalls by process ID. Uses DTrace
syscallbyproc.d(1m) - syscalls by process name. Uses DTrace
syscallbysysc.d(1m) - syscalls by syscall. Uses DTrace
topsyscall(1m) - top syscalls by syscall name. Uses DTrace
topsysproc(1m) - top syscalls by process name. Uses DTrace
weblatency.d(1m) - website latency statistics. Uses DTrace
まとめ
Macの開発環境でDtraceを使うと、動的トレースを使って手軽に詳細な内部処理状況が見れることを紹介しました。
動的トレースは奥深く、当方まだまだ触ってみたレベルですが
是非使いこなして今後の開発やパフォーマンス調査に使い 「推測するな、計測せよ」を深掘る 実践して行きたいと思いました。
まだまだ使いこなしてる感ないので試行錯誤して、知見たまったらより詳しい記事を書きたいと思います。