varnishlogを見やすくするツールを作ってみた

1月 282012

みなさんVarnish使ってますか?僕はよく使ってます。

VCLの動作を調査するときなどによくvarnishlogを使うと思うのですが
これが若干わかりづらいと思います。

例えば下はESIを一つ含んだvarnishlogの出力です

varnishlog

 13 BackendOpen b default 192.168.1.199 36011 192.168.1.199 81 ★ここでバックエンド開いてる
 13 TxRequest b GET
 13 TxURL b /test2.html
 13 TxProtocol b HTTP/1.1
 13 TxHeader b User-Agent: Wget/1.12 (linux-gnu)
 13 TxHeader b Accept: */*
 13 TxHeader b Host: 192.168.1.199:6081
 13 TxHeader b X-Varnish: 171551254
 13 TxHeader b Accept-Encoding: gzip
 13 RxProtocol b HTTP/1.1
 13 RxStatus b 200
 13 RxResponse b OK
 13 RxHeader b Date: 2012年1月28日 05:05:59 GMT
 13 RxHeader b Server: Apache/2.2.15 (Scientific Linux)
 13 RxHeader b Last-Modified: 2011年7月23日 08:09:05 GMT
 13 RxHeader b ETag: "5a28-51-4a8b8187f8177"
 13 RxHeader b Accept-Ranges: bytes
 13 RxHeader b Content-Length: 81
 13 RxHeader b Connection: close
 13 RxHeader b Content-Type: text/html; charset=UTF-8
 13 Fetch_Body b 4(length) cls 0 mklen 1
 13 Length b 81
 13 BackendClose b default
 13 BackendOpen b default 192.168.1.199 36012 192.168.1.199 81
 13 TxRequest b GET
 13 TxURL b /test3.html
 13 TxProtocol b HTTP/1.1
 13 TxHeader b User-Agent: Wget/1.12 (linux-gnu)
 13 TxHeader b Accept: */*
 13 TxHeader b Host: 192.168.1.199:6081
 13 TxHeader b X-Varnish: 171551254
 13 TxHeader b Accept-Encoding: gzip
 13 RxProtocol b HTTP/1.1
 13 RxStatus b 200
 13 RxResponse b OK
 13 RxHeader b Date: 2012年1月28日 05:05:59 GMT
 13 RxHeader b Server: Apache/2.2.15 (Scientific Linux)
 13 RxHeader b Last-Modified: 2011年7月23日 08:08:59 GMT
 13 RxHeader b ETag: "5a29-14-4a8b81829c835"
 13 RxHeader b Accept-Ranges: bytes
 13 RxHeader b Content-Length: 20
 13 RxHeader b Connection: close
 13 RxHeader b Content-Type: text/html; charset=UTF-8
 13 Fetch_Body b 4(length) cls 0 mklen 1
 13 Length b 20
 13 BackendClose b default ★バックエンド閉じてる
 12 SessionOpen c 192.168.1.199 55115 :6081 ★クライアントとのセッションを開始
 12 ReqStart c 192.168.1.199 55115 171551254 ★クライアントからのリクエスト開始
 12 RxRequest c GET
 12 RxURL c /test2.html
 12 RxProtocol c HTTP/1.0
 12 RxHeader c User-Agent: Wget/1.12 (linux-gnu)
 12 RxHeader c Accept: */*
 12 RxHeader c Host: 192.168.1.199:6081
 12 RxHeader c Connection: Keep-Alive
 12 VCL_call c recv 1 7.1
 12 VCL_Log c a
 12 VCL_trace c 2 9.1
 12 VCL_Log c b
 12 VCL_trace c 3 11.1
 12 VCL_Log c a
 12 VCL_return c lookup
 12 VCL_call c hash 18 85.5
 12 Hash c /test2.html
 12 VCL_trace c 19 87.9
 12 Hash c 192.168.1.199:6081
 12 VCL_return c hash
 12 VCL_call c miss 22 99.5 fetch
 12 Backend c 13 default default ★バックエンドを呼び出してる
 12 TTL c 171551254 RFC 120 -1 -1 1327727160 0 1327727159 0 0
 12 VCL_call c fetch 4 18.1 deliver
 12 ObjProtocol c HTTP/1.1
 12 ObjResponse c OK
 12 ObjHeader c Date: 2012年1月28日 05:05:59 GMT
 12 ObjHeader c Server: Apache/2.2.15 (Scientific Linux)
 12 ObjHeader c Last-Modified: 2011年7月23日 08:09:05 GMT
 12 ObjHeader c ETag: "5a28-51-4a8b8187f8177"
 12 ObjHeader c Content-Type: text/html; charset=UTF-8
 12 VCL_call c deliver 26 116.5 deliver
 12 TxProtocol c HTTP/1.1
 12 TxStatus c 200
 12 TxResponse c OK
 12 TxHeader c Server: Apache/2.2.15 (Scientific Linux)
 12 TxHeader c Last-Modified: 2011年7月23日 08:09:05 GMT
 12 TxHeader c ETag: "5a28-51-4a8b8187f8177"
 12 TxHeader c Content-Type: text/html; charset=UTF-8
 12 TxHeader c Date: 2012年1月28日 05:05:59 GMT
 12 TxHeader c X-Varnish: 171551254
 12 TxHeader c Age: 0
 12 TxHeader c Via: 1.1 varnish
 12 TxHeader c Connection: close
 12 VCL_call c recv 1 7.1 ★ESIの呼び出し
 12 VCL_Log c a
 12 VCL_trace c 2 9.1
 12 VCL_Log c b
 12 VCL_trace c 3 11.1
 12 VCL_Log c a
 12 VCL_return c lookup
 12 VCL_call c hash 18 85.5
 12 Hash c /test3.html
 12 VCL_trace c 19 87.9
 12 Hash c 192.168.1.199:6081
 12 VCL_return c hash
 12 VCL_call c miss 22 99.5 fetch
 12 Backend c 13 default default
 12 TTL c 171551254 RFC 120 -1 -1 1327727160 0 1327727159 0 0
 12 VCL_call c fetch 4 18.1 deliver
 12 ObjProtocol c HTTP/1.1
 12 ObjResponse c OK
 12 ObjHeader c Date: 2012年1月28日 05:05:59 GMT
 12 ObjHeader c Server: Apache/2.2.15 (Scientific Linux)
 12 ObjHeader c Last-Modified: 2011年7月23日 08:08:59 GMT
 12 ObjHeader c ETag: "5a29-14-4a8b81829c835"
 12 ObjHeader c Content-Type: text/html; charset=UTF-8
 12 VCL_call c deliver 26 116.5 deliver
 12 Length c 20
 12 ReqEnd c 171551254 1327727159.889132023 1327727159.890880346 -0.001736164 nan nan ★リクエストの終了
 12 SessionClose c EOF mode ★セッション閉じる
 12 StatSess c 192.168.1.199 55115 0 1 1 0 0 2 282 20
 0 CLI - Rd ping
 0 CLI - Wr 200 19 PONG 1327727160 1.0

★で少しコメントかいて見ましたがぶっちゃけわかりづらいと思います。
そこで整形して表示するツールを作って見ました。
このツールを使うと上記の出力が以下のようになります。

varnishlog | php vltrans.php

client ip | 192.168.1.199
client request host | 192.168.1.199:6081
client request url | /test2.html
response size | 20 byte
response status | HTTP/1.1 200 OK
Total time | 0.0017483234405518 sec
restart count | 0
ESI count | 1
call backend | 2 default(192.168.1.199:81) default(192.168.1.199:81)
Cache | HIT:0 MISS:2
------------------------------------------------------------
-------------------
| recv |
-------------------
 |
 | trace | vrt_count:1 vcl_line:7 vcl_pos:1
 | log | a
 | trace | vrt_count:2 vcl_line:9 vcl_pos:1
 | log | b
 | trace | vrt_count:3 vcl_line:11 vcl_pos:1
 | log | a
 | |
 | return | lookup
 |
-------------------
| hash |
-------------------
 |
 | trace | vrt_count:18 vcl_line:85 vcl_pos:5
 | trace | vrt_count:19 vcl_line:87 vcl_pos:9
 | |
 | hash | /test2.html + 192.168.1.199:6081
 | return | hash
 |
-------------------
| miss |
-------------------
 |
 | trace | vrt_count:22 vcl_line:99 vcl_pos:5
 | |
 | return | fetch
 |
-------------------
| fetch |
-------------------
 |
 | trace | vrt_count:4 vcl_line:18 vcl_pos:1
 | |
 | return | deliver
 |
-------------------
| deliver |
-------------------
 |
 | trace | vrt_count:26 vcl_line:116 vcl_pos:5
 | |
 | return | deliver
 |
 <<ESI request>>
-------------------
| recv |
-------------------
 |
 | trace | vrt_count:1 vcl_line:7 vcl_pos:1
 | log | a
 | trace | vrt_count:2 vcl_line:9 vcl_pos:1
 | log | b
 | trace | vrt_count:3 vcl_line:11 vcl_pos:1
 | log | a
 | |
 | return | lookup
 |
-------------------
| hash |
-------------------
 |
 | trace | vrt_count:18 vcl_line:85 vcl_pos:5
 | trace | vrt_count:19 vcl_line:87 vcl_pos:9
 | |
 | hash | /test3.html + 192.168.1.199:6081
 | return | hash
 |
-------------------
| miss |
-------------------
 |
 | trace | vrt_count:22 vcl_line:99 vcl_pos:5
 | |
 | return | fetch
 |
-------------------
| fetch |
-------------------
 |
 | trace | vrt_count:4 vcl_line:18 vcl_pos:1
 | |
 | return | deliver
 |
-------------------
| deliver |
-------------------
 |
 | trace | vrt_count:26 vcl_line:116 vcl_pos:5
 | |
 | return | deliver
 |
############################################################
variable infomation.
 |
hash | /test2.html + 192.168.1.199:6081
------------------------------------------------------------
client.ip | 192.168.1.199
------------------------------------------------------------
req.request | GET
req.url | /test2.html
req.proto | HTTP/1.0
req.http.User-Agent | Wget/1.12 (linux-gnu)
req.http.Accept | */*
req.http.Host | 192.168.1.199:6081
req.http.Connection | Keep-Alive
------------------------------------------------------------
bereq.request | GET
bereq.url | /test2.html
bereq.proto | HTTP/1.1
bereq.http.User-Agent | Wget/1.12 (linux-gnu)
bereq.http.Accept | */*
bereq.http.Host | 192.168.1.199:6081
bereq.http.X-Varnish | 171551254
bereq.http.Accept-Encoding | gzip
------------------------------------------------------------
beresp.proto | HTTP/1.1
beresp.status | 200
beresp.response | OK
beresp.http.Date | 2012年1月28日 05:05:59 GMT
beresp.http.Server | Apache/2.2.15 (Scientific Linux)
beresp.http.Last-Modified | 2011年7月23日 08:09:05 GMT
beresp.http.ETag | "5a28-51-4a8b8187f8177"
beresp.http.Accept-Ranges | bytes
beresp.http.Content-Length | 81
beresp.http.Connection | close
beresp.http.Content-Type | text/html; charset=UTF-8
------------------------------------------------------------
obj.proto | HTTP/1.1
obj.response | OK
obj.http.Date | 2012年1月28日 05:05:59 GMT
obj.http.Server | Apache/2.2.15 (Scientific Linux)
obj.http.Last-Modified | 2011年7月23日 08:09:05 GMT
obj.http.ETag | "5a28-51-4a8b8187f8177"
obj.http.Content-Type | text/html; charset=UTF-8
------------------------------------------------------------
resp.proto | HTTP/1.1
resp.status | 200
resp.response | OK
resp.http.Server | Apache/2.2.15 (Scientific Linux)
resp.http.Last-Modified | 2011年7月23日 08:09:05 GMT
resp.http.ETag | "5a28-51-4a8b8187f8177"
resp.http.Content-Type | text/html; charset=UTF-8
resp.http.Date | 2012年1月28日 05:05:59 GMT
resp.http.X-Varnish | 171551254
resp.http.Age | 0
resp.http.Via | 1.1 varnish
resp.http.Connection | close
############################################################
variable infomation.
 |
ESI | yes
hash | /test3.html + 192.168.1.199:6081
------------------------------------------------------------
bereq.request | GET
bereq.url | /test3.html
bereq.proto | HTTP/1.1
bereq.http.User-Agent | Wget/1.12 (linux-gnu)
bereq.http.Accept | */*
bereq.http.Host | 192.168.1.199:6081
bereq.http.X-Varnish | 171551254
bereq.http.Accept-Encoding | gzip
------------------------------------------------------------
beresp.proto | HTTP/1.1
beresp.status | 200
beresp.response | OK
beresp.http.Date | 2012年1月28日 05:05:59 GMT
beresp.http.Server | Apache/2.2.15 (Scientific Linux)
beresp.http.Last-Modified | 2011年7月23日 08:08:59 GMT
beresp.http.ETag | "5a29-14-4a8b81829c835"
beresp.http.Accept-Ranges | bytes
beresp.http.Content-Length | 20
beresp.http.Connection | close
beresp.http.Content-Type | text/html; charset=UTF-8
------------------------------------------------------------
obj.proto | HTTP/1.1
obj.response | OK
obj.http.Date | 2012年1月28日 05:05:59 GMT
obj.http.Server | Apache/2.2.15 (Scientific Linux)
obj.http.Last-Modified | 2011年7月23日 08:08:59 GMT
obj.http.ETag | "5a29-14-4a8b81829c835"
obj.http.Content-Type | text/html; charset=UTF-8
############################################################
############################################################
############################################################

