Perl Hackers Hub

第17回Webアプリケーションのパフォーマンス改善(1)

本連載では第一線のPerlハッカーが回替わりで執筆していきます。今回は面白法人カヤックでWebアプリケーションの運用、インフラを担当している藤原俊一郎さんで、テーマはWebアプリケーションのパフォーマンス改善です。

パフォーマンスチューニングとは

カヤックではWebアプリケーションはもちろん、ソーシャルゲームもサーバサイドではPerlでの実装を主に行っており、性能的な問題を改善したりトラブルシューティングをしたりすることが多くあります。本稿ではそこで得られた知見を、Webアプリケーションのパフォーマンスチューニング(性能改善)というお題でまとめます。

「Webアプリケーションのパフォーマンスチューニング」と言うと、具体的にはどのような作業を想像するでしょうか?「チューニング」「調整」という語感からか、OSやミドルウェアのパラメータを調整することを思い浮かべる人も多いと思います。

チューニングイベントの結果から

2011年からWebアプリケーションのチューニングイベントとして、チューニンガソン⁠、ISUCONというイベントが開催されています。チューニンガソンは、アプリケーションのコードに手を入れることがルール上許されていないため、OSやミドルウェアの設定を主に行うことになります。ISUCONは「なんでもあり」ということで、アプリケーションをどれだけ書き換えても最終的にベンチマーク計測で問題が発見されなければOKというルールでした。

この2つのイベントの結果をまとめると、興味深い傾向が見えてきます表1⁠。スコアの改善率が10倍以下のチューニンガソン#1~#3と、100倍以上のチューニンガソン#4およびISUCONに二分されます。チューニンガソン#4については上位2チームが飛び抜けたスコア(1,000以上)を残し、3位のスコアは23.95でした。リバースプロキシでのキャッシュ設定が有効に作用したため、スコアが大きく伸びたのだそうです

表1 各チューニングイベントのスコアと改善率
イベント名初期スコア優勝スコア改善率
チューニンガソン#1約120秒約22秒約6倍
チューニンガソン#2約0.8約3.7約5倍
チューニンガソン#3約21約60約3倍
チューニンガソン#4約2.5約1,351.5約500倍
ISUCON約800
クエリ/分
約90,700
クエリ/分
約100倍

大きな効果を上げるために

チューニンガソン#1~#3の改善率を見ると、アプリケーションや全体のアーキテクチャに手を入れないで改善できるのは最大でも10倍以下です。もちろん数倍速度が違えばサーバ台数を大きく減らせるので有意義なのは間違いないのですが、ISUCONやチューニンガソン#4のような飛躍的な高速化は望めないことがわかります。

つまりチューニングでは、単にパラメータ設定を変更するのみではなく、ボトルネックになっているコードやクエリ、アーキテクチャに的確に手を入れていくことで大きな効果を上げることができるのです。

ボトルネックの発見と解消が大事

システム全体の処理時間についてパレートの法則(経験則)を適用すると、⁠全体の処理時間の80%は20%の部分で発生している」ということになります。実際にシステム全体で一番ボトルネックになっている部分を解消しないことには、ほかの部分に手を入れても大きな効果を上げることはできません。

そのボトルネックはシステムによってまちまちです。データベースの設定であったり、非効率なSQLクエリであったり、行儀の悪いアプリケーションのコードであったり、時間がかかる外部APIの呼び出しだったりします。

以降では、そのボトルネックを発見するには具体的にどうすればよいのかを見ていきます。

システムの現状を知る

パフォーマンスチューニングが必要な場合、何らかの理由で「遅い」と認識しているわけですが、本稿ではサーバサイドのWebアプリケーションに対象を絞りますので、フロントエンド側での問題がないかを簡単に確認しましょう。

『ハイパフォーマンスWebサイト』では、次のように書かれています。

エンドユーザーの応答時間のうち、HTML文書のダウンロードにかかる時間は10%から20%にすぎない。残りの80%から90%はページ内のすべてのコンポーネントをダウンロードするのに消費される。

─⁠─ Steve Souders著/武舎広幸ほか訳
⁠ハイパフォーマンスWebサイト―高速サイトを実現する14のルール』
オライリー・ジャパン、2008年、p.5

Google ChromeのPageSpeed拡張などを利用し、フロントエンド側での問題がないか確認してください。

各種メトリクスの収集

フロントエンド側ではなく、サーバサイドのWebアプリケーションがレスポンスを返すまでの速度に問題があるという確信が得られたら、まず現状の把握を行います。

チューニングを行う場合の鉄則ですが、何を変更し、その結果どのように数値指標が変化したかを計測可能な状態にすることが大事です。計測できない状態でむやみに変更を行うと、改善どころか、かえって性能を落とすことになりかねません。

プロダクション環境では普通に行われていることと思いますが、MuninCactiZabbixGangliaCloudForecastなどのリソースモニタリングツールを利用し、各種の基本的な数値を収集、グラフ化します。

  • CPU使用率
  • メモリ使用率
  • ネットワーク帯域・パケット数
  • ディスクI/O
  • HTTPリクエスト数
  • データベース、KVSKey-Value Storeなどに対する発行クエリ数

レスポンスタイムの計測

Webアプリケーションへのリクエストに対してレスポンスタイムを計測して可視化することで、次のような現象を把握できます。

  • 突発的な現象で、短時間だけレスポンスタイムが悪化した
  • 日時が経つにつれて徐々に性能が劣化している
  • ある時点のデプロイ後、障害になるほどではないが性能劣化が認められる

