2019-11-25 15:16:39

by Changbin Du

[permalink] [raw]
Subject: [PATCH v6 0/2] perf: add support for logging debug messages to file

When in TUI mode, it is impossible to show all the debug messages to
console. This make it hard to debug perf issues using debug messages.
This patch adds support for logging debug messages to file to resolve
this problem.

v6:
o rebase to perf/core.
v5:
o doc default log path.
v4:
o fix another segfault.
v3:
o fix a segfault issue.
v2:
o specific all debug options one time.

Changbin Du (2):
perf: support multiple debug options separated by ','
perf: add support for logging debug messages to file

tools/perf/Documentation/perf.txt | 20 +++--
tools/perf/util/debug.c | 127 ++++++++++++++++++++----------
2 files changed, 96 insertions(+), 51 deletions(-)

--
2.20.1


2019-11-25 15:19:45

by Changbin Du

[permalink] [raw]
Subject: [PATCH v6 2/2] perf: add support for logging debug messages to file

When in TUI mode, it is impossible to show all the debug messages to
console. This make it hard to debug perf issues using debug messages.
This patch adds support for logging debug messages to file to resolve
this problem.

The usage is:
perf -debug verbose=2,file=~/perf.log COMMAND

Signed-off-by: Changbin Du <[email protected]>

---
v5: doc default log path.
v4: fix another segfault.
v3: fix a segfault issue.
---
tools/perf/Documentation/perf.txt | 15 +++++++----
tools/perf/util/debug.c | 44 ++++++++++++++++++++++++++++---
2 files changed, 50 insertions(+), 9 deletions(-)

diff --git a/tools/perf/Documentation/perf.txt b/tools/perf/Documentation/perf.txt
index fd8d790f68a7..a47933b53fbe 100644
--- a/tools/perf/Documentation/perf.txt
+++ b/tools/perf/Documentation/perf.txt
@@ -16,15 +16,20 @@ OPTIONS
Setup debug variable (see list below) in value
range (0, 10). Use like:
--debug verbose # sets verbose = 1
- --debug verbose=2 # sets verbose = 2
+ --debug verbose=2,file=~/perf.log
+ # sets verbose = 2 and save log to file

List of debug variables allowed to set:
- verbose=level - general debug messages
- ordered-events=level - ordered events object debug messages
- data-convert=level - data convert command debug messages
- stderr - write debug output (option -v) to stderr
+ verbose=level - general debug messages
+ ordered-events=level - ordered events object debug messages
+ data-convert=level - data convert command debug messages
+ stderr - write debug output (option -v) to stderr
+ in browser mode
perf-event-open - Print perf_event_open() arguments and
return value in browser mode
+ file[=path] - write debug output to log file, default
+ 'perf.log' (stderr and file options are
+ exclusive)

--buildid-dir::
Setup buildid cache directory. It has higher priority than
diff --git a/tools/perf/util/debug.c b/tools/perf/util/debug.c
index 929da46ece92..21bc889976bc 100644
--- a/tools/perf/util/debug.c
+++ b/tools/perf/util/debug.c
@@ -6,6 +6,7 @@
#include <stdarg.h>
#include <stdio.h>
#include <stdlib.h>
+#include <errno.h>
#include <sys/wait.h>
#include <api/debug.h>
#include <linux/kernel.h>
@@ -27,7 +28,7 @@ int verbose;
int debug_peo_args;
bool dump_trace = false, quiet = false;
int debug_ordered_events;
-static bool redirect_to_stderr;
+static FILE *log_file;
int debug_data_convert;

int veprintf(int level, int var, const char *fmt, va_list args)
@@ -35,8 +36,10 @@ 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 && !log_file)
ui_helpline__vshow(fmt, args);
+ else if (log_file)
+ ret = vfprintf(log_file, fmt, args);
else
ret = vfprintf(stderr, fmt, args);
}
@@ -198,6 +201,24 @@ static int str2loglevel(const char *vstr)
return v;
}

