Re: Linux 5.18.x: sdhci issue

Re: Linux 5.18.x: sdhci issue

[Tony Lindgren]

Hi,

* Yegor Yefremov <yegorslists@googlemail.com> [220504 09:12]:
> Hi Tony, all,
> 
> During the kernel boot I see the following error. The device is still
> working afterwards. 5.17.5 shows the same behavior. Is this a known
> issue?

Thanks for reporting it, I was not aware of this one. Might be worth
bisecting. Adding linux-mmc and Ulf.

Regards,

Tony

> [    3.734570] sdhci-omap 48060000.mmc: Got CD GPIO
> [    3.739989] INFO: trying to register non-static key.
> [    3.744991] The code is fine but needs lockdep annotation, or maybe
> [    3.751286] you didn't initialize this object before use?
> [    3.756707] turning off the locking correctness validator.
> [    3.762221] CPU: 0 PID: 8 Comm: kworker/u2:0 Not tainted 5.18.0-rc5 #1
> [    3.768787] Hardware name: Generic AM33XX (Flattened Device Tree)
> [    3.774913] Workqueue: events_unbound async_run_entry_fn
> [    3.780283]  unwind_backtrace from show_stack+0x10/0x14
> [    3.785555]  show_stack from dump_stack_lvl+0x58/0x70
> [    3.790643]  dump_stack_lvl from register_lock_class+0x4ec/0x55c
> [    3.796695]  register_lock_class from __lock_acquire+0x60/0x2bd4
> [    3.802738]  __lock_acquire from lock_acquire.part.0+0xb0/0x248
> [    3.808695]  lock_acquire.part.0 from _raw_spin_lock_irqsave+0x4c/0x68
> [    3.815265]  _raw_spin_lock_irqsave from sdhci_init+0x34/0xf4
> [    3.821051]  sdhci_init from sdhci_runtime_resume_host+0x3c/0x1bc
> [    3.827180]  sdhci_runtime_resume_host from
> sdhci_omap_runtime_resume+0x108/0x110
> [    3.834710]  sdhci_omap_runtime_resume from __rpm_callback+0x3c/0x148
> [    3.841197]  __rpm_callback from rpm_callback+0x50/0x54
> [    3.846453]  rpm_callback from rpm_resume+0x518/0x71c
> [    3.851534]  rpm_resume from __pm_runtime_resume+0x50/0x68
> [    3.857052]  __pm_runtime_resume from sdhci_omap_probe+0x1e4/0x7a8
> [    3.863270]  sdhci_omap_probe from platform_probe+0x58/0xbc
> [    3.868886]  platform_probe from really_probe.part.0+0x9c/0x290
> [    3.874843]  really_probe.part.0 from __driver_probe_device+0xa0/0x138
> [    3.881409]  __driver_probe_device from driver_probe_device+0x30/0x10c
> [    3.887975]  driver_probe_device from __device_attach_driver+0xb0/0xf8
> [    3.894540]  __device_attach_driver from bus_for_each_drv+0x80/0xd0
> [    3.900845]  bus_for_each_drv from __device_attach_async_helper+0xac/0xe0
> [    3.907672]  __device_attach_async_helper from async_run_entry_fn+0x20/0xb0
> [    3.914675]  async_run_entry_fn from process_one_work+0x284/0x72c
> [    3.920811]  process_one_work from worker_thread+0x28/0x4b0
> [    3.926418]  worker_thread from kthread+0xe4/0x104
> [    3.931243]  kthread from ret_from_fork+0x14/0x28
> [    3.935977] Exception stack(0xd0035fb0 to 0xd0035ff8)
> [    3.941056] 5fa0:                                     00000000
> 00000000 00000000 00000000
> [    3.949274] 5fc0: 00000000 00000000 00000000 00000000 00000000
> 00000000 00000000 00000000
> [    3.957491] 5fe0: 00000000 00000000 00000000 00000000 00000013 00000000
> [    3.964359] sdhci-omap 48060000.mmc: supply pbias not found, using
> dummy regulator
> [    3.972468] sdhci-omap 48060000.mmc: supply vqmmc not found, using
> dummy regulator
> [    3.982478] sdhci-omap 481d8000.mmc: supply pbias not found, using
> dummy regulator
> [    3.990665] sdhci-omap 481d8000.mmc: supply vqmmc not found, using
> dummy regulator
> 
> Regards,
> Yegor

Re: Linux 5.18.x: sdhci issue

[Yegor Yefremov]

Hi,

On Thu, May 5, 2022 at 7:03 AM Tony Lindgren <tony@atomide.com> wrote:
>
> Hi,
>
> * Yegor Yefremov <yegorslists@googlemail.com> [220504 09:12]:
> > Hi Tony, all,
> >
> > During the kernel boot I see the following error. The device is still
> > working afterwards. 5.17.5 shows the same behavior. Is this a known
> > issue?
>
> Thanks for reporting it, I was not aware of this one. Might be worth
> bisecting. Adding linux-mmc and Ulf.

After enabling the CONFIG_DMA_API_DEBUG option, I also get the following error:

Starting syslogd: OK
Starting klogd: OK
Running sysctl: OK
Populating /dev using udev: [    7.511893] ------------[ cut here ]------------
[    7.516605] WARNING: CPU: 0 PID: 73 at kernel/dma/debug.c:1073
check_for_illegal_area+0xd0/0x180
[    7.525734] DMA-API: sdhci-omap 48060000.mmc: device driver maps
memory from kernel text or rodata [addr=(ptrval)] [len=12288]
[    7.537275] Modules linked in:
[    7.540429] CPU: 0 PID: 73 Comm: kworker/0:2H Not tainted 5.18.0-rc7 #14
[    7.547182] Hardware name: Generic AM33XX (Flattened Device Tree)
[    7.553320] Workqueue: kblockd blk_mq_run_work_fn
[    7.558098]  unwind_backtrace from show_stack+0x10/0x14
[    7.563386]  show_stack from dump_stack_lvl+0x58/0x70
[    7.568501]  dump_stack_lvl from __warn+0xb4/0x24c
[    7.573342]  __warn from warn_slowpath_fmt+0x74/0xb8
[    7.578352]  warn_slowpath_fmt from check_for_illegal_area+0xd0/0x180
[    7.584845]  check_for_illegal_area from debug_dma_map_sg+0x60/0x3d8
[    7.591249]  debug_dma_map_sg from __dma_map_sg_attrs+0xa4/0x13c
[    7.597316]  __dma_map_sg_attrs from dma_map_sg_attrs+0x14/0x20
[    7.603288]  dma_map_sg_attrs from sdhci_pre_dma_transfer+0xcc/0x134
[    7.609705]  sdhci_pre_dma_transfer from mmc_blk_mq_issue_rq+0x2f4/0xa58
[    7.616462]  mmc_blk_mq_issue_rq from mmc_mq_queue_rq+0x124/0x258
[    7.622604]  mmc_mq_queue_rq from blk_mq_dispatch_rq_list+0x1b8/0x8ac
[    7.629104]  blk_mq_dispatch_rq_list from
blk_mq_do_dispatch_sched+0x2ec/0x350
[    7.636387]  blk_mq_do_dispatch_sched from
__blk_mq_sched_dispatch_requests+0x118/0x170
[    7.644448]  __blk_mq_sched_dispatch_requests from
blk_mq_sched_dispatch_requests+0x34/0x5c
[    7.652859]  blk_mq_sched_dispatch_requests from
__blk_mq_run_hw_queue+0xf8/0x230
[    7.660402]  __blk_mq_run_hw_queue from process_one_work+0x284/0x72c
[    7.666820]  process_one_work from worker_thread+0x28/0x4b0
[    7.672441]  worker_thread from kthread+0xe4/0x104
[    7.677280]  kthread from ret_from_fork+0x14/0x28
[    7.682027] Exception stack(0xd0421fb0 to 0xd0421ff8)
[    7.687116] 1fa0:                                     00000000
00000000 00000000 00000000
[    7.695346] 1fc0: 00000000 00000000 00000000 00000000 00000000
00000000 00000000 00000000
[    7.703574] 1fe0: 00000000 00000000 00000000 00000000 00000013 00000000
[    7.710321] irq event stamp: 0
[    7.713411] hardirqs last  enabled at (0): [<00000000>] 0x0
[    7.719029] hardirqs last disabled at (0): [<c0135e68>]
copy_process+0x630/0x19c4
[    7.726626] softirqs last  enabled at (0): [<c0135e68>]
copy_process+0x630/0x19c4
[    7.734219] softirqs last disabled at (0): [<00000000>] 0x0
[    7.739883] ---[ end trace 0000000000000000 ]---
[    7.837580] udevd[101]: starting version 3.2.11

Regards,
Yegor

Re: Linux 5.18.x: sdhci issue

[Arnd Bergmann]

On Tue, May 31, 2022 at 10:28 AM Yegor Yefremov
<yegorslists@googlemail.com> wrote:
> On Thu, May 5, 2022 at 7:03 AM Tony Lindgren <tony@atomide.com> wrote:
> >
> > Hi,
> >
> > * Yegor Yefremov <yegorslists@googlemail.com> [220504 09:12]:
> > > Hi Tony, all,
> > >
> > > During the kernel boot I see the following error. The device is still
> > > working afterwards. 5.17.5 shows the same behavior. Is this a known
> > > issue?
> >
> > Thanks for reporting it, I was not aware of this one. Might be worth
> > bisecting. Adding linux-mmc and Ulf.
>
> After enabling the CONFIG_DMA_API_DEBUG option, I also get the following error:

> [    7.603288]  dma_map_sg_attrs from sdhci_pre_dma_transfer+0xcc/0x134
> [    7.609705]  sdhci_pre_dma_transfer from mmc_blk_mq_issue_rq+0x2f4/0xa58
> [    7.616462]  mmc_blk_mq_issue_rq from mmc_mq_queue_rq+0x124/0x258
> [    7.622604]  mmc_mq_queue_rq from blk_mq_dispatch_rq_list+0x1b8/0x8ac
> [    7.629104]  blk_mq_dispatch_rq_list from
> blk_mq_do_dispatch_sched+0x2ec/0x350
> [    7.636387]  blk_mq_do_dispatch_sched from
> __blk_mq_sched_dispatch_requests+0x118/0x170
> [    7.644448]  __blk_mq_sched_dispatch_requests from
> blk_mq_sched_dispatch_requests+0x34/0x5c
> [    7.652859]  blk_mq_sched_dispatch_requests from
> __blk_mq_run_hw_queue+0xf8/0x230
> [    7.660402]  __blk_mq_run_hw_queue from process_one_work+0x284/0x72c

