この記事はアピリッツの技術ブログ「DoRuby」から移行した記事です。情報が古い可能性がありますのでご注意ください。
メロスは激怒した。必ず、かの30秒も掛かるAPIを高速化せねばならぬと決意した。メロスにはボトルネックがわからぬ。メロスは、クライアントエンジニアである。XCodeを使い、仮想iOSと遊んで暮して来た。けれどもボトルネックに対しては、人一倍に敏感であった。きょう未明メロスは電子の海を出発し、SSHで海外へ飛び、三千里はなれた此このシラクスのサーバーにやって来た。メロスには父も、母も無い。女房も無い。十六の、内気な二次元の妹と二人暮しだ。この妹は齢二十になるかの邪智暴虐の王を倒した勇者を花婿として迎える事になっていた。結婚式も間近かなのである。メロスは、それゆえ、泣きながらも仕事に励んでいたのだ。
メロスには竹馬の友があった。セリヌンティウスである。今は此のシラクスのサーバーで、サーバーエンジニアをしている。その友を、これから不正に手にいれたroot権限で訪ねてみるつもりなのだ。久しく逢わなかったのだから、訪ねて行くのが楽しみである。歩いているうちにメロスは、サーバーの様子を怪しく思った。タイプがやけに重い。もう既に日も落ちて、あちらの時刻は暗いだろうけれども、全体が、やけに重い。のんきなメロスも、だんだん不安になって来た。セリヌンティウスの痕跡を発見し、何かあったのか、追跡した。二年まえに此のサーバーに来たときは、夜でもサーバーは穏やかで、軽かったはずだった。管理者からは中々その痕跡が分からなかった。メロスは両手でコマンドをゆすぶって追跡を重ねた。セリヌンティウスは、あたりをはばかるように、わずかながら痕跡を残していた。
#このAPIは、時間がかかっている
「なぜかかるのだ。」
//悪心を抱いている、というのですが、誰もそんな、悪心を持っては居りませぬ。ただ、コードがアレなだけです。
「たくさんのSQLをよんでいるのか。」
=begin
はじめはアクセスしたユーザーを。
それから、御自身の設定ファイルを。
それから、メモ化されていないマスタデータを。
それから、たくさんのユーザーデータを一つずつ参照して。
それから、新たに作成されるデータを念のため一つ一つバリデーションをかけて。
それから、キャッシュの更新を。
=end
「おどろいた。セリヌンティウスは乱心か。」
<!-- ユーザー数が急激に増えたことに加えて、仕様変更が重なったことが原因。
このごろは、それによってぐちゃぐちゃになったAPIそのものの振る舞いもおかしくなっている。
レスポンスが30秒を超えることも全くおかしくない。
-->
コメントを読んで、メロスは激怒した。「呆れたAPIだ。生かして置けぬ。」
メロスは、単純な男であった。アクセスログを残したままで、のそのそソースのディレクトリにはいって行った。たちまち彼は、問題のAPIを読んだ。調べて、メロスの脳裏からはデータベースにインデックスが貼られていない疑惑が出て来たので、胸騒ぎが大きくなってしまった。メロスは、セリヌンティウスに直接電話をした。
「このデータベースは何をするつもりであったか。言え！」暴君メロスは静かに、けれども威厳を以もって問いつめた。そのセリヌンティウスの顔は蒼白で、眉間の皺は、刻み込まれたように深かった。
「元からそうだったのだ」とセリヌンティウスは悪びれずに答えた。
「元から？」メロスは、憫笑した。
「仕方の無いやつじゃ。おまえには、わしの孤独がわからぬ。」セリヌンティウスは悲しそうに返した。
「言うな！」とメロスは、いきり立って反駁した。「人の心を疑うのは、最も恥ずべき悪徳だ。セリヌンティウスは、ユーザーの期待さえ疑って居る」
「疑うのが、正当の心構えなのだと、わしに教えてくれたのは、おまえだ。自分のコードは、あてにならない。コードは、もともとバグのかたまりさ。信じては、ならぬ。」セリヌンティウスは落着いて呟き、ほっと溜息をついた。「わしだって、平和を望んでいるのだが。」
「なんの為の平和だ。自分の地位を守る為か。」こんどはメロスが嘲笑した。「罪の無いサーバーを熱くして、何が平和だ。」
「だまれ」セリヌンティウスは、さっと顔を挙げて報いた。「口では、どんな清らかな事でも言える。わしには、コードのバグの奥底が見え透いてならぬ。おまえだって、いまに、威力業務妨害になってから、泣いて詫びたって聞かぬぞ。」
「ああ、セリヌンティウスは悧巧だ。自惚れているがよい。私は、ちゃんと死ぬる覚悟なんてない。さようなら」
ガチャ。
そんな事にならないように負荷テストはちゃんとしましょう。
その為のサーバーの性能を計るツールとして、JMeterというものがあります。
JMeterとは
一言で言えば、サーバーに負荷を掛け、パフォーマンスを測定する為のオープンソースです。
これを使えば、任意のAPIに対して秒間N回のリクエストを投げたりどの位の同時接続数までなら快適に動作するのか、どのAPIがボトルネック(ボトルネックではなく、ボルトネック、そんな風に呼んでいた時期が俺にもありました)なのかなど、様々な事を調べる事ができます。
それで、JMeterの基本的な扱い方に関しては色んな所に書いてある為、実際のテスト時に、役に立つような事を上げていきたいと思います。
CUIでの実行時に色々と条件を変えてテストしたい
基本的にJMeterでちゃんと負荷テストを行う時は、GUIからの実行ではなく、CUIからの実行になります。GUIで行わない理由は、そのGUIの処理そのもののせいで、より正確なデータが出力されないという事が理由です。
その時に、RampUpやSleep時間、メインスレッド数など様々な条件を変更して負荷をより正確に測っていく事もあると思いますが、その色々の設定を変更する際に、
・GUIを同時に開いてその設定を書き加えて、保存してCUIから実行とか、
・テスト計画ファイルであるJMXファイルを直接弄って編集(JMXファイルの中身はXMLなので、修正しようと思えばできる)とか、
そういう事は面倒臭いです。上記はある程度楽かもしれませんが、GUIを使えない別サーバーからの実行とかそんな事もありますし。
幸い、JMeterにはCUI実行時にコマンドライン引数を参照する仕組みがあるので、それを活用しましょう。
この上記のように、変数を指定する部分を${__P(変数名)}とする事によって、CUI実行時にそのコマンドライン引数を取ってきてくれるようになります。
コマンドライン引数の指定の仕方は、
-J変数名=値
といったように、文頭に-Jを付けて後は変数名と値を=で結ぶだけです。
上記のように、スレッド数(client)、Ramp-Up期間(ramp_up)、sleep時間(sleep)、メインループ回数(main_loop)を指定したいときは、以下のようになります。
>path/to/jmeter -n -t execute_jmeter_source.jmx -l output_result.jtl -Jclient=100 -Jmain_loop=20 -Jsleep=1000 -Jramp_up=300
※ -n : 非GUIモードで起動, -t : 実行ファイル名を指定, -l : 結果ファイル出力先を指定
※ Ramp-Up期間の単位はsec(秒)で、sleep時間の単位はmsec(ミリ秒)です。
……え？ こんな長いコマンド打つの面倒？
……シェルでも組みましょうか。
データをエクセルに纏める
上記のコマンドを終えると、output_result.jtlという結果ファイルが吐き出されます。
ただ、中身としてそれは実行した一つ一つのリクエストに対するデータがずらりと並んでいるCSVファイルであって、統計的にはデータを見れません。
HTMLでレポートを出力してくれるオプションもあるのですが、それではテストを複数回行った時の差分も分かりづらいです。
では、どうしたらいいか。
取り敢えず、GUIでJMeterを開いて、統計レポートの部分を出しましょう。
そこで参照で、出力されたjtlファイルを入れてやれば、リクエストの種別毎に平均値や中央値、90%lineなどを計算した上で結果をまとめてくれます。
※参照した時に元からそのGUIで実行したデータや前に参照したものがあると、それを上書きするのではなく加算してしまうので、必ず空っぽにしておきましょう。
これなら、どのAPIが問題なのか等が分かりやすく見えてきました。
そして、Save Table DataでCSVに出力しなおせば、ちゃんとリクエストの種別毎にデータをエクセルに纏める事ができます。
※文字はUTF-8で保存されるので、環境によっては文字化けします。なので、適した文字列にエンコードしなおしてあげる必要があります。Macなら、CSVファイルをテキストエディットで開いて複製、その複製を保存する時に文字コードをUTF-16に変換、とか。
負荷試験で掛かる時間を計算する
CPUが100%になっていない範囲、待ちなどが発生していない前提の話になりますが、負荷試験で掛かる時間は概算する事ができます。
まず、軽くテストを流してみて、メインループ内での1つのリクエスト単位での平均レスポンス時間を出します。
そうすると、
1回のメインループで掛かる時間 ＝ メインループ内のリクエスト数 × (メインループ内での1リクエスト辺りの平均レスポンス時間 + Sleep秒)
と計算できます。そして、メインループ外の処理がメインループに比べて小さければ、その1回のメインループで掛かる時間にメインループ数を掛ければ、それがスレッド一つで掛かる時間となります。
そして、最後に影響するのがRamp-Upです。
Ramp-Upは指定した数のスレッド全てが負荷テストを実行開始するまでの時間です。
スレッド数を10、Ramp-Upを60(秒)と設定した場合、6秒間に1スレッドずつテストを開始し、そして60秒が経った時に全てのスレッドが実行されている状態となります。
そこから考えると、
負荷試験に掛かる全体時間 = Ramp-Up + 最後のスレッドに掛かる時間
となります。そして、待ちが発生しない限りは最後のスレッドに掛かる時間と1スレッドの全体時間は変わらないので、
負荷試験に掛かる全体時間 = Ramp-Up + 1スレッドの全体時間
≒ Ramp-Up + メインループ数 * 1回のメインループで掛かる時間
≒ Ramp-Up + メインループ数 * メインループ内のリクエスト数 × (平均レスポンス時間 + Sleep秒)
と、出せます。
これでずっと画面に張り付いていなくとも、大体終わる時間がわかって、終わった後長らく放置しているような事もなく、他の事を出来たりします(当たると嬉しいのでそういう意味でも計算は楽しい)。
重い原因を調べる
さて、試験結果を出せるようになったところで、それが何故重いのかを調べる必要があります。
コードが悪いのか、サーバーの性能が足りないのか、それともサーバーの設定が悪いのか、IO負荷が酷いのか、待ち状態が発生しているのか、そもそものテストの条件が悪いのか……。
そんな時に役に立つのが、監視ツールです。監視ツールを駆使すれば、メモリやCPUの消費量、局所のみならず全体の軽量化にも大きな役割を果たせます。
まあ、こちらも調べれば色々と無料から有料のものまでたっぷりと出て行くのでそこからプロジェクトと相談して何をどう使っていくか決めていくべきでしょう。
後、簡単にメモリやCPUの状況を調べたいなら、その負荷を掛けている実サーバーでsarやらpsやらvmstatやらのコマンドを打てば色々と出せます。
実際触ってみてなどの所感
JMeterを触って2ヶ月ほどが経ち、こうして社内ブログに載せてみた訳ですが、少々触れてみた感想を。
編集手段が専用のGUIしかない事が辛い
レスポンスを受け取ってそれを次のパラメータの値として送る、とかもやったりしたのですが、それを自分はjavascript(複数の言語から選べる)で値をいじったり保存したりとして実装しました。
ただ、エラーが起きてもそれがどこの何行で起きているのか表示してくれなかったり、(postやputメソッドを送った時に形式をちゃんとヘッダの情報に付与しないときちんとパラメータが送れない事を知らなくて長い時間悩んだり)、動的にパラメータを作成しようと思ったらJavaオンリーで色々触れなくてはいけない事を知ったりと、色々と大変でした。
気づかなかったボトルネックに気付く事が出来た
ここはボトルネックじゃないだろーと思いながらもテストしてみたら酷く重い事になって、よくよく調べてみたら、データの紐付けがきちんとしていなくて取得するのに時間が掛かっていた、などという事もあったので盲点からのコードの見直しもできるようになります(全APIのリクエストを実装するのは……大変です)。
では、本番でパンクしないように適切な設計を考えながら負荷テストをしましょう。
▲参照元別にセッション数と構成比を視覚的に比較しやすくした表
