推測するな、計測せよ　フォージビジョンのエンジニアが教えるパフォーマンス改善に必要なログ分析

Webサービスのパフォーマンスとログ分析

山口正徳氏：山口と言います。よろしくお願いします。今日はみなさんお集まりいただきありがとうございます。なんと現時点で参加いただいているのが303人。こんなに多くの方に参加してもらえるとは思ってもいなかったので、変な緊張感に包まれています。カミカミなところとかがあったりしても、そこはあたたかい目で見てもらえればなと思います。

また、ログ分析勉強会のオンライン配信は JAWS-UG 札幌の三浦一樹さんに協力いただています。配信環境の設営、配信レイアウトの作成などをすべてボランティアで対応いただきました。ありがとうございます。

私からは『Webサービスのパフォーマンスとログ分析（入門編）』というところで。Webサービスのパフォーマンスを改善するのに、どういうログをどう分析していけばいいのかについて、少し入り口のところをお話しできればなと思っています。

山口って誰やねんっていう人もいると思いますので、少し自己紹介します。Twitterは@kinunoriというIDでやってます。普段はAWS関連の仕事をやっています。その仕事もあってか、AWSの認定資格をいくつかと、あとPMPだったり認定スクラムマスターなのでプロジェクト管理などもやってます。

セキュリティも昔、少しかじっていたことがあって、CISSPをもっています。もっと昔はログ分析ツールの製品担当とかをやっていました。それが4年前くらいですかね。現在はAWS上で構成されたWebサービスの開発とか構築を行っています。

パフォーマンスチューニングに必要なログとその分析方法

本日は、Webサービスのパフォーマンスチューニングのために必要と考えるログとその分析方法について少しお話します。ここでは、先ほど釜山さんがお話してくれた中の一部である /var/log/messagesとか、そういったテキストに起こされるものだけではなくてデバッグツールの情報や、継続するコマンドの実行結果等も含めてシステムの状態を可視化するための情報をトータルでログと表現しています。

Webサービスのパフォーマンスチューニングをどうすればいいのかというところとかは今回は話さないです。

このテーマ設定をしたときにちょっと後悔したところもあって、パフォーマンス―チューニングをした結果、またそれを測って、それをどうやって分析するのかまでやらないと中身なくなっちゃうんじゃないのかなというところはあったんですけども。20分じゃ話しきれなくなってしまうので、それはまた次の機会に残しておきたいなと思います。

Webサービスのパフォーマンスチューニングといえば。知る人は知っていると思いますが、ISUCONですね。ISUCONは私、7回から9回まで参加をしていまして。最高で予選1日目の8位で、最後はフェイルで予選落ちするというところが最高結果になっています。

日々の業務とかISUCONで実践した内容とかをまとめて、Webサービスのパフォーマンスチューニングを行うために必要と考えるログとその分析方法として今回お話させていただきます。

注意事項ですが、この資料、今日お話する内容なんですけれども、闇雲に実行すると環境の負荷を上げる原因になる可能性があります。本番環境でいきなりポーンと実行すると怒られるので、まずテスト環境で確認することを推奨します。

いきなりMySQLでスロークエリで0で設定して全部のクエリログを取ろうとすると、ディスクの負荷とかもかかってそもそもパフォーマンスが出なくなるので、本番環境ではやめてください。

パフォーマンスチューニングの定義なんですけども、ここで私が定義しているものとしては一定の条件を満たしたうえで処理できるHTTPのリクエスト数を多くする。HTTPSのリクエスト数を多くするというかたちです。あと一定の条件を満たしたうえでHTTPレスポンスを返す速度を速くする。この2つを満たすものをパフォーマンスチューニングの定義としています。

一定の条件って何って言うと、画像の最適化とかサイズを縮小するというところが認められない、HTML、CSSとかも書き換えられないという環境とか。レスポンスはリクエストが来てから何秒以内に返してください、何ミリセック以内に返してくださいとかっていうような内容をここで一定の条件としています。

パフォーマンスチューニングも「推測するな、計測せよ」

これは参考というか有名な言葉ですけれども。「推測するな、計測せよ」と。パフォーマンスチューニングとかもそうなんですね。チューニングするとき、いきなり推測でものごとを実行したとしてもうまくいかないです。

ちゃんと最初に計測をして、そのうえでボトルネックはどこなのかというのをはっきりする。ボトルネックはどこなのかというところを特定したうえでスピードハックをしていきましょう。そのうえでさらに計測するというかたちですね。

