sata_mv on Orion: mv_err_intr when shutting down

sata_mv on Orion: mv_err_intr when shutting down

[Martin Michlmayr]

With 2.6.26-rc1 on an Orion based platform (QNAP TS-209) I sometimes
get the following during shut down:

[42949439.950000] qnap_ts209_power_off: triggering power-off...
[42949439.960000] ata1: mv_err_intr: err_cause=02000020 pp_flags=0x2
[42949439.970000] ata1: exception Emask 0x10 SAct 0x0 SErr 0x190002 action 0xe fro

I never got this with 2.6.25.  With 2.6.26-rc1 I get this message from
time to time, but not always.  The disk spins down properly.  I think
it wants to print a 3rd line because once it was printed "[42949439"
once but the machine got shut off because the full line was printed.

<tries some more>

I just got:

[42949421.700000] qnap_ts209_power_off: triggering power-off...
[42949421.710000] ata1: mv_err_intr: err_cause=02000020 pp_flags=0x2
[42949421.720000] ata1: exception Emask 0x10 SAct 0x0 SErr 0x190002 action 0xe frozen
[42949421.720000] ata1: edma_err_cause=02000020 pp_flags

Any idea?
-- 
Martin Michlmayr
http://www.cyrius.com/

Re: sata_mv on Orion: mv_err_intr when shutting down

[Mark Lord]

Martin Michlmayr wrote:
> With 2.6.26-rc1 on an Orion based platform (QNAP TS-209) I sometimes
> get the following during shut down:
> 
> [42949439.950000] qnap_ts209_power_off: triggering power-off...
> [42949439.960000] ata1: mv_err_intr: err_cause=02000020 pp_flags=0x2
> [42949439.970000] ata1: exception Emask 0x10 SAct 0x0 SErr 0x190002 action 0xe fro
> 
> I never got this with 2.6.25.  With 2.6.26-rc1 I get this message from
> time to time, but not always.  The disk spins down properly.  I think
> it wants to print a 3rd line because once it was printed "[42949439"
> once but the machine got shut off because the full line was printed.
> 
> <tries some more>
> 
> I just got:
> 
> [42949421.700000] qnap_ts209_power_off: triggering power-off...
> [42949421.710000] ata1: mv_err_intr: err_cause=02000020 pp_flags=0x2
> [42949421.720000] ata1: exception Emask 0x10 SAct 0x0 SErr 0x190002 action 0xe frozen
> [42949421.720000] ata1: edma_err_cause=02000020 pp_flags
> 
> Any idea?
..

Nothing harmful -- the SATA link is reporting that something weird
happened on the drive end: perhaps the drive was powered down or something?

The code that triggers this was fixed up more after -rc1, so if you can
still get messages like that with, say -rc2 or later, then please post them.

cheers

Re: sata_mv on Orion: mv_err_intr when shutting down

[Martin Michlmayr]

* Mark Lord <liml@rtr.ca> [2008-05-12 11:39]:
> Nothing harmful -- the SATA link is reporting that something weird
> happened on the drive end: perhaps the drive was powered down or something?

It happens on shut down, so yes, the drive is being powered down at
this point.

> The code that triggers this was fixed up more after -rc1, so if you can
> still get messages like that with, say -rc2 or later, then please post them.

Cool.  I'll let you know in case the message doesn't go away with rc2.
-- 
Martin Michlmayr
http://www.cyrius.com/

Re: sata_mv on Orion: mv_err_intr when shutting down

[Martin Michlmayr]

* Martin Michlmayr <tbm@cyrius.com> [2008-05-12 17:46]:
> > The code that triggers this was fixed up more after -rc1, so if you can
> > still get messages like that with, say -rc2 or later, then please post them.
> 
> Cool.  I'll let you know in case the message doesn't go away with rc2.

I still get the same message with rc2.

-- 
Martin Michlmayr
http://www.cyrius.com/

Re: sata_mv on Orion: mv_err_intr when shutting down

[Martin Michlmayr]

* Martin Michlmayr <tbm@cyrius.com> [2008-05-12 21:15]:
> * Martin Michlmayr <tbm@cyrius.com> [2008-05-12 17:46]:
> > > The code that triggers this was fixed up more after -rc1, so if you can
> > > still get messages like that with, say -rc2 or later, then please post them.
> > 
> > Cool.  I'll let you know in case the message doesn't go away with rc2.
> 
> I still get the same message with rc2.

