diff mbox series

perf tool: Fix output unexpected messages in quiet mode

Message ID 20221219024911.62741-1-yangjihong1@huawei.com
State New
Headers
Series perf tool: Fix output unexpected messages in quiet mode |

Commit Message

Yang Jihong Dec. 19, 2022, 2:49 a.m. UTC 
  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 <yangjihong1@huawei.com>
---
 tools/perf/util/debug.h | 2 +-
 tools/perf/util/evsel.c | 2 +-
 2 files changed, 2 insertions(+), 2 deletions(-)

Comments

Adrian Hunter Dec. 19, 2022, 6:59 a.m. UTC | #1 
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 <yangjihong1@huawei.com>

Reviewed-by: Adrian Hunter <adrian.hunter@intel.com>

> ---
>  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);
Yang Jihong Dec. 19, 2022, 9:28 a.m. UTC | #2 
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 <yangjihong1@huawei.com>
> 
> Reviewed-by: Adrian Hunter <adrian.hunter@intel.com>
> 
Thanks for reviewed-by.

Thanks,
Yang
Adrian Hunter Dec. 19, 2022, 10:28 a.m. UTC | #3 
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 <yangjihong1@huawei.com>
>>
>> Reviewed-by: Adrian Hunter <adrian.hunter@intel.com>
>>
> Thanks for reviewed-by.
> 
> Thanks,
> Yang
Yang Jihong Dec. 19, 2022, 1:14 p.m. UTC | #4 
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
Adrian Hunter Dec. 19, 2022, 1:19 p.m. UTC | #5 
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
diff mbox series

Patch

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