suspicious memory usage with 3.0.5

Lucas Luitjes lucas at silk.co
Mon Dec 21 15:44:41 CET 2015


Hi,

We're handling only 2-8 req/s and are using file based storage. Yet 
somehow varnish is using 1-2GB memory. RSS, not VM. I looked at the 
usual suspects, but the Transient storage is barely used, and there are 
only 33000 objects in cache so it can't be the object overhead either. 
I've read through two years worth on this list but wasn't able to find 
other possible causes.

Can anybody point me in the right direction?

I'm starting varnish with the following options:

DAEMON_OPTS="-a :80 \
              -T localhost:6082 \
              -f /etc/varnish/default.vcl \
              -S /etc/varnish/secret \
              -p sess_timeout=30s \
              -p shm_reclen=2048 \
              -s file,/mnt/varnish-storage/varnish.bin,15000m\
              -w 100,1000,120"

ps output:

USER       PID %CPU %MEM    VSZ   RSS TTY      STAT START   TIME COMMAND
root     19382  0.0  0.1 126700  5200 ?        Ss   Dec13 0:15 
/usr/sbin/varnishd -P /var/run/varnishd.pid -a :80 -T localhost:6082 -f 
/etc/varnish/default.vcl -S /etc/varnish/secret -p sess_timeout=30s -p 
shm_reclen=2048 -s
nobody   19386  0.4 31.5 4081716 1215100 ?     Sl   Dec13 46:45 
/usr/sbin/varnishd -P /var/run/varnishd.pid -a :80 -T localhost:6082 -f 
/etc/varnish/default.vcl -S /etc/varnish/secret -p sess_timeout=30s -p 
shm_reclen=2048 -s

Param.show:

varnish> param.show
200
acceptor_sleep_decay        0.900000 []
acceptor_sleep_incr         0.001000 [s]
acceptor_sleep_max          0.050000 [s]
auto_restart                on [bool]
ban_dups                    on [bool]
ban_lurker_sleep            0.010000 [s]
between_bytes_timeout       60.000000 [s]
cc_command                  "exec gcc -std=gnu99 -g -O2 
-fstack-protector --param=ssp-buffer-size=4 -Wformat 
-Werror=format-security -pthread -fpic -shared -Wl,-x -o %o %s"
cli_buffer                  8192 [bytes]
cli_timeout                 10 [seconds]
clock_skew                  10 [s]
connect_timeout             0.700000 [s]
critbit_cooloff             180.000000 [s]
default_grace               10.000000 [seconds]
default_keep                0.000000 [seconds]
default_ttl                 120.000000 [seconds]
diag_bitmap                 0x0 [bitmap]
esi_syntax                  0 [bitmap]
expiry_sleep                1.000000 [seconds]
fetch_chunksize             128 [kilobytes]
fetch_maxchunksize          262144 [kilobytes]
first_byte_timeout          60.000000 [s]
group                       nogroup (65534)
gzip_level                  6 []
gzip_memlevel               8 []
gzip_stack_buffer           32768 [Bytes]
gzip_tmp_space              0 []
gzip_window                 15 []
http_gzip_support           on [bool]
http_max_hdr                64 [header lines]
http_range_support          on [bool]
http_req_hdr_len            8192 [bytes]
http_req_size               32768 [bytes]
http_resp_hdr_len           8192 [bytes]
http_resp_size              32768 [bytes]
idle_send_timeout           60 [seconds]
listen_address              :80
listen_depth                1024 [connections]
log_hashstring              on [bool]
log_local_address           off [bool]
lru_interval                2 [seconds]
max_esi_depth               5 [levels]
max_restarts                4 [restarts]
nuke_limit                  50 [allocations]
pcre_match_limit            10000 []
pcre_match_limit_recursion  10000 []
ping_interval               3 [seconds]
pipe_timeout                60 [seconds]
prefer_ipv6                 off [bool]
queue_max                   100 [%]
rush_exponent               3 [requests per request]
saintmode_threshold         10 [objects]
send_timeout                600 [seconds]
sess_timeout                30 [seconds]
sess_workspace              65536 [bytes]
session_linger              50 [ms]
session_max                 100000 [sessions]
shm_reclen                  2048 [bytes]
shm_workspace               8192 [bytes]
shortlived                  10.000000 [s]
syslog_cli_traffic          on [bool]
thread_pool_add_delay       2 [milliseconds]
thread_pool_add_threshold   2 [requests]
thread_pool_fail_delay      200 [milliseconds]
thread_pool_max             1000 [threads]
thread_pool_min             100 [threads]
thread_pool_purge_delay     1000 [milliseconds]
thread_pool_stack           unlimited [bytes]
thread_pool_timeout         120 [seconds]
thread_pool_workspace       65536 [bytes]
thread_pools                2 [pools]
thread_stats_rate           10 [requests]
user                        nobody (65534)
vcc_err_unref               on [bool]
vcl_dir                     /etc/varnish
vcl_trace                   off [bool]
vmod_dir /usr/lib/x86_64-linux-gnu/varnish/vmods
waiter                      default (epoll, poll)

Varnishstat:

varnishstat -1
client_conn            1137599         1.63 Client connections accepted
client_drop                  0         0.00 Connection dropped, no sess/wrk
client_req             2032210         2.91 Client requests received
cache_hit               341943         0.49 Cache hits
cache_hitpass             1842         0.00 Cache hits for pass
cache_miss              708115         1.01 Cache misses
backend_conn             89175         0.13 Backend conn. success
backend_unhealthy            0         0.00 Backend conn. not attempted
backend_busy                 0         0.00 Backend conn. too many
backend_fail               560         0.00 Backend conn. failures
backend_reuse          1578521         2.26 Backend conn. reuses
backend_toolate          13907         0.02 Backend conn. was closed
backend_recycle        1592791         2.28 Backend conn. recycles
backend_retry             3123         0.00 Backend conn. retry
fetch_head               11776         0.02 Fetch head
fetch_length            198636         0.28 Fetch with Length
fetch_chunked          1387593         1.99 Fetch chunked
fetch_eof                    0         0.00 Fetch EOF
fetch_bad                    0         0.00 Fetch had bad headers
fetch_close                371         0.00 Fetch wanted close
fetch_oldhttp                0         0.00 Fetch pre HTTP/1.1 closed
fetch_zero                   0         0.00 Fetch zero len
fetch_failed                23         0.00 Fetch failed
fetch_1xx                    0         0.00 Fetch no body (1xx)
fetch_204                    0         0.00 Fetch no body (204)
fetch_304                  854         0.00 Fetch no body (304)
n_sess_mem                 199          .   N struct sess_mem
n_sess                      22          .   N struct sess
n_object                 32945          .   N struct object
n_vampireobject              0          .   N unresurrected objects
n_objectcore             33006          .   N struct objectcore
n_objecthead             33434          .   N struct objecthead
n_waitinglist              175          .   N struct waitinglist
n_vbc                       10          .   N struct vbc
n_wrk                      200          .   N worker threads
n_wrk_create               200         0.00 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_lqueue                 0         0.00 work request queue length
n_wrk_queued                 2         0.00 N queued work requests
n_wrk_drop                   0         0.00 N dropped work requests
n_backend                    4          .   N backends
n_expired               274186          .   N expired objects
n_lru_nuked             394697          .   N LRU nuked objects
n_lru_moved             286567          .   N LRU moved objects
losthdr                      8         0.00 HTTP header overflows
n_objsendfile                0         0.00 Objects sent with sendfile
n_objwrite             1993358         2.86 Objects sent with write
n_objoverflow                0         0.00 Objects overflowing workspace
s_sess                 1137600         1.63 Total Sessions
s_req                  2032210         2.91 Total Requests
s_pipe                   62579         0.09 Total pipe
s_pass                  894827         1.28 Total pass
s_fetch                1594496         2.28 Total fetch
s_hdrbytes           944136821      1352.28 Total header bytes
s_bodybytes        50610526058     72489.02 Total body bytes
sess_closed             230365         0.33 Session Closed
sess_pipeline              106         0.00 Session Pipeline
sess_readahead               0         0.00 Session Read Ahead
sess_linger            1857635         2.66 Session Linger
sess_herd              1831395         2.62 Session herd
shm_records          179189892       256.65 SHM records
shm_writes            13094383        18.75 SHM writes
shm_flushes               4218         0.01 SHM flushes due to overflow
shm_cont                 12594         0.02 SHM MTX contention
shm_cycles                 104         0.00 SHM cycles through buffer
sms_nreq                 11871         0.02 SMS allocator requests
sms_nobj                     0          .   SMS outstanding allocations
sms_nbytes                   0          .   SMS outstanding bytes
sms_balloc            10070143          .   SMS bytes allocated
sms_bfree             10070143          .   SMS bytes freed
backend_req            1601778         2.29 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_ban                       45          .   N total active bans
n_ban_gone                  42          .   N total gone bans
n_ban_add               173359         0.25 N new bans added
n_ban_retire            173314         0.25 N old bans deleted
n_ban_obj_test        65906808        94.40 N objects tested
n_ban_re_test        233394372       334.29 N regexps tested against
n_ban_dups              168535         0.24 N duplicate bans removed
hcb_nolock             1051594         1.51 HCB Lookups without lock
hcb_lock                705667         1.01 HCB Lookups with lock
hcb_insert              705663         1.01 HCB Inserts
esi_errors                   0         0.00 ESI parse errors (unlock)
esi_warnings                 0         0.00 ESI parse warnings (unlock)
accept_fail                  0         0.00 Accept failures
client_drop_late             0         0.00 Connection dropped late
uptime                  698182         1.00 Client uptime
dir_dns_lookups              0         0.00 DNS director lookups
dir_dns_failed               0         0.00 DNS director failed lookups
dir_dns_hit                  0         0.00 DNS director cached lookups hit
dir_dns_cache_full           0         0.00 DNS director full dnscache
vmods                        5          .   Loaded VMODs
n_gzip                       0         0.00 Gzip operations
n_gunzip                666967         0.96 Gunzip operations
sess_pipe_overflow           0          .   Dropped sessions due to 
session pipe overflow
LCK.sms.creat                1         0.00 Created locks
LCK.sms.destroy              0         0.00 Destroyed locks
LCK.sms.locks            35613         0.05 Lock Operations
LCK.sms.colls                0         0.00 Collisions
LCK.smp.creat                0         0.00 Created locks
LCK.smp.destroy              0         0.00 Destroyed locks
LCK.smp.locks                0         0.00 Lock Operations
LCK.smp.colls                0         0.00 Collisions
LCK.sma.creat                1         0.00 Created locks
LCK.sma.destroy              0         0.00 Destroyed locks
LCK.sma.locks          4808562         6.89 Lock Operations
LCK.sma.colls                0         0.00 Collisions
LCK.smf.creat                1         0.00 Created locks
LCK.smf.destroy              0         0.00 Destroyed locks
LCK.smf.locks          3799704         5.44 Lock Operations
LCK.smf.colls                0         0.00 Collisions
LCK.hsl.creat                0         0.00 Created locks
LCK.hsl.destroy              0         0.00 Destroyed locks
LCK.hsl.locks                0         0.00 Lock Operations
LCK.hsl.colls                0         0.00 Collisions
LCK.hcb.creat                1         0.00 Created locks
LCK.hcb.destroy              0         0.00 Destroyed locks
LCK.hcb.locks          1382264         1.98 Lock Operations
LCK.hcb.colls                0         0.00 Collisions
LCK.hcl.creat                0         0.00 Created locks
LCK.hcl.destroy              0         0.00 Destroyed locks
LCK.hcl.locks                0         0.00 Lock Operations
LCK.hcl.colls                0         0.00 Collisions
LCK.vcl.creat                1         0.00 Created locks
LCK.vcl.destroy              0         0.00 Destroyed locks
LCK.vcl.locks             2387         0.00 Lock Operations
LCK.vcl.colls                0         0.00 Collisions
LCK.stat.creat               1         0.00 Created locks
LCK.stat.destroy             0         0.00 Destroyed locks
LCK.stat.locks         1137777         1.63 Lock Operations
LCK.stat.colls               0         0.00 Collisions
LCK.sessmem.creat            1         0.00 Created locks
LCK.sessmem.destroy            0         0.00 Destroyed locks
LCK.sessmem.locks        1146538         1.64 Lock Operations
LCK.sessmem.colls              0         0.00 Collisions
LCK.wstat.creat                1         0.00 Created locks
LCK.wstat.destroy              0         0.00 Destroyed locks
LCK.wstat.locks           713721         1.02 Lock Operations
LCK.wstat.colls                0         0.00 Collisions
LCK.herder.creat               1         0.00 Created locks
LCK.herder.destroy             0         0.00 Destroyed locks
LCK.herder.locks               1         0.00 Lock Operations
LCK.herder.colls               0         0.00 Collisions
LCK.wq.creat                   2         0.00 Created locks
LCK.wq.destroy                 0         0.00 Destroyed locks
LCK.wq.locks             5522531         7.91 Lock Operations
LCK.wq.colls                   0         0.00 Collisions
LCK.objhdr.creat          705475         1.01 Created locks
LCK.objhdr.destroy        672290         0.96 Destroyed locks
LCK.objhdr.locks        73461950       105.22 Lock Operations
LCK.objhdr.colls               0         0.00 Collisions
LCK.exp.creat                  1         0.00 Created locks
LCK.exp.destroy                0         0.00 Destroyed locks
LCK.exp.locks            2312896         3.31 Lock Operations
LCK.exp.colls                  0         0.00 Collisions
LCK.lru.creat                  2         0.00 Created locks
LCK.lru.destroy                0         0.00 Destroyed locks
LCK.lru.locks            1340625         1.92 Lock Operations
LCK.lru.colls                  0         0.00 Collisions
LCK.cli.creat                  1         0.00 Created locks
LCK.cli.destroy                0         0.00 Destroyed locks
LCK.cli.locks             232608         0.33 Lock Operations
LCK.cli.colls                  0         0.00 Collisions
LCK.ban.creat                  1         0.00 Created locks
LCK.ban.destroy                0         0.00 Destroyed locks
LCK.ban.locks          135656520       194.30 Lock Operations
LCK.ban.colls                  0         0.00 Collisions
LCK.vbp.creat                  1         0.00 Created locks
LCK.vbp.destroy                0         0.00 Destroyed locks
LCK.vbp.locks                  0         0.00 Lock Operations
LCK.vbp.colls                  0         0.00 Collisions
LCK.vbe.creat                  1         0.00 Created locks
LCK.vbe.destroy                0         0.00 Destroyed locks
LCK.vbe.locks             179544         0.26 Lock Operations
LCK.vbe.colls                  0         0.00 Collisions
LCK.backend.creat              4         0.00 Created locks
LCK.backend.destroy            0         0.00 Destroyed locks
LCK.backend.locks        3454891         4.95 Lock Operations
LCK.backend.colls              0         0.00 Collisions
SMF.s0.c_req             1797552         2.57 Allocator requests
SMF.s0.c_fail             395043         0.57 Allocator failures
SMF.s0.c_bytes       95012720640    136085.89 Bytes allocated
SMF.s0.c_freed       94071521280    134737.82 Bytes freed
SMF.s0.g_alloc             67056          .   Allocations outstanding
SMF.s0.g_bytes         941199360          .   Bytes outstanding
SMF.s0.g_space         840527872          .   Bytes available
SMF.s0.g_smf               76469          .   N struct smf
SMF.s0.g_smf_frag           9402          .   N small free smf
SMF.s0.g_smf_large            11          .   N large free smf
SMA.Transient.c_req      1954222         2.80 Allocator requests
SMA.Transient.c_fail           0         0.00 Allocator failures
SMA.Transient.c_bytes 135146176063    193568.69 Bytes allocated
SMA.Transient.c_freed 135146173687    193568.69 Bytes freed
SMA.Transient.g_alloc            2          .   Allocations outstanding
SMA.Transient.g_bytes         2376          .   Bytes outstanding
SMA.Transient.g_space            0          .   Bytes available
VBE.prerender(10.0.0.194,,12000).vcls            1 .   VCL references
VBE.prerender(10.0.0.194,,12000).happy           0 .   Happy health probes
VBE.haproxy(127.0.0.1,,8080).vcls                1 .   VCL references
VBE.haproxy(127.0.0.1,,8080).happy               0 .   Happy health probes
VBE.tuna(127.0.0.1,,5555).vcls                   1 .   VCL references
VBE.tuna(127.0.0.1,,5555).happy                  0 .   Happy health probes
VBE.apache(127.0.0.1,,81).vcls                   1 .   VCL references
VBE.apache(127.0.0.1,,81).happy                  0 .   Happy health probes

Thanks!

Lucas Luitjes



More information about the varnish-misc mailing list