Groups | Search | Server Info | Keyboard shortcuts | Login | Register [http] [https] [nntp] [nntps]

Groups > linux.kernel > #1620640 > unrolled thread

Re: iov_iter_pipe warning.

Started byAl Viro <viro@ZenIV.linux.org.uk>
First post2017-04-10 21:30 +0200
Last post2017-04-12 02:00 +0200
Articles 8 on this page of 28 — 2 participants

Back to article view | Back to linux.kernel

This discussion starts older than the indexed window; earlier articles aren't shown. The article labeled Started by below is the oldest one visible, not the original post.

Contents

  Re: iov_iter_pipe warning. Al Viro <viro@ZenIV.linux.org.uk> - 2017-04-10 21:30 +0200
    Re: iov_iter_pipe warning. Dave Jones <davej@codemonkey.org.uk> - 2017-04-10 21:50 +0200
      Re: iov_iter_pipe warning. Al Viro <viro@ZenIV.linux.org.uk> - 2017-04-10 22:00 +0200
        Re: iov_iter_pipe warning. Dave Jones <davej@codemonkey.org.uk> - 2017-04-11 01:50 +0200
          Re: iov_iter_pipe warning. Al Viro <viro@ZenIV.linux.org.uk> - 2017-04-11 02:30 +0200
            Re: iov_iter_pipe warning. Dave Jones <davej@codemonkey.org.uk> - 2017-04-11 05:10 +0200
              Re: iov_iter_pipe warning. Al Viro <viro@ZenIV.linux.org.uk> - 2017-04-11 05:30 +0200
                Re: iov_iter_pipe warning. Dave Jones <davej@codemonkey.org.uk> - 2017-04-11 23:00 +0200
                  Re: iov_iter_pipe warning. Al Viro <viro@ZenIV.linux.org.uk> - 2017-04-11 23:20 +0200
                    Re: iov_iter_pipe warning. Dave Jones <davej@codemonkey.org.uk> - 2017-04-12 00:30 +0200
                      Re: iov_iter_pipe warning. Al Viro <viro@ZenIV.linux.org.uk> - 2017-04-12 01:30 +0200
                        Re: iov_iter_pipe warning. Dave Jones <davej@codemonkey.org.uk> - 2017-04-12 01:40 +0200
                          Re: iov_iter_pipe warning. Al Viro <viro@ZenIV.linux.org.uk> - 2017-04-12 01:50 +0200
                        Re: iov_iter_pipe warning. Dave Jones <davej@codemonkey.org.uk> - 2017-04-12 01:50 +0200
                          Re: iov_iter_pipe warning. Al Viro <viro@ZenIV.linux.org.uk> - 2017-04-12 02:00 +0200
                            Re: iov_iter_pipe warning. Dave Jones <davej@codemonkey.org.uk> - 2017-04-12 02:10 +0200
                              Re: iov_iter_pipe warning. Al Viro <viro@ZenIV.linux.org.uk> - 2017-04-12 02:20 +0200
                                Re: iov_iter_pipe warning. Dave Jones <davej@codemonkey.org.uk> - 2017-04-12 03:00 +0200
                                  Re: iov_iter_pipe warning. Al Viro <viro@ZenIV.linux.org.uk> - 2017-04-12 03:20 +0200
                                    Re: iov_iter_pipe warning. Dave Jones <davej@codemonkey.org.uk> - 2017-04-12 04:30 +0200
                                      Re: iov_iter_pipe warning. Al Viro <viro@ZenIV.linux.org.uk> - 2017-04-12 05:00 +0200
                                        Re: iov_iter_pipe warning. Dave Jones <davej@codemonkey.org.uk> - 2017-04-12 16:40 +0200
                                          Re: iov_iter_pipe warning. Al Viro <viro@ZenIV.linux.org.uk> - 2017-04-12 17:30 +0200
                                            Re: iov_iter_pipe warning. Dave Jones <davej@codemonkey.org.uk> - 2017-04-12 18:30 +0200
                                              Re: iov_iter_pipe warning. Al Viro <viro@ZenIV.linux.org.uk> - 2017-04-12 19:10 +0200
                                                Re: iov_iter_pipe warning. Dave Jones <davej@codemonkey.org.uk> - 2017-04-12 21:10 +0200
                                                  Re: iov_iter_pipe warning. Al Viro <viro@ZenIV.linux.org.uk> - 2017-04-21 21:10 +0200
                          Re: iov_iter_pipe warning. Al Viro <viro@ZenIV.linux.org.uk> - 2017-04-12 02:00 +0200

Page 2 of 2 — ← Prev page 1 [2]

#1621755

