Re: [PATCH] mmc/sdio: don't allow interface to runtime-suspenduntil probe is finished.

From: NeilBrown
Date: Thu Dec 15 2011 - 23:08:42 EST

Next message: Rik van Riel: "Re: [PATCH 07/11] mm: page allocator: Do not call direct reclaimfor THP allocations while compaction is deferred"
Previous message: Frank Rowand: "adding cc to stable-rt: [PATCH] PREEMPT_RT_FULL: ARM context switchneeds IRQs enabled"
In reply to: Bing Zhao: "RE: [PATCH] mmc/sdio: don't allow interface to runtime-suspenduntil probe is finished."
Next in thread: Bing Zhao: "RE: [PATCH] mmc/sdio: don't allow interface to runtime-suspenduntil probe is finished."
Messages sorted by: [ date ] [ thread ] [ subject ] [ author ]

On Sun, 11 Dec 2011 09:30:48 +0200 Ohad Ben-Cohen <ohad@xxxxxxxxxx> wrote:

> On Sat, Dec 10, 2011 at 9:15 AM, NeilBrown <neilb@xxxxxxx> wrote:
> > When I force it to hold off suspend for a little while I see (starting at the
> > same place):
> >
> > [ Â656.189697] bus: 'sdio': driver_probe_device: matched device mmc1:0001:1 with driver libertas_sdio
> > [ Â656.212768] bus: 'sdio': really_probe: probing driver libertas_sdio with device mmc1:0001:1
> > [ Â656.247741] libertas_sdio mmc1:0001:1: firmware: requesting libertas/sd8686_v9_helper.bin
> > [ Â656.257537] device: 'mmc1:0001:1': device_add
> > [ Â656.263580] PM: Adding info for No Bus:mmc1:0001:1
> > [ Â656.298187] device: 'mmc1:0001:1': device_unregister
> > [ Â656.303375] PM: Removing info for No Bus:mmc1:0001:1
> > [ Â656.322967] libertas_sdio mmc1:0001:1: firmware: requesting libertas/sd8686_v8_helper.bin
> > [ Â656.344207] device: 'mmc1:0001:1': device_add
> > [ Â656.357147] PM: Adding info for No Bus:mmc1:0001:1
> > [ Â656.395782] device: 'mmc1:0001:1': device_unregister
> > [ Â656.407409] PM: Removing info for No Bus:mmc1:0001:1
> > [ Â656.418579] libertas_sdio mmc1:0001:1: firmware: requesting sd8686_helper.bin
> > [ Â656.435699] device: 'mmc1:0001:1': device_add
> > [ Â656.446655] PM: Adding info for No Bus:mmc1:0001:1
> > [ Â656.504974] device: 'mmc1:0001:1': device_unregister
> > [ Â656.511749] PM: Removing info for No Bus:mmc1:0001:1
> > [ Â656.521148] libertas_sdio mmc1:0001:1: firmware: requesting sd8686.bin
> > [ Â656.529205] device: 'mmc1:0001:1': device_add
> > [ Â656.535095] PM: Adding info for No Bus:mmc1:0001:1
> > [ Â656.584625] device: 'mmc1:0001:1': device_unregister
> > [ Â656.591369] PM: Removing info for No Bus:mmc1:0001:1
> > [ Â657.384063] libertas_sdio mmc1:0001:1: (unregistered net_device): 00:19:88:3d:ff:f0, fw 9.70.3p24, cap 0x00000303
> > [ Â657.454467] libertas_sdio mmc1:0001:1: (unregistered net_device): PREP_CMD: command 0x00a3 failed: 2
> > [ Â657.464080] device: 'phy0': device_add
> >
> >
> > ÂBut shortly there after the extra tracing I put in shows that mmc_power_off
> > Âis called,
>
> Probably right after libertas' if_sdio_probe() returns ?

Sort-of. It is actually called from pm_runtime_work so it is an async
pm_suspend.

It is triggered by the pm_runtime_put_sync() call in driver_probe_device()
just after really_probe() is called, and it was really_probe() that ultimately
called if_sdio_probe(). So depending on what you mean by "right after"
exactly, that might describe when it happened.