+static void flush_log(void)
+{
+ if (log_file)
+ fflush(log_file);
+}
+
+static void set_log_output(FILE *f)
+{
+ if (f == log_file)
+ return;
+
+ if (log_file && log_file != stderr)
+ fclose(log_file);
+
+ log_file = f;
+ atexit(flush_log);
+}
+
int perf_debug_option(const char *str)
{
char *sep, *vstr;
@@ -219,10 +240,25 @@ int perf_debug_option(const char *str)
else if (!strcmp(opt, "data-convert"))
debug_data_convert = str2loglevel(vstr);
else if (!strcmp(opt, "stderr"))
- redirect_to_stderr = true;
+ set_log_output(stderr);
else if (!strcmp(opt, "perf-event-open"))
debug_peo_args = true;
- else {
+ else if (!strcmp(opt, "file")) {
+ FILE *f;
+
+ if (!vstr)
+ vstr = (char *)"perf.log";
+
+ f = fopen(vstr, "a");
+ if (!f) {
+ pr_err("Can not create log file: %s\n",
+ strerror(errno));
+ free(dstr);
+ return -1;
+ }
+ fprintf(f, "\n===========perf log===========\n");
+ set_log_output(f);
+ } else {
fprintf(stderr, "unkown debug option '%s'\n", opt);
free(dstr);
return -1;
--
2.20.1

2019-11-25 18:46:32

by Changbin Du

[permalink] [raw]
Subject: [PATCH v6 1/2] perf: support multiple debug options separated by ','

This patch adds support for multiple debug options separated by ',' and
non-int values.
--debug verbose=2,stderr

Signed-off-by: Changbin Du <[email protected]>
---
tools/perf/Documentation/perf.txt | 13 +++--
tools/perf/util/debug.c | 89 ++++++++++++++++---------------
2 files changed, 53 insertions(+), 49 deletions(-)

diff --git a/tools/perf/Documentation/perf.txt b/tools/perf/Documentation/perf.txt
index 3f37ded13f8c..fd8d790f68a7 100644
--- a/tools/perf/Documentation/perf.txt
+++ b/tools/perf/Documentation/perf.txt
@@ -19,13 +19,12 @@ OPTIONS
--debug verbose=2 # sets verbose = 2

List of debug variables allowed to set:
- verbose - general debug messages
- ordered-events - ordered events object debug messages
- data-convert - data convert command debug messages
- stderr - write debug output (option -v) to stderr
- in browser mode
- perf-event-open - Print perf_event_open() arguments and
- return value
+ verbose=level - general debug messages
+ ordered-events=level - ordered events object debug messages
+ data-convert=level - data convert command debug messages
+ stderr - write debug output (option -v) to stderr
+ perf-event-open - Print perf_event_open() arguments and
+ return value in browser mode

--buildid-dir::
Setup buildid cache directory. It has higher priority than
diff --git a/tools/perf/util/debug.c b/tools/perf/util/debug.c
index adb656745ecc..929da46ece92 100644
--- a/tools/perf/util/debug.c
+++ b/tools/perf/util/debug.c
@@ -27,7 +27,7 @@ int verbose;
int debug_peo_args;
bool dump_trace = false, quiet = false;
int debug_ordered_events;
-static int redirect_to_stderr;
+static bool redirect_to_stderr;
int debug_data_convert;

int veprintf(int level, int var, const char *fmt, va_list args)
@@ -173,42 +173,18 @@ void trace_event(union perf_event *event)
trace_event_printer, event);
}

-static struct debug_variable {
- const char *name;
- int *ptr;
-} debug_variables[] = {
- { .name = "verbose", .ptr = &verbose },
- { .name = "ordered-events", .ptr = &debug_ordered_events},
- { .name = "stderr", .ptr = &redirect_to_stderr},
- { .name = "data-convert", .ptr = &debug_data_convert },
- { .name = "perf-event-open", .ptr = &debug_peo_args },
- { .name = NULL, }
-};
-
-int perf_debug_option(const char *str)
+static int str2loglevel(const char *vstr)
{
- struct debug_variable *var = &debug_variables[0];
- char *vstr, *s = strdup(str);
int v = 1;
-
- vstr = strchr(s, '=');
- if (vstr)
- *vstr++ = 0;
-
- while (var->name) {
- if (!strcmp(s, var->name))
- break;
- var++;
- }
-
- if (!var->name) {
- pr_err("Unknown debug variable name '%s'\n", s);
- free(s);
- return -1;
- }
+ char *endptr;

if (vstr) {
- v = atoi(vstr);
+ v = strtol(vstr, &endptr,0);
+ if (vstr == endptr) {
+ fprintf(stderr, "warning: '%s' is not a digit\n", vstr);
+ return -1;
+ }
+
/*
* Allow only values in range (0, 10),
* otherwise set 0.
@@ -219,20 +195,49 @@ int perf_debug_option(const char *str)
if (quiet)
v = -1;

- *var->ptr = v;
- free(s);
+ return v;
+}
+
+int perf_debug_option(const char *str)
+{
+ char *sep, *vstr;
+ char *dstr = strdup(str);
+ char *opt = dstr;
+
+ do {
+ if ((sep = strchr(opt, ',')) != NULL)
+ *sep = '\0';
+
+ vstr = strchr(opt, '=');
+ if (vstr)
+ *vstr++ = 0;
+
+ if (!strcmp(opt, "verbose"))
+ verbose = str2loglevel(vstr);
+ else if (!strcmp(opt, "ordered-events"))
+ debug_ordered_events = str2loglevel(vstr);
+ else if (!strcmp(opt, "data-convert"))
+ debug_data_convert = str2loglevel(vstr);
+ else if (!strcmp(opt, "stderr"))
+ redirect_to_stderr = true;
+ else if (!strcmp(opt, "perf-event-open"))
+ debug_peo_args = true;
+ else {
+ fprintf(stderr, "unkown debug option '%s'\n", opt);
+ free(dstr);
+ return -1;
+ }
+
+ opt = sep + 1;
+ } while (sep && sep[1]);
+
+ free(dstr);
return 0;
}

int perf_quiet_option(void)
{
- struct debug_variable *var = &debug_variables[0];
-
- /* disable all debug messages */
- while (var->name) {
- *var->ptr = -1;
- var++;
- }
+ verbose = debug_ordered_events = debug_data_convert = -1;

return 0;
}
--
2.20.1

2019-11-26 05:44:41

by Ravi Bangoria

[permalink] [raw]
Subject: Re: [PATCH v6 1/2] perf: support multiple debug options separated by ','



On 11/25/19 8:44 PM, Changbin Du wrote:
> List of debug variables allowed to set:
> - verbose - general debug messages
> - ordered-events - ordered events object debug messages
> - data-convert - data convert command debug messages
> - stderr - write debug output (option -v) to stderr
> - in browser mode
> - perf-event-open - Print perf_event_open() arguments and
> - return value
> + verbose=level - general debug messages
> + ordered-events=level - ordered events object debug messages
> + data-convert=level - data convert command debug messages
> + stderr - write debug output (option -v) to stderr
> + perf-event-open - Print perf_event_open() arguments and
> + return value in browser mode
Shouldn't this be:

stderr - write debug output (option -v) to stderr
in browser mode
perf-event-open - Print perf_event_open() arguments and
return value

-Ravi

2019-11-26 09:48:49

by Jiri Olsa

[permalink] [raw]
Subject: Re: [PATCH v6 1/2] perf: support multiple debug options separated by ','

On Mon, Nov 25, 2019 at 11:14:45PM +0800, Changbin Du wrote:
> This patch adds support for multiple debug options separated by ',' and
> non-int values.
> --debug verbose=2,stderr
>
> Signed-off-by: Changbin Du <[email protected]>
> ---
> tools/perf/Documentation/perf.txt | 13 +++--
> tools/perf/util/debug.c | 89 ++++++++++++++++---------------
> 2 files changed, 53 insertions(+), 49 deletions(-)
>
> diff --git a/tools/perf/Documentation/perf.txt b/tools/perf/Documentation/perf.txt
> index 3f37ded13f8c..fd8d790f68a7 100644
> --- a/tools/perf/Documentation/perf.txt
> +++ b/tools/perf/Documentation/perf.txt
> @@ -19,13 +19,12 @@ OPTIONS
> --debug verbose=2 # sets verbose = 2
>
> List of debug variables allowed to set:
> - verbose - general debug messages
> - ordered-events - ordered events object debug messages
> - data-convert - data convert command debug messages
> - stderr - write debug output (option -v) to stderr
> - in browser mode
> - perf-event-open - Print perf_event_open() arguments and
> - return value
> + verbose=level - general debug messages
> + ordered-events=level - ordered events object debug messages
> + data-convert=level - data convert command debug messages
> + stderr - write debug output (option -v) to stderr
> + perf-event-open - Print perf_event_open() arguments and
> + return value in browser mode

it's just the list and the doc says user can use values
there, so no need for the '=level' there

also we allow this:
perf --debug stderr=9 record ls

so I thinks we should keep it general in documentation,
eventhough it will always mean just stderr=true for any
value

jirka

2019-11-26 09:52:54

by Jiri Olsa

[permalink] [raw]
Subject: Re: [PATCH v6 2/2] perf: add support for logging debug messages to file

On Mon, Nov 25, 2019 at 11:14:46PM +0800, Changbin Du wrote:
> When in TUI mode, it is impossible to show all the debug messages to
> console. This make it hard to debug perf issues using debug messages.
> This patch adds support for logging debug messages to file to resolve
> this problem.
>
> The usage is:
> perf -debug verbose=2,file=~/perf.log COMMAND
>
> Signed-off-by: Changbin Du <[email protected]>
>
> ---
> v5: doc default log path.
> v4: fix another segfault.
> v3: fix a segfault issue.
> ---
> tools/perf/Documentation/perf.txt | 15 +++++++----
> tools/perf/util/debug.c | 44 ++++++++++++++++++++++++++++---
> 2 files changed, 50 insertions(+), 9 deletions(-)
>
> diff --git a/tools/perf/Documentation/perf.txt b/tools/perf/Documentation/perf.txt
> index fd8d790f68a7..a47933b53fbe 100644
> --- a/tools/perf/Documentation/perf.txt
> +++ b/tools/perf/Documentation/perf.txt
> @@ -16,15 +16,20 @@ OPTIONS
> Setup debug variable (see list below) in value
> range (0, 10). Use like:
> --debug verbose # sets verbose = 1
> - --debug verbose=2 # sets verbose = 2
> + --debug verbose=2,file=~/perf.log
> + # sets verbose = 2 and save log to file
>
> List of debug variables allowed to set:
> - verbose=level - general debug messages
> - ordered-events=level - ordered events object debug messages
> - data-convert=level - data convert command debug messages
> - stderr - write debug output (option -v) to stderr
> + verbose=level - general debug messages
> + ordered-events=level - ordered events object debug messages
> + data-convert=level - data convert command debug messages
> + stderr - write debug output (option -v) to stderr
> + in browser mode

hum, why is this changed in this patch?

jirka

> perf-event-open - Print perf_event_open() arguments and
> return value in browser mode
> + file[=path] - write debug output to log file, default
> + 'perf.log' (stderr and file options are
> + exclusive)
>
> --buildid-dir::
> Setup buildid cache directory. It has higher priority than
> diff --git a/tools/perf/util/debug.c b/tools/perf/util/debug.c
> index 929da46ece92..21bc889976bc 100644
> --- a/tools/perf/util/debug.c
> +++ b/tools/perf/util/debug.c
> @@ -6,6 +6,7 @@
> #include <stdarg.h>
> #include <stdio.h>
> #include <stdlib.h>
> +#include <errno.h>
> #include <sys/wait.h>
> #include <api/debug.h>
> #include <linux/kernel.h>
> @@ -27,7 +28,7 @@ int verbose;
> int debug_peo_args;
> bool dump_trace = false, quiet = false;
> int debug_ordered_events;
> -static bool redirect_to_stderr;
> +static FILE *log_file;
> int debug_data_convert;
>
> int veprintf(int level, int var, const char *fmt, va_list args)
> @@ -35,8 +36,10 @@ 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 && !log_file)
> ui_helpline__vshow(fmt, args);
> + else if (log_file)
> + ret = vfprintf(log_file, fmt, args);
> else
> ret = vfprintf(stderr, fmt, args);
> }
> @@ -198,6 +201,24 @@ static int str2loglevel(const char *vstr)
> return v;
> }
>
> +static void flush_log(void)
> +{
> + if (log_file)
> + fflush(log_file);
> +}
> +
> +static void set_log_output(FILE *f)
> +{
> + if (f == log_file)
> + return;
> +
> + if (log_file && log_file != stderr)
> + fclose(log_file);
> +
> + log_file = f;
> + atexit(flush_log);
> +}
> +
> int perf_debug_option(const char *str)
> {
> char *sep, *vstr;
> @@ -219,10 +240,25 @@ int perf_debug_option(const char *str)
> else if (!strcmp(opt, "data-convert"))
> debug_data_convert = str2loglevel(vstr);
> else if (!strcmp(opt, "stderr"))
> - redirect_to_stderr = true;
> + set_log_output(stderr);
> else if (!strcmp(opt, "perf-event-open"))
> debug_peo_args = true;
> - else {
> + else if (!strcmp(opt, "file")) {
> + FILE *f;
> +
> + if (!vstr)
> + vstr = (char *)"perf.log";
> +
> + f = fopen(vstr, "a");
> + if (!f) {
> + pr_err("Can not create log file: %s\n",
> + strerror(errno));
> + free(dstr);
> + return -1;
> + }
> + fprintf(f, "\n===========perf log===========\n");
> + set_log_output(f);
> + } else {
> fprintf(stderr, "unkown debug option '%s'\n", opt);
> free(dstr);
> return -1;
> --
> 2.20.1
>

2019-11-26 14:36:25

by Changbin Du

[permalink] [raw]
Subject: Re: [PATCH v6 1/2] perf: support multiple debug options separated by ','

On Tue, Nov 26, 2019 at 11:10:45AM +0530, Ravi Bangoria wrote:
>
>
> On 11/25/19 8:44 PM, Changbin Du wrote:
> > List of debug variables allowed to set:
> > - verbose - general debug messages
> > - ordered-events - ordered events object debug messages
> > - data-convert - data convert command debug messages
> > - stderr - write debug output (option -v) to stderr
> > - in browser mode
> > - perf-event-open - Print perf_event_open() arguments and
> > - return value
> > + verbose=level - general debug messages
> > + ordered-events=level - ordered events object debug messages
> > + data-convert=level - data convert command debug messages
> > + stderr - write debug output (option -v) to stderr
> > + perf-event-open - Print perf_event_open() arguments and
> > + return value in browser mode
> Shouldn't this be:
>
> stderr - write debug output (option -v) to stderr
> in browser mode
> perf-event-open - Print perf_event_open() arguments and
> return value
>
This is an accident when rebasing. Thank you.

> -Ravi
>

--
Cheers,
Changbin Du

2019-11-26 14:38:54

by Changbin Du

[permalink] [raw]
Subject: Re: [PATCH v6 1/2] perf: support multiple debug options separated by ','

On Tue, Nov 26, 2019 at 10:45:08AM +0100, Jiri Olsa wrote:
> On Mon, Nov 25, 2019 at 11:14:45PM +0800, Changbin Du wrote:
> > This patch adds support for multiple debug options separated by ',' and
> > non-int values.
> > --debug verbose=2,stderr
> >
> > Signed-off-by: Changbin Du <[email protected]>
> > ---
> > tools/perf/Documentation/perf.txt | 13 +++--
> > tools/perf/util/debug.c | 89 ++++++++++++++++---------------
> > 2 files changed, 53 insertions(+), 49 deletions(-)
> >
> > diff --git a/tools/perf/Documentation/perf.txt b/tools/perf/Documentation/perf.txt
> > index 3f37ded13f8c..fd8d790f68a7 100644
> > --- a/tools/perf/Documentation/perf.txt
> > +++ b/tools/perf/Documentation/perf.txt
> > @@ -19,13 +19,12 @@ OPTIONS
> > --debug verbose=2 # sets verbose = 2
> >
> > List of debug variables allowed to set:
> > - verbose - general debug messages
> > - ordered-events - ordered events object debug messages
> > - data-convert - data convert command debug messages
> > - stderr - write debug output (option -v) to stderr
> > - in browser mode
> > - perf-event-open - Print perf_event_open() arguments and
> > - return value
> > + verbose=level - general debug messages
> > + ordered-events=level - ordered events object debug messages
> > + data-convert=level - data convert command debug messages
> > + stderr - write debug output (option -v) to stderr
> > + perf-event-open - Print perf_event_open() arguments and
> > + return value in browser mode
>
> it's just the list and the doc says user can use values
> there, so no need for the '=level' there
>
> also we allow this:
> perf --debug stderr=9 record ls
>
> so I thinks we should keep it general in documentation,
> eventhough it will always mean just stderr=true for any
> value
>
I changed them as below. For stderr and perf_event_open, the value is ignored
even it is given.

--debug::
Setup debug variable (see list below). The range of 'level' value
is (0, 10). Use like:
--debug verbose # sets verbose = 1
--debug verbose=2,file=~/perf.log
# sets verbose = 2 and save log to file

List of debug variables allowed to set:
verbose[=level] - general debug messages
ordered-events[=level]- ordered events object debug messages
data-convert[=level] - data convert command debug messages
stderr - write debug output (option -v) to stderr
in browser mode
perf-event-open - Print perf_event_open() arguments and
return value

> jirka
>

--
Cheers,
Changbin Du