Martin.Pichlmaier@xxxxxxxxxxxxxxxxxxxxxxxxxxx wrote:
Amos Jeffries <squid3@xxxxxxxxxxxxx> wrote on 15.06.2010 10:48:33:
Martin.Pichlmaier@xxxxxxxxxxxxxxxxxxxxxxxxxxx wrote:
Hello list,
I have a question regarding memory and CPU usage change from 3.0 to
3.1.
I have 4 forwards proxies with ICAP (c-icap and clamav), NTLMv2
authentication, all four proxies each have about 200-400 req/sec
on RedHat AS5 64bit servers with each 16GB mem for about 15k to 30k
users.
cache_mem is set to 3.5 GB, no disk cache, some ACLs are used.
With 3.0.STABLE23 the typical memory usage was about 7 GB and CPU
usage of
about 30-40% for the main squid process, without the helpers or other
processes.
With 3.1.4 the proxies use up to 2GB more memory and CPU usage rose at
times to 60% or 80%.
After a restart of one of the proxies it behaved "normally" since
then.
Status: (the CPU usage, Client HTTP out and requests per second are
all
from last 5 minute-info)
Proxy1: 36% CPU 7.2 GB mem 3.3 MB/s client out 341
req/s
Version 3.1.4
Proxy2: 77% CPU 8.6 GB mem 2.6 MB/s client out 384
req/s
Version 3.1.4 <-----
Proxy3: 53% CPU 8.8 GB mem 6.8 MB/s client out 402
req/s
Version 3.1.4
Proxy4: 32% CPU 6.8 GB mem 2.7 MB/s client out 405
req/s
Version 3.0.STABLE23
Configuration of the proxies is the same, with only the changes for
3.1,
mainly icap config.
Is there some kind of memory leak that additionally causes massive CPU
usage, could it be load related or is this normal behaviour?
Martin
With an explicit cache_mem there should be no difference between the
two.
Maybe; ICAP needs to buffer traffic twice as much as normal. One buffer
queue to ICAP server, one to client.
Maybe; with HTTP/1.1 being advertised now, if you have ignore_expect_100
turned on you can see the number of waiting clients rise. These are
active but 'hung' connections which waste more resources until the
client times out and continues.
Maybe; There are some known leaks in 3.0/3.1 auth. But that does not
account for the extra CPU unless it contributes to making the box swap
memory pages.
In general 3.1.4 has a lot of memory fixes than 3.0. Which are supposed
to cause less resource waste. Earlier 3.1.x default memory features were
broken on 64-bit. Check if turning memory pools on/off has any good
effect.
Amos
--
Please be using
Current Stable Squid 2.7.STABLE9 or 3.1.4
Hi Amos,
thanks for your reply and suggestions!
ICAP needs about two times of memory, that is true but was already the
same with 3.0.
ignore_expect_100 is not configured, therefore the default (turned off)
is used and about the same amount of ESTABLISHED and TIME_WAIT is seen
on 3.0 and 3.1, and only few other connection states, therefore I
"think" there is no problem of hanging connections.
Auth - hmm I have no idea to trace mem leaks here but at least the box
itself does not swap.
I am now checking with mem pools off on one of the proxies and report
later whether it changes anything.
But I have found two things to mention:
First squid is slowly needing more memory over time. In 3 hours the
"Process Data Segment Size via sbrk():" rose about 600MB. I will check
whether it will continue rising so fast and whether it changes with
memory_pool off.
The other thing is that with 3.1.4 I now have many
"ctx: enter level 1234: '<lost>'" messages in cache.log.
ctx messages were also with 3.0 but normally I had
"ctx enter level 0: 'some text'" immediately followed by
"ctx exit level 0".
With all three 3.1.4 proxies I see many "ctx enter level <rising number>"
without or only very few "ctx exit level" messages. This is new with
3.1.4 -- 3.1.3 here behaved like 3.0.
Here is a snip from the cache.log:
2010/06/15 11:36:09| ctx: enter level 2007: '<lost>'
2010/06/15 11:36:09| ctx: enter level 2008: '<lost>'
2010/06/15 11:36:09| ctx: enter level 2009: '<lost>'
2010/06/15 11:36:09| ctx: enter level 2010: '<lost>'
2010/06/15 11:36:09| ctx: enter level 2011: '<lost>'
2010/06/15 11:36:09| ctx: enter level 2012: '<lost>'
2010/06/15 11:36:09| ctx: enter level 2013: '<lost>'
2010/06/15 11:36:09| ctx: enter level 2014: '<lost>'
2010/06/15 11:36:09| ctx: enter level 2015: '<lost>'
2010/06/15 11:36:09| ctx: enter level 2016: '<lost>'
2010/06/15 11:36:09| ctx: enter level 2017: '<lost>'
2010/06/15 11:36:09| ctx: enter level 2018: '<lost>'
2010/06/15 11:36:09| ctx: enter level 2019: '<lost>'
2010/06/15 11:36:09| ctx: enter level 2020: '<lost>'
2010/06/15 11:36:09| ctx: enter level 2021: '<lost>'
2010/06/15 11:36:09| ctx: enter level 2022: '<lost>'
2010/06/15 11:36:09| ctx: enter level 2023: '<lost>'
2010/06/15 11:36:09| ctx: enter level 2024: '<lost>'
2010/06/15 11:36:09| ctx: enter level 2025: '<lost>'
2010/06/15 11:36:09| ctx: enter level 2026: '<lost>'
2010/06/15 11:36:09| ctx: enter level 2027: '<lost>'
2010/06/15 11:36:09| ctx: enter level 2028: '<lost>'
2010/06/15 11:36:09| ctx: enter level 2029: '<lost>'
2010/06/15 11:36:09| ctx: enter level 2030: '<lost>'
2010/06/15 11:36:09| ctx: enter level 2031: '<lost>'
2010/06/15 11:36:09| ctx: enter level 2032: '<lost>'
2010/06/15 11:36:09| ctx: enter level 2033: '<lost>'
2010/06/15 11:36:09| ctx: enter level 2034: '<lost>'
2010/06/15 11:36:09| ctx: enter level 2035: '<lost>'
2010/06/15 11:36:09| ctx: enter level 2036: '<lost>'
2010/06/15 11:36:09| ctx: enter level 2037: '<lost>'
2010/06/15 11:36:09| ctx: enter level 2038: '<lost>'
2010/06/15 11:36:09| ctx: enter level 2039: '<lost>'
2010/06/15 11:36:09| ctx: enter level 2040: '<lost>'
2010/06/15 11:36:09| ctx: enter level 2041: '<lost>'
2010/06/15 11:36:09| ctx: enter level 2042: '<lost>'
2010/06/15 11:36:09| ctx: enter level 2043: '<lost>'
2010/06/15 11:36:09| ctx: enter level 2044: '<lost>'
2010/06/15 11:36:09| ctx: enter level 2045: '<lost>'
2010/06/15 11:36:09| ctx: enter level 2046: '<lost>'
2010/06/15 11:36:09| ctx: enter level 2047: '<lost>'
2010/06/15 11:36:09| ctx: enter level 2048: '<lost>'
2010/06/15 11:36:09| # ctx: suspiciously deep (2048) nesting:
2010/06/15 11:37:06| ctx: exit level 2048
2010/06/15 11:37:06| ctx: enter level 2048: '<lost>'
2010/06/15 11:37:06| ctx: enter level 2049: '<lost>'
2010/06/15 11:37:06| ctx: enter level 2050: '<lost>'
2010/06/15 11:37:06| ctx: enter level 2051: '<lost>'
2010/06/15 11:37:06| ctx: enter level 2052: '<lost>'
2010/06/15 11:37:06| ctx: enter level 2053: '<lost>'
2010/06/15 11:37:06| ctx: enter level 2054: '<lost>'
2010/06/15 11:37:06| ctx: enter level 2055: '<lost>'
2010/06/15 11:37:06| ctx: enter level 2056: '<lost>'
2010/06/15 11:37:06| ctx: enter level 2057: '<lost>'
2010/06/15 11:37:06| ctx: enter level 2058: '<lost>'
2010/06/15 11:37:06| ctx: enter level 2059: '<lost>'
2010/06/15 11:37:06| ctx: enter level 2060: '<lost>'
X:}0/06/15 11:37:06| WARNING: suspicious CR characters in HTTP header {
2010/06/15 11:37:06| ctx: exit level 2060
2010/06/15 11:37:06| ctx: enter level 2060: '<lost>'
X:}0/06/15 11:37:06| WARNING: suspicious CR characters in HTTP header {
2010/06/15 11:37:06| ctx: exit level 2060
2010/06/15 11:37:06| ctx: enter level 2060: '<lost>'
X:}0/06/15 11:37:06| WARNING: suspicious CR characters in HTTP header {
2010/06/15 11:37:06| ctx: exit level 2060
2010/06/15 11:37:06| ctx: enter level 2060: '<lost>'
X:}0/06/15 11:37:06| WARNING: suspicious CR characters in HTTP header {
2010/06/15 11:37:06| ctx: exit level 2060
2010/06/15 11:37:06| ctx: enter level 2060: '<lost>'
X:}0/06/15 11:37:06| WARNING: suspicious CR characters in HTTP header {
2010/06/15 11:40:56| ctx: exit level 2060
2010/06/15 11:40:56| ctx: enter level 2060: '<lost>'
2010/06/15 11:40:56| ctx: enter level 2061: '<lost>'
Ouch. We've been wondering about these ctx loops. It is not something to
be terribly worried about, but can cause some "weird stuff" (yes that is
probably the best explanation).
Thanks to your reminder, I've just had another look and found one more
in header processing. Hopefully that was it.
Amos
--
Please be using
Current Stable Squid 2.7.STABLE9 or 3.1.4
