Bug 1173728 - journal is flooded with "upowerd: treating change event as add on" when Dell WD15 Dock is connected
journal is flooded with "upowerd: treating change event as add on" when Dell ...
Status: NEW
Classification: openSUSE
Product: openSUSE Distribution
Classification: openSUSE
Component: Basesystem
Leap 15.2
Other Other
: P5 - None : Normal (vote)
: ---
Assigned To: openSUSE Kernel Bugs
E-mail List
:
Depends on:
Blocks:
  Show dependency treegraph
 
Reported: 2020-07-05 09:38 UTC by Srinidhi B S
Modified: 2021-04-10 20:13 UTC (History)
4 users (show)

See Also:
Found By: ---
Services Priority:
Business Priority:
Blocker: ---
Marketing QA Status: ---
IT Deployment: ---


Attachments
Output of "udevadm monitor -u" and other commands (42.03 KB, text/plain)
2020-10-20 11:34 UTC, Srinidhi B S
Details
Output of `dmesg` command. (85.80 KB, text/plain)
2020-12-15 15:42 UTC, Srinidhi B S
Details

Note You need to log in before you can comment on or make changes to this bug.
Description Srinidhi B S 2020-07-05 09:38:52 UTC
After updating to openSUSE Leap 15.2 from openSUSE Leap 15.1, my journal is filled with messages like this:

> Jul 05 14:51:17 srinidhi upowerd[2156]: treating change event as add on /sys/devices/pci0000:00/0000:00:1c.4/0000:03:00.0/0000:04:02.0/0000:3b:00.0/usb4/4-1/4-1:1.0
> Jul 05 14:51:17 srinidhi upowerd[2156]: treating change event as add on /sys/devices/pci0000:00/0000:00:1c.4/0000:03:00.0/0000:04:02.0/0000:3b:00.0/usb3/3-1/3-1:1.0
> Jul 05 14:51:17 srinidhi upowerd[2156]: treating change event as add on /sys/devices/pci0000:00/0000:00:1c.4/0000:03:00.0/0000:04:02.0/0000:3b:00.0/usb3/3-1/3-1:1.0

These messages are shown only when I connect my Dell WD15 docking station. I don't know how to debug this problem. What I have found is that both these devices are USB hubs on the Dock - one is a USB 2.0 hub and the other is a USB 3.0 hub.

# cat /sys/devices/pci0000:00/0000:00:1c.4/0000:03:00.0/0000:04:02.0/0000:3b:00.0/usb4/4-1/4-1:1.0/uevent
DEVTYPE=usb_interface
DRIVER=hub
PRODUCT=424/5807/204
TYPE=9/0/3
INTERFACE=9/0/0
MODALIAS=usb:v0424p5807d0204dc09dsc00dp03ic09isc00ip00in00

# cat /sys/devices/pci0000:00/0000:00:1c.4/0000:03:00.0/0000:04:02.0/0000:3b:00.0/usb3/3-1/3-1:1.0/uevent
DEVTYPE=usb_interface
DRIVER=hub
PRODUCT=424/2807/204
TYPE=9/0/2
INTERFACE=9/0/2
MODALIAS=usb:v0424p2807d0204dc09dsc00dp02ic09isc00ip02in00
Comment 1 Srinidhi B S 2020-07-07 09:27:12 UTC
I updated BIOS and everything else available for my laptop. I still see the same errors. upowerd is constantly consuming 17% to 20% of available CPU and the system load average is at a constant 3.5 to 3.8 even when the system is idle.

I would appreciate it if someone could please let me know what debug information would be needed to help debug this issue.
Comment 2 Srinidhi B S 2020-07-13 05:48:40 UTC
Along with upowerd, now systemd-udevd takes about 95% CPU almost the entire time. Here's my current uptime of my laptop:

# uptime
 11:15:58  up 2 days 22:43,  4 users,  load average: 47.90, 46.58, 46.00

This is *after* I ran "killall upowerd" around 10 minutes back and the load average reduced by a couple of decimal numbers and is back up again to 47.90!

Any updates on this would be greatly appreciated! I'm seriously contemplating reinstalling openSUSE Leap 15.1 on my laptop until this is resolved.
Comment 3 Srinidhi B S 2020-10-20 11:30:34 UTC
I had stopped using my Dell WD15 docking station because reinstalling openSUSE Leap 15.1 was going to be too much work! 

I would like to share some more information:

1. The upowerd messages mentioned in comment#0 continue to be printed even after disconnecting the docking station.
2. "udevadm monitor -u" continuously prints events of "change" events for USB devices.
3. If I kill all of the systemd-udevd processes, then the issue seems to be gone. But as soon as I connect the docking station again, all of the problems mentioned in this bug show up!

