Linux環境下でのパフォーマンス問題調査
今、仕事で使っているパッケージ製品で、どうにもまったりと遅い画面操作があることに気付いたので、調査していました。今後の自分の参考情報として、作業記録を残しておくことにしました。
まずはtopコマンドで確認
OSのリソース状況確認をすれば、およそ検討はつくかなと作業を始めました。まあ、とりあえずは、topコマンドでも打っとくかということで。
[root]# top top - 15:35:28 up 9 days, 13:30, 2 users, load average: 0.88, 0.30, 0.14 Tasks: 296 total, 2 running, 294 sleeping, 0 stopped, 0 zombie Cpu(s): 2.3%us, 0.8%sy, 0.0%ni, 96.2%id, 0.0%wa, 0.0%hi, 0.2%si, 0.5%st Mem: 1048752k total, 1029212k used, 19540k free, 67160k buffers Swap: 1052248k total, 60k used, 1052188k free, 784108k cached PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND 7667 postgres 15 0 55684 33m 31m S 3.7 3.2 0:05.46 postgres 7492 apache 15 0 77076 39m 8440 S 1.7 3.8 0:02.76 httpd
しばらく、topを眺めていても、この状況は変わらりませんでした。ずっと、PostgreSQLが動いているようです。普段はtopコマンドの1位の座を何分間も独占するようなことはありません。でもCPUは使ってないし、、、LoadAverageも（1以下なので）全然問題なしですね。でも処理はまったりと続いているようです。
一応、sarコマンドも見ておこう
sarコマンドでも見てみました。ちなみに、「sar -P ALL」でCPU が複数ある場合にそれぞれ別に表示することができます。今時のサーバはほぼ確実にマルチコアなわけですから、単に「sar」としてしまうとCPUのコア数で割り算されたものになるため、負荷の状況が見えなくなってしまいます。*1
[root]# sar -P ALL 15時10分01秒 CPU %user %nice %system %iowait %steal %idle 15時20分01秒 all 0.07 0.00 0.05 0.00 0.01 99.87 15時20分01秒 0 0.09 0.00 0.07 0.01 0.01 99.82 15時20分01秒 1 0.05 0.00 0.03 0.00 0.00 99.92 15時30分01秒 all 0.02 0.00 0.02 0.00 0.00 99.96 15時30分01秒 0 0.02 0.00 0.02 0.00 0.00 99.95 15時30分01秒 1 0.02 0.00 0.02 0.00 0.00 99.96 15時40分01秒 all 1.88 0.00 0.90 0.01 0.33 96.88 15時40分01秒 0 2.78 0.00 1.66 0.02 0.46 95.08 15時40分01秒 1 0.99 0.00 0.14 0.01 0.19 98.68
やはり、sarコマンドの結果も、特に問題ないように見える。。。これはI/Oボトルネックか？
さらに、iostatで調べてみる
I/Oボトルネックかどうかを調べるために、iostatコマンドを打ってみました。ちなみに、「-x」オプションは付けるとディスクに関する詳細な情報が表示されていいと思います。
[root]# iostat -x -t 2 Linux 2.6.18-92.1.22.el5xen (sitedb01) 2010年10月28日 時間: 15時33分34秒 avg-cpu: %user %nice %system %iowait %steal %idle 2.24 0.00 1.00 0.00 0.50 96.26 Device: rrqm/s wrqm/s r/s w/s rsec/s wsec/s avgrq-sz avgqu-sz await svctm %util xvda 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 時間: 15時33分36秒 avg-cpu: %user %nice %system %iowait %steal %idle 2.00 0.00 1.00 0.00 0.50 96.51 Device: rrqm/s wrqm/s r/s w/s rsec/s wsec/s avgrq-sz avgqu-sz await svctm %util xvda 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 (↓ 重いと言う対象の画面の操作をした途端、以下のような変化が見られた) 時間: 15時33分41秒 avg-cpu: %user %nice %system %iowait %steal %idle 0.02 0.00 0.01 0.01 0.00 99.96 Device: rrqm/s wrqm/s r/s w/s rsec/s wsec/s avgrq-sz avgqu-sz await svctm %util xvda 0.01 0.94 0.12 0.63 1.93 12.62 19.38 0.00 3.85 0.47 0.04 時間: 15時33分43秒 avg-cpu: %user %nice %system %iowait %steal %idle 3.99 0.00 1.50 0.00 0.50 94.01 Device: rrqm/s wrqm/s r/s w/s rsec/s wsec/s avgrq-sz avgqu-sz await svctm %util xvda 0.00 38.81 0.00 12.44 0.00 409.95 32.96 0.00 0.00 0.00 0.00 時間: 15時33分45秒 avg-cpu: %user %nice %system %iowait %steal %idle 2.24 0.00 1.74 0.00 0.50 95.52 Device: rrqm/s wrqm/s r/s w/s rsec/s wsec/s avgrq-sz avgqu-sz await svctm %util xvda 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 時間: 15時33分47秒 avg-cpu: %user %nice %system %iowait %steal %idle 2.51 0.00 2.01 0.00 0.50 94.97 Device: rrqm/s wrqm/s r/s w/s rsec/s wsec/s avgrq-sz avgqu-sz await svctm %util xvda 0.00 36.50 0.00 20.50 0.00 456.00 22.24 0.01 0.29 0.10 0.20 時間: 15時33分49秒 avg-cpu: %user %nice %system %iowait %steal %idle 2.74 0.00 1.24 0.00 0.50 95.52 Device: rrqm/s wrqm/s r/s w/s rsec/s wsec/s avgrq-sz avgqu-sz await svctm %util xvda 0.00 69.65 0.00 22.89 0.00 740.30 32.35 0.00 0.00 0.00 0.00
「%iowait」が70％〜90％だったり、「avgqu-sz」が50とか100とかだったり、「%util」も90％台じゃないの？と予想していたのですが、そんなことも無く、これはどういうことだろう？確かに、対象の操作を行うと「wsec/s」「avgrq-sz」は変化して、その操作が終わるまでの数分間は高いままなのですが、これが原因？
継続調査
I/Oまわりの雰囲気はありつつ、明らかに変な値は出ていませんでした。原因は継続調査ということにしたいと思います。とりあえず、今分かっていることを書いておきます。
- 重い画面は数千件の他のデータに紐づいている。
- 他のデータとの紐付きがほとんど無いものはすぐ終わる。
- 従って、関連するデータ件数依存であることは明らか。
- なので、PostgreSQLの視点から調べる。めちゃくちゃな数のSQL発行があるのか？
- でもそうなら、iostatにもっと何かでるのではないのか？
- 仮想環境（VMWare）による影響はないか？
- もしや、NWまわり？確かにこの操作の時、外部サーバ通信している可能性はある。
