btrfs_direct_IO oops

btrfs_direct_IO oops

[Dave Jones]

Found this in logs this morning. First time I've seen this one.
Might be related to some direct IO related changes I made in Trinity
that is tickling some new path.

Oops: 0000 [#1] PREEMPT SMP DEBUG_PAGEALLOC
CPU: 2 PID: 25313 Comm: trinity-c18 Not tainted 4.8.0-think+ #7 
task: ffff88040f7b1c00 task.stack: ffffc9000076c000
 RIP: 0010:[<ffffffffc0289d5c>] 
  [<ffffffffc0289d5c>] btrfs_direct_IO+0x13c/0x480 [btrfs]
RSP: 0018:ffffc9000076fb40  EFLAGS: 00010202
RAX: 0000000000002580 RBX: 0000000000000258 RCX: 0000000000000018
RDX: 0000000000000000 RSI: ffff8804f4d16868 RDI: ffffc9000076fc40
RBP: ffffc9000076fbd8 R08: 0000000000000001 R09: 0000000000000000
R10: 0000000000000001 R11: 0000000000000006 R12: ffff880300000000
R13: ffff8803643e1a88 R14: 0000000000000001 R15: 0000000000000258
FS:  00007efc0af88b40(0000) GS:ffff880507c00000(0000) knlGS:0000000000000000
CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
CR2: ffff8803643e4008 CR3: 00000003ad69e000 CR4: 00000000001406e0
DR0: 0000006f00200000 DR1: 0000000000000000 DR2: 0000000000000000
DR3: 0000000000000000 DR6: 00000000ffff0ff0 DR7: 0000000000000600
Stack:
  ffff88050174dda0 ffffc9000076fb60 ffff8804ffaab3f8 ffffc9000076fcd8
  0000000000000000 0000000000000001 00000001c93b8050 ffff8804f4d16868
  ffffc9000076fc40 0000000000000000 0000000000000000 0000000000000000
 
Call Trace:
 [<ffffffff89195d9d>] generic_file_read_iter+0x33d/0xce0
 [<ffffffff8920be97>] ? ___slab_alloc.constprop.86+0x277/0x5c0
 [<ffffffff89275edd>] generic_file_splice_read+0xfd/0x230
 [<ffffffff89275de0>] ? pipe_to_user+0x40/0x40
 [<ffffffff892758f8>] do_splice_to+0x98/0xd0
 [<ffffffff89275a04>] splice_direct_to_actor+0xd4/0x2c0
 [<ffffffff89275050>] ? generic_pipe_buf_nosteal+0x10/0x10
 [<ffffffff89275cb5>] do_splice_direct+0xc5/0x110
 [<ffffffff89237c52>] do_sendfile+0x242/0x470
 [<ffffffff89238d2d>] SyS_sendfile64+0x7d/0xf0
 [<ffffffff8900279f>] do_syscall_64+0x7f/0x200
 [<ffffffff899ddbcb>] entry_SYSCALL64_slow_path+0x25/0x25
 Code:  4d 8b 74 1d 00 4d 3b 74 1d 10 74 26 44 89 fb e8 3b de eb c8 83 c3 01 4c 63 fb 4d 39 e7 73 a5 e8 2b de eb c8 4c 89 f8 48 c1 e0 04 <4d> 3b 74 05 00 75 dd 31 db e8 16 de eb c8 48 89 d8 48 8b 7d d0 
 
 RIP 
  [<ffffffffc0289d5c>] btrfs_direct_IO+0x13c/0x480 [btrfs]
 RSP <ffffc9000076fb40>
CR2: ffff8803643e4008


That code: matches this dissembly:

                for (i = seg + 1; i < iter->nr_segs; i++) {
   41d40:       e8 00 00 00 00          callq  41d45 <btrfs_direct_IO+0x125>
   41d45:       83 c3 01                add    $0x1,%ebx
   41d48:       4c 63 fb                movslq %ebx,%r15
   41d4b:       4d 39 e7                cmp    %r12,%r15
   41d4e:       73 a5                   jae    41cf5 <btrfs_direct_IO+0xd5>
                        if (iter->iov[seg].iov_base == iter->iov[i].iov_base)
   41d50:       e8 00 00 00 00          callq  41d55 <btrfs_direct_IO+0x135>
   41d55:       4c 89 f8                mov    %r15,%rax
   41d58:       48 c1 e0 04             shl    $0x4,%rax
   41d5c:       4d 3b 74 05 00          cmp    0x0(%r13,%rax,1),%r14
   41d61:       75 dd                   jne    41d40 <btrfs_direct_IO+0x120>
                return 0;

 

Re: btrfs_direct_IO oops

[Al Viro]

On Sat, Oct 08, 2016 at 02:08:06PM -0400, Dave Jones wrote:
> That code: matches this dissembly:
> 
>                 for (i = seg + 1; i < iter->nr_segs; i++) {

*whoa*

OK, that loop in check_direct_IO() should be done *ONLY* for
iovec iter - even for a bvec one it's completely bogus, and
for pipe ones it blows up immediately.

Sorry, I'd missed that bogosity - replace
        if (iov_iter_rw(iter) == WRITE)
		return 0;
with
	if (iov_iter_rw(iter) != READ || !iter_is_iovec(iter))
		return 0;
in there; that should fix the damn thing.

Re: btrfs_direct_IO oops

[Dave Jones]

On Sat, Oct 08, 2016 at 07:29:03PM +0100, Al Viro wrote:
 > On Sat, Oct 08, 2016 at 02:08:06PM -0400, Dave Jones wrote:
 > > That code: matches this dissembly:
 > > 
 > >                 for (i = seg + 1; i < iter->nr_segs; i++) {
 > 
 > *whoa*
 > 
 > OK, that loop in check_direct_IO() should be done *ONLY* for
 > iovec iter - even for a bvec one it's completely bogus, and
 > for pipe ones it blows up immediately.
 > 
 > Sorry, I'd missed that bogosity - replace
 >         if (iov_iter_rw(iter) == WRITE)
 > 		return 0;
 > with
 > 	if (iov_iter_rw(iter) != READ || !iter_is_iovec(iter))
 > 		return 0;
 > in there; that should fix the damn thing.

Yep, seems to do the trick. Have been running the last six hours
without seeing it or anything similar since.

	Dave

Re: btrfs_direct_IO oops

[Dave Jones]

On Sat, Oct 08, 2016 at 07:20:08PM -0400, Dave Jones wrote:
 > On Sat, Oct 08, 2016 at 07:29:03PM +0100, Al Viro wrote:
 >  > On Sat, Oct 08, 2016 at 02:08:06PM -0400, Dave Jones wrote:
 >  > > That code: matches this dissembly:
 >  > > 
 >  > >                 for (i = seg + 1; i < iter->nr_segs; i++) {
 >  > 
 >  > *whoa*
 >  > 
 >  > OK, that loop in check_direct_IO() should be done *ONLY* for
 >  > iovec iter - even for a bvec one it's completely bogus, and
 >  > for pipe ones it blows up immediately.
 >  > 
 >  > Sorry, I'd missed that bogosity - replace
 >  >         if (iov_iter_rw(iter) == WRITE)
 >  > 		return 0;
 >  > with
 >  > 	if (iov_iter_rw(iter) != READ || !iter_is_iovec(iter))
 >  > 		return 0;
 >  > in there; that should fix the damn thing.
 > 
 > Yep, seems to do the trick. Have been running the last six hours
 > without seeing it or anything similar since.

Overnight, I did hit another iov related warning..

idx = 0, offset = 0
curbuf = 0, nrbufs = 1, buffers = 16
[ffffffff9fa21100 ffffea00065f6d80 0 4096]
[          (null)           (null) 0 0]
[          (null)           (null) 0 0]
[          (null)           (null) 0 0]
[          (null)           (null) 0 0]
[          (null)           (null) 0 0]
[          (null)           (null) 0 0]
[          (null)           (null) 0 0]
[          (null)           (null) 0 0]
[          (null)           (null) 0 0]
[          (null)           (null) 0 0]
[          (null)           (null) 0 0]
[          (null)           (null) 0 0]
[          (null)           (null) 0 0]
[          (null)           (null) 0 0]
[          (null)           (null) 0 0]

WARNING: CPU: 0 PID: 29610 at lib/iov_iter.c:327 sanity+0x102/0x150
CPU: 0 PID: 29610 Comm: trinity-c9 Not tainted 4.8.0-think+ #8 
 ffffc900007b7ae8
 ffffffff9f3e2011
 0000000000000000
 0000000000000000

 ffffffff9fc1e22b
 ffffffff9f3fa2f2
 ffffc900007b7b28
 ffffffff9f08b010

 0000014734c3d60f
 ffffffff9fc1e22b
 0000000000000147
 0000000000000010

Call Trace:
 [<ffffffff9f3e2011>] dump_stack+0x6c/0x9b
 [<ffffffff9f3fa2f2>] ? sanity+0x102/0x150
 [<ffffffff9f08b010>] __warn+0x110/0x130
 [<ffffffff9f08b19c>] warn_slowpath_null+0x2c/0x40
 [<ffffffff9f3fa2f2>] sanity+0x102/0x150
 [<ffffffff9f3fe62e>] copy_page_to_iter+0x2be/0x480
 [<ffffffff9f1932da>] ? pagecache_get_page+0xba/0x4f0
 [<ffffffff9f195b85>] generic_file_read_iter+0x245/0xd30
 [<ffffffff9f2764ed>] generic_file_splice_read+0xfd/0x230
 [<ffffffff9f2763f0>] ? pipe_to_user+0x40/0x40
 [<ffffffff9f275f08>] do_splice_to+0x98/0xd0
 [<ffffffff9f276014>] splice_direct_to_actor+0xd4/0x2c0
 [<ffffffff9f275660>] ? generic_pipe_buf_nosteal+0x10/0x10
 [<ffffffff9f2762c5>] do_splice_direct+0xc5/0x110
 [<ffffffff9f2381c2>] do_sendfile+0x242/0x470
 [<ffffffff9f23929d>] SyS_sendfile64+0x7d/0xf0
 [<ffffffff9f00279f>] do_syscall_64+0x7f/0x200
 [<ffffffff9f9de5cb>] entry_SYSCALL64_slow_path+0x25/0x25
---[ end trace 2c7bd411d4aa0491 ]---

Re: btrfs_direct_IO oops

[Al Viro]

On Sun, Oct 09, 2016 at 11:11:06AM -0400, Dave Jones wrote:
> idx = 0, offset = 0

== starts at slot 0, nothing put into it yet, but

> curbuf = 0, nrbufs = 1, buffers = 16
> [ffffffff9fa21100 ffffea00065f6d80 0 4096]

the underlying pipe has something stored into slot 0.  That definitely
should not happen.

> WARNING: CPU: 0 PID: 29610 at lib/iov_iter.c:327 sanity+0x102/0x150
> CPU: 0 PID: 29610 Comm: trinity-c9 Not tainted 4.8.0-think+ #8 
>  ffffc900007b7ae8
>  ffffffff9f3e2011
>  0000000000000000
>  0000000000000000

>  ffffffff9fc1e22b
>  ffffffff9f3fa2f2
>  ffffc900007b7b28
>  ffffffff9f08b010
> 
>  0000014734c3d60f
>  ffffffff9fc1e22b
>  0000000000000147
>  0000000000000010

*blink*

where have those come from?
 
> Call Trace:
>  [<ffffffff9f3e2011>] dump_stack+0x6c/0x9b
>  [<ffffffff9f3fa2f2>] ? sanity+0x102/0x150
>  [<ffffffff9f08b010>] __warn+0x110/0x130
>  [<ffffffff9f08b19c>] warn_slowpath_null+0x2c/0x40
>  [<ffffffff9f3fa2f2>] sanity+0x102/0x150
>  [<ffffffff9f3fe62e>] copy_page_to_iter+0x2be/0x480
>  [<ffffffff9f1932da>] ? pagecache_get_page+0xba/0x4f0
>  [<ffffffff9f195b85>] generic_file_read_iter+0x245/0xd30
>  [<ffffffff9f2764ed>] generic_file_splice_read+0xfd/0x230
>  [<ffffffff9f2763f0>] ? pipe_to_user+0x40/0x40
>  [<ffffffff9f275f08>] do_splice_to+0x98/0xd0
>  [<ffffffff9f276014>] splice_direct_to_actor+0xd4/0x2c0
>  [<ffffffff9f275660>] ? generic_pipe_buf_nosteal+0x10/0x10
>  [<ffffffff9f2762c5>] do_splice_direct+0xc5/0x110
>  [<ffffffff9f2381c2>] do_sendfile+0x242/0x470
>  [<ffffffff9f23929d>] SyS_sendfile64+0x7d/0xf0
>  [<ffffffff9f00279f>] do_syscall_64+0x7f/0x200
>  [<ffffffff9f9de5cb>] entry_SYSCALL64_slow_path+0x25/0x25
> ---[ end trace 2c7bd411d4aa0491 ]---

Very interesting.  Could you slap something like
diff --git a/lib/iov_iter.c b/lib/iov_iter.c
index 0ce3411..1ef00e7 100644
--- a/lib/iov_iter.c
+++ b/lib/iov_iter.c
@@ -682,8 +682,9 @@ static void pipe_advance(struct iov_iter *i, size_t size)
 {
 	struct pipe_inode_info *pipe = i->pipe;
 	struct pipe_buffer *buf;
-	int idx = i->idx;
-	size_t off = i->iov_offset;
+	int old_idx = idx = i->idx;
+	size_t old_off = off = i->iov_offset;
+	size_t old_size = size;
 	
 	if (unlikely(i->count < size))
 		size = i->count;
@@ -713,6 +714,9 @@ static void pipe_advance(struct iov_iter *i, size_t size)
 			pipe->nrbufs--;
 		}
 	}
+	if (!sanity(i))
+		printk(KERN_ERR "buggered pipe_advance(%zd) [%d,%zd]",
+				old_size, old_idx, old_off);
 }
 
 void iov_iter_advance(struct iov_iter *i, size_t size)

in there and try to reproduce that one?

Re: btrfs_direct_IO oops

[Dave Jones]

On Mon, Oct 10, 2016 at 04:43:57AM +0100, Al Viro wrote:
 
 > Very interesting.  Could you slap something like
 > diff --git a/lib/iov_iter.c b/lib/iov_iter.c
 > index 0ce3411..1ef00e7 100644
 > --- a/lib/iov_iter.c
 > +++ b/lib/iov_iter.c
 > @@ -682,8 +682,9 @@ static void pipe_advance(struct iov_iter *i, size_t size)
 >  {
 >  	struct pipe_inode_info *pipe = i->pipe;
 >  	struct pipe_buffer *buf;
 > -	int idx = i->idx;
 > -	size_t off = i->iov_offset;
 > +	int old_idx = idx = i->idx;
 > +	size_t old_off = off = i->iov_offset;
 > +	size_t old_size = size;
 >  	
 >  	if (unlikely(i->count < size))
 >  		size = i->count;
 > @@ -713,6 +714,9 @@ static void pipe_advance(struct iov_iter *i, size_t size)
 >  			pipe->nrbufs--;
 >  		}
 >  	}
 > +	if (!sanity(i))
 > +		printk(KERN_ERR "buggered pipe_advance(%zd) [%d,%zd]",
 > +				old_size, old_idx, old_off);
 >  }
 >  
 >  void iov_iter_advance(struct iov_iter *i, size_t size)
 > 
 > in there and try to reproduce that one?

My compiler choked on that, but I fixed it up. The printk didn't
trigger though..


idx = 0, offset = 0
curbuf = 0, nrbufs = 1, buffers = 16
[ffffffffb9a21100 ffffea00126019c0 0 4096]
[          (null) ffffea0013746440 0 0]
[          (null) ffffea00132956c0 0 0]
[          (null) ffffea0013295700 0 0]
[          (null) ffffea0013295740 0 0]
[          (null) ffffea0013295780 0 0]
[          (null) ffffea00132957c0 0 0]
[          (null) ffffea0013595c00 0 0]
[          (null) ffffea0012b1b6c0 0 0]
[          (null)           (null) 0 0]
[          (null)           (null) 0 0]
[          (null)           (null) 0 0]
[          (null)           (null) 0 0]
[          (null)           (null) 0 0]
[          (null)           (null) 0 0]
[          (null)           (null) 0 0]
------------[ cut here ]------------
WARNING: CPU: 1 PID: 13581 at lib/iov_iter.c:327 sanity+0x102/0x150
CPU: 1 PID: 13581 Comm: trinity-c17 Not tainted 4.8.0-think+ #9 
 ffffc90000963ae8
 ffffffffb93e22d1
 0000000000000000
 0000000000000000

 ffffffffb9c1e1cb
 ffffffffb93fa5b2
 ffffc90000963b28
 ffffffffb908b010

 00000147d43c0e7f
 ffffffffb9c1e1cb
 0000000000000147
 0000000000000010

Call Trace:
 [<ffffffffb93e22d1>] dump_stack+0x6c/0x9b
 [<ffffffffb93fa5b2>] ? sanity+0x102/0x150
 [<ffffffffb908b010>] __warn+0x110/0x130
 [<ffffffffb908b19c>] warn_slowpath_null+0x2c/0x40
 [<ffffffffb93fa5b2>] sanity+0x102/0x150
 [<ffffffffb93fe94e>] copy_page_to_iter+0x2be/0x480
 [<ffffffffb91cc8b1>] ? workingset_activation+0xc1/0x120
 [<ffffffffb91cc7f0>] ? workingset_refault+0x190/0x190
 [<ffffffffb9195b85>] generic_file_read_iter+0x245/0xd30
 [<ffffffffb92764ed>] generic_file_splice_read+0xfd/0x230
 [<ffffffffb92763f0>] ? pipe_to_user+0x40/0x40
 [<ffffffffb9275f08>] do_splice_to+0x98/0xd0
 [<ffffffffb9276014>] splice_direct_to_actor+0xd4/0x2c0
 [<ffffffffb9275660>] ? generic_pipe_buf_nosteal+0x10/0x10
 [<ffffffffb92762c5>] do_splice_direct+0xc5/0x110
 [<ffffffffb92381c2>] do_sendfile+0x242/0x470
 [<ffffffffb923929d>] SyS_sendfile64+0x7d/0xf0
 [<ffffffffb900279f>] do_syscall_64+0x7f/0x200
 [<ffffffffb99de8cb>] entry_SYSCALL64_slow_path+0x25/0x25
---[ end trace 6773f425063b7f84 ]---

Re: btrfs_direct_IO oops

[Al Viro]

On Mon, Oct 10, 2016 at 09:11:22AM -0400, Dave Jones wrote:

> My compiler choked on that, but I fixed it up. The printk didn't
> trigger though..
> 
> idx = 0, offset = 0
> curbuf = 0, nrbufs = 1, buffers = 16
> [ffffffffb9a21100 ffffea00126019c0 0 4096]
> [          (null) ffffea0013746440 0 0]
> [          (null) ffffea00132956c0 0 0]
> [          (null) ffffea0013295700 0 0]
> [          (null) ffffea0013295740 0 0]
> [          (null) ffffea0013295780 0 0]
> [          (null) ffffea00132957c0 0 0]
> [          (null) ffffea0013595c00 0 0]
> [          (null) ffffea0012b1b6c0 0 0]
> [          (null)           (null) 0 0]
> [          (null)           (null) 0 0]
> [          (null)           (null) 0 0]
> [          (null)           (null) 0 0]
> [          (null)           (null) 0 0]
> [          (null)           (null) 0 0]
> [          (null)           (null) 0 0]
> ------------[ cut here ]------------
> WARNING: CPU: 1 PID: 13581 at lib/iov_iter.c:327 sanity+0x102/0x150
> CPU: 1 PID: 13581 Comm: trinity-c17 Not tainted 4.8.0-think+ #9 
>  ffffc90000963ae8
>  ffffffffb93e22d1
>  0000000000000000
>  0000000000000000
> 
>  ffffffffb9c1e1cb
>  ffffffffb93fa5b2
>  ffffc90000963b28
>  ffffffffb908b010
> 
>  00000147d43c0e7f
>  ffffffffb9c1e1cb
>  0000000000000147
>  0000000000000010

What are these from?  Confused...

> Call Trace:

[via splice_direct_to_actor()]

Hmmm...  I think I see it.  Could you try the following (on top of debugging
in lib/iov_iter.c) and see if anything triggers?

diff --git a/fs/xfs/xfs_file.c b/fs/xfs/xfs_file.c
index bfc2aa7..b63d8c5 100644
--- a/fs/xfs/xfs_file.c
+++ b/fs/xfs/xfs_file.c
@@ -319,7 +319,7 @@ xfs_file_dio_aio_read(
 	data = *to;
 	ret = __blockdev_direct_IO(iocb, inode, target->bt_bdev, &data,
 			xfs_get_blocks_direct, NULL, NULL, 0);
-	if (ret > 0) {
+	if (ret >= 0) {
 		iocb->ki_pos += ret;
 		iov_iter_advance(to, ret);
 	}
diff --git a/mm/filemap.c b/mm/filemap.c
index 68f1813..88e5ddd 100644
--- a/mm/filemap.c
+++ b/mm/filemap.c
@@ -1935,7 +1935,7 @@ generic_file_read_iter(struct kiocb *iocb, struct iov_iter *iter)
 		file_accessed(file);
 
 		retval = mapping->a_ops->direct_IO(iocb, &data);
-		if (retval > 0) {
+		if (retval >= 0) {
 			iocb->ki_pos += retval;
 			iov_iter_advance(iter, retval);
 		}

Re: btrfs_direct_IO oops

[Dave Jones]

On Mon, Oct 10, 2016 at 04:55:03PM +0100, Al Viro wrote:
 
 > > WARNING: CPU: 1 PID: 13581 at lib/iov_iter.c:327 sanity+0x102/0x150
 > > CPU: 1 PID: 13581 Comm: trinity-c17 Not tainted 4.8.0-think+ #9 
 > >  ffffc90000963ae8
 > >  ffffffffb93e22d1
 > >  0000000000000000
 > >  0000000000000000
 > > 
 > >  ffffffffb9c1e1cb
 > >  ffffffffb93fa5b2
 > >  ffffc90000963b28
 > >  ffffffffb908b010
 > > 
 > >  00000147d43c0e7f
 > >  ffffffffb9c1e1cb
 > >  0000000000000147
 > >  0000000000000010
 > 
 > What are these from?  Confused...

That's the stack I think. I don't know why it started printing all weird..

 > [via splice_direct_to_actor()]
 > 
 > Hmmm...  I think I see it.  Could you try the following (on top of debugging
 > in lib/iov_iter.c) and see if anything triggers?
 
Been running for an hour without incident so far, so this looks promising.
I'll follow-up if anything jumps out, but normally I'd have seen this by now.

	Dave