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

From: <mikie_at_x.org.pl>
Date: Thu, 12 Feb 2009 23:24:03 +0100 (CET)

> 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.

Thanks,
Mike
Received on Thu Feb 12 2009 - 22:24:12 MST

This archive was generated by hypermail 2.2.0 : Fri Feb 13 2009 - 12:00:02 MST