とあるサービスの高負荷チューニング日記

とあるサイトのとあるサービス機能について相談を受けた。高負荷が原因で 95% の確率でリクエストを無処理で NULL を返す仕様になっているとかなんとか。
正直 95% が結果が NULL なサービスは存在価値そのものから疑う必要があるわけだが、必要な機能らしい。

と言うわけでサーバへログインしてみた。
高負荷サイトのチューニングについて以前記述した手順でサイトの状態を把握していきます。

1. top をみて上位に張り付いているプロセスを確認しつつ CPU or I/O のどちらが原因か判別

top で apache の幾つかのプロセスが CPU を食いつぶしていることが確認できます。メモリ不足というわけではなさそうです。

top - 19:11:41 up 294 days,  9:51,  4 users,  load average: 1.66, 1.18, 1.05
Tasks: 416 total,   3 running, 412 sleeping,   0 stopped,   1 zombie
Cpu(s): 75.2% us,  0.1% sy,  0.0% ni, 24.7% id,  0.0% wa,  0.0% hi,  0.0% si
Mem:   8173080k total,  7784328k used,   388752k free,    47060k buffers
Swap:  8191992k total,   696000k used,  7495992k free,  6184208k cached

  PID USER      PR  NI  VIRT  RES  SHR S %CPU %MEM    TIME+  COMMAND    
 9304 apache    25   0 70728  46m 3644 R 99.0  0.6  12:10.90 httpd      
 9300 apache    25   0  111m  89m 3644 R 99.7  1.1  13:36.71 httpd      
 9298 root      16   0  6424 1404  852 R  0.3  0.0   0:00.13 top        
    1 root      16   0  4772  276  244 S  0.0  0.0   0:40.47 init       
    2 root      RT   0     0    0    0 S  0.0  0.0   0:06.12 migration/0
    3 root      34  19     0    0    0 S  0.0  0.0   0:00.17 ksoftirqd/0

2. ps を使ってプロセスの状態を確認して(T),(D)の状態から CPU or I/O のどちらが原因か判別

top で確認した CPU を食いつぶしている apache のプロセスの実行時間が 10 分以上を超えるのが確認できます。怪しさ満点です。

root      9320  0.2  0.0  6424 1404 pts/2    S+   19:13   0:00 top
root      9322  0.0  0.0  5452  816 pts/7    R+   19:13   0:00 ps aux
root     11773  0.0  0.0     0    0 ?        S    Sep12   0:50 [pdflush]
apache    9304 94.0  0.6 75612 52216 ?       R    18:53  12:14 /usr/local/apache2/bin/httpd -k start
apache    9300 99.5  0.5 72312 48900 ?       R    18:19  13:40 /usr/local/apache2/bin/httpd -k start
apache   12249  0.0  0.0 76732 2612 ?        S    Oct21   0:00 /usr/local/apache2/bin/httpd -k start
apache   12252  0.0  0.4 212576 37804 ?      S    Oct21   0:00 /usr/local/apache2/bin/httpd -k start
apache   12253  0.0  0.4 212576 37804 ?      S    Oct21   0:00 /usr/local/apache2/bin/httpd -k start
apache   12254  0.0  0.4 206676 33072 ?      S    Oct21   0:00 /usr/local/apache2/bin/httpd -k start
apache   12255  0.0  0.4 206676 33072 ?      S    Oct21   0:00 /usr/local/apache2/bin/httpd -k start

3. vmstat で procs の r, b の数、swap の si, so の状態、I/O の bi, bo の状態を確認
4. sar を使って os の状態をさらに詳しく確認

I/O 関連の数値は健全な値を示しているので、iowait 負荷問題ではなく、CPU 負荷問題であることが判別できました。かつ CPU 負荷の原因は apache が原因であることもわかりました。

00:00:01          CPU     %user     %nice   %system   %iowait    %steal     %idle
・・・中略・・・
15:10:02          all     97.84      0.00      1.88      0.00      0.00      0.28
15:10:02            0     93.59      0.00      6.24      0.00      0.00      0.17
15:10:02            1     99.48      0.00      0.21      0.00      0.00      0.31
15:10:02            2     99.39      0.00      0.39      0.00      0.00      0.22
15:10:02            3     98.91      0.00      0.67      0.00      0.00      0.42
15:20:01          all     91.85      0.00      2.03      0.00      0.00      6.12
15:20:01            0     76.52      0.00      6.79      0.00      0.00     16.69
15:20:01            1     99.52      0.00      0.38      0.00      0.00      0.09
15:20:01            2     99.40      0.00      0.40      0.00      0.00      0.21
15:20:01            3     91.98      0.00      0.55      0.00      0.00      7.47

5. apache のログと conf を確認

apache のログと conf を確認して、どんなアクセスが原因かを推測してみます。結局このサーバは、apache2 上で mod_perl を動作させていて、とある１つの CGI を動作させているだけであることがわかりました。つまりチューニングポイントは、その CGI プログラムであることが確定しました。

6. プログラムのチューニング

プログラムの構成を確認してみます。何をしているプログラムかも初めて知ることになるわけですが、指定の URL を渡すと、URL のコンテンツをクロールして取得し、html を解析して <img> タグを抽出して width が大きい画像の URL を返す CGI であることがわかりました。

プログラムの構成は概ね下記のような構成になっていました。

解析の結果、他サイト（外部サイト）を GET でクロールした際に、Content-Type が text/html 以外の場合（つまりバイナリデータ）に html 解析時に仕込まれた Encode::decode() を実行すると、CPU が高負荷になることが判明しました。
Content-Type の判定ロジックを追加して、http://xxx/hoge.pdf などの入力を受け取った際に何も処理せず値を返すことで、CPU 高騰を回避することに成功しました。劇的な効果があったので、確率 95% の部分も良い数値に改善することが可能でしょう。加えて LWP::UserAgent を使っていたので、max_size() メソッドで response のサイズにも制限を加えれば完璧です。
ロジック修正後のプログラム構成は概ね下記のような構成になりました。

障害調査プログラムはこんなコードを書いて解析しました。引数に pdf な url を入力すると cpu が高騰することがご確認いただけるかと思います。

use utf8;
use LWP::UserAgent;
use Encode::Guess qw/euc-jp shiftjis utf8/;
use Encode ();
use Data::Dumper;

# perl test.pl http://xxx 1
my $bugfix = 0 || $ARGV[1];
my $url = $ARGV[0] or die "input url\n";
print $url, "\n";

# LWP 制限
my $ua = LWP::UserAgent->new;
$ua->timeout(5);
$ua->max_size( 1 * 1024 * 1024 ) if $bugfix;

# コンテンツ取得
my $req = HTTP::Request->new( GET => $url );
my $res = $ua->request($req);
die $!, "\n" unless $res->is_success;
print $res->header('Content-Type'), "\n";
die "ContentType error\n" if $res->header('Content-Type') !~ /text/ && $bugfix;

my $html = $res->content;
print "guess_encoding", "\n";

# 文字コード変換
my $guess = Encode::Guess::guess_encoding($html);
if ($guess) {
    if ( ref $guess ) {
        $html = Encode::decode( $guess->name(), $html );
    }
    else {
        $html = Encode::decode( 'utf-8', $html );
    }
}
else {
    $html = Encode::decode( 'utf-8', $html );
}
print "decode", "\n";

# img 抽出
my @imgs;
foreach ( $html =~ /<img\s[^>]+>/g ) {
    push @imgs, $_;
}
print Dumper \@imgs;

今のお仕事は全然プログラムのお仕事じゃないので、たまに perl コードを書く機会があると、とっても楽しいです。ｗ