Varnish 2.0.3 consuming excessive memory

[Darryl Dixon - Winterhouse Consulting]

> Not that I have an answer, but I'd be curious to see the differences
> in 'pmap -x <pid>' output for the different children.
>
> --Michael
>

That's a good thought - I'd almost forgotten about pmap. Anyhow, the
'normal' process is set up with a 2GB storage cache and pmap shows pretty
much what you would expect - the largest anonymous segment is 41MB, with
the vast majority of allocated memory booked against storage.cache (2GB).
The pmap for the 'runaway' process shows 256MB booked against
storage.cache, and then one of the an anonymous allocations is 2.3GB. For
example:


Normal process:
------------------------------------------------------
3896:   /u01/app/varnish/sbin/varnishd -a web-cms1.prd.internal:8080
web-cms.prd.internal:8080 -T web-cms1.prd.internal:18080 -t 108000 -f
/u01/data/prd/varnish/vcl.conf -s
file,/u01/data/prd/varnish/storage.cache,2048M -n
/u01/data/prd/varnish/state -P /u01/data/prd/varnish/varnishd.pid
Address           Kbytes     RSS    Anon  Locked Mode   Mapping
0000000000400000     312       -       -       - r-x--  varnishd
000000000064d000       8       -       -       - rw---  varnishd
000000000064f000      68       -       -       - rw---    [ anon ]
0000000040000000       4       -       -       - -----    [ anon ]
0000000040001000   10240       -       -       - rw---    [ anon ]
[...snip...]
00002aaab0900000 2097152       -       -       - rw-s-  storage.cache
00002aab30900000      28       -       -       - r-x--  vcl.1P9zoqAU.so
00002aab30907000    2044       -       -       - -----  vcl.1P9zoqAU.so
00002aab30b06000       8       -       -       - rw---  vcl.1P9zoqAU.so
00002aab30c00000    2056       -       -       - rw---    [ anon ]
00002aab30f00000    2056       -       -       - rw---    [ anon ]
00002aab31200000   41984       -       -       - rw---    [ anon ]
00007fffae8f2000      88       -       -       - rw---    [ stack ]
ffffffffff600000    8192       -       -       - -----    [ anon ]
----------------  ------  ------  ------  ------
total kB         2468512       -       -       -
------------------------------------------------------



Runaway process:
------------------------------------------------------
3940:   /u01/app/varnish/sbin/varnishd -a web-cms-edit1.prd.internal:8080
web-cms-edit.prd.internal:8080 -T web-cms-edit1.prd.internal:18080 -t 3600
-f /u01/data/prd-edit/varnish/vcl.conf -s
file,/u01/data/prd-edit/varnish/storage.cache,256M -n
/u01/data/prd-edit/varnish/state -P
/u01/data/prd-edit/varnish/varnishd.pid
Address           Kbytes     RSS    Anon  Locked Mode   Mapping
0000000000400000     312       -       -       - r-x--  varnishd
000000000064d000       8       -       -       - rw---  varnishd
000000000064f000      68       -       -       - rw---    [ anon ]
0000000040000000       4       -       -       - -----    [ anon ]
0000000040001000   10240       -       -       - rw---    [ anon ]
[...snip...]
00002aaab0900000  262144       -       -       - rw-s-  storage.cache
00002aaac0900000      28       -       -       - r-x--  vcl.1P9zoqAU.so
00002aaac0907000    2048       -       -       - -----  vcl.1P9zoqAU.so
00002aaac0b07000       8       -       -       - rw---  vcl.1P9zoqAU.so
00002aaac0c00000    2056       -       -       - rw---    [ anon ]
00002aaac0f00000    2052       -       -       - rw---    [ anon ]
00002aaac1200000  233476       -       -       - rw---    [ anon ]
00002aaacf700000 2337792       -       -       - rw---    [ anon ]
00007fff4b619000      84       -       -       - rw---    [ stack ]
ffffffffff600000    8192       -       -       - -----    [ anon ]
----------------  ------  ------  ------  ------
total kB         3121808       -       -       -
------------------------------------------------------


Both processes have been running for the same amount of time - 1day 17hours.

regards,
Darryl Dixon
Winterhouse Consulting Ltd
http://www.winterhouseconsulting.com



> On Apr 7, 2009, at 6:27 PM, Darryl Dixon - Winterhouse Consulting wrote:
>
>>> Hi All,
>>>
>>> I have an odd problem that I have only noticed happening since
>>> moving from
>>> 1.1.2 to 2.0.3 - excessive memory consumption of the varnish child
>>> process. For example, I have a varnish instance with a 256MB cache
>>> allocated, that is currently consuming 4.9GB of resident memory
>>> (6.5GB
>>> virtual). The instance has only been running for 4 days and has
>>> only got
>>> 25MB of objects in the cache.
>>>
>>> This is clearly excessive and is causing us some serious problems
>>> in terms
>>> of memory pressure on the machine. Our VCL is largely unchanged
>>> from our
>>> 1.1.2 setup to the 2.0.3 except for the obvious vcl.syntax changes,
>>> and
>>> the introduction of request restarts under certain limited
>>> scenarios. Can
>>> anyone shed some light?
>>>
>>
>> One further footnote to this. I have a second varnish instance
>> running on
>> the same machine which talks to different backend servers (still
>> primarily
>> the same sort of content though), with the VCL only fractionally
>> different
>> - it does not seem to suffer from the runaway memory consumption of
>> the
>> first instance. The only difference in the VCL between the two is
>> that in
>> the one with runaway memory this is present in vcl_recv():
>>
>> +    if (req.http.Pragma ~ ".*no-cache.*" || req.http.Cache-Control ~
>> ".*no-cache.*") {
>> +        purge_url(regsub(req.url, "[?].*$", ".*$"));
>> +    }
>> +
>>
>> Is there possibly something in the regsub engine being triggered
>> that is
>> very expensive and would cause it to consume and hold on to large
>> amounts
>> of memory?
>>