How to determine if Varnish/Pressflow is caching content in a useful way?

Question

I recently converted one of my D6 sites to Varnish/Pressflow and saw a very modest improvement in average load speed (from ~550ms before to ~450ms now). But, I also noticed that the initial load time for the first load in a round of tests were consistently much higher --- around 1000ms. They quickly fall down to ~450ms during subsequent reloads during the same test.

This makes me think that I've configured something incorrectly, and Varnish isn't serving from the cache until after the (anonymous) user has already visited the page in question. Perhaps the session IDs are causing each session to be cached independently from eachother (though I understand that shouldn't happen for anonymous users under Pressflow).

The X-Varnish headers appear in both the initial page load, and subsequent loads, so I know the content is at least getting passed through Varnish.

Is there a way to get details about part of the Varnish cache is serving a particular page (e.g. when the cached page was created)? I've tried looking at the logs generated by varnishlog, but apart from various apearances of "X-Drupal-Cache: HIT" I'm not sure what to look for.

Answer 1

Below is the text that can been seen when using Google Chrome and under Network inspecting the response for you webpage. Observe the very last line. There you should get two numbers X-Varnish:1125490268 1125489929.

I've had problems before setting up Varnish and everything seemed to be going fine, then I noticed that only one number was present in X-Varnish. When fixed the two numbers appeared with a decrease in response time form 500ms to 45ms :)

Hope it can help you on the way.

Request URL:http://www.somepage.com/
Request Method:GET
Status Code:200 OK
Request Headersview source
Accept:text/html,application/xhtml+xml,application/xml;q=0.9,
Accept-Encoding:gzip,deflate,sdch
Accept-Language:en-US,en;q=0.8
Connection:keep-alive
Host:www.somepage.com
User-Agent:Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Ubuntu Chromium/28.0.1500.52 Chrome/28.0.1500.52 Safari/537.36
Response Headersview source
Accept-Ranges:bytes
Age:230
Cache-Control:public, max-age=900
Connection:keep-alive
Content-Encoding:gzip
Content-Language:en
Content-Length:6411
Content-Type:text/html; charset=utf-8
Date:Tue, 30 Jul 2013 08:03:13 GMT
Etag:"1375164849-1"
Expires:Sun, 19 Nov 1978 05:00:00 GMT
Last-Modified:Tue, 30 Jul 2013 06:14:09 +0000
Server:Apache
Vary:Cookie,Accept-Encoding
Via:1.1 varnish
X-Drupal-Cache:HIT
X-Generator:Drupal 7 (http://drupal.org)
X-Powered-By:PHP/5.3.10-1ubuntu3.6
X-Varnish:1125490268 1125489929