Re: [squid-users] High CPU

From: <[email protected]>
Date: Fri, 28 Dec 2001 10:15:08 +1100

Here's the result from cachemanager:

File descriptor usage for squid:
           Maximum number of file descriptors: 4096
           Largest file desc currently in use: 137
           Number of file desc currently in use: 99
           Files queued for open: 0
           Available number of file descriptors: 3997
           Reserved number of file descriptors: 100
           Store Disk files open: 0
I don't really see any problems there.

Here is the setting for debug in squid.conf
debug_options ALL,1

Here's some very average output from Squid, which tells me that its okay,
although, you can correct me there:

2001/12/28 09:26:17| comm_poll: 0 FDs ready
2001/12/28 09:26:17| comm_poll: time out: 1009491977.
2001/12/28 09:26:17| eventRun: RUN ID 2133981210
2001/12/28 09:26:17| eventRun: Running 'MaintainSwapSpace', id 2133981209
2001/12/28 09:26:17| eventAdd: Adding 'MaintainSwapSpace', in 0.000000
seconds
2001/12/28 09:26:17| storeMaintainSwapSpace: f=1.000000, max_scan=500,
max_remove
=80
2001/12/28 09:26:17| storeMaintainSwapSpace stats:
2001/12/28 09:26:17| 30 objects
2001/12/28 09:26:17| 30 were scanned
2001/12/28 09:26:17| 18 were locked
2001/12/28 09:26:17| 0 were expired
2001/12/28 09:26:17| comm_poll: 0 FDs ready
2001/12/28 09:26:17| comm_poll: time out: 1009491977.
2001/12/28 09:26:17| eventRun: RUN ID 2133981211
2001/12/28 09:26:17| eventRun: Running 'MaintainSwapSpace', id 2133981210
2001/12/28 09:26:17| eventAdd: Adding 'MaintainSwapSpace', in 0.000000
seconds
2001/12/28 09:26:17| storeMaintainSwapSpace: f=1.000000, max_scan=500,
max_remove
=80

<BREAK and look for something interesting>

2001/12/28 09:26:17| storeMaintainSwapSpace stats:
2001/12/28 09:26:17| 30 objects
2001/12/28 09:26:17| 30 were scanned
2001/12/28 09:26:17| 18 were locked
2001/12/28 09:26:17| 0 were expired
2001/12/28 09:26:17| comm_poll: 1 FDs ready
2001/12/28 09:26:17| comm_poll: FD 87 ready for reading
2001/12/28 09:26:17| httpReadReply: FD 87: len 1380.
2001/12/28 09:26:17| commSetTimeout: FD 87 timeout 420
2001/12/28 09:26:17| httpProcessReplyHeader: key
'76431C47CBAFD02B95DE09A4CBC5D6D
7'
2001/12/28 09:26:17| ctx: enter level 0:
'http://bikepoint.ninemsn.com.au/conten
t/products/silrapt.jpg'
2001/12/28 09:26:17| GOT HTTP REPLY HDR:
---------
HTTP/1.0 200 OK^M
Server: Microsoft-IIS/5.0^M
P3P: CP="BUS CUR CONi FIN IVDi ONL OUR PHY SAMo"^M
Date: Thu, 27 Dec 2001 22:56:59 GMT^M
Content-Type: image/jpeg^M
Accept-Ranges: bytes^M
Last-Modified: Tue, 21 Aug 2001 03:46:11 GMT^M
ETag: "e0aa90d1f329c11:8c2"^M
Content-Length: 24969^M
Age: 0^M
X-Cache: MISS from ext-cache^M
Proxy-Connection: close^M
^M

----------
2001/12/28 09:26:17| cleaning hdr: 9f65e8 owner: 2
2001/12/28 09:26:17| init-ing hdr: 9f65e8 owner: 2
2001/12/28 09:26:17| 9f65e8 lookup for 35
2001/12/28 09:26:17| 9f65e8 lookup for 9
2001/12/28 09:26:17| 9f65e8 lookup for 20
2001/12/28 09:26:17| parsing hdr: (9f65e8)
Server: Microsoft-IIS/5.0^M
P3P: CP="BUS CUR CONi FIN IVDi ONL OUR PHY SAMo"^M
Date: Thu, 27 Dec 2001 22:56:59 GMT^M
Content-Type: image/jpeg^M
Accept-Ranges: bytes^M
Last-Modified: Tue, 21 Aug 2001 03:46:11 GMT^M
ETag: "e0aa90d1f329c11:8c2"^M
Content-Length: 24969^M
Age: 0^M
X-Cache: MISS from ext-cache^M
Proxy-Connection: close^M

