[squid-users] Squid3: 100 % CPU load during object caching

Sat Jul 25 08:25:32 UTC 2015

Thanks a lot for your comprehensive testing. Now we are sure that the issue is independent of the underlying OS.

I can easily reduce the maximum_object_size_in_memory. I have some constraints from our IT at the moment. I am confronted with a very bad disk IO in our BladeCenter, so I am forced to put as many objects in memory as possible in order to get adequate performance values. We are also rare with disk space. RAM is not an issue right now.

Maybe Amos finds a way to fix the issue. Fortunately, we have a find a workaround.

Have a nice weekend!

Regards,
Jens

Gesendet: Freitag, 24. Juli 2015 um 19:01 Uhr
Von: "Marcus Kool" <marcus.kool at urlfilterdb.com>
An: "Jens Offenbach" <wolle5050 at gmx.de>, squid-users at lists.squid-cache.org
Betreff: Re: Aw: Re: [squid-users] Squid3: 100 % CPU load during object caching

On 07/24/2015 01:01 PM, Jens Offenbach wrote:
> @Marcus:
> I am not sure what exactly causes the problems, but could you please make a test with these two different settings:
> cache_mem 4 GB
> maximum_object_size_in_memory 1 GB

I think this setting for maximum_object_size_in_memory is too high, independent of how the performance is.
The tests also show that large objects cached on disk have a good performance.
The perfect place for a large ISO image is the disk cache.

I did the test with squid 3.5.6 and got the same result as you have:
the download starts fast but quickly drops. Squid uses 100% CPU.
wget displays 14 MB/sec ... 10 MB/sec ... 8 7 6 5 4 3 2 MB/sec and stays there for a long time.
At 50% downloaded the speed drops more to 1 MB/sec and at the end of the download I got 500 KB/sec *average*.
The second cached download was sustained 190 MB/sec and 120% CPU.

I did a second test with
cache_mem 4 GB
maximum_object_size_in_memory 200 MB

The download speed varied a lot: started with 30 MB/sec and went down and up many times between 6 MB/sec and 35 MB/sec.
The final average download speed was 31 MB/sec. 100% CPU.
The second cached download was sustained 190 MB/sec and 120% CPU.

Third test with
cache_mem 4 GB
maximum_object_size_in_memory 8 MB

The download speed started with 70 MB/sec and increased to 87 MB/sec. 100% CPU
The second cached download was sustained 190 MB/sec and 120% CPU.

4th test with
cache_mem 4 GB
maximum_object_size_in_memory 32 MB

The download speed started with 40 MB/sec and increased to 75 MB/sec. 100% CPU.
The second cached download was sustained 190 MB/sec and 120% CPU.

So Squid appears to have an issue with higher values of maximum_object_size_in_memory, the higher they are, the worse the performance.
For now, I would not go beyond 16 MB.
The question is, what is a reasonable size that you would like to be able to use for maximum_object_size_in_memory.
Do you have any particular requirement for a high maximum_object_size_in_memory ?

Marcus

