Received-SPF: pass (google.com: domain of linux-kernel-owner@vger.kernel.org designates 23.128.96.18 as permitted sender) client-ip=23.128.96.18;
MIME-Version: 1.0
References: <11459cde-7f57-c95b-8cac-4301f0a2390e@gmail.com>
 <9d75a67b-87f0-161c-02d7-c9fc4efe97e7@intel.com> <CANA+-vBURc0ivB=UHXK5Xg_tVJOV_h9Uz_Ke4ZG3Gu_sMhfTvQ@mail.gmail.com>
 <78faec4a-bf98-a731-b505-a1ccfb6e4557@gmail.com> <CANA+-vCDrE7Kmr3XspSCwCue1ic4tKyW=FuXS7PhsK0581_+Mg@mail.gmail.com>
 <92e9cb5a-48f3-5809-3ca7-427ee8b4f29e@gmail.com>
In-Reply-To: <92e9cb5a-48f3-5809-3ca7-427ee8b4f29e@gmail.com>
From:   Tri Vo <trong@android.com>
Date:   Sat, 30 May 2020 15:33:04 -0700
Message-ID: <CANA+-vBei-vRN0hFxYCDcm41k+j1cJXuE8MvpiZH_prrc--bhw@mail.gmail.com>
Subject: Re: Regression with PM / wakeup: Show wakeup sources stats in sysfs"
To:     Florian Fainelli <f.fainelli@gmail.com>
Cc:     "linux-kernel@vger.kernel.org" <linux-kernel@vger.kernel.org>,
        "Rafael J. Wysocki" <rafael.j.wysocki@intel.com>,
        Greg KH <gregkh@linuxfoundation.org>,
        Stephen Boyd <swboyd@chromium.org>
Content-Type: text/plain; charset="UTF-8"
Sender: linux-kernel-owner@vger.kernel.org
Precedence: bulk

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.)