Default async probing for DT based systems

Default async probing for DT based systems

[Saravana Kannan]

Hi,

TL;DR: I want to improve boot times by enabling async probing by
default for DT based systems. Can you give it a shot please?

Why do you think it might work when async probing has been a pain before?
==========================================================
Since fw_devlink=on is the default behavior and fw_devlink understands
approximately 24 DT bindings, it should capture most of the device
dependencies and ensure proper probe ordering. For example, on a Pixel
6, fw_devlink figures out 325 dependencies that it uses to enforce
probe ordering.

You can find all the dependencies under /sys/class/devlink.

Fine! What do you want me to try?
==========================
With the patches that have landed in 5.19-rc1, we can now enable
default async probing for all built-in drivers by adding the following
to the kernel command line:

driver_async_probe=*

I'd really appreciate it if folks can try adding driver_async_probe=*
to their kernel command line and report any boot time
improvements/regression or boot/probe failures it causes.

(* insert cat begging pic *)
Can I haz some reports pleez?!

Tips:
====
One easy way to check for devices probe failures is to compare the
output of this command with/without the commandline changes:

# find /sys/devices -name driver

Btw, if you need to force sync probing for a few drivers so that your
rootfs mounts properly, you can set the flag in the driver, or you can
list them as exceptions following the * in the command line option.
For example:
driver_async_probe=*,my_flash_driver,my_sdio_driver

Report these too.

Known issues:
===========
fw_devlink doesn't yet support phy-handle and mdio-parent DT bindings.
They have some tricky issues I need to resolve first and I need to add
both of them together -- I'm working on it. If there are other DT
bindings that are missing support, do let me know. Most of them are
easy to add.

The driver_async_probe=* won't have any useful impact for modules
without adding <module_name>.async_probe to the commandline or
async_probe as a module option when loading it. This is because
modules intentionally force sync before they exit. There's a patch for
a global flag for modules too [1], but it can never be set by default
for userspace reasons[2].

[1] - https://lore.kernel.org/lkml/20220604010101.719508-1-saravanak@google.com/
[2] - https://lore.kernel.org/lkml/CA+55aFxV40V2WvNtJY3EC0F-B9wPk8CV2o1TTTyoF4CoWH7rhQ@mail.gmail.com/

Thanks,
Saravana

_______________________________________________
linux-arm-kernel mailing list
linux-arm-kernel@lists.infradead.org
http://lists.infradead.org/mailman/listinfo/linux-arm-kernel

Re: Default async probing for DT based systems

[Frank Rowand]

Hi Saravana,

You failed to include me in the distribution.  Adding myself now...

-Frank

On 6/15/22 23:24, Saravana Kannan wrote:
> Hi,
> 
> TL;DR: I want to improve boot times by enabling async probing by
> default for DT based systems. Can you give it a shot please?
> 
> Why do you think it might work when async probing has been a pain before?
> ==========================================================
> Since fw_devlink=on is the default behavior and fw_devlink understands
> approximately 24 DT bindings, it should capture most of the device
> dependencies and ensure proper probe ordering. For example, on a Pixel
> 6, fw_devlink figures out 325 dependencies that it uses to enforce
> probe ordering.
> 
> You can find all the dependencies under /sys/class/devlink.
> 
> Fine! What do you want me to try?
> ==========================
> With the patches that have landed in 5.19-rc1, we can now enable
> default async probing for all built-in drivers by adding the following
> to the kernel command line:
> 
> driver_async_probe=*
> 
> I'd really appreciate it if folks can try adding driver_async_probe=*
> to their kernel command line and report any boot time
> improvements/regression or boot/probe failures it causes.
> 
> (* insert cat begging pic *)
> Can I haz some reports pleez?!
> 
> Tips:
> ====
> One easy way to check for devices probe failures is to compare the
> output of this command with/without the commandline changes:
> 
> # find /sys/devices -name driver
> 
> Btw, if you need to force sync probing for a few drivers so that your
> rootfs mounts properly, you can set the flag in the driver, or you can
> list them as exceptions following the * in the command line option.
> For example:
> driver_async_probe=*,my_flash_driver,my_sdio_driver
> 
> Report these too.
> 
> Known issues:
> ===========
> fw_devlink doesn't yet support phy-handle and mdio-parent DT bindings.
> They have some tricky issues I need to resolve first and I need to add
> both of them together -- I'm working on it. If there are other DT
> bindings that are missing support, do let me know. Most of them are
> easy to add.
> 
> The driver_async_probe=* won't have any useful impact for modules
> without adding <module_name>.async_probe to the commandline or
> async_probe as a module option when loading it. This is because
> modules intentionally force sync before they exit. There's a patch for
> a global flag for modules too [1], but it can never be set by default
> for userspace reasons[2].
> 
> [1] - https://lore.kernel.org/lkml/20220604010101.719508-1-saravanak@google.com/
> [2] - https://lore.kernel.org/lkml/CA+55aFxV40V2WvNtJY3EC0F-B9wPk8CV2o1TTTyoF4CoWH7rhQ@mail.gmail.com/
> 
> Thanks,
> Saravana
> 
> _______________________________________________
> linux-arm-kernel mailing list
> linux-arm-kernel@lists.infradead.org
> http://lists.infradead.org/mailman/listinfo/linux-arm-kernel


_______________________________________________
linux-arm-kernel mailing list
linux-arm-kernel@lists.infradead.org
http://lists.infradead.org/mailman/listinfo/linux-arm-kernel

Re: Default async probing for DT based systems

[Linus Walleij]

On Thu, Jun 16, 2022 at 5:25 AM Saravana Kannan <saravanak@google.com> wrote:

> Since fw_devlink=on is the default behavior and fw_devlink understands
> approximately 24 DT bindings,