Just saw it again with 2.6.26-rc6:

[42949509.440000] Power down.
[42949509.440000] qnap_ts209_power_off: triggering power-off...
[42949509.460000] ata1: exception Emask 0x10 SAct 0x0 SErr 0x190002 action 0xe frozen
[42949509.460000] ata1: edma_err_cause=02000020 pp_f

-- 
Martin Michlmayr
http://www.cyrius.com/

Re: sata_mv on Orion: mv_err_intr when shutting down

[Mark Lord]

Martin Michlmayr wrote:
> * Martin Michlmayr <tbm@cyrius.com> [2008-05-12 21:15]:
>> * Martin Michlmayr <tbm@cyrius.com> [2008-05-12 17:46]:
>>>> The code that triggers this was fixed up more after -rc1, so if you can
>>>> still get messages like that with, say -rc2 or later, then please post them.
>>> Cool.  I'll let you know in case the message doesn't go away with rc2.
>> I still get the same message with rc2.
> 
> Just saw it again with 2.6.26-rc6:
> 
> [42949509.440000] Power down.
> [42949509.440000] qnap_ts209_power_off: triggering power-off...
> [42949509.460000] ata1: exception Emask 0x10 SAct 0x0 SErr 0x190002 action 0xe frozen
> [42949509.460000] ata1: edma_err_cause=02000020 pp_f
..

Mmm.. I don't know how this can happen, even if it does happen.
Unless perhaps the plaform code doesn't do a (driver).remove() call,
which is where we disable the interrupt you see above.

This *is* a "platform" (non-PCI) device, right?

That being the case, can you stick a printk() into mv_platform_remove()
so we can see whether or not it gets called before "power down" ?

Something like this:

--- old/drivers/ata/sata_mv.c	2008-05-30 19:36:52.000000000 -0400
+++ linux/drivers/ata/sata_mv.c	2008-06-13 08:42:02.000000000 -0400
@@ -3186,6 +3186,7 @@
 	struct mv_host_priv *hpriv;
 	struct resource *res;
 	int n_ports, rc;
+	printk(KERN_INFO "%s(%p)\n", __func__, pdev);
 
 	if (!printed_version++)
 		dev_printk(KERN_INFO, &pdev->dev, "version " DRV_VERSION "\n");
@@ -3258,7 +3259,9 @@
 	struct device *dev = &pdev->dev;
 	struct ata_host *host = dev_get_drvdata(dev);
 
+	printk(KERN_INFO "%s(%p) enter\n", __func__, pdev);
 	ata_host_detach(host);
+	printk(KERN_INFO "%s(%p) exit\n", __func__, pdev);
 	return 0;
 }
 

Re: sata_mv on Orion: mv_err_intr when shutting down

[Frans Pop]

Hello Mark,

Martin forwarded your mail to me as I'm seeing the same/similar issue on
my QNAP TS-109 running arm 2.6.26-rc6 (old ABI).

On Friday 13 June 2008, Mark Lord wrote:
> Mmm.. I don't know how this can happen, even if it does happen.
> Unless perhaps the plaform code doesn't do a (driver).remove() call,
> which is where we disable the interrupt you see above.
>
> This *is* a "platform" (non-PCI) device, right?

With your debug patch included, I get on boot:

console [ttyS0] enabled
serial8250.0: ttyS1 at MMIO 0xf1012100 (irq = 4) is a 16550A
brd: module loaded
Driver 'sd' needs updating - please use bus_type methods
mv_platform_probe(c02ec910)
sata_mv sata_mv.0: version 1.24
sata_mv sata_mv.0: slots 32 ports 2
scsi0 : sata_mv
scsi1 : sata_mv
ata1: SATA max UDMA/133 irq 29
ata2: SATA max UDMA/133 irq 29
ata1: SATA link up 1.5 Gbps (SStatus 113 SControl 300)
ata1.00: ATA-7: HDT722516DLA380, V43OA91A, max UDMA/133
ata1.00: 321672960 sectors, multi 0: LBA48 NCQ (depth 31/32)
ata1.00: configured for UDMA/133
ata2: SATA link down (SStatus 0 SControl 300)
scsi 0:0:0:0: Direct-Access     ATA      HDT722516DLA380  V43O PQ: 0 ANSI: 5
sd 0:0:0:0: [sda] 321672960 512-byte hardware sectors (164697 MB)
sd 0:0:0:0: [sda] Write Protect is off
sd 0:0:0:0: [sda] Write cache: enabled, read cache: enabled, doesn't support DPO or FUA
sd 0:0:0:0: [sda] 321672960 512-byte hardware sectors (164697 MB)
sd 0:0:0:0: [sda] Write Protect is off
sd 0:0:0:0: [sda] Write cache: enabled, read cache: enabled, doesn't support DPO or FUA
 sda: sda1 sda2 < sda5 sda6 >
