From: Josef Bacik <hidden> Date: 2017-01-24 11:21:03
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
From: Eric Dumazet <hidden> Date: 2017-01-24 14:07:55
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,
From: Josef Bacik <hidden> Date: 2017-01-25 14:14:32
On Tue, Jan 24, 2017 at 9:07 AM, Eric Dumazet [off-list ref]
wrote:
On Tue, 2017-01-24 at 06:20 -0500, Josef Bacik wrote:
quoted
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,
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
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 ?
From: Josef Bacik <hidden> Date: 2017-01-25 14:27:11
On Wed, Jan 25, 2017 at 9:14 AM, Josef Bacik [off-list ref] wrote:
On Tue, Jan 24, 2017 at 9:07 AM, Eric Dumazet
[off-list ref] wrote:
quoted
On Tue, 2017-01-24 at 06:20 -0500, Josef Bacik wrote:
quoted
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,
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
From: Eric Dumazet <hidden> Date: 2017-01-25 14:40:01
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.
From: Josef Bacik <hidden> Date: 2017-01-26 22:00:30
On Wed, 2017-01-25 at 06:39 -0800, Eric Dumazet wrote:
On Wed, 2017-01-25 at 09:26 -0500, Josef Bacik wrote:
quoted
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