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

mikie_at_x.org.pl wrote:
>> 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?
>
> It was run from another computer. Intercepted by proxy.
>
> The configuration is something like:
>
>
> Internet
> |
> eth0 |
> |-------------|
> | Proxy Box |
> | ninja |
> |-------------|
> eth1 |10.10.0.26
> |
> |
> | 10.10.0.0/22 network
> |
> |
> Client (10.10.1.4)
>
> There is iptables rule at proxy box:
>
> iptables -A PREROUTING -t nat -i eth1 -s 10.10.0.0/22 -p tcp --dport 80 -j
> REDIRECT --to-port 3128
>
>
>> What does the access log look like after this request?
>
> In access.log around this request there was :
>
> 1234448425.123 9 10.10.2.133 TCP_MISS/200 3368 GET
> http://m.onet.pl/_m/187a57b2378f7f02dd93d2c1bf6500c7,39,29,0-0-321-214-0.jpg
> - DIRECT/213.180.130.204 image/jpeg
> 1234448425.133 8 10.10.2.133 TCP_MISS/200 2259 GET
> http://m.onet.pl/_m/3d31dcd40ed9a7005487ec67f1463bc1,39,29,0-2-460-305-0.jpg
> - DIRECT/213.180.130.204 image/jpeg
> 1234448425.137 0 10.10.2.133 TCP_HIT/200 6185 GET
> http://m.onet.pl/_m/26bcf6361b28af8acf4cbbf281a597f3,44,29,0-293-667-326-0.jpg
> - NONE/- image/jpeg
> 1234448425.159 7 10.10.2.133 TCP_MISS/200 3812 GET
> http://m.onet.pl/_m/e8e6bcb1a0f521461b6181707bc34543,43,29,0-0-300-196-0.jpg
> - DIRECT/213.180.130.204 image/jpeg
> 1234448425.177 7 10.10.2.133 TCP_MISS/200 2969 GET
> http://m.onet.pl/_m/18fefe81dbc86382cc83ba8ed8e12b18,42,29,24-1-229-154-0.jpg
> - DIRECT/213.180.130.204 image/jpeg
> 1234448425.192 7 10.10.2.133 TCP_MISS/200 2178 GET
> http://m.onet.pl/_m/d8f8780a335ad8d39bb75c34505f05ae,42,29,40-2-221-149-0.jpg
> - DIRECT/213.180.130.204 image/jpeg
> 1234448425.205 7 10.10.2.133 TCP_MISS/200 2549 GET
> http://m.onet.pl/_m/f766f193723220d2e712863f376ccf77,42,29,24-1-250-168-0.jpg
> - DIRECT/213.180.130.204 image/jpeg
> 1234448425.718 52 10.10.2.216 TCP_MISS/200 404 GET
> http://mail.google.com/a/gazeta.pl/channel/test? - DIRECT/74.125.39.19
> text/html
> 1234448426.733 77 10.10.2.216 TCP_MISS/200 418 GET
> http://mail.google.com/a/gazeta.pl/images/cleardot.gif? -
> DIRECT/74.125.39.83 image/gif
> 1234448427.805 10 10.10.1.43 TCP_MISS/200 692 GET
> http://gg.hit.gemius.pl/_1234448382820/rexdot.gif? - DIRECT/91.197.13.134
> image/gif
> 1234448428.742 19 10.10.2.2 TCP_MISS/200 1636 GET
> http://adserver.gadu-gadu.pl/getbanner.asp? - DIRECT/91.197.13.212
> text/html
> 1234448429.915 0 10.10.1.29 TCP_MEM_HIT/200 3450 GET
> http://pictures.trader.pl/pictures/0/2/0/107567540-101118-3.jpg - NONE/-
> image/jpeg
> 1234448429.921 0 10.10.1.29 TCP_MEM_HIT/200 3450 GET
> http://pictures.trader.pl/pictures/0/2/0/107567540-101118-3.jpg - NONE/-
> image/jpeg
> 1234448429.924 0 10.10.1.29 TCP_MEM_HIT/200 1787 GET
> http://pictures.trader.pl/pictures/search-results/0/2/0/107567540-101118-3.jpg
> - NONE/- image/jpeg
> 1234448430.443 16 10.10.2.48 TCP_MISS/200 1712 GET
> http://www.tvn24.pl/messages.xml - DIRECT/213.180.130.210 text/xml
> 1234448430.824 10 10.10.1.227 TCP_MISS/200 665 GET
> http://ggao.hit.gemius.pl/_1234448400782/redot.js/id=1_Xg7aszd5jQsnlOOSjrb5ZWP_gFPy_cuKEa0btbQ.H.87/stparam=qlgegkijli/sarg=0000000240675C7A
> - DIRECT/91.197.13.200 application/x-javascript
> 1234448431.854 0 10.10.1.29 TCP_MEM_HIT/200 1787 GET
> http://pictures.trader.pl/pictures/search-results/0/2/0/107567540-101118-3.jpg
> - NONE/- image/jpeg
> 1234448431.863 0 10.10.1.29 TCP_MEM_HIT/200 4850 GET
> http://pictures.trader.pl/pictures/0/8/6/107567540-101120-4.jpg - NONE/-
> image/jpeg
> 1234448431.882 0 10.10.1.29 TCP_MEM_HIT/200 2399 GET
> http://pictures.trader.pl/pictures/search-results/0/8/6/107567540-101120-4.jpg
> - NONE/- image/jpeg
> 1234448431.885 0 10.10.1.29 TCP_MEM_HIT/200 4850 GET
> http://pictures.trader.pl/pictures/0/8/6/107567540-101120-4.jpg - NONE/-
> image/jpeg
> 1234448431.942 267 10.10.2.195 TCP_MISS/200 32315 GET
> http://wyborcza.pl/reklamagw/0,78728.html - DIRECT/80.252.0.132 text/html
> 1234448432.612 1 10.10.1.4 TCP_HIT/200 14522 GET
> http://www.slackware.org/ - NONE/- text/html
> 1234448433.741 58 10.10.2.250 TCP_MISS/302 551 GET
> http://www.google.pl/ - DIRECT/74.125.39.104 text/html
> 1234448433.868 110 10.10.2.250 TCP_MISS/200 11702 GET
> http://www.google.pl/ig? - DIRECT/74.125.39.104 text/html
> 1234448434.158 34 10.10.2.250 TCP_MISS/302 551 GET
> http://www.google.pl/ - DIRECT/74.125.39.104 text/html
> 1234448434.466 0 10.10.2.137 TCP_MEM_HIT/301 600 GET
> http://google.pl/ - NONE/- text/html
> 1234448434.531 43 10.10.2.137 TCP_MISS/200 3279 GET
> http://www.google.pl/ - DIRECT/74.125.39.104 text/html
> 1234448434.611 35 10.10.2.137 TCP_MISS/200 6687 GET
> http://www.google.pl/images/nav_logo3.png - DIRECT/74.125.39.104 image/png
> 1234448434.658 0 10.10.2.53 TCP_MISS/504 1495 GET
> http://www.stelsy.com/page1 - DIRECT/www.stelsy.com text/html
> 1234448436.677 107 10.10.2.137 TCP_MISS/200 8117 GET
> http://www.google.pl/search? - DIRECT/74.125.39.104 text/html
> 1234448436.741 59 10.10.2.137 TCP_MISS/200 1982 GET
> http://www.google.pl/images/newspaper.gif - DIRECT/74.125.39.147 image/gif
> 1234448437.047 1264 10.10.1.105 TCP_MISS/200 21685 GET
> http://www.skyscrapercity.com/showthread.php? - DIRECT/66.249.128.93
> text/html
> 1234448437.731 0 10.10.2.53 TCP_MISS/504 1495 GET
> http://www.stelsy.com/page1 - DIRECT/www.stelsy.com text/html
> 1234448438.318 0 10.10.1.29 TCP_MEM_HIT/200 2399 GET
> http://pictures.trader.pl/pictures/search-results/0/8/6/107567540-101120-4.jpg
> - NONE/- image/jpeg
> 1234448438.343 1 10.10.1.29 TCP_HIT/200 13299 GET
> http://pictures.trader.pl/pictures/4/0/5/107567540-101122-5.jpg - NONE/-
> image/jpeg
> 1234448438.350 0 10.10.1.29 TCP_MEM_HIT/200 2267 GET
> http://pictures.trader.pl/pictures/search-results/4/0/5/107567540-101122-5.jpg
> - NONE/- image/jpeg
> 1234448438.996 4 10.10.1.244 TCP_MISS/200 692 GET
> http://arbo.hit.gemius.pl/_1234448439205/rexdot.gif? -
> DIRECT/195.42.113.219 image/gif
> 1234448439.526 14 10.10.1.209 TCP_MISS/200 556 GET
> http://interia.hit.gemius.pl/_1234448439529/redot.gif? -
> DIRECT/217.74.64.40 image/gif
> 1234448439.624 0 10.10.2.53 TCP_MISS/504 1495 GET
> http://www.stelsy.com/page1 - DIRECT/www.stelsy.com text/html
> 1234448440.673 0 10.10.2.53 TCP_MISS/504 1495 GET
> http://www.stelsy.com/page1 - DIRECT/www.stelsy.com text/html
> 1234448440.847 30 10.10.2.137 TCP_MISS/204 351 GET
> http://www.google.pl/url? - DIRECT/74.125.39.147 text/html
> 1234448441.692 31 10.10.1.141 TCP_MISS/204 330 GET
> http://www.google.pl/csi? - DIRECT/74.125.39.147 text/html
> 1234448442.627 0 10.10.2.6 TCP_MEM_HIT/301 600 GET http://google.pl/
> - NONE/- text/html
> 1234448443.926 13 10.10.1.35 TCP_MISS/304 392 GET
> http://film.onet.pl/zwiastuny/0 - DIRECT/213.180.130.201 image/gif
> 1234448443.938 109 10.10.2.250 TCP_MISS/200 11484 GET
> http://www.gazetaprawna.pl/serwisy/fundusze_unijne -
> DIRECT/193.164.157.253 text/html
> 1234448443.943 7 10.10.1.35 TCP_MISS/304 392 GET
> http://film.onet.pl/_g/_s/forum/abuse001.css - DIRECT/213.180.130.201
> text/css
>
>
>> Any additional
>> entries in the cache log?
>
> 2009/02/12 15:14:49| NOTICE: no explicit transparent proxy support
> enabled. Assuming getsockname() works on intercepted connections
> 2009/02/12 15:14:49| WARNING: Forwarding loop detected for:
> Client: 10.10.0.26 http_port: 10.10.0.26:3128
> GET
> http://10.10.0.26:3128/40E800104644424D5953464849455343475448506C000001BD6600000001760000003DEB000530BCC2C7CC
> HTTP/1.0
> Via: 1.0 ninja:3128 (squid/2.7.STABLE6)
> X-Forwarded-For: 10.10.2.191
> Host: 10.10.0.26:3128
> Cache-Control: max-age=259200
> Connection: keep-alive
>
>
> Hmmm... I didn't find such a records in cache.log before ("no explicit
> transparent proxy supported"). May be because I compiled squid with
> "--enable-linux-netfilter" that time. Anyway it worked the same way then.
>

That message only occurs when interception support is DISABLED during
build and attempted to be used at run-time.

It's probably causing the forwarding loops, which are guaranteed speed
killers.

The alternative is that the site you are trying to contact is virtual
hosted. When asked for raw-IPs such as can be generated by a
non-intercept supporting squid when given intercepted requests.

Amos

-- 
Please be using
   Current Stable Squid 2.7.STABLE6 or 3.0.STABLE13
   Current Beta Squid 3.1.0.5