On 2025-01-18 15:04, Neal Cardwell wrote:

On Fri, Jan 17, 2025 at 4:41 PM wrote:

...

From: Jon Maloy

Testing with iperf3 using the "pasta" protocol splicer has revealed a bug in the way tcp handles window advertising in extreme memory squeeze situations.

Under memory pressure, a socket endpoint may temporarily advertise a zero-sized window, but this is not stored as part of the socket data. The reasoning behind this is that it is considered a temporary setting which shouldn't influence any further calculations.

However, if we happen to stall at an unfortunate value of the current window size, the algorithm selecting a new value will consistently fail to advertise a non-zero window once we have freed up enough memory.

The "if we happen to stall at an unfortunate value of the current window size" phrase is a little vague... :-) Do you have a sense of what might count as "unfortunate" here? That might help in crafting a packetdrill test to reproduce this and have an automated regression test.

Obviously, it happens when the following code snippet in __tcp_cleanup_rbuf() { [....] if (copied > 0 && !time_to_ack && !(sk->sk_shutdown & RCV_SHUTDOWN)) { __u32 rcv_window_now = tcp_receive_window(tp); /* Optimize, __tcp_select_window() is not cheap. */ if (2*rcv_window_now <= tp->window_clamp) { __u32 new_window = __tcp_select_window(sk); /* Send ACK now, if this read freed lots of space * in our buffer. Certainly, new_window is new window. * We can advertise it now, if it is not less than * current one. * "Lots" means "at least twice" here. */ if (new_window && new_window >= 2 * rcv_window_now) time_to_ack = true; } } [....] } yields time_to_ack = false, i.e. __tcp_select_window(sk) returns a value new_window < (2 * tcp_receive_window(tp)). In my log I have for brevity used the following names: win_now: same as rcv_window_now (= tcp_receive_window(tp), = tp->rcv_wup + tp->rcv_wnd - tp->rcv_nxt, = 265469200 + 262144 - 265600160, = 131184) new_win: same as new_window (= __tcp_select_window(sk), = 0 first time, later 262144 ) rcv_wnd: same as tp->rcv_wnd, (=262144) We see that although the last test actually is pretty close (262144 >= 262368 ? => false) it is not close enough. We also notice that (tp->rcv_nxt - tp->rcv_wup) = (265600160 - 265469200) = 130960. 130960 < tp->rcv_wnd / 2, so the last test in __tcp_cleanup_rbuf(): (new_window >= 2 * rcv_window_now) will always be false. Too me it looks like __tcp_select_window(sk) doesn't at all take the freed-up memory into account when calculating a new window. I haven't looked into why that is happening.

...

This means that this side's notion of the current window size is different from the one last advertised to the peer, causing the latter to not send any data to resolve the sitution.

Since the peer last saw a zero receive window at the time of the memory-pressure drop, shouldn't the peer be sending repeated zero window probes, and shouldn't the local host respond to a ZWP with an ACK with the correct non-zero window?

It should, but at the moment when I found this bug the peer stack was not the Linux kernel stack, but one we develop for our own purpose. We fixed that later, but it still means that traffic stops for a couple of seconds now and then before the timer restarts the flow. This happens too often for comfort in our usage scenarios. We can of course blame the the peer stack, but I still feel this is a bug, and that it could be handled better by the kernel stack.

Do you happen to have a tcpdump .pcap of one of these cases that you can share?

I had one, although not for this particular run, and I cannot find it right now. I will continue looking or make a new one. Is there some shared space I can put it?

...

The problem occurs on the iperf3 server side, and the socket in question is a completely regular socket with the default settings for the fedora40 kernel. We do not use SO_PEEK or SO_RCVBUF on the socket.

The following excerpt of a logging session, with own comments added, shows more in detail what is happening:

// tcp_v4_rcv(->) // tcp_rcv_established(->) [5201<->39222]: ==== Activating log @ net/ipv4/tcp_input.c/tcp_data_queue()/5257 ==== [5201<->39222]: tcp_data_queue(->) [5201<->39222]: DROPPING skb [265600160..265665640], reason: SKB_DROP_REASON_PROTO_MEM [rcv_nxt 265600160, rcv_wnd 262144, snt_ack 265469200, win_now 131184]

