[V2] wlcore: sdio: Fixup power on/off sequence

Commit Message

Ulf Hansson Jan. 16, 2019, 11:37 a.m. UTC

During "wlan-up", we are programming the FW into the WiFi-chip. However,
re-programming the FW doesn't work, unless a power cycle of the WiFi-chip
is made in-between the programmings.

To conform to this requirement and to fix the regression in a simple way,
let's start by allowing that the SDIO card (WiFi-chip) may stay powered on
(runtime resumed) when wl12xx_sdio_power_off() returns. The intent with the
current code is to treat this scenario as an error, but unfortunate this
doesn't work as expected, so let's fix this.

The other part is to guarantee that a power cycle of the SDIO card has been
completed when wl12xx_sdio_power_on() returns, as to allow the FW
programming to succeed. However, relying solely on runtime PM to deal with
this isn't sufficient. For example, userspace may prevent runtime suspend
via sysfs for the device that represents the SDIO card, leading to that the
mmc core also keeps it powered on. For this reason, let's instead do a
brute force power cycle in wl12xx_sdio_power_on().

Fixes: 728a9dc61f13 ("wlcore: sdio: Fix flakey SDIO runtime PM handling")
Signed-off-by: Ulf Hansson <[e-mail]>
---

Changes in v2:
	- Keep the SDIO host claimed when calling mmc_hw_reset().
	- Add a fixes tag.
---
 drivers/net/wireless/ti/wlcore/sdio.c | 15 +++++++--------
 1 file changed, 7 insertions(+), 8 deletions(-)

Comments

Tony Lindgren Jan. 16, 2019, 3:43 p.m. UTC | #1

* Ulf Hansson <[e-mail]> [190116 11:37]:
> During "wlan-up", we are programming the FW into the WiFi-chip. However,
> re-programming the FW doesn't work, unless a power cycle of the WiFi-chip
> is made in-between the programmings.
> 
> To conform to this requirement and to fix the regression in a simple way,
> let's start by allowing that the SDIO card (WiFi-chip) may stay powered on
> (runtime resumed) when wl12xx_sdio_power_off() returns. The intent with the
> current code is to treat this scenario as an error, but unfortunate this
> doesn't work as expected, so let's fix this.
> 
> The other part is to guarantee that a power cycle of the SDIO card has been
> completed when wl12xx_sdio_power_on() returns, as to allow the FW
> programming to succeed. However, relying solely on runtime PM to deal with
> this isn't sufficient. For example, userspace may prevent runtime suspend
> via sysfs for the device that represents the SDIO card, leading to that the
> mmc core also keeps it powered on. For this reason, let's instead do a
> brute force power cycle in wl12xx_sdio_power_on().
> 
> Fixes: 728a9dc61f13 ("wlcore: sdio: Fix flakey SDIO runtime PM handling")
> Signed-off-by: Ulf Hansson <[e-mail]>
> ---
> 
> Changes in v2:
> 	- Keep the SDIO host claimed when calling mmc_hw_reset().
> 	- Add a fixes tag.

This v2 version works for me as tested with:

# while [ 1 ]; do ifconfig wlan0 down; ifconfig wlan0 up; done
[  181.364990] wlcore: down
[  182.116424] wlcore: firmware booted (Rev 6.3.10.0.141)
[  182.151641] IPv6: ADDRCONF(NETDEV_UP): wlan0: link is not ready
[  182.166778] wlcore: down
[  182.773132] wlcore: firmware booted (Rev 6.3.10.0.141)
[  182.811096] IPv6: ADDRCONF(NETDEV_UP): wlan0: link is not ready
...

Thanks for fixing this issue properly, and feel free to add:

Tested-by: Tony Lindgren <[e-mail]>

Ulf Hansson Jan. 16, 2019, 3:48 p.m. UTC | #2

On Wed, 16 Jan 2019 at 16:43, Tony Lindgren <[e-mail]> wrote:
>
> * Ulf Hansson <[e-mail]> [190116 11:37]:
> > During "wlan-up", we are programming the FW into the WiFi-chip. However,
> > re-programming the FW doesn't work, unless a power cycle of the WiFi-chip
> > is made in-between the programmings.
> >
> > To conform to this requirement and to fix the regression in a simple way,
> > let's start by allowing that the SDIO card (WiFi-chip) may stay powered on
> > (runtime resumed) when wl12xx_sdio_power_off() returns. The intent with the
> > current code is to treat this scenario as an error, but unfortunate this
> > doesn't work as expected, so let's fix this.
> >
> > The other part is to guarantee that a power cycle of the SDIO card has been
> > completed when wl12xx_sdio_power_on() returns, as to allow the FW
> > programming to succeed. However, relying solely on runtime PM to deal with
> > this isn't sufficient. For example, userspace may prevent runtime suspend
> > via sysfs for the device that represents the SDIO card, leading to that the
> > mmc core also keeps it powered on. For this reason, let's instead do a
> > brute force power cycle in wl12xx_sdio_power_on().
> >
> > Fixes: 728a9dc61f13 ("wlcore: sdio: Fix flakey SDIO runtime PM handling")
> > Signed-off-by: Ulf Hansson <[e-mail]>
> > ---
> >
> > Changes in v2:
> >       - Keep the SDIO host claimed when calling mmc_hw_reset().
> >       - Add a fixes tag.
>
> This v2 version works for me as tested with:
>
> # while [ 1 ]; do ifconfig wlan0 down; ifconfig wlan0 up; done
> [  181.364990] wlcore: down
> [  182.116424] wlcore: firmware booted (Rev 6.3.10.0.141)
> [  182.151641] IPv6: ADDRCONF(NETDEV_UP): wlan0: link is not ready
> [  182.166778] wlcore: down
> [  182.773132] wlcore: firmware booted (Rev 6.3.10.0.141)
> [  182.811096] IPv6: ADDRCONF(NETDEV_UP): wlan0: link is not ready
> ...
>
> Thanks for fixing this issue properly, and feel free to add:
>
> Tested-by: Tony Lindgren <[e-mail]>

Thanks for testing, great news!

Before queuing this as fix, let's also see what the Hikey folkz thinks
of this. I have pinged Anders and he is currently running a test
suite.

Kalle, can you please tag this for stable as well?

Kind regards
Uffe

Kalle Valo Jan. 16, 2019, 4:18 p.m. UTC | #3

Ulf Hansson <[e-mail]> writes:

> On Wed, 16 Jan 2019 at 16:43, Tony Lindgren <[e-mail]> wrote:
>>
>> * Ulf Hansson <[e-mail]> [190116 11:37]:
>> > During "wlan-up", we are programming the FW into the WiFi-chip. However,
>> > re-programming the FW doesn't work, unless a power cycle of the WiFi-chip
>> > is made in-between the programmings.
>> >
>> > To conform to this requirement and to fix the regression in a simple way,
>> > let's start by allowing that the SDIO card (WiFi-chip) may stay powered on
>> > (runtime resumed) when wl12xx_sdio_power_off() returns. The intent with the
>> > current code is to treat this scenario as an error, but unfortunate this
>> > doesn't work as expected, so let's fix this.
>> >
>> > The other part is to guarantee that a power cycle of the SDIO card has been
>> > completed when wl12xx_sdio_power_on() returns, as to allow the FW
>> > programming to succeed. However, relying solely on runtime PM to deal with
>> > this isn't sufficient. For example, userspace may prevent runtime suspend
>> > via sysfs for the device that represents the SDIO card, leading to that the
>> > mmc core also keeps it powered on. For this reason, let's instead do a
>> > brute force power cycle in wl12xx_sdio_power_on().
>> >
>> > Fixes: 728a9dc61f13 ("wlcore: sdio: Fix flakey SDIO runtime PM handling")
>> > Signed-off-by: Ulf Hansson <[e-mail]>
>> > ---
>> >
>> > Changes in v2:
>> >       - Keep the SDIO host claimed when calling mmc_hw_reset().
>> >       - Add a fixes tag.
>>
>> This v2 version works for me as tested with:
>>
>> # while [ 1 ]; do ifconfig wlan0 down; ifconfig wlan0 up; done
>> [  181.364990] wlcore: down
>> [  182.116424] wlcore: firmware booted (Rev 6.3.10.0.141)
>> [  182.151641] IPv6: ADDRCONF(NETDEV_UP): wlan0: link is not ready
>> [  182.166778] wlcore: down
>> [  182.773132] wlcore: firmware booted (Rev 6.3.10.0.141)
>> [  182.811096] IPv6: ADDRCONF(NETDEV_UP): wlan0: link is not ready
>> ...
>>
>> Thanks for fixing this issue properly, and feel free to add:
>>
>> Tested-by: Tony Lindgren <[e-mail]>
>
> Thanks for testing, great news!
>
> Before queuing this as fix, let's also see what the Hikey folkz thinks
> of this. I have pinged Anders and he is currently running a test
> suite.
>
> Kalle, can you please tag this for stable as well?

Ok, I'll queue this for 5.0 (but wait for testing feedback at least a
day) and add:

Cc: <[e-mail]>

Jan Kiszka Jan. 16, 2019, 8:26 p.m. UTC | #4

On 16.01.19 12:37, Ulf Hansson wrote:
> During "wlan-up", we are programming the FW into the WiFi-chip. However,
> re-programming the FW doesn't work, unless a power cycle of the WiFi-chip
> is made in-between the programmings.
>
> To conform to this requirement and to fix the regression in a simple way,
> let's start by allowing that the SDIO card (WiFi-chip) may stay powered on
> (runtime resumed) when wl12xx_sdio_power_off() returns. The intent with the
> current code is to treat this scenario as an error, but unfortunate this
> doesn't work as expected, so let's fix this.
>
> The other part is to guarantee that a power cycle of the SDIO card has been
> completed when wl12xx_sdio_power_on() returns, as to allow the FW
> programming to succeed. However, relying solely on runtime PM to deal with
> this isn't sufficient. For example, userspace may prevent runtime suspend
> via sysfs for the device that represents the SDIO card, leading to that the
> mmc core also keeps it powered on. For this reason, let's instead do a
> brute force power cycle in wl12xx_sdio_power_on().
>
> Fixes: 728a9dc61f13 ("wlcore: sdio: Fix flakey SDIO runtime PM handling")
> Signed-off-by: Ulf Hansson <[e-mail]>
> ---
>
> Changes in v2:
> 	- Keep the SDIO host claimed when calling mmc_hw_reset().
> 	- Add a fixes tag.
> ---
>   drivers/net/wireless/ti/wlcore/sdio.c | 15 +++++++--------
>   1 file changed, 7 insertions(+), 8 deletions(-)
>
> diff --git a/drivers/net/wireless/ti/wlcore/sdio.c b/drivers/net/wireless/ti/wlcore/sdio.c
> index bd10165d7eec..4d4b07701149 100644
> --- a/drivers/net/wireless/ti/wlcore/sdio.c
> +++ b/drivers/net/wireless/ti/wlcore/sdio.c
> @@ -164,6 +164,12 @@ static int wl12xx_sdio_power_on(struct wl12xx_sdio_glue *glue)
>   	}
>
>   	sdio_claim_host(func);
> +	/*
> +	 * To guarantee that the SDIO card is power cycled, as required to make
> +	 * the FW programming to succeed, let's do a brute force HW reset.
> +	 */
> +	mmc_hw_reset(card->host);
> +
>   	sdio_enable_func(func);
>   	sdio_release_host(func);
>
> @@ -174,20 +180,13 @@ static int wl12xx_sdio_power_off(struct wl12xx_sdio_glue *glue)
>   {
>   	struct sdio_func *func = dev_to_sdio_func(glue->dev);
>   	struct mmc_card *card = func->card;
> -	int error;
>
>   	sdio_claim_host(func);
>   	sdio_disable_func(func);
>   	sdio_release_host(func);
>
>   	/* Let runtime PM know the card is powered off */
> -	error = pm_runtime_put(&card->dev);
> -	if (error < 0 && error != -EBUSY) {
> -		dev_err(&card->dev, "%s failed: %i\n", __func__, error);
> -
> -		return error;
> -	}
> -
> +	pm_runtime_put(&card->dev);
>   	return 0;
>   }
>
>

Just tested on both HiKey (620) and Ultra96 but it fails to fix the issue on
both. I'm getting

wl1271_sdio: probe of mmc2:0001:1 failed with error -16

during boot again, and the interface is not available.

Jan

Ulf Hansson Jan. 17, 2019, 9:54 a.m. UTC | #5

On Wed, 16 Jan 2019 at 21:26, Jan Kiszka <[e-mail]> wrote:
>
> On 16.01.19 12:37, Ulf Hansson wrote:
> > During "wlan-up", we are programming the FW into the WiFi-chip. However,
> > re-programming the FW doesn't work, unless a power cycle of the WiFi-chip
> > is made in-between the programmings.
> >
> > To conform to this requirement and to fix the regression in a simple way,
> > let's start by allowing that the SDIO card (WiFi-chip) may stay powered on
> > (runtime resumed) when wl12xx_sdio_power_off() returns. The intent with the
> > current code is to treat this scenario as an error, but unfortunate this
> > doesn't work as expected, so let's fix this.
> >
> > The other part is to guarantee that a power cycle of the SDIO card has been
> > completed when wl12xx_sdio_power_on() returns, as to allow the FW
> > programming to succeed. However, relying solely on runtime PM to deal with
> > this isn't sufficient. For example, userspace may prevent runtime suspend
> > via sysfs for the device that represents the SDIO card, leading to that the
> > mmc core also keeps it powered on. For this reason, let's instead do a
> > brute force power cycle in wl12xx_sdio_power_on().
> >
> > Fixes: 728a9dc61f13 ("wlcore: sdio: Fix flakey SDIO runtime PM handling")
> > Signed-off-by: Ulf Hansson <[e-mail]>
> > ---
> >
> > Changes in v2:
> >       - Keep the SDIO host claimed when calling mmc_hw_reset().
> >       - Add a fixes tag.
> > ---
> >   drivers/net/wireless/ti/wlcore/sdio.c | 15 +++++++--------
> >   1 file changed, 7 insertions(+), 8 deletions(-)
> >
> > diff --git a/drivers/net/wireless/ti/wlcore/sdio.c b/drivers/net/wireless/ti/wlcore/sdio.c
> > index bd10165d7eec..4d4b07701149 100644
> > --- a/drivers/net/wireless/ti/wlcore/sdio.c
> > +++ b/drivers/net/wireless/ti/wlcore/sdio.c
> > @@ -164,6 +164,12 @@ static int wl12xx_sdio_power_on(struct wl12xx_sdio_glue *glue)
> >       }
> >
> >       sdio_claim_host(func);
> > +     /*
> > +      * To guarantee that the SDIO card is power cycled, as required to make
> > +      * the FW programming to succeed, let's do a brute force HW reset.
> > +      */
> > +     mmc_hw_reset(card->host);
> > +
> >       sdio_enable_func(func);
> >       sdio_release_host(func);
> >
> > @@ -174,20 +180,13 @@ static int wl12xx_sdio_power_off(struct wl12xx_sdio_glue *glue)
> >   {
> >       struct sdio_func *func = dev_to_sdio_func(glue->dev);
> >       struct mmc_card *card = func->card;
> > -     int error;
> >
> >       sdio_claim_host(func);
> >       sdio_disable_func(func);
> >       sdio_release_host(func);
> >
> >       /* Let runtime PM know the card is powered off */
> > -     error = pm_runtime_put(&card->dev);
> > -     if (error < 0 && error != -EBUSY) {
> > -             dev_err(&card->dev, "%s failed: %i\n", __func__, error);
> > -
> > -             return error;
> > -     }
> > -
> > +     pm_runtime_put(&card->dev);
> >       return 0;
> >   }
> >
> >
>
> Just tested on both HiKey (620) and Ultra96 but it fails to fix the issue on
> both. I'm getting
>
> wl1271_sdio: probe of mmc2:0001:1 failed with error -16
>
> during boot again, and the interface is not available.

Okay, sounds like this may be a different problem then. Can you share
the complete log and the kernel config?
I can prepare a debug patch as well, if you are willing to re-run the test?

Adding a post-power-on-delay-ms of 1 ms as you suggested [1], doesn't
sounds like the correct solution to me, unless I am overlooking some
things. The point is, since the mmc core succeeds to detect and
initialize the SDIO card, the power sequence seems to be correct.

Kind regards
Uffe

[1]
https://patchwork.kernel.org/patch/10745075/

Jan Kiszka Jan. 18, 2019, 12:09 p.m. UTC | #6

On 17.01.19 10:54, Ulf Hansson wrote:
> On Wed, 16 Jan 2019 at 21:26, Jan Kiszka <[e-mail]> wrote:
>>
>> On 16.01.19 12:37, Ulf Hansson wrote:
>>> During "wlan-up", we are programming the FW into the WiFi-chip. However,
>>> re-programming the FW doesn't work, unless a power cycle of the WiFi-chip
>>> is made in-between the programmings.
>>>
>>> To conform to this requirement and to fix the regression in a simple way,
>>> let's start by allowing that the SDIO card (WiFi-chip) may stay powered on
>>> (runtime resumed) when wl12xx_sdio_power_off() returns. The intent with the
>>> current code is to treat this scenario as an error, but unfortunate this
>>> doesn't work as expected, so let's fix this.
>>>
>>> The other part is to guarantee that a power cycle of the SDIO card has been
>>> completed when wl12xx_sdio_power_on() returns, as to allow the FW
>>> programming to succeed. However, relying solely on runtime PM to deal with
>>> this isn't sufficient. For example, userspace may prevent runtime suspend
>>> via sysfs for the device that represents the SDIO card, leading to that the
>>> mmc core also keeps it powered on. For this reason, let's instead do a
>>> brute force power cycle in wl12xx_sdio_power_on().
>>>
>>> Fixes: 728a9dc61f13 ("wlcore: sdio: Fix flakey SDIO runtime PM handling")
>>> Signed-off-by: Ulf Hansson <[e-mail]>
>>> ---
>>>
>>> Changes in v2:
>>>        - Keep the SDIO host claimed when calling mmc_hw_reset().
>>>        - Add a fixes tag.
>>> ---
>>>    drivers/net/wireless/ti/wlcore/sdio.c | 15 +++++++--------
>>>    1 file changed, 7 insertions(+), 8 deletions(-)
>>>
>>> diff --git a/drivers/net/wireless/ti/wlcore/sdio.c b/drivers/net/wireless/ti/wlcore/sdio.c
>>> index bd10165d7eec..4d4b07701149 100644
>>> --- a/drivers/net/wireless/ti/wlcore/sdio.c
>>> +++ b/drivers/net/wireless/ti/wlcore/sdio.c
>>> @@ -164,6 +164,12 @@ static int wl12xx_sdio_power_on(struct wl12xx_sdio_glue *glue)
>>>        }
>>>
>>>        sdio_claim_host(func);
>>> +     /*
>>> +      * To guarantee that the SDIO card is power cycled, as required to make
>>> +      * the FW programming to succeed, let's do a brute force HW reset.
>>> +      */
>>> +     mmc_hw_reset(card->host);
>>> +
>>>        sdio_enable_func(func);
>>>        sdio_release_host(func);
>>>
>>> @@ -174,20 +180,13 @@ static int wl12xx_sdio_power_off(struct wl12xx_sdio_glue *glue)
>>>    {
>>>        struct sdio_func *func = dev_to_sdio_func(glue->dev);
>>>        struct mmc_card *card = func->card;
>>> -     int error;
>>>
>>>        sdio_claim_host(func);
>>>        sdio_disable_func(func);
>>>        sdio_release_host(func);
>>>
>>>        /* Let runtime PM know the card is powered off */
>>> -     error = pm_runtime_put(&card->dev);
>>> -     if (error < 0 && error != -EBUSY) {
>>> -             dev_err(&card->dev, "%s failed: %i\n", __func__, error);
>>> -
>>> -             return error;
>>> -     }
>>> -
>>> +     pm_runtime_put(&card->dev);
>>>        return 0;
>>>    }
>>>
>>>
>>
>> Just tested on both HiKey (620) and Ultra96 but it fails to fix the issue on
>> both. I'm getting
>>
>> wl1271_sdio: probe of mmc2:0001:1 failed with error -16
>>
>> during boot again, and the interface is not available.
>
> Okay, sounds like this may be a different problem then. Can you share
> the complete log and the kernel config?

