Hi Mr. Lauro,
Attached are the files you asked for:
iostat -dx 1 11
vmstat 1 11
netstat -s
Both with a baseline (ie, at a non-troubled time :-)), and at a
moment of pressure.
On the baseline, "/usr/bin/time squidclient http://www.amazon.com";
took 0.03s, and on the pressure files, the same command took around 4
seconds.
Just so you know, sda is the system, and sdb is exclusively for squid cache.
Does these numbers indicate that I/O operations might be the
bottleneck of the slowdown?
Thanks,
Felipe Damasio
2010/1/26 John Lauro <john.lauro@xxxxxxxxxxxxxxxx>:
> Yup, your stats on free look fine, especially if squid has been running
> awhile. If it was recently restarted, it might not be accurate. Looking
> closer at the data you originally provided, it should be accurate... You
> may want to add 1-2GB of RAM cache to reduce your disk I/O (if that turns
> out to be the bottleneck).
>
> The vmstat and iostat should eliminate disk I/O as a bottleneck (or point to
> it).
>
>
> You may want to check out the stats with "netstat -s", maybe before and
> after the other commands so you can see the deltas.
>
> Hmmm, I just reread and noticed it was around midnight... I wonder if a
> bunch of stuff goes invalid in the cache because of the date change? Never
> noticed that behavior before, but not currently running on a large setup
> either.
>
> Should probably run the vmstat/iostat prior to the extreme slow time to get
> a bit of a baseline for normal operation.
>
>
> Given the high number of connections you have, you may want to consider:
> echo 1024 60999 > /proc/sys/net/ipv4/ip_local_port_range (probably not an
> issue given transparent mode)
>
> and check to see how close you are coming to your connection tracking limit.
> Probably ok, but could cause connections to require retries if a problem.
>
>
>
>
> PS: You mentioned this is in bridge mode? I am trying to get squid working
> in bridge mode... have it working fine in transparent mode as a router, but
> no luck with bridge mode. Can you send your iptables/ebtables/kernel's
> .config, etc? I'm going to compile that kernel (2.6.29.6) now, in case it's
> something broke in the more recent kernels.
>
>
>
>> -----Original Message-----
>> From: Felipe W Damasio [mailto:felipewd@xxxxxxxxx]
>> Sent: Monday, January 25, 2010 10:06 PM
>> To: John Lauro
>> Cc: squid-users@xxxxxxxxxxxxxxx
>> Subject: Re: Squid performance issues
>>
>> Hi Mr. John,
>>
>> 2010/1/26 John Lauro <john.lauro@xxxxxxxxxxxxxxxx>:
>> > What does the following give:
>> > uname -a
>>
>> uname -a:
>>
>> Linux squid 2.6.29.6 #4 SMP Thu Jan 14 21:00:42 BRST 2010 x86_64
>> Intel(R) Core(TM) i7 CPU @ 9200 @ 2.67GHz GenuineIntel GNU/Linux
>>
>> > While it's being slow, run the following to get some stats:
>> >
>> > vmstat 1 11 ;# Will run for 11 seconds
>> > iostat -dx 11 ;# Will run for 11 seconds, install sysstat if not
>> found
>>
>> I'll run these tonight.
>>
>> > My first guess is memory swapping, but could be I/O. The above
>> should help
>> > narrow it down.
>>
>> I thought that, but actually both top and free -m tells me the same
>> thing:
>>
>> total used free shared buffers
>> cached
>> Mem: 7979 5076 2903 0 0
>> 4144
>> -/+ buffers/cache: 931 7047
>> Swap: 3812 0 3811
>>
>> Swap isn't even touched...even when slow.
>>
>> But if you think vmstat and iostat can help, I'll run them no
>> problem.
>>
>> Thanks,
>>
>> Felipe Damasio
>>
>> No virus found in this incoming message.
>> Checked by AVG - www.avg.com
>> Version: 8.5.432 / Virus Database: 271.1.1/2644 - Release Date:
>> 01/25/10 19:36:00
>
>
Tue Jan 26 16:47:42 BRST 2010
Linux 2.6.29.6 (hyper) 01/26/10 _x86_64_ (8 CPU)
Device: rrqm/s wrqm/s r/s w/s rsec/s wsec/s avgrq-sz avgqu-sz await svctm %util
sda 0.01 14.97 0.43 2.36 11.93 678.83 247.49 0.40 143.89 12.53 3.50
sdb 0.02 2.25 2.89 17.04 417.55 2127.18 127.67 7.51 376.56 9.59 19.12
Device: rrqm/s wrqm/s r/s w/s rsec/s wsec/s avgrq-sz avgqu-sz await svctm %util
sda 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00
sdb 0.00 0.00 2.97 0.00 261.39 0.00 88.00 0.03 10.00 9.00 2.67
Device: rrqm/s wrqm/s r/s w/s rsec/s wsec/s avgrq-sz avgqu-sz await svctm %util
sda 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00
sdb 0.00 0.00 3.00 2.00 768.00 9.00 155.40 0.10 19.60 19.40 9.70
Device: rrqm/s wrqm/s r/s w/s rsec/s wsec/s avgrq-sz avgqu-sz await svctm %util
sda 0.00 1.98 0.00 6.93 0.00 73.27 10.57 0.57 81.71 30.71 21.29
sdb 0.00 5.94 0.99 98.02 253.47 11955.45 123.31 43.94 443.78 9.47 93.76
Device: rrqm/s wrqm/s r/s w/s rsec/s wsec/s avgrq-sz avgqu-sz await svctm %util
sda 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00
sdb 0.00 0.00 1.98 3.96 506.93 24.75 89.50 0.02 3.00 2.50 1.49
Device: rrqm/s wrqm/s r/s w/s rsec/s wsec/s avgrq-sz avgqu-sz await svctm %util
sda 0.00 0.00 1.00 0.00 8.00 0.00 8.00 0.02 18.00 18.00 1.80
sdb 0.00 0.00 1.00 5.00 256.00 40.00 49.33 0.10 16.50 14.33 8.60
Device: rrqm/s wrqm/s r/s w/s rsec/s wsec/s avgrq-sz avgqu-sz await svctm %util
sda 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00
sdb 0.00 0.00 3.96 0.00 768.32 0.00 194.00 0.10 27.25 26.50 10.50
Device: rrqm/s wrqm/s r/s w/s rsec/s wsec/s avgrq-sz avgqu-sz await svctm %util
sda 0.00 0.00 0.00 6.00 0.00 809.00 134.83 0.36 59.83 15.83 9.50
sdb 0.00 0.00 2.00 154.00 264.00 1233.00 9.60 16.53 105.99 1.45 22.60
Device: rrqm/s wrqm/s r/s w/s rsec/s wsec/s avgrq-sz avgqu-sz await svctm %util
sda 0.00 0.00 0.00 0.99 0.00 7.92 8.00 0.97 26.00 983.00 97.33
sdb 0.00 0.00 0.99 0.00 253.47 0.00 256.00 1.48 43.00 971.00 96.14
Device: rrqm/s wrqm/s r/s w/s rsec/s wsec/s avgrq-sz avgqu-sz await svctm %util
sda 0.00 0.00 1.00 6.00 8.00 73.00 11.57 0.17 161.29 23.86 16.70
sdb 0.00 9.00 6.00 95.00 1048.00 16207.00 170.84 39.86 409.05 9.61 97.10
Device: rrqm/s wrqm/s r/s w/s rsec/s wsec/s avgrq-sz avgqu-sz await svctm %util
sda 0.00 0.00 0.99 0.00 7.92 0.00 8.00 0.03 34.00 34.00 3.37
sdb 0.00 0.00 3.96 4.95 277.23 633.66 102.22 0.40 44.67 21.11 18.81
Tue Jan 26 22:40:14 BRST 2010
Linux 2.6.29.6 (hyper) 01/26/10 _x86_64_ (8 CPU)
Device: rrqm/s wrqm/s r/s w/s rsec/s wsec/s avgrq-sz avgqu-sz await svctm %util
sda 0.01 15.64 0.46 2.42 13.45 702.86 249.06 0.41 144.19 12.56 3.61
sdb 0.02 2.28 2.90 17.72 415.77 2181.54 125.99 7.83 379.96 9.53 19.64
Device: rrqm/s wrqm/s r/s w/s rsec/s wsec/s avgrq-sz avgqu-sz await svctm %util
sda 0.00 0.00 1.98 0.00 23.76 0.00 12.00 0.03 14.50 14.50 2.87
sdb 0.00 0.00 5.94 0.99 784.16 7.92 114.29 0.13 245.14 6.57 4.55
Device: rrqm/s wrqm/s r/s w/s rsec/s wsec/s avgrq-sz avgqu-sz await svctm %util
sda 0.00 0.00 1.00 0.00 8.00 0.00 8.00 0.01 14.00 14.00 1.40
sdb 0.00 0.00 1.00 0.00 256.00 0.00 256.00 0.02 15.00 19.00 1.90
Device: rrqm/s wrqm/s r/s w/s rsec/s wsec/s avgrq-sz avgqu-sz await svctm %util
sda 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00
sdb 0.00 0.00 8.00 5.00 552.00 83.00 48.85 0.15 12.08 10.77 14.00
Device: rrqm/s wrqm/s r/s w/s rsec/s wsec/s avgrq-sz avgqu-sz await svctm %util
sda 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00
sdb 0.00 0.00 2.00 0.00 256.00 0.00 128.00 0.07 32.50 17.00 3.40
Device: rrqm/s wrqm/s r/s w/s rsec/s wsec/s avgrq-sz avgqu-sz await svctm %util
sda 0.00 3.00 0.00 34.00 0.00 12407.00 364.91 2.27 66.71 9.38 31.90
sdb 0.00 11.00 5.00 77.00 1024.00 12193.00 161.18 14.33 174.71 4.60 37.70
Device: rrqm/s wrqm/s r/s w/s rsec/s wsec/s avgrq-sz avgqu-sz await svctm %util
sda 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00
sdb 0.00 0.00 1.00 0.00 256.00 0.00 256.00 0.02 19.00 19.00 1.90
Device: rrqm/s wrqm/s r/s w/s rsec/s wsec/s avgrq-sz avgqu-sz await svctm %util
sda 0.00 0.00 0.99 0.00 7.92 0.00 8.00 0.10 101.00 101.00 10.00
sdb 0.00 0.00 1.98 0.00 506.93 0.00 256.00 0.13 58.00 68.00 13.47
Device: rrqm/s wrqm/s r/s w/s rsec/s wsec/s avgrq-sz avgqu-sz await svctm %util
sda 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00
sdb 0.00 0.00 4.00 0.00 528.00 0.00 132.00 0.05 17.25 12.25 4.90
Device: rrqm/s wrqm/s r/s w/s rsec/s wsec/s avgrq-sz avgqu-sz await svctm %util
sda 0.00 0.00 0.00 3.00 0.00 17.00 5.67 0.07 10.00 18.00 5.40
sdb 0.00 0.00 0.00 65.00 0.00 513.00 7.89 1.11 16.26 1.12 7.30
Device: rrqm/s wrqm/s r/s w/s rsec/s wsec/s avgrq-sz avgqu-sz await svctm %util
sda 0.00 878.00 1.00 45.00 8.00 21809.00 474.28 9.23 201.54 17.30 79.60
sdb 0.00 8.00 0.00 108.00 0.00 8097.00 74.97 50.46 320.93 9.25 99.90
Tue Jan 26 16:48:08 BRST 2010
Ip:
3875482903 total packets received
95 with invalid headers
2228 with invalid addresses
12236199 forwarded
0 incoming packets discarded
3863204029 incoming packets delivered
3392428979 requests sent out
11044 dropped because of missing route
35 fragments dropped after timeout
4674 reassemblies required
997 packets reassembled ok
137 packet reassembles failed
949 fragments received ok
4221 fragments created
Icmp:
1387 ICMP messages received
10 input ICMP message failed.
ICMP input histogram:
destination unreachable: 96
timeout in transit: 2
redirects: 21
echo requests: 1268
2544 ICMP messages sent
0 ICMP messages failed
ICMP output histogram:
destination unreachable: 1181
time exceeded: 95
echo replies: 1268
IcmpMsg:
InType3: 96
InType5: 21
InType8: 1268
InType11: 2
OutType0: 1268
OutType3: 1181
OutType11: 95
Tcp:
68163183 active connections openings
62479783 passive connection openings
517735 failed connection attempts
13193923 connection resets received
17981 connections established
3856715164 segments received
3332533002 segments send out
41268836 segments retransmited
70105 bad segments received.
5831342 resets sent
Udp:
6471609 packets received
1180 packets to unknown port received.
7638 packet receive errors
6484631 packets sent
RcvbufErrors: 7638
UdpLite:
TcpExt:
2380006 SYN cookies sent
1630104 SYN cookies received
155897 invalid SYN cookies received
328988 resets received for embryonic SYN_RECV sockets
296152 packets pruned from receive queue because of socket buffer overrun
51376028 TCP sockets finished time wait in fast timer
4 active connections rejected because of time stamp
36561 packets rejects in established connections because of timestamp
72810806 delayed acks sent
10792 delayed acks further delayed because of locked socket
Quick ack mode was activated 7988689 times
165946 times the listen queue of a socket overflowed
165946 SYNs to LISTEN sockets dropped
1489228993 packet headers predicted
569152541 acknowledgments not containing data payload received
761306636 predicted acknowledgments
54982 times recovered from packet loss due to fast retransmit
3638998 times recovered from packet loss by selective acknowledgements
37 bad SACK blocks received
Detected reordering 1416 times using FACK
Detected reordering 1162 times using SACK
Detected reordering 307 times using reno fast retransmit
Detected reordering 155 times using time stamp
1001 congestion windows fully recovered without slow start
1194 congestion windows partially recovered using Hoe heuristic
675545 congestion windows recovered without slow start by DSACK
1714587 congestion windows recovered without slow start after partial ack
4081569 TCP data loss events
TCPLostRetransmit: 56088
55198 timeouts after reno fast retransmit
1206471 timeouts after SACK recovery
361345 timeouts in loss state
7645551 fast retransmits
597229 forward retransmits
6426955 retransmits in slow start
14447603 other TCP timeouts
28963 classic Reno fast retransmits failed
350064 SACK retransmits failed
65683343 packets collapsed in receive queue due to low socket buffer
7626964 DSACKs sent for old packets
181141 DSACKs sent for out of order packets
2584091 DSACKs received
3283 DSACKs for out of order packets received
4 connections reset due to unexpected SYN
882967 connections reset due to unexpected data
103818 connections reset due to early user close
1059794 connections aborted due to timeout
TCPSACKDiscard: 1443
TCPDSACKIgnoredOld: 1299847
TCPDSACKIgnoredNoUndo: 315039
TCPSpuriousRTOs: 171866
TCPSackShifted: 12573411
TCPSackMerged: 12150887
TCPSackShiftFallback: 12676741
IpExt:
InBcastPkts: 7040
Tue Jan 26 22:40:24 BRST 2010
Ip:
4128075352 total packets received
112 with invalid headers
2234 with invalid addresses
13100968 forwarded
0 incoming packets discarded
4114931248 incoming packets delivered
3627540585 requests sent out
11044 dropped because of missing route
35 fragments dropped after timeout
4674 reassemblies required
997 packets reassembled ok
137 packet reassembles failed
949 fragments received ok
4221 fragments created
Icmp:
1458 ICMP messages received
10 input ICMP message failed.
ICMP input histogram:
destination unreachable: 104
timeout in transit: 2
redirects: 21
echo requests: 1331
2661 ICMP messages sent
0 ICMP messages failed
ICMP output histogram:
destination unreachable: 1218
time exceeded: 112
echo replies: 1331
IcmpMsg:
InType3: 104
InType5: 21
InType8: 1331
InType11: 2
OutType0: 1331
OutType3: 1218
OutType11: 112
Tcp:
73098271 active connections openings
67082954 passive connection openings
529071 failed connection attempts
14230204 connection resets received
23970 connections established
4107946668 segments received
3563362092 segments send out
44191955 segments retransmited
78553 bad segments received.
6242751 resets sent
Udp:
6966960 packets received
1217 packets to unknown port received.
7638 packet receive errors
6979999 packets sent
RcvbufErrors: 7638
UdpLite:
TcpExt:
2380006 SYN cookies sent
1630104 SYN cookies received
155897 invalid SYN cookies received
336123 resets received for embryonic SYN_RECV sockets
305413 packets pruned from receive queue because of socket buffer overrun
55208794 TCP sockets finished time wait in fast timer
4 active connections rejected because of time stamp
38883 packets rejects in established connections because of timestamp
77000504 delayed acks sent
11440 delayed acks further delayed because of locked socket
Quick ack mode was activated 8599101 times
183364 times the listen queue of a socket overflowed
183364 SYNs to LISTEN sockets dropped
1582938875 packet headers predicted
611319312 acknowledgments not containing data payload received
806845760 predicted acknowledgments
55784 times recovered from packet loss due to fast retransmit
3851484 times recovered from packet loss by selective acknowledgements
37 bad SACK blocks received
Detected reordering 1615 times using FACK
Detected reordering 1347 times using SACK
Detected reordering 310 times using reno fast retransmit
Detected reordering 173 times using time stamp
1084 congestion windows fully recovered without slow start
1359 congestion windows partially recovered using Hoe heuristic
731057 congestion windows recovered without slow start by DSACK
1898331 congestion windows recovered without slow start after partial ack
4323150 TCP data loss events
TCPLostRetransmit: 59467
57206 timeouts after reno fast retransmit
1295717 timeouts after SACK recovery
384599 timeouts in loss state
8102205 fast retransmits
635290 forward retransmits
6854385 retransmits in slow start
15607895 other TCP timeouts
29411 classic Reno fast retransmits failed
371555 SACK retransmits failed
67476322 packets collapsed in receive queue due to low socket buffer
8216494 DSACKs sent for old packets
200115 DSACKs sent for out of order packets
2804049 DSACKs received
3548 DSACKs for out of order packets received
4 connections reset due to unexpected SYN
950355 connections reset due to unexpected data
108171 connections reset due to early user close
1132529 connections aborted due to timeout
TCPSACKDiscard: 1460
TCPDSACKIgnoredOld: 1417302
TCPDSACKIgnoredNoUndo: 337905
TCPSpuriousRTOs: 184012
TCPSackShifted: 13281748
TCPSackMerged: 12846638
TCPSackShiftFallback: 13661792
IpExt:
InBcastPkts: 7296
Tue Jan 26 16:45:13 BRST 2010
procs -----------memory---------- ---swap-- -----io---- -system-- ----cpu----
r b swpd free buff cache si so bi bo in cs us sy id wa
2 0 848 166148 0 6592896 0 0 27 170 10 8 2 3 94 1
2 0 848 194544 0 6565424 0 0 4 132 15902 12761 4 5 92 0
2 0 848 192216 0 6567884 0 0 388 0 15867 13041 5 4 91 0
1 0 848 189744 0 6570076 0 0 128 3068 16453 14568 5 4 91 0
1 0 848 186744 0 6572088 0 0 256 0 16386 13177 5 5 91 0
0 0 848 185732 0 6573768 0 0 132 0 15971 13349 5 5 90 0
0 0 848 184680 0 6575716 0 0 256 0 15598 13350 4 5 91 0
2 0 848 185076 0 6577708 0 0 128 0 15875 12743 5 4 91 0
2 0 848 183924 0 6579644 0 0 260 24657 16252 13864 4 5 91 0
2 0 848 182144 0 6581976 0 0 0 0 16134 12959 4 5 91 0
0 0 848 180344 0 6584440 0 0 200 0 15774 12927 5 4 92 0
Tue Jan 26 22:40:04 BRST 2010
procs -----------memory---------- ---swap-- -----io---- -system-- ----cpu----
r b swpd free buff cache si so bi bo in cs us sy id wa
0 3 848 132472 0 6694660 0 0 27 175 0 7 3 3 94 1
1 0 848 130124 0 6696516 0 0 8 471 16539 8827 6 5 77 13
2 0 848 129036 0 6699156 0 0 416 49 17002 12905 5 5 89 1
1 0 848 126896 0 6701412 0 0 160 0 16989 13153 5 5 90 0
1 0 848 123872 0 6703244 0 0 128 0 17080 12789 5 5 90 0
0 0 848 121588 0 6706256 0 0 256 4953 17106 12993 5 5 91 0
1 0 848 118260 0 6708940 0 0 0 25 16877 11248 5 5 90 0
1 2 848 139564 0 6685816 0 0 408 750 17361 12234 6 5 87 3
2 0 848 136772 0 6688196 0 0 232 0 16753 14234 5 5 88 2
2 0 848 134384 0 6690276 0 0 64 0 16590 12374 5 5 90 0
1 1 848 133068 0 6692176 0 0 520 5570 16556 11330 5 4 85 6