What is "win_now"? That doesn't seem to correspond to any variable name in the Linux source tree.

See above. Can this be renamed to the

tcp_select_window() variable it is printing, like "cur_win" or "effective_win" or "new_win", etc?

Or perhaps you can attach your debugging patch in some email thread? I agree with Eric that these debug dumps are a little hard to parse without seeing the patch that allows us to understand what some of these fields are...

I agree with Eric that probably tp->pred_flags should be cleared, and a packetdrill test for this would be super-helpful.

I must admit I have never used packetdrill, but I can make an effort. ///jon

thanks, neal

On Mon, Jan 20, 2025 at 5:10 PM Jon Maloy wrote:

On 2025-01-20 00:03, Jon Maloy wrote:

...

On 2025-01-18 15:04, Neal Cardwell wrote:

...

On Fri, Jan 17, 2025 at 4:41 PM wrote:

...

From: Jon Maloy

Testing with iperf3 using the "pasta" protocol splicer has revealed a bug in the way tcp handles window advertising in extreme memory squeeze situations.

Under memory pressure, a socket endpoint may temporarily advertise a zero-sized window, but this is not stored as part of the socket data. The reasoning behind this is that it is considered a temporary setting which shouldn't influence any further calculations.

However, if we happen to stall at an unfortunate value of the current window size, the algorithm selecting a new value will consistently fail to advertise a non-zero window once we have freed up enough memory.

The "if we happen to stall at an unfortunate value of the current window size" phrase is a little vague... :-) Do you have a sense of what might count as "unfortunate" here? That might help in crafting a packetdrill test to reproduce this and have an automated regression test.

Obviously, it happens when the following code snippet in

__tcp_cleanup_rbuf() { [....] if (copied > 0 && !time_to_ack && !(sk->sk_shutdown & RCV_SHUTDOWN)) { __u32 rcv_window_now = tcp_receive_window(tp);

/* Optimize, __tcp_select_window() is not cheap. */ if (2*rcv_window_now <= tp->window_clamp) { __u32 new_window = __tcp_select_window(sk);

/* Send ACK now, if this read freed lots of space * in our buffer. Certainly, new_window is new window. * We can advertise it now, if it is not less than * current one. * "Lots" means "at least twice" here. */ if (new_window && new_window >= 2 * rcv_window_now) time_to_ack = true; } } [....] }

yields time_to_ack = false, i.e. __tcp_select_window(sk) returns a value new_window < (2 * tcp_receive_window(tp)).

In my log I have for brevity used the following names:

win_now: same as rcv_window_now (= tcp_receive_window(tp), = tp->rcv_wup + tp->rcv_wnd - tp->rcv_nxt, = 265469200 + 262144 - 265600160, = 131184)

new_win: same as new_window (= __tcp_select_window(sk), = 0 first time, later 262144 )

rcv_wnd: same as tp->rcv_wnd, (=262144)

We see that although the last test actually is pretty close (262144 >= 262368 ? => false) it is not close enough.

We also notice that (tp->rcv_nxt - tp->rcv_wup) = (265600160 - 265469200) = 130960. 130960 < tp->rcv_wnd / 2, so the last test in __tcp_cleanup_rbuf(): (new_window >= 2 * rcv_window_now) will always be false.

Too me it looks like __tcp_select_window(sk) doesn't at all take the freed-up memory into account when calculating a new window. I haven't looked into why that is happening.

...

...

This means that this side's notion of the current window size is different from the one last advertised to the peer, causing the latter to not send any data to resolve the sitution.

Since the peer last saw a zero receive window at the time of the memory-pressure drop, shouldn't the peer be sending repeated zero window probes, and shouldn't the local host respond to a ZWP with an ACK with the correct non-zero window?

It should, but at the moment when I found this bug the peer stack was not the Linux kernel stack, but one we develop for our own purpose. We fixed that later, but it still means that traffic stops for a couple of seconds now and then before the timer restarts the flow. This happens too often for comfort in our usage scenarios. We can of course blame the the peer stack, but I still feel this is a bug, and that it could be handled better by the kernel stack.

...

Do you happen to have a tcpdump .pcap of one of these cases that you can share?

I had one, although not for this particular run, and I cannot find it right now. I will continue looking or make a new one. Is there some shared space I can put it?

Here it is. Look at frame #1067.

