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


Groups > linux.kernel > #1721953 > unrolled thread

Re: iov_iter_pipe warning.

Started byDave Jones <davej@codemonkey.org.uk>
First post2017-08-28 22:40 +0200
Last post2017-09-10 05:00 +0200
Articles 12 — 4 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. Dave Jones <davej@codemonkey.org.uk> - 2017-08-28 22:40 +0200
    Re: iov_iter_pipe warning. "Darrick J. Wong" <darrick.wong@oracle.com> - 2017-08-29 06:30 +0200
      Re: iov_iter_pipe warning. Dave Jones <davej@codemonkey.org.uk> - 2017-08-30 19:10 +0200
        Re: iov_iter_pipe warning. "Darrick J. Wong" <darrick.wong@oracle.com> - 2017-08-30 19:20 +0200
          Re: iov_iter_pipe warning. Dave Jones <davej@codemonkey.org.uk> - 2017-08-30 19:20 +0200
      Re: iov_iter_pipe warning. Dave Jones <davej@codemonkey.org.uk> - 2017-09-06 22:10 +0200
        Re: iov_iter_pipe warning. Dave Chinner <david@fromorbit.com> - 2017-09-07 01:50 +0200
          Re: iov_iter_pipe warning. Dave Jones <davej@codemonkey.org.uk> - 2017-09-07 05:50 +0200
            Re: iov_iter_pipe warning. Al Viro <viro@ZenIV.linux.org.uk> - 2017-09-07 06:40 +0200
          Re: iov_iter_pipe warning. Al Viro <viro@ZenIV.linux.org.uk> - 2017-09-08 03:10 +0200
            Re: iov_iter_pipe warning. Dave Jones <davej@codemonkey.org.uk> - 2017-09-10 03:10 +0200
              Re: iov_iter_pipe warning. Al Viro <viro@ZenIV.linux.org.uk> - 2017-09-10 05:00 +0200

#1721953 — Re: iov_iter_pipe warning.