How can I see which these are, in the kernel tree?

Yours,
Linus Walleij

_______________________________________________
linux-arm-kernel mailing list
linux-arm-kernel@lists.infradead.org
http://lists.infradead.org/mailman/listinfo/linux-arm-kernel

Re: Default async probing for DT based systems

[Saravana Kannan]

On Fri, Jun 17, 2022 at 1:21 AM Linus Walleij <linus.walleij@linaro.org> wrote:
>
> On Thu, Jun 16, 2022 at 5:25 AM Saravana Kannan <saravanak@google.com> wrote:
>
> > Since fw_devlink=on is the default behavior and fw_devlink understands
> > approximately 24 DT bindings,
>
> How can I see which these are, in the kernel tree?

device/of/property.c has an array of these binding handling functions
in of_supplier_bindings[].

Most of the functions there are created using DEFINE_SIMPLE_PROP() or
DEFINE_SUFFIX_PROP() that's also in the same file.

-Saravana

_______________________________________________
linux-arm-kernel mailing list
linux-arm-kernel@lists.infradead.org
http://lists.infradead.org/mailman/listinfo/linux-arm-kernel

Re: Default async probing for DT based systems

[Linus Walleij]

On Fri, Jun 17, 2022 at 8:01 PM Saravana Kannan <saravanak@google.com> wrote:
> On Fri, Jun 17, 2022 at 1:21 AM Linus Walleij <linus.walleij@linaro.org> wrote:
> > On Thu, Jun 16, 2022 at 5:25 AM Saravana Kannan <saravanak@google.com> wrote:
> >
> > > Since fw_devlink=on is the default behavior and fw_devlink understands
> > > approximately 24 DT bindings,
> >
> > How can I see which these are, in the kernel tree?
>
> device/of/property.c has an array of these binding handling functions
> in of_supplier_bindings[].
>
> Most of the functions there are created using DEFINE_SIMPLE_PROP() or
> DEFINE_SUFFIX_PROP() that's also in the same file.

Thanks!

We already have some device links in pin control, it's an opt-in for
drivers, used e.g in drivers/pinctrl/stm32/pinctrl-stm32.c
where you see
pctl->pctl_desc.link_consumers = true;
how does that
play with this? Double device links at different levels?

I had a patch to just enforce device links on all pinctrl resources,
but it seemed over the top:
https://git.kernel.org/pub/scm/linux/kernel/git/linusw/linux-pinctrl.git/commit/?h=consumer-link-enforce&id=73441cf773ed91bff0e7f66614d391b2514188bf

Yours,
Linus Walleij

_______________________________________________
linux-arm-kernel mailing list
linux-arm-kernel@lists.infradead.org
http://lists.infradead.org/mailman/listinfo/linux-arm-kernel

Re: Default async probing for DT based systems

[Saravana Kannan]

On Sat, Jun 25, 2022 at 11:09 AM Linus Walleij <linus.walleij@linaro.org> wrote:
>
> On Fri, Jun 17, 2022 at 8:01 PM Saravana Kannan <saravanak@google.com> wrote:
> > On Fri, Jun 17, 2022 at 1:21 AM Linus Walleij <linus.walleij@linaro.org> wrote:
> > > On Thu, Jun 16, 2022 at 5:25 AM Saravana Kannan <saravanak@google.com> wrote:
> > >
> > > > Since fw_devlink=on is the default behavior and fw_devlink understands
> > > > approximately 24 DT bindings,
> > >
> > > How can I see which these are, in the kernel tree?
> >
> > device/of/property.c has an array of these binding handling functions
> > in of_supplier_bindings[].
> >
> > Most of the functions there are created using DEFINE_SIMPLE_PROP() or
> > DEFINE_SUFFIX_PROP() that's also in the same file.
>
> Thanks!
>
> We already have some device links in pin control, it's an opt-in for
> drivers, used e.g in drivers/pinctrl/stm32/pinctrl-stm32.c
> where you see
> pctl->pctl_desc.link_consumers = true;
> how does that
> play with this? Double device links at different levels?

Depends on what device you use for the supplier.

If it's the true device that probes and registers with the pinctrl
framework, then there won't be any double device links. It'll actually
be helpful because fw_devlink uses these attempts initiated by the
driver to confirm the dependencies it inferred from DT -- so when it
infers a cycle, it'll keep the links that drivers have attempted and
"ignore" the rest of the links in the cycle when it comes to probe
ordering.

If you use the devices the pinctrl framework creates on the gpio-bus
as the supplier for the device link, then yes, it'll be additional
device links. I'm not sure how useful they are on top of the ones
fw_devlink creates with the true device. If you don't need to do any
special suspend sequence for each of the individual gpio-devices, then
I'd recommend just creating one with the true device as the supplier.

-Saravana

>
> I had a patch to just enforce device links on all pinctrl resources,
> but it seemed over the top:
> https://git.kernel.org/pub/scm/linux/kernel/git/linusw/linux-pinctrl.git/commit/?h=consumer-link-enforce&id=73441cf773ed91bff0e7f66614d391b2514188bf
>
> Yours,
> Linus Walleij

_______________________________________________
linux-arm-kernel mailing list
linux-arm-kernel@lists.infradead.org
http://lists.infradead.org/mailman/listinfo/linux-arm-kernel

Re: Default async probing for DT based systems

[Marek Szyprowski]

Hi Saravana,

On 16.06.2022 05:24, Saravana Kannan wrote:
> Hi,
>
> TL;DR: I want to improve boot times by enabling async probing by
> default for DT based systems. Can you give it a shot please?

