On 21-Apr-08 My Secret NSA Wiretap Overheard Nicole Saying : > > > I have several FreeBSD servers with 3 disks just for cache spools running > Stable_2.6.19 in accelerator mode. > > Every so often, I have had a server lock up on me. Usually, before I > upgraded > them to ver 19, I would just reboot them and they would recover and start > working again. Now however, apon reboot, all the cache spools show lots of > disk > activity at the same time, even when there is little to no traffic being sent > to the unit and requesting a file via the squid server is painfully slow. > > As you can see the cpu usage is very high. It takes almost 5 seconds for the > report to even show up. This is after the disks swap.state files are checked > one > by one. > > The only solution I have been able to find so far is to destroy all the > data > and have it rebuild it all. > > Any auggestions woudl be greatly appreciatted. > > Thanks > > Nicole > > > Squid Object Cache: Version 2.6.STABLE19 > Start Time: Mon, 21 Apr 2008 00:12:20 GMT > Current Time: Mon, 21 Apr 2008 00:14:27 GMT > Connection information for squid: > Number of clients accessing cache: 3 > Number of HTTP requests received: 4 > Number of ICP messages received: 150 > Number of ICP messages sent: 150 > Number of queued ICP replies: 0 > Request failure ratio: 0.00 > Average HTTP requests per minute since start: 1.9 > Average ICP messages per minute since start: 141.6 > Select loop called: 67 times, 1896.758 ms avg > Cache information for squid: > Request Hit Ratios: 5min: 0.0%, 60min: 0.0% > Byte Hit Ratios: 5min: -0.0%, 60min: -0.0% > Request Memory Hit Ratios: 5min: 0.0%, 60min: 0.0% > Request Disk Hit Ratios: 5min: 0.0%, 60min: 0.0% > Storage Swap size: 162934 KB > Storage Mem size: 104 KB > Mean Object Size: 16.22 KB > Requests given to unlinkd: 0 > Median Service Times (seconds) 5 min 60 min: > HTTP Requests (All): 0.00000 0.00000 > Cache Misses: 0.00000 0.00000 > Cache Hits: 0.00000 0.00000 > Near Hits: 0.00000 0.00000 > Not-Modified Replies: 0.00000 0.00000 > DNS Lookups: 0.00000 0.00000 > ICP Queries: 0.00000 0.00000 > Resource usage for squid: > UP Time: 127.083 seconds > CPU Time: 58.899 seconds > CPU Usage: 46.35% > CPU Usage, 5 minute avg: 86.28% > CPU Usage, 60 minute avg: 86.28% > Process Data Segment Size via sbrk(): 1003544 KB > Maximum Resident Size: 1010936 KB > Page faults with physical i/o: 0 > Memory accounted for: > Total accounted: 705341 KB > memPoolAlloc calls: 28539766 > memPoolFree calls: 11615581 > File descriptor usage for squid: > Maximum number of file descriptors: 32768 > Largest file desc currently in use: 22 > Number of file desc currently in use: 16 > Files queued for open: 0 > Available number of file descriptors: 32752 > Reserved number of file descriptors: 100 > Store Disk files open: 0 > IO loop method: kqueue > Internal Data Structures: > 5641174 StoreEntries > 26 StoreEntries with MemObjects > 25 Hot Object Cache Items > 10043 on-disk objects > > > 1 users Load 0.11 0.11 0.05 Apr 20 17:17 > > Mem:KB REAL VIRTUAL VN PAGER SWAP PAGER > Tot Share Tot Share Free in out in out > Act 1024352 7564 1049192 10376 865900 count > All 3055196 7916502365388 10992 pages > Interrupts > Proc:r p d s w Csw Trp Sys Int Sof Flt cow 4127 total > 2 63 1777 119 476 285 116 208660 wire 1: atkb > 1017156 act 118 17: ata > 0.9%Sys 0.2%Intr 0.0%User 0.0%Nice 98.9%Idl 1833440 inact 7 24: bge >| | | | | | | | | | cache 4 25: bge > + 865900 free 1999 cpu0: > time > daefr 1999 cpu1: > time > Namei Name-cache Dir-cache prcfr > Calls hits % hits % react > 1300 931 72 120 9 pdwake > zfod pdpgs > Disks ad4 ad6 ad8 ad10 ozfod intrn > KB/t 0.00 6.00 6.00 6.00 %slo-z 219632 buf > tps 0 36 39 43 238 tfree 6 dirtybuf > MB/s 0.00 0.21 0.23 0.25 100000 desiredvnodes > % busy 0 29 32 38 42849 numvnodes > 25006 freevnodes > > I hate replying to my own post, but some further info on this in that quite a bit of time that the cache.log is reporting that it is validating entries and taking quite a bit of time. Why is it going through this validation procedure and it seems to be taking a great deal of time. Also usually, when this is done, it does it one disk at a time, not all disks at once I thought. Again, any idea's on why this could be happening would be greatly apreciatted. Thanks Nicole 2008/04/20 17:12:20| Starting Squid Cache version 2.6.STABLE19 for amd64-unknown-freebsd6.2... 2008/04/20 17:12:20| Process ID 1854 2008/04/20 17:12:20| With 32768 file descriptors available 2008/04/20 17:12:20| Using kqueue for the IO loop 2008/04/20 17:12:20| Performing DNS Tests... 2008/04/20 17:12:20| Successful DNS name lookup tests... 2008/04/20 17:12:20| DNS Socket created at 0.0.0.0, port 31060, FD 6 2008/04/20 17:12:20| Adding nameserver from squid.conf 2008/04/20 17:12:20| Adding nameserver from squid.conf 2008/04/20 17:12:20| Referer logging is disabled. 2008/04/20 17:12:20| Unlinkd pipe opened on FD 11 2008/04/20 17:12:20| Swap maxSize 239616000 KB, estimated 18432000 objects 2008/04/20 17:12:20| Target number of buckets: 921600 2008/04/20 17:12:20| Using 1048576 Store buckets 2008/04/20 17:12:20| Max Mem size: 512000 KB 2008/04/20 17:12:20| Max Swap size: 239616000 KB 2008/04/20 17:12:20| Store logging disabled 2008/04/20 17:12:20| Rebuilding storage in /cache1 (DIRTY) 2008/04/20 17:12:20| Rebuilding storage in /cache2 (DIRTY) 2008/04/20 17:12:20| Rebuilding storage in /cache3 (DIRTY) 2008/04/20 17:12:20| Using Least Load store dir selection 2008/04/20 17:12:20| Loaded Icons. 2008/04/20 17:12:21| Accepting accelerated HTTP connections at 0.0.0.0, port 80, FD 20. 2008/04/20 17:12:21| Accepting ICP messages at 0.0.0.0, port 3130, FD 21. 2008/04/20 17:12:21| Accepting SNMP messages on port 3401, FD 22. 2008/04/20 17:12:21| WCCP Disabled. 2008/04/20 17:12:21| Ready to serve requests. 2008/04/20 17:12:21| Configuring Parent 1.domain.com/80/3130 2008/04/20 17:12:21| Configuring Parent 2.domain.com/80/3130 2008/04/20 17:12:21| Done reading /cache1 swaplog (1916360 entries) 2008/04/20 17:12:39| Store rebuilding is 50.1% complete 2008/04/20 17:12:39| Done reading /cache2 swaplog (1907802 entries) 2008/04/20 17:12:59| Store rebuilding is 66.7% complete 2008/04/20 17:12:59| Done reading /cache3 swaplog (1900088 entries) 2008/04/20 17:12:59| Finished rebuilding storage from disk. 2008/04/20 17:12:59| 5682699 Entries scanned 2008/04/20 17:12:59| 0 Invalid entries. 2008/04/20 17:12:59| 0 With invalid flags. 2008/04/20 17:12:59| 5682699 Objects loaded. 2008/04/20 17:12:59| 0 Objects expired. 2008/04/20 17:12:59| 41551 Objects cancelled. 2008/04/20 17:12:59| 0 Duplicate URLs purged. 2008/04/20 17:12:59| 0 Swapfile clashes avoided. 2008/04/20 17:12:59| Took 38.3 seconds (148197.2 objects/sec). 2008/04/20 17:12:59| Beginning Validation Procedure 2008/04/20 17:39:25| 262144 Entries Validated so far. 2008/04/20 18:05:22| 524288 Entries Validated so far. 2008/04/20 18:31:16| 786432 Entries Validated so far. 2008/04/20 18:57:09| 1048576 Entries Validated so far. 2008/04/20 19:23:05| 1310720 Entries Validated so far. 2008/04/20 19:49:01| 1572864 Entries Validated so far. 2008/04/20 20:14:56| 1835008 Entries Validated so far. 2008/04/20 20:40:49| 2097152 Entries Validated so far. 2008/04/20 21:06:47| 2359296 Entries Validated so far. 2008/04/20 21:32:40| 2621440 Entries Validated so far. 2008/04/20 21:58:38| 2883584 Entries Validated so far.