You can find the config here [1], log from the HiKey boot attached.

> I can prepare a debug patch as well, if you are willing to re-run the test?

Sure, send it over, I can run it.

>
> Adding a post-power-on-delay-ms of 1 ms as you suggested [1], doesn't
> sounds like the correct solution to me, unless I am overlooking some
> things. The point is, since the mmc core succeeds to detect and
> initialize the SDIO card, the power sequence seems to be correct.

Yeah, I'm not claiming at all I know what I'm doing there, just that it happens
to work.

Jan

[1]
https://github.com/siemens/jailhouse-images/blob/next/recipes-kernel/linux/files/arm64_defconfig_4.19

Anders Roxell Jan. 18, 2019, 3:05 p.m. UTC | #7

On Wed, 16 Jan 2019 at 16:43, Tony Lindgren <[e-mail]> wrote:
>
> * Ulf Hansson <[e-mail]> [190116 11:37]:
> > During "wlan-up", we are programming the FW into the WiFi-chip. However,
> > re-programming the FW doesn't work, unless a power cycle of the WiFi-chip
> > is made in-between the programmings.
> >
> > To conform to this requirement and to fix the regression in a simple way,
> > let's start by allowing that the SDIO card (WiFi-chip) may stay powered on
> > (runtime resumed) when wl12xx_sdio_power_off() returns. The intent with the
> > current code is to treat this scenario as an error, but unfortunate this
> > doesn't work as expected, so let's fix this.
> >
> > The other part is to guarantee that a power cycle of the SDIO card has been
> > completed when wl12xx_sdio_power_on() returns, as to allow the FW
> > programming to succeed. However, relying solely on runtime PM to deal with
> > this isn't sufficient. For example, userspace may prevent runtime suspend
> > via sysfs for the device that represents the SDIO card, leading to that the
> > mmc core also keeps it powered on. For this reason, let's instead do a
> > brute force power cycle in wl12xx_sdio_power_on().
> >
> > Fixes: 728a9dc61f13 ("wlcore: sdio: Fix flakey SDIO runtime PM handling")
> > Signed-off-by: Ulf Hansson <[e-mail]>
> > ---
> >
> > Changes in v2:
> >       - Keep the SDIO host claimed when calling mmc_hw_reset().
> >       - Add a fixes tag.
>
> This v2 version works for me as tested with:
>
> # while [ 1 ]; do ifconfig wlan0 down; ifconfig wlan0 up; done
> [  181.364990] wlcore: down
> [  182.116424] wlcore: firmware booted (Rev 6.3.10.0.141)
> [  182.151641] IPv6: ADDRCONF(NETDEV_UP): wlan0: link is not ready
> [  182.166778] wlcore: down
> [  182.773132] wlcore: firmware booted (Rev 6.3.10.0.141)
> [  182.811096] IPv6: ADDRCONF(NETDEV_UP): wlan0: link is not ready
> ...
>
> Thanks for fixing this issue properly, and feel free to add:
>
> Tested-by: Tony Lindgren <[e-mail]>

Tested-by: Anders Roxell <[e-mail]>

I tested it on a hikey-6220, and it worked.

Cheers,
Anders

Ulf Hansson Jan. 18, 2019, 3:09 p.m. UTC | #8

On Fri, 18 Jan 2019 at 13:09, Jan Kiszka <[e-mail]> wrote:
>
> On 17.01.19 10:54, Ulf Hansson wrote:
> > On Wed, 16 Jan 2019 at 21:26, Jan Kiszka <[e-mail]> wrote:
> >>
> >> On 16.01.19 12:37, Ulf Hansson wrote:
> >>> During "wlan-up", we are programming the FW into the WiFi-chip. However,
> >>> re-programming the FW doesn't work, unless a power cycle of the WiFi-chip
> >>> is made in-between the programmings.
> >>>
> >>> To conform to this requirement and to fix the regression in a simple way,
> >>> let's start by allowing that the SDIO card (WiFi-chip) may stay powered on
> >>> (runtime resumed) when wl12xx_sdio_power_off() returns. The intent with the
> >>> current code is to treat this scenario as an error, but unfortunate this
> >>> doesn't work as expected, so let's fix this.
> >>>
> >>> The other part is to guarantee that a power cycle of the SDIO card has been
> >>> completed when wl12xx_sdio_power_on() returns, as to allow the FW
> >>> programming to succeed. However, relying solely on runtime PM to deal with
> >>> this isn't sufficient. For example, userspace may prevent runtime suspend
> >>> via sysfs for the device that represents the SDIO card, leading to that the
> >>> mmc core also keeps it powered on. For this reason, let's instead do a
> >>> brute force power cycle in wl12xx_sdio_power_on().
> >>>
> >>> Fixes: 728a9dc61f13 ("wlcore: sdio: Fix flakey SDIO runtime PM handling")
> >>> Signed-off-by: Ulf Hansson <[e-mail]>
> >>> ---
> >>>
> >>> Changes in v2:
> >>>        - Keep the SDIO host claimed when calling mmc_hw_reset().
> >>>        - Add a fixes tag.
> >>> ---
> >>>    drivers/net/wireless/ti/wlcore/sdio.c | 15 +++++++--------
> >>>    1 file changed, 7 insertions(+), 8 deletions(-)
> >>>
> >>> diff --git a/drivers/net/wireless/ti/wlcore/sdio.c b/drivers/net/wireless/ti/wlcore/sdio.c
> >>> index bd10165d7eec..4d4b07701149 100644
> >>> --- a/drivers/net/wireless/ti/wlcore/sdio.c
> >>> +++ b/drivers/net/wireless/ti/wlcore/sdio.c
> >>> @@ -164,6 +164,12 @@ static int wl12xx_sdio_power_on(struct wl12xx_sdio_glue *glue)
> >>>        }
> >>>
> >>>        sdio_claim_host(func);
> >>> +     /*
> >>> +      * To guarantee that the SDIO card is power cycled, as required to make
> >>> +      * the FW programming to succeed, let's do a brute force HW reset.
> >>> +      */
> >>> +     mmc_hw_reset(card->host);
> >>> +
> >>>        sdio_enable_func(func);
> >>>        sdio_release_host(func);
> >>>
> >>> @@ -174,20 +180,13 @@ static int wl12xx_sdio_power_off(struct wl12xx_sdio_glue *glue)
> >>>    {
> >>>        struct sdio_func *func = dev_to_sdio_func(glue->dev);
> >>>        struct mmc_card *card = func->card;
> >>> -     int error;
> >>>
> >>>        sdio_claim_host(func);
> >>>        sdio_disable_func(func);
> >>>        sdio_release_host(func);
> >>>
> >>>        /* Let runtime PM know the card is powered off */
> >>> -     error = pm_runtime_put(&card->dev);
> >>> -     if (error < 0 && error != -EBUSY) {
> >>> -             dev_err(&card->dev, "%s failed: %i\n", __func__, error);
> >>> -
> >>> -             return error;
> >>> -     }
> >>> -
> >>> +     pm_runtime_put(&card->dev);
> >>>        return 0;
> >>>    }
> >>>
> >>>
> >>
> >> Just tested on both HiKey (620) and Ultra96 but it fails to fix the issue on
> >> both. I'm getting
> >>
> >> wl1271_sdio: probe of mmc2:0001:1 failed with error -16
> >>
> >> during boot again, and the interface is not available.
> >
> > Okay, sounds like this may be a different problem then. Can you share
> > the complete log and the kernel config?
>
> You can find the config here [1], log from the HiKey boot attached.
>
> > I can prepare a debug patch as well, if you are willing to re-run the test?
>
> Sure, send it over, I can run it.

Alright, sounds great. However, I need to defer that to Monday/Tuesday
next week.

>
> >
> > Adding a post-power-on-delay-ms of 1 ms as you suggested [1], doesn't
> > sounds like the correct solution to me, unless I am overlooking some
> > things. The point is, since the mmc core succeeds to detect and
> > initialize the SDIO card, the power sequence seems to be correct.
>
> Yeah, I'm not claiming at all I know what I'm doing there, just that it happens
> to work.

I see. Good to know, thanks!

>
> Jan
>
> [1]
> https://github.com/siemens/jailhouse-images/blob/next/recipes-kernel/linux/files/arm64_defconfig_4.19

I have looked through the log and the defconfig. No obvious things
found at this point. Thanks for sharing them!

Kind regards
Uffe

Tony Lindgren Jan. 18, 2019, 3:35 p.m. UTC | #9

* Ulf Hansson <[e-mail]> [190118 15:09]:
> On Fri, 18 Jan 2019 at 13:09, Jan Kiszka <[e-mail]> wrote:
> > Yeah, I'm not claiming at all I know what I'm doing there, just that it happens
> > to work.
> 
> I see. Good to know, thanks!

This seems like some separate issue. I wonder if adding
another reset just before pm_runtime_put() clears this
one instead of using the msleep? Just guessing..

Regards,

Tony

Kalle Valo Jan. 18, 2019, 3:36 p.m. UTC | #10

Anders Roxell <[e-mail]> writes:

> On Wed, 16 Jan 2019 at 16:43, Tony Lindgren <[e-mail]> wrote:
>>
>> * Ulf Hansson <[e-mail]> [190116 11:37]:
>> > During "wlan-up", we are programming the FW into the WiFi-chip. However,
>> > re-programming the FW doesn't work, unless a power cycle of the WiFi-chip
>> > is made in-between the programmings.
>> >
>> > To conform to this requirement and to fix the regression in a simple way,
>> > let's start by allowing that the SDIO card (WiFi-chip) may stay powered on
>> > (runtime resumed) when wl12xx_sdio_power_off() returns. The intent with the
>> > current code is to treat this scenario as an error, but unfortunate this
>> > doesn't work as expected, so let's fix this.
>> >
>> > The other part is to guarantee that a power cycle of the SDIO card has been
>> > completed when wl12xx_sdio_power_on() returns, as to allow the FW
>> > programming to succeed. However, relying solely on runtime PM to deal with
>> > this isn't sufficient. For example, userspace may prevent runtime suspend
>> > via sysfs for the device that represents the SDIO card, leading to that the
>> > mmc core also keeps it powered on. For this reason, let's instead do a
>> > brute force power cycle in wl12xx_sdio_power_on().
>> >
>> > Fixes: 728a9dc61f13 ("wlcore: sdio: Fix flakey SDIO runtime PM handling")
>> > Signed-off-by: Ulf Hansson <[e-mail]>
>> > ---
>> >
>> > Changes in v2:
>> >       - Keep the SDIO host claimed when calling mmc_hw_reset().
>> >       - Add a fixes tag.
>>
>> This v2 version works for me as tested with:
>>
>> # while [ 1 ]; do ifconfig wlan0 down; ifconfig wlan0 up; done
>> [  181.364990] wlcore: down
>> [  182.116424] wlcore: firmware booted (Rev 6.3.10.0.141)
>> [  182.151641] IPv6: ADDRCONF(NETDEV_UP): wlan0: link is not ready
>> [  182.166778] wlcore: down
>> [  182.773132] wlcore: firmware booted (Rev 6.3.10.0.141)
>> [  182.811096] IPv6: ADDRCONF(NETDEV_UP): wlan0: link is not ready
>> ...
>>
>> Thanks for fixing this issue properly, and feel free to add:
>>
>> Tested-by: Tony Lindgren <[e-mail]>
>
> Tested-by: Anders Roxell <[e-mail]>
>
> I tested it on a hikey-6220, and it worked.

So what's the conclusion, can I take this patch? I see that this didn't
help with Jan but as Tony and Anders provided positive test results I'm
inclined to take this now and Jan's problem can be fixed with another
patch. Do everyone agree?

Tony Lindgren Jan. 18, 2019, 3:49 p.m. UTC | #11

* Kalle Valo <[e-mail]> [190118 15:37]:
> Anders Roxell <[e-mail]> writes:
> 
> > On Wed, 16 Jan 2019 at 16:43, Tony Lindgren <[e-mail]> wrote:
> >>
> >> * Ulf Hansson <[e-mail]> [190116 11:37]:
> >> > During "wlan-up", we are programming the FW into the WiFi-chip. However,
> >> > re-programming the FW doesn't work, unless a power cycle of the WiFi-chip
> >> > is made in-between the programmings.
> >> >
> >> > To conform to this requirement and to fix the regression in a simple way,
> >> > let's start by allowing that the SDIO card (WiFi-chip) may stay powered on
> >> > (runtime resumed) when wl12xx_sdio_power_off() returns. The intent with the
> >> > current code is to treat this scenario as an error, but unfortunate this
> >> > doesn't work as expected, so let's fix this.
> >> >
> >> > The other part is to guarantee that a power cycle of the SDIO card has been
> >> > completed when wl12xx_sdio_power_on() returns, as to allow the FW
> >> > programming to succeed. However, relying solely on runtime PM to deal with
> >> > this isn't sufficient. For example, userspace may prevent runtime suspend
> >> > via sysfs for the device that represents the SDIO card, leading to that the
> >> > mmc core also keeps it powered on. For this reason, let's instead do a
> >> > brute force power cycle in wl12xx_sdio_power_on().
> >> >
> >> > Fixes: 728a9dc61f13 ("wlcore: sdio: Fix flakey SDIO runtime PM handling")
> >> > Signed-off-by: Ulf Hansson <[e-mail]>
> >> > ---
> >> >
> >> > Changes in v2:
> >> >       - Keep the SDIO host claimed when calling mmc_hw_reset().
> >> >       - Add a fixes tag.
> >>
> >> This v2 version works for me as tested with:
> >>
> >> # while [ 1 ]; do ifconfig wlan0 down; ifconfig wlan0 up; done
> >> [  181.364990] wlcore: down
> >> [  182.116424] wlcore: firmware booted (Rev 6.3.10.0.141)
> >> [  182.151641] IPv6: ADDRCONF(NETDEV_UP): wlan0: link is not ready
> >> [  182.166778] wlcore: down
> >> [  182.773132] wlcore: firmware booted (Rev 6.3.10.0.141)
> >> [  182.811096] IPv6: ADDRCONF(NETDEV_UP): wlan0: link is not ready
> >> ...
> >>
> >> Thanks for fixing this issue properly, and feel free to add:
> >>
> >> Tested-by: Tony Lindgren <[e-mail]>
> >
> > Tested-by: Anders Roxell <[e-mail]>
> >
> > I tested it on a hikey-6220, and it worked.
> 
> So what's the conclusion, can I take this patch? I see that this didn't
> help with Jan but as Tony and Anders provided positive test results I'm
> inclined to take this now and Jan's problem can be fixed with another
> patch. Do everyone agree?

Sounds good to me, seems like there is another separate issue
lurking around somewhere.

Regards,

Tony

Ulf Hansson Jan. 21, 2019, 2:40 p.m. UTC | #12

On Fri, 18 Jan 2019 at 16:09, Ulf Hansson <[e-mail]> wrote:
>
> On Fri, 18 Jan 2019 at 13:09, Jan Kiszka <[e-mail]> wrote:
> >
> > On 17.01.19 10:54, Ulf Hansson wrote:
> > > On Wed, 16 Jan 2019 at 21:26, Jan Kiszka <[e-mail]> wrote:
> > >>
> > >> On 16.01.19 12:37, Ulf Hansson wrote:
> > >>> During "wlan-up", we are programming the FW into the WiFi-chip. However,
> > >>> re-programming the FW doesn't work, unless a power cycle of the WiFi-chip
> > >>> is made in-between the programmings.
> > >>>
> > >>> To conform to this requirement and to fix the regression in a simple way,
> > >>> let's start by allowing that the SDIO card (WiFi-chip) may stay powered on
> > >>> (runtime resumed) when wl12xx_sdio_power_off() returns. The intent with the
> > >>> current code is to treat this scenario as an error, but unfortunate this
> > >>> doesn't work as expected, so let's fix this.
> > >>>
> > >>> The other part is to guarantee that a power cycle of the SDIO card has been
> > >>> completed when wl12xx_sdio_power_on() returns, as to allow the FW
> > >>> programming to succeed. However, relying solely on runtime PM to deal with
> > >>> this isn't sufficient. For example, userspace may prevent runtime suspend
> > >>> via sysfs for the device that represents the SDIO card, leading to that the
> > >>> mmc core also keeps it powered on. For this reason, let's instead do a
> > >>> brute force power cycle in wl12xx_sdio_power_on().
> > >>>
> > >>> Fixes: 728a9dc61f13 ("wlcore: sdio: Fix flakey SDIO runtime PM handling")
> > >>> Signed-off-by: Ulf Hansson <[e-mail]>
> > >>> ---
> > >>>
> > >>> Changes in v2:
> > >>>        - Keep the SDIO host claimed when calling mmc_hw_reset().
> > >>>        - Add a fixes tag.
> > >>> ---
> > >>>    drivers/net/wireless/ti/wlcore/sdio.c | 15 +++++++--------
> > >>>    1 file changed, 7 insertions(+), 8 deletions(-)
> > >>>
> > >>> diff --git a/drivers/net/wireless/ti/wlcore/sdio.c b/drivers/net/wireless/ti/wlcore/sdio.c
> > >>> index bd10165d7eec..4d4b07701149 100644
> > >>> --- a/drivers/net/wireless/ti/wlcore/sdio.c
> > >>> +++ b/drivers/net/wireless/ti/wlcore/sdio.c
> > >>> @@ -164,6 +164,12 @@ static int wl12xx_sdio_power_on(struct wl12xx_sdio_glue *glue)
> > >>>        }
> > >>>
> > >>>        sdio_claim_host(func);
> > >>> +     /*
> > >>> +      * To guarantee that the SDIO card is power cycled, as required to make
> > >>> +      * the FW programming to succeed, let's do a brute force HW reset.
> > >>> +      */
> > >>> +     mmc_hw_reset(card->host);
> > >>> +
> > >>>        sdio_enable_func(func);
> > >>>        sdio_release_host(func);
> > >>>
> > >>> @@ -174,20 +180,13 @@ static int wl12xx_sdio_power_off(struct wl12xx_sdio_glue *glue)
> > >>>    {
> > >>>        struct sdio_func *func = dev_to_sdio_func(glue->dev);
> > >>>        struct mmc_card *card = func->card;
> > >>> -     int error;
> > >>>
> > >>>        sdio_claim_host(func);
> > >>>        sdio_disable_func(func);
> > >>>        sdio_release_host(func);
> > >>>
> > >>>        /* Let runtime PM know the card is powered off */
> > >>> -     error = pm_runtime_put(&card->dev);
> > >>> -     if (error < 0 && error != -EBUSY) {
> > >>> -             dev_err(&card->dev, "%s failed: %i\n", __func__, error);
> > >>> -
> > >>> -             return error;
> > >>> -     }
> > >>> -
> > >>> +     pm_runtime_put(&card->dev);
> > >>>        return 0;
> > >>>    }
> > >>>
> > >>>
> > >>
> > >> Just tested on both HiKey (620) and Ultra96 but it fails to fix the issue on
> > >> both. I'm getting
> > >>
> > >> wl1271_sdio: probe of mmc2:0001:1 failed with error -16
> > >>
> > >> during boot again, and the interface is not available.
> > >
> > > Okay, sounds like this may be a different problem then. Can you share
> > > the complete log and the kernel config?
> >
> > You can find the config here [1], log from the HiKey boot attached.
> >
> > > I can prepare a debug patch as well, if you are willing to re-run the test?
> >
> > Sure, send it over, I can run it.
>
> Alright, sounds great. However, I need to defer that to Monday/Tuesday
> next week.
>
> >
> > >
> > > Adding a post-power-on-delay-ms of 1 ms as you suggested [1], doesn't
> > > sounds like the correct solution to me, unless I am overlooking some
> > > things. The point is, since the mmc core succeeds to detect and
> > > initialize the SDIO card, the power sequence seems to be correct.
> >
> > Yeah, I'm not claiming at all I know what I'm doing there, just that it happens
> > to work.
>
> I see. Good to know, thanks!
>
> >
> > Jan
> >
> > [1]
> > https://github.com/siemens/jailhouse-images/blob/next/recipes-kernel/linux/files/arm64_defconfig_4.19
>
> I have looked through the log and the defconfig. No obvious things
> found at this point. Thanks for sharing them!
>

So, I have put together a debug patch, mostly to verify that things
seems to be correct in regards to runtime PM. It should produce some
prints to the log, particular during power on/off of the SDIO card and
during probe of the wifi driver. Please re-run the test on top of the
v2 version of the $subject patch.

