Re: [BUG] fatal hang untarring 90GB file, possibly writebackrelated.

[Dave Chinner]

On Wed, Apr 27, 2011 at 12:21:42PM -0500, James Bottomley wrote:
> On Wed, 2011-04-27 at 12:54 -0400, Chris Mason wrote:
> > Ok, I'd try turning it on so we catch the sleeping with a spinlock held
> > case better.
> 
> Will do, that's CONFIG_PREEMPT (rather than CONFIG_PREEMPT_VOLUNTARY)?
> 
> This is the trace with sysrq-l and sysrq-w
> 
> The repro this time doesn't have a soft lockup, just the tar is hung and
> one of my CPUs is in 99% system.
> 
> James 
> 
> ---
> [  454.742935] flush-253:2     D 0000000000000000     0   793      2 0x00000000
> [  454.745425]  ffff88006355b710 0000000000000046 ffff88006355b6b0 ffffffff00000000
> [  454.747955]  ffff880037ee9700 ffff88006355bfd8 ffff88006355bfd8 0000000000013b40
> [  454.750506]  ffffffff81a0b020 ffff880037ee9700 ffff88006355b710 000000018106e7c3
> [  454.753048] Call Trace:
> [  454.755537]  [<ffffffff811c82b8>] do_get_write_access+0x1c6/0x38d
> [  454.758071]  [<ffffffff8106e88b>] ? autoremove_wake_function+0x3d/0x3d
> [  454.760644]  [<ffffffff811c8588>] jbd2_journal_get_write_access+0x2b/0x42
> [  454.763206]  [<ffffffff8118ea4f>] ? ext4_read_block_bitmap+0x54/0x2d0
> [  454.765770]  [<ffffffff811b5888>] __ext4_journal_get_write_access+0x58/0x66
> [  454.768353]  [<ffffffff811b8dbe>] ext4_mb_mark_diskspace_used+0x70/0x2ae
> [  454.770942]  [<ffffffff811bb10e>] ext4_mb_new_blocks+0x1c8/0x3c2
> [  454.773501]  [<ffffffff811b4628>] ext4_ext_map_blocks+0x1961/0x1c04
> [  454.776082]  [<ffffffff8122ed78>] ? radix_tree_gang_lookup_tag_slot+0x81/0xa2
> [  454.778711]  [<ffffffff810d55f9>] ? find_get_pages_tag+0x3b/0xd6
> [  454.781323]  [<ffffffff811967fa>] ext4_map_blocks+0x112/0x1e7
> [  454.783894]  [<ffffffff811984e8>] mpage_da_map_and_submit+0x93/0x2cd
> [  454.786491]  [<ffffffff81198de5>] ext4_da_writepages+0x2c1/0x44d
> [  454.789090]  [<ffffffff810ddeb4>] do_writepages+0x21/0x2a
> [  454.791703]  [<ffffffff8113cbb7>] writeback_single_inode+0xb2/0x1bc
> [  454.794334]  [<ffffffff8113cf03>] writeback_sb_inodes+0xcd/0x161
> [  454.796962]  [<ffffffff8113d407>] writeback_inodes_wb+0x119/0x12b
> [  454.799582]  [<ffffffff8113d607>] wb_writeback+0x1ee/0x335
> [  454.802204]  [<ffffffff81080be3>] ? arch_local_irq_save+0x15/0x1b
> [  454.804803]  [<ffffffff8147be3a>] ? _raw_spin_lock_irqsave+0x12/0x2f
> [  454.807427]  [<ffffffff8113d891>] wb_do_writeback+0x143/0x19d
> [  454.810077]  [<ffffffff8147acc7>] ? schedule_timeout+0xb0/0xde
> [  454.812776]  [<ffffffff8113d973>] bdi_writeback_thread+0x88/0x1e5
> [  454.815464]  [<ffffffff8113d8eb>] ? wb_do_writeback+0x19d/0x19d
> [  454.818129]  [<ffffffff8106e157>] kthread+0x84/0x8c
> [  454.820808]  [<ffffffff81483764>] kernel_thread_helper+0x4/0x10
> [  454.823452]  [<ffffffff8106e0d3>] ? kthread_worker_fn+0x148/0x148
> [  454.826103]  [<ffffffff81483760>] ? gs_change+0x13/0x13

Looks like it is blocked waiting for the journal.