Yes, I've gave it a try on my test systems. It looks that there are a 
few issues. The first one, the most obvious to notice, is related to 
__request_module() calls from various drivers and frameworks. Here are 
some examples:

------------[ cut here ]------------
WARNING: CPU: 3 PID: 73 at kernel/kmod.c:136 __request_module+0x230/0x600
Modules linked in:
CPU: 3 PID: 73 Comm: kworker/u12:5 Not tainted 5.19.0-rc2-next-20220615+ 
#5203
Hardware name: ARM Juno development board (r1) (DT)
Workqueue: events_unbound async_run_entry_fn
pstate: 00000005 (nzcv daif -PAN -UAO -TCO -DIT -SSBS BTYPE=--)
UDC core: g_ether: couldn't find an available UDC
pc : __request_module+0x230/0x600
lr : __request_module+0x228/0x600
...
Call trace:
  __request_module+0x230/0x600
  phy_request_driver_module+0x118/0x164
  phy_device_create+0x210/0x23c
  get_phy_device+0x8c/0x160
  mdiobus_scan+0x40/0x1cc
  __mdiobus_register+0x184/0x36c
  smsc911x_drv_probe+0x648/0xa84
  platform_probe+0x68/0xe0
  really_probe+0xbc/0x2e0
  __driver_probe_device+0x78/0xe0
  driver_probe_device+0xa8/0x140
  __driver_attach_async_helper+0x50/0xbc
  async_run_entry_fn+0x34/0xd0
  process_one_work+0x288/0x6bc
  worker_thread+0x74/0x450
  kthread+0x118/0x11c
  ret_from_fork+0x10/0x20
irq event stamp: 2032
hardirqs last  enabled at (2031): [<ffff8000091b91dc>] 
_raw_spin_unlock_irqrestore+0x98/0x9c
hardirqs last disabled at (2032): [<ffff8000091ac844>] el1_dbg+0x24/0x90
softirqs last  enabled at (2018): [<ffff800008010470>] _stext+0x470/0x5e8
softirqs last disabled at (2007): [<ffff8000080a5214>] 
__irq_exit_rcu+0x180/0x1ac
---[ end trace 0000000000000000 ]---

------------[ cut here ]------------
WARNING: CPU: 0 PID: 54 at kernel/kmod.c:136 __request_module+0x230/0x600
Modules linked in: rng_core(+) rtc_meson_vrtc(+) mdio_mux_meson_g12a(+) 
meson_ir pcs_xpcs meson_canvas(+) meson_dw_hdmi dw_hdmi 
snd_soc_meson_axg_tdm_interface di
xg_tdm_formatter nvmem_meson_efuse
CPU: 0 PID: 54 Comm: kworker/u8:3 Not tainted 5.19.0-rc2-next-20220615+ 
#5203
Hardware name: Hardkernel ODROID-C4 (DT)
Workqueue: events_unbound async_run_entry_fn
pstate: 00400009 (nzcv daif +PAN -UAO -TCO -DIT -SSBS BTYPE=--)
pc : __request_module+0x230/0x600
lr : __request_module+0x228/0x600
...
Call trace:
  __request_module+0x230/0x600
  rc_map_get+0xa8/0x134
  rc_register_device+0x10c/0x600
  devm_rc_register_device+0x4c/0x170
  meson_ir_probe+0x160/0x2bc [meson_ir]
  platform_probe+0x68/0xe0
  really_probe+0xbc/0x2e0
  __driver_probe_device+0x78/0xe0
  driver_probe_device+0x3c/0x140
  __driver_attach_async_helper+0x50/0xbc
  async_run_entry_fn+0x34/0xd0
  process_one_work+0x288/0x6bc
  worker_thread+0x74/0x450
  kthread+0x118/0x11c
  ret_from_fork+0x10/0x20
irq event stamp: 62052
hardirqs last  enabled at (62051): [<ffff800008329c08>] 
___slab_alloc+0x734/0x82c
hardirqs last disabled at (62052): [<ffff8000091ac844>] el1_dbg+0x24/0x90
softirqs last  enabled at (61920): [<ffff800008010470>] _stext+0x470/0x5e8
softirqs last disabled at (61859): [<ffff8000080a5214>] 
__irq_exit_rcu+0x180/0x1ac
---[ end trace 0000000000000000 ]---

------------[ cut here ]------------
WARNING: CPU: 0 PID: 46 at kernel/kmod.c:136 __request_module+0x230/0x600
Modules linked in:
CPU: 0 PID: 46 Comm: kworker/u4:4 Not tainted 5.19.0-rc2-next-20220615+ 
#5203
Hardware name: linux,dummy-virt (DT)
Workqueue: events_unbound async_run_entry_fn
pstate: 00000005 (nzcv daif -PAN -UAO -TCO -DIT -SSBS BTYPE=--)
pc : __request_module+0x230/0x600
lr : __request_module+0x228/0x600
...
Call trace:
  __request_module+0x230/0x600
  parse_mtd_partitions+0x2b4/0x490
  mtd_device_parse_register+0x90/0x2bc
  physmap_flash_probe+0x4c8/0x7b0
  platform_probe+0x68/0xe0
  really_probe+0xbc/0x2e0
  __driver_probe_device+0x78/0xe0
  driver_probe_device+0xa8/0x140
  __driver_attach_async_helper+0x50/0xbc
  async_run_entry_fn+0x34/0xd0
  process_one_work+0x288/0x6bc
  worker_thread+0x74/0x450
  kthread+0x118/0x11c
  ret_from_fork+0x10/0x20