>
> > then mmc_sdio_power_restore calls mmc_send_io_op_cond
>
> Is that as a result of libertas' if_sdio_power_restore() being called
> (i.e. someone/something called 'ifconfig up') ?

Probably. It is definitely if_sdio_power_restore() being called because
something did an ioctl, and that was probably wpa_supplicant trying to
configure the device.

>
> > which again
> > Âreturns -110, but now it isn't a problem and the wifi chip keeps working.
>
> if_sdio_power_restore doesn't check the return value of
> pm_runtime_get_sync, so it won't error out, but I wonder how come the
> chip still works.

That bit is still a mystery. I don't think it always works, but certainly
does some times.

I put some tracing in mmc_wait_for_command and see:

[ 69.939819] mmc_wait_for_cmd 52 -> -110
[ 69.944274] mmc_wait_for_cmd 52 -> -110
[ 69.949066] mmc_wait_for_cmd 0 -> 0
[ 69.954254] mmc_wait_for_cmd 8 -> -110
[ 69.958679] mmc_wait_for_cmd 5 -> 0
[ 69.962707] mmc_wait_for_cmd 5 -> 0
[ 69.966827] mmc_wait_for_cmd 3 -> 0
[ 69.970886] mmc_wait_for_cmd 7 -> 0
[ 69.974914] mmc_wait_for_cmd 52 -> 0
[ 69.979064] mmc_wait_for_cmd 52 -> 0
[ 69.983154] mmc_wait_for_cmd 52 -> 0
[ 69.987274] mmc_wait_for_cmd 52 -> 0

When I first try to start the wifi (turn on the regulator and assert the
card-detect).

mmc_wait_for_req(host, &mrq);
+ if (host->index == 1)
+ printk("mmc_wait_for_cmd %d -> %d\n", cmd->opcode, cmd->error);

That last line repeats every few millisecs until

[ 79.444793] mmc_wait_for_cmd 52 -> 0

about 10 seconds later (1777 repeats) when it stops.

Then when I start up wpa_supplicant I see

[ 132.313293] mmc_wait_for_cmd 52 -> 0
[ 132.317443] mmc_wait_for_cmd 52 -> 0
[ 132.321990] mmc_wait_for_cmd 0 -> 0
[ 132.327239] mmc_wait_for_cmd 8 -> -110
[ 132.332824] mmc_wait_for_cmd 5 -> -110
[ 132.337280] mmc_wait_for_cmd 52 -> 0
[ 132.341400] mmc_wait_for_cmd 52 -> 0
[ 132.345520] mmc_wait_for_cmd 52 -> 0
[ 132.349639] mmc_wait_for_cmd 52 -> 0
[ 132.353759] mmc_wait_for_cmd 52 -> 0

And the "52 -> 0" repeats indefinitely until I reboot. But at this point
wifi is working - I get a dhcp reply and can ping hosts.

In the other case where I do let it suspend early (And it never recovers
without the reset line being toggled) I see:

[ 2170.100982] mmc_wait_for_cmd 52 -> -110
[ 2170.105407] mmc_wait_for_cmd 52 -> -110
[ 2170.110260] mmc_wait_for_cmd 0 -> 0
[ 2170.115509] mmc_wait_for_cmd 8 -> -110
[ 2170.119842] mmc_wait_for_cmd 5 -> 0
[ 2170.123901] mmc_wait_for_cmd 5 -> 0
[ 2170.127929] mmc_wait_for_cmd 3 -> 0
[ 2170.131958] mmc_wait_for_cmd 7 -> 0
[ 2170.135986] mmc_wait_for_cmd 52 -> 0
[ 2170.140136] mmc_wait_for_cmd 52 -> 0
[ 2170.144226] mmc_wait_for_cmd 52 -> 0
[ 2170.148376] mmc_wait_for_cmd 52 -> 0
[ 2170.152465] mmc_wait_for_cmd 52 -> 0

which is much the same but then one second later:

[ 2171.166656] mmc_wait_for_cmd 52 -> 0
[ 2171.170806] mmc_wait_for_cmd 52 -> 0
[ 2171.175384] mmc_wait_for_cmd 0 -> 0
[ 2171.180603] mmc_wait_for_cmd 8 -> -110
[ 2171.185943] mmc_wait_for_cmd 5 -> -110
[ 2171.190093] libertas_sdio: probe of mmc1:0001:1 failed with error -16

