Re: Regression with PM / wakeup: Show wakeup sources stats in sysfs"

From: Tri Vo
Date: Fri May 29 2020 - 19:14:28 EST

On Fri, May 29, 2020 at 3:37 PM Florian Fainelli <f.fainelli@xxxxxxxxx> wrote:
>
> On 5/29/20 3:28 PM, Tri Vo wrote:
> > On Fri, May 29, 2020 at 9:51 AM Rafael J. Wysocki
> > <rafael.j.wysocki@xxxxxxxxx> wrote:
> >>
> >> On 5/28/2020 10:46 PM, Florian Fainelli wrote:
> >>> Hi,
> >>>
> >>> Commit c8377adfa78103be5380200eb9dab764d7ca890e ("PM / wakeup: Show
> >>> wakeup sources stats in sysfs") is causing some of our tests to fail
> >>> because /sys/class/net/*/device/power/wakeup_count is now 0, despite
> >>> /sys/kernel/debug/wakeup_sources clearly indicating that the Ethernet
> >>> device was responsible for system wake-up.
> >>>
> >>> What's more in looking at /sys/class/wakekup/wakeup2/event_count, we
> >>> have the number of Wake-on-LAN wakeups recorded properly, but
> >>> wakeup_count is desperately 0, why is that?
> >>
> >> I need to look at that commit in detail to find out what is going on.
> >
> > It would be helpful to see the contents of
> > /sys/kernel/debug/wakeup_sources, /sys/class/net/*/device/power/*, and
> > /sys/class/wakekup/* corresponding to the device in question. The
> > values in these files are queried from the same struct wakeup_source.
> > So it's odd if wakeup_count diverges.
>
> Most certainly, below is the information you want, the two cat
> /s/k/d/wakeup_sources were done before Wake-on-LAN and after waking-up
> from LAN. /sys/class/wakeup/wakeup2 maps to the Ethernet device.
>
> The Ethernet device calls pm_wakeup_event() against the struct device
> that is embedded in the platform_device that it was probed with. I will
> try to debug this myself over the weekend, time permitting.
>
>
> # ethtool -s eth0 wol g
> # cat /sys/kernel/debug/wakeup_sources
> name active_count event_count wakeup_count
> expire_count active_since total_time max_time last_changep
> revent_suspend_time
> 47d580000.ethernet 0 0 0
> 0 0 0 0 0 0
> alarmtimer 0 0 0 0
> 0 0 0 0 0
> 47c408400.waketimer 2 2 0
> 0 0 0 0 6144
> 1 0
> # pml -w20
> [ 3449.937142] brcm-waketimer 47c408400.waketimer: Using sysfs
> attributes, consider using 'rtcwake'
> Pass 1 out of 1, mode=none, tp_al[ 3449.952654] PM: suspend entry (shallow)
> l=1, cycle_tp=, sleep=, [ 3449.959004] Filesystems sync: 0.000 seconds
> wakeup_time=20
> [ 3449.965984] Freezing user space processes ... (elapsed 0.001 seconds)
> done.
> [ 3449.974087] OOM killer disabled.
> [ 3449.977316] Freezing remaining freezable tasks ... (elapsed 0.006
> seconds) done.
> [ 3449.991114] printk: Suspending console(s) (use no_console_suspend to
> debug)
> AMS: System is entering S2...
> [ 3450.022381] bcmgenet 47d580000.ethernet eth0: Link is Down
> [ 3450.048340] Disabling non-boot CPUs ...
> [ 3450.049344] CPU1: shutdown
> [ 3450.050393] psci: CPU1 killed (polled 1 ms)
> [ 3450.051332] Enabling non-boot CPUs ...
> [ 3450.051712] Detected PIPT I-cache on CPU1
> [ 3450.051812] CPU1: Booted secondary processor 0x0000000001 [0x410fd083]
> [ 3450.052435] CPU1 is up
> [ 3450.683588] bcmgenet 47d580000.ethernet eth0: Link is Up - 1Gbps/Full
> - flow control rx/tx
> [ 3450.729677] OOM killer enabled.
> [ 3450.732908] Restarting tasks ... done.
> [ 3450.738539] PM: suspend exit
> ------------------------------
> [ 3450.744239] brcm-waketimer 47c408400.waketimer: Using sysfs
> attributes, consider using 'rtcwake'
> # cat /sys/kernel/debug/wakeup_sources
> name active_count event_count wakeup_count
> expire_count active_since total_time max_time last_changep
> revent_suspend_time
> 47d580000.ethernet 1 1 0
> 0 0 0 0 3450
> 054 0
> alarmtimer 0 0 0 0
> 0 0 0 0 0
> 47c408400.waketimer 2 2 0
> 0 0 0 0 6144
> 1 0
> # cat /sys/class/net/*/device/power/*
> cat: read error: Input/output error
> auto
> 0
> unsupported
> 0
> enabled
> 0
> 0
> 1
> 0
> 0
> 3450054
> 0
> 0

UUIC, 47d580000.ethernet is the device of interest here. It's
wakeup_count was 0 before wake up, and we expect it to be 1 after wake
up. One of the files you cat'ed here has a 1 in it. I can't tell which
value corresponds to which file though, but I suspect that's
wakeup_count.

> # ls -l /sys/class/net/eth0/device/
> driver/ net/ subsystem/ wakeup/
> driver_override of_node/ uevent
> modalias power/ unimac-mdio.0/
> # ls -l /sys/class/net/eth0/device/power/wakeup
> wakeup wakeup_active_count wakeup_last_time_ms
> wakeup_abort_count wakeup_count wakeup_max_time_ms
> wakeup_active wakeup_expire_count wakeup_total_time_ms
> # ls -l /sys/class/net/eth0/device/power/wakeup^C
> # ls -l /sys/class/wakeup/wakeup
> wakeup0/ wakeup1/ wakeup2/
> # ls -l /sys/class/wakeup/wakeup2/
> total 0
> -r--r--r-- 1 root root 4096 Jan 1 00:59 active_count
> -r--r--r-- 1 root root 4096 Jan 1 00:59 active_time_ms
> lrwxrwxrwx 1 root root 0 Jan 1 00:59 device ->
> ../../../47d580000.ethernet
> -r--r--r-- 1 root root 4096 Jan 1 00:59 event_count
> -r--r--r-- 1 root root 4096 Jan 1 00:59 expire_count
> -r--r--r-- 1 root root 4096 Jan 1 00:59 last_change_ms
> -r--r--r-- 1 root root 4096 Jan 1 00:59 max_time_ms
> -r--r--r-- 1 root root 4096 Jan 1 00:59 name
> -r--r--r-- 1 root root 4096 Jan 1 00:59
> prevent_suspend_time_ms
> lrwxrwxrwx 1 root root 0 Jan 1 00:59 subsystem ->
> ../../../../../../class/wakeup
> -r--r--r-- 1 root root 4096 Jan 1 00:59 total_time_ms
> -rw-r--r-- 1 root root 4096 Jan 1 00:59 uevent
> -r--r--r-- 1 root root 4096 Jan 1 00:59 wakeup_count
> # cat /sys/class/wakeup/wakeup2/*
> 1
> 0
> cat: read error: Is a directory
> 1
> 0
> 3450054
> 0
> 47d580000.ethernet
> 0
> cat: read error: Is a directory
> 0
> 0
> #
>
> --
> Florian