FromDave Jones <davej@codemonkey.org.uk>
Date2017-08-28 22:40 +0200
SubjectRe: iov_iter_pipe warning.
Message-ID<ujyZc-1HG-37@gated-at.bofh.it>
On Mon, Aug 07, 2017 at 04:18:18PM -0400, Dave Jones wrote:
 > On Fri, Apr 28, 2017 at 06:20:25PM +0100, Al Viro wrote:
 >  > On Fri, Apr 28, 2017 at 12:50:24PM -0400, Dave Jones wrote:
 >  > > currently running v4.11-rc8-75-gf83246089ca0
 >  > > 
 >  > > sunrpc bit is for the other unrelated problem I'm chasing.
 >  > > 
 >  > > note also, I saw the backtrace without the fs/splice.c changes.
 >  > 
 >  > 	Interesting...  Could you add this and see if that triggers?
 >  > 
 >  > diff --git a/fs/splice.c b/fs/splice.c
 >  > index 540c4a44756c..12a12d9c313f 100644
 >  > --- a/fs/splice.c
 >  > +++ b/fs/splice.c
 >  > @@ -306,6 +306,9 @@ 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) {
 >  > +		if (WARN_ON(iov_iter_count(&to) != len - ret))
 >  > +			printk(KERN_ERR "ops %p: was %zd, left %zd, returned %d\n",
 >  > +				in->f_op, len, iov_iter_count(&to), ret);
 >  >  		*ppos = kiocb.ki_pos;
 >  >  		file_accessed(in);
 >  >  	} else if (ret < 0) {
 > 
 > Hey Al,
 >  Due to a git stash screw up on my part, I've had this leftover WARN_ON
 > in my tree for the last couple months. (That screw-up might turn out to be
 > serendipitous if this is a real bug..)
 > 
 > Today I decided to change things up and beat up on xfs for a change, and
 > was able to trigger this again.
 > 
 > Is this check no longer valid, or am I triggering the same bug we were chased
 > down in nfs, but now in xfs ?  (None of the other detritus from that debugging
 > back in April made it, just those three lines above).

Revisiting this. I went back and dug out some of the other debug diffs [1]
from that old thread.

I can easily trigger this spew on xfs.


WARNING: CPU: 1 PID: 2251 at fs/splice.c:292 test_it+0xd4/0x1d0
CPU: 1 PID: 2251 Comm: trinity-c42 Not tainted 4.13.0-rc7-think+ #1 
task: ffff880459173a40 task.stack: ffff88044f7d0000
RIP: 0010:test_it+0xd4/0x1d0
RSP: 0018:ffff88044f7d7878 EFLAGS: 00010283
RAX: 0000000000000000 RBX: ffff88044f44b968 RCX: ffffffff81511ea0
RDX: 0000000000000003 RSI: dffffc0000000000 RDI: ffff88044f44ba68
RBP: ffff88044f7d78c8 R08: ffff88046b218ec0 R09: 0000000000000000
R10: ffff88044f7d7518 R11: 0000000000000000 R12: 0000000000001000
R13: 0000000000000001 R14: 00000000ffffffff R15: 0000000000000001
FS:  00007fdbc09b2700(0000) GS:ffff88046b200000(0000) knlGS:0000000000000000
CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
CR2: 0000000000000000 CR3: 0000000459e1d000 CR4: 00000000001406e0
Call Trace:
 generic_file_splice_read+0x414/0x4e0
 ? opipe_prep.part.14+0x180/0x180
 ? lockdep_init_map+0xb2/0x2b0
 ? rw_verify_area+0x65/0x150
 do_splice_to+0xab/0xc0
 splice_direct_to_actor+0x1f5/0x540
 ? generic_pipe_buf_nosteal+0x10/0x10
 ? do_splice_to+0xc0/0xc0
 ? rw_verify_area+0x9d/0x150
 do_splice_direct+0x1b9/0x230
 ? splice_direct_to_actor+0x540/0x540
 ? __sb_start_write+0x164/0x1c0
 ? do_sendfile+0x7b3/0x840
 do_sendfile+0x428/0x840
 ? do_compat_pwritev64+0xb0/0xb0
 ? __might_sleep+0x72/0xe0
 ? kasan_check_write+0x14/0x20
 SyS_sendfile64+0xa4/0x120
 ? SyS_sendfile+0x150/0x150
 ? mark_held_locks+0x23/0xb0
 ? do_syscall_64+0xc0/0x3e0
 ? SyS_sendfile+0x150/0x150
 do_syscall_64+0x1bc/0x3e0
 ? syscall_return_slowpath+0x240/0x240
 ? mark_held_locks+0x23/0xb0
 ? return_from_SYSCALL_64+0x2d/0x7a
 ? trace_hardirqs_on_caller+0x182/0x260
 ? trace_hardirqs_on_thunk+0x1a/0x1c
 entry_SYSCALL64_slow_path+0x25/0x25
RIP: 0033:0x7fdbc02dd219
RSP: 002b:00007ffc5024fa48 EFLAGS: 00000246
 ORIG_RAX: 0000000000000028
RAX: ffffffffffffffda RBX: 0000000000000028 RCX: 00007fdbc02dd219
RDX: 00007fdbbe348000 RSI: 0000000000000011 RDI: 0000000000000015
RBP: 00007ffc5024faf0 R08: 000000000000006d R09: 0094e82f2c730a50
R10: 0000000000001000 R11: 0000000000000246 R12: 0000000000000002
R13: 00007fdbc0885058 R14: 00007fdbc09b2698 R15: 00007fdbc0885000
---[ end trace a5847ef0f7be7e20 ]---
asked to read 4096, claims to have read 1
actual size of data in pipe 4096 
[0:4096]
f_op: ffffffffa058c920, f_flags: 49154, pos: 0/1, size: 0


I'm still trying to narrow down an exact reproducer, but it seems having
trinity do a combination of sendfile & writev, with pipes and regular
files as fd's is the best repro.

Is this a real problem, or am I chasing ghosts ?  That it doesn't happen
on ext4 or btrfs is making me wonder...

	Dave


[1] https://lkml.org/lkml/2017/4/11/921

[toc] | [next] | [standalone]


#1722132

From"Darrick J. Wong" <darrick.wong@oracle.com>
Date2017-08-29 06:30 +0200
Message-ID<ujGk1-6l8-1@gated-at.bofh.it>
In reply to#1721953
On Mon, Aug 28, 2017 at 04:31:30PM -0400, Dave Jones wrote:
> On Mon, Aug 07, 2017 at 04:18:18PM -0400, Dave Jones wrote:
>  > On Fri, Apr 28, 2017 at 06:20:25PM +0100, Al Viro wrote:
>  >  > On Fri, Apr 28, 2017 at 12:50:24PM -0400, Dave Jones wrote:
>  >  > > currently running v4.11-rc8-75-gf83246089ca0
>  >  > > 
>  >  > > sunrpc bit is for the other unrelated problem I'm chasing.
>  >  > > 
>  >  > > note also, I saw the backtrace without the fs/splice.c changes.
>  >  > 
>  >  > 	Interesting...  Could you add this and see if that triggers?
>  >  > 
>  >  > diff --git a/fs/splice.c b/fs/splice.c
>  >  > index 540c4a44756c..12a12d9c313f 100644
>  >  > --- a/fs/splice.c
>  >  > +++ b/fs/splice.c
>  >  > @@ -306,6 +306,9 @@ 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) {
>  >  > +		if (WARN_ON(iov_iter_count(&to) != len - ret))
>  >  > +			printk(KERN_ERR "ops %p: was %zd, left %zd, returned %d\n",
>  >  > +				in->f_op, len, iov_iter_count(&to), ret);
>  >  >  		*ppos = kiocb.ki_pos;
>  >  >  		file_accessed(in);
>  >  >  	} else if (ret < 0) {
>  > 
>  > Hey Al,
>  >  Due to a git stash screw up on my part, I've had this leftover WARN_ON
>  > in my tree for the last couple months. (That screw-up might turn out to be
>  > serendipitous if this is a real bug..)
>  > 
>  > Today I decided to change things up and beat up on xfs for a change, and
>  > was able to trigger this again.
>  > 
>  > Is this check no longer valid, or am I triggering the same bug we were chased
>  > down in nfs, but now in xfs ?  (None of the other detritus from that debugging
>  > back in April made it, just those three lines above).
> 
> Revisiting this. I went back and dug out some of the other debug diffs [1]
> from that old thread.
> 
> I can easily trigger this spew on xfs.
> 
> 
> WARNING: CPU: 1 PID: 2251 at fs/splice.c:292 test_it+0xd4/0x1d0
> CPU: 1 PID: 2251 Comm: trinity-c42 Not tainted 4.13.0-rc7-think+ #1 
> task: ffff880459173a40 task.stack: ffff88044f7d0000
> RIP: 0010:test_it+0xd4/0x1d0
> RSP: 0018:ffff88044f7d7878 EFLAGS: 00010283
> RAX: 0000000000000000 RBX: ffff88044f44b968 RCX: ffffffff81511ea0
> RDX: 0000000000000003 RSI: dffffc0000000000 RDI: ffff88044f44ba68
> RBP: ffff88044f7d78c8 R08: ffff88046b218ec0 R09: 0000000000000000
> R10: ffff88044f7d7518 R11: 0000000000000000 R12: 0000000000001000
> R13: 0000000000000001 R14: 00000000ffffffff R15: 0000000000000001
> FS:  00007fdbc09b2700(0000) GS:ffff88046b200000(0000) knlGS:0000000000000000
> CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
> CR2: 0000000000000000 CR3: 0000000459e1d000 CR4: 00000000001406e0
> Call Trace:
>  generic_file_splice_read+0x414/0x4e0
>  ? opipe_prep.part.14+0x180/0x180
>  ? lockdep_init_map+0xb2/0x2b0
>  ? rw_verify_area+0x65/0x150
>  do_splice_to+0xab/0xc0
>  splice_direct_to_actor+0x1f5/0x540
>  ? generic_pipe_buf_nosteal+0x10/0x10
>  ? do_splice_to+0xc0/0xc0
>  ? rw_verify_area+0x9d/0x150
>  do_splice_direct+0x1b9/0x230
>  ? splice_direct_to_actor+0x540/0x540
>  ? __sb_start_write+0x164/0x1c0
>  ? do_sendfile+0x7b3/0x840
>  do_sendfile+0x428/0x840
>  ? do_compat_pwritev64+0xb0/0xb0
>  ? __might_sleep+0x72/0xe0
>  ? kasan_check_write+0x14/0x20
>  SyS_sendfile64+0xa4/0x120
>  ? SyS_sendfile+0x150/0x150
>  ? mark_held_locks+0x23/0xb0
>  ? do_syscall_64+0xc0/0x3e0
>  ? SyS_sendfile+0x150/0x150
>  do_syscall_64+0x1bc/0x3e0
>  ? syscall_return_slowpath+0x240/0x240
>  ? mark_held_locks+0x23/0xb0
>  ? return_from_SYSCALL_64+0x2d/0x7a
>  ? trace_hardirqs_on_caller+0x182/0x260
>  ? trace_hardirqs_on_thunk+0x1a/0x1c
>  entry_SYSCALL64_slow_path+0x25/0x25
> RIP: 0033:0x7fdbc02dd219
> RSP: 002b:00007ffc5024fa48 EFLAGS: 00000246
>  ORIG_RAX: 0000000000000028
> RAX: ffffffffffffffda RBX: 0000000000000028 RCX: 00007fdbc02dd219
> RDX: 00007fdbbe348000 RSI: 0000000000000011 RDI: 0000000000000015
> RBP: 00007ffc5024faf0 R08: 000000000000006d R09: 0094e82f2c730a50
> R10: 0000000000001000 R11: 0000000000000246 R12: 0000000000000002
> R13: 00007fdbc0885058 R14: 00007fdbc09b2698 R15: 00007fdbc0885000
> ---[ end trace a5847ef0f7be7e20 ]---
> asked to read 4096, claims to have read 1
> actual size of data in pipe 4096 
> [0:4096]
> f_op: ffffffffa058c920, f_flags: 49154, pos: 0/1, size: 0
> 
> 
> I'm still trying to narrow down an exact reproducer, but it seems having
> trinity do a combination of sendfile & writev, with pipes and regular
> files as fd's is the best repro.
> 
> Is this a real problem, or am I chasing ghosts ?  That it doesn't happen
> on ext4 or btrfs is making me wonder...

<shrug> I haven't heard of any problems w/ directio xfs lately, but OTOH
I think it's the only filesystem that uses iomap_dio_rw, which would
explain why ext4/btrfs don't have this problem.

Granted that's idle speculation; is there a reproducer/xfstest for this?

--D

> 
> 	Dave
> 
> 
> [1] https://lkml.org/lkml/2017/4/11/921
> 
> --
> To unsubscribe from this list: send the line "unsubscribe linux-xfs" in
> the body of a message to majordomo@vger.kernel.org
> More majordomo info at  http://vger.kernel.org/majordomo-info.html

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


#1723515

FromDave Jones <davej@codemonkey.org.uk>
Date2017-08-30 19:10 +0200
Message-ID<ukeF5-2E4-31@gated-at.bofh.it>
In reply to#1722132
On Mon, Aug 28, 2017 at 09:25:42PM -0700, Darrick J. Wong wrote:
 > On Mon, Aug 28, 2017 at 04:31:30PM -0400, Dave Jones wrote:
 > > On Mon, Aug 07, 2017 at 04:18:18PM -0400, Dave Jones wrote:
 > >  > On Fri, Apr 28, 2017 at 06:20:25PM +0100, Al Viro wrote:
 > >  >  > On Fri, Apr 28, 2017 at 12:50:24PM -0400, Dave Jones wrote:
 > >  >  > 
 > >  >  > diff --git a/fs/splice.c b/fs/splice.c
 > >  >  > index 540c4a44756c..12a12d9c313f 100644
 > >  >  > --- a/fs/splice.c
 > >  >  > +++ b/fs/splice.c
 > >  >  > @@ -306,6 +306,9 @@ 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) {
 > >  >  > +		if (WARN_ON(iov_iter_count(&to) != len - ret))
 > >  >  > +			printk(KERN_ERR "ops %p: was %zd, left %zd, returned %d\n",
 > >  >  > +				in->f_op, len, iov_iter_count(&to), ret);
 > >  >  >  		*ppos = kiocb.ki_pos;
 > >  >  >  		file_accessed(in);
 > >  >  >  	} else if (ret < 0) {
 > >  > 
 > >  > Hey Al,
 > >  >  Due to a git stash screw up on my part, I've had this leftover WARN_ON
 > >  > in my tree for the last couple months. (That screw-up might turn out to be
 > >  > serendipitous if this is a real bug..)
 > >  > 
 > >  > Today I decided to change things up and beat up on xfs for a change, and
 > >  > was able to trigger this again.
 > >  > 
 > >  > Is this check no longer valid, or am I triggering the same bug we were chased
 > >  > down in nfs, but now in xfs ?  (None of the other detritus from that debugging
 > >  > back in April made it, just those three lines above).
 > > 
 > > Revisiting this. I went back and dug out some of the other debug diffs [1]
 > > from that old thread.
 > > 
 > > I can easily trigger this spew on xfs.
 > > 
 > > ...
 > >
 > > asked to read 4096, claims to have read 1
 > > actual size of data in pipe 4096 
 > > [0:4096]
 > > f_op: ffffffffa058c920, f_flags: 49154, pos: 0/1, size: 0
 > > 
 > > 
 > > I'm still trying to narrow down an exact reproducer, but it seems having
 > > trinity do a combination of sendfile & writev, with pipes and regular
 > > files as fd's is the best repro.
 > > 
 > > Is this a real problem, or am I chasing ghosts ?  That it doesn't happen
 > > on ext4 or btrfs is making me wonder...
 > 
 > <shrug> I haven't heard of any problems w/ directio xfs lately, but OTOH
 > I think it's the only filesystem that uses iomap_dio_rw, which would
 > explain why ext4/btrfs don't have this problem.
 > 
 > Granted that's idle speculation; is there a reproducer/xfstest for this?

I reverted the debug patches mentioned above, and ran trinity for a while again,
and got this which smells really suspiciously related

WARNING: CPU: 1 PID: 10380 at fs/iomap.c:993 iomap_dio_rw+0x825/0x840
CPU: 1 PID: 10380 Comm: trinity-c30 Not tainted 4.13.0-rc7-think+ #3 
task: ffff8804613a5740 task.stack: ffff880432120000
RIP: 0010:iomap_dio_rw+0x825/0x840
RSP: 0018:ffff880432127890 EFLAGS: 00010286
RAX: 00000000fffffff0 RBX: ffff88046a64d0e8 RCX: 0000000000000000
RDX: ffffed0086424e9b RSI: 0000000000000000 RDI: ffffed0086424f03
RBP: ffff880432127a70 R08: ffff88046b239840 R09: 0000000000000001
R10: ffff880432126f50 R11: 0000000000000000 R12: ffff880432127c40
R13: 0000000000000e0a R14: 1ffff10086424f20 R15: ffff880432127ca0
FS:  00007f4cda32f700(0000) GS:ffff88046b200000(0000) knlGS:0000000000000000
CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
CR2: 00007f181e02f000 CR3: 000000043d32a000 CR4: 00000000001406e0
Call Trace:
 ? iomap_seek_data+0xc0/0xc0
 ? down_read_non_owner+0x40/0x40
 ? xfs_ilock+0x3f2/0x490 [xfs]
 ? touch_atime+0x9c/0x180
 ? __atime_needs_update+0x440/0x440
 xfs_file_dio_aio_read+0x12d/0x390 [xfs]
 ? xfs_file_dio_aio_read+0x12d/0x390 [xfs]
 ? xfs_file_fallocate+0x660/0x660 [xfs]
 ? cyc2ns_read_end+0x10/0x10
 xfs_file_read_iter+0x1bb/0x1d0 [xfs]
 __vfs_read+0x332/0x440
 ? default_llseek+0x140/0x140
 ? cyc2ns_read_end+0x10/0x10
 ? __fget_light+0x1ae/0x230
 ? rcu_is_watching+0x8d/0xd0
 ? exit_to_usermode_loop+0x1b0/0x1b0
 ? rw_verify_area+0x9d/0x150
 vfs_read+0xc8/0x1c0
 SyS_pread64+0x11a/0x140
 ? SyS_write+0x160/0x160
 ? do_syscall_64+0xc0/0x3e0
 ? SyS_write+0x160/0x160
 do_syscall_64+0x1bc/0x3e0
 ? syscall_return_slowpath+0x240/0x240
 ? cpumask_check.part.2+0x10/0x10
 ? cpumask_check.part.2+0x10/0x10
 ? mark_held_locks+0x23/0xb0
 ? return_from_SYSCALL_64+0x2d/0x7a
 ? trace_hardirqs_on_caller+0x182/0x260
 ? trace_hardirqs_on_thunk+0x1a/0x1c
 entry_SYSCALL64_slow_path+0x25/0x25
RIP: 0033:0x7f4cd9c5a219
RSP: 002b:00007ffce0d90888 EFLAGS: 00000246
 ORIG_RAX: 0000000000000011
RAX: ffffffffffffffda RBX: 0000000000000011 RCX: 00007f4cd9c5a219
RDX: 0000000000000e0a RSI: 00007f4cd7ec5000 RDI: 000000000000000f
RBP: 00007ffce0d90930 R08: fffffffffffffffd R09: 000000000000001b
R10: 0000000000000002 R11: 0000000000000246 R12: 0000000000000002
R13: 00007f4cda256058 R14: 00007f4cda32f698 R15: 00007f4cda256000
Code: 83 bd 78 08 00 00 00 f 85 8e fd ff ff 4c 89 ef e8 d1 46 fa ff 85 c0 89 c2 0f 89 7c fd ff ff 31 c0 f0 0f b1 53 28 e9 70 fd ff ff <0f> ff e9 82 fc ff ff 48 c7 c1 f4 ff ff ff e9 0d f9 ff ff e8 93 
---[ end trace 2f6189daedf1df6e ]---



That's this..

 987         ret = filemap_write_and_wait_range(mapping, start, end);
 988         if (ret)
 989                 goto out_free_dio;
 990 
 991         ret = invalidate_inode_pages2_range(mapping,
 992                         start >> PAGE_SHIFT, end >> PAGE_SHIFT);
 993         WARN_ON_ONCE(ret);


Plot thickens..

	Dave

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


#1723523

From"Darrick J. Wong" <darrick.wong@oracle.com>
Date2017-08-30 19:20 +0200
Message-ID<ukeOK-2Hq-19@gated-at.bofh.it>
In reply to#1723515
On Wed, Aug 30, 2017 at 01:05:23PM -0400, Dave Jones wrote:
> On Mon, Aug 28, 2017 at 09:25:42PM -0700, Darrick J. Wong wrote:
>  > On Mon, Aug 28, 2017 at 04:31:30PM -0400, Dave Jones wrote:
>  > > On Mon, Aug 07, 2017 at 04:18:18PM -0400, Dave Jones wrote:
>  > >  > On Fri, Apr 28, 2017 at 06:20:25PM +0100, Al Viro wrote:
>  > >  >  > On Fri, Apr 28, 2017 at 12:50:24PM -0400, Dave Jones wrote:
>  > >  >  > 
>  > >  >  > diff --git a/fs/splice.c b/fs/splice.c
>  > >  >  > index 540c4a44756c..12a12d9c313f 100644
>  > >  >  > --- a/fs/splice.c
>  > >  >  > +++ b/fs/splice.c
>  > >  >  > @@ -306,6 +306,9 @@ 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) {
>  > >  >  > +		if (WARN_ON(iov_iter_count(&to) != len - ret))
>  > >  >  > +			printk(KERN_ERR "ops %p: was %zd, left %zd, returned %d\n",
>  > >  >  > +				in->f_op, len, iov_iter_count(&to), ret);
>  > >  >  >  		*ppos = kiocb.ki_pos;
>  > >  >  >  		file_accessed(in);
>  > >  >  >  	} else if (ret < 0) {
>  > >  > 
>  > >  > Hey Al,
>  > >  >  Due to a git stash screw up on my part, I've had this leftover WARN_ON
>  > >  > in my tree for the last couple months. (That screw-up might turn out to be
>  > >  > serendipitous if this is a real bug..)
>  > >  > 
>  > >  > Today I decided to change things up and beat up on xfs for a change, and
>  > >  > was able to trigger this again.
>  > >  > 
>  > >  > Is this check no longer valid, or am I triggering the same bug we were chased
>  > >  > down in nfs, but now in xfs ?  (None of the other detritus from that debugging
>  > >  > back in April made it, just those three lines above).
>  > > 
>  > > Revisiting this. I went back and dug out some of the other debug diffs [1]
>  > > from that old thread.
>  > > 
>  > > I can easily trigger this spew on xfs.
>  > > 
>  > > ...
>  > >
>  > > asked to read 4096, claims to have read 1
>  > > actual size of data in pipe 4096 
>  > > [0:4096]
>  > > f_op: ffffffffa058c920, f_flags: 49154, pos: 0/1, size: 0
>  > > 
>  > > 
>  > > I'm still trying to narrow down an exact reproducer, but it seems having
>  > > trinity do a combination of sendfile & writev, with pipes and regular
>  > > files as fd's is the best repro.
>  > > 
>  > > Is this a real problem, or am I chasing ghosts ?  That it doesn't happen
>  > > on ext4 or btrfs is making me wonder...
>  > 
>  > <shrug> I haven't heard of any problems w/ directio xfs lately, but OTOH
>  > I think it's the only filesystem that uses iomap_dio_rw, which would
>  > explain why ext4/btrfs don't have this problem.
>  > 
>  > Granted that's idle speculation; is there a reproducer/xfstest for this?
> 
> I reverted the debug patches mentioned above, and ran trinity for a while again,
> and got this which smells really suspiciously related
> 
> WARNING: CPU: 1 PID: 10380 at fs/iomap.c:993 iomap_dio_rw+0x825/0x840
> CPU: 1 PID: 10380 Comm: trinity-c30 Not tainted 4.13.0-rc7-think+ #3 
> task: ffff8804613a5740 task.stack: ffff880432120000
> RIP: 0010:iomap_dio_rw+0x825/0x840
> RSP: 0018:ffff880432127890 EFLAGS: 00010286
> RAX: 00000000fffffff0 RBX: ffff88046a64d0e8 RCX: 0000000000000000
> RDX: ffffed0086424e9b RSI: 0000000000000000 RDI: ffffed0086424f03
> RBP: ffff880432127a70 R08: ffff88046b239840 R09: 0000000000000001
> R10: ffff880432126f50 R11: 0000000000000000 R12: ffff880432127c40
> R13: 0000000000000e0a R14: 1ffff10086424f20 R15: ffff880432127ca0
> FS:  00007f4cda32f700(0000) GS:ffff88046b200000(0000) knlGS:0000000000000000
> CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
> CR2: 00007f181e02f000 CR3: 000000043d32a000 CR4: 00000000001406e0
> Call Trace:
>  ? iomap_seek_data+0xc0/0xc0
>  ? down_read_non_owner+0x40/0x40
>  ? xfs_ilock+0x3f2/0x490 [xfs]
>  ? touch_atime+0x9c/0x180
>  ? __atime_needs_update+0x440/0x440
>  xfs_file_dio_aio_read+0x12d/0x390 [xfs]
>  ? xfs_file_dio_aio_read+0x12d/0x390 [xfs]
>  ? xfs_file_fallocate+0x660/0x660 [xfs]
>  ? cyc2ns_read_end+0x10/0x10
>  xfs_file_read_iter+0x1bb/0x1d0 [xfs]
>  __vfs_read+0x332/0x440
>  ? default_llseek+0x140/0x140
>  ? cyc2ns_read_end+0x10/0x10
>  ? __fget_light+0x1ae/0x230
>  ? rcu_is_watching+0x8d/0xd0
>  ? exit_to_usermode_loop+0x1b0/0x1b0
>  ? rw_verify_area+0x9d/0x150
>  vfs_read+0xc8/0x1c0
>  SyS_pread64+0x11a/0x140
>  ? SyS_write+0x160/0x160
>  ? do_syscall_64+0xc0/0x3e0
>  ? SyS_write+0x160/0x160
>  do_syscall_64+0x1bc/0x3e0
>  ? syscall_return_slowpath+0x240/0x240
>  ? cpumask_check.part.2+0x10/0x10
>  ? cpumask_check.part.2+0x10/0x10
>  ? mark_held_locks+0x23/0xb0
>  ? return_from_SYSCALL_64+0x2d/0x7a
>  ? trace_hardirqs_on_caller+0x182/0x260
>  ? trace_hardirqs_on_thunk+0x1a/0x1c
>  entry_SYSCALL64_slow_path+0x25/0x25
> RIP: 0033:0x7f4cd9c5a219
> RSP: 002b:00007ffce0d90888 EFLAGS: 00000246
>  ORIG_RAX: 0000000000000011
> RAX: ffffffffffffffda RBX: 0000000000000011 RCX: 00007f4cd9c5a219
> RDX: 0000000000000e0a RSI: 00007f4cd7ec5000 RDI: 000000000000000f
> RBP: 00007ffce0d90930 R08: fffffffffffffffd R09: 000000000000001b
> R10: 0000000000000002 R11: 0000000000000246 R12: 0000000000000002
> R13: 00007f4cda256058 R14: 00007f4cda32f698 R15: 00007f4cda256000
> Code: 83 bd 78 08 00 00 00 f 85 8e fd ff ff 4c 89 ef e8 d1 46 fa ff 85 c0 89 c2 0f 89 7c fd ff ff 31 c0 f0 0f b1 53 28 e9 70 fd ff ff <0f> ff e9 82 fc ff ff 48 c7 c1 f4 ff ff ff e9 0d f9 ff ff e8 93 
> ---[ end trace 2f6189daedf1df6e ]---
> 
> 
> 
> That's this..
> 
>  987         ret = filemap_write_and_wait_range(mapping, start, end);
>  988         if (ret)
>  989                 goto out_free_dio;
>  990 
>  991         ret = invalidate_inode_pages2_range(mapping,
>  992                         start >> PAGE_SHIFT, end >> PAGE_SHIFT);
>  993         WARN_ON_ONCE(ret);
> 
> 
> Plot thickens..

Hm, that's the WARN_ON that comes from a failed pagecache invalidation
prior to a dio operation, which implies that something's mixing buffered
and dio?

Given that it's syzkaller it wouldn't surprise me to hear that it's
doing that... :)