> [  454.828711] jbd2/dm-2-8     D 0000000000000000     0   799      2 0x00000000
> [  454.831390]  ffff88006d59db10 0000000000000046 ffff88006d59daa0 ffffffff00000000
> [  454.834094]  ffff88006deb4500 ffff88006d59dfd8 ffff88006d59dfd8 0000000000013b40
> [  454.836788]  ffffffff81a0b020 ffff88006deb4500 ffff88006d59dad0 000000016d59dad0
> [  454.839453] Call Trace:
> [  454.842098]  [<ffffffff810d5904>] ? lock_page+0x3e/0x3e
> [  454.844738]  [<ffffffff810d5904>] ? lock_page+0x3e/0x3e
> [  454.847303]  [<ffffffff8147a7c9>] io_schedule+0x63/0x7e
> [  454.849877]  [<ffffffff810d5912>] sleep_on_page+0xe/0x12
> [  454.852469]  [<ffffffff8147aea9>] __wait_on_bit+0x48/0x7b
> [  454.855021]  [<ffffffff810d5a8c>] wait_on_page_bit+0x72/0x74
> [  454.857583]  [<ffffffff8106e88b>] ? autoremove_wake_function+0x3d/0x3d
> [  454.860171]  [<ffffffff810d5b6b>] filemap_fdatawait_range+0x84/0x163
> [  454.862744]  [<ffffffff810d5c6e>] filemap_fdatawait+0x24/0x26
> [  454.865299]  [<ffffffff811c94a2>] jbd2_journal_commit_transaction+0x922/0x1194
> [  454.867892]  [<ffffffff81008714>] ? __switch_to+0xc6/0x220
> [  454.870496]  [<ffffffff811cd3b6>] kjournald2+0xc9/0x20a
> [  454.873103]  [<ffffffff8106e84e>] ? remove_wait_queue+0x3a/0x3a
> [  454.875690]  [<ffffffff811cd2ed>] ? commit_timeout+0x10/0x10
> [  454.878327]  [<ffffffff8106e157>] kthread+0x84/0x8c
> [  454.880961]  [<ffffffff81483764>] kernel_thread_helper+0x4/0x10
> [  454.883604]  [<ffffffff8106e0d3>] ? kthread_worker_fn+0x148/0x148
> [  454.886262]  [<ffffffff81483760>] ? gs_change+0x13/0x13

which is blocked waiting for _data_ IO completion.

> [  454.888875] tar             D ffff88006e573af8     0   991    838 0x00000000
> [  454.891546]  ffff880037f5b8a8 0000000000000086 ffff8801002a1d40 0000000000000282
> [  454.894213]  ffff88006d644500 ffff880037f5bfd8 ffff880037f5bfd8 0000000000013b40
> [  454.896889]  ffff8801002b4500 ffff88006d644500 ffff880037f5b8a8 ffffffff8106e7c3
> [  454.899530] Call Trace:
> [  454.902118]  [<ffffffff8106e7c3>] ? prepare_to_wait+0x6c/0x78
> [  454.904724]  [<ffffffff811c82b8>] do_get_write_access+0x1c6/0x38d
> [  454.907344]  [<ffffffff8106e88b>] ? autoremove_wake_function+0x3d/0x3d
> [  454.909967]  [<ffffffff811991cc>] ? ext4_dirty_inode+0x33/0x4c
> [  454.912574]  [<ffffffff811c8588>] jbd2_journal_get_write_access+0x2b/0x42
> [  454.915192]  [<ffffffff811b5888>] __ext4_journal_get_write_access+0x58/0x66
> [  454.917819]  [<ffffffff81195526>] ext4_reserve_inode_write+0x41/0x83
> [  454.920459]  [<ffffffff811955e4>] ext4_mark_inode_dirty+0x7c/0x1f0
> [  454.923070]  [<ffffffff811991cc>] ext4_dirty_inode+0x33/0x4c
> [  454.925660]  [<ffffffff8113c3d6>] __mark_inode_dirty+0x2f/0x175
> [  454.928247]  [<ffffffff81143a0d>] generic_write_end+0x6c/0x7e
> [  454.930865]  [<ffffffff811983f6>] ext4_da_write_end+0x1a5/0x204
> [  454.933454]  [<ffffffff810d5e9d>] generic_file_buffered_write+0x17e/0x23a
> [  454.936062]  [<ffffffff810d6c9d>] __generic_file_aio_write+0x242/0x272
> [  454.938648]  [<ffffffff810d6d2e>] generic_file_aio_write+0x61/0xba
> [  454.941288]  [<ffffffff8118fe00>] ext4_file_write+0x1dc/0x234
> [  454.943909]  [<ffffffff8111edab>] do_sync_write+0xbf/0xff
> [  454.946501]  [<ffffffff8114b9fc>] ? fsnotify+0x1eb/0x217
> [  454.949114]  [<ffffffff811f1866>] ? selinux_file_permission+0x58/0xb4
> [  454.951736]  [<ffffffff811e9cfe>] ? security_file_permission+0x2e/0x33
> [  454.954349]  [<ffffffff8111f196>] ? rw_verify_area+0xb0/0xcd
> [  454.956943]  [<ffffffff8111f421>] vfs_write+0xac/0xf3
> [  454.959530]  [<ffffffff8111f610>] sys_write+0x4a/0x6e
> [  454.962129]  [<ffffffff81482642>] system_call_fastpath+0x16/0x1b

And tar is blocked waiting for the journal, too.

Looks like a case of a ordered mode data writeback journal stall
(the same basic problem as the ext3 fsync sync-the-world issue).

Cheers,

Dave.
-- 
Dave Chinner
david@xxxxxxxxxxxxx
--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@xxxxxxxxxxxxxxx
More majordomo info at  http://vger.kernel.org/majordomo-info.html
Please read the FAQ at  http://www.tux.org/lkml/