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;
Subject: Re: Regression with PM / wakeup: Show wakeup sources stats in sysfs"
To:     Tri Vo <trong@android.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>
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>
From:   Florian Fainelli <f.fainelli@gmail.com>
Message-ID: <92e9cb5a-48f3-5809-3ca7-427ee8b4f29e@gmail.com>
Date:   Sat, 30 May 2020 11:52:12 -0700
User-Agent: Mozilla/5.0 (Windows NT 10.0; WOW64; rv:68.0) Gecko/20100101
 Firefox/68.0 Thunderbird/68.8.1
MIME-Version: 1.0
In-Reply-To: <CANA+-vCDrE7Kmr3XspSCwCue1ic4tKyW=FuXS7PhsK0581_+Mg@mail.gmail.com>
Content-Type: text/plain; charset=utf-8
Content-Language: en-US
Content-Transfer-Encoding: 7bit
Sender: linux-kernel-owner@vger.kernel.org
Precedence: bulk


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