--D

> 
> 	Dave
> --
> To unsubscribe from this list: send the line "unsubscribe linux-xfs" in
> the body of a message to majordomo@vger.kernel.org
> More majordomo info at  http://vger.kernel.org/majordomo-info.html

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


#1723525

FromDave Jones <davej@codemonkey.org.uk>
Date2017-08-30 19:20 +0200
Message-ID<ukeOK-2Hq-21@gated-at.bofh.it>
In reply to#1723523
On Wed, Aug 30, 2017 at 10:13:43AM -0700, Darrick J. Wong wrote:


 > > I reverted the debug patches mentioned above, and ran trinity for a while again,
 > > and got this which smells really suspiciously related
 > > 
 > > WARNING: CPU: 1 PID: 10380 at fs/iomap.c:993 iomap_dio_rw+0x825/0x840
 > > RAX: 00000000fffffff0 RBX: ffff88046a64d0e8 RCX: 0000000000000000
 > > 
 > > 
 > > 
 > > That's this..
 > > 
 > >  987         ret = filemap_write_and_wait_range(mapping, start, end);
 > >  988         if (ret)
 > >  989                 goto out_free_dio;
 > >  990 
 > >  991         ret = invalidate_inode_pages2_range(mapping,
 > >  992                         start >> PAGE_SHIFT, end >> PAGE_SHIFT);
 > >  993         WARN_ON_ONCE(ret);
 > > 
 > > 
 > > Plot thickens..
 > 
 > Hm, that's the WARN_ON that comes from a failed pagecache invalidation
 > prior to a dio operation, which implies that something's mixing buffered
 > and dio?

