requests keep timing out
Tung Nguyen
tnguyen at bleacherreport.com
Wed Apr 1 16:47:51 CEST 2009
Here's the full varnishstat -1
varnishstat -1
uptime 212 . Child uptime
client_conn 1518 7.16 Client connections accepted
client_req 5662 26.71 Client requests received
cache_hit 3230 15.24 Cache hits
cache_hitpass 8 0.04 Cache hits for pass
cache_miss 561 2.65 Cache misses
backend_conn 2307 10.88 Backend connections success
backend_unhealthy 0 0.00 Backend connections not attempted
backend_busy 0 0.00 Backend connections too many
backend_fail 0 0.00 Backend connections failures
backend_reuse 1920 9.06 Backend connections reuses
backend_recycle 2038 9.61 Backend connections recycles
backend_unused 0 0.00 Backend connections unused
n_srcaddr 365 . N struct srcaddr
n_srcaddr_act 0 . N active struct srcaddr
n_sess_mem 952 . N struct sess_mem
n_sess 1 . N struct sess
n_object 750 . N struct object
n_objecthead 1079 . N struct objecthead
n_smf 1272 . N struct smf
n_smf_frag 98 . N small free smf
n_smf_large 2 . N large free smf
n_vbe_conn 4 . N struct vbe_conn
n_bereq 88 . N struct bereq
n_wrk 1600 . N worker threads
n_wrk_create 1600 7.55 N worker threads created
n_wrk_failed 0 0.00 N worker threads not created
n_wrk_max 0 0.00 N worker threads limited
n_wrk_queue 0 0.00 N queued work requests
n_wrk_overflow 980 4.62 N overflowed work requests
n_wrk_drop 0 0.00 N dropped work requests
n_backend 6 . N backends
n_expired 54 . N expired objects
n_lru_nuked 0 . N LRU nuked objects
n_lru_saved 0 . N LRU saved objects
n_lru_moved 833 . N LRU moved objects
n_deathrow 0 . N objects on deathrow
losthdr 0 0.00 HTTP header overflows
n_objsendfile 0 0.00 Objects sent with sendfile
n_objwrite 4589 21.65 Objects sent with write
n_objoverflow 0 0.00 Objects overflowing workspace
s_sess 1517 7.16 Total Sessions
s_req 5662 26.71 Total Requests
s_pipe 0 0.00 Total pipe
s_pass 1871 8.83 Total pass
s_fetch 2307 10.88 Total fetch
s_hdrbytes 1673491 7893.83 Total header bytes
s_bodybytes 26560497 125285.36 Total body bytes
sess_closed 249 1.17 Session Closed
sess_pipeline 0 0.00 Session Pipeline
sess_readahead 0 0.00 Session Read Ahead
sess_linger 0 0.00 Session Linger
sess_herd 5428 25.60 Session herd
shm_records 308891 1457.03 SHM records
shm_writes 20426 96.35 SHM writes
shm_flushes 0 0.00 SHM flushes due to overflow
shm_cont 14 0.07 SHM MTX contention
shm_cycles 0 0.00 SHM cycles through buffer
sm_nreq 5117 24.14 allocator requests
sm_nobj 1172 . outstanding allocations
sm_balloc 10076160 . bytes allocated
sm_bfree 5983641600 . bytes free
sma_nreq 0 0.00 SMA allocator requests
sma_nobj 0 . SMA outstanding allocations
sma_nbytes 0 . SMA outstanding bytes
sma_balloc 0 . SMA bytes allocated
sma_bfree 0 . SMA bytes free
sms_nreq 125 0.59 SMS allocator requests
sms_nobj 0 . SMS outstanding allocations
sms_nbytes 0 . SMS outstanding bytes
sms_balloc 58250 . SMS bytes allocated
sms_bfree 58250 . SMS bytes freed
backend_req 2307 10.88 Backend requests made
n_vcl 1 0.00 N vcl total
n_vcl_avail 1 0.00 N vcl available
n_vcl_discard 0 0.00 N vcl discarded
n_purge 1 . N total active purges
n_purge_add 1 0.00 N new purges added
n_purge_retire 0 0.00 N old purges deleted
n_purge_obj_test 0 0.00 N objects tested
n_purge_re_test 0 0.00 N regexps tested against
n_purge_dups 0 0.00 N duplicate purges removed
hcb_nolock 0 0.00 HCB Lookups without lock
hcb_lock 0 0.00 HCB Lookups with lock
hcb_insert 0 0.00 HCB Inserts
esi_parse 0 0.00 Objects ESI parsed (unlock)
esi_errors 0 0.00 ESI parse errors (unlock)
Tung
On Wed, Apr 1, 2009 at 7:24 AM, Tung Nguyen <tnguyen at bleacherreport.com>wrote:
> Hey guys,
>
> Our requests seem to be getting timed out. I set all the timeout
> parameters pretty high, so wondering what could be causing it.
>
> Also, how do I check out the number of current threads being used in
> varnishstat?
>
> Thanks,
> Tung
>
> # ps auxww | grep varnish
> root 2649 0.0 2.4 101776 82744 pts/0 S< 13:48 0:00 varnishlog
> -w varnish.log
> root 4301 0.0 0.0 110552 1136 ? S<s 14:05 0:00
> /usr/sbin/varnishd -P /var/run/varnishd.pid -a :6081 -T localhost:6082 -p
> sess_timeout 25 -p obj_workspace 8192 -p sess_workspace 32768 -p
> listen_depth 8192 -p connect_timeout 3s -p thread_pool_min 100 -f
> /etc/varnish/default.vcl
> nobody 4302 0.0 1.1 7781688 39468 ? S<l 14:05 0:00
> /usr/sbin/varnishd -P /var/run/varnishd.pid -a :6081 -T localhost:6082 -p
> sess_timeout 25 -p obj_workspace 8192 -p sess_workspace 32768 -p
> listen_depth 8192 -p connect_timeout 3s -p thread_pool_min 100 -f
> /etc/varnish/default.vcl
> root 4872 0.0 0.0 3876 556 pts/0 R<+ 14:22 0:00 grep
> --colour=auto varnish
> #
>
>
> 0 VCL_call - prefetch
> 0 VCL_return - fetch
> 0 Debug - "Attempt Prefetch 1804102565"
> 0 Backend_health - A3 Still healthy 4--X-S-RH 5 3 5 0.000000 0.000000
> HTTP/1.1 200 OK
> 0 Backend_health - A1 Still healthy 4--X-S-RH 5 3 5 0.000000 0.001500
> HTTP/1.1 200 OK
> 0 Backend_health - A6 Still healthy 4--X-S-RH 5 3 5 0.000000 0.000001
> HTTP/1.1 200 OK
> 0 Backend_health - A2 Still healthy 4--X-S-RH 5 3 5 0.000000 0.000000
> HTTP/1.1 200 OK
> 0 Backend_health - A4 Still healthy 4--X-S-RH 5 3 5 0.000000 0.000042
> HTTP/1.1 200 OK
> 0 ExpPick - 1804096341 ttl
> 0 VCL_call - timeout
> 0 VCL_return - discard
> 0 ExpKill - 1804096341 -30
> 0 ExpPick - 1804096350 ttl
> 0 VCL_call - timeout
> 0 VCL_return - discard
> 0 ExpKill - 1804096350 -30
> 0 ExpPick - 1804096354 ttl
> 0 VCL_call - timeout
> 0 VCL_return - discard
> 0 ExpKill - 1804096354 -30
> 0 ExpPick - 1804096376 ttl
> 0 VCL_call - timeout
> 0 VCL_return - discard
> 0 ExpKill - 1804096376 -30
> 0 ExpPick - 1804096384 ttl
> 0 VCL_call - timeout
> 0 VCL_return - discard
> 0 ExpKill - 1804096384 -30
> 0 CLI - Rd ping
> 0 CLI - Wr 0 200 PONG 1238593700 1.0
> 0 Backend_health - A5 Still healthy 4--X-S-RH 5 3 5 0.000000 0.000000
> HTTP/1.1 200 OK
> 0 ExpPick - 1804102829 prefetch
> 0 VCL_call - prefetch
> 0 VCL_return - fetch
> 0 Debug - "Attempt Prefetch 1804102829"
> 0 Backend_health - A3 Still healthy 4--X-S-RH 5 3 5 0.000000 0.000000
> HTTP/1.1 200 OK
> 0 Backend_health - A1 Still healthy 4--X-S-RH 5 3 5 0.000000 0.001125
> HTTP/1.1 200 OK
> 0 Backend_health - A6 Still healthy 4--X-S-RH 5 3 5 0.000000 0.000001
> HTTP/1.1 200 OK
> 0 Backend_health - A2 Still healthy 4--X-S-RH 5 3 5 0.000000 0.000000
> HTTP/1.1 200 OK
> 0 Backend_health - A4 Still healthy 4--X-S-RH 5 3 5 0.000000 0.000032
> HTTP/1.1 200 OK
> 0 CLI - Rd ping
> 0 CLI - Wr 0 200 PONG 1238593703 1.0
> 0 ExpPick - 1803925354 ttl
> 0 VCL_call - timeout
>
>
> param.show
> 200 2137
> accept_fd_holdoff 50 [ms]
> acceptor default (epoll, poll)
> auto_restart on [bool]
> backend_http11 on [bool]
> between_bytes_timeout 60.000000 [s]
> cache_vbe_conns off [bool]
> cc_command "exec cc -fpic -shared -Wl,-x -o %o %s"
> cli_buffer 8192 [bytes]
> cli_timeout 5 [seconds]
> client_http11 off [bool]
> clock_skew 10 [s]
> connect_timeout 1.000000 [s]
> default_grace 10
> default_ttl 120 [seconds]
> diag_bitmap 0x0 [bitmap]
> err_ttl 0 [seconds]
> esi_syntax 0 [bitmap]
> fetch_chunksize 128 [kilobytes]
> first_byte_timeout 60.000000 [s]
> group nobody (65534)
> listen_address :6081
> listen_depth 8192 [connections]
> log_hashstring off [bool]
> log_local_address off [bool]
> lru_interval 2 [seconds]
> max_esi_includes 5 [includes]
> max_restarts 4 [restarts]
> obj_workspace 8192 [bytes]
> overflow_max 100 [%]
> ping_interval 3 [seconds]
> pipe_timeout 60 [seconds]
> prefer_ipv6 off [bool]
> purge_dups off [bool]
> purge_hash on [bool]
> rush_exponent 3 [requests per request]
> send_timeout 600 [seconds]
> sess_timeout 10 [seconds]
> sess_workspace 32768 [bytes]
> session_linger 0 [ms]
> shm_reclen 255 [bytes]
> shm_workspace 8192 [bytes]
> srcaddr_hash 1049 [buckets]
> srcaddr_ttl 30 [seconds]
> thread_pool_add_delay 20 [milliseconds]
> thread_pool_add_threshold 2 [requests]
> thread_pool_fail_delay 200 [milliseconds]
> thread_pool_max 500 [threads]
> thread_pool_min 100 [threads]
> thread_pool_purge_delay 1000 [milliseconds]
> thread_pool_timeout 300 [seconds]
> thread_pools 2 [pools]
> user nobody (65534)
> vcl_trace off [bool]
>
>
>
> 0+00:01:23 ey03-s00419
> Hitrate ratio: 4 4 4
> Hitrate avg: 0.7154 0.7154 0.7154
>
>
> 2111 0.00 25.43 Client connections accepted
>
> 8315 0.00 100.18 Client requests received
>
> 5019 0.00 60.47 Cache hits
>
> 6 0.00 0.07 Cache hits for pass
>
> 805 0.00 9.70 Cache misses
>
> 2848 0.00 34.31 Backend connections success
>
> 2471 0.00 29.77 Backend connections reuses
>
> 2691 0.00 32.42 Backend connections recycles
>
> 456 . . N struct srcaddr
>
> 27 . . N active struct srcaddr
>
> 995 . . N struct sess_mem
>
> 55 . . N struct sess
>
> 584 . . N struct object
>
> 670 . . N struct objecthead
>
> 1147 . . N struct smf
>
> 1 . . N small free smf
>
> 1 . . N large free smf
>
> 6 . . N struct vbe_conn
>
> 22 . . N struct bereq
>
> 200 . . N worker threads
>
> 200 0.00 2.41 N worker threads created
>
> 57 0.00 0.69 N overflowed work requests
>
> 6 . . N backends
>
> 2046 . . N LRU moved objects
>
> 6277 0.00 75.63 Objects sent with write
>
> 2110 0.00 25.42 Total Sessions
>
> 8314 0.00 100.17 Total Requests
>
> 2491 0.00 30.01 Total pass
>
> 2847 0.00 34.30 Total fetch
>
> 2410204 0.00 29038.60 Total header bytes
>
> 38160409 0.00 459763.96 Total body bytes
>
> 605 0.00 7.29 Session Closed
>
> 2 0.00 0.02 Session Pipeline
>
> 6 0.00 0.07 Session Read Ahead
>
> 7734 0.00 93.18 Session herd
>
> 428358 12.00 5160.94 SHM records
>
> 26190 12.00 315.54 SHM writes
>
> 2 0.00 0.02 SHM MTX contention
>
> 6378 0.00 76.84 allocator requests
>
> 1145 . . outstanding allocations
>
> 12103680 . . bytes allocated
>
> 6028206080 . . bytes free
>
> 448 0.00 5.40 SMS allocator requests
>
> 208768 . . SMS bytes allocated
>
> 208768 . . SMS bytes freed
>
> 2848 0.00 34.31 Backend requests made
>
> 1 0.00 0.01 N vcl total
>
> 1 0.00 0.01 N vcl available
>
> 1 . . N total active purges
>
> 1 0.00 0.01 N new purges added
>
>
>
>
> Thanks,
> Tung
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <https://www.varnish-cache.org/lists/pipermail/varnish-misc/attachments/20090401/8ad8566e/attachment.html>
More information about the varnish-misc
mailing list