RE: [squid-users] Problem with Restarted Squid Stable 2.6_19 Addl Info

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.
Received on Tue Apr 22 2008 - 13:18:00 MDT