2009年 2月 22日 日曜日
やっぱり Sun がスキ！
2009年 2月 22日 日曜日
パフォーマンスボトルネックの探し方
はじめに
先日、sys が発生した場合の解析手順の 記事 を書きました。今回はその続きとして、ベンチマーク中のボトルネック解析手順を実例を元に解説していきたいと思います。サーバに対して実際に負荷を掛けた状態での解析の流れをご覧下さい。
今回の解析の対象は『10 ギガビットイーサネットを使用した HTTP のダウンロードサーバ』です。HTTP のダウンロードサーバは動画配信サイトや画像共有サイト等をご想像頂くと分かりやすいと思います（Y**tube や Fr*ckr 等ですね）。『増え続けるトラフィックに対応する為にサーバを増強して来たが、ネットワークを 10 ギガビットイーサネットに集約する事でマシンの台数を減らし、サーバの管理コストやデータセンターの電力消費を減らしたい』という筋書きを想定しています。解析の目的はスループットを 10 ギガビットになるべく近付ける事になります。
解析対象のシステム : 10GbE を使用した配信サーバ 解析の目的 : なるべく 10Gbps に近付ける
ベンチマーク環境
ベンチマーク環境は次の様なシステムを用意しました。x86-64 を 8 コア搭載したマシンをサーバ用に 1 台、クライアント用に 1 台。各マシンには nxge ドライバのネットワークインターフェイスカードを 1 枚ずつ挿し、クロスオーバーケーブルで間を直結しています。それぞれに Solaris 10 の最新版 ( 10/08 ) と最新の推奨パッチクラスタをインストールしてあります。また、内蔵ディスクに ZFS でファイルシステムを作成し、mkfile コマンドで作成した 10MB のコンテンツファイルを配置してあります。
x86-64 8 Core のマシン 2 台をクロスで直結しました
HTTP サーバ
- HTTP サーバは Solaris 10 にバンドルされている Apache を使用します。バンドルされている Apache のバージョンは 2.0.63 です。Apache のバージョンは httpd コマンドに -v オプションを付けて実行する事で確認出来ます。また file コマンドで httpd バイナリを確認すると "ELF 32-bt LSB executable" とありますので、32bit でコンパイルされている事が分かります。pflags コマンドで Apache のプロセスを調べると "data model = _ILP32" とありますのでやはり 32bit バイナリである事が分かります。Apache は httpd.conf に最低限の設定をして svcadm コマンドで起動しました。
# /usr/apache2/bin/httpd -v
Server version: Apache/2.0.63
Server built: Nov 21 2008 13:18:55
# file /usr/apache2/bin/httpd
/usr/apache2/bin/httpd: ELF 32-bit LSB executable 80386 Version 1 [FPU],
dynamically linked, stripped
# pflags `pgrep -nx httpd` | head
849: /usr/apache2/bin/httpd -k start
data model = _ILP32 flags = ORPHAN|MSACCT|MSFORK
/1: flags = ASLEEP accept(0x100,0x8186494,0x81864b4,0x1)
# svcadm enable apache2
Solaris に付属の Apache 2.0.63 を使用します
負荷生成ツール
HTTP ダウンロード負荷のシミュレートには Apache 2.0 に付属する ab ユーティリティを使用します。具体的には、下記のシェルスクリプトを作成し実行しました。ab を 100 並列で実行し、各 ab プロセスがサーバ上のコンテンツ 1 ファイルに対応しています。全部で 100 ファイル (001, 002, 003, ..., 100) をダウンロードし続けます。
また、事前にこのスクリプトを何度か実行し、Apache のログや snoop コマンドを使用して HTTP のエラーが発生していない事を確認しています。
# cat ab.sh
#!/bin/zsh
for i in {001..100}
do /usr/apache2/bin/ab -c 16 -n 100000 -k http://web/${i} &
done
ab を 100 並列で負荷生成します
性能測定ツール
ネットワークの帯域使用量の測定に dladm コマンドを使用します。送信データ量を 10Gbps に近付ける事が目標ですので、obytes のカラムを見ます。obytes は Output Bytes の略で、送信したデータ量をバイト単位で表示します。オプションは show-dev -s を付けてネットワークインターフェイスデバイスの統計情報を表示させています。-i 1 で統計情報を取得する間隔を 1 秒に設定しています。nxge0 は今回使用する 10GbE のインターフェイスです。ipackets ... oerrors の行は出力のヘッダです。
# dladm show-dev -s -i 1 nxge0
ipackets rbytes ierrors opackets obytes oerrors
nxge0 89729 5388591 0 172151 247017464
...
dladm コマンドの opackets で測定します
Apache 2.0.63 の測定結果
まずはこの状態でどのくらい性能が出るかを dladm コマンドで測定します。obytes を見てみると大体 230MB/s なので 1.9Gbps くらいの性能が出ている事が分かります。ネットワークインターフェイスは 10Gbps まで出す能力がありますので、期待した性能には程遠い結果となってしまいました。何故この結果になってしまったのか Solaris の解析ツールを使用して調査してみます。
# dladm show-dev -s -i 1 nxge0
...
ipackets rbytes ierrors opackets obytes oerrors
nxge0 89729 5388591 0 172151 247017464 0
ipackets rbytes ierrors opackets obytes oerrors
nxge0 89252 5359773 0 173132 248454662 0
ipackets rbytes ierrors opackets obytes oerrors
nxge0 84931 5102931 0 175147 251212868 0
ipackets rbytes ierrors opackets obytes oerrors
nxge0 83052 4987575 0 174098 249920422 0
ipackets rbytes ierrors opackets obytes oerrors
nxge0 90112 5410779 0 169266 242766400 0
ipackets rbytes ierrors opackets obytes oerrors
nxge0 91136 5469942 0 170997 245360749 0
ネットワーク帯域を使い切れていない事が分かりました
vmstat
システムの解析は vmstat から始めます。以下の出力を見てみると、一番右の cpu の id のカラムの値が 73-72 になっています。id は CPU の空き時間の割合を表していますので、70% 以上の時間で CPU が使用されていない事が分かります。これは CPU リソースが余っている状態です。次に memory の free のカラムを見てみます。free はメモリの空き領域のサイズと考えてほぼ問題ありません。free はキロバイト表示ですので 28GB 程メモリが余っています。先ほど dladm コマンドの出力ではネットワークの帯域は余っていました。vmstat の結果を見ると CPU もメモリも余っている様です。リソースが余っているという事はサーバにまだまだ余力があるという事かもしれません。
# vmstat 1 ... kthr memory page disk faults cpu r b w swap free re mf pi po fr de sr s0 s1 s2 -- in sy cs us sy id 7 0 0 25326452 29827836 0 6 0 0 0 0 0 0 0 0 0 556 67634 18259 0 26 73 7 0 0 25326452 29827836 0 6 0 0 0 0 0 0 0 0 0 705 69389 18383 1 27 72 7 0 0 25326444 29827820 0 6 0 0 0 0 0 0 0 0 0 608 70864 18482 0 27 72 7 0 0 25326444 29827820 0 6 0 0 0 0 0 0 0 0 0 575 69910 18249 1 27 72 7 0 0 25326444 29827820 0 6 0 0 0 0 0 0 0 0 0 669 70137 18259 1 27 72
CPU とメモリも余っている事が判明しました
クライアントを増やしてみる
サーバのリソースを使い切るほど負荷が掛かっていないのかもしれないので、負荷を倍に増やして再度測定してみました。先ほどの ab.sh をもう一つ起動して測定した結果が以下の出力になります。obytes は大体 235MB/s を示していますので凡そ 1.9Gbps です。負荷を増やす前も 1.9Gbps でしたので、負荷の量を増やしてもスループットは変わっていない様です。どうやらサーバに余力がある訳では無さそうです。
# dladm show-dev -s -i 1 nxge0
...
ipackets rbytes ierrors opackets obytes oerrors
nxge0 78849 4731633 0 171089 245548675 0
ipackets rbytes ierrors opackets obytes oerrors
nxge0 77824 4670925 0 172243 247202319 0
ipackets rbytes ierrors opackets obytes oerrors
nxge0 78848 4733058 0 172843 248038608 0
ipackets rbytes ierrors opackets obytes oerrors
nxge0 79872 4794003 0 173978 249708411 0
ipackets rbytes ierrors opackets obytes oerrors
nxge0 78848 4732563 0 173718 249306384 0
ipackets rbytes ierrors opackets obytes oerrors
nxge0 78848 4731672 0 173770 249404258 0
負荷が足りていない訳ではない様です
ディスク I/O を見てみる
ネットワークの帯域もメモリも CPU も余っていましたので、次はディスク I/O を見てみます。I/O の観察には iostat コマンドを使用します。iostat のオプションは -xnCmpz 1 がお薦めです。-z オプションを付けると、全てのカラムの値が 0 だった場合は出力を省略します。沢山ディスクがある時に -z を付けると出力が見やすくなるのでお薦めです。それ以外のオプションの意味はマニュアルページをご覧下さい。
iostat の出力を見てみると、%w のカラムが 0 または表示されていない（つまり 0）事が分かります。%w は I/O リクエストの実行待ちをしているキューが何 % 埋まっているかを示しています。通常、%w が出ていたら I/O ボトルネックと判断していますが、現時点では I/O はボトルネックにはなっていない様です。
# iostat -xnCmpz 1
...
extended device statistics
r/s w/s kr/s kw/s wait actv wsvc_t asvc_t %w %b device
0.0 1.0 0.0 16.0 0.0 0.0 0.0 0.1 0 0 c0
0.0 1.0 0.0 16.0 0.0 0.0 0.0 0.1 0 0 c0t0d0
0.0 1.0 0.0 16.0 0.0 0.0 0.0 0.1 0 0 c0t0d0s0 (/)
extended device statistics
r/s w/s kr/s kw/s wait actv wsvc_t asvc_t %w %b device
extended device statistics
r/s w/s kr/s kw/s wait actv wsvc_t asvc_t %w %b device
extended device statistics
r/s w/s kr/s kw/s wait actv wsvc_t asvc_t %w %b device
extended device statistics
ディスク I/O はボトルネックになっていませんでした
fsstat
fsstat でファイルシステムの I/O も見てみると、ZFS の read は 220MB/s ほど発生している様です。コンテンツファイルが ZFS のキャッシュに載っている為、物理 I/O として iostat で検知出来なかったと思われます。この場合は少し寄り道になってしまいましたが、色々なコマンドを試してみると思わぬ結果が得られる場合があります。
# fsstat zfs 1
new name name attr attr lookup rddir read read write write
file remov chng get set ops ops ops bytes ops bytes
0 0 0 110K 0 222K 10 38.5M 308G 0 0 zfs
0 0 0 51 0 102 0 28.4K 227M 0 0 zfs
0 0 0 81 0 162 0 27.6K 221M 0 0 zfs
0 0 0 48 0 96 0 27.4K 219M 0 0 zfs
0 0 0 78 0 156 0 26.8K 214M 0 0 zfs
ここまでのまとめ
ネットワーク帯域も CPU もメモリもディスクも足りている様です。リソースは足りていますが、余ったリソースを上手く使い切れない理由が何かありそうです。もう少し解析を続けて、その原因を探ってみたいと思います。
mpstat
マルチプロセッサの使用状況を見る為に mpstat を実行します。mpstat を使用すると、各プロセッサコア単位（ストランドがある場合はストランド単位）で CPU の状態を把握する事が出来ます。今回は 8 コアのマシンを使用していますので、出力は 8 行ずつ表示されます。一番左のカラムがプロセッサ番号で、今回使用したシステムでは 0 から順に番号が振られています。ここで 7 番のプロセッサの表示を見てみると、sys のカラムの値が 100 になっている事が分かります。これは CPU 7 番がシステム処理の為に使い切られている状態です。カーネル空間で何らかのシングルスレッドの処理が CPU 7 番を占有しており、他の処理を待たせている事が予想出来ます。この sys の発生源を突き止められれば、処理性能を上げる事が出来るかもしれません。
# mpstat 1 ... CPU minf mjf xcal intr ithr csw icsw migr smtx srw syscl usr sys wt idl 0 6 0 0 370 138 3796 22 1077 681 0 14748 1 24 0 75 1 0 0 0 41 0 4073 25 1062 597 0 9778 1 17 0 82 2 0 0 0 19 0 891 4 292 565 0 8023 1 14 0 85 3 0 0 0 26 0 2374 10 656 738 0 15472 1 24 0 75 4 0 0 96 13 9 904 3 233 623 0 6796 1 11 0 88 5 0 0 0 31 3 1468 13 482 628 0 10173 1 17 0 82 6 0 0 0 156 13 4240 125 736 294 0 6819 0 13 0 87 7 0 0 0 27 12 0 0 0 15 0 0 0 100 0 0
シングルスレッドの処理がボトルネックになっていました
prstat -mL 1
プロセスが発生させている sys の量を見る為に prstat -mL を実行します。PROCESS のカラムがプロセス名で httpd という名前のプロセスは Apache のプロセスです。SYS のカラムの値が各プロセスが発生させている sys の割合です。httpd が発生させている sys は 0.1% と非常に低い値になっている事が分かります。mpstat で見つけた sys の原因はプロセスでは無さそうです。
# prstat -mL 1
...
PID USERNAME USR SYS TRP TFL DFL LCK SLP LAT VCX ICX SCL SIG PROCESS/LWPID
3717 root 0.7 8.3 0.0 0.0 0.0 0.0 91 0.0 22 18 4K 0 prstat/1
3714 root 0.1 0.1 0.0 0.0 0.0 0.0 100 0.0 1 0 9 0 dladm/1
3130 webservd 0.0 0.1 0.0 0.0 0.0 0.0 100 0.0 4 0 61 0 httpd/1
2287 webservd 0.0 0.1 0.0 0.0 0.0 0.0 100 0.0 4 1 64 0 httpd/1
2518 webservd 0.0 0.1 0.0 0.0 0.0 0.0 100 0.0 4 0 64 0 httpd/1
3175 webservd 0.0 0.1 0.0 0.0 0.0 0.0 100 0.0 4 0 64 0 httpd/1
1298 webservd 0.0 0.1 0.0 0.0 0.0 0.0 100 0.0 4 0 64 0 httpd/1
1606 webservd 0.0 0.1 0.0 0.0 0.0 0.0 100 0.0 4 1 64 0 httpd/1
3528 webservd 0.0 0.1 0.0 0.0 0.0 0.0 100 0.0 4 0 64 0 httpd/1
2806 webservd 0.0 0.1 0.0 0.0 0.0 0.0 100 0.0 4 0 59 0 httpd/1
1584 webservd 0.0 0.1 0.0 0.0 0.0 0.0 100 0.0 4 0 64 0 httpd/1
3498 webservd 0.0 0.1 0.0 0.0 0.0 0.0 100 0.0 4 0 64 0 httpd/1
プロセスは sys の直接的な原因ではありませんでした
intrstat 1
プロセス以外の sys の発生源はカーネルサービスです。intrstat でインタラプト処理の CPU 使用率を見てみます。device のカラムがインタラプトを発生させているデバイス名です。右側は CPU 毎に統計情報がまとめられています。%tim が各 CPU 毎、デバイス毎に消費された CPU 時間の割合です。CPU 7 番で nxge#0 がほぼ 100% の CPU を使用している事が分かります。これがボトルネックになっていた為に他のリソースを十分に使えなかったと考えて間違い無さそうです。
# intrstat 1
...
device | cpu0 %tim cpu1 %tim cpu2 %tim cpu3 %tim
-------------+------------------------------------------------------------
aac#0 | 0 0.0 0 0.0 0 0.0 0 0.0
ahci#0 | 0 0.0 0 0.0 0 0.0 0 0.0
e1000g#0 | 0 0.0 0 0.0 0 0.0 0 0.0
e1000g#1 | 0 0.0 0 0.0 0 0.0 0 0.0
ehci#0 | 0 0.0 0 0.0 0 0.0 0 0.0
nxge#0 | 0 0.0 0 0.0 0 0.0 0 0.0
pcie_pci#6 | 0 0.0 0 0.0 0 0.0 0 0.0
uhci#0 | 0 0.0 0 0.0 0 0.0 0 0.0
uhci#1 | 0 0.0 0 0.0 0 0.0 0 0.0
uhci#2 | 0 0.0 0 0.0 0 0.0 0 0.0
uhci#3 | 0 0.0 0 0.0 0 0.0 0 0.0
device | cpu4 %tim cpu5 %tim cpu6 %tim cpu7 %tim
-------------+------------------------------------------------------------
aac#0 | 0 0.0 0 0.0 0 0.0 0 0.0
ahci#0 | 0 0.0 2 0.0 0 0.0 0 0.0
e1000g#0 | 0 0.0 0 0.0 15 0.0 0 0.0
e1000g#1 | 0 0.0 0 0.0 1 0.0 0 0.0
ehci#0 | 4 0.0 0 0.0 0 0.0 0 0.0
nxge#0 | 0 0.0 0 0.0 0 0.0 12 96.1
pcie_pci#6 | 0 0.0 0 0.0 0 0.0 0 0.0
uhci#0 | 4 0.0 0 0.0 0 0.0 0 0.0
uhci#1 | 0 0.0 1 0.0 0 0.0 0 0.0
uhci#2 | 0 0.0 1 0.0 0 0.0 0 0.0
uhci#3 | 0 0.0 2 0.0 0 0.0 0 0.0
sys の発生源は nxge0 でした
ここまでのまとめ
ネットワーク、CPU、メモリ、ディスクのリソースは余っています。nxge のシングルスレッドの処理が性能の足枷になっていました。
ネットワークチューニング
ここで nxge を使用しているシステムでよく使われるチューニングを施してみます。以下のパラメータを /etc/system に設定しました。主に DMA と IP ドライバの並列化を行う事によって nxge を並列で動く様に設定しています。
* nxge ring tuning set nxge:nxge_tx_ring_size=2048 set nxge:nxge_rbr_size=2048 * IP tuning set ip:ip_squeue_fanout=1 set ip_squeue_soft_ring=1 set ip:ip_soft_rings_cnt=16 * MSI/X tuning set ddi_msix_alloc_limit=16 set pcplusmp:apic_multi_msi_max=16 set pcplusmp:apic_msix_max=16 set pcplusmp:apic_intr_policy=1 set nxge:nxge_msi_enable=2 * DLD tuning set dld:dld_opt=2
nxge の並列度を高める為のチューニングを施しました
再測定
以下がチューニングを施して再測定した結果です。性能は 447MB/s つまり 3.6Gbps まで上がりました。先ほどは 1.9Gbps でしたので、ほぼ倍に向上しました。何が原因で性能が上がったのかを詳しく調べて行きたいと思います。10Gbps に更に近付けるヒントがあるかもしれません。
# dladm show-dev -s -i 1 nxge0
...
ipackets rbytes ierrors opackets obytes oerrors
nxge0 109373 6567435 0 328385 471276327 0
ipackets rbytes ierrors opackets obytes oerrors
nxge0 107817 6472485 0 327270 469703245 0
ipackets rbytes ierrors opackets obytes oerrors
nxge0 107435 6450159 0 327234 469638194 0
ipackets rbytes ierrors opackets obytes oerrors
nxge0 107314 6443598 0 327231 469628076 0
ipackets rbytes ierrors opackets obytes oerrors
性能が倍になりました！
リソースの使用状況を確認
まず intrstat で nxge のインタラプト処理がどうなったのかを見てみます。先ほどは CPU 7 番に nxge が張り付いていましたが、今度は全ての CPU に分散されています。nxge のボトルネックが解消された事が性能向上につながっている様です。
# intrstat 1
...
device | cpu0 %tim cpu1 %tim cpu2 %tim cpu3 %tim
-------------+------------------------------------------------------------
aac#0 | 0 0.0 0 0.0 0 0.0 0 0.0
ahci#0 | 0 0.0 0 0.0 0 0.0 0 0.0
e1000g#0 | 13 0.0 0 0.0 0 0.0 0 0.0
e1000g#1 | 0 0.0 0 0.0 0 0.0 0 0.0
ehci#0 | 0 0.0 0 0.0 0 0.0 0 0.0
nxge#0 | 2830 5.6 2922 6.8 2131 3.8 2648 4.3
pcie_pci#6 | 0 0.0 0 0.0 0 0.0 0 0.0
uhci#0 | 0 0.0 0 0.0 0 0.0 0 0.0
uhci#1 | 0 0.0 0 0.0 0 0.0 0 0.0
uhci#2 | 0 0.0 0 0.0 0 0.0 0 0.0
uhci#3 | 0 0.0 0 0.0 0 0.0 0 0.0
device | cpu4 %tim cpu5 %tim cpu6 %tim cpu7 %tim
-------------+------------------------------------------------------------
aac#0 | 0 0.0 0 0.0 0 0.0 0 0.0
ahci#0 | 0 0.0 0 0.0 0 0.0 1 0.0
e1000g#0 | 0 0.0 0 0.0 0 0.0 0 0.0
e1000g#1 | 0 0.0 0 0.0 0 0.0 0 0.0
ehci#0 | 3 0.0 0 0.0 0 0.0 0 0.0
nxge#0 | 2947 5.7 2351 3.6 3026 5.3 2859 4.6
pcie_pci#6 | 0 0.0 0 0.0 0 0.0 0 0.0
uhci#0 | 3 0.0 0 0.0 0 0.0 0 0.0
uhci#1 | 0 0.0 0 0.0 0 0.0 0 0.0
uhci#2 | 0 0.0 0 0.0 0 0.0 0 0.0
uhci#3 | 0 0.0 0 0.0 0 0.0 1 0.0
nxge は奇麗に分散されました
リソースの使用状況を再確認
再び vmstat でシステムリソースの概要を見てみます。id の値が 0 になっており、CPU を使い切っている事が分かります。run queue(kthr の r) も溢れており、CPU の取り合い状態になっています。CPU の使われ方を見ると sys(CPU の sy) が 99% 使っている様です。faults の sy の値が高いのでシステムコールが大量に発生している事が分かります。
kthr memory page disk faults cpu r b w swap free re mf pi po fr de sr s0 s1 s2 -- in sy cs us sy id 107 0 0 28499508 30640068 24 7 0 0 0 0 0 0 1 0 0 798992 111397 50799 1 99 0 105 0 0 28499508 30640060 0 6 0 0 0 0 0 0 0 0 0 801334 111615 50349 1 99 0 106 0 0 28499508 30640060 0 6 0 0 0 0 0 0 0 0 0 801775 111234 51349 1 99 0 100 0 0 28499508 30640060 0 7 0 0 0 0 0 0 0 0 0 807296 111576 54869 1 99 0 107 0 0 28499508 30640048 0 6 0 0 0 0 0 0 0 0 0 803047 111479 52951 1 99 0
今度は CPU ボトルネックになりました
誰がシステムコールを発行しているのか
先ほどと同様、prstat コマンドを使用してシステムコールを発生させているプロセスを探します。PROCESS と SYS のカラムを見ると、各 httpd が 10% 以上の値を示しており、今度は Apache が sys を大量に発生させている事が分かります。
# prstat -mL 1
...
PID USERNAME USR SYS TRP TFL DFL LCK SLP LAT VCX ICX SCL SIG PROCESS/LWPID
1355 webservd 0.3 16 0.0 0.0 0.0 0.0 1.4 82 100 806 3K 0 httpd/1
1467 webservd 0.3 12 0.0 0.0 0.0 0.0 1.7 86 96 324 2K 0 httpd/1
1366 webservd 0.3 11 0.0 0.0 0.0 0.0 1.1 87 70 558 2K 0 httpd/1
1449 webservd 0.2 11 0.0 0.0 0.0 0.0 1.2 88 63 478 2K 0 httpd/1
1465 webservd 0.2 10 0.0 0.0 0.0 0.0 1.2 88 82 501 2K 0 httpd/1
1469 webservd 0.2 10 0.0 0.0 0.0 0.0 3.0 87 98 300 2K 0 httpd/1
1410 webservd 0.2 10 0.0 0.0 0.0 0.0 0.5 89 50 659 1K 0 httpd/1
1384 webservd 0.2 10 0.0 0.0 0.0 0.0 2.1 88 66 366 2K 0 httpd/1
1357 webservd 0.2 9.6 0.0 0.0 0.0 0.0 2.1 88 70 367 2K 0 httpd/1
1444 webservd 0.2 9.4 0.0 0.0 0.0 0.0 0.1 90 45 591 1K 0 httpd/1
CPU を消費しているのは Apache が発行しているシステムコールでした
どんなシステムコールが発生しているのか
Apache のプロセスが発生させているシステムコールの種類を truss -c コマンドを使用して調べます。httpd のプロセス ID を指定して truss -c を実行すると、そのプロセスが発行したシステムコールの名前、処理時間、発行回数等を見る事が出来ます。一番左の syscall のカラムが発行されたシステムコールの名前です。seconds のカラムが、そのシステムコールの処理に費やした秒数、calls のカラムは何回発行されたかを示しています。詳しく見てみると、時間、回数共に read と write が多い様に見えます。どんな read / write なのかもう少し細かく見てみる事にしましょう。
# truss -c -p `pgrep -nx httpd`
^C
syscall seconds calls errors
read .553 8355 4
write .623 8365 21
close .000 14
getpid .000 7
writev .000 7
llseek .000 7
pollsys .000 25
stat64 .000 7
open64 .000 14
-------- ------ ----
sys totals: 1.178 16801 25
usr time: .043
elapsed: 56.240
システムコールは read と write が多い様です
システムコールの詳細
システムコールの詳細は -c オプションを付けずに truss コマンドを実行すると見る事が出来ます。出力が多くなりますので、-o オプションで一旦ファイルに書き出しています。また、-E オプションでシステムコールの実行に費やした秒数も合わせて表示させています。
各行を詳しく見て行きます。最初のカラムはシステムコールの実行に費やした時間を示しています。次のカラムがシステムコール名です。出力内容から、発行されているシステムコールは read -> write -> read -> write の順に規則正しく並んでいる事が分かります。括弧の中はシステムコールに渡された引数です。最初の read システムコールには 10, "¥0¥0¥0¥0¥0¥0¥0¥0¥0¥0¥0¥0".., 8192 が引数として渡されています。それぞれの引数の意味は Solaris のマニュアルページから調べる事が出来ます（read システムコールのマニュアルページを表示するコマンドは "man -s 2 read" です）。最初の引数は読み込み元のファイルディスクリプタ番号で、ファイルディスクリプタ 10 番からデータを読み出していることになります。次の引数は読み込んだ内容を保存するバッファへのポインタですが、truss の出力は自動的にバッファに書き込まれた内容の抜粋を表示してくれます。この出力では "¥0¥0¥0¥0¥0¥0¥0¥0¥0¥0¥0¥0" で始まるデータが読み出された事を意味しています。3番目の引数は読み出しバイト数です。この場合は 8192 bytes のデータを一度に読み出そうとしている事になります。"=" の右側の値はシステムコールの返り値です。read システムコールの返り値は実際に読み出されたバイト数なので 8192 bytes のデータが実際に読み出された事が分かります。次の行の write も同じ様にマニュアルを参照しながら見て行くと、ファイルディスクリプタ 257 番に "¥0¥0¥0¥0¥0¥0¥0¥0¥0¥0¥0¥0" で始まるデータを 8192 bytes 書き出している事が分かります。
# truss -o /var/tmp/truss-httpd-01.dump -E -vall -p `pgrep -nx httpd` ^C # less /var/tmp/truss-httpd-01.dump 0.0001 read(10, "¥0¥0¥0¥0¥0¥0¥0¥0¥0¥0¥0¥0".., 8192) = 8192 0.0001 write(257, "¥0¥0¥0¥0¥0¥0¥0¥0¥0¥0¥0¥0".., 8192) = 8192 0.0001 read(10, "¥0¥0¥0¥0¥0¥0¥0¥0¥0¥0¥0¥0".., 8192) = 8192 0.0001 write(257, "¥0¥0¥0¥0¥0¥0¥0¥0¥0¥0¥0¥0".., 8192) = 8192 0.0000 read(10, "¥0¥0¥0¥0¥0¥0¥0¥0¥0¥0¥0¥0".., 8192) = 8192 0.0001 write(257, "¥0¥0¥0¥0¥0¥0¥0¥0¥0¥0¥0¥0".., 8192) = 8192 0.0001 read(10, "¥0¥0¥0¥0¥0¥0¥0¥0¥0¥0¥0¥0".., 8192) = 8192 0.0001 write(257, "¥0¥0¥0¥0¥0¥0¥0¥0¥0¥0¥0¥0".., 8192) = 8192 0.0001 read(10, "¥0¥0¥0¥0¥0¥0¥0¥0¥0¥0¥0¥0".., 8192) = 8192 0.0001 write(257, "¥0¥0¥0¥0¥0¥0¥0¥0¥0¥0¥0¥0".., 8192) = 8192 0.0001 read(10, "¥0¥0¥0¥0¥0¥0¥0¥0¥0¥0¥0¥0".., 8192) = 8192 0.0000 write(257, "¥0¥0¥0¥0¥0¥0¥0¥0¥0¥0¥0¥0".., 8192) = 8192 0.0001 read(10, "¥0¥0¥0¥0¥0¥0¥0¥0¥0¥0¥0¥0".., 8192) = 8192 0.0001 write(257, "¥0¥0¥0¥0¥0¥0¥0¥0¥0¥0¥0¥0".., 8192) = 8192 0.0001 read(10, "¥0¥0¥0¥0¥0¥0¥0¥0¥0¥0¥0¥0".., 8192) = 8192 0.0001 write(257, "¥0¥0¥0¥0¥0¥0¥0¥0¥0¥0¥0¥0".., 8192) = 8192
特定のファイルディスクリプタに対して 8KB の read / write が発生しています
ファイルディスクリプタの特定
truss の結果、ファイルディスクリプタ 10 番と 257 番に read / write が発生している事が分かりました。もう少し詳しく見てみるため pfiles コマンドでそれぞれのファイルディスクリプタが何のファイルと関連付けられているかを調査します。
出力の一番左がファイルディスクリプタ番号です。出力内容を詳しく見てみると 10 番のファイルディスクリプタは /data/web/001 というファイルに関連付けられており、257 番は IP Address 192.168.0.1 の 80 番ポートと 192.168.0.2 の 41043 番ポートを結ぶソケットに関連付けられています。/deta/web/001 は最初に用意したコンテンツファイルです。192.168.0.1 は HTTP サーバの IP Address で 192.168.0.2 はクライアントマシンの IP Address です。つまりコンテンツファイルを read して、クライアント宛のソケットに write していたという事が分かります。なお、今回は mkfile コマンドでコンテンツファイルを作成しましたが、truss コマンドで表示されていた "¥0¥0¥0¥0¥0¥0¥0¥0¥0¥0¥0¥0" は mkfile で作成したコンテンツデータの中身です。
# pfiles `pgrep -nx httpd`
1481: /usr/apache2/bin/httpd -k start
Current rlimit: 65536 file descriptors
0: S_IFCHR mode:0666 dev:284,0 ino:6815752 uid:0 gid:3 rdev:13,2
O_RDONLY|O_LARGEFILE
/devices/pseudo/mm@0:null
1: S_IFCHR mode:0666 dev:284,0 ino:6815752 uid:0 gid:3 rdev:13,2
O_WRONLY|O_CREAT|O_TRUNC|O_LARGEFILE
/devices/pseudo/mm@0:null
2: S_IFREG mode:0644 dev:30,64 ino:69373 uid:0 gid:0 size:106441
O_WRONLY|O_APPEND|O_CREAT|O_LARGEFILE
/var/apache2/logs/error_log
3: S_IFDOOR mode:0444 dev:293,0 ino:60 uid:0 gid:0 size:0
O_RDONLY|O_LARGEFILE FD_CLOEXEC door to nscd[134]
/var/run/name_service_door
4: S_IFIFO mode:0000 dev:282,0 ino:527 uid:0 gid:0 size:0
O_RDWR|O_NONBLOCK
5: S_IFIFO mode:0000 dev:282,0 ino:527 uid:0 gid:0 size:0
O_RDWR
6: S_IFREG mode:0644 dev:30,64 ino:69374 uid:0 gid:0 size:17803723
O_WRONLY|O_APPEND|O_CREAT|O_LARGEFILE
/var/apache2/logs/access_log
7: S_IFREG mode:0600 dev:288,2 ino:4096490321 uid:0 gid:0 size:0
O_RDWR|O_CREAT|O_EXCL|O_LARGEFILE
8: S_IFREG mode:0644 dev:288,3 ino:4096490265 uid:0 gid:0 size:0
O_WRONLY|O_CREAT|O_EXCL|O_LARGEFILE
9: S_IFREG mode:0766 dev:181,65538 ino:5 uid:0 gid:0 size:10485760
O_RDONLY|O_LARGEFILE
/data/web/001
10: S_IFREG mode:0766 dev:181,65538 ino:5 uid:0 gid:0 size:10485760
O_RDONLY|O_LARGEFILE
/data/web/001
256: S_IFSOCK mode:0666 dev:291,0 ino:40525 uid:0 gid:0 size:0
O_RDWR
SOCK_STREAM
SO_REUSEADDR,SO_KEEPALIVE,SO_SNDBUF(49152),SO_RCVBUF(49152),IP_NEXTHOP(0.192.0.0)
sockname: AF_INET6 :: port: 80
257: S_IFSOCK mode:0666 dev:291,0 ino:16917 uid:0 gid:0 size:0
O_RDWR|O_NONBLOCK
SOCK_STREAM
SO_REUSEADDR,SO_KEEPALIVE,SO_SNDBUF(49152),SO_RCVBUF(49640),IP_NEXTHOP(232.193.0.0)
sockname: AF_INET6 ::ffff:192.168.0.1 port: 80
peername: AF_INET6 ::ffff:192.168.0.2 port: 41043
コンテンツファイルを読んでソケットに書き出していました
現状のまとめとチューニングの候補
これまで分かった事を簡単にまとめてみますと、CPU がボトルネックになってネットワーク帯域が使えていませんでした。CPU を消費しているのはプロセスが発生させているシステムコールです。システムコールは Apache が発行した read と write でした。read と write のサイズはどちらも 8KB です。
この状態で考えられるチューニングの一つに Apache のチューニングがあります。httpd.conf は殆どデフォルトのままでしたので MPM の設定等をもう少し練り直せば性能が向上するかもしれません。また、Apache は Solaris にバンドルされているバイナリをそのまま使用しましたが、Sun Studio の最適化機能を活用してコンパイルし直すと効果があるかもしれません。read, write のサイズは 8KB 単位でしたが、コンテンツのサイズは 10MB ですので、read / write のサイズがもっと大きくなる様にソースコードを書き換えれば I/O の抜けが良くなるかもしれません。また Jumbo Frame Packet 機能を使用して、パケットのサイズを大きくしてあげれば、更にスループットを稼げます。
今回はボトルネックが出易い様に古いマシンを使用しています。CPU がボトルネックになっていますので、よりクロックの高いマシンやよりコア数の多いマシンにアップグレードすれば、チューニングをする事無く性能を上げる事が可能です。Sun SPARC Enterprise T5440 はこういった用途に最適でしょう。
紙面が尽きてしまったため続きは 次回 に持ち越しますが、この後まだまだ性能は上がりますので、ご期待下さい。
Posted at 06:20午後 2 22, 2009 by Daisuke Homma in Sun | 投稿されたコメント[0]
Subscribe!