sd 0:0:0:0: [sda] Attached SCSI disk
sd 0:0:0:0: Attached scsi generic sg0 type 0

Which has your 'mv_platform_probe(c02ec910)'

> That being the case, can you stick a printk() into mv_platform_remove()
> so we can see whether or not it gets called before "power down" ?

But on poweroff:

Will now halt.
sd 0:0:0:0: [sda] Synchronizing SCSI cache
sd 0:0:0:0: [sda] Stopping disk
Power down.
qnap_ts209_power_off: triggering power-off...
ata1: exception Emask 0�

So no sign of anything getting called here.

Cheers,
FJP

Re: sata_mv on Orion: mv_err_intr when shutting down

[Mark Lord]

Frans Pop wrote:
> Hello Mark,
> 
> Martin forwarded your mail to me as I'm seeing the same/similar issue on
> my QNAP TS-109 running arm 2.6.26-rc6 (old ABI).
> 
> On Friday 13 June 2008, Mark Lord wrote:
>> Mmm.. I don't know how this can happen, even if it does happen.
>> Unless perhaps the plaform code doesn't do a (driver).remove() call,
>> which is where we disable the interrupt you see above.
>>
>> This *is* a "platform" (non-PCI) device, right?
> 
> With your debug patch included, I get on boot:
> 
> console [ttyS0] enabled
> serial8250.0: ttyS1 at MMIO 0xf1012100 (irq = 4) is a 16550A
> brd: module loaded
> Driver 'sd' needs updating - please use bus_type methods
> mv_platform_probe(c02ec910)
> sata_mv sata_mv.0: version 1.24
> sata_mv sata_mv.0: slots 32 ports 2
> scsi0 : sata_mv
> scsi1 : sata_mv
> ata1: SATA max UDMA/133 irq 29
> ata2: SATA max UDMA/133 irq 29
> ata1: SATA link up 1.5 Gbps (SStatus 113 SControl 300)
> ata1.00: ATA-7: HDT722516DLA380, V43OA91A, max UDMA/133
> ata1.00: 321672960 sectors, multi 0: LBA48 NCQ (depth 31/32)
> ata1.00: configured for UDMA/133
> ata2: SATA link down (SStatus 0 SControl 300)
> scsi 0:0:0:0: Direct-Access     ATA      HDT722516DLA380  V43O PQ: 0 ANSI: 5
> sd 0:0:0:0: [sda] 321672960 512-byte hardware sectors (164697 MB)
> sd 0:0:0:0: [sda] Write Protect is off
> sd 0:0:0:0: [sda] Write cache: enabled, read cache: enabled, doesn't support DPO or FUA
> sd 0:0:0:0: [sda] 321672960 512-byte hardware sectors (164697 MB)
> sd 0:0:0:0: [sda] Write Protect is off
> sd 0:0:0:0: [sda] Write cache: enabled, read cache: enabled, doesn't support DPO or FUA
>  sda: sda1 sda2 < sda5 sda6 >
> sd 0:0:0:0: [sda] Attached SCSI disk
> sd 0:0:0:0: Attached scsi generic sg0 type 0
> 
> Which has your 'mv_platform_probe(c02ec910)'
> 
>> That being the case, can you stick a printk() into mv_platform_remove()
>> so we can see whether or not it gets called before "power down" ?
> 
> But on poweroff:
> 
> Will now halt.
> sd 0:0:0:0: [sda] Synchronizing SCSI cache
> sd 0:0:0:0: [sda] Stopping disk
> Power down.
> qnap_ts209_power_off: triggering power-off...
> ata1: exception Emask 0�
> 
> So no sign of anything getting called here.
..