FromAl Viro <viro@ZenIV.linux.org.uk>
Date2017-04-12 05:00 +0200
Message-ID<tvgFH-7hv-5@gated-at.bofh.it>
In reply to#1621748
On Tue, Apr 11, 2017 at 10:29:11PM -0400, Dave Jones wrote:
> On Wed, Apr 12, 2017 at 02:15:32AM +0100, Al Viro wrote:
>  > On Tue, Apr 11, 2017 at 08:58:53PM -0400, Dave Jones wrote:
>  > > [  462.696557] in->f_op = ffffffffa02df980, ->splice_write = ffffffff812b2b20
>  > > $ grep ffffffffa02df980 /proc/kallsyms 
>  > > ffffffffa02df980 r nfs4_file_operations	[nfsv4]
>  > > $ grep ffffffff812b2b20 /proc/kallsyms 
>  > > ffffffff812b2b20 T iter_file_splice_write
>  > 
>  > Let's try to figure out whether it's read or write side going wrong.
>  > 
>  > diff --git a/fs/splice.c b/fs/splice.c
>  > index 006ba50f4ece..0a7c0bd3e164 100644
>  > --- a/fs/splice.c
>  > +++ b/fs/splice.c
>  > @@ -970,10 +970,26 @@ ssize_t splice_direct_to_actor(struct file *in, struct splice_desc *sd,
>  >  	while (len) {
>  >  		size_t read_len;
>  >  		loff_t pos = sd->pos, prev_pos = pos;
>  > +		if (WARN_ON(pipe->nrbufs)) {
>  > +			printk(KERN_ERR "in->f_op = %p, ->splice_write = %p\n",
>  > +				in->f_op,
>  > +				sd->u.file->f_op->splice_write);
>  > +		}
>  >  
>  >  		ret = do_splice_to(in, &pos, pipe, len, flags);
>  >  		if (unlikely(ret <= 0))
>  >  			goto out_release;
>  > +		{
>  > +			int idx = pipe->curbuf;
>  > +			int n = pipe->nrbufs;
>  > +			size_t size = 0;
>  > +			while (n--) {
>  > +				size += pipe->bufs[idx++].len;
>  > +				if (idx == pipe->buffers)
>  > +					idx = 0;
>  > +			}
>  > +			WARN_ON(size != ret);
>  > +		}
>  >  
>  >  		read_len = ret;
>  >  		sd->total_len = read_len;
> 
> WARNING: CPU: 0 PID: 21500 at fs/splice.c:985 splice_direct_to_actor+0x13f/0x280
> CPU: 0 PID: 21500 Comm: trinity-c4 Not tainted 4.11.0-rc6-think+ #10 
> Call Trace:
>  dump_stack+0x68/0x93
>  __warn+0xcb/0xf0
>  warn_slowpath_null+0x1d/0x20
>  splice_direct_to_actor+0x13f/0x280
>  ? generic_pipe_buf_nosteal+0x10/0x10
>  do_splice_direct+0x9e/0xd0
>  do_sendfile+0x1d7/0x3c0
>  SyS_sendfile64+0x73/0xe0
>  do_syscall_64+0x66/0x1d0
>  entry_SYSCALL64_slow_path+0x25/0x25
> RIP: 0033:0x7febc78b30f9
> RSP: 002b:00007ffd767b6398 EFLAGS: 00000246
>   ORIG_RAX: 0000000000000028
> RAX: ffffffffffffffda RBX: 0000000000000028 RCX: 00007febc78b30f9
> RDX: 00007febc5c1e000 RSI: 0000000000000130 RDI: 0000000000000130
> RBP: 00007febc7f66000 R08: 0000000000000ff1 R09: fffffffffffffffd
> R10: 0000000000000008 R11: 0000000000000246 R12: 0000000000000002
> R13: 00007febc7f66048 R14: 00007febc7f89ad8 R15: 00007febc7f66000
> ---[ end trace d002d06d5879c8a9 ]---
> in->f_op = ffffffffa02df980, ->splice_write = ffffffff812b2b20
> 
> This time around it locked up completely. Weird.

No idea about the lockup, but this definitely looks like the read side being
bogus.  Let's try this:

diff --git a/fs/splice.c b/fs/splice.c
index 006ba50f4ece..73ff284fb20f 100644
--- a/fs/splice.c
+++ b/fs/splice.c
@@ -284,6 +284,41 @@ void splice_shrink_spd(struct splice_pipe_desc *spd)
 	kfree(spd->partial);
 }
 
+static void test_it(struct pipe_inode_info *pipe, size_t len, long ret)
+{
+	int idx = pipe->curbuf;
+	int n = pipe->nrbufs;
+	size_t size = 0;
+	while (n--) {
+		size += pipe->bufs[idx++].len;
+		if (idx == pipe->buffers)
+			idx = 0;
+	}
+	if (WARN_ON(size != ret)) {
+		char c = '[';
+		printk(KERN_ERR "asked to read %zu, claims to have read %ld",
+			len, ret);
+		printk(KERN_CONT "actual size of data in pipe %zd ", size);
+		for (n = pipe->nrbufs, idx = pipe->curbuf; n--; ) {
+			printk(KERN_CONT "%c%d:%u", c, idx,
+				pipe->bufs[idx].len);
+			c = ',';
+			if (++idx == pipe->buffers)
+				idx = 0;
+		}
+		if (c == ' ')
+			printk(KERN_CONT "]");
+	}
+}
+
+static inline void insane_splice_read(struct pipe_inode_info *pipe,
+					size_t len, long ret)
+{
+	if (ret <= 0 || pipe != current->splice_pipe)
+		return;
+	test_it(pipe, len, ret);
+}
+
 /**
  * generic_file_splice_read - splice data from file to a pipe
  * @in:		file to splice from
@@ -313,6 +348,7 @@ ssize_t generic_file_splice_read(struct file *in, loff_t *ppos,
 	if (ret > 0) {
 		*ppos = kiocb.ki_pos;
 		file_accessed(in);
+		insane_splice_read(pipe, len, ret);
 	} else if (ret < 0) {
 		to.idx = idx;
 		to.iov_offset = 0;
@@ -394,7 +430,7 @@ static ssize_t default_file_splice_read(struct file *in, loff_t *ppos,
 	struct page **pages;
 	unsigned int nr_pages;
 	size_t offset, dummy, copied = 0;
-	ssize_t res;
+	ssize_t res, old_len = len;
 	int i;
 
 	if (pipe->nrbufs == pipe->buffers)
@@ -448,6 +484,7 @@ static ssize_t default_file_splice_read(struct file *in, loff_t *ppos,
 		put_page(pages[i]);
 	kvfree(pages);
 	iov_iter_advance(&to, copied);	/* truncates and discards */
+	insane_splice_read(pipe, old_len, res);
 	return res;
 }
 
