TCP stops sending packets over loopback on 4.10-rc3?

TCP stops sending packets over loopback on 4.10-rc3?

[Josef Bacik]

Hello,

I've been trying to test some NBD changes I had made recently and I 
started having packet timeouts.  I traced this down to tcp just 
stopping sending packets after a lot of writing.  All NBD does is call 
kernel_sendmsg() with a request struct and some pages when it does 
writes.  I did a bunch of tracing and I've narrowed it down to running 
out of sk_wmem_queued space.  In tcp_sendmsg() here

new_segment:
                        /* Allocate new segment. If the interface is SG,
                         * allocate skb fitting to single page.
                         */
                        if (!sk_stream_memory_free(sk))
                                goto wait_for_sndbuf;

we hit this pretty regularly, and eventually just get stuck in 
sk_stream_wait_memory until the timeout ends and we error out 
everything.  Now sk_stream_memory_free checks the sk_wmem_queued and 
calls into the sk_prot->stream_memory_free(), so I broke this out like 
the following


    if (sk->sk_wmem_queued >= sk->sk_sndbuf) {
        trace_printk("sk_wmem_queued %d, sk_sndbuf %d\n", 
sk->sk_wmem_queued, sk->sk_sndbuf);
        goto wait_for_sndbuf;
     }
     if (sk->sk_prot->stream_memory_free && 
!sk->sk_prot->stream_memory_free(sk)) {
        trace_printk("sk_stream_memory_free\n");
        goto wait_for_sndbuf;
     }

And I got this in my tracing

   kworker/u16:5-112   [001] ....  1375.637564: tcp_sendmsg: 
sk_wmem_queued 4204872, sk_sndbuf 4194304
   kworker/u16:5-112   [001] ....  1375.639657: tcp_sendmsg: 
sk_wmem_queued 4204872, sk_sndbuf 4194304
   kworker/u16:5-112   [003] ....  1375.641128: tcp_sendmsg: 
sk_wmem_queued 4204872, sk_sndbuf 4194304
   kworker/u16:5-112   [003] ....  1375.643441: tcp_sendmsg: 
sk_wmem_queued 4204872, sk_sndbuf 4194304
   kworker/u16:5-112   [001] ....  1375.807614: tcp_sendmsg: 
sk_wmem_queued 4204872, sk_sndbuf 4194304
   kworker/u16:5-112   [001] ....  1377.538744: tcp_sendmsg: 
sk_wmem_queued 4204872, sk_sndbuf 4194304
   kworker/u16:5-112   [001] ....  1377.543418: tcp_sendmsg: 
sk_wmem_queued 4204872, sk_sndbuf 4194304
    kworker/2:4H-1535  [002] ....  1377.544685: tcp_sendmsg: 
sk_wmem_queued 4204872, sk_sndbuf 4194304
   kworker/u16:5-112   [000] ....  1379.378352: tcp_sendmsg: 
sk_wmem_queued 4205796, sk_sndbuf 4194304
   kworker/u16:5-112   [003] ....  1380.985721: tcp_sendmsg: 
sk_wmem_queued 4212416, sk_sndbuf 4194304

This is as far as I've gotten and I'll keep digging into it, but I was 
wondering if this looks familiar to anybody?  Also one thing I've 
noticed is sk_stream_wait_memory() will wait on sk_sleep(sk), but 
basically nothing wakes this up.  For example it seems the main way we 
reduce sk_wmem_queued is through sk_wmem_free_skb(), which doesn't 
appear to wake anything up in any of its callers, so anybody who does 
end up sleeping will basically never wake up.  That seems like it 
should be more broken than it is, so I'm curious to know how things are 
actually woken up in this case.  Thanks,

Josef

Re: TCP stops sending packets over loopback on 4.10-rc3?

[Eric Dumazet]