2001/12/28 09:26:17| creating entry 843470: near 'Server:
Microsoft-IIS/5.0'
2001/12/28 09:26:17| created entry 843470: 'Server: Microsoft-IIS/5.0'
2001/12/28 09:26:17| 9f65e8 adding entry: 41 at 0
2001/12/28 09:26:17| creating entry 9d1778: near 'P3P: CP="BUS CUR CONi FIN
IVDi
ONL OUR PHY SAMo"'
2001/12/28 09:26:17| created entry 9d1778: 'P3P: CP="BUS CUR CONi FIN IVDi
ONL OU
R PHY SAMo"'
2001/12/28 09:26:17| 9f65e8 adding entry: 55 at 1
2001/12/28 09:26:17| creating entry 8a2bf8: near 'Date: Thu, 27 Dec 2001
22:56:59
 GMT'
2001/12/28 09:26:17| created entry 8a2bf8: 'Date: Thu, 27 Dec 2001 22:56:59
GMT'
2001/12/28 09:26:17| 9f65e8 adding entry: 18 at 2
2001/12/28 09:26:17| creating entry 55ef70: near 'Content-Type: image/jpeg'
2001/12/28 09:26:17| created entry 55ef70: 'Content-Type: image/jpeg'
2001/12/28 09:26:17| 9f65e8 adding entry: 17 at 3
2001/12/28 09:26:17| creating entry 55f0d0: near 'Accept-Ranges: bytes'
2001/12/28 09:26:17| created entry 55f0d0: 'Accept-Ranges: bytes'
2001/12/28 09:26:17| 9f65e8 adding entry: 4 at 4
2001/12/28 09:26:17| creating entry 91dec0: near 'Last-Modified: Tue, 21
Aug 2001
 03:46:11 GMT'