https://passt.top/static/iperf3_jon_zero_window_cut.pcap

...

...

...

The problem occurs on the iperf3 server side, and the socket in question is a completely regular socket with the default settings for the fedora40 kernel. We do not use SO_PEEK or SO_RCVBUF on the socket.

The following excerpt of a logging session, with own comments added, shows more in detail what is happening:

// tcp_v4_rcv(->) // tcp_rcv_established(->) [5201<->39222]: ==== Activating log @ net/ipv4/tcp_input.c/ tcp_data_queue()/5257 ==== [5201<->39222]: tcp_data_queue(->) [5201<->39222]: DROPPING skb [265600160..265665640], reason: SKB_DROP_REASON_PROTO_MEM [rcv_nxt 265600160, rcv_wnd 262144, snt_ack 265469200, win_now 131184]

What is "win_now"? That doesn't seem to correspond to any variable name in the Linux source tree.

See above.

Can this be renamed to the

...

tcp_select_window() variable it is printing, like "cur_win" or "effective_win" or "new_win", etc?

Or perhaps you can attach your debugging patch in some email thread? I agree with Eric that these debug dumps are a little hard to parse without seeing the patch that allows us to understand what some of these fields are...

I agree with Eric that probably tp->pred_flags should be cleared, and a packetdrill test for this would be super-helpful.

I must admit I have never used packetdrill, but I can make an effort.

I hear from other sources that you cannot force a memory exhaustion with packetdrill anyway, so this sounds like a pointless exercise.

We certainly can and should add a feature like that to packetdrill. Documentation/fault-injection/ has some relevant information. Even without this, tcp_try_rmem_schedule() is reading sk->sk_rcvbuf that could be lowered by a packetdrill script I think.

On Fri, Jan 24, 2025 at 6:40 PM Jon Maloy wrote:

On 2025-01-20 11:22, Eric Dumazet wrote:

...

On Mon, Jan 20, 2025 at 5:10 PM Jon Maloy wrote:

...

On 2025-01-20 00:03, Jon Maloy wrote:

...

[...]

...

...

...

...

I agree with Eric that probably tp->pred_flags should be cleared, and a packetdrill test for this would be super-helpful.

I must admit I have never used packetdrill, but I can make an effort.

I hear from other sources that you cannot force a memory exhaustion with packetdrill anyway, so this sounds like a pointless exercise.

We certainly can and should add a feature like that to packetdrill.

Documentation/fault-injection/ has some relevant information.

Even without this, tcp_try_rmem_schedule() is reading sk->sk_rcvbuf that could be lowered by a packetdrill script I think.

Neal, Eric, How do you suggest we proceed with this? I downloaded packetdrill and tried it a bit, but to understand it well enough to introduce a new feature would require more time than I am able to spend on this. Maybe Neal, who I see is one of the contributors to packetdrill could help out?

I will spend some time this week preparing for some tests. I would prefer not merging new code without a clear understanding of the issue. Thanks.

I can certainly clear tp->pred_flags and post it again, maybe with an improved and shortened log. Would that be acceptable?

I also made a run where I looked into why __tcp_select_window() ignores all the space that has been freed up:

tcp_recvmsg_locked(->) __tcp_cleanup_rbuf(->) (copied 131072) tp->rcv_wup: 1788299855, tp->rcv_wnd: 5812224, tp->rcv_nxt 1793800175 __tcp_select_window(->) tcp_space(->) tcp_space(<-) returning 458163 free_space = round_down(458163, 1 << 4096) = 454656 (free_space > tp->rcv_ssthresh) --> free_space = tp->rcv_ssthresh = 261920 window = ALIGN(261920, 4096) = 26144 __tcp_select_window(<-) returning 262144 [rcv_win_now 311904, 2 * rcv_win_now 623808, new_window 262144] (new_window >= (2 * rcv_win_now)) ? --> time_to_ack 0 NOT calling tcp_send_ack() __tcp_cleanup_rbuf(<-) [tp->rcv_wup 1788299855, tp->rcv_wnd 5812224, tp->rcv_nxt 1793800175] tcp_recvmsg_locked(<-) returning 131072 bytes. [tp->rcv_nxt 1793800175, tp->rcv_wnd 5812224, tp->rcv_wup 1788299855, sk->last_ack 0, tcp_receive_win() 311904, copied_seq 1788299855->1788395953 (96098), unread 5404222, sk_rcv_qlen 83, ofo_qlen 0]

