>> 2009/01/16 09:30:24| Starting Squid Cache version 2.6.STABLE6 for x86_64-redhat-linux-gnu...
>> 2009/01/16 09:30:24| Process ID 2625
>> 2009/01/16 09:30:24| With 1024 file descriptors available
>> 2009/01/16 09:30:24| Using epoll for the IO loop
>> 2009/01/16 09:30:24| DNS Socket created at 0.0.0.0, port 60302, FD 5
>> 2009/01/16 09:30:24| Adding domain mydomain.com from /etc/resolv.conf
>> 2009/01/16 09:30:24| Adding nameserver 22.179.1.11 from /etc/resolv.conf
>> 2009/01/16 09:30:24| Adding nameserver 22.179.1.15 from /etc/resolv.conf
>> 2009/01/16 09:30:24| User-Agent logging is disabled.
>> 2009/01/16 09:30:24| Referer logging is disabled.
>> 2009/01/16 09:30:24| Unlinkd pipe opened on FD 10
>> 2009/01/16 09:30:24| Swap maxSize 16777216 KB, estimated 1290555 objects
>> 2009/01/16 09:30:24| Target number of buckets: 64527
>> 2009/01/16 09:30:24| Using 65536 Store buckets
>> 2009/01/16 09:30:24| Max Mem size: 393216 KB
>> 2009/01/16 09:30:24| Max Swap size: 16777216 KB
>> 2009/01/16 09:30:24| Local cache digest enabled; rebuild/rewrite every 3600/3600 sec
>> 2009/01/16 09:30:24| Store logging disabled
>> 2009/01/16 09:30:24| Rebuilding storage in /var/spool/squid (CLEAN)
>> 2009/01/16 09:30:24| Using Least Load store dir selection
>> 2009/01/16 09:30:24| Set Current Directory to /var/spool/squid
>> 2009/01/16 09:30:24| Loaded Icons.
>> 2009/01/16 09:30:26| Accepting proxy HTTP connections at 0.0.0.0, port 8080, FD 11.
>> 2009/01/16 09:30:26| Accepting ICP messages at 0.0.0.0, port 3130, FD 12.
>> 2009/01/16 09:30:26| WCCP Disabled.
>> 2009/01/16 09:30:26| Ready to serve requests.
>> 2009/01/16 09:30:35| Store rebuilding is 0.4% complete
>> 2009/01/16 09:30:53| Store rebuilding is 1.1% complete
>> 2009/01/16 09:31:08| Store rebuilding is 1.5% complete
>> 2009/01/16 09:31:24| Store rebuilding is 2.3% complete
>> 2009/01/16 09:31:44| Store rebuilding is 3.1% complete
>> 2009/01/16 09:32:01| Store rebuilding is 3.4% complete
>> ...
>> 2009/01/16 10:32:41| Store rebuilding is 98.1% complete
>> 2009/01/16 10:33:06| Store rebuilding is 98.5% complete
>> 2009/01/16 10:33:26| Store rebuilding is 98.9% complete
>> 2009/01/16 10:33:53| Store rebuilding is 99.6% complete
>> 2009/01/16 10:34:13| Done reading /var/spool/squid swaplog (1072895 entries)
>> 2009/01/16 10:34:13| Finished rebuilding storage from disk.
>> 2009/01/16 10:34:13| 1072895 Entries scanned
>> 2009/01/16 10:34:13| 0 Invalid entries.
>> 2009/01/16 10:34:13| 0 With invalid flags.
>> 2009/01/16 10:34:13| 1044791 Objects loaded.
>> 2009/01/16 10:34:13| 0 Objects expired.
>> 2009/01/16 10:34:13| 0 Objects cancelled.
>> 2009/01/16 10:34:13| 7253 Duplicate URLs purged.
>> 2009/01/16 10:34:13| 20851 Swapfile clashes avoided.
>> 2009/01/16 10:34:13| Took 3829.6 seconds ( 272.8 objects/sec).
>>
> Yikes. That's slow...
>> 2009/01/16 10:34:13| Beginning Validation Procedure
>> 2009/01/16 10:35:04| 262144 Entries Validated so far.
>> 2009/01/16 10:35:17| 524288 Entries Validated so far.
>> 2009/01/16 10:35:25| 786432 Entries Validated so far.
>> 2009/01/16 10:35:43| Completed Validation Procedure
>> 2009/01/16 10:35:43| Validated 1044747 Entries
>> 2009/01/16 10:35:43| store_swap_size = 15131260k
>> 2009/01/16 10:37:58| storeLateRelease: released 4184 objects
>>
>> I never stop squid abnormally and I never restart server abnormally.
>> So I don't understand why does squid do it. It takes a lot of CPU
>> resources and about an hour of time.
> What kind of CPU resources? Userspace, system, or wait?
Squid cache resides on NFS partition on storage system. It is 1Gb link
and both sides are connected to the same switch. Squid has dual core
Xeon processor and 4GB of RAM.
The main concern here is that squid always eats 100% of 1 core. And
our clients can't reach full channel throughput (4Gbs). As I can see
outside link is half full. Secondly it looks like FS performance is
very poor. I tried to clear cache by setting
cache_swap_low 0
cache_swap_high 0
and it took about 15 hours for squid to actually clear the cache!
Why does squid eat 100% of processor if the problem is in FS? Maybe
it's not an FS problem at all? What can I do to find the performance
bottleneck?
Here is the squid stats before clearing the cache:
Squid Object Cache: Version 2.6.STABLE6
Start Time: Fri, 16 Jan 2009 05:16:44 GMT
Current Time: Tue, 20 Jan 2009 02:40:59 GMT
Connection information for squid:
Number of clients accessing cache: 216
Number of HTTP requests received: 2423885
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: 432.5
Average ICP messages per minute since start: 0.0
Select loop called: 19962772 times, 16.844 ms avg
Cache information for squid:
Request Hit Ratios: 5min: 44.4%, 60min: 44.4%
Byte Hit Ratios: 5min: 20.8%, 60min: 20.1%
Request Memory Hit Ratios: 5min: 45.1%, 60min: 32.8%
Request Disk Hit Ratios: 5min: 14.2%, 60min: 17.2%
Storage Swap size: 14671820 KB
Storage Mem size: 393152 KB
Mean Object Size: 14.03 KB
Requests given to unlinkd: 365915
Median Service Times (seconds) 5 min 60 min:
HTTP Requests (All): 0.52331 0.19742
Cache Misses: 0.89858 0.35832
Cache Hits: 0.15888 0.05633
Near Hits: 0.80651 0.33943
Not-Modified Replies: 0.16775 0.05633
DNS Lookups: 0.17826 0.10428
ICP Queries: 0.00000 0.00000
Resource usage for squid:
UP Time: 336255.433 seconds
CPU Time: 109467.061 seconds
CPU Usage: 32.55%
CPU Usage, 5 minute avg: 89.01%
CPU Usage, 60 minute avg: 56.24%
Process Data Segment Size via sbrk(): 735376 KB
Maximum Resident Size: 0 KB
Page faults with physical i/o: 0
Memory usage for squid via mallinfo():
Total space in arena: 735508 KB
Ordinary blocks: 727648 KB 32546 blks
Small blocks: 0 KB 0 blks
Holding blocks: 12900 KB 5 blks
Free Small blocks: 0 KB
Free Ordinary blocks: 7859 KB
Total in use: 740548 KB 99%
Total free: 7859 KB 1%
Total size: 748408 KB
Memory accounted for:
Total accounted: 608297 KB
memPoolAlloc calls: 290964864
memPoolFree calls: 287132098
File descriptor usage for squid:
Maximum number of file descriptors: 1024
Largest file desc currently in use: 546
Number of file desc currently in use: 540
Files queued for open: 0
Available number of file descriptors: 484
Reserved number of file descriptors: 100
Store Disk files open: 10
IO loop method: epoll
Internal Data Structures:
1050616 StoreEntries
79482 StoreEntries with MemObjects
79432 Hot Object Cache Items
1045934 on-disk objects
Regards,
Nikita.
