requests keep timing out
Tung Nguyen
tnguyen at bleacherreport.com
Wed Apr 1 17:29:33 CEST 2009
And here's the backtrace I tried to capture from one the hunged varnishes.
# ps auxww | grep varnish
root 2649 0.0 2.4 101776 82744 pts/0 S< 13:48 0:01 varnishlog
-w varnish.log
root 25199 0.0 0.0 110556 1140 ? S<s 15:12 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 262144 -p
listen_depth 8192 -w 400,1000,60 -p connect_timeout 3s -p thread_pools 4 -p
thread_pool_min 400 -p thread_pool_max 4000 -f /etc/varnish/default.vcl
nobody 25200 0.0 1.9 19500060 64732 ? S<l 15:12 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 262144 -p
listen_depth 8192 -w 400,1000,60 -p connect_timeout 3s -p thread_pools 4 -p
thread_pool_min 400 -p thread_pool_max 4000 -f /etc/varnish/default.vcl
root 27034 0.0 0.0 3876 556 pts/0 R<+ 15:23 0:00 grep
--colour=auto varnish
# which gdb
/usr/bin/gdb
# gdb /usr/sbin/varnishd 25200
GNU gdb 6.7.1
Copyright (C) 2007 Free Software Foundation, Inc.
License GPLv3+: GNU GPL version 3 or later <http://gnu.org/licenses/gpl.html
>
This is free software: you are free to change and redistribute it.
There is NO WARRANTY, to the extent permitted by law. Type "show copying"
and "show warranty" for details.
This GDB was configured as "x86_64-pc-linux-gnu"...
(no debugging symbols found)
Using host libthread_db library "/lib/libthread_db.so.1".
(no debugging symbols found)
Attaching to program: /usr/sbin/varnishd, process 25200
Error while mapping shared library sections:
./vcl.1P9zoqAU.so: No such file or directory.
Reading symbols from /usr/lib64/libvarnish.so.1...Reading symbols from
/usr/lib64/debug/usr/lib64/libvarnish.so.1.0.0.debug...(no debugging symbols
found)...done.
(no debugging symbols found)...done.
Loaded symbols for /usr/lib/libvarnish.so.1
Reading symbols from /usr/lib64/libvarnishcompat.so.1...Reading symbols from
/usr/lib64/debug/usr/lib64/libvarnishcompat.so.1.0.0.debug...(no debugging
symbols found)...done.
(no debugging symbols found)...done.
Loaded symbols for /usr/lib/libvarnishcompat.so.1
Reading symbols from /usr/lib64/libvcl.so.1...Reading symbols from
/usr/lib64/debug/usr/lib64/libvcl.so.1.0.0.debug...(no debugging symbols
found)...done.
(no debugging symbols found)...done.
Loaded symbols for /usr/lib/libvcl.so.1
Reading symbols from /lib64/libdl.so.2...Reading symbols from
/usr/lib64/debug/lib64/libdl-2.6.1.so.debug...done.
done.
Loaded symbols for /lib/libdl.so.2
Reading symbols from /lib64/libpthread.so.0...Reading symbols from
/usr/lib64/debug/lib64/libpthread-2.6.1.so.debug...done.
[Thread debugging using libthread_db enabled]
[New Thread 0x2ac6f560c440 (LWP 25200)]
[New Thread 0x2aaf18807950 (LWP 26852)]
.....
Loaded symbols for /lib/libnss_files.so.2
Symbol file not found for ./vcl.1P9zoqAU.so
0x00002ac6f5179c46 in poll () from /lib/libc.so.6
(gdb) bt
#0 0x00002ac6f5179c46 in poll () from /lib/libc.so.6
#1 0x0000000000411e95 in CLI_Run ()
#2 0x000000000041a5e3 in child_main ()
#3 0x000000000042954c in start_child ()
#4 0x000000000042985c in mgt_run ()
#5 0x000000000043316a in main ()
(gdb) cont
Continuing.
Program received signal SIGQUIT, Quit.
[Switching to Thread 0x40800950 (LWP 25201)]
0x00002ac6f5153a51 in nanosleep () from /lib/libc.so.6
(gdb) exit
Undefined command: "exit". Try "help".
(gdb) quit
The program is running. Quit anyway (and detach it)? (y or n) y
Quitting: Can't detach LWP 25949: No such process
Any help is appreciated.
Tung
On Wed, Apr 1, 2009 at 7:47 AM, Tung Nguyen <tnguyen at bleacherreport.com>wrote:
> 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/b345dcf3/attachment-0001.html>
More information about the varnish-misc
mailing list