Mmm.. I suppose .remove() is not supposed to be called, then.
What does happen, is sd_shutdown() runs ("Stopping disk"),
and that's that.

Weird.  I'd have thought there'd be a call somewhere to .port_stop()
or even .host_stop() on shutdown, but I don't see one anywhere.

Tejun?
Don't we try and turn off the hardware (IRQs) after stopping the drives?
Because these guys are seeing interrupts afterwards (loss of PHY, it seems),
and that looks somewhat risky -- such an interrupt might kill the shutdown sequence,
leaving a machine in limbo.  Or not (?).

-ml

Re: sata_mv on Orion: mv_err_intr when shutting down

[Frans Pop]

On Friday 13 June 2008, Mark Lord wrote:
> > But on poweroff:
> >
> > Will now halt.
> > sd 0:0:0:0: [sda] Synchronizing SCSI cache
> > sd 0:0:0:0: [sda] Stopping disk
> > Power down.
> > qnap_ts209_power_off: triggering power-off...
> > ata1: exception Emask 0�
> >
> > So no sign of anything getting called here.
>
> Mmm.. I suppose .remove() is not supposed to be called, then.
> What does happen, is sd_shutdown() runs ("Stopping disk"),
> and that's that.
>
> Weird.  I'd have thought there'd be a call somewhere to .port_stop()
> or even .host_stop() on shutdown, but I don't see one anywhere.

One additional note: this does look like a regression from 2.6.25 which 
does _not_ show the last line on poweroff.

Re: sata_mv on Orion: mv_err_intr when shutting down

[Nicolas Pitre]

On Fri, 13 Jun 2008, Frans Pop wrote:

> On Friday 13 June 2008, Mark Lord wrote:
> > > But on poweroff:
> > >
> > > Will now halt.
> > > sd 0:0:0:0: [sda] Synchronizing SCSI cache
> > > sd 0:0:0:0: [sda] Stopping disk
> > > Power down.
> > > qnap_ts209_power_off: triggering power-off...
> > > ata1: exception Emask 0???
> > >
> > > So no sign of anything getting called here.
> >
> > Mmm.. I suppose .remove() is not supposed to be called, then.
> > What does happen, is sd_shutdown() runs ("Stopping disk"),
> > and that's that.
> >
> > Weird.  I'd have thought there'd be a call somewhere to .port_stop()
> > or even .host_stop() on shutdown, but I don't see one anywhere.
> 
> One additional note: this does look like a regression from 2.6.25 which 
> does _not_ show the last line on poweroff.

FWIW, I also see that partial "exception Emask"message whenever power to 
the device is abruptly removed.


Nicolas

Re: sata_mv on Orion: mv_err_intr when shutting down

[Mark Lord]

Nicolas Pitre wrote:
..
> FWIW, I also see that partial "exception Emask"message whenever power to 
> the device is abruptly removed.
..

Well, yes, you should see it.  That's what it is telling us ("power lost").

It's just kind of odd (but thus far harmless) to also see it at shutdown.
This indicates that the drive is being powered off
before the CPU is powered off -- perhaps a peculiarity of the platform ?

Cheers

Re: sata_mv on Orion: mv_err_intr when shutting down

[Nicolas Pitre]

On Fri, 13 Jun 2008, Mark Lord wrote:

> Nicolas Pitre wrote:
> ..
> > FWIW, I also see that partial "exception Emask"message whenever power to the
> > device is abruptly removed.
> ..
> 
> Well, yes, you should see it.  That's what it is telling us ("power lost").
> 
> It's just kind of odd (but thus far harmless) to also see it at shutdown.
> This indicates that the drive is being powered off
> before the CPU is powered off -- perhaps a peculiarity of the platform ?

It is well possible that the CPU is able to survive a few 
additional milliseconds on thin air after main power is out.


Nicolas

Re: sata_mv on Orion: mv_err_intr when shutting down

[Tejun Heo]

Mark Lord wrote:
> Mmm.. I suppose .remove() is not supposed to be called, then.
> What does happen, is sd_shutdown() runs ("Stopping disk"),
> and that's that.
> 
> Weird.  I'd have thought there'd be a call somewhere to .port_stop()
> or even .host_stop() on shutdown, but I don't see one anywhere.
> 
> Tejun?
> Don't we try and turn off the hardware (IRQs) after stopping the drives?
> Because these guys are seeing interrupts afterwards (loss of PHY, it
> seems),
> and that looks somewhat risky -- such an interrupt might kill the
> shutdown sequence,
> leaving a machine in limbo.  Or not (?).

