From: NeilBrown <neilb@suse.de>
To: Brassow Jonathan <jbrassow@redhat.com>
Cc: Eivind Sarto <eivindsarto@gmail.com>,
"linux-raid@vger.kernel.org Raid" <linux-raid@vger.kernel.org>
Subject: Re: raid1 data corruption during resync
Date: Thu, 4 Sep 2014 15:28:30 +1000 [thread overview]
Message-ID: <20140904152830.252f6270@notabene.brown> (raw)
In-Reply-To: <4A5FFCF0-B3D2-464D-AE72-9CFCD2F23139@redhat.com>
[-- Attachment #1: Type: text/plain, Size: 14911 bytes --]
On Wed, 3 Sep 2014 16:39:52 -0500 Brassow Jonathan <jbrassow@redhat.com>
wrote:
>
> On Sep 2, 2014, at 8:45 PM, Brassow Jonathan wrote:
>
> >
> > On Sep 2, 2014, at 8:31 PM, NeilBrown wrote:
> >
> >> Thanks for the details Jon. I don't suppose you have a stack trace from an
> >> upstream kernel? Not that I doubt you have one, and I suspect it is very
> >> similar. But I've learnt not to trust "suspect" and "presume" and "no doubt".
> >>
> >> I'll have a look anyway.
> >
> > Indeed - me too. I'll get started on recreating it on the latest upstream kernel now. It does take several hours to reproduce on average, so I likely won't send the update until tomorrow.
> >
> > brassow
>
> The test being run does the following:
> 1) Writes I/O to an FS which is sitting on a RAID dev (created via LVM, but using MD personalities)
> 2) The RAID dev is undergoing its initial resync
> 3) The device in slot 0 suffers a failure. (I can't be sure at the moment if I've seen this trigger from a device failure from a different slot.)
> Sorry the test is so involved. I haven't been able to create a simple reproducer and the tests I have take quite a while (i.e. a number of iterations) to hit the problem. These backtraces came after 45min, which is actually really quick compared to what I've seen.
>
> The kernel I used was 3.17.0-rc3. It is unmodified - I have not applied the patch for reads to potentially resync'ing areas.
>
> brassow
>
> Sep 3 09:18:36 bp-01 kernel: INFO: task kworker/u130:1:6600 blocked for more than 120 seconds.
> Sep 3 09:18:36 bp-01 kernel: Tainted: G E 3.17.0-rc3 #1
> Sep 3 09:18:36 bp-01 kernel: "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> Sep 3 09:18:36 bp-01 kernel: kworker/u130:1 D 0000000000000008 0 6600 2 0x00000080
> Sep 3 09:18:36 bp-01 kernel: Workqueue: writeback bdi_writeback_workfn (flush-253:11)
> Sep 3 09:18:36 bp-01 kernel: ffff880415b3b868 0000000000000046 ffff880415b3b858 ffff88021727efc0
> Sep 3 09:18:36 bp-01 kernel: ffff880415b38010 0000000000012bc0 0000000000012bc0 ffff8804024e4150
> Sep 3 09:18:36 bp-01 kernel: ffff880415b3b838 ffff88041ea52bc0 ffff8804024e4150 ffff880415b3b920
> Sep 3 09:18:36 bp-01 kernel: Call Trace:
> Sep 3 09:18:36 bp-01 kernel: [<ffffffff81580830>] ? yield_to+0x180/0x180
> Sep 3 09:18:36 bp-01 kernel: [<ffffffff81580549>] schedule+0x29/0x70
> Sep 3 09:18:36 bp-01 kernel: [<ffffffff8158061c>] io_schedule+0x8c/0xd0
> Sep 3 09:18:36 bp-01 kernel: [<ffffffff8158085c>] bit_wait_io+0x2c/0x50
> Sep 3 09:18:36 bp-01 kernel: [<ffffffff81580946>] __wait_on_bit_lock+0x76/0xb0
> Sep 3 09:18:36 bp-01 kernel: [<ffffffff81135057>] __lock_page+0x67/0x70
> Sep 3 09:18:36 bp-01 kernel: [<ffffffff8108eb90>] ? wake_atomic_t_function+0x40/0x40
> Sep 3 09:18:36 bp-01 kernel: [<ffffffff81141468>] write_cache_pages+0x318/0x510
> Sep 3 09:18:36 bp-01 kernel: [<ffffffffa01d8b5a>] ? ext4_writepages+0x5a/0x6a0 [ext4]
> Sep 3 09:18:36 bp-01 kernel: [<ffffffff8113ffc0>] ? set_page_dirty+0x60/0x60
> Sep 3 09:18:36 bp-01 kernel: [<ffffffff811416b1>] generic_writepages+0x51/0x80
> Sep 3 09:18:36 bp-01 kernel: [<ffffffff81141715>] do_writepages+0x35/0x40
> Sep 3 09:18:36 bp-01 kernel: [<ffffffff811bfcf9>] __writeback_single_inode+0x49/0x230
> Sep 3 09:18:36 bp-01 kernel: [<ffffffff8108eeef>] ? wake_up_bit+0x2f/0x40
> Sep 3 09:18:36 bp-01 kernel: [<ffffffff811c3139>] writeback_sb_inodes+0x249/0x360
> Sep 3 09:18:36 bp-01 kernel: [<ffffffff8119a415>] ? put_super+0x25/0x40
> Sep 3 09:18:36 bp-01 kernel: [<ffffffff811c32ee>] __writeback_inodes_wb+0x9e/0xd0
> Sep 3 09:18:36 bp-01 kernel: [<ffffffff811c351b>] wb_writeback+0x1fb/0x2c0
> Sep 3 09:18:36 bp-01 kernel: [<ffffffff811c3662>] wb_do_writeback+0x82/0x1f0
> Sep 3 09:18:36 bp-01 kernel: [<ffffffff81078fda>] ? ttwu_do_activate.clone.0+0x4a/0x60
> Sep 3 09:18:36 bp-01 kernel: [<ffffffff811c3840>] bdi_writeback_workfn+0x70/0x210
> Sep 3 09:18:36 bp-01 kernel: [<ffffffff8106b762>] process_one_work+0x182/0x450
> Sep 3 09:18:36 bp-01 kernel: [<ffffffff8106bb4f>] worker_thread+0x11f/0x3c0
> Sep 3 09:18:36 bp-01 kernel: [<ffffffff8106ba30>] ? process_one_work+0x450/0x450
> Sep 3 09:18:36 bp-01 kernel: [<ffffffff8107083e>] kthread+0xce/0xf0
> Sep 3 09:18:36 bp-01 kernel: [<ffffffff81070770>] ? kthread_freezable_should_stop+0x70/0x70
> Sep 3 09:18:36 bp-01 kernel: [<ffffffff8158412c>] ret_from_fork+0x7c/0xb0
> Sep 3 09:18:36 bp-01 kernel: [<ffffffff81070770>] ? kthread_freezable_should_stop+0x70/0x70
> Sep 3 09:18:36 bp-01 kernel: INFO: task kworker/0:4:8765 blocked for more than 120 seconds.
> Sep 3 09:18:36 bp-01 kernel: Tainted: G E 3.17.0-rc3 #1
> Sep 3 09:18:36 bp-01 kernel: "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> Sep 3 09:18:36 bp-01 kernel: kworker/0:4 D 0000000000000000 0 8765 2 0x00000080
> Sep 3 09:18:36 bp-01 kernel: Workqueue: kcopyd do_work [dm_mod]
> Sep 3 09:18:36 bp-01 kernel: ffff8802102ab898 0000000000000046 0000000000000000 ffffffff81a19480
> Sep 3 09:18:36 bp-01 kernel: ffff8802102a8010 0000000000012bc0 0000000000012bc0 ffff880215950010
> Sep 3 09:18:36 bp-01 kernel: ffff8802102ab898 ffff88040171e100 ffff88040171e178 ffff8802102ab8c8
> Sep 3 09:18:36 bp-01 kernel: Call Trace:
> Sep 3 09:18:36 bp-01 kernel: [<ffffffff81580549>] schedule+0x29/0x70
> Sep 3 09:18:36 bp-01 kernel: [<ffffffffa0389e99>] wait_barrier+0xb9/0x260 [raid1]
> Sep 3 09:18:36 bp-01 kernel: [<ffffffff8108eb00>] ? bit_waitqueue+0xe0/0xe0
> Sep 3 09:18:36 bp-01 kernel: [<ffffffff8108ee13>] ? __wake_up+0x53/0x70
> Sep 3 09:18:36 bp-01 kernel: [<ffffffffa038caaa>] make_request+0x9a/0xc00 [raid1]
> Sep 3 09:18:37 bp-01 lvm[2109]: device-mapper: waitevent ioctl on (LVM-PSbaO1Zwzw2wYurZrkrTkI5grmcS3IQ3ot9VJPwplnllFf45AU5vBkbtjfLU0adG) failed: Interrupted system call
> Sep 3 09:18:37 bp-01 kernel: [<ffffffff81137f60>] ? mempool_alloc+0x60/0x170
> Sep 3 09:18:37 bp-01 kernel: [<ffffffff81186ea8>] ? cache_alloc_refill+0x98/0x2c0
> Sep 3 09:18:37 bp-01 kernel: [<ffffffffa03a4018>] raid_map+0x18/0x20 [dm_raid]
> Sep 3 09:18:37 bp-01 kernel: [<ffffffffa000336a>] __map_bio+0x4a/0x120 [dm_mod]
> Sep 3 09:18:37 bp-01 kernel: [<ffffffffa0003723>] __clone_and_map_data_bio+0x113/0x130 [dm_mod]
> Sep 3 09:18:37 bp-01 kernel: [<ffffffffa00037ac>] __split_and_process_non_flush+0x6c/0xb0 [dm_mod]
> Sep 3 09:18:37 bp-01 kernel: [<ffffffffa0003991>] __split_and_process_bio+0x1a1/0x200 [dm_mod]
> Sep 3 09:18:37 bp-01 kernel: [<ffffffffa0003b12>] _dm_request+0x122/0x190 [dm_mod]
> Sep 3 09:18:37 bp-01 kernel: [<ffffffffa0003ba8>] dm_request+0x28/0x40 [dm_mod]
> Sep 3 09:18:37 bp-01 kernel: [<ffffffff812693b0>] generic_make_request+0xc0/0x100
> Sep 3 09:18:37 bp-01 kernel: [<ffffffffa03ba00c>] pending_complete+0x13c/0x2a0 [dm_snapshot]
> Sep 3 09:18:37 bp-01 kernel: [<ffffffffa03ba29e>] commit_callback+0xe/0x10 [dm_snapshot]
> Sep 3 09:18:37 bp-01 kernel: [<ffffffffa03bcea8>] persistent_commit_exception+0xb8/0x160 [dm_snapshot]
> Sep 3 09:18:37 bp-01 kernel: [<ffffffffa03ba1a3>] complete_exception+0x33/0x50 [dm_snapshot]
> Sep 3 09:18:37 bp-01 kernel: [<ffffffffa03ba26a>] copy_callback+0xaa/0xd0 [dm_snapshot]
> Sep 3 09:18:37 bp-01 kernel: [<ffffffffa03ba1c0>] ? complete_exception+0x50/0x50 [dm_snapshot]
> Sep 3 09:18:37 bp-01 kernel: [<ffffffffa000b788>] run_complete_job+0x98/0xe0 [dm_mod]
> Sep 3 09:18:37 bp-01 kernel: [<ffffffffa000b21b>] process_jobs+0x5b/0x100 [dm_mod]
> Sep 3 09:18:37 bp-01 kernel: [<ffffffffa000b6f0>] ? dispatch_job+0x80/0x80 [dm_mod]
> Sep 3 09:18:37 bp-01 kernel: [<ffffffffa000b2ff>] do_work+0x3f/0x80 [dm_mod]
> Sep 3 09:18:37 bp-01 kernel: [<ffffffff8106b762>] process_one_work+0x182/0x450
> Sep 3 09:18:37 bp-01 kernel: [<ffffffff8106bb4f>] worker_thread+0x11f/0x3c0
> Sep 3 09:18:37 bp-01 kernel: [<ffffffff8106ba30>] ? process_one_work+0x450/0x450
> Sep 3 09:18:37 bp-01 kernel: [<ffffffff8107083e>] kthread+0xce/0xf0
> Sep 3 09:18:37 bp-01 kernel: [<ffffffff81070770>] ? kthread_freezable_should_stop+0x70/0x70
> Sep 3 09:18:37 bp-01 kernel: [<ffffffff8158412c>] ret_from_fork+0x7c/0xb0
> Sep 3 09:18:37 bp-01 kernel: [<ffffffff81070770>] ? kthread_freezable_should_stop+0x70/0x70
> Sep 3 09:18:37 bp-01 kernel: INFO: task kjournald:12268 blocked for more than 120 seconds.
> Sep 3 09:18:37 bp-01 kernel: Tainted: G E 3.17.0-rc3 #1
> Sep 3 09:18:37 bp-01 kernel: "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> Sep 3 09:18:37 bp-01 kernel: kjournald D 0000000000000000 0 12268 2 0x00000080
> Sep 3 09:18:37 bp-01 kernel: ffff88040d373c08 0000000000000046 ffff88040d373bd8 ffffffff81a19480
> Sep 3 09:18:37 bp-01 kernel: ffff88040d370010 0000000000012bc0 0000000000012bc0 ffff8804153a0e80
> Sep 3 09:18:37 bp-01 kernel: ffff88040d373c08 ffff88021fa12bc0 ffff8804153a0e80 ffffffff81580830
> Sep 3 09:18:37 bp-01 kernel: Call Trace:
> Sep 3 09:18:37 bp-01 kernel: [<ffffffff81580830>] ? yield_to+0x180/0x180
> Sep 3 09:18:37 bp-01 kernel: [<ffffffff81580549>] schedule+0x29/0x70
> Sep 3 09:18:37 bp-01 kernel: [<ffffffff8158061c>] io_schedule+0x8c/0xd0
> Sep 3 09:18:37 bp-01 kernel: [<ffffffff8158085c>] bit_wait_io+0x2c/0x50
> Sep 3 09:18:37 bp-01 kernel: [<ffffffff81580b45>] __wait_on_bit+0x65/0x90
> Sep 3 09:18:37 bp-01 kernel: [<ffffffff81580830>] ? yield_to+0x180/0x180
> Sep 3 09:18:37 bp-01 kernel: [<ffffffff81580be8>] out_of_line_wait_on_bit+0x78/0x90
> Sep 3 09:18:37 bp-01 kernel: [<ffffffff8108eb90>] ? wake_atomic_t_function+0x40/0x40
> Sep 3 09:18:37 bp-01 kernel: [<ffffffff811ca14e>] __wait_on_buffer+0x2e/0x30
> Sep 3 09:18:37 bp-01 kernel: [<ffffffffa0448372>] journal_commit_transaction+0x872/0xf80 [jbd]
> Sep 3 09:18:37 bp-01 kernel: [<ffffffff8108847f>] ? put_prev_entity+0x2f/0x400
> Sep 3 09:18:37 bp-01 kernel: [<ffffffff810b21bb>] ? try_to_del_timer_sync+0x5b/0x70
> Sep 3 09:18:37 bp-01 kernel: [<ffffffffa044bae1>] kjournald+0xf1/0x270 [jbd]
> Sep 3 09:18:37 bp-01 kernel: [<ffffffff8108eb00>] ? bit_waitqueue+0xe0/0xe0
> Sep 3 09:18:37 bp-01 kernel: [<ffffffffa044b9f0>] ? commit_timeout+0x10/0x10 [jbd]
> Sep 3 09:18:37 bp-01 kernel: [<ffffffff8107083e>] kthread+0xce/0xf0
> Sep 3 09:18:37 bp-01 kernel: [<ffffffff81070770>] ? kthread_freezable_should_stop+0x70/0x70
> Sep 3 09:18:37 bp-01 kernel: [<ffffffff8158412c>] ret_from_fork+0x7c/0xb0
> Sep 3 09:18:37 bp-01 kernel: [<ffffffff81070770>] ? kthread_freezable_should_stop+0x70/0x70
> Sep 3 09:18:37 bp-01 kernel: INFO: task xdoio:12364 blocked for more than 120 seconds.
> Sep 3 09:18:37 bp-01 kernel: Tainted: G E 3.17.0-rc3 #1
> Sep 3 09:18:37 bp-01 kernel: "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> Sep 3 09:18:37 bp-01 kernel: xdoio D 0000000000000005 0 12364 12363 0x00000080
> Sep 3 09:18:37 bp-01 kernel: ffff8804037af978 0000000000000082 ffff8804037af948 ffff88021726c1d0
> Sep 3 09:18:37 bp-01 kernel: ffff8804037ac010 0000000000012bc0 0000000000012bc0 ffff8804063a0050
> Sep 3 09:18:37 bp-01 kernel: ffff8804037af978 ffff88021fab2bc0 ffff8804063a0050 ffff8804037afa30
> Sep 3 09:18:37 bp-01 kernel: Call Trace:
> Sep 3 09:18:37 bp-01 kernel: [<ffffffff81580830>] ? yield_to+0x180/0x180
> Sep 3 09:18:37 bp-01 kernel: [<ffffffff81580549>] schedule+0x29/0x70
> Sep 3 09:18:37 bp-01 kernel: [<ffffffff8158061c>] io_schedule+0x8c/0xd0
> Sep 3 09:18:37 bp-01 kernel: [<ffffffff8158085c>] bit_wait_io+0x2c/0x50
> Sep 3 09:18:37 bp-01 kernel: [<ffffffff81580946>] __wait_on_bit_lock+0x76/0xb0
> Sep 3 09:18:37 bp-01 kernel: [<ffffffff81580830>] ? yield_to+0x180/0x180
> Sep 3 09:18:37 bp-01 kernel: [<ffffffff815809f8>] out_of_line_wait_on_bit_lock+0x78/0x90
> Sep 3 09:18:37 bp-01 kernel: [<ffffffff8108eb90>] ? wake_atomic_t_function+0x40/0x40
> Sep 3 09:18:37 bp-01 kernel: [<ffffffff811ca36e>] __lock_buffer+0x2e/0x30
> Sep 3 09:18:37 bp-01 kernel: [<ffffffff811cb520>] __sync_dirty_buffer+0xa0/0xd0
> Sep 3 09:18:37 bp-01 kernel: [<ffffffff811cb563>] sync_dirty_buffer+0x13/0x20
> Sep 3 09:18:37 bp-01 kernel: [<ffffffffa0446e12>] journal_dirty_data+0x1f2/0x260 [jbd]
> Sep 3 09:18:37 bp-01 kernel: [<ffffffffa0464200>] ext3_journal_dirty_data+0x20/0x50 [ext3]
> Sep 3 09:18:37 bp-01 kernel: [<ffffffffa0464255>] journal_dirty_data_fn+0x25/0x30 [ext3]
> Sep 3 09:18:37 bp-01 kernel: [<ffffffffa04638d4>] walk_page_buffers+0x84/0xc0 [ext3]
> Sep 3 09:18:37 bp-01 kernel: [<ffffffffa0464230>] ? ext3_journal_dirty_data+0x50/0x50 [ext3]
> Sep 3 09:18:37 bp-01 kernel: [<ffffffffa046797f>] ext3_ordered_write_end+0xaf/0x1e0 [ext3]
> Sep 3 09:18:37 bp-01 kernel: [<ffffffff81134b42>] generic_perform_write+0x112/0x1c0
> Sep 3 09:18:37 bp-01 kernel: [<ffffffff81137aaf>] __generic_file_write_iter+0x18f/0x390
> Sep 3 09:18:37 bp-01 kernel: [<ffffffff81137cfe>] generic_file_write_iter+0x4e/0xd0
> Sep 3 09:18:37 bp-01 kernel: [<ffffffff81197347>] do_iter_readv_writev+0x77/0xb0
> Sep 3 09:18:37 bp-01 kernel: [<ffffffff8122e483>] ? security_file_permission+0x23/0x90
> Sep 3 09:18:37 bp-01 kernel: [<ffffffff81137cb0>] ? __generic_file_write_iter+0x390/0x390
> Sep 3 09:18:37 bp-01 kernel: [<ffffffff81137cb0>] ? __generic_file_write_iter+0x390/0x390
> Sep 3 09:18:37 bp-01 kernel: [<ffffffff81198a60>] do_readv_writev+0xd0/0x320
> Sep 3 09:18:37 bp-01 kernel: [<ffffffff81137cb0>] ? __generic_file_write_iter+0x390/0x390
> Sep 3 09:18:37 bp-01 kernel: [<ffffffff81197400>] ? do_sync_readv_writev+0x80/0x80
> Sep 3 09:18:37 bp-01 kernel: [<ffffffff810c724f>] ? do_futex+0xaf/0x1b0
> Sep 3 09:18:37 bp-01 kernel: [<ffffffff81198cf1>] vfs_writev+0x41/0x50
> Sep 3 09:18:37 bp-01 kernel: [<ffffffff81198e26>] SyS_writev+0x56/0xf0
> Sep 3 09:18:37 bp-01 kernel: [<ffffffff810ec456>] ? __audit_syscall_exit+0x216/0x2c0
> Sep 3 09:18:37 bp-01 kernel: [<ffffffff815841d2>] system_call_fastpath+0x16/0x1b
Thanks a lot. I love having concrete data....
I had a theory. Then another. None of them have really stood up yet. But
there are definitely problems with the code.
1/ When the resync aborts close_sync() may set ->start_next_window to
MaxSector without merging next_window_requests into current_window_requests.
So those numbers can be wrong.
2/ raise_barrier() cannot detect if there are any pending requests in the
region it is about to resync. That can lead to corruption!!
Neither of these explain the hang you are seeing.
I note that the "md0-resync" thread isn't listed. I don't suppose you know
what it was doing (stack trace)??
Also, had "md: md0: sync done" appeared in syslog yet?
Thanks,
NeilBrown
[-- Attachment #2: signature.asc --]
[-- Type: application/pgp-signature, Size: 828 bytes --]
next prev parent reply other threads:[~2014-09-04 5:28 UTC|newest]
Thread overview: 16+ messages / expand[flat|nested] mbox.gz Atom feed top
2014-08-29 19:29 raid1 data corruption during resync Eivind Sarto
2014-09-02 14:10 ` Brassow Jonathan
2014-09-02 16:43 ` Eivind Sarto
2014-09-02 17:04 ` Eivind Sarto
2014-09-02 16:59 ` Brassow Jonathan
2014-09-02 19:24 ` Brassow Jonathan
2014-09-02 22:07 ` Eivind Sarto
2014-09-02 22:14 ` Brassow Jonathan
2014-09-02 23:55 ` NeilBrown
2014-09-03 0:48 ` Eivind Sarto
2014-09-03 1:18 ` Brassow Jonathan
2014-09-03 1:31 ` NeilBrown
2014-09-03 1:45 ` Brassow Jonathan
2014-09-03 21:39 ` Brassow Jonathan
2014-09-04 5:28 ` NeilBrown [this message]
[not found] <D4FE2D75-4208-48C9-A4D0-432F092E5AE9@redhat.com>
2014-09-08 15:52 ` Fwd: " Brassow Jonathan
2014-09-09 1:08 ` NeilBrown
Reply instructions:
You may reply publicly to this message via plain-text email
using any one of the following methods:
* Save the following mbox file, import it into your mail client,
and reply-to-all from there: mbox
Avoid top-posting and favor interleaved quoting:
https://en.wikipedia.org/wiki/Posting_style#Interleaved_style
* Reply using the --to, --cc, and --in-reply-to
switches of git-send-email(1):
git send-email \
--in-reply-to=20140904152830.252f6270@notabene.brown \
--to=neilb@suse.de \
--cc=eivindsarto@gmail.com \
--cc=jbrassow@redhat.com \
--cc=linux-raid@vger.kernel.org \
/path/to/YOUR_REPLY
https://kernel.org/pub/software/scm/git/docs/git-send-email.html
* If your mail client supports setting the In-Reply-To header
via mailto: links, try the mailto: link
Be sure your reply has a Subject: header at the top and a blank line
before the message body.
This is a public inbox, see mirroring instructions
for how to clone and mirror all data and code used for this inbox;
as well as URLs for NNTP newsgroup(s).