irq event stamp: 674
hardirqs last  enabled at (673): [<ffffddb219125380>] 
vprintk_store+0x440/0x4a0
hardirqs last disabled at (674): [<ffffddb21a1ac844>] el1_dbg+0x24/0x90
softirqs last  enabled at (618): [<ffffddb219010470>] _stext+0x470/0x5e8
softirqs last disabled at (613): [<ffffddb2190a5214>] 
__irq_exit_rcu+0x180/0x1ac
---[ end trace 0000000000000000 ]---

------------[ cut here ]------------
WARNING: CPU: 0 PID: 63 at kernel/kmod.c:136 __request_module+0x23c/0x42c
Modules linked in: exynos_bus soundcore s5p_mfc lima brcmutil 
drm_shmem_helper exynos_adc gpu_sched sha256_generic libsha256 
sha256_arm cfg80211 phy_exynos_usb2 s
dma_contig videobuf2_memops videobuf2_v4l2 videobuf2_common videodev 
exynosdrm analogix_dp mc exynos_ppmu rtc_s3c i2c_gpio
CPU: 0 PID: 63 Comm: kworker/u4:5 Not tainted 
5.19.0-rc2-next-20220615-00040-g868471ca3680-dirty #5205
Hardware name: Samsung Exynos (Flattened Device Tree)
Workqueue: events_unbound async_run_entry_fn
  unwind_backtrace from show_stack+0x10/0x14
  show_stack from dump_stack_lvl+0x40/0x4c
  dump_stack_lvl from __warn+0xcc/0x144
  __warn from warn_slowpath_fmt+0x5c/0xb4
  warn_slowpath_fmt from __request_module+0x23c/0x42c
  __request_module from try_then_request_governor+0x60/0xb0
  try_then_request_governor from devfreq_add_device+0x498/0x5c8
  devfreq_add_device from devm_devfreq_add_device+0x58/0x94
  devm_devfreq_add_device from exynos_bus_probe+0x1b4/0x6bc [exynos_bus]
  exynos_bus_probe [exynos_bus] from platform_probe+0x5c/0xb8
  platform_probe from really_probe+0xc8/0x2f0
  really_probe from __driver_probe_device+0x84/0xe4
  __driver_probe_device from driver_probe_device+0x30/0x104
  driver_probe_device from __driver_attach_async_helper+0x48/0x98
  __driver_attach_async_helper from async_run_entry_fn+0x24/0xb0
  async_run_entry_fn from process_one_work+0x1ec/0x4d0
  process_one_work from worker_thread+0x58/0x54c
  worker_thread from kthread+0xd0/0xec
  kthread from ret_from_fork+0x14/0x2c
Exception stack(0xe0349fb0 to 0xe0349ff8)
...
---[ end trace 0000000000000000 ]---
------------[ cut here ]------------
WARNING: CPU: 0 PID: 63 at kernel/kmod.c:136 __request_module+0x23c/0x42c
Modules linked in: exynos_bus soundcore s5p_mfc lima brcmutil 
drm_shmem_helper exynos_adc gpu_sched sha256_generic libsha256 
sha256_arm cfg80211 phy_exynos_usb2 s
dma_contig videobuf2_memops videobuf2_v4l2 videobuf2_common videodev 
exynosdrm analogix_dp mc exynos_ppmu rtc_s3c i2c_gpio
CPU: 0 PID: 63 Comm: kworker/u4:5 Not tainted 
5.19.0-rc2-next-20220615-00040-g868471ca3680-dirty #5205
Hardware name: Samsung Exynos (Flattened Device Tree)
Workqueue: events_unbound async_run_entry_fn
  unwind_backtrace from show_stack+0x10/0x14
  show_stack from dump_stack_lvl+0x40/0x4c
  dump_stack_lvl from __warn+0xcc/0x144
  __warn from warn_slowpath_fmt+0x5c/0xb4
  warn_slowpath_fmt from __request_module+0x23c/0x42c
  __request_module from try_then_request_governor+0x60/0xb0
  try_then_request_governor from devfreq_add_device+0x498/0x5c8
  devfreq_add_device from devm_devfreq_add_device+0x58/0x94
  devm_devfreq_add_device from exynos_bus_probe+0x1b4/0x6bc [exynos_bus]
  exynos_bus_probe [exynos_bus] from platform_probe+0x5c/0xb8
  platform_probe from really_probe+0xc8/0x2f0
  really_probe from __driver_probe_device+0x84/0xe4
  __driver_probe_device from driver_probe_device+0x30/0x104
  driver_probe_device from __driver_attach_async_helper+0x48/0x98
  __driver_attach_async_helper from async_run_entry_fn+0x24/0xb0
  async_run_entry_fn from process_one_work+0x1ec/0x4d0
  process_one_work from worker_thread+0x58/0x54c
  worker_thread from kthread+0xd0/0xec
  kthread from ret_from_fork+0x14/0x2c
Exception stack(0xe0349fb0 to 0xe0349ff8)
...
---[ end trace 0000000000000000 ]---

------------[ cut here ]------------
WARNING: CPU: 0 PID: 23 at kernel/kmod.c:136 __request_module+0x23c/0x42c
Modules linked in: g_ether usb_f_rndis u_ether libcomposite brcmfmac 
brcmutil sha256_generic libsha256 snd_soc_hdmi_codec snd_soc_core 
sha256_arm ac97_bus snd_pcm
_timer snd soundcore panel_samsung_ld9040 hci_uart btbcm bluetooth 
s5p_csis s5p_fimc exynos4_is_common v4l2_fwnode ecdh_generic ecc 
v4l2_async spi_gpio phy_exynos
x8998 pwm_samsung max8952 drm_shmem_helper libaes s5p_mfc gpu_sched 
s5p_jpeg v4l2_mem2mem videobuf2_dma_contig videobuf2_memops 
videobuf2_v4l2 phy_exynos_usb2 vid
m ohci_exynos ehci_exynos analogix_dp mc s5p_sss exynos_rng rtc_s3c 
s3c2410_wdt i2c_gpio
CPU: 0 PID: 23 Comm: kworker/u4:7 Not tainted 
5.19.0-rc2-next-20220615-00040-g868471ca3680-dirty #5205
Hardware name: Samsung Exynos (Flattened Device Tree)
Workqueue: events_unbound async_run_entry_fn
  unwind_backtrace from show_stack+0x10/0x14
  show_stack from dump_stack_lvl+0x40/0x4c
  dump_stack_lvl from __warn+0xcc/0x144
  __warn from warn_slowpath_fmt+0x5c/0xb4
  warn_slowpath_fmt from __request_module+0x23c/0x42c
  __request_module from usb_get_function_instance+0x3c/0x58 [libcomposite]
  usb_get_function_instance [libcomposite] from eth_bind+0x3c/0x334 
