[squid-users] Squid using 80-90% CPU usage, but only when MSN login fails

Hello!

First post to this list, hope somebody can help me with this rather
strange problem...

First, this problem seems to be related to Microsofts service MSN
Messenger. Earlier this evening I noticed that the CPU usage on the
computer that runs squid (a P2 400Mhz with 256Mb RAM) was unusually high,
and looking more closly I saw my squid process using ~85-90% CPU
(according to top).

According to this graph: http://stats.stromnet.org/cacti/graph_182.html,
this high cpu usage started around 18.00. Thats about the same time as I
lost my MSN connectivity (no, the problem was not mine, since aloooot of
other people had the same problem, reported over IRC).

So, I started to investigate this rather strange CPU usage by turning
debugging on in Squid... After watching the log for some minutes, this
kind of entrys appeared:

2005/02/08 22:58:40| comm_poll: 1+0 FDs ready
2005/02/08 22:58:40| comm_poll: FD 12 ready for reading
2005/02/08 22:58:40| clientReadRequest: FD 12: reading request...
2005/02/08 22:58:40| commSetSelect: FD 12 type 1
2005/02/08 22:58:40| clientReadRequest: FD 12 closed?

These messages were repeated thousands of times per second (doing a grep
for the first line there, including the timestamp, gave me 3003
rows...).

What I also noticed was that those FDs that were reported in those
messages, seemed to be FDs associated with the MSN servers (MSN tried to
connect to
http://gateway.messenger.hotmail.com/gateway/gateway.dll?Action=open&Server=NS&IP=messenger.hotmail.com).

After some more investigation, I just got another confirmation that this
is related to MSN...
I noticed that the CPU usage was normal, and checked out MSN. It seems
it wasn't trying to connect any more. So, I turned on logging, and
pressed the "Sign In" button in MSN... CPU usage was still normal.. But
the second that MSN gave up logging in (telling me it had failed), the
CPU usage went up to 80-90%, and those messages started to appear in the
log. After a couple of minutes, it stopped and the CPU usage went down
again.

To verify it again, I did the same thing.. Stopped squid, started squid,
enabled debugging, tried to signin in MSN. As soon as the sing in timed
out, I got the same result, same messages, and same CPU usage...

Then I tried the same thing, but instead of waiting for MSN to time out,
I pressed Abort Sign in.
The same results where noticed...

So, does anyone have any ideas what this could be??

I've put up the log for anyone to watch at
http://www.stromnet.org/~johan/squid_cache.log.gz
Note that it's only 700kb, but the unpacked file is ~120Mb/3 069 363
lines.. So don't open it in your web-browser, Firefox didn't realy like
it anyways, hehe.

Here are some timestamps that I noted (not very exact though...):

~22:58:10, Sing in button pressed
~22:58:40, Abort Sing in pressed, Squid CPU usage went from ~0 to 80
instantly.
~23:01:15, Squid returned to normal CPU usage.

I did some googling, but didn't find anything (Except for someone
talking about high CPU usage when /dev/null wasn't present/writeable,
but it is there and has 666 as permission so that aint the problem)

Oh, and some information about the squid setup I'm running to:

squid-2.5-STABLE7 (Ran stable5 before, same problem, so I tried to
upgrade to latest version, but no change...) running in transparent mode
on linux-2.4.27.
Manually compiled with the following options:

--enable-useragent-log --enable-referer-log --enable-snmp
--enable-linux-netfilter --disable-ident-lookups --enable-delay-pools
 --enable-storeio=ufs,null
 
The configuration file I'm using can be found at
http://www.stromnet.org/~johan/squid.conf

Nothing fancy there.. Tried disabling all ACL's, didn't help so that
ain't the problem..

Well, lets hope someone can shed some light over this rather strange
problem... :)

Sincerly
Johan Ström
johan@stromnet.org
Received on Tue Feb 08 2005 - 15:40:54 MST