* Re: [PATCH] tcp: fix ICMP-RTO war
@ 2010-01-27 13:56 Denys Fedoryshchenko
2010-01-29 12:13 ` Damian Lukowski
0 siblings, 1 reply; 16+ messages in thread
From: Denys Fedoryshchenko @ 2010-01-27 13:56 UTC (permalink / raw)
To: Ilpo Järvinen, Netdev, Damian Lukowski, David Miller
On Wednesday 27 January 2010 14:36:18 you wrote:
> Unless they are for a different connection? We might have to print sk (%p)
> in all those printouts to be sure which maps to which. If a peer becomes
> unreachable, it may well have multiple connections open (this was a
> proxy, iirc?).
>
Ok i will try to do that today.
Most probably different connections, on this proxy i have 10-15k established
connections at peak time.
Also about estimating rtt, maybe there is something wrong in idea. Just what
will happen if ip visible for proxy have multiple people behind? It can be
small router for hotspot and 10-20 people behind it, some with very large
rtt, some with very small.
And some of them getting disconnected (out of range from wireless, for
example), and thats most probably why host unreachable sent... at same time
proxy have established and running tcp connections with other people on same
router (means for proxy same ip).
Sorry, again to Ilpo Järvinen, by default i have reply, instead of reply all.
^ permalink raw reply [flat|nested] 16+ messages in thread
* Re: [PATCH] tcp: fix ICMP-RTO war
2010-01-27 13:56 [PATCH] tcp: fix ICMP-RTO war Denys Fedoryshchenko
@ 2010-01-29 12:13 ` Damian Lukowski
2010-01-29 15:15 ` Denys Fedoryshchenko
0 siblings, 1 reply; 16+ messages in thread
From: Damian Lukowski @ 2010-01-29 12:13 UTC (permalink / raw)
To: Denys Fedoryshchenko; +Cc: Ilpo Järvinen, Netdev, David Miller
Denys Fedoryshchenko schrieb:
> On Wednesday 27 January 2010 14:36:18 you wrote:
>> Unless they are for a different connection? We might have to print sk (%p)
>> in all those printouts to be sure which maps to which. If a peer becomes
>> unreachable, it may well have multiple connections open (this was a
>> proxy, iirc?).
>>
> Ok i will try to do that today.
>
> Most probably different connections, on this proxy i have 10-15k established
> connections at peak time.
In total, there are probably multiple sockets involved, but for the pattern
I mentioned, I doubt that. The pattern is all over the place; look at another
sample:
> [ 1497.679255] rto: 200 (0 >> 3 + 0, 21) time: 1197679 sent: 1197679 pen: 1 1198079 rem: 200
> [ 1497.679356] rto: 120000 (18111 >> 3 + 2633, 7) time: 1197679 sent: 1195423 pen: 1 1315423 rem: 117744
> [ 1501.113786] rto: 200 (0 >> 3 + 0, 24) time: 1201113 sent: 1200679 pen: 1 1203879 rem: 0
> [ 1501.116064] rto: 120000 (17704 >> 3 + 4426, 8) time: 1201116 sent: 1198638 pen: 1 1318638 rem: 117522
> [ 1501.116216] rto: 200 (0 >> 3 + 0, 24) time: 1201116 sent: 1201113 pen: 1 1201513 rem: 197
> [ 1504.165953] rto: 200 (0 >> 3 + 0, 27) time: 1204165 sent: 1204113 pen: 1 1207313 rem: 148
> [ 1504.168151] rto: 200 (0 >> 3 + 0, 26) time: 1204168 sent: 1204113 pen: 1 1204313 rem: 145
> [ 1504.168327] rto: 200 (0 >> 3 + 0, 25) time: 1204168 sent: 1204113 pen: 1 1204313 rem: 145
> [ 1507.280096] rto: 200 (0 >> 3 + 0, 28) time: 1207280 sent: 1207113 pen: 1 1210313 rem: 33
> [ 1507.280255] rto: 200 (0 >> 3 + 0, 27) time: 1207280 sent: 1207113 pen: 1 1207313 rem: 33
> [ 1510.974574] rto: 200 (0 >> 3 + 0, 30) time: 1210974 sent: 1210113 pen: 1 1213313 rem: 0
> [ 1510.974766] rto: 200 (0 >> 3 + 0, 30) time: 1210974 sent: 1210974 pen: 1 1211374 rem: 200
> [ 1514.436214] rto: 200 (0 >> 3 + 0, 33) time: 1214436 sent: 1213974 pen: 1 1217174 rem: 0
> [ 1514.436378] rto: 200 (0 >> 3 + 0, 33) time: 1214436 sent: 1214436 pen: 1 1214836 rem: 200
> [ 1514.436525] rto: 200 (0 >> 3 + 0, 32) time: 1214436 sent: 1214436 pen: 1 1214636 rem: 200
> [ 1517.516537] rto: 200 (0 >> 3 + 0, 35) time: 1217516 sent: 1217436 pen: 1 1220636 rem: 120
> [ 1517.520724] rto: 200 (0 >> 3 + 0, 34) time: 1217520 sent: 1217436 pen: 1 1217636 rem: 116
> [ 1517.520919] rto: 200 (0 >> 3 + 0, 33) time: 1217520 sent: 1217436 pen: 1 1217636 rem: 116
> [ 1520.580000] rto: 200 (0 >> 3 + 0, 36) time: 1220579 sent: 1220436 pen: 1 1223636 rem: 57
> [ 1520.580165] rto: 200 (0 >> 3 + 0, 35) time: 1220580 sent: 1220436 pen: 1 1220637 rem: 56
> [ 1520.580744] rto: 200 (0 >> 3 + 0, 34) time: 1220580 sent: 1220436 pen: 1 1220636 rem: 56
The two 120000ms RTOs are a different socket, but the rest is one socket,
I believe. There is the sequence (N+2, N+1, N) for backoff, followed by
3 seconds silence, which I assume, are used for regular RTO retransmissions,
and then again a burst of ICMPs.
The three seconds are enough to fire backed-off retransmissions at
t+0.2, t+0.6, t+1.4 and t+3.0. There is a slight deviation of this pattern
when rem becomes 0.
This pattern is too perfect to be triggered by different sockets, I think.
But we will see, when Denys submits new test outputs.
>
> Also about estimating rtt, maybe there is something wrong in idea. Just what
> will happen if ip visible for proxy have multiple people behind? It can be
> small router for hotspot and 10-20 people behind it, some with very large
> rtt, some with very small.
>
> And some of them getting disconnected (out of range from wireless, for
> example), and thats most probably why host unreachable sent... at same time
> proxy have established and running tcp connections with other people on same
> router (means for proxy same ip).
Sockets are identified on a (src-ip, src-port)::(dst-ip, dst-port) quadruple basis,
so RTT calculation usually is independent even for same ip-pairs, unless
with TCB interdependence. But I don't know if that is implemented and/or enabled
by default.
Regards
Damian
> Sorry, again to Ilpo Järvinen, by default i have reply, instead of reply all.
^ permalink raw reply [flat|nested] 16+ messages in thread
* Re: [PATCH] tcp: fix ICMP-RTO war
2010-01-29 12:13 ` Damian Lukowski
@ 2010-01-29 15:15 ` Denys Fedoryshchenko
2010-01-29 21:45 ` Damian Lukowski
0 siblings, 1 reply; 16+ messages in thread
From: Denys Fedoryshchenko @ 2010-01-29 15:15 UTC (permalink / raw)
To: Damian Lukowski; +Cc: Ilpo Järvinen, Netdev, David Miller
On Friday 29 January 2010 14:13:18 Damian Lukowski wrote:
> Denys Fedoryshchenko schrieb:
> > On Wednesday 27 January 2010 14:36:18 you wrote:
> >> Unless they are for a different connection? We might have to print sk
> >> (%p) in all those printouts to be sure which maps to which. If a peer
> >> becomes unreachable, it may well have multiple connections open (this
> >> was a proxy, iirc?).
> >
> > Ok i will try to do that today.
> >
> > Most probably different connections, on this proxy i have 10-15k
> > established connections at peak time.
http://www.nuclearcat.com/files/report1.txt
http://www.nuclearcat.com/files/report2.txt
Here with %p and sk.
^ permalink raw reply [flat|nested] 16+ messages in thread
* Re: [PATCH] tcp: fix ICMP-RTO war
2010-01-29 15:15 ` Denys Fedoryshchenko
@ 2010-01-29 21:45 ` Damian Lukowski
2010-01-30 13:35 ` Denys Fedoryshchenko
0 siblings, 1 reply; 16+ messages in thread
From: Damian Lukowski @ 2010-01-29 21:45 UTC (permalink / raw)
To: Denys Fedoryshchenko; +Cc: Ilpo Järvinen, Netdev, David Miller
Denys Fedoryshchenko schrieb:
> On Friday 29 January 2010 14:13:18 Damian Lukowski wrote:
>> Denys Fedoryshchenko schrieb:
>>> On Wednesday 27 January 2010 14:36:18 you wrote:
>>>> Unless they are for a different connection? We might have to print sk
>>>> (%p) in all those printouts to be sure which maps to which. If a peer
>>>> becomes unreachable, it may well have multiple connections open (this
>>>> was a proxy, iirc?).
>>> Ok i will try to do that today.
>>>
>>> Most probably different connections, on this proxy i have 10-15k
>>> established connections at peak time.
> http://www.nuclearcat.com/files/report1.txt
> http://www.nuclearcat.com/files/report2.txt
>
> Here with %p and sk.
Ok, thanks for testing.
So it is ec0f3440 causing the trouble. Are there still objections
on the lower bound check in __tcp_set_rto()? Well, I will submit
an updated patch and you can make comments there.
Regards
Damian
^ permalink raw reply [flat|nested] 16+ messages in thread
* Re: [PATCH] tcp: fix ICMP-RTO war
2010-01-29 21:45 ` Damian Lukowski
@ 2010-01-30 13:35 ` Denys Fedoryshchenko
2010-01-30 13:56 ` Damian Lukowski
0 siblings, 1 reply; 16+ messages in thread
From: Denys Fedoryshchenko @ 2010-01-30 13:35 UTC (permalink / raw)
To: Damian Lukowski; +Cc: Ilpo Järvinen, Netdev, David Miller
On Friday 29 January 2010 23:45:35 Damian Lukowski wrote:
> Denys Fedoryshchenko schrieb:
> > On Friday 29 January 2010 14:13:18 Damian Lukowski wrote:
> >> Denys Fedoryshchenko schrieb:
> >>> On Wednesday 27 January 2010 14:36:18 you wrote:
> >>>> Unless they are for a different connection? We might have to print sk
> >>>> (%p) in all those printouts to be sure which maps to which. If a peer
> >>>> becomes unreachable, it may well have multiple connections open (this
> >>>> was a proxy, iirc?).
> >>>
> >>> Ok i will try to do that today.
> >>>
> >>> Most probably different connections, on this proxy i have 10-15k
> >>> established connections at peak time.
> >
> > http://www.nuclearcat.com/files/report1.txt
> > http://www.nuclearcat.com/files/report2.txt
> >
> > Here with %p and sk.
>
> Ok, thanks for testing.
> So it is ec0f3440 causing the trouble. Are there still objections
> on the lower bound check in __tcp_set_rto()? Well, I will submit
> an updated patch and you can make comments there.
There is another sk also. I can catch for more time - there is many different
pointers to sk appearing (but not in same time, it is rare case even with my
thousands of connections).
^ permalink raw reply [flat|nested] 16+ messages in thread
* Re: [PATCH] tcp: fix ICMP-RTO war
2010-01-30 13:35 ` Denys Fedoryshchenko
@ 2010-01-30 13:56 ` Damian Lukowski
2010-02-07 10:28 ` Denys Fedoryshchenko
0 siblings, 1 reply; 16+ messages in thread
From: Damian Lukowski @ 2010-01-30 13:56 UTC (permalink / raw)
To: Denys Fedoryshchenko; +Cc: Ilpo Järvinen, Netdev, David Miller
> On Friday 29 January 2010 23:45:35 Damian Lukowski wrote:
>> Denys Fedoryshchenko schrieb:
>> > On Friday 29 January 2010 14:13:18 Damian Lukowski wrote:
>> >> Denys Fedoryshchenko schrieb:
>> >>> On Wednesday 27 January 2010 14:36:18 you wrote:
>> >>>> Unless they are for a different connection? We might have to print
>> sk
>> >>>> (%p) in all those printouts to be sure which maps to which. If a
>> peer
>> >>>> becomes unreachable, it may well have multiple connections open
>> (this
>> >>>> was a proxy, iirc?).
>> >>>
>> >>> Ok i will try to do that today.
>> >>>
>> >>> Most probably different connections, on this proxy i have 10-15k
>> >>> established connections at peak time.
>> >
>> > http://www.nuclearcat.com/files/report1.txt
>> > http://www.nuclearcat.com/files/report2.txt
>> >
>> > Here with %p and sk.
>>
>> Ok, thanks for testing.
>> So it is ec0f3440 causing the trouble. Are there still objections
>> on the lower bound check in __tcp_set_rto()? Well, I will submit
>> an updated patch and you can make comments there.
> There is another sk also. I can catch for more time - there is many
> different
> pointers to sk appearing (but not in same time, it is rare case even
> with my thousands of connections).
Hmm, I shouldn't have posted so late yesterday, as I forgot to CC
you and the others when submitting the patch, amongst the grammar error. :/
Can you test the patch in
http://marc.info/?l=linux-netdev&m=126480336216898
please?
Damian
^ permalink raw reply [flat|nested] 16+ messages in thread
* Re: [PATCH] tcp: fix ICMP-RTO war
2010-01-30 13:56 ` Damian Lukowski
@ 2010-02-07 10:28 ` Denys Fedoryshchenko
0 siblings, 0 replies; 16+ messages in thread
From: Denys Fedoryshchenko @ 2010-02-07 10:28 UTC (permalink / raw)
To: Damian Lukowski; +Cc: Ilpo Järvinen, Netdev, David Miller
On Saturday 30 January 2010 15:56:37 Damian Lukowski wrote:
> > On Friday 29 January 2010 23:45:35 Damian Lukowski wrote:
> >> Denys Fedoryshchenko schrieb:
> >> > On Friday 29 January 2010 14:13:18 Damian Lukowski wrote:
> >> >> Denys Fedoryshchenko schrieb:
> >> >>> On Wednesday 27 January 2010 14:36:18 you wrote:
> >> >>>> Unless they are for a different connection? We might have to print
> >>
> >> sk
> >>
> >> >>>> (%p) in all those printouts to be sure which maps to which. If a
> >>
> >> peer
> >>
> >> >>>> becomes unreachable, it may well have multiple connections open
> >>
> >> (this
> >>
> >> >>>> was a proxy, iirc?).
> >> >>>
> >> >>> Ok i will try to do that today.
> >> >>>
> >> >>> Most probably different connections, on this proxy i have 10-15k
> >> >>> established connections at peak time.
> >> >
> >> > http://www.nuclearcat.com/files/report1.txt
> >> > http://www.nuclearcat.com/files/report2.txt
> >> >
> >> > Here with %p and sk.
> >>
> >> Ok, thanks for testing.
> >> So it is ec0f3440 causing the trouble. Are there still objections
> >> on the lower bound check in __tcp_set_rto()? Well, I will submit
> >> an updated patch and you can make comments there.
> >
> > There is another sk also. I can catch for more time - there is many
> > different
> > pointers to sk appearing (but not in same time, it is rare case even
> > with my thousands of connections).
>
> Hmm, I shouldn't have posted so late yesterday, as I forgot to CC
> you and the others when submitting the patch, amongst the grammar error. :/
> Can you test the patch in
> http://marc.info/?l=linux-netdev&m=126480336216898
> please?
>
> Damian
>
Seems no more lower bound violation.
Thanks a lot!
^ permalink raw reply [flat|nested] 16+ messages in thread
* Re: [PATCH] tcp: fix ICMP-RTO war
2010-01-27 12:41 ` Ilpo Järvinen
@ 2010-01-27 14:14 ` Alexey Kuznetsov
0 siblings, 0 replies; 16+ messages in thread
From: Alexey Kuznetsov @ 2010-01-27 14:14 UTC (permalink / raw)
To: Ilpo J?rvinen; +Cc: David Miller, damian, denys, Netdev
Hello!
> I went through some history, it seems that this comment about the lower
> bound originates from Alexey [1]:
Yes, I even remember why it was done.
Actual comment starts with "If rtt variance happened to be less 50msec...".
It was observed that sometimes due to high burstiness of ACKs
(found originally when linux commuinitected to solaris tcp stack,
which issued huge burst of acks each 50msec. I think he data can be found
in netdev archives), rtt deviation tends to collapse to 0 during such burst,
rto was calculated as plain rtt and obviously we falled to retransmit.
So, the algorithm was repaired. First, to avoid glitches in the future
mdev was clamped to 50ms (rttvar, contribution to rto, is 200msec).
That's what the comment is about.
Second, Linux used to sample rtt each ack, not each rtt (which is technically
main source of the problem). Instead of decreasing sampling rate
I used different sampling rates for growing and dropping rtt:
it grows with rate of arriving acks and drops each rtt i.e. rto grows
quickly, but drops slowly.
Alexey
^ permalink raw reply [flat|nested] 16+ messages in thread
* Re: [PATCH] tcp: fix ICMP-RTO war
2010-01-26 7:45 ` David Miller
@ 2010-01-27 12:41 ` Ilpo Järvinen
2010-01-27 14:14 ` Alexey Kuznetsov
0 siblings, 1 reply; 16+ messages in thread
From: Ilpo Järvinen @ 2010-01-27 12:41 UTC (permalink / raw)
To: David Miller; +Cc: damian, denys, Netdev, Alexey Kuznetsov
On Mon, 25 Jan 2010, David Miller wrote:
> From: Damian Lukowski <damian@tvk.rwth-aachen.de>
> Date: Mon, 25 Jan 2010 16:07:43 +0100
>
> > @@ -530,7 +530,11 @@ static inline void tcp_bound_rto(const struct sock *sk)
> >
> > static inline u32 __tcp_set_rto(const struct tcp_sock *tp)
> > {
> > - return (tp->srtt >> 3) + tp->rttvar;
> > + u32 rto = (tp->srtt >> 3) + tp->rttvar;
> > + if (unlikely(rto < TCP_RTO_MIN))
> > + return TCP_RTO_MIN;
> > + else
> > + return rto;
> > }
>
> The min RTO is now a runtime variable, TCP_RTO_MIN is merely the
> default, so we should use tcp_rto_min() for obtaining that value.
>
> And if we make this change, we might want to delete the comment in
> tcp_set_rto() which claims:
>
> /* NOTE: clamping at TCP_RTO_MIN is not required, current algo
> * guarantees that rto is higher.
> */
> tcp_bound_rto(sk);
>
> And we have shown here at least one case where that is not true.
> :-)
I went through some history, it seems that this comment about the lower
bound originates from Alexey [1]:
commit 893e1302654a9bcdc0e7d9ac95159657a8f5e0e8
Author: davem <davem>
Date: Wed Dec 13 04:10:12 2000 +0000
Fix numerous RTO bugs.
Withdraw CWR when DSACKs are seen.
Do not allow recvmsg on unbound socket, it is
senseless.
All from Alexey.
> I've looked at Denys's traces and your analysis, and I still
> can't figure out who the true culprit is that lets us get into
> such a state that RTO is evaluated so low...
--
i.
[1] http://git.kernel.org/?p=linux/kernel/git/davem/netdev-vger-cvs.git;a=commit;h=893e1302654a9bcdc0e7d9ac95159657a8f5e0e8
^ permalink raw reply [flat|nested] 16+ messages in thread
* Re: [PATCH] tcp: fix ICMP-RTO war
2010-01-25 12:12 ` Damian Lukowski
@ 2010-01-27 12:36 ` Ilpo Järvinen
0 siblings, 0 replies; 16+ messages in thread
From: Ilpo Järvinen @ 2010-01-27 12:36 UTC (permalink / raw)
To: Damian Lukowski
Cc: Denys Fedoryshchenko, Netdev, David Miller, Alexey Kuznetsov
On Mon, 25 Jan 2010, Damian Lukowski wrote:
> considering Denys' latest tests, I think we should bound
> at TCP_RTO_MIN inside __tcp_set_rto().
> Look at the following piece:
> > [ 604.193389] rto: 200 (0 >> 3 + 0, 32) time: 304193 sent: 304091 pen: 1 307291 rem: 98
> > [ 604.193518] lower bound violation: 0 code 1 sk_state 1
> > [ 604.193589] rto: 200 (0 >> 3 + 0, 31) time: 304193 sent: 304091 pen: 1 304291 rem: 98
> > [ 604.193706] lower bound violation: 0 code 1 sk_state 1
> > [ 604.193776] rto: 200 (0 >> 3 + 0, 30) time: 304193 sent: 304091 pen: 1 304291 rem: 98
> > [ 607.341327] lower bound violation: 0 code 1 sk_state 1
> > [ 607.341412] rto: 200 (0 >> 3 + 0, 33) time: 307341 sent: 307091 pen: 1 310291 rem: 0
>
> We have a burst of three incoming ICMPs, not triggering retransmissions because
> of rem > 0. Nevertheless, there is an increase of icsk_backoff by four
> within 3100ms, with no ICMPs in between.
> For me, this is explainable by the broken mdev/rtt issue together with
> bursty ICMP replies.
Unless they are for a different connection? We might have to print sk (%p)
in all those printouts to be sure which maps to which. If a peer becomes
unreachable, it may well have multiple connections open (this was a
proxy, iirc?).
--
i.
^ permalink raw reply [flat|nested] 16+ messages in thread
* Re: [PATCH] tcp: fix ICMP-RTO war
2010-01-25 15:07 ` Damian Lukowski
@ 2010-01-26 7:45 ` David Miller
2010-01-27 12:41 ` Ilpo Järvinen
0 siblings, 1 reply; 16+ messages in thread
From: David Miller @ 2010-01-26 7:45 UTC (permalink / raw)
To: damian; +Cc: denys, ilpo.jarvinen, netdev
From: Damian Lukowski <damian@tvk.rwth-aachen.de>
Date: Mon, 25 Jan 2010 16:07:43 +0100
> @@ -530,7 +530,11 @@ static inline void tcp_bound_rto(const struct sock *sk)
>
> static inline u32 __tcp_set_rto(const struct tcp_sock *tp)
> {
> - return (tp->srtt >> 3) + tp->rttvar;
> + u32 rto = (tp->srtt >> 3) + tp->rttvar;
> + if (unlikely(rto < TCP_RTO_MIN))
> + return TCP_RTO_MIN;
> + else
> + return rto;
> }
The min RTO is now a runtime variable, TCP_RTO_MIN is merely the
default, so we should use tcp_rto_min() for obtaining that value.
And if we make this change, we might want to delete the comment in
tcp_set_rto() which claims:
/* NOTE: clamping at TCP_RTO_MIN is not required, current algo
* guarantees that rto is higher.
*/
tcp_bound_rto(sk);
And we have shown here at least one case where that is not true.
:-)
I've looked at Denys's traces and your analysis, and I still
can't figure out who the true culprit is that lets us get into
such a state that RTO is evaluated so low...
^ permalink raw reply [flat|nested] 16+ messages in thread
* Re: [PATCH] tcp: fix ICMP-RTO war
2010-01-23 22:45 ` Denys Fedoryshchenko
@ 2010-01-25 15:07 ` Damian Lukowski
2010-01-26 7:45 ` David Miller
0 siblings, 1 reply; 16+ messages in thread
From: Damian Lukowski @ 2010-01-25 15:07 UTC (permalink / raw)
To: Denys Fedoryshchenko; +Cc: Ilpo Järvinen, Netdev, David Miller
Denys Fedoryshchenko schrieb:
>> Cool, thanks for testing.
>>
>> Dave, please send into stable too (besides net-2.6). If we want less strict
>> state check we can continue playing with that in net-next, IMHO.
>>
> Maybe better to wait. Sad news, got messages after while (before they was
> appearing almost immediately on such load).
>
> [ ... ]
Hi Denys,
could you test the following patch, please?
Damian
diff --git a/include/net/tcp.h b/include/net/tcp.h
index 34f5cc2..ec2fc91 100644
--- a/include/net/tcp.h
+++ b/include/net/tcp.h
@@ -530,7 +530,11 @@ static inline void tcp_bound_rto(const struct sock *sk)
static inline u32 __tcp_set_rto(const struct tcp_sock *tp)
{
- return (tp->srtt >> 3) + tp->rttvar;
+ u32 rto = (tp->srtt >> 3) + tp->rttvar;
+ if (unlikely(rto < TCP_RTO_MIN))
+ return TCP_RTO_MIN;
+ else
+ return rto;
}
static inline void __tcp_fast_path_on(struct tcp_sock *tp, u32 snd_wnd)
^ permalink raw reply related [flat|nested] 16+ messages in thread
* Re: [PATCH] tcp: fix ICMP-RTO war
2010-01-23 22:34 ` [PATCH] tcp: fix ICMP-RTO war Ilpo Järvinen
2010-01-23 22:45 ` Denys Fedoryshchenko
2010-01-23 23:28 ` Denys Fedoryshchenko
@ 2010-01-25 12:12 ` Damian Lukowski
2010-01-27 12:36 ` Ilpo Järvinen
2 siblings, 1 reply; 16+ messages in thread
From: Damian Lukowski @ 2010-01-25 12:12 UTC (permalink / raw)
To: Ilpo Järvinen; +Cc: Denys Fedoryshchenko, Netdev, David Miller
Hi,
considering Denys' latest tests, I think we should bound
at TCP_RTO_MIN inside __tcp_set_rto().
Look at the following piece:
> [ 604.193389] rto: 200 (0 >> 3 + 0, 32) time: 304193 sent: 304091 pen: 1 307291 rem: 98
> [ 604.193518] lower bound violation: 0 code 1 sk_state 1
> [ 604.193589] rto: 200 (0 >> 3 + 0, 31) time: 304193 sent: 304091 pen: 1 304291 rem: 98
> [ 604.193706] lower bound violation: 0 code 1 sk_state 1
> [ 604.193776] rto: 200 (0 >> 3 + 0, 30) time: 304193 sent: 304091 pen: 1 304291 rem: 98
> [ 607.341327] lower bound violation: 0 code 1 sk_state 1
> [ 607.341412] rto: 200 (0 >> 3 + 0, 33) time: 307341 sent: 307091 pen: 1 310291 rem: 0
We have a burst of three incoming ICMPs, not triggering retransmissions because
of rem > 0. Nevertheless, there is an increase of icsk_backoff by four
within 3100ms, with no ICMPs in between.
For me, this is explainable by the broken mdev/rtt issue together with
bursty ICMP replies.
- At t=0, RTT is at 0.2 seconds when connectivity breaks
- At t=3, TCP has emitted 4 eponentially backed-off retransmits,
and icsk_rto is at 3.2s.
- At t=3+eps, three of four ICMPs arrive in one burst.
- Due to broken mdev, rto is reset to 0.2s inside tcp_v4_err(),
independent of icsk_backoff.
Damian
> Restored Damian cc, please keep them.
>
> On Sat, 23 Jan 2010, Denys Fedoryshchenko wrote:
>> On Tuesday 19 January 2010 13:17:51 you wrote:
>>> On Tue, 19 Jan 2010, Denys Fedoryshchenko wrote:
>>>> On Tuesday 19 January 2010 11:10:12 you wrote:
>>>>> Hi,
>>>>> thank you for testing. So srtt and rttvar is zero in any of those
>>>>> cases. Ilpo, it is a bug in tcp_rtt_estimator then, I suppose?
>>>>>
>>>>> There is also a code comment in tcp_input.c, saying:
>>>>>> * NOTE: clamping at TCP_RTO_MIN is not required, current algo
>>>>>> * guarantees that rto is higher.
>>>>> So we either fix tcp_rtt_estimator or simply clamp at TCP_RTO_MIN?
>>>>>
>>>>> Damian
>>>>>
>>>>>> On Monday 11 January 2010 15:02:34 you wrote:
>>>>>>> On Sat, 26 Dec 2009, Denys Fedoryshchenko wrote:
>>>>>>>> Few more dumps. I notice:
>>>>>>>> 1)Ack always equal 1
>>>>>>>> 2)It is usually first segment of data sent (?)
>>>>>>>>
>>>>>>>> Maybe some value not initialised properly?
>>>>>>> Can you see if the RTO lower bound is violated (I added some
>>>>>>> printing of vars there too already now if it turns out to be
>>>>>>> something):
>>>>>>>
>>>>>>> diff --git a/net/ipv4/tcp_ipv4.c b/net/ipv4/tcp_ipv4.c
>>>>>>> index 65b8ebf..d84469f 100644
>>>>>>> --- a/net/ipv4/tcp_ipv4.c
>>>>>>> +++ b/net/ipv4/tcp_ipv4.c
>>>> As i see in code it is rounding RTO to minimum value.
>>>> It fixes my problem seems.
>>>>
>>>> Btw just a bit about my environment - wireless networks (sometimes
>>>> lossy!) with low speed (128-512Kbps) customers working over pppoe. Maybe
>>>> it will give a tip why rtt value is too low.
>>> What I find most strange in it is the fact that when it triggers for the
>>> first time, the srtt and mdev are zero, not some value in between 0 and
>>> 200ms. Therefore I suspect that this case might be something that we've
>>> overlooked where srtt/mdev are not valid at all.
>>>
>>> Maybe the patch below helps...
>>>
>> Seems after this patch (and debug patch with warnings) my dmesg is clean.
>
> Cool, thanks for testing.
>
> Dave, please send into stable too (besides net-2.6). If we want less strict
> state check we can continue playing with that in net-next, IMHO.
>
^ permalink raw reply [flat|nested] 16+ messages in thread
* Re: [PATCH] tcp: fix ICMP-RTO war
2010-01-23 22:34 ` [PATCH] tcp: fix ICMP-RTO war Ilpo Järvinen
2010-01-23 22:45 ` Denys Fedoryshchenko
@ 2010-01-23 23:28 ` Denys Fedoryshchenko
2010-01-25 12:12 ` Damian Lukowski
2 siblings, 0 replies; 16+ messages in thread
From: Denys Fedoryshchenko @ 2010-01-23 23:28 UTC (permalink / raw)
To: Ilpo Järvinen; +Cc: Damian Lukowski, Netdev, David Miller
On Sunday 24 January 2010 00:34:43 Ilpo Järvinen wrote:
> Restored Damian cc, please keep them.
>
> On Sat, 23 Jan 2010, Denys Fedoryshchenko wrote:
> > On Tuesday 19 January 2010 13:17:51 you wrote:
> > > On Tue, 19 Jan 2010, Denys Fedoryshchenko wrote:
> > > > On Tuesday 19 January 2010 11:10:12 you wrote:
> > > > > Hi,
> > > > > thank you for testing. So srtt and rttvar is zero in any of those
> > > > > cases. Ilpo, it is a bug in tcp_rtt_estimator then, I suppose?
> > > > >
> > > > > There is also a code comment in tcp_input.c, saying:
> > > > > > * NOTE: clamping at TCP_RTO_MIN is not required, current algo
> > > > > > * guarantees that rto is higher.
> > > > >
> > > > > So we either fix tcp_rtt_estimator or simply clamp at TCP_RTO_MIN?
> > > > >
> > > > > Damian
> > > > >
> > > > > > On Monday 11 January 2010 15:02:34 you wrote:
> > > > > >> On Sat, 26 Dec 2009, Denys Fedoryshchenko wrote:
> > > > > >>> Few more dumps. I notice:
> > > > > >>> 1)Ack always equal 1
> > > > > >>> 2)It is usually first segment of data sent (?)
> > > > > >>>
> > > > > >>> Maybe some value not initialised properly?
> > > > > >>
> > > > > >> Can you see if the RTO lower bound is violated (I added some
> > > > > >> printing of vars there too already now if it turns out to be
> > > > > >> something):
> > > > > >>
> > > > > >> diff --git a/net/ipv4/tcp_ipv4.c b/net/ipv4/tcp_ipv4.c
> > > > > >> index 65b8ebf..d84469f 100644
> > > > > >> --- a/net/ipv4/tcp_ipv4.c
> > > > > >> +++ b/net/ipv4/tcp_ipv4.c
> > > >
> > > > As i see in code it is rounding RTO to minimum value.
> > > > It fixes my problem seems.
> > > >
> > > > Btw just a bit about my environment - wireless networks (sometimes
> > > > lossy!) with low speed (128-512Kbps) customers working over pppoe.
> > > > Maybe it will give a tip why rtt value is too low.
> > >
> > > What I find most strange in it is the fact that when it triggers for
> > > the first time, the srtt and mdev are zero, not some value in between 0
> > > and 200ms. Therefore I suspect that this case might be something that
> > > we've overlooked where srtt/mdev are not valid at all.
> > >
> > > Maybe the patch below helps...
> >
> > Seems after this patch (and debug patch with warnings) my dmesg is clean.
>
> Cool, thanks for testing.
>
> Dave, please send into stable too (besides net-2.6). If we want less strict
> state check we can continue playing with that in net-next, IMHO.
>
I extend a little bit debug to
printk("lower bound violation: %u code %u sk_state %u\n", icsk->icsk_rto,
code,sk->sk_state);
Here is result:
[ 566.990065] lower bound violation: 0 code 1 sk_state 1
[ 566.990111] rto: 200 (0 >> 3 + 0, 5) time: 266990 sent: 263925 pen: 1
383925 rem: 0
[ 570.058555] lower bound violation: 0 code 1 sk_state 1
[ 570.058603] rto: 200 (0 >> 3 + 0, 8) time: 270058 sent: 269790 pen: 1
272990 rem: 0
[ 570.058660] lower bound violation: 0 code 1 sk_state 1
[ 570.058698] rto: 200 (0 >> 3 + 0, 8) time: 270058 sent: 270058 pen: 1
270458 rem: 200
[ 573.122550] lower bound violation: 0 code 1 sk_state 1
[ 573.122626] rto: 200 (0 >> 3 + 0, 11) time: 273122 sent: 273058 pen: 1
276258 rem: 136
[ 573.122745] lower bound violation: 0 code 1 sk_state 1
[ 573.122815] rto: 200 (0 >> 3 + 0, 10) time: 273122 sent: 273058 pen: 1
273258 rem: 136
[ 573.122931] lower bound violation: 0 code 1 sk_state 1
[ 573.123001] rto: 200 (0 >> 3 + 0, 9) time: 273122 sent: 273058 pen: 1
273258 rem: 136
[ 576.304338] lower bound violation: 0 code 1 sk_state 1
[ 576.304423] rto: 200 (0 >> 3 + 0, 12) time: 276304 sent: 276059 pen: 1
279259 rem: 0
[ 576.326167] lower bound violation: 0 code 1 sk_state 1
[ 576.326251] rto: 200 (0 >> 3 + 0, 12) time: 276326 sent: 276304 pen: 1
276704 rem: 178
[ 579.360343] lower bound violation: 0 code 1 sk_state 1
[ 579.360427] rto: 200 (0 >> 3 + 0, 15) time: 279360 sent: 279304 pen: 1
282504 rem: 144
[ 582.566834] lower bound violation: 0 code 1 sk_state 1
[ 582.566919] rto: 200 (0 >> 3 + 0, 18) time: 282566 sent: 282304 pen: 1
285504 rem: 0
[ 582.567085] lower bound violation: 0 code 1 sk_state 1
[ 582.567162] rto: 200 (0 >> 3 + 0, 18) time: 282567 sent: 282567 pen: 1
282967 rem: 200
[ 582.567280] lower bound violation: 0 code 1 sk_state 1
[ 582.567351] rto: 200 (0 >> 3 + 0, 17) time: 282567 sent: 282567 pen: 1
282767 rem: 200
[ 585.649877] lower bound violation: 0 code 1 sk_state 1
[ 585.649962] rto: 200 (0 >> 3 + 0, 20) time: 285649 sent: 285567 pen: 1
288767 rem: 118
[ 585.650097] lower bound violation: 0 code 1 sk_state 1
[ 585.650178] rto: 200 (0 >> 3 + 0, 19) time: 285650 sent: 285567 pen: 1
285768 rem: 117
[ 588.836754] lower bound violation: 0 code 1 sk_state 1
[ 588.836845] rto: 200 (0 >> 3 + 0, 22) time: 288836 sent: 288567 pen: 1
291767 rem: 0
[ 588.836970] lower bound violation: 0 code 1 sk_state 1
[ 588.837042] rto: 200 (0 >> 3 + 0, 22) time: 288836 sent: 288836 pen: 1
289236 rem: 200
[ 591.902908] lower bound violation: 0 code 1 sk_state 1
[ 591.902996] rto: 200 (0 >> 3 + 0, 25) time: 291902 sent: 291837 pen: 1
295037 rem: 135
[ 591.903129] lower bound violation: 0 code 1 sk_state 1
[ 591.903205] rto: 200 (0 >> 3 + 0, 24) time: 291903 sent: 291837 pen: 1
292038 rem: 134
[ 595.091391] lower bound violation: 0 code 1 sk_state 1
[ 595.091477] rto: 200 (0 >> 3 + 0, 27) time: 295091 sent: 294837 pen: 1
298037 rem: 0
[ 595.091627] lower bound violation: 0 code 1 sk_state 1
[ 595.091702] rto: 200 (0 >> 3 + 0, 27) time: 295091 sent: 295091 pen: 1
295491 rem: 200
[ 598.141828] lower bound violation: 0 code 1 sk_state 1
[ 598.141913] rto: 200 (0 >> 3 + 0, 30) time: 298141 sent: 298091 pen: 1
301291 rem: 150
[ 598.142043] lower bound violation: 0 code 1 sk_state 1
[ 598.142114] rto: 200 (0 >> 3 + 0, 29) time: 298141 sent: 298091 pen: 1
298291 rem: 150
[ 598.142252] lower bound violation: 0 code 1 sk_state 1
[ 598.142344] rto: 200 (0 >> 3 + 0, 28) time: 298142 sent: 298091 pen: 1
298291 rem: 149
[ 601.146649] lower bound violation: 0 code 1 sk_state 1
[ 601.146734] rto: 200 (0 >> 3 + 0, 31) time: 301146 sent: 301091 pen: 1
304291 rem: 145
[ 601.178998] lower bound violation: 0 code 1 sk_state 1
[ 601.179090] rto: 200 (0 >> 3 + 0, 30) time: 301179 sent: 301091 pen: 1
301291 rem: 112
[ 601.179227] lower bound violation: 0 code 1 sk_state 1
[ 601.179298] rto: 200 (0 >> 3 + 0, 29) time: 301179 sent: 301091 pen: 1
301291 rem: 112
[ 604.193304] lower bound violation: 0 code 1 sk_state 1
[ 604.193389] rto: 200 (0 >> 3 + 0, 32) time: 304193 sent: 304091 pen: 1
307291 rem: 98
[ 604.193518] lower bound violation: 0 code 1 sk_state 1
[ 604.193589] rto: 200 (0 >> 3 + 0, 31) time: 304193 sent: 304091 pen: 1
304291 rem: 98
[ 604.193706] lower bound violation: 0 code 1 sk_state 1
[ 604.193776] rto: 200 (0 >> 3 + 0, 30) time: 304193 sent: 304091 pen: 1
304291 rem: 98
[ 607.341327] lower bound violation: 0 code 1 sk_state 1
[ 607.341412] rto: 200 (0 >> 3 + 0, 33) time: 307341 sent: 307091 pen: 1
310291 rem: 0
[ 607.370345] lower bound violation: 0 code 1 sk_state 1
[ 607.370427] rto: 200 (0 >> 3 + 0, 33) time: 307370 sent: 307341 pen: 1
307741 rem: 171
[ 607.370657] lower bound violation: 0 code 1 sk_state 1
[ 607.370730] rto: 200 (0 >> 3 + 0, 32) time: 307370 sent: 307341 pen: 1
307541 rem: 171
[ 610.437075] lower bound violation: 0 code 1 sk_state 1
[ 610.437161] rto: 200 (0 >> 3 + 0, 35) time: 310437 sent: 310341 pen: 1
313541 rem: 104
[ 610.437302] lower bound violation: 0 code 1 sk_state 1
[ 610.437374] rto: 200 (0 >> 3 + 0, 34) time: 310437 sent: 310341 pen: 1
310541 rem: 104
[ 610.437497] lower bound violation: 0 code 1 sk_state 1
[ 610.437567] rto: 200 (0 >> 3 + 0, 33) time: 310437 sent: 310341 pen: 1
310541 rem: 104
[ 613.429680] lower bound violation: 0 code 1 sk_state 1
[ 613.429770] rto: 200 (0 >> 3 + 0, 36) time: 313429 sent: 313341 pen: 1
316541 rem: 112
[ 613.429899] lower bound violation: 0 code 1 sk_state 1
[ 613.429970] rto: 200 (0 >> 3 + 0, 35) time: 313429 sent: 313341 pen: 1
313541 rem: 112
[ 613.430087] lower bound violation: 0 code 1 sk_state 1
[ 613.430164] rto: 200 (0 >> 3 + 0, 34) time: 313430 sent: 313341 pen: 1
313542 rem: 111
[ 616.644279] lower bound violation: 0 code 1 sk_state 1
[ 616.644364] rto: 200 (0 >> 3 + 0, 37) time: 316644 sent: 316341 pen: 1
319541 rem: 0
[ 616.644500] lower bound violation: 0 code 1 sk_state 1
[ 616.644572] rto: 200 (0 >> 3 + 0, 37) time: 316644 sent: 316644 pen: 1
317044 rem: 200
[ 616.644689] lower bound violation: 0 code 1 sk_state 1
[ 616.644760] rto: 200 (0 >> 3 + 0, 36) time: 316644 sent: 316644 pen: 1
316844 rem: 200
[ 617.028542] rto: 120000 (788 >> 3 + 266, 10) time: 317028 sent: 313993 pen:
1 433993 rem: 116965
[ 619.711969] lower bound violation: 0 code 1 sk_state 1
[ 619.712050] rto: 200 (0 >> 3 + 0, 39) time: 319712 sent: 319644 pen: 1
322844 rem: 132
[ 619.712169] lower bound violation: 0 code 1 sk_state 1
[ 619.712240] rto: 200 (0 >> 3 + 0, 38) time: 319712 sent: 319644 pen: 1
319844 rem: 132
[ 619.712364] lower bound violation: 0 code 1 sk_state 1
[ 619.712435] rto: 200 (0 >> 3 + 0, 37) time: 319712 sent: 319644 pen: 1
319844 rem: 132
[ 622.908447] lower bound violation: 0 code 1 sk_state 1
[ 622.908531] rto: 200 (0 >> 3 + 0, 40) time: 322908 sent: 322644 pen: 1
325844 rem: 0
[ 622.909274] lower bound violation: 0 code 1 sk_state 1
[ 622.909347] rto: 200 (0 >> 3 + 0, 40) time: 322909 sent: 322908 pen: 1
323308 rem: 199
[ 622.914930] lower bound violation: 0 code 1 sk_state 1
[ 622.915014] rto: 200 (0 >> 3 + 0, 39) time: 322914 sent: 322908 pen: 1
323108 rem: 194
[ 625.975145] lower bound violation: 0 code 1 sk_state 1
[ 625.975232] rto: 200 (0 >> 3 + 0, 42) time: 325975 sent: 325909 pen: 1
329109 rem: 134
[ 625.975350] lower bound violation: 0 code 1 sk_state 1
[ 625.975422] rto: 200 (0 >> 3 + 0, 41) time: 325975 sent: 325909 pen: 1
326109 rem: 134
[ 625.975538] lower bound violation: 0 code 1 sk_state 1
[ 625.975609] rto: 200 (0 >> 3 + 0, 40) time: 325975 sent: 325909 pen: 1
326109 rem: 134
[ 629.187199] lower bound violation: 0 code 1 sk_state 1
[ 629.187286] rto: 200 (0 >> 3 + 0, 43) time: 329187 sent: 328909 pen: 1
332109 rem: 0
[ 629.187454] lower bound violation: 0 code 1 sk_state 1
[ 629.187529] rto: 200 (0 >> 3 + 0, 43) time: 329187 sent: 329187 pen: 1
329587 rem: 200
[ 629.187646] lower bound violation: 0 code 1 sk_state 1
[ 629.187717] rto: 200 (0 >> 3 + 0, 42) time: 329187 sent: 329187 pen: 1
329387 rem: 200
[ 632.232822] lower bound violation: 0 code 1 sk_state 1
[ 632.232907] rto: 200 (0 >> 3 + 0, 45) time: 332232 sent: 332187 pen: 1
335387 rem: 155
[ 632.250500] lower bound violation: 0 code 1 sk_state 1
[ 632.250585] rto: 200 (0 >> 3 + 0, 44) time: 332250 sent: 332187 pen: 1
332388 rem: 137
[ 632.250714] lower bound violation: 0 code 1 sk_state 1
[ 632.250785] rto: 200 (0 >> 3 + 0, 43) time: 332250 sent: 332187 pen: 1
332387 rem: 137
[ 635.247889] lower bound violation: 0 code 1 sk_state 1
[ 635.247974] rto: 200 (0 >> 3 + 0, 46) time: 335247 sent: 335187 pen: 1
338387 rem: 140
[ 635.248416] lower bound violation: 0 code 1 sk_state 1
[ 635.248490] rto: 200 (0 >> 3 + 0, 45) time: 335248 sent: 335187 pen: 1
335387 rem: 139
[ 635.251046] lower bound violation: 0 code 1 sk_state 1
[ 635.251122] rto: 200 (0 >> 3 + 0, 44) time: 335251 sent: 335187 pen: 1
335387 rem: 136
[ 638.434799] lower bound violation: 0 code 1 sk_state 1
[ 638.434883] rto: 200 (0 >> 3 + 0, 47) time: 338434 sent: 338187 pen: 1
341387 rem: 0
[ 638.435018] lower bound violation: 0 code 1 sk_state 1
[ 638.435090] rto: 200 (0 >> 3 + 0, 47) time: 338435 sent: 338434 pen: 1
338834 rem: 199
[ 638.435215] lower bound violation: 0 code 1 sk_state 1
[ 638.435993] rto: 200 (0 >> 3 + 0, 46) time: 338435 sent: 338434 pen: 1
338634 rem: 199
[ 641.501303] lower bound violation: 0 code 1 sk_state 1
[ 641.501380] rto: 200 (0 >> 3 + 0, 49) time: 341501 sent: 341435 pen: 1
344635 rem: 134
[ 641.501501] lower bound violation: 0 code 1 sk_state 1
[ 641.501571] rto: 200 (0 >> 3 + 0, 48) time: 341501 sent: 341435 pen: 1
341635 rem: 134
[ 641.501687] lower bound violation: 0 code 1 sk_state 1
[ 641.501757] rto: 200 (0 >> 3 + 0, 47) time: 341501 sent: 341435 pen: 1
341635 rem: 134
[ 644.518586] lower bound violation: 0 code 1 sk_state 1
[ 644.518672] rto: 200 (0 >> 3 + 0, 50) time: 344518 sent: 344435 pen: 1
347635 rem: 117
[ 644.518849] lower bound violation: 0 code 1 sk_state 1
[ 644.518930] rto: 200 (0 >> 3 + 0, 49) time: 344518 sent: 344435 pen: 1
344635 rem: 117
[ 644.519071] lower bound violation: 0 code 1 sk_state 1
[ 644.519158] rto: 200 (0 >> 3 + 0, 48) time: 344519 sent: 344435 pen: 1
344636 rem: 116
[ 647.725632] lower bound violation: 0 code 1 sk_state 1
[ 647.725717] rto: 200 (0 >> 3 + 0, 51) time: 347725 sent: 347435 pen: 1
350635 rem: 0
[ 647.725850] lower bound violation: 0 code 1 sk_state 1
[ 647.725921] rto: 200 (0 >> 3 + 0, 51) time: 347725 sent: 347725 pen: 1
348125 rem: 200
[ 647.729343] lower bound violation: 0 code 1 sk_state 1
[ 647.729417] rto: 200 (0 >> 3 + 0, 50) time: 347729 sent: 347725 pen: 1
347925 rem: 196
[ 650.787543] lower bound violation: 0 code 1 sk_state 1
[ 650.787619] rto: 200 (0 >> 3 + 0, 53) time: 350787 sent: 350726 pen: 1
353926 rem: 139
[ 650.798651] lower bound violation: 0 code 1 sk_state 1
[ 650.798749] rto: 200 (0 >> 3 + 0, 52) time: 350798 sent: 350726 pen: 1
350926 rem: 128
[ 650.805039] lower bound violation: 0 code 1 sk_state 1
[ 650.805123] rto: 200 (0 >> 3 + 0, 51) time: 350805 sent: 350726 pen: 1
350926 rem: 121
[ 653.801712] lower bound violation: 0 code 1 sk_state 1
[ 653.801788] rto: 200 (0 >> 3 + 0, 54) time: 353801 sent: 353726 pen: 1
356926 rem: 125
[ 653.801937] lower bound violation: 0 code 1 sk_state 1
[ 653.802023] rto: 200 (0 >> 3 + 0, 53) time: 353802 sent: 353726 pen: 1
353926 rem: 124
[ 653.802475] lower bound violation: 0 code 1 sk_state 1
[ 653.802548] rto: 200 (0 >> 3 + 0, 52) time: 353802 sent: 353726 pen: 1
353926 rem: 124
[ 656.985567] lower bound violation: 0 code 1 sk_state 1
[ 656.985653] rto: 200 (0 >> 3 + 0, 55) time: 356985 sent: 356726 pen: 1
359926 rem: 0
[ 656.986226] lower bound violation: 0 code 1 sk_state 1
[ 656.986299] rto: 200 (0 >> 3 + 0, 55) time: 356986 sent: 356985 pen: 1
357385 rem: 199
[ 656.986416] lower bound violation: 0 code 1 sk_state 1
[ 656.986486] rto: 200 (0 >> 3 + 0, 54) time: 356986 sent: 356985 pen: 1
357185 rem: 199
[ 660.042091] lower bound violation: 0 code 1 sk_state 1
[ 660.042168] rto: 200 (0 >> 3 + 0, 57) time: 360042 sent: 359985 pen: 1
363185 rem: 143
[ 660.042286] lower bound violation: 0 code 1 sk_state 1
[ 660.042357] rto: 200 (0 >> 3 + 0, 56) time: 360042 sent: 359985 pen: 1
360185 rem: 143
[ 660.076230] lower bound violation: 0 code 1 sk_state 1
[ 660.076315] rto: 200 (0 >> 3 + 0, 55) time: 360076 sent: 359985 pen: 1
360185 rem: 109
[ 663.256655] lower bound violation: 0 code 1 sk_state 1
[ 663.256731] rto: 200 (0 >> 3 + 0, 58) time: 363256 sent: 362985 pen: 1
366185 rem: 0
[ 663.341934] lower bound violation: 0 code 1 sk_state 1
[ 663.342010] rto: 200 (0 >> 3 + 0, 58) time: 363341 sent: 363256 pen: 1
363656 rem: 115
[ 663.428067] lower bound violation: 0 code 1 sk_state 1
[ 663.428156] rto: 200 (0 >> 3 + 0, 57) time: 363428 sent: 363256 pen: 1
363457 rem: 28
[ 666.308896] lower bound violation: 0 code 1 sk_state 1
[ 666.308980] rto: 200 (0 >> 3 + 0, 60) time: 366308 sent: 366256 pen: 1
369456 rem: 148
[ 666.309110] lower bound violation: 0 code 1 sk_state 1
[ 666.309186] rto: 200 (0 >> 3 + 0, 59) time: 366309 sent: 366256 pen: 1
366457 rem: 147
[ 666.309315] lower bound violation: 0 code 1 sk_state 1
[ 666.309386] rto: 200 (0 >> 3 + 0, 58) time: 366309 sent: 366256 pen: 1
366456 rem: 147
[ 669.519782] lower bound violation: 0 code 1 sk_state 1
[ 669.519866] rto: 200 (0 >> 3 + 0, 61) time: 369519 sent: 369256 pen: 1
372456 rem: 0
[ 669.520011] lower bound violation: 0 code 1 sk_state 1
[ 669.520083] rto: 200 (0 >> 3 + 0, 61) time: 369520 sent: 369519 pen: 1
369919 rem: 199
[ 669.520206] lower bound violation: 0 code 1 sk_state 1
[ 669.520286] rto: 200 (0 >> 3 + 0, 60) time: 369520 sent: 369519 pen: 1
369719 rem: 199
[ 672.641672] lower bound violation: 0 code 1 sk_state 1
[ 672.641756] rto: 200 (0 >> 3 + 0, 63) time: 372641 sent: 372519 pen: 1
375719 rem: 78
[ 672.642325] lower bound violation: 0 code 1 sk_state 1
[ 672.642407] rto: 200 (0 >> 3 + 0, 62) time: 372642 sent: 372519 pen: 1
372719 rem: 77
[ 672.642524] lower bound violation: 0 code 1 sk_state 1
[ 672.642596] rto: 200 (0 >> 3 + 0, 61) time: 372642 sent: 372519 pen: 1
372719 rem: 77
[ 675.789437] lower bound violation: 0 code 1 sk_state 1
[ 675.789522] rto: 200 (0 >> 3 + 0, 64) time: 375789 sent: 375519 pen: 1
378719 rem: 0
[ 675.789657] lower bound violation: 0 code 1 sk_state 1
[ 675.789727] rto: 200 (0 >> 3 + 0, 64) time: 375789 sent: 375789 pen: 1
376189 rem: 200
[ 675.813158] lower bound violation: 0 code 1 sk_state 1
[ 675.813242] rto: 200 (0 >> 3 + 0, 63) time: 375813 sent: 375789 pen: 1
375989 rem: 176
[ 678.902625] lower bound violation: 0 code 1 sk_state 1
[ 678.902689] rto: 200 (0 >> 3 + 0, 66) time: 378902 sent: 378789 pen: 1
381989 rem: 87
[ 678.902808] lower bound violation: 0 code 1 sk_state 1
[ 678.902869] rto: 200 (0 >> 3 + 0, 65) time: 378902 sent: 378789 pen: 1
378989 rem: 87
[ 678.902967] lower bound violation: 0 code 1 sk_state 1
[ 678.903027] rto: 200 (0 >> 3 + 0, 64) time: 378903 sent: 378789 pen: 1
378989 rem: 86
[ 682.086610] lower bound violation: 0 code 1 sk_state 1
[ 682.086673] rto: 200 (0 >> 3 + 0, 67) time: 382086 sent: 381789 pen: 1
384989 rem: 0
[ 682.086823] lower bound violation: 0 code 1 sk_state 1
[ 682.086885] rto: 200 (0 >> 3 + 0, 67) time: 382086 sent: 382086 pen: 1
382486 rem: 200
[ 682.086988] lower bound violation: 0 code 1 sk_state 1
[ 682.087042] rto: 200 (0 >> 3 + 0, 66) time: 382087 sent: 382086 pen: 1
382286 rem: 199
[ 685.177400] lower bound violation: 0 code 1 sk_state 1
[ 685.177460] rto: 200 (0 >> 3 + 0, 69) time: 385177 sent: 385086 pen: 1
388286 rem: 109
[ 685.177566] lower bound violation: 0 code 1 sk_state 1
[ 685.177630] rto: 200 (0 >> 3 + 0, 68) time: 385177 sent: 385086 pen: 1
385286 rem: 109
[ 685.177734] lower bound violation: 0 code 1 sk_state 1
[ 685.177790] rto: 200 (0 >> 3 + 0, 67) time: 385177 sent: 385086 pen: 1
385286 rem: 109
[ 688.339503] lower bound violation: 0 code 1 sk_state 1
[ 688.339565] rto: 200 (0 >> 3 + 0, 70) time: 388339 sent: 388086 pen: 1
391286 rem: 0
[ 688.339684] lower bound violation: 0 code 1 sk_state 1
[ 688.339745] rto: 200 (0 >> 3 + 0, 70) time: 388339 sent: 388339 pen: 1
388739 rem: 200
[ 688.339844] lower bound violation: 0 code 1 sk_state 1
[ 688.339896] rto: 200 (0 >> 3 + 0, 69) time: 388339 sent: 388339 pen: 1
388539 rem: 200
[ 691.925180] lower bound violation: 0 code 1 sk_state 1
[ 691.925242] rto: 200 (0 >> 3 + 0, 72) time: 391925 sent: 391339 pen: 1
394539 rem: 0
[ 692.010074] lower bound violation: 0 code 1 sk_state 1
[ 692.010131] rto: 200 (0 >> 3 + 0, 72) time: 392009 sent: 391925 pen: 1
392325 rem: 116
[ 692.096188] lower bound violation: 0 code 1 sk_state 1
[ 692.096254] rto: 200 (0 >> 3 + 0, 71) time: 392096 sent: 391925 pen: 1
392126 rem: 29
[ 694.474680] lower bound violation: 0 code 1 sk_state 1
[ 694.474742] rto: 200 (0 >> 3 + 0, 73) time: 394474 sent: 393325 pen: 1
394925 rem: 0
[ 694.475751] lower bound violation: 0 code 1 sk_state 1
[ 694.475810] rto: 200 (0 >> 3 + 0, 73) time: 394475 sent: 394474 pen: 1
394874 rem: 199
[ 694.475918] lower bound violation: 0 code 1 sk_state 1
[ 694.475975] rto: 200 (0 >> 3 + 0, 72) time: 394475 sent: 394474 pen: 1
394674 rem: 199
[ 697.572814] lower bound violation: 0 code 1 sk_state 1
[ 697.572877] rto: 200 (0 >> 3 + 0, 75) time: 397572 sent: 397474 pen: 1
400674 rem: 102
[ 697.572986] lower bound violation: 0 code 1 sk_state 1
[ 697.573052] rto: 200 (0 >> 3 + 0, 74) time: 397573 sent: 397474 pen: 1
397674 rem: 101
[ 697.573159] lower bound violation: 0 code 1 sk_state 1
[ 697.573211] rto: 200 (0 >> 3 + 0, 73) time: 397573 sent: 397474 pen: 1
397674 rem: 101
[ 700.728072] lower bound violation: 0 code 1 sk_state 1
[ 700.728135] rto: 200 (0 >> 3 + 0, 76) time: 400728 sent: 400474 pen: 1
403674 rem: 0
[ 700.734010] lower bound violation: 0 code 1 sk_state 1
[ 700.734079] rto: 200 (0 >> 3 + 0, 76) time: 400734 sent: 400728 pen: 1
401128 rem: 194
[ 700.734191] lower bound violation: 0 code 1 sk_state 1
[ 700.734944] rto: 200 (0 >> 3 + 0, 75) time: 400734 sent: 400728 pen: 1
400928 rem: 194
[ 703.779459] lower bound violation: 0 code 1 sk_state 1
[ 703.779521] rto: 200 (0 >> 3 + 0, 78) time: 403779 sent: 403729 pen: 1
406929 rem: 150
[ 703.779628] lower bound violation: 0 code 1 sk_state 1
[ 703.779680] rto: 200 (0 >> 3 + 0, 77) time: 403779 sent: 403729 pen: 1
403929 rem: 150
[ 703.779797] lower bound violation: 0 code 1 sk_state 1
[ 703.779850] rto: 200 (0 >> 3 + 0, 76) time: 403779 sent: 403729 pen: 1
403929 rem: 150
^ permalink raw reply [flat|nested] 16+ messages in thread
* Re: [PATCH] tcp: fix ICMP-RTO war
2010-01-23 22:34 ` [PATCH] tcp: fix ICMP-RTO war Ilpo Järvinen
@ 2010-01-23 22:45 ` Denys Fedoryshchenko
2010-01-25 15:07 ` Damian Lukowski
2010-01-23 23:28 ` Denys Fedoryshchenko
2010-01-25 12:12 ` Damian Lukowski
2 siblings, 1 reply; 16+ messages in thread
From: Denys Fedoryshchenko @ 2010-01-23 22:45 UTC (permalink / raw)
To: Ilpo Järvinen; +Cc: Damian Lukowski, Netdev, David Miller
>
> Cool, thanks for testing.
>
> Dave, please send into stable too (besides net-2.6). If we want less strict
> state check we can continue playing with that in net-next, IMHO.
>
Maybe better to wait. Sad news, got messages after while (before they was
appearing almost immediately on such load).
Here it is
[ 1253.821745] rto: 26496 (58 >> 3 + 200, 7) time: 953821 sent: 953283 pen: 1
1006275 rem: 25958
[ 1278.791976] rto: 75264 (398 >> 3 + 245, 8) time: 978791 sent: 977749 pen: 1
1097749 rem: 74222
[ 1299.537823] lower bound violation: 0
[ 1299.537846] rto: 200 (0 >> 3 + 0, 1) time: 999537 sent: 997699 pen: 1
1009699 rem: 0
[ 1324.022158] rto: 11072 (2512 >> 3 + 1070, 3) time: 1024022 sent: 1023672
pen: 1 1045816 rem: 10722
[ 1333.112517] rto: 52992 (58 >> 3 + 200, 8) time: 1033112 sent: 1032771 pen:
1 1138755 rem: 52651
[ 1336.152839] rto: 11072 (2512 >> 3 + 1070, 3) time: 1036152 sent: 1034744
pen: 1 1056888 rem: 9664
[ 1426.219799] lower bound violation: 0
[ 1426.219858] rto: 200 (0 >> 3 + 0, 1) time: 1126219 sent: 1125040 pen: 1
1137040 rem: 0
[ 1429.235911] lower bound violation: 0
[ 1429.235964] rto: 200 (0 >> 3 + 0, 4) time: 1129235 sent: 1129019 pen: 1
1132219 rem: 0
[ 1432.279829] lower bound violation: 0
[ 1432.279887] rto: 200 (0 >> 3 + 0, 7) time: 1132279 sent: 1132036 pen: 1
1135236 rem: 0
[ 1435.311008] lower bound violation: 0
[ 1435.311068] rto: 200 (0 >> 3 + 0, 10) time: 1135311 sent: 1135079 pen: 1
1138279 rem: 0
[ 1479.029269] lower bound violation: 0
[ 1479.029323] rto: 200 (0 >> 3 + 0, 9) time: 1179029 sent: 1174129 pen: 1
1294129 rem: 0
[ 1483.851712] lower bound violation: 0
[ 1483.851773] rto: 200 (0 >> 3 + 0, 12) time: 1183851 sent: 1181829 pen: 1
1185029 rem: 0
[ 1483.851878] lower bound violation: 0
[ 1483.851926] rto: 200 (0 >> 3 + 0, 12) time: 1183851 sent: 1183851 pen: 1
1184251 rem: 200
[ 1483.852034] lower bound violation: 0
[ 1483.852082] rto: 200 (0 >> 3 + 0, 11) time: 1183852 sent: 1183851 pen: 1
1184052 rem: 199
[ 1486.934283] lower bound violation: 0
[ 1486.934339] rto: 200 (0 >> 3 + 0, 14) time: 1186934 sent: 1186851 pen: 1
1190051 rem: 117
[ 1486.934500] lower bound violation: 0
[ 1486.934554] rto: 200 (0 >> 3 + 0, 13) time: 1186934 sent: 1186851 pen: 1
1187051 rem: 117
[ 1490.170941] lower bound violation: 0
[ 1490.171000] rto: 200 (0 >> 3 + 0, 16) time: 1190170 sent: 1189851 pen: 1
1193051 rem: 0
[ 1490.171126] lower bound violation: 0
[ 1490.171189] rto: 200 (0 >> 3 + 0, 16) time: 1190171 sent: 1190171 pen: 1
1190571 rem: 200
[ 1490.171312] lower bound violation: 0
[ 1490.171361] rto: 200 (0 >> 3 + 0, 15) time: 1190171 sent: 1190171 pen: 1
1190371 rem: 200
[ 1494.052047] lower bound violation: 0
[ 1494.052105] rto: 200 (0 >> 3 + 0, 18) time: 1194052 sent: 1193171 pen: 1
1196371 rem: 0
[ 1494.052704] lower bound violation: 0
[ 1494.052760] rto: 200 (0 >> 3 + 0, 18) time: 1194052 sent: 1194052 pen: 1
1194452 rem: 200
[ 1497.678945] lower bound violation: 0
[ 1497.679004] rto: 200 (0 >> 3 + 0, 21) time: 1197678 sent: 1197052 pen: 1
1200252 rem: 0
[ 1497.679205] lower bound violation: 0
[ 1497.679255] rto: 200 (0 >> 3 + 0, 21) time: 1197679 sent: 1197679 pen: 1
1198079 rem: 200
[ 1497.679356] rto: 120000 (18111 >> 3 + 2633, 7) time: 1197679 sent: 1195423
pen: 1 1315423 rem: 117744
[ 1501.113733] lower bound violation: 0
[ 1501.113786] rto: 200 (0 >> 3 + 0, 24) time: 1201113 sent: 1200679 pen: 1
1203879 rem: 0
[ 1501.116064] rto: 120000 (17704 >> 3 + 4426, 8) time: 1201116 sent: 1198638
pen: 1 1318638 rem: 117522
[ 1501.116168] lower bound violation: 0
[ 1501.116216] rto: 200 (0 >> 3 + 0, 24) time: 1201116 sent: 1201113 pen: 1
1201513 rem: 197
[ 1504.165893] lower bound violation: 0
[ 1504.165953] rto: 200 (0 >> 3 + 0, 27) time: 1204165 sent: 1204113 pen: 1
1207313 rem: 148
[ 1504.168090] lower bound violation: 0
[ 1504.168151] rto: 200 (0 >> 3 + 0, 26) time: 1204168 sent: 1204113 pen: 1
1204313 rem: 145
[ 1504.168272] lower bound violation: 0
[ 1504.168327] rto: 200 (0 >> 3 + 0, 25) time: 1204168 sent: 1204113 pen: 1
1204313 rem: 145
[ 1507.280037] lower bound violation: 0
[ 1507.280096] rto: 200 (0 >> 3 + 0, 28) time: 1207280 sent: 1207113 pen: 1
1210313 rem: 33
[ 1507.280207] lower bound violation: 0
[ 1507.280255] rto: 200 (0 >> 3 + 0, 27) time: 1207280 sent: 1207113 pen: 1
1207313 rem: 33
[ 1510.974508] lower bound violation: 0
[ 1510.974574] rto: 200 (0 >> 3 + 0, 30) time: 1210974 sent: 1210113 pen: 1
1213313 rem: 0
[ 1510.974716] lower bound violation: 0
[ 1510.974766] rto: 200 (0 >> 3 + 0, 30) time: 1210974 sent: 1210974 pen: 1
1211374 rem: 200
[ 1514.436146] lower bound violation: 0
[ 1514.436214] rto: 200 (0 >> 3 + 0, 33) time: 1214436 sent: 1213974 pen: 1
1217174 rem: 0
[ 1514.436329] lower bound violation: 0
[ 1514.436378] rto: 200 (0 >> 3 + 0, 33) time: 1214436 sent: 1214436 pen: 1
1214836 rem: 200
[ 1514.436477] lower bound violation: 0
[ 1514.436525] rto: 200 (0 >> 3 + 0, 32) time: 1214436 sent: 1214436 pen: 1
1214636 rem: 200
[ 1517.516478] lower bound violation: 0
[ 1517.516537] rto: 200 (0 >> 3 + 0, 35) time: 1217516 sent: 1217436 pen: 1
1220636 rem: 120
[ 1517.520665] lower bound violation: 0
[ 1517.520724] rto: 200 (0 >> 3 + 0, 34) time: 1217520 sent: 1217436 pen: 1
1217636 rem: 116
[ 1517.520865] lower bound violation: 0
[ 1517.520919] rto: 200 (0 >> 3 + 0, 33) time: 1217520 sent: 1217436 pen: 1
1217636 rem: 116
[ 1520.579941] lower bound violation: 0
[ 1520.580000] rto: 200 (0 >> 3 + 0, 36) time: 1220579 sent: 1220436 pen: 1
1223636 rem: 57
[ 1520.580111] lower bound violation: 0
[ 1520.580165] rto: 200 (0 >> 3 + 0, 35) time: 1220580 sent: 1220436 pen: 1
1220637 rem: 56
[ 1520.580686] lower bound violation: 0
[ 1520.580744] rto: 200 (0 >> 3 + 0, 34) time: 1220580 sent: 1220436 pen: 1
1220636 rem: 56
[ 1523.693352] lower bound violation: 0
[ 1523.693412] rto: 200 (0 >> 3 + 0, 37) time: 1223693 sent: 1223436 pen: 1
1226636 rem: 0
[ 1523.693538] lower bound violation: 0
[ 1523.693588] rto: 200 (0 >> 3 + 0, 37) time: 1223693 sent: 1223693 pen: 1
1224093 rem: 200
[ 1523.693686] lower bound violation: 0
[ 1523.693735] rto: 200 (0 >> 3 + 0, 36) time: 1223693 sent: 1223693 pen: 1
1223893 rem: 200
[ 1526.737059] lower bound violation: 0
[ 1526.737125] rto: 200 (0 >> 3 + 0, 39) time: 1226737 sent: 1226693 pen: 1
1229893 rem: 156
[ 1526.737271] lower bound violation: 0
[ 1526.737323] rto: 200 (0 >> 3 + 0, 38) time: 1226737 sent: 1226693 pen: 1
1226893 rem: 156
[ 1526.737557] lower bound violation: 0
[ 1526.737607] rto: 200 (0 >> 3 + 0, 37) time: 1226737 sent: 1226693 pen: 1
1226893 rem: 156
[ 1529.979070] lower bound violation: 0
[ 1529.979130] rto: 200 (0 >> 3 + 0, 40) time: 1229979 sent: 1229693 pen: 1
1232893 rem: 0
[ 1529.979249] lower bound violation: 0
[ 1529.979304] rto: 200 (0 >> 3 + 0, 40) time: 1229979 sent: 1229979 pen: 1
1230379 rem: 200
[ 1529.979412] lower bound violation: 0
[ 1529.979461] rto: 200 (0 >> 3 + 0, 39) time: 1229979 sent: 1229979 pen: 1
1230179 rem: 200
[ 1533.211875] lower bound violation: 0
[ 1533.211934] rto: 200 (0 >> 3 + 0, 42) time: 1233211 sent: 1232979 pen: 1
1236179 rem: 0
[ 1533.212049] lower bound violation: 0
[ 1533.212098] rto: 200 (0 >> 3 + 0, 42) time: 1233211 sent: 1233211 pen: 1
1233611 rem: 200
[ 1533.212203] lower bound violation: 0
[ 1533.212259] rto: 200 (0 >> 3 + 0, 41) time: 1233212 sent: 1233211 pen: 1
1233412 rem: 199
[ 1536.287558] lower bound violation: 0
[ 1536.287611] rto: 200 (0 >> 3 + 0, 44) time: 1236287 sent: 1236211 pen: 1
1239411 rem: 124
[ 1536.287712] lower bound violation: 0
[ 1536.287760] rto: 200 (0 >> 3 + 0, 43) time: 1236287 sent: 1236211 pen: 1
1236411 rem: 124
[ 1536.291704] lower bound violation: 0
[ 1536.291767] rto: 200 (0 >> 3 + 0, 42) time: 1236291 sent: 1236211 pen: 1
1236411 rem: 120
[ 1539.530596] lower bound violation: 0
[ 1539.530657] rto: 200 (0 >> 3 + 0, 45) time: 1239530 sent: 1239211 pen: 1
1242411 rem: 0
[ 1539.530804] lower bound violation: 0
[ 1539.530862] rto: 200 (0 >> 3 + 0, 45) time: 1239530 sent: 1239530 pen: 1
1239930 rem: 200
[ 1544.020855] lower bound violation: 0
[ 1544.020916] rto: 200 (0 >> 3 + 0, 48) time: 1244020 sent: 1242530 pen: 1
1245730 rem: 0
[ 1544.021022] lower bound violation: 0
[ 1544.021071] rto: 200 (0 >> 3 + 0, 48) time: 1244021 sent: 1244020 pen: 1
1244421 rem: 199
[ 1544.021186] lower bound violation: 0
[ 1544.021243] rto: 200 (0 >> 3 + 0, 47) time: 1244021 sent: 1244020 pen: 1
1244220 rem: 199
[ 1547.214143] lower bound violation: 0
[ 1547.214212] rto: 200 (0 >> 3 + 0, 50) time: 1247214 sent: 1247020 pen: 1
1250220 rem: 6
[ 1547.214330] lower bound violation: 0
[ 1547.214388] rto: 200 (0 >> 3 + 0, 49) time: 1247214 sent: 1247020 pen: 1
1247220 rem: 6
[ 1547.215213] lower bound violation: 0
[ 1547.215269] rto: 200 (0 >> 3 + 0, 48) time: 1247215 sent: 1247020 pen: 1
1247221 rem: 5
[ 1551.820989] lower bound violation: 0
[ 1551.821059] rto: 200 (0 >> 3 + 0, 51) time: 1251821 sent: 1250020 pen: 1
1253220 rem: 0
[ 1551.821211] lower bound violation: 0
[ 1551.821265] rto: 200 (0 >> 3 + 0, 51) time: 1251821 sent: 1251821 pen: 1
1252221 rem: 200
[ 1551.824378] lower bound violation: 0
[ 1551.824437] rto: 200 (0 >> 3 + 0, 50) time: 1251824 sent: 1251821 pen: 1
1252021 rem: 197
[ 1556.833941] lower bound violation: 0
[ 1556.834001] rto: 200 (0 >> 3 + 0, 53) time: 1256833 sent: 1254821 pen: 1
1258021 rem: 0
[ 1556.834120] lower bound violation: 0
[ 1556.834168] rto: 200 (0 >> 3 + 0, 53) time: 1256834 sent: 1256834 pen: 1
1257234 rem: 200
[ 1556.834280] lower bound violation: 0
[ 1556.834335] rto: 200 (0 >> 3 + 0, 52) time: 1256834 sent: 1256834 pen: 1
1257034 rem: 200
[ 1559.862274] lower bound violation: 0
[ 1559.862332] rto: 200 (0 >> 3 + 0, 55) time: 1259862 sent: 1259834 pen: 1
1263034 rem: 172
[ 1559.862439] lower bound violation: 0
[ 1559.862488] rto: 200 (0 >> 3 + 0, 54) time: 1259862 sent: 1259834 pen: 1
1260034 rem: 172
[ 1559.862599] lower bound violation: 0
[ 1559.862653] rto: 200 (0 >> 3 + 0, 53) time: 1259862 sent: 1259834 pen: 1
1260034 rem: 172
[ 1563.299323] lower bound violation: 0
[ 1563.299392] rto: 200 (0 >> 3 + 0, 56) time: 1263299 sent: 1262834 pen: 1
1266034 rem: 0
[ 1563.299544] lower bound violation: 0
[ 1563.299593] rto: 200 (0 >> 3 + 0, 56) time: 1263299 sent: 1263299 pen: 1
1263699 rem: 200
[ 1563.299692] lower bound violation: 0
[ 1563.299740] rto: 200 (0 >> 3 + 0, 55) time: 1263299 sent: 1263299 pen: 1
1263499 rem: 200
[ 1566.413518] lower bound violation: 0
[ 1566.413571] rto: 200 (0 >> 3 + 0, 58) time: 1266413 sent: 1266299 pen: 1
1269499 rem: 86
[ 1566.413689] lower bound violation: 0
[ 1566.413745] rto: 200 (0 >> 3 + 0, 57) time: 1266413 sent: 1266299 pen: 1
1266499 rem: 86
[ 1566.413844] lower bound violation: 0
[ 1566.413892] rto: 200 (0 >> 3 + 0, 56) time: 1266413 sent: 1266299 pen: 1
1266499 rem: 86
[ 1569.443770] lower bound violation: 0
[ 1569.443829] rto: 200 (0 >> 3 + 0, 59) time: 1269443 sent: 1269299 pen: 1
1272499 rem: 56
[ 1569.444010] lower bound violation: 0
[ 1569.444064] rto: 200 (0 >> 3 + 0, 58) time: 1269444 sent: 1269299 pen: 1
1269499 rem: 55
[ 1569.451656] lower bound violation: 0
[ 1569.451714] rto: 200 (0 >> 3 + 0, 57) time: 1269451 sent: 1269299 pen: 1
1269499 rem: 48
[ 1573.751979] lower bound violation: 0
[ 1573.752048] rto: 200 (0 >> 3 + 0, 60) time: 1273752 sent: 1272299 pen: 1
1275499 rem: 0
[ 1573.752172] lower bound violation: 0
[ 1573.752229] rto: 200 (0 >> 3 + 0, 60) time: 1273752 sent: 1273752 pen: 1
1274152 rem: 200
[ 1573.752343] lower bound violation: 0
[ 1573.752392] rto: 200 (0 >> 3 + 0, 59) time: 1273752 sent: 1273752 pen: 1
1273952 rem: 200
[ 1579.041006] lower bound violation: 0
[ 1579.041068] rto: 200 (0 >> 3 + 0, 62) time: 1279041 sent: 1276752 pen: 1
1279952 rem: 0
[ 1579.041177] lower bound violation: 0
[ 1579.041226] rto: 200 (0 >> 3 + 0, 62) time: 1279041 sent: 1279041 pen: 1
1279441 rem: 200
[ 1579.041325] lower bound violation: 0
[ 1579.041373] rto: 200 (0 >> 3 + 0, 61) time: 1279041 sent: 1279041 pen: 1
1279241 rem: 200
[ 1584.072083] lower bound violation: 0
[ 1584.072149] rto: 200 (0 >> 3 + 0, 64) time: 1284072 sent: 1282041 pen: 1
1285241 rem: 0
[ 1587.094402] lower bound violation: 0
[ 1587.094461] rto: 200 (0 >> 3 + 0, 67) time: 1287094 sent: 1286872 pen: 1
1290072 rem: 0
[ 1587.095380] lower bound violation: 0
[ 1587.095442] rto: 200 (0 >> 3 + 0, 67) time: 1287095 sent: 1287094 pen: 1
1287494 rem: 199
[ 1590.118759] lower bound violation: 0
[ 1590.118818] rto: 200 (0 >> 3 + 0, 70) time: 1290118 sent: 1290094 pen: 1
1293294 rem: 176
[ 1590.118931] lower bound violation: 0
[ 1590.118979] rto: 200 (0 >> 3 + 0, 69) time: 1290118 sent: 1290094 pen: 1
1290294 rem: 176
[ 1590.119085] lower bound violation: 0
[ 1590.119142] rto: 200 (0 >> 3 + 0, 68) time: 1290119 sent: 1290094 pen: 1
1290295 rem: 175
[ 1593.342497] lower bound violation: 0
[ 1593.342556] rto: 200 (0 >> 3 + 0, 71) time: 1293342 sent: 1293094 pen: 1
1296294 rem: 0
[ 1593.342675] lower bound violation: 0
[ 1593.342723] rto: 200 (0 >> 3 + 0, 71) time: 1293342 sent: 1293342 pen: 1
1293742 rem: 200
[ 1593.342822] lower bound violation: 0
[ 1593.342870] rto: 200 (0 >> 3 + 0, 70) time: 1293342 sent: 1293342 pen: 1
1293542 rem: 200
[ 1597.517273] lower bound violation: 0
[ 1597.517326] rto: 200 (0 >> 3 + 0, 73) time: 1297517 sent: 1296342 pen: 1
1299542 rem: 0
[ 1597.517433] lower bound violation: 0
[ 1597.517481] rto: 200 (0 >> 3 + 0, 73) time: 1297517 sent: 1297517 pen: 1
1297917 rem: 200
[ 1597.517579] lower bound violation: 0
[ 1597.517627] rto: 200 (0 >> 3 + 0, 72) time: 1297517 sent: 1297517 pen: 1
1297717 rem: 200
[ 1600.931564] lower bound violation: 0
[ 1600.931625] rto: 200 (0 >> 3 + 0, 75) time: 1300931 sent: 1300517 pen: 1
1303717 rem: 0
[ 1600.931743] lower bound violation: 0
[ 1600.931792] rto: 200 (0 >> 3 + 0, 75) time: 1300931 sent: 1300931 pen: 1
1301331 rem: 200
[ 1600.931903] lower bound violation: 0
[ 1600.931954] rto: 200 (0 >> 3 + 0, 74) time: 1300931 sent: 1300931 pen: 1
1301131 rem: 200
[ 1603.939116] lower bound violation: 0
[ 1603.939176] rto: 200 (0 >> 3 + 0, 77) time: 1303939 sent: 1303932 pen: 1
1307132 rem: 193
[ 1603.939289] lower bound violation: 0
[ 1603.939337] rto: 200 (0 >> 3 + 0, 76) time: 1303939 sent: 1303932 pen: 1
1304132 rem: 193
[ 1603.939436] lower bound violation: 0
[ 1603.939484] rto: 200 (0 >> 3 + 0, 75) time: 1303939 sent: 1303932 pen: 1
1304132 rem: 193
[ 1607.414745] lower bound violation: 0
[ 1607.414808] rto: 200 (0 >> 3 + 0, 78) time: 1307414 sent: 1306932 pen: 1
1310132 rem: 0
[ 1607.414956] lower bound violation: 0
[ 1607.415015] rto: 200 (0 >> 3 + 0, 78) time: 1307414 sent: 1307414 pen: 1
1307814 rem: 200
[ 1610.428738] lower bound violation: 0
[ 1610.428797] rto: 200 (0 >> 3 + 0, 81) time: 1310428 sent: 1310414 pen: 1
1313614 rem: 186
[ 1610.428909] lower bound violation: 0
[ 1610.428957] rto: 200 (0 >> 3 + 0, 80) time: 1310428 sent: 1310414 pen: 1
1310614 rem: 186
[ 1610.429061] lower bound violation: 0
[ 1610.429118] rto: 200 (0 >> 3 + 0, 79) time: 1310428 sent: 1310414 pen: 1
1310614 rem: 186
[ 1613.744633] lower bound violation: 0
[ 1613.744696] rto: 200 (0 >> 3 + 0, 82) time: 1313744 sent: 1313415 pen: 1
1316615 rem: 0
[ 1613.745417] lower bound violation: 0
[ 1613.745480] rto: 200 (0 >> 3 + 0, 82) time: 1313745 sent: 1313744 pen: 1
1314144 rem: 199
[ 1617.868468] lower bound violation: 0
[ 1617.868531] rto: 200 (0 >> 3 + 0, 85) time: 1317868 sent: 1316744 pen: 1
1319944 rem: 0
[ 1617.868657] lower bound violation: 0
[ 1617.868716] rto: 200 (0 >> 3 + 0, 85) time: 1317868 sent: 1317868 pen: 1
1318268 rem: 200
[ 1617.868831] rto: 120000 (18111 >> 3 + 2633, 7) time: 1317868 sent: 1315423
pen: 1 1435423 rem: 117555
[ 1621.001005] lower bound violation: 0
[ 1621.001064] rto: 200 (0 >> 3 + 0, 88) time: 1321000 sent: 1320868 pen: 1
1324068 rem: 68
[ 1621.001176] lower bound violation: 0
[ 1621.001225] rto: 200 (0 >> 3 + 0, 87) time: 1321000 sent: 1320868 pen: 1
1321068 rem: 68
[ 1621.002106] rto: 120000 (17704 >> 3 + 4426, 8) time: 1321002 sent: 1318638
pen: 1 1438638 rem: 117636
[ 1624.776425] lower bound violation: 0
[ 1624.776484] rto: 200 (0 >> 3 + 0, 90) time: 1324776 sent: 1323868 pen: 1
1327068 rem: 0
[ 1624.776602] lower bound violation: 0
[ 1624.776651] rto: 200 (0 >> 3 + 0, 90) time: 1324776 sent: 1324776 pen: 1
1325176 rem: 200
[ 1624.776766] lower bound violation: 0
[ 1624.776815] rto: 200 (0 >> 3 + 0, 89) time: 1324776 sent: 1324776 pen: 1
1324976 rem: 200
[ 1628.635107] lower bound violation: 0
[ 1628.635166] rto: 200 (0 >> 3 + 0, 92) time: 1328635 sent: 1327776 pen: 1
1330976 rem: 0
[ 1628.635292] lower bound violation: 0
[ 1628.635340] rto: 200 (0 >> 3 + 0, 92) time: 1328635 sent: 1328635 pen: 1
1329035 rem: 200
[ 1628.636141] lower bound violation: 0
[ 1628.636189] rto: 200 (0 >> 3 + 0, 91) time: 1328636 sent: 1328635 pen: 1
1328836 rem: 199
[ 1632.229674] lower bound violation: 0
[ 1632.229736] rto: 200 (0 >> 3 + 0, 94) time: 1332229 sent: 1331635 pen: 1
1334835 rem: 0
[ 1632.231588] lower bound violation: 0
[ 1632.231645] rto: 200 (0 >> 3 + 0, 94) time: 1332231 sent: 1332229 pen: 1
1332629 rem: 198
[ 1636.335644] lower bound violation: 0
[ 1636.335704] rto: 200 (0 >> 3 + 0, 97) time: 1336335 sent: 1335229 pen: 1
1338429 rem: 0
[ 1636.335821] lower bound violation: 0
[ 1636.335870] rto: 200 (0 >> 3 + 0, 97) time: 1336335 sent: 1336335 pen: 1
1336735 rem: 200
[ 1636.335968] lower bound violation: 0
[ 1636.336015] rto: 200 (0 >> 3 + 0, 96) time: 1336335 sent: 1336335 pen: 1
1336535 rem: 200
[ 1639.557760] lower bound violation: 0
[ 1639.557819] rto: 200 (0 >> 3 + 0, 99) time: 1339557 sent: 1339336 pen: 1
1342536 rem: 0
[ 1639.557937] lower bound violation: 0
[ 1639.557985] rto: 200 (0 >> 3 + 0, 99) time: 1339557 sent: 1339557 pen: 1
1339957 rem: 200
[ 1639.558575] lower bound violation: 0
[ 1639.558631] rto: 200 (0 >> 3 + 0, 98) time: 1339558 sent: 1339557 pen: 1
1339758 rem: 199
[ 1642.786990] lower bound violation: 0
[ 1642.787060] rto: 200 (0 >> 3 + 0, 101) time: 1342787 sent: 1342557 pen: 1
1345757 rem: 0
[ 1642.787238] lower bound violation: 0
[ 1642.787296] rto: 200 (0 >> 3 + 0, 101) time: 1342787 sent: 1342787 pen: 1
1343187 rem: 200
[ 1642.787395] lower bound violation: 0
[ 1642.787444] rto: 200 (0 >> 3 + 0, 100) time: 1342787 sent: 1342787 pen: 1
1342987 rem: 200
[ 1647.154582] lower bound violation: 0
[ 1647.154634] rto: 200 (0 >> 3 + 0, 103) time: 1347154 sent: 1345787 pen: 1
1348987 rem: 0
[ 1647.154744] lower bound violation: 0
[ 1647.154792] rto: 200 (0 >> 3 + 0, 103) time: 1347154 sent: 1347154 pen: 1
1347554 rem: 200
[ 1647.154904] lower bound violation: 0
[ 1647.154952] rto: 200 (0 >> 3 + 0, 102) time: 1347154 sent: 1347154 pen: 1
1347354 rem: 200
[ 1650.574345] lower bound violation: 0
[ 1650.574406] rto: 200 (0 >> 3 + 0, 105) time: 1350574 sent: 1350155 pen: 1
1353355 rem: 0
[ 1650.574532] lower bound violation: 0
[ 1650.574591] rto: 200 (0 >> 3 + 0, 105) time: 1350574 sent: 1350574 pen: 1
1350974 rem: 200
[ 1650.574691] lower bound violation: 0
[ 1650.574739] rto: 200 (0 >> 3 + 0, 104) time: 1350574 sent: 1350574 pen: 1
1350774 rem: 200
[ 1653.629874] lower bound violation: 0
[ 1653.629937] rto: 200 (0 >> 3 + 0, 107) time: 1353629 sent: 1353574 pen: 1
1356774 rem: 145
[ 1653.630037] lower bound violation: 0
[ 1653.630086] rto: 200 (0 >> 3 + 0, 106) time: 1353629 sent: 1353574 pen: 1
1353774 rem: 145
[ 1653.630185] lower bound violation: 0
[ 1653.630233] rto: 200 (0 >> 3 + 0, 105) time: 1353629 sent: 1353574 pen: 1
1353774 rem: 145
[ 1656.859174] lower bound violation: 0
[ 1656.859236] rto: 200 (0 >> 3 + 0, 108) time: 1356859 sent: 1356574 pen: 1
1359774 rem: 0
[ 1656.860594] lower bound violation: 0
[ 1656.860650] rto: 200 (0 >> 3 + 0, 108) time: 1356860 sent: 1356859 pen: 1
1357259 rem: 199
[ 1656.860770] lower bound violation: 0
[ 1656.860818] rto: 200 (0 >> 3 + 0, 107) time: 1356860 sent: 1356859 pen: 1
1357059 rem: 199
[ 1661.395294] lower bound violation: 0
[ 1661.395347] rto: 200 (0 >> 3 + 0, 110) time: 1361395 sent: 1359859 pen: 1
1363059 rem: 0
[ 1661.395716] lower bound violation: 0
[ 1661.395772] rto: 200 (0 >> 3 + 0, 110) time: 1361395 sent: 1361395 pen: 1
1361795 rem: 200
[ 1700.995078] rto: 120000 (2636 >> 3 + 542, 8) time: 1400995 sent: 1397985
pen: 1 1517985 rem: 116990
[ 1730.706641] lower bound violation: 0
[ 1730.706700] rto: 200 (0 >> 3 + 0, 7) time: 1430706 sent: 1429991 pen: 1
1549991 rem: 0
[ 1733.727118] lower bound violation: 0
[ 1733.727186] rto: 200 (0 >> 3 + 0, 10) time: 1433727 sent: 1433506 pen: 1
1436706 rem: 0
[ 1736.737622] lower bound violation: 0
[ 1736.737674] rto: 200 (0 >> 3 + 0, 13) time: 1436737 sent: 1436527 pen: 1
1439727 rem: 0
[ 1739.769166] lower bound violation: 0
[ 1739.769219] rto: 200 (0 >> 3 + 0, 16) time: 1439769 sent: 1439537 pen: 1
1442737 rem: 0
[ 1739.818141] lower bound violation: 0
[ 1739.818197] rto: 200 (0 >> 3 + 0, 16) time: 1439818 sent: 1439769 pen: 1
1440169 rem: 151
[ 1742.779541] lower bound violation: 0
[ 1742.779610] rto: 200 (0 >> 3 + 0, 19) time: 1442779 sent: 1442769 pen: 1
1445969 rem: 190
[ 1742.828450] lower bound violation: 0
[ 1742.828509] rto: 200 (0 >> 3 + 0, 18) time: 1442828 sent: 1442769 pen: 1
1442969 rem: 141
[ 1745.838989] lower bound violation: 0
[ 1745.839059] rto: 200 (0 >> 3 + 0, 21) time: 1445839 sent: 1445769 pen: 1
1448969 rem: 130
[ 1748.849390] lower bound violation: 0
[ 1748.849450] rto: 200 (0 >> 3 + 0, 24) time: 1448849 sent: 1448769 pen: 1
1451969 rem: 120
[ 1751.851312] lower bound violation: 0
[ 1751.851371] rto: 200 (0 >> 3 + 0, 27) time: 1451851 sent: 1451769 pen: 1
1454969 rem: 118
[ 1755.020232] lower bound violation: 0
[ 1755.020294] rto: 200 (0 >> 3 + 0, 30) time: 1455020 sent: 1454769 pen: 1
1457969 rem: 0
[ 1758.032994] lower bound violation: 0
[ 1758.033065] rto: 200 (0 >> 3 + 0, 33) time: 1458032 sent: 1457820 pen: 1
1461020 rem: 0
[ 1761.044708] lower bound violation: 0
[ 1761.044766] rto: 200 (0 >> 3 + 0, 36) time: 1461044 sent: 1460833 pen: 1
1464033 rem: 0
[ 1764.057713] lower bound violation: 0
[ 1764.057773] rto: 200 (0 >> 3 + 0, 39) time: 1464057 sent: 1463844 pen: 1
1467044 rem: 0
[ 1767.081929] lower bound violation: 0
[ 1767.082002] rto: 200 (0 >> 3 + 0, 42) time: 1467081 sent: 1466857 pen: 1
1470057 rem: 0
[ 1770.093869] lower bound violation: 0
[ 1770.093928] rto: 200 (0 >> 3 + 0, 45) time: 1470093 sent: 1469882 pen: 1
1473082 rem: 0
[ 1773.152744] lower bound violation: 0
[ 1773.152796] rto: 200 (0 >> 3 + 0, 48) time: 1473152 sent: 1472893 pen: 1
1476093 rem: 0
[ 1818.986470] rto: 120000 (2636 >> 3 + 542, 8) time: 1518986 sent: 1517985
pen: 1 1637985 rem: 118999
[ 1939.433063] rto: 120000 (2636 >> 3 + 542, 8) time: 1639432 sent: 1637985
pen: 1 1757985 rem: 118553
[ 2127.032954] lower bound violation: 0
[ 2127.033019] rto: 200 (0 >> 3 + 0, 5) time: 1827033 sent: 1824734 pen: 1
1944734 rem: 0
[ 2130.198949] lower bound violation: 0
[ 2130.199008] rto: 200 (0 >> 3 + 0, 8) time: 1830198 sent: 1829833 pen: 1
1833033 rem: 0
[ 2130.199134] lower bound violation: 0
[ 2130.199191] rto: 200 (0 >> 3 + 0, 8) time: 1830199 sent: 1830199 pen: 1
1830599 rem: 200
[ 2130.199289] lower bound violation: 0
[ 2130.199336] rto: 200 (0 >> 3 + 0, 7) time: 1830199 sent: 1830199 pen: 1
1830399 rem: 200
[ 2133.313262] lower bound violation: 0
[ 2133.313321] rto: 200 (0 >> 3 + 0, 10) time: 1833313 sent: 1833199 pen: 1
1836399 rem: 86
[ 2133.313430] lower bound violation: 0
[ 2133.313483] rto: 200 (0 >> 3 + 0, 9) time: 1833313 sent: 1833199 pen: 1
1833399 rem: 86
[ 2136.355135] lower bound violation: 0
[ 2136.355194] rto: 200 (0 >> 3 + 0, 12) time: 1836355 sent: 1836199 pen: 1
1839399 rem: 44
[ 2136.355302] lower bound violation: 0
[ 2136.355355] rto: 200 (0 >> 3 + 0, 11) time: 1836355 sent: 1836199 pen: 1
1836399 rem: 44
[ 2136.355462] lower bound violation: 0
[ 2136.355510] rto: 200 (0 >> 3 + 0, 10) time: 1836355 sent: 1836199 pen: 1
1836399 rem: 44
[ 2139.336730] lower bound violation: 0
[ 2139.336790] rto: 200 (0 >> 3 + 0, 13) time: 1839336 sent: 1839199 pen: 1
1842399 rem: 63
[ 2139.336911] lower bound violation: 0
[ 2139.336960] rto: 200 (0 >> 3 + 0, 12) time: 1839336 sent: 1839199 pen: 1
1839399 rem: 63
[ 2142.603552] lower bound violation: 0
[ 2142.603612] rto: 200 (0 >> 3 + 0, 15) time: 1842603 sent: 1842200 pen: 1
1845400 rem: 0
[ 2142.603729] lower bound violation: 0
[ 2142.603777] rto: 200 (0 >> 3 + 0, 15) time: 1842603 sent: 1842603 pen: 1
1843003 rem: 200
[ 2145.821472] lower bound violation: 0
[ 2145.821533] rto: 200 (0 >> 3 + 0, 18) time: 1845821 sent: 1845603 pen: 1
1848803 rem: 0
[ 2145.821638] lower bound violation: 0
[ 2145.821687] rto: 200 (0 >> 3 + 0, 18) time: 1845821 sent: 1845821 pen: 1
1846221 rem: 200
[ 2149.113311] lower bound violation: 0
[ 2149.113371] rto: 200 (0 >> 3 + 0, 21) time: 1849113 sent: 1848822 pen: 1
1852022 rem: 0
[ 2149.124655] lower bound violation: 0
[ 2149.124717] rto: 200 (0 >> 3 + 0, 21) time: 1849124 sent: 1849113 pen: 1
1849513 rem: 189
[ 2152.214537] lower bound violation: 0
[ 2152.214596] rto: 200 (0 >> 3 + 0, 24) time: 1852214 sent: 1852113 pen: 1
1855313 rem: 99
[ 2152.214836] lower bound violation: 0
[ 2152.214892] rto: 200 (0 >> 3 + 0, 23) time: 1852214 sent: 1852113 pen: 1
1852313 rem: 99
[ 2152.216836] lower bound violation: 0
[ 2152.216892] rto: 200 (0 >> 3 + 0, 22) time: 1852216 sent: 1852113 pen: 1
1852313 rem: 97
[ 2155.212630] lower bound violation: 0
[ 2155.212683] rto: 200 (0 >> 3 + 0, 25) time: 1855212 sent: 1855113 pen: 1
1858313 rem: 101
[ 2155.271403] lower bound violation: 0
[ 2155.271462] rto: 200 (0 >> 3 + 0, 24) time: 1855271 sent: 1855113 pen: 1
1855313 rem: 42
[ 2155.271570] lower bound violation: 0
[ 2155.271624] rto: 200 (0 >> 3 + 0, 23) time: 1855271 sent: 1855113 pen: 1
1855313 rem: 42
[ 2158.247617] lower bound violation: 0
[ 2158.247676] rto: 200 (0 >> 3 + 0, 26) time: 1858247 sent: 1858113 pen: 1
1861313 rem: 66
[ 2158.308891] lower bound violation: 0
[ 2158.308949] rto: 200 (0 >> 3 + 0, 25) time: 1858308 sent: 1858113 pen: 1
1858313 rem: 5
[ 2161.267856] lower bound violation: 0
[ 2161.267918] rto: 200 (0 >> 3 + 0, 28) time: 1861267 sent: 1861114 pen: 1
1864314 rem: 47
[ 2161.268020] lower bound violation: 0
[ 2161.268068] rto: 200 (0 >> 3 + 0, 27) time: 1861268 sent: 1861114 pen: 1
1861315 rem: 46
[ 2161.268283] lower bound violation: 0
[ 2161.268339] rto: 200 (0 >> 3 + 0, 26) time: 1861268 sent: 1861114 pen: 1
1861314 rem: 46
[ 2164.483740] lower bound violation: 0
[ 2164.483799] rto: 200 (0 >> 3 + 0, 29) time: 1864483 sent: 1864114 pen: 1
1867314 rem: 0
[ 2164.485758] lower bound violation: 0
[ 2164.485809] rto: 200 (0 >> 3 + 0, 29) time: 1864485 sent: 1864483 pen: 1
1864883 rem: 198
[ 2460.739324] rto: 7040 (757 >> 3 + 346, 4) time: 2160739 sent: 2160696 pen:
1 2174776 rem: 6997
[ 2477.769916] rto: 120000 (17147 >> 3 + 1705, 6) time: 2177769 sent: 2174642
pen: 1 2294642 rem: 116873
[ 2484.364919] rto: 69440 (3542 >> 3 + 643, 6) time: 2184364 sent: 2182505
pen: 1 2302505 rem: 67581
[ 2555.105348] rto: 69440 (3542 >> 3 + 643, 6) time: 2255105 sent: 2251946
pen: 1 2371946 rem: 66281
[ 2597.920272] rto: 120000 (17147 >> 3 + 1705, 6) time: 2297920 sent: 2294643
pen: 1 2414643 rem: 116723
[ 2624.616823] rto: 69440 (3542 >> 3 + 643, 6) time: 2324616 sent: 2321386
pen: 1 2441386 rem: 66210
[ 2693.911647] rto: 69440 (3542 >> 3 + 643, 6) time: 2393911 sent: 2390826
pen: 1 2510826 rem: 66355
[ 2763.385982] rto: 69440 (3542 >> 3 + 643, 6) time: 2463385 sent: 2460266
pen: 1 2580266 rem: 66321
[ 2779.512699] rto: 1256 (1556 >> 3 + 434, 1) time: 2479512 sent: 2478219 pen:
1 2480731 rem: 0
[ 2832.786161] rto: 69440 (3542 >> 3 + 643, 6) time: 2532786 sent: 2529707
pen: 1 2649707 rem: 66361
[ 2851.953268] rto: 120000 (9704 >> 3 + 2426, 7) time: 2551953 sent: 2548934
pen: 1 2668934 rem: 116981
[ 2902.338631] rto: 69440 (3542 >> 3 + 643, 6) time: 2602338 sent: 2599147
pen: 1 2719147 rem: 66249
[ 2957.718611] rto: 120000 (17147 >> 3 + 1705, 8) time: 2657718 sent: 2654643
pen: 1 2774643 rem: 116925
[ 2971.736295] rto: 69440 (3542 >> 3 + 643, 6) time: 2671736 sent: 2668587
pen: 1 2788587 rem: 66291
[ 2972.118479] rto: 120000 (9704 >> 3 + 2426, 7) time: 2672118 sent: 2668934
pen: 1 2788934 rem: 116816
[ 3041.036185] rto: 69440 (3542 >> 3 + 643, 6) time: 2741036 sent: 2738027
pen: 1 2858027 rem: 66431
[ 3091.942676] rto: 120000 (9704 >> 3 + 2426, 7) time: 2791942 sent: 2788934
pen: 1 2908934 rem: 116992
[ 3110.560285] rto: 69440 (3542 >> 3 + 643, 6) time: 2810560 sent: 2807467
pen: 1 2927467 rem: 66347
[ 3180.044502] rto: 69440 (3542 >> 3 + 643, 6) time: 2880044 sent: 2876907
pen: 1 2996907 rem: 66303
[ 3211.952300] rto: 120000 (9704 >> 3 + 2426, 7) time: 2911952 sent: 2908934
pen: 1 3028934 rem: 116982
[ 3288.275909] rto: 120000 (9674 >> 3 + 2484, 9) time: 2988275 sent: 2987173
pen: 1 3107173 rem: 118898
[ 3330.221683] rto: 120000 (200 >> 3 + 200, 13) time: 3030221 sent: 3027658
pen: 1 3147658 rem: 117437
[ 3383.376964] rto: 13296 (1388 >> 3 + 658, 4) time: 3083376 sent: 3082998
pen: 1 3109590 rem: 12918
[ 3408.805976] rto: 120000 (9674 >> 3 + 2484, 9) time: 3108805 sent: 3107174
pen: 1 3227174 rem: 118369
[ 3447.968663] rto: 120000 (200 >> 3 + 200, 13) time: 3147968 sent: 3147658
pen: 1 3267658 rem: 119690
[ 3798.180697] rto: 1482 (1976 >> 3 + 494, 1) time: 3498180 sent: 3497035 pen:
1 3499999 rem: 337
[ 3798.180827] rto: 741 (1976 >> 3 + 494, 0) time: 3498180 sent: 3497035 pen:
1 3498517 rem: 0
[ 3801.277029] rto: 1482 (1976 >> 3 + 494, 1) time: 3501276 sent: 3499662 pen:
1 3502626 rem: 0
[ 3801.277184] rto: 1482 (1976 >> 3 + 494, 1) time: 3501277 sent: 3501277 pen:
1 3504241 rem: 1482
[ 3804.486861] rto: 1482 (1976 >> 3 + 494, 1) time: 3504486 sent: 3502759 pen:
1 3505723 rem: 0
[ 3804.487007] rto: 1482 (1976 >> 3 + 494, 1) time: 3504486 sent: 3504486 pen:
1 3507450 rem: 1482
[ 3812.053012] rto: 2964 (1976 >> 3 + 494, 2) time: 3512052 sent: 3508933 pen:
1 3514861 rem: 0
[ 3815.238764] rto: 2964 (1976 >> 3 + 494, 2) time: 3515238 sent: 3512053 pen:
1 3517981 rem: 0
[ 3818.394748] rto: 2964 (1976 >> 3 + 494, 2) time: 3518394 sent: 3515238 pen:
1 3521166 rem: 0
[ 3821.481936] rto: 2964 (1976 >> 3 + 494, 2) time: 3521481 sent: 3518394 pen:
1 3524322 rem: 0
[ 3824.873120] rto: 2964 (1976 >> 3 + 494, 2) time: 3524873 sent: 3521482 pen:
1 3527410 rem: 0
[ 3827.898656] rto: 2964 (1976 >> 3 + 494, 2) time: 3527898 sent: 3524873 pen:
1 3530801 rem: 0
[ 3830.943112] rto: 2964 (1976 >> 3 + 494, 2) time: 3530943 sent: 3527898 pen:
1 3533826 rem: 0
[ 3833.974064] rto: 2964 (1976 >> 3 + 494, 2) time: 3533974 sent: 3530943 pen:
1 3536871 rem: 0
[ 3837.112487] rto: 2964 (1976 >> 3 + 494, 2) time: 3537112 sent: 3533974 pen:
1 3539902 rem: 0
[ 3840.130296] rto: 2964 (1976 >> 3 + 494, 2) time: 3540130 sent: 3537112 pen:
1 3543040 rem: 0
[ 3843.191881] rto: 2964 (1976 >> 3 + 494, 2) time: 3543191 sent: 3540130 pen:
1 3546058 rem: 0
[ 3846.633862] rto: 2964 (1976 >> 3 + 494, 2) time: 3546633 sent: 3543191 pen:
1 3549119 rem: 0
[ 3849.682215] rto: 2964 (1976 >> 3 + 494, 2) time: 3549682 sent: 3546633 pen:
1 3552561 rem: 0
[ 3852.728190] rto: 2964 (1976 >> 3 + 494, 2) time: 3552728 sent: 3549682 pen:
1 3555610 rem: 0
[ 3869.778290] rto: 79136 (14257 >> 3 + 691, 5) time: 3569778 sent: 3564894
pen: 1 3684894 rem: 74252
[ 3942.001467] rto: 47424 (1976 >> 3 + 494, 6) time: 3642001 sent: 3641648
pen: 1 3736496 rem: 47071
[ 3948.754452] rto: 79136 (14257 >> 3 + 691, 5) time: 3648754 sent: 3644030
pen: 1 3764030 rem: 74412
[ 3972.841345] rto: 47168 (1911 >> 3 + 499, 6) time: 3672841 sent: 3672158
pen: 1 3766494 rem: 46485
[ 3992.364664] rto: 47424 (1976 >> 3 + 494, 6) time: 3692364 sent: 3689072
pen: 1 3783920 rem: 44132
[ 4019.342183] rto: 47168 (1911 >> 3 + 499, 6) time: 3719342 sent: 3719326
pen: 1 3813662 rem: 47152
[ 4028.049905] rto: 79136 (14257 >> 3 + 691, 5) time: 3728049 sent: 3723166
pen: 1 3843166 rem: 74253
[ 4039.530444] rto: 47424 (1976 >> 3 + 494, 6) time: 3739530 sent: 3736496
pen: 1 3831344 rem: 44390
[ 4067.954752] rto: 47168 (1911 >> 3 + 499, 6) time: 3767954 sent: 3766494
pen: 1 3860830 rem: 45708
[ 4087.534683] rto: 47424 (1976 >> 3 + 494, 6) time: 3787534 sent: 3783920
pen: 1 3878768 rem: 43810
[ 4116.817143] rto: 47168 (1911 >> 3 + 499, 6) time: 3816817 sent: 3813662
pen: 1 3907998 rem: 44013
[ 4134.515420] rto: 47424 (1976 >> 3 + 494, 6) time: 3834515 sent: 3831344
pen: 1 3926192 rem: 44253
[ 4146.622061] rto: 40592 (3300 >> 3 + 2125, 4) time: 3846622 sent: 3846199
pen: 1 3927383 rem: 40169
[ 4182.217172] rto: 47424 (1976 >> 3 + 494, 6) time: 3882217 sent: 3878768
pen: 1 3973616 rem: 43975
[ 4226.387945] rto: 120000 (14257 >> 3 + 691, 6) time: 3926387 sent: 3922303
pen: 1 4042303 rem: 115916
[ 4228.876327] rto: 85152 (11055 >> 3 + 1280, 5) time: 3928876 sent: 3925792
pen: 1 4045792 rem: 82068
[ 4229.248393] rto: 47424 (1976 >> 3 + 494, 6) time: 3929248 sent: 3926192
pen: 1 4021040 rem: 44368
[ 4264.022196] rto: 103072 (11062 >> 3 + 1839, 5) time: 3964022 sent: 3963411
pen: 1 4083411 rem: 102461
[ 4271.074364] rto: 81184 (3300 >> 3 + 2125, 5) time: 3971074 sent: 3967975
pen: 1 4087975 rem: 78085
[ 4276.683784] rto: 47424 (1976 >> 3 + 494, 6) time: 3976683 sent: 3973616
pen: 1 4068464 rem: 44357
^ permalink raw reply [flat|nested] 16+ messages in thread
* [PATCH] tcp: fix ICMP-RTO war
2010-01-23 21:37 ` Denys Fedoryshchenko
@ 2010-01-23 22:34 ` Ilpo Järvinen
2010-01-23 22:45 ` Denys Fedoryshchenko
` (2 more replies)
0 siblings, 3 replies; 16+ messages in thread
From: Ilpo Järvinen @ 2010-01-23 22:34 UTC (permalink / raw)
To: Denys Fedoryshchenko; +Cc: Damian Lukowski, Netdev, David Miller
[-- Attachment #1: Type: TEXT/PLAIN, Size: 3482 bytes --]
Restored Damian cc, please keep them.
On Sat, 23 Jan 2010, Denys Fedoryshchenko wrote:
> On Tuesday 19 January 2010 13:17:51 you wrote:
> > On Tue, 19 Jan 2010, Denys Fedoryshchenko wrote:
> > > On Tuesday 19 January 2010 11:10:12 you wrote:
> > > > Hi,
> > > > thank you for testing. So srtt and rttvar is zero in any of those
> > > > cases. Ilpo, it is a bug in tcp_rtt_estimator then, I suppose?
> > > >
> > > > There is also a code comment in tcp_input.c, saying:
> > > > > * NOTE: clamping at TCP_RTO_MIN is not required, current algo
> > > > > * guarantees that rto is higher.
> > > >
> > > > So we either fix tcp_rtt_estimator or simply clamp at TCP_RTO_MIN?
> > > >
> > > > Damian
> > > >
> > > > > On Monday 11 January 2010 15:02:34 you wrote:
> > > > >> On Sat, 26 Dec 2009, Denys Fedoryshchenko wrote:
> > > > >>> Few more dumps. I notice:
> > > > >>> 1)Ack always equal 1
> > > > >>> 2)It is usually first segment of data sent (?)
> > > > >>>
> > > > >>> Maybe some value not initialised properly?
> > > > >>
> > > > >> Can you see if the RTO lower bound is violated (I added some
> > > > >> printing of vars there too already now if it turns out to be
> > > > >> something):
> > > > >>
> > > > >> diff --git a/net/ipv4/tcp_ipv4.c b/net/ipv4/tcp_ipv4.c
> > > > >> index 65b8ebf..d84469f 100644
> > > > >> --- a/net/ipv4/tcp_ipv4.c
> > > > >> +++ b/net/ipv4/tcp_ipv4.c
> > >
> > > As i see in code it is rounding RTO to minimum value.
> > > It fixes my problem seems.
> > >
> > > Btw just a bit about my environment - wireless networks (sometimes
> > > lossy!) with low speed (128-512Kbps) customers working over pppoe. Maybe
> > > it will give a tip why rtt value is too low.
> >
> > What I find most strange in it is the fact that when it triggers for the
> > first time, the srtt and mdev are zero, not some value in between 0 and
> > 200ms. Therefore I suspect that this case might be something that we've
> > overlooked where srtt/mdev are not valid at all.
> >
> > Maybe the patch below helps...
> >
> Seems after this patch (and debug patch with warnings) my dmesg is clean.
Cool, thanks for testing.
Dave, please send into stable too (besides net-2.6). If we want less strict
state check we can continue playing with that in net-next, IMHO.
--
i.
--
[PATCH] tcp: fix ICMP-RTO war
When destination is not reachable, ICMP of that is processed
here. In some TCP state srtt and mdev are not valid, yielding
to zero rto. Since the code below then immediately forces
timeout, a segment is sent which again triggers another ICMP
causing ICMP-RTO war to happen.
Broken since f1ecd5d9e736660 (Revert Backoff [v3]: Revert RTO
on ICMP destination unreachable).
Signed-off-by: Ilpo Järvinen <ilpo.jarvinen@helsinki.fi>
Reported-by: Denys Fedoryshchenko <denys@visp.net.lb>
Tested-by: Denys Fedoryshchenko <denys@visp.net.lb>
---
net/ipv4/tcp_ipv4.c | 3 +++
1 files changed, 3 insertions(+), 0 deletions(-)
diff --git a/net/ipv4/tcp_ipv4.c b/net/ipv4/tcp_ipv4.c
index 65b8ebf..ebcfcf6 100644
--- a/net/ipv4/tcp_ipv4.c
+++ b/net/ipv4/tcp_ipv4.c
@@ -401,6 +401,9 @@ void tcp_v4_err(struct sk_buff *icmp_skb, u32 info)
* (see draft-zimmermann-tcp-lcd) */
if (code != ICMP_NET_UNREACH && code != ICMP_HOST_UNREACH)
break;
+ /* A bit too strict, just want to be on the safe side for now */
+ if (sk->sk_state != TCP_ESTABLISHED)
+ break;
if (seq != tp->snd_una || !icsk->icsk_retransmits ||
!icsk->icsk_backoff)
break;
--
1.5.6.5
^ permalink raw reply related [flat|nested] 16+ messages in thread
end of thread, other threads:[~2010-02-07 10:29 UTC | newest]
Thread overview: 16+ messages (download: mbox.gz / follow: Atom feed)
-- links below jump to the message on this page --
2010-01-27 13:56 [PATCH] tcp: fix ICMP-RTO war Denys Fedoryshchenko
2010-01-29 12:13 ` Damian Lukowski
2010-01-29 15:15 ` Denys Fedoryshchenko
2010-01-29 21:45 ` Damian Lukowski
2010-01-30 13:35 ` Denys Fedoryshchenko
2010-01-30 13:56 ` Damian Lukowski
2010-02-07 10:28 ` Denys Fedoryshchenko
-- strict thread matches above, loose matches on Subject: below --
2009-12-26 15:03 Crazy TCP bug (keepalive flood?) in 2.6.32? Denys Fedoryshchenko
2010-01-19 11:09 ` Denys Fedoryshchenko
2010-01-19 11:17 ` Ilpo Järvinen
2010-01-23 21:37 ` Denys Fedoryshchenko
2010-01-23 22:34 ` [PATCH] tcp: fix ICMP-RTO war Ilpo Järvinen
2010-01-23 22:45 ` Denys Fedoryshchenko
2010-01-25 15:07 ` Damian Lukowski
2010-01-26 7:45 ` David Miller
2010-01-27 12:41 ` Ilpo Järvinen
2010-01-27 14:14 ` Alexey Kuznetsov
2010-01-23 23:28 ` Denys Fedoryshchenko
2010-01-25 12:12 ` Damian Lukowski
2010-01-27 12:36 ` Ilpo Järvinen
This is an external index of several public inboxes,
see mirroring instructions on how to clone and mirror
all data and code used by this external index.