[squid-users] squid cpu usage

Fri Oct 27 07:05:55 UTC 2017

> From: Alex Rousskov <rousskov at measurement-factory.com>
>
>> # cat /etc/security/limits.d/01_squid.conf 
>> * hard nofile 65535
>> * soft nofile 16384
>
> Your Squid does not know about the above configured limits. It thinks the limit is 1024.

That's interesting.

# grep "file descriptors available" cache.log
2017/10/24 11:49:33 kid1| With 1024 file descriptors available
2017/10/24 12:57:10 kid1| With 16384 file descriptors available
2017/10/24 12:57:52 kid1| With 16384 file descriptors available
2017/10/25 05:50:32 kid1| With 1024 file descriptors available
2017/10/25 09:20:15 kid1| With 1024 file descriptors available
2017/10/25 10:00:15 kid1| With 1024 file descriptors available
2017/10/25 12:00:15 kid1| With 1024 file descriptors available
2017/10/25 13:00:16 kid1| With 1024 file descriptors available
2017/10/25 13:20:16 kid1| With 1024 file descriptors available
2017/10/25 14:00:15 kid1| With 1024 file descriptors available
2017/10/26 04:09:30 kid1| With 1024 file descriptors available
2017/10/26 10:57:45 kid1| With 16384 file descriptors available

The issues I reported yesterday came up after 2017/10/26 04:09:30, so here's the relevant part in the log:

2017/10/26 04:09:27 kid1| Reconfiguring Squid Cache (version 3.5.27-20170916-re69e56c)...
2017/10/26 04:09:27 kid1| Closing HTTP port [::]:3128
2017/10/26 04:09:27 kid1| Closing HTTP port [::]:3129
2017/10/26 04:09:27 kid1| Closing HTTPS port [::]:3130
2017/10/26 04:09:27 kid1| Closing Pinger socket on FD 801
2017/10/26 04:09:27 kid1| Logfile: closing log daemon:/var/log/squid/access.log
2017/10/26 04:09:27 kid1| Logfile Daemon: closing log daemon:/var/log/squid/access.log
2017/10/26 04:09:27 kid1| FATAL: dying from an unhandled exception: IsConnOpen(conn)
2017/10/26 04:09:30| Pinger exiting.
2017/10/26 04:09:30 kid1| Set Current Directory to /var/cache/squid
2017/10/26 04:09:30 kid1| Starting Squid Cache version 3.5.27-20170916-re69e56c for x86_64-pc-linux-gnu...
2017/10/26 04:09:30 kid1| Service Name: squid
2017/10/26 04:09:30 kid1| Process ID 22581
2017/10/26 04:09:30 kid1| Process Roles: worker
2017/10/26 04:09:30 kid1| With 1024 file descriptors available

A "reload" was issued at that time.

When my openrc init script reloads, it runs the following command:

# /etc/init.d/squid reload
* Reloading squid with /usr/sbin/squid -k reconfigure -f /etc/squid/squid.conf -n squid ...                                                            [ ok ]

I issued another "reload" today, and I didn't come up with any "file descriptors available" messages in cache.log (as expected).
I also checked mgr:info, and all seems OK:

File descriptor usage for squid:
Maximum number of file descriptors:   16384
Largest file desc currently in use:   3067
Number of file desc currently in use: 2901
Files queued for open:                   0
Available number of file descriptors: 13483
Reserved number of file descriptors:   100
Store Disk files open:                   0

I also grep'ed for the log lines around "2017/10/25 05:50:32 kid1| With 1024 file descriptors available" where I see 1024 file descriptors for the first time.
It was a clean restart (with no "FATAL" error message).
The "restart" command was launched from crontab as a daily job (calling the openrc init script) just like it is launched at boot time from openrc (when the number of file descriptors is "as expected").

In particular, I have: KRB5_KTNAME="/etc/krb5.keytab" /usr/sbin/squid -YC -f /etc/squid/squid.conf -n squid

I'm wondering why Squid only detected 1024 file descriptors available after that restart.

Moving back in time:

- "2017/10/24 12:57:52 kid1| With 16384 file descriptors available" was probably a manual restart on my behalf (passing "restart" to the init script on the console).

- the one right before (2017/10/24 12:57:10) was probably also a manual restart as the init script probably exited non-zero due to an error I found in the log: "FATAL: dying from an unhandled exception: IsConnOpen(conn)"

- moving back a little (11:49:30), I had a "reload" with a fatal error:

2017/10/24 11:49:30.406 kid1| Reconfiguring Squid Cache (version 3.5.27-20170916-re69e56c)...
2017/10/24 11:49:30.406 kid1| Closing HTTP port [::]:3128
2017/10/24 11:49:30.406 kid1| Closing HTTP port [::]:3129
2017/10/24 11:49:30.406 kid1| Closing HTTPS port [::]:3130
2017/10/24 11:49:30.406 kid1| Closing Pinger socket on FD 788
2017/10/24 11:49:30.406 kid1| Logfile: closing log daemon:/var/log/squid/access.log
2017/10/24 11:49:30.406 kid1| Logfile Daemon: closing log daemon:/var/log/squid/access.log
2017/10/24 11:49:30.406 kid1| FATAL: dying from an unhandled exception: IsConnOpen(conn)
2017/10/24 11:49:33 kid1| Set Current Directory to /var/cache/squid
2017/10/24 11:49:33 kid1| Starting Squid Cache version 3.5.27-20170916-re69e56c for x86_64-pc-linux-gnu...
2017/10/24 11:49:33 kid1| Service Name: squid
2017/10/24 11:49:33 kid1| Process ID 30753
2017/10/24 11:49:33 kid1| Process Roles: worker
2017/10/24 11:49:33 kid1| With 1024 file descriptors available

- searching within the older rotated cache.log files I noticed this:

2017/10/20 10:42:12 kid1| With 16384 file descriptors available
2017/10/21 05:50:32 kid1| With 1024 file descriptors available

The restart at 05:50:32 is performed by a cron job.

Conclusion: it seems that the cron daemon I use (https://github.com/cronie-crond/cronie) is not honoring system-wide ulimits defined in /etc/security/limits.d/* as, eg.:
* hard nofile 65535
* soft nofile 16384

Weird.

I'm not going to be using the cron job anymore.

Thanks,

Vieri