[g_ether]
  eth_bind [g_ether] from composite_bind+0x78/0x18c [libcomposite]
  composite_bind [libcomposite] from gadget_bind_driver+0x8c/0x1d0
  gadget_bind_driver from really_probe+0xc8/0x2f0
  really_probe from __driver_probe_device+0x84/0xe4
  __driver_probe_device from driver_probe_device+0x30/0x104
  driver_probe_device from __driver_attach_async_helper+0x48/0x98
  __driver_attach_async_helper from async_run_entry_fn+0x24/0xb0
  async_run_entry_fn from process_one_work+0x1ec/0x4d0
  process_one_work from worker_thread+0x58/0x54c
  worker_thread from kthread+0xd0/0xec
  kthread from ret_from_fork+0x14/0x2c
Exception stack(0xe08ddfb0 to 0xe08ddff8)
...
---[ end trace 0000000000000000 ]---


Some Exynos-based boards also freeze quite early, after the 'EXYNOS5420 
PMU initialized' message. I will investigate this later once I find some 
spare time.

 > ...

Best regards
-- 
Marek Szyprowski, PhD
Samsung R&D Institute Poland


_______________________________________________
linux-arm-kernel mailing list
linux-arm-kernel@lists.infradead.org
http://lists.infradead.org/mailman/listinfo/linux-arm-kernel

Re: Default async probing for DT based systems

[Saravana Kannan]

On Fri, Jun 17, 2022 at 2:04 AM Marek Szyprowski
<m.szyprowski@samsung.com> wrote:
>
> Hi Saravana,
>
> On 16.06.2022 05:24, Saravana Kannan wrote:
> > Hi,
> >
> > TL;DR: I want to improve boot times by enabling async probing by
> > default for DT based systems. Can you give it a shot please?
>
> Yes, I've gave it a try on my test systems. It looks that there are a
> few issues. The first one, the most obvious to notice, is related to
> __request_module() calls from various drivers and frameworks. Here are
> some examples:
>
> ------------[ cut here ]------------
> WARNING: CPU: 3 PID: 73 at kernel/kmod.c:136 __request_module+0x230/0x600
> Modules linked in:
> CPU: 3 PID: 73 Comm: kworker/u12:5 Not tainted 5.19.0-rc2-next-20220615+
> #5203
> Hardware name: ARM Juno development board (r1) (DT)
> Workqueue: events_unbound async_run_entry_fn
> pstate: 00000005 (nzcv daif -PAN -UAO -TCO -DIT -SSBS BTYPE=--)
> UDC core: g_ether: couldn't find an available UDC
> pc : __request_module+0x230/0x600
> lr : __request_module+0x228/0x600

Ah, I think I know what these might be. Going by memory,
__request_module() from asyc thread context has some issues for module
loading. So I think a check was added like this. And I think the check
is triggering when it shouldn't (this isn't module context here).