On Tue, 2017-01-24 at 06:20 -0500, Josef Bacik wrote:
> Hello,
> 
> I've been trying to test some NBD changes I had made recently and I 
> started having packet timeouts.  I traced this down to tcp just 
> stopping sending packets after a lot of writing.  All NBD does is call 
> kernel_sendmsg() with a request struct and some pages when it does 
> writes.  I did a bunch of tracing and I've narrowed it down to running 
> out of sk_wmem_queued space.  In tcp_sendmsg() here
> 
> new_segment:
>                         /* Allocate new segment. If the interface is SG,
>                          * allocate skb fitting to single page.
>                          */
>                         if (!sk_stream_memory_free(sk))
>                                 goto wait_for_sndbuf;
> 
> we hit this pretty regularly, and eventually just get stuck in 
> sk_stream_wait_memory until the timeout ends and we error out 
> everything.  Now sk_stream_memory_free checks the sk_wmem_queued and 
> calls into the sk_prot->stream_memory_free(), so I broke this out like 
> the following
> 
> 
>     if (sk->sk_wmem_queued >= sk->sk_sndbuf) {
>         trace_printk("sk_wmem_queued %d, sk_sndbuf %d\n", 
> sk->sk_wmem_queued, sk->sk_sndbuf);
>         goto wait_for_sndbuf;
>      }
>      if (sk->sk_prot->stream_memory_free && 
> !sk->sk_prot->stream_memory_free(sk)) {
>         trace_printk("sk_stream_memory_free\n");
>         goto wait_for_sndbuf;
>      }
> 
> And I got this in my tracing
> 
>    kworker/u16:5-112   [001] ....  1375.637564: tcp_sendmsg: 
> sk_wmem_queued 4204872, sk_sndbuf 4194304
>    kworker/u16:5-112   [001] ....  1375.639657: tcp_sendmsg: 
> sk_wmem_queued 4204872, sk_sndbuf 4194304
>    kworker/u16:5-112   [003] ....  1375.641128: tcp_sendmsg: 
> sk_wmem_queued 4204872, sk_sndbuf 4194304
>    kworker/u16:5-112   [003] ....  1375.643441: tcp_sendmsg: 
> sk_wmem_queued 4204872, sk_sndbuf 4194304
>    kworker/u16:5-112   [001] ....  1375.807614: tcp_sendmsg: 
> sk_wmem_queued 4204872, sk_sndbuf 4194304
>    kworker/u16:5-112   [001] ....  1377.538744: tcp_sendmsg: 
> sk_wmem_queued 4204872, sk_sndbuf 4194304
>    kworker/u16:5-112   [001] ....  1377.543418: tcp_sendmsg: 
> sk_wmem_queued 4204872, sk_sndbuf 4194304
>     kworker/2:4H-1535  [002] ....  1377.544685: tcp_sendmsg: 
> sk_wmem_queued 4204872, sk_sndbuf 4194304
>    kworker/u16:5-112   [000] ....  1379.378352: tcp_sendmsg: 
> sk_wmem_queued 4205796, sk_sndbuf 4194304
>    kworker/u16:5-112   [003] ....  1380.985721: tcp_sendmsg: 
> sk_wmem_queued 4212416, sk_sndbuf 4194304
> 
> This is as far as I've gotten and I'll keep digging into it, but I was 
> wondering if this looks familiar to anybody?  Also one thing I've 
> noticed is sk_stream_wait_memory() will wait on sk_sleep(sk), but 
> basically nothing wakes this up.  For example it seems the main way we 
> reduce sk_wmem_queued is through sk_wmem_free_skb(), which doesn't 
> appear to wake anything up in any of its callers, so anybody who does 
> end up sleeping will basically never wake up.  That seems like it 
> should be more broken than it is, so I'm curious to know how things are 
> actually woken up in this case.  Thanks,


git grep -n SOCK_QUEUE_SHRUNK

-> tcp_check_space()

Re: TCP stops sending packets over loopback on 4.10-rc3?

[Josef Bacik]