This is the blk_mq code taking things off the queue, so we don't really
know how they got put on there at this point. To find that, we'd need to
annotate the mmc code with the same kind of check to test the buffer
address whenever something gets submitted on the blk_mq queue.

Looking at the calls to sg_init*(), I found sdio_io_rw_ext_helper(), which
is what all sdio commands pass through. We could annotate that using

diff --git a/drivers/mmc/core/sdio_io.c b/drivers/mmc/core/sdio_io.c
index 79dbf90216b5..4ab063c50649 100644
--- a/drivers/mmc/core/sdio_io.c
+++ b/drivers/mmc/core/sdio_io.c
@@ -322,6 +322,11 @@ static int sdio_io_rw_ext_helper(struct sdio_func
*func, int write,
        if (!func || (func->num > 7))
                return -EINVAL;

+       WARN_ON_ONCE(memory_intersects(_stext, _etext, buf, size));
+       WARN_ON_ONCE(memory_intersects(__start_rodata, __end_rodata,
buf, size));
+       WARN_ON_ONCE(object_is_on_stack(buf));
+       WARN_ON_ONCE(is_vmalloc_or_module_addr(buf));
+
        /* Do the bulk of the transfer using block mode (if supported). */
        if (func->card->cccr.multi_block && (size > sdio_max_byte_size(func))) {
                /* Blocks per command is limited by host count, host transfer

 Does that show something new?

If this is a block device, the change won't help, but I can't find a good place
to hook into that at the moment. mmc_mq_queue_rq() might work, but
I think that is still called asynchronously.

       Arnd

Re: Linux 5.18.x: sdhci issue

[Yegor Yefremov]

On Tue, May 31, 2022 at 11:23 AM Arnd Bergmann <arnd@arndb.de> wrote:
>
> On Tue, May 31, 2022 at 10:28 AM Yegor Yefremov
> <yegorslists@googlemail.com> wrote:
> > On Thu, May 5, 2022 at 7:03 AM Tony Lindgren <tony@atomide.com> wrote:
> > >
> > > Hi,
> > >
> > > * Yegor Yefremov <yegorslists@googlemail.com> [220504 09:12]:
> > > > Hi Tony, all,
> > > >
> > > > During the kernel boot I see the following error. The device is still
> > > > working afterwards. 5.17.5 shows the same behavior. Is this a known
> > > > issue?
> > >
> > > Thanks for reporting it, I was not aware of this one. Might be worth
> > > bisecting. Adding linux-mmc and Ulf.
> >
> > After enabling the CONFIG_DMA_API_DEBUG option, I also get the following error:
>
> > [    7.603288]  dma_map_sg_attrs from sdhci_pre_dma_transfer+0xcc/0x134
> > [    7.609705]  sdhci_pre_dma_transfer from mmc_blk_mq_issue_rq+0x2f4/0xa58
> > [    7.616462]  mmc_blk_mq_issue_rq from mmc_mq_queue_rq+0x124/0x258
> > [    7.622604]  mmc_mq_queue_rq from blk_mq_dispatch_rq_list+0x1b8/0x8ac
> > [    7.629104]  blk_mq_dispatch_rq_list from
> > blk_mq_do_dispatch_sched+0x2ec/0x350
> > [    7.636387]  blk_mq_do_dispatch_sched from
> > __blk_mq_sched_dispatch_requests+0x118/0x170
> > [    7.644448]  __blk_mq_sched_dispatch_requests from
> > blk_mq_sched_dispatch_requests+0x34/0x5c
> > [    7.652859]  blk_mq_sched_dispatch_requests from
> > __blk_mq_run_hw_queue+0xf8/0x230
> > [    7.660402]  __blk_mq_run_hw_queue from process_one_work+0x284/0x72c
>
> This is the blk_mq code taking things off the queue, so we don't really
> know how they got put on there at this point. To find that, we'd need to
> annotate the mmc code with the same kind of check to test the buffer
> address whenever something gets submitted on the blk_mq queue.
>
> Looking at the calls to sg_init*(), I found sdio_io_rw_ext_helper(), which
> is what all sdio commands pass through. We could annotate that using
>
> diff --git a/drivers/mmc/core/sdio_io.c b/drivers/mmc/core/sdio_io.c
> index 79dbf90216b5..4ab063c50649 100644
> --- a/drivers/mmc/core/sdio_io.c
> +++ b/drivers/mmc/core/sdio_io.c
> @@ -322,6 +322,11 @@ static int sdio_io_rw_ext_helper(struct sdio_func
> *func, int write,
>         if (!func || (func->num > 7))
>                 return -EINVAL;
>
> +       WARN_ON_ONCE(memory_intersects(_stext, _etext, buf, size));
> +       WARN_ON_ONCE(memory_intersects(__start_rodata, __end_rodata,
> buf, size));
> +       WARN_ON_ONCE(object_is_on_stack(buf));
> +       WARN_ON_ONCE(is_vmalloc_or_module_addr(buf));
> +
>         /* Do the bulk of the transfer using block mode (if supported). */
>         if (func->card->cccr.multi_block && (size > sdio_max_byte_size(func))) {
>                 /* Blocks per command is limited by host count, host transfer
>
>  Does that show something new?
>
> If this is a block device, the change won't help, but I can't find a good place
> to hook into that at the moment. mmc_mq_queue_rq() might work, but
> I think that is still called asynchronously.

No, the patch provides the same output.

Yegor

Re: Linux 5.18.x: sdhci issue

[Arnd Bergmann]

On Wed, Jun 1, 2022 at 8:08 AM Yegor Yefremov
<yegorslists@googlemail.com> wrote:
> On Tue, May 31, 2022 at 11:23 AM Arnd Bergmann <arnd@arndb.de> wrote:
> > On Tue, May 31, 2022 at 10:28 AM Yegor Yefremov
> >
> > +       WARN_ON_ONCE(memory_intersects(_stext, _etext, buf, size));
> > +       WARN_ON_ONCE(memory_intersects(__start_rodata, __end_rodata,
> > buf, size));
> > +       WARN_ON_ONCE(object_is_on_stack(buf));
> > +       WARN_ON_ONCE(is_vmalloc_or_module_addr(buf));
> > +
> >         /* Do the bulk of the transfer using block mode (if supported). */
> >         if (func->card->cccr.multi_block && (size > sdio_max_byte_size(func))) {
> >                 /* Blocks per command is limited by host count, host transfer
> >
> >  Does that show something new?
> >
> > If this is a block device, the change won't help, but I can't find a good place
> > to hook into that at the moment. mmc_mq_queue_rq() might work, but
> > I think that is still called asynchronously.
>
> No, the patch provides the same output.

Can you say what devices are attached to the mmc controller? Is it
an eMMC block device, an SDIO device, or both?

         Arnd

Re: Linux 5.18.x: sdhci issue

[Yegor Yefremov]

On Wed, Jun 1, 2022 at 8:45 AM Arnd Bergmann <arnd@arndb.de> wrote:
>
> On Wed, Jun 1, 2022 at 8:08 AM Yegor Yefremov
> <yegorslists@googlemail.com> wrote:
> > On Tue, May 31, 2022 at 11:23 AM Arnd Bergmann <arnd@arndb.de> wrote:
> > > On Tue, May 31, 2022 at 10:28 AM Yegor Yefremov
> > >
> > > +       WARN_ON_ONCE(memory_intersects(_stext, _etext, buf, size));
> > > +       WARN_ON_ONCE(memory_intersects(__start_rodata, __end_rodata,
> > > buf, size));
> > > +       WARN_ON_ONCE(object_is_on_stack(buf));
> > > +       WARN_ON_ONCE(is_vmalloc_or_module_addr(buf));
> > > +
> > >         /* Do the bulk of the transfer using block mode (if supported). */
> > >         if (func->card->cccr.multi_block && (size > sdio_max_byte_size(func))) {
> > >                 /* Blocks per command is limited by host count, host transfer
> > >
> > >  Does that show something new?
> > >
> > > If this is a block device, the change won't help, but I can't find a good place
> > > to hook into that at the moment. mmc_mq_queue_rq() might work, but
> > > I think that is still called asynchronously.
> >
> > No, the patch provides the same output.
>
> Can you say what devices are attached to the mmc controller? Is it
> an eMMC block device, an SDIO device, or both?

From DTS point of view: MMC and WiFi (SDIO). Physically, only MMC
(removable SDcard).

Yegor

Re: Linux 5.18.x: sdhci issue

[Arnd Bergmann]

On Wed, Jun 1, 2022 at 8:49 AM Yegor Yefremov
<yegorslists@googlemail.com> wrote:
> On Wed, Jun 1, 2022 at 8:45 AM Arnd Bergmann <arnd@arndb.de> wrote:
> > On Wed, Jun 1, 2022 at 8:08 AM Yegor Yefremov
> > <yegorslists@googlemail.com> wrote:
> > > On Tue, May 31, 2022 at 11:23 AM Arnd Bergmann <arnd@arndb.de> wrote:
> > > > On Tue, May 31, 2022 at 10:28 AM Yegor Yefremov
> > > >
> > > > +       WARN_ON_ONCE(memory_intersects(_stext, _etext, buf, size));
> > > > +       WARN_ON_ONCE(memory_intersects(__start_rodata, __end_rodata,
> > > > buf, size));
> > > > +       WARN_ON_ONCE(object_is_on_stack(buf));
> > > > +       WARN_ON_ONCE(is_vmalloc_or_module_addr(buf));
> > > > +
> > > >         /* Do the bulk of the transfer using block mode (if supported). */
> > > >         if (func->card->cccr.multi_block && (size > sdio_max_byte_size(func))) {
> > > >                 /* Blocks per command is limited by host count, host transfer
> > > >
> > > >  Does that show something new?
> > > >
> > > > If this is a block device, the change won't help, but I can't find a good place
> > > > to hook into that at the moment. mmc_mq_queue_rq() might work, but
> > > > I think that is still called asynchronously.
> > >
> > > No, the patch provides the same output.
> >
> > Can you say what devices are attached to the mmc controller? Is it
> > an eMMC block device, an SDIO device, or both?
>
> From DTS point of view: MMC and WiFi (SDIO). Physically, only MMC
> (removable SDcard).

Ok, I see. Actually I suppose I should have ruled out SDIO as the source
of the problem because the backtrace clearly listed the blk_mq layer.

This might instead work:

index 4e67c1403cc9..e8f1d89bd019 100644
--- a/drivers/mmc/core/block.c
+++ b/drivers/mmc/core/block.c
@@ -1401,6 +1401,11 @@ static void mmc_blk_data_prep(struct mmc_queue
*mq, struct mmc_queue_req *mqrq,
                struct scatterlist *sg;

                for_each_sg(brq->data.sg, sg, brq->data.sg_len, i) {
+                       void *v = sg_virt(sg);
+
+                       WARN_ONCE(memory_intersects(_stext, _etext, v,
sg->length), "dma in .text: %p\n", v);
+                       WARN_ONCE(memory_intersects(__start_rodata,
__end_rodata, v, sg->length), "dma in .rodata: %p\n", v);
+
                        data_size -= sg->length;
                        if (data_size <= 0) {
                                sg->length += data_size;

Maybe also try passing "no_hash_pointers" on the command line to have
the warning
print the actual pointer value. If that is indeed part of the kernel
vmlinux image, you
should be able to find the address in System.map.

      Arnd

Re: Linux 5.18.x: sdhci issue

[Arnd Bergmann]

On Thu, May 5, 2022 at 7:02 AM Tony Lindgren <tony@atomide.com> wrote:
>
> Hi,
>
> * Yegor Yefremov <yegorslists@googlemail.com> [220504 09:12]:
> > Hi Tony, all,
> >
> > During the kernel boot I see the following error. The device is still
> > working afterwards. 5.17.5 shows the same behavior. Is this a known
> > issue?
>
> Thanks for reporting it, I was not aware of this one. Might be worth
> bisecting. Adding linux-mmc and Ulf.
>
> Regards,
>
> Tony
>
> > [    3.734570] sdhci-omap 48060000.mmc: Got CD GPIO
> > [    3.739989] INFO: trying to register non-static key.
> > [    3.744991] The code is fine but needs lockdep annotation, or maybe
> > [    3.751286] you didn't initialize this object before use?
> > [    3.756707] turning off the locking correctness validator.
> > [    3.762221] CPU: 0 PID: 8 Comm: kworker/u2:0 Not tainted 5.18.0-rc5 #1
> > [    3.768787] Hardware name: Generic AM33XX (Flattened Device Tree)
> > [    3.774913] Workqueue: events_unbound async_run_entry_fn
> > [    3.780283]  unwind_backtrace from show_stack+0x10/0x14
> > [    3.785555]  show_stack from dump_stack_lvl+0x58/0x70
> > [    3.790643]  dump_stack_lvl from register_lock_class+0x4ec/0x55c
> > [    3.796695]  register_lock_class from __lock_acquire+0x60/0x2bd4
> > [    3.802738]  __lock_acquire from lock_acquire.part.0+0xb0/0x248
> > [    3.808695]  lock_acquire.part.0 from _raw_spin_lock_irqsave+0x4c/0x68
> > [    3.815265]  _raw_spin_lock_irqsave from sdhci_init+0x34/0xf4
> > [    3.821051]  sdhci_init from sdhci_runtime_resume_host+0x3c/0x1bc
> > [    3.827180]  sdhci_runtime_resume_host from
> > sdhci_omap_runtime_resume+0x108/0x110
> > [    3.834710]  sdhci_omap_runtime_resume from __rpm_callback+0x3c/0x148
> > [    3.841197]  __rpm_callback from rpm_callback+0x50/0x54
> > [    3.846453]  rpm_callback from rpm_resume+0x518/0x71c
> > [    3.851534]  rpm_resume from __pm_runtime_resume+0x50/0x68
> > [    3.857052]  __pm_runtime_resume from sdhci_omap_probe+0x1e4/0x7a8
> > [    3.863270]  sdhci_omap_probe from platform_probe+0x58/0xbc
> > [    3.868886]  platform_probe from really_probe.part.0+0x9c/0x290

The problem is that sdhci_omap_probe() calls pm_runtime_enable()
before calling sdhci_setup_host(), so it's not in the correct state at this
point. One could get rid of the warning by moving the spin_lock_init()
from sdhci_setup_host() to sdhi_alloc_host(), but I suspect the problem
is in the omap part, and it would still be wrong to do the resume first.

       Arnd

Re: Linux 5.18.x: sdhci issue

[Tony Lindgren]

* Arnd Bergmann <arnd@arndb.de> [220531 11:38]:
> On Thu, May 5, 2022 at 7:02 AM Tony Lindgren <tony@atomide.com> wrote:
> >
> > Hi,
> >
> > * Yegor Yefremov <yegorslists@googlemail.com> [220504 09:12]:
> > > Hi Tony, all,
> > >
> > > During the kernel boot I see the following error. The device is still
> > > working afterwards. 5.17.5 shows the same behavior. Is this a known
> > > issue?
> >
> > Thanks for reporting it, I was not aware of this one. Might be worth
> > bisecting. Adding linux-mmc and Ulf.
> >
> > Regards,
> >
> > Tony
> >
> > > [    3.734570] sdhci-omap 48060000.mmc: Got CD GPIO
> > > [    3.739989] INFO: trying to register non-static key.
> > > [    3.744991] The code is fine but needs lockdep annotation, or maybe
> > > [    3.751286] you didn't initialize this object before use?
> > > [    3.756707] turning off the locking correctness validator.
> > > [    3.762221] CPU: 0 PID: 8 Comm: kworker/u2:0 Not tainted 5.18.0-rc5 #1
> > > [    3.768787] Hardware name: Generic AM33XX (Flattened Device Tree)
> > > [    3.774913] Workqueue: events_unbound async_run_entry_fn
> > > [    3.780283]  unwind_backtrace from show_stack+0x10/0x14
> > > [    3.785555]  show_stack from dump_stack_lvl+0x58/0x70
> > > [    3.790643]  dump_stack_lvl from register_lock_class+0x4ec/0x55c
> > > [    3.796695]  register_lock_class from __lock_acquire+0x60/0x2bd4
> > > [    3.802738]  __lock_acquire from lock_acquire.part.0+0xb0/0x248
> > > [    3.808695]  lock_acquire.part.0 from _raw_spin_lock_irqsave+0x4c/0x68
> > > [    3.815265]  _raw_spin_lock_irqsave from sdhci_init+0x34/0xf4
> > > [    3.821051]  sdhci_init from sdhci_runtime_resume_host+0x3c/0x1bc
> > > [    3.827180]  sdhci_runtime_resume_host from
> > > sdhci_omap_runtime_resume+0x108/0x110
> > > [    3.834710]  sdhci_omap_runtime_resume from __rpm_callback+0x3c/0x148
> > > [    3.841197]  __rpm_callback from rpm_callback+0x50/0x54
> > > [    3.846453]  rpm_callback from rpm_resume+0x518/0x71c
> > > [    3.851534]  rpm_resume from __pm_runtime_resume+0x50/0x68
> > > [    3.857052]  __pm_runtime_resume from sdhci_omap_probe+0x1e4/0x7a8
> > > [    3.863270]  sdhci_omap_probe from platform_probe+0x58/0xbc
> > > [    3.868886]  platform_probe from really_probe.part.0+0x9c/0x290
> 
> The problem is that sdhci_omap_probe() calls pm_runtime_enable()
> before calling sdhci_setup_host(), so it's not in the correct state at this
> point. One could get rid of the warning by moving the spin_lock_init()
> from sdhci_setup_host() to sdhi_alloc_host(), but I suspect the problem
> is in the omap part, and it would still be wrong to do the resume first.

Yes that makes sense. We need to resume early to detect the hardware
capabilities, we already check the status on first resume for context
save so we can just expand that.

Yegor, care to try to the following patch and see if that works for you?

Regards,

Tony

8< --------------
diff --git a/drivers/mmc/host/sdhci-omap.c b/drivers/mmc/host/sdhci-omap.c
--- a/drivers/mmc/host/sdhci-omap.c
+++ b/drivers/mmc/host/sdhci-omap.c
@@ -1441,7 +1441,8 @@ static int __maybe_unused sdhci_omap_runtime_suspend(struct device *dev)
 	struct sdhci_pltfm_host *pltfm_host = sdhci_priv(host);
 	struct sdhci_omap_host *omap_host = sdhci_pltfm_priv(pltfm_host);
 
-	sdhci_runtime_suspend_host(host);
+	if (omap_host->con != -EINVAL)
+		sdhci_runtime_suspend_host(host);
 
 	sdhci_omap_context_save(omap_host);
 
@@ -1458,10 +1459,10 @@ static int __maybe_unused sdhci_omap_runtime_resume(struct device *dev)
 
 	pinctrl_pm_select_default_state(dev);
 
-	if (omap_host->con != -EINVAL)
+	if (omap_host->con != -EINVAL) {
 		sdhci_omap_context_restore(omap_host);
-
-	sdhci_runtime_resume_host(host, 0);
+		sdhci_runtime_resume_host(host, 0);
+	}
 
 	return 0;
 }

Re: Linux 5.18.x: sdhci issue

[Yegor Yefremov]

Hi Tony, Ulf,

On Thu, May 5, 2022 at 7:03 AM Tony Lindgren <tony@atomide.com> wrote:
>
> Hi,
>
> * Yegor Yefremov <yegorslists@googlemail.com> [220504 09:12]:
> > Hi Tony, all,
> >
> > During the kernel boot I see the following error. The device is still
> > working afterwards. 5.17.5 shows the same behavior. Is this a known
> > issue?
>
> Thanks for reporting it, I was not aware of this one. Might be worth
> bisecting. Adding linux-mmc and Ulf.

This is my bisect result:

f433e8aac6b94218394c6e7b80bb89e4e79c9549 is the first bad commit
commit f433e8aac6b94218394c6e7b80bb89e4e79c9549
Author: Tony Lindgren <tony@atomide.com>
Date:   Fri Oct 15 13:47:18 2021 +0300

    mmc: sdhci-omap: Implement PM runtime functions

    Implement PM runtime functions and enable autosuspend.

    Note that we save context in probe to avoid restoring invalid context
    on the first resume. For system suspend, we have the new PM runtime
    functions do most of the work.

    Signed-off-by: Tony Lindgren <tony@atomide.com>
    Link: https://lore.kernel.org/r/20211015104720.52240-5-tony@atomide.com
    Signed-off-by: Ulf Hansson <ulf.hansson@linaro.org>

:040000 040000 52e18e4301299b678068dceb061cb5cab2b9e1c2
3a23df57d41d54132ca5dac0e8c6d189d5dc3773 M      drivers

Yegor

> > [    3.734570] sdhci-omap 48060000.mmc: Got CD GPIO
> > [    3.739989] INFO: trying to register non-static key.
> > [    3.744991] The code is fine but needs lockdep annotation, or maybe
> > [    3.751286] you didn't initialize this object before use?
> > [    3.756707] turning off the locking correctness validator.
> > [    3.762221] CPU: 0 PID: 8 Comm: kworker/u2:0 Not tainted 5.18.0-rc5 #1
> > [    3.768787] Hardware name: Generic AM33XX (Flattened Device Tree)
> > [    3.774913] Workqueue: events_unbound async_run_entry_fn
> > [    3.780283]  unwind_backtrace from show_stack+0x10/0x14
> > [    3.785555]  show_stack from dump_stack_lvl+0x58/0x70
> > [    3.790643]  dump_stack_lvl from register_lock_class+0x4ec/0x55c
> > [    3.796695]  register_lock_class from __lock_acquire+0x60/0x2bd4
> > [    3.802738]  __lock_acquire from lock_acquire.part.0+0xb0/0x248
> > [    3.808695]  lock_acquire.part.0 from _raw_spin_lock_irqsave+0x4c/0x68
> > [    3.815265]  _raw_spin_lock_irqsave from sdhci_init+0x34/0xf4
> > [    3.821051]  sdhci_init from sdhci_runtime_resume_host+0x3c/0x1bc
> > [    3.827180]  sdhci_runtime_resume_host from
> > sdhci_omap_runtime_resume+0x108/0x110
> > [    3.834710]  sdhci_omap_runtime_resume from __rpm_callback+0x3c/0x148
> > [    3.841197]  __rpm_callback from rpm_callback+0x50/0x54
> > [    3.846453]  rpm_callback from rpm_resume+0x518/0x71c
> > [    3.851534]  rpm_resume from __pm_runtime_resume+0x50/0x68
> > [    3.857052]  __pm_runtime_resume from sdhci_omap_probe+0x1e4/0x7a8
> > [    3.863270]  sdhci_omap_probe from platform_probe+0x58/0xbc
> > [    3.868886]  platform_probe from really_probe.part.0+0x9c/0x290
> > [    3.874843]  really_probe.part.0 from __driver_probe_device+0xa0/0x138
> > [    3.881409]  __driver_probe_device from driver_probe_device+0x30/0x10c
> > [    3.887975]  driver_probe_device from __device_attach_driver+0xb0/0xf8
> > [    3.894540]  __device_attach_driver from bus_for_each_drv+0x80/0xd0
> > [    3.900845]  bus_for_each_drv from __device_attach_async_helper+0xac/0xe0
> > [    3.907672]  __device_attach_async_helper from async_run_entry_fn+0x20/0xb0
> > [    3.914675]  async_run_entry_fn from process_one_work+0x284/0x72c
> > [    3.920811]  process_one_work from worker_thread+0x28/0x4b0
> > [    3.926418]  worker_thread from kthread+0xe4/0x104
> > [    3.931243]  kthread from ret_from_fork+0x14/0x28
> > [    3.935977] Exception stack(0xd0035fb0 to 0xd0035ff8)
> > [    3.941056] 5fa0:                                     00000000
> > 00000000 00000000 00000000
> > [    3.949274] 5fc0: 00000000 00000000 00000000 00000000 00000000
> > 00000000 00000000 00000000
> > [    3.957491] 5fe0: 00000000 00000000 00000000 00000000 00000013 00000000
> > [    3.964359] sdhci-omap 48060000.mmc: supply pbias not found, using
> > dummy regulator
> > [    3.972468] sdhci-omap 48060000.mmc: supply vqmmc not found, using
> > dummy regulator
> > [    3.982478] sdhci-omap 481d8000.mmc: supply pbias not found, using
> > dummy regulator
> > [    3.990665] sdhci-omap 481d8000.mmc: supply vqmmc not found, using
> > dummy regulator
> >
> > Regards,
> > Yegor

Re: Linux 5.18.x: sdhci issue

[Tony Lindgren]

* Yegor Yefremov <yegorslists@googlemail.com> [220615 09:40]:
> Hi Tony, Ulf,
> 
> On Thu, May 5, 2022 at 7:03 AM Tony Lindgren <tony@atomide.com> wrote:
> >
> > Hi,
> >
> > * Yegor Yefremov <yegorslists@googlemail.com> [220504 09:12]:
> > > Hi Tony, all,
> > >
> > > During the kernel boot I see the following error. The device is still
> > > working afterwards. 5.17.5 shows the same behavior. Is this a known
> > > issue?
> >
> > Thanks for reporting it, I was not aware of this one. Might be worth
> > bisecting. Adding linux-mmc and Ulf.
> 
> This is my bisect result:
> 
> f433e8aac6b94218394c6e7b80bb89e4e79c9549 is the first bad commit
> commit f433e8aac6b94218394c6e7b80bb89e4e79c9549
> Author: Tony Lindgren <tony@atomide.com>
> Date:   Fri Oct 15 13:47:18 2021 +0300
> 
>     mmc: sdhci-omap: Implement PM runtime functions
> 
>     Implement PM runtime functions and enable autosuspend.
> 
>     Note that we save context in probe to avoid restoring invalid context
>     on the first resume. For system suspend, we have the new PM runtime
>     functions do most of the work.
> 
>     Signed-off-by: Tony Lindgren <tony@atomide.com>
>     Link: https://lore.kernel.org/r/20211015104720.52240-5-tony@atomide.com
>     Signed-off-by: Ulf Hansson <ulf.hansson@linaro.org>

OK thanks this makes sense based on what Arnd replied a few days ago.

Regards,

Tony

Re: Linux 5.18.x: sdhci issue

[Yegor Yefremov]

Hi Tony,

On Wed, Jun 15, 2022 at 10:08 AM Tony Lindgren <tony@atomide.com> wrote:
>
> * Yegor Yefremov <yegorslists@googlemail.com> [220615 09:40]:
> > Hi Tony, Ulf,
> >
> > On Thu, May 5, 2022 at 7:03 AM Tony Lindgren <tony@atomide.com> wrote:
> > >
> > > Hi,
> > >
> > > * Yegor Yefremov <yegorslists@googlemail.com> [220504 09:12]:
> > > > Hi Tony, all,
> > > >
> > > > During the kernel boot I see the following error. The device is still
> > > > working afterwards. 5.17.5 shows the same behavior. Is this a known
> > > > issue?
> > >
> > > Thanks for reporting it, I was not aware of this one. Might be worth
> > > bisecting. Adding linux-mmc and Ulf.
> >
> > This is my bisect result:
> >
> > f433e8aac6b94218394c6e7b80bb89e4e79c9549 is the first bad commit
> > commit f433e8aac6b94218394c6e7b80bb89e4e79c9549
> > Author: Tony Lindgren <tony@atomide.com>
> > Date:   Fri Oct 15 13:47:18 2021 +0300
> >
> >     mmc: sdhci-omap: Implement PM runtime functions
> >
> >     Implement PM runtime functions and enable autosuspend.
> >
> >     Note that we save context in probe to avoid restoring invalid context
> >     on the first resume. For system suspend, we have the new PM runtime
> >     functions do most of the work.
> >
> >     Signed-off-by: Tony Lindgren <tony@atomide.com>
> >     Link: https://lore.kernel.org/r/20211015104720.52240-5-tony@atomide.com
> >     Signed-off-by: Ulf Hansson <ulf.hansson@linaro.org>
>
> OK thanks this makes sense based on what Arnd replied a few days ago.
>
> Regards,

Your patch did the trick: all warnings/errors are gone. Thanks
everyone for the help.

Yegor

Re: Linux 5.18.x: sdhci issue

[Tony Lindgren]

* Yegor Yefremov <yegorslists@googlemail.com> [220615 08:54]:
> Hi Tony,
> 
> On Wed, Jun 15, 2022 at 10:08 AM Tony Lindgren <tony@atomide.com> wrote:
> >
> > * Yegor Yefremov <yegorslists@googlemail.com> [220615 09:40]:
> > > Hi Tony, Ulf,
> > >
> > > On Thu, May 5, 2022 at 7:03 AM Tony Lindgren <tony@atomide.com> wrote:
> > > >
> > > > Hi,
> > > >
> > > > * Yegor Yefremov <yegorslists@googlemail.com> [220504 09:12]:
> > > > > Hi Tony, all,
> > > > >
> > > > > During the kernel boot I see the following error. The device is still
> > > > > working afterwards. 5.17.5 shows the same behavior. Is this a known
> > > > > issue?
> > > >
> > > > Thanks for reporting it, I was not aware of this one. Might be worth
> > > > bisecting. Adding linux-mmc and Ulf.
> > >
> > > This is my bisect result:
> > >
> > > f433e8aac6b94218394c6e7b80bb89e4e79c9549 is the first bad commit
> > > commit f433e8aac6b94218394c6e7b80bb89e4e79c9549
> > > Author: Tony Lindgren <tony@atomide.com>
> > > Date:   Fri Oct 15 13:47:18 2021 +0300
> > >
> > >     mmc: sdhci-omap: Implement PM runtime functions
> > >
> > >     Implement PM runtime functions and enable autosuspend.
> > >
> > >     Note that we save context in probe to avoid restoring invalid context
> > >     on the first resume. For system suspend, we have the new PM runtime
> > >     functions do most of the work.
> > >
> > >     Signed-off-by: Tony Lindgren <tony@atomide.com>
> > >     Link: https://lore.kernel.org/r/20211015104720.52240-5-tony@atomide.com
> > >     Signed-off-by: Ulf Hansson <ulf.hansson@linaro.org>
> >
> > OK thanks this makes sense based on what Arnd replied a few days ago.
> >
> > Regards,
> 
> Your patch did the trick: all warnings/errors are gone. Thanks
> everyone for the help.

OK thanks for testing, will send out a proper patch today for this.

Regards,

Tony