Bug 1720638 - 60s+ delay on Wait for Complete Device Initialization - i2c_nvidia_gpu
Summary: 60s+ delay on Wait for Complete Device Initialization - i2c_nvidia_gpu
Keywords:
Status: CLOSED CURRENTRELEASE
Alias: None
Product: Fedora
Classification: Fedora
Component: kernel
Version: 31
Hardware: Unspecified
OS: Unspecified
unspecified
unspecified
Target Milestone: ---
Assignee: Kernel Maintainer List
QA Contact: Fedora Extras Quality Assurance
URL:
Whiteboard:
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2019-06-14 12:14 UTC by Marcin Zajaczkowski
Modified: 2020-05-05 14:24 UTC (History)
21 users (show)

Fixed In Version:
Doc Type: If docs needed, set a value
Doc Text:
Clone Of:
Environment:
Last Closed: 2020-05-05 14:24:22 UTC
Type: Bug
Embargoed:


Attachments (Terms of Use)

Description Marcin Zajaczkowski 2019-06-14 12:14:01 UTC
1. Please describe the problem:

The booting process of Fedora on Hyperbook NH5/Clevo NH55RCQ (with GeForce GTX 1660 Ti) hangs on:
> Wait for Complete Device Initialization
for 60s+.

After intensive research I have found a culprit and blacklisting i2c_nvidia_hpu helps. However, (if possible) it could be fixed upstream or at least applied automatically in corresponding cases.

