[Regression?] qemu-system-arm flooding "sd_write_data: not in Receiving-Data state"

[Regression?] qemu-system-arm flooding "sd_write_data: not in Receiving-Data state"

[John Stultz]

(Forgive the duplicate, I forgot to cc lkml)

I was testing v3.15-rc1 in my qemu-system-arm environment and noticed a
flood of the following messages:
    sd_write_data: not in Receiving-Data state

After looking around in the kernel and not finding such a message, I
realized this was actually a message from qemu, not the kernel.

The system seems to boot normally, but is just very noisy w/ the qemu
messages.

Not sure if this is really a problem with qemu-system-arm, but this
doesn't occur w/ 3.14 and previous kernels.

Bisecting it down pointed to:

commit e7f3d22289e4307b3071cc18b1d8ecc6598c0be4
Author: Ulf Hansson <ulf.hansson@linaro.org>
Date:   Fri Jan 10 14:51:42 2014 +0100

    mmc: mmci: Handle CMD irq before DATA irq
        In case of a read operation both MCI_CMDRESPEND and MCI_DATAEND
can be
    set in the status register when entering the interrupt handler. This is
    due to that the card start sending data before the host has
    acknowledged the command response.
        To resolve the issue for this scenario, we must start by
handling the
    CMD irq instead of the DATA irq. The reason is beacuse the completion
    of the DATA irq will not respect the current command and then causing
    it to be garbled.
        Cc: Russell King <linux@arm.linux.org.uk>
    Cc: Johan Rudholm <jrudholm@gmail.com>
    Signed-off-by: Ulf Hansson <ulf.hansson@linaro.org>
    Signed-off-by: Chris Ball <chris@printf.net>




$ qemu-system-arm -version
QEMU emulator version 1.5.0 (Debian 1.5.0+dfsg-3ubuntu5.3), Copyright
(c) 2003-2008 Fabrice Bellard

Booting w/:
qemu-system-arm -kernel zImage-arm -M vexpress-a9 -cpu cortex-a9
-nographic -m 1024  -append 'root=/dev/mmcblk0p2 rw mem=1024M
raid=noautodetect console=ttyAMA0,38400n8 rootwait vmalloc=256MB
devtmpfs.mount=0' -sd test-arm.img -redir tcp:4300::22

Let me know if you have any other questions or need any other info to
help trouble-shoot this.

thanks
-john

Re: [Regression?] qemu-system-arm flooding "sd_write_data: not in Receiving-Data state"

[Ulf Hansson]

On 15 April 2014 02:28, John Stultz <john.stultz@linaro.org> wrote:
> (Forgive the duplicate, I forgot to cc lkml)
>
> I was testing v3.15-rc1 in my qemu-system-arm environment and noticed a
> flood of the following messages:
>     sd_write_data: not in Receiving-Data state
>
> After looking around in the kernel and not finding such a message, I
> realized this was actually a message from qemu, not the kernel.
>
> The system seems to boot normally, but is just very noisy w/ the qemu
> messages.
>
> Not sure if this is really a problem with qemu-system-arm, but this
> doesn't occur w/ 3.14 and previous kernels.
>
> Bisecting it down pointed to:
>
> commit e7f3d22289e4307b3071cc18b1d8ecc6598c0be4
> Author: Ulf Hansson <ulf.hansson@linaro.org>
> Date:   Fri Jan 10 14:51:42 2014 +0100
>
>     mmc: mmci: Handle CMD irq before DATA irq
>         In case of a read operation both MCI_CMDRESPEND and MCI_DATAEND
> can be
>     set in the status register when entering the interrupt handler. This is
>     due to that the card start sending data before the host has
>     acknowledged the command response.
>         To resolve the issue for this scenario, we must start by
> handling the
>     CMD irq instead of the DATA irq. The reason is beacuse the completion
>     of the DATA irq will not respect the current command and then causing
>     it to be garbled.
>         Cc: Russell King <linux@arm.linux.org.uk>
>     Cc: Johan Rudholm <jrudholm@gmail.com>
>     Signed-off-by: Ulf Hansson <ulf.hansson@linaro.org>
>     Signed-off-by: Chris Ball <chris@printf.net>
>

Hi John,

Just some more background to the patch; it resolves a race condition
in the IRQ handler for the mmci driver. A quite simple patch which
thus seems to trigger an issue for the qemu-system-arm model. I
haven't seen this on real hardware, at least yet. :-)