So this answers Bing Zhao's question - it was CMD5 that timed out and caused
the failure.

If I just get mmc_wait_for_cmd to hide error -110 for cmd 5 it complains

[ 26.420440] mmc1: host doesn't support card's voltages

so that isn't a simple solution :-)

>
> > ÂSo maybe the fact that we error-out in the first case is a problem??
>
> It might be nice if Marvell could comment on this, though we can
> probably empirically deduce this too.
>
> > ÂI found that if I pull the reset line down and then let it back up then it
> > Âall works.
>
> Nice. Joe, did this work out for you too ?
>
> > So I have run out of ideas. ÂI can make it work by reseting the chip during
> > mmc_power_up but I have no idea what is causing the chip to need a reset.
>
> I wonder why the sdio reset command isn't helpful for you - it did
> seem to resolve some issues for Daniel. Maybe you have two different
> hardware revisions of the 8686 which behave differently in this
> respect ?
>
> > However for now I think I'll go with my 'remux' hack.
>
> Feel free to post it so we can take a look.
>
> Thanks,
> Ohad.

It isn't very exciting but I include it below.

The change is entirely inside my 'board' file which isn't in mainline.

I define a 'remux' function that lowers the reset line for 10msec and raises
it again. (I don't know if the 10msec is needed).
tca_setup() is a callback from the driver that enables the gpio line (it is
one pin on an LED driver chip).

NeilBrown

diff --git a/arch/arm/mach-omap2/board-omap3gta04.c b/arch/arm/mach-omap2/board-omap3gta04.c
index 8a09b98..6a13822 100644
--- a/arch/arm/mach-omap2/board-omap3gta04.c
+++ b/arch/arm/mach-omap2/board-omap3gta04.c
@@ -357,6 +357,8 @@ static struct regulator_consumer_supply gta04_vdvi_supply = {

#include "sdram-micron-mt46h32m32lf-6.h"

+static void wlan_reset(struct device *dev, int slow, int power_on);
+
static struct omap2_hsmmc_info mmc[] = {
{
.mmc = 1,
@@ -370,6 +372,7 @@ static struct omap2_hsmmc_info mmc[] = {
.gpio_cd = -EINVAL, // virtual card detect
.gpio_wp = -EINVAL, // no write protect
.transceiver = true, // external transceiver
+ .remux = wlan_reset,
// .ocr_mask = 0x00100000, /* fixed 3.3V */
},
{} /* Terminator */
@@ -769,11 +772,22 @@ struct bmp085_platform_data bmp085_info = {
/* "+2" because TWL4030 adds 2 LED drives as gpio outputs */
#define GPIO_WIFI_RESET (OMAP_MAX_GPIO_LINES + TWL4030_GPIO_MAX + 2)

+static int reset_ready;
+static void wlan_reset(struct device *dev, int slow, int power_on)
+{
+ if (power_on && reset_ready) {
+ gpio_set_value(GPIO_WIFI_RESET, 0);
+ msleep(10);
+ gpio_set_value(GPIO_WIFI_RESET, 1);
+ }
+}
+
void tca_setup(unsigned gpio_base, unsigned ngpio)
{
gpio_request(GPIO_WIFI_RESET, "WIFI_RESET");
gpio_direction_output(GPIO_WIFI_RESET, true);
gpio_export(GPIO_WIFI_RESET, 0);
+ reset_ready = 1;
}

static struct led_info tca6507_leds[] = {

Attachment: signature.asc
Description: PGP signature

Next message: Rik van Riel: "Re: [PATCH 07/11] mm: page allocator: Do not call direct reclaimfor THP allocations while compaction is deferred"
Previous message: Frank Rowand: "adding cc to stable-rt: [PATCH] PREEMPT_RT_FULL: ARM context switchneeds IRQs enabled"
In reply to: Bing Zhao: "RE: [PATCH] mmc/sdio: don't allow interface to runtime-suspenduntil probe is finished."
Next in thread: Bing Zhao: "RE: [PATCH] mmc/sdio: don't allow interface to runtime-suspenduntil probe is finished."
Messages sorted by: [ date ] [ thread ] [ subject ] [ author ]