From patchwork Wed Jan 29 19:13:22 2014 Content-Type: text/plain; charset="utf-8" MIME-Version: 1.0 Content-Transfer-Encoding: 7bit X-Patchwork-Submitter: Andrew Ruder X-Patchwork-Id: 315196 Return-Path: X-Original-To: incoming@patchwork.ozlabs.org Delivered-To: patchwork-incoming@bilbo.ozlabs.org Received: from casper.infradead.org (unknown [IPv6:2001:770:15f::2]) (using TLSv1.2 with cipher ECDHE-RSA-AES256-GCM-SHA384 (256/256 bits)) (No client certificate requested) by ozlabs.org (Postfix) with ESMTPS id 19DD72C00CE for ; Thu, 30 Jan 2014 06:17:25 +1100 (EST) Received: from merlin.infradead.org ([2001:4978:20e::2]) by casper.infradead.org with esmtps (Exim 4.80.1 #2 (Red Hat Linux)) id 1W8adD-0004Lv-RB; Wed, 29 Jan 2014 19:17:04 +0000 Received: from localhost ([::1] helo=merlin.infradead.org) by merlin.infradead.org with esmtp (Exim 4.80.1 #2 (Red Hat Linux)) id 1W8adC-0006o3-8m; Wed, 29 Jan 2014 19:17:02 +0000 Received: from mail-ig0-f170.google.com ([209.85.213.170]) by merlin.infradead.org with esmtps (Exim 4.80.1 #2 (Red Hat Linux)) id 1W8ad9-0006mu-Bi for linux-mtd@lists.infradead.org; Wed, 29 Jan 2014 19:17:01 +0000 Received: by mail-ig0-f170.google.com with SMTP id m12so18051765iga.1 for ; Wed, 29 Jan 2014 11:16:37 -0800 (PST) X-Google-DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=1e100.net; s=20130820; h=x-gm-message-state:date:from:to:cc:subject:message-id :mail-followup-to:references:mime-version:content-type :content-disposition:in-reply-to:user-agent; bh=kdk0l2SNvJzKk4nOsiJDImKRNOLaLul6ix7R6RbkXJg=; b=fmHeYwynC6mY2Dc45SP4zV4rvjL9HHUwKdWdXZJetzraCfO02fhzPAi1U6lJKqqERg 75hIQBotp7d1SKcF7S9Gh8Wkr5m+KrZ1gaq1ZYiZ2qUlYgR5HNP3h2W0o0nECd/1+ENp cg2OSMLD6pm7h2Uh+xCVWmwgNJsuB8tWqKSGVsg6Shaf8+bZU6OHEQC2uiBjY3s4tJE7 cVz3l48LIMrzml/4ouLkb6GrjbB2aPTaYbWColC9LZ+z6YunBzA2451GgVjaYAmpBYpL e7mhU709xofBAGL2gQQcY3UKvrVhOjbw7JfDWQALtpmZ8KHuYHnwGhEVXUAwKyQxoBaO Wj4Q== X-Gm-Message-State: ALoCoQkV2K/oqzGGX0QXus5kKxrTde2p3xNFY85LfK1JL22n7nHTqz55UIrp0RFvQ4b2cj0fV7/A X-Received: by 10.50.60.105 with SMTP id g9mr30473116igr.14.1391022997224; Wed, 29 Jan 2014 11:16:37 -0800 (PST) Received: from gmail.com (64-198-156-98.ip.mcleodusa.net. [64.198.156.98]) by mx.google.com with ESMTPSA id ni8sm70849592igb.7.2014.01.29.11.16.34 for (version=TLSv1.2 cipher=RC4-SHA bits=128/128); Wed, 29 Jan 2014 11:16:35 -0800 (PST) Date: Wed, 29 Jan 2014 13:13:22 -0600 From: Andrew Ruder To: linux-arm-kernel@lists.infradead.org, linux-kernel@vger.kernel.org, linux-mtd@lists.infradead.org Subject: Re: [BUG] reproducable ubifs reboot assert and corruption Message-ID: <20140129191322.GC7278@gmail.com> Mail-Followup-To: linux-arm-kernel@lists.infradead.org, linux-kernel@vger.kernel.org, linux-mtd@lists.infradead.org, richard@not.at References: <20140122051510.GB17284@gmail.com> <20140127163939.GA27809@gmail.com> <20140129053238.GA6035@gmail.com> <52E8AE25.8080502@nod.at> <20140129154622.GB7278@gmail.com> <52E92494.1090407@nod.at> MIME-Version: 1.0 Content-Disposition: inline In-Reply-To: <52E92494.1090407@nod.at> User-Agent: Mutt/1.5.21+155 (d3096e8796e7) (2012-12-30) X-CRM114-Version: 20100106-BlameMichelson ( TRE 0.8.0 (BSD) ) MR-646709E3 X-CRM114-CacheID: sfid-20140129_141659_525681_6BF25297 X-CRM114-Status: GOOD ( 17.93 ) X-Spam-Score: 0.2 (/) X-Spam-Report: SpamAssassin version 3.3.2 on merlin.infradead.org summary: Content analysis details: (0.2 points) pts rule name description ---- ---------------------- -------------------------------------------------- -0.7 RCVD_IN_DNSWL_LOW RBL: Sender listed at http://www.dnswl.org/, low trust [209.85.213.170 listed in list.dnswl.org] 2.8 FSL_HELO_FAKE FSL_HELO_FAKE -1.9 BAYES_00 BODY: Bayes spam probability is 0 to 1% [score: 0.0000] Cc: richard@not.at X-BeenThere: linux-mtd@lists.infradead.org X-Mailman-Version: 2.1.15 Precedence: list List-Id: Linux MTD discussion mailing list List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , Sender: "linux-mtd" Errors-To: linux-mtd-bounces+incoming=patchwork.ozlabs.org@lists.infradead.org On Wed, Jan 29, 2014 at 04:56:04PM +0100, Richard Weinberger wrote: > Does the issue also happen if you disable preemption? > i.e. CONFIG_PREEMPT_NONE=y CONFIG_PREEMPT_NONE=y still breaks. I suspect that sync_filesystem has some blocking behavior that allows other processes to schedule. Another log is attached and the patch I used to create this log is below. I think the most interesting part of this patch is the last hunk that modifies ubifs_remount_ro. This clearly shows that after the mount has been marked as read-only we have dirty inodes waiting for the writeback to come in and hit all the asserts. Here's some of the important parts of the log: 170 pre sync_filesystem # Notice that while we were running sync_filesystem # a inode (0xd75ab658) snuck in with a sys_rename 204 inode: d75ab658 205 ------------[ cut here ]------------ 206 WARNING: CPU: 0 PID: 625 at fs/fs-writeback.c:1213 __mark_inode_dirty+0x2a4/0x2f4() 207 Modules linked in: 208 CPU: 0 PID: 625 Comm: fsstress Tainted: G W 3.12.0-00041-g7f12d39-dirty #250 209 [] (unwind_backtrace+0x0/0x128) from [] (show_stack+0x20/0x24) 210 [] (show_stack+0x20/0x24) from [] (dump_stack+0x20/0x28) 211 [] (dump_stack+0x20/0x28) from [] (warn_slowpath_common+0x78/0x98) 212 [] (warn_slowpath_common+0x78/0x98) from [] (warn_slowpath_null+0x2c/0x34) 213 [] (warn_slowpath_null+0x2c/0x34) from [] (__mark_inode_dirty+0x2a4/0x2f4) 214 [] (__mark_inode_dirty+0x2a4/0x2f4) from [] (ubifs_rename+0x4a4/0x600) 215 [] (ubifs_rename+0x4a4/0x600) from [] (vfs_rename+0x280/0x3f4) 216 [] (vfs_rename+0x280/0x3f4) from [] (SyS_renameat+0x18c/0x218) 217 [] (SyS_renameat+0x18c/0x218) from [] (SyS_rename+0x2c/0x30) 218 [] (SyS_rename+0x2c/0x30) from [] (ret_fast_syscall+0x0/0x2c) 219 ---[ end trace 35ebec8569a53526 ]--- 754 post sync_filesystem 755 pre prepare_remount 756 post prepare_remount 757 prepare_remount success 758 UBIFS: background thread "ubifs_bgt0_0" stops 759 we are now a read-only mount 760 bdi.work_list = d7ac4110, .next = d7ac4110 # WE HAVE DIRTY I/O (notice the .next != &b_dirty) 761 bdi.wb.b_dirty = d7ac40d8, .next = d75accd0 762 bdi.wb.b_io = d7ac40e0, .next = d7ac40e0 763 bdi.wb.b_more_io = d7ac40e8, .next = d7ac40e8 764 do_remount_sb success # And now our friend (inode 0xd75ab658) comes in with a writeback after # we are read-only triggering the assert 779 inode: d75ab658 780 UBIFS assert failed in reserve_space at 125 (pid 11) 781 CPU: 0 PID: 11 Comm: kworker/u2:1 Tainted: G W 3.12.0-00041-g7f12d39-dirty #250 782 Workqueue: writeback bdi_writeback_workfn (flush-ubifs_0_0) 783 [] (unwind_backtrace+0x0/0x128) from [] (show_stack+0x20/0x24) 784 [] (show_stack+0x20/0x24) from [] (dump_stack+0x20/0x28) 785 [] (dump_stack+0x20/0x28) from [] (make_reservation+0x8c/0x560) 786 [] (make_reservation+0x8c/0x560) from [] (ubifs_jnl_write_inode+0xbc/0x214) 787 [] (ubifs_jnl_write_inode+0xbc/0x214) from [] (ubifs_write_inode+0xec/0x17c) 788 [] (ubifs_write_inode+0xec/0x17c) from [] (__writeback_single_inode+0x1fc/0x308) 789 [] (__writeback_single_inode+0x1fc/0x308) from [] (writeback_sb_inodes+0x1f8/0x3c4) 790 [] (writeback_sb_inodes+0x1f8/0x3c4) from [] (__writeback_inodes_wb+0x80/0xc0) 791 [] (__writeback_inodes_wb+0x80/0xc0) from [] (wb_writeback+0x198/0x310) 792 [] (wb_writeback+0x198/0x310) from [] (bdi_writeback_workfn+0x15c/0x454) 793 [] (bdi_writeback_workfn+0x15c/0x454) from [] (process_one_work+0x280/0x420) 794 [] (process_one_work+0x280/0x420) from [] (worker_thread+0x240/0x380) 795 [] (worker_thread+0x240/0x380) from [] (kthread+0xbc/0xc8) 796 [] (kthread+0xbc/0xc8) from [] (ret_from_fork+0x14/0x20) - Andy --- patch --- diff --git a/fs/fs-writeback.c b/fs/fs-writeback.c index 9f4935b..48e4272 100644 --- a/fs/fs-writeback.c +++ b/fs/fs-writeback.c @@ -93,6 +93,10 @@ static void bdi_queue_work(struct backing_dev_info *bdi, { trace_writeback_queue(bdi, work); + do { + extern bool ubifs_enable_debug; + WARN_ON(ubifs_enable_debug); + } while (0); spin_lock_bh(&bdi->wb_lock); list_add_tail(&work->list, &bdi->work_list); spin_unlock_bh(&bdi->wb_lock); @@ -194,6 +198,11 @@ static void redirty_tail(struct inode *inode, struct bdi_writeback *wb) if (time_before(inode->dirtied_when, tail->dirtied_when)) inode->dirtied_when = jiffies; } + do { + extern bool ubifs_enable_debug; + if (ubifs_enable_debug) pr_info("inode: %p\n", inode); + WARN_ON(ubifs_enable_debug); + } while (0); list_move(&inode->i_wb_list, &wb->b_dirty); } @@ -204,6 +213,11 @@ static void requeue_io(struct inode *inode, struct bdi_writeback *wb) { assert_spin_locked(&wb->list_lock); list_move(&inode->i_wb_list, &wb->b_more_io); + do { + extern bool ubifs_enable_debug; + if (ubifs_enable_debug) pr_info("inode: %p\n", inode); + WARN_ON(ubifs_enable_debug); + } while (0); } static void inode_sync_complete(struct inode *inode) @@ -437,6 +451,8 @@ __writeback_single_inode(struct inode *inode, struct writeback_control *wbc) unsigned dirty; int ret; + extern bool ubifs_enable_debug; + if (ubifs_enable_debug) pr_info("inode: %p\n", inode); WARN_ON(!(inode->i_state & I_SYNC)); trace_writeback_single_inode_start(inode, wbc, nr_to_write); @@ -1191,6 +1207,11 @@ void __mark_inode_dirty(struct inode *inode, int flags) inode->dirtied_when = jiffies; list_move(&inode->i_wb_list, &bdi->wb.b_dirty); + do { + extern bool ubifs_enable_debug; + if (ubifs_enable_debug) pr_info("inode: %p\n", inode); + WARN_ON(ubifs_enable_debug); + } while (0); spin_unlock(&bdi->wb.list_lock); if (wakeup_bdi) diff --git a/fs/super.c b/fs/super.c index 0225c20..29afc68 100644 --- a/fs/super.c +++ b/fs/super.c @@ -737,6 +737,12 @@ int do_remount_sb(struct super_block *sb, int flags, void *data, int force) int retval; int remount_ro; + extern bool ubifs_enable_debug; + if (flags & MS_RDONLY) { + ubifs_enable_debug = true; + } + WARN_ON(ubifs_enable_debug); + if (sb->s_writers.frozen != SB_UNFROZEN) return -EBUSY; @@ -747,8 +753,11 @@ int do_remount_sb(struct super_block *sb, int flags, void *data, int force) if (flags & MS_RDONLY) acct_auto_close(sb); + pr_info("pre shrink_dcache_sb\n"); shrink_dcache_sb(sb); + pr_info("pre sync_filesystem\n"); sync_filesystem(sb); + pr_info("post sync_filesystem\n"); remount_ro = (flags & MS_RDONLY) && !(sb->s_flags & MS_RDONLY); @@ -758,9 +767,12 @@ int do_remount_sb(struct super_block *sb, int flags, void *data, int force) if (force) { mark_files_ro(sb); } else { + pr_info("pre prepare_remount\n"); retval = sb_prepare_remount_readonly(sb); + pr_info("post prepare_remount\n"); if (retval) return retval; + pr_info("prepare_remount success\n"); } } @@ -789,6 +801,7 @@ int do_remount_sb(struct super_block *sb, int flags, void *data, int force) */ if (remount_ro && sb->s_bdev) invalidate_bdev(sb->s_bdev); + pr_info("do_remount_sb success\n"); return 0; cancel_readonly: diff --git a/fs/ubifs/file.c b/fs/ubifs/file.c index 123c79b..c9f2d5d 100644 --- a/fs/ubifs/file.c +++ b/fs/ubifs/file.c @@ -902,6 +902,8 @@ static int do_writepage(struct page *page, int len) struct inode *inode = page->mapping->host; struct ubifs_info *c = inode->i_sb->s_fs_info; + WARN_ON(c->ro_mount); + #ifdef UBIFS_DEBUG spin_lock(&ui->ui_lock); ubifs_assert(page->index <= ui->synced_i_size << PAGE_CACHE_SIZE); diff --git a/fs/ubifs/super.c b/fs/ubifs/super.c index 3e4aa72..8cbb731 100644 --- a/fs/ubifs/super.c +++ b/fs/ubifs/super.c @@ -38,6 +38,8 @@ #include #include "ubifs.h" +bool ubifs_enable_debug; + /* * Maximum amount of memory we may 'kmalloc()' without worrying that we are * allocating too much. @@ -1756,6 +1758,11 @@ static void ubifs_remount_ro(struct ubifs_info *c) err = dbg_check_space_info(c); if (err) ubifs_ro_mode(c, err); + pr_info("we are now a read-only mount\n"); + pr_info("bdi.work_list = %p, .next = %p\n", &c->bdi.work_list, c->bdi.work_list.next); + pr_info("bdi.wb.b_dirty = %p, .next = %p\n", &c->bdi.wb.b_dirty, c->bdi.wb.b_dirty.next); + pr_info("bdi.wb.b_io = %p, .next = %p\n", &c->bdi.wb.b_io, c->bdi.wb.b_io.next); + pr_info("bdi.wb.b_more_io = %p, .next = %p\n", &c->bdi.wb.b_more_io, c->bdi.wb.b_more_io.next); mutex_unlock(&c->umount_mutex); }