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()



Reply via email to