2. What is the Version-Release number of the kernel:
kernel-core-5.2.0-0.rc4.git0.1.fc30.x86_64 (rebuilt from SRPM due to https://bugs.freedesktop.org/show_bug.cgi?id=110830)
kernel-core-5.1.5-300.fc30.x86_64

3. Did it work previously in Fedora? If so, what kernel version did the issue
   *first* appear?  Old kernels are available for download at
   https://koji.fedoraproject.org/koji/packageinfo?packageID=8 :

Not with the original kernel in Fedora 30 - it was also affected. I haven't tested with the previous Fedora versions.

4. Can you reproduce this issue? If so, please provide the steps to reproduce
   the issue below:

Try to boot Fedora.

5. Does this problem occur with the latest Rawhide kernel? To install the
   Rawhide kernel, run ``sudo dnf install fedora-repos-rawhide`` followed by
   ``sudo dnf update --enablerepo=rawhide kernel``:

Yes, with:
kernel-core-5.2.0-0.rc4.git0.1.fc30.x86_64

6. Are you running any modules that not shipped with directly Fedora's kernel?:

No.

7. Please attach the kernel logs. You can get the complete kernel log
   for a boot with ``journalctl --no-hostname -k > dmesg.txt``. If the
   issue occurred on a previous boot, use the journalctl ``-b`` flag.

As it took me ahile, I post here a way how I found a reason to (potentially) help others struggling with similar issues.

> Jun 14 11:14:06 foobar systemd[1]: Starting udev Wait for Complete Device Initialization...
> ...
> Jun 14 11:14:12 foobar systemd[1]: systemd-rfkill.service: Succeeded.
> Jun 14 11:14:12 foobar audit[1]: SERVICE_STOP pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='unit=systemd-rfkill comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? >
> Jun 14 11:14:12 foobar kernel: kauditd_printk_skb: 42 callbacks suppressed
> Jun 14 11:14:12 foobar kernel: audit: type=1131 audit(1560503652.402:64): pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='unit=systemd-rfkill comm="systemd" exe="/usr/lib/systemd/systemd" h>
> Jun 14 11:15:07 foobar systemd-udevd[1095]: 24-0008: Worker [1171] processing SEQNUM=3730 is taking a long time
> Jun 14 11:15:40 foobar systemd[1]: Started udev Wait for Complete Device Initialization.


"systemd-analyze blame" confirmed "systemd-udev-settle.service" as the main delay point.

I turned on debug logs in udev by adding udev_log="debug" in /etc/udev/udev.conf. With that I've got:

> $ journalctl -b -2 | grep 24-0008
> Jun 14 12:44:48 foobar systemd-udevd[1089]: 24-0008: Device (SEQNUM=3683, ACTION=add) is queued
> Jun 14 12:44:48 foobar systemd-udevd[1089]: 24-0008: sd-device-monitor: Passed 195 byte to netlink monitor
> Jun 14 12:44:48 foobar systemd-udevd[1098]: 24-0008: Processing device (SEQNUM=3683, ACTION=add)
> Jun 14 12:44:48 foobar systemd-udevd[1098]: 24-0008: IMPORT builtin 'hwdb' /usr/lib/udev/rules.d/50-udev-default.rules:14
> Jun 14 12:44:48 foobar systemd-udevd[1098]: 24-0008: No entry found from hwdb.
> Jun 14 12:44:48 foobar systemd-udevd[1098]: 24-0008: IMPORT builtin 'hwdb' fails: No data available
> Jun 14 12:44:48 foobar systemd-udevd[1098]: 24-0008: RUN 'kmod load $env{MODALIAS}' /usr/lib/udev/rules.d/80-drivers.rules:5
> Jun 14 12:45:48 foobar systemd-udevd[1089]: 24-0008: Worker [1098] processing SEQNUM=3683 is taking a long time
> Jun 14 12:46:21 foobar systemd-udevd[1089]: 24-0008: Device (SEQNUM=3959, ACTION=bind) is queued
> Jun 14 12:46:21 foobar systemd-udevd[1098]: 24-0008: Device (SEQNUM=3683, ACTION=add) processed
> Jun 14 12:46:21 foobar systemd-udevd[1098]: 24-0008: sd-device-monitor: Passed 195 byte to netlink monitor
> Jun 14 12:46:21 foobar systemd-udevd[1089]: 24-0008: sd-device-monitor: Passed 213 byte to netlink monitor
> Jun 14 12:46:21 foobar systemd-udevd[1100]: 24-0008: Processing device (SEQNUM=3959, ACTION=bind)
> Jun 14 12:46:21 foobar systemd-udevd[1100]: 24-0008: IMPORT builtin 'hwdb' /usr/lib/udev/rules.d/50-udev-default.rules:14
> Jun 14 12:46:21 foobar systemd-udevd[1100]: 24-0008: No entry found from hwdb.
> Jun 14 12:46:21 foobar systemd-udevd[1100]: 24-0008: IMPORT builtin 'hwdb' fails: No data available
> Jun 14 12:46:21 foobar systemd-udevd[1100]: 24-0008: Device (SEQNUM=3959, ACTION=bind) processed
> Jun 14 12:46:21 foobar systemd-udevd[1100]: 24-0008: sd-device-monitor: Passed 213 byte to netlink monitor
> Jun 14 12:47:16 foobar kernel: ucsi_ccg 24-0008: failed to reset PPM!
> Jun 14 12:47:16 foobar kernel: ucsi_ccg 24-0008: PPM init failed (-110)

And:

> $ udevadm info /sys/bus/i2c/devices/24-0008
> Successfully loaded SELinux database in 1.002ms, size on heap is 328K.
> P: /devices/pci0000:00/0000:00:01.0/0000:01:00.3/i2c-24/24-0008
> L: 0
> E: DEVPATH=/devices/pci0000:00/0000:00:01.0/0000:01:00.3/i2c-24/24-0008
> E: DRIVER=ucsi_ccg
> E: MODALIAS=i2c:ccgx-ucsi
> E: SUBSYSTEM=i2c

which suggests NVidia. Having more keywords I was albe to find this thread related to similar Clevo-based laptop:
https://github.com/pop-os/pop/issues/520#issuecomment-486338074

Blacklisting i2c_nvidia_gpu in fact removed the delay.

Comment 1 Roger Noble 2019-08-10 11:30:50 UTC
Same issue here on Fedora 30 with 5.2.6 and previous kernels at least as far back as 5.1.20. Nvidia 2060 graphics card. Blacklisting i2c_nvidia_gpu removes the delay.

Comment 2 Alex Smith 2019-12-09 08:25:39 UTC
This issue also occurs for me on kernel 5.3.13-300.fc31.x86_64 with an NVIDIA RTX 2080 Super GPU. It only started happening after upgrading to that GPU, it didn't not occur with my previous GTX 1070.

Blacklisting i2c_nvidia_gpu works around the issue.

Comment 3 Peter Schiffer 2020-01-20 22:45:11 UTC
Still an issue on 5.4.10-200.fc31.x86_64 with geforce 2060. Blacklisting i2c_nvidia_gpu fixed it.

Comment 4 Diep Pham 2020-02-24 03:59:04 UTC
This is still an issue with Fedora 31 (kernel: 5.5.5-200.fc31.x86_64). I don't know what i2c_nvidia_gpu provides, what is the downside of blacklisting it?

Comment 5 Justin M. Forbes 2020-03-03 16:33:37 UTC
*********** MASS BUG UPDATE **************

We apologize for the inconvenience.  There are a large number of bugs to go through and several of them have gone stale.  Due to this, we are doing a mass bug update across all of the Fedora 30 kernel bugs.

Fedora 30 has now been rebased to 5.5.7-100.fc30.  Please test this kernel update (or newer) and let us know if you issue has been resolved or if it is still present with the newer kernel.

If you have moved on to Fedora 31, and are still experiencing this issue, please change the version to Fedora 31.

If you experience different issues, please open a new bug report for those.

Comment 6 Steven Schlansker 2020-03-12 06:38:01 UTC
Hello, I can confirm this bug still exists in F31 5.5.7-200.fc31.x86_64.  Applying the suggested i2c_nvidia_gpu blacklist fixes the issue with no observed harm.

Comment 7 Steven Schlansker 2020-03-12 06:45:51 UTC
Sorry, just noticed the update.  Exact same story with 5.5.8-200.fc31.x86_64

Comment 8 Ben Cotton 2020-04-30 20:21:30 UTC
This message is a reminder that Fedora 30 is nearing its end of life.
Fedora will stop maintaining and issuing updates for Fedora 30 on 2020-05-26.
It is Fedora's policy to close all bug reports from releases that are no longer
maintained. At that time this bug will be closed as EOL if it remains open with a
Fedora 'version' of '30'.

Package Maintainer: If you wish for this bug to remain open because you
plan to fix it in a currently maintained version, simply change the 'version' 
to a later Fedora version.

Thank you for reporting this issue and we are sorry that we were not 
able to fix it before Fedora 30 is end of life. If you would still like 
to see this bug fixed and are able to reproduce it against a later version 
of Fedora, you are encouraged  change the 'version' to a later Fedora 
version prior this bug is closed as described in the policy above.

Although we aim to fix as many bugs as possible during every release's 
lifetime, sometimes those efforts are overtaken by events. Often a 
more recent Fedora release includes newer upstream software that fixes 
bugs or makes them obsolete.

Comment 9 Alex Smith 2020-05-03 08:30:18 UTC
This issue appears to be resolved for me in kernel 5.6 in Fedora 32 (5.6.8-300.fc32.x86_64), I no longer see a hang with the i2c_nvidia_gpu blacklist removed.

Comment 10 Steven Schlansker 2020-05-03 15:22:07 UTC
I upgraded to the same kernel in F32, removed the blacklist entry, all is well.  I agree this seems to be fixed.  Thanks all!

Comment 11 Marcin Zajaczkowski 2020-05-05 14:24:22 UTC
Confirmed with 5.6.8-300 in Fedora 32. Closing.


Note You need to log in before you can comment on or make changes to this bug.