Re: epoll patch on squid2.5stable13 logging way too much debug

ok. thanks a lot for your reply Steven.
taking a quick look just now, I am seeing 91 of those messages from the last minute.

some more questions/info:

1. if it turns out that they are indeed harmless, (and not indicative of a big issue)...in the patch,
can I just change:

+ debug(20, 1) ("storeClientCopy3: %s - clearing ENTRY_DEFER_READ\n",e->mem_obj->url);

to read:

+ debug(20, 20) ("storeClientCopy3: %s - clearing ENTRY_DEFER_READ\n",e->mem_obj->url);

?? (I'm not a C guy, just a dirty hacker)

2. I'll give you some more info, so you have it:

these are decently loaded squids, reverse-proxying apache on 127.0.0.1:81.

they have 4GB of RAM, 6 x SCSI drives, each with a /cache on it. top shows:
  PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
19098 squid 16 0 1896m 1.4g 1568 S 33.2 35.8 597:41.62 squid

I'll include the /info:

HTTP/1.0 200 OK
Server: squid/2.5.STABLE13
Mime-Version: 1.0
Date: Wed, 05 Apr 2006 13:29:40 GMT
Content-Type: text/plain
Expires: Wed, 05 Apr 2006 13:29:40 GMT
Last-Modified: Wed, 05 Apr 2006 13:29:40 GMT
X-Cache: MISS from <hostname taken out>
Proxy-Connection: close

Squid Object Cache: Version 2.5.STABLE13
Start Time: Tue, 04 Apr 2006 09:18:41 GMT
Current Time: Wed, 05 Apr 2006 13:29:40 GMT
Connection information for squid:
        Number of clients accessing cache: 0
        Number of HTTP requests received: 44900433
        Number of ICP messages received: 0
        Number of ICP messages sent: 0
        Number of queued ICP replies: 0
        Request failure ratio: 0.00
        Average HTTP requests per minute since start: 26552.7
        Average ICP messages per minute since start: 0.0
        Select loop called: 389792848 times, 0.260 ms avg
Cache information for squid:
        Request Hit Ratios: 5min: 78.9%, 60min: 77.8%
        Byte Hit Ratios: 5min: 69.9%, 60min: 69.8%
        Request Memory Hit Ratios: 5min: 19.5%, 60min: 20.5%
        Request Disk Hit Ratios: 5min: 55.7%, 60min: 54.0%
        Storage Swap size: 52536736 KB
        Storage Mem size: 1152572 KB
        Mean Object Size: 24.66 KB
        Requests given to unlinkd: 0
Median Service Times (seconds) 5 min 60 min:
        HTTP Requests (All): 0.00463 0.00463
        Cache Misses: 0.07014 0.06640
        Cache Hits: 0.00463 0.00463
        Near Hits: 0.05951 0.06640
        Not-Modified Replies: 0.00000 0.00000
        DNS Lookups: 0.04433 0.04854
        ICP Queries: 0.00000 0.00000
Resource usage for squid:
        UP Time: 101459.557 seconds
        CPU Time: 41369.102 seconds
        CPU Usage: 40.77%
        CPU Usage, 5 minute avg: 44.74%
        CPU Usage, 60 minute avg: 41.32%
        Process Data Segment Size via sbrk(): 1482004 KB
        Maximum Resident Size: 0 KB
        Page faults with physical i/o: 10
Memory usage for squid via mallinfo():
        Total space in arena: 1482004 KB
        Ordinary blocks: 1471084 KB 61520 blks
        Small blocks: 0 KB 0 blks
        Holding blocks: 4200 KB 5 blks
        Free Small blocks: 0 KB
        Free Ordinary blocks: 10919 KB
        Total in use: 1475284 KB 99%
        Total free: 10919 KB 1%
        Total size: 1486204 KB
Memory accounted for:
        Total accounted: 1393970 KB
        memPoolAlloc calls: 962385083
        memPoolFree calls: 953751981
File descriptor usage for squid:
        Maximum number of file descriptors: 8192
        Largest file desc currently in use: 980
        Number of file desc currently in use: 905
        Files queued for open: 0
        Available number of file descriptors: 7287
        Reserved number of file descriptors: 100
        Store Disk files open: 340
Internal Data Structures:
        2130224 StoreEntries
         96500 StoreEntries with MemObjects
         96134 Hot Object Cache Items
        2130094 on-disk objects

box is doing around 490 req/sec, and is basically full.

any ideas ? health-wise, the machine looks fine. I'm seeing this logging on all 4 of the machines I installed
epoll onto, I patched the squid-2.5STABLE13 source.

thanks a lot,
john

----- Original Message ----
From: Steven Wilton <swilton@q-net.net.au>
To: john allspaw <jallspaw@yahoo.com>
Cc: Squid Developers <squid-dev@squid-cache.org>
Sent: Wednesday, April 5, 2006 12:29:26 AM
Subject: RE: epoll patch on squid2.5stable13 logging way too much debug

These messages are harmless, and the debug code can safely be raised to a
higher number (to stop them being output). The reason that I have left them
in at debug level 1 is because they indicate that squid has somehow sent all
the data it has in memory to all clients, but it has marked the reading
filedescriptor (ie the socket to the web server, or the on-disk object) as
deferred. If left unchecked, this would cause squid to never send any more
data to this client.

In theory this should never happen, as squid will normally mark a reading
filedescriptor as deferred when the object is using too much memory, and
will resume reading from the filedescriptor when data is sent to the client
(and the memory is freed). If a transfer is causing these debug messages,
it means that something unusual has happened in another part of the squid
code.

I personally see about 150 of these messages a day in our cache logs (out of
12 million requests). I don't know if there are any normal conditions that
would cause squid to behave this way, so I have left this code at debug
level 1. If there is a definite way to hit this error, it can be replicated
and debugged further.

Steven

> -----Original Message-----
> From: john allspaw [mailto:jallspaw@yahoo.com]
> Sent: Saturday, 1 April 2006 6:10 AM
> To: squid-dev@squid-cache.org
> Subject: epoll patch on squid2.5stable13 logging way too much debug
>
> ...or, if it's not debug info, then how would it be useful:
>
> I'm getting boatloads (as many as 4 every second) in my
> cache.out file:
>
> 2006/03/31 03:05:37| storeClientCopy3: http://(URL) -
> clearing ENTRY_DEFER_READ
>
> the patch I applied was taken from:
> http://devel.squid-cache.org/cgi-bin/diff2/epoll-2_5.patch?s2_5
>
> and it says:
> This patch is generated from the epoll-2_5 branch of s2_5 in squid
> Tue Jan 10 22:35:19 2006 GMTI saw someone mention this on the
> mailing-list sometime last year, but no real resolution came from it.
> thoughts ?
>
> thanks,
> John
>
>
>
> --
> No virus found in this incoming message.
> Checked by AVG Free Edition.
> Version: 7.1.385 / Virus Database: 268.3.5/301 - Release
> Date: 4/04/2006
>
>

-- 
No virus found in this outgoing message.
Checked by AVG Free Edition.
Version: 7.1.385 / Virus Database: 268.3.5/301 - Release Date: 4/04/2006