@@ -970,6 +1007,11 @@ ssize_t splice_direct_to_actor(struct file *in, struct splice_desc *sd,
 	while (len) {
 		size_t read_len;
 		loff_t pos = sd->pos, prev_pos = pos;
+		if (WARN_ON(pipe->nrbufs)) {
+			printk(KERN_ERR "in->f_op = %p, ->splice_write = %p\n",
+				in->f_op,
+				sd->u.file->f_op->splice_write);
+		}
 
 		ret = do_splice_to(in, &pos, pipe, len, flags);
 		if (unlikely(ret <= 0))

[toc] | [prev] | [next] | [standalone]

#1622185

FromDave Jones <davej@codemonkey.org.uk>
Date2017-04-12 16:40 +0200
Message-ID<tvrB8-5Bn-11@gated-at.bofh.it>
In reply to#1621755
On Wed, Apr 12, 2017 at 03:58:42AM +0100, Al Viro wrote:
 > On Tue, Apr 11, 2017 at 10:29:11PM -0400, Dave Jones wrote:
 > > On Wed, Apr 12, 2017 at 02:15:32AM +0100, Al Viro wrote:
 > >  > On Tue, Apr 11, 2017 at 08:58:53PM -0400, Dave Jones wrote:
 > >  > > [  462.696557] in->f_op = ffffffffa02df980, ->splice_write = ffffffff812b2b20
 > >  > > $ grep ffffffffa02df980 /proc/kallsyms 
 > >  > > ffffffffa02df980 r nfs4_file_operations	[nfsv4]
 > >  > > $ grep ffffffff812b2b20 /proc/kallsyms 
 > >  > > ffffffff812b2b20 T iter_file_splice_write
 > >  > 
 > >  > Let's try to figure out whether it's read or write side going wrong.

[ 4139.722363] WARNING: CPU: 0 PID: 30536 at fs/splice.c:297 test_it+0x7b/0x100
[ 4139.734795] CPU: 0 PID: 30536 Comm: trinity-c2 Not tainted 4.11.0-rc6-think+ #12 
[ 4139.759574] Call Trace:
[ 4139.771840]  dump_stack+0x68/0x93
[ 4139.784062]  __warn+0xcb/0xf0
[ 4139.796127]  warn_slowpath_null+0x1d/0x20
[ 4139.808062]  test_it+0x7b/0x100
[ 4139.819903]  generic_file_splice_read+0x19b/0x1b0
[ 4139.831728]  do_splice_to+0x79/0x90
[ 4139.843547]  splice_direct_to_actor+0xc6/0x280
[ 4139.855329]  ? generic_pipe_buf_nosteal+0x10/0x10
[ 4139.867021]  do_splice_direct+0x9e/0xd0
[ 4139.878681]  do_sendfile+0x1d7/0x3c0
[ 4139.890349]  SyS_sendfile64+0x73/0xe0
[ 4139.902019]  do_syscall_64+0x66/0x1d0
[ 4139.913592]  entry_SYSCALL64_slow_path+0x25/0x25
[ 4139.925225] RIP: 0033:0x7f279ed980f9
[ 4139.936749] RSP: 002b:00007ffe5f42b858 EFLAGS: 00000246
[ 4139.948230]  ORIG_RAX: 0000000000000028
[ 4139.959677] RAX: ffffffffffffffda RBX: 0000000000000028 RCX: 00007f279ed980f9
[ 4139.971180] RDX: 00007f279cb03000 RSI: 0000000000000185 RDI: 000000000000011a
[ 4139.982653] RBP: 00007f279f459000 R08: 0000005353535353 R09: ffffffff8100ffff
[ 4139.994080] R10: 0000000000000008 R11: 0000000000000246 R12: 0000000000000002
[ 4140.005511] R13: 00007f279f459048 R14: 00007f279f46ead8 R15: 00007f279f459000
[ 4140.016837]  ? intel_pmu_lbr_read+0x4bf/0x5f0
[ 4140.028389] ---[ end trace d074a8823fe244d3 ]---
[ 4140.040002] asked to read 8, claims to have read 4
[ 4140.051634] actual size of data in pipe 8 
[ 4140.063234] [0:8
[ 4140.074673] ------------[ cut here ]------------
[ 4140.085985] WARNING: CPU: 3 PID: 30536 at fs/splice.c:1010 splice_direct_to_actor+0x13f/0x280
[ 4140.097406] CPU: 3 PID: 30536 Comm: trinity-c2 Tainted: G        W       4.11.0-rc6-think+ #12 
[ 4140.120382] Call Trace:
[ 4140.131729]  dump_stack+0x68/0x93
[ 4140.143030]  __warn+0xcb/0xf0
[ 4140.154376]  warn_slowpath_null+0x1d/0x20
[ 4140.165606]  splice_direct_to_actor+0x13f/0x280
[ 4140.176794]  ? generic_pipe_buf_nosteal+0x10/0x10
[ 4140.187934]  do_splice_direct+0x9e/0xd0
[ 4140.199033]  do_sendfile+0x1d7/0x3c0
[ 4140.210084]  SyS_sendfile64+0x73/0xe0
[ 4140.221122]  do_syscall_64+0x66/0x1d0
[ 4140.232137]  entry_SYSCALL64_slow_path+0x25/0x25
[ 4140.243192] RIP: 0033:0x7f279ed980f9
[ 4140.254194] RSP: 002b:00007ffe5f42b858 EFLAGS: 00000246
[ 4140.265156]  ORIG_RAX: 0000000000000028
[ 4140.276084] RAX: ffffffffffffffda RBX: 0000000000000028 RCX: 00007f279ed980f9
[ 4140.287186] RDX: 00007f279cb03000 RSI: 0000000000000185 RDI: 000000000000011a
[ 4140.298229] RBP: 00007f279f459000 R08: 0000005353535353 R09: ffffffff8100ffff
[ 4140.309236] R10: 0000000000000008 R11: 0000000000000246 R12: 0000000000000002
[ 4140.320077] R13: 00007f279f459048 R14: 00007f279f46ead8 R15: 00007f279f459000
[ 4140.330891]  ? intel_pmu_lbr_read+0x4bf/0x5f0
[ 4140.342955] ---[ end trace d074a8823fe244d4 ]---
[ 4140.353868] in->f_op = ffffffffa02dc980, ->splice_write = ffffffff812b2c20

[toc] | [prev] | [next] | [standalone]

#1622243

FromAl Viro <viro@ZenIV.linux.org.uk>
Date2017-04-12 17:30 +0200
Message-ID<tvsnw-680-15@gated-at.bofh.it>
In reply to#1622185
On Wed, Apr 12, 2017 at 10:35:19AM -0400, Dave Jones wrote:

> [ 4140.040002] asked to read 8, claims to have read 4
> [ 4140.051634] actual size of data in pipe 8 
> [ 4140.063234] [0:8

> [ 4140.342955] ---[ end trace d074a8823fe244d4 ]---
> [ 4140.353868] in->f_op = ffffffffa02dc980, ->splice_write = ffffffff812b2c20

IOW, we just had someone's ->read_iter() return 4 after having deposited 8
bytes.  The next question is which file_operations had that been, whether
it was O_DIRECT or not and where in file had we been reading from...

diff --git a/fs/splice.c b/fs/splice.c
index 006ba50f4ece..0e67ddf8618d 100644
--- a/fs/splice.c
+++ b/fs/splice.c
@@ -284,6 +284,43 @@ void splice_shrink_spd(struct splice_pipe_desc *spd)
 	kfree(spd->partial);
 }
 
+static bool test_it(struct pipe_inode_info *pipe, size_t len, long ret)
+{
+	int idx = pipe->curbuf;
+	int n = pipe->nrbufs;
+	size_t size = 0;
+	while (n--) {
+		size += pipe->bufs[idx++].len;
+		if (idx == pipe->buffers)
+			idx = 0;
+	}
+	if (WARN_ON(size != ret)) {
+		char c = '[';
+		printk(KERN_ERR "asked to read %zu, claims to have read %ld",
+			len, ret);
+		printk(KERN_CONT "actual size of data in pipe %zd ", size);
+		for (n = pipe->nrbufs, idx = pipe->curbuf; n--; ) {
+			printk(KERN_CONT "%c%d:%u", c, idx,
+				pipe->bufs[idx].len);
+			c = ',';
+			if (++idx == pipe->buffers)
+				idx = 0;
+		}
+		if (c != '[')
+			printk(KERN_CONT "]");
+		return true;
+	}
+	return false;
+}
+
+static inline bool insane_splice_read(struct pipe_inode_info *pipe,
+					size_t len, long ret)
+{
+	if (ret <= 0 || pipe != current->splice_pipe)
+		return false;
+	return test_it(pipe, len, ret);
+}
+
 /**
  * generic_file_splice_read - splice data from file to a pipe
  * @in:		file to splice from
@@ -311,8 +348,14 @@ ssize_t generic_file_splice_read(struct file *in, loff_t *ppos,
 	kiocb.ki_pos = *ppos;
 	ret = call_read_iter(in, &kiocb, &to);
 	if (ret > 0) {
-		*ppos = kiocb.ki_pos;
 		file_accessed(in);
+		if (unlikely(insane_splice_read(pipe, len, ret))) {
+			printk(KERN_ERR "f_op: %p, f_flags: %d, pos: %lld/%lld, size: %lld",
+				in->f_op, in->f_flags, (long long)*ppos,
+				(long long)kiocb.ki_pos,
+				(long long)i_size_read(file_inode(in)));
+		}
+		*ppos = kiocb.ki_pos;
 	} else if (ret < 0) {
 		to.idx = idx;
 		to.iov_offset = 0;
@@ -394,7 +437,7 @@ static ssize_t default_file_splice_read(struct file *in, loff_t *ppos,
 	struct page **pages;
 	unsigned int nr_pages;
 	size_t offset, dummy, copied = 0;
-	ssize_t res;
+	ssize_t res, old_len = len;
 	int i;
 
 	if (pipe->nrbufs == pipe->buffers)
@@ -448,6 +491,7 @@ static ssize_t default_file_splice_read(struct file *in, loff_t *ppos,
 		put_page(pages[i]);
 	kvfree(pages);
 	iov_iter_advance(&to, copied);	/* truncates and discards */
+	insane_splice_read(pipe, old_len, res);
 	return res;
 }
 
@@ -970,6 +1014,11 @@ ssize_t splice_direct_to_actor(struct file *in, struct splice_desc *sd,
 	while (len) {
 		size_t read_len;
 		loff_t pos = sd->pos, prev_pos = pos;
+		if (WARN_ON(pipe->nrbufs)) {
+			printk(KERN_ERR "in->f_op = %p, ->splice_write = %p\n",
+				in->f_op,
+				sd->u.file->f_op->splice_write);
+		}
 
 		ret = do_splice_to(in, &pos, pipe, len, flags);
 		if (unlikely(ret <= 0))

[toc] | [prev] | [next] | [standalone]

#1622296

FromDave Jones <davej@codemonkey.org.uk>
Date2017-04-12 18:30 +0200
Message-ID<tvtjA-6IX-15@gated-at.bofh.it>
In reply to#1622243
On Wed, Apr 12, 2017 at 04:26:00PM +0100, Al Viro wrote:
 > On Wed, Apr 12, 2017 at 10:35:19AM -0400, Dave Jones wrote:
 > 
 > > [ 4140.040002] asked to read 8, claims to have read 4
 > > [ 4140.051634] actual size of data in pipe 8 
 > > [ 4140.063234] [0:8
 > 
 > > [ 4140.342955] ---[ end trace d074a8823fe244d4 ]---
 > > [ 4140.353868] in->f_op = ffffffffa02dc980, ->splice_write = ffffffff812b2c20
 > 
 > IOW, we just had someone's ->read_iter() return 4 after having deposited 8
 > bytes.  The next question is which file_operations had that been, whether
 > it was O_DIRECT or not and where in file had we been reading from...

[ 1010.008906] WARNING: CPU: 2 PID: 15216 at fs/splice.c:297 test_it+0x7d/0x120
[ 1010.021094] CPU: 2 PID: 15216 Comm: trinity-c5 Not tainted 4.11.0-rc6-think+ #13 
[ 1010.045849] Call Trace:
[ 1010.058136]  dump_stack+0x68/0x93
[ 1010.070379]  __warn+0xcb/0xf0
[ 1010.082473]  warn_slowpath_null+0x1d/0x20
[ 1010.094489]  test_it+0x7d/0x120
[ 1010.106443]  generic_file_splice_read+0x19a/0x1e0
[ 1010.118337]  do_splice_to+0x79/0x90
[ 1010.130161]  splice_direct_to_actor+0xc6/0x280
[ 1010.142032]  ? generic_pipe_buf_nosteal+0x10/0x10
[ 1010.153871]  do_splice_direct+0x9e/0xd0
[ 1010.165687]  do_sendfile+0x1d7/0x3c0
[ 1010.177442]  SyS_sendfile64+0x73/0xe0
[ 1010.189128]  do_syscall_64+0x66/0x1d0
[ 1010.200743]  entry_SYSCALL64_slow_path+0x25/0x25
[ 1010.212287] RIP: 0033:0x7f1bda69d0f9
[ 1010.223883] RSP: 002b:00007ffede478db8 EFLAGS: 00000246
[ 1010.235516]  ORIG_RAX: 0000000000000028
[ 1010.247115] RAX: ffffffffffffffda RBX: 0000000000000028 RCX: 00007f1bda69d0f9
[ 1010.258850] RDX: 00007f1bdac39000 RSI: 0000000000000186 RDI: 0000000000000186
[ 1010.270550] RBP: 00007f1bdad49000 R08: ffffe5d6e7f7c7f4 R09: 0000000092d54252
[ 1010.282174] R10: 0000000000200000 R11: 0000000000000246 R12: 0000000000000002
[ 1010.293781] R13: 00007f1bdad49048 R14: 00007f1bdad73ad8 R15: 00007f1bdad49000
[ 1010.305695] ---[ end trace 048fab9469c0948e ]---
[ 1010.317696] asked to read 2097152, claims to have read 7025
[ 1010.329471] actual size of data in pipe 65536 
[ 1010.341162] [0:4096
[ 1010.353232] ,1:4096
[ 1010.364402] ,2:4096
[ 1010.375608] ,3:4096
[ 1010.386346] ,4:4096
[ 1010.397027] ,5:4096
[ 1010.407611] ,6:4096
[ 1010.418010] ,7:4096
[ 1010.428533] ,8:4096
[ 1010.438885] ,9:4096
[ 1010.449269] ,10:4096
[ 1010.459462] ,11:4096
[ 1010.469519] ,12:4096
[ 1010.479326] ,13:4096
[ 1010.489093] ,14:4096
[ 1010.498711] ,15:4096
[ 1010.508217] ]
[ 1010.517570] f_op: ffffffffa0242980, f_flags: 311298, pos: 11/7036, size: 7036

[toc] | [prev] | [next] | [standalone]

#1622381

FromAl Viro <viro@ZenIV.linux.org.uk>
Date2017-04-12 19:10 +0200
Message-ID<tvtWi-7dn-21@gated-at.bofh.it>
In reply to#1622296
On Wed, Apr 12, 2017 at 12:27:09PM -0400, Dave Jones wrote:

> [ 1010.317696] asked to read 2097152, claims to have read 7025
> [ 1010.329471] actual size of data in pipe 65536 
> [ 1010.341162] [0:4096
> [ 1010.353232] ,1:4096
> [ 1010.364402] ,2:4096
> [ 1010.375608] ,3:4096
> [ 1010.386346] ,4:4096
> [ 1010.397027] ,5:4096
> [ 1010.407611] ,6:4096
> [ 1010.418010] ,7:4096
> [ 1010.428533] ,8:4096
> [ 1010.438885] ,9:4096
> [ 1010.449269] ,10:4096
> [ 1010.459462] ,11:4096
> [ 1010.469519] ,12:4096
> [ 1010.479326] ,13:4096
> [ 1010.489093] ,14:4096
> [ 1010.498711] ,15:4096
> [ 1010.508217] ]
> [ 1010.517570] f_op: ffffffffa0242980, f_flags: 311298, pos: 11/7036, size: 7036

	OK, I see what's going on.  Could you check if the following stops
the warnings?  It's not the final variant of fix - there's no need to copy
the entire iov_iter, it's just that the primitive needed to deal with that
in cleaner way is still not in mainline - davem has pulled it into
net.git, but that was after the latest pull from net.git into mainline.

	For now it should at least tell whether there's something else
going on, though:

diff --git a/fs/nfs/direct.c b/fs/nfs/direct.c
index aab32fc3d6a8..d1633753a1a8 100644
--- a/fs/nfs/direct.c
+++ b/fs/nfs/direct.c
@@ -568,6 +568,7 @@ ssize_t nfs_file_direct_read(struct kiocb *iocb, struct iov_iter *iter)
 	struct nfs_lock_context *l_ctx;
 	ssize_t result = -EINVAL;
 	size_t count = iov_iter_count(iter);
+	struct iov_iter data;
 	nfs_add_stats(mapping->host, NFSIOS_DIRECTREADBYTES, count);
 
 	dfprintk(FILE, "NFS: direct read(%pD2, %zd@%Ld)\n",
@@ -600,14 +601,17 @@ ssize_t nfs_file_direct_read(struct kiocb *iocb, struct iov_iter *iter)
 	nfs_start_io_direct(inode);
 
 	NFS_I(inode)->read_io += count;
-	result = nfs_direct_read_schedule_iovec(dreq, iter, iocb->ki_pos);
+	data = *iter;
+	result = nfs_direct_read_schedule_iovec(dreq, &data, iocb->ki_pos);
 
 	nfs_end_io_direct(inode);
 
 	if (!result) {
 		result = nfs_direct_wait(dreq);
-		if (result > 0)
+		if (result > 0) {
+			iov_iter_advance(iter, result);
 			iocb->ki_pos += result;
+		}
 	}
 
 out_release:

[toc] | [prev] | [next] | [standalone]

#1622488

FromDave Jones <davej@codemonkey.org.uk>
Date2017-04-12 21:10 +0200
Message-ID<tvvOq-8oz-17@gated-at.bofh.it>
In reply to#1622381
On Wed, Apr 12, 2017 at 06:07:23PM +0100, Al Viro wrote:
 > On Wed, Apr 12, 2017 at 12:27:09PM -0400, Dave Jones wrote:
 > 
 > > [ 1010.317696] asked to read 2097152, claims to have read 7025
 > > [ 1010.329471] actual size of data in pipe 65536 
 > > [ 1010.341162] [0:4096
 > > [ 1010.353232] ,1:4096
 > > [ 1010.364402] ,2:4096
 > > [ 1010.375608] ,3:4096
 > > [ 1010.386346] ,4:4096
 > > [ 1010.397027] ,5:4096
 > > [ 1010.407611] ,6:4096
 > > [ 1010.418010] ,7:4096
 > > [ 1010.428533] ,8:4096
 > > [ 1010.438885] ,9:4096
 > > [ 1010.449269] ,10:4096
 > > [ 1010.459462] ,11:4096
 > > [ 1010.469519] ,12:4096
 > > [ 1010.479326] ,13:4096
 > > [ 1010.489093] ,14:4096
 > > [ 1010.498711] ,15:4096
 > > [ 1010.508217] ]
 > > [ 1010.517570] f_op: ffffffffa0242980, f_flags: 311298, pos: 11/7036, size: 7036
 > 
 > 	OK, I see what's going on.  Could you check if the following stops
 > the warnings?  It's not the final variant of fix - there's no need to copy
 > the entire iov_iter, it's just that the primitive needed to deal with that
 > in cleaner way is still not in mainline - davem has pulled it into
 > net.git, but that was after the latest pull from net.git into mainline.
 > 
 > 	For now it should at least tell whether there's something else
 > going on, though:

Well it's been running an hour without incident, which looks promising.
I'll leave it run, but I'd say you're on the right track given how quick
it reproduced so far.

	Dave

[toc] | [prev] | [next] | [standalone]

#1628517

FromAl Viro <viro@ZenIV.linux.org.uk>
Date2017-04-21 21:10 +0200
Message-ID<tyM6m-1aE-23@gated-at.bofh.it>
In reply to#1622488
On Wed, Apr 12, 2017 at 03:03:18PM -0400, Dave Jones wrote:

> Well it's been running an hour without incident, which looks promising.
> I'll leave it run, but I'd say you're on the right track given how quick
> it reproduced so far.

Could you try this and see if it works?  What happens is that unlike
e.g. generic_file_read_iter/generic_file_write_iter, NFS O_DIRECT handling
does not make sure that iov_iter had been advanced by the amount
actually transferred - it is left advanced by the amount *requested*.

mm/filemap.c code gets around that by taking a copy of iov_iter, feeding
it to ->direct_IO() and then advancing the original by the amount actually
done.  That's what the previous patch had duplicated for NFS, but we have
a cleaner way to do that now - both for NFS and in mm/filemap.c.  Namely,
use iov_iter_revert().  For NFS it means making nfs_direct_..._schedule_iovec()
return how much it has actually requested from server and having their
callers do iov_iter_revert() after nfs_direct_wait() has reported how much
has actually come through.  I've similar patches for mm/filemap.c avoiding
the games with copy of iov_iter there, but those are not fixes per se,
so they are separate.  This one just deals with NFS.

fix nfs O_DIRECT advancing iov_iter too much
    
It leaves the iterator advanced by the amount of IO it has requested
instead of the amount actually transferred.  Among other things,
that confuses the hell out of generic_file_splice_read().

Signed-off-by: Al Viro <viro@zeniv.linux.org.uk>

diff --git a/fs/nfs/direct.c b/fs/nfs/direct.c
index aab32fc3d6a8..c1b5fed7c863 100644
--- a/fs/nfs/direct.c
+++ b/fs/nfs/direct.c
@@ -537,7 +537,7 @@ static ssize_t nfs_direct_read_schedule_iovec(struct nfs_direct_req *dreq,
 
 	if (put_dreq(dreq))
 		nfs_direct_complete(dreq);
-	return 0;
+	return requested_bytes;
 }
 
 /**
@@ -566,7 +566,7 @@ ssize_t nfs_file_direct_read(struct kiocb *iocb, struct iov_iter *iter)
 	struct inode *inode = mapping->host;
 	struct nfs_direct_req *dreq;
 	struct nfs_lock_context *l_ctx;
-	ssize_t result = -EINVAL;
+	ssize_t result = -EINVAL, requested;
 	size_t count = iov_iter_count(iter);
 	nfs_add_stats(mapping->host, NFSIOS_DIRECTREADBYTES, count);
 
@@ -600,14 +600,19 @@ ssize_t nfs_file_direct_read(struct kiocb *iocb, struct iov_iter *iter)
 	nfs_start_io_direct(inode);
 
 	NFS_I(inode)->read_io += count;
-	result = nfs_direct_read_schedule_iovec(dreq, iter, iocb->ki_pos);
+	requested = nfs_direct_read_schedule_iovec(dreq, iter, iocb->ki_pos);
 
 	nfs_end_io_direct(inode);
 
-	if (!result) {
+	if (requested > 0) {
 		result = nfs_direct_wait(dreq);
-		if (result > 0)
+		if (result > 0) {
+			requested -= result;
 			iocb->ki_pos += result;
+		}
+		iov_iter_revert(iter, requested);
+	} else {
+		result = requested;
 	}
 
 out_release:
@@ -954,7 +959,7 @@ static ssize_t nfs_direct_write_schedule_iovec(struct nfs_direct_req *dreq,
 
 	if (put_dreq(dreq))
 		nfs_direct_write_complete(dreq);
-	return 0;
+	return requested_bytes;
 }
 
 /**
@@ -979,7 +984,7 @@ static ssize_t nfs_direct_write_schedule_iovec(struct nfs_direct_req *dreq,
  */
 ssize_t nfs_file_direct_write(struct kiocb *iocb, struct iov_iter *iter)
 {
-	ssize_t result = -EINVAL;
+	ssize_t result = -EINVAL, requested;
 	size_t count;
 	struct file *file = iocb->ki_filp;
 	struct address_space *mapping = file->f_mapping;
@@ -1022,7 +1027,7 @@ ssize_t nfs_file_direct_write(struct kiocb *iocb, struct iov_iter *iter)
 
 	nfs_start_io_direct(inode);
 
-	result = nfs_direct_write_schedule_iovec(dreq, iter, pos);
+	requested = nfs_direct_write_schedule_iovec(dreq, iter, pos);
 
 	if (mapping->nrpages) {
 		invalidate_inode_pages2_range(mapping,
@@ -1031,13 +1036,17 @@ ssize_t nfs_file_direct_write(struct kiocb *iocb, struct iov_iter *iter)
 
 	nfs_end_io_direct(inode);
 
-	if (!result) {
+	if (requested > 0) {
 		result = nfs_direct_wait(dreq);
 		if (result > 0) {
+			requested -= result;
 			iocb->ki_pos = pos + result;
 			/* XXX: should check the generic_write_sync retval */
 			generic_write_sync(iocb, result);
 		}
+		iov_iter_revert(iter, requested);
+	} else {
+		result = requested;
 	}
 out_release:
 	nfs_direct_req_release(dreq);

[toc] | [prev] | [next] | [standalone]

#1621703

FromAl Viro <viro@ZenIV.linux.org.uk>
Date2017-04-12 02:00 +0200
Message-ID<tvdRw-5mf-7@gated-at.bofh.it>
In reply to#1621695
On Tue, Apr 11, 2017 at 07:45:58PM -0400, Dave Jones wrote:
>  > 	if (file->f_op->splice_write == generic_splice_sendpage) {
>  > 		struct socket *sock = file->private_data;
>  > 		printk(KERN_ERR "socket [%d, %p]\n", sock->type, sock->ops);
>  > 	}
>  > 	printk(KERN_ERR "in->f_op = %p\n", in->f_op);
> 
> Ugh, this explodes with a million errors when I try to compile it. 
> It misses socket definition, and include <linux/net.h> causes another
> cascade of errors about linkage.h and nonsense.

Ignore the socket part - you've already triggered it with NFS file as
destination, so this is not particularly interesting.  I would still like
to see in->f_op and even more - the checks in default_file_splice_read().

[toc] | [prev] | [standalone]

Page 2 of 2 — ← Prev page 1 [2]

Back to top | Article view | linux.kernel

csiph-web