* Re: /sys/block/md126 still exists even after stopping the array
From: NeilBrown @ 2014-09-29 4:47 UTC (permalink / raw)
To: Francis Moreau; +Cc: linux-raid, sebastian.riemer
In-Reply-To: <54256100.3090507@gmail.com>
[-- Attachment #1: Type: text/plain, Size: 3413 bytes --]
On Fri, 26 Sep 2014 14:50:08 +0200 Francis Moreau <francis.moro@gmail.com>
wrote:
> On 09/26/2014 02:21 PM, Francis Moreau wrote:
> [...]
>
> >
> >>>> mdadm --stop --scan <<<
> >
> > [ 89.975162] md_open(): md125 opened by mdadm [930]
> > [ 89.975305] md_release(): md125 released by mdadm [930]
> > [ 89.977434] md_open(): md125 opened by mdadm [932]
> > [ 89.978813] md_open(): md125 opened by mdadm [930]
> > [ 89.979365] md_release(): md125 released by mdadm [932]
> > [ 89.979693] md_open(): md125 opened by systemd-udevd [931]
> > [ 89.985790] md_release(): md125 released by systemd-udevd [931]
> > [ 90.179911] md_release(): md125 released by mdadm [930]
> > [ 90.180168] md_open(): md127 opened by mdadm [459]
> > [ 90.180187] md_release(): md127 released by mdadm [459]
> > [ 90.180199] md_open(): md126 opened by mdadm [459]
> > [ 90.180205] md_release(): md126 released by mdadm [459]
> > [ 90.180556] md_open(): md126 opened by mdadm [930]
> > [ 90.180653] md_release(): md126 released by mdadm [930]
> > [ 90.180690] md_open(): md126 opened by mdadm [930]
> > [ 90.180758] md_open(): mdX opened by mdadm [459]
>
> What is this 'mdX' device that mdadm operates on ?
>
> It also doesn't have a counterpart release() call.
'mdX' is the name used if mddev->gendisk is NULL.
In that case, md_open() will return an error (ERESTARTSYS).
As the 'open' failed, we wouldn't expect a matching close/release.
NeilBrown
>
>
> > [ 90.180995] md_open(): md125 opened by mdadm [459]
> > [ 90.181056] md_release(): md125 released by mdadm [459]
> > [ 90.182717] md_open(): md127 opened by mdadm [459]
> > [ 90.182725] md_release(): md127 released by mdadm [459]
> > [ 90.182732] md_open(): md126 opened by mdadm [459]
> > [ 90.182761] md_release(): md126 released by mdadm [459]
> > [ 90.182770] md_open(): md125 opened by mdadm [459]
> > [ 90.182775] md_release(): md125 released by mdadm [459]
> > [ 90.182940] md_release(): md126 released by mdadm [930]
> > [ 90.183167] md_open(): md127 opened by mdadm [930]
> > [ 90.183257] md_release(): md127 released by mdadm [930]
> > [ 90.183288] md_open(): md127 opened by mdadm [930]
> > [ 90.183461] md_open(): md127 opened by mdadm [459]
> > [ 90.183488] md_release(): md127 released by mdadm [459]
> > [ 90.183499] md_open(): md125 opened by mdadm [459]
> > [ 90.183505] md_release(): md125 released by mdadm [459]
> > [ 90.183686] md_release(): md127 released by mdadm [930]
> >
> >
> >> Probably there is a 'change' event happening just before the 'remove' event,
> >> and udev runs "mdadm" on the 'change' event, and that ends up happening after
> >> the device has been removed.
> >>
> >> Is this really a problem? Can't you just ignore it and pretend it isn't
> >> there?
> >
> > Well, if you list the block devices that the kernel detected in order to
> > operate on them, it could. I don't know exactly what would be the result
> > to use it but it could confuse some tools.
> >
> > Is there a way to check that the 'ghost' device has been removed by
> > poking sysfs ?
> >
> > Thanks
> >
>
> --
> To unsubscribe from this list: send the line "unsubscribe linux-raid" in
> the body of a message to majordomo@vger.kernel.org
> More majordomo info at http://vger.kernel.org/majordomo-info.html
[-- Attachment #2: OpenPGP digital signature --]
[-- Type: application/pgp-signature, Size: 828 bytes --]
^ permalink raw reply
* Re: Raid5 hang in 3.14.19
From: NeilBrown @ 2014-09-29 4:43 UTC (permalink / raw)
To: BillStuff; +Cc: linux-raid
In-Reply-To: <5428DFE1.9080600@sbcglobal.net>
[-- Attachment #1: Type: text/plain, Size: 4929 bytes --]
On Sun, 28 Sep 2014 23:28:17 -0500 BillStuff <billstuff2001@sbcglobal.net>
wrote:
> On 09/28/2014 11:08 PM, NeilBrown wrote:
> > On Sun, 28 Sep 2014 22:56:19 -0500 BillStuff <billstuff2001@sbcglobal.net>
> > wrote:
> >
> >> On 09/28/2014 09:25 PM, NeilBrown wrote:
> >>> On Fri, 26 Sep 2014 17:33:58 -0500 BillStuff <billstuff2001@sbcglobal.net>
> >>> wrote:
> >>>
> >>>> Hi Neil,
> >>>>
> >>>> I found something that looks similar to the problem described in
> >>>> "Re: seems like a deadlock in workqueue when md do a flush" from Sept 14th.
> >>>>
> >>>> It's on 3.14.19 with 7 recent patches for fixing raid1 recovery hangs.
> >>>>
> >>>> on this array:
> >>>> md3 : active raid5 sdf1[5] sde1[4] sdd1[3] sdc1[2] sdb1[1] sda1[0]
> >>>> 104171200 blocks level 5, 64k chunk, algorithm 2 [6/6] [UUUUUU]
> >>>> bitmap: 1/5 pages [4KB], 2048KB chunk
> >>>>
> >>>> I was running a test doing parallel kernel builds, read/write loops, and
> >>>> disk add / remove / check loops,
> >>>> on both this array and a raid1 array.
> >>>>
> >>>> I was trying to stress test your recent raid1 fixes, which went well,
> >>>> but then after 5 days,
> >>>> the raid5 array hung up with this in dmesg:
> >>> I think this is different to the workqueue problem you mentioned, though as I
> >>> don't know exactly what caused either I cannot be certain.
> >>>
> >>> From the data you provided it looks like everything is waiting on
> >>> get_active_stripe(), or on a process that is waiting on that.
> >>> That seems pretty common whenever anything goes wrong in raid5 :-(
> >>>
> >>> The md3_raid5 task is listed as blocked, but not stack trace is given.
> >>> If the machine is still in the state, then
> >>>
> >>> cat /proc/1698/stack
> >>>
> >>> might be useful.
> >>> (echo t > /proc/sysrq-trigger is always a good idea)
> >> Might this help? I believe the array was doing a "check" when things
> >> hung up.
> > It looks like it was trying to start doing a 'check'.
> > The 'resync' thread hadn't been started yet.
> > What is 'kthreadd' doing?
> > My guess is that it is in try_to_free_pages() waiting for writeout
> > for some xfs file page onto the md array ... which won't progress until
> > the thread gets started.
> >
> > That would suggest that we need an async way to start threads...
> >
> > Thanks,
> > NeilBrown
> >
>
> I suspect your guess is correct:
Yes, looks like it is - thanks.
I'll probably get a workqueue to start the thread, so the md thread doesn't
block on it.
thanks,
NeilBrown
>
> kthreadd D c106ea4c 0 2 0 0x00000000
> e9d6db58 00000046 e9d6db4c c106ea4c ce493c00 00000001 1e9bb7bd 0001721a
> c17d6700 c17d6700 d3b6a880 e9d38510 f2cf4c00 00000000 f2e51c00 e9d6db60
> f3cec0b6 e9d38510 f2e51d14 f2e51d00 f2e51c00 00043132 00000964 0000a4b0
> Call Trace:
> [<c106ea4c>] ? update_blocked_averages+0x1ec/0x700
> [<f3cec0b6>] ? xlog_cil_force_lsn+0xd6/0x1c0 [xfs]
> [<f3cc077b>] ? xfs_bmbt_get_all+0x2b/0x40 [xfs]
> [<c153e7f3>] schedule+0x23/0x60
> [<f3ceaa71>] _xfs_log_force_lsn+0x141/0x270 [xfs]
> [<c1069ca0>] ? wake_up_process+0x40/0x40
> [<f3ceabd8>] xfs_log_force_lsn+0x38/0x90 [xfs]
> [<f3cd7ee0>] __xfs_iunpin_wait+0x80/0x100 [xfs]
> [<f3cdb02d>] ? xfs_iunpin_wait+0x1d/0x30 [xfs]
> [<c10799d0>] ? autoremove_wake_function+0x40/0x40
> [<f3cdb02d>] xfs_iunpin_wait+0x1d/0x30 [xfs]
> [<f3c99938>] xfs_reclaim_inode+0x58/0x2f0 [xfs]
> [<f3c99e04>] xfs_reclaim_inodes_ag+0x234/0x330 [xfs]
> [<f3c9a6a1>] ? xfs_inode_set_reclaim_tag+0x91/0x150 [xfs]
> [<c115cc41>] ? fsnotify_clear_marks_by_inode+0x21/0xe0
> [<f3ca5ac5>] ? xfs_fs_destroy_inode+0xa5/0xd0 [xfs]
> [<c113b061>] ? destroy_inode+0x31/0x50
> [<c113b160>] ? evict+0xe0/0x160
> [<f3c9a7ad>] xfs_reclaim_inodes_nr+0x2d/0x40 [xfs]
> [<f3ca5103>] xfs_fs_free_cached_objects+0x13/0x20 [xfs]
> [<c11278ce>] super_cache_scan+0x12e/0x140
> [<c10f2bb5>] shrink_slab_node+0x125/0x280
> [<c1101a1c>] ? compact_zone+0x2c/0x450
> [<c10f3489>] shrink_slab+0xd9/0xf0
> [<c10f557d>] try_to_free_pages+0x25d/0x4f0
> [<c10eb96d>] __alloc_pages_nodemask+0x52d/0x820
> [<c103c452>] copy_process.part.47+0xd2/0x14e0
> [<c153e254>] ? __schedule+0x224/0x7a0
> [<c105ad80>] ? kthread_create_on_node+0x110/0x110
> [<c105ad80>] ? kthread_create_on_node+0x110/0x110
> [<c103da01>] do_fork+0xc1/0x320
> [<c105ad80>] ? kthread_create_on_node+0x110/0x110
> [<c103dc8d>] kernel_thread+0x2d/0x40
> [<c105b542>] kthreadd+0x122/0x170
> [<c1541837>] ret_from_kernel_thread+0x1b/0x28
> [<c105b420>] ? kthread_create_on_cpu+0x60/0x60
>
>
> --
> To unsubscribe from this list: send the line "unsubscribe linux-raid" in
> the body of a message to majordomo@vger.kernel.org
> More majordomo info at http://vger.kernel.org/majordomo-info.html
[-- Attachment #2: OpenPGP digital signature --]
[-- Type: application/pgp-signature, Size: 828 bytes --]
^ permalink raw reply
* Re: /sys/block/md126 still exists even after stopping the array
From: NeilBrown @ 2014-09-29 4:37 UTC (permalink / raw)
To: Francis Moreau; +Cc: linux-raid, sebastian.riemer
In-Reply-To: <54255A30.9010406@gmail.com>
[-- Attachment #1: Type: text/plain, Size: 8866 bytes --]
On Fri, 26 Sep 2014 14:21:04 +0200 Francis Moreau <francis.moro@gmail.com>
wrote:
> On 09/26/2014 12:44 PM, NeilBrown wrote:
> > On Fri, 26 Sep 2014 12:23:27 +0200 Francis Moreau <francis.moro@gmail.com>
> > wrote:
> >
> >> Hello Neil,
> >>
> >> On 09/26/2014 02:33 AM, NeilBrown wrote:
> >>> On Thu, 25 Sep 2014 18:12:07 +0200 Francis Moreau <francis.moro@gmail.com>
> >>> wrote:
> >> [...]
> >>>> I tried to find out what could have opened the md device by using fuser,
> >>>> but fuser reports no users.
> >>>
> >>> It is probably a transient open/close.
> >>>
> >>
> >> If it's open/close wouldn't the 'close' part make the device disapear ?
> >
> > No. It's ... complicated.
> >
> >>
> >>>>
> >>>> I took a look to the udev rules which are the one shipped by mdadm 3.3.2
> >>>> but nothing keep the device opened during the remove event.
> >>>>
> >>>> Could you give me some hints here to debug this ?
> >>>
> >>> Modify md_open in drivers/md/md.c to add
> >>> printk("Opened by %s\n", current->comm);
> >>>
> >>> and build a new kernel. That will tell you the name of the process which
> >>> opened the device.
> >>>
> >>
> >> I did that I also added a trace in md_release() but strangely no trace
> >> were outputed from there.
> >
> > Without seeing your patch I can't guess what it happening, but I am *certain*
> > that md_release() would get called providing md_open didn't return an error.
>
> Here's the patch:
>
> diff --git a/drivers/md/md.c b/drivers/md/md.c
> index 73aedcb..08ead8d 100644
> --- a/drivers/md/md.c
> +++ b/drivers/md/md.c
> @@ -6703,6 +6703,8 @@ static int md_open(struct block_device *bdev,
> fmode_t mode)
> struct mddev *mddev = mddev_find(bdev->bd_dev);
> int err;
>
> + printk("md_open(): opened by %s\n", current->comm);
> +
> if (!mddev)
> return -ENODEV;
>
> @@ -6735,6 +6737,8 @@ static void md_release(struct gendisk *disk,
> fmode_t mode)
> {
> struct mddev *mddev = disk->private_data;
>
> + printk("md_release(): released by %s\n", current->comm);
> +
> BUG_ON(!mddev);
> atomic_dec(&mddev->openers);
> mddev_put(mddev);
>
> >
> > It might be helpful to print out the pid and the md device number too
> > task_tgid_vnr(current)
> > will give you the pid.
> > mdname(mddev)
> > give the name of the device.
> >
>
> Here's the new trace, this time md_release() was called, so I probably
> did something wrong the first time, sorry for that.
>
> [ 1.470744] md_open(): md127 opened by mdadm [388]
> [ 1.485437] md_release(): md127 released by mdadm [388]
> [ 1.486888] md_open(): md126 opened by mdadm [381]
> [ 1.487468] md_release(): md126 released by mdadm [381]
> [ 1.488646] md_open(): md125 opened by mdadm [383]
> [ 1.489074] md_release(): md125 released by mdadm [383]
> [ 1.490555] md_open(): md127 opened by mdadm [385]
> [ 1.512556] md_release(): md127 released by mdadm [385]
> [ 1.512582] md_open(): md127 opened by mdadm [385]
> [ 1.512682] md_open(): md126 opened by mdadm [384]
> [ 1.553414] md_release(): md126 released by mdadm [384]
> [ 1.553442] md_open(): md126 opened by mdadm [384]
> [ 1.553549] md_open(): md125 opened by mdadm [382]
> [ 1.573263] md_release(): md125 released by mdadm [382]
> [ 1.573288] md_open(): md125 opened by mdadm [382]
> [ 1.601034] md_open(): md125 opened by mdadm [459]
> [ 1.601041] md_release(): md125 released by mdadm [459]
> [ 1.601065] md_open(): md126 opened by mdadm [459]
> [ 1.601067] md_release(): md126 released by mdadm [459]
> [ 1.601090] md_open(): md127 opened by mdadm [459]
> [ 1.601092] md_release(): md127 released by mdadm [459]
> [ 1.601130] md_open(): md127 opened by mdadm [459]
> [ 1.601220] md_release(): md127 released by mdadm [459]
> [ 1.601633] md_open(): md126 opened by mdadm [459]
> [ 1.601661] md_release(): md126 released by mdadm [459]
> [ 1.601673] md_open(): md125 opened by mdadm [459]
> [ 1.601695] md_release(): md125 released by mdadm [459]
> [ 1.606127] md_open(): md125 opened by mdadm [454]
> [ 1.608682] md_open(): md126 opened by mdadm [453]
> [ 1.609514] md_open(): md127 opened by mdadm [448]
> [ 1.622512] md_release(): md126 released by mdadm [453]
> [ 1.623028] md_release(): md127 released by mdadm [448]
> [ 1.625288] md_open(): md126 opened by systemd-udevd [363]
> [ 1.625391] md_release(): md125 released by mdadm [454]
> [ 1.625619] md_open(): md127 opened by systemd-udevd [368]
> [ 1.625737] md_open(): md125 opened by systemd-udevd [366]
> [ 1.637137] md_release(): md125 released by systemd-udevd [366]
> [ 1.643982] md_open(): md125 opened by mdadm [476]
> [ 1.644071] md_release(): md127 released by systemd-udevd [368]
> [ 1.647787] md_release(): md125 released by mdadm [382]
> [ 1.648171] md_release(): md126 released by systemd-udevd [363]
> [ 1.651629] md_open(): md126 opened by mdadm [479]
> [ 1.656666] md_open(): md127 opened by mdadm [480]
> [ 1.657771] md_release(): md125 released by mdadm [476]
> [ 1.659312] md_open(): md125 opened by systemd-udevd [365]
> [ 1.663193] md_release(): md127 released by mdadm [385]
> [ 1.673669] md_release(): md125 released by systemd-udevd [365]
> [ 1.685527] md_release(): md127 released by mdadm [480]
> [ 1.685599] md_release(): md126 released by mdadm [479]
> [ 1.686058] md_open(): md126 opened by systemd-udevd [366]
> [ 1.686282] md_release(): md126 released by systemd-udevd [366]
> [ 1.691024] md_open(): md127 opened by systemd-udevd [363]
> [ 1.695415] md_release(): md126 released by mdadm [384]
> [ 1.707163] md_release(): md127 released by systemd-udevd [363]
>
> >>> mdadm --stop --scan <<<
>
> [ 89.975162] md_open(): md125 opened by mdadm [930]
> [ 89.975305] md_release(): md125 released by mdadm [930]
> [ 89.977434] md_open(): md125 opened by mdadm [932]
> [ 89.978813] md_open(): md125 opened by mdadm [930]
> [ 89.979365] md_release(): md125 released by mdadm [932]
> [ 89.979693] md_open(): md125 opened by systemd-udevd [931]
> [ 89.985790] md_release(): md125 released by systemd-udevd [931]
> [ 90.179911] md_release(): md125 released by mdadm [930]
> [ 90.180168] md_open(): md127 opened by mdadm [459]
> [ 90.180187] md_release(): md127 released by mdadm [459]
> [ 90.180199] md_open(): md126 opened by mdadm [459]
> [ 90.180205] md_release(): md126 released by mdadm [459]
> [ 90.180556] md_open(): md126 opened by mdadm [930]
> [ 90.180653] md_release(): md126 released by mdadm [930]
> [ 90.180690] md_open(): md126 opened by mdadm [930]
> [ 90.180758] md_open(): mdX opened by mdadm [459]
> [ 90.180995] md_open(): md125 opened by mdadm [459]
> [ 90.181056] md_release(): md125 released by mdadm [459]
> [ 90.182717] md_open(): md127 opened by mdadm [459]
> [ 90.182725] md_release(): md127 released by mdadm [459]
> [ 90.182732] md_open(): md126 opened by mdadm [459]
> [ 90.182761] md_release(): md126 released by mdadm [459]
> [ 90.182770] md_open(): md125 opened by mdadm [459]
> [ 90.182775] md_release(): md125 released by mdadm [459]
> [ 90.182940] md_release(): md126 released by mdadm [930]
> [ 90.183167] md_open(): md127 opened by mdadm [930]
> [ 90.183257] md_release(): md127 released by mdadm [930]
> [ 90.183288] md_open(): md127 opened by mdadm [930]
> [ 90.183461] md_open(): md127 opened by mdadm [459]
> [ 90.183488] md_release(): md127 released by mdadm [459]
> [ 90.183499] md_open(): md125 opened by mdadm [459]
> [ 90.183505] md_release(): md125 released by mdadm [459]
> [ 90.183686] md_release(): md127 released by mdadm [930]
So what were pids 930 and 459?
One was presumably the "mdadm -Ss" - probably 930.
Is 459 the "mdadm --monitor" ?? That might be useful hint.
>
>
> > Probably there is a 'change' event happening just before the 'remove' event,
> > and udev runs "mdadm" on the 'change' event, and that ends up happening after
> > the device has been removed.
> >
> > Is this really a problem? Can't you just ignore it and pretend it isn't
> > there?
>
> Well, if you list the block devices that the kernel detected in order to
> operate on them, it could. I don't know exactly what would be the result
> to use it but it could confuse some tools.
>
> Is there a way to check that the 'ghost' device has been removed by
> poking sysfs ?
If you look at /sys/block/md*/md/array_state, those that contain 'inactive'
or 'clear' might be 'ghosts', or might be in the process of being assembled.
If you write 'clear' to the same file they should disappear.... unless udev
does something to re-create them.
NeilBrown
[-- Attachment #2: OpenPGP digital signature --]
[-- Type: application/pgp-signature, Size: 828 bytes --]
^ permalink raw reply
* Re: Raid5 hang in 3.14.19
From: BillStuff @ 2014-09-29 4:28 UTC (permalink / raw)
To: NeilBrown; +Cc: linux-raid
In-Reply-To: <20140929140818.1086972e@notabene.brown>
On 09/28/2014 11:08 PM, NeilBrown wrote:
> On Sun, 28 Sep 2014 22:56:19 -0500 BillStuff <billstuff2001@sbcglobal.net>
> wrote:
>
>> On 09/28/2014 09:25 PM, NeilBrown wrote:
>>> On Fri, 26 Sep 2014 17:33:58 -0500 BillStuff <billstuff2001@sbcglobal.net>
>>> wrote:
>>>
>>>> Hi Neil,
>>>>
>>>> I found something that looks similar to the problem described in
>>>> "Re: seems like a deadlock in workqueue when md do a flush" from Sept 14th.
>>>>
>>>> It's on 3.14.19 with 7 recent patches for fixing raid1 recovery hangs.
>>>>
>>>> on this array:
>>>> md3 : active raid5 sdf1[5] sde1[4] sdd1[3] sdc1[2] sdb1[1] sda1[0]
>>>> 104171200 blocks level 5, 64k chunk, algorithm 2 [6/6] [UUUUUU]
>>>> bitmap: 1/5 pages [4KB], 2048KB chunk
>>>>
>>>> I was running a test doing parallel kernel builds, read/write loops, and
>>>> disk add / remove / check loops,
>>>> on both this array and a raid1 array.
>>>>
>>>> I was trying to stress test your recent raid1 fixes, which went well,
>>>> but then after 5 days,
>>>> the raid5 array hung up with this in dmesg:
>>> I think this is different to the workqueue problem you mentioned, though as I
>>> don't know exactly what caused either I cannot be certain.
>>>
>>> From the data you provided it looks like everything is waiting on
>>> get_active_stripe(), or on a process that is waiting on that.
>>> That seems pretty common whenever anything goes wrong in raid5 :-(
>>>
>>> The md3_raid5 task is listed as blocked, but not stack trace is given.
>>> If the machine is still in the state, then
>>>
>>> cat /proc/1698/stack
>>>
>>> might be useful.
>>> (echo t > /proc/sysrq-trigger is always a good idea)
>> Might this help? I believe the array was doing a "check" when things
>> hung up.
> It looks like it was trying to start doing a 'check'.
> The 'resync' thread hadn't been started yet.
> What is 'kthreadd' doing?
> My guess is that it is in try_to_free_pages() waiting for writeout
> for some xfs file page onto the md array ... which won't progress until
> the thread gets started.
>
> That would suggest that we need an async way to start threads...
>
> Thanks,
> NeilBrown
>
I suspect your guess is correct:
kthreadd D c106ea4c 0 2 0 0x00000000
e9d6db58 00000046 e9d6db4c c106ea4c ce493c00 00000001 1e9bb7bd 0001721a
c17d6700 c17d6700 d3b6a880 e9d38510 f2cf4c00 00000000 f2e51c00 e9d6db60
f3cec0b6 e9d38510 f2e51d14 f2e51d00 f2e51c00 00043132 00000964 0000a4b0
Call Trace:
[<c106ea4c>] ? update_blocked_averages+0x1ec/0x700
[<f3cec0b6>] ? xlog_cil_force_lsn+0xd6/0x1c0 [xfs]
[<f3cc077b>] ? xfs_bmbt_get_all+0x2b/0x40 [xfs]
[<c153e7f3>] schedule+0x23/0x60
[<f3ceaa71>] _xfs_log_force_lsn+0x141/0x270 [xfs]
[<c1069ca0>] ? wake_up_process+0x40/0x40
[<f3ceabd8>] xfs_log_force_lsn+0x38/0x90 [xfs]
[<f3cd7ee0>] __xfs_iunpin_wait+0x80/0x100 [xfs]
[<f3cdb02d>] ? xfs_iunpin_wait+0x1d/0x30 [xfs]
[<c10799d0>] ? autoremove_wake_function+0x40/0x40
[<f3cdb02d>] xfs_iunpin_wait+0x1d/0x30 [xfs]
[<f3c99938>] xfs_reclaim_inode+0x58/0x2f0 [xfs]
[<f3c99e04>] xfs_reclaim_inodes_ag+0x234/0x330 [xfs]
[<f3c9a6a1>] ? xfs_inode_set_reclaim_tag+0x91/0x150 [xfs]
[<c115cc41>] ? fsnotify_clear_marks_by_inode+0x21/0xe0
[<f3ca5ac5>] ? xfs_fs_destroy_inode+0xa5/0xd0 [xfs]
[<c113b061>] ? destroy_inode+0x31/0x50
[<c113b160>] ? evict+0xe0/0x160
[<f3c9a7ad>] xfs_reclaim_inodes_nr+0x2d/0x40 [xfs]
[<f3ca5103>] xfs_fs_free_cached_objects+0x13/0x20 [xfs]
[<c11278ce>] super_cache_scan+0x12e/0x140
[<c10f2bb5>] shrink_slab_node+0x125/0x280
[<c1101a1c>] ? compact_zone+0x2c/0x450
[<c10f3489>] shrink_slab+0xd9/0xf0
[<c10f557d>] try_to_free_pages+0x25d/0x4f0
[<c10eb96d>] __alloc_pages_nodemask+0x52d/0x820
[<c103c452>] copy_process.part.47+0xd2/0x14e0
[<c153e254>] ? __schedule+0x224/0x7a0
[<c105ad80>] ? kthread_create_on_node+0x110/0x110
[<c105ad80>] ? kthread_create_on_node+0x110/0x110
[<c103da01>] do_fork+0xc1/0x320
[<c105ad80>] ? kthread_create_on_node+0x110/0x110
[<c103dc8d>] kernel_thread+0x2d/0x40
[<c105b542>] kthreadd+0x122/0x170
[<c1541837>] ret_from_kernel_thread+0x1b/0x28
[<c105b420>] ? kthread_create_on_cpu+0x60/0x60
^ permalink raw reply
* Re: /sys/block/md126 still exists even after stopping the array
From: NeilBrown @ 2014-09-29 4:19 UTC (permalink / raw)
To: Artur Paszkiewicz; +Cc: Francis Moreau, linux-raid, sebastian.riemer
In-Reply-To: <54254CBD.5080704@intel.com>
[-- Attachment #1: Type: text/plain, Size: 9567 bytes --]
On Fri, 26 Sep 2014 13:23:41 +0200 Artur Paszkiewicz
<artur.paszkiewicz@intel.com> wrote:
> On 09/26/2014 12:44 PM, NeilBrown wrote:
> > On Fri, 26 Sep 2014 12:23:27 +0200 Francis Moreau <francis.moro@gmail.com>
> > wrote:
> >
> >> Hello Neil,
> >>
> >> On 09/26/2014 02:33 AM, NeilBrown wrote:
> >>> On Thu, 25 Sep 2014 18:12:07 +0200 Francis Moreau <francis.moro@gmail.com>
> >>> wrote:
> >> [...]
> >>>> I tried to find out what could have opened the md device by using fuser,
> >>>> but fuser reports no users.
> >>>
> >>> It is probably a transient open/close.
> >>>
> >>
> >> If it's open/close wouldn't the 'close' part make the device disapear ?
> >
> > No. It's ... complicated.
> >
> >>
> >>>>
> >>>> I took a look to the udev rules which are the one shipped by mdadm 3.3.2
> >>>> but nothing keep the device opened during the remove event.
> >>>>
> >>>> Could you give me some hints here to debug this ?
> >>>
> >>> Modify md_open in drivers/md/md.c to add
> >>> printk("Opened by %s\n", current->comm);
> >>>
> >>> and build a new kernel. That will tell you the name of the process which
> >>> opened the device.
> >>>
> >>
> >> I did that I also added a trace in md_release() but strangely no trace
> >> were outputed from there.
> >
> > Without seeing your patch I can't guess what it happening, but I am *certain*
> > that md_release() would get called providing md_open didn't return an error.
> >
> > It might be helpful to print out the pid and the md device number too
> > task_tgid_vnr(current)
> > will give you the pid.
> > mdname(mddev)
> > give the name of the device.
> >
> > Probably there is a 'change' event happening just before the 'remove' event,
> > and udev runs "mdadm" on the 'change' event, and that ends up happening after
> > the device has been removed.
> >
> > Is this really a problem? Can't you just ignore it and pretend it isn't
> > there?
> >
> > NeilBrown
> >
> >>
> >> Here's the details of what I did:
> >>
> >> --- %< ---
> >> [root@localhost ~]# cat /proc/mdstat
> >> Personalities : [raid1]
> >> md125 : active raid1 vdc1[1] vdb1[0]
> >> 65472 blocks super 1.0 [2/2] [UU]
> >>
> >> md126 : active raid1 vdc2[1] vdb2[0]
> >> 209536 blocks super 1.2 [2/2] [UU]
> >>
> >> md127 : active raid1 vdb3[0] vdc3[1]
> >> 1819584 blocks super 1.2 [2/2] [UU]
> >>
> >> unused devices: <none>
> >>
> >> [root@localhost ~]# mdadm --stop --scan
> >>
> >> [root@localhost ~]# dmesg | grep md_
> >> [ 1.474207] md_open(): opened by mdadm
> >> [ 1.475316] md_open(): opened by mdadm
> >> [ 1.492880] md_open(): opened by mdadm
> >> [ 1.493201] md_open(): opened by mdadm
> >> [ 1.494690] md_open(): opened by mdadm
> >> [ 1.499369] md_open(): opened by mdadm
> >> [ 1.533566] md_open(): opened by mdadm
> >> [ 1.533697] md_open(): opened by mdadm
> >> [ 1.554419] md_open(): opened by mdadm
> >> [ 1.574451] md_open(): opened by mdadm
> >> [ 1.574666] md_open(): opened by mdadm
> >> [ 1.574877] md_open(): opened by mdadm
> >> [ 1.576822] md_open(): opened by systemd-udevd
> >> [ 1.576895] md_open(): opened by systemd-udevd
> >> [ 1.577029] md_open(): opened by systemd-udevd
> >> [ 1.581850] md_open(): opened by mdadm
> >> [ 1.584054] md_open(): opened by systemd-udevd
> >> [ 1.584770] md_open(): opened by mdadm
> >> [ 1.585175] md_open(): opened by mdadm
> >> [ 1.586328] md_open(): opened by systemd-udevd
> >> [ 1.586933] md_open(): opened by systemd-udevd
> >> [ 1.651265] md_open(): opened by mdadm
> >> [ 1.651320] md_open(): opened by mdadm
> >> [ 1.651364] md_open(): opened by mdadm
> >> [ 1.651437] md_open(): opened by mdadm
> >> [ 1.652376] md_open(): opened by mdadm
> >> [ 1.652452] md_open(): opened by mdadm
> >> [ 33.486704] md_open(): opened by mdadm
> >> [ 33.489259] md_open(): opened by mdadm
> >> [ 33.491000] md_open(): opened by mdadm
> >> [ 33.491767] md_open(): opened by systemd-udevd
> >> [ 33.692255] md_open(): opened by mdadm
> >> [ 33.692288] md_open(): opened by mdadm
> >> [ 33.692606] md_open(): opened by mdadm
> >> [ 33.692858] md_open(): opened by mdadm
> >> [ 33.692942] md_open(): opened by mdadm
> >> [ 33.693237] md_open(): opened by mdadm
> >> [ 33.694254] md_open(): opened by mdadm
> >> [ 33.694275] md_open(): opened by mdadm
> >> [ 33.694373] md_open(): opened by mdadm
> >> [ 33.695558] md_open(): opened by mdadm
> >> [ 33.695679] md_open(): opened by mdadm
> >> [ 33.695855] md_open(): opened by mdadm
> >> [ 33.695894] md_open(): opened by mdadm
> >>
> >> [root@localhost ~]# ls /dev/md125
> >> /dev/md125
> >>
> >> [root@localhost ~]# fuser /dev/md125
> >>
> >> [root@localhost ~]# ps aux | grep "mdadm\|systemd-udevd"
> >> root 366 0.0 0.1 38172 1696 ? Ss 06:04 0:00
> >> /usr/lib/systemd/systemd-udevd
> >> root 465 0.0 0.0 4964 924 ? Ss 06:04 0:00
> >> /sbin/mdadm --monitor --scan --daemonise --syslog
> >> --pid-file=/run/mdadm/mdadm.pid
> >>
> >> [root@localhost ~]# ls -l /proc/366/fd/
> >> total 0
> >> lrwx------ 1 root root 64 Sep 26 06:04 0 -> /dev/null
> >> lrwx------ 1 root root 64 Sep 26 06:04 1 -> /dev/null
> >> lrwx------ 1 root root 64 Sep 26 06:04 10 -> socket:[8665]
> >> lr-x------ 1 root root 64 Sep 26 06:04 11 -> /etc/udev/hwdb.bin
> >> lrwx------ 1 root root 64 Sep 26 06:04 12 -> anon_inode:[eventpoll]
> >> lrwx------ 1 root root 64 Sep 26 06:04 2 -> /dev/null
> >> lrwx------ 1 root root 64 Sep 26 06:04 3 -> socket:[8144]
> >> lrwx------ 1 root root 64 Sep 26 06:04 4 -> socket:[8103]
> >> lrwx------ 1 root root 64 Sep 26 06:04 5 -> socket:[8660]
> >> lrwx------ 1 root root 64 Sep 26 06:04 6 -> /run/udev/queue.bin
> >> lr-x------ 1 root root 64 Sep 26 06:04 7 -> anon_inode:inotify
> >> lrwx------ 1 root root 64 Sep 26 06:04 8 -> anon_inode:[signalfd]
> >> lrwx------ 1 root root 64 Sep 26 06:04 9 -> socket:[8664]
> >>
> >> [root@localhost ~]# ls -l /proc/465/fd/
> >> total 0
> >> lrwx------ 1 root root 64 Sep 26 06:04 0 -> /dev/null
> >> lrwx------ 1 root root 64 Sep 26 06:04 1 -> /dev/null
> >> lrwx------ 1 root root 64 Sep 26 06:04 2 -> /dev/null
> >> lr-x------ 1 root root 64 Sep 26 06:06 4 -> /proc/mdstat
> >> lrwx------ 1 root root 64 Sep 26 06:06 5 -> socket:[10038]
> >>
> >> [root@localhost ~]# cat /proc/mdstat
> >> Personalities : [raid1]
> >> unused devices: <none>
> >>
> >> [root@localhost ~]# ls /sys/block/md125/md/
> >> array_size array_state bitmap/ chunk_size component_size layout
> >> level max_read_errors metadata_version new_dev raid_disks
> >> reshape_direction reshape_position resync_start safe_mode_delay
> >>
> >> --- >% ---
> >>
> >> So in my understanding, only mdadm and udevd are opening the MD devices
> >> and mdamd was the last to open the device. For some unknown reasons,
> >> md_release() is never called.
> >>
> >> This happens with:
> >>
> >> - kernel 3.14.19
> >> - mdadm 3.3.2
> >> - systemd 208
> >>
> >> Can you see something wrong here ?
> >>
> >> Thanks.
> >> --
>
> Hi,
>
> I have also been debugging this issue and I came up with this
> fix/workaround. It works for me. Can you take a look a this?
>
> Thanks,
> Artur
>
> >From c547e39789cde93d4a7ea1d3f845d61b82e4f0ed Mon Sep 17 00:00:00 2001
> From: Artur Paszkiewicz <artur.paszkiewicz@intel.com>
> Date: Fri, 26 Sep 2014 12:20:46 +0200
> Subject: [PATCH] md: avoid creating new devices for stopped arrays in
> md_open()
>
> When an array is about to be destroyed, set mddev->gendisk->private_data
> to NULL as it is no longer needed and check it in md_open(). If
> bdev->bd_disk->private_data is NULL, then this indicates that the array
> is stopped and return -ENODEV.
>
> Signed-off-by: Artur Paszkiewicz <artur.paszkiewicz@intel.com>
> ---
> drivers/md/md.c | 8 +++++++-
> 1 file changed, 7 insertions(+), 1 deletion(-)
>
> diff --git a/drivers/md/md.c b/drivers/md/md.c
> index 1294238..7109d48 100644
> --- a/drivers/md/md.c
> +++ b/drivers/md/md.c
> @@ -449,6 +449,7 @@ static void mddev_put(struct mddev *mddev)
> bs = mddev->bio_set;
> mddev->bio_set = NULL;
> if (mddev->gendisk) {
> + mddev->gendisk->private_data = NULL;
> /* We did a probe so need to clean up. Call
> * queue_work inside the spinlock so that
> * flush_workqueue() after mddev_find will
> @@ -6693,9 +6694,14 @@ static int md_open(struct block_device *bdev, fmode_t mode)
> * Succeed if we can lock the mddev, which confirms that
> * it isn't being stopped right now.
> */
> - struct mddev *mddev = mddev_find(bdev->bd_dev);
> + struct mddev *mddev;
> int err;
>
> + if (!bdev->bd_disk->private_data)
> + return -ENODEV;
> +
> + mddev = mddev_find(bdev->bd_dev);
> +
> if (!mddev)
> return -ENODEV;
>
Thanks, but I don't think this is a complete fix.
It creates a small window after an array is stopped during which an attempt
to open the device will fail. Once mddev_delayed_delete() completes, the
device can be opened again.
So it might occasionally fix the symptom, but it is very dependant on timing
and won't always work.
NeilBrown
[-- Attachment #2: OpenPGP digital signature --]
[-- Type: application/pgp-signature, Size: 828 bytes --]
^ permalink raw reply
* Re: Raid5 hang in 3.14.19
From: NeilBrown @ 2014-09-29 4:08 UTC (permalink / raw)
To: BillStuff; +Cc: linux-raid
In-Reply-To: <5428D863.7090409@sbcglobal.net>
[-- Attachment #1: Type: text/plain, Size: 2132 bytes --]
On Sun, 28 Sep 2014 22:56:19 -0500 BillStuff <billstuff2001@sbcglobal.net>
wrote:
> On 09/28/2014 09:25 PM, NeilBrown wrote:
> > On Fri, 26 Sep 2014 17:33:58 -0500 BillStuff <billstuff2001@sbcglobal.net>
> > wrote:
> >
> >> Hi Neil,
> >>
> >> I found something that looks similar to the problem described in
> >> "Re: seems like a deadlock in workqueue when md do a flush" from Sept 14th.
> >>
> >> It's on 3.14.19 with 7 recent patches for fixing raid1 recovery hangs.
> >>
> >> on this array:
> >> md3 : active raid5 sdf1[5] sde1[4] sdd1[3] sdc1[2] sdb1[1] sda1[0]
> >> 104171200 blocks level 5, 64k chunk, algorithm 2 [6/6] [UUUUUU]
> >> bitmap: 1/5 pages [4KB], 2048KB chunk
> >>
> >> I was running a test doing parallel kernel builds, read/write loops, and
> >> disk add / remove / check loops,
> >> on both this array and a raid1 array.
> >>
> >> I was trying to stress test your recent raid1 fixes, which went well,
> >> but then after 5 days,
> >> the raid5 array hung up with this in dmesg:
> > I think this is different to the workqueue problem you mentioned, though as I
> > don't know exactly what caused either I cannot be certain.
> >
> > From the data you provided it looks like everything is waiting on
> > get_active_stripe(), or on a process that is waiting on that.
> > That seems pretty common whenever anything goes wrong in raid5 :-(
> >
> > The md3_raid5 task is listed as blocked, but not stack trace is given.
> > If the machine is still in the state, then
> >
> > cat /proc/1698/stack
> >
> > might be useful.
> > (echo t > /proc/sysrq-trigger is always a good idea)
>
> Might this help? I believe the array was doing a "check" when things
> hung up.
It looks like it was trying to start doing a 'check'.
The 'resync' thread hadn't been started yet.
What is 'kthreadd' doing?
My guess is that it is in try_to_free_pages() waiting for writeout
for some xfs file page onto the md array ... which won't progress until
the thread gets started.
That would suggest that we need an async way to start threads...
Thanks,
NeilBrown
[-- Attachment #2: OpenPGP digital signature --]
[-- Type: application/pgp-signature, Size: 828 bytes --]
^ permalink raw reply
* Re: Raid5 hang in 3.14.19
From: BillStuff @ 2014-09-29 3:56 UTC (permalink / raw)
To: NeilBrown; +Cc: linux-raid
In-Reply-To: <20140929122533.3b91a543@notabene.brown>
On 09/28/2014 09:25 PM, NeilBrown wrote:
> On Fri, 26 Sep 2014 17:33:58 -0500 BillStuff <billstuff2001@sbcglobal.net>
> wrote:
>
>> Hi Neil,
>>
>> I found something that looks similar to the problem described in
>> "Re: seems like a deadlock in workqueue when md do a flush" from Sept 14th.
>>
>> It's on 3.14.19 with 7 recent patches for fixing raid1 recovery hangs.
>>
>> on this array:
>> md3 : active raid5 sdf1[5] sde1[4] sdd1[3] sdc1[2] sdb1[1] sda1[0]
>> 104171200 blocks level 5, 64k chunk, algorithm 2 [6/6] [UUUUUU]
>> bitmap: 1/5 pages [4KB], 2048KB chunk
>>
>> I was running a test doing parallel kernel builds, read/write loops, and
>> disk add / remove / check loops,
>> on both this array and a raid1 array.
>>
>> I was trying to stress test your recent raid1 fixes, which went well,
>> but then after 5 days,
>> the raid5 array hung up with this in dmesg:
> I think this is different to the workqueue problem you mentioned, though as I
> don't know exactly what caused either I cannot be certain.
>
> From the data you provided it looks like everything is waiting on
> get_active_stripe(), or on a process that is waiting on that.
> That seems pretty common whenever anything goes wrong in raid5 :-(
>
> The md3_raid5 task is listed as blocked, but not stack trace is given.
> If the machine is still in the state, then
>
> cat /proc/1698/stack
>
> might be useful.
> (echo t > /proc/sysrq-trigger is always a good idea)
Might this help? I believe the array was doing a "check" when things
hung up.
md3_raid5 D ea49d770 0 1698 2 0x00000000
e833dda8 00000046 c106d92d ea49d770 e9d38554 1cc20b58 1e79a404 0001721a
c17d6700 c17d6700 e956d610 c2217470 c13af054 e9e8f000 00000000 00000000
e833dd78 00000000 00000000 00000271 00000000 00000005 00000000 0000a193
Call Trace:
[<c106d92d>] ? __enqueue_entity+0x6d/0x80
[<c13af054>] ? scsi_init_io+0x24/0xb0
[<c1072683>] ? enqueue_task_fair+0x2d3/0x660
[<c153e7f3>] schedule+0x23/0x60
[<c153db85>] schedule_timeout+0x145/0x1c0
[<c1065698>] ? update_rq_clock.part.92+0x18/0x50
[<c1067a65>] ? check_preempt_curr+0x65/0x90
[<c1067aa8>] ? ttwu_do_wakeup+0x18/0x120
[<c153ef5b>] wait_for_common+0x9b/0x110
[<c1069ca0>] ? wake_up_process+0x40/0x40
[<c153f077>] wait_for_completion_killable+0x17/0x30
[<c105ad0a>] kthread_create_on_node+0x9a/0x110
[<c1453ecc>] md_register_thread+0x8c/0xc0
[<c1453f00>] ? md_register_thread+0xc0/0xc0
[<c145ad14>] md_check_recovery+0x304/0x490
[<c12b1192>] ? blk_finish_plug+0x12/0x40
[<f3dc3a10>] raid5d+0x20/0x4c0 [raid456]
[<c104a022>] ? try_to_del_timer_sync+0x42/0x60
[<c153db3d>] ? schedule_timeout+0xfd/0x1c0
[<c1453fe8>] md_thread+0xe8/0x100
[<c1079990>] ? __wake_up_sync+0x20/0x20
[<c1453f00>] ? md_register_thread+0xc0/0xc0
[<c105ae21>] kthread+0xa1/0xc0
[<c1541837>] ret_from_kernel_thread+0x1b/0x28
[<c105ad80>] ? kthread_create_on_node+0x110/0x110
I've already rebooted the system, but I did get a snapshot of all the
blocked processes.
It's kind of long but I can post it if it's useful.
Thanks,
Bill
^ permalink raw reply
* Re: Raid5 hang in 3.14.19
From: NeilBrown @ 2014-09-29 2:25 UTC (permalink / raw)
To: BillStuff; +Cc: linux-raid
In-Reply-To: <5425E9D6.1050102@sbcglobal.net>
[-- Attachment #1: Type: text/plain, Size: 10758 bytes --]
On Fri, 26 Sep 2014 17:33:58 -0500 BillStuff <billstuff2001@sbcglobal.net>
wrote:
> Hi Neil,
>
> I found something that looks similar to the problem described in
> "Re: seems like a deadlock in workqueue when md do a flush" from Sept 14th.
>
> It's on 3.14.19 with 7 recent patches for fixing raid1 recovery hangs.
>
> on this array:
> md3 : active raid5 sdf1[5] sde1[4] sdd1[3] sdc1[2] sdb1[1] sda1[0]
> 104171200 blocks level 5, 64k chunk, algorithm 2 [6/6] [UUUUUU]
> bitmap: 1/5 pages [4KB], 2048KB chunk
>
> I was running a test doing parallel kernel builds, read/write loops, and
> disk add / remove / check loops,
> on both this array and a raid1 array.
>
> I was trying to stress test your recent raid1 fixes, which went well,
> but then after 5 days,
> the raid5 array hung up with this in dmesg:
I think this is different to the workqueue problem you mentioned, though as I
don't know exactly what caused either I cannot be certain.
From the data you provided it looks like everything is waiting on
get_active_stripe(), or on a process that is waiting on that.
That seems pretty common whenever anything goes wrong in raid5 :-(
The md3_raid5 task is listed as blocked, but not stack trace is given.
If the machine is still in the state, then
cat /proc/1698/stack
might be useful.
(echo t > /proc/sysrq-trigger is always a good idea)
NeilBrown
>
> INFO: task kworker/7:2:15726 blocked for more than 120 seconds.
> Tainted: P W O 3.14.19fe-dirty #2
> "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> kworker/7:2 D 00000001 0 15726 2 0x00000000
> Workqueue: xfs-log/md3 xfs_log_worker [xfs]
> d1809b1c 00000046 e95e0a80 00000001 c15b56a0 00000008 cf92b77a 0001721a
> c17d6700 c17d6700 d198bcc0 d3b6a880 c236dc00 c8290fb0 c2328468 00000352
> 000000e2 c209c000 00000001 e9606000 c209c000 d1809b1c c14b05f4 c12d0c4a
> Call Trace:
> [<c14b05f4>] ? sch_direct_xmit+0x54/0x180
> [<c12d0c4a>] ? radix_tree_lookup+0xa/0x10
> [<c10798bb>] ? prepare_to_wait_event+0x6b/0xd0
> [<c153e7f3>] schedule+0x23/0x60
> [<c144fdf1>] md_flush_request+0x51/0xd0
> [<c1079990>] ? __wake_up_sync+0x20/0x20
> [<f3dc0095>] make_request+0xb55/0xc30 [raid456]
> [<c14be153>] ? ip_finish_output+0x1e3/0x440
> [<c14bf5e7>] ? ip_output+0x77/0x80
> [<c14beeb0>] ? ip_local_out+0x20/0x30
> [<c12ae873>] ? generic_make_request_checks+0x343/0x400
> [<c1049903>] ? internal_add_timer+0x13/0x40
> [<c14501d1>] md_make_request+0xb1/0x1d0
> [<c10e6ee3>] ? mempool_alloc_slab+0x13/0x20
> [<c12af629>] generic_make_request+0x89/0xc0
> [<c12af6ba>] submit_bio+0x5a/0x120
> [<c1152cb8>] ? bio_add_page+0x38/0x40
> [<f3c919c0>] _xfs_buf_ioapply+0x250/0x300 [xfs]
> [<f3c91bb4>] xfs_buf_iorequest+0x44/0x80 [xfs]
> [<f3ce7dbe>] ? xlog_bdstrat+0x1e/0x50 [xfs]
> [<f3ce7dbe>] xlog_bdstrat+0x1e/0x50 [xfs]
> [<f3ce9900>] xlog_sync+0x2a0/0x460 [xfs]
> [<f3ce9b34>] xlog_state_release_iclog+0x74/0xa0 [xfs]
> [<f3cea3ef>] xlog_write+0x4af/0x630 [xfs]
> [<f3caa306>] ? kmem_zone_alloc+0x66/0xe0 [xfs]
> [<f3ceb897>] xlog_cil_push+0x1e7/0x3c0 [xfs]
> [<c1054c56>] ? flush_work+0x16/0x100
> [<f3cec059>] xlog_cil_force_lsn+0x79/0x1c0 [xfs]
> [<c106c864>] ? sched_clock_cpu+0x104/0x110
> [<c106d8bc>] ? __dequeue_entity+0x3c/0x40
> [<f3cea670>] _xfs_log_force+0x50/0x230 [xfs]
> [<c153e254>] ? __schedule+0x224/0x7a0
> [<f3cea876>] xfs_log_force+0x26/0x90 [xfs]
> [<f3cebb87>] ? xlog_cil_empty+0x17/0x30 [xfs]
> [<f3cea900>] xfs_log_worker+0x20/0x50 [xfs]
> [<c105521c>] process_one_work+0x10c/0x340
> [<c1055d31>] worker_thread+0x101/0x330
> [<c1055c30>] ? manage_workers.isra.27+0x250/0x250
> [<c105ae21>] kthread+0xa1/0xc0
> [<c1541837>] ret_from_kernel_thread+0x1b/0x28
> [<c105ad80>] ? kthread_create_on_node+0x110/0x110
> INFO: task kworker/u16:2:24280 blocked for more than 120 seconds.
> Tainted: P W O 3.14.19fe-dirty #2
> "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> kworker/u16:2 D d56879e0 0 24280 2 0x00000000
> Workqueue: writeback bdi_writeback_workfn (flush-9:3)
> d5687a3c 00000046 00000000 d56879e0 f2fbd600 f3dbc81b 2e86d607 0001721c
> c17d6700 c17d6700 c49cbcc0 e601c6e0 f3dbc81b 00000002 00000001 e9e0fc00
> c2328468 0000003b d5687a28 d5687d74 00000001 d5687a3c c12b0db6 f3dba382
> Call Trace:
> [<f3dbc81b>] ? raid5_unplug+0xbb/0x120 [raid456]
> [<f3dbc81b>] ? raid5_unplug+0xbb/0x120 [raid456]
> [<c12b0db6>] ? blk_flush_plug_list+0x86/0x1b0
> [<f3dba382>] ? stripe_set_idx+0xa2/0xc0 [raid456]
> [<c10798bb>] ? prepare_to_wait_event+0x6b/0xd0
> [<c153e7f3>] schedule+0x23/0x60
> [<f3dbe38b>] get_active_stripe+0x19b/0x5a0 [raid456]
> [<c145f80b>] ? bitmap_startwrite+0x5b/0x170
> [<c1079990>] ? __wake_up_sync+0x20/0x20
> [<f3dbf6b0>] make_request+0x170/0xc30 [raid456]
> [<c10b7193>] ? delayacct_end+0x93/0xa0
> [<c1079990>] ? __wake_up_sync+0x20/0x20
> [<c14501d1>] md_make_request+0xb1/0x1d0
> [<c10e6ee3>] ? mempool_alloc_slab+0x13/0x20
> [<c12af629>] generic_make_request+0x89/0xc0
> [<c12af6ba>] submit_bio+0x5a/0x120
> [<c1152b09>] ? __bio_add_page+0xd9/0x220
> [<c1153248>] ? bvec_alloc+0x78/0xe0
> [<f3c8b612>] xfs_submit_ioend_bio.isra.9+0x32/0x40 [xfs]
> [<f3c8b70c>] xfs_submit_ioend+0xec/0x120 [xfs]
> [<f3c8b981>] xfs_vm_writepage+0x241/0x580 [xfs]
> [<c10ec730>] __writepage+0x10/0x40
> [<c10ec720>] ? mapping_tagged+0x20/0x20
> [<c10ecc30>] write_cache_pages+0x170/0x3d0
> [<f3dbc81b>] ? raid5_unplug+0xbb/0x120 [raid456]
> [<c10ec720>] ? mapping_tagged+0x20/0x20
> [<c10ecec3>] generic_writepages+0x33/0x60
> [<f3c8aa43>] xfs_vm_writepages+0x33/0x40 [xfs]
> [<c10ee38a>] do_writepages+0x1a/0x40
> [<c11486b2>] __writeback_single_inode+0x42/0x1f0
> [<c107965c>] ? wake_up_bit+0x1c/0x20
> [<c1149423>] writeback_sb_inodes+0x193/0x2e0
> [<c11495ec>] __writeback_inodes_wb+0x7c/0xb0
> [<c11497f2>] wb_writeback+0x1d2/0x270
> [<c1149c11>] bdi_writeback_workfn+0x151/0x380
> [<c153e254>] ? __schedule+0x224/0x7a0
> [<c105521c>] process_one_work+0x10c/0x340
> [<c1069cb0>] ? default_wake_function+0x10/0x20
> [<c1055d31>] worker_thread+0x101/0x330
> [<c1055c30>] ? manage_workers.isra.27+0x250/0x250
> [<c105ae21>] kthread+0xa1/0xc0
> [<c1541837>] ret_from_kernel_thread+0x1b/0x28
> [<c105ad80>] ? kthread_create_on_node+0x110/0x110
> INFO: task kworker/3:3:26958 blocked for more than 120 seconds.
> Tainted: P W O 3.14.19fe-dirty #2
> "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> kworker/3:3 D 00000000 0 26958 2 0x00000000
> Workqueue: md md_submit_flush_data
> c6d41dd8 00000046 d128391d 00000000 00000000 00000000 2d875421 0001721c
> c17d6700 c17d6700 e9d3bcc0 d4bf5610 00000000 00000000 00000000 ea469748
> df1132aa 0000c335 d4bf5654 d4bf5654 de5a17aa c6d41dec c106fe31 57d98c16
> Call Trace:
> [<c106fe31>] ? update_curr+0xf1/0x1a0
> [<c10798bb>] ? prepare_to_wait_event+0x6b/0xd0
> [<c153e7f3>] schedule+0x23/0x60
> [<f3dbe38b>] get_active_stripe+0x19b/0x5a0 [raid456]
> [<c107030f>] ? dequeue_entity+0x11f/0x510
> [<c1079990>] ? __wake_up_sync+0x20/0x20
> [<f3dbf6b0>] make_request+0x170/0xc30 [raid456]
> [<c153e254>] ? __schedule+0x224/0x7a0
> [<c111bf45>] ? kmem_cache_free+0xe5/0x110
> [<c1079990>] ? __wake_up_sync+0x20/0x20
> [<c144fd60>] md_submit_flush_data+0x30/0x70
> [<c105521c>] process_one_work+0x10c/0x340
> [<c104a30f>] ? mod_timer+0xef/0x1d0
> [<c1055d31>] worker_thread+0x101/0x330
> [<c1055c30>] ? manage_workers.isra.27+0x250/0x250
> [<c105ae21>] kthread+0xa1/0xc0
> [<c1541837>] ret_from_kernel_thread+0x1b/0x28
> [<c105ad80>] ? kthread_create_on_node+0x110/0x110
>
> There's more, mostly xfs threads complaining about being blocked and
> some user processes.
> Thinking it was an xfs problem, I did "echo w > /proc/sysrq-trigger" and
> got this in syslog:
>
> Sep 26 12:33:06 xplane kernel: SysRq : Show Blocked State
> Sep 26 12:33:06 xplane kernel: task PC stack pid father
> Sep 26 12:33:06 xplane kernel: kthreadd D c106ea4c 0 2 0
> 0x00000000
> Sep 26 12:33:06 xplane kernel: kswapd0 D 00017219 0 711
> 2 0x00000000
> Sep 26 12:33:06 xplane kernel: md3_raid5 D ea49d770 0
> 1698 2 0x00000000
> Sep 26 12:33:06 xplane kernel: xfsaild/md3 D e7d72700 0
> 2234 2 0x00000000
> Sep 26 12:33:06 xplane kernel: kworker/7:2 D 00000001 0
> 15726 2 0x00000000
> Sep 26 12:33:06 xplane kernel: Workqueue: xfs-log/md3 xfs_log_worker [xfs]
> Sep 26 12:33:06 xplane kernel: kworker/u16:2 D d56879e0 0
> 24280 2 0x00000000
> Sep 26 12:33:06 xplane kernel: Workqueue: writeback bdi_writeback_workfn
> (flush-9:3)
> Sep 26 12:33:06 xplane kernel: kworker/3:3 D 00000000 0
> 26958 2 0x00000000
> Sep 26 12:33:06 xplane kernel: Workqueue: md md_submit_flush_data
> Sep 26 12:33:06 xplane kernel: cat D 00000000 0 11412
> 11410 0x00000000
> Sep 26 12:33:06 xplane kernel: cc1 D d00c3bac 0 12102
> 12101 0x00000000
> Sep 26 12:33:06 xplane kernel: ld D c16ef900 0 12132
> 12130 0x00000000
> Sep 26 12:33:06 xplane kernel: make D 00000000 0 12147
> 12047 0x00000000
> Sep 26 12:33:06 xplane kernel: make D d896ea80 0 12374
> 11263 0x00000000
> Sep 26 12:33:06 xplane kernel: cat D f2e51d0c 0 23219
> 23217 0x00000000
> Sep 26 12:33:06 xplane kernel: gcc D f2e51d0c 0 23564
> 23563 0x00000000
> Sep 26 12:33:06 xplane kernel: sh D f2e51d0c 0 25753
> 23615 0x00000000
>
> which looks similar to the problem from the above mentioned list-post.
>
> I did a few test writes to the filesystem, and it looked like xfs
> created the files, and could read them
> and delete them, but there was never any disk activity and access to
> /sys/block/md3/md/{anything} was hung up
>
> "top" showed consistent I/O wait time, first 25%, then 50%, with no disc
> activity
>
> In the end I had to reboot, and I'm running the test again.
>
> Any thoughts on what's happening here or ideas to help debug it?
>
> Thanks,
> Bill
>
> --
> To unsubscribe from this list: send the line "unsubscribe linux-raid" in
> the body of a message to majordomo@vger.kernel.org
> More majordomo info at http://vger.kernel.org/majordomo-info.html
[-- Attachment #2: OpenPGP digital signature --]
[-- Type: application/pgp-signature, Size: 828 bytes --]
^ permalink raw reply
* BOUNTY REQUEST: Patch to RAID1/mdadm to DISABLE/ENABLE ALL SYNC ACTIONS, RECOVERY, etc
From: Errol Neal @ 2014-09-28 23:31 UTC (permalink / raw)
To: linux-raid
*** IF **** Anyone is interested, please drop me a line.
Thank you,
Errol Neal
^ permalink raw reply
* Re: [RESEND PATCH] drivers/md: Use rcu_dereference() for accessing rcu pointer
From: Paul E. McKenney @ 2014-09-28 21:43 UTC (permalink / raw)
To: Pranith Kumar
Cc: Alasdair Kergon, Mike Snitzer, maintainer:DEVICE-MAPPER (LVM),
Neil Brown, linux-raid, open list
In-Reply-To: <1411916712-17631-1-git-send-email-bobby.prani@gmail.com>
On Sun, Sep 28, 2014 at 11:05:04AM -0400, Pranith Kumar wrote:
> Got Paul's email wrong the first time.
>
> The map field in 'struct mapped_device' is an rcu pointer. Use rcu_dereference()
> while accessing it.
>
> Signed-off-by: Pranith Kumar <bobby.prani@gmail.com>
OK, I now have all three queued (including the extraneous first line of
the commit log above...), will see what 0day thinks of it.
Thanx, Paul
> ---
> drivers/md/dm.c | 8 ++++----
> 1 file changed, 4 insertions(+), 4 deletions(-)
>
> diff --git a/drivers/md/dm.c b/drivers/md/dm.c
> index 746411b..fbdf0bb 100644
> --- a/drivers/md/dm.c
> +++ b/drivers/md/dm.c
> @@ -2211,7 +2211,7 @@ static struct dm_table *__bind(struct mapped_device *md, struct dm_table *t,
>
> merge_is_optional = dm_table_merge_is_optional(t);
>
> - old_map = md->map;
> + old_map = rcu_dereference(md->map);
> rcu_assign_pointer(md->map, t);
> md->immutable_target_type = dm_table_get_immutable_target_type(t);
>
> @@ -2230,7 +2230,7 @@ static struct dm_table *__bind(struct mapped_device *md, struct dm_table *t,
> */
> static struct dm_table *__unbind(struct mapped_device *md)
> {
> - struct dm_table *map = md->map;
> + struct dm_table *map = rcu_dereference(md->map);
>
> if (!map)
> return NULL;
> @@ -2624,7 +2624,7 @@ int dm_suspend(struct mapped_device *md, unsigned suspend_flags)
> goto out_unlock;
> }
>
> - map = md->map;
> + map = rcu_dereference(md->map);
>
> /*
> * DMF_NOFLUSH_SUSPENDING must be set before presuspend.
> @@ -2718,7 +2718,7 @@ int dm_resume(struct mapped_device *md)
> if (!dm_suspended_md(md))
> goto out;
>
> - map = md->map;
> + map = rcu_dereference(md->map);
> if (!map || !dm_table_get_size(map))
> goto out;
>
> --
> 1.9.1
>
^ permalink raw reply
* [RESEND PATCH] drivers/md: Use rcu_dereference() for accessing rcu pointer
From: Pranith Kumar @ 2014-09-28 15:05 UTC (permalink / raw)
To: Alasdair Kergon, Mike Snitzer, maintainer:DEVICE-MAPPER LVM,
Neil Brown, linux-raid, open list
Cc: paulmck
Got Paul's email wrong the first time.
The map field in 'struct mapped_device' is an rcu pointer. Use rcu_dereference()
while accessing it.
Signed-off-by: Pranith Kumar <bobby.prani@gmail.com>
---
drivers/md/dm.c | 8 ++++----
1 file changed, 4 insertions(+), 4 deletions(-)
diff --git a/drivers/md/dm.c b/drivers/md/dm.c
index 746411b..fbdf0bb 100644
--- a/drivers/md/dm.c
+++ b/drivers/md/dm.c
@@ -2211,7 +2211,7 @@ static struct dm_table *__bind(struct mapped_device *md, struct dm_table *t,
merge_is_optional = dm_table_merge_is_optional(t);
- old_map = md->map;
+ old_map = rcu_dereference(md->map);
rcu_assign_pointer(md->map, t);
md->immutable_target_type = dm_table_get_immutable_target_type(t);
@@ -2230,7 +2230,7 @@ static struct dm_table *__bind(struct mapped_device *md, struct dm_table *t,
*/
static struct dm_table *__unbind(struct mapped_device *md)
{
- struct dm_table *map = md->map;
+ struct dm_table *map = rcu_dereference(md->map);
if (!map)
return NULL;
@@ -2624,7 +2624,7 @@ int dm_suspend(struct mapped_device *md, unsigned suspend_flags)
goto out_unlock;
}
- map = md->map;
+ map = rcu_dereference(md->map);
/*
* DMF_NOFLUSH_SUSPENDING must be set before presuspend.
@@ -2718,7 +2718,7 @@ int dm_resume(struct mapped_device *md)
if (!dm_suspended_md(md))
goto out;
- map = md->map;
+ map = rcu_dereference(md->map);
if (!map || !dm_table_get_size(map))
goto out;
--
1.9.1
^ permalink raw reply related
* [PATCH] drivers/md: Use rcu_dereference() for accessing rcu pointer
From: Pranith Kumar @ 2014-09-28 15:01 UTC (permalink / raw)
To: Alasdair Kergon, Mike Snitzer, maintainer:DEVICE-MAPPER LVM,
Neil Brown, linux-raid, open list
Cc: paulmck
The map field in 'struct mapped_device' is an rcu pointer. Use rcu_dereference()
while accessing it.
Signed-off-by: Pranith Kumar <bobby.prani@gmail.com>
---
drivers/md/dm.c | 8 ++++----
1 file changed, 4 insertions(+), 4 deletions(-)
diff --git a/drivers/md/dm.c b/drivers/md/dm.c
index 746411b..fbdf0bb 100644
--- a/drivers/md/dm.c
+++ b/drivers/md/dm.c
@@ -2211,7 +2211,7 @@ static struct dm_table *__bind(struct mapped_device *md, struct dm_table *t,
merge_is_optional = dm_table_merge_is_optional(t);
- old_map = md->map;
+ old_map = rcu_dereference(md->map);
rcu_assign_pointer(md->map, t);
md->immutable_target_type = dm_table_get_immutable_target_type(t);
@@ -2230,7 +2230,7 @@ static struct dm_table *__bind(struct mapped_device *md, struct dm_table *t,
*/
static struct dm_table *__unbind(struct mapped_device *md)
{
- struct dm_table *map = md->map;
+ struct dm_table *map = rcu_dereference(md->map);
if (!map)
return NULL;
@@ -2624,7 +2624,7 @@ int dm_suspend(struct mapped_device *md, unsigned suspend_flags)
goto out_unlock;
}
- map = md->map;
+ map = rcu_dereference(md->map);
/*
* DMF_NOFLUSH_SUSPENDING must be set before presuspend.
@@ -2718,7 +2718,7 @@ int dm_resume(struct mapped_device *md)
if (!dm_suspended_md(md))
goto out;
- map = md->map;
+ map = rcu_dereference(md->map);
if (!map || !dm_table_get_size(map))
goto out;
--
1.9.1
^ permalink raw reply related
* Re: [PATCH] dm: sparse: Annotate field with __rcu for checking
From: Paul E. McKenney @ 2014-09-28 7:34 UTC (permalink / raw)
To: Pranith Kumar
Cc: Alasdair Kergon, Mike Snitzer, maintainer:DEVICE-MAPPER (LVM),
Neil Brown, linux-raid, open list, josh
In-Reply-To: <1411671049-20441-1-git-send-email-bobby.prani@gmail.com>
On Thu, Sep 25, 2014 at 02:50:43PM -0400, Pranith Kumar wrote:
> Annotate the map field with __rcu since this is a rcu pointer which is checked
> by sparse.
>
> Signed-off-by: Pranith Kumar <bobby.prani@gmail.com>
Queued them both, thank you!
Josh, given this change, are you OK with my applying your Reviewed-by
to the RCU_INIT_POINTER() patch?
Thanx, Paul
> ---
> drivers/md/dm.c | 2 +-
> 1 file changed, 1 insertion(+), 1 deletion(-)
>
> diff --git a/drivers/md/dm.c b/drivers/md/dm.c
> index 32b958d..746411b 100644
> --- a/drivers/md/dm.c
> +++ b/drivers/md/dm.c
> @@ -140,7 +140,7 @@ struct mapped_device {
> * Use dm_get_live_table{_fast} or take suspend_lock for
> * dereference.
> */
> - struct dm_table *map;
> + struct dm_table __rcu *map;
>
> unsigned long flags;
>
> --
> 2.1.0
>
^ permalink raw reply
* [PATCH] md, sysfs, LLVMLinux: Remove nested function from bcache sysfs
From: Behan Webster @ 2014-09-27 1:09 UTC (permalink / raw)
To: kmo; +Cc: behanw, linux-bcache, linux-kernel, linux-raid, neilb,
Arnd Bergmann
Replace the use of nested functions where a normal function will suffice.
Nested functions are not liked by upstream kernel developers in general. Their
use breaks the use of clang as a compiler, and doesn't make the code any
better.
This code now works for both gcc and clang.
Signed-off-by: Behan Webster <behanw@converseincode.com>
Suggested-by: Arnd Bergmann <arnd@arndb.de>
Cc: Arnd Bergmann <arnd@arndb.de>
---
drivers/md/bcache/sysfs.c | 10 ++++++----
1 file changed, 6 insertions(+), 4 deletions(-)
diff --git a/drivers/md/bcache/sysfs.c b/drivers/md/bcache/sysfs.c
index b3ff57d..53d8baa 100644
--- a/drivers/md/bcache/sysfs.c
+++ b/drivers/md/bcache/sysfs.c
@@ -731,6 +731,11 @@ static struct attribute *bch_cache_set_internal_files[] = {
};
KTYPE(bch_cache_set_internal);
+static int __bch_cache_cmp(const void *l, const void *r)
+{
+ return *((uint16_t *) r) - *((uint16_t *) l);
+}
+
SHOW(__bch_cache)
{
struct cache *ca = container_of(kobj, struct cache, kobj);
@@ -755,9 +760,6 @@ SHOW(__bch_cache)
CACHE_REPLACEMENT(&ca->sb));
if (attr == &sysfs_priority_stats) {
- int cmp(const void *l, const void *r)
- { return *((uint16_t *) r) - *((uint16_t *) l); }
-
struct bucket *b;
size_t n = ca->sb.nbuckets, i;
size_t unused = 0, available = 0, dirty = 0, meta = 0;
@@ -786,7 +788,7 @@ SHOW(__bch_cache)
p[i] = ca->buckets[i].prio;
mutex_unlock(&ca->set->bucket_lock);
- sort(p, n, sizeof(uint16_t), cmp, NULL);
+ sort(p, n, sizeof(uint16_t), __bch_cache_cmp, NULL);
while (n &&
!cached[n - 1])
--
1.9.1
^ permalink raw reply related
* Re: [GIT PULL REQUEST] late md/raid1 bug fixes for 3.17
From: NeilBrown @ 2014-09-27 0:09 UTC (permalink / raw)
To: BillStuff; +Cc: linux RAID
In-Reply-To: <5425B998.7080304@sbcglobal.net>
[-- Attachment #1: Type: text/plain, Size: 1186 bytes --]
On Fri, 26 Sep 2014 14:08:08 -0500 BillStuff <billstuff2001@sbcglobal.net>
wrote:
> On 09/23/2014 09:18 PM, NeilBrown wrote:
> [snip]
> > md/raid1: intialise start_next_window for READ case to avoid hang
> >
>
> Neil, I've been testing these patches for the past week or two to see if
> they help a raid1 "check" hang I had.
>
> They seem to help, but I noticed the above patch is different from what
> you originally sent on the list.
>
> The original patch has an extra chunk:
>
> @@ -1444,6 +1445,7 @@ read_again:
> r1_bio->state = 0;
> r1_bio->mddev = mddev;
> r1_bio->sector = bio->bi_iter.bi_sector + sectors_handled;
> + start_next_window = wait_barrier(conf, bio);
> goto retry_write;
> }
>
> Is the correct patch with or without this chunk?
>
> Thanks,
> Bill
That hunk was wrong.
This new r1_bio is attached to the previous one and they all complete (and
particularly all "allow_barrier") as a unit. So only one wait_barrier is
needed.
That chunk only has any affect if you have a bad-blocks list with bad blocks
in it, and try to write a range of the device which includes the bad block.
Thanks,
NeilBrown
[-- Attachment #2: signature.asc --]
[-- Type: application/pgp-signature, Size: 828 bytes --]
^ permalink raw reply
* Raid5 hang in 3.14.19
From: BillStuff @ 2014-09-26 22:33 UTC (permalink / raw)
To: linux-raid, Neil Brown
Hi Neil,
I found something that looks similar to the problem described in
"Re: seems like a deadlock in workqueue when md do a flush" from Sept 14th.
It's on 3.14.19 with 7 recent patches for fixing raid1 recovery hangs.
on this array:
md3 : active raid5 sdf1[5] sde1[4] sdd1[3] sdc1[2] sdb1[1] sda1[0]
104171200 blocks level 5, 64k chunk, algorithm 2 [6/6] [UUUUUU]
bitmap: 1/5 pages [4KB], 2048KB chunk
I was running a test doing parallel kernel builds, read/write loops, and
disk add / remove / check loops,
on both this array and a raid1 array.
I was trying to stress test your recent raid1 fixes, which went well,
but then after 5 days,
the raid5 array hung up with this in dmesg:
INFO: task kworker/7:2:15726 blocked for more than 120 seconds.
Tainted: P W O 3.14.19fe-dirty #2
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
kworker/7:2 D 00000001 0 15726 2 0x00000000
Workqueue: xfs-log/md3 xfs_log_worker [xfs]
d1809b1c 00000046 e95e0a80 00000001 c15b56a0 00000008 cf92b77a 0001721a
c17d6700 c17d6700 d198bcc0 d3b6a880 c236dc00 c8290fb0 c2328468 00000352
000000e2 c209c000 00000001 e9606000 c209c000 d1809b1c c14b05f4 c12d0c4a
Call Trace:
[<c14b05f4>] ? sch_direct_xmit+0x54/0x180
[<c12d0c4a>] ? radix_tree_lookup+0xa/0x10
[<c10798bb>] ? prepare_to_wait_event+0x6b/0xd0
[<c153e7f3>] schedule+0x23/0x60
[<c144fdf1>] md_flush_request+0x51/0xd0
[<c1079990>] ? __wake_up_sync+0x20/0x20
[<f3dc0095>] make_request+0xb55/0xc30 [raid456]
[<c14be153>] ? ip_finish_output+0x1e3/0x440
[<c14bf5e7>] ? ip_output+0x77/0x80
[<c14beeb0>] ? ip_local_out+0x20/0x30
[<c12ae873>] ? generic_make_request_checks+0x343/0x400
[<c1049903>] ? internal_add_timer+0x13/0x40
[<c14501d1>] md_make_request+0xb1/0x1d0
[<c10e6ee3>] ? mempool_alloc_slab+0x13/0x20
[<c12af629>] generic_make_request+0x89/0xc0
[<c12af6ba>] submit_bio+0x5a/0x120
[<c1152cb8>] ? bio_add_page+0x38/0x40
[<f3c919c0>] _xfs_buf_ioapply+0x250/0x300 [xfs]
[<f3c91bb4>] xfs_buf_iorequest+0x44/0x80 [xfs]
[<f3ce7dbe>] ? xlog_bdstrat+0x1e/0x50 [xfs]
[<f3ce7dbe>] xlog_bdstrat+0x1e/0x50 [xfs]
[<f3ce9900>] xlog_sync+0x2a0/0x460 [xfs]
[<f3ce9b34>] xlog_state_release_iclog+0x74/0xa0 [xfs]
[<f3cea3ef>] xlog_write+0x4af/0x630 [xfs]
[<f3caa306>] ? kmem_zone_alloc+0x66/0xe0 [xfs]
[<f3ceb897>] xlog_cil_push+0x1e7/0x3c0 [xfs]
[<c1054c56>] ? flush_work+0x16/0x100
[<f3cec059>] xlog_cil_force_lsn+0x79/0x1c0 [xfs]
[<c106c864>] ? sched_clock_cpu+0x104/0x110
[<c106d8bc>] ? __dequeue_entity+0x3c/0x40
[<f3cea670>] _xfs_log_force+0x50/0x230 [xfs]
[<c153e254>] ? __schedule+0x224/0x7a0
[<f3cea876>] xfs_log_force+0x26/0x90 [xfs]
[<f3cebb87>] ? xlog_cil_empty+0x17/0x30 [xfs]
[<f3cea900>] xfs_log_worker+0x20/0x50 [xfs]
[<c105521c>] process_one_work+0x10c/0x340
[<c1055d31>] worker_thread+0x101/0x330
[<c1055c30>] ? manage_workers.isra.27+0x250/0x250
[<c105ae21>] kthread+0xa1/0xc0
[<c1541837>] ret_from_kernel_thread+0x1b/0x28
[<c105ad80>] ? kthread_create_on_node+0x110/0x110
INFO: task kworker/u16:2:24280 blocked for more than 120 seconds.
Tainted: P W O 3.14.19fe-dirty #2
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
kworker/u16:2 D d56879e0 0 24280 2 0x00000000
Workqueue: writeback bdi_writeback_workfn (flush-9:3)
d5687a3c 00000046 00000000 d56879e0 f2fbd600 f3dbc81b 2e86d607 0001721c
c17d6700 c17d6700 c49cbcc0 e601c6e0 f3dbc81b 00000002 00000001 e9e0fc00
c2328468 0000003b d5687a28 d5687d74 00000001 d5687a3c c12b0db6 f3dba382
Call Trace:
[<f3dbc81b>] ? raid5_unplug+0xbb/0x120 [raid456]
[<f3dbc81b>] ? raid5_unplug+0xbb/0x120 [raid456]
[<c12b0db6>] ? blk_flush_plug_list+0x86/0x1b0
[<f3dba382>] ? stripe_set_idx+0xa2/0xc0 [raid456]
[<c10798bb>] ? prepare_to_wait_event+0x6b/0xd0
[<c153e7f3>] schedule+0x23/0x60
[<f3dbe38b>] get_active_stripe+0x19b/0x5a0 [raid456]
[<c145f80b>] ? bitmap_startwrite+0x5b/0x170
[<c1079990>] ? __wake_up_sync+0x20/0x20
[<f3dbf6b0>] make_request+0x170/0xc30 [raid456]
[<c10b7193>] ? delayacct_end+0x93/0xa0
[<c1079990>] ? __wake_up_sync+0x20/0x20
[<c14501d1>] md_make_request+0xb1/0x1d0
[<c10e6ee3>] ? mempool_alloc_slab+0x13/0x20
[<c12af629>] generic_make_request+0x89/0xc0
[<c12af6ba>] submit_bio+0x5a/0x120
[<c1152b09>] ? __bio_add_page+0xd9/0x220
[<c1153248>] ? bvec_alloc+0x78/0xe0
[<f3c8b612>] xfs_submit_ioend_bio.isra.9+0x32/0x40 [xfs]
[<f3c8b70c>] xfs_submit_ioend+0xec/0x120 [xfs]
[<f3c8b981>] xfs_vm_writepage+0x241/0x580 [xfs]
[<c10ec730>] __writepage+0x10/0x40
[<c10ec720>] ? mapping_tagged+0x20/0x20
[<c10ecc30>] write_cache_pages+0x170/0x3d0
[<f3dbc81b>] ? raid5_unplug+0xbb/0x120 [raid456]
[<c10ec720>] ? mapping_tagged+0x20/0x20
[<c10ecec3>] generic_writepages+0x33/0x60
[<f3c8aa43>] xfs_vm_writepages+0x33/0x40 [xfs]
[<c10ee38a>] do_writepages+0x1a/0x40
[<c11486b2>] __writeback_single_inode+0x42/0x1f0
[<c107965c>] ? wake_up_bit+0x1c/0x20
[<c1149423>] writeback_sb_inodes+0x193/0x2e0
[<c11495ec>] __writeback_inodes_wb+0x7c/0xb0
[<c11497f2>] wb_writeback+0x1d2/0x270
[<c1149c11>] bdi_writeback_workfn+0x151/0x380
[<c153e254>] ? __schedule+0x224/0x7a0
[<c105521c>] process_one_work+0x10c/0x340
[<c1069cb0>] ? default_wake_function+0x10/0x20
[<c1055d31>] worker_thread+0x101/0x330
[<c1055c30>] ? manage_workers.isra.27+0x250/0x250
[<c105ae21>] kthread+0xa1/0xc0
[<c1541837>] ret_from_kernel_thread+0x1b/0x28
[<c105ad80>] ? kthread_create_on_node+0x110/0x110
INFO: task kworker/3:3:26958 blocked for more than 120 seconds.
Tainted: P W O 3.14.19fe-dirty #2
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
kworker/3:3 D 00000000 0 26958 2 0x00000000
Workqueue: md md_submit_flush_data
c6d41dd8 00000046 d128391d 00000000 00000000 00000000 2d875421 0001721c
c17d6700 c17d6700 e9d3bcc0 d4bf5610 00000000 00000000 00000000 ea469748
df1132aa 0000c335 d4bf5654 d4bf5654 de5a17aa c6d41dec c106fe31 57d98c16
Call Trace:
[<c106fe31>] ? update_curr+0xf1/0x1a0
[<c10798bb>] ? prepare_to_wait_event+0x6b/0xd0
[<c153e7f3>] schedule+0x23/0x60
[<f3dbe38b>] get_active_stripe+0x19b/0x5a0 [raid456]
[<c107030f>] ? dequeue_entity+0x11f/0x510
[<c1079990>] ? __wake_up_sync+0x20/0x20
[<f3dbf6b0>] make_request+0x170/0xc30 [raid456]
[<c153e254>] ? __schedule+0x224/0x7a0
[<c111bf45>] ? kmem_cache_free+0xe5/0x110
[<c1079990>] ? __wake_up_sync+0x20/0x20
[<c144fd60>] md_submit_flush_data+0x30/0x70
[<c105521c>] process_one_work+0x10c/0x340
[<c104a30f>] ? mod_timer+0xef/0x1d0
[<c1055d31>] worker_thread+0x101/0x330
[<c1055c30>] ? manage_workers.isra.27+0x250/0x250
[<c105ae21>] kthread+0xa1/0xc0
[<c1541837>] ret_from_kernel_thread+0x1b/0x28
[<c105ad80>] ? kthread_create_on_node+0x110/0x110
There's more, mostly xfs threads complaining about being blocked and
some user processes.
Thinking it was an xfs problem, I did "echo w > /proc/sysrq-trigger" and
got this in syslog:
Sep 26 12:33:06 xplane kernel: SysRq : Show Blocked State
Sep 26 12:33:06 xplane kernel: task PC stack pid father
Sep 26 12:33:06 xplane kernel: kthreadd D c106ea4c 0 2 0
0x00000000
Sep 26 12:33:06 xplane kernel: kswapd0 D 00017219 0 711
2 0x00000000
Sep 26 12:33:06 xplane kernel: md3_raid5 D ea49d770 0
1698 2 0x00000000
Sep 26 12:33:06 xplane kernel: xfsaild/md3 D e7d72700 0
2234 2 0x00000000
Sep 26 12:33:06 xplane kernel: kworker/7:2 D 00000001 0
15726 2 0x00000000
Sep 26 12:33:06 xplane kernel: Workqueue: xfs-log/md3 xfs_log_worker [xfs]
Sep 26 12:33:06 xplane kernel: kworker/u16:2 D d56879e0 0
24280 2 0x00000000
Sep 26 12:33:06 xplane kernel: Workqueue: writeback bdi_writeback_workfn
(flush-9:3)
Sep 26 12:33:06 xplane kernel: kworker/3:3 D 00000000 0
26958 2 0x00000000
Sep 26 12:33:06 xplane kernel: Workqueue: md md_submit_flush_data
Sep 26 12:33:06 xplane kernel: cat D 00000000 0 11412
11410 0x00000000
Sep 26 12:33:06 xplane kernel: cc1 D d00c3bac 0 12102
12101 0x00000000
Sep 26 12:33:06 xplane kernel: ld D c16ef900 0 12132
12130 0x00000000
Sep 26 12:33:06 xplane kernel: make D 00000000 0 12147
12047 0x00000000
Sep 26 12:33:06 xplane kernel: make D d896ea80 0 12374
11263 0x00000000
Sep 26 12:33:06 xplane kernel: cat D f2e51d0c 0 23219
23217 0x00000000
Sep 26 12:33:06 xplane kernel: gcc D f2e51d0c 0 23564
23563 0x00000000
Sep 26 12:33:06 xplane kernel: sh D f2e51d0c 0 25753
23615 0x00000000
which looks similar to the problem from the above mentioned list-post.
I did a few test writes to the filesystem, and it looked like xfs
created the files, and could read them
and delete them, but there was never any disk activity and access to
/sys/block/md3/md/{anything} was hung up
"top" showed consistent I/O wait time, first 25%, then 50%, with no disc
activity
In the end I had to reboot, and I'm running the test again.
Any thoughts on what's happening here or ideas to help debug it?
Thanks,
Bill
^ permalink raw reply
* Re: [GIT PULL REQUEST] late md/raid1 bug fixes for 3.17
From: BillStuff @ 2014-09-26 19:08 UTC (permalink / raw)
To: NeilBrown; +Cc: linux RAID
In-Reply-To: <20140924121805.1b8c3bd9@notabene.brown>
On 09/23/2014 09:18 PM, NeilBrown wrote:
[snip]
> md/raid1: intialise start_next_window for READ case to avoid hang
>
Neil, I've been testing these patches for the past week or two to see if
they help a raid1 "check" hang I had.
They seem to help, but I noticed the above patch is different from what
you originally sent on the list.
The original patch has an extra chunk:
@@ -1444,6 +1445,7 @@ read_again:
r1_bio->state = 0;
r1_bio->mddev = mddev;
r1_bio->sector = bio->bi_iter.bi_sector + sectors_handled;
+ start_next_window = wait_barrier(conf, bio);
goto retry_write;
}
Is the correct patch with or without this chunk?
Thanks,
Bill
^ permalink raw reply
* Re: /sys/block/md126 still exists even after stopping the array
From: Francis Moreau @ 2014-09-26 12:50 UTC (permalink / raw)
To: NeilBrown; +Cc: linux-raid, sebastian.riemer
In-Reply-To: <54255A30.9010406@gmail.com>
On 09/26/2014 02:21 PM, Francis Moreau wrote:
[...]
>
>>>> mdadm --stop --scan <<<
>
> [ 89.975162] md_open(): md125 opened by mdadm [930]
> [ 89.975305] md_release(): md125 released by mdadm [930]
> [ 89.977434] md_open(): md125 opened by mdadm [932]
> [ 89.978813] md_open(): md125 opened by mdadm [930]
> [ 89.979365] md_release(): md125 released by mdadm [932]
> [ 89.979693] md_open(): md125 opened by systemd-udevd [931]
> [ 89.985790] md_release(): md125 released by systemd-udevd [931]
> [ 90.179911] md_release(): md125 released by mdadm [930]
> [ 90.180168] md_open(): md127 opened by mdadm [459]
> [ 90.180187] md_release(): md127 released by mdadm [459]
> [ 90.180199] md_open(): md126 opened by mdadm [459]
> [ 90.180205] md_release(): md126 released by mdadm [459]
> [ 90.180556] md_open(): md126 opened by mdadm [930]
> [ 90.180653] md_release(): md126 released by mdadm [930]
> [ 90.180690] md_open(): md126 opened by mdadm [930]
> [ 90.180758] md_open(): mdX opened by mdadm [459]
What is this 'mdX' device that mdadm operates on ?
It also doesn't have a counterpart release() call.
> [ 90.180995] md_open(): md125 opened by mdadm [459]
> [ 90.181056] md_release(): md125 released by mdadm [459]
> [ 90.182717] md_open(): md127 opened by mdadm [459]
> [ 90.182725] md_release(): md127 released by mdadm [459]
> [ 90.182732] md_open(): md126 opened by mdadm [459]
> [ 90.182761] md_release(): md126 released by mdadm [459]
> [ 90.182770] md_open(): md125 opened by mdadm [459]
> [ 90.182775] md_release(): md125 released by mdadm [459]
> [ 90.182940] md_release(): md126 released by mdadm [930]
> [ 90.183167] md_open(): md127 opened by mdadm [930]
> [ 90.183257] md_release(): md127 released by mdadm [930]
> [ 90.183288] md_open(): md127 opened by mdadm [930]
> [ 90.183461] md_open(): md127 opened by mdadm [459]
> [ 90.183488] md_release(): md127 released by mdadm [459]
> [ 90.183499] md_open(): md125 opened by mdadm [459]
> [ 90.183505] md_release(): md125 released by mdadm [459]
> [ 90.183686] md_release(): md127 released by mdadm [930]
>
>
>> Probably there is a 'change' event happening just before the 'remove' event,
>> and udev runs "mdadm" on the 'change' event, and that ends up happening after
>> the device has been removed.
>>
>> Is this really a problem? Can't you just ignore it and pretend it isn't
>> there?
>
> Well, if you list the block devices that the kernel detected in order to
> operate on them, it could. I don't know exactly what would be the result
> to use it but it could confuse some tools.
>
> Is there a way to check that the 'ghost' device has been removed by
> poking sysfs ?
>
> Thanks
>
^ permalink raw reply
* Re: /sys/block/md126 still exists even after stopping the array
From: Francis Moreau @ 2014-09-26 12:21 UTC (permalink / raw)
To: NeilBrown; +Cc: linux-raid, sebastian.riemer
In-Reply-To: <20140926204445.1ec830b9@notabene.brown>
On 09/26/2014 12:44 PM, NeilBrown wrote:
> On Fri, 26 Sep 2014 12:23:27 +0200 Francis Moreau <francis.moro@gmail.com>
> wrote:
>
>> Hello Neil,
>>
>> On 09/26/2014 02:33 AM, NeilBrown wrote:
>>> On Thu, 25 Sep 2014 18:12:07 +0200 Francis Moreau <francis.moro@gmail.com>
>>> wrote:
>> [...]
>>>> I tried to find out what could have opened the md device by using fuser,
>>>> but fuser reports no users.
>>>
>>> It is probably a transient open/close.
>>>
>>
>> If it's open/close wouldn't the 'close' part make the device disapear ?
>
> No. It's ... complicated.
>
>>
>>>>
>>>> I took a look to the udev rules which are the one shipped by mdadm 3.3.2
>>>> but nothing keep the device opened during the remove event.
>>>>
>>>> Could you give me some hints here to debug this ?
>>>
>>> Modify md_open in drivers/md/md.c to add
>>> printk("Opened by %s\n", current->comm);
>>>
>>> and build a new kernel. That will tell you the name of the process which
>>> opened the device.
>>>
>>
>> I did that I also added a trace in md_release() but strangely no trace
>> were outputed from there.
>
> Without seeing your patch I can't guess what it happening, but I am *certain*
> that md_release() would get called providing md_open didn't return an error.
Here's the patch:
diff --git a/drivers/md/md.c b/drivers/md/md.c
index 73aedcb..08ead8d 100644
--- a/drivers/md/md.c
+++ b/drivers/md/md.c
@@ -6703,6 +6703,8 @@ static int md_open(struct block_device *bdev,
fmode_t mode)
struct mddev *mddev = mddev_find(bdev->bd_dev);
int err;
+ printk("md_open(): opened by %s\n", current->comm);
+
if (!mddev)
return -ENODEV;
@@ -6735,6 +6737,8 @@ static void md_release(struct gendisk *disk,
fmode_t mode)
{
struct mddev *mddev = disk->private_data;
+ printk("md_release(): released by %s\n", current->comm);
+
BUG_ON(!mddev);
atomic_dec(&mddev->openers);
mddev_put(mddev);
>
> It might be helpful to print out the pid and the md device number too
> task_tgid_vnr(current)
> will give you the pid.
> mdname(mddev)
> give the name of the device.
>
Here's the new trace, this time md_release() was called, so I probably
did something wrong the first time, sorry for that.
[ 1.470744] md_open(): md127 opened by mdadm [388]
[ 1.485437] md_release(): md127 released by mdadm [388]
[ 1.486888] md_open(): md126 opened by mdadm [381]
[ 1.487468] md_release(): md126 released by mdadm [381]
[ 1.488646] md_open(): md125 opened by mdadm [383]
[ 1.489074] md_release(): md125 released by mdadm [383]
[ 1.490555] md_open(): md127 opened by mdadm [385]
[ 1.512556] md_release(): md127 released by mdadm [385]
[ 1.512582] md_open(): md127 opened by mdadm [385]
[ 1.512682] md_open(): md126 opened by mdadm [384]
[ 1.553414] md_release(): md126 released by mdadm [384]
[ 1.553442] md_open(): md126 opened by mdadm [384]
[ 1.553549] md_open(): md125 opened by mdadm [382]
[ 1.573263] md_release(): md125 released by mdadm [382]
[ 1.573288] md_open(): md125 opened by mdadm [382]
[ 1.601034] md_open(): md125 opened by mdadm [459]
[ 1.601041] md_release(): md125 released by mdadm [459]
[ 1.601065] md_open(): md126 opened by mdadm [459]
[ 1.601067] md_release(): md126 released by mdadm [459]
[ 1.601090] md_open(): md127 opened by mdadm [459]
[ 1.601092] md_release(): md127 released by mdadm [459]
[ 1.601130] md_open(): md127 opened by mdadm [459]
[ 1.601220] md_release(): md127 released by mdadm [459]
[ 1.601633] md_open(): md126 opened by mdadm [459]
[ 1.601661] md_release(): md126 released by mdadm [459]
[ 1.601673] md_open(): md125 opened by mdadm [459]
[ 1.601695] md_release(): md125 released by mdadm [459]
[ 1.606127] md_open(): md125 opened by mdadm [454]
[ 1.608682] md_open(): md126 opened by mdadm [453]
[ 1.609514] md_open(): md127 opened by mdadm [448]
[ 1.622512] md_release(): md126 released by mdadm [453]
[ 1.623028] md_release(): md127 released by mdadm [448]
[ 1.625288] md_open(): md126 opened by systemd-udevd [363]
[ 1.625391] md_release(): md125 released by mdadm [454]
[ 1.625619] md_open(): md127 opened by systemd-udevd [368]
[ 1.625737] md_open(): md125 opened by systemd-udevd [366]
[ 1.637137] md_release(): md125 released by systemd-udevd [366]
[ 1.643982] md_open(): md125 opened by mdadm [476]
[ 1.644071] md_release(): md127 released by systemd-udevd [368]
[ 1.647787] md_release(): md125 released by mdadm [382]
[ 1.648171] md_release(): md126 released by systemd-udevd [363]
[ 1.651629] md_open(): md126 opened by mdadm [479]
[ 1.656666] md_open(): md127 opened by mdadm [480]
[ 1.657771] md_release(): md125 released by mdadm [476]
[ 1.659312] md_open(): md125 opened by systemd-udevd [365]
[ 1.663193] md_release(): md127 released by mdadm [385]
[ 1.673669] md_release(): md125 released by systemd-udevd [365]
[ 1.685527] md_release(): md127 released by mdadm [480]
[ 1.685599] md_release(): md126 released by mdadm [479]
[ 1.686058] md_open(): md126 opened by systemd-udevd [366]
[ 1.686282] md_release(): md126 released by systemd-udevd [366]
[ 1.691024] md_open(): md127 opened by systemd-udevd [363]
[ 1.695415] md_release(): md126 released by mdadm [384]
[ 1.707163] md_release(): md127 released by systemd-udevd [363]
>>> mdadm --stop --scan <<<
[ 89.975162] md_open(): md125 opened by mdadm [930]
[ 89.975305] md_release(): md125 released by mdadm [930]
[ 89.977434] md_open(): md125 opened by mdadm [932]
[ 89.978813] md_open(): md125 opened by mdadm [930]
[ 89.979365] md_release(): md125 released by mdadm [932]
[ 89.979693] md_open(): md125 opened by systemd-udevd [931]
[ 89.985790] md_release(): md125 released by systemd-udevd [931]
[ 90.179911] md_release(): md125 released by mdadm [930]
[ 90.180168] md_open(): md127 opened by mdadm [459]
[ 90.180187] md_release(): md127 released by mdadm [459]
[ 90.180199] md_open(): md126 opened by mdadm [459]
[ 90.180205] md_release(): md126 released by mdadm [459]
[ 90.180556] md_open(): md126 opened by mdadm [930]
[ 90.180653] md_release(): md126 released by mdadm [930]
[ 90.180690] md_open(): md126 opened by mdadm [930]
[ 90.180758] md_open(): mdX opened by mdadm [459]
[ 90.180995] md_open(): md125 opened by mdadm [459]
[ 90.181056] md_release(): md125 released by mdadm [459]
[ 90.182717] md_open(): md127 opened by mdadm [459]
[ 90.182725] md_release(): md127 released by mdadm [459]
[ 90.182732] md_open(): md126 opened by mdadm [459]
[ 90.182761] md_release(): md126 released by mdadm [459]
[ 90.182770] md_open(): md125 opened by mdadm [459]
[ 90.182775] md_release(): md125 released by mdadm [459]
[ 90.182940] md_release(): md126 released by mdadm [930]
[ 90.183167] md_open(): md127 opened by mdadm [930]
[ 90.183257] md_release(): md127 released by mdadm [930]
[ 90.183288] md_open(): md127 opened by mdadm [930]
[ 90.183461] md_open(): md127 opened by mdadm [459]
[ 90.183488] md_release(): md127 released by mdadm [459]
[ 90.183499] md_open(): md125 opened by mdadm [459]
[ 90.183505] md_release(): md125 released by mdadm [459]
[ 90.183686] md_release(): md127 released by mdadm [930]
> Probably there is a 'change' event happening just before the 'remove' event,
> and udev runs "mdadm" on the 'change' event, and that ends up happening after
> the device has been removed.
>
> Is this really a problem? Can't you just ignore it and pretend it isn't
> there?
Well, if you list the block devices that the kernel detected in order to
operate on them, it could. I don't know exactly what would be the result
to use it but it could confuse some tools.
Is there a way to check that the 'ghost' device has been removed by
poking sysfs ?
Thanks
^ permalink raw reply related
* Re: /sys/block/md126 still exists even after stopping the array
From: Artur Paszkiewicz @ 2014-09-26 11:23 UTC (permalink / raw)
To: NeilBrown, Francis Moreau; +Cc: linux-raid, sebastian.riemer
In-Reply-To: <20140926204445.1ec830b9@notabene.brown>
On 09/26/2014 12:44 PM, NeilBrown wrote:
> On Fri, 26 Sep 2014 12:23:27 +0200 Francis Moreau <francis.moro@gmail.com>
> wrote:
>
>> Hello Neil,
>>
>> On 09/26/2014 02:33 AM, NeilBrown wrote:
>>> On Thu, 25 Sep 2014 18:12:07 +0200 Francis Moreau <francis.moro@gmail.com>
>>> wrote:
>> [...]
>>>> I tried to find out what could have opened the md device by using fuser,
>>>> but fuser reports no users.
>>>
>>> It is probably a transient open/close.
>>>
>>
>> If it's open/close wouldn't the 'close' part make the device disapear ?
>
> No. It's ... complicated.
>
>>
>>>>
>>>> I took a look to the udev rules which are the one shipped by mdadm 3.3.2
>>>> but nothing keep the device opened during the remove event.
>>>>
>>>> Could you give me some hints here to debug this ?
>>>
>>> Modify md_open in drivers/md/md.c to add
>>> printk("Opened by %s\n", current->comm);
>>>
>>> and build a new kernel. That will tell you the name of the process which
>>> opened the device.
>>>
>>
>> I did that I also added a trace in md_release() but strangely no trace
>> were outputed from there.
>
> Without seeing your patch I can't guess what it happening, but I am *certain*
> that md_release() would get called providing md_open didn't return an error.
>
> It might be helpful to print out the pid and the md device number too
> task_tgid_vnr(current)
> will give you the pid.
> mdname(mddev)
> give the name of the device.
>
> Probably there is a 'change' event happening just before the 'remove' event,
> and udev runs "mdadm" on the 'change' event, and that ends up happening after
> the device has been removed.
>
> Is this really a problem? Can't you just ignore it and pretend it isn't
> there?
>
> NeilBrown
>
>>
>> Here's the details of what I did:
>>
>> --- %< ---
>> [root@localhost ~]# cat /proc/mdstat
>> Personalities : [raid1]
>> md125 : active raid1 vdc1[1] vdb1[0]
>> 65472 blocks super 1.0 [2/2] [UU]
>>
>> md126 : active raid1 vdc2[1] vdb2[0]
>> 209536 blocks super 1.2 [2/2] [UU]
>>
>> md127 : active raid1 vdb3[0] vdc3[1]
>> 1819584 blocks super 1.2 [2/2] [UU]
>>
>> unused devices: <none>
>>
>> [root@localhost ~]# mdadm --stop --scan
>>
>> [root@localhost ~]# dmesg | grep md_
>> [ 1.474207] md_open(): opened by mdadm
>> [ 1.475316] md_open(): opened by mdadm
>> [ 1.492880] md_open(): opened by mdadm
>> [ 1.493201] md_open(): opened by mdadm
>> [ 1.494690] md_open(): opened by mdadm
>> [ 1.499369] md_open(): opened by mdadm
>> [ 1.533566] md_open(): opened by mdadm
>> [ 1.533697] md_open(): opened by mdadm
>> [ 1.554419] md_open(): opened by mdadm
>> [ 1.574451] md_open(): opened by mdadm
>> [ 1.574666] md_open(): opened by mdadm
>> [ 1.574877] md_open(): opened by mdadm
>> [ 1.576822] md_open(): opened by systemd-udevd
>> [ 1.576895] md_open(): opened by systemd-udevd
>> [ 1.577029] md_open(): opened by systemd-udevd
>> [ 1.581850] md_open(): opened by mdadm
>> [ 1.584054] md_open(): opened by systemd-udevd
>> [ 1.584770] md_open(): opened by mdadm
>> [ 1.585175] md_open(): opened by mdadm
>> [ 1.586328] md_open(): opened by systemd-udevd
>> [ 1.586933] md_open(): opened by systemd-udevd
>> [ 1.651265] md_open(): opened by mdadm
>> [ 1.651320] md_open(): opened by mdadm
>> [ 1.651364] md_open(): opened by mdadm
>> [ 1.651437] md_open(): opened by mdadm
>> [ 1.652376] md_open(): opened by mdadm
>> [ 1.652452] md_open(): opened by mdadm
>> [ 33.486704] md_open(): opened by mdadm
>> [ 33.489259] md_open(): opened by mdadm
>> [ 33.491000] md_open(): opened by mdadm
>> [ 33.491767] md_open(): opened by systemd-udevd
>> [ 33.692255] md_open(): opened by mdadm
>> [ 33.692288] md_open(): opened by mdadm
>> [ 33.692606] md_open(): opened by mdadm
>> [ 33.692858] md_open(): opened by mdadm
>> [ 33.692942] md_open(): opened by mdadm
>> [ 33.693237] md_open(): opened by mdadm
>> [ 33.694254] md_open(): opened by mdadm
>> [ 33.694275] md_open(): opened by mdadm
>> [ 33.694373] md_open(): opened by mdadm
>> [ 33.695558] md_open(): opened by mdadm
>> [ 33.695679] md_open(): opened by mdadm
>> [ 33.695855] md_open(): opened by mdadm
>> [ 33.695894] md_open(): opened by mdadm
>>
>> [root@localhost ~]# ls /dev/md125
>> /dev/md125
>>
>> [root@localhost ~]# fuser /dev/md125
>>
>> [root@localhost ~]# ps aux | grep "mdadm\|systemd-udevd"
>> root 366 0.0 0.1 38172 1696 ? Ss 06:04 0:00
>> /usr/lib/systemd/systemd-udevd
>> root 465 0.0 0.0 4964 924 ? Ss 06:04 0:00
>> /sbin/mdadm --monitor --scan --daemonise --syslog
>> --pid-file=/run/mdadm/mdadm.pid
>>
>> [root@localhost ~]# ls -l /proc/366/fd/
>> total 0
>> lrwx------ 1 root root 64 Sep 26 06:04 0 -> /dev/null
>> lrwx------ 1 root root 64 Sep 26 06:04 1 -> /dev/null
>> lrwx------ 1 root root 64 Sep 26 06:04 10 -> socket:[8665]
>> lr-x------ 1 root root 64 Sep 26 06:04 11 -> /etc/udev/hwdb.bin
>> lrwx------ 1 root root 64 Sep 26 06:04 12 -> anon_inode:[eventpoll]
>> lrwx------ 1 root root 64 Sep 26 06:04 2 -> /dev/null
>> lrwx------ 1 root root 64 Sep 26 06:04 3 -> socket:[8144]
>> lrwx------ 1 root root 64 Sep 26 06:04 4 -> socket:[8103]
>> lrwx------ 1 root root 64 Sep 26 06:04 5 -> socket:[8660]
>> lrwx------ 1 root root 64 Sep 26 06:04 6 -> /run/udev/queue.bin
>> lr-x------ 1 root root 64 Sep 26 06:04 7 -> anon_inode:inotify
>> lrwx------ 1 root root 64 Sep 26 06:04 8 -> anon_inode:[signalfd]
>> lrwx------ 1 root root 64 Sep 26 06:04 9 -> socket:[8664]
>>
>> [root@localhost ~]# ls -l /proc/465/fd/
>> total 0
>> lrwx------ 1 root root 64 Sep 26 06:04 0 -> /dev/null
>> lrwx------ 1 root root 64 Sep 26 06:04 1 -> /dev/null
>> lrwx------ 1 root root 64 Sep 26 06:04 2 -> /dev/null
>> lr-x------ 1 root root 64 Sep 26 06:06 4 -> /proc/mdstat
>> lrwx------ 1 root root 64 Sep 26 06:06 5 -> socket:[10038]
>>
>> [root@localhost ~]# cat /proc/mdstat
>> Personalities : [raid1]
>> unused devices: <none>
>>
>> [root@localhost ~]# ls /sys/block/md125/md/
>> array_size array_state bitmap/ chunk_size component_size layout
>> level max_read_errors metadata_version new_dev raid_disks
>> reshape_direction reshape_position resync_start safe_mode_delay
>>
>> --- >% ---
>>
>> So in my understanding, only mdadm and udevd are opening the MD devices
>> and mdamd was the last to open the device. For some unknown reasons,
>> md_release() is never called.
>>
>> This happens with:
>>
>> - kernel 3.14.19
>> - mdadm 3.3.2
>> - systemd 208
>>
>> Can you see something wrong here ?
>>
>> Thanks.
>> --
Hi,
I have also been debugging this issue and I came up with this
fix/workaround. It works for me. Can you take a look a this?
Thanks,
Artur
From c547e39789cde93d4a7ea1d3f845d61b82e4f0ed Mon Sep 17 00:00:00 2001
From: Artur Paszkiewicz <artur.paszkiewicz@intel.com>
Date: Fri, 26 Sep 2014 12:20:46 +0200
Subject: [PATCH] md: avoid creating new devices for stopped arrays in
md_open()
When an array is about to be destroyed, set mddev->gendisk->private_data
to NULL as it is no longer needed and check it in md_open(). If
bdev->bd_disk->private_data is NULL, then this indicates that the array
is stopped and return -ENODEV.
Signed-off-by: Artur Paszkiewicz <artur.paszkiewicz@intel.com>
---
drivers/md/md.c | 8 +++++++-
1 file changed, 7 insertions(+), 1 deletion(-)
diff --git a/drivers/md/md.c b/drivers/md/md.c
index 1294238..7109d48 100644
--- a/drivers/md/md.c
+++ b/drivers/md/md.c
@@ -449,6 +449,7 @@ static void mddev_put(struct mddev *mddev)
bs = mddev->bio_set;
mddev->bio_set = NULL;
if (mddev->gendisk) {
+ mddev->gendisk->private_data = NULL;
/* We did a probe so need to clean up. Call
* queue_work inside the spinlock so that
* flush_workqueue() after mddev_find will
@@ -6693,9 +6694,14 @@ static int md_open(struct block_device *bdev, fmode_t mode)
* Succeed if we can lock the mddev, which confirms that
* it isn't being stopped right now.
*/
- struct mddev *mddev = mddev_find(bdev->bd_dev);
+ struct mddev *mddev;
int err;
+ if (!bdev->bd_disk->private_data)
+ return -ENODEV;
+
+ mddev = mddev_find(bdev->bd_dev);
+
if (!mddev)
return -ENODEV;
--
1.8.4.5
^ permalink raw reply related
* Re: /sys/block/md126 still exists even after stopping the array
From: NeilBrown @ 2014-09-26 10:44 UTC (permalink / raw)
To: Francis Moreau; +Cc: linux-raid, sebastian.riemer
In-Reply-To: <54253E9F.4070505@gmail.com>
[-- Attachment #1: Type: text/plain, Size: 6784 bytes --]
On Fri, 26 Sep 2014 12:23:27 +0200 Francis Moreau <francis.moro@gmail.com>
wrote:
> Hello Neil,
>
> On 09/26/2014 02:33 AM, NeilBrown wrote:
> > On Thu, 25 Sep 2014 18:12:07 +0200 Francis Moreau <francis.moro@gmail.com>
> > wrote:
> [...]
> >> I tried to find out what could have opened the md device by using fuser,
> >> but fuser reports no users.
> >
> > It is probably a transient open/close.
> >
>
> If it's open/close wouldn't the 'close' part make the device disapear ?
No. It's ... complicated.
>
> >>
> >> I took a look to the udev rules which are the one shipped by mdadm 3.3.2
> >> but nothing keep the device opened during the remove event.
> >>
> >> Could you give me some hints here to debug this ?
> >
> > Modify md_open in drivers/md/md.c to add
> > printk("Opened by %s\n", current->comm);
> >
> > and build a new kernel. That will tell you the name of the process which
> > opened the device.
> >
>
> I did that I also added a trace in md_release() but strangely no trace
> were outputed from there.
Without seeing your patch I can't guess what it happening, but I am *certain*
that md_release() would get called providing md_open didn't return an error.
It might be helpful to print out the pid and the md device number too
task_tgid_vnr(current)
will give you the pid.
mdname(mddev)
give the name of the device.
Probably there is a 'change' event happening just before the 'remove' event,
and udev runs "mdadm" on the 'change' event, and that ends up happening after
the device has been removed.
Is this really a problem? Can't you just ignore it and pretend it isn't
there?
NeilBrown
>
> Here's the details of what I did:
>
> --- %< ---
> [root@localhost ~]# cat /proc/mdstat
> Personalities : [raid1]
> md125 : active raid1 vdc1[1] vdb1[0]
> 65472 blocks super 1.0 [2/2] [UU]
>
> md126 : active raid1 vdc2[1] vdb2[0]
> 209536 blocks super 1.2 [2/2] [UU]
>
> md127 : active raid1 vdb3[0] vdc3[1]
> 1819584 blocks super 1.2 [2/2] [UU]
>
> unused devices: <none>
>
> [root@localhost ~]# mdadm --stop --scan
>
> [root@localhost ~]# dmesg | grep md_
> [ 1.474207] md_open(): opened by mdadm
> [ 1.475316] md_open(): opened by mdadm
> [ 1.492880] md_open(): opened by mdadm
> [ 1.493201] md_open(): opened by mdadm
> [ 1.494690] md_open(): opened by mdadm
> [ 1.499369] md_open(): opened by mdadm
> [ 1.533566] md_open(): opened by mdadm
> [ 1.533697] md_open(): opened by mdadm
> [ 1.554419] md_open(): opened by mdadm
> [ 1.574451] md_open(): opened by mdadm
> [ 1.574666] md_open(): opened by mdadm
> [ 1.574877] md_open(): opened by mdadm
> [ 1.576822] md_open(): opened by systemd-udevd
> [ 1.576895] md_open(): opened by systemd-udevd
> [ 1.577029] md_open(): opened by systemd-udevd
> [ 1.581850] md_open(): opened by mdadm
> [ 1.584054] md_open(): opened by systemd-udevd
> [ 1.584770] md_open(): opened by mdadm
> [ 1.585175] md_open(): opened by mdadm
> [ 1.586328] md_open(): opened by systemd-udevd
> [ 1.586933] md_open(): opened by systemd-udevd
> [ 1.651265] md_open(): opened by mdadm
> [ 1.651320] md_open(): opened by mdadm
> [ 1.651364] md_open(): opened by mdadm
> [ 1.651437] md_open(): opened by mdadm
> [ 1.652376] md_open(): opened by mdadm
> [ 1.652452] md_open(): opened by mdadm
> [ 33.486704] md_open(): opened by mdadm
> [ 33.489259] md_open(): opened by mdadm
> [ 33.491000] md_open(): opened by mdadm
> [ 33.491767] md_open(): opened by systemd-udevd
> [ 33.692255] md_open(): opened by mdadm
> [ 33.692288] md_open(): opened by mdadm
> [ 33.692606] md_open(): opened by mdadm
> [ 33.692858] md_open(): opened by mdadm
> [ 33.692942] md_open(): opened by mdadm
> [ 33.693237] md_open(): opened by mdadm
> [ 33.694254] md_open(): opened by mdadm
> [ 33.694275] md_open(): opened by mdadm
> [ 33.694373] md_open(): opened by mdadm
> [ 33.695558] md_open(): opened by mdadm
> [ 33.695679] md_open(): opened by mdadm
> [ 33.695855] md_open(): opened by mdadm
> [ 33.695894] md_open(): opened by mdadm
>
> [root@localhost ~]# ls /dev/md125
> /dev/md125
>
> [root@localhost ~]# fuser /dev/md125
>
> [root@localhost ~]# ps aux | grep "mdadm\|systemd-udevd"
> root 366 0.0 0.1 38172 1696 ? Ss 06:04 0:00
> /usr/lib/systemd/systemd-udevd
> root 465 0.0 0.0 4964 924 ? Ss 06:04 0:00
> /sbin/mdadm --monitor --scan --daemonise --syslog
> --pid-file=/run/mdadm/mdadm.pid
>
> [root@localhost ~]# ls -l /proc/366/fd/
> total 0
> lrwx------ 1 root root 64 Sep 26 06:04 0 -> /dev/null
> lrwx------ 1 root root 64 Sep 26 06:04 1 -> /dev/null
> lrwx------ 1 root root 64 Sep 26 06:04 10 -> socket:[8665]
> lr-x------ 1 root root 64 Sep 26 06:04 11 -> /etc/udev/hwdb.bin
> lrwx------ 1 root root 64 Sep 26 06:04 12 -> anon_inode:[eventpoll]
> lrwx------ 1 root root 64 Sep 26 06:04 2 -> /dev/null
> lrwx------ 1 root root 64 Sep 26 06:04 3 -> socket:[8144]
> lrwx------ 1 root root 64 Sep 26 06:04 4 -> socket:[8103]
> lrwx------ 1 root root 64 Sep 26 06:04 5 -> socket:[8660]
> lrwx------ 1 root root 64 Sep 26 06:04 6 -> /run/udev/queue.bin
> lr-x------ 1 root root 64 Sep 26 06:04 7 -> anon_inode:inotify
> lrwx------ 1 root root 64 Sep 26 06:04 8 -> anon_inode:[signalfd]
> lrwx------ 1 root root 64 Sep 26 06:04 9 -> socket:[8664]
>
> [root@localhost ~]# ls -l /proc/465/fd/
> total 0
> lrwx------ 1 root root 64 Sep 26 06:04 0 -> /dev/null
> lrwx------ 1 root root 64 Sep 26 06:04 1 -> /dev/null
> lrwx------ 1 root root 64 Sep 26 06:04 2 -> /dev/null
> lr-x------ 1 root root 64 Sep 26 06:06 4 -> /proc/mdstat
> lrwx------ 1 root root 64 Sep 26 06:06 5 -> socket:[10038]
>
> [root@localhost ~]# cat /proc/mdstat
> Personalities : [raid1]
> unused devices: <none>
>
> [root@localhost ~]# ls /sys/block/md125/md/
> array_size array_state bitmap/ chunk_size component_size layout
> level max_read_errors metadata_version new_dev raid_disks
> reshape_direction reshape_position resync_start safe_mode_delay
>
> --- >% ---
>
> So in my understanding, only mdadm and udevd are opening the MD devices
> and mdamd was the last to open the device. For some unknown reasons,
> md_release() is never called.
>
> This happens with:
>
> - kernel 3.14.19
> - mdadm 3.3.2
> - systemd 208
>
> Can you see something wrong here ?
>
> Thanks.
> --
> To unsubscribe from this list: send the line "unsubscribe linux-raid" in
> the body of a message to majordomo@vger.kernel.org
> More majordomo info at http://vger.kernel.org/majordomo-info.html
[-- Attachment #2: signature.asc --]
[-- Type: application/pgp-signature, Size: 828 bytes --]
^ permalink raw reply
* Re: /sys/block/md126 still exists even after stopping the array
From: Francis Moreau @ 2014-09-26 10:23 UTC (permalink / raw)
To: NeilBrown; +Cc: linux-raid, sebastian.riemer
In-Reply-To: <20140926103348.5f5ea568@notabene.brown>
Hello Neil,
On 09/26/2014 02:33 AM, NeilBrown wrote:
> On Thu, 25 Sep 2014 18:12:07 +0200 Francis Moreau <francis.moro@gmail.com>
> wrote:
[...]
>> I tried to find out what could have opened the md device by using fuser,
>> but fuser reports no users.
>
> It is probably a transient open/close.
>
If it's open/close wouldn't the 'close' part make the device disapear ?
>>
>> I took a look to the udev rules which are the one shipped by mdadm 3.3.2
>> but nothing keep the device opened during the remove event.
>>
>> Could you give me some hints here to debug this ?
>
> Modify md_open in drivers/md/md.c to add
> printk("Opened by %s\n", current->comm);
>
> and build a new kernel. That will tell you the name of the process which
> opened the device.
>
I did that I also added a trace in md_release() but strangely no trace
were outputed from there.
Here's the details of what I did:
--- %< ---
[root@localhost ~]# cat /proc/mdstat
Personalities : [raid1]
md125 : active raid1 vdc1[1] vdb1[0]
65472 blocks super 1.0 [2/2] [UU]
md126 : active raid1 vdc2[1] vdb2[0]
209536 blocks super 1.2 [2/2] [UU]
md127 : active raid1 vdb3[0] vdc3[1]
1819584 blocks super 1.2 [2/2] [UU]
unused devices: <none>
[root@localhost ~]# mdadm --stop --scan
[root@localhost ~]# dmesg | grep md_
[ 1.474207] md_open(): opened by mdadm
[ 1.475316] md_open(): opened by mdadm
[ 1.492880] md_open(): opened by mdadm
[ 1.493201] md_open(): opened by mdadm
[ 1.494690] md_open(): opened by mdadm
[ 1.499369] md_open(): opened by mdadm
[ 1.533566] md_open(): opened by mdadm
[ 1.533697] md_open(): opened by mdadm
[ 1.554419] md_open(): opened by mdadm
[ 1.574451] md_open(): opened by mdadm
[ 1.574666] md_open(): opened by mdadm
[ 1.574877] md_open(): opened by mdadm
[ 1.576822] md_open(): opened by systemd-udevd
[ 1.576895] md_open(): opened by systemd-udevd
[ 1.577029] md_open(): opened by systemd-udevd
[ 1.581850] md_open(): opened by mdadm
[ 1.584054] md_open(): opened by systemd-udevd
[ 1.584770] md_open(): opened by mdadm
[ 1.585175] md_open(): opened by mdadm
[ 1.586328] md_open(): opened by systemd-udevd
[ 1.586933] md_open(): opened by systemd-udevd
[ 1.651265] md_open(): opened by mdadm
[ 1.651320] md_open(): opened by mdadm
[ 1.651364] md_open(): opened by mdadm
[ 1.651437] md_open(): opened by mdadm
[ 1.652376] md_open(): opened by mdadm
[ 1.652452] md_open(): opened by mdadm
[ 33.486704] md_open(): opened by mdadm
[ 33.489259] md_open(): opened by mdadm
[ 33.491000] md_open(): opened by mdadm
[ 33.491767] md_open(): opened by systemd-udevd
[ 33.692255] md_open(): opened by mdadm
[ 33.692288] md_open(): opened by mdadm
[ 33.692606] md_open(): opened by mdadm
[ 33.692858] md_open(): opened by mdadm
[ 33.692942] md_open(): opened by mdadm
[ 33.693237] md_open(): opened by mdadm
[ 33.694254] md_open(): opened by mdadm
[ 33.694275] md_open(): opened by mdadm
[ 33.694373] md_open(): opened by mdadm
[ 33.695558] md_open(): opened by mdadm
[ 33.695679] md_open(): opened by mdadm
[ 33.695855] md_open(): opened by mdadm
[ 33.695894] md_open(): opened by mdadm
[root@localhost ~]# ls /dev/md125
/dev/md125
[root@localhost ~]# fuser /dev/md125
[root@localhost ~]# ps aux | grep "mdadm\|systemd-udevd"
root 366 0.0 0.1 38172 1696 ? Ss 06:04 0:00
/usr/lib/systemd/systemd-udevd
root 465 0.0 0.0 4964 924 ? Ss 06:04 0:00
/sbin/mdadm --monitor --scan --daemonise --syslog
--pid-file=/run/mdadm/mdadm.pid
[root@localhost ~]# ls -l /proc/366/fd/
total 0
lrwx------ 1 root root 64 Sep 26 06:04 0 -> /dev/null
lrwx------ 1 root root 64 Sep 26 06:04 1 -> /dev/null
lrwx------ 1 root root 64 Sep 26 06:04 10 -> socket:[8665]
lr-x------ 1 root root 64 Sep 26 06:04 11 -> /etc/udev/hwdb.bin
lrwx------ 1 root root 64 Sep 26 06:04 12 -> anon_inode:[eventpoll]
lrwx------ 1 root root 64 Sep 26 06:04 2 -> /dev/null
lrwx------ 1 root root 64 Sep 26 06:04 3 -> socket:[8144]
lrwx------ 1 root root 64 Sep 26 06:04 4 -> socket:[8103]
lrwx------ 1 root root 64 Sep 26 06:04 5 -> socket:[8660]
lrwx------ 1 root root 64 Sep 26 06:04 6 -> /run/udev/queue.bin
lr-x------ 1 root root 64 Sep 26 06:04 7 -> anon_inode:inotify
lrwx------ 1 root root 64 Sep 26 06:04 8 -> anon_inode:[signalfd]
lrwx------ 1 root root 64 Sep 26 06:04 9 -> socket:[8664]
[root@localhost ~]# ls -l /proc/465/fd/
total 0
lrwx------ 1 root root 64 Sep 26 06:04 0 -> /dev/null
lrwx------ 1 root root 64 Sep 26 06:04 1 -> /dev/null
lrwx------ 1 root root 64 Sep 26 06:04 2 -> /dev/null
lr-x------ 1 root root 64 Sep 26 06:06 4 -> /proc/mdstat
lrwx------ 1 root root 64 Sep 26 06:06 5 -> socket:[10038]
[root@localhost ~]# cat /proc/mdstat
Personalities : [raid1]
unused devices: <none>
[root@localhost ~]# ls /sys/block/md125/md/
array_size array_state bitmap/ chunk_size component_size layout
level max_read_errors metadata_version new_dev raid_disks
reshape_direction reshape_position resync_start safe_mode_delay
--- >% ---
So in my understanding, only mdadm and udevd are opening the MD devices
and mdamd was the last to open the device. For some unknown reasons,
md_release() is never called.
This happens with:
- kernel 3.14.19
- mdadm 3.3.2
- systemd 208
Can you see something wrong here ?
Thanks.
^ permalink raw reply
* RE: [PATCH] md: avoid potential long delay under pers_lock
From: Chao Yu @ 2014-09-26 8:59 UTC (permalink / raw)
To: 'NeilBrown'; +Cc: linux-raid, linux-kernel
In-Reply-To: <20140926103620.7c397832@notabene.brown>
> -----Original Message-----
> From: NeilBrown [mailto:neilb@suse.de]
> Sent: Friday, September 26, 2014 8:36 AM
> To: Chao Yu
> Cc: linux-raid@vger.kernel.org; linux-kernel@vger.kernel.org
> Subject: Re: [PATCH] md: avoid potential long delay under pers_lock
>
> On Thu, 25 Sep 2014 15:28:34 +0800 Chao Yu <chao2.yu@samsung.com> wrote:
>
> > printk may cause long time lapse if value of printk_delay in sysctl is
> > configured large by user. If register_md_personality takes long time to print in
> > spinlock pers_lock, we may encounter high CPU usage rate when there are other
> > pers_lock competitors who may be blocked to spin.
> > We can avoid this condition by moving printk out of coverage of pers_lock
> > spinlock.
> >
> > Signed-off-by: Chao Yu <chao2.yu@samsung.com>
> > ---
> > drivers/md/md.c | 3 ++-
> > 1 file changed, 2 insertions(+), 1 deletion(-)
> >
> > diff --git a/drivers/md/md.c b/drivers/md/md.c
> > index e02de05..5fcf215 100644
> > --- a/drivers/md/md.c
> > +++ b/drivers/md/md.c
> > @@ -7200,9 +7200,10 @@ static const struct file_operations md_seq_fops = {
> >
> > int register_md_personality(struct md_personality *p)
> > {
> > + printk(KERN_INFO "md: %s personality registered for level %d\n",
> > + p->name, p->level);
> > spin_lock(&pers_lock);
> > list_add_tail(&p->list, &pers_list);
> > - printk(KERN_INFO "md: %s personality registered for level %d\n", p->name, p->level);
> > spin_unlock(&pers_lock);
> > return 0;
> > }
>
> I'm not sure I see the pressing need for this - have you noticed actual
> problems?
Haven't, I found this by code review.
Thanks,
Yu
> However it seems to make sense so I've applied it.
>
> Thanks,
> NeilBrown
^ permalink raw reply
* RE: [PATCH] md: avoid potential long delay under pers_lock
From: Chao Yu @ 2014-09-26 8:56 UTC (permalink / raw)
To: 'Henrique de Moraes Holschuh'; +Cc: neilb, linux-raid, linux-kernel
In-Reply-To: <20140925165114.GE10814@khazad-dum.debian.net>
> -----Original Message-----
> From: Henrique de Moraes Holschuh [mailto:hmh@hmh.eng.br]
> Sent: Friday, September 26, 2014 12:51 AM
> To: Chao Yu
> Cc: neilb@suse.de; linux-raid@vger.kernel.org; linux-kernel@vger.kernel.org
> Subject: Re: [PATCH] md: avoid potential long delay under pers_lock
>
> On Thu, 25 Sep 2014, Chao Yu wrote:
> > printk may cause long time lapse if value of printk_delay in sysctl is
> > configured large by user. If register_md_personality takes long time to print in
> > spinlock pers_lock, we may encounter high CPU usage rate when there are other
> > pers_lock competitors who may be blocked to spin.
> > We can avoid this condition by moving printk out of coverage of pers_lock
> > spinlock.
> >
> > Signed-off-by: Chao Yu <chao2.yu@samsung.com>
> > ---
> > drivers/md/md.c | 3 ++-
> > 1 file changed, 2 insertions(+), 1 deletion(-)
> >
> > diff --git a/drivers/md/md.c b/drivers/md/md.c
> > index e02de05..5fcf215 100644
> > --- a/drivers/md/md.c
> > +++ b/drivers/md/md.c
> > @@ -7200,9 +7200,10 @@ static const struct file_operations md_seq_fops = {
> >
> > int register_md_personality(struct md_personality *p)
> > {
> > + printk(KERN_INFO "md: %s personality registered for level %d\n",
> > + p->name, p->level);
> > spin_lock(&pers_lock);
> > list_add_tail(&p->list, &pers_list);
> > - printk(KERN_INFO "md: %s personality registered for level %d\n", p->name, p->level);
> > spin_unlock(&pers_lock);
> > return 0;
> > }
>
> Wouldn't it make more sense to move the printk after the spin_unlock ?
As original printk msg in {,un}register_md_personality shows '{,un}registered'
which means the main job is done before printk, it's better to move the printk
after spin_unlock in both {,un}register_md_personality. But IMHO, it's another
minor issue, should we fix in this patch?
Thanks,
Yu
>
> --
> "One disk to rule them all, One disk to find them. One disk to bring
> them all and in the darkness grind them. In the Land of Redmond
> where the shadows lie." -- The Silicon Valley Tarot
> Henrique Holschuh
^ permalink raw reply
* Re: [PATCH] md: avoid potential long delay under pers_lock
From: NeilBrown @ 2014-09-26 0:36 UTC (permalink / raw)
To: Chao Yu; +Cc: linux-raid, linux-kernel
In-Reply-To: <002801cfd892$696e39d0$3c4aad70$@samsung.com>
[-- Attachment #1: Type: text/plain, Size: 1352 bytes --]
On Thu, 25 Sep 2014 15:28:34 +0800 Chao Yu <chao2.yu@samsung.com> wrote:
> printk may cause long time lapse if value of printk_delay in sysctl is
> configured large by user. If register_md_personality takes long time to print in
> spinlock pers_lock, we may encounter high CPU usage rate when there are other
> pers_lock competitors who may be blocked to spin.
> We can avoid this condition by moving printk out of coverage of pers_lock
> spinlock.
>
> Signed-off-by: Chao Yu <chao2.yu@samsung.com>
> ---
> drivers/md/md.c | 3 ++-
> 1 file changed, 2 insertions(+), 1 deletion(-)
>
> diff --git a/drivers/md/md.c b/drivers/md/md.c
> index e02de05..5fcf215 100644
> --- a/drivers/md/md.c
> +++ b/drivers/md/md.c
> @@ -7200,9 +7200,10 @@ static const struct file_operations md_seq_fops = {
>
> int register_md_personality(struct md_personality *p)
> {
> + printk(KERN_INFO "md: %s personality registered for level %d\n",
> + p->name, p->level);
> spin_lock(&pers_lock);
> list_add_tail(&p->list, &pers_list);
> - printk(KERN_INFO "md: %s personality registered for level %d\n", p->name, p->level);
> spin_unlock(&pers_lock);
> return 0;
> }
I'm not sure I see the pressing need for this - have you noticed actual
problems?
However it seems to make sense so I've applied it.
Thanks,
NeilBrown
[-- Attachment #2: signature.asc --]
[-- Type: application/pgp-signature, Size: 828 bytes --]
^ permalink raw reply
page: next (older) | prev (newer) | latest
- recent:[subjects (threaded)|topics (new)|topics (active)]
This is a public inbox, see mirroring instructions
for how to clone and mirror all data and code used for this inbox