[squid-users] 10 seconds delay squdclient delay

Javier Barroso javibarroso at gmail.com
Fri Dec 9 11:55:53 UTC 2016


Hello,

We are having trouble with cachemgr performance. Do you know why
squidclient could delay 10 seconds on mgr:xxx queries ?

I have looked about any timeout, or network error, or something, but I
did not find nothing

See info and storedir outputs :

11:16:24 O: HTTP/1.1 200 OK
11:16:24 O: Server: squid/3.5.1
11:16:24 O: Mime-Version: 1.0
11:16:24 O: Date: Fri, 09 Dec 2016 10:16:24 GMT
11:16:24 O: Content-Type: text/plain
11:16:24 O: Expires: Fri, 09 Dec 2016 10:16:24 GMT
11:16:24 O: Last-Modified: Fri, 09 Dec 2016 10:16:24 GMT
11:16:24 O: Connection: close
11:16:24 O: < ===================== STALE 10 seconds ====
11:16:34 O: Squid Object Cache: Version 3.5.1
11:16:34 E: Shared connection to proxyweb02 closed.
11:16:34 O: Build Info:
11:16:34 O: Service Name: squid
11:16:34 O: Start Time:    Fri, 09 Dec 2016 08:30:20 GMT
11:16:34 O: Current Time:    Fri, 09 Dec 2016 10:16:24 GMT
11:16:34 O: Connection information for squid:
11:16:34 O:     Number of clients accessing cache:    1630
11:16:34 O:     Number of HTTP requests received:    541924
11:16:34 O:     Number of ICP messages received:    0
11:16:34 O:     Number of ICP messages sent:    0
11:16:34 O:     Number of queued ICP replies:    0
11:16:34 O:     Number of HTCP messages received:    0
11:16:34 O:     Number of HTCP messages sent:    0
11:16:34 O:     Request failure ratio:     0.00
11:16:34 O:     Average HTTP requests per minute since start:    5109.1
11:16:34 O:     Average ICP messages per minute since start:    0.0
11:16:34 O:     Select loop called: 13075819 times, 1.967 ms avg
11:16:34 O: Cache information for squid:
11:16:34 O:     Hits as % of all requests:    5min: 7.7%, 60min: 6.6%
11:16:34 O:     Hits as % of bytes sent:    5min: 6.7%, 60min: 9.2%
11:16:34 O:     Memory hits as % of hit requests:    5min: 0.0%, 60min: 0.0%
11:16:34 O:     Disk hits as % of hit requests:    5min: 73.9%, 60min: 74.1%
11:16:34 O:     Storage Swap size:    11325052 KB
11:16:34 O:     Storage Swap capacity:    90.0% used, 10.0% free
11:16:34 O:     Storage Mem size:    736 KB
11:16:34 O:     Storage Mem capacity:     0.1% used, 99.9% free
11:16:34 O:     Mean Object Size:    29.44 KB
11:16:34 O:     Requests given to unlinkd:    0
11:16:34 O: Median Service Times (seconds)  5 min    60 min:
11:16:34 O:     HTTP Requests (All):   0.03698  0.03437
11:16:34 O:     Cache Misses:          0.04456  0.04870
11:16:34 O:     Cache Hits:            0.00091  0.00179
11:16:34 O:     Near Hits:             0.00683  0.00707
11:16:34 O:     Not-Modified Replies:  0.00000  0.00065
11:16:34 O:     DNS Lookups:           0.00126  0.00126
11:16:34 O:     ICP Queries:           0.00000  0.00000
11:16:34 O: Resource usage for squid:
11:16:34 O:     UP Time:    6364.214 seconds
11:16:34 O:     CPU Time:    2481.987 seconds
11:16:34 O:     CPU Usage:    39.00%
11:16:34 O:     CPU Usage, 5 minute avg:    37.19%
11:16:34 O:     CPU Usage, 60 minute avg:    38.61%
11:16:34 O:     Maximum Resident Size: 2347456 KB
11:16:34 O:     Page faults with physical i/o: 0
11:16:34 O: Memory accounted for:
11:16:34 O:     Total accounted:       199928 KB
11:16:34 O:     memPoolAlloc calls: 295256640
11:16:34 O:     memPoolFree calls:  301578438
11:16:34 O: File descriptor usage for squid:
11:16:34 O:     Maximum number of file descriptors:   98304
11:16:34 O:     Largest file desc currently in use:   2566
11:16:34 O:     Number of file desc currently in use: 4030
11:16:34 O:     Files queued for open:                   0
11:16:34 O:     Available number of file descriptors: 94274
11:16:34 O:     Reserved number of file descriptors:   300
11:16:34 O:     Store Disk files open:                   3
11:16:34 O: Internal Data Structures:
11:16:34 O:     384892 StoreEntries
11:16:34 O:        208 StoreEntries with MemObjects
11:16:34 O:         14 Hot Object Cache Items
11:16:34 O:     384687 on-disk objects
11:16:34 O:
11:16:34 O: real    0m10.019s
11:16:34 O: user    0m0.006s
11:16:34 O: sys    0m0.006s