> I think you will observe the behavior, that I was confronted with. The bad download rates of 500 KB/sec are gone, when I used the following settings:
> cache_mem 256 MB
> maximum_object_size_in_memory 16 MB
>
> I think Amos has an idea what seems to be the source of the problem:
> http://lists.squid-cache.org/pipermail/squid-users/2015-July/004728.html
>
> Regards,
> Jens
>
>
> Gesendet: Freitag, 24. Juli 2015 um 14:33 Uhr
> Von: "Marcus Kool" <marcus.kool at urlfilterdb.com>
> An: "Jens Offenbach" <wolle5050 at gmx.de>, squid-users at lists.squid-cache.org
> Betreff: Re: [squid-users] Squid3: 100 % CPU load during object caching
>
> On 07/24/2015 03:25 AM, Jens Offenbach wrote:
>> I have made a quick test of Squid 3.3.8 on Ubuntu 15.04 and I get the same problem: 100 % CPU usage, 500 KB/sec download rate.
>>
>>
>> Gesendet: Freitag, 24. Juli 2015 um 07:54 Uhr
>> Von: "Jens Offenbach" <wolle5050 at gmx.de>
>> An: "Marcus Kool" <marcus.kool at urlfilterdb.com>, "Eliezer Croitoru" <eliezer at ngtech.co.il>, "Amos Jeffries" <squid3 at treenet.co.nz>, squid-users at lists.squid-cache.org
>> Betreff: Re: [squid-users] Squid3: 100 % CPU load during object caching
>> It is not easy for me, but I have tested Squid 3.3.8 from the Ubuntu packaging on a "real" physical infrastructure. I get the same results on the physical machine (1x Intel(R) Xeon(R) CPU E3-1225 V2 @ 3.20GHz, 32 GB RAM, 1 TB disk) where Squid is running: 100 % CPU usage, 500 KB/sec download rate. All machines are idle and we have 1 GBit ethernet.
>>
>> The strace log from the physical test scenario can be found here, but I think it does not differ from the "virtual" test scenario:
>> http://wikisend.com/download/293856/squid.strace2[http://wikisend.com/download/293856/squid.strace2]
>>
>> @Marcus:
>> Have you verified that the file does not fit into memory and gets cached on disk? On which OS is Squid running? What are your build options of Squid (squid -v)? Is it possible that the issue is not part of 3.4.12? Do we have a regression?
>
> I screwed up earlier since the maximum_object_size was too low for the test with a 1 GB file and did a new test.
>
> The system has 64 GB memory and for sure the entire file is in the file system cache. The disk system is HW RAID-1 with 1 GB cache.
> The OS is Linux 3.10, CentOS 7 latest patches.
>
> New test:
> test system: 1 CPU with 4 cores/8 threads @ 3.7 GHz, 64 GB memory, AUFS, 1 Gbit pipe, 500 mbit guaranteed
>
> with Squid 3.4.12 :
> 1st download starts with 90 MB/sec and halfway drops to 30 MB/sec. My guess is that the file system cache got stressed and slowed things down.
> 2nd cached download with 190 MB/sec sustained and 120% CPU time.
>
> With Squid 3.5.6 :
> 1st download starts with 90 MB/sec sustained and 80% CPU time.
> 2nd cached download with 190 MB/sec sustained and 120% CPU time.
>
> As a comparison, I did "dd if=test of=test2 bs=4k" which uses 100% CPU time and has a throughput of 1200 MB/sec.
> With bs=16k the throughput is 1300 MB/sec and with bs=64k the throughput is 1400 MB/sec.
>
> relevant parameters :
> read_ahead_gap 64 KB
> cache_mem 256 MB
> maximum_object_size_in_memory 8 MB
> maximum_object_size 8000 MB
> cache_dir aufs /local/squid34/cache 10000 32 256
> cache_swap_low 92
> cache_swap_high 93
> # also ICAP daemon and URL rewriter configured
> debug_options ALL,1 93,3 61,9
>
> configure options:
> '--prefix=/local/squid35' '--disable-ipv6' '--enable-fd-config' '--with-maxfd=3200' '--enable-async-io=64' '--enable-storeio=aufs' '--with-pthreads' '--enable-removal-policies=lru'
> '--disable-auto-locale' '--enable-default-err-language=English' '--enable-err-languages=Dutch English Portuguese' '--with-openssl' '--enable-ssl' '--enable-ssl-crtd'
> '--enable-cachemgr-hostname=localhost' '--enable-cache-digests' '--enable-follow-x-forwarded-for' '--enable-xmalloc-statistics' '--disable-hostname-checks' '--enable-epoll' '--enable-icap-client'
> '--enable-useragent-log' '--enable-referer-log' '--enable-stacktraces' '--enable-underscores' '--disable-icmp' '--mandir=/usr/local/share' 'CC=gcc' 'CFLAGS=-g -O2 -Wall -march=native' 'CXXFLAGS=-g -O2
> -Wall -march=native' --enable-ltdl-convenience
>
> As you can see the cache_mem is small, If Amos finds it useful, I can do another test with a larger cache_mem.
>
> Jens, since all your tests have a drop to 500 KB/sec I think the cause is somewhere is the configuration (Squid and/or OS).
>
> Marcus
>
>
>> @Amos, Eliezer
>> Is someone able to reproduce the disk caching effect?
>>
>> Regards,
>> Jens
>>
>>
>> Gesendet: Donnerstag, 23. Juli 2015 um 20:08 Uhr
>> Von: "Marcus Kool" <marcus.kool at urlfilterdb.com>
>> An: "Jens Offenbach" <wolle5050 at gmx.de>, "Amos Jeffries" <squid3 at treenet.co.nz>, "Eliezer Croitoru" <eliezer at ngtech.co.il>, squid-users at lists.squid-cache.org
>> Betreff: Re: Aw: Re: [squid-users] Squid3: 100 % CPU load during object caching
>> The strace output shows this loop:
>>
>> Squid reads 16K-1 bytes from FD 13 webserver
>> Squid writes 4 times 4K to FD 17 /var/cache/squid3/00/00/00000000
>> Squid writes 4 times 4K to FD 12 browser
>>
>> But this loop does not explain the 100% CPU usage...
>>
>> Does Squid do a buffer reshuffle when it reads 16K-1 and writes 16K ?
>>
>> I did the download test with Squid 3.4.12 AUFS on an idle system with a 500 mbit connection and 1 CPU with 4 cores @ 3.7 GHz.
>> The first download used 35% of 1 CPU core with a steady download speed of 62 MB/sec.
>> The second (cached) download used 50% of 1 CPU core with a steady download speed of 87 MB/sec.
>> I never looked at Squid CPU usage and do not know what is reasonable but it feels high.
>>
>> With respect to the 100% CPU issue of Jens, one factor is that Squid runs in a virtual machine.
>> Squid in a virtual machine cannot be compared with a wget test since Squid allocates a lot of memory that the host must manage.
>> This is a possible explanation for the fact that you see the performance going down and up.
>> Can you do the same test on the host (i.e. not inside a VM).
>>
>> Marcus
>>
>>
>>
>> On 07/23/2015 10:39 AM, Jens Offenbach wrote:
>>> I have attached strace to Squid and waited until the download rate has decreased to 500 KB/sec.
>>> I used "cache_dir aufs /var/cache/squid3 88894 16 256 max-size=10737418240".
>>> Here is the download link:
>>> http://w1.wikisend.com/node-fs/download/6a004a416f65b4cdf7f8eff4ff961199/squid.strace[http://w1.wikisend.com/node-fs/download/6a004a416f65b4cdf7f8eff4ff961199/squid.strace][http://w1.wikisend.com/node-fs/download/6a004a416f65b4cdf7f8eff4ff961199/squid.strace[http://w1.wikisend.com/node-fs/download/6a004a416f65b4cdf7f8eff4ff961199/squid.strace]][http://w1.wikisend.com/node-fs/download/6a004a416f65b4cdf7f8eff4ff961199/squid.strace[http://w1.wikisend.com/node-fs/download/6a004a416f65b4cdf7f8eff4ff961199/squid.strace][http://w1.wikisend.com/node-fs/download/6a004a416f65b4cdf7f8eff4ff961199/squid.strace[http://w1.wikisend.com/node-fs/download/6a004a416f65b4cdf7f8eff4ff961199/squid.strace]]]
>>> I hope it can help you.
>>> *Gesendet:* Donnerstag, 23. Juli 2015 um 13:29 Uhr
>>> *Von:* "Marcus Kool" <marcus.kool at urlfilterdb.com>
>>> *An:* "Jens Offenbach" <wolle5050 at gmx.de>, "Eliezer Croitoru" <eliezer at ngtech.co.il>, "Amos Jeffries" <squid3 at treenet.co.nz>, squid-users at lists.squid-cache.org
>>> *Betreff:* Re: [squid-users] Squid3: 100 % CPU load during object caching
>>> I am not sure if it is relevant, maybe it is:
>>>
>>> I am developing an ICAP daemon and after the ICAP server sends a "100 continue"
>>> Squid sends the object to the ICAP server in small chunks of varying sizes:
>>> 4095, 5813, 1448, 4344, 1448, 1448, 2896, etc.
>>> Note that the interval of receiving the chunks is 1/1000th of a second.
>>> It seems that Squid forwards the object to the ICAP server every time it receives
>>> one or a few TCP packets.
>>>
>>> I have a suspicion that in the scenario of 100% CPU, large #write calls and low throughput a similar thing is happening:
>>> Squid physically stores a small part of the object many times, i.e. every time one or a few TCP packets arrive.
>>>
>>> Amos, is there a debug setting that can confirm/reject this suspicion?
>>>
>>> Marcus
>>>
>>>
>>> On 07/23/2015 04:25 AM, Jens Offenbach wrote:
>>>> A test with ROCK "cache_dir rock /var/cache/squid3 51200" gives very confusing results.
>>>>
>>>> I cleared the cache:
>>>> rm -rf /var/cache/squid3/*
>>>> squid -z
>>>> squid
>>>> http_proxy=http://139.2.57.120:3128/[http://139.2.57.120:3128/][http://139.2.57.120:3128/[http://139.2.57.120:3128/]][http://139.2.57.120:3128/[http://139.2.57.120:3128/][http://139.2.57.120:3128/[http://139.2.57.120:3128/]]][http://139.2.57.120:3128/[http://139.2.57.120:3128/][http://139.2.57.120:3128/[http://139.2.57.120:3128/]][http://139.2.57.120:3128/[http://139.2.57.120:3128/][http://139.2.57.120:3128/[http://139.2.57.120:3128/]]]] wget http://test-server/freesurfer-Linux-centos6_x86_64-stable-pub-v5.3.0.tar
>>>>
>>>> The download starts with 10 MB/sec and stays constant for 1 minutes, then it drops gradually to 1 MB/sec and stays there for some time. After 5 minutes the download rate returns back to 10 MB/sec
>>> very quickly and drops again step-by-step to 1 MB/sec. After 5-6 minutes the download rates rises again to 10 MB/sec and drops again gradually to 1 MB/sec.
>>>>
>>>> During caching progress, we have 100 % CPU usage and a disk IO that is corresponds with the download rate.
>>>>
>>>> For further investigations I give you my build properties:
>>>> squid -v
>>>> Squid Cache: Version 3.5.6
>>>> Service Name: squid
>>>> configure options: '--build=x86_64-linux-gnu' '--prefix=/usr' '--includedir=/include' '--mandir=/share/man' '--infodir=/share/info' '--sysconfdir=/etc' '--localstatedir=/var'
>>> '--libexecdir=/lib/squid3' '--srcdir=.' '--disable-maintainer-mode' '--disable-dependency-tracking' '--disable-silent-rules' '--datadir=/usr/share/squid3' '--sysconfdir=/etc/squid3'
>>> '--mandir=/usr/share/man' '--enable-inline' '--enable-async-io=8' '--enable-storeio=ufs,aufs,diskd,rock' '--enable-removal-policies=lru,heap' '--enable-delay-pools' '--enable-cache-digests'
>>> '--enable-underscores' '--enable-icap-client' '--enable-follow-x-forwarded-for' '--enable-auth-basic=DB,fake,getpwnam,LDAP,NCSA,NIS,PAM,POP3,RADIUS,SASL,SMB' '--enable-auth-digest=file,LDAP'
>>> '--enable-auth-negotiate=kerberos,wrapper' '--enable-auth-ntlm=fake,smb_lm' '--enable-external-acl-helpers=file_userip,kerberos_ldap_group,LDAP_group,session,SQL_session,unix_group,wbinfo_group'
>>> '--enable-url-rewrite-helpers=fake' '--enable-eui' '--enable-e
>>> s
>>> i' '--enable-icmp' '--enable-zph-qos' '--enable-ecap' '--disable-translation' '--with-swapdir=/var/cache/squid3' '--with-logdir=/var/log/squid3' '--with-pidfile=/var/run/squid3.pid'
>>> '--with-filedescriptors=65536' '--with-large-files' '--with-default-user=proxy' '--enable-linux-netfilter' 'build_alias=x86_64-linux-gnu' 'CFLAGS=-g -O2 -fPIE -fstack-protector
>>> --param=ssp-buffer-size=4 -Wformat -Werror=format-security -Wall' 'LDFLAGS=-Wl,-Bsymbolic-functions -fPIE -pie -Wl,-z,relro -Wl,-z,now' 'CPPFLAGS=-D_FORTIFY_SOURCE=2' 'CXXFLAGS=-g -O2 -fPIE
>>> -fstack-protector --param=ssp-buffer-size=4 -Wformat -Werror=format-security'
>>>>
>>>>
>>>> Gesendet: Mittwoch, 22. Juli 2015 um 21:47 Uhr
>>>> Von: "Eliezer Croitoru" <eliezer at ngtech.co.il>
>>>> An: squid-users at lists.squid-cache.org
>>>> Betreff: Re: [squid-users] Squid3: 100 % CPU load during object caching
>>>> On 22/07/2015 21:59, Eliezer Croitoru wrote:
>>>>> Hey Jens,
>>>>>
>>>>> I have tested the issue with LARGE ROCK and not AUFS or UFS.
>>>>> Using squid or not my connection to the server is about 2.5 MBps (20Mbps).
>>>>> Squid is sitting on an intel atom with SSD drive and on a HIT case the
>>>>> download speed is more then doubled to 4.5 MBps(36Mbps).
>>>>> I have not tried it with AUFS yet.
>>>>
>>>>
>>>> And I must admit that AUFS beats rock cache with speed.
>>>> I have tried rock with basic "cache_dir rock /var/spool/squid 8000" vs
>>>> "cache_dir aufs /var/spool/squid 8000 16 256" and the aufs cache HIT
>>>> results more then doubles 3 the speed rock gave with default settings.
>>>>
>>>> So about 15MBps which is 120Mbps.
>>>> I do not seem to feel what Jens feels but the 100% CPU might be because
>>>> of spinning disk hangs while reading the file from disk.
>>>>
>>>> Amos, I remember that there were some suggestions how to tune large rock.
>>>> Any hints?
>>>> I can test it and make it a suggestion for big files.
>>>>
>>>> Eliezer
>>>>
>>>> _______________________________________________
>>>> squid-users mailing list
>>>> squid-users at lists.squid-cache.org
>>>> http://lists.squid-cache.org/listinfo/squid-users[http://lists.squid-cache.org/listinfo/squid-users][http://lists.squid-cache.org/listinfo/squid-users[http://lists.squid-cache.org/listinfo/squid-users]][http://lists.squid-cache.org/listinfo/squid-users[http://lists.squid-cache.org/listinfo/squid-users][http://lists.squid-cache.org/listinfo/squid-users[http://lists.squid-cache.org/listinfo/squid-users]]][http://lists.squid-cache.org/listinfo/squid-users[http://lists.squid-cache.org/listinfo/squid-users][http://lists.squid-cache.org/listinfo/squid-users[http://lists.squid-cache.org/listinfo/squid-users]][http://lists.squid-cache.org/listinfo/squid-users[http://lists.squid-cache.org/listinfo/squid-users][http://lists.squid-cache.org/listinfo/squid-users[http://lists.squid-cache.org/listinfo/squid-users]]]]
>>>> _______________________________________________
>>>> squid-users mailing list
>>>> squid-users at lists.squid-cache.org
>>>> http://lists.squid-cache.org/listinfo/squid-users[http://lists.squid-cache.org/listinfo/squid-users][http://lists.squid-cache.org/listinfo/squid-users[http://lists.squid-cache.org/listinfo/squid-users]][http://lists.squid-cache.org/listinfo/squid-users[http://lists.squid-cache.org/listinfo/squid-users][http://lists.squid-cache.org/listinfo/squid-users[http://lists.squid-cache.org/listinfo/squid-users]]][http://lists.squid-cache.org/listinfo/squid-users[http://lists.squid-cache.org/listinfo/squid-users][http://lists.squid-cache.org/listinfo/squid-users[http://lists.squid-cache.org/listinfo/squid-users]][http://lists.squid-cache.org/listinfo/squid-users[http://lists.squid-cache.org/listinfo/squid-users][http://lists.squid-cache.org/listinfo/squid-users[http://lists.squid-cache.org/listinfo/squid-users]]]]
>>>>
>> _______________________________________________
>> squid-users mailing list
>> squid-users at lists.squid-cache.org
>> http://lists.squid-cache.org/listinfo/squid-users[http://lists.squid-cache.org/listinfo/squid-users][http://lists.squid-cache.org/listinfo/squid-users[http://lists.squid-cache.org/listinfo/squid-users]][http://lists.squid-cache.org/listinfo/squid-users[http://lists.squid-cache.org/listinfo/squid-users][http://lists.squid-cache.org/listinfo/squid-users[http://lists.squid-cache.org/listinfo/squid-users]]]
>> _______________________________________________
>> squid-users mailing list
>> squid-users at lists.squid-cache.org
>> http://lists.squid-cache.org/listinfo/squid-users[http://lists.squid-cache.org/listinfo/squid-users][http://lists.squid-cache.org/listinfo/squid-users[http://lists.squid-cache.org/listinfo/squid-users]]
>>
>
>