I'll attaching output of udevadm monitor -u and other commands to this bug.
Comment 4 Srinidhi B S 2020-10-20 11:34:11 UTC
Created attachment 842823 [details]
Output of "udevadm monitor -u" and other commands
Comment 5 Srinidhi B S 2020-10-20 11:36:19 UTC
I'm really not able to figure out if this issue is with kernel's USB subsystem, systemd, udev or upowerd!

I would greatly appreciate if someone could triage this bug and assign it to the correct team so that this issue could get some attention.
Comment 6 Srinidhi B S 2020-12-15 10:01:43 UTC
What more information can I provide here? I would really like to start using the Dock and avoid being tethered to multiple cables.
Comment 7 Oliver Neukum 2020-12-15 10:18:35 UTC
Hi,

we need to find out whether the kernel generates bogus events of upowerd is doing something stupid. Please provide the output of "dmesg"
Comment 8 Srinidhi B S 2020-12-15 11:27:30 UTC
(In reply to Srinidhi B S from comment #1)
> I updated BIOS and everything else available for my laptop. I still see the
> same errors. upowerd is constantly consuming 17% to 20% of available CPU and
> the system load average is at a constant 3.5 to 3.8 even when the system is
> idle.
> 
> I would appreciate it if someone could please let me know what debug
> information would be needed to help debug this issue.

Thank you so much, Oliver, for responding to this bug!

This would require me to reboot and reconnect the dock. I will try to get this information for you later tonight.
Comment 9 Srinidhi B S 2020-12-15 15:42:25 UTC
Created attachment 844483 [details]
Output of `dmesg` command.

Please find the output of `dmesg` attached.

I'm still seeing the same upowerd messages.
Comment 10 Srinidhi B S 2020-12-15 19:44:56 UTC
With the latest updates, I am happy to report that the 95% CPU issue is gone! upowerd is not hogging on all the available CPU power.

> # ps axo stat,euid,ruid,tty,pid,pcpu,comm k -pcpu | head
> STAT  EUID  RUID TT         PID %CPU COMMAND
> Sl    1001  1001 ?        10245 15.9 firefox
> Sl    1001  1001 ?         7266  9.6 teams
> Ssl      0     0 ?         5606  9.0 upowerd
> Rsl   1001  1001 ?         8429  8.5 gnome-shell
> Sl    1001  1001 ?         3350  8.3 evolution
> Ss       0     0 ?          453  6.5 systemd-udevd
> Sl    1001  1001 ?        10410  4.5 Web Content
> S+    1001  1001 pts/3    12994  3.8 htop
> Rl+   1001  1001 tty2      8059  3.7 X

Although, the journalctl is still getting flooded with the upowerd messages - probably, the reason why it is using 9% of CPU. But yes, much better than 20% of the CPU!

> Dec 16 01:12:20 srinidhi upowerd[5606]: treating change event as add on /sys/devices/pci0000:00/0000:00:1c.4/0000:03:00.0/0000:04:02.0/0000:3b:00.0/usb3/3-1/3-1:1.0
> Dec 16 01:12:20 srinidhi upowerd[5606]: treating change event as add on /sys/devices/pci0000:00/0000:00:1c.4/0000:03:00.0/0000:04:02.0/0000:3b:00.0/usb4/4-1/4-1:1.0
> Dec 16 01:12:21 srinidhi upowerd[5606]: treating change event as add on /sys/devices/pci0000:00/0000:00:1c.4/0000:03:00.0/0000:04:02.0/0000:3b:00.0/usb3/3-1/3-1:1.0
> Dec 16 01:12:21 srinidhi upowerd[5606]: treating change event as add on /sys/devices/pci0000:00/0000:00:1c.4/0000:03:00.0/0000:04:02.0/0000:3b:00.0/usb3/3-1/3-1:1.0
Comment 11 Srinidhi B S 2021-04-10 20:13:02 UTC
(In reply to Srinidhi B S from comment #10)
> With the latest updates, I am happy to report that the 95% CPU issue is
> gone! upowerd is not hogging on all the available CPU power.
> 

It looks like I was too eager to post this! A couple of hours later, the upowerd CPU consumption was again above 90%, and the system temperature really shot up.

I thought I had updated this defect and wanted to check if someone had a chance to look at the data I've provided so far.

If anyone has any clue where I'm getting things wrong or what more information I can provide, please let me know!! I would really really appreciate it!

Since comment#10, I've force updated the Dell WD15 docking station's firmware. If this is indeed a faulty hardware issue, I would be extremely grateful if someone could tell me how I could prove it to someone else.

Regards,
Srinidhi.