11:14:53 O: HTTP/1.1 200 OK
11:14:53 O: Server: squid/3.5.1
11:14:53 O: Mime-Version: 1.0
11:14:53 O: Date: Fri, 09 Dec 2016 10:14:53 GMT
11:14:53 O: Content-Type: text/plain
11:14:53 O: Expires: Fri, 09 Dec 2016 10:14:53 GMT
11:14:53 O: Last-Modified: Fri, 09 Dec 2016 10:14:53 GMT
11:14:53 O: Connection: close
11:14:53 O:
11:14:53 O: by kid1 {
11:14:53 O: Store Directory Statistics:
11:14:53 O: Store Entries          : 126418
11:14:53 O: Maximum Swap Size      : 4194304 KB
11:14:53 O: Current Store Swap Size: 3774836.00 KB
11:14:53 O: Current Capacity       : 90.00% used, 10.00% free
11:14:53 O:
11:14:53 O:
11:14:53 O: Shared Memory Cache
11:14:53 O: Maximum Size: 1048576 KB
11:14:53 O: Current Size: 736.00 KB 0.07%
11:14:53 O: Maximum entries:     32768
11:14:53 O: Current entries: 14 0.04%
11:14:53 O: Maximum slots:       32768
11:14:53 O: Used slots:             23 0.07%
11:14:53 O:
11:14:53 O: Store Directory #0 (aufs): /var/log/squid/cache/cache1
11:14:53 O: FS Block Size 4096 Bytes
11:14:53 O: First level subdirectories: 128
11:14:53 O: Second level subdirectories: 128
11:14:53 O: Maximum Size: 4194304 KB
11:14:53 O: Current Size: 3774836.00 KB
11:14:53 O: Percent Used: 90.00%
11:14:53 O: Filemap bits in use: 126340 of 262144 (48%)
11:14:53 O: Filesystem Space in use: 15704112/22008352 KB (71%)
11:14:53 O: Filesystem Inodes in use: 575168/29360128 (2%)
11:14:53 O: Flags: SELECTED
11:14:53 O: Removal policy: lru
11:14:53 O: LRU reference age: 2.00 days
11:14:53 O: } by kid1
11:14:53 O:
11:14:53 O: by kid2 {
11:14:53 O: Store Directory Statistics:
11:14:53 O: Store Entries          : 131817
11:14:53 O: Maximum Swap Size      : 4194304 KB
11:14:53 O: Current Store Swap Size: 3774848.00 KB
11:14:53 O: Current Capacity       : 90.00% used, 10.00% free
11:14:53 O:
11:14:53 O:
11:14:53 O: Shared Memory Cache
11:14:53 O: Maximum Size: 1048576 KB
11:14:53 O: Current Size: 736.00 KB 0.07%
11:14:53 O: Maximum entries:     32768
11:14:53 O: Current entries: 14 0.04%
11:14:53 O: Maximum slots:       32768
11:14:53 O: Used slots:             23 0.07%
11:14:53 O:
11:14:53 O: Store Directory #0 (aufs): /var/log/squid/cache/cache2
11:14:53 O: FS Block Size 4096 Bytes
11:14:53 O: First level subdirectories: 128
11:14:53 O: Second level subdirectories: 128
11:14:53 O: Maximum Size: 4194304 KB
11:14:53 O: Current Size: 3774848.00 KB
11:14:53 O: Percent Used: 90.00%
11:14:53 O: Filemap bits in use: 131752 of 262144 (50%)
11:14:53 O: Filesystem Space in use: 15704112/22008352 KB (71%)
11:14:53 O: Filesystem Inodes in use: 575168/29360128 (2%)
11:14:53 O: Flags: SELECTED
11:14:53 O: Removal policy: lru
11:14:53 O: LRU reference age: 2.14 days
11:14:53 O: } by kid2
11:14:53 O:
11:14:53 O: by kid3 {
11:14:53 O: Store Directory Statistics:
11:14:53 O: Store Entries          : 126609
11:14:53 O: Maximum Swap Size      : 4194304 KB
11:14:53 O: Current Store Swap Size: 3774872.00 KB
11:14:53 O: Current Capacity       : 90.00% used, 10.00% free
11:14:53 O:
11:14:53 O:
11:14:53 O: Shared Memory Cache
11:14:53 O: Maximum Size: 1048576 KB
11:14:53 O: Current Size: 736.00 KB 0.07%
11:14:53 O: Maximum entries:     32768
11:14:53 O: Current entries: 14 0.04%
11:14:53 O: Maximum slots:       32768
11:14:53 O: Used slots:             23 0.07%
11:14:53 O:
11:14:53 O: Store Directory #0 (aufs): /var/log/squid/cache/cache3
11:14:53 O: FS Block Size 4096 Bytes
11:14:53 O: First level subdirectories: 128
11:14:53 O: Second level subdirectories: 128
11:14:53 O: Maximum Size: 4194304 KB
11:14:53 O: Current Size: 3774872.00 KB
11:14:53 O: Percent Used: 90.00%
11:14:53 O: Filemap bits in use: 126552 of 262144 (48%)
11:14:53 O: Filesystem Space in use: 15704112/22008352 KB (71%)
11:14:53 O: Filesystem Inodes in use: 575168/29360128 (2%)
11:14:53 O: Flags: SELECTED
11:14:53 O: Removal policy: lru
11:14:53 O: LRU reference age: 3.91 days
11:14:53 O: } by kid3
11:15:03 O: < ===================== STALE 10 seconds ====
11:15:03 O: real    0m10.017s
11:15:03 O: user    0m0.006s
11:15:03 O: sys    0m0.006s

We have 3 balanced squid proxy,  at another squid I have seen the same
behaviour but with 20 seconds delay. When we restarted that squid,
mgr:info / mgr:storedir become inmediate.

Thank you very much


More information about the squid-users mailing list