Squidのボトルネックを探す

■squidclientの統計情報を確認する。
 ※squid+squidguardの環境。

最初のヒット時だけ変に遅いのが気になった。。。
それ以外は快速。

■squidclientの導入。
 ※Windows版squidには「bin」配下にあり、同じように使える。

> bin\squidclient.exe

$ apt-cache search ^squidclient
squidclient - フル機能のウェブプロキシキャッシュ (HTTP プロキシ) - 制御ユーティリティ

■隠し属性の制御系のコマンドは使いません。

$ sudo squidclient mgr: | grep -v public
 config                 Current Squid Configuration     hidden
 shutdown               Shut Down the Squid Process     hidden
 reconfigure            Reconfigure the Squid Process   hidden
 offline_toggle         Toggle offline_mode setting     hidden

■パブリック属性の統計コマンドを使います。

$ sudo squidclient mgr: | grep public | sed s/" *public"//g
 mem                    Memory Utilization
 cbdata                 Callback Data Registry Contents
 events                 Event Queue
 squidaio_counts        Async IO Function Counters
 coss                   COSS Stats
 diskd                  DISKD Stats
 ipcache                IP Cache Stats and Contents
 fqdncache              FQDN Cache Stats and Contents
 idns                   Internal DNS Statistics
 url_rewriter           URL Rewriter Stats
 external_acl           External ACL stats
 http_headers           HTTP Header Statistics
 menu                   This Cachemanager Menu
 info                   General Runtime Information
 filedescriptors        Process Filedescriptor Allocation
 objects                All Cache Objects
 vm_objects             In-Memory and In-Transit Objects
 openfd_objects         Objects with Swapout files open
 pending_objects        Objects being retreived from the network
 client_objects         Objects being sent to clients
 io                     Server-side network read() size histograms
 counters               Traffic and Resource Counters
 peer_select            Peer Selection Algorithms
 digest_stats           Cache Digest and ICP blob
 5min                   5 Minute Average of Counters
 60min                  60 Minute Average of Counters
 utilization            Cache Utilization
 histograms             Full Histogram Counts
 active_requests        Client-side Active Requests
 store_digest           Store Digest
 storedir               Store Directory Stats
 store_check_cachable_stats     storeCheckCachable() Stats
 store_io               Store IO Interface Stats
 pconn                  Persistent Connection Utilization Histograms
 refresh                Refresh Algorithm Statistics
 delay                  Delay Pool Levels
 forward                Request Forwarding Statistics
 client_list            Cache Client List
 asndb                  AS Number Database
 server_list            Peer Cache Statistics
 non_peers              List of Unknown sites sending ICP messages

■上記の細かいところは置いといて、システムメールします。

$ cat myscripts/squidsummary.sh
#!/bin/bash

if [ "`id -u`" -ne "0" ];then
  echo "Sorry,Not Permit User"
  exit 1
fi

TODAY="`date '+%Y-%m-%d'`"
SQUIDSTAT="/var/log/squidsummary_$TODAY"
squidclient mgr:info > $SQUIDSTAT
squidclient mgr:60min >> $SQUIDSTAT
cat "$SQUIDSTAT" | \
  mail -s "Squid Summary Report $TODAY" root
unset TODAY SQUIDSTAT
exit 0

■以下のように出ます。
 ICPを使用していない(設定が0)であること、
 キャッシュ率はもう少し調整の余地がありそうなこと、
 やはり「DNS Lookups」が遅すぎること等が分かります。
 4秒って何かのタイムアウトでしょうか。。。

Squid Object Cache: Version 2.7.STABLE9
Start Time:     Sun, 26 Aug 2012 13:17:48 GMT
Current Time:   Fri, 31 Aug 2012 12:51:22 GMT
Connection information for squid:
        Number of clients accessing cache:      5
        Number of HTTP requests received:       119340
        Number of ICP messages received:        0
        Number of ICP messages sent:    0
        Number of queued ICP replies:   0
        Number of HTCP messages received:       0
        Number of HTCP messages sent:   0
        Request failure ratio:   0.00
        Average HTTP requests per minute since start:   16.6
        Average ICP messages per minute since start:    0.0
        Select loop called: 15281854 times, 28.165 ms avg