> ...
> Call trace:
>   __request_module+0x230/0x600
>   phy_request_driver_module+0x118/0x164
>   phy_device_create+0x210/0x23c
>   get_phy_device+0x8c/0x160
>   mdiobus_scan+0x40/0x1cc
>   __mdiobus_register+0x184/0x36c
>   smsc911x_drv_probe+0x648/0xa84
>   platform_probe+0x68/0xe0
>   really_probe+0xbc/0x2e0
>   __driver_probe_device+0x78/0xe0
>   driver_probe_device+0xa8/0x140
>   __driver_attach_async_helper+0x50/0xbc
>   async_run_entry_fn+0x34/0xd0
>   process_one_work+0x288/0x6bc
>   worker_thread+0x74/0x450
>   kthread+0x118/0x11c
>   ret_from_fork+0x10/0x20
> irq event stamp: 2032
> hardirqs last  enabled at (2031): [<ffff8000091b91dc>]
> _raw_spin_unlock_irqrestore+0x98/0x9c
> hardirqs last disabled at (2032): [<ffff8000091ac844>] el1_dbg+0x24/0x90
> softirqs last  enabled at (2018): [<ffff800008010470>] _stext+0x470/0x5e8
> softirqs last disabled at (2007): [<ffff8000080a5214>]
> __irq_exit_rcu+0x180/0x1ac
> ---[ end trace 0000000000000000 ]---
>
> ------------[ cut here ]------------
> WARNING: CPU: 0 PID: 54 at kernel/kmod.c:136 __request_module+0x230/0x600
> Modules linked in: rng_core(+) rtc_meson_vrtc(+) mdio_mux_meson_g12a(+)
> meson_ir pcs_xpcs meson_canvas(+) meson_dw_hdmi dw_hdmi
> snd_soc_meson_axg_tdm_interface di
> xg_tdm_formatter nvmem_meson_efuse
> CPU: 0 PID: 54 Comm: kworker/u8:3 Not tainted 5.19.0-rc2-next-20220615+
> #5203
> Hardware name: Hardkernel ODROID-C4 (DT)
> Workqueue: events_unbound async_run_entry_fn
> pstate: 00400009 (nzcv daif +PAN -UAO -TCO -DIT -SSBS BTYPE=--)
> pc : __request_module+0x230/0x600
> lr : __request_module+0x228/0x600
> ...
> Call trace:
>   __request_module+0x230/0x600
>   rc_map_get+0xa8/0x134
>   rc_register_device+0x10c/0x600
>   devm_rc_register_device+0x4c/0x170
>   meson_ir_probe+0x160/0x2bc [meson_ir]
>   platform_probe+0x68/0xe0
>   really_probe+0xbc/0x2e0
>   __driver_probe_device+0x78/0xe0
>   driver_probe_device+0x3c/0x140
>   __driver_attach_async_helper+0x50/0xbc
>   async_run_entry_fn+0x34/0xd0
>   process_one_work+0x288/0x6bc
>   worker_thread+0x74/0x450
>   kthread+0x118/0x11c
>   ret_from_fork+0x10/0x20
> irq event stamp: 62052
> hardirqs last  enabled at (62051): [<ffff800008329c08>]
> ___slab_alloc+0x734/0x82c
> hardirqs last disabled at (62052): [<ffff8000091ac844>] el1_dbg+0x24/0x90
> softirqs last  enabled at (61920): [<ffff800008010470>] _stext+0x470/0x5e8
> softirqs last disabled at (61859): [<ffff8000080a5214>]
> __irq_exit_rcu+0x180/0x1ac
> ---[ end trace 0000000000000000 ]---
>
> ------------[ cut here ]------------
> WARNING: CPU: 0 PID: 46 at kernel/kmod.c:136 __request_module+0x230/0x600
> Modules linked in:
> CPU: 0 PID: 46 Comm: kworker/u4:4 Not tainted 5.19.0-rc2-next-20220615+
> #5203
> Hardware name: linux,dummy-virt (DT)
> Workqueue: events_unbound async_run_entry_fn
> pstate: 00000005 (nzcv daif -PAN -UAO -TCO -DIT -SSBS BTYPE=--)
> pc : __request_module+0x230/0x600
> lr : __request_module+0x228/0x600
> ...
> Call trace:
>   __request_module+0x230/0x600
>   parse_mtd_partitions+0x2b4/0x490
>   mtd_device_parse_register+0x90/0x2bc
>   physmap_flash_probe+0x4c8/0x7b0
>   platform_probe+0x68/0xe0
>   really_probe+0xbc/0x2e0
>   __driver_probe_device+0x78/0xe0
>   driver_probe_device+0xa8/0x140
>   __driver_attach_async_helper+0x50/0xbc
>   async_run_entry_fn+0x34/0xd0
>   process_one_work+0x288/0x6bc
>   worker_thread+0x74/0x450
>   kthread+0x118/0x11c
>   ret_from_fork+0x10/0x20
> irq event stamp: 674
> hardirqs last  enabled at (673): [<ffffddb219125380>]
> vprintk_store+0x440/0x4a0
> hardirqs last disabled at (674): [<ffffddb21a1ac844>] el1_dbg+0x24/0x90
> softirqs last  enabled at (618): [<ffffddb219010470>] _stext+0x470/0x5e8
> softirqs last disabled at (613): [<ffffddb2190a5214>]
> __irq_exit_rcu+0x180/0x1ac
> ---[ end trace 0000000000000000 ]---
>
> ------------[ cut here ]------------
> WARNING: CPU: 0 PID: 63 at kernel/kmod.c:136 __request_module+0x23c/0x42c
> Modules linked in: exynos_bus soundcore s5p_mfc lima brcmutil
> drm_shmem_helper exynos_adc gpu_sched sha256_generic libsha256
> sha256_arm cfg80211 phy_exynos_usb2 s
> dma_contig videobuf2_memops videobuf2_v4l2 videobuf2_common videodev
> exynosdrm analogix_dp mc exynos_ppmu rtc_s3c i2c_gpio
> CPU: 0 PID: 63 Comm: kworker/u4:5 Not tainted
> 5.19.0-rc2-next-20220615-00040-g868471ca3680-dirty #5205
> Hardware name: Samsung Exynos (Flattened Device Tree)
> Workqueue: events_unbound async_run_entry_fn
>   unwind_backtrace from show_stack+0x10/0x14
>   show_stack from dump_stack_lvl+0x40/0x4c
>   dump_stack_lvl from __warn+0xcc/0x144
>   __warn from warn_slowpath_fmt+0x5c/0xb4
>   warn_slowpath_fmt from __request_module+0x23c/0x42c
>   __request_module from try_then_request_governor+0x60/0xb0
>   try_then_request_governor from devfreq_add_device+0x498/0x5c8
>   devfreq_add_device from devm_devfreq_add_device+0x58/0x94
>   devm_devfreq_add_device from exynos_bus_probe+0x1b4/0x6bc [exynos_bus]
>   exynos_bus_probe [exynos_bus] from platform_probe+0x5c/0xb8
>   platform_probe from really_probe+0xc8/0x2f0
>   really_probe from __driver_probe_device+0x84/0xe4
>   __driver_probe_device from driver_probe_device+0x30/0x104
>   driver_probe_device from __driver_attach_async_helper+0x48/0x98
>   __driver_attach_async_helper from async_run_entry_fn+0x24/0xb0
>   async_run_entry_fn from process_one_work+0x1ec/0x4d0
>   process_one_work from worker_thread+0x58/0x54c
>   worker_thread from kthread+0xd0/0xec
>   kthread from ret_from_fork+0x14/0x2c
> Exception stack(0xe0349fb0 to 0xe0349ff8)
> ...
> ---[ end trace 0000000000000000 ]---
> ------------[ cut here ]------------
> WARNING: CPU: 0 PID: 63 at kernel/kmod.c:136 __request_module+0x23c/0x42c
> Modules linked in: exynos_bus soundcore s5p_mfc lima brcmutil
> drm_shmem_helper exynos_adc gpu_sched sha256_generic libsha256
> sha256_arm cfg80211 phy_exynos_usb2 s
> dma_contig videobuf2_memops videobuf2_v4l2 videobuf2_common videodev
> exynosdrm analogix_dp mc exynos_ppmu rtc_s3c i2c_gpio
> CPU: 0 PID: 63 Comm: kworker/u4:5 Not tainted
> 5.19.0-rc2-next-20220615-00040-g868471ca3680-dirty #5205
> Hardware name: Samsung Exynos (Flattened Device Tree)
> Workqueue: events_unbound async_run_entry_fn
>   unwind_backtrace from show_stack+0x10/0x14
>   show_stack from dump_stack_lvl+0x40/0x4c
>   dump_stack_lvl from __warn+0xcc/0x144
>   __warn from warn_slowpath_fmt+0x5c/0xb4
>   warn_slowpath_fmt from __request_module+0x23c/0x42c
>   __request_module from try_then_request_governor+0x60/0xb0
>   try_then_request_governor from devfreq_add_device+0x498/0x5c8
>   devfreq_add_device from devm_devfreq_add_device+0x58/0x94
>   devm_devfreq_add_device from exynos_bus_probe+0x1b4/0x6bc [exynos_bus]
>   exynos_bus_probe [exynos_bus] from platform_probe+0x5c/0xb8
>   platform_probe from really_probe+0xc8/0x2f0
>   really_probe from __driver_probe_device+0x84/0xe4
>   __driver_probe_device from driver_probe_device+0x30/0x104
>   driver_probe_device from __driver_attach_async_helper+0x48/0x98
>   __driver_attach_async_helper from async_run_entry_fn+0x24/0xb0
>   async_run_entry_fn from process_one_work+0x1ec/0x4d0
>   process_one_work from worker_thread+0x58/0x54c
>   worker_thread from kthread+0xd0/0xec
>   kthread from ret_from_fork+0x14/0x2c
> Exception stack(0xe0349fb0 to 0xe0349ff8)
> ...
> ---[ end trace 0000000000000000 ]---
>
> ------------[ cut here ]------------
> WARNING: CPU: 0 PID: 23 at kernel/kmod.c:136 __request_module+0x23c/0x42c
> Modules linked in: g_ether usb_f_rndis u_ether libcomposite brcmfmac
> brcmutil sha256_generic libsha256 snd_soc_hdmi_codec snd_soc_core
> sha256_arm ac97_bus snd_pcm
> _timer snd soundcore panel_samsung_ld9040 hci_uart btbcm bluetooth
> s5p_csis s5p_fimc exynos4_is_common v4l2_fwnode ecdh_generic ecc
> v4l2_async spi_gpio phy_exynos
> x8998 pwm_samsung max8952 drm_shmem_helper libaes s5p_mfc gpu_sched
> s5p_jpeg v4l2_mem2mem videobuf2_dma_contig videobuf2_memops
> videobuf2_v4l2 phy_exynos_usb2 vid
> m ohci_exynos ehci_exynos analogix_dp mc s5p_sss exynos_rng rtc_s3c
> s3c2410_wdt i2c_gpio
> CPU: 0 PID: 23 Comm: kworker/u4:7 Not tainted
> 5.19.0-rc2-next-20220615-00040-g868471ca3680-dirty #5205
> Hardware name: Samsung Exynos (Flattened Device Tree)
> Workqueue: events_unbound async_run_entry_fn
>   unwind_backtrace from show_stack+0x10/0x14
>   show_stack from dump_stack_lvl+0x40/0x4c
>   dump_stack_lvl from __warn+0xcc/0x144
>   __warn from warn_slowpath_fmt+0x5c/0xb4
>   warn_slowpath_fmt from __request_module+0x23c/0x42c
>   __request_module from usb_get_function_instance+0x3c/0x58 [libcomposite]
>   usb_get_function_instance [libcomposite] from eth_bind+0x3c/0x334
> [g_ether]
>   eth_bind [g_ether] from composite_bind+0x78/0x18c [libcomposite]
>   composite_bind [libcomposite] from gadget_bind_driver+0x8c/0x1d0
>   gadget_bind_driver from really_probe+0xc8/0x2f0
>   really_probe from __driver_probe_device+0x84/0xe4
>   __driver_probe_device from driver_probe_device+0x30/0x104
>   driver_probe_device from __driver_attach_async_helper+0x48/0x98
>   __driver_attach_async_helper from async_run_entry_fn+0x24/0xb0
>   async_run_entry_fn from process_one_work+0x1ec/0x4d0
>   process_one_work from worker_thread+0x58/0x54c
>   worker_thread from kthread+0xd0/0xec
>   kthread from ret_from_fork+0x14/0x2c
> Exception stack(0xe08ddfb0 to 0xe08ddff8)
> ...
> ---[ end trace 0000000000000000 ]---
>
>
> Some Exynos-based boards also freeze quite early, after the 'EXYNOS5420
> PMU initialized' message. I will investigate this later once I find some
> spare time.

