Why does serving a cached page take one second?

Question

** you may want to read the update below first **

I'm building a Drupal site. I've configured it with nginx and varnish. I have not even installed apache on the server.

I'm trying to improve performance. One major thing is that the first request (in a single page load; say, the first request after pressing F5) takes much more time than the other requests.

response:

Accept-Ranges       bytes
Age                 0
Cache-Control       no-cache, must-revalidate, post-check=0, pre-check=0
Connection          keep-alive
Content-Encoding    gzip
Content-Language    en
Content-Length      7541
Content-Type        text/html; charset=utf-8
Date                Fri, 08 Nov 2013 15:55:07 GMT
Etag                "1383926106"
Expires             Sun, 19 Nov 1978 05:00:00 GMT
Last-Modified       Fri, 08 Nov 2013 15:55:06 +0000
Server              nginx/1.1.19
Via                 1.1 varnish
X-Powered-By        PHP/5.3.10-1ubuntu3.8
X-Varnish           1319371045

request:

Accept              text/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8
Accept-Encoding     gzip, deflate
Accept-Language     nl,en-us;q=0.7,en;q=0.3
Connection          keep-alive
Cookie              has_js=1
Host                _____________________ (removed by me)
Referer             _____________________ (removed by me)
User-Agent          Mozilla/5.0 (Windows NT 6.1; WOW64; rv:25.0) Gecko/20100101 Firefox/25.0

This is the timeline (translated from Dutch) in firebug

Block:              123ms
Dns, Connect, Send: 0
Wait:               1.29s
Receive:            22ms

1. Based on the response headers, can I conclude that the page was indeed served from cache?
2. Why can it take so long? Is there a way to break down whatever steps are taken by nginx and varnish to serve the page?

UPDATE:

After turning on debugging log for nginx, I found this:

....
2013/11/08 17:23:05 [debug] 4992#0: *3786 http run request: "/index.php?"
2013/11/08 17:23:05 [debug] 4992#0: *3786 http upstream check client, write event:1, "/index.php"
2013/11/08 17:23:05 [debug] 4992#0: *3786 http upstream recv(): -1 (11: Resource     temporarily unavailable)
2013/11/08 17:23:06 [debug] 4992#0: *3786 post event 00000000021FFD78
2013/11/08 17:23:06 [debug] 4992#0: *3786 post event 000000000221CEB8
....

It should be no coincidence that the second changes (so I assume the "Resource temporarily unavailable" takes one second).

Answer 1

You can see that this was not a cache hit because the X-Varnish header has only one number (xid) in it. Any cache hit will reference both the current xid and the xid that originally did the backend fetch.

Your Expires header is in the past, which means that Varnish would not (by default) cache it.

This is your backend taking a long time to answer, and when it is done sends a response that isn't cacheable.

Answer 2

You have to enable Drupal page cache in order to avoid Cache-Control : no-cache, must-revalidate, post-check=0, pre-check=0, wich prevents Varnish from caching the response.