Groups | Search | Server Info | Keyboard shortcuts | Login | Register [http] [https] [nntp] [nntps]

Groups > linux.kernel > #1580543 > unrolled thread

Re: Boot regression (was "Re: [PATCH] genhd: Do not hold event lock when scheduling workqueue elements")

Back to article view | Back to linux.kernel

This discussion starts older than the indexed window; earlier articles aren't shown. The article labeled Started by below is the oldest one visible, not the original post.

Contents

  Re: Boot regression (was "Re: [PATCH] genhd: Do not hold event         lock when scheduling workqueue elements") "hch@lst.de" <hch@lst.de> - 2017-02-14 14:50 +0100
    Re: Boot regression (was "Re: [PATCH] genhd: Do not hold event         lock when scheduling workqueue elements") "hch@lst.de" <hch@lst.de> - 2017-02-14 15:40 +0100
      RE: Boot regression (was "Re: [PATCH] genhd: Do not hold event lock  when scheduling workqueue elements") Dexuan Cui <decui@microsoft.com> - 2017-02-14 15:50 +0100
        Re: Boot regression (was "Re: [PATCH] genhd: Do not hold event         lock when scheduling workqueue elements") "hch@lst.de" <hch@lst.de> - 2017-02-14 16:00 +0100
          Re: Boot regression (was "Re: [PATCH] genhd: Do not hold event         lock when scheduling workqueue elements") "hch@lst.de" <hch@lst.de> - 2017-02-14 17:40 +0100
            RE: Boot regression (was "Re: [PATCH] genhd: Do not hold event lock  when scheduling workqueue elements") Dexuan Cui <decui@microsoft.com> - 2017-02-15 15:00 +0100

#1580543 — Re: Boot regression (was "Re: [PATCH] genhd: Do not hold event lock when scheduling workqueue elements")

Hi Dexuan,

can you try the hack below for now?  I disable the TUR call from
sd_check_events, which I think your VM is hanging on.  The checks
it does on the sense data look a bit fishy, but so far I've not
identified a possible root cause.

diff --git a/drivers/scsi/sd.c b/drivers/scsi/sd.c
index 40b4038c019e..1502e87c2be9 100644
--- a/drivers/scsi/sd.c
+++ b/drivers/scsi/sd.c
@@ -1457,9 +1457,13 @@ static unsigned int sd_check_events(struct gendisk *disk, unsigned int clearing)
 	retval = -ENODEV;
 
 	if (scsi_block_when_processing_errors(sdp)) {
+#if 0
 		sshdr  = kzalloc(sizeof(*sshdr), GFP_KERNEL);
 		retval = scsi_test_unit_ready(sdp, SD_TIMEOUT, SD_MAX_RETRIES,
 					      sshdr);
+#else
+		retval = 0;
+#endif
 	}
 
 	/* failed to execute TUR, assume media not present */

[toc] | [next] | [standalone]

#1580579

[Multipart message — attachments visible in raw view] — view raw

Ok, thanks for testing.  Can you try the patch below?  It fixes a
clear problem which was partially papered over before the commit
you bisected to, although it can't explain why blk-mq still works.

[toc] | [prev] | [next] | [standalone]

#1580583 — RE: Boot regression (was "Re: [PATCH] genhd: Do not hold event lock when scheduling workqueue elements")

