[squid-users] Squid processing very slow on some pdf

From: Sandrini Christian \(xsnd\) <xsnd_at_zhaw.ch>
Date: Wed, 30 Jan 2013 07:54:08 +0000

Hi

We are using an f5 appliance that is loadbalancing http request to 3 squid servers. We use squid 3.1.10. When I want to open a pdf file of a certain domain it takes several minutes for 160kb. If I open the pdf without going through the proxy it is very quick. We have seen this problem only on the pdf of the following domain

http://www2.zhlex.zh.ch/appl/zhlex_r.nsf/0/62FABE8867570E44C1257A210032892E/$file/414.252.3_29.1.08_77.pdf

This is in the access.log. Squid takes 115 seconds to handle the request.

1359524314.374 115810 160.85.85.46 TCP_HIT/200 111028 GET http://www2.zhlex.zh.ch/appl/zhlex_r.nsf/0/62FABE8867570E44C1257A210032892E/$file/414.252.3_29.1.08_77.pdf - NONE/- application/pdf

No logs have been written to cache.log during that time.

I have captured the network traffic from the squidbox to www2.zhlex.zh.ch to find out the time squid takes to get the pdf. It does it in less than a second.

tcpdump -i eth1 host www2.zhlex.zh.ch
tcpdump: verbose output suppressed, use -v or -vv for full protocol decode
listening on eth1, link-type EN10MB (Ethernet), capture size 65535 bytes
06:30:45.491906 IP srv-app-902.zhaw.ch.34179 > 195.65.218.66.http: Flags [S], seq 1530511587, win 5840, options [mss 1460,nop,nop,sackOK], length 0
06:30:45.494241 IP 195.65.218.66.http > srv-app-902.zhaw.ch.34179: Flags [S.], seq 3031868726, ack 1530511588, win 64240, options [mss 1380,nop,nop,sackOK], length 0
06:30:45.494259 IP srv-app-902.zhaw.ch.34179 > 195.65.218.66.http: Flags [.], ack 1, win 5840, length 0
06:30:45.494353 IP srv-app-902.zhaw.ch.34179 > 195.65.218.66.http: Flags [P.], seq 1:519, ack 1, win 5840, length 518
06:30:45.524850 IP 195.65.218.66.http > srv-app-902.zhaw.ch.34179: Flags [P.], seq 1:290, ack 519, win 63722, length 289
06:30:45.524864 IP srv-app-902.zhaw.ch.34179 > 195.65.218.66.http: Flags [.], ack 290, win 6432, length 0
06:30:45.541484 IP 195.65.218.66.http > srv-app-902.zhaw.ch.34179: Flags [.], seq 290:1670, ack 519, win 63722, length 1380
06:30:45.541493 IP srv-app-902.zhaw.ch.34179 > 195.65.218.66.http: Flags [.], ack 1670, win 9660, length 0
06:30:45.541603 IP 195.65.218.66.http > srv-app-902.zhaw.ch.34179: Flags [.], seq 1670:3050, ack 519, win 63722, length 1380
06:30:45.541612 IP srv-app-902.zhaw.ch.34179 > 195.65.218.66.http: Flags [.], ack 3050, win 12420, length 0
06:30:45.541709 IP 195.65.218.66.http > srv-app-902.zhaw.ch.34179: Flags [.], seq 3050:4430, ack 519, win 63722, length 1380
06:30:45.541718 IP srv-app-902.zhaw.ch.34179 > 195.65.218.66.http: Flags [.], ack 4430, win 15180, length 0
06:30:45.543929 IP 195.65.218.66.http > srv-app-902.zhaw.ch.34179: Flags [.], seq 4430:5810, ack 519, win 63722, length 1380
06:30:45.543937 IP srv-app-902.zhaw.ch.34179 > 195.65.218.66.http: Flags [.], ack 5810, win 17940, length 0
06:30:45.544053 IP 195.65.218.66.http > srv-app-902.zhaw.ch.34179: Flags [.], seq 5810:7190, ack 519, win 63722, length 1380
06:30:45.544062 IP srv-app-902.zhaw.ch.34179 > 195.65.218.66.http: Flags [.], ack 7190, win 20700, length 0
06:30:45.544162 IP 195.65.218.66.http > srv-app-902.zhaw.ch.34179: Flags [.], seq 7190:8570, ack 519, win 63722, length 1380
06:30:45.544170 IP srv-app-902.zhaw.ch.34179 > 195.65.218.66.http: Flags [.], ack 8570, win 23460, length 0
06:30:45.544303 IP 195.65.218.66.http > srv-app-902.zhaw.ch.34179: Flags [.], seq 8570:9950, ack 519, win 63722, length 1380
06:30:45.544308 IP srv-app-902.zhaw.ch.34179 > 195.65.218.66.http: Flags [.], ack 9950, win 26220, length 0
06:30:45.544372 IP 195.65.218.66.http > srv-app-902.zhaw.ch.34179: Flags [.], seq 9950:11330, ack 519, win 63722, length 1380
06:30:45.544381 IP srv-app-902.zhaw.ch.34179 > 195.65.218.66.http: Flags [.], ack 11330, win 28980, length 0
06:30:45.544531 IP 195.65.218.66.http > srv-app-902.zhaw.ch.34179: Flags [.], seq 11330:12710, ack 519, win 63722, length 1380
06:30:45.544541 IP srv-app-902.zhaw.ch.34179 > 195.65.218.66.http: Flags [.], ack 12710, win 33120, length 0
06:30:45.546216 IP 195.65.218.66.http > srv-app-902.zhaw.ch.34179: Flags [.], seq 12710:14090, ack 519, win 63722, length 1380
06:30:45.546226 IP srv-app-902.zhaw.ch.34179 > 195.65.218.66.http: Flags [.], ack 14090, win 35880, length 0
06:30:45.546332 IP 195.65.218.66.http > srv-app-902.zhaw.ch.34179: Flags [.], seq 14090:15470, ack 519, win 63722, length 1380
06:30:45.546341 IP srv-app-902.zhaw.ch.34179 > 195.65.218.66.http: Flags [.], ack 15470, win 38640, length 0
06:30:45.546463 IP 195.65.218.66.http > srv-app-902.zhaw.ch.34179: Flags [.], seq 15470:16850, ack 519, win 63722, length 1380
06:30:45.546472 IP srv-app-902.zhaw.ch.34179 > 195.65.218.66.http: Flags [.], ack 16850, win 41400, length 0
06:30:45.546585 IP 195.65.218.66.http > srv-app-902.zhaw.ch.34179: Flags [.], seq 16850:18230, ack 519, win 63722, length 1380
06:30:45.548946 IP 195.65.218.66.http > srv-app-902.zhaw.ch.34179: Flags [.], seq 32030:33410, ack 519, win 63722, length 1380
06:30:45.549036 IP 195.65.218.66.http > srv-app-902.zhaw.ch.34179: Flags [.], seq 33410:34790, ack 519, win 63722, length 1380
06:30:45.549045 IP srv-app-902.zhaw.ch.34179 > 195.65.218.66.http: Flags [.], ack 34790, win 64860, length 0
06:30:45.549150 IP 195.65.218.66.http > srv-app-902.zhaw.ch.34179: Flags [.], seq 34790:36170, ack 519, win 63722, length 1380
06:30:45.549283 IP 195.65.218.66.http > srv-app-902.zhaw.ch.34179: Flags [.], seq 36170:37550, ack 519, win 63722, length 1380
06:30:45.549293 IP srv-app-902.zhaw.ch.34179 > 195.65.218.66.http: Flags [.], ack 37550, win 64860, length 0
06:30:45.549403 IP 195.65.218.66.http > srv-app-902.zhaw.ch.34179: Flags [.], seq 37550:38930, ack 519, win 63722, length 1380
06:30:45.549520 IP 195.65.218.66.http > srv-app-902.zhaw.ch.34179: Flags [.], seq 38930:40310, ack 519, win 63722, length 1380
06:30:45.549530 IP srv-app-902.zhaw.ch.34179 > 195.65.218.66.http: Flags [.], ack 40310, win 64860, length 0
06:30:45.549651 IP 195.65.218.66.http > srv-app-902.zhaw.ch.34179: Flags [.], seq 40310:41690, ack 519, win 63722, length 1380
06:30:45.549863 IP 195.65.218.66.http > srv-app-902.zhaw.ch.34179: Flags [.], seq 41690:43070, ack 519, win 63722, length 1380
06:30:45.549875 IP srv-app-902.zhaw.ch.34179 > 195.65.218.66.http: Flags [.], ack 43070, win 64860, length 0
06:30:45.549880 IP 195.65.218.66.http > srv-app-902.zhaw.ch.34179: Flags [.], seq 43070:44450, ack 519, win 63722, length 1380
06:30:45.549989 IP 195.65.218.66.http > srv-app-902.zhaw.ch.34179: Flags [.], seq 44450:45830, ack 519, win 63722, length 1380
06:30:45.549998 IP srv-app-902.zhaw.ch.34179 > 195.65.218.66.http: Flags [.], ack 45830, win 64860, length 0
06:30:45.550120 IP 195.65.218.66.http > srv-app-902.zhaw.ch.34179: Flags [.], seq 45830:47210, ack 519, win 63722, length 1380
06:30:45.550229 IP 195.65.218.66.http > srv-app-902.zhaw.ch.34179: Flags [.], seq 47210:48590, ack 519, win 63722, length 1380
06:30:45.550239 IP srv-app-902.zhaw.ch.34179 > 195.65.218.66.http: Flags [.], ack 48590, win 64860, length 0
06:30:45.550404 IP 195.65.218.66.http > srv-app-902.zhaw.ch.34179: Flags [.], seq 48590:49970, ack 519, win 63722, length 1380
06:30:45.550413 IP 195.65.218.66.http > srv-app-902.zhaw.ch.34179: Flags [P.], seq 49970:50566, ack 519, win 63722, length 596
06:30:45.550420 IP srv-app-902.zhaw.ch.34179 > 195.65.218.66.http: Flags [.], ack 50566, win 64860, length 0
06:30:45.550730 IP srv-app-902.zhaw.ch.34179 > 195.65.218.66.http: Flags [F.], seq 519, ack 50566, win 64860, length 0
06:30:45.552075 IP 195.65.218.66.http > srv-app-902.zhaw.ch.34179: Flags [F.], seq 50566, ack 519, win 63722, length 0
06:30:45.552084 IP srv-app-902.zhaw.ch.34179 > 195.65.218.66.http: Flags [.], ack 50567, win 64860, length 0
06:30:45.552535 IP 195.65.218.66.http > srv-app-902.zhaw.ch.34179: Flags [.], ack 520, win 63722, length 0