2001/12/28 09:26:17| created entry 91dec0: 'Last-Modified: Tue, 21 Aug 2001
03:46
:11 GMT'
2001/12/28 09:26:17| 9f65e8 adding entry: 27 at 5
2001/12/28 09:26:17| creating entry 55f270: near 'ETag:
"e0aa90d1f329c11:8c2"'
2001/12/28 09:26:17| created entry 55f270: 'ETag: "e0aa90d1f329c11:8c2"'
2001/12/28 09:26:17| 9f65e8 adding entry: 19 at 6
2001/12/28 09:26:17| creating entry 9b07c8: near 'Content-Length: 24969'
2001/12/28 09:26:17| created entry 9b07c8: 'Content-Length: 24969'
2001/12/28 09:26:17| 9f65e8 adding entry: 13 at 7
2001/12/28 09:26:17| creating entry 9f70a0: near 'Age: 0'
2001/12/28 09:26:17| created entry 9f70a0: 'Age: 0'
2001/12/28 09:26:17| 9f65e8 adding entry: 5 at 8
2001/12/28 09:26:17| creating entry 91de80: near 'X-Cache: MISS from
ext-cache'
2001/12/28 09:26:17| created entry 91de80: 'X-Cache: MISS from ext-cache'
2001/12/28 09:26:17| 9f65e8 adding entry: 50 at 9
2001/12/28 09:26:17| creating entry 91db60: near 'Proxy-Connection: close'
2001/12/28 09:26:17| created entry 91db60: 'Proxy-Connection: close'
2001/12/28 09:26:17| 9f65e8 adding entry: 35 at 10
2001/12/28 09:26:17| 9f65e8 lookup for 35
2001/12/28 09:26:17| 9f65e8 lookup for 20
2001/12/28 09:26:17| httpProcessReplyHeader: HTTP CODE: 200
2001/12/28 09:26:17| storeGet: looking up 7F65154B1B544592B9047A6F53FBFF28
2001/12/28 09:26:17| storeGet: looking up 077757AD383D5CD8BFE7E5F65A1EF16F
2001/12/28 09:26:17| 9f65e8 lookup for 46
2001/12/28 09:26:17| 9f65e8 lookup for 32
2001/12/28 09:26:17| refreshCheck(On Store):
'http://bikepoint.ninemsn.com.au/con
tent/products/silrapt.jpg'
2001/12/28 09:26:17| refreshCheck: Matched '. 0 20% 259200'
2001/12/28 09:26:17| refreshCheck: age = -1782
2001/12/28 09:26:17| check_time: Thu, 27 Dec 2001 22:27:17 GMT
2001/12/28 09:26:17| entry->timestamp: Thu, 27 Dec 2001 22:56:59
GMT
2001/12/28 09:26:17| refreshCheck: factor = -0.000160
2001/12/28 09:26:17| refreshCheck: NO: factor < pct
2001/12/28 09:26:17| storeHashInsert: Inserting Entry 7e8100 key
'7F65154B1B54459
2B9047A6F53FBFF28'
2001/12/28 09:26:17| ctx: exit level 0
2001/12/28 09:26:17| storeAppend: appending 1380 bytes for
'7F65154B1B544592B9047
A6F53FBFF28'
2001/12/28 09:26:17| memAppend: len 1380
2001/12/28 09:26:17| InvokeHandlers: 7F65154B1B544592B9047A6F53FBFF28
2001/12/28 09:26:17| InvokeHandlers: checking client #0
2001/12/28 09:26:17| cbdataLock: aaa3a0
2001/12/28 09:26:17| storeClientCopy2: 7F65154B1B544592B9047A6F53FBFF28
2001/12/28 09:26:17| storeClientCopy2: Copying from memory
2001/12/28 09:26:17| memCopy: offset 0: size 4096
2001/12/28 09:26:17| clientSendMoreData:
http://bikepoint.ninemsn.com.au/content/
products/silrapt.jpg, 1380 bytes
2001/12/28 09:26:17| clientSendMoreData: FD 86
'http://bikepoint.ninemsn.com.au/c
ontent/products/silrapt.jpg', out.offset=0
2001/12/28 09:26:17| creating rep: a89f00
2001/12/28 09:26:17| init-ing hdr: a89f38 owner: 2
2001/12/28 09:26:17| a89f38 lookup for 35
2001/12/28 09:26:17| a89f38 lookup for 9
2001/12/28 09:26:17| a89f38 lookup for 20
2001/12/28 09:26:17| cleaning hdr: a89f38 owner: 2
2001/12/28 09:26:17| init-ing hdr: a89f38 owner: 2
2001/12/28 09:26:17| a89f38 lookup for 35

Correct me if I'm wrong, but I can't see anything wrong there either.

Sorry for my ignorance, but how do you dump the poll table using 'truss'?
I've tried a few options, but I don't really know what I'm looking for.
Also, I'm using the following process ID:

ps -ef |grep squid
nobody 13818 13815 97 15:19:42 pts/0 1100:40 squid -NsY

Is this the correct ID to use?

Thanks for you help so far.

                                                                                           
                    Henrik
                    Nordstrom To: philip.wolfe@centrelink.gov.au,
                    <hno@marasyst squid-users@squid-cache.org
                    ems.com> cc:
                                         Subject: Re: [squid-users] High CPU
                    27/12/2001
                    22:11
                                                                                           
                                                                                           

On Thursday 27 December 2001 04.55, philip.wolfe@centrelink.gov.au wrote:

> Still looking into the high CPU for squid. Now averages 88-91% of CPU.
>
> Performed a truss -p <process-id>
>
> poll(0xEFFF7C54, 147, 0) = 0
> poll(0xEFFF7C54, 147, 0) = 0
> poll(0xEFFF7C54, 147, 0) = 0
> poll(0xEFFF7C54, 147, 0) = 0

Looks like Squid has forgotten what to do with one of the active
filedescriptors..

Do you get anything in cache.log?

> I have set Squid to debug, but that doesn't really show anything up.

If you turn on debugging then lots of stuff should show up in cache.log.
Question is what to look for...

A better start is to use cachemgr I think. See the list of active
filedescriptors.

It could also be helpful to ask truss to dump the poll table to see which
filedescriptor that has got stuck..

lsof could also provide helpful information.

Regards
Henrik Nordstr�m
Squid Developer 

--
MARA Systems AB, Giving you basic free Squid support
Customized solutions, packaged solutions and priority support
available on request
Received on Thu Dec 27 2001 - 16:16:24 MST

This archive was generated by hypermail pre-2.1.9 : Tue Dec 09 2003 - 17:05:30 MST