Thanks!

-Saravana

>
>  > ...
>
> Best regards
> --
> Marek Szyprowski, PhD
> Samsung R&D Institute Poland
>
> --
> To unsubscribe from this group and stop receiving emails from it, send an email to kernel-team+unsubscribe@android.com.
>

_______________________________________________
linux-arm-kernel mailing list
linux-arm-kernel@lists.infradead.org
http://lists.infradead.org/mailman/listinfo/linux-arm-kernel

Re: Default async probing for DT based systems

[Saravana Kannan]

On Fri, Jun 17, 2022 at 11:04 AM Saravana Kannan <saravanak@google.com> wrote:
>
> On Fri, Jun 17, 2022 at 2:04 AM Marek Szyprowski
> <m.szyprowski@samsung.com> wrote:
> >
> > Hi Saravana,
> >
> > On 16.06.2022 05:24, Saravana Kannan wrote:
> > > Hi,
> > >
> > > TL;DR: I want to improve boot times by enabling async probing by
> > > default for DT based systems. Can you give it a shot please?
> >
> > Yes, I've gave it a try on my test systems. It looks that there are a
> > few issues. The first one, the most obvious to notice, is related to
> > __request_module() calls from various drivers and frameworks. Here are
> > some examples:
> >
> > ------------[ cut here ]------------
> > WARNING: CPU: 3 PID: 73 at kernel/kmod.c:136 __request_module+0x230/0x600
> > Modules linked in:
> > CPU: 3 PID: 73 Comm: kworker/u12:5 Not tainted 5.19.0-rc2-next-20220615+
> > #5203
> > Hardware name: ARM Juno development board (r1) (DT)
> > Workqueue: events_unbound async_run_entry_fn
> > pstate: 00000005 (nzcv daif -PAN -UAO -TCO -DIT -SSBS BTYPE=--)
> > UDC core: g_ether: couldn't find an available UDC
> > pc : __request_module+0x230/0x600
> > lr : __request_module+0x228/0x600
>
> Ah, I think I know what these might be. Going by memory,
> __request_module() from asyc thread context has some issues for module
> loading. So I think a check was added like this. And I think the check
> is triggering when it shouldn't (this isn't module context here).

