Re: [squid-users] very slow responses from squid

mikie_at_x.org.pl wrote:
> Hi all,
>
> I'm going crazy with squid configuration. I've been trying to make it work
> fine for couple of weeks and finally gave up. Please, help! :)
>
> The problem is that squid responses are very very slow. I can notice a
> significant delays even when I use squid by myself (only my browser using
> it) and if I let some more people use it as transparent proxy, there is
> barely any response from squid on all machines.
>
> I install squid on slackware 12.2. Already tried few versions
> (2.7.STABLE5,2.7.STABLE6, 3.0.STABLE11) and many compile parameters. Let's
> say I do:
>
> ./configure \
> --prefix=/usr \
> --includedir=/usr/include \
> --datadir=/usr/share \
> --bindir=/usr/sbin \
> --libexecdir=/usr/lib/squid \
> --localstatedir=/var \
> --sysconfdir=/etc/squid
>
> I have the other instance of squid on other machine which works fine. But
> even when I move the config from this machine to my slackware box it does
> the same way - SLOW.
>
> System configuration is:
>
> # uname -a
> Linux ninja 2.6.27.7-smp #2 SMP Thu Nov 20 22:32:43 CST 2008 i686 Intel(R)
> Xeon(TM) CPU 3.40GHz GenuineIntel GNU/Linux
>
> # free -m
> total used free shared buffers cached
> Mem: 3036 666 2370 0 356 203
> -/+ buffers/cache: 107 2929
> Swap: 4102 0 4102
>
> # df -h
> Filesystem Size Used Avail Use% Mounted on
> /dev/root 30G 6.8G 22G 24% /
> tmpfs 1.5G 0 1.5G 0% /dev/shm
>
>
>
> This is what I call SLOW:
>
> $ time w3m -dump www.slackware.org
> [...]
> real 3m9.045s
> ^^^^^^^^ !!!
> user 0m0.032s
> sys 0m0.008s
>
>

Where was this request run from (the proxy itself, or another
computer)? Was this request intercepted by the proxy, and if so, how?
What does the access log look like after this request? Any additional
entries in the cache log?

>
>
> ================== squidclient mgr:info ============================
> HTTP/1.0 200 OK
> Server: squid/2.7.STABLE6
> Date: Thu, 12 Feb 2009 14:27:43 GMT
> Content-Type: text/plain
> Expires: Thu, 12 Feb 2009 14:27:43 GMT
> X-Cache: MISS from ninja
> Via: 1.0 ninja:3128 (squid/2.7.STABLE6)
> Connection: close
>
> Squid Object Cache: Version 2.7.STABLE6
> Start Time: Thu, 12 Feb 2009 14:09:54 GMT
> Current Time: Thu, 12 Feb 2009 14:27:43 GMT
> Connection information for squid:
> Number of clients accessing cache: 113
> Number of HTTP requests received: 3487
> 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: 195.7
> Average ICP messages per minute since start: 0.0
> Select loop called: 54532 times, 19.601 ms avg
> Cache information for squid:
> Request Hit Ratios: 5min: 23.5%, 60min: 15.9%
> Byte Hit Ratios: 5min: 7.5%, 60min: 9.3%
> Request Memory Hit Ratios: 5min: 42.6%, 60min: 46.1%
> Request Disk Hit Ratios: 5min: 21.1%, 60min: 23.9%
> Storage Swap size: 35564 KB
> Storage Mem size: 4520 KB
> Mean Object Size: 12.13 KB
> Requests given to unlinkd: 35
> Median Service Times (seconds) 5 min 60 min:
> HTTP Requests (All): 0.01164 0.02742
> Cache Misses: 0.03066 0.03829
> Cache Hits: 0.00000 0.00000
> Near Hits: 0.06286 0.01309
> Not-Modified Replies: 0.00000 0.00000
> DNS Lookups: 0.00094 0.00094
> ICP Queries: 0.00000 0.00000
>

That all looks like there is no problem with Squid...