Kind regards
Uffe
From ef7890463ae9bec8fab7d16448681923736706e3 Mon Sep 17 00:00:00 2001
From: Ulf Hansson <[e-mail]>
Date: Mon, 21 Jan 2019 15:31:57 +0100
Subject: [PATCH] wlcore/sdio/mmc: Debug for runtime PM and power on/off of
 SDIO

Signed-off-by: Ulf Hansson <[e-mail]>
---
 drivers/mmc/core/pwrseq_simple.c      |  2 ++
 drivers/mmc/core/sdio.c               | 19 +++++++++++++++++--
 drivers/mmc/core/sdio_bus.c           | 26 +++++++++++++++++++++++---
 drivers/net/wireless/ti/wlcore/sdio.c | 27 ++++++++++++++++++++++++++-
 4 files changed, 68 insertions(+), 6 deletions(-)

diff --git a/drivers/mmc/core/pwrseq_simple.c b/drivers/mmc/core/pwrseq_simple.c
index ece34c734693..b9b1fc73a5a0 100644
--- a/drivers/mmc/core/pwrseq_simple.c
+++ b/drivers/mmc/core/pwrseq_simple.c
@@ -66,6 +66,7 @@ static void mmc_pwrseq_simple_pre_power_on(struct mmc_host *host)
 	if (!IS_ERR(pwrseq->ext_clk) && !pwrseq->clk_enabled) {
 		clk_prepare_enable(pwrseq->ext_clk);
 		pwrseq->clk_enabled = true;
+		dev_info(mmc_dev(host), "%s clk_prepare_enable()\n", __func__);
 	}
 
 	mmc_pwrseq_simple_set_gpios_value(pwrseq, 1);
@@ -94,6 +95,7 @@ static void mmc_pwrseq_simple_power_off(struct mmc_host *host)
 	if (!IS_ERR(pwrseq->ext_clk) && pwrseq->clk_enabled) {
 		clk_disable_unprepare(pwrseq->ext_clk);
 		pwrseq->clk_enabled = false;
+		dev_info(mmc_dev(host), "%s clk_disable_unprepare()\n", __func__);
 	}
 }
 
diff --git a/drivers/mmc/core/sdio.c b/drivers/mmc/core/sdio.c
index d8e17ea6126d..ce7d29ad2651 100644
--- a/drivers/mmc/core/sdio.c
+++ b/drivers/mmc/core/sdio.c
@@ -1029,11 +1029,13 @@ static int mmc_sdio_power_restore(struct mmc_host *host)
 
 static int mmc_sdio_runtime_suspend(struct mmc_host *host)
 {
+	dev_info(&host->card->dev, "%s\n", __func__);
 	/* No references to the card, cut the power to it. */
 	mmc_claim_host(host);
 	mmc_power_off(host);
 	mmc_release_host(host);
 
+	dev_info(&host->card->dev, "%s - DONE\n", __func__);
 	return 0;
 }
 
@@ -1041,19 +1043,27 @@ static int mmc_sdio_runtime_resume(struct mmc_host *host)
 {
 	int ret;
 
+	dev_info(&host->card->dev, "%s\n", __func__);
 	/* Restore power and re-initialize. */
 	mmc_claim_host(host);
 	mmc_power_up(host, host->card->ocr);
 	ret = mmc_sdio_power_restore(host);
 	mmc_release_host(host);
 
+	dev_info(&host->card->dev, "%s - ret=%d DONE\n", __func__, ret);
 	return ret;
 }
 
 static int mmc_sdio_hw_reset(struct mmc_host *host)
 {
+	int ret;
+
+	dev_info(&host->card->dev, "%s\n", __func__);
 	mmc_power_cycle(host, host->card->ocr);
-	return mmc_sdio_power_restore(host);
+	ret = mmc_sdio_power_restore(host);
+
+	dev_info(&host->card->dev, "%s - ret=%d DONE\n", __func__, ret);
+	return ret;
 }
 
 static int mmc_sdio_sw_reset(struct mmc_host *host)
@@ -1142,6 +1152,8 @@ int mmc_attach_sdio(struct mmc_host *host)
 		 * Enable runtime PM for this card
 		 */
 		pm_runtime_enable(&card->dev);
+
+		dev_info(&card->dev, "%s Enabled runtime PM()\n", __func__);
 	}
 
 	/*
@@ -1183,8 +1195,11 @@ int mmc_attach_sdio(struct mmc_host *host)
 			goto remove_added;
 	}
 
-	if (host->caps & MMC_CAP_POWER_OFF_CARD)
+
+	if (host->caps & MMC_CAP_POWER_OFF_CARD) {
+		dev_info(&card->dev, "%s pm_runtime_put()\n", __func__);
 		pm_runtime_put(&card->dev);
+	}
 
 	mmc_claim_host(host);
 	return 0;
diff --git a/drivers/mmc/core/sdio_bus.c b/drivers/mmc/core/sdio_bus.c
index b6d8203e46eb..e4357ce188ef 100644
--- a/drivers/mmc/core/sdio_bus.c
+++ b/drivers/mmc/core/sdio_bus.c
@@ -134,6 +134,8 @@ static int sdio_bus_probe(struct device *dev)
 	const struct sdio_device_id *id;
 	int ret;
 
+	dev_info(dev, "%s\n", __func__);
+
 	id = sdio_match_device(func, drv);
 	if (!id)
 		return -ENODEV;
@@ -149,6 +151,7 @@ static int sdio_bus_probe(struct device *dev)
 	 * pm_runtime_get_noresume() in its remove routine.
 	 */
 	if (func->card->host->caps & MMC_CAP_POWER_OFF_CARD) {
+		dev_info(dev, "%s - pm_runtime_get_sync()\n", __func__);
 		ret = pm_runtime_get_sync(dev);
 		if (ret < 0)
 			goto disable_runtimepm;
@@ -166,11 +169,14 @@ static int sdio_bus_probe(struct device *dev)
 	if (ret)
 		goto disable_runtimepm;
 
+	dev_info(dev, "%s - probe OK\n", __func__);
 	return 0;
 
 disable_runtimepm:
-	if (func->card->host->caps & MMC_CAP_POWER_OFF_CARD)
+	if (func->card->host->caps & MMC_CAP_POWER_OFF_CARD) {
+		dev_info(dev, "%s - ERR call pm_runtime_put_noidle()\n", __func__);
 		pm_runtime_put_noidle(dev);
+	}
 	dev_pm_domain_detach(dev, false);
 	return ret;
 }
@@ -208,11 +214,25 @@ static int sdio_bus_remove(struct device *dev)
 	return ret;
 }
 
+#ifdef CONFIG_PM
+static int sdio_bus_runtime_suspend(struct device *dev)
+{
+	dev_info(dev, "%s\n", __func__);
+	return pm_generic_runtime_suspend(dev);
+}
+
+static int sdio_bus_runtime_resume(struct device *dev)
+{
+	dev_info(dev, "%s\n", __func__);
+	return pm_generic_runtime_resume(dev);
+}
+#endif
+
 static const struct dev_pm_ops sdio_bus_pm_ops = {
 	SET_SYSTEM_SLEEP_PM_OPS(pm_generic_suspend, pm_generic_resume)
 	SET_RUNTIME_PM_OPS(
-		pm_generic_runtime_suspend,
-		pm_generic_runtime_resume,
+		sdio_bus_runtime_suspend,
+		sdio_bus_runtime_resume,
 		NULL
 	)
 };
diff --git a/drivers/net/wireless/ti/wlcore/sdio.c b/drivers/net/wireless/ti/wlcore/sdio.c
index 4d4b07701149..0a82a11cae97 100644
--- a/drivers/net/wireless/ti/wlcore/sdio.c
+++ b/drivers/net/wireless/ti/wlcore/sdio.c
@@ -154,6 +154,8 @@ static int wl12xx_sdio_power_on(struct wl12xx_sdio_glue *glue)
 	struct sdio_func *func = dev_to_sdio_func(glue->dev);
 	struct mmc_card *card = func->card;
 
+	dev_info(glue->dev, "%s: STEP1\n", __func__);
+
 	ret = pm_runtime_get_sync(&card->dev);
 	if (ret < 0) {
 		pm_runtime_put_noidle(&card->dev);
@@ -163,7 +165,12 @@ static int wl12xx_sdio_power_on(struct wl12xx_sdio_glue *glue)
 		return ret;
 	}
 
+	dev_info(glue->dev, "%s: STEP2\n", __func__);
+
 	sdio_claim_host(func);
+
+	dev_info(glue->dev, "%s: STEP3\n", __func__);
+
 	/*
 	 * To guarantee that the SDIO card is power cycled, as required to make
 	 * the FW programming to succeed, let's do a brute force HW reset.
@@ -171,8 +178,12 @@ static int wl12xx_sdio_power_on(struct wl12xx_sdio_glue *glue)
 	mmc_hw_reset(card->host);
 
 	sdio_enable_func(func);
+
+	dev_info(glue->dev, "%s: STEP4\n", __func__);
+
 	sdio_release_host(func);
 
+	dev_info(glue->dev, "%s: STEP5\n", __func__);
 	return 0;
 }
 
@@ -181,12 +192,20 @@ static int wl12xx_sdio_power_off(struct wl12xx_sdio_glue *glue)
 	struct sdio_func *func = dev_to_sdio_func(glue->dev);
 	struct mmc_card *card = func->card;
 
+	dev_info(glue->dev, "%s: STEP1\n", __func__);
+
 	sdio_claim_host(func);
 	sdio_disable_func(func);
+
+	dev_info(glue->dev, "%s: STEP2\n", __func__);
 	sdio_release_host(func);
 
+
+	dev_info(glue->dev, "%s: STEP3\n", __func__);
 	/* Let runtime PM know the card is powered off */
 	pm_runtime_put(&card->dev);
+
+	dev_info(glue->dev, "%s: STEP4\n", __func__);
 	return 0;
 }
 
