2022-12-19 04:22:54

by Yang Jihong

[permalink] [raw]
Subject: [PATCH] perf tool: Fix output unexpected messages in quiet mode

When perf uses quiet mode, perf_quiet_option sets debug_peo_args to -1,
and display_attr incorrectly determines the value of debug_peo_args.
As a result, unexpected information is displayed.

Before:
# perf record --quiet -- ls > /dev/null
------------------------------------------------------------
perf_event_attr:
size 128
{ sample_period, sample_freq } 4000
sample_type IP|TID|TIME|PERIOD
read_format ID|LOST
disabled 1
inherit 1
mmap 1
comm 1
freq 1
enable_on_exec 1
task 1
precise_ip 3
sample_id_all 1
exclude_guest 1
mmap2 1
comm_exec 1
ksymbol 1
bpf_event 1
------------------------------------------------------------
...

After:
# perf record --quiet -- ls > /dev/null
#

Fixes: ccd26741f5e6 ("perf tool: Provide an option to print perf_event_open args and return value")
Signed-off-by: Yang Jihong <[email protected]>
---
tools/perf/util/debug.h | 2 +-
tools/perf/util/evsel.c | 2 +-
2 files changed, 2 insertions(+), 2 deletions(-)

diff --git a/tools/perf/util/debug.h b/tools/perf/util/debug.h
index f99468a7f681..f6ab84c93ec0 100644
--- a/tools/perf/util/debug.h
+++ b/tools/perf/util/debug.h
@@ -41,7 +41,7 @@ extern int debug_data_convert;

