Re: [PATCH] iomap: Submit the BIO at the end of each extent

["Darrick J. Wong" <darrick.wong@oracle.com>]

On Mon, May 04, 2020 at 07:59:02PM -0700, Darrick J. Wong wrote:
> On Mon, May 04, 2020 at 07:24:15PM -0700, Matthew Wilcox wrote:
> > On Mon, May 04, 2020 at 05:37:10PM -0700, Darrick J. Wong wrote:
> > > run fstests generic/418 at 2020-05-04 17:27:51
> > > rm (3338) used greatest stack depth: 11728 bytes left
> > > BUG: kernel NULL pointer dereference, address: 0000000000000000
> > > #PF: supervisor read access in kernel mode
> > > #PF: error_code(0x0000) - not-present page
> > > PGD 0 P4D 0 
> > > Oops: 0000 [#1] PREEMPT SMP
> > > CPU: 1 PID: 4900 Comm: dio-invalidate- Not tainted 5.7.0-rc4-djw #rc4
> > > Hardware name: QEMU Standard PC (Q35 + ICH9, 2009), BIOS 1.13.0-1ubuntu1 04/01/2014
> > > RIP: 0010:iomap_set_range_uptodate+0x5d/0x170
> > > Code: 07 00 60 00 00 75 13 f0 80 0f 04 48 83 c4 18 5b 5d 41 5c 41 5d 41 5e 41 5f c3 48 8b 47 18 44 8d 74 16 ff 41 89 f1 4c 8b 6f 28 <4c> 8b 38 41 0f b6 af ca 00 00 00 89 e9 41 d3 e9 40 80 fd 1f 0f 87
> > > RSP: 0018:ffffc90004b0b8e8 EFLAGS: 00010206
> > > RAX: 0000000000000000 RBX: ffffea0000292440 RCX: 0000000000000000
> > > RDX: 0000000000000400 RSI: 0000000000000c00 RDI: ffffea0000292440
> > > RBP: 0000000000001000 R08: ffffc90004b0b958 R09: 0000000000000c00
> > > R10: 0000000000000002 R11: ffff888017806720 R12: ffffc90004b0ba20
> > > R13: ffff888017806720 R14: 0000000000000fff R15: ffff88801872c610
> > > FS:  00007f2091593740(0000) GS:ffff88801e800000(0000) knlGS:0000000000000000
> > > CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
> > > CR2: 0000000000000000 CR3: 0000000017abb005 CR4: 00000000001606a0
> > > Call Trace:
> > >  ? __raw_spin_lock_init+0x39/0x60
> > >  iomap_readpage_actor+0x113/0x3f0
> > >  iomap_readpages_actor+0x1dc/0x240
> > >  iomap_apply+0x12d/0x4e9
> > >  ? iomap_readpage_actor+0x3f0/0x3f0
> > >  ? mark_held_locks+0x45/0x70
> > >  iomap_readpages+0xc2/0x290
> > >  ? iomap_readpage_actor+0x3f0/0x3f0
> > >  ? xa_clear_mark+0x30/0x30
> > >  read_pages+0x75/0x1b0
> > >  __do_page_cache_readahead+0x1bb/0x1d0
> > >  ondemand_readahead+0x21a/0x540
> > >  ? pagecache_get_page+0x26/0x320
> > >  generic_file_read_iter+0x91a/0xd10
> > >  ? xfs_file_buffered_aio_read+0x88/0x170 [xfs]
> > >  xfs_file_buffered_aio_read+0x65/0x170 [xfs]
> > >  xfs_file_read_iter+0xe9/0x2a0 [xfs]
> > >  new_sync_read+0x12d/0x1d0
> > >  vfs_read+0xc7/0x180
> > >  ksys_pread64+0x64/0xa0
> > >  do_syscall_64+0x50/0x1a0
> > >  entry_SYSCALL_64_after_hwframe+0x49/0xb3
> > > RIP: 0033:0x7f209179cbca
> > > 
> > > Digging into this with gcc, the RIP value is:
> > > 
> > > 0xffffffff813047cd is in iomap_set_range_uptodate (/storage/home/djwong/cdev/work/linux-djw/fs/iomap/buffered-io.c:147).
> > > 142
> > > 143     static void
> > > 144     iomap_iop_set_range_uptodate(struct page *page, unsigned off, unsigned len)
> > > 145     {
> > > 146             struct iomap_page *iop = to_iomap_page(page);
> > > 147             struct inode *inode = page->mapping->host;
> > > 148             unsigned first = off >> inode->i_blkbits;
> > > 149             unsigned last = (off + len - 1) >> inode->i_blkbits;
> > > 150             bool uptodate = true;
> > > 151             unsigned long flags;
> > > 
> > > So now this makes me wonder, is it possible to be performing readahead
> > > into a page that doesn't have page->mapping set yet?  I reran this a few
> > > times, got crashes in different places, but the common factor is that
> > > page->mapping is NULL, and we're doing readhead.
> > > 
> > > I also tried this with the patch *not* applied and had the same
> > > problems, so it's not actually this patch.  But there's something going
> > > wrong in the iomap code...
> > 
> > Thanks for tracking that down!  I don't see a way for that to happen.
> > The page is originally allocated in __do_page_cache_readahead() and
> > (in 5.7) does not have page->mapping set.  Instead, it gets put on
> > the page_pool list head which gets passed into iomap_readpages().
> > iomap_next_page() calls add_to_page_cache_lru() which either sets
> > page->mapping or returns an error.  So I don't see how iomap_next_page()
> > can give us a page which doesn't have ->mapping set.
> > 
> > Is it possible that it's the second dereference, not the first that's
> > NULL?  ie mapping->host is NULL?
> 
> Hmm, that's possible too.  I haven't gotten around (it's 19:58 here) to
> digging further into the disassembly to figure out which pointer
> deference it really is.

To summarize the live-debugging session willy and I just had on irc,
this doesn't quite work because an extremely fragmented extent map on a
blocksize < pagesize filesystem can cause problems:

Thread A gets the mapping for the first block, increments read_count,
and issues the IO.  The IO completes immediately, so we decrement
read_count, and since there are no other readers, we unlock the page.
A's readahead context still points to the page.

Meanwhile, a directio write in thread B wanders in and invalidates the
page cache, which unmaps the page.  Uhoh...

Next, thread A continues its readahead loop.  It gets the mapping for
the second block and calls iomap_readpages_actor with the page that is
still pointed to by the readahead context ... which if we're lucky is
now unmapped and unlocked, and hasn't been reused yet.

--D

> --D