My memory was right and this is indeed the spurious warning that was
meant to cover a potential deadlock in a module load path. I was
trying to disable this warning till we hit the point in the boot flow
where request_module() can actually succeed. But I got stuck trying to
figure it out.

It looks like the usermode helper that's used for module loading
triggered by request_module() is enabled in populate_rootfs() that
runs well before most of the initcalls are done. I was under the
impression that init with pid 0 would be the first userspace thread
that can start. But I don't see anything obvious that prevents the
usermode helper from running and loading a module before init process
has been exec'ed after we set system_state to SYSTEM_RUNNING.

Can someone clarify when is the earliest request_module() can succeed?

Thanks,
Saravana

_______________________________________________
linux-arm-kernel mailing list
linux-arm-kernel@lists.infradead.org
http://lists.infradead.org/mailman/listinfo/linux-arm-kernel

Re: Default async probing for DT based systems

[Greg Kroah-Hartman]

On Wed, Jun 22, 2022 at 07:36:24PM -0700, Saravana Kannan wrote:
> On Fri, Jun 17, 2022 at 11:04 AM Saravana Kannan <saravanak@google.com> wrote:
> >
> > On Fri, Jun 17, 2022 at 2:04 AM Marek Szyprowski
> > <m.szyprowski@samsung.com> wrote:
> > >
> > > Hi Saravana,
> > >
> > > On 16.06.2022 05:24, Saravana Kannan wrote:
> > > > Hi,
> > > >
> > > > TL;DR: I want to improve boot times by enabling async probing by
> > > > default for DT based systems. Can you give it a shot please?
> > >
> > > Yes, I've gave it a try on my test systems. It looks that there are a
> > > few issues. The first one, the most obvious to notice, is related to
> > > __request_module() calls from various drivers and frameworks. Here are
> > > some examples:
> > >
> > > ------------[ cut here ]------------
> > > WARNING: CPU: 3 PID: 73 at kernel/kmod.c:136 __request_module+0x230/0x600
> > > Modules linked in:
> > > CPU: 3 PID: 73 Comm: kworker/u12:5 Not tainted 5.19.0-rc2-next-20220615+
> > > #5203
> > > Hardware name: ARM Juno development board (r1) (DT)
> > > Workqueue: events_unbound async_run_entry_fn
> > > pstate: 00000005 (nzcv daif -PAN -UAO -TCO -DIT -SSBS BTYPE=--)
> > > UDC core: g_ether: couldn't find an available UDC
> > > pc : __request_module+0x230/0x600
> > > lr : __request_module+0x228/0x600
> >
> > Ah, I think I know what these might be. Going by memory,
> > __request_module() from asyc thread context has some issues for module
> > loading. So I think a check was added like this. And I think the check
> > is triggering when it shouldn't (this isn't module context here).
> 
> My memory was right and this is indeed the spurious warning that was
> meant to cover a potential deadlock in a module load path. I was
> trying to disable this warning till we hit the point in the boot flow
> where request_module() can actually succeed. But I got stuck trying to
> figure it out.
> 
> It looks like the usermode helper that's used for module loading
> triggered by request_module() is enabled in populate_rootfs() that
> runs well before most of the initcalls are done. I was under the
> impression that init with pid 0 would be the first userspace thread
> that can start. But I don't see anything obvious that prevents the
> usermode helper from running and loading a module before init process
> has been exec'ed after we set system_state to SYSTEM_RUNNING.
> 
> Can someone clarify when is the earliest request_module() can succeed?

It can succeed very very early, when we have the initial ramfs mounted
before init runs as you sometimes need the modules there to be able to
load the device that init is on.

thanks,

greg k-h

_______________________________________________
linux-arm-kernel mailing list
linux-arm-kernel@lists.infradead.org
http://lists.infradead.org/mailman/listinfo/linux-arm-kernel