Plausible. Judging by RAX, we got -EBUSY

 > Given that it's syzkaller it wouldn't surprise me to hear that it's
 > doing that... :)

s/syzkaller/trinity/, but yes.

	Dave

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


#1727700

FromDave Jones <davej@codemonkey.org.uk>
Date2017-09-06 22:10 +0200
Message-ID<umOO5-6BS-3@gated-at.bofh.it>
In reply to#1722132
On Mon, Aug 28, 2017 at 09:25:42PM -0700, Darrick J. Wong wrote:
 > On Mon, Aug 28, 2017 at 04:31:30PM -0400, Dave Jones wrote:
 > > On Mon, Aug 07, 2017 at 04:18:18PM -0400, Dave Jones wrote:
 > >  > On Fri, Apr 28, 2017 at 06:20:25PM +0100, Al Viro wrote:
 > >  >  > On Fri, Apr 28, 2017 at 12:50:24PM -0400, Dave Jones wrote:
 > >  >  > > currently running v4.11-rc8-75-gf83246089ca0
 > >  >  > > 
 > >  >  > > sunrpc bit is for the other unrelated problem I'm chasing.
 > >  >  > > 
 > >  >  > > note also, I saw the backtrace without the fs/splice.c changes.
 > >  >  > 
 > >  >  > 	Interesting...  Could you add this and see if that triggers?
 > >  >  > 
 > >  >  > diff --git a/fs/splice.c b/fs/splice.c
 > >  >  > index 540c4a44756c..12a12d9c313f 100644
 > >  >  > --- a/fs/splice.c
 > >  >  > +++ b/fs/splice.c
 > >  >  > @@ -306,6 +306,9 @@ 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) {
 > >  >  > +		if (WARN_ON(iov_iter_count(&to) != len - ret))
 > >  >  > +			printk(KERN_ERR "ops %p: was %zd, left %zd, returned %d\n",
 > >  >  > +				in->f_op, len, iov_iter_count(&to), ret);
 > >  >  >  		*ppos = kiocb.ki_pos;
 > >  >  >  		file_accessed(in);
 > >  >  >  	} else if (ret < 0) {
 > >  > 
 > >  > Hey Al,
 > >  >  Due to a git stash screw up on my part, I've had this leftover WARN_ON
 > >  > in my tree for the last couple months. (That screw-up might turn out to be
 > >  > serendipitous if this is a real bug..)
 > >  > 
 > >  > Today I decided to change things up and beat up on xfs for a change, and
 > >  > was able to trigger this again.
 > >  > 
 > >  > Is this check no longer valid, or am I triggering the same bug we were chased
 > >  > down in nfs, but now in xfs ?  (None of the other detritus from that debugging
 > >  > back in April made it, just those three lines above).
 > > 
 > > Revisiting this. I went back and dug out some of the other debug diffs [1]
 > > from that old thread.
 > > 
 > > I can easily trigger this spew on xfs.
 > > 
 > > 
 > > WARNING: CPU: 1 PID: 2251 at fs/splice.c:292 test_it+0xd4/0x1d0
 > > CPU: 1 PID: 2251 Comm: trinity-c42 Not tainted 4.13.0-rc7-think+ #1 
 > > task: ffff880459173a40 task.stack: ffff88044f7d0000
 > > RIP: 0010:test_it+0xd4/0x1d0
 > > RSP: 0018:ffff88044f7d7878 EFLAGS: 00010283
 > > RAX: 0000000000000000 RBX: ffff88044f44b968 RCX: ffffffff81511ea0
 > > RDX: 0000000000000003 RSI: dffffc0000000000 RDI: ffff88044f44ba68
 > > RBP: ffff88044f7d78c8 R08: ffff88046b218ec0 R09: 0000000000000000
 > > R10: ffff88044f7d7518 R11: 0000000000000000 R12: 0000000000001000
 > > R13: 0000000000000001 R14: 00000000ffffffff R15: 0000000000000001
 > > FS:  00007fdbc09b2700(0000) GS:ffff88046b200000(0000) knlGS:0000000000000000
 > > CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
 > > CR2: 0000000000000000 CR3: 0000000459e1d000 CR4: 00000000001406e0
 > > Call Trace:
 > >  generic_file_splice_read+0x414/0x4e0
 > >  ? opipe_prep.part.14+0x180/0x180
 > >  ? lockdep_init_map+0xb2/0x2b0
 > >  ? rw_verify_area+0x65/0x150
 > >  do_splice_to+0xab/0xc0
 > >  splice_direct_to_actor+0x1f5/0x540
 > >  ? generic_pipe_buf_nosteal+0x10/0x10
 > >  ? do_splice_to+0xc0/0xc0
 > >  ? rw_verify_area+0x9d/0x150
 > >  do_splice_direct+0x1b9/0x230
 > >  ? splice_direct_to_actor+0x540/0x540
 > >  ? __sb_start_write+0x164/0x1c0
 > >  ? do_sendfile+0x7b3/0x840
 > >  do_sendfile+0x428/0x840
 > >  ? do_compat_pwritev64+0xb0/0xb0
 > >  ? __might_sleep+0x72/0xe0
 > >  ? kasan_check_write+0x14/0x20
 > >  SyS_sendfile64+0xa4/0x120
 > >  ? SyS_sendfile+0x150/0x150
 > >  ? mark_held_locks+0x23/0xb0
 > >  ? do_syscall_64+0xc0/0x3e0
 > >  ? SyS_sendfile+0x150/0x150
 > >  do_syscall_64+0x1bc/0x3e0
 > >  ? syscall_return_slowpath+0x240/0x240
 > >  ? mark_held_locks+0x23/0xb0
 > >  ? return_from_SYSCALL_64+0x2d/0x7a
 > >  ? trace_hardirqs_on_caller+0x182/0x260
 > >  ? trace_hardirqs_on_thunk+0x1a/0x1c
 > >  entry_SYSCALL64_slow_path+0x25/0x25
 > > RIP: 0033:0x7fdbc02dd219
 > > RSP: 002b:00007ffc5024fa48 EFLAGS: 00000246
 > >  ORIG_RAX: 0000000000000028
 > > RAX: ffffffffffffffda RBX: 0000000000000028 RCX: 00007fdbc02dd219
 > > RDX: 00007fdbbe348000 RSI: 0000000000000011 RDI: 0000000000000015
 > > RBP: 00007ffc5024faf0 R08: 000000000000006d R09: 0094e82f2c730a50
 > > R10: 0000000000001000 R11: 0000000000000246 R12: 0000000000000002
 > > R13: 00007fdbc0885058 R14: 00007fdbc09b2698 R15: 00007fdbc0885000
 > > ---[ end trace a5847ef0f7be7e20 ]---
 > > asked to read 4096, claims to have read 1
 > > actual size of data in pipe 4096 
 > > [0:4096]
 > > f_op: ffffffffa058c920, f_flags: 49154, pos: 0/1, size: 0
 > > 
 > > 
 > > I'm still trying to narrow down an exact reproducer, but it seems having
 > > trinity do a combination of sendfile & writev, with pipes and regular
 > > files as fd's is the best repro.
 > > 
 > > Is this a real problem, or am I chasing ghosts ?  That it doesn't happen
 > > on ext4 or btrfs is making me wonder...
 > 
 > <shrug> I haven't heard of any problems w/ directio xfs lately, but OTOH
 > I think it's the only filesystem that uses iomap_dio_rw, which would
 > explain why ext4/btrfs don't have this problem.

Another warning, from likely the same root cause.

WARNING: CPU: 3 PID: 572 at lib/iov_iter.c:962 iov_iter_pipe+0xe2/0xf0
CPU: 3 PID: 572 Comm: trinity-c45 Not tainted 4.13.0-think+ #5 
task: ffff88042e5f8040 task.stack: ffff880454cb0000
RIP: 0010:iov_iter_pipe+0xe2/0xf0
RSP: 0018:ffff880454cb7950 EFLAGS: 00010246
RAX: 0000000000000000 RBX: ffff880454cb79c0 RCX: ffffffff818fc581
RDX: 0000000000000003 RSI: dffffc0000000000 RDI: ffff88043f07fa80
RBP: ffff88043f07f968 R08: 0000000000000000 R09: 0000000000000000
R10: ffff880454cb7468 R11: 0000000000000000 R12: 000000000003fff8
R13: 0000000000000010 R14: ffff88043f07fa80 R15: ffff88043f07fa78
FS:  00007fac217a1700(0000) GS:ffff88046b400000(0000) knlGS:0000000000000000
CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
CR2: 0000000000000000 CR3: 000000043f37e001 CR4: 00000000001606e0
Call Trace:
 generic_file_splice_read+0x8d/0x340
 ? pipe_unlock+0x15/0x30
 ? splice_from_pipe+0x10e/0x160
 ? pipe_to_user+0x80/0x80
 ? splice_shrink_spd+0x40/0x40
 ? init_wait_entry+0x100/0x100
 ? rw_verify_area+0x87/0x130
 splice_direct_to_actor+0x186/0x420
 ? generic_pipe_buf_nosteal+0x10/0x10
 ? do_splice_to+0xc0/0xc0
 ? __fget_light+0x181/0x200
 do_splice_direct+0x173/0x1e0
 ? splice_direct_to_actor+0x420/0x420
 ? mark_held_locks+0x1c/0x90
 ? retint_kernel+0x10/0x10
 do_sendfile+0x3a2/0x6d0
 ? do_compat_pwritev64+0xa0/0xa0
 ? copy_user_generic_unrolled+0x83/0xb0
 SyS_sendfile64+0xa4/0x130
 ? SyS_sendfile+0x140/0x140
 ? mark_held_locks+0x1c/0x90
 ? do_syscall_64+0xae/0x3e0
 ? SyS_sendfile+0x140/0x140
 do_syscall_64+0x182/0x3e0
 ? syscall_return_slowpath+0x250/0x250
 ? rcu_read_lock_sched_held+0x90/0xa0
 ? __context_tracking_exit.part.5+0x226/0x290
 ? mark_held_locks+0x1c/0x90
 ? return_from_SYSCALL_64+0x2d/0x7a
 ? trace_hardirqs_on_caller+0x17a/0x250
 ? trace_hardirqs_on_thunk+0x1a/0x1c
 entry_SYSCALL64_slow_path+0x25/0x25
RIP: 0033:0x7fac210cc219
RSP: 002b:00007ffd7fe8ab38 EFLAGS: 00000246
 ORIG_RAX: 0000000000000028
RAX: ffffffffffffffda RBX: 0000000000000028 RCX: 00007fac210cc219
RDX: 00007fac215de000 RSI: 000000000000001b RDI: 000000000000000b
RBP: 00007ffd7fe8abe0 R08: 00000000c8c8c8c8 R09: 00000000000000c9
R10: 0000000000040000 R11: 0000000000000246 R12: 0000000000000002
R13: 00007fac2165f058 R14: 00007fac217a1698 R15: 00007fac2165f000
Code: 10 48 c7 43 08 00 00 00 00 e8 bb 79 b1 ff 4c 89 63 10 48 8d 7b 24 e8 ae 78 b1 ff 89 6b 24 5b 5d 41 5c 41 5d 41 5e 41 5f c3 0f 0b <0f> ff e9 65 ff ff ff 0f 1f 80 00 00 00 00 41 57 41 56 41 55 49 
---[ end trace 4507dec15e49aca7 ]---


 962         WARN_ON(pipe->nrbufs == pipe->buffers);


 

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


#1727826

FromDave Chinner <david@fromorbit.com>
Date2017-09-07 01:50 +0200
Message-ID<umSeZ-dZ-5@gated-at.bofh.it>
In reply to#1727700
On Wed, Sep 06, 2017 at 04:03:37PM -0400, Dave Jones wrote:
> On Mon, Aug 28, 2017 at 09:25:42PM -0700, Darrick J. Wong wrote:
>  > On Mon, Aug 28, 2017 at 04:31:30PM -0400, Dave Jones wrote:
>  > > I'm still trying to narrow down an exact reproducer, but it seems having
>  > > trinity do a combination of sendfile & writev, with pipes and regular
>  > > files as fd's is the best repro.
>  > > 
>  > > Is this a real problem, or am I chasing ghosts ?  That it doesn't happen
>  > > on ext4 or btrfs is making me wonder...
>  > 
>  > <shrug> I haven't heard of any problems w/ directio xfs lately, but OTOH
>  > I think it's the only filesystem that uses iomap_dio_rw, which would
>  > explain why ext4/btrfs don't have this problem.
> 
> Another warning, from likely the same root cause.
> 
> WARNING: CPU: 3 PID: 572 at lib/iov_iter.c:962 iov_iter_pipe+0xe2/0xf0

	WARN_ON(pipe->nrbufs == pipe->buffers);

 *      @nrbufs: the number of non-empty pipe buffers in this pipe
 *      @buffers: total number of buffers (should be a power of 2)

So that's warning that the pipe buffer is already full before we
try to read from the filesystem?

That doesn't seem like an XFS problem - it indicates the pipe we are
filling in generic_file_splice_read() is not being emptied by
whatever we are splicing the file data to....

Cheers,

Dave.
-- 
Dave Chinner
david@fromorbit.com

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


#1727896

FromDave Jones <davej@codemonkey.org.uk>
Date2017-09-07 05:50 +0200
Message-ID<umVZg-2GT-5@gated-at.bofh.it>
In reply to#1727826
On Thu, Sep 07, 2017 at 09:46:17AM +1000, Dave Chinner wrote:
 > On Wed, Sep 06, 2017 at 04:03:37PM -0400, Dave Jones wrote:
 > > On Mon, Aug 28, 2017 at 09:25:42PM -0700, Darrick J. Wong wrote:
 > >  > On Mon, Aug 28, 2017 at 04:31:30PM -0400, Dave Jones wrote:
 > >  > > I'm still trying to narrow down an exact reproducer, but it seems having
 > >  > > trinity do a combination of sendfile & writev, with pipes and regular
 > >  > > files as fd's is the best repro.
 > >  > > 
 > >  > > Is this a real problem, or am I chasing ghosts ?  That it doesn't happen
 > >  > > on ext4 or btrfs is making me wonder...
 > >  > 
 > >  > <shrug> I haven't heard of any problems w/ directio xfs lately, but OTOH
 > >  > I think it's the only filesystem that uses iomap_dio_rw, which would
 > >  > explain why ext4/btrfs don't have this problem.
 > > 
 > > Another warning, from likely the same root cause.
 > > 
 > > WARNING: CPU: 3 PID: 572 at lib/iov_iter.c:962 iov_iter_pipe+0xe2/0xf0
 > 
 > 	WARN_ON(pipe->nrbufs == pipe->buffers);
 > 
 >  *      @nrbufs: the number of non-empty pipe buffers in this pipe
 >  *      @buffers: total number of buffers (should be a power of 2)
 > 
 > So that's warning that the pipe buffer is already full before we
 > try to read from the filesystem?
 > 
 > That doesn't seem like an XFS problem - it indicates the pipe we are
 > filling in generic_file_splice_read() is not being emptied by
 > whatever we are splicing the file data to....

The puzzling part is this runs for a day on ext4 or btrfs, whereas I can
make xfs fall over pretty quickly.  As Darrick pointed out though, this
could be due to xfs being the only user of iomap_dio_rw.

I'm juggling a few other things right now, so probably not going to
have much time to dig further on this until after plumbers + 1 wk.

	Dave

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


#1727904

FromAl Viro <viro@ZenIV.linux.org.uk>
Date2017-09-07 06:40 +0200
Message-ID<umWLD-3ez-3@gated-at.bofh.it>
In reply to#1727896
On Wed, Sep 06, 2017 at 11:48:35PM -0400, Dave Jones wrote:

>  > That doesn't seem like an XFS problem - it indicates the pipe we are
>  > filling in generic_file_splice_read() is not being emptied by
>  > whatever we are splicing the file data to....
> 
> The puzzling part is this runs for a day on ext4 or btrfs, whereas I can
> make xfs fall over pretty quickly.  As Darrick pointed out though, this
> could be due to xfs being the only user of iomap_dio_rw.
> 
> I'm juggling a few other things right now, so probably not going to
> have much time to dig further on this until after plumbers + 1 wk.

I'll look into that tomorrow...

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


#1728523

FromAl Viro <viro@ZenIV.linux.org.uk>
Date2017-09-08 03:10 +0200
Message-ID<unfXX-8dp-3@gated-at.bofh.it>
In reply to#1727826
On Thu, Sep 07, 2017 at 09:46:17AM +1000, Dave Chinner wrote:
> On Wed, Sep 06, 2017 at 04:03:37PM -0400, Dave Jones wrote:
> > On Mon, Aug 28, 2017 at 09:25:42PM -0700, Darrick J. Wong wrote:
> >  > On Mon, Aug 28, 2017 at 04:31:30PM -0400, Dave Jones wrote:
> >  > > I'm still trying to narrow down an exact reproducer, but it seems having
> >  > > trinity do a combination of sendfile & writev, with pipes and regular
> >  > > files as fd's is the best repro.
> >  > > 
> >  > > Is this a real problem, or am I chasing ghosts ?  That it doesn't happen
> >  > > on ext4 or btrfs is making me wonder...
> >  > 
> >  > <shrug> I haven't heard of any problems w/ directio xfs lately, but OTOH
> >  > I think it's the only filesystem that uses iomap_dio_rw, which would
> >  > explain why ext4/btrfs don't have this problem.
> > 
> > Another warning, from likely the same root cause.
> > 
> > WARNING: CPU: 3 PID: 572 at lib/iov_iter.c:962 iov_iter_pipe+0xe2/0xf0
> 
> 	WARN_ON(pipe->nrbufs == pipe->buffers);
> 
>  *      @nrbufs: the number of non-empty pipe buffers in this pipe
>  *      @buffers: total number of buffers (should be a power of 2)
> 
> So that's warning that the pipe buffer is already full before we
> try to read from the filesystem?
> 
> That doesn't seem like an XFS problem - it indicates the pipe we are
> filling in generic_file_splice_read() is not being emptied by
> whatever we are splicing the file data to....

Or that XFS in some conditions shoves into pipe more than it reports,
so not all of that gets emptied, filling the sucker up after sufficient
amount of iterations...

There's at least one suspicious place in iomap_dio_actor() -
                if (!(dio->flags & IOMAP_DIO_WRITE)) {
                        iov_iter_zero(length, dio->submit.iter);
                        dio->size += length;
                        return length;
                }
which assumes that iov_iter_zero() always succeeds.  That's very
much _not_ true - neither for iovec-backed, not for pipe-backed.
Orangefs read_one_page() is fine (it calls that sucker for bvec-backed
iov_iter it's just created), but iomap_dio_actor() is not.

I'm not saying that it will suffice, but we definitely need this:

diff --git a/fs/iomap.c b/fs/iomap.c
index 269b24a01f32..4a671263475f 100644
--- a/fs/iomap.c
+++ b/fs/iomap.c
@@ -843,7 +843,7 @@ iomap_dio_actor(struct inode *inode, loff_t pos, loff_t length,
 		/*FALLTHRU*/
 	case IOMAP_UNWRITTEN:
 		if (!(dio->flags & IOMAP_DIO_WRITE)) {
-			iov_iter_zero(length, dio->submit.iter);
+			length = iov_iter_zero(length, dio->submit.iter);
 			dio->size += length;
 			return length;
 		}

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


#1729893

FromDave Jones <davej@codemonkey.org.uk>
Date2017-09-10 03:10 +0200
Message-ID<unYV3-4ZZ-5@gated-at.bofh.it>
In reply to#1728523
On Fri, Sep 08, 2017 at 02:04:41AM +0100, Al Viro wrote:
 
 > There's at least one suspicious place in iomap_dio_actor() -
 >                 if (!(dio->flags & IOMAP_DIO_WRITE)) {
 >                         iov_iter_zero(length, dio->submit.iter);
 >                         dio->size += length;
 >                         return length;
 >                 }
 > which assumes that iov_iter_zero() always succeeds.  That's very
 > much _not_ true - neither for iovec-backed, not for pipe-backed.
 > Orangefs read_one_page() is fine (it calls that sucker for bvec-backed
 > iov_iter it's just created), but iomap_dio_actor() is not.
 > 
 > I'm not saying that it will suffice, but we definitely need this:
 > 
 > diff --git a/fs/iomap.c b/fs/iomap.c
 > index 269b24a01f32..4a671263475f 100644
 > --- a/fs/iomap.c
 > +++ b/fs/iomap.c
 > @@ -843,7 +843,7 @@ iomap_dio_actor(struct inode *inode, loff_t pos, loff_t length,
 >  		/*FALLTHRU*/
 >  	case IOMAP_UNWRITTEN:
 >  		if (!(dio->flags & IOMAP_DIO_WRITE)) {
 > -			iov_iter_zero(length, dio->submit.iter);
 > +			length = iov_iter_zero(length, dio->submit.iter);
 >  			dio->size += length;
 >  			return length;

With this in place, I'm still seeing -EBUSY from invalidate_inode_pages2_range
which doesn't end well...


WARNING: CPU: 3 PID: 11443 at fs/iomap.c:993 iomap_dio_rw+0x825/0x840
CPU: 3 PID: 11443 Comm: trinity-c39 Not tainted 4.13.0-think+ #9 
task: ffff880461080040 task.stack: ffff88043d720000
RIP: 0010:iomap_dio_rw+0x825/0x840
RSP: 0018:ffff88043d727730 EFLAGS: 00010286
RAX: 00000000fffffff0 RBX: ffff88044f036428 RCX: 0000000000000000
RDX: ffffed0087ae4e67 RSI: 0000000000000000 RDI: ffffed0087ae4ed7
RBP: ffff88043d727910 R08: ffff88046b4176c0 R09: 0000000000000000
R10: ffff88043d726d20 R11: 0000000000000001 R12: ffff88043d727a90
R13: 00000000027253f7 R14: 1ffff10087ae4ef4 R15: ffff88043d727c10
FS:  00007f5d8613e700(0000) GS:ffff88046b400000(0000) knlGS:0000000000000000
CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
CR2: 00007f5d84503000 CR3: 00000004594e1000 CR4: 00000000001606e0
Call Trace:
 ? iomap_seek_data+0xb0/0xb0
 ? down_read_nested+0xd3/0x160
 ? down_read_non_owner+0x40/0x40
 ? xfs_ilock+0x3cb/0x460 [xfs]
 ? sched_clock_cpu+0x14/0xf0
 ? __lock_is_held+0x51/0xc0
 ? xfs_file_dio_aio_read+0x123/0x350 [xfs]
 xfs_file_dio_aio_read+0x123/0x350 [xfs]
 ? xfs_file_fallocate+0x550/0x550 [xfs]
 ? lock_release+0xa00/0xa00
 ? ___might_sleep.part.70+0x118/0x320
 xfs_file_read_iter+0x1b1/0x1d0 [xfs]
 do_iter_readv_writev+0x2ea/0x330
 ? vfs_dedupe_file_range+0x400/0x400
 do_iter_read+0x149/0x280
 vfs_readv+0x107/0x180
 ? vfs_iter_read+0x60/0x60
 ? fget_raw+0x10/0x10
 ? native_sched_clock+0xf9/0x1a0
 ? __fdget_pos+0xd6/0x110
 ? __fdget_pos+0xd6/0x110
 ? __fdget_raw+0x10/0x10
 ? do_readv+0xc0/0x1b0
 do_readv+0xc0/0x1b0
 ? vfs_readv+0x180/0x180
 ? mark_held_locks+0x1c/0x90
 ? do_syscall_64+0xae/0x3e0
 ? compat_rw_copy_check_uvector+0x1b0/0x1b0
 do_syscall_64+0x182/0x3e0
 ? syscall_return_slowpath+0x250/0x250
 ? rcu_read_lock_sched_held+0x90/0xa0
 ? mark_held_locks+0x1c/0x90
 ? return_from_SYSCALL_64+0x2d/0x7a
 ? trace_hardirqs_on_caller+0x17a/0x250
 ? trace_hardirqs_on_thunk+0x1a/0x1c
 entry_SYSCALL64_slow_path+0x25/0x25
RIP: 0033:0x7f5d85a69219
RSP: 002b:00007ffdf090afd8 EFLAGS: 00000246
 ORIG_RAX: 0000000000000013
RAX: ffffffffffffffda RBX: 0000000000000013 RCX: 00007f5d85a69219
RDX: 00000000000000ae RSI: 0000565183cd5490 RDI: 0000000000000056
RBP: 00007ffdf090b080 R08: 0141082b00011c63 R09: 0000000000000000
R10: 00000000ffffe000 R11: 0000000000000246 R12: 0000000000000002
R13: 00007f5d86026058 R14: 00007f5d8613e698 R15: 00007f5d86026000

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


#1729895

FromAl Viro <viro@ZenIV.linux.org.uk>
Date2017-09-10 05:00 +0200
Message-ID<uo0Dv-5VJ-3@gated-at.bofh.it>
In reply to#1729893
On Sat, Sep 09, 2017 at 09:07:56PM -0400, Dave Jones wrote:

> With this in place, I'm still seeing -EBUSY from invalidate_inode_pages2_range
> which doesn't end well...

Different issue, and I'm not sure why that WARN_ON() is there in the
first place.  Note that in a similar situation generic_file_direct_write()
simply buggers off and lets the caller do buffered write...

iov_iter_pipe() warning is a sign of ->read_iter() on pipe-backed iov_iter
putting into the pipe more than it claims to have done.

[toc] | [prev] | [standalone]


Back to top | Article view | linux.kernel


csiph-web