Config:

#debug_options ALL,1 33,2 28,8

acl manager proto cache_object
acl localhost src 127.0.0.1/32
acl bigip src 160.85.104.21/32
acl to_localhost dst 127.0.0.0/8
acl monhost   src 160.85.192.190/32
acl srv-ts-057   src 160.85.186.73/32
acl srv-ts-058   src 160.85.186.74/32
acl snmppublic snmp_community Fast3thernet
acl ZHAWnet src 160.85.0.0/16       # ZHAW
acl ZHAWnet src 195.176.253.59/32   # HSWNAT
acl ZHAWnet src 10.196.0.0/16           # VoIP
acl ZHAWnet src 10.194.4.0/22       # HAP
acl ZHAWnet src 10.194.36.0/22      # HSSAZ
acl ZHAWnet src 172.28.8.0/24       # Management Netz 1
acl ZHAWnet src 172.28.9.0/24       # Management Netz 2
acl ZHAWnet src 172.28.10.0/24      # FET-DEV
acl ZHAWnet src 172.28.11.0/24      # FET-TEST
acl ZHAWnet src 172.28.12.0/24      # BET-DEV
acl ZHAWnet src 172.28.13.0/24      # BET-TEST
acl ZHAWnet src 172.28.14.0/24      # FET-VDP
acl ZHAWnet src 172.28.15.0/24      # FET-VDP
acl STAFFMGR src 160.85.85.0/26
acl SSL_ports port 443 8443 28443 50001
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
acl MONZHAWCH dstdomain mon.sanitized.ch
acl ZREG dstdomain zreg.sanitized.ch
acl MS dstdomain domzhwin01.sanitized.ch
acl MS dstdomain domzhwin02.sanitized.ch
acl MS dstdomain domzhwin03.sanitized.ch
acl MS dstdomain dc01.sanitized.ch
acl MS dstdomain dc02.sanitized.ch
acl MS dstdomain dc03.sanitized.ch
acl MS dstdomain dc04.sanitized.ch
acl MS dstdomain dc10.sanitized.ch
acl MS dstdomain dc11.sanitized.ch
acl MS dstdomain turtle.sanitized.ch
acl MS dstdomain zebra.sanitized.ch
acl MS dstdomain dolphin.sanitized.ch
acl MS dstdomain orca.sanitized.ch
acl MS dstdomain kangaroo.sanitized.ch
acl MS dstdomain lobster.sanitized.ch
acl MS dstdomain calamari.sanitized.ch
acl MS dstdomain warthog.sanitized.ch
acl MS dstdomain billabong.sanitized.ch
acl MS dstdomain zeus.sanitized.ch
acl MS dstdomain rhino1.sanitized.ch
acl MS dstdomain rhino2.sanitized.ch
acl MS dstdomain zhaw.sanitized.ch
acl MS dstdomain barracuda.sanitized.ch
acl MS dstdomain caesar.sanitized.ch
acl MS dstdomain octopus.sanitized.ch
acl MS dstdomain pandora.sanitized.ch
acl MS dstdomain gonzo.sanitized.ch
acl PUT method PUT
http_access allow PUT ZHAWnet
http_access deny PUT
acl PURGE method PURGE
http_access allow PURGE localhost
http_access deny PURGE
acl PROPFIND method PROPFIND
http_access allow PROPFIND srv-ts-057
http_access allow PROPFIND srv-ts-058
http_access deny PROPFIND
http_access allow manager localhost
http_access deny manager
http_access deny !Safe_ports
http_access deny CONNECT !SSL_ports
http_access deny to_localhost
http_access deny !STAFFMGR MONZHAWCH
http_access deny !STAFFMGR ZREG
http_access deny MS
http_access allow ZHAWnet
http_access deny all
icp_access deny all
follow_x_forwarded_for allow localhost
follow_x_forwarded_for allow bigip
acl_uses_indirect_client on
delay_pool_uses_indirect_client on
log_uses_indirect_client on
http_port 160.85.104.11:8080
hierarchy_stoplist cgi-bin ?
cache_mem 768 MB
maximum_object_size_in_memory 32 KB
cache_dir ufs /var/cache/squid 25000 64 256
coredump_dir /var/cache/squid
#access_log /var/log/squid/access.log
#cache_log /var/log/squid/cache.log
cache_store_log none
#pid_filename /var/run/squid.pid
ftp_user wwwuser_at_sanitized.ch
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]
acl apache rep_header Server ^Apache
request_timeout 30 seconds
cache_mgr servicedesk_at_sanitized.ch
#mail_from squid_at_srv-app-901.sanitized.ch
#mail_program /usr/local/bin/mutt
cache_effective_user squid
cache_effective_group squid
httpd_suppress_version_string on
visible_hostname srv-app-901.sanitized.ch
unique_hostname srv-app-901.sanitized.ch
snmp_port 3401
snmp_access allow snmppublic monhost
snmp_access deny all
snmp_incoming_address 160.85.104.11
snmp_outgoing_address 255.255.255.255
icp_port 0
allow_underscore off
dns_retransmit_interval 3 seconds
dns_timeout 1 minute
#dns_nameservers 160.85.192.100 160.85.193.100
dns_nameservers 160.85.192.100
append_domain .sanitized.ch
max_filedescriptors 8192

Has anyone an idea why squid takes so long for this request? How could I debug further?

Thanks a lot.
Received on Wed Jan 30 2013 - 07:54:18 MST

This archive was generated by hypermail 2.2.0 : Wed Jan 30 2013 - 12:00:04 MST