As we see tp->rcv_ssthresh is the limiting factor, causing a consistent situation where (new_window < (rcv_win_now * 2)), and even (new_window < rcv_win_now).

To me, it looks like tp->ssthresh should have a higher value in this situation, or maybe we should alter this test.

The combination of these two issues, -not updating tp->wnd and _tcp_select_window() returning a wrong value, is what is causing this whole problem.

///jon

On Mon, Jan 27, 2025 at 11:01 AM Stefano Brivio wrote:

On Fri, 24 Jan 2025 12:40:16 -0500 Jon Maloy wrote:

...

I can certainly clear tp->pred_flags and post it again, maybe with an improved and shortened log. Would that be acceptable?

Talking about an improved log, what strikes me the most of the whole problem is:

$ tshark -r iperf3_jon_zero_window.pcap -td -Y 'frame.number in { 1064 .. 1068 }' 1064 0.004416 192.168.122.1 → 192.168.122.198 TCP 65534 34482 → 5201 [ACK] Seq=1611679466 Ack=1 Win=36864 Len=65480 1065 0.007334 192.168.122.1 → 192.168.122.198 TCP 65534 34482 → 5201 [ACK] Seq=1611744946 Ack=1 Win=36864 Len=65480 1066 0.005104 192.168.122.1 → 192.168.122.198 TCP 56382 [TCP Window Full] 34482 → 5201 [ACK] Seq=1611810426 Ack=1 Win=36864 Len=56328 1067 0.015226 192.168.122.198 → 192.168.122.1 TCP 54 [TCP ZeroWindow] 5201 → 34482 [ACK] Seq=1 Ack=1611090146 Win=0 Len=0 1068 6.298138 fe80::44b3:f5ff:fe86:c529 → ff02::2 ICMPv6 70 Router Solicitation from 46:b3:f5:86:c5:29

...and then the silence, 192.168.122.198 never announces that its window is not zero, so the peer gives up 15 seconds later:

$ tshark -r iperf3_jon_zero_window_cut.pcap -td -Y 'frame.number in { 1069 .. 1070 }' 1069 8.709313 192.168.122.1 → 192.168.122.198 TCP 55 34466 → 5201 [ACK] Seq=166 Ack=5 Win=36864 Len=1 1070 0.008943 192.168.122.198 → 192.168.122.1 TCP 54 5201 → 34482 [FIN, ACK] Seq=1 Ack=1611090146 Win=778240 Len=0

Data in frame #1069 is iperf3 ending the test.

This didn't happen before e2142825c120 ("net: tcp: send zero-window ACK when no memory") so it's a relatively recent (17 months) regression.

It actually looks pretty simple (and rather serious) to me.

With all that, it should be pretty easy to cook a packetdrill test, right ? packetdrill tests are part of tools/testing/selftests/net/ already, we are not asking for something unreasonable.

On Mon, Jan 27, 2025 at 6:01 PM Stefano Brivio wrote:

On Fri, 24 Jan 2025 12:40:16 -0500 Jon Maloy wrote:

...

I can certainly clear tp->pred_flags and post it again, maybe with an improved and shortened log. Would that be acceptable?

Talking about an improved log, what strikes me the most of the whole problem is:

$ tshark -r iperf3_jon_zero_window.pcap -td -Y 'frame.number in { 1064 .. 1068 }' 1064 0.004416 192.168.122.1 → 192.168.122.198 TCP 65534 34482 → 5201 [ACK] Seq=1611679466 Ack=1 Win=36864 Len=65480 1065 0.007334 192.168.122.1 → 192.168.122.198 TCP 65534 34482 → 5201 [ACK] Seq=1611744946 Ack=1 Win=36864 Len=65480 1066 0.005104 192.168.122.1 → 192.168.122.198 TCP 56382 [TCP Window Full] 34482 → 5201 [ACK] Seq=1611810426 Ack=1 Win=36864 Len=56328 1067 0.015226 192.168.122.198 → 192.168.122.1 TCP 54 [TCP ZeroWindow] 5201 → 34482 [ACK] Seq=1 Ack=1611090146 Win=0 Len=0 1068 6.298138 fe80::44b3:f5ff:fe86:c529 → ff02::2 ICMPv6 70 Router Solicitation from 46:b3:f5:86:c5:29

