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)
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