@@ -315,7 +334,7 @@ static int wl1271_probe(struct sdio_func *func,
 
 	/* if sdio can keep power while host is suspended, enable wow */
 	mmcflags = sdio_get_host_pm_caps(func);
-	dev_dbg(glue->dev, "sdio PM caps = 0x%x\n", mmcflags);
+	dev_info(glue->dev, "sdio PM caps = 0x%x\n", mmcflags);
 
 	if (mmcflags & MMC_PM_KEEP_POWER)
 		pdev_data->pwr_in_suspend = true;
@@ -336,6 +355,8 @@ static int wl1271_probe(struct sdio_func *func,
 	else
 		chip_family = "wl12xx";
 
+	dev_info(glue->dev, "chip_family is %s\n", chip_family);
+
 	glue->core = platform_device_alloc(chip_family, PLATFORM_DEVID_AUTO);
 	if (!glue->core) {
 		dev_err(glue->dev, "can't allocate platform_device");
@@ -375,11 +396,15 @@ static int wl1271_probe(struct sdio_func *func,
 		goto out_dev_put;
 	}
 
+	dev_info(glue->dev, "About to add core dev (child)...\n");
+
 	ret = platform_device_add(glue->core);
 	if (ret) {
 		dev_err(glue->dev, "can't add platform device\n");
 		goto out_dev_put;
 	}
+
+	dev_info(glue->dev, "...added core dev (child) - probe complete!\n");
 	return 0;
 
 out_dev_put:

Tony Lindgren Jan. 21, 2019, 7:30 p.m. UTC | #13

* Ulf Hansson <[e-mail]> [190121 06:41]:
> So, I have put together a debug patch, mostly to verify that things
> seems to be correct in regards to runtime PM. It should produce some
> prints to the log, particular during power on/off of the SDIO card and
> during probe of the wifi driver. Please re-run the test on top of the
> v2 version of the $subject patch.

For reference, here's what I'm seeing on omap4 with your v2 fix
and the debug patch for:

# ifconfig wlan0 up; ifconfig wlan0 down

Note that this is without pwrseq, so maybe that's the difference.

Regards,

Tony

8< -----------------
[  148.458282] wl1271_sdio mmc4:0001:2: wl12xx_sdio_power_on: STEP1
[  148.464691] mmc mmc4:0001: mmc_sdio_runtime_resume
[  148.641021] mmc mmc4:0001: mmc_sdio_runtime_resume - ret=0 DONE
[  148.647613] wl1271_sdio mmc4:0001:2: wl12xx_sdio_power_on: STEP2
[  148.653961] wl1271_sdio mmc4:0001:2: wl12xx_sdio_power_on: STEP3
[  148.660430] mmc mmc4:0001: mmc_sdio_hw_reset
[  148.828735] mmc mmc4:0001: mmc_sdio_hw_reset - ret=0 DONE
[  148.834503] wl1271_sdio mmc4:0001:2: wl12xx_sdio_power_on: STEP4
[  148.840789] wl1271_sdio mmc4:0001:2: wl12xx_sdio_power_on: STEP5
[  149.194671] wlcore: firmware booted (Rev 7.3.10.0.141)
[  149.200134] wl1271_sdio mmc4:0001:2: sdio_bus_runtime_resume
[  149.233276] IPv6: ADDRCONF(NETDEV_UP): wlan0: link is not ready
[  149.248352] wlcore: down
[  149.253082] wl1271_sdio mmc4:0001:2: wl12xx_sdio_power_off: STEP1
[  149.259613] wl1271_sdio mmc4:0001:2: wl12xx_sdio_power_off: STEP2
[  149.265869] wl1271_sdio mmc4:0001:2: wl12xx_sdio_power_off: STEP3
[  149.272155] wl1271_sdio mmc4:0001:2: wl12xx_sdio_power_off: STEP4
[  149.307952] wl1271_sdio mmc4:0001:2: sdio_bus_runtime_suspend
[  149.314147] mmc mmc4:0001: mmc_sdio_runtime_suspend
[  149.321136] mmc mmc4:0001: mmc_sdio_runtime_suspend - DONE

Jan Kiszka Jan. 22, 2019, 4:08 p.m. UTC | #14

On 21.01.19 15:40, Ulf Hansson wrote:
> On Fri, 18 Jan 2019 at 16:09, Ulf Hansson <[e-mail]> wrote:
>>
>> On Fri, 18 Jan 2019 at 13:09, Jan Kiszka <[e-mail]> wrote:
>>>
>>> On 17.01.19 10:54, Ulf Hansson wrote:
>>>> On Wed, 16 Jan 2019 at 21:26, Jan Kiszka <[e-mail]> wrote:
>>>>>
>>>>> On 16.01.19 12:37, Ulf Hansson wrote:
>>>>>> During "wlan-up", we are programming the FW into the WiFi-chip. However,
>>>>>> re-programming the FW doesn't work, unless a power cycle of the WiFi-chip
>>>>>> is made in-between the programmings.
>>>>>>
>>>>>> To conform to this requirement and to fix the regression in a simple way,
>>>>>> let's start by allowing that the SDIO card (WiFi-chip) may stay powered on
>>>>>> (runtime resumed) when wl12xx_sdio_power_off() returns. The intent with the
>>>>>> current code is to treat this scenario as an error, but unfortunate this
>>>>>> doesn't work as expected, so let's fix this.
>>>>>>
>>>>>> The other part is to guarantee that a power cycle of the SDIO card has been
>>>>>> completed when wl12xx_sdio_power_on() returns, as to allow the FW
>>>>>> programming to succeed. However, relying solely on runtime PM to deal with
>>>>>> this isn't sufficient. For example, userspace may prevent runtime suspend
>>>>>> via sysfs for the device that represents the SDIO card, leading to that the
>>>>>> mmc core also keeps it powered on. For this reason, let's instead do a
>>>>>> brute force power cycle in wl12xx_sdio_power_on().
>>>>>>
>>>>>> Fixes: 728a9dc61f13 ("wlcore: sdio: Fix flakey SDIO runtime PM handling")
>>>>>> Signed-off-by: Ulf Hansson <[e-mail]>
>>>>>> ---
>>>>>>
>>>>>> Changes in v2:
>>>>>>         - Keep the SDIO host claimed when calling mmc_hw_reset().
>>>>>>         - Add a fixes tag.
>>>>>> ---
>>>>>>     drivers/net/wireless/ti/wlcore/sdio.c | 15 +++++++--------
>>>>>>     1 file changed, 7 insertions(+), 8 deletions(-)
>>>>>>
>>>>>> diff --git a/drivers/net/wireless/ti/wlcore/sdio.c b/drivers/net/wireless/ti/wlcore/sdio.c
>>>>>> index bd10165d7eec..4d4b07701149 100644
>>>>>> --- a/drivers/net/wireless/ti/wlcore/sdio.c
>>>>>> +++ b/drivers/net/wireless/ti/wlcore/sdio.c
>>>>>> @@ -164,6 +164,12 @@ static int wl12xx_sdio_power_on(struct wl12xx_sdio_glue *glue)
>>>>>>         }
>>>>>>
>>>>>>         sdio_claim_host(func);
>>>>>> +     /*
>>>>>> +      * To guarantee that the SDIO card is power cycled, as required to make
>>>>>> +      * the FW programming to succeed, let's do a brute force HW reset.
>>>>>> +      */
>>>>>> +     mmc_hw_reset(card->host);
>>>>>> +
>>>>>>         sdio_enable_func(func);
>>>>>>         sdio_release_host(func);
>>>>>>
>>>>>> @@ -174,20 +180,13 @@ static int wl12xx_sdio_power_off(struct wl12xx_sdio_glue *glue)
>>>>>>     {
>>>>>>         struct sdio_func *func = dev_to_sdio_func(glue->dev);
>>>>>>         struct mmc_card *card = func->card;
>>>>>> -     int error;
>>>>>>
>>>>>>         sdio_claim_host(func);
>>>>>>         sdio_disable_func(func);
>>>>>>         sdio_release_host(func);
>>>>>>
>>>>>>         /* Let runtime PM know the card is powered off */
>>>>>> -     error = pm_runtime_put(&card->dev);
>>>>>> -     if (error < 0 && error != -EBUSY) {
>>>>>> -             dev_err(&card->dev, "%s failed: %i\n", __func__, error);
>>>>>> -
>>>>>> -             return error;
>>>>>> -     }
>>>>>> -
>>>>>> +     pm_runtime_put(&card->dev);
>>>>>>         return 0;
>>>>>>     }
>>>>>>
>>>>>>
>>>>>
>>>>> Just tested on both HiKey (620) and Ultra96 but it fails to fix the issue on
>>>>> both. I'm getting
>>>>>
>>>>> wl1271_sdio: probe of mmc2:0001:1 failed with error -16
>>>>>
>>>>> during boot again, and the interface is not available.
>>>>
>>>> Okay, sounds like this may be a different problem then. Can you share
>>>> the complete log and the kernel config?
>>>
>>> You can find the config here [1], log from the HiKey boot attached.
>>>
>>>> I can prepare a debug patch as well, if you are willing to re-run the test?
>>>
>>> Sure, send it over, I can run it.
>>
>> Alright, sounds great. However, I need to defer that to Monday/Tuesday
>> next week.
>>
>>>
>>>>
>>>> Adding a post-power-on-delay-ms of 1 ms as you suggested [1], doesn't
>>>> sounds like the correct solution to me, unless I am overlooking some
>>>> things. The point is, since the mmc core succeeds to detect and
>>>> initialize the SDIO card, the power sequence seems to be correct.
>>>
>>> Yeah, I'm not claiming at all I know what I'm doing there, just that it happens
>>> to work.
>>
>> I see. Good to know, thanks!
>>
>>>
>>> Jan
>>>
>>> [1]
>>> https://github.com/siemens/jailhouse-images/blob/next/recipes-kernel/linux/files/arm64_defconfig_4.19
>>
>> I have looked through the log and the defconfig. No obvious things
>> found at this point. Thanks for sharing them!
>>
>
> So, I have put together a debug patch, mostly to verify that things
> seems to be correct in regards to runtime PM. It should produce some
> prints to the log, particular during power on/off of the SDIO card and
> during probe of the wifi driver. Please re-run the test on top of the
> v2 version of the $subject patch.
>

Log attached.

Jan
[    0.000000] Booting Linux on physical CPU 0x0000000000 [0x410fd033]
[    0.000000] Linux version 4.19.16 (builder@870f50503134) (gcc version 6.3.0 20170516 (Debian 6.3.0-18)) #1 SMP PREEMPT Tue Jan 22 15:50:59 UTC 2019
[    0.000000] Machine model: HiKey Development Board
[    0.000000] Memory limited to 1820MB
[    0.000000] efi: Getting EFI parameters from FDT:
[    0.000000] efi: EFI v2.60 by EDK II
[    0.000000] efi:  MEMATTR=0x3cd48a98
[    0.000000] Reserved memory: created CMA memory pool at 0x000000006bc00000, size 128 MiB
[    0.000000] OF: reserved mem: initialized node linux,cma, compatible id shared-dma-pool
[    0.000000] NUMA: No NUMA configuration found
[    0.000000] NUMA: Faking a node at [mem 0x0000000000000000-0x0000000073ef2fff]
[    0.000000] NUMA: NODE_DATA [mem 0x73ea95c0-0x73eaad7f]
[    0.000000] Zone ranges:
[    0.000000]   DMA32    [mem 0x0000000000000000-0x0000000073ef2fff]
[    0.000000]   Normal   empty
[    0.000000] Movable zone start for each node
[    0.000000] Early memory node ranges
[    0.000000]   node   0: [mem 0x0000000000000000-0x0000000005dfffff]
[    0.000000]   node   0: [mem 0x0000000005f00000-0x0000000005f00fff]
[    0.000000]   node   0: [mem 0x0000000005f02000-0x0000000006dfefff]
[    0.000000]   node   0: [mem 0x0000000006e00000-0x000000000740efff]
[    0.000000]   node   0: [mem 0x0000000007410000-0x0000000021efffff]
[    0.000000]   node   0: [mem 0x0000000022000000-0x0000000034ffffff]
[    0.000000]   node   0: [mem 0x00000000350f0000-0x000000003864ffff]
[    0.000000]   node   0: [mem 0x0000000038650000-0x000000003888ffff]
[    0.000000]   node   0: [mem 0x0000000038890000-0x0000000038897fff]
[    0.000000]   node   0: [mem 0x0000000038898000-0x000000003889bfff]
[    0.000000]   node   0: [mem 0x000000003889c000-0x000000003d85ffff]
[    0.000000]   node   0: [mem 0x000000003d860000-0x000000003d89ffff]
[    0.000000]   node   0: [mem 0x000000003d8a0000-0x000000003d8affff]
[    0.000000]   node   0: [mem 0x000000003d8b0000-0x000000003d8fffff]
[    0.000000]   node   0: [mem 0x000000003d900000-0x000000003dffffff]
[    0.000000]   node   0: [mem 0x0000000040000000-0x0000000073ef2fff]
[    0.000000] Reserved but unavailable: 256 pages
[    0.000000] Initmem setup node 0 [mem 0x0000000000000000-0x0000000073ef2fff]
[    0.000000] On node 0 totalpages: 465920
[    0.000000]   DMA32 zone: 7420 pages used for memmap
[    0.000000]   DMA32 zone: 0 pages reserved
[    0.000000]   DMA32 zone: 465920 pages, LIFO batch:63
[    0.000000] psci: probing for conduit method from DT.
[    0.000000] psci: PSCIv1.1 detected in firmware.
[    0.000000] psci: Using standard PSCI v0.2 function IDs
[    0.000000] psci: Trusted OS migration not required
[    0.000000] psci: SMC Calling Convention v1.1
[    0.000000] random: get_random_bytes called from start_kernel+0xac/0x414 with crng_init=0
[    0.000000] percpu: Embedded 22 pages/cpu @(____ptrval____) s53016 r8192 d28904 u90112
[    0.000000] pcpu-alloc: s53016 r8192 d28904 u90112 alloc=22*4096
[    0.000000] pcpu-alloc: [0] 0 [0] 1 [0] 2 [0] 3 [0] 4 [0] 5 [0] 6 [0] 7
[    0.000000] Detected VIPT I-cache on CPU0
[    0.000000] CPU features: enabling workaround for ARM erratum 843419
[    0.000000] CPU features: enabling workaround for ARM erratum 845719
[    0.000000] Speculative Store Bypass Disable mitigation not required
[    0.000000] CPU features: detected: Kernel page table isolation (KPTI)
[    0.000000] Built 1 zonelists, mobility grouping on.  Total pages: 458500
[    0.000000] Policy zone: DMA32
[    0.000000] Kernel command line: BOOT_IMAGE=/vmlinuz root=PARTUUID=1250070a-bba0-4399-a775-c8a68ed480bd rootwait mem=1820M
[    0.000000] Memory: 1676320K/1863680K available (9980K kernel code, 1294K rwdata, 4312K rodata, 1152K init, 371K bss, 56288K reserved, 131072K cma-reserved)
[    0.000000] SLUB: HWalign=64, Order=0-3, MinObjects=0, CPUs=8, Nodes=1
[    0.000000] rcu: Preemptible hierarchical RCU implementation.
[    0.000000] rcu: 	RCU restricting CPUs from NR_CPUS=64 to nr_cpu_ids=8.
[    0.000000] 	Tasks RCU enabled.
[    0.000000] rcu: Adjusting geometry for rcu_fanout_leaf=16, nr_cpu_ids=8
[    0.000000] NR_IRQS: 64, nr_irqs: 64, preallocated irqs: 0
[    0.000000] GIC: Using split EOI/Deactivate mode
[    0.000000] arch_timer: cp15 timer(s) running at 1.20MHz (phys).
[    0.000000] clocksource: arch_sys_counter: mask: 0xffffffffffffff max_cycles: 0x11b661f8e, max_idle_ns: 1763180809113 ns
[    0.000004] sched_clock: 56 bits at 1200kHz, resolution 833ns, wraps every 4398046510838ns
[    0.000125] clocksource: arm,sp804: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 99544814920 ns
[    0.000134] sched_clock: 32 bits at 19MHz, resolution 52ns, wraps every 111848106981ns
[    0.000805] Console: colour dummy device 80x25
[    0.001354] console [tty0] enabled
[    0.001435] Calibrating delay loop (skipped), value calculated using timer frequency.. 2.40 BogoMIPS (lpj=4800)
[    0.001459] pid_max: default: 32768 minimum: 301
[    0.001537] Security Framework initialized
[    0.002207] Dentry cache hash table entries: 262144 (order: 9, 2097152 bytes)
[    0.002553] Inode-cache hash table entries: 131072 (order: 8, 1048576 bytes)
[    0.002594] Mount-cache hash table entries: 4096 (order: 3, 32768 bytes)
[    0.002622] Mountpoint-cache hash table entries: 4096 (order: 3, 32768 bytes)
[    0.024004] ASID allocator initialised with 32768 entries
[    0.031998] rcu: Hierarchical SRCU implementation.
[    0.042077] Remapping and enabling EFI services.
[    0.048039] smp: Bringing up secondary CPUs ...
[    0.080290] Detected VIPT I-cache on CPU1
[    0.080345] CPU1: Booted secondary processor 0x0000000001 [0x410fd033]
[    0.112304] Detected VIPT I-cache on CPU2
[    0.112330] CPU2: Booted secondary processor 0x0000000002 [0x410fd033]
[    0.144364] Detected VIPT I-cache on CPU3
[    0.144387] CPU3: Booted secondary processor 0x0000000003 [0x410fd033]
[    0.176477] Detected VIPT I-cache on CPU4
[    0.176520] CPU4: Booted secondary processor 0x0000000100 [0x410fd033]
[    0.208490] Detected VIPT I-cache on CPU5
[    0.208515] CPU5: Booted secondary processor 0x0000000101 [0x410fd033]
[    0.240555] Detected VIPT I-cache on CPU6
[    0.240579] CPU6: Booted secondary processor 0x0000000102 [0x410fd033]
[    0.272618] Detected VIPT I-cache on CPU7
[    0.272642] CPU7: Booted secondary processor 0x0000000103 [0x410fd033]
[    0.272729] smp: Brought up 1 node, 8 CPUs
[    0.272861] SMP: Total of 8 processors activated.
[    0.272874] CPU features: detected: 32-bit EL0 Support
[    0.277450] CPU: All CPU(s) started at EL2
[    0.277496] alternatives: patching kernel code
[    0.278226] devtmpfs: initialized
[    0.284175] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 7645041785100000 ns
[    0.284240] futex hash table entries: 2048 (order: 5, 131072 bytes)
[    0.288417] pinctrl core: initialized pinctrl subsystem
[    0.289983] DMI not present or invalid.
[    0.290363] NET: Registered protocol family 16
[    0.290763] audit: initializing netlink subsys (disabled)
[    0.290910] audit: type=2000 audit(0.288:1): state=initialized audit_enabled=0 res=1
[    0.292415] cpuidle: using governor menu
[    0.292614] vdso: 2 pages (1 code @ (____ptrval____), 1 data @ (____ptrval____))
[    0.292634] hw-breakpoint: found 6 breakpoint and 4 watchpoint registers.
[    0.298153] DMA: preallocated 256 KiB pool for atomic allocations
[    0.299352] Serial: AMBA PL011 UART driver
[    0.301621] f8015000.uart: ttyAMA0 at MMIO 0xf8015000 (irq = 7, base_baud = 0) is a PL011 rev2
[    0.307188] hi6220-mbox f7510000.mailbox: Mailbox enabled
[    0.320408] HugeTLB registered 2.00 MiB page size, pre-allocated 0 pages
[    0.320870] cryptd: max_cpu_qlen set to 1000
[    0.321606] ACPI: Interpreter disabled.
[    0.322376] VDD_3V3: supplied by SYS_5V
[    0.322802] vgaarb: loaded
[    0.323062] SCSI subsystem initialized
[    0.323258] libata version 3.00 loaded.
[    0.323572] usbcore: registered new interface driver usbfs
[    0.323623] usbcore: registered new interface driver hub
[    0.323726] usbcore: registered new device driver usb
[    0.324374] pps_core: LinuxPPS API ver. 1 registered
[    0.324388] pps_core: Software ver. 5.3.6 - Copyright 2005-2007 Rodolfo Giometti <[e-mail]>
[    0.324420] PTP clock support registered
[    0.324540] EDAC MC: Ver: 3.0.0
[    0.324881] Registered efivars operations
[    0.326251] clocksource: Switched to clocksource arch_sys_counter
[    0.326427] VFS: Disk quotas dquot_6.6.0
[    0.326486] VFS: Dquot-cache hash table entries: 512 (order 0, 4096 bytes)
[    0.326620] pnp: PnP ACPI: disabled
[    0.331971] NET: Registered protocol family 2
[    0.332508] tcp_listen_portaddr_hash hash table entries: 1024 (order: 2, 16384 bytes)
[    0.332581] TCP established hash table entries: 16384 (order: 5, 131072 bytes)
[    0.332726] TCP bind hash table entries: 16384 (order: 6, 262144 bytes)
[    0.332939] TCP: Hash tables configured (established 16384 bind 16384)
[    0.333051] UDP hash table entries: 1024 (order: 3, 32768 bytes)
[    0.333106] UDP-Lite hash table entries: 1024 (order: 3, 32768 bytes)
[    0.333262] NET: Registered protocol family 1
[    0.333617] RPC: Registered named UNIX socket transport module.
[    0.333631] RPC: Registered udp transport module.
[    0.333642] RPC: Registered tcp transport module.
[    0.333653] RPC: Registered tcp NFSv4.1 backchannel transport module.
[    0.333671] PCI: CLS 0 bytes, default 64
[    0.333812] Unpacking initramfs...
[    0.424700] Freeing initrd memory: 2372K
[    0.428683] Initialise system trusted keyrings
[    0.428834] workingset: timestamp_bits=44 max_order=19 bucket_order=0
[    0.434485] squashfs: version 4.0 (2009/01/31) Phillip Lougher
[    0.435121] NFS: Registering the id_resolver key type
[    0.435153] Key type id_resolver registered
[    0.435164] Key type id_legacy registered
[    0.435181] nfs4filelayout_init: NFSv4 File Layout Driver Registering...
[    0.435330] 9p: Installing v9fs 9p2000 file system support
[    0.435417] pstore: using deflate compression
[    0.437819] Key type asymmetric registered
[    0.437838] Asymmetric key parser 'x509' registered
[    0.437892] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 246)
[    0.437911] io scheduler noop registered
[    0.438035] io scheduler cfq registered (default)
[    0.438049] io scheduler mq-deadline registered
[    0.438061] io scheduler kyber registered
[    0.441198] pinctrl-single f7010000.pinmux: 159 pins, size 636
[    0.441778] pinctrl-single f7010800.pinmux: 163 pins, size 652
[    0.442135] pinctrl-single f8001800.pinmux: 30 pins, size 120
[    0.443921] pl061_gpio f8011000.gpio: PL061 GPIO chip @0x00000000f8011000 registered
[    0.444208] pl061_gpio f8012000.gpio: PL061 GPIO chip @0x00000000f8012000 registered
[    0.444401] pl061_gpio f8013000.gpio: PL061 GPIO chip @0x00000000f8013000 registered
[    0.444503] gpio gpiochip3: names 9 do not match number of GPIOs 8
[    0.444605] pl061_gpio f8014000.gpio: PL061 GPIO chip @0x00000000f8014000 registered
[    0.444781] pl061_gpio f7020000.gpio: PL061 GPIO chip @0x00000000f7020000 registered
[    0.444952] pl061_gpio f7021000.gpio: PL061 GPIO chip @0x00000000f7021000 registered
[    0.445127] pl061_gpio f7022000.gpio: PL061 GPIO chip @0x00000000f7022000 registered
[    0.445301] pl061_gpio f7023000.gpio: PL061 GPIO chip @0x00000000f7023000 registered
[    0.445405] gpio gpiochip8: names 9 do not match number of GPIOs 8
[    0.445505] pl061_gpio f7024000.gpio: PL061 GPIO chip @0x00000000f7024000 registered
[    0.445702] pl061_gpio f7025000.gpio: PL061 GPIO chip @0x00000000f7025000 registered
[    0.445890] pl061_gpio f7026000.gpio: PL061 GPIO chip @0x00000000f7026000 registered
[    0.446065] pl061_gpio f7027000.gpio: PL061 GPIO chip @0x00000000f7027000 registered
[    0.446271] pl061_gpio f7028000.gpio: PL061 GPIO chip @0x00000000f7028000 registered
[    0.446479] pl061_gpio f7029000.gpio: PL061 GPIO chip @0x00000000f7029000 registered
[    0.446654] pl061_gpio f702a000.gpio: PL061 GPIO chip @0x00000000f702a000 registered
[    0.446841] pl061_gpio f702b000.gpio: PL061 GPIO chip @0x00000000f702b000 registered
[    0.447015] pl061_gpio f702c000.gpio: PL061 GPIO chip @0x00000000f702c000 registered
[    0.447186] pl061_gpio f702d000.gpio: PL061 GPIO chip @0x00000000f702d000 registered
[    0.447372] pl061_gpio f702e000.gpio: PL061 GPIO chip @0x00000000f702e000 registered
[    0.447558] pl061_gpio f702f000.gpio: PL061 GPIO chip @0x00000000f702f000 registered
[    0.456262] Serial: 8250/16550 driver, 4 ports, IRQ sharing enabled
[    0.457809] SuperH (H)SCI(F) driver initialized
[    0.458120] msm_serial: driver initialized
[    0.465824] loop: module loaded
[    0.472021] libphy: Fixed MDIO Bus: probed
[    0.472860] tun: Universal TUN/TAP device driver, 1.6
[    0.473851] e1000e: Intel(R) PRO/1000 Network Driver - 3.2.6-k
[    0.473872] e1000e: Copyright(c) 1999 - 2015 Intel Corporation.
[    0.473918] igb: Intel(R) Gigabit Ethernet Network Driver - version 5.4.0-k
[    0.473931] igb: Copyright (c) 2007-2014 Intel Corporation.
[    0.473980] igbvf: Intel(R) Gigabit Virtual Function Network Driver - version 2.4.0-k
[    0.473996] igbvf: Copyright (c) 2009 - 2012 Intel Corporation.
[    0.474270] sky2: driver version 1.30
[    0.474730] VFIO - User Level meta-driver version: 0.3
[    0.475909] ehci_hcd: USB 2.0 'Enhanced' Host Controller (EHCI) Driver
[    0.475936] ehci-pci: EHCI PCI platform driver
[    0.475977] ehci-platform: EHCI generic platform driver
[    0.476076] ehci-orion: EHCI orion driver
[    0.476151] ehci-exynos: EHCI EXYNOS driver
[    0.476219] ohci_hcd: USB 1.1 'Open' Host Controller (OHCI) Driver
[    0.476253] ohci-pci: OHCI PCI platform driver
[    0.476296] ohci-platform: OHCI generic platform driver
[    0.476386] ohci-exynos: OHCI EXYNOS driver
[    0.476732] usbcore: registered new interface driver usb-storage
[    0.478735] rtc-efi rtc-efi: rtc core: registered rtc-efi as rtc0
[    0.479127] rtc-pl031 f8003000.rtc: rtc core: registered pl031 as rtc1
[    0.479451] rtc-pl031 f8004000.rtc: rtc core: registered pl031 as rtc2
[    0.479983] i2c /dev entries driver
[    0.484243] sdhci: Secure Digital Host Controller Interface driver
[    0.484273] sdhci: Copyright(c) Pierre Ossman
[    0.484429] Synopsys Designware Multimedia Card Interface Driver
[    0.485017] dwmmc_k3 f723d000.dwmmc0: fifo-depth property not found, using value of FIFOTH register as default
[    0.485140] dwmmc_k3 f723d000.dwmmc0: IDMAC supports 32-bit address mode.
[    0.486286] dwmmc_k3 f723d000.dwmmc0: Using internal DMA controller.
[    0.486306] dwmmc_k3 f723d000.dwmmc0: Version ID is 250a
[    0.486363] dwmmc_k3 f723d000.dwmmc0: DW MMC controller at irq 41,32 bit host data width,256 deep fifo
[    0.486480] dwmmc_k3 f723d000.dwmmc0: Linked as a consumer to regulator.10
[    0.486559] mmc_host mmc0: card is non-removable.
[    0.498585] mmc_host mmc0: Bus speed (slot 0) = 24800000Hz (slot req 400000Hz, actual 400000HZ div = 31)
[    0.511734] dwmmc_k3 f723e000.dwmmc1: fifo-depth property not found, using value of FIFOTH register as default
[    0.511996] dwmmc_k3 f723e000.dwmmc1: IDMAC supports 32-bit address mode.
[    0.512893] dwmmc_k3 f723e000.dwmmc1: Using internal DMA controller.
[    0.512914] dwmmc_k3 f723e000.dwmmc1: Version ID is 250a
[    0.512965] dwmmc_k3 f723e000.dwmmc1: DW MMC controller at irq 42,32 bit host data width,128 deep fifo
[    0.513058] dwmmc_k3 f723e000.dwmmc1: Linked as a consumer to regulator.5
[    0.513131] dwmmc_k3 f723e000.dwmmc1: Linked as a consumer to regulator.4
[    0.513198] dwmmc_k3 f723e000.dwmmc1: Got CD GPIO
[    0.526150] mmc_host mmc1: Bus speed (slot 0) = 24800000Hz (slot req 400000Hz, actual 400000HZ div = 31)
[    0.540311] dwmmc_k3 f723f000.dwmmc2: fifo-depth property not found, using value of FIFOTH register as default
[    0.540450] dwmmc_k3 f723f000.dwmmc2: IDMAC supports 32-bit address mode.
[    0.541504] dwmmc_k3 f723f000.dwmmc2: Using internal DMA controller.
[    0.541528] dwmmc_k3 f723f000.dwmmc2: Version ID is 250a
[    0.541580] dwmmc_k3 f723f000.dwmmc2: DW MMC controller at irq 43,32 bit host data width,128 deep fifo
[    0.541678] dwmmc_k3 f723f000.dwmmc2: Linked as a consumer to regulator.2
[    0.541760] dwmmc_k3 f723f000.dwmmc2: allocated mmc-pwrseq
[    0.541776] mmc_host mmc2: card is non-removable.
[    0.541896] dwmmc_k3 f723f000.dwmmc2: mmc_pwrseq_simple_pre_power_on clk_prepare_enable()
[    0.554372] mmc_host mmc2: Bus speed (slot 0) = 24800000Hz (slot req 400000Hz, actual 400000HZ div = 31)
[    0.567010] sdhci-pltfm: SDHCI platform and OF driver helper
[    0.569070] ledtrig-cpu: registered to indicate activity on CPUs
[    0.570064] usbcore: registered new interface driver usbhid
[    0.570087] usbhid: USB HID core driver
[    0.571877] NET: Registered protocol family 10
[    0.572489] Segment Routing with IPv6
[    0.572548] NET: Registered protocol family 17
[    0.572616] 9pnet: Installing 9P2000 support
[    0.572690] Key type dns_resolver registered
[    0.573216] registered taskstats version 1
[    0.573229] Loading compiled-in X.509 certificates
[    0.578841] f7111000.uart: ttyAMA1 at MMIO 0xf7111000 (irq = 8, base_baud = 0) is a PL011 rev2
[    0.579405] f7112000.uart: ttyAMA2 at MMIO 0xf7112000 (irq = 9, base_baud = 0) is a PL011 rev2
[    0.579754] f7113000.uart: ttyAMA3 at MMIO 0xf7113000 (irq = 10, base_baud = 0) is a PL011 rev2
[    0.580809] dwmmc_k3 f723f000.dwmmc2: mmc_pwrseq_simple_power_off clk_disable_unprepare()
[    0.584406] mmc_host mmc0: Bus speed (slot 0) = 198400000Hz (slot req 200000000Hz, actual 198400000HZ div = 0)
[    0.584840] mmc0: new HS200 MMC card at address 0001
[    0.585647] mmcblk0: mmc0:0001 H8G1e 7.28 GiB
[    0.586215] console [ttyAMA3] enabled
[    0.586326] mmcblk0boot0: mmc0:0001 H8G1e partition 1 4.00 MiB
[    0.586920] mmcblk0boot1: mmc0:0001 H8G1e partition 2 4.00 MiB
[    0.587058] mmcblk0rpmb: mmc0:0001 H8G1e partition 3 4.00 MiB, chardev (241:0)
[    0.590367]  mmcblk0: p1 p2 p3 p4 p5 p6 p7 p8 p9
[    0.600720] dwmmc_k3 f723f000.dwmmc2: mmc_pwrseq_simple_pre_power_on clk_prepare_enable()
[    0.604750] 5V_HUB: supplied by SYS_5V
[    0.618550] mmc_host mmc2: Bus speed (slot 0) = 24800000Hz (slot req 300000Hz, actual 295238HZ div = 42)
[    0.620103] ssp-pl022 f7106000.spi: ARM PL022 driver, device ID: 0x00041022
[    0.648998] dwmmc_k3 f723f000.dwmmc2: card claims to support voltages below defined range
[    0.652706] ssp-pl022 f7106000.spi: mapped registers from 0x00000000f7106000 to (____ptrval____)
[    0.698032] mmc_host mmc2: Bus speed (slot 0) = 24800000Hz (slot req 25000000Hz, actual 24800000HZ div = 0)
[    0.703415] ssp-pl022 f7106000.spi: Failed to work in dma mode, work without dma!
[    0.709637] mmc (null): mmc_attach_sdio Enabled runtime PM()
[    0.719864] phy phy-soc:usbphy.0: Linked as a consumer to regulator.13
[    0.725031] random: fast init done
[    0.729308] dwc2 f72c0000.usb: f72c0000.usb supply vusb_d not found, using dummy regulator
[    0.736405] mmc2: new SDIO card at address 0001
[    0.741034] dwc2 f72c0000.usb: Linked as a consumer to regulator.0
[    2.247186] dwc2 f72c0000.usb: f72c0000.usb supply vusb_a not found, using dummy regulator
[    2.247462] mmc mmc2:0001: mmc_attach_sdio pm_runtime_put()
[    2.255571] mmc_host mmc1: Bus speed (slot 0) = 99200000Hz (slot req 100000000Hz, actual 99200000HZ div = 0)
[    2.261083] mmc mmc2:0001: mmc_sdio_runtime_suspend
[    2.270923] mmc1: new ultra high speed SDR50 SDHC card at address 1234
[    2.275843] dwmmc_k3 f723f000.dwmmc2: mmc_pwrseq_simple_power_off clk_disable_unprepare()
[    2.283288] mmcblk1: mmc1:1234 SA16G 14.6 GiB
[    2.291814] mmc mmc2:0001: mmc_sdio_runtime_suspend - DONE
[    2.301156] GPT:Primary header thinks Alt. header is not at the end of the disk.
[    2.308588] GPT:755225 != 30703615
[    2.312008] GPT:Alternate GPT header not at the end of the disk.
[    2.318034] GPT:755225 != 30703615
[    2.321451] GPT: Use GNU Parted to correct GPT errors.
[    2.326634]  mmcblk1: p1 p2
[    2.490661] dwc2 f72c0000.usb: EPs: 16, dedicated fifos, 1920 entries in SPRAM
[    2.500154] dwc2 f72c0000.usb: DWC OTG Controller
[    2.504920] dwc2 f72c0000.usb: new USB bus registered, assigned bus number 1
[    2.512023] dwc2 f72c0000.usb: irq 39, io mem 0xf72c0000
[    2.518435] hub 1-0:1.0: USB hub found
[    2.522226] hub 1-0:1.0: 1 port detected
[    2.528390] rtc-efi rtc-efi: setting system clock to 1970-01-01 00:00:13 UTC (13)
[    2.536174] LDO2_2V8: disabling
[    2.539338] LDO13_1V8: disabling
[    2.542577] LDO14_2V8: disabling
[    2.545810] LDO17_2V5: disabling
[    2.549423] uart-pl011 f7113000.uart: no DMA platform data
[    2.555375] Freeing unused kernel memory: 1152K
[    2.559995] Run /init as init process
[    2.591174] random: systemd-udevd: uninitialized urandom read (16 bytes read)
[    2.594870] random: udevadm: uninitialized urandom read (16 bytes read)
[    2.598927] random: systemd-udevd: uninitialized urandom read (16 bytes read)
[    2.922606] dwc2 f72c0000.usb: Set speed to high-speed
[    2.927796] usb 1-1: new high-speed USB device number 2 using dwc2
[    3.122609] dwc2 f72c0000.usb: Set speed to high-speed
[    3.149712] hub 1-1:1.0: USB hub found
[    3.154043] hub 1-1:1.0: 3 ports detected
[    3.439743] EXT4-fs (mmcblk1p2): mounted filesystem with ordered data mode. Opts: (null)
[    3.788928] systemd[1]: System time before build time, advancing clock.
[    3.823109] systemd[1]: systemd 232 running in system mode. (+PAM +AUDIT +SELINUX +IMA +APPARMOR +SMACK +SYSVINIT +UTMP +LIBCRYPTSETUP +GCRYPT +GNUTLS +ACL +XZ +LZ4 +SECCOMP +BLKID +ELFUTILS +KMOD +IDN)
[    3.841569] systemd[1]: Detected architecture arm64.
[    3.863341] systemd[1]: Set hostname to <demo>.
[    4.102781] systemd[1]: Listening on Journal Socket.
[    4.123099] systemd[1]: Created slice System Slice.
[    4.148749] systemd[1]: Starting Load Kernel Modules...
[    4.166761] systemd[1]: Listening on Journal Audit Socket.
[    4.187161] systemd[1]: Created slice system-serial\x2dgetty.slice.
[    4.204064] jailhouse: loading out-of-tree module taints kernel.
[    4.221264] systemd[1]: Mounting Huge Pages File System...
[    4.238907] systemd[1]: Listening on /dev/initctl Compatibility Named Pipe.
[    4.372111] EXT4-fs (mmcblk1p2): re-mounted. Opts: (null)
[    4.888925] systemd-journald[1590]: Received request to flush runtime journal from PID 1
[    5.069003] random: crng init done
[    5.069013] random: 7 urandom warning(s) missed due to ratelimiting
[    5.792047] k3-dma f7370000.dma: initialized
[    6.216442] mmc mmc2:0001: mmc_sdio_runtime_resume
[    6.216476] dwmmc_k3 f723f000.dwmmc2: mmc_pwrseq_simple_pre_power_on clk_prepare_enable()
[    6.226783] mmc_host mmc2: Bus speed (slot 0) = 24800000Hz (slot req 300000Hz, actual 295238HZ div = 42)
[    6.251465] mmc mmc2:0001: mmc_sdio_runtime_resume - ret=-110 DONE
[    6.251543] wl1271_sdio mmc2:0001:1: sdio_bus_probe
[    6.251550] wl1271_sdio mmc2:0001:1: sdio_bus_probe - pm_runtime_get_sync()
[    6.251557] wl1271_sdio mmc2:0001:1: sdio_bus_probe - ERR call pm_runtime_put_noidle()
[    6.251573] wl1271_sdio: probe of mmc2:0001:1 failed with error -16
[    6.251612] wl1271_sdio mmc2:0001:2: sdio_bus_probe
[    6.251618] wl1271_sdio mmc2:0001:2: sdio_bus_probe - pm_runtime_get_sync()
[    6.251623] wl1271_sdio mmc2:0001:2: sdio_bus_probe - ERR call pm_runtime_put_noidle()
[    6.251631] wl1271_sdio: probe of mmc2:0001:2 failed with error -16
[    6.329559] EXT4-fs (mmcblk1p2): resizing filesystem from 359164 to 15333356 blocks
[   13.573757] EXT4-fs (mmcblk1p2): resized filesystem to 15333356

Kalle Valo Jan. 22, 2019, 4:24 p.m. UTC | #15

Ulf Hansson <[e-mail]> wrote:

> During "wlan-up", we are programming the FW into the WiFi-chip. However,
> re-programming the FW doesn't work, unless a power cycle of the WiFi-chip
> is made in-between the programmings.
> 
> To conform to this requirement and to fix the regression in a simple way,
> let's start by allowing that the SDIO card (WiFi-chip) may stay powered on
> (runtime resumed) when wl12xx_sdio_power_off() returns. The intent with the
> current code is to treat this scenario as an error, but unfortunate this
> doesn't work as expected, so let's fix this.
> 
> The other part is to guarantee that a power cycle of the SDIO card has been
> completed when wl12xx_sdio_power_on() returns, as to allow the FW
> programming to succeed. However, relying solely on runtime PM to deal with
> this isn't sufficient. For example, userspace may prevent runtime suspend
> via sysfs for the device that represents the SDIO card, leading to that the
> mmc core also keeps it powered on. For this reason, let's instead do a
> brute force power cycle in wl12xx_sdio_power_on().
> 
> Fixes: 728a9dc61f13 ("wlcore: sdio: Fix flakey SDIO runtime PM handling")
> Signed-off-by: Ulf Hansson <[e-mail]>
> Tested-by: Tony Lindgren <[e-mail]>
> Tested-by: Anders Roxell <[e-mail]>
> Signed-off-by: Ulf Hansson <[e-mail]>

Patch applied to wireless-drivers.git, thanks.

13e62626c578 wlcore: sdio: Fixup power on/off sequence

Ulf Hansson Jan. 23, 2019, 8:50 a.m. UTC | #16

On Tue, 22 Jan 2019 at 17:08, Jan Kiszka <[e-mail]> wrote:
>
> On 21.01.19 15:40, Ulf Hansson wrote:
> > On Fri, 18 Jan 2019 at 16:09, Ulf Hansson <[e-mail]> wrote:
> >>
> >> On Fri, 18 Jan 2019 at 13:09, Jan Kiszka <[e-mail]> wrote:
> >>>
> >>> On 17.01.19 10:54, Ulf Hansson wrote:
> >>>> On Wed, 16 Jan 2019 at 21:26, Jan Kiszka <[e-mail]> wrote:
> >>>>>
> >>>>> On 16.01.19 12:37, Ulf Hansson wrote:
> >>>>>> During "wlan-up", we are programming the FW into the WiFi-chip. However,
> >>>>>> re-programming the FW doesn't work, unless a power cycle of the WiFi-chip
> >>>>>> is made in-between the programmings.
> >>>>>>
> >>>>>> To conform to this requirement and to fix the regression in a simple way,
> >>>>>> let's start by allowing that the SDIO card (WiFi-chip) may stay powered on
> >>>>>> (runtime resumed) when wl12xx_sdio_power_off() returns. The intent with the
> >>>>>> current code is to treat this scenario as an error, but unfortunate this
> >>>>>> doesn't work as expected, so let's fix this.
> >>>>>>
> >>>>>> The other part is to guarantee that a power cycle of the SDIO card has been
> >>>>>> completed when wl12xx_sdio_power_on() returns, as to allow the FW
> >>>>>> programming to succeed. However, relying solely on runtime PM to deal with
> >>>>>> this isn't sufficient. For example, userspace may prevent runtime suspend
> >>>>>> via sysfs for the device that represents the SDIO card, leading to that the
> >>>>>> mmc core also keeps it powered on. For this reason, let's instead do a
> >>>>>> brute force power cycle in wl12xx_sdio_power_on().
> >>>>>>
> >>>>>> Fixes: 728a9dc61f13 ("wlcore: sdio: Fix flakey SDIO runtime PM handling")
> >>>>>> Signed-off-by: Ulf Hansson <[e-mail]>
> >>>>>> ---
> >>>>>>
> >>>>>> Changes in v2:
> >>>>>>         - Keep the SDIO host claimed when calling mmc_hw_reset().
> >>>>>>         - Add a fixes tag.
> >>>>>> ---
> >>>>>>     drivers/net/wireless/ti/wlcore/sdio.c | 15 +++++++--------
> >>>>>>     1 file changed, 7 insertions(+), 8 deletions(-)
> >>>>>>
> >>>>>> diff --git a/drivers/net/wireless/ti/wlcore/sdio.c b/drivers/net/wireless/ti/wlcore/sdio.c
> >>>>>> index bd10165d7eec..4d4b07701149 100644
> >>>>>> --- a/drivers/net/wireless/ti/wlcore/sdio.c
> >>>>>> +++ b/drivers/net/wireless/ti/wlcore/sdio.c
> >>>>>> @@ -164,6 +164,12 @@ static int wl12xx_sdio_power_on(struct wl12xx_sdio_glue *glue)
> >>>>>>         }
> >>>>>>
> >>>>>>         sdio_claim_host(func);
> >>>>>> +     /*
> >>>>>> +      * To guarantee that the SDIO card is power cycled, as required to make
> >>>>>> +      * the FW programming to succeed, let's do a brute force HW reset.
> >>>>>> +      */
> >>>>>> +     mmc_hw_reset(card->host);
> >>>>>> +
> >>>>>>         sdio_enable_func(func);
> >>>>>>         sdio_release_host(func);
> >>>>>>
> >>>>>> @@ -174,20 +180,13 @@ static int wl12xx_sdio_power_off(struct wl12xx_sdio_glue *glue)
> >>>>>>     {
> >>>>>>         struct sdio_func *func = dev_to_sdio_func(glue->dev);
> >>>>>>         struct mmc_card *card = func->card;
> >>>>>> -     int error;
> >>>>>>
> >>>>>>         sdio_claim_host(func);
> >>>>>>         sdio_disable_func(func);
> >>>>>>         sdio_release_host(func);
> >>>>>>
> >>>>>>         /* Let runtime PM know the card is powered off */
> >>>>>> -     error = pm_runtime_put(&card->dev);
> >>>>>> -     if (error < 0 && error != -EBUSY) {
> >>>>>> -             dev_err(&card->dev, "%s failed: %i\n", __func__, error);
> >>>>>> -
> >>>>>> -             return error;
> >>>>>> -     }
> >>>>>> -
> >>>>>> +     pm_runtime_put(&card->dev);
> >>>>>>         return 0;
> >>>>>>     }
> >>>>>>
> >>>>>>
> >>>>>
> >>>>> Just tested on both HiKey (620) and Ultra96 but it fails to fix the issue on
> >>>>> both. I'm getting
> >>>>>
> >>>>> wl1271_sdio: probe of mmc2:0001:1 failed with error -16
> >>>>>
> >>>>> during boot again, and the interface is not available.
> >>>>
> >>>> Okay, sounds like this may be a different problem then. Can you share
> >>>> the complete log and the kernel config?
> >>>
> >>> You can find the config here [1], log from the HiKey boot attached.
> >>>
> >>>> I can prepare a debug patch as well, if you are willing to re-run the test?
> >>>
> >>> Sure, send it over, I can run it.
> >>
> >> Alright, sounds great. However, I need to defer that to Monday/Tuesday
> >> next week.
> >>
> >>>
> >>>>
> >>>> Adding a post-power-on-delay-ms of 1 ms as you suggested [1], doesn't
> >>>> sounds like the correct solution to me, unless I am overlooking some
> >>>> things. The point is, since the mmc core succeeds to detect and
> >>>> initialize the SDIO card, the power sequence seems to be correct.
> >>>
> >>> Yeah, I'm not claiming at all I know what I'm doing there, just that it happens
> >>> to work.
> >>
> >> I see. Good to know, thanks!
> >>
> >>>
> >>> Jan
> >>>
> >>> [1]
> >>> https://github.com/siemens/jailhouse-images/blob/next/recipes-kernel/linux/files/arm64_defconfig_4.19
> >>
> >> I have looked through the log and the defconfig. No obvious things
> >> found at this point. Thanks for sharing them!
> >>
> >
> > So, I have put together a debug patch, mostly to verify that things
> > seems to be correct in regards to runtime PM. It should produce some
> > prints to the log, particular during power on/off of the SDIO card and
> > during probe of the wifi driver. Please re-run the test on top of the
> > v2 version of the $subject patch.
> >
>
> Log attached.

