Logging
Poul-Henning Kamp
phk at phk.freebsd.dk
Mon Jul 10 17:33:47 CEST 2006
In message <20060710082955.GA30842 at totem.fix.no>, Anders Nordby writes:
>Hi,
>
>Will it be possible to log cache misses? And would it be possible to log
>them separately?
This is one of those questions that can either be answered with
"yes" (which go you right there) or a quite long explanation, which
takes up the rest of the email :-)
While it runs, Varnish logs anything of even moderate relevance to
the shared-memory circular buffer.
Any number of processes can attached to that shared memory and
keep an eye on whatever they find relevant.
To give an you an idea what is logged, here is a commented sample
from a very simple run I just did. (Please note that we have not
quite nailed these messages down yet, but all but "Debug" they will
be part of the defined API to Varnish)
The first column is the numeric type-tag (== column 3)
Column 2 is the length of any variable part (the stuff in column 4)
max is 255 bytes.
Column 3 is a filedescriptor number (or zero) and is used to
match entries to the session or backend connection.
The fourth column is the variable text.
01 25 0 Debug [Starting 1 worker threads]
The minimum number of threads specified was 1. These
threads are started as permanent and will never die.
03 4 0 CLI <ping>
This is the management process checking of the cache
process is alive. It happens every few seconds. If
the management process doesn't get a reply, it kills
the cache process and forks it again.
1f 16 0 WorkThread <1 born permanent>
The first thread is created and signs in.
03 4 0 CLI <ping>
03 4 0 CLI <ping>
04 15 19 SessionOpen <127.0.0.1 53578>
We get a connection from localhost
1a 10 19 XID <1243897116>
This is a transaction ID which is used to cross reference
things in the log. The first one after startup is random
and they increment after that. When an object is inserted
in the hash, it retains the XID of the transaction that
created it (see more below)
0e 3 19 Request <GET>
12 1 19 URL </>
13 8 19 Protocol <HTTP/1.1>
14 15 19 Header <Host: localhost>
14 30 19 Header <User-Agent: fetch libfetch/2.0>
14 17 19 Header <Connection: close>
This is the request we got
17 4 19 VCL_call <recv>
We call the vcl_recv() function to figure out what should
happen.
18 6 19 VCL_trace <1 4.14>
18 5 19 VCL_trace <2 5.9>
18 5 19 VCL_trace <5 8.5>
18 5 19 VCL_trace <6 8.9>
18 6 19 VCL_trace <7 8.34>
18 6 19 VCL_trace <9 11.5>
These tell us which bits of vcl code were executed, the
first number is an index into a table the second is line.char
19 6 19 VCL_return <lookup>
vcl_recv returns "lookup", so we do...
17 4 19 VCL_call <miss>
And we didn't find anything so we call vcl_miss()
18 8 19 VCL_trace <14 21.14>
19 5 19 VCL_return <fetch>
Which tells us to fetch it.
07 35 20 BackendOpen <192.168.64.2 53931 193.69.165.89 80>
08 10 20 BackendXID <1243897116>
0d 10 19 Backend <20 default>
Session 19 opened a connection to the default backend
and got fd=20. We log both ends of the TCP connection
and the XID with the backends fd. Notice that these
come out of order because we don't know the "20" until
we have established the connection.
15 15 20 BldHdr <Host: localhost>
15 30 20 BldHdr <User-Agent: fetch libfetch/2.0>
We build the headers to send to the backend (this is
currently incompletly logged)
13 8 20 Protocol <HTTP/1.1>
11 3 20 Status <200>
0f 2 20 Response <OK>
14 35 20 Header <Date: Mon, 10 Jul 2006 15:07:20 GMT>
14 28 20 Header <Server: Apache/1.3.27 (Unix)>
14 26 20 Header <Cache-Control: max-age=900>
14 38 20 Header <Expires: Mon, 10 Jul 2006 15:22:20 GMT>
14 44 20 Header <Last-Modified: Mon, 10 Jul 2006 15:05:02 GMT>
14 29 20 Header <ETag: "2b400e-26506-44b26c9e">
14 20 20 Header <Accept-Ranges: bytes>
14 22 20 Header <Content-Length: 156934>
14 17 20 Header <Connection: close>
14 43 20 Header <Content-Type: text/html; charset=iso-8859-1>
And we get a reply. Notice that we have not picked up the
body of the object yet.
01 114 0 Debug [TTD: max-age 900 Age: 0 Date: 1152544040 (0) Expires 1152544940 (900) our_clock 1152544040 -> ttd 1152544940 (900)]
Our TTL calculations
17 5 19 VCL_call <fetch>
18 8 19 VCL_trace <15 25.15>
18 7 19 VCL_trace <16 26.9>
18 7 19 VCL_trace <18 29.5>
18 7 19 VCL_trace <19 29.9>
18 7 19 VCL_trace <21 32.5>
19 6 19 VCL_return <insert>
We call vcl_fetch to tell us what to do, (the object might
not be cacheable etc etc) we are told to insert the object
which implies delivery.
15 35 19 BldHdr <Date: Mon, 10 Jul 2006 15:07:20 GMT>
15 28 19 BldHdr <Server: Apache/1.3.27 (Unix)>
15 38 19 BldHdr <Expires: Mon, 10 Jul 2006 15:22:20 GMT>
15 44 19 BldHdr <Last-Modified: Mon, 10 Jul 2006 15:05:02 GMT>
15 29 19 BldHdr <ETag: "2b400e-26506-44b26c9e">
15 43 19 BldHdr <Content-Type: text/html; charset=iso-8859-1>
We build the headers and send the object to the client.
(incompletely logged presently)
03 4 0 CLI <ping>
11 3 19 Status <200>
10 6 19 Length <156934>
Status and length send back.
The body is received, stored and delivered here, but that
generates no log messages if all goes well.
0a 0 20 BackendClose
The backend connection is closed (because of the header from
the backend)
06 17 19 SessionClose <Connection header>
We close the clients TCP also, because it asked us to.
04 15 19 SessionOpen <127.0.0.1 60180>
New client connection
1a 10 19 XID <1243897117>
0e 3 19 Request <GET>
12 1 19 URL </>
13 8 19 Protocol <HTTP/1.1>
14 15 19 Header <Host: localhost>
14 30 19 Header <User-Agent: fetch libfetch/2.0>
14 17 19 Header <Connection: close>
17 4 19 VCL_call <recv>
18 6 19 VCL_trace <1 4.14>
18 5 19 VCL_trace <2 5.9>
18 5 19 VCL_trace <5 8.5>
18 5 19 VCL_trace <6 8.9>
18 6 19 VCL_trace <7 8.34>
18 6 19 VCL_trace <9 11.5>
19 6 19 VCL_return <lookup>
1b 10 19 Hit <1243897116>
This time we got a hit, and the XID of the matched object
(== of the session that feched it) is recorded.
17 3 19 VCL_call <hit>
18 8 19 VCL_trace <10 14.13>
18 7 19 VCL_trace <11 15.9>
18 7 19 VCL_trace <13 18.5>
19 7 19 VCL_return <deliver>
vcl_hit() tells us to deliver
11 3 19 Status <200>
10 6 19 Length <156934>
06 17 19 SessionClose <Connection header>
So we do, and close.
03 4 0 CLI <ping>
03 4 0 CLI <ping>
03 4 0 CLI <ping>
03 4 0 CLI <ping>
>PS: Performance counters? :-)
Performance counters are also stored in the shared memory segment
and can be read by any number of processes. We're no where near
done defining all these, but these are the current ones:
Hitrate ratio: 10 19 19
Hitrate avg: 0.5635 0.5566 0.5566
2 0.00 Client connections accepted
2 0.00 Client requests received
1 0.00 Cache hits
1 0.00 Cache misses
1 0.00 Backend connections initiated
0 0.00 Backend connections recyles
0 0.00 N struct sess
2 0.00 N struct object
2 0.00 N struct objecthead
1 0.00 N struct header
2 0.00 N struct smf
0 0.00 N struct vbe
0 0.00 N struct vbe_conn
1 0.00 N worker threads
0 0.00 N worker threads created
0 0.00 N worker threads not created
0 0.00 N worker threads shortages
0 0.00 N busy worker threads
Poul-Henning
--
Poul-Henning Kamp | UNIX since Zilog Zeus 3.20
phk at FreeBSD.ORG | TCP/IP since RFC 956
FreeBSD committer | BSD since 4.3-tahoe
Never attribute to malice what can adequately be explained by incompetence.
More information about the varnish-dev
mailing list