On Tue, Jan 24, 2017 at 9:07 AM, Eric Dumazet <eric.dumazet@gmail.com> 
wrote:
> On Tue, 2017-01-24 at 06:20 -0500, Josef Bacik wrote:
>>  Hello,
>> 
>>  I've been trying to test some NBD changes I had made recently and I
>>  started having packet timeouts.  I traced this down to tcp just
>>  stopping sending packets after a lot of writing.  All NBD does is 
>> call
>>  kernel_sendmsg() with a request struct and some pages when it does
>>  writes.  I did a bunch of tracing and I've narrowed it down to 
>> running
>>  out of sk_wmem_queued space.  In tcp_sendmsg() here
>> 
>>  new_segment:
>>                          /* Allocate new segment. If the interface 
>> is SG,
>>                           * allocate skb fitting to single page.
>>                           */
>>                          if (!sk_stream_memory_free(sk))
>>                                  goto wait_for_sndbuf;
>> 
>>  we hit this pretty regularly, and eventually just get stuck in
>>  sk_stream_wait_memory until the timeout ends and we error out
>>  everything.  Now sk_stream_memory_free checks the sk_wmem_queued and
>>  calls into the sk_prot->stream_memory_free(), so I broke this out 
>> like
>>  the following
>> 
>> 
>>      if (sk->sk_wmem_queued >= sk->sk_sndbuf) {
>>          trace_printk("sk_wmem_queued %d, sk_sndbuf %d\n",
>>  sk->sk_wmem_queued, sk->sk_sndbuf);
>>          goto wait_for_sndbuf;
>>       }
>>       if (sk->sk_prot->stream_memory_free &&
>>  !sk->sk_prot->stream_memory_free(sk)) {
>>          trace_printk("sk_stream_memory_free\n");
>>          goto wait_for_sndbuf;
>>       }
>> 
>>  And I got this in my tracing
>> 
>>     kworker/u16:5-112   [001] ....  1375.637564: tcp_sendmsg:
>>  sk_wmem_queued 4204872, sk_sndbuf 4194304
>>     kworker/u16:5-112   [001] ....  1375.639657: tcp_sendmsg:
>>  sk_wmem_queued 4204872, sk_sndbuf 4194304
>>     kworker/u16:5-112   [003] ....  1375.641128: tcp_sendmsg:
>>  sk_wmem_queued 4204872, sk_sndbuf 4194304
>>     kworker/u16:5-112   [003] ....  1375.643441: tcp_sendmsg:
>>  sk_wmem_queued 4204872, sk_sndbuf 4194304
>>     kworker/u16:5-112   [001] ....  1375.807614: tcp_sendmsg:
>>  sk_wmem_queued 4204872, sk_sndbuf 4194304
>>     kworker/u16:5-112   [001] ....  1377.538744: tcp_sendmsg:
>>  sk_wmem_queued 4204872, sk_sndbuf 4194304
>>     kworker/u16:5-112   [001] ....  1377.543418: tcp_sendmsg:
>>  sk_wmem_queued 4204872, sk_sndbuf 4194304
>>      kworker/2:4H-1535  [002] ....  1377.544685: tcp_sendmsg:
>>  sk_wmem_queued 4204872, sk_sndbuf 4194304
>>     kworker/u16:5-112   [000] ....  1379.378352: tcp_sendmsg:
>>  sk_wmem_queued 4205796, sk_sndbuf 4194304
>>     kworker/u16:5-112   [003] ....  1380.985721: tcp_sendmsg:
>>  sk_wmem_queued 4212416, sk_sndbuf 4194304
>> 
>>  This is as far as I've gotten and I'll keep digging into it, but I 
>> was
>>  wondering if this looks familiar to anybody?  Also one thing I've
>>  noticed is sk_stream_wait_memory() will wait on sk_sleep(sk), but
>>  basically nothing wakes this up.  For example it seems the main way 
>> we
>>  reduce sk_wmem_queued is through sk_wmem_free_skb(), which doesn't
>>  appear to wake anything up in any of its callers, so anybody who 
>> does
>>  end up sleeping will basically never wake up.  That seems like it
>>  should be more broken than it is, so I'm curious to know how things 
>> are
>>  actually woken up in this case.  Thanks,
> 
> 
> git grep -n SOCK_QUEUE_SHRUNK
> 
> -> tcp_check_space()

But tcp_check_space() doesn't actually reduce sk_wmem_queued from what 
I can see.  The only places that appear to reduce it are tcp_trim_head, 
which is only called in the retransmit path, and sk_wmem_free_skb, 
which seems to be right, but I added a trace_printk() in it to see if 
it was firing during my test and it never fires.  So we _appear_ to 
only ever be incrementing this counter, but never decrementing it.  I'm 
doing a bunch of tracing trying to figure out what is going on here but 
so far nothing is popping which is starting to make me think ftrace is 
broken.  Thanks,

Josef

Re: TCP stops sending packets over loopback on 4.10-rc3?

[Eric Dumazet]

On Wed, 2017-01-25 at 09:14 -0500, Josef Bacik wrote:
> On Tue, Jan 24, 2017 at 9:07 AM, Eric Dumazet <eric.dumazet@gmail.com> 

> > 
> > git grep -n SOCK_QUEUE_SHRUNK
> > 
> > -> tcp_check_space()
> 
> But tcp_check_space() doesn't actually reduce sk_wmem_queued from what 
> I can see.  The only places that appear to reduce it are tcp_trim_head, 
> which is only called in the retransmit path, and sk_wmem_free_skb, 
> which seems to be right,

This is exactly how it works.

We free a bunch of skbs (an ACK can acknowledge dozens of them), and set
the SOCK_QUEUE_SHRUNK.

Then later, tcp_check_space() is called once and check if the bit was
set by a prior call to tcp_trim_head() or full skb freeing.