Thanks! Okay, so the re-initialization of the SDIO card is failing,
that's very valuable information.

I noticed one difference while comparing your log with the one I
received (offlist) from Anders... In your case the initialization
frequency that works the first time is 300KHz, while in Anders case
it's 100KHz. This sounds a bit fishy to me, so maybe there are some
problems with the pwrseq after all.

Let me think a bit and see what I can come up with as a possible solution.

In the meantime, can you re-run the test with same debug patch, but
change the post-power-on-delay-ms to let's say 10 ms in the DTS? I am
going to ask Anders to do the same test on his side, as to see if we
get different values of the found initialization frequency.

Kind regards
Uffe

Ulf Hansson Jan. 23, 2019, 8:52 a.m. UTC | #17

On Tue, 22 Jan 2019 at 17:24, Kalle Valo <[e-mail]> wrote:
>
> Ulf Hansson <[e-mail]> wrote:
>
> > During "wlan-up", we are programming the FW into the WiFi-chip. However,
> > re-programming the FW doesn't work, unless a power cycle of the WiFi-chip
> > is made in-between the programmings.
> >
> > To conform to this requirement and to fix the regression in a simple way,
> > let's start by allowing that the SDIO card (WiFi-chip) may stay powered on
> > (runtime resumed) when wl12xx_sdio_power_off() returns. The intent with the
> > current code is to treat this scenario as an error, but unfortunate this
> > doesn't work as expected, so let's fix this.
> >
> > The other part is to guarantee that a power cycle of the SDIO card has been
> > completed when wl12xx_sdio_power_on() returns, as to allow the FW
> > programming to succeed. However, relying solely on runtime PM to deal with
> > this isn't sufficient. For example, userspace may prevent runtime suspend
> > via sysfs for the device that represents the SDIO card, leading to that the
> > mmc core also keeps it powered on. For this reason, let's instead do a
> > brute force power cycle in wl12xx_sdio_power_on().
> >
> > Fixes: 728a9dc61f13 ("wlcore: sdio: Fix flakey SDIO runtime PM handling")
> > Signed-off-by: Ulf Hansson <[e-mail]>
> > Tested-by: Tony Lindgren <[e-mail]>
> > Tested-by: Anders Roxell <[e-mail]>
> > Signed-off-by: Ulf Hansson <[e-mail]>
>
> Patch applied to wireless-drivers.git, thanks.
>
> 13e62626c578 wlcore: sdio: Fixup power on/off sequence

Great, thanks! Let's see how we can fix Jan's problem on top.

Kind regards
Uffe

Jan Kiszka Jan. 23, 2019, 8:17 p.m. UTC | #18

