Re: [PATCH v4 2/2] perf: add support for logging debug messages to file

[Changbin Du <changbin.du@gmail.com>]

On Mon, Oct 14, 2019 at 05:29:53PM +0200, Jiri Olsa wrote:
> On Tue, Oct 08, 2019 at 08:35:54PM +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 <changbin.du@gmail.com>
> > 
> > --
> > v4: fix another segfault.
> > v3: fix a segfault issue.
> 
> hi,
> no crash this time ;-) some questions below
> 
> > ---
> >  tools/perf/Documentation/perf.txt | 15 ++++++-----
> >  tools/perf/util/debug.c           | 44 ++++++++++++++++++++++++++++---
> >  2 files changed, 49 insertions(+), 10 deletions(-)
> > 
> > diff --git a/tools/perf/Documentation/perf.txt b/tools/perf/Documentation/perf.txt
> > index c05a94b2488e..a6b19661e5c3 100644
> > --- a/tools/perf/Documentation/perf.txt
> > +++ b/tools/perf/Documentation/perf.txt
> > @@ -16,14 +16,17 @@ 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
> > -				  in browser mode
> > +	  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
> > +	  file=path             - write debug output to log file (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 df82ad9cd16d..5cc2479d63ea 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>
> > @@ -26,7 +27,7 @@
> >  int verbose;
> >  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)
> > @@ -34,8 +35,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);
> >  	}
> > @@ -197,6 +200,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;
> > @@ -218,8 +239,23 @@ 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;
> 
> do you ned to fflush stderr? I thought it's unbuffered
>
Acorrding to my test, some messages are lost after ctrl-c without flusing. So
I think it is buffered by libc?

> > -		else {
> > +			set_log_output(stderr);
> > +		else if (!strcmp(opt, "file")) {
> > +			FILE *f;
> > +
> > +			if (!vstr)
> > +				vstr = (char *)"perf.log";
> 
> you did not mention in doc that perf.log is default
> 
yes, it should be mentioned.

> > +
> > +			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");
> 
> is this necessary?
> 
Yes, because we will append new log to existing one. So we'd beeter put a margin
there.

> jirka
> 
> > +			set_log_output(f);
> > +		} else {
> >  			fprintf(stderr, "unkown debug option '%s'\n", opt);
> >  			free(dstr);
> >  			return -1;
> > -- 
> > 2.20.1
> > 

-- 
Cheers,
Changbin Du