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: Sat, 28 Jan 2012 05:05:59 GMT
   13 RxHeader     b Server: Apache/2.2.15 (Scientific Linux)
   13 RxHeader     b Last-Modified: Sat, 23 Jul 2011 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: Sat, 28 Jan 2012 05:05:59 GMT
   13 RxHeader     b Server: Apache/2.2.15 (Scientific Linux)
   13 RxHeader     b Last-Modified: Sat, 23 Jul 2011 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: Sat, 28 Jan 2012 05:05:59 GMT
   12 ObjHeader    c Server: Apache/2.2.15 (Scientific Linux)
   12 ObjHeader    c Last-Modified: Sat, 23 Jul 2011 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: Sat, 23 Jul 2011 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: Sat, 28 Jan 2012 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: Sat, 28 Jan 2012 05:05:59 GMT
   12 ObjHeader    c Server: Apache/2.2.15 (Scientific Linux)
   12 ObjHeader    c Last-Modified: Sat, 23 Jul 2011 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           | Sat, 28 Jan 2012 05:05:59 GMT
beresp.http.Server         | Apache/2.2.15 (Scientific Linux)
beresp.http.Last-Modified  | Sat, 23 Jul 2011 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          | Sat, 28 Jan 2012 05:05:59 GMT
obj.http.Server        | Apache/2.2.15 (Scientific Linux)
obj.http.Last-Modified | Sat, 23 Jul 2011 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 | Sat, 23 Jul 2011 08:09:05 GMT
resp.http.ETag          | "5a28-51-4a8b8187f8177"
resp.http.Content-Type  | text/html; charset=UTF-8
resp.http.Date          | Sat, 28 Jan 2012 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           | Sat, 28 Jan 2012 05:05:59 GMT
beresp.http.Server         | Apache/2.2.15 (Scientific Linux)
beresp.http.Last-Modified  | Sat, 23 Jul 2011 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          | Sat, 28 Jan 2012 05:05:59 GMT
obj.http.Server        | Apache/2.2.15 (Scientific Linux)
obj.http.Last-Modified | Sat, 23 Jul 2011 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.


 Leave a Reply

You may use these HTML tags and attributes: <a href="" title=""> <abbr title=""> <acronym title=""> <b> <blockquote cite=""> <cite> <code> <del datetime=""> <em> <i> <q cite=""> <s> <strike> <strong>

(required)

(required)