On 23.01.19 09:50, Ulf Hansson wrote:
> On Tue, 22 Jan 2019 at 17:08, Jan Kiszka <[e-mail]> wrote:
>>
>> On 21.01.19 15:40, Ulf Hansson wrote:
>>> On Fri, 18 Jan 2019 at 16:09, Ulf Hansson <[e-mail]> wrote:
>>>>
>>>> On Fri, 18 Jan 2019 at 13:09, Jan Kiszka <[e-mail]> wrote:
>>>>>
>>>>> On 17.01.19 10:54, Ulf Hansson wrote:
>>>>>> On Wed, 16 Jan 2019 at 21:26, Jan Kiszka <[e-mail]> wrote:
>>>>>>>
>>>>>>> On 16.01.19 12:37, Ulf Hansson wrote:
>>>>>>>> During "wlan-up", we are programming the FW into the WiFi-chip. However,
>>>>>>>> re-programming the FW doesn't work, unless a power cycle of the WiFi-chip
>>>>>>>> is made in-between the programmings.
>>>>>>>>
>>>>>>>> To conform to this requirement and to fix the regression in a simple way,
>>>>>>>> let's start by allowing that the SDIO card (WiFi-chip) may stay powered on
>>>>>>>> (runtime resumed) when wl12xx_sdio_power_off() returns. The intent with the
>>>>>>>> current code is to treat this scenario as an error, but unfortunate this
>>>>>>>> doesn't work as expected, so let's fix this.
>>>>>>>>
>>>>>>>> The other part is to guarantee that a power cycle of the SDIO card has been
>>>>>>>> completed when wl12xx_sdio_power_on() returns, as to allow the FW
>>>>>>>> programming to succeed. However, relying solely on runtime PM to deal with
>>>>>>>> this isn't sufficient. For example, userspace may prevent runtime suspend
>>>>>>>> via sysfs for the device that represents the SDIO card, leading to that the
>>>>>>>> mmc core also keeps it powered on. For this reason, let's instead do a
>>>>>>>> brute force power cycle in wl12xx_sdio_power_on().
>>>>>>>>
>>>>>>>> Fixes: 728a9dc61f13 ("wlcore: sdio: Fix flakey SDIO runtime PM handling")
>>>>>>>> Signed-off-by: Ulf Hansson <[e-mail]>
>>>>>>>> ---
>>>>>>>>
>>>>>>>> Changes in v2:
>>>>>>>>          - Keep the SDIO host claimed when calling mmc_hw_reset().
>>>>>>>>          - Add a fixes tag.
>>>>>>>> ---
>>>>>>>>      drivers/net/wireless/ti/wlcore/sdio.c | 15 +++++++--------
>>>>>>>>      1 file changed, 7 insertions(+), 8 deletions(-)
>>>>>>>>
>>>>>>>> diff --git a/drivers/net/wireless/ti/wlcore/sdio.c b/drivers/net/wireless/ti/wlcore/sdio.c
>>>>>>>> index bd10165d7eec..4d4b07701149 100644
>>>>>>>> --- a/drivers/net/wireless/ti/wlcore/sdio.c
>>>>>>>> +++ b/drivers/net/wireless/ti/wlcore/sdio.c
>>>>>>>> @@ -164,6 +164,12 @@ static int wl12xx_sdio_power_on(struct wl12xx_sdio_glue *glue)
>>>>>>>>          }
>>>>>>>>
>>>>>>>>          sdio_claim_host(func);
>>>>>>>> +     /*
>>>>>>>> +      * To guarantee that the SDIO card is power cycled, as required to make
>>>>>>>> +      * the FW programming to succeed, let's do a brute force HW reset.
>>>>>>>> +      */
>>>>>>>> +     mmc_hw_reset(card->host);
>>>>>>>> +
>>>>>>>>          sdio_enable_func(func);
>>>>>>>>          sdio_release_host(func);
>>>>>>>>
>>>>>>>> @@ -174,20 +180,13 @@ static int wl12xx_sdio_power_off(struct wl12xx_sdio_glue *glue)
>>>>>>>>      {
>>>>>>>>          struct sdio_func *func = dev_to_sdio_func(glue->dev);
>>>>>>>>          struct mmc_card *card = func->card;
>>>>>>>> -     int error;
>>>>>>>>
>>>>>>>>          sdio_claim_host(func);
>>>>>>>>          sdio_disable_func(func);
>>>>>>>>          sdio_release_host(func);
>>>>>>>>
>>>>>>>>          /* Let runtime PM know the card is powered off */
>>>>>>>> -     error = pm_runtime_put(&card->dev);
>>>>>>>> -     if (error < 0 && error != -EBUSY) {
>>>>>>>> -             dev_err(&card->dev, "%s failed: %i\n", __func__, error);
>>>>>>>> -
>>>>>>>> -             return error;
>>>>>>>> -     }
>>>>>>>> -
>>>>>>>> +     pm_runtime_put(&card->dev);
>>>>>>>>          return 0;
>>>>>>>>      }
>>>>>>>>
>>>>>>>>
>>>>>>>
>>>>>>> Just tested on both HiKey (620) and Ultra96 but it fails to fix the issue on
>>>>>>> both. I'm getting
>>>>>>>
>>>>>>> wl1271_sdio: probe of mmc2:0001:1 failed with error -16
>>>>>>>
>>>>>>> during boot again, and the interface is not available.
>>>>>>
>>>>>> Okay, sounds like this may be a different problem then. Can you share
>>>>>> the complete log and the kernel config?
>>>>>
>>>>> You can find the config here [1], log from the HiKey boot attached.
>>>>>
>>>>>> I can prepare a debug patch as well, if you are willing to re-run the test?
>>>>>
>>>>> Sure, send it over, I can run it.
>>>>
>>>> Alright, sounds great. However, I need to defer that to Monday/Tuesday
>>>> next week.
>>>>
>>>>>
>>>>>>
>>>>>> Adding a post-power-on-delay-ms of 1 ms as you suggested [1], doesn't
>>>>>> sounds like the correct solution to me, unless I am overlooking some
>>>>>> things. The point is, since the mmc core succeeds to detect and
>>>>>> initialize the SDIO card, the power sequence seems to be correct.
>>>>>
>>>>> Yeah, I'm not claiming at all I know what I'm doing there, just that it happens
>>>>> to work.
>>>>
>>>> I see. Good to know, thanks!
>>>>
>>>>>
>>>>> Jan
>>>>>
>>>>> [1]
>>>>> https://github.com/siemens/jailhouse-images/blob/next/recipes-kernel/linux/files/arm64_defconfig_4.19
>>>>
>>>> I have looked through the log and the defconfig. No obvious things
>>>> found at this point. Thanks for sharing them!
>>>>
>>>
>>> So, I have put together a debug patch, mostly to verify that things
>>> seems to be correct in regards to runtime PM. It should produce some
>>> prints to the log, particular during power on/off of the SDIO card and
>>> during probe of the wifi driver. Please re-run the test on top of the
>>> v2 version of the $subject patch.
>>>
>>
>> Log attached.
>
> Thanks! Okay, so the re-initialization of the SDIO card is failing,
> that's very valuable information.
>
> I noticed one difference while comparing your log with the one I
> received (offlist) from Anders... In your case the initialization
> frequency that works the first time is 300KHz, while in Anders case
> it's 100KHz. This sounds a bit fishy to me, so maybe there are some
> problems with the pwrseq after all.
>
> Let me think a bit and see what I can come up with as a possible solution.
>
> In the meantime, can you re-run the test with same debug patch, but
> change the post-power-on-delay-ms to let's say 10 ms in the DTS? I am
> going to ask Anders to do the same test on his side, as to see if we
> get different values of the found initialization frequency.

Here is a log with 10 ms power-on-delay.