> Resource usage for squid:
> UP Time: 1068.862 seconds
> CPU Time: 2.192 seconds
> CPU Usage: 0.21%
> CPU Usage, 5 minute avg: 0.23%
> CPU Usage, 60 minute avg: 0.21%
> Process Data Segment Size via sbrk(): 8536 KB
> Maximum Resident Size: 0 KB
> Page faults with physical i/o: 0
> Memory usage for squid via mallinfo():
> Total space in arena: 8536 KB
> Ordinary blocks: 8450 KB 12 blks
> Small blocks: 0 KB 0 blks
> Holding blocks: 2664 KB 2 blks
> Free Small blocks: 0 KB
> Free Ordinary blocks: 85 KB
> Total in use: 11114 KB 99%
> Total free: 85 KB 1%
> Total size: 11200 KB
> Memory accounted for:
> Total accounted: 6216 KB
> memPoolAlloc calls: 483763
> memPoolFree calls: 449379
> File descriptor usage for squid:
> Maximum number of file descriptors: 8192
> Largest file desc currently in use: 95
> Number of file desc currently in use: 55
> Files queued for open: 0
> Available number of file descriptors: 8137
> Reserved number of file descriptors: 100
> Store Disk files open: 0
> IO loop method: epoll
> Internal Data Structures:
> 2978 StoreEntries
> 980 StoreEntries with MemObjects
> 976 Hot Object Cache Items
> 2931 on-disk objects
>
>
>
> =============== squid.conf [ almost default ] ==================
> root_at_ninja:/etc/squid# cat squid.conf | grep -v '^#' | uniq
>
> acl all src all
> acl manager proto cache_object
> acl localhost src 127.0.0.1/32
> acl to_localhost dst 127.0.0.0/8
> acl localnet src 10.0.0.0/8 # RFC1918 possible internal network
> acl localnet src 172.16.0.0/12 # RFC1918 possible internal network
> acl localnet src 192.168.0.0/16 # RFC1918 possible internal network
> acl SSL_ports port 443
> acl Safe_ports port 80 # http
> acl Safe_ports port 21 # ftp
> acl Safe_ports port 443 # https
> acl Safe_ports port 70 # gopher
> acl Safe_ports port 210 # wais
> acl Safe_ports port 1025-65535 # unregistered ports
> acl Safe_ports port 280 # http-mgmt
> acl Safe_ports port 488 # gss-http
> acl Safe_ports port 591 # filemaker
> acl Safe_ports port 777 # multiling http
> acl CONNECT method CONNECT
>
> http_access allow manager localhost
> http_access deny manager
> http_access deny !Safe_ports
> http_access deny CONNECT !SSL_ports
>
> http_access allow localnet
>
> http_access deny all
>
> icp_access allow localnet
> icp_access deny all
>
> http_port 3128 transparent
>
> hierarchy_stoplist cgi-bin ?
>
> cache_mem 256 MB
>
> cache_dir ufs /var/squid/cache 20000 64 256
>
> access_log /var/log/squid/access.log squid
>
> cache_log /var/log/squid/cache.log
>
> cache_store_log /var/log/squid/store.log
>
> pid_filename /var/run/squid.pid
>
> netdb_filename /var/log/squid/netdb.state
>
> refresh_pattern ^ftp: 1440 20% 10080
> refresh_pattern ^gopher: 1440 0% 1440
> refresh_pattern -i (/cgi-bin/|\?) 0 0% 0
> refresh_pattern . 0 20% 4320
>
> acl shoutcast rep_header X-HTTP09-First-Line ^ICY.[0-9]
> upgrade_http0.9 deny shoutcast
>
> acl apache rep_header Server ^Apache
> broken_vary_encoding allow apache
>
> cache_effective_user squid
>
> cache_effective_user squid
>
> coredump_dir /var/squid/cache
>
>
>
> ================= cache.log =====================
>
> 2009/02/12 14:15:01| Starting Squid Cache version 2.7.STABLE6 for
> i686-pc-linux-gnu...
> 2009/02/12 14:15:01| Process ID 30656
> 2009/02/12 14:15:01| With 8192 file descriptors available
> 2009/02/12 14:15:01| Using epoll for the IO loop
> 2009/02/12 14:15:01| Performing DNS Tests...
> 2009/02/12 14:15:01| Successful DNS name lookup tests...
>

The DNS tests completed within a second... That's a good sign.

> 2009/02/12 14:15:01| DNS Socket created at 0.0.0.0, port 51877, FD 6
> 2009/02/12 14:15:01| Adding nameserver 213.134.134.134 from /etc/resolv.conf
> 2009/02/12 14:15:01| logfileOpen: opening log /var/log/squid/access.log
> 2009/02/12 14:15:01| Unlinkd pipe opened on FD 11
> 2009/02/12 14:15:01| Swap maxSize 20480000 + 262144 KB, estimated 0 objects
> 2009/02/12 14:15:01| Target number of buckets: 79777
> 2009/02/12 14:15:01| Using 131072 Store buckets
> 2009/02/12 14:15:01| Max Mem size: 262144 KB
> 2009/02/12 14:15:01| Max Swap size: 20480000 KB
> 2009/02/12 14:15:01| logfileOpen: opening log /var/log/squid/store.log
> 2009/02/12 14:15:01| Rebuilding storage in /var/squid/cache (DIRTY)
>

Squid wasn't cleanly shut down, or the store.log was corrupted...

> 2009/02/12 14:15:01| Using Least Load store dir selection
> 2009/02/12 14:15:01| Set Current Directory to /var/squid/cache
> 2009/02/12 14:15:01| Loaded Icons.
> 2009/02/12 14:15:01| Accepting transparently proxied HTTP connections at
> 10.10.0.26, port 3128, FD 13.
> 2009/02/12 14:15:01| Accepting ICP messages at 0.0.0.0, port 3130, FD 14.
> 2009/02/12 14:15:01| WCCP Disabled.
> 2009/02/12 14:15:01| Ready to serve requests.
> 2009/02/12 14:15:01| Done reading /var/squid/cache swaplog (1138 entries)
> 2009/02/12 14:15:01| Finished rebuilding storage from disk.
> 2009/02/12 14:15:01| 1095 Entries scanned
> 2009/02/12 14:15:01| 0 Invalid entries.
> 2009/02/12 14:15:01| 0 With invalid flags.
> 2009/02/12 14:15:01| 1095 Objects loaded.
> 2009/02/12 14:15:01| 0 Objects expired.
> 2009/02/12 14:15:01| 42 Objects cancelled.
> 2009/02/12 14:15:01| 0 Duplicate URLs purged.
> 2009/02/12 14:15:01| 0 Swapfile clashes avoided.
> 2009/02/12 14:15:01| Took 0.3 seconds (3929.1 objects/sec).
>

But rebuilding the store was quick. No obvious problems here.

> 2009/02/12 14:15:01| Beginning Validation Procedure
> 2009/02/12 14:15:01| Completed Validation Procedure
> 2009/02/12 14:15:01| Validated 1053 Entries
> 2009/02/12 14:15:01| store_swap_size = 12804k
> 2009/02/12 14:15:02| storeLateRelease: released 0 objects
>

It's looking like the problem exists outside of Squid.

Chris
Received on Thu Feb 12 2009 - 20:33:09 MST