Cache information for squid:
        Request Hit Ratios:     5min: 6.2%, 60min: 5.0%
        Byte Hit Ratios:        5min: 0.0%, 60min: 0.0%
        Request Memory Hit Ratios:      5min: 0.0%, 60min: 25.0%
        Request Disk Hit Ratios:        5min: 0.0%, 60min: 0.0%
        Storage Swap size:      92056 KB
        Storage Mem size:       58280 KB
        Mean Object Size:       11.92 KB
        Requests given to unlinkd:      77973
Median Service Times (seconds)  5 min    60 min:
        HTTP Requests (All):   0.00091  0.11465
        Cache Misses:          0.00091  0.11465
        Cache Hits:            0.00000  0.00000
        Near Hits:             0.00000  5.34113
        Not-Modified Replies:  0.00000  0.00000
        DNS Lookups:           4.77162  4.77162
        ICP Queries:           0.00000  0.00000
Resource usage for squid:
        UP Time:        430414.434 seconds
        CPU Time:       660.901 seconds
        CPU Usage:      0.15%
        CPU Usage, 5 minute avg:        1.03%
        CPU Usage, 60 minute avg:       0.86%
        Process Data Segment Size via sbrk(): 82664 KB
        Maximum Resident Size: 333520 KB
        Page faults with physical i/o: 34
Memory usage for squid via mallinfo():
        Total space in arena:   82664 KB
        Ordinary blocks:        80046 KB    898 blks
        Small blocks:               0 KB      0 blks
        Holding blocks:           396 KB      1 blks
        Free Small blocks:          0 KB
        Free Ordinary blocks:    2617 KB
        Total in use:           80442 KB 97%
        Total free:              2617 KB 3%
        Total size:             83060 KB
Memory accounted for:
        Total accounted:        71960 KB
        memPoolAlloc calls: 30458307
        memPoolFree calls: 30221180
File descriptor usage for squid:
        Maximum number of file descriptors:   1024
        Largest file desc currently in use:     54
        Number of file desc currently in use:   28
        Files queued for open:                   0
        Available number of file descriptors:  996
        Reserved number of file descriptors:   100
        Store Disk files open:                   0
        IO loop method:                     epoll
Internal Data Structures:
          7899 StoreEntries
          7496 StoreEntries with MemObjects
          7493 Hot Object Cache Items
          7724 on-disk objects
...

■60minは以下のように取得しなおし。
 CPUの利用率も低く、スワップによる遅延も少ないのに、
 やはりDNSがボトルネックになっています。

$ sudo squidclient mgr:60min | \
  grep -v "0.000000" | sort -t\= -k 2 -nr | grep -v GMT | head -15 | sort
client_http.all_median_svc_time = 0.142521 seconds
client_http.kbytes_out = 221.445516/sec
client_http.nh_median_svc_time = 5.341132 seconds
cpu_time = 30.845927 seconds
cpu_usage = 0.856808%
dns.median_svc_time = 4.771619 seconds
select_fds = 259.283076/sec
select_loops = 253.184912/sec
server.all.kbytes_in = 221.367740/sec
server.http.kbytes_in = 221.255243/sec
syscalls.disk.writes = 0.187495/sec
syscalls.polls = 253.184912/sec
syscalls.sock.reads = 126.135107/sec
syscalls.sock.writes = 133.101025/sec
wall_time = 3600.099998 seconds

■なるほど、起動していない仮想のvyattaのDNSを見に行ってたわけですね。。。

$ sudo squidclient mgr:idns | grep -A 3 ^IP
IP ADDRESS      # QUERIES # REPLIES
--------------- --------- ---------
192.168.72.213       1702         0
192.168.54.1         1702      1702

■「/etc/resolv.conf」を修正して解決です。
 1時間置きに監視します。

$ sudo crontab -l | grep ^[0-9] | tail -1
55 * * * * /usr/local/sbin/myscripts/squidsummary.sh