* Regression with PM / wakeup: Show wakeup sources stats in sysfs"
@ 2020-05-28 20:46 Florian Fainelli
2020-05-29 16:51 ` Rafael J. Wysocki
0 siblings, 1 reply; 10+ messages in thread
From: Florian Fainelli @ 2020-05-28 20:46 UTC (permalink / raw)
To: rafael.j.wysocki, linux-kernel, trong, Greg KH, swboyd, kaleshsingh
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?
This is seen on 5.4.43, but it is reproducible on Linus' master as well.
The Ethernet driver being used is under
drivers/net/ethernet/broadcom/genet/ and the relevant part is in the
function bcmgenet_set_wol().
BTW, I think you want to backport
e976eb4b91e906f20ec25b20c152d53c472fc3fd ("PM: wakeup: Show statistics
for deleted wakeup sources again") into 5.4 and 4.19 at least.
Thank you!
--
Florian
^ permalink raw reply [flat|nested] 10+ messages in thread* Re: Regression with PM / wakeup: Show wakeup sources stats in sysfs" 2020-05-28 20:46 Regression with PM / wakeup: Show wakeup sources stats in sysfs" Florian Fainelli @ 2020-05-29 16:51 ` Rafael J. Wysocki 2020-05-29 22:28 ` Tri Vo 0 siblings, 1 reply; 10+ messages in thread From: Rafael J. Wysocki @ 2020-05-29 16:51 UTC (permalink / raw) To: Florian Fainelli, linux-kernel, trong, Greg KH, swboyd, kaleshsingh 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. > This is seen on 5.4.43, but it is reproducible on Linus' master as well. > > The Ethernet driver being used is under > drivers/net/ethernet/broadcom/genet/ and the relevant part is in the > function bcmgenet_set_wol(). > > BTW, I think you want to backport > e976eb4b91e906f20ec25b20c152d53c472fc3fd ("PM: wakeup: Show statistics > for deleted wakeup sources again") into 5.4 and 4.19 at least. Well, please feel free to send a request to do that to stable@vger.kernel.org. Thanks! ^ permalink raw reply [flat|nested] 10+ messages in thread
* Re: Regression with PM / wakeup: Show wakeup sources stats in sysfs" 2020-05-29 16:51 ` Rafael J. Wysocki @ 2020-05-29 22:28 ` Tri Vo 2020-05-29 22:37 ` Florian Fainelli 0 siblings, 1 reply; 10+ messages in thread From: Tri Vo @ 2020-05-29 22:28 UTC (permalink / raw) To: Florian Fainelli; +Cc: linux-kernel, Rafael J. Wysocki, Greg KH, Stephen Boyd On Fri, May 29, 2020 at 9:51 AM Rafael J. Wysocki <rafael.j.wysocki@intel.com> 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. ^ permalink raw reply [flat|nested] 10+ messages in thread
* Re: Regression with PM / wakeup: Show wakeup sources stats in sysfs" 2020-05-29 22:28 ` Tri Vo @ 2020-05-29 22:37 ` Florian Fainelli 2020-05-29 23:14 ` Tri Vo 0 siblings, 1 reply; 10+ messages in thread From: Florian Fainelli @ 2020-05-29 22:37 UTC (permalink / raw) To: Tri Vo; +Cc: linux-kernel, Rafael J. Wysocki, Greg KH, Stephen Boyd 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@intel.com> 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 ^ permalink raw reply [flat|nested] 10+ messages in thread
* Re: Regression with PM / wakeup: Show wakeup sources stats in sysfs" 2020-05-29 22:37 ` Florian Fainelli @ 2020-05-29 23:14 ` Tri Vo 2020-05-30 18:52 ` Florian Fainelli 0 siblings, 1 reply; 10+ messages in thread From: Tri Vo @ 2020-05-29 23:14 UTC (permalink / raw) To: Florian Fainelli; +Cc: linux-kernel, Rafael J. Wysocki, Greg KH, Stephen Boyd On Fri, May 29, 2020 at 3:37 PM Florian Fainelli <f.fainelli@gmail.com> 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@intel.com> 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 ^ permalink raw reply [flat|nested] 10+ messages in thread
* Re: Regression with PM / wakeup: Show wakeup sources stats in sysfs" 2020-05-29 23:14 ` Tri Vo @ 2020-05-30 18:52 ` Florian Fainelli 2020-05-30 22:33 ` Tri Vo 0 siblings, 1 reply; 10+ messages in thread From: Florian Fainelli @ 2020-05-30 18:52 UTC (permalink / raw) To: Tri Vo; +Cc: linux-kernel, Rafael J. Wysocki, Greg KH, Stephen Boyd On 5/29/2020 4:14 PM, Tri Vo wrote: > On Fri, May 29, 2020 at 3:37 PM Florian Fainelli <f.fainelli@gmail.com> 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@intel.com> 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 -- Florian ^ permalink raw reply [flat|nested] 10+ messages in thread
* Re: Regression with PM / wakeup: Show wakeup sources stats in sysfs" 2020-05-30 18:52 ` Florian Fainelli @ 2020-05-30 22:33 ` Tri Vo 2020-06-02 1:30 ` Florian Fainelli 0 siblings, 1 reply; 10+ messages in thread From: Tri Vo @ 2020-05-30 22:33 UTC (permalink / raw) To: Florian Fainelli; +Cc: linux-kernel, Rafael J. Wysocki, Greg KH, Stephen Boyd On Sat, May 30, 2020 at 11:52 AM Florian Fainelli <f.fainelli@gmail.com> wrote: > > > > On 5/29/2020 4:14 PM, Tri Vo wrote: > > On Fri, May 29, 2020 at 3:37 PM Florian Fainelli <f.fainelli@gmail.com> 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@intel.com> 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.) ^ permalink raw reply [flat|nested] 10+ messages in thread
* Re: Regression with PM / wakeup: Show wakeup sources stats in sysfs" 2020-05-30 22:33 ` Tri Vo @ 2020-06-02 1:30 ` Florian Fainelli 2020-06-02 3:06 ` Florian Fainelli 0 siblings, 1 reply; 10+ messages in thread From: Florian Fainelli @ 2020-06-02 1:30 UTC (permalink / raw) To: Tri Vo; +Cc: linux-kernel, Rafael J. Wysocki, Greg KH, Stephen Boyd On 5/30/2020 3:33 PM, Tri Vo wrote: > On Sat, May 30, 2020 at 11:52 AM Florian Fainelli <f.fainelli@gmail.com> wrote: >> >> >> >> On 5/29/2020 4:14 PM, Tri Vo wrote: >>> On Fri, May 29, 2020 at 3:37 PM Florian Fainelli <f.fainelli@gmail.com> 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@intel.com> 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! -- Florian ^ permalink raw reply [flat|nested] 10+ messages in thread
* Re: Regression with PM / wakeup: Show wakeup sources stats in sysfs" 2020-06-02 1:30 ` Florian Fainelli @ 2020-06-02 3:06 ` Florian Fainelli 2020-06-05 14:35 ` Rafael J. Wysocki 0 siblings, 1 reply; 10+ messages in thread From: Florian Fainelli @ 2020-06-02 3:06 UTC (permalink / raw) To: Tri Vo, Ravi Chandra Sadineni Cc: linux-kernel, Rafael J. Wysocki, Greg KH, Stephen Boyd 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@gmail.com> wrote: >>> >>> >>> >>> On 5/29/2020 4:14 PM, Tri Vo wrote: >>>> On Fri, May 29, 2020 at 3:37 PM Florian Fainelli <f.fainelli@gmail.com> 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@intel.com> 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 ^ permalink raw reply [flat|nested] 10+ messages in thread
* Re: Regression with PM / wakeup: Show wakeup sources stats in sysfs" 2020-06-02 3:06 ` Florian Fainelli @ 2020-06-05 14:35 ` Rafael J. Wysocki 0 siblings, 0 replies; 10+ messages in thread From: Rafael J. Wysocki @ 2020-06-05 14:35 UTC (permalink / raw) To: Florian Fainelli Cc: linux-kernel, Tri Vo, Ravi Chandra Sadineni, Rafael J. Wysocki, Greg KH, Stephen Boyd On Tuesday, June 2, 2020 5:06:29 AM CEST Florian Fainelli wrote: > > 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@gmail.com> wrote: > >>> > >>> > >>> > >>> On 5/29/2020 4:14 PM, Tri Vo wrote: > >>>> On Fri, May 29, 2020 at 3:37 PM Florian Fainelli <f.fainelli@gmail.com> 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@intel.com> 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. It is unfortunate that you relied on the behavior that's changed, sorry about that. Reverting the above commit is still an option, so please let me know if you want me to do that. > The sysfs description under Documentation/ABI/testing/sysfs-devices-power > may also need clarification. Well, feel free to propose specific changes in there. > 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 This way one can only say whether or not a key has been pressed during the period between two consecutive wakeup_count reads. That may not even be related to waking up the system from sleep, though. Thanks! ^ permalink raw reply [flat|nested] 10+ messages in thread
end of thread, other threads:[~2020-06-05 14:35 UTC | newest] Thread overview: 10+ messages (download: mbox.gz / follow: Atom feed) -- links below jump to the message on this page -- 2020-05-28 20:46 Regression with PM / wakeup: Show wakeup sources stats in sysfs" Florian Fainelli 2020-05-29 16:51 ` Rafael J. Wysocki 2020-05-29 22:28 ` Tri Vo 2020-05-29 22:37 ` Florian Fainelli 2020-05-29 23:14 ` Tri Vo 2020-05-30 18:52 ` Florian Fainelli 2020-05-30 22:33 ` Tri Vo 2020-06-02 1:30 ` Florian Fainelli 2020-06-02 3:06 ` Florian Fainelli 2020-06-05 14:35 ` Rafael J. Wysocki
This is an external index of several public inboxes, see mirroring instructions on how to clone and mirror all data and code used by this external index.