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

[Florian Fainelli]

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
# 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