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

[Florian Fainelli]

On 6/1/2020 6:30 PM, Florian Fainelli wrote:
> 
> 
> On 5/30/2020 3:33 PM, Tri Vo wrote:
>> On Sat, May 30, 2020 at 11:52 AM Florian Fainelli <f.fainelli@xxxxxxxxx> wrote:
>>>
>>>
>>>
>>> On 5/29/2020 4:14 PM, Tri Vo wrote:
>>>> 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.
>>>
>>> That file is actually event_count which is not what is expected:
>>>
>>> # sh print.sh
>>> /sys/class/wakeup/wakeup2/uevent:
>>> /sys/class/wakeup/wakeup2/event_count: 1
>>> /sys/class/wakeup/wakeup2/max_time_ms: 0
>>> /sys/class/wakeup/wakeup2/wakeup_count: 0
>>> /sys/class/wakeup/wakeup2/total_time_ms: 0
>>> /sys/class/wakeup/wakeup2/expire_count: 0
>>> /sys/class/wakeup/wakeup2/active_count: 1
>>> /sys/class/wakeup/wakeup2/last_change_ms: 3450054
>>> /sys/class/wakeup/wakeup2/prevent_suspend_time_ms: 0
>>> /sys/class/wakeup/wakeup2/name: 47d580000.ethernet
>>> /sys/class/wakeup/wakeup2/active_time_ms: 0
>>
>> Thanks! Although 0 is not the expected wakeup_count, both
>> /sys/kernel/debug/wakeup_sources and /sys/class/wakeup/* are reporting
>> the same thing. So it's probably not an issue with how these values
>> are reported. The underlying struct wakeup_source has 0 wakeup_count
>> recorded.
>>
>> How sure are you that commit c8377adfa78103be5380200eb9dab764d7ca890e
>> introduces the regression? (That commit adds sysfs attributes to
>> display wakeup source information, so it seems unlikely that actual
>> wakeup event accounting is affected by it.)
> 
> Not anymore, it looks like my automated bisection was flawed, I will
> restart it now and find out the offending commit when this started to
> break. Thanks for reviewing the logs!

It was more obvious than I thought, this commit:

2d5ed61ce9820a1fe7b076cc45c169524d767746 ("PM / wakeup: Export
wakeup_count instead of event_count via sysfs") did change the structure
member being displayed by the wakeup_count sysfs attribute.

The commit message and rationale does make sense, however it sounds like
there should still be a proper differentiation between pm_wakeup_event()
calls done from resume cycle versus non-resume cycles. The sysfs
description under  Documentation/ABI/testing/sysfs-devices-power may
also need clarification.

One example that I can think of is the gpio_keys.c driver which calls
pm_wakeup_event() every time a GPIO button is pressed, provided that the
device is marked as wakeup enabled. Granted, applications can read the
count before and after suspend and determine if the count is different
to identify whether gpio_keys.c is responsible for wake-up, but it would
be much
-- 
Florian