Jan
[    0.000000] Booting Linux on physical CPU 0x0000000000 [0x410fd033]
[    0.000000] Linux version 4.19.16 (builder@a9d1a77f2ff6) (gcc version 6.3.0 20170516 (Debian 6.3.0-18)) #1 SMP PREEMPT Wed Jan 23 17:59:41 UTC 2019
[    0.000000] Machine model: HiKey Development Board
[    0.000000] Memory limited to 1820MB
[    0.000000] efi: Getting EFI parameters from FDT:
[    0.000000] efi: EFI v2.60 by EDK II
[    0.000000] efi:  MEMATTR=0x3cd48a98
[    0.000000] Reserved memory: created CMA memory pool at 0x000000006bc00000, size 128 MiB
[    0.000000] OF: reserved mem: initialized node linux,cma, compatible id shared-dma-pool
[    0.000000] NUMA: No NUMA configuration found
[    0.000000] NUMA: Faking a node at [mem 0x0000000000000000-0x0000000073ef2fff]
[    0.000000] NUMA: NODE_DATA [mem 0x73ea95c0-0x73eaad7f]
[    0.000000] Zone ranges:
[    0.000000]   DMA32    [mem 0x0000000000000000-0x0000000073ef2fff]
[    0.000000]   Normal   empty
[    0.000000] Movable zone start for each node
[    0.000000] Early memory node ranges
[    0.000000]   node   0: [mem 0x0000000000000000-0x0000000005dfffff]
[    0.000000]   node   0: [mem 0x0000000005f00000-0x0000000005f00fff]
[    0.000000]   node   0: [mem 0x0000000005f02000-0x0000000006dfefff]
[    0.000000]   node   0: [mem 0x0000000006e00000-0x000000000740efff]
[    0.000000]   node   0: [mem 0x0000000007410000-0x0000000021efffff]
[    0.000000]   node   0: [mem 0x0000000022000000-0x0000000034ffffff]
[    0.000000]   node   0: [mem 0x00000000350f0000-0x000000003864ffff]
[    0.000000]   node   0: [mem 0x0000000038650000-0x000000003888ffff]
[    0.000000]   node   0: [mem 0x0000000038890000-0x0000000038897fff]
[    0.000000]   node   0: [mem 0x0000000038898000-0x000000003889bfff]
[    0.000000]   node   0: [mem 0x000000003889c000-0x000000003d85ffff]
[    0.000000]   node   0: [mem 0x000000003d860000-0x000000003d89ffff]
[    0.000000]   node   0: [mem 0x000000003d8a0000-0x000000003d8affff]
[    0.000000]   node   0: [mem 0x000000003d8b0000-0x000000003d8fffff]
[    0.000000]   node   0: [mem 0x000000003d900000-0x000000003dffffff]
[    0.000000]   node   0: [mem 0x0000000040000000-0x0000000073ef2fff]
[    0.000000] Reserved but unavailable: 256 pages
[    0.000000] Initmem setup node 0 [mem 0x0000000000000000-0x0000000073ef2fff]
[    0.000000] On node 0 totalpages: 465920
[    0.000000]   DMA32 zone: 7420 pages used for memmap
[    0.000000]   DMA32 zone: 0 pages reserved
[    0.000000]   DMA32 zone: 465920 pages, LIFO batch:63
[    0.000000] psci: probing for conduit method from DT.
[    0.000000] psci: PSCIv1.1 detected in firmware.
[    0.000000] psci: Using standard PSCI v0.2 function IDs
[    0.000000] psci: Trusted OS migration not required
[    0.000000] psci: SMC Calling Convention v1.1
[    0.000000] random: get_random_bytes called from start_kernel+0xac/0x414 with crng_init=0
[    0.000000] percpu: Embedded 22 pages/cpu @(____ptrval____) s53016 r8192 d28904 u90112
[    0.000000] pcpu-alloc: s53016 r8192 d28904 u90112 alloc=22*4096
[    0.000000] pcpu-alloc: [0] 0 [0] 1 [0] 2 [0] 3 [0] 4 [0] 5 [0] 6 [0] 7
[    0.000000] Detected VIPT I-cache on CPU0
[    0.000000] CPU features: enabling workaround for ARM erratum 843419
[    0.000000] CPU features: enabling workaround for ARM erratum 845719
[    0.000000] Speculative Store Bypass Disable mitigation not required
[    0.000000] CPU features: detected: Kernel page table isolation (KPTI)
[    0.000000] Built 1 zonelists, mobility grouping on.  Total pages: 458500
[    0.000000] Policy zone: DMA32
[    0.000000] Kernel command line: BOOT_IMAGE=/vmlinuz root=PARTUUID=2aa1d65d-cfdc-4ffa-b59c-c70cb3e25633 rootwait mem=1820M
[    0.000000] Memory: 1676320K/1863680K available (9980K kernel code, 1294K rwdata, 4312K rodata, 1152K init, 371K bss, 56288K reserved, 131072K cma-reserved)
[    0.000000] SLUB: HWalign=64, Order=0-3, MinObjects=0, CPUs=8, Nodes=1
[    0.000000] rcu: Preemptible hierarchical RCU implementation.
[    0.000000] rcu: 	RCU restricting CPUs from NR_CPUS=64 to nr_cpu_ids=8.
[    0.000000] 	Tasks RCU enabled.
[    0.000000] rcu: Adjusting geometry for rcu_fanout_leaf=16, nr_cpu_ids=8
[    0.000000] NR_IRQS: 64, nr_irqs: 64, preallocated irqs: 0
[    0.000000] GIC: Using split EOI/Deactivate mode
[    0.000000] arch_timer: cp15 timer(s) running at 1.20MHz (phys).
[    0.000000] clocksource: arch_sys_counter: mask: 0xffffffffffffff max_cycles: 0x11b661f8e, max_idle_ns: 1763180809113 ns
[    0.000004] sched_clock: 56 bits at 1200kHz, resolution 833ns, wraps every 4398046510838ns
[    0.000126] clocksource: arm,sp804: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 99544814920 ns
[    0.000135] sched_clock: 32 bits at 19MHz, resolution 52ns, wraps every 111848106981ns
[    0.000801] Console: colour dummy device 80x25
[    0.001349] console [tty0] enabled
[    0.001433] Calibrating delay loop (skipped), value calculated using timer frequency.. 2.40 BogoMIPS (lpj=4800)
[    0.001457] pid_max: default: 32768 minimum: 301
[    0.001534] Security Framework initialized
[    0.002211] Dentry cache hash table entries: 262144 (order: 9, 2097152 bytes)
[    0.002554] Inode-cache hash table entries: 131072 (order: 8, 1048576 bytes)
[    0.002596] Mount-cache hash table entries: 4096 (order: 3, 32768 bytes)
[    0.002624] Mountpoint-cache hash table entries: 4096 (order: 3, 32768 bytes)
[    0.024001] ASID allocator initialised with 32768 entries
[    0.031997] rcu: Hierarchical SRCU implementation.
[    0.042067] Remapping and enabling EFI services.
[    0.048040] smp: Bringing up secondary CPUs ...
[    0.080291] Detected VIPT I-cache on CPU1
[    0.080345] CPU1: Booted secondary processor 0x0000000001 [0x410fd033]
[    0.112305] Detected VIPT I-cache on CPU2
[    0.112331] CPU2: Booted secondary processor 0x0000000002 [0x410fd033]
[    0.144364] Detected VIPT I-cache on CPU3
[    0.144388] CPU3: Booted secondary processor 0x0000000003 [0x410fd033]
[    0.176479] Detected VIPT I-cache on CPU4
[    0.176519] CPU4: Booted secondary processor 0x0000000100 [0x410fd033]
[    0.208491] Detected VIPT I-cache on CPU5
[    0.208516] CPU5: Booted secondary processor 0x0000000101 [0x410fd033]
[    0.240557] Detected VIPT I-cache on CPU6
[    0.240580] CPU6: Booted secondary processor 0x0000000102 [0x410fd033]
[    0.272621] Detected VIPT I-cache on CPU7
[    0.272645] CPU7: Booted secondary processor 0x0000000103 [0x410fd033]
[    0.272733] smp: Brought up 1 node, 8 CPUs
[    0.272864] SMP: Total of 8 processors activated.
[    0.272877] CPU features: detected: 32-bit EL0 Support
[    0.277459] CPU: All CPU(s) started at EL2
[    0.277506] alternatives: patching kernel code
[    0.278231] devtmpfs: initialized
[    0.284194] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 7645041785100000 ns
[    0.284259] futex hash table entries: 2048 (order: 5, 131072 bytes)
[    0.288449] pinctrl core: initialized pinctrl subsystem
[    0.290020] DMI not present or invalid.
[    0.290393] NET: Registered protocol family 16
[    0.290790] audit: initializing netlink subsys (disabled)
[    0.290922] audit: type=2000 audit(0.288:1): state=initialized audit_enabled=0 res=1
[    0.292454] cpuidle: using governor menu
[    0.292657] vdso: 2 pages (1 code @ (____ptrval____), 1 data @ (____ptrval____))
[    0.292678] hw-breakpoint: found 6 breakpoint and 4 watchpoint registers.
[    0.298210] DMA: preallocated 256 KiB pool for atomic allocations
[    0.299481] Serial: AMBA PL011 UART driver
[    0.301783] f8015000.uart: ttyAMA0 at MMIO 0xf8015000 (irq = 7, base_baud = 0) is a PL011 rev2
[    0.307567] hi6220-mbox f7510000.mailbox: Mailbox enabled
[    0.320751] HugeTLB registered 2.00 MiB page size, pre-allocated 0 pages
[    0.321189] cryptd: max_cpu_qlen set to 1000
[    0.321948] ACPI: Interpreter disabled.
[    0.322765] VDD_3V3: supplied by SYS_5V
[    0.323184] vgaarb: loaded
[    0.323435] SCSI subsystem initialized
[    0.323651] libata version 3.00 loaded.
[    0.323953] usbcore: registered new interface driver usbfs
[    0.324002] usbcore: registered new interface driver hub
[    0.324107] usbcore: registered new device driver usb
[    0.324960] pps_core: LinuxPPS API ver. 1 registered
[    0.324974] pps_core: Software ver. 5.3.6 - Copyright 2005-2007 Rodolfo Giometti <[e-mail]>
[    0.325006] PTP clock support registered
[    0.325128] EDAC MC: Ver: 3.0.0
[    0.325428] Registered efivars operations
[    0.326780] clocksource: Switched to clocksource arch_sys_counter
[    0.326965] VFS: Disk quotas dquot_6.6.0
[    0.327023] VFS: Dquot-cache hash table entries: 512 (order 0, 4096 bytes)
[    0.327163] pnp: PnP ACPI: disabled
[    0.332699] NET: Registered protocol family 2
[    0.333225] tcp_listen_portaddr_hash hash table entries: 1024 (order: 2, 16384 bytes)
[    0.333310] TCP established hash table entries: 16384 (order: 5, 131072 bytes)
[    0.333467] TCP bind hash table entries: 16384 (order: 6, 262144 bytes)
[    0.333678] TCP: Hash tables configured (established 16384 bind 16384)
[    0.333789] UDP hash table entries: 1024 (order: 3, 32768 bytes)
[    0.333846] UDP-Lite hash table entries: 1024 (order: 3, 32768 bytes)
[    0.333998] NET: Registered protocol family 1
[    0.334352] RPC: Registered named UNIX socket transport module.
[    0.334365] RPC: Registered udp transport module.
[    0.334376] RPC: Registered tcp transport module.
[    0.334388] RPC: Registered tcp NFSv4.1 backchannel transport module.
[    0.334405] PCI: CLS 0 bytes, default 64
[    0.334542] Unpacking initramfs...
[    0.425489] Freeing initrd memory: 2372K
[    0.429435] Initialise system trusted keyrings
[    0.429581] workingset: timestamp_bits=44 max_order=19 bucket_order=0
[    0.435281] squashfs: version 4.0 (2009/01/31) Phillip Lougher
[    0.435949] NFS: Registering the id_resolver key type
[    0.435981] Key type id_resolver registered
[    0.435992] Key type id_legacy registered
[    0.436009] nfs4filelayout_init: NFSv4 File Layout Driver Registering...
[    0.436165] 9p: Installing v9fs 9p2000 file system support
[    0.436251] pstore: using deflate compression
[    0.438738] Key type asymmetric registered
[    0.438758] Asymmetric key parser 'x509' registered
[    0.438839] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 246)
[    0.438858] io scheduler noop registered
[    0.439004] io scheduler cfq registered (default)
[    0.439019] io scheduler mq-deadline registered
[    0.439030] io scheduler kyber registered
[    0.442121] pinctrl-single f7010000.pinmux: 159 pins, size 636
[    0.442672] pinctrl-single f7010800.pinmux: 163 pins, size 652
[    0.443068] pinctrl-single f8001800.pinmux: 30 pins, size 120
[    0.444788] pl061_gpio f8011000.gpio: PL061 GPIO chip @0x00000000f8011000 registered
[    0.445019] pl061_gpio f8012000.gpio: PL061 GPIO chip @0x00000000f8012000 registered
[    0.445191] pl061_gpio f8013000.gpio: PL061 GPIO chip @0x00000000f8013000 registered
[    0.445293] gpio gpiochip3: names 9 do not match number of GPIOs 8
[    0.445396] pl061_gpio f8014000.gpio: PL061 GPIO chip @0x00000000f8014000 registered
[    0.445568] pl061_gpio f7020000.gpio: PL061 GPIO chip @0x00000000f7020000 registered
[    0.445753] pl061_gpio f7021000.gpio: PL061 GPIO chip @0x00000000f7021000 registered
[    0.445931] pl061_gpio f7022000.gpio: PL061 GPIO chip @0x00000000f7022000 registered
[    0.446116] pl061_gpio f7023000.gpio: PL061 GPIO chip @0x00000000f7023000 registered
[    0.446208] gpio gpiochip8: names 9 do not match number of GPIOs 8
[    0.446306] pl061_gpio f7024000.gpio: PL061 GPIO chip @0x00000000f7024000 registered
[    0.446491] pl061_gpio f7025000.gpio: PL061 GPIO chip @0x00000000f7025000 registered
[    0.446697] pl061_gpio f7026000.gpio: PL061 GPIO chip @0x00000000f7026000 registered
[    0.446925] pl061_gpio f7027000.gpio: PL061 GPIO chip @0x00000000f7027000 registered
[    0.447119] pl061_gpio f7028000.gpio: PL061 GPIO chip @0x00000000f7028000 registered
[    0.447315] pl061_gpio f7029000.gpio: PL061 GPIO chip @0x00000000f7029000 registered
[    0.447494] pl061_gpio f702a000.gpio: PL061 GPIO chip @0x00000000f702a000 registered
[    0.447686] pl061_gpio f702b000.gpio: PL061 GPIO chip @0x00000000f702b000 registered
[    0.447871] pl061_gpio f702c000.gpio: PL061 GPIO chip @0x00000000f702c000 registered
[    0.448064] pl061_gpio f702d000.gpio: PL061 GPIO chip @0x00000000f702d000 registered
[    0.448243] pl061_gpio f702e000.gpio: PL061 GPIO chip @0x00000000f702e000 registered
[    0.448432] pl061_gpio f702f000.gpio: PL061 GPIO chip @0x00000000f702f000 registered
[    0.457044] Serial: 8250/16550 driver, 4 ports, IRQ sharing enabled
[    0.458604] SuperH (H)SCI(F) driver initialized
[    0.458944] msm_serial: driver initialized
[    0.466574] loop: module loaded
[    0.472927] libphy: Fixed MDIO Bus: probed
[    0.473747] tun: Universal TUN/TAP device driver, 1.6
[    0.474730] e1000e: Intel(R) PRO/1000 Network Driver - 3.2.6-k
[    0.474753] e1000e: Copyright(c) 1999 - 2015 Intel Corporation.
[    0.474827] igb: Intel(R) Gigabit Ethernet Network Driver - version 5.4.0-k
[    0.474842] igb: Copyright (c) 2007-2014 Intel Corporation.
[    0.474886] igbvf: Intel(R) Gigabit Virtual Function Network Driver - version 2.4.0-k
[    0.474902] igbvf: Copyright (c) 2009 - 2012 Intel Corporation.
[    0.475163] sky2: driver version 1.30
[    0.475622] VFIO - User Level meta-driver version: 0.3
[    0.476795] ehci_hcd: USB 2.0 'Enhanced' Host Controller (EHCI) Driver
[    0.476818] ehci-pci: EHCI PCI platform driver
[    0.476858] ehci-platform: EHCI generic platform driver
[    0.476957] ehci-orion: EHCI orion driver
[    0.477032] ehci-exynos: EHCI EXYNOS driver
[    0.477105] ohci_hcd: USB 1.1 'Open' Host Controller (OHCI) Driver
[    0.477137] ohci-pci: OHCI PCI platform driver
[    0.477178] ohci-platform: OHCI generic platform driver
[    0.477261] ohci-exynos: OHCI EXYNOS driver
[    0.477611] usbcore: registered new interface driver usb-storage
[    0.479541] rtc-efi rtc-efi: rtc core: registered rtc-efi as rtc0
[    0.479903] rtc-pl031 f8003000.rtc: rtc core: registered pl031 as rtc1
[    0.480211] rtc-pl031 f8004000.rtc: rtc core: registered pl031 as rtc2
[    0.480731] i2c /dev entries driver
[    0.484962] sdhci: Secure Digital Host Controller Interface driver
[    0.484992] sdhci: Copyright(c) Pierre Ossman
[    0.485166] Synopsys Designware Multimedia Card Interface Driver
[    0.485765] dwmmc_k3 f723d000.dwmmc0: fifo-depth property not found, using value of FIFOTH register as default
[    0.485889] dwmmc_k3 f723d000.dwmmc0: IDMAC supports 32-bit address mode.
[    0.486903] dwmmc_k3 f723d000.dwmmc0: Using internal DMA controller.
[    0.486924] dwmmc_k3 f723d000.dwmmc0: Version ID is 250a
[    0.486990] dwmmc_k3 f723d000.dwmmc0: DW MMC controller at irq 41,32 bit host data width,256 deep fifo
[    0.487113] dwmmc_k3 f723d000.dwmmc0: Linked as a consumer to regulator.10
[    0.487193] mmc_host mmc0: card is non-removable.
[    0.500101] mmc_host mmc0: Bus speed (slot 0) = 24800000Hz (slot req 400000Hz, actual 400000HZ div = 31)
[    0.513254] dwmmc_k3 f723e000.dwmmc1: fifo-depth property not found, using value of FIFOTH register as default
[    0.513517] dwmmc_k3 f723e000.dwmmc1: IDMAC supports 32-bit address mode.
[    0.514226] dwmmc_k3 f723e000.dwmmc1: Using internal DMA controller.
[    0.514247] dwmmc_k3 f723e000.dwmmc1: Version ID is 250a
[    0.514298] dwmmc_k3 f723e000.dwmmc1: DW MMC controller at irq 42,32 bit host data width,128 deep fifo
[    0.514403] dwmmc_k3 f723e000.dwmmc1: Linked as a consumer to regulator.5
[    0.514453] dwmmc_k3 f723e000.dwmmc1: Linked as a consumer to regulator.4
[    0.514520] dwmmc_k3 f723e000.dwmmc1: Got CD GPIO
[    0.527407] mmc_host mmc1: Bus speed (slot 0) = 24800000Hz (slot req 400000Hz, actual 400000HZ div = 31)
[    0.541535] dwmmc_k3 f723f000.dwmmc2: fifo-depth property not found, using value of FIFOTH register as default
[    0.541674] dwmmc_k3 f723f000.dwmmc2: IDMAC supports 32-bit address mode.
[    0.542630] dwmmc_k3 f723f000.dwmmc2: Using internal DMA controller.
[    0.542653] dwmmc_k3 f723f000.dwmmc2: Version ID is 250a
[    0.542703] dwmmc_k3 f723f000.dwmmc2: DW MMC controller at irq 43,32 bit host data width,128 deep fifo
[    0.542824] dwmmc_k3 f723f000.dwmmc2: Linked as a consumer to regulator.2
[    0.542910] dwmmc_k3 f723f000.dwmmc2: allocated mmc-pwrseq
[    0.542926] mmc_host mmc2: card is non-removable.
[    0.543046] dwmmc_k3 f723f000.dwmmc2: mmc_pwrseq_simple_pre_power_on clk_prepare_enable()
[    0.574948] mmc_host mmc2: Bus speed (slot 0) = 24800000Hz (slot req 400000Hz, actual 400000HZ div = 31)
[    0.588535] sdhci-pltfm: SDHCI platform and OF driver helper
[    0.589747] mmc_host mmc0: Bus speed (slot 0) = 198400000Hz (slot req 200000000Hz, actual 198400000HZ div = 0)
[    0.590218] mmc0: new HS200 MMC card at address 0001
[    0.591431] ledtrig-cpu: registered to indicate activity on CPUs
[    0.591933] mmcblk0: mmc0:0001 H8G1e 7.28 GiB
[    0.592628] mmcblk0boot0: mmc0:0001 H8G1e partition 1 4.00 MiB
[    0.592959] usbcore: registered new interface driver usbhid
[    0.592977] usbhid: USB HID core driver
[    0.593340] mmcblk0boot1: mmc0:0001 H8G1e partition 2 4.00 MiB
[    0.593494] mmcblk0rpmb: mmc0:0001 H8G1e partition 3 4.00 MiB, chardev (241:0)
[    0.594671] mmc_host mmc1: Bus speed (slot 0) = 99200000Hz (slot req 100000000Hz, actual 99200000HZ div = 0)
[    0.594724] mmc1: new ultra high speed SDR50 SDHC card at address 1234
[    0.594917] dwmmc_k3 f723f000.dwmmc2: card claims to support voltages below defined range
[    0.595199] NET: Registered protocol family 10
[    0.595964] mmcblk1: mmc1:1234 SA16G 14.6 GiB
[    0.596108] Segment Routing with IPv6
[    0.596206] NET: Registered protocol family 17
[    0.596273] 9pnet: Installing 9P2000 support
[    0.596343] Key type dns_resolver registered
[    0.596959] registered taskstats version 1
[    0.596978] Loading compiled-in X.509 certificates
[    0.597659]  mmcblk0: p1 p2 p3 p4 p5 p6 p7 p8 p9
[    0.602127]  mmcblk1: p1 p2
[    0.602869] f7111000.uart: ttyAMA1 at MMIO 0xf7111000 (irq = 8, base_baud = 0) is a PL011 rev2
[    0.603351] f7112000.uart: ttyAMA2 at MMIO 0xf7112000 (irq = 9, base_baud = 0) is a PL011 rev2
[    0.603821] f7113000.uart: ttyAMA3 at MMIO 0xf7113000 (irq = 10, base_baud = 0) is a PL011 rev2
[    0.777768] mmc_host mmc2: Bus speed (slot 0) = 24800000Hz (slot req 25000000Hz, actual 24800000HZ div = 0)
[    0.777784] mmc (null): mmc_attach_sdio Enabled runtime PM()
[    1.184324] random: fast init done
[    1.189466] console [ttyAMA3] enabled
[    2.218195] 5V_HUB: supplied by SYS_5V
[    2.222613] ssp-pl022 f7106000.spi: ARM PL022 driver, device ID: 0x00041022
[    2.229737] ssp-pl022 f7106000.spi: mapped registers from 0x00000000f7106000 to (____ptrval____)
[    2.238604] ssp-pl022 f7106000.spi: Failed to work in dma mode, work without dma!
[    2.246119] mmc2: new SDIO card at address 0001
[    2.250884] mmc mmc2:0001: mmc_attach_sdio pm_runtime_put()
[    2.256626] mmc mmc2:0001: mmc_sdio_runtime_suspend
[    2.261567] dwmmc_k3 f723f000.dwmmc2: mmc_pwrseq_simple_power_off clk_disable_unprepare()
[    2.271185] mmc mmc2:0001: mmc_sdio_runtime_suspend - DONE
[    2.277843] phy phy-soc:usbphy.0: Linked as a consumer to regulator.13
[    2.285272] dwc2 f72c0000.usb: f72c0000.usb supply vusb_d not found, using dummy regulator
[    2.293638] dwc2 f72c0000.usb: Linked as a consumer to regulator.0
[    2.299839] dwc2 f72c0000.usb: f72c0000.usb supply vusb_a not found, using dummy regulator
[    2.515191] dwc2 f72c0000.usb: EPs: 16, dedicated fifos, 1920 entries in SPRAM
[    2.524180] dwc2 f72c0000.usb: DWC OTG Controller
[    2.528954] dwc2 f72c0000.usb: new USB bus registered, assigned bus number 1
[    2.536046] dwc2 f72c0000.usb: irq 39, io mem 0xf72c0000
[    2.542413] hub 1-0:1.0: USB hub found
[    2.546222] hub 1-0:1.0: 1 port detected
[    2.552410] rtc-efi rtc-efi: setting system clock to 1970-01-01 00:00:13 UTC (13)
[    2.560169] LDO2_2V8: disabling
[    2.563340] LDO13_1V8: disabling
[    2.566573] LDO14_2V8: disabling
[    2.569814] LDO17_2V5: disabling
[    2.573421] uart-pl011 f7113000.uart: no DMA platform data
[    2.579353] Freeing unused kernel memory: 1152K
[    2.583976] Run /init as init process
[    2.613909] random: systemd-udevd: uninitialized urandom read (16 bytes read)
[    2.617366] random: udevadm: uninitialized urandom read (16 bytes read)
[    2.621636] random: systemd-udevd: uninitialized urandom read (16 bytes read)
[    2.943139] dwc2 f72c0000.usb: Set speed to high-speed
[    2.948330] usb 1-1: new high-speed USB device number 2 using dwc2
[    3.139132] dwc2 f72c0000.usb: Set speed to high-speed
[    3.166187] hub 1-1:1.0: USB hub found
[    3.170415] hub 1-1:1.0: 3 ports detected
[    3.497735] EXT4-fs (mmcblk1p2): mounted filesystem with ordered data mode. Opts: (null)
[    3.880254] systemd[1]: System time before build time, advancing clock.
[    3.919810] systemd[1]: systemd 232 running in system mode. (+PAM +AUDIT +SELINUX +IMA +APPARMOR +SMACK +SYSVINIT +UTMP +LIBCRYPTSETUP +GCRYPT +GNUTLS +ACL +XZ +LZ4 +SECCOMP +BLKID +ELFUTILS +KMOD +IDN)
[    3.938260] systemd[1]: Detected architecture arm64.
[    3.960044] systemd[1]: Set hostname to <demo>.
[    4.202660] systemd[1]: Reached target Remote File Systems.
[    4.223196] systemd[1]: Listening on /dev/initctl Compatibility Named Pipe.
[    4.247522] systemd[1]: Listening on Journal Audit Socket.
[    4.267212] systemd[1]: Listening on Journal Socket (/dev/log).
[    4.287267] systemd[1]: Started Dispatch Password Requests to Console Directory Watch.
[    4.311077] systemd[1]: Reached target Swap.
[    4.327134] systemd[1]: Started Forward Password Requests to Wall Directory Watch.
[    4.498311] EXT4-fs (mmcblk1p2): re-mounted. Opts: (null)
[    4.647830] jailhouse: loading out-of-tree module taints kernel.
[    5.158443] systemd-journald[1592]: Received request to flush runtime journal from PID 1
[    5.201856] k3-dma f7370000.dma: initialized
[    5.274730] mmc mmc2:0001: mmc_sdio_runtime_resume
[    5.274813] dwmmc_k3 f723f000.dwmmc2: mmc_pwrseq_simple_pre_power_on clk_prepare_enable()
[    5.311065] mmc_host mmc2: Bus speed (slot 0) = 24800000Hz (slot req 400000Hz, actual 400000HZ div = 31)
[    5.352148] mmc_host mmc2: Bus speed (slot 0) = 24800000Hz (slot req 25000000Hz, actual 24800000HZ div = 0)
[    5.352169] mmc mmc2:0001: mmc_sdio_runtime_resume - ret=0 DONE
[    5.352237] wl1271_sdio mmc2:0001:1: sdio_bus_probe
[    5.352244] wl1271_sdio mmc2:0001:1: sdio_bus_probe - pm_runtime_get_sync()
[    5.352251] wl1271_sdio mmc2:0001:1: sdio_bus_runtime_resume
[    5.352303] wl1271_sdio mmc2:0001:1: sdio_bus_probe - ERR call pm_runtime_put_noidle()
[    5.352334] sdio mmc2:0001:1: sdio_bus_runtime_suspend
[    5.352351] mmc mmc2:0001: mmc_sdio_runtime_suspend
[    5.352411] dwmmc_k3 f723f000.dwmmc2: mmc_pwrseq_simple_power_off clk_disable_unprepare()
[    5.353713] mmc mmc2:0001: mmc_sdio_runtime_suspend - DONE
[    5.353854] mmc mmc2:0001: mmc_sdio_runtime_resume
[    5.353877] dwmmc_k3 f723f000.dwmmc2: mmc_pwrseq_simple_pre_power_on clk_prepare_enable()
[    5.386849] mmc_host mmc2: Bus speed (slot 0) = 24800000Hz (slot req 400000Hz, actual 400000HZ div = 31)
[    5.441732] mmc_host mmc2: Bus speed (slot 0) = 24800000Hz (slot req 25000000Hz, actual 24800000HZ div = 0)
[    5.441753] mmc mmc2:0001: mmc_sdio_runtime_resume - ret=0 DONE
[    5.441807] wl1271_sdio mmc2:0001:2: sdio_bus_probe
[    5.441816] wl1271_sdio mmc2:0001:2: sdio_bus_probe - pm_runtime_get_sync()
[    5.441823] wl1271_sdio mmc2:0001:2: sdio_bus_runtime_resume
[    5.442065] wl1271_sdio mmc2:0001:2: sdio PM caps = 0x0
[    5.442072] wl1271_sdio mmc2:0001:2: chip_family is wl18xx
[    5.442084] wl1271_sdio mmc2:0001:2: About to add core dev (child)...
[    5.442564] wl1271_sdio mmc2:0001:2: sdio_bus_runtime_suspend
[    5.442582] wl1271_sdio mmc2:0001:2: ...added core dev (child) - probe complete!
[    5.442588] wl1271_sdio mmc2:0001:2: sdio_bus_probe - probe OK
[    5.442672] mmc mmc2:0001: mmc_sdio_runtime_suspend
[    5.442734] dwmmc_k3 f723f000.dwmmc2: mmc_pwrseq_simple_power_off clk_disable_unprepare()
[    5.444122] mmc mmc2:0001: mmc_sdio_runtime_suspend - DONE
[    5.481727] cfg80211: Loading compiled-in X.509 certificates for regulatory database
[    5.488722] cfg80211: Loaded X.509 cert 'sforshee: 00b28ddf47aef9cea7'
[    5.489716] platform regulatory.0: Direct firmware load for regulatory.db failed with error -2
[    5.489730] cfg80211: failed to load regulatory.db
[    5.560312] mmc mmc2:0001: mmc_sdio_runtime_resume
[    5.560344] dwmmc_k3 f723f000.dwmmc2: mmc_pwrseq_simple_pre_power_on clk_prepare_enable()
[    5.591249] mmc_host mmc2: Bus speed (slot 0) = 24800000Hz (slot req 400000Hz, actual 400000HZ div = 31)
[    5.652199] mmc_host mmc2: Bus speed (slot 0) = 24800000Hz (slot req 25000000Hz, actual 24800000HZ div = 0)
[    5.652221] mmc mmc2:0001: mmc_sdio_runtime_resume - ret=0 DONE
[    5.652235] wl1271_sdio mmc2:0001:2: sdio_bus_runtime_resume
[    5.653256] wl1271_sdio mmc2:0001:2: sdio_bus_runtime_suspend
[    5.653269] mmc mmc2:0001: mmc_sdio_runtime_suspend
[    5.653324] dwmmc_k3 f723f000.dwmmc2: mmc_pwrseq_simple_power_off clk_disable_unprepare()
[    5.654652] wl18xx_driver wl18xx.3.auto: Direct firmware load for ti-connectivity/wl18xx-conf.bin failed with error -2
[    5.654663] wlcore: ERROR could not get configuration binary ti-connectivity/wl18xx-conf.bin: -2
[    5.654667] wlcore: WARNING falling back to default config
[    5.654690] mmc mmc2:0001: mmc_sdio_runtime_suspend - DONE
[    5.683522] wl1271_sdio mmc2:0001:2: wl12xx_sdio_power_on: STEP1
[    5.683538] mmc mmc2:0001: mmc_sdio_runtime_resume
[    5.683566] dwmmc_k3 f723f000.dwmmc2: mmc_pwrseq_simple_pre_power_on clk_prepare_enable()
[    5.715041] mmc_host mmc2: Bus speed (slot 0) = 24800000Hz (slot req 400000Hz, actual 400000HZ div = 31)
[    5.768567] mmc_host mmc2: Bus speed (slot 0) = 24800000Hz (slot req 25000000Hz, actual 24800000HZ div = 0)
[    5.768587] mmc mmc2:0001: mmc_sdio_runtime_resume - ret=0 DONE
[    5.768599] wl1271_sdio mmc2:0001:2: wl12xx_sdio_power_on: STEP2
[    5.768605] wl1271_sdio mmc2:0001:2: wl12xx_sdio_power_on: STEP3
[    5.768610] mmc mmc2:0001: mmc_sdio_hw_reset
[    5.768668] dwmmc_k3 f723f000.dwmmc2: mmc_pwrseq_simple_power_off clk_disable_unprepare()
[    5.771229] dwmmc_k3 f723f000.dwmmc2: mmc_pwrseq_simple_pre_power_on clk_prepare_enable()
[    5.806938] mmc_host mmc2: Bus speed (slot 0) = 24800000Hz (slot req 400000Hz, actual 400000HZ div = 31)
[    5.849536] mmc_host mmc2: Bus speed (slot 0) = 24800000Hz (slot req 25000000Hz, actual 24800000HZ div = 0)
[    5.849555] mmc mmc2:0001: mmc_sdio_hw_reset - ret=0 DONE
[    5.849613] wl1271_sdio mmc2:0001:2: wl12xx_sdio_power_on: STEP4
[    5.849621] wl1271_sdio mmc2:0001:2: wl12xx_sdio_power_on: STEP5
[    6.057307] wlcore: wl18xx HW: 183x or 180x, PG 2.2 (ROM 0x11)
[    6.058866] wl1271_sdio mmc2:0001:2: wl12xx_sdio_power_off: STEP1
[    6.058908] wl1271_sdio mmc2:0001:2: wl12xx_sdio_power_off: STEP2
[    6.058916] wl1271_sdio mmc2:0001:2: wl12xx_sdio_power_off: STEP3
[    6.058929] wl1271_sdio mmc2:0001:2: wl12xx_sdio_power_off: STEP4
[    6.058939] wlcore: WARNING Detected unconfigured mac address in nvs, derive from fuse instead.
[    6.058942] wlcore: WARNING This default nvs file can be removed from the file system
[    6.059360] mmc mmc2:0001: mmc_sdio_runtime_suspend
[    6.059431] dwmmc_k3 f723f000.dwmmc2: mmc_pwrseq_simple_power_off clk_disable_unprepare()
[    6.060764] mmc mmc2:0001: mmc_sdio_runtime_suspend - DONE
[    6.070262] wlcore: loaded
[    6.407037] wl1271_sdio mmc2:0001:2: wl12xx_sdio_power_on: STEP1
[    6.407055] mmc mmc2:0001: mmc_sdio_runtime_resume
[    6.407084] dwmmc_k3 f723f000.dwmmc2: mmc_pwrseq_simple_pre_power_on clk_prepare_enable()
[    6.438967] mmc_host mmc2: Bus speed (slot 0) = 24800000Hz (slot req 400000Hz, actual 400000HZ div = 31)
[    6.499607] mmc_host mmc2: Bus speed (slot 0) = 24800000Hz (slot req 25000000Hz, actual 24800000HZ div = 0)
[    6.499630] mmc mmc2:0001: mmc_sdio_runtime_resume - ret=0 DONE
[    6.499643] wl1271_sdio mmc2:0001:2: wl12xx_sdio_power_on: STEP2
[    6.499650] wl1271_sdio mmc2:0001:2: wl12xx_sdio_power_on: STEP3
[    6.499656] mmc mmc2:0001: mmc_sdio_hw_reset
[    6.499715] dwmmc_k3 f723f000.dwmmc2: mmc_pwrseq_simple_power_off clk_disable_unprepare()
[    6.502401] dwmmc_k3 f723f000.dwmmc2: mmc_pwrseq_simple_pre_power_on clk_prepare_enable()
[    6.535419] mmc_host mmc2: Bus speed (slot 0) = 24800000Hz (slot req 400000Hz, actual 400000HZ div = 31)
[    6.593615] mmc_host mmc2: Bus speed (slot 0) = 24800000Hz (slot req 25000000Hz, actual 24800000HZ div = 0)
[    6.593636] mmc mmc2:0001: mmc_sdio_hw_reset - ret=0 DONE
[    6.593713] wl1271_sdio mmc2:0001:2: wl12xx_sdio_power_on: STEP4
[    6.593721] wl1271_sdio mmc2:0001:2: wl12xx_sdio_power_on: STEP5
[    7.071691] wlcore: PHY firmware version: Rev 8.2.0.0.236
[    7.097309] wl1271_sdio mmc2:0001:2: sdio_bus_runtime_resume
[    7.198175] wlcore: firmware booted (Rev 8.9.0.0.69)
[    7.220230] IPv6: ADDRCONF(NETDEV_UP): wlan0: link is not ready
[    7.275524] wl1271_sdio mmc2:0001:2: sdio_bus_runtime_suspend
[    7.288748] wl1271_sdio mmc2:0001:2: sdio_bus_runtime_resume
[    7.351658] wl1271_sdio mmc2:0001:2: sdio_bus_runtime_suspend
[    7.352957] wl1271_sdio mmc2:0001:2: sdio_bus_runtime_resume
[    7.415441] wl1271_sdio mmc2:0001:2: sdio_bus_runtime_suspend
[    7.442367] wl1271_sdio mmc2:0001:2: sdio_bus_runtime_resume
[    7.499248] wl1271_sdio mmc2:0001:2: sdio_bus_runtime_suspend
[    7.664877] wl1271_sdio mmc2:0001:2: sdio_bus_runtime_resume
[    7.759207] wl1271_sdio mmc2:0001:2: sdio_bus_runtime_suspend
[    7.813956] wl1271_sdio mmc2:0001:2: sdio_bus_runtime_resume
[    7.979209] wl1271_sdio mmc2:0001:2: sdio_bus_runtime_suspend
[    8.041710] wl1271_sdio mmc2:0001:2: sdio_bus_runtime_resume
[    8.143207] wl1271_sdio mmc2:0001:2: sdio_bus_runtime_suspend
[   11.511579] wl1271_sdio mmc2:0001:2: sdio_bus_runtime_resume
[   11.513676] wlan0: authenticate with 00:26:f2:a6:54:9b
[   11.518209] wlan0: send auth to 00:26:f2:a6:54:9b (try 1/3)
[   11.548949] wlan0: authenticated
[   11.551101] wlan0: associate with 00:26:f2:a6:54:9b (try 1/3)
[   11.555771] wlan0: RX AssocResp from 00:26:f2:a6:54:9b (capab=0x431 status=0 aid=4)
[   11.569988] wlan0: associated
[   11.583652] IPv6: ADDRCONF(NETDEV_CHANGE): wlan0: link becomes ready
[   11.585286] wlcore: Association completed.
[   11.663208] wl1271_sdio mmc2:0001:2: sdio_bus_runtime_suspend
[   11.903311] wl1271_sdio mmc2:0001:2: sdio_bus_runtime_resume
[   11.959544] wl1271_sdio mmc2:0001:2: sdio_bus_runtime_suspend
[   12.223401] wl1271_sdio mmc2:0001:2: sdio_bus_runtime_resume
[   12.279756] wl1271_sdio mmc2:0001:2: sdio_bus_runtime_suspend
[   13.247416] wl1271_sdio mmc2:0001:2: sdio_bus_runtime_resume
[   13.303324] wl1271_sdio mmc2:0001:2: sdio_bus_runtime_suspend
[   13.999476] wl1271_sdio mmc2:0001:2: sdio_bus_runtime_resume
[   14.079304] wl1271_sdio mmc2:0001:2: sdio_bus_runtime_suspend
[   14.239127] wl1271_sdio mmc2:0001:2: sdio_bus_runtime_resume
[   14.294940] wl1271_sdio mmc2:0001:2: sdio_bus_runtime_suspend
[   17.119299] wl1271_sdio mmc2:0001:2: sdio_bus_runtime_resume
[   17.179547] wl1271_sdio mmc2:0001:2: sdio_bus_runtime_suspend
[   19.573020] wl1271_sdio mmc2:0001:2: sdio_bus_runtime_resume
[   19.675205] wl1271_sdio mmc2:0001:2: sdio_bus_runtime_suspend
[   23.795813] wl1271_sdio mmc2:0001:2: sdio_bus_runtime_resume
[   23.851205] wl1271_sdio mmc2:0001:2: sdio_bus_runtime_suspend
[   23.903410] wl1271_sdio mmc2:0001:2: sdio_bus_runtime_resume
[   23.959755] wl1271_sdio mmc2:0001:2: sdio_bus_runtime_suspend
[   23.969946] wl1271_sdio mmc2:0001:2: sdio_bus_runtime_resume
[   24.059205] wl1271_sdio mmc2:0001:2: sdio_bus_runtime_suspend
[   24.543304] wl1271_sdio mmc2:0001:2: sdio_bus_runtime_resume
[   24.599606] wl1271_sdio mmc2:0001:2: sdio_bus_runtime_suspend
[   29.422337] random: crng init done
[   29.422350] random: 7 urandom warning(s) missed due to ratelimiting
[   33.013600] wl1271_sdio mmc2:0001:2: sdio_bus_runtime_resume
[   33.067210] wl1271_sdio mmc2:0001:2: sdio_bus_runtime_suspend
[   35.674097] wl1271_sdio mmc2:0001:2: sdio_bus_runtime_resume
[   35.735759] wl1271_sdio mmc2:0001:2: sdio_bus_runtime_suspend
[   35.791301] wl1271_sdio mmc2:0001:2: sdio_bus_runtime_resume
[   35.887623] wl1271_sdio mmc2:0001:2: sdio_bus_runtime_suspend
[   35.993765] wl1271_sdio mmc2:0001:2: sdio_bus_runtime_resume
[   36.083209] wl1271_sdio mmc2:0001:2: sdio_bus_runtime_suspend
[   38.879248] wl1271_sdio mmc2:0001:2: sdio_bus_runtime_resume
[   38.939401] wl1271_sdio mmc2:0001:2: sdio_bus_runtime_suspend
[   46.327234] wl1271_sdio mmc2:0001:2: sdio_bus_runtime_resume
[   46.382961] wl1271_sdio mmc2:0001:2: sdio_bus_runtime_suspend