死活監視として、特定URLのレスポンスに時間がかかり過ぎた場合に障害と見なすようなことは広く行われているでしょう。しかしそれだけでは、一部のリクエストのみ遅くなっていたり、全体の処理速度が徐々に遅くなっていったりする現象を把握できません。

チューニングする際の指標となるデータとして、レスポンスタイムを記録し可視化することをお勧めします。

nginxの設定例

Webサーバがnginxの場合、処理時間として$request_time、$upstream_response_timeをログに記録できます$request_timeはnginxがリクエストを受け取りはじめてからレスポンスをクライアントに返しきるまでの時間(小数点を含む秒数⁠⁠、$upstream_response_timeはnginxがリバースプロキシとして動作する場合に、プロキシ先からのレスポンスを得るまでの時間が記録されています。

それに加えてリスト1のように$upstream_addrも同時に記録することで、どのアプリケーションサーバに接続して何秒でレスポンスが得られたかをログから読み取ることができます。トラブル時には特定のアプリケーションサーバからのレスポンスのみが悪化するような場合もあるため、同時に記録するとよいでしょう。

リスト1 nginx.confの設定
log_format main
    '$remote_addr - $remote_user [$time_local] '
    '"$request" $status $body_bytes_sent '
    '"$http_referer" "$http_user_agent" '
    '"$request_time" "$upstream_response_time" '
    '"$upstream_addr"';

Apacheの設定例

WebサーバがApacheの場合、LogFormatの書式に%Dを使用することで処理にかかった時間(マイクロ秒単位)をログに記録できますリスト2⁠。

リスト2 httpd.confの設定(%Dの記録)
LogFormat "%h %l %u %t \"%r\" %>s %b \"%{Referer}i\" \"%{User-agent}i\" %D" combined_time

Apacheをリバースプロキシとして動作させた場合には、nginxの$upstream_response_time相当の処理時間を記録する方法がありません。代替として、アプリケーション側から処理時間をレスポンスヘッダにX-Runtime: 1.234などと出力してログに記録する方法がありますリスト3⁠。ただし、この数値にはWebサーバとアプリケーションサーバの通信にかかった時間が含まれないため、nginxの$upstream_response_timeと完全に等価ではありません。

PSGIで動作するアプリケーションでは、Plackに付属するPlack::Middleware::Runtimeを使用することで、簡単にX-Runtimeヘッダを出力できます。

リスト3 httpd.confの設定(%DとX-Runtimeヘッダの記録)
LogFormat "%h %l %u %t \"%r\" %>s %b \"%{Referer}i\" \"%{User-agent}i\" %D %{X-Runtime}o" combined_runtime

レスポンスタイムの可視化

ログファイルに記録しただけでは状態を一目で把握できないため、可視化を行いましょう。

多数のホストに記録されたログファイルを収集、マージして解析するのはとても面倒な作業のため、日次で各ホストからscpやrsyncで集約したあとに解析、レポート作成という手段をとることも多いでしょう。そんなときはFluentdを利用すれば、リアルタイムにログを収集し、解析、グラフ化まで行うことができます。

Fluentd でアクセスログをパースし、numericcounterでレスポンスタイムの値ごとにグループ化し、GrowthForecastZabbixなどのメトリクス収集ツールに送信することで、全体のレスポンスタイムが一目でわかるグラフを作成できます。

リスト1の設定でnginxから出力したアクセスログをパースし、$request_timeをZabbixへ送信する例はリスト4のようになります。

リスト4 fluentd.conf
<source>
  type tail
path /var/log/nginx/access.log
  tag access_log
  format /^(?<host>[^ ]*) [^ ]* (?<user>[^ ]*) [(?<time>[^]]
*)] "(?<method>S+)(?: +(?<path>[^ ]*) +S*)?" (?<code>[^ ]*)
(?<size>[^ ]*) "(?<referer>[^"]*)" "(?<agent>[^"]*)"
"(?<request_time>[^"]*)"/ 実際は1 行
  time_format %d/%b/%Y:%H:%M:%S %z
</source>
<match access_log>
  type numeric_counter
  unit minute
  tag numcount.response_time
  count_key request_time
  pattern1 0_10ms 0 0.01
  pattern2 10_100ms 0.01 0.1
  pattern3 100_500ms 0.1 0.5
  pattern4 500_1000ms 0.5 1
  pattern5 1_2s 1 3
  pattern6 3_5s 3 6
  pattern7 6_9s 6 10
  pattern8 over_10s 10
</match>
<match numcount.**>
  type zabbix
  zabbix_server localhost
  host www.example.com
  name_key_pattern .*m?s_percentage
</match>

この例では、ログファイルに記録されたレスポンスタイムを1分ごとに、10ミリ秒未満、10ミリ秒以上~100ミリ秒未満、100ミリ秒以上~500ミリ秒未満、500ミリ秒以上~1秒未満……などとグループ化しています。レスポンスタイムの推移をほぼリアルタイムに(ログが発生してから1分程度の遅れで)把握できるため、運用に非常に役立ちます図1⁠。

図1 レスポンスタイムの可視化
図1 レスポンスタイムの可視化

<続きの(2)こちら。>

おすすめ記事

記事・ニュース一覧