>  but I added a trace_printk() in it to see if 
> it was firing during my test and it never fires.  So we _appear_ to 
> only ever be incrementing this counter, but never decrementing it.  I'm 
> doing a bunch of tracing trying to figure out what is going on here but 
> so far nothing is popping which is starting to make me think ftrace is 
> broken.  Thanks,
> 

Just to make sure, are you telling use native/standard TCP is broken
over loopback, or is that only when using an additional kernel module ?

Re: TCP stops sending packets over loopback on 4.10-rc3?

[Josef Bacik]

On Wed, Jan 25, 2017 at 9:14 AM, Josef Bacik <jbacik@fb.com> wrote:
> On Tue, Jan 24, 2017 at 9:07 AM, Eric Dumazet 
> <eric.dumazet@gmail.com> wrote:
>> On Tue, 2017-01-24 at 06:20 -0500, Josef Bacik wrote:
>>>  Hello,
>>> 
>>>  I've been trying to test some NBD changes I had made recently and I
>>>  started having packet timeouts.  I traced this down to tcp just
>>>  stopping sending packets after a lot of writing.  All NBD does is 
>>> call
>>>  kernel_sendmsg() with a request struct and some pages when it does
>>>  writes.  I did a bunch of tracing and I've narrowed it down to 
>>> running
>>>  out of sk_wmem_queued space.  In tcp_sendmsg() here
>>> 
>>>  new_segment:
>>>                          /* Allocate new segment. If the interface 
>>> is SG,
>>>                           * allocate skb fitting to single page.
>>>                           */
>>>                          if (!sk_stream_memory_free(sk))
>>>                                  goto wait_for_sndbuf;
>>> 
>>>  we hit this pretty regularly, and eventually just get stuck in
>>>  sk_stream_wait_memory until the timeout ends and we error out
>>>  everything.  Now sk_stream_memory_free checks the sk_wmem_queued 
>>> and
>>>  calls into the sk_prot->stream_memory_free(), so I broke this out 
>>> like
>>>  the following
>>> 
>>> 
>>>      if (sk->sk_wmem_queued >= sk->sk_sndbuf) {
>>>          trace_printk("sk_wmem_queued %d, sk_sndbuf %d\n",
>>>  sk->sk_wmem_queued, sk->sk_sndbuf);
>>>          goto wait_for_sndbuf;
>>>       }
>>>       if (sk->sk_prot->stream_memory_free &&
>>>  !sk->sk_prot->stream_memory_free(sk)) {
>>>          trace_printk("sk_stream_memory_free\n");
>>>          goto wait_for_sndbuf;
>>>       }
>>> 
>>>  And I got this in my tracing
>>> 
>>>     kworker/u16:5-112   [001] ....  1375.637564: tcp_sendmsg:
>>>  sk_wmem_queued 4204872, sk_sndbuf 4194304
>>>     kworker/u16:5-112   [001] ....  1375.639657: tcp_sendmsg:
>>>  sk_wmem_queued 4204872, sk_sndbuf 4194304
>>>     kworker/u16:5-112   [003] ....  1375.641128: tcp_sendmsg:
>>>  sk_wmem_queued 4204872, sk_sndbuf 4194304
>>>     kworker/u16:5-112   [003] ....  1375.643441: tcp_sendmsg:
>>>  sk_wmem_queued 4204872, sk_sndbuf 4194304
>>>     kworker/u16:5-112   [001] ....  1375.807614: tcp_sendmsg:
>>>  sk_wmem_queued 4204872, sk_sndbuf 4194304
>>>     kworker/u16:5-112   [001] ....  1377.538744: tcp_sendmsg:
>>>  sk_wmem_queued 4204872, sk_sndbuf 4194304
>>>     kworker/u16:5-112   [001] ....  1377.543418: tcp_sendmsg:
>>>  sk_wmem_queued 4204872, sk_sndbuf 4194304
>>>      kworker/2:4H-1535  [002] ....  1377.544685: tcp_sendmsg:
>>>  sk_wmem_queued 4204872, sk_sndbuf 4194304
>>>     kworker/u16:5-112   [000] ....  1379.378352: tcp_sendmsg:
>>>  sk_wmem_queued 4205796, sk_sndbuf 4194304
>>>     kworker/u16:5-112   [003] ....  1380.985721: tcp_sendmsg:
>>>  sk_wmem_queued 4212416, sk_sndbuf 4194304
>>> 
>>>  This is as far as I've gotten and I'll keep digging into it, but I 
>>> was
>>>  wondering if this looks familiar to anybody?  Also one thing I've
>>>  noticed is sk_stream_wait_memory() will wait on sk_sleep(sk), but
>>>  basically nothing wakes this up.  For example it seems the main 
>>> way we
>>>  reduce sk_wmem_queued is through sk_wmem_free_skb(), which doesn't
>>>  appear to wake anything up in any of its callers, so anybody who 
>>> does
>>>  end up sleeping will basically never wake up.  That seems like it
>>>  should be more broken than it is, so I'm curious to know how 
>>> things are
>>>  actually woken up in this case.  Thanks,
>> 
>> 
>> git grep -n SOCK_QUEUE_SHRUNK
>> 
>> -> tcp_check_space()
> 
> But tcp_check_space() doesn't actually reduce sk_wmem_queued from 
> what I can see.  The only places that appear to reduce it are 
> tcp_trim_head, which is only called in the retransmit path, and 
> sk_wmem_free_skb, which seems to be right, but I added a 
> trace_printk() in it to see if it was firing during my test and it 
> never fires.  So we _appear_ to only ever be incrementing this 
> counter, but never decrementing it.  I'm doing a bunch of tracing 
> trying to figure out what is going on here but so far nothing is 
> popping which is starting to make me think ftrace is broken.  Thanks,

