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