[PATCH v1] power: add wakeup log

[PATCH v1] power: add wakeup log

[Miao Li]

This patch adds a log in rte_power_monitor to show the core has been
waked up.

Signed-off-by: Miao Li <miao.li@intel.com>
---
 lib/eal/x86/rte_power_intrinsics.c | 8 ++++++++
 1 file changed, 8 insertions(+)

diff --git a/lib/eal/x86/rte_power_intrinsics.c b/lib/eal/x86/rte_power_intrinsics.c
index f749da9b85..dd63e2b6eb 100644
--- a/lib/eal/x86/rte_power_intrinsics.c
+++ b/lib/eal/x86/rte_power_intrinsics.c
@@ -128,6 +128,14 @@ rte_power_monitor(const struct rte_power_monitor_cond *pmc,
 			: "D"(0), /* enter C0.2 */
 			  "a"(tsc_l), "d"(tsc_h));
 
+	cur_value = __get_umwait_val(pmc->addr, pmc->size);
+
+	/* check if core has been waked up by changing monitoring value */
+	if (pmc->fn(cur_value, pmc->opaque) != 0)
+		RTE_LOG(INFO, EAL,
+			"lcore %u is waked up from value change\n",
+			rte_lcore_id());
+
 end:
 	/* erase sleep address */
 	rte_spinlock_lock(&s->lock);
-- 
2.25.1

Re: [PATCH v1] power: add wakeup log

[Stephen Hemminger]

On Tue, 22 Feb 2022 13:52:27 +0000
Miao Li <miao.li@intel.com> wrote:

> +			"lcore %u is waked up from value change\n",

That is awkward phrasing in English and should be DEBUG not INFO level
because it may happen often.

Maybe:
		"lcore %u awoke because value changed\n"
or something better.

PS: sometimes it is good idea to using grammar tools when wording commit
or messages.

Re: [PATCH v1] power: add wakeup log

[David Hunt]

On 22/2/2022 1:52 PM, Miao Li wrote:
> This patch adds a log in rte_power_monitor to show the core has been
> waked up.
>
> Signed-off-by: Miao Li <miao.li@intel.com>
> ---
>   lib/eal/x86/rte_power_intrinsics.c | 8 ++++++++
>   1 file changed, 8 insertions(+)
>
> diff --git a/lib/eal/x86/rte_power_intrinsics.c b/lib/eal/x86/rte_power_intrinsics.c
> index f749da9b85..dd63e2b6eb 100644
> --- a/lib/eal/x86/rte_power_intrinsics.c
> +++ b/lib/eal/x86/rte_power_intrinsics.c
> @@ -128,6 +128,14 @@ rte_power_monitor(const struct rte_power_monitor_cond *pmc,
>   			: "D"(0), /* enter C0.2 */
>   			  "a"(tsc_l), "d"(tsc_h));
>   
> +	cur_value = __get_umwait_val(pmc->addr, pmc->size);
> +
> +	/* check if core has been waked up by changing monitoring value */
> +	if (pmc->fn(cur_value, pmc->opaque) != 0)
> +		RTE_LOG(INFO, EAL,
> +			"lcore %u is waked up from value change\n",
> +			rte_lcore_id());
> +
>   end:
>   	/* erase sleep address */
>   	rte_spinlock_lock(&s->lock);


Hi Li,

If I'm not mistaken, a similar patch was added to a previous DPDK 
release and then removed because of the enormous performance impact.

This looks to be something similar, and it's adding a log message to a 
low-level function. Also, as mentioned before, the intention in the 
future is to call this function much more agressively, so there would be 
hundreds of thousands of messages every second.

We cannot add an RTE_LOG here. Please rework and put the log in the test 
case instead.

Also, regarding the wording, I would suggest  "lcore %u awoke due to 
monitor address value change\n"

Rgds,

Dave.

RE: [PATCH v1] power: add wakeup log

[Li, Miao]

Hi,

