Greetings All, I was wondering if there is anyone working on tracing this bug. If no one else is I am will look into this later when I am at my actual work system. Nick
On February 23, 2015 6:33:53 PM EST, Jaegeuk Kim <[email protected]> wrote: >Hi Sebastian, > >Thank you for the report. > >On Fri, Feb 20, 2015 at 09:10:35PM +0100, Sebastian Andrzej Siewior >wrote: >> Hi, >> >> I've been playing with f2fs on eMMC with v3.19. I simply cp/rm files >on >> the partition for a while. The partition has a size of 510MiB and >runs >> out of space now and then. >> I managed to run into this: >> >> |[ 428.035231] NMI watchdog: BUG: soft lockup - CPU#0 stuck for 22s! >[kworker/u2:2:59] >> |[ 428.042896] Modules linked in: >> |[ 428.045972] CPU: 0 PID: 59 Comm: kworker/u2:2 Tainted: G W > 3.19.0-00010-g10c11c51ffed #153 >> |[ 428.062166] Workqueue: writeback bdi_writeback_workfn >(flush-179:0) >> |[ 428.068460] task: df230000 ti: df23e000 task.ti: df23e000 >> |[ 428.073866] PC is at __submit_merged_bio+0x6c/0x110 >> |[ 428.078746] LR is at f2fs_submit_merged_bio+0x74/0x80 >> |[ 428.126618] CPU: 0 PID: 59 Comm: kworker/u2:2 Tainted: G W > 3.19.0-00010-g10c11c51ffed #153 >> |[ 428.142802] Workqueue: writeback bdi_writeback_workfn >(flush-179:0) >> … >> |[ 428.256579] [<c00085c4>] (gic_handle_irq) from [<c0012e84>] >(__irq_svc+0x44/0x5c) >> |[ 428.264063] Exception stack(0xdf23fb48 to 0xdf23fb90) >> |[ 428.269119] fb40: deef3484 ffff0001 ffff0001 >00000027 deef3484 00000000 >> |[ 428.277299] fb60: deef3440 00000000 de426000 deef34ec deefc440 >df23fbb4 df23fbb8 df23fb90 >> |[ 428.285477] fb80: c02191f0 c0218fa0 60000013 ffffffff >> |[ 428.290539] [<c0012e84>] (__irq_svc) from [<c0218fa0>] >(__submit_merged_bio+0x6c/0x110) >> |[ 428.298552] [<c0218fa0>] (__submit_merged_bio) from [<c02191f0>] >(f2fs_submit_merged_bio+0x74/0x80) >> |[ 428.307604] [<c02191f0>] (f2fs_submit_merged_bio) from >[<c021624c>] (sync_dirty_dir_inodes+0x70/0x78) >> |[ 428.316831] [<c021624c>] (sync_dirty_dir_inodes) from >[<c0216358>] (write_checkpoint+0x104/0xc10) >> |[ 428.325709] [<c0216358>] (write_checkpoint) from [<c021231c>] >(f2fs_sync_fs+0x80/0xbc) >> |[ 428.333637] [<c021231c>] (f2fs_sync_fs) from [<c0221eb8>] >(f2fs_balance_fs_bg+0x4c/0x68) >> |[ 428.341736] [<c0221eb8>] (f2fs_balance_fs_bg) from [<c021e9b8>] >(f2fs_write_node_pages+0x40/0x110) >> |[ 428.350704] [<c021e9b8>] (f2fs_write_node_pages) from >[<c00de620>] (do_writepages+0x34/0x48) >> |[ 428.359152] [<c00de620>] (do_writepages) from [<c0145714>] >(__writeback_single_inode+0x50/0x228) >> |[ 428.367946] [<c0145714>] (__writeback_single_inode) from >[<c0146184>] (writeback_sb_inodes+0x1a8/0x378) >> |[ 428.377346] [<c0146184>] (writeback_sb_inodes) from [<c01463e4>] >(__writeback_inodes_wb+0x90/0xc8) >> |[ 428.386312] [<c01463e4>] (__writeback_inodes_wb) from >[<c01465f8>] (wb_writeback+0x1dc/0x28c) >> |[ 428.394843] [<c01465f8>] (wb_writeback) from [<c0146dd8>] >(bdi_writeback_workfn+0x2ac/0x460) >> |[ 428.403293] [<c0146dd8>] (bdi_writeback_workfn) from [<c003c3fc>] >(process_one_work+0x11c/0x3a4) >> |[ 428.412087] [<c003c3fc>] (process_one_work) from [<c003c844>] >(worker_thread+0x17c/0x490) >> |[ 428.420272] [<c003c844>] (worker_thread) from [<c0041398>] >(kthread+0xec/0x100) >> |[ 428.427590] [<c0041398>] (kthread) from [<c000ed10>] >(ret_from_fork+0x14/0x24) >> >> The kernel config is UP no preemption/server. Once in this state, it >> does not recover. I have more backtraces and they all look more or >less >> the same. I pulled in the f2fs changes from this merge window and was >able >> to reproduce the same thing. It can take hours to get it reproduced. >> >> The backtrace up to sync_dirty_dir_inodes() is same once this "stall" >> occures. I meassured the time spent within this function and added >> printk() once 5 seconds were reached and I saw output. >> At the point of the stall, the task state of this work queue: >> >> |kworker/u2:1 R running 0 53 2 0x00000002 >> |Workqueue: writeback bdi_writeback_workfn (flush-179:0) >> |[<c0012e84>] (__irq_svc) from [<c0219dd8>] >(f2fs_submit_merged_bio+0x4c/0x84) >> |[<c0219dd8>] (f2fs_submit_merged_bio) from [<c021632c>] >(sync_dirty_dir_inodes+0x70/0x78) >> |[<c021632c>] (sync_dirty_dir_inodes) from [<c0216448>] >(write_checkpoint+0x114/0xbf0) >> |[<c0216448>] (write_checkpoint) from [<c0212314>] >(f2fs_sync_fs+0x7c/0xcc) >> |[<c0212314>] (f2fs_sync_fs) from [<c0221f14>] >(f2fs_balance_fs_bg+0x4c/0x68) >> |[<c0221f14>] (f2fs_balance_fs_bg) from [<c021ed28>] >(f2fs_write_node_pages+0x40/0x110) >> |[<c021ed28>] (f2fs_write_node_pages) from [<c00de620>] >(do_writepages+0x34/0x48) >> |[<c00de620>] (do_writepages) from [<c0145714>] >(__writeback_single_inode+0x50/0x228) >> |[<c0145714>] (__writeback_single_inode) from [<c0146184>] >(writeback_sb_inodes+0x1a8/0x378) >> |[<c0146184>] (writeback_sb_inodes) from [<c01463e4>] >(__writeback_inodes_wb+0x90/0xc8) >> |[<c01463e4>] (__writeback_inodes_wb) from [<c01465f8>] >(wb_writeback+0x1dc/0x28c) >> |[<c01465f8>] (wb_writeback) from [<c0146dd8>] >(bdi_writeback_workfn+0x2ac/0x460) >> |[<c0146dd8>] (bdi_writeback_workfn) from [<c003c3fc>] >(process_one_work+0x11c/0x3a4) >> |[<c003c3fc>] (process_one_work) from [<c003c844>] >(worker_thread+0x17c/0x490) >> |[<c003c844>] (worker_thread) from [<c0041398>] (kthread+0xec/0x100) >> |[<c0041398>] (kthread) from [<c000ed10>] (ret_from_fork+0x14/0x24) >> >> The 0x0…2 mean TIF_NEED_RESCHED is set but since preemption is off >this >> schedule() seem not to happen. >> >> I have no idea what sync_dirty_dir_inodes() is doing :) Can you image >a >> case where it could busy loop? I could come up with this: >> >> | void sync_dirty_dir_inodes(struct f2fs_sb_info *sbi) >> | { >> | retry: >> … >> | head = &sbi->dir_inode_list; >> … >> | entry = list_entry(head->next, struct inode_entry, list); >> | inode = igrab(entry->inode); >> | spin_unlock(&sbi->dir_inode_lock); >> … >> | } else { >> | /* >> | * We should submit bio, since it exists several >> | * wribacking dentry pages in the freeing inode. >> | */ >> | f2fs_submit_merged_bio(sbi, DATA, WRITE); >> -> >> |void f2fs_submit_merged_bio(struct f2fs_sb_info *sbi, >> | enum page_type type, int rw) >> | { >> | io = is_read_io(rw) ? &sbi->read_io : >&sbi->write_io[btype]; >> | >> | down_write(&io->io_rwsem); >> … >> | >> | __submit_merged_bio(io); >> -> >> | static void __submit_merged_bio(struct f2fs_bio_info *io) >> | { >> | if (!io->bio) >> exit here since it is set to NULL at the end of this function. >> | return; >> … >> | submit_bio(fio->rw, io->bio); >> | io->bio = NULL; >> | } >> <- >> | up_write(&io->io_rwsem); >> | } >> | >> <- >> | } >> | goto retry; >> | } >> >> I don't know what submit_bio() does (in terms of terminating the loop >> here) but I haven't seen it in my backtraces (and assume it does not >get >> invoked). >> Ah. The other process that (I think) could run: >> | rm R running 0 1989 1774 0x00000000 >> | [<c047c55c>] (__schedule) from [<c00486dc>] >(__cond_resched+0x30/0x4c) >> | [<c00486dc>] (__cond_resched) from [<c047c8c8>] >(_cond_resched+0x4c/0x54) >> | [<c047c8c8>] (_cond_resched) from [<c00e1aec>] >(truncate_inode_pages_range+0x1f0/0x5e8) >> | [<c00e1aec>] (truncate_inode_pages_range) from [<c00e1fd8>] >(truncate_inode_pages+0x28/0x30) >> | [<c00e1fd8>] (truncate_inode_pages) from [<c00e2148>] >(truncate_inode_pages_final+0x60/0x64) >> | [<c00e2148>] (truncate_inode_pages_final) from [<c020c92c>] >(f2fs_evict_inode+0x4c/0x268) >> | [<c020c92c>] (f2fs_evict_inode) from [<c0137214>] >(evict+0x94/0x140) >> | [<c0137214>] (evict) from [<c01377e8>] (iput+0xc8/0x134) >> | [<c01377e8>] (iput) from [<c01333e4>] (d_delete+0x154/0x180) >> | [<c01333e4>] (d_delete) from [<c0129870>] (vfs_rmdir+0x114/0x12c) >> | [<c0129870>] (vfs_rmdir) from [<c012d644>] (do_rmdir+0x158/0x168) >> | [<c012d644>] (do_rmdir) from [<c012dd90>] (SyS_unlinkat+0x30/0x3c) >> | [<c012dd90>] (SyS_unlinkat) from [<c000ec40>] >(ret_fast_syscall+0x0/0x4c) > >This inode is the directory (c.f., do_rmdir) causing a infinite loop on >sync_dirty_dir_inodes. >The sync_dirty_dir_inodes tries to flush dirty dentry pages, but if the >inode is >under eviction, it submits bios and do it again until eviction is >finished. > >It needs to check why truncate_inode_pages_range cannot be completed. > >How about adding cond_resched() right after f2fs_submit_merged_bio in >sync_dirty_dir_inodes? > >Could you test this? > >Thanks, > >> >> I wasn't able reproduce the issue after enable preemption (low >latency >> desktop). I saw however the the code looping in >sync_dirty_dir_inodes() >> for 5 seconds but it did not lockup the machine. The box continued to >> work and the file system access was working. >> >> Sebastian > >------------------------------------------------------------------------------ >Download BIRT iHub F-Type - The Free Enterprise-Grade BIRT Server >from Actuate! Instantly Supercharge Your Business Reports and >Dashboards >with Interactivity, Sharing, Native Excel Exports, App Integration & >more >Get technology previously reserved for billion-dollar corporations, >FREE >http://pubads.g.doubleclick.net/gampad/clk?id=190641631&iu=/4140/ostg.clktrk >_______________________________________________ >Linux-f2fs-devel mailing list >[email protected] >https://lists.sourceforge.net/lists/listinfo/linux-f2fs-devel -- Sent from my Android device with K-9 Mail. Please excuse my brevity. ------------------------------------------------------------------------------ Dive into the World of Parallel Programming The Go Parallel Website, sponsored by Intel and developed in partnership with Slashdot Media, is your hub for all things parallel software development, from weekly thought leadership blogs to news, videos, case studies, tutorials and more. Take a look and join the conversation now. http://goparallel.sourceforge.net/ _______________________________________________ Linux-f2fs-devel mailing list [email protected] https://lists.sourceforge.net/lists/listinfo/linux-f2fs-devel