説明なしでもとりあえずわかるんじゃないかなと思います。
主な機能として

リクエストのサマリ表示

client ip | 192.168.1.199
client request host | 192.168.1.199:6081
client request url | /test2.html
response size | 20 byte
response status | HTTP/1.1 200 OK
Total time | 0.0017483234405518 sec
restart count | 0
ESI count | 1
call backend | 2 default(192.168.1.199:81) default(192.168.1.199:81)
Cache | HIT:0 MISS:2
------------------------------------------------------------

アクションの呼び出しを見やすくする

 <<ESI request>> ★ESIやrestartの時はここに表示
-------------------
| recv | ★呼び出したアクション名
-------------------
 |
 | trace | vrt_count:1 vcl_line:7 vcl_pos:1 ★アクション中に呼び出されたログなどの表示
 | log | a
 | trace | vrt_count:2 vcl_line:9 vcl_pos:1
 | log | b
 | trace | vrt_count:3 vcl_line:11 vcl_pos:1
 | log | a
 | |
 | return | lookup ★return値

変数をわかりやすくする

variable infomation.
 |
ESI | yes ★ESIやrestartの時はここに情報が表示されます
hash | /test3.html + 192.168.1.199:6081 ★このリクエストで使われたhash値
------------------------------------------------------------
bereq.request | GET ★各変数
bereq.url | /test3.html
bereq.proto | HTTP/1.1

まだ若干治したいところもあるんですが(特にソースが汚いので・・)
ひと通り使えるんじゃないかなと思うので公開します。

一応Varnish3で動作確認はしています。
2系は確認していませんがうごくといいな・・

ソースはこちら
github:vltrans.php

English article is here.

このサイトはスパムを低減するために Akismet を使っています。コメントデータの処理方法の詳細はこちらをご覧ください。

cat /dev/random > /dev/null &