> From: hch@lst.de [mailto:hch@lst.de]
> Sent: Tuesday, February 14, 2017 22:29
> To: Dexuan Cui <decui@microsoft.com>
> Subject: Re: Boot regression (was "Re: [PATCH] genhd: Do not hold event lock
> when scheduling workqueue elements")
> 
> Ok, thanks for testing.  Can you try the patch below?  It fixes a
> clear problem which was partially papered over before the commit
> you bisected to, although it can't explain why blk-mq still works.

Still bad luck. :-(

BTW, I'm using the first "bad" commit (scsi: allocate scsi_cmnd structures as
part of struct request) + the 2 patches you provided today.

I suppose I don't need to test the 2 patches on the latest linux-next repo.

Thanks,
-- Dexuan

[toc] | [prev] | [next] | [standalone]

#1580589

On Tue, Feb 14, 2017 at 02:46:41PM +0000, Dexuan Cui wrote:
> > From: hch@lst.de [mailto:hch@lst.de]
> > Sent: Tuesday, February 14, 2017 22:29
> > To: Dexuan Cui <decui@microsoft.com>
> > Subject: Re: Boot regression (was "Re: [PATCH] genhd: Do not hold event lock
> > when scheduling workqueue elements")
> > 
> > Ok, thanks for testing.  Can you try the patch below?  It fixes a
> > clear problem which was partially papered over before the commit
> > you bisected to, although it can't explain why blk-mq still works.
> 
> Still bad luck. :-(
> 
> BTW, I'm using the first "bad" commit (scsi: allocate scsi_cmnd structures as
> part of struct request) + the 2 patches you provided today.
> 
> I suppose I don't need to test the 2 patches on the latest linux-next repo.

I'd love a test on that repo actually.  We had a few other for sense
handling since then I think.

[toc] | [prev] | [next] | [standalone]

#1580650

> I tested today's linux-next (next-20170214) + the 2 patches just now and got
> a weird result: 
> sometimes the VM stills hung with a new calltrace (BUG: spinlock bad
> magic) , but sometimes the VM did boot up despite the new calltrace!
> 
> Attached is the log of a "good" boot.
> 
> It looks we have a memory corruption issue somewhere...

Yes.

> Actually previously I saw the "BUG: spinlock bad magic" message once, but I
> couldn't repro it later, so I didn't mention it to you.

Interesting.

> 
> The good news is that now I can repro the "spinlock bad magic" message
> every time. 
> I tried to dig into this by enabling Kernel hacking -> Memory debugging,
> but didn't find anything abnormal. 
> Is it possible that the SCSI layer passes a wrong memory address?

It's possible, but this looks like it might be a different issue.

A few questions on the dmesg:

[    6.208794] sd 2:0:0:0: [storvsc] Sense Key : Illegal Request [current] 
[    6.209447] sd 2:0:0:0: [storvsc] Add. Sense: Invalid command operation code
[    6.210043] sd 3:0:0:0: [storvsc] Sense Key : Illegal Request [current] 
[    6.210618] sd 3:0:0:0: [storvsc] Add. Sense: Invalid command operation code
[    6.212272] sd 2:0:0:0: [storvsc] Sense Key : Illegal Request [current] 
[    6.212897] sd 2:0:0:0: [storvsc] Add. Sense: Invalid command operation code
[    6.213474] sd 3:0:0:0: [storvsc] Sense Key : Illegal Request [current] 
[    6.214051] sd 3:0:0:0: [storvsc] Add. Sense: Invalid command operation code

I didn't see anything like this in the other logs.  Are these messages
something usual on HyperV VMs?

[    6.358405] XFS (sdb1): Mounting V5 Filesystem
[    6.404478] XFS (sdb1): Ending clean mount
[    7.535174] BUG: spinlock bad magic on CPU#0, swapper/0/0
[    7.536807]  lock: host_ts+0x30/0xffffffffffffe1a0 [hv_utils], .magic: 00000000, .owner: <none>/-1, .owner_cpu: 0
[    7.538436] CPU: 0 PID: 0 Comm: swapper/0 Not tainted 4.10.0-rc8-next-20170214+ #1
[    7.539142] Hardware name: Microsoft Corporation Virtual Machine/Virtual Machine, BIOS 090006  04/28/2016
[    7.539142] Call Trace:
[    7.539142]  <IRQ>
[    7.539142]  dump_stack+0x63/0x82
[    7.539142]  spin_dump+0x78/0xc0
[    7.539142]  do_raw_spin_lock+0xfd/0x160
[    7.539142]  _raw_spin_lock_irqsave+0x4c/0x60
[    7.539142]  ? timesync_onchannelcallback+0x153/0x220 [hv_utils]
[    7.539142]  timesync_onchannelcallback+0x153/0x220 [hv_utils]

Can you resolve this address using gdb to a line of code?  Once inside
gdb do:

l *(timesync_onchannelcallback+0x153)

[toc] | [prev] | [next] | [standalone]

#1581322 — RE: Boot regression (was "Re: [PATCH] genhd: Do not hold event lock when scheduling workqueue elements")

> From: hch@lst.de [mailto:hch@lst.de]
> Sent: Wednesday, February 15, 2017 00:35
> > I tested today's linux-next (next-20170214) + the 2 patches just now and
> got
> > a weird result:
> > sometimes the VM stills hung with a new calltrace (BUG: spinlock bad
> > magic) , but sometimes the VM did boot up despite the new calltrace!
> >
> > Attached is the log of a "good" boot.
> >
> > It looks we have a memory corruption issue somewhere...
>
> Yes.
It's due to an uninitialized spinlock. Please see the below.

> > Actually previously I saw the "BUG: spinlock bad magic" message once, but
> I
> > couldn't repro it later, so I didn't mention it to you.
>
> Interesting.
Ditto.
And probably my memory was inaccurate due to the long period of bisecting.
We should always see the message.

>
> A few questions on the dmesg:
>
> [    6.208794] sd 2:0:0:0: [storvsc] Sense Key : Illegal Request [current]
> [    6.209447] sd 2:0:0:0: [storvsc] Add. Sense: Invalid command operation
> code
> [    6.210043] sd 3:0:0:0: [storvsc] Sense Key : Illegal Request [current]
> [    6.210618] sd 3:0:0:0: [storvsc] Add. Sense: Invalid command operation
> code
> [    6.212272] sd 2:0:0:0: [storvsc] Sense Key : Illegal Request [current]
> [    6.212897] sd 2:0:0:0: [storvsc] Add. Sense: Invalid command operation
> code
> [    6.213474] sd 3:0:0:0: [storvsc] Sense Key : Illegal Request [current]
> [    6.214051] sd 3:0:0:0: [storvsc] Add. Sense: Invalid command operation
> code
>
> I didn't see anything like this in the other logs.  Are these messages
> something usual on HyperV VMs?

The messages should be normal, and I have always seen them for years
at least.

I think they're triggered by "/sbin/hdparm /dev/sda" or
"/lib/udev/ata_id /dev/sda"  in my Ubuntu 16.04 VM: during the VM
boot-up, the 2 programs are executed by the initrd's systemd-udev or other
system init scripts and the 2 programs try to run these 2 SCSI commands,
which are not supported by Hyper-V:

ATA PASS THROUGH (12) -- 0xa1
ATA PASS THROUGH (16) -- 0x85

IMO the commands are used when PATA/SATA devices are connected to
SCSI-to-ATA bridge, so it's understandable that Hyper-V doesn't support
them.

In the case of boot failure (hang), the 2 programs don't have a chance to
run, so we can't see the messages.

IMO we should ignore the messages, which should be harmless.

> [    6.358405] XFS (sdb1): Mounting V5 Filesystem
> [    6.404478] XFS (sdb1): Ending clean mount
> [    7.535174] BUG: spinlock bad magic on CPU#0, swapper/0/0
> [    7.536807]  lock: host_ts+0x30/0xffffffffffffe1a0 [hv_utils], .magic:
> 00000000, .owner: <none>/-1, .owner_cpu: 0
> [    7.538436] CPU: 0 PID: 0 Comm: swapper/0 Not tainted 4.10.0-rc8-next-
> 20170214+ #1
> [    7.539142] Hardware name: Microsoft Corporation Virtual Machine/Virtual
> Machine, BIOS 090006  04/28/2016
> [    7.539142] Call Trace:
> [    7.539142]  <IRQ>
> [    7.539142]  dump_stack+0x63/0x82
> [    7.539142]  spin_dump+0x78/0xc0
> [    7.539142]  do_raw_spin_lock+0xfd/0x160
> [    7.539142]  _raw_spin_lock_irqsave+0x4c/0x60
> [    7.539142]  ? timesync_onchannelcallback+0x153/0x220 [hv_utils]
> [    7.539142]  timesync_onchannelcallback+0x153/0x220 [hv_utils]
>
> Can you resolve this address using gdb to a line of code?  Once inside
> gdb do:
>
> l *(timesync_onchannelcallback+0x153)

(gdb) l *(timesync_onchannelcallback+0x153)
0xffffffffc0104593 is in timesync_onchannelcallback (drivers/hv/hv_util.c:279).
274             } else {
275                     /*
276                      * Save the adjusted time sample from the host and the snapshot
277                      * of the current system time for PTP device.
278                      */
279                     spin_lock_irqsave(&host_ts.lock, flags);
280
281                     cur_reftime = hyperv_cs->read(hyperv_cs);
282                     host_ts.host_time = hosttime;
283                     host_ts.ref_time = cur_reftime;

It turns out the "host_ts.lock" isn't initialized with spin_lock_init().
I'll submit a patch for this.

However, the SCSI issue (i.e. *sometimes* the VM fails to boot) is still there, I think.
We need to continue to debug...

Thanks,
-- Dexuan

[toc] | [prev] | [standalone]

Back to top | Article view | linux.kernel

csiph-web