Re: fs/dcache.c - BUG: soft lockup - CPU#5 stuck for 22s! [systemd-udevd:1667]

From: Mika Westerberg
Date: Wed May 28 2014 - 09:12:48 EST


On Wed, May 28, 2014 at 12:57:01PM +0100, Al Viro wrote:
> On Wed, May 28, 2014 at 10:37:51AM +0300, Mika Westerberg wrote:
>
> > I sent you the whole log privately so that I don't spam everyone.
> >
> > Summary is here:
> >
> > May 28 10:24:23 lahna kernel: scsi 14:0:0:0: Direct-Access JetFlash Transcend 4GB 8.07 PQ: 0 ANSI: 4
> > May 28 10:24:23 lahna kernel: sd 14:0:0:0: Attached scsi generic sg4 type 0
> > May 28 10:24:23 lahna kernel: sd 14:0:0:0: [sdc] 7864320 512-byte logical blocks: (4.02 GB/3.75 GiB)
> > May 28 10:24:23 lahna kernel: sd 14:0:0:0: [sdc] Write Protect is off
> > May 28 10:24:23 lahna kernel: sd 14:0:0:0: [sdc] Mode Sense: 23 00 00 00
> > May 28 10:24:23 lahna kernel: sd 14:0:0:0: [sdc] Write cache: disabled, read cache: enabled, doesn't support DPO or FUA
> > May 28 10:24:23 lahna kernel: sdc: sdc1
> > May 28 10:24:23 lahna kernel: sd 14:0:0:0: [sdc] Attached SCSI removable disk
> >
> > Here I detached the USB stick:
> >
> > May 28 10:24:32 lahna kernel: usb 3-10.4: USB disconnect, device number 6
> > May 28 10:24:32 lahna kernel: check_submounts_and_drop[/dev/block/8:33]; CPU 4 PID 576 [systemd-udevd]
> > May 28 10:24:32 lahna kernel: dput[/dev/block/8:33]; CPU 4 PID 576 [systemd-udevd]
> > May 28 10:24:32 lahna kernel: check_submounts_and_drop[3-10/3-10.4/3-10.4:1.0/host14]; CPU 1 PID 1683 [systemd-udevd]
> > May 28 10:24:32 lahna kernel: shrink[3-10.4:1.0/host14/target14:0:0/subsystem]; CPU 1 PID 1683 [systemd-udevd]
> > May 28 10:24:32 lahna kernel: shrink[host14/target14:0:0/14:0:0:0/rev]; CPU 1 PID 1683 [systemd-udevd]
> > May 28 10:24:32 lahna kernel: shrink[host14/target14:0:0/14:0:0:0/vendor]; CPU 1 PID 1683 [systemd-udevd]
> > May 28 10:24:32 lahna kernel: shrink[host14/target14:0:0/14:0:0:0/model]; CPU 1 PID 1683 [systemd-udevd]
> > May 28 10:24:32 lahna kernel: check_submounts_and_drop[/dev/block/8:32]; CPU 4 PID 576 [systemd-udevd]
> > ...
> > May 28 10:24:32 lahna kernel: check_submounts_and_drop[0000:00:14.0/usb3/3-10/3-10.4]; CPU 6 PID 1684 [systemd-udevd]
> > May 28 10:24:32 lahna kernel: check_submounts_and_drop[0000:00:14.0/usb3/3-10/3-10.4]; CPU 7 PID 1685 [systemd-udevd]
> > May 28 10:24:32 lahna kernel: shrink[usb3/3-10/3-10.4/ltm_capable]; CPU 7 PID 1685 [systemd-udevd]
> > May 28 10:24:32 lahna kernel: A
> ...
>
> Hmm... As it is, we have d_walk() trying _very_ hard in those situations.
> Could you add that on top of the previous and see if livelock changes?
>
> diff --git a/fs/dcache.c b/fs/dcache.c
> index 42ae01e..4ce58d3 100644
> --- a/fs/dcache.c
> +++ b/fs/dcache.c
> @@ -1209,7 +1209,7 @@ static enum d_walk_ret select_collect(void *_data, struct dentry *dentry)
> * ensures forward progress). We'll be coming back to find
> * the rest.
> */
> - if (!list_empty(&data->dispose))
> + if (data->found)
> ret = need_resched() ? D_WALK_QUIT : D_WALK_NORETRY;
> out:
> return ret;

I added this on top of your previus patch and unfortunately the livelock
is still there :-(

>From the previous log, it looks like udev is doing exactly same operation
(check_submounts_and_drop) on 4 of the CPUs in paraller:

May 28 10:24:32 lahna kernel: check_submounts_and_drop[0000:00:14.0/usb3/3-10/3-10.4]; CPU 6 PID 1684 [systemd-udevd]
May 28 10:24:32 lahna kernel: check_submounts_and_drop[0000:00:14.0/usb3/3-10/3-10.4]; CPU 7 PID 1685 [systemd-udevd]
May 28 10:24:32 lahna kernel: check_submounts_and_drop[0000:00:14.0/usb3/3-10/3-10.4]; CPU 1 PID 1683 [systemd-udevd]
May 28 10:24:32 lahna kernel: check_submounts_and_drop[0000:00:14.0/usb3/3-10/3-10.4]; CPU 0 PID 1686 [systemd-udevd]

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