Ulf Hansson Jan. 23, 2019, 9:18 p.m. UTC | #19

On Wed, 23 Jan 2019 at 21:17, Jan Kiszka <[e-mail]> wrote:
>
> On 23.01.19 09:50, Ulf Hansson wrote:
> > On Tue, 22 Jan 2019 at 17:08, Jan Kiszka <[e-mail]> wrote:
> >>
> >> On 21.01.19 15:40, Ulf Hansson wrote:
> >>> On Fri, 18 Jan 2019 at 16:09, Ulf Hansson <[e-mail]> wrote:
> >>>>
> >>>> On Fri, 18 Jan 2019 at 13:09, Jan Kiszka <[e-mail]> wrote:
> >>>>>
> >>>>> On 17.01.19 10:54, Ulf Hansson wrote:
> >>>>>> On Wed, 16 Jan 2019 at 21:26, Jan Kiszka <[e-mail]> wrote:
> >>>>>>>
> >>>>>>> On 16.01.19 12:37, Ulf Hansson wrote:
> >>>>>>>> During "wlan-up", we are programming the FW into the WiFi-chip. However,
> >>>>>>>> re-programming the FW doesn't work, unless a power cycle of the WiFi-chip
> >>>>>>>> is made in-between the programmings.
> >>>>>>>>
> >>>>>>>> To conform to this requirement and to fix the regression in a simple way,
> >>>>>>>> let's start by allowing that the SDIO card (WiFi-chip) may stay powered on
> >>>>>>>> (runtime resumed) when wl12xx_sdio_power_off() returns. The intent with the
> >>>>>>>> current code is to treat this scenario as an error, but unfortunate this
> >>>>>>>> doesn't work as expected, so let's fix this.
> >>>>>>>>
> >>>>>>>> The other part is to guarantee that a power cycle of the SDIO card has been
> >>>>>>>> completed when wl12xx_sdio_power_on() returns, as to allow the FW
> >>>>>>>> programming to succeed. However, relying solely on runtime PM to deal with
> >>>>>>>> this isn't sufficient. For example, userspace may prevent runtime suspend
> >>>>>>>> via sysfs for the device that represents the SDIO card, leading to that the
> >>>>>>>> mmc core also keeps it powered on. For this reason, let's instead do a
> >>>>>>>> brute force power cycle in wl12xx_sdio_power_on().
> >>>>>>>>
> >>>>>>>> Fixes: 728a9dc61f13 ("wlcore: sdio: Fix flakey SDIO runtime PM handling")
> >>>>>>>> Signed-off-by: Ulf Hansson <[e-mail]>
> >>>>>>>> ---
> >>>>>>>>
> >>>>>>>> Changes in v2:
> >>>>>>>>          - Keep the SDIO host claimed when calling mmc_hw_reset().
> >>>>>>>>          - Add a fixes tag.
> >>>>>>>> ---
> >>>>>>>>      drivers/net/wireless/ti/wlcore/sdio.c | 15 +++++++--------
> >>>>>>>>      1 file changed, 7 insertions(+), 8 deletions(-)
> >>>>>>>>
> >>>>>>>> diff --git a/drivers/net/wireless/ti/wlcore/sdio.c b/drivers/net/wireless/ti/wlcore/sdio.c
> >>>>>>>> index bd10165d7eec..4d4b07701149 100644
> >>>>>>>> --- a/drivers/net/wireless/ti/wlcore/sdio.c
> >>>>>>>> +++ b/drivers/net/wireless/ti/wlcore/sdio.c
> >>>>>>>> @@ -164,6 +164,12 @@ static int wl12xx_sdio_power_on(struct wl12xx_sdio_glue *glue)
> >>>>>>>>          }
> >>>>>>>>
> >>>>>>>>          sdio_claim_host(func);
> >>>>>>>> +     /*
> >>>>>>>> +      * To guarantee that the SDIO card is power cycled, as required to make
> >>>>>>>> +      * the FW programming to succeed, let's do a brute force HW reset.
> >>>>>>>> +      */
> >>>>>>>> +     mmc_hw_reset(card->host);
> >>>>>>>> +
> >>>>>>>>          sdio_enable_func(func);
> >>>>>>>>          sdio_release_host(func);
> >>>>>>>>
> >>>>>>>> @@ -174,20 +180,13 @@ static int wl12xx_sdio_power_off(struct wl12xx_sdio_glue *glue)
> >>>>>>>>      {
> >>>>>>>>          struct sdio_func *func = dev_to_sdio_func(glue->dev);
> >>>>>>>>          struct mmc_card *card = func->card;
> >>>>>>>> -     int error;
> >>>>>>>>
> >>>>>>>>          sdio_claim_host(func);
> >>>>>>>>          sdio_disable_func(func);
> >>>>>>>>          sdio_release_host(func);
> >>>>>>>>
> >>>>>>>>          /* Let runtime PM know the card is powered off */
> >>>>>>>> -     error = pm_runtime_put(&card->dev);
> >>>>>>>> -     if (error < 0 && error != -EBUSY) {
> >>>>>>>> -             dev_err(&card->dev, "%s failed: %i\n", __func__, error);
> >>>>>>>> -
> >>>>>>>> -             return error;
> >>>>>>>> -     }
> >>>>>>>> -
> >>>>>>>> +     pm_runtime_put(&card->dev);
> >>>>>>>>          return 0;
> >>>>>>>>      }
> >>>>>>>>
> >>>>>>>>
> >>>>>>>
> >>>>>>> Just tested on both HiKey (620) and Ultra96 but it fails to fix the issue on
> >>>>>>> both. I'm getting
> >>>>>>>
> >>>>>>> wl1271_sdio: probe of mmc2:0001:1 failed with error -16
> >>>>>>>
> >>>>>>> during boot again, and the interface is not available.
> >>>>>>
> >>>>>> Okay, sounds like this may be a different problem then. Can you share
> >>>>>> the complete log and the kernel config?
> >>>>>
> >>>>> You can find the config here [1], log from the HiKey boot attached.
> >>>>>
> >>>>>> I can prepare a debug patch as well, if you are willing to re-run the test?
> >>>>>
> >>>>> Sure, send it over, I can run it.
> >>>>
> >>>> Alright, sounds great. However, I need to defer that to Monday/Tuesday
> >>>> next week.
> >>>>
> >>>>>
> >>>>>>
> >>>>>> Adding a post-power-on-delay-ms of 1 ms as you suggested [1], doesn't
> >>>>>> sounds like the correct solution to me, unless I am overlooking some
> >>>>>> things. The point is, since the mmc core succeeds to detect and
> >>>>>> initialize the SDIO card, the power sequence seems to be correct.
> >>>>>
> >>>>> Yeah, I'm not claiming at all I know what I'm doing there, just that it happens
> >>>>> to work.
> >>>>
> >>>> I see. Good to know, thanks!
> >>>>
> >>>>>
> >>>>> Jan
> >>>>>
> >>>>> [1]
> >>>>> https://github.com/siemens/jailhouse-images/blob/next/recipes-kernel/linux/files/arm64_defconfig_4.19
> >>>>
> >>>> I have looked through the log and the defconfig. No obvious things
> >>>> found at this point. Thanks for sharing them!
> >>>>
> >>>
> >>> So, I have put together a debug patch, mostly to verify that things
> >>> seems to be correct in regards to runtime PM. It should produce some
> >>> prints to the log, particular during power on/off of the SDIO card and
> >>> during probe of the wifi driver. Please re-run the test on top of the
> >>> v2 version of the $subject patch.
> >>>
> >>
> >> Log attached.
> >
> > Thanks! Okay, so the re-initialization of the SDIO card is failing,
> > that's very valuable information.
> >
> > I noticed one difference while comparing your log with the one I
> > received (offlist) from Anders... In your case the initialization
> > frequency that works the first time is 300KHz, while in Anders case
> > it's 100KHz. This sounds a bit fishy to me, so maybe there are some
> > problems with the pwrseq after all.
> >
> > Let me think a bit and see what I can come up with as a possible solution.
> >
> > In the meantime, can you re-run the test with same debug patch, but
> > change the post-power-on-delay-ms to let's say 10 ms in the DTS? I am
> > going to ask Anders to do the same test on his side, as to see if we
> > get different values of the found initialization frequency.
>
> Here is a log with 10 ms power-on-delay.

Thanks!

According to the log, we are now using 400KHz as the init frequency,
because we succeeds to initialize the SDIO card already at the first
attempt. The same thing happens to Anders' new tests.

Conclusion from my side: We need the delay, probably because the
internals of the WiFi chip isn't ready as soon as the WiFi spec
states. In either case, I suggest you to re-spin your patch [1] and
extend to delay to 10ms (instead of 1ms, just to be safe). Let it have
also have the below fixes tag (as it seems like an original problem
with the pwrseq) and also tag it for stable.

Fixes: ea452678734e ("arm64: dts: hikey: Fix WiFi support")

Finally, feel free to add my ack for it.

Kind regards
Uffe

[1]
https://patchwork.kernel.org/patch/10745075/

Patch

diff --git a/drivers/net/wireless/ti/wlcore/sdio.c b/drivers/net/wireless/ti/wlcore/sdio.c
index bd10165d7eec..4d4b07701149 100644
--- a/drivers/net/wireless/ti/wlcore/sdio.c
+++ b/drivers/net/wireless/ti/wlcore/sdio.c
@@ -164,6 +164,12 @@  static int wl12xx_sdio_power_on(struct wl12xx_sdio_glue *glue)
 	}
 
 	sdio_claim_host(func);
+	/*
+	 * To guarantee that the SDIO card is power cycled, as required to make
+	 * the FW programming to succeed, let's do a brute force HW reset.
+	 */
+	mmc_hw_reset(card->host);
+
 	sdio_enable_func(func);
 	sdio_release_host(func);
 
@@ -174,20 +180,13 @@  static int wl12xx_sdio_power_off(struct wl12xx_sdio_glue *glue)
 {
 	struct sdio_func *func = dev_to_sdio_func(glue->dev);
 	struct mmc_card *card = func->card;
-	int error;
 
 	sdio_claim_host(func);
 	sdio_disable_func(func);
 	sdio_release_host(func);
 
 	/* Let runtime PM know the card is powered off */
-	error = pm_runtime_put(&card->dev);
-	if (error < 0 && error != -EBUSY) {
-		dev_err(&card->dev, "%s failed: %i\n", __func__, error);
-
-		return error;
-	}
-
+	pm_runtime_put(&card->dev);
 	return 0;
 }