lfeys at reference
Feb 7, 2012, 11:38 AM
Post #1 of 1
(100 views)
Permalink
|
|
Request coalescing and disappearing requests
|
|
Hello,
I am using Varnish in front of a Drupal website and we are currently performing load tests. The test this issue is about, is executing multiple requests for the same page on an empty (freshly restarted) Varnish.But I get results I don't understand, since even with only 10 simultaneous requests for the same page not all requests effectively lead to a response.
If I have a look at the output of varnishstat (see below) after a run with 10 requests, I conclude the following:
*) backend_req=1 => so request coalescing is working as expected
*) n_objwrite=7 => 7 objects have been written to the response. This corresponds to the test results: 7 responses and 3 timeouts. Also corresponds with 1 miss and 6 hits in Varnish (cache_hit and cache_miss)
*) sess_closed=7 => the sessions for the 7 succesful requests are being closed
*) n_sess=3 => so 3 sessions just remain open?
So what happened to those 3 unclosed sessions? Why don't they result in cache hits? Should I configure something in Varnish or my VCL in order for these requests to be handled as expected (meaning they should return the cached response and be removed from the request queue)?
'Varnishstat' output:
10 0.00 0.02 client_conn - Client connections accepted
10 0.00 0.02 client_req - Client requests received
6 0.00 0.01 cache_hit - Cache hits
1 0.00 0.00 cache_miss - Cache misses
1 0.00 0.00 backend_conn - Backend conn. success
1 0.00 0.00 fetch_chunked - Fetch chunked
14 . . n_sess_mem - N struct sess_mem
3 . . n_sess - N struct sess
1 . . n_object - N struct object
3 . . n_objectcore - N struct objectcore
3 . . n_objecthead - N struct objecthead
4 . . n_waitinglist - N struct waitinglist
2 . . n_wrk - N worker threads
3 0.00 0.01 n_wrk_create - N worker threads created
334272 0.00 642.83 n_wrk_max - N worker threads limited
4 0.00 0.01 n_wrk_queued - N queued work requests
3 . . n_backend - N backends
7 0.00 0.01 n_objwrite - Objects sent with write
10 0.00 0.02 s_sess - Total Sessions
10 0.00 0.02 s_req - Total Requests
1 0.00 0.00 s_fetch - Total fetch
3162 0.00 6.08 s_hdrbytes - Total header bytes
832083 0.00 1600.16 s_bodybytes - Total body bytes
7 0.00 0.01 sess_closed - Session Closed
807 0.00 1.55 shm_records - SHM records
396 0.00 0.76 shm_writes - SHM writes
1 0.00 0.00 backend_req - Backend requests made
1 0.00 0.00 n_vcl - N vcl total
1 0.00 0.00 n_vcl_avail - N vcl available
1 . . n_ban - N total active bans
1 0.00 0.00 n_ban_add - N new bans added
10 0.00 0.02 hcb_nolock - HCB Lookups without lock
1 0.00 0.00 hcb_lock - HCB Lookups with lock
1 0.00 0.00 hcb_insert - HCB Inserts
520 1.00 1.00 uptime - Client uptime
1 0.00 0.00 LCK.sms.creat - Created locks
1 0.00 0.00 LCK.sma.creat - Created locks
1 0.00 0.00 LCK.smf.creat - Created locks
4 0.00 0.01 LCK.smf.locks - Lock Operations
1 0.00 0.00 LCK.hcb.creat - Created locks
4 0.00 0.01 LCK.hcb.locks - Lock Operations
1 0.00 0.00 LCK.vcl.creat - Created locks
11 0.00 0.02 LCK.vcl.locks - Lock Operations
1 0.00 0.00 LCK.stat.creat - Created locks
14 0.00 0.03 LCK.stat.locks - Lock Operations
1 0.00 0.00 LCK.sessmem.creat - Created locks
20 0.00 0.04 LCK.sessmem.locks - Lock Operations
1 0.00 0.00 LCK.wstat.creat - Created locks
103097 198.74 198.26 LCK.wstat.locks - Lock Operations
Below you can find an extract from the varnish log. It was generated using the -O option and imported into Excel. I then added one more column with increasing numbers for each line indicating the original order of the items in the log and then sorted them by request id.
*) Requests 12, 15 and 17 were succesful
*) Request 14 was a back-end request (executed from request 12, which was the first one)
*) Request 16 never returned a response and is an example of the problem I described in my previous post.
'Varnishlog -O' output
101 0 WorkThread - 0x7fd132bfeb60 start
452 0 WorkThread - 0x7fd132bfeb60 end
1 12 SessionOpen c 192.168.10.168 2497 :6081
2 12 ReqStart c 192.168.10.168 2497 556239272
3 12 RxRequest c GET
4 12 RxURL c /nl/homepage
5 12 RxProtocol c HTTP/1.1
6 12 RxHeader c Connection: keep-alive
7 12 RxHeader c "Accept-Language: en,nl;q=0.7,nl-nl;q=0.3"
8 12 RxHeader c "Accept: text/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8"
9 12 RxHeader c "User-Agent: Mozilla/5.0 (Windows; U; Windows NT 5.1; en-US; rv:1.9.2.23) Gecko/20110920 Firefox/3.6.23 ( .NET CLR 3.5.30729)"
10 12 RxHeader c Keep-Alive: 115
11 12 RxHeader c "Accept-Charset: ISO-8859-1,utf-8;q=0.7,*;q=0.7"
12 12 RxHeader c Cache-Control: max-age=0
13 12 RxHeader c Accept-Encoding: gzip,deflate
14 12 RxHeader c Referer: http://www.footbel-2011.com/
15 12 RxHeader c Host: www.footbel-load.com:6081<http://www.footbel-load.com:6081>
16 12 VCL_call c recv
17 12 VCL_return c lookup
18 12 VCL_call c hash
19 12 Hash c /nl/homepage
20 12 Hash c www.footbel-load.com:6081<http://www.footbel-load.com:6081>
21 12 VCL_return c hash
22 12 VCL_call c miss
23 12 VCL_return c fetch
25 12 Backend c 14 default default
179 12 TTL c 556239272 RFC 3600 1327500664 0 0 3600 0
180 12 VCL_call c fetch
181 12 VCL_return c deliver
182 12 ObjProtocol c HTTP/1.1
183 12 ObjResponse c OK
184 12 ObjHeader c Date: Wed, 25 Jan 2012 14:11:03 GMT
185 12 ObjHeader c Server: Apache/2.2.15 (Red Hat)
186 12 ObjHeader c X-Powered-By: PHP/5.2.17
187 12 ObjHeader c Cache-Control: public, max-age=3600
188 12 ObjHeader c Last-Modified: Wed, 25 Jan 2012 14:11:03 +0000
189 12 ObjHeader c Expires: Sun, 11 Mar 1984 12:00:00 GMT
190 12 ObjHeader c Vary: Cookie
191 12 ObjHeader c "ETag: ""1327500663"""
192 12 ObjHeader c "Content-Type: text/html; charset=utf-8"
197 12 VCL_call c deliver
198 12 VCL_return c deliver
199 12 TxProtocol c HTTP/1.1
200 12 TxStatus c 200
201 12 TxResponse c OK
202 12 TxHeader c Server: Apache/2.2.15 (Red Hat)
203 12 TxHeader c X-Powered-By: PHP/5.2.17
204 12 TxHeader c Cache-Control: public, max-age=3600
205 12 TxHeader c Last-Modified: Wed, 25 Jan 2012 14:11:03 +0000
206 12 TxHeader c Expires: Sun, 11 Mar 1984 12:00:00 GMT
207 12 TxHeader c Vary: Cookie
208 12 TxHeader c "ETag: ""1327500663"""
209 12 TxHeader c "Content-Type: text/html; charset=utf-8"
210 12 TxHeader c Content-Length: 118856
211 12 TxHeader c Accept-Ranges: bytes
212 12 TxHeader c Date: Wed, 25 Jan 2012 14:11:04 GMT
213 12 TxHeader c X-Varnish: 556239272
214 12 TxHeader c Age: 0
215 12 TxHeader c Via: 1.1 varnish
216 12 TxHeader c Connection: keep-alive
217 12 TxHeader c X-HITMISS: MISS
218 12 Length c 118856
219 12 ReqEnd c 556239272 1327500663.298880816 1327500664.062960863 0.000065565 0.760407686 0.003672361
292 12 Debug c """herding"""
442 12 SessionClose c no request
443 12 StatSess c 192.168.10.168 2497 1 1 1 0 0 1 449 118856
24 14 BackendOpen b default 127.0.0.1 59206 127.0.0.1 80
26 14 TxRequest b GET
27 14 TxURL b /nl/homepage
28 14 TxProtocol b HTTP/1.1
29 14 TxHeader b "Accept-Language: en,nl;q=0.7,nl-nl;q=0.3"
30 14 TxHeader b "Accept: text/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8"
31 14 TxHeader b "User-Agent: Mozilla/5.0 (Windows; U; Windows NT 5.1; en-US; rv:1.9.2.23) Gecko/20110920 Firefox/3.6.23 ( .NET CLR 3.5.30729)"
32 14 TxHeader b "Accept-Charset: ISO-8859-1,utf-8;q=0.7,*;q=0.7"
33 14 TxHeader b Referer: http://www.footbel-2011.com/
34 14 TxHeader b Host: www.footbel-load.com:6081<http://www.footbel-load.com:6081>
35 14 TxHeader b X-Forwarded-For: 192.168.10.168, 192.168.10.168
36 14 TxHeader b X-Varnish: 556239272
37 14 TxHeader b Accept-Encoding: gzip
165 14 RxProtocol b HTTP/1.1
166 14 RxStatus b 200
167 14 RxResponse b OK
168 14 RxHeader b Date: Wed, 25 Jan 2012 14:11:03 GMT
169 14 RxHeader b Server: Apache/2.2.15 (Red Hat)
170 14 RxHeader b X-Powered-By: PHP/5.2.17
171 14 RxHeader b Cache-Control: public, max-age=3600
172 14 RxHeader b Last-Modified: Wed, 25 Jan 2012 14:11:03 +0000
173 14 RxHeader b Expires: Sun, 11 Mar 1984 12:00:00 GMT
174 14 RxHeader b Vary: Cookie
175 14 RxHeader b "ETag: ""1327500663"""
176 14 RxHeader b Connection: close
177 14 RxHeader b Transfer-Encoding: chunked
178 14 RxHeader b "Content-Type: text/html; charset=utf-8"
193 14 Fetch_Body b 3 0 1
194 14 Length b 118856
195 14 BackendClose b default
196 14 SessionOpen c 192.168.10.168 2504 :6081
246 14 ReqStart c 192.168.10.168 2504 556239279
247 14 RxRequest c GET
248 14 RxURL c /nl/homepage
249 14 RxProtocol c HTTP/1.1
250 14 RxHeader c Connection: keep-alive
251 14 RxHeader c "Accept-Language: en,nl;q=0.7,nl-nl;q=0.3"
252 14 RxHeader c "Accept: text/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8"
253 14 RxHeader c "User-Agent: Mozilla/5.0 (Windows; U; Windows NT 5.1; en-US; rv:1.9.2.23) Gecko/20110920 Firefox/3.6.23 ( .NET CLR 3.5.30729)"
254 14 RxHeader c Keep-Alive: 115
255 14 RxHeader c "Accept-Charset: ISO-8859-1,utf-8;q=0.7,*;q=0.7"
256 14 RxHeader c Cache-Control: max-age=0
257 14 RxHeader c Accept-Encoding: gzip,deflate
258 14 RxHeader c Referer: http://www.footbel-2011.com/
259 14 RxHeader c Host: www.footbel-load.com:6081<http://www.footbel-load.com:6081>
260 14 VCL_call c recv
261 14 VCL_return c lookup
262 14 VCL_call c hash
263 14 Hash c /nl/homepage
264 14 Hash c www.footbel-load.com:6081<http://www.footbel-load.com:6081>
265 14 VCL_return c hash
266 14 Hit c 556239272
267 14 VCL_call c hit
268 14 VCL_return c deliver
269 14 VCL_call c deliver
270 14 VCL_return c deliver
271 14 TxProtocol c HTTP/1.1
272 14 TxStatus c 200
273 14 TxResponse c OK
274 14 TxHeader c Server: Apache/2.2.15 (Red Hat)
275 14 TxHeader c X-Powered-By: PHP/5.2.17
276 14 TxHeader c Cache-Control: public, max-age=3600
277 14 TxHeader c Last-Modified: Wed, 25 Jan 2012 14:11:03 +0000
278 14 TxHeader c Expires: Sun, 11 Mar 1984 12:00:00 GMT
279 14 TxHeader c Vary: Cookie
280 14 TxHeader c "ETag: ""1327500663"""
281 14 TxHeader c "Content-Type: text/html; charset=utf-8"
282 14 TxHeader c Content-Length: 118856
283 14 TxHeader c Accept-Ranges: bytes
284 14 TxHeader c Date: Wed, 25 Jan 2012 14:11:04 GMT
285 14 TxHeader c X-Varnish: 556239279 556239272
286 14 TxHeader c Age: 0
287 14 TxHeader c Via: 1.1 varnish
288 14 TxHeader c Connection: keep-alive
289 14 TxHeader c X-HITMISS: HIT
290 14 Length c 118856
291 14 ReqEnd c 556239279 1327500664.059293509 1327500664.063805580 0.000077963 0.000107527 0.004404545
293 14 Debug c """herding"""
446 14 SessionClose c timeout
447 14 StatSess c 192.168.10.168 2504 0 1 1 0 0 0 458 118856
38 15 SessionOpen c 192.168.10.168 2498 :6081
39 15 ReqStart c 192.168.10.168 2498 556239273
40 15 RxRequest c GET
41 15 RxURL c /nl/homepage
42 15 RxProtocol c HTTP/1.1
43 15 RxHeader c Connection: keep-alive
44 15 RxHeader c "Accept-Language: en,nl;q=0.7,nl-nl;q=0.3"
45 15 RxHeader c "Accept: text/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8"
46 15 RxHeader c "User-Agent: Mozilla/5.0 (Windows; U; Windows NT 5.1; en-US; rv:1.9.2.23) Gecko/20110920 Firefox/3.6.23 ( .NET CLR 3.5.30729)"
47 15 RxHeader c Keep-Alive: 115
48 15 RxHeader c "Accept-Charset: ISO-8859-1,utf-8;q=0.7,*;q=0.7"
49 15 RxHeader c Cache-Control: max-age=0
50 15 RxHeader c Accept-Encoding: gzip,deflate
51 15 RxHeader c Referer: http://www.footbel-2011.com/
52 15 RxHeader c Host: www.footbel-load.com:6081<http://www.footbel-load.com:6081>
53 15 VCL_call c recv
54 15 VCL_return c lookup
55 15 VCL_call c hash
56 15 Hash c /nl/homepage
57 15 Hash c www.footbel-load.com:6081<http://www.footbel-load.com:6081>
58 15 VCL_return c hash
220 15 Hit c 556239272
221 15 VCL_call c hit
222 15 VCL_return c deliver
223 15 VCL_call c deliver
224 15 VCL_return c deliver
225 15 TxProtocol c HTTP/1.1
226 15 TxStatus c 200
227 15 TxResponse c OK
228 15 TxHeader c Server: Apache/2.2.15 (Red Hat)
229 15 TxHeader c X-Powered-By: PHP/5.2.17
230 15 TxHeader c Cache-Control: public, max-age=3600
231 15 TxHeader c Last-Modified: Wed, 25 Jan 2012 14:11:03 +0000
232 15 TxHeader c Expires: Sun, 11 Mar 1984 12:00:00 GMT
233 15 TxHeader c Vary: Cookie
234 15 TxHeader c "ETag: ""1327500663"""
235 15 TxHeader c "Content-Type: text/html; charset=utf-8"
236 15 TxHeader c Content-Length: 118856
237 15 TxHeader c Accept-Ranges: bytes
238 15 TxHeader c Date: Wed, 25 Jan 2012 14:11:04 GMT
239 15 TxHeader c X-Varnish: 556239273 556239272
240 15 TxHeader c Age: 0
241 15 TxHeader c Via: 1.1 varnish
242 15 TxHeader c Connection: keep-alive
243 15 TxHeader c X-HITMISS: HIT
244 15 Length c 118856
245 15 ReqEnd c 556239273 1327500663.402845621 1327500664.063805580 0.000059605 0.656617880 0.004342079
294 15 Debug c """herding"""
444 15 SessionClose c no request
445 15 StatSess c 192.168.10.168 2498 1 1 1 0 0 0 458 118856
102 16 SessionOpen c 192.168.10.168 2499 :6081
103 16 ReqStart c 192.168.10.168 2499 556239276
104 16 RxRequest c GET
105 16 RxURL c /nl/homepage
106 16 RxProtocol c HTTP/1.1
107 16 RxHeader c Connection: keep-alive
108 16 RxHeader c "Accept-Language: en,nl;q=0.7,nl-nl;q=0.3"
109 16 RxHeader c "Accept: text/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8"
110 16 RxHeader c "User-Agent: Mozilla/5.0 (Windows; U; Windows NT 5.1; en-US; rv:1.9.2.23) Gecko/20110920 Firefox/3.6.23 ( .NET CLR 3.5.30729)"
111 16 RxHeader c Keep-Alive: 115
112 16 RxHeader c "Accept-Charset: ISO-8859-1,utf-8;q=0.7,*;q=0.7"
113 16 RxHeader c Cache-Control: max-age=0
114 16 RxHeader c Accept-Encoding: gzip,deflate
115 16 RxHeader c Referer: http://www.footbel-2011.com/
116 16 RxHeader c Host: www.footbel-load.com:6081<http://www.footbel-load.com:6081>
117 16 VCL_call c recv
118 16 VCL_return c lookup
119 16 VCL_call c hash
120 16 Hash c /nl/homepage
121 16 Hash c www.footbel-load.com:6081<http://www.footbel-load.com:6081>
122 16 VCL_return c hash
59 17 SessionOpen c 192.168.10.168 2500 :6081
60 17 ReqStart c 192.168.10.168 2500 556239274
61 17 RxRequest c GET
62 17 RxURL c /nl/homepage
63 17 RxProtocol c HTTP/1.1
64 17 RxHeader c Connection: keep-alive
65 17 RxHeader c "Accept-Language: en,nl;q=0.7,nl-nl;q=0.3"
66 17 RxHeader c "Accept: text/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8"
67 17 RxHeader c "User-Agent: Mozilla/5.0 (Windows; U; Windows NT 5.1; en-US; rv:1.9.2.23) Gecko/20110920 Firefox/3.6.23 ( .NET CLR 3.5.30729)"
68 17 RxHeader c Keep-Alive: 115
69 17 RxHeader c "Accept-Charset: ISO-8859-1,utf-8;q=0.7,*;q=0.7"
70 17 RxHeader c Cache-Control: max-age=0
71 17 RxHeader c Accept-Encoding: gzip,deflate
72 17 RxHeader c Referer: http://www.footbel-2011.com/
73 17 RxHeader c Host: www.footbel-load.com:6081<http://www.footbel-load.com:6081>
74 17 VCL_call c recv
75 17 VCL_return c lookup
76 17 VCL_call c hash
77 17 Hash c /nl/homepage
78 17 Hash c www.footbel-load.com:6081<http://www.footbel-load.com:6081>
79 17 VCL_return c hash
321 17 Hit c 556239272
322 17 VCL_call c hit
323 17 VCL_return c deliver
324 17 VCL_call c deliver
325 17 VCL_return c deliver
326 17 TxProtocol c HTTP/1.1
327 17 TxStatus c 200
328 17 TxResponse c OK
329 17 TxHeader c Server: Apache/2.2.15 (Red Hat)
330 17 TxHeader c X-Powered-By: PHP/5.2.17
331 17 TxHeader c Cache-Control: public, max-age=3600
332 17 TxHeader c Last-Modified: Wed, 25 Jan 2012 14:11:03 +0000
333 17 TxHeader c Expires: Sun, 11 Mar 1984 12:00:00 GMT
334 17 TxHeader c Vary: Cookie
335 17 TxHeader c "ETag: ""1327500663"""
336 17 TxHeader c "Content-Type: text/html; charset=utf-8"
337 17 TxHeader c Content-Length: 118856
338 17 TxHeader c Accept-Ranges: bytes
339 17 TxHeader c Date: Wed, 25 Jan 2012 14:11:04 GMT
340 17 TxHeader c X-Varnish: 556239274 556239272
341 17 TxHeader c Age: 0
342 17 TxHeader c Via: 1.1 varnish
343 17 TxHeader c Connection: keep-alive
344 17 TxHeader c X-HITMISS: HIT
345 17 Length c 118856
346 17 ReqEnd c 556239274 1327500663.621091604 1327500664.115823030 0.000060558 0.492846012 0.001885414
348 17 Debug c """herding"""
349 17 ReqStart c 192.168.10.168 2500 556239280
350 17 RxRequest c GET
351 17 RxURL c /nl/homepage
352 17 RxProtocol c HTTP/1.1
353 17 RxHeader c Connection: keep-alive
354 17 RxHeader c "Accept-Language: en,nl;q=0.7,nl-nl;q=0.3"
355 17 RxHeader c "Accept: text/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8"
356 17 RxHeader c "User-Agent: Mozilla/5.0 (Windows; U; Windows NT 5.1; en-US; rv:1.9.2.23) Gecko/20110920 Firefox/3.6.23 ( .NET CLR 3.5.30729)"
357 17 RxHeader c Keep-Alive: 115
358 17 RxHeader c "Accept-Charset: ISO-8859-1,utf-8;q=0.7,*;q=0.7"
359 17 RxHeader c Cache-Control: max-age=0
360 17 RxHeader c Accept-Encoding: gzip,deflate
361 17 RxHeader c Referer: http://www.footbel-2011.com/
362 17 RxHeader c Host: www.footbel-load.com:6081<http://www.footbel-load.com:6081>
363 17 VCL_call c recv
364 17 VCL_return c lookup
365 17 VCL_call c hash
366 17 Hash c /nl/homepage
367 17 Hash c www.footbel-load.com:6081<http://www.footbel-load.com:6081>
368 17 VCL_return c hash
369 17 Hit c 556239272
370 17 VCL_call c hit
371 17 VCL_return c deliver
372 17 VCL_call c deliver
373 17 VCL_return c deliver
374 17 TxProtocol c HTTP/1.1
375 17 TxStatus c 200
376 17 TxResponse c OK
377 17 TxHeader c Server: Apache/2.2.15 (Red Hat)
378 17 TxHeader c X-Powered-By: PHP/5.2.17
379 17 TxHeader c Cache-Control: public, max-age=3600
380 17 TxHeader c Last-Modified: Wed, 25 Jan 2012 14:11:03 +0000
381 17 TxHeader c Expires: Sun, 11 Mar 1984 12:00:00 GMT
382 17 TxHeader c Vary: Cookie
383 17 TxHeader c "ETag: ""1327500663"""
384 17 TxHeader c "Content-Type: text/html; charset=utf-8"
385 17 TxHeader c Content-Length: 118856
386 17 TxHeader c Accept-Ranges: bytes
387 17 TxHeader c Date: Wed, 25 Jan 2012 14:11:04 GMT
388 17 TxHeader c X-Varnish: 556239280 556239272
389 17 TxHeader c Age: 0
390 17 TxHeader c Via: 1.1 varnish
391 17 TxHeader c Connection: keep-alive
392 17 TxHeader c X-HITMISS: HIT
393 17 Length c 118856
394 17 ReqEnd c 556239280 1327500664.214530468 1327500664.215306759 0.098707438 0.000080824 0.000695467
I am totally of ideas on this, so any help would be appreciated. I already posted this on the forum, but someone suggested to send it to the mailing list. Since I'm not sure this is actually a Varnish bug, I have posted to this list.
Kind regards,
Luc Feys
Luc Feys
Java Team Leader
THE REFERENCE
Stapelplein 70, bus 201
B-9000 Gent
Phone: +32 (0)9 269 12 84
Fax: +32 (0)9 234 05 37
http://www.reference.be<http://www.reference.be/>
P Instead of printing this e-mail, you could carve it into stone.
|