>
>
> $ qemu-system-arm -version
> QEMU emulator version 1.5.0 (Debian 1.5.0+dfsg-3ubuntu5.3), Copyright
> (c) 2003-2008 Fabrice Bellard
>
> Booting w/:
> qemu-system-arm -kernel zImage-arm -M vexpress-a9 -cpu cortex-a9
> -nographic -m 1024  -append 'root=/dev/mmcblk0p2 rw mem=1024M
> raid=noautodetect console=ttyAMA0,38400n8 rootwait vmalloc=256MB
> devtmpfs.mount=0' -sd test-arm.img -redir tcp:4300::22
>
> Let me know if you have any other questions or need any other info to
> help trouble-shoot this.

I am quite new to the qemu-system-arm model, I will need to spend some
time with it to be able to help out more.

Though, maybe you can provide me with some information about the qemu
environment you are using?

1. Especially, what variant of the ARM primcell pl180 is being
modelled/used here? The mmci driver handles a handful of different
variants.
2. What type of mmc/sd card is being modelled/used here?

Kind regards
Ulf Hansson

>
> thanks
> -john

Re: [Regression?] qemu-system-arm flooding "sd_write_data: not in Receiving-Data state"

[John Stultz]

On 04/15/2014 12:26 AM, Ulf Hansson wrote:
> On 15 April 2014 02:28, John Stultz <john.stultz@linaro.org> wrote:
>> $ qemu-system-arm -version
>> QEMU emulator version 1.5.0 (Debian 1.5.0+dfsg-3ubuntu5.3), Copyright
>> (c) 2003-2008 Fabrice Bellard
>>
>> Booting w/:
>> qemu-system-arm -kernel zImage-arm -M vexpress-a9 -cpu cortex-a9
>> -nographic -m 1024  -append 'root=/dev/mmcblk0p2 rw mem=1024M
>> raid=noautodetect console=ttyAMA0,38400n8 rootwait vmalloc=256MB
>> devtmpfs.mount=0' -sd test-arm.img -redir tcp:4300::22
>>
>> Let me know if you have any other questions or need any other info to
>> help trouble-shoot this.
> I am quite new to the qemu-system-arm model, I will need to spend some
> time with it to be able to help out more.
>
> Though, maybe you can provide me with some information about the qemu
> environment you are using?
>
> 1. Especially, what variant of the ARM primcell pl180 is being
> modelled/used here? The mmci driver handles a handful of different
> variants.

Not totally sure, honestly.

>From dmesg, the mmc related messages are:
mmci-pl18x mb:mmci: mmc0: PL181 manf 41 rev0 at 0x10005000 irq 41,42 (pio)
mmc0: new SDHC card at address 4567
mmcblk0: mmc0:4567 QEMU! 2.00 GiB
mmcblk0: p1 p2 p3 p4 < p5 p6 >


> 2. What type of mmc/sd card is being modelled/used here?

Not sure, other then if the SDHC bit above is enlightening. Is there
some other debug info (from sysfs or something) I can get to you to
answer these better?

I can also provide a .config and point you to similar disk images as I'm
using so you can reproduce if you'd like.

thanks
-john

Re: [Regression?] qemu-system-arm flooding "sd_write_data: not in Receiving-Data state"

[Peter Maydell]

On 15 April 2014 08:26, Ulf Hansson <ulf.hansson@linaro.org> wrote:
> Though, maybe you can provide me with some information about the qemu
> environment you are using?
>
> 1. Especially, what variant of the ARM primcell pl180 is being
> modelled/used here? The mmci driver handles a handful of different
> variants.

QEMU's device modelling is not generally sufficiently accurate
to make this a very meaningful question :-) We model a PL181,
but we will inevitably behave differently from h/w one way or another.
(Most notably, data read/write operations will complete instantaneously,
whereas on real h/w there's always some delay. There's also a hack
in the pl181 model working around a Linux 2.6.x driver bug:
    /* The linux 2.6.21 driver is buggy, and misbehaves if new data arrives
       while it is reading the FIFO.  We hack around this be defering
       subsequent transfers until after the driver polls the status word.
       http://www.arm.linux.org.uk/developer/patches/viewpatch.php?id=4446/1
     */
I hate those, because once they get into QEMU it's very hard
to get them back out again...)

> 2. What type of mmc/sd card is being modelled/used here?

The comment at the top of the source file says "as defined in the
"SD Memory Card Physical layer specification, Version 1.10."
It might even still be accurate...

The message from QEMU indicates that the SD card model's
state machine thinks that it should not be receiving data but
it has just got a pile of data from the pl181. The obvious guess
is that what you did in the CMD irq handling has moved it from
"ok for data" to something else.

Beyond that, somebody would need to reproduce with a newer
QEMU than 1.5.0 and enable debugging printfs in the kernel
and the model to figure out what the interaction is here.
Chances are quite high that this is a QEMU model bug, but it's
not 100% :-)

thanks
-- PMM