Squid 3.5.21 - High CPU (100%)

[Jasper Van Der Westhuizen <jvdwesthuiz@xxxxxxxxxxxxxx>]

Hi all

In my environment I have two Squid clusters that comprise of 4 VM's each, load balanced over a F5 LB. I will refer to them as cluster A (client facing) and cluster B(edge proxies). Depending on the destination, the traffic is routed from cluster A via ISP 1 or to cluster B via ISP 2. I have been having some problems with Squid using 100% CPU at times which impacts my users browsing experience. This would happen on both clusters, even after upgrading to the latest 3.5.21 build.

I also recently saw the following errors in the cache logs:

2016/09/20 14:37:02 kid1| DiskThreadsDiskFile::openDone: (2) No such file or directory

After some reading up it looks like files were removed without Squid knowing about it. My cache director was on a EXT3 FS with journaling enabled. To try and address a possible disk access/speed issue I disabled journaling on the LV.

I have also done some optimizing from a OS point of view.

In order to get the CPU utilization down, a simple squid -k reconfigure will be enough. Not a full restart.

During the last time I had a proxy servers CPU reach 100% I ran a cachemgr export and below is an extract. 

---

sample_start_time = 1474463096.261275 (Wed, 21 Sep 2016 13:04:56 GMT)
sample_end_time = 1474463396.382713 (Wed, 21 Sep 2016 13:09:56 GMT)
client_http.requests = 101.722157/sec
client_http.hits = 6.623985/sec
client_http.errors = 18.505842/sec
client_http.kbytes_in = 4718.936473/sec
client_http.kbytes_out = 4148.813921/sec
client_http.all_median_svc_time = 0.898576 seconds
client_http.miss_median_svc_time = 0.321543 seconds
client_http.nm_median_svc_time = 0.008653 seconds
client_http.nh_median_svc_time = 0.220042 seconds
client_http.hit_median_svc_time = 0.013867 seconds
server.all.requests = 78.671488/sec
server.all.errors = 0.000000/sec
server.all.kbytes_in = 7963.083264/sec
server.all.kbytes_out = 4704.282405/sec
server.http.requests = 31.533902/sec
server.http.errors = 0.000000/sec
server.http.kbytes_in = 4451.098225/sec
server.http.kbytes_out = 45.414950/sec
server.ftp.requests = 0.000000/sec
server.ftp.errors = 0.000000/sec
server.ftp.kbytes_in = 0.000000/sec
server.ftp.kbytes_out = 0.000000/sec
server.other.requests = 47.137586/sec
server.other.errors = 0.000000/sec
server.other.kbytes_in = 3511.981707/sec
server.other.kbytes_out = 4658.870787/sec
icp.pkts_sent = 0.000000/sec
icp.pkts_recv = 0.000000/sec
icp.queries_sent = 0.000000/sec
icp.replies_sent = 0.000000/sec
icp.queries_recv = 0.000000/sec
icp.replies_recv = 0.000000/sec
icp.replies_queued = 0.000000/sec
icp.query_timeouts = 0.000000/sec
icp.kbytes_sent = 0.000000/sec
icp.kbytes_recv = 0.000000/sec
icp.q_kbytes_sent = 0.000000/sec
icp.r_kbytes_sent = 0.000000/sec
icp.q_kbytes_recv = 0.000000/sec
icp.r_kbytes_recv = 0.000000/sec
icp.query_median_svc_time = 0.000000 seconds
icp.reply_median_svc_time = 0.000000 seconds
dns.median_svc_time = 0.002783 seconds
unlink.requests = 0.000000/sec
page_faults = 0.029988/sec
select_loops = 260.427914/sec
select_fds = 4391.065859/sec
average_select_fd_period = 0.000000/fd
median_select_fds = 1.000000
swap.outs = 6.204155/sec
swap.ins = 2.312397/sec
swap.files_cleaned = 0.000000/sec
aborted_requests = 2.962134/sec
syscalls.disk.opens = 8.253326/sec
syscalls.disk.closes = 16.216769/sec
syscalls.disk.reads = 24.953232/sec
syscalls.disk.writes = 998.445836/sec
syscalls.disk.seeks = 0.000000/sec
syscalls.disk.unlinks = 1.426089/sec
syscalls.sock.accepts = 74.449863/sec
syscalls.sock.sockets = 59.052763/sec
syscalls.sock.connects = 59.052763/sec
syscalls.sock.binds = 0.000000/sec
syscalls.sock.closes = 137.934165/sec
syscalls.sock.reads = 2467.637783/sec
syscalls.sock.writes = 1735.070988/sec
syscalls.sock.recvfroms = 24.050265/sec
syscalls.sock.sendtos = 14.464145/sec
cpu_time = 295.754484 seconds
wall_time = 300.121438 seconds
cpu_usage = 98.544938%

