long ucsi_acpi_platform_driver_init

long ucsi_acpi_platform_driver_init

[Randy Dunlap]

[-- Attachment #1: Type: text/plain, Size: 544 bytes --]

Hi,

On my custom 5.16, 5.17-rc1, and 5.17-rc2 kernels I am seeing
ucsi_acpi_platform_driver_init() take around 60 seconds.

[    2.733138] calling  ucsi_acpi_platform_driver_init+0x0/0x1000 [ucsi_acpi] @ 470
[   64.603126] initcall ucsi_acpi_platform_driver_init+0x0/0x1000 [ucsi_acpi] returned 0 after 58690601 usecs


Did I miss some other (needed) Kconfig option or is something missing in
my system's ACPI tables e.g.?

DMI: Dell Inc. Inspiron 15 5510/076F7Y, BIOS 2.4.1 11/05/2021


Full kernel boot log is attached (gzipped).

-- 
~Randy

[-- Attachment #2: boot-517rc2-ucsi.log.gz --]
[-- Type: application/gzip, Size: 46358 bytes --]

Re: long ucsi_acpi_platform_driver_init

[Heikki Krogerus]

On Sun, Feb 06, 2022 at 05:28:48PM -0800, Randy Dunlap wrote:
> Hi,
> 
> On my custom 5.16, 5.17-rc1, and 5.17-rc2 kernels I am seeing
> ucsi_acpi_platform_driver_init() take around 60 seconds.
> 
> [    2.733138] calling  ucsi_acpi_platform_driver_init+0x0/0x1000 [ucsi_acpi] @ 470
> [   64.603126] initcall ucsi_acpi_platform_driver_init+0x0/0x1000 [ucsi_acpi] returned 0 after 58690601 usecs

I don't have any ideas what could be causing it to take that long?
That driver does not really do anything else except it queues a work
that then actually initialises the UCSI interface. The probe() in that
driver (ucsi_acpi) does not stay and wait for the initialisation to
finish.

Can you check are the USB Type-C devices appearing under
/sys/class/typec faster then that?

Also, if the driver is a module, can you check does it always take
that long if you unload and the reload the module (ucsi_acpi.ko)?

> Did I miss some other (needed) Kconfig option or is something missing in
> my system's ACPI tables e.g.?

There shouldn't be any dependencies that are missing, but it would not
hurt to take a look at your acpi tables. Can you send acpidump?

Though, I doubt there is anything missing from there either.

> DMI: Dell Inc. Inspiron 15 5510/076F7Y, BIOS 2.4.1 11/05/2021

thanks,

-- 
heikki

Re: long ucsi_acpi_platform_driver_init

[Randy Dunlap]

On 2/7/22 03:35, Heikki Krogerus wrote:
> On Sun, Feb 06, 2022 at 05:28:48PM -0800, Randy Dunlap wrote:
>> Hi,
>>
>> On my custom 5.16, 5.17-rc1, and 5.17-rc2 kernels I am seeing
>> ucsi_acpi_platform_driver_init() take around 60 seconds.
>>
>> [    2.733138] calling  ucsi_acpi_platform_driver_init+0x0/0x1000 [ucsi_acpi] @ 470
>> [   64.603126] initcall ucsi_acpi_platform_driver_init+0x0/0x1000 [ucsi_acpi] returned 0 after 58690601 usecs
> 
> I don't have any ideas what could be causing it to take that long?
> That driver does not really do anything else except it queues a work
> that then actually initialises the UCSI interface. The probe() in that
> driver (ucsi_acpi) does not stay and wait for the initialisation to
> finish.
> 
> Can you check are the USB Type-C devices appearing under
> /sys/class/typec faster then that?

One entry there:

lrwxrwxrwx 1 root root 0 Feb  7 08:57 port0 -> ../../devices/platform/USBC000:00/typec/port0/

Do you want more than that?

> Also, if the driver is a module, can you check does it always take
> that long if you unload and the reload the module (ucsi_acpi.ko)?
> 
>> Did I miss some other (needed) Kconfig option or is something missing in
>> my system's ACPI tables e.g.?
> 
> There shouldn't be any dependencies that are missing, but it would not
> hurt to take a look at your acpi tables. Can you send acpidump?
> 
> Though, I doubt there is anything missing from there either.
> 
>> DMI: Dell Inc. Inspiron 15 5510/076F7Y, BIOS 2.4.1 11/05/2021

The (large) acpidump output is here:
  http://www.infradead.org/~rdunlap/doc/dell15-acpidump.out.gz


thanks.
-- 
~Randy

Re: long ucsi_acpi_platform_driver_init

[Heikki Krogerus]

On Mon, Feb 07, 2022 at 09:01:50AM -0800, Randy Dunlap wrote:
> 
> 
> On 2/7/22 03:35, Heikki Krogerus wrote:
> > On Sun, Feb 06, 2022 at 05:28:48PM -0800, Randy Dunlap wrote:
> >> Hi,
> >>
> >> On my custom 5.16, 5.17-rc1, and 5.17-rc2 kernels I am seeing
> >> ucsi_acpi_platform_driver_init() take around 60 seconds.
> >>
> >> [    2.733138] calling  ucsi_acpi_platform_driver_init+0x0/0x1000 [ucsi_acpi] @ 470
> >> [   64.603126] initcall ucsi_acpi_platform_driver_init+0x0/0x1000 [ucsi_acpi] returned 0 after 58690601 usecs
> > 
> > I don't have any ideas what could be causing it to take that long?
> > That driver does not really do anything else except it queues a work
> > that then actually initialises the UCSI interface. The probe() in that
> > driver (ucsi_acpi) does not stay and wait for the initialisation to
> > finish.
> > 
> > Can you check are the USB Type-C devices appearing under
> > /sys/class/typec faster then that?
> 
> One entry there:
> 
> lrwxrwxrwx 1 root root 0 Feb  7 08:57 port0 -> ../../devices/platform/USBC000:00/typec/port0/
> 
> Do you want more than that?

You should have a port there for every physical USB Type-C
port on you system.

I can't really tell from that was the port registered before
ucsi_acpi_platform_driver_init() finished or not.

> > Also, if the driver is a module, can you check does it always take
> > that long if you unload and the reload the module (ucsi_acpi.ko)?
> > 
> >> Did I miss some other (needed) Kconfig option or is something missing in
> >> my system's ACPI tables e.g.?
> > 
> > There shouldn't be any dependencies that are missing, but it would not
> > hurt to take a look at your acpi tables. Can you send acpidump?
> > 
> > Though, I doubt there is anything missing from there either.
> > 
> >> DMI: Dell Inc. Inspiron 15 5510/076F7Y, BIOS 2.4.1 11/05/2021
> 
> The (large) acpidump output is here:
>   http://www.infradead.org/~rdunlap/doc/dell15-acpidump.out.gz

Thanks!

Br,

-- 
heikki

Re: long ucsi_acpi_platform_driver_init

[Randy Dunlap]

Hi,

On 2/9/22 06:35, Heikki Krogerus wrote:
> On Mon, Feb 07, 2022 at 09:01:50AM -0800, Randy Dunlap wrote:
>>
>>
>> On 2/7/22 03:35, Heikki Krogerus wrote:
>>> On Sun, Feb 06, 2022 at 05:28:48PM -0800, Randy Dunlap wrote:
>>>> Hi,
>>>>
>>>> On my custom 5.16, 5.17-rc1, and 5.17-rc2 kernels I am seeing
>>>> ucsi_acpi_platform_driver_init() take around 60 seconds.
>>>>
>>>> [    2.733138] calling  ucsi_acpi_platform_driver_init+0x0/0x1000 [ucsi_acpi] @ 470
>>>> [   64.603126] initcall ucsi_acpi_platform_driver_init+0x0/0x1000 [ucsi_acpi] returned 0 after 58690601 usecs
>>>
>>> I don't have any ideas what could be causing it to take that long?
>>> That driver does not really do anything else except it queues a work
>>> that then actually initialises the UCSI interface. The probe() in that
>>> driver (ucsi_acpi) does not stay and wait for the initialisation to
>>> finish.
>>>
>>> Can you check are the USB Type-C devices appearing under
>>> /sys/class/typec faster then that?
>>
>> One entry there:
>>
>> lrwxrwxrwx 1 root root 0 Feb  7 08:57 port0 -> ../../devices/platform/USBC000:00/typec/port0/
>>
>> Do you want more than that?
> 
> You should have a port there for every physical USB Type-C
> port on you system.

Yes, I have only one Type-C port.

> I can't really tell from that was the port registered before
> ucsi_acpi_platform_driver_init() finished or not.

Sorry, I didn't understand the first time...

I rebooted and checked /sys/class/typec multiple times. It was empty until
the end of ucsi_acpi_platform_driver_init() roughly 55 seconds later.


>>> Also, if the driver is a module, can you check does it always take
>>> that long if you unload and the reload the module (ucsi_acpi.ko)?
>>>
>>>> Did I miss some other (needed) Kconfig option or is something missing in
>>>> my system's ACPI tables e.g.?
>>>
>>> There shouldn't be any dependencies that are missing, but it would not
>>> hurt to take a look at your acpi tables. Can you send acpidump?
>>>
>>> Though, I doubt there is anything missing from there either.
>>>
>>>> DMI: Dell Inc. Inspiron 15 5510/076F7Y, BIOS 2.4.1 11/05/2021
>>
>> The (large) acpidump output is here:
>>   http://www.infradead.org/~rdunlap/doc/dell15-acpidump.out.gz
> 
> Thanks!
> 
> Br,
> 

-- 
~Randy

Re: long ucsi_acpi_platform_driver_init

[Randy Dunlap]

Hi again,

On 2/9/22 09:14, Randy Dunlap wrote:
> Hi,
> 
> On 2/9/22 06:35, Heikki Krogerus wrote:
>> On Mon, Feb 07, 2022 at 09:01:50AM -0800, Randy Dunlap wrote:
>>>
>>>
>>> On 2/7/22 03:35, Heikki Krogerus wrote:
>>>> On Sun, Feb 06, 2022 at 05:28:48PM -0800, Randy Dunlap wrote:
>>>>> Hi,
>>>>>
>>>>> On my custom 5.16, 5.17-rc1, and 5.17-rc2 kernels I am seeing
>>>>> ucsi_acpi_platform_driver_init() take around 60 seconds.
>>>>>
>>>>> [    2.733138] calling  ucsi_acpi_platform_driver_init+0x0/0x1000 [ucsi_acpi] @ 470
>>>>> [   64.603126] initcall ucsi_acpi_platform_driver_init+0x0/0x1000 [ucsi_acpi] returned 0 after 58690601 usecs
>>>>
>>>> I don't have any ideas what could be causing it to take that long?
>>>> That driver does not really do anything else except it queues a work
>>>> that then actually initialises the UCSI interface. The probe() in that
>>>> driver (ucsi_acpi) does not stay and wait for the initialisation to
>>>> finish.
>>>>
>>>> Can you check are the USB Type-C devices appearing under
>>>> /sys/class/typec faster then that?
>>>
>>> One entry there:
>>>
>>> lrwxrwxrwx 1 root root 0 Feb  7 08:57 port0 -> ../../devices/platform/USBC000:00/typec/port0/
>>>
>>> Do you want more than that?
>>
>> You should have a port there for every physical USB Type-C
>> port on you system.
> 
> Yes, I have only one Type-C port.
> 
>> I can't really tell from that was the port registered before
>> ucsi_acpi_platform_driver_init() finished or not.
> 
> Sorry, I didn't understand the first time...
> 
> I rebooted and checked /sys/class/typec multiple times. It was empty until
> the end of ucsi_acpi_platform_driver_init() roughly 55 seconds later.
> 

Good news. Pretty sure that it's not a problem with ucsi_acpi code.

I noticed that there were a few kernel log messages about firmware loading
near the ucsi_acpi init messages so I looked at my kernel's config options.

I had this one set/enabled:

config FW_LOADER_USER_HELPER_FALLBACK
	bool "Force the firmware sysfs fallback mechanism when possible"
	depends on FW_LOADER_USER_HELPER
	help
...
	  If you are unsure about this, say N here.

After disabling it, there is no significant delay in ucsi_acpi_platform_driver_init.

I'm happy to blame it on this kernel config option.


cheers.
-- 
~Randy

Re: long ucsi_acpi_platform_driver_init

[Heikki Krogerus]

On Wed, Feb 09, 2022 at 10:11:30PM -0800, Randy Dunlap wrote:
> Hi again,
> 
> On 2/9/22 09:14, Randy Dunlap wrote:
> > Hi,
> > 
> > On 2/9/22 06:35, Heikki Krogerus wrote:
> >> On Mon, Feb 07, 2022 at 09:01:50AM -0800, Randy Dunlap wrote:
> >>>
> >>>
> >>> On 2/7/22 03:35, Heikki Krogerus wrote:
> >>>> On Sun, Feb 06, 2022 at 05:28:48PM -0800, Randy Dunlap wrote:
> >>>>> Hi,
> >>>>>
> >>>>> On my custom 5.16, 5.17-rc1, and 5.17-rc2 kernels I am seeing
> >>>>> ucsi_acpi_platform_driver_init() take around 60 seconds.
> >>>>>
> >>>>> [    2.733138] calling  ucsi_acpi_platform_driver_init+0x0/0x1000 [ucsi_acpi] @ 470
> >>>>> [   64.603126] initcall ucsi_acpi_platform_driver_init+0x0/0x1000 [ucsi_acpi] returned 0 after 58690601 usecs
> >>>>
> >>>> I don't have any ideas what could be causing it to take that long?
> >>>> That driver does not really do anything else except it queues a work
> >>>> that then actually initialises the UCSI interface. The probe() in that
> >>>> driver (ucsi_acpi) does not stay and wait for the initialisation to
> >>>> finish.
> >>>>
> >>>> Can you check are the USB Type-C devices appearing under
> >>>> /sys/class/typec faster then that?
> >>>
> >>> One entry there:
> >>>
> >>> lrwxrwxrwx 1 root root 0 Feb  7 08:57 port0 -> ../../devices/platform/USBC000:00/typec/port0/
> >>>
> >>> Do you want more than that?
> >>
> >> You should have a port there for every physical USB Type-C
> >> port on you system.
> > 
> > Yes, I have only one Type-C port.
> > 
> >> I can't really tell from that was the port registered before
> >> ucsi_acpi_platform_driver_init() finished or not.
> > 
> > Sorry, I didn't understand the first time...
> > 
> > I rebooted and checked /sys/class/typec multiple times. It was empty until
> > the end of ucsi_acpi_platform_driver_init() roughly 55 seconds later.
> > 
> 
> Good news. Pretty sure that it's not a problem with ucsi_acpi code.
> 
> I noticed that there were a few kernel log messages about firmware loading
> near the ucsi_acpi init messages so I looked at my kernel's config options.
> 
> I had this one set/enabled:
> 
> config FW_LOADER_USER_HELPER_FALLBACK
> 	bool "Force the firmware sysfs fallback mechanism when possible"
> 	depends on FW_LOADER_USER_HELPER
> 	help
> ...
> 	  If you are unsure about this, say N here.
> 
> After disabling it, there is no significant delay in ucsi_acpi_platform_driver_init.
> 
> I'm happy to blame it on this kernel config option.

OK, that works for me, at least for now.

thanks,

-- 
heikki