GREE Engineering

Varnishのログにアクセスしてみよう!

Varnishのログにアクセスしてみよう!

こんにちは、Service Reliabilityチームのいわなちゃん(@xcir)です。チーム名が読みづらいのでSRやSレアと呼ばれたりもしています。レアリティが上がるように頑張って行きたいと考えています。

前回は「Varnishでテストコードを書こう!」という記事を書いたので、今回はGREE Advent calendar 2013の17日目も兼ねてVarnish Cache(以下Varnish)のログを読んだり加工してみたりしようと思います。

また、使用したVersionは3.0.3です。

Varnishのログのしくみ

Proxyでアクセスログを取得したいというのはよくあると思います。通常のミドルウェアでは設定ファイルで出力ファイル名を決めたりします。しかし、Varnish本体(varnishd)の設定ではそのような項目はありません。

では、Varnishはログを出していないのか?というとそうではなく、共有メモリ(Varnish Shared memory Log 以下VSL)上にログを出力しています。そしてvarnishncsaなどのコマンドでVSLを読み込んでファイルに書き込んだり標準出力したりします。

</vsl-mw-varnish

ではなぜこのような仕組みになっているのでしょうか?一番の理由はパフォーマンスです。
例えばApacheのアクセスログはリクエストのたびにファイルに書き込みを行うため、高リクエストかつi/oに余裕がない場合は、そこがボトルネックになったりします。(BufferedLogsを有効にするとパフォーマンスが上がったりしますよね)
Varnishの場合はそのような操作をしないためログ出力がボトルネックになりません。そしてVarnishがVSLに吐き出すログは非常に多くの情報が含まれています。リクエスト・レスポンスヘッダなどはもちろんの事、どのようなAction(vcl_missなど)を通過したかなどもわかります。
また、オプション(vcl_trace)を有効にした場合、どの分岐(if文)を通過したかなども保存されます。そして膨大なログをパフォーマンスを損なわずにアクセスログの形(varnishncsa)やレスポンスタイムとヒット率のヒストグラム(varnishhist)で整形しているわけです。もちろんフィルタリングもできるので、たとえば404だけを抜き出すことも非常に簡単に行えます。

生ログを読んでみよう(varnishlog)

VSLで出力されている全情報を見る際に便利なのがvarnishlogです。
以下はwgetで叩いてみた時のログです

リクエストのヘッダやレスポンスのヘッダなどが見えたりしますがどのように読めばいいのか解説します。

トランザクション番号 タグ データの流れ データ
11 TxStatus c 200

ログは4つの部分に分かれています。
それぞれ解説します。

トランザクション番号
番号が同一の場合は同一のHTTPのトランザクションであることを示します。あくまでリクエストのグループではなくトランザクションのグループなのでClient<->VarnishとVarnish<->Backendでは同じリクエストでもトランザクションが違います。

タグ
このデータがどのようなアクティビティなのかを示しています。例えばReqStartはリクエストの開始を意味します。
またPrefixにRx・Txが付くものにはそれぞれ意味があります。

Rx Varnishが受け取ったデータ
Tx Varnishが送信したデータ

データの流れ
Varnishがどことデータのやりとりをしているかを示しています。

c clientに関するデータ
b backendに関するデータ

データ
実際のデータになります。

これらを図解すると以下の様な感じになります。
data

これらを考えていくつかのタグとデータの流れの組み合わせで何を示しているかを表にしてみました

データの流れ タグ 意味
c Backend 使用するバックエンドを示す
[backendのTrx] [director/backend] [backend w/index]
c VCL_call どのアクションを通過したか
[通過アクション名] [(VCL_Returnがない場合)returnで指定したもの]
c VCL_Return vcl中でreturn(XXXX)した際のXXXXの内容
c VCL_trace optionのvcl_traceをonの場合に出力。VCLのどの行を通過したかを示す
[VRT_Count番号] [行数].[行頭からの文字数]
c SessionOpen セッションを開いたことを示す
[clientのIP] [clientのポート] [LISTEN]
c ReqStart リクエストの処理を開始したことを示す
[clientのIP] [clientのポート] [req.xid]
c Hit キャッシュヒットした
[ヒットしたobjectのxid]
c Hash Objectのハッシュ生成に使った文字列
[hash_dataの引数]

またVCLでの変数と一緒に扱えるのは以下です