Here is one some time later after running a suid -k reconfigure.

Cache Manager menu

sample_start_time = 1474465618.601004 (Wed, 21 Sep 2016 13:46:58 GMT)
sample_end_time = 1474465918.604173 (Wed, 21 Sep 2016 13:51:58 GMT)
client_http.requests = 72.862564/sec
client_http.hits = 1.216654/sec
client_http.errors = 3.693294/sec
client_http.kbytes_in = 904.270448/sec
client_http.kbytes_out = 3676.207834/sec
client_http.all_median_svc_time = 0.649683 seconds
client_http.miss_median_svc_time = 0.177113 seconds
client_http.nm_median_svc_time = 0.000000 seconds
client_http.nh_median_svc_time = 0.034266 seconds
client_http.hit_median_svc_time = 0.009754 seconds
server.all.requests = 72.545900/sec
server.all.errors = 0.000000/sec
server.all.kbytes_in = 3668.624580/sec
server.all.kbytes_out = 892.610571/sec
server.http.requests = 32.159660/sec
server.http.errors = 0.000000/sec
server.http.kbytes_in = 503.211351/sec
server.http.kbytes_out = 43.506207/sec
server.ftp.requests = 0.000000/sec
server.ftp.errors = 0.000000/sec
server.ftp.kbytes_in = 0.000000/sec
server.ftp.kbytes_out = 0.000000/sec
server.other.requests = 40.386240/sec
server.other.errors = 0.000000/sec
server.other.kbytes_in = 3165.409896/sec
server.other.kbytes_out = 849.101031/sec
icp.pkts_sent = 0.000000/sec
icp.pkts_recv = 0.000000/sec
icp.queries_sent = 0.000000/sec
icp.replies_sent = 0.000000/sec
icp.queries_recv = 0.000000/sec
icp.replies_recv = 0.000000/sec
icp.replies_queued = 0.000000/sec
icp.query_timeouts = 0.000000/sec
icp.kbytes_sent = 0.000000/sec
icp.kbytes_recv = 0.000000/sec
icp.q_kbytes_sent = 0.000000/sec
icp.r_kbytes_sent = 0.000000/sec
icp.q_kbytes_recv = 0.000000/sec
icp.r_kbytes_recv = 0.000000/sec
icp.query_median_svc_time = 0.000000 seconds
icp.reply_median_svc_time = 0.000000 seconds
dns.median_svc_time = 0.000000 seconds
unlink.requests = 0.000000/sec
page_faults = 0.000000/sec
select_loops = 4294.267972/sec
select_fds = 3765.856887/sec
average_select_fd_period = 0.000000/fd
median_select_fds = 0.000000
swap.outs = 9.133237/sec
swap.ins = 2.816637/sec
swap.files_cleaned = 0.000000/sec
aborted_requests = 0.623327/sec
syscalls.disk.opens = 10.643221/sec
syscalls.disk.closes = 21.233109/sec
syscalls.disk.reads = 3.226633/sec
syscalls.disk.writes = 201.931200/sec
syscalls.disk.seeks = 0.000000/sec
syscalls.disk.unlinks = 0.433329/sec
syscalls.sock.accepts = 44.596196/sec
syscalls.sock.sockets = 49.176147/sec
syscalls.sock.connects = 49.176147/sec
syscalls.sock.binds = 49.176147/sec
syscalls.sock.closes = 93.635678/sec
syscalls.sock.reads = 1762.804712/sec
syscalls.sock.writes = 1817.204138/sec
syscalls.sock.recvfroms = 38.502927/sec
syscalls.sock.sendtos = 21.323108/sec
cpu_time = 59.151697 seconds
wall_time = 300.003169 seconds
cpu_usage = 19.717024%

Compile options:

Squid Cache: Version 3.5.21
Service Name: squid
configure options:  '--prefix=/usr/local/squid3.5.21' '--sysconfdir=/etc/squid3.5.21' '--enable-follow-x-forwarded-for' '--with-logdir=/var/log/squid/' '-with-pidfile=/var/run/squid.pid' '--w
ith-swapdir=/var/cache/squid/' '--with-large-files' '--with-default-user=squid' '--with-included-ltdl' '--enable-snmp' '--enable-storeio=ufs,aufs' '--enable-removal-policies=lru,heap' '--enab
le-ltdl-convenience'

Any help or suggestions would be greatly appreciated.

--

Kind Regards

Jasper

Disclaimer:
http://www.shopriteholdings.co.za/Pages/ShopriteE-mailDisclaimer.aspx

_______________________________________________
squid-users mailing list
squid-users@xxxxxxxxxxxxxxxxxxxxx
http://lists.squid-cache.org/listinfo/squid-users