...and then the silence, 192.168.122.198 never announces that its window is not zero, so the peer gives up 15 seconds later:

$ tshark -r iperf3_jon_zero_window_cut.pcap -td -Y 'frame.number in { 1069 .. 1070 }' 1069 8.709313 192.168.122.1 → 192.168.122.198 TCP 55 34466 → 5201 [ACK] Seq=166 Ack=5 Win=36864 Len=1 1070 0.008943 192.168.122.198 → 192.168.122.1 TCP 54 5201 → 34482 [FIN, ACK] Seq=1 Ack=1611090146 Win=778240 Len=0

Data in frame #1069 is iperf3 ending the test.

This didn't happen before e2142825c120 ("net: tcp: send zero-window ACK when no memory") so it's a relatively recent (17 months) regression.

It actually looks pretty simple (and rather serious) to me.

I remembered last time it really also took me some time to totally follow. Packetdrill should be helpful :) As to the patch itself, I agreed with this fix last time while now I have to re-read that long analysis to recall as much as possible. I'm not that sure if it's a bug belonging to the Linux kernel. The other side not sending a window probe causes this issue...? The other part of me says we cannot break the user's behaviour. One way or another, I will also take a look at it again. Thanks, Jason

On Fri, Jan 24, 2025 at 6:40 PM Jon Maloy wrote:

On 2025-01-20 11:22, Eric Dumazet wrote:

...

On Mon, Jan 20, 2025 at 5:10 PM Jon Maloy wrote:

...

On 2025-01-20 00:03, Jon Maloy wrote:

...

[...]

...

...

...

...

I agree with Eric that probably tp->pred_flags should be cleared, and a packetdrill test for this would be super-helpful.

I must admit I have never used packetdrill, but I can make an effort.

I hear from other sources that you cannot force a memory exhaustion with packetdrill anyway, so this sounds like a pointless exercise.

We certainly can and should add a feature like that to packetdrill.

Documentation/fault-injection/ has some relevant information.

Even without this, tcp_try_rmem_schedule() is reading sk->sk_rcvbuf that could be lowered by a packetdrill script I think.

Neal, Eric, How do you suggest we proceed with this? I downloaded packetdrill and tried it a bit, but to understand it well enough to introduce a new feature would require more time than I am able to spend on this. Maybe Neal, who I see is one of the contributors to packetdrill could help out?

I can certainly clear tp->pred_flags and post it again, maybe with an improved and shortened log. Would that be acceptable?

Yes.

I also made a run where I looked into why __tcp_select_window() ignores all the space that has been freed up:

tcp_recvmsg_locked(->) __tcp_cleanup_rbuf(->) (copied 131072) tp->rcv_wup: 1788299855, tp->rcv_wnd: 5812224, tp->rcv_nxt 1793800175 __tcp_select_window(->) tcp_space(->) tcp_space(<-) returning 458163 free_space = round_down(458163, 1 << 4096) = 454656 (free_space > tp->rcv_ssthresh) --> free_space = tp->rcv_ssthresh = 261920 window = ALIGN(261920, 4096) = 26144 __tcp_select_window(<-) returning 262144 [rcv_win_now 311904, 2 * rcv_win_now 623808, new_window 262144] (new_window >= (2 * rcv_win_now)) ? --> time_to_ack 0 NOT calling tcp_send_ack() __tcp_cleanup_rbuf(<-) [tp->rcv_wup 1788299855, tp->rcv_wnd 5812224, tp->rcv_nxt 1793800175] tcp_recvmsg_locked(<-) returning 131072 bytes. [tp->rcv_nxt 1793800175, tp->rcv_wnd 5812224, tp->rcv_wup 1788299855, sk->last_ack 0, tcp_receive_win() 311904, copied_seq 1788299855->1788395953 (96098), unread 5404222, sk_rcv_qlen 83, ofo_qlen 0]

As we see tp->rcv_ssthresh is the limiting factor, causing a consistent situation where (new_window < (rcv_win_now * 2)), and even (new_window < rcv_win_now).

Your changelog could simply explain this, in one sentence. instead of lengthy traces.