/* Special macro to print perf_event_open arguments/return value. */
#define pr_debug2_peo(fmt, ...) { \
- if (debug_peo_args) \
+ if (debug_peo_args > 0) \
pr_debugN(0, pr_fmt(fmt), ##__VA_ARGS__); \
else \
pr_debugN(2, pr_fmt(fmt), ##__VA_ARGS__); \
diff --git a/tools/perf/util/evsel.c b/tools/perf/util/evsel.c
index 999dd1700502..45cf144c5d5d 100644
--- a/tools/perf/util/evsel.c
+++ b/tools/perf/util/evsel.c
@@ -1775,7 +1775,7 @@ static int __open_attr__fprintf(FILE *fp, const char *name, const char *val,

static void display_attr(struct perf_event_attr *attr)
{
- if (verbose >= 2 || debug_peo_args) {
+ if (verbose >= 2 || debug_peo_args > 0) {
fprintf(stderr, "%.60s\n", graph_dotted_line);
fprintf(stderr, "perf_event_attr:\n");
perf_event_attr__fprintf(stderr, attr, __open_attr__fprintf, NULL);
--
2.30.GIT


2022-12-19 07:36:09

by Adrian Hunter

[permalink] [raw]
Subject: Re: [PATCH] perf tool: Fix output unexpected messages in quiet mode

On 19/12/22 04:49, Yang Jihong wrote:
> When perf uses quiet mode, perf_quiet_option sets debug_peo_args to -1,

Seems like redirect_to_stderr has similar issue?

> and display_attr incorrectly determines the value of debug_peo_args.
> As a result, unexpected information is displayed.
>
> Before:
> # perf record --quiet -- ls > /dev/null
> ------------------------------------------------------------
> perf_event_attr:
> size 128
> { sample_period, sample_freq } 4000
> sample_type IP|TID|TIME|PERIOD
> read_format ID|LOST
> disabled 1
> inherit 1
> mmap 1
> comm 1
> freq 1
> enable_on_exec 1
> task 1
> precise_ip 3
> sample_id_all 1
> exclude_guest 1
> mmap2 1
> comm_exec 1
> ksymbol 1
> bpf_event 1
> ------------------------------------------------------------
> ...
>
> After:
> # perf record --quiet -- ls > /dev/null
> #
>
> Fixes: ccd26741f5e6 ("perf tool: Provide an option to print perf_event_open args and return value")
> Signed-off-by: Yang Jihong <[email protected]>

Reviewed-by: Adrian Hunter <[email protected]>

> ---
> tools/perf/util/debug.h | 2 +-
> tools/perf/util/evsel.c | 2 +-
> 2 files changed, 2 insertions(+), 2 deletions(-)
>
> diff --git a/tools/perf/util/debug.h b/tools/perf/util/debug.h
> index f99468a7f681..f6ab84c93ec0 100644
> --- a/tools/perf/util/debug.h
> +++ b/tools/perf/util/debug.h
> @@ -41,7 +41,7 @@ extern int debug_data_convert;
>
> /* Special macro to print perf_event_open arguments/return value. */
> #define pr_debug2_peo(fmt, ...) { \
> - if (debug_peo_args) \
> + if (debug_peo_args > 0) \
> pr_debugN(0, pr_fmt(fmt), ##__VA_ARGS__); \
> else \
> pr_debugN(2, pr_fmt(fmt), ##__VA_ARGS__); \
> diff --git a/tools/perf/util/evsel.c b/tools/perf/util/evsel.c
> index 999dd1700502..45cf144c5d5d 100644
> --- a/tools/perf/util/evsel.c
> +++ b/tools/perf/util/evsel.c
> @@ -1775,7 +1775,7 @@ static int __open_attr__fprintf(FILE *fp, const char *name, const char *val,
>
> static void display_attr(struct perf_event_attr *attr)
> {
> - if (verbose >= 2 || debug_peo_args) {
> + if (verbose >= 2 || debug_peo_args > 0) {
> fprintf(stderr, "%.60s\n", graph_dotted_line);
> fprintf(stderr, "perf_event_attr:\n");
> perf_event_attr__fprintf(stderr, attr, __open_attr__fprintf, NULL);

2022-12-19 09:43:45

by Yang Jihong

[permalink] [raw]
Subject: Re: [PATCH] perf tool: Fix output unexpected messages in quiet mode

Hello,

On 2022/12/19 14:59, Adrian Hunter wrote:
> On 19/12/22 04:49, Yang Jihong wrote:
>> When perf uses quiet mode, perf_quiet_option sets debug_peo_args to -1,
>
> Seems like redirect_to_stderr has similar issue?
The redirect_to_stderr is used only in the veprintf function:

int veprintf(int level, int var, const char *fmt, va_list args)
{
int ret = 0;

if (var >= level) {
if (use_browser >= 1 && redirect_to_stderr <= 0) {
ui_helpline__vshow(fmt, args);
} else {
ret = fprintf_time(debug_file);
ret += vfprintf(debug_file, fmt, args);
}
}

return ret;
}

If use quiet mode, verbose sets to -1. (also assigned in the
perf_quiet_option function)
Because "var >= level" is false, veprintf function returns directly,
which avoids this problem.

However, there are cases where:
# perf --debug stderr=-1 report -vvv 2>/tmp/debug

If stderr is -1, should we redirect pr_debug in this case?

Because I'm not sure if this is a problem,
if redirect_to_stderr needs to be fixed as well,
let me know and I'll submit a patch to fix it.

>
>> and display_attr incorrectly determines the value of debug_peo_args.
>> As a result, unexpected information is displayed.
>>
>> Before:
>> # perf record --quiet -- ls > /dev/null
>> ------------------------------------------------------------
>> perf_event_attr:
>> size 128
>> { sample_period, sample_freq } 4000
>> sample_type IP|TID|TIME|PERIOD
>> read_format ID|LOST
>> disabled 1
>> inherit 1
>> mmap 1
>> comm 1
>> freq 1
>> enable_on_exec 1
>> task 1
>> precise_ip 3
>> sample_id_all 1
>> exclude_guest 1
>> mmap2 1
>> comm_exec 1
>> ksymbol 1
>> bpf_event 1
>> ------------------------------------------------------------
>> ...
>>
>> After:
>> # perf record --quiet -- ls > /dev/null
>> #
>>
>> Fixes: ccd26741f5e6 ("perf tool: Provide an option to print perf_event_open args and return value")
>> Signed-off-by: Yang Jihong <[email protected]>
>
> Reviewed-by: Adrian Hunter <[email protected]>
>
Thanks for reviewed-by.

Thanks,
Yang

2022-12-19 11:43:19

by Adrian Hunter

[permalink] [raw]
Subject: Re: [PATCH] perf tool: Fix output unexpected messages in quiet mode

On 19/12/22 11:28, Yang Jihong wrote:
> Hello,
>
> On 2022/12/19 14:59, Adrian Hunter wrote:
>> On 19/12/22 04:49, Yang Jihong wrote:
>>> When perf uses quiet mode, perf_quiet_option sets debug_peo_args to -1,
>>
>> Seems like redirect_to_stderr has similar issue?
> The redirect_to_stderr is used only in the veprintf function:
>
>   int veprintf(int level, int var, const char *fmt, va_list args)
>   {
>           int ret = 0;
>
>           if (var >= level) {
>                   if (use_browser >= 1 && redirect_to_stderr <= 0) {
>                           ui_helpline__vshow(fmt, args);
>                   } else {
>                           ret = fprintf_time(debug_file);
>                           ret += vfprintf(debug_file, fmt, args);
>                   }
>           }
>
>           return ret;
>   }
>
> If use quiet mode, verbose sets to -1. (also assigned in the perf_quiet_option function)
> Because "var >= level" is false, veprintf function returns directly, which avoids this problem.
>
> However, there are cases where:
>   # perf --debug stderr=-1 report -vvv 2>/tmp/debug
>
> If stderr is -1, should we redirect pr_debug in this case?

tools/perf/Documentation/perf.txt says debug variables are in value
range (0, 10), so -1 is invalid anyway.

>
> Because I'm not sure if this is a problem,
> if redirect_to_stderr needs to be fixed as well,
> let me know and I'll submit a patch to fix it.

perf_quiet_option() sets redirect_to_stderr = -1 with the intention
that it turns it off, but it doesn't, although it gets turned of by
verbose = -1. Perhaps set redirect_to_stderr = 0 in perf_quiet_option() ?

I see we have another problem as well: places that check "if (verbose)"
instead of "if (verbose > 0)"

>
>>
>>> and display_attr incorrectly determines the value of debug_peo_args.
>>> As a result, unexpected information is displayed.
>>>
>>> Before:
>>>    # perf record --quiet -- ls > /dev/null
>>>    ------------------------------------------------------------
>>>    perf_event_attr:
>>>      size                             128
>>>      { sample_period, sample_freq }   4000
>>>      sample_type                      IP|TID|TIME|PERIOD
>>>      read_format                      ID|LOST
>>>      disabled                         1
>>>      inherit                          1
>>>      mmap                             1
>>>      comm                             1
>>>      freq                             1
>>>      enable_on_exec                   1
>>>      task                             1
>>>      precise_ip                       3
>>>      sample_id_all                    1
>>>      exclude_guest                    1
>>>      mmap2                            1
>>>      comm_exec                        1
>>>      ksymbol                          1
>>>      bpf_event                        1
>>>    ------------------------------------------------------------
>>>    ...
>>>
>>> After:
>>>    # perf record --quiet -- ls > /dev/null
>>>    #
>>>
>>> Fixes: ccd26741f5e6 ("perf tool: Provide an option to print perf_event_open args and return value")
>>> Signed-off-by: Yang Jihong <[email protected]>
>>
>> Reviewed-by: Adrian Hunter <[email protected]>
>>
> Thanks for reviewed-by.
>
> Thanks,
> Yang

2022-12-19 13:43:12

by Yang Jihong

[permalink] [raw]
Subject: Re: [PATCH] perf tool: Fix output unexpected messages in quiet mode

Hello,

On 2022/12/19 18:28, Adrian Hunter wrote:
> On 19/12/22 11:28, Yang Jihong wrote:
>> Hello,
>>
>> On 2022/12/19 14:59, Adrian Hunter wrote:
>>> On 19/12/22 04:49, Yang Jihong wrote:
>>>> When perf uses quiet mode, perf_quiet_option sets debug_peo_args to -1,
>>>
>>> Seems like redirect_to_stderr has similar issue?
>> The redirect_to_stderr is used only in the veprintf function:
>>
>>   int veprintf(int level, int var, const char *fmt, va_list args)
>>   {
>>           int ret = 0;
>>
>>           if (var >= level) {
>>                   if (use_browser >= 1 && redirect_to_stderr <= 0) {
>>                           ui_helpline__vshow(fmt, args);
>>                   } else {
>>                           ret = fprintf_time(debug_file);
>>                           ret += vfprintf(debug_file, fmt, args);
>>                   }
>>           }
>>
>>           return ret;
>>   }
>>
>> If use quiet mode, verbose sets to -1. (also assigned in the perf_quiet_option function)
>> Because "var >= level" is false, veprintf function returns directly, which avoids this problem.
>>
>> However, there are cases where:
>>   # perf --debug stderr=-1 report -vvv 2>/tmp/debug
>>
>> If stderr is -1, should we redirect pr_debug in this case?
>
> tools/perf/Documentation/perf.txt says debug variables are in value
> range (0, 10), so -1 is invalid anyway.
>
Okay, I see.
>>
>> Because I'm not sure if this is a problem,
>> if redirect_to_stderr needs to be fixed as well,
>> let me know and I'll submit a patch to fix it.
>
> perf_quiet_option() sets redirect_to_stderr = -1 with the intention
> that it turns it off, but it doesn't, although it gets turned of by
> verbose = -1. Perhaps set redirect_to_stderr = 0 in perf_quiet_option() ?
>
I think it's better to fix redirect_to_stderr and debug_peo_args in the
same way (because they're similar):

Solution A:
diff --git a/tools/perf/util/debug.c b/tools/perf/util/debug.c
index 65e6c22f38e4..908b26e579e5 100644
--- a/tools/perf/util/debug.c
+++ b/tools/perf/util/debug.c
@@ -68,7 +68,7 @@ int veprintf(int level, int var, const char *fmt,
va_list args)
int ret = 0;

if (var >= level) {
- if (use_browser >= 1 && !redirect_to_stderr) {
+ if (use_browser >= 1 && redirect_to_stderr <= 0) {
ui_helpline__vshow(fmt, args);
} else {
ret = fprintf_time(debug_file);
diff --git a/tools/perf/util/debug.h b/tools/perf/util/debug.h
index f99468a7f681..f6ab84c93ec0 100644
--- a/tools/perf/util/debug.h
+++ b/tools/perf/util/debug.h
@@ -41,7 +41,7 @@ extern int debug_data_convert;

/* Special macro to print perf_event_open arguments/return value. */
#define pr_debug2_peo(fmt, ...) { \
- if (debug_peo_args) \
+ if (debug_peo_args > 0) \
pr_debugN(0, pr_fmt(fmt), ##__VA_ARGS__); \
else \
pr_debugN(2, pr_fmt(fmt), ##__VA_ARGS__); \
diff --git a/tools/perf/util/evsel.c b/tools/perf/util/evsel.c
index 999dd1700502..45cf144c5d5d 100644
--- a/tools/perf/util/evsel.c
+++ b/tools/perf/util/evsel.c
@@ -1775,7 +1775,7 @@ static int __open_attr__fprintf(FILE *fp, const
char *name, const char *val,

static void display_attr(struct perf_event_attr *attr)
{
- if (verbose >= 2 || debug_peo_args) {
+ if (verbose >= 2 || debug_peo_args > 0) {
fprintf(stderr, "%.60s\n", graph_dotted_line);
fprintf(stderr, "perf_event_attr:\n");
perf_event_attr__fprintf(stderr, attr,
__open_attr__fprintf, NULL);

or
Solution B:

diff --git a/tools/perf/util/debug.c b/tools/perf/util/debug.c
index 908b26e579e5..e3acc213edd1 100644
--- a/tools/perf/util/debug.c
+++ b/tools/perf/util/debug.c
@@ -241,6 +241,9 @@ int perf_quiet_option(void)
opt++;
}

+ redirect_to_stderr = 0;
+ debug_peo_args = 0;
+

> I see we have another problem as well: places that check "if (verbose)"
> instead of "if (verbose > 0)"
Yes, places that "if (verbose)" also have problems, I'll submit a patch
to change them to "if (verbose > 0)"

In addition, I found another problem, perf lock/stat/probe does not call
the perf_quiet_option function when quiet is true.

Thanks,
Yang

2022-12-19 14:03:23

by Adrian Hunter

[permalink] [raw]
Subject: Re: [PATCH] perf tool: Fix output unexpected messages in quiet mode

On 19/12/22 15:14, Yang Jihong wrote:
> Hello,
>
> On 2022/12/19 18:28, Adrian Hunter wrote:
>> On 19/12/22 11:28, Yang Jihong wrote:
>>> Hello,
>>>
>>> On 2022/12/19 14:59, Adrian Hunter wrote:
>>>> On 19/12/22 04:49, Yang Jihong wrote:
>>>>> When perf uses quiet mode, perf_quiet_option sets debug_peo_args to -1,
>>>>
>>>> Seems like redirect_to_stderr has similar issue?
>>> The redirect_to_stderr is used only in the veprintf function:
>>>
>>>    int veprintf(int level, int var, const char *fmt, va_list args)
>>>    {
>>>            int ret = 0;
>>>
>>>            if (var >= level) {
>>>                    if (use_browser >= 1 && redirect_to_stderr <= 0) {
>>>                            ui_helpline__vshow(fmt, args);
>>>                    } else {
>>>                            ret = fprintf_time(debug_file);
>>>                            ret += vfprintf(debug_file, fmt, args);
>>>                    }
>>>            }
>>>
>>>            return ret;
>>>    }
>>>
>>> If use quiet mode, verbose sets to -1. (also assigned in the perf_quiet_option function)
>>> Because "var >= level" is false, veprintf function returns directly, which avoids this problem.
>>>
>>> However, there are cases where:
>>>    # perf --debug stderr=-1 report -vvv 2>/tmp/debug
>>>
>>> If stderr is -1, should we redirect pr_debug in this case?
>>
>> tools/perf/Documentation/perf.txt says debug variables are in value
>> range (0, 10), so -1 is invalid anyway.
>>
> Okay, I see.
>>>
>>> Because I'm not sure if this is a problem,
>>> if redirect_to_stderr needs to be fixed as well,
>>> let me know and I'll submit a patch to fix it.
>>
>> perf_quiet_option() sets redirect_to_stderr = -1 with the intention
>> that it turns it off, but it doesn't, although it gets turned of by
>> verbose = -1. Perhaps set redirect_to_stderr = 0 in perf_quiet_option() ?
>>
> I think it's better to fix redirect_to_stderr and debug_peo_args in the same way (because they're similar):
>
> Solution A:
>   diff --git a/tools/perf/util/debug.c b/tools/perf/util/debug.c
>   index 65e6c22f38e4..908b26e579e5 100644
>   --- a/tools/perf/util/debug.c
>   +++ b/tools/perf/util/debug.c
>   @@ -68,7 +68,7 @@ int veprintf(int level, int var, const char *fmt, va_list args)
>           int ret = 0;
>
>           if (var >= level) {
>   -               if (use_browser >= 1 && !redirect_to_stderr) {
>   +               if (use_browser >= 1 && redirect_to_stderr <= 0) {
>                           ui_helpline__vshow(fmt, args);
>                   } else {
>                           ret = fprintf_time(debug_file);
>   diff --git a/tools/perf/util/debug.h b/tools/perf/util/debug.h
>   index f99468a7f681..f6ab84c93ec0 100644
>   --- a/tools/perf/util/debug.h
>   +++ b/tools/perf/util/debug.h
>   @@ -41,7 +41,7 @@ extern int debug_data_convert;
>
>    /* Special macro to print perf_event_open arguments/return value. */
>    #define pr_debug2_peo(fmt, ...) {                              \
>   -       if (debug_peo_args)                                             \
>   +       if (debug_peo_args > 0)                                         \
>                   pr_debugN(0, pr_fmt(fmt), ##__VA_ARGS__);       \
>           else                                                    \
>                   pr_debugN(2, pr_fmt(fmt), ##__VA_ARGS__);       \
>   diff --git a/tools/perf/util/evsel.c b/tools/perf/util/evsel.c
>   index 999dd1700502..45cf144c5d5d 100644
>   --- a/tools/perf/util/evsel.c
>   +++ b/tools/perf/util/evsel.c
>   @@ -1775,7 +1775,7 @@ static int __open_attr__fprintf(FILE *fp, const char *name, const char *val,
>
>    static void display_attr(struct perf_event_attr *attr)
>    {
>   -       if (verbose >= 2 || debug_peo_args) {
>   +       if (verbose >= 2 || debug_peo_args > 0) {
>                   fprintf(stderr, "%.60s\n", graph_dotted_line);
>                   fprintf(stderr, "perf_event_attr:\n");
>                   perf_event_attr__fprintf(stderr, attr, __open_attr__fprintf, NULL);
>
> or
> Solution B:
>
>   diff --git a/tools/perf/util/debug.c b/tools/perf/util/debug.c
>   index 908b26e579e5..e3acc213edd1 100644
>   --- a/tools/perf/util/debug.c
>   +++ b/tools/perf/util/debug.c
>   @@ -241,6 +241,9 @@ int perf_quiet_option(void)
>                   opt++;
>           }
>
>   +       redirect_to_stderr = 0;
>   +       debug_peo_args = 0;
>   +

That seems good to me.

>
>> I see we have another problem as well: places that check "if (verbose)"
>> instead of "if (verbose > 0)"
> Yes,  places that "if (verbose)" also have problems, I'll submit a patch to change them to "if (verbose > 0)"

Thank you!

>
> In addition, I found another problem, perf lock/stat/probe does not call the perf_quiet_option function when quiet is true.
>
> Thanks,
> Yang