なので、計測せずにいきなり推測をしてコードを書き換えるとか、アプリケーションのチューニングを行うというのは、それはあまりよくないアンチパターンです。ちゃんと計測しましょう。

計測を行ったうえでのパフォーマンスチューニングなんですけども。まず通常の業務上のリクエスト状況とかでもいいです。もしくはなにかしらのベンチマーカーを使って計測を行うとかでもいいです。なにかしら今の指標というものがあるはずなので、そのうえで計測を行いましょう。

リクエストをいくつかシミュレーションをして行うとか。Apache Benchを使うとかでもありだと思いますね。その上でパフォーマンスが出ない原因を特定する。特定したうえで改善を適応して、さらに計測をして改善効果があるかどうかを確認する。これを繰り返していくことが、パフォーマンスチューニングだと思っています。

そのうえで今日話す内容は、パフォーマンスが出ない原因を特定するため、そのためにどういうログをどう分析していこうかという話になります。

対象とする構成のイメージは、俗に言うWebの三層構成ですね。クライアントがあって、そこからWebサーバーがあって、裏にアプリケーションサーバーがあって、DBがいると。

WebサーバーはApacheだったりNginxだったりh2oだったり。アプリケーションはNodeだったりとかJava、Perl、Rubyとかいろいろあると思います。DBはMySQL、ポスグレ、SQL Serverとかもあると思います。もしくはキャッシュとかNoSQLとかもあると思います。

あとはクラウドだとマネージドサービスだったりとか。サーバーを立てて構成するものとかもいろいろあると思いますが。そこらへんはあまり深く考えずに、汎用的なかたちで見ていきましょう。

クライアントから見たログを確認する

まず1つ目なんですけども、クライアントから見たログを確認するというところです。ログといってもクライアントなので、どうやって見るかと言うと、有名なのはChromeのDevToolですよね。

ここでサイトにアクセスして、これはヤフーさんのサイトなので完全に爆速というか最適化されているような構成を取ってるので、あんまり意味はないですけれども。

左側にあるHTTPステータスと赤く囲っているところと、右側にあるリクエストにかかった時間ですね。ここでどこにどれだけのボトルネックがあるかを見ていきます。

この画面はあまり深掘りしないですけれども、左側のいずれかをクリックすると、そこで実際にどういうタイミングで、どれくらいトータルで時間がかかったかというようなタイムの列に対して、もう少し深掘りした情報も見ることができます。

例えばでかい画像をここで表示していると、そこだけで2、3秒かかったりとかする。そうなるとその画像を最適化、縮小して配信の速度を上げるとか。あとはクライアント側のキャッシュを使って、なるべくサーバーに毎回リクエストが飛んでこないようにする方法もあると思います。

これが、クライアントから見たときにWebサービスがどう見えるかという、1つの指標になるかなというところです。

Webとアプリケーションのログを確認する

続いてWebとアプリケーションのログを確認するところですね。WebというのはWebとアプリケーションの2つをミックスしています。まずWebサーバのログですけれども。よく使うものとしてApacheとNginxがあると思います。

上がApacheの2.2系のアクセスログと、下がNginxの1.16系のアクセスログですね。だいたいAWS上でEC2でインストールすると、こういうバージョンのものが入ります、というのを並べています。

左側にどのIPアドレスから接続があったとか、どのコンテンツに対してリクエストがあって、リクエストのメソッドは何が使われていてとか。ステータスコードは何を返していてとかですね。あとはクライアントのブラウザは何を使っているとかが出てきたりします。

Nginxのほうも同じですね。Nginxは、例えばここに3441という別の指標の数字が入ったりとかしますが、時間がかかるものがあったりします。あとはサイズを表現するものもあったりします。ほかの部分に関してはほぼ同じですかね。若干フォーマットは違うものも、俗に言うcombinedログのフォーマットになっています。

ここからどうパフォーマンスを見るかということなんですけれども、このままだとなかなかわかることは少ないです。どの時間にどうリクエストがあったかくらいしかわからないです。それをどうしていこうかというところが次に書いてありますが。

まずNginxの場合ですけれども。Nginxのログの設定ですね。nginx.confの中のlog_formatというのがありますが、ここに"$request_time"を入れることで、そのリクエストから実際にレスポンスを処理するまでの処理時間が表示されます。

Apacheの場合は、log_formatに%Dだとか%Tを追加すると出ます。%Dの場合はナノセックで出るので、細かい時間まで見ることが可能になります。

これを入れてあげてNginxをリロードをしてあげると、指定したログファイルにこの中身が出てきます。この場合だとhttp_x_forwarded_forの前に入ってくるので、このブラウザのユーザーエージェントの情報と、今-（ハイフン）になっているところ、この間に数字として入ってくるイメージです。

分析するのにparseに労力がかかることも…

実際にリクエストしたものがこちらです。image.pngのリクエストに対してのログですけれども。約0.14秒かかっていますね。

これで、どのリクエストに対してどれくらい時間がかかっているかがわかります。なので、これですべてのリクエストに対してログを取っていくと、それぞれどのparseに対してリクエストがあったらどれだけの時間がかかるとか、すなわちどこにボトルネックがあるのかがわかります。

ただこの状態だとけっこう苦労することが多くて。実際に使ってみるとわかるというか、苦労している人も多いと思うんですけれども、"$request_time"を追加するだけだと分析するのにparseがけっこう必要だったりします。

これ好きなところに入れられるんですよね。今このケースだとx_forwarded_forとユーザーエージェントの間に入れてますが、エンジニアによっては、ほかのところに入れたりということもあります。

parseを書くときは、基本的に正規表現で書かなければいけないのですが、違うところに入っていると正規表現が壊れるので、それをまた直してあげなきゃいけなかったりします。なので、複数の人たちで調査するときには困ることがあります。

あとは開発が必要で追加のフィールドを追加したときにも、同じように正規表現の影響を受けます。調査のための課題が残ります。もちろん独自にカスタマイズせずにこのままで取りますとなれば、fluentdとかで手間をかけずにparseすることも可能です。

課題解決はLTSVを使うこと

この課題にどう対応していくかというところで、LTSVを使います。Labeled Tab separated Valuesというもので、はてなさんで使われているログフォーマットです。けっこう前ですね、2013年くらいに話題になったもので。

当時はてなのCTOだった田中さんが書いたブログで、そこからこれけっこういいんじゃないかってWeb界隈でみんな使い出して。今ではパフォーマンスチューニングするときとか、普段の分析でもLTSVを使うことがあります。

LTSV化したログは下です。このままだとけっこう可読性が先ほどのcombinedログと比べて見づらかったりとかするんですが。ラベルが付いていて、タブ区切りで、かつコロンでセパレートされているので、すごくParseしやすいです。

行指向で作られているので、なにかしら列を追加をしたとしても、それをparseするための正規表現が壊れたりとかしないです。なので非常に扱いやすいことが特徴になっています。扱いやすい、イコール分析や統計を取りやすいということです。

LTSVにしたときに、リクエストタイムとか出てきたりしますけれども、私はこういったものを使ってラベルを付けて分析しています。

Nginxを設定するにはどうすればいいかと言うと、こういったかたちでlog_format ltsvとして入れてあげる。これでリロードしてあげるとLTSV形式で追記されます。

ちょっと書いてないですけど、combinedログ入れてる状態で途中でLTSVすると、同じファイルに違うフォーマットで書かれて死ぬので。一旦アクセスログは古いものは退避して、新しいもので書き換えてあげたほうがいいかなと思います。

統計情報を取って改善の対象を決める

LTSVを使いました。そのあと統計情報取りましょうというときに出てくるのが、alpというツールですね。kataribeというツールもありしますが、私はalpを使います。

alpはAccess Log Parserというもので、GitHubで公開されているOSSになります。GOで動くOSSです。こちらを使って統計を取ることで、アクセスログからどのリクエストに対してどれくらい時間がかかっているのかというのを見ることができます。

この場合だと、例えばcssだったりjsがminifyされているので、あんまり処理時間的はかかってないよねと。これを例えばNginxでキャッシュして配信したとしてもあんまり効果は見込めないでしょう。

それよりもこのpngファイルとか、あとchannelっていうところの下のリクエスト、これに時間がかかっているので、ここを改善することでパフォーマンス向上につなげることができるんじゃないかと見ることができます。

これで例えばパフォーマンス改善したあと、もう1回同じように取ると、ここのMAXの数字とかSUMの数字が下がっていれば、その分リクエストに対する処理時間が短くなっていることがわかります。

基本はレスポンス処理に時間がかかっているリクエスト×リクエスト数で対象を決めます。時間とカウントの数で、どれくらいトータルかかっているかというところが出てくるので、そこでどこを改善するかの対象を決めるのがよろしいかなと思います。