Nope ftrace isn't broken, I'm just dumb, the space is being reclaimed 
by sk_wmem_free_skb().  So I guess I need to figure out why I stop 
getting ACK's from the other side of the loopback.  Thanks,

Josef

Re: TCP stops sending packets over loopback on 4.10-rc3?

[Eric Dumazet]

On Wed, 2017-01-25 at 09:26 -0500, Josef Bacik wrote:

> Nope ftrace isn't broken, I'm just dumb, the space is being reclaimed 
> by sk_wmem_free_skb().  So I guess I need to figure out why I stop 
> getting ACK's from the other side of the loopback.  Thanks,

ss -temoi dst 127.0.0.1

Might give you some hints, like packets being dropped.

ACK can be delayed if the reader is slow to consume bytes.

Re: TCP stops sending packets over loopback on 4.10-rc3?

[Josef Bacik]

On Wed, 2017-01-25 at 06:39 -0800, Eric Dumazet wrote:
> On Wed, 2017-01-25 at 09:26 -0500, Josef Bacik wrote:
> 
> > 
> > Nope ftrace isn't broken, I'm just dumb, the space is being
> > reclaimed 
> > by sk_wmem_free_skb().  So I guess I need to figure out why I stop 
> > getting ACK's from the other side of the loopback.  Thanks,
> ss -temoi dst 127.0.0.1
> 
> Might give you some hints, like packets being dropped.
> 
> ACK can be delayed if the reader is slow to consume bytes.
> 

Yup looks like I'm getting packet loss for some reason, but the
application is sitting there in recvmsg, so it's not hung and
definitely available for receiving new packets.

ESTAB      0      4124232                                              
                                                          ::1:34044    
                                                                       
                                            ::1:nbd                   t
imer:(on,1min38sec,9) ino:20067 sk:8 <->
         skmem:(r0,rb6291456,t0,tb4194304,f1720,w4204872,o0,bl0) ts
sack cubic wscale:7,7 rto:102912 backoff:9 rtt:0.084/0.038 ato:40
mss:65464 cwnd:1 ssthresh:18 bytes_acked:71964077253
bytes_received:68804409996 segs_out:3882829 segs_in:4092731 send
6234.7Mbps lastsnd:4336 lastrcv:111289 lastack:111299 unacked:28
retrans:1/4277 lost:28 reordering:60 rcv_rtt:1.875 rcv_space:1315136

ESTAB      0      0                                                    
                                                         ::1:nbd       
                                                                       
                                           ::1:34044                 ti
mer:(keepalive,109min,0) ino:19396 sk:2 <->
         skmem:(r0,rb6291456,t0,tb2626560,f0,w0,o0,bl0) ts sack cubic
wscale:7,7 rto:201 rtt:0.279/0.16 ato:40 mss:65464 cwnd:16 ssthresh:9
bytes_acked:68804409996 bytes_received:71964077252 segs_out:4092730
segs_in:3882792 send 30033.7Mbps lastsnd:111286 lastrcv:111307
lastack:111286 retrans:0/3113 reordering:26 rcv_rtt:1 rcv_space:4782816

I traced tcp_enter_loss() and once things stop moving that starts
firing.  That's all I have so far, been busy with other things but I'm
devoting my full attention to this now.  Thanks,

Josef