We don't call port or host stop during shutdown.  We only do so when the
controller goes away or the module is being unloaded.  All that happens
is spinning down the disks via sd_shutdown().  I don't think drivers are
supposed to put everything into quiesced state when shutting down.  The
system can remain in working state except for ones which require special
care.

The interesting thing here is that sata_mv can see the disk going off
the power, which is kind of cool.  The controller and CPU are watching
itself as it goes off the life support and is drifting awaaaaaayyyy.

The PSU has switched off and power to the drive was cut.  I don't think
anything can go wrong at that point.

Thanks.

-- 
tejun

Re: sata_mv on Orion: mv_err_intr when shutting down

[Frans Pop]

On Sunday 15 June 2008, Tejun Heo wrote:
> The interesting thing here is that sata_mv can see the disk going off
> the power, which is kind of cool.  The controller and CPU are watching
> itself as it goes off the life support and is drifting awaaaaaayyyy.
>
> The PSU has switched off and power to the drive was cut.  I don't think
> anything can go wrong at that point.

What I still find most interesting is that with 2.6.25 the extra 
message(s) do not appear and the poweroff is "clean". And that it affects 
2 different systems where one seems to live on just a bit longer than the 
other. So it does look as if something _has_ changed.

I'll probably do a bisect to see if I can discover what/where/why...

Cheers,
FJP

Re: sata_mv on Orion: mv_err_intr when shutting down

[Byron Bradley]

On Sun, Jun 15, 2008 at 10:41 AM, Frans Pop <elendil@planet.nl> wrote:
> On Sunday 15 June 2008, Tejun Heo wrote:
>> The interesting thing here is that sata_mv can see the disk going off
>> the power, which is kind of cool.  The controller and CPU are watching
>> itself as it goes off the life support and is drifting awaaaaaayyyy.
>>
>> The PSU has switched off and power to the drive was cut.  I don't think
>> anything can go wrong at that point.
>
> What I still find most interesting is that with 2.6.25 the extra
> message(s) do not appear and the poweroff is "clean". And that it affects
> 2 different systems where one seems to live on just a bit longer than the
> other. So it does look as if something _has_ changed.

I'm not sure you can actually rely on that. lb_worm had the same
problem back in December [0].

[0] http://buffalo.nas-central.org/forums/viewtopic.php?f=18&t=4242&p=43161#p43161

Cheers,

-- 
Byron Bradley

Re: sata_mv on Orion: mv_err_intr when shutting down

[Mark Lord]

Frans Pop wrote:
> On Sunday 15 June 2008, Tejun Heo wrote:
>> The interesting thing here is that sata_mv can see the disk going off
>> the power, which is kind of cool.  The controller and CPU are watching
>> itself as it goes off the life support and is drifting awaaaaaayyyy.
>>
>> The PSU has switched off and power to the drive was cut.  I don't think
>> anything can go wrong at that point.
> 
> What I still find most interesting is that with 2.6.25 the extra 
> message(s) do not appear and the poweroff is "clean". And that it affects 
> 2 different systems where one seems to live on just a bit longer than the 
> other. So it does look as if something _has_ changed.
> 
> I'll probably do a bisect to see if I can discover what/where/why...
..

Sure, go for it.

But I think that you will simply discover that,
the sata_mv driver now actually correctly detects/reports most errors,
which it didn't necessarily do in the past.

There were lots of EH bugfixes in sata_mv this time around.

Cheers

Re: sata_mv on Orion: mv_err_intr when shutting down

[Martin Michlmayr]

Just got a more complete error this time in case this is of interest:

[42949696.850000] qnap_tsx09_power_off: triggering power-off...
[42949696.860000] ata1: exception Emask 0x10 SAct 0x0 SErr 0x180000 action 0x6 frozen
[42949696.870000] ata1: edma_err_cause=02000020 pp_flags=00000002, SError=00180000
[42949696.880000] ata1: SError: { 10B8B Dispar }
[42949696.880000] ata1: hard resetting link

-- 
Martin Michlmayr
http://www.cyrius.com/