データの流れ タグ vclでの変数
c ObjResponse obj.response
c ObjProtocol obj.proto
c ObjHeader obj.http
c RxRequest req.request
c RxURL req.url
c RxProtocol req.proto
c RxHeader req.http
c TxResponse resp.response
c TxStatus resp.status
c TxProtocol resp.proto
c TxHeader resp.http
b RxResponse beresp.response
b RxStatus beresp.status
b RxProtocol beresp.proto
b RxHeader beresp.http
b TxRequest req.request
b TxURL bereq.url
b TxProtocol bereq.proto
b TxHeader bereq.http

そして先程の生ログからvcl_callとVCL_Returnをピックアップして読むと

という経路で処理されたのがわかります。
これほどの情報がデバッグフラグをOnにすることなく、本番で稼働しているvarnishから取得できるのは非常に便利だと思います。弊社本番環境でもピークタイムに特に気にせずvarnishlogを叩いたりしていますが問題ありません。

VSLにアクセスしてみよう

さて、varnishでlogを読むにはvarnishlogやvarnishhistやvarnishncsaなどの別のコマンドを使います。先に書いたとおり、これらはVSLからログを読み込んで加工やフィルタリングして出力しています。これらはコマンドはAPI経由でVSLにアクセスしています。そこでPythonを使って簡単にアクセスする方法を説明します。
今回は拙作のVSLにアクセスするpython-varnishapiを使用します。

コード

出力

非常に簡単にvarnishlogと同じ出力が得られました。これを使えば自由な計測を作ることができると思います。
拙作ですがvarnishlogをデバッグする際にどうアクションが呼ばれて、変数がどのような状態かを調べたかったため
vsltransというログを整形するツールを作りました。
vsltrans
このようなものも作れますし、たとえばドメイン別・ディレクトリ別のヒット率の計測ツールもお手軽につくれます。

VSL-Query Expressions(おまけ)

2014Q1でリリースされるかも?と言われているVarnish4ですが、先日technology preview1(以下TP1)が出ましたので、変更点の1つであるログ関係の話をしようと思います。
これはTP1での話で正式リリース時には変更がある可能性がありますのでご注意ください。また、現時点で本番投入はオススメできません。

Varnish4ではログを取る仕組み自体(VSLを通して外部コマンドから読み取る)については変更はありませんが、libvarnishapiのバージョンが1.1から1.3に上がり、ログ関係の新機能が追加されました。
一番大きいのはVSL-Query Expressionsというもので、簡単に言うとログの絞り込みに式が使えます。例えば、現在のversionのvarnishlogだけで複数の条件で絞り込みを行うのは難しいですがVarnish4では非常に簡単に行うことができます。
例えば以下はuser-agentにiPhoneを含みexample.netへのアクセスでミスヒットしたリクエストを出力した例です。

簡単に複数の条件で絞り込みができました。
他にも1秒以上かかったリクエストだけ、ESIのサブリクエストでかかった時間での絞り込みなども可能です。

また、だいぶ表示が変わった?と思われる人もいると思いますが半分正解です。
ログのグループ分けができるようになり以下の4種類があります。

Session

クライアントからの接続のOpen~Closeまでのトランザクションをグループ化したものです

ログのprefixの* ** ***ですがネストしていることを表現しています。
上記ログの場合は以下のとおりです。

また、注目すべきタグにLinkとBeginがあります。例えばリクエスト処理中のバックエンドを呼び出した場合はLink bereq XXXXとなり、それに対応するBegin bereq XXXXがあります。非常にわかりやすくなっています。

ちなみにkeep-aliveでやりとりした場合は

と同一Sessionで3回のリクエストを処理したことがわかります。

Request

上のSessionでのやりとりを除いたものです。

VXID

Session・Requestはネストの情報(* **…)が付与されていましたが、その情報が抜けたものです。

終了したトランザクションから表示するので、深いとこから表示されていきます。

Raw

Varnish3までのフォーマットと同じです。タグも変わっていますがだいぶわかりやすくなったと思います。
他にもVarnish4ではログの変更がありますが、エッセンスということでこれぐらいにとどめておきます。

まとめ

以上がvarnishのログの読み方・アクセスの仕方とおまけでした。Varnishを使う場合VSLにアクセスすることでより高度な計測ができると思いますのでみなさんもぜひチャレンジしてみてください。
あと本日12/17は私の誕生日だったりします!プレゼントお待ちしております!

次はScalaとDDDのかとじゅんです!

参考資料

trac(Varnish公式)
Lost in Translation:varnishlog, varnishtest(VUG7)
Varnish VSL Query Expressions
VUG8 Outro & Varnish 4 Release Parties! #v4rp
Varnish 4.0.0 technology preview 1 released

関連記事