> -----Original Message-----
> From: Hunt, David <david.hunt@intel.com>
> Sent: Wednesday, February 23, 2022 12:32 AM
> To: Li, Miao <miao.li@intel.com>; dev@dpdk.org
> Cc: Wang, Yinan <yinan.wang@intel.com>; stephen@networkplumber.org
> Subject: Re: [PATCH v1] power: add wakeup log
> 
> 
> On 22/2/2022 1:52 PM, Miao Li wrote:
> > This patch adds a log in rte_power_monitor to show the core has been
> > waked up.
> >
> > Signed-off-by: Miao Li <miao.li@intel.com>
> > ---
> >   lib/eal/x86/rte_power_intrinsics.c | 8 ++++++++
> >   1 file changed, 8 insertions(+)
> >
> > diff --git a/lib/eal/x86/rte_power_intrinsics.c
> b/lib/eal/x86/rte_power_intrinsics.c
> > index f749da9b85..dd63e2b6eb 100644
> > --- a/lib/eal/x86/rte_power_intrinsics.c
> > +++ b/lib/eal/x86/rte_power_intrinsics.c
> > @@ -128,6 +128,14 @@ rte_power_monitor(const struct
> rte_power_monitor_cond *pmc,
> >   			: "D"(0), /* enter C0.2 */
> >   			  "a"(tsc_l), "d"(tsc_h));
> >
> > +	cur_value = __get_umwait_val(pmc->addr, pmc->size);
> > +
> > +	/* check if core has been waked up by changing monitoring value */
> > +	if (pmc->fn(cur_value, pmc->opaque) != 0)
> > +		RTE_LOG(INFO, EAL,
> > +			"lcore %u is waked up from value change\n",
> > +			rte_lcore_id());
> > +
> >   end:
> >   	/* erase sleep address */
> >   	rte_spinlock_lock(&s->lock);
> 
> 
> Hi Li,
> 
> If I'm not mistaken, a similar patch was added to a previous DPDK
> release and then removed because of the enormous performance impact.
> 
> This looks to be something similar, and it's adding a log message to a
> low-level function. Also, as mentioned before, the intention in the
> future is to call this function much more agressively, so there would be
> hundreds of thousands of messages every second.
> 
> We cannot add an RTE_LOG here. Please rework and put the log in the test
> case instead.

I add a judgment before the output. When no packet arriver, the log will not be printed. When a lot of packets arriver, the rte_power_monitor will not be called. So I think the performance impact is small.

> 
> Also, regarding the wording, I would suggest  "lcore %u awoke due to
> monitor address value change\n"

I will change the log content in next version.

> 
> Rgds,
> 
> Dave.
> 

Thanks,
Miao

RE: [PATCH v1] power: add wakeup log

[Li, Miao]

Hi,

> -----Original Message-----
> From: Stephen Hemminger <stephen@networkplumber.org>
> Sent: Wednesday, February 23, 2022 12:07 AM
> To: Li, Miao <miao.li@intel.com>
> Cc: dev@dpdk.org; Hunt, David <david.hunt@intel.com>; Wang, Yinan
> <yinan.wang@intel.com>
> Subject: Re: [PATCH v1] power: add wakeup log
> 
> On Tue, 22 Feb 2022 13:52:27 +0000
> Miao Li <miao.li@intel.com> wrote:
> 
> > +			"lcore %u is waked up from value change\n",
> 
> That is awkward phrasing in English and should be DEBUG not INFO level
> because it may happen often.

I will fix it in the next version.

> 
> Maybe:
> 		"lcore %u awoke because value changed\n"
> or something better.

I will change the log content in next version.

> 
> PS: sometimes it is good idea to using grammar tools when wording commit
> or messages.

Thanks,
Miao

Re: [PATCH v1] power: add wakeup log

[Burakov, Anatoly]

On 24-Feb-22 2:38 AM, Li, Miao wrote:
> Hi,
> 
>> -----Original Message-----
>> From: Hunt, David <david.hunt@intel.com>
>> Sent: Wednesday, February 23, 2022 12:32 AM
>> To: Li, Miao <miao.li@intel.com>; dev@dpdk.org
>> Cc: Wang, Yinan <yinan.wang@intel.com>; stephen@networkplumber.org
>> Subject: Re: [PATCH v1] power: add wakeup log
>>
>>
>> On 22/2/2022 1:52 PM, Miao Li wrote:
>>> This patch adds a log in rte_power_monitor to show the core has been
>>> waked up.
>>>
>>> Signed-off-by: Miao Li <miao.li@intel.com>
>>> ---
>>>    lib/eal/x86/rte_power_intrinsics.c | 8 ++++++++
>>>    1 file changed, 8 insertions(+)
>>>
>>> diff --git a/lib/eal/x86/rte_power_intrinsics.c
>> b/lib/eal/x86/rte_power_intrinsics.c
>>> index f749da9b85..dd63e2b6eb 100644
>>> --- a/lib/eal/x86/rte_power_intrinsics.c
>>> +++ b/lib/eal/x86/rte_power_intrinsics.c
>>> @@ -128,6 +128,14 @@ rte_power_monitor(const struct
>> rte_power_monitor_cond *pmc,
>>>    			: "D"(0), /* enter C0.2 */
>>>    			  "a"(tsc_l), "d"(tsc_h));
>>>
>>> +	cur_value = __get_umwait_val(pmc->addr, pmc->size);
>>> +
>>> +	/* check if core has been waked up by changing monitoring value */
>>> +	if (pmc->fn(cur_value, pmc->opaque) != 0)
>>> +		RTE_LOG(INFO, EAL,
>>> +			"lcore %u is waked up from value change\n",
>>> +			rte_lcore_id());
>>> +
>>>    end:
>>>    	/* erase sleep address */
>>>    	rte_spinlock_lock(&s->lock);
>>
>>
>> Hi Li,
>>
>> If I'm not mistaken, a similar patch was added to a previous DPDK
>> release and then removed because of the enormous performance impact.
>>
>> This looks to be something similar, and it's adding a log message to a
>> low-level function. Also, as mentioned before, the intention in the
>> future is to call this function much more agressively, so there would be
>> hundreds of thousands of messages every second.
>>
>> We cannot add an RTE_LOG here. Please rework and put the log in the test
>> case instead.
> 
> I add a judgment before the output. When no packet arriver, the log will not be printed. When a lot of packets arriver, the rte_power_monitor will not be called. So I think the performance impact is small.
> 
>>
>> Also, regarding the wording, I would suggest  "lcore %u awoke due to
>> monitor address value change\n"
> 
> I will change the log content in next version.
> 
>>
>> Rgds,
>>
>> Dave.
>>
> 
> Thanks,
> Miao
> 
> 

Hi Miao,

I have to agree with Dave here, I don't think this patch should be 
merged, as there are several problems with it.

First of all, the result might be inaccurate in practice, because there 
is a race condition between reading value first and second time - 
UMONITOR protects us from that before we sleep, but not after. So, the 
information we get with `__get_umwait_val()` and calling a callback 
might be out of date by the time we reach that code. So, this code is 
*provably* vulnerable to race conditions.

More importantly, I do not see how this is a useful addition to DPDK. I 
have to ask: what is the problem the patch is trying to solve? Because 
if the problem being solved is validating full path from l3fwd-power 
down to `rte_power_monitor`, then it could be solved in other ways that 
are more agreeable.

For example, I believe we have logging inside l3fwd-power, so we can 
validate that it wakes up correctly. We *don't* have logging inside 
rte_power for these particular code paths, but IMO it would be 
unnecessary because l3fwd-power already effectively does that anyway. We 
*don't* have logging inside `rte_power_monitor`, but we can still 
validate it with unit tests, if the concern here is validating that the 
functionality works correctly.

So, we can verify `rte_power_monitor` works with unit tests. We *could* 
introspect `rte_power` callback code with more logging if that's 
required (although IMO unnecessary, given that l3fwd-power already does 
that), and we can validate that l3fwd-power wakes up correctly with 
existing logging. So, with the addition of unit tests, the entire stack 
would be validated.

Thus, to me, it seems like the patch is adding a (conditional) log 
message to a low level function, supported by an unnecessary and racy 
read/callback call for the sole purpose of checking information that 
does not get used anywhere else in the function other than in a log 
message, to solve a problem that could be solved in another way (with 
unit tests).

Is there anything that I'm missing here?

-- 
Thanks,
Anatoly