[PATCH RESEND 1/4] tools lib traceevent: Check string is really printable

[PATCH RESEND 1/4] tools lib traceevent: Check string is really printable

[Namhyung Kim]

From: Namhyung Kim <namhyung.kim@lge.com>

When libtraceevent parses format fields, it assumes that
array of 1 byte is string but it's not always true. The
kvm_emulate_insn contains 15 u8 array of insn that contains
(binary) instructions. Thus when it's printed, it'll have
broken output like below:

  kvm_emulate_insn:     [FAILED TO PARSE] rip=3238197797 csbase=0 len=2 \
  insn=<89>P^]<B4>& flags=5 failed=0

With this patch:

  kvm_emulate_insn:     [FAILED TO PARSE] rip=3238197797 csbase=0 len=2 \
  insn=ARRAY[89, 10, 5d, c3, 8d, b4, 26, 00, 00, 00, 00, 55, 89, e5, 3e] flags=5 failed=0

Suggested-by: Steven Rostedt <rostedt@goodmis.org>
Link: http://lkml.kernel.org/n/tip-ki5fuys70vig80gzsz3g58r1@git.kernel.org
Signed-off-by: Namhyung Kim <namhyung@kernel.org>
---
 tools/lib/traceevent/event-parse.c |   14 +++++++++++++-
 1 file changed, 13 insertions(+), 1 deletion(-)

diff --git a/tools/lib/traceevent/event-parse.c b/tools/lib/traceevent/event-parse.c
index 853b604b6240..eb195cbc841c 100644
--- a/tools/lib/traceevent/event-parse.c
+++ b/tools/lib/traceevent/event-parse.c
@@ -3655,6 +3655,16 @@ static void print_mac_arg(struct trace_seq *s, int mac, void *data, int size,
 	trace_seq_printf(s, fmt, buf[0], buf[1], buf[2], buf[3], buf[4], buf[5]);
 }
 
+static int is_printable_array(char *p, unsigned int len)
+{
+	unsigned int i;
+
+	for (i = 0; i < len && p[i]; i++)
+		if (!isprint(p[i]))
+			return 0;
+	return 1;
+}
+
 static void print_event_fields(struct trace_seq *s, void *data, int size,
 			       struct event_format *event)
 {
@@ -3674,7 +3684,8 @@ static void print_event_fields(struct trace_seq *s, void *data, int size,
 				len = offset >> 16;
 				offset &= 0xffff;
 			}
-			if (field->flags & FIELD_IS_STRING) {
+			if (field->flags & FIELD_IS_STRING &&
+			    is_printable_array(data + offset, len)) {
 				trace_seq_printf(s, "%s", (char *)data + offset);
 			} else {
 				trace_seq_puts(s, "ARRAY[");
@@ -3685,6 +3696,7 @@ static void print_event_fields(struct trace_seq *s, void *data, int size,
 							 *((unsigned char *)data + offset + i));
 				}
 				trace_seq_putc(s, ']');
+				field->flags &= ~FIELD_IS_STRING;
 			}
 		} else {
 			val = pevent_read_number(event->pevent, data + field->offset,
-- 
1.7.10.2

[PATCH 2/4] KVM: Use __print_hex() for kvm_emulate_insn tracepoint

[Namhyung Kim]

From: Namhyung Kim <namhyung.kim@lge.com>

The kvm_emulate_insn tracepoint used __print_insn()
for printing its instructions. However it makes the
format of the event hard to parse as it reveals TP
internals.

Fortunately, kernel provides __print_hex for almost
same purpose, we can use it instead of open coding
it. The user-space can be changed to parse it later.

That means raw kernel tracing will not be affected
by this change:

 # cd /sys/kernel/debug/tracing/
 # cat events/kvm/kvm_emulate_insn/format
 name: kvm_emulate_insn
 ID: 29
 format:
	...
 print fmt: "%x:%llx:%s (%s)%s", REC->csbase, REC->rip, __print_hex(REC->insn, REC->len), \
 __print_symbolic(REC->flags, { 0, "real" }, { (1 << 0) | (1 << 1), "vm16" }, \
 { (1 << 0), "prot16" }, { (1 << 0) | (1 << 2), "prot32" }, { (1 << 0) | (1 << 3), "prot64" }), \
 REC->failed ? " failed" : ""

 # echo 1 > events/kvm/kvm_emulate_insn/enable
 # cat trace
 # tracer: nop
 #
 # entries-in-buffer/entries-written: 2183/2183   #P:12
 #
 #                              _-----=> irqs-off
 #                             / _----=> need-resched
 #                            | / _---=> hardirq/softirq
 #                            || / _--=> preempt-depth
 #                            ||| /     delay
 #           TASK-PID   CPU#  ||||    TIMESTAMP  FUNCTION
 #              | |       |   ||||       |         |
         qemu-kvm-1782  [002] ...1   140.931636: kvm_emulate_insn: 0:c102fa25:89 10 (prot32)
         qemu-kvm-1781  [004] ...1   140.931637: kvm_emulate_insn: 0:c102fa25:89 10 (prot32)

Cc: kvm@vger.kernel.org
Link: http://lkml.kernel.org/n/tip-wfw6y3b9ugtey8snaow9nmg5@git.kernel.org
Signed-off-by: Namhyung Kim <namhyung@kernel.org>
---
 arch/x86/kvm/trace.h   |   12 +-----------
 include/trace/ftrace.h |    1 +
 2 files changed, 2 insertions(+), 11 deletions(-)

diff --git a/arch/x86/kvm/trace.h b/arch/x86/kvm/trace.h
index 911d2641f14c..62d02e3c3ed6 100644
--- a/arch/x86/kvm/trace.h
+++ b/arch/x86/kvm/trace.h
@@ -710,16 +710,6 @@ TRACE_EVENT(kvm_skinit,
 		  __entry->rip, __entry->slb)
 );
 
-#define __print_insn(insn, ilen) ({		                 \
-	int i;							 \
-	const char *ret = p->buffer + p->len;			 \
-								 \
-	for (i = 0; i < ilen; ++i)				 \
-		trace_seq_printf(p, " %02x", insn[i]);		 \
-	trace_seq_printf(p, "%c", 0);				 \
-	ret;							 \
-	})
-
 #define KVM_EMUL_INSN_F_CR0_PE (1 << 0)
 #define KVM_EMUL_INSN_F_EFL_VM (1 << 1)
 #define KVM_EMUL_INSN_F_CS_D   (1 << 2)
@@ -786,7 +776,7 @@ TRACE_EVENT(kvm_emulate_insn,
 
 	TP_printk("%x:%llx:%s (%s)%s",
 		  __entry->csbase, __entry->rip,
-		  __print_insn(__entry->insn, __entry->len),
+		  __print_hex(__entry->insn, __entry->len),
 		  __print_symbolic(__entry->flags,
 				   kvm_trace_symbol_emul_flags),
 		  __entry->failed ? " failed" : ""
diff --git a/include/trace/ftrace.h b/include/trace/ftrace.h
index 769724944fc6..c6bc2faaf261 100644
--- a/include/trace/ftrace.h
+++ b/include/trace/ftrace.h
@@ -571,6 +571,7 @@ static inline void ftrace_test_probe_##call(void)			\
 
 #undef __print_flags
 #undef __print_symbolic
+#undef __print_hex
 #undef __get_dynamic_array
 #undef __get_str
 
-- 
1.7.10.2

[PATCH 3/4] tools lib traceevent: Use local variable 'field'

[Namhyung Kim]

From: Namhyung Kim <namhyung.kim@lge.com>

Use local variable 'field' to reduce typing. It is needed
by later patch not to exceed 80 column.

Link: http://lkml.kernel.org/n/tip-fz5zzpw09j937nly556wmgfn@git.kernel.org
Signed-off-by: Namhyung Kim <namhyung@kernel.org>
---
 tools/lib/traceevent/event-parse.c |   19 +++++++++++--------
 1 file changed, 11 insertions(+), 8 deletions(-)

diff --git a/tools/lib/traceevent/event-parse.c b/tools/lib/traceevent/event-parse.c
index eb195cbc841c..96cafa7a0fc8 100644
--- a/tools/lib/traceevent/event-parse.c
+++ b/tools/lib/traceevent/event-parse.c
@@ -3257,6 +3257,7 @@ static void print_str_arg(struct trace_seq *s, void *data, int size,
 {
 	struct pevent *pevent = event->pevent;
 	struct print_flag_sym *flag;
+	struct format_field *field;
 	unsigned long long val, fval;
 	unsigned long addr;
 	char *str;
@@ -3271,27 +3272,29 @@ static void print_str_arg(struct trace_seq *s, void *data, int size,
 		print_str_to_seq(s, format, len_arg, arg->atom.atom);
 		return;
 	case PRINT_FIELD:
-		if (!arg->field.field) {
-			arg->field.field = pevent_find_any_field(event, arg->field.name);
-			if (!arg->field.field)
+		field = arg->field.field;
+		if (!field) {
+			field = pevent_find_any_field(event, arg->field.name);
+			if (!field)
 				die("field %s not found", arg->field.name);
+			arg->field.field = field;
 		}
 		/* Zero sized fields, mean the rest of the data */
-		len = arg->field.field->size ? : size - arg->field.field->offset;
+		len = field->size ? : size - field->offset;
 
 		/*
 		 * Some events pass in pointers. If this is not an array
 		 * and the size is the same as long_size, assume that it
 		 * is a pointer.
 		 */
-		if (!(arg->field.field->flags & FIELD_IS_ARRAY) &&
-		    arg->field.field->size == pevent->long_size) {
-			addr = *(unsigned long *)(data + arg->field.field->offset);
+		if (!(field->flags & FIELD_IS_ARRAY) &&
+		    field->size == pevent->long_size) {
+			addr = *(unsigned long *)(data + field->offset);
 			trace_seq_printf(s, "%lx", addr);
 			break;
 		}
 		str = malloc_or_die(len + 1);
-		memcpy(str, data + arg->field.field->offset, len);
+		memcpy(str, data + field->offset, len);
 		str[len] = 0;
 		print_str_to_seq(s, format, len_arg, str);
 		free(str);
-- 
1.7.10.2

[PATCH 4/4] tools lib traceevent: Add support for __print_hex()

[Namhyung Kim]

From: Namhyung Kim <namhyung.kim@lge.com>

Since the __print_hex() function is used in print fmt now,
add corresponding parser routines. This makes the output of
perf script on the kvm_emulate_insn event not to fail any more.

 before:
      kvm_emulate_insn:     [FAILED TO PARSE] rip=3238197797 ...

 after:
      kvm_emulate_insn:     0:c102fa25:89 10 (prot32)

Link: http://lkml.kernel.org/n/tip-ic6oh4flbu7zfznpv1dgktlu@git.kernel.org
Signed-off-by: Namhyung Kim <namhyung@kernel.org>
---
 tools/lib/traceevent/event-parse.c                 |   75 +++++++++++++++++++-
 tools/lib/traceevent/event-parse.h                 |    7 ++
 .../perf/util/scripting-engines/trace-event-perl.c |    4 ++
 .../util/scripting-engines/trace-event-python.c    |    4 ++
 4 files changed, 89 insertions(+), 1 deletion(-)

diff --git a/tools/lib/traceevent/event-parse.c b/tools/lib/traceevent/event-parse.c
index 96cafa7a0fc8..ae56377cadd9 100644
--- a/tools/lib/traceevent/event-parse.c
+++ b/tools/lib/traceevent/event-parse.c
@@ -693,6 +693,10 @@ static void free_arg(struct print_arg *arg)
 		free_arg(arg->symbol.field);
 		free_flag_sym(arg->symbol.symbols);
 		break;
+	case PRINT_HEX:
+		free_arg(arg->hex.field);
+		free_arg(arg->hex.size);
+		break;
 	case PRINT_TYPE:
 		free(arg->typecast.type);
 		free_arg(arg->typecast.item);
@@ -2293,6 +2297,45 @@ process_symbols(struct event_format *event, struct print_arg *arg, char **tok)
 }
 
 static enum event_type
+process_hex(struct event_format *event, struct print_arg *arg, char **tok)
+{
+	struct print_arg *field;
+	enum event_type type;
+	char *token;
+
+	memset(arg, 0, sizeof(*arg));
+	arg->type = PRINT_HEX;
+
+	field = alloc_arg();
+	type = process_arg(event, field, &token);
+
+	if (test_type_token(type, token, EVENT_DELIM, ","))
+		goto out_free;
+
+	arg->hex.field = field;
+
+	free_token(token);
+
+	field = alloc_arg();
+	type = process_arg(event, field, &token);
+
+	if (test_type_token(type, token, EVENT_DELIM, ")"))
+		goto out_free;
+
+	arg->hex.size = field;
+
+	free_token(token);
+	type = read_token_item(tok);
+	return type;
+
+ out_free:
+	free_arg(field);
+	free_token(token);
+	*tok = NULL;
+	return EVENT_ERROR;
+}
+
+static enum event_type
 process_dynamic_array(struct event_format *event, struct print_arg *arg, char **tok)
 {
 	struct format_field *field;
@@ -2521,6 +2564,10 @@ process_function(struct event_format *event, struct print_arg *arg,
 		is_symbolic_field = 1;
 		return process_symbols(event, arg, tok);
 	}
+	if (strcmp(token, "__print_hex") == 0) {
+		free_token(token);
+		return process_hex(event, arg, tok);
+	}
 	if (strcmp(token, "__get_str") == 0) {
 		free_token(token);
 		return process_str(event, arg, tok);
@@ -3038,6 +3085,7 @@ eval_num_arg(void *data, int size, struct event_format *event, struct print_arg
 		break;
 	case PRINT_FLAGS:
 	case PRINT_SYMBOL:
+	case PRINT_HEX:
 		break;
 	case PRINT_TYPE:
 		val = eval_num_arg(data, size, event, arg->typecast.item);
@@ -3261,8 +3309,9 @@ static void print_str_arg(struct trace_seq *s, void *data, int size,
 	unsigned long long val, fval;
 	unsigned long addr;
 	char *str;
+	unsigned char *hex;
 	int print;
-	int len;
+	int i, len;
 
 	switch (arg->type) {
 	case PRINT_NULL:
@@ -3327,6 +3376,23 @@ static void print_str_arg(struct trace_seq *s, void *data, int size,
 			}
 		}
 		break;
+	case PRINT_HEX:
+		field = arg->hex.field->field.field;
+		if (!field) {
+			str = arg->hex.field->field.name;
+			field = pevent_find_any_field(event, str);
+			if (!field)
+				die("field %s not found", str);
+			arg->hex.field->field.field = field;
+		}
+		hex = data + field->offset;
+		len = eval_num_arg(data, size, event, arg->hex.size);
+		for (i = 0; i < len; i++) {
+			if (i)
+				trace_seq_putc(s, ' ');
+			trace_seq_printf(s, "%02x", hex[i]);
+		}
+		break;
 
 	case PRINT_TYPE:
 		break;
@@ -4376,6 +4442,13 @@ static void print_args(struct print_arg *args)
 		trace_seq_destroy(&s);
 		printf(")");
 		break;
+	case PRINT_HEX:
+		printf("__print_hex(");
+		print_args(args->hex.field);
+		printf(", ");
+		print_args(args->hex.size);
+		printf(")");
+		break;
 	case PRINT_STRING:
 	case PRINT_BSTRING:
 		printf("__get_str(%s)", args->string.string);
diff --git a/tools/lib/traceevent/event-parse.h b/tools/lib/traceevent/event-parse.h
index a8121d78a046..527df038a25f 100644
--- a/tools/lib/traceevent/event-parse.h
+++ b/tools/lib/traceevent/event-parse.h
@@ -226,6 +226,11 @@ struct print_arg_symbol {
 	struct print_flag_sym	*symbols;
 };
 
+struct print_arg_hex {
+	struct print_arg	*field;
+	struct print_arg	*size;
+};
+
 struct print_arg_dynarray {
 	struct format_field	*field;
 	struct print_arg	*index;
@@ -253,6 +258,7 @@ enum print_arg_type {
 	PRINT_FIELD,
 	PRINT_FLAGS,
 	PRINT_SYMBOL,
+	PRINT_HEX,
 	PRINT_TYPE,
 	PRINT_STRING,
 	PRINT_BSTRING,
@@ -270,6 +276,7 @@ struct print_arg {
 		struct print_arg_typecast	typecast;
 		struct print_arg_flags		flags;
 		struct print_arg_symbol		symbol;
+		struct print_arg_hex		hex;
 		struct print_arg_func		func;
 		struct print_arg_string		string;
 		struct print_arg_op		op;
diff --git a/tools/perf/util/scripting-engines/trace-event-perl.c b/tools/perf/util/scripting-engines/trace-event-perl.c
index 4c1b3d72a1d2..a579495d35b5 100644
--- a/tools/perf/util/scripting-engines/trace-event-perl.c
+++ b/tools/perf/util/scripting-engines/trace-event-perl.c
@@ -209,6 +209,10 @@ static void define_event_symbols(struct event_format *event,
 		define_symbolic_values(args->symbol.symbols, ev_name,
 				       cur_field_name);
 		break;
+	case PRINT_HEX:
+		define_event_symbols(event, ev_name, args->hex.field);
+		define_event_symbols(event, ev_name, args->hex.size);
+		break;
 	case PRINT_BSTRING:
 	case PRINT_DYNAMIC_ARRAY:
 	case PRINT_STRING:
diff --git a/tools/perf/util/scripting-engines/trace-event-python.c b/tools/perf/util/scripting-engines/trace-event-python.c
index acb9795286c4..f5c3485640ad 100644
--- a/tools/perf/util/scripting-engines/trace-event-python.c
+++ b/tools/perf/util/scripting-engines/trace-event-python.c
@@ -166,6 +166,10 @@ static void define_event_symbols(struct event_format *event,
 		define_values(PRINT_SYMBOL, args->symbol.symbols, ev_name,
 			      cur_field_name);
 		break;
+	case PRINT_HEX:
+		define_event_symbols(event, ev_name, args->hex.field);
+		define_event_symbols(event, ev_name, args->hex.size);
+		break;
 	case PRINT_STRING:
 		break;
 	case PRINT_TYPE:
-- 
1.7.10.2

Re: [PATCH 2/4] KVM: Use __print_hex() for kvm_emulate_insn tracepoint

[Steven Rostedt]

[ Added Avi]

On Wed, 2012-06-27 at 09:41 +0900, Namhyung Kim wrote:
> From: Namhyung Kim <namhyung.kim@lge.com>
> 
> The kvm_emulate_insn tracepoint used __print_insn()
> for printing its instructions. However it makes the
> format of the event hard to parse as it reveals TP
> internals.
> 
> Fortunately, kernel provides __print_hex for almost
> same purpose, we can use it instead of open coding
> it. The user-space can be changed to parse it later.
> 
> That means raw kernel tracing will not be affected
> by this change:
> 
>  # cd /sys/kernel/debug/tracing/
>  # cat events/kvm/kvm_emulate_insn/format
>  name: kvm_emulate_insn
>  ID: 29
>  format:
> 	...
>  print fmt: "%x:%llx:%s (%s)%s", REC->csbase, REC->rip, __print_hex(REC->insn, REC->len), \
>  __print_symbolic(REC->flags, { 0, "real" }, { (1 << 0) | (1 << 1), "vm16" }, \
>  { (1 << 0), "prot16" }, { (1 << 0) | (1 << 2), "prot32" }, { (1 << 0) | (1 << 3), "prot64" }), \
>  REC->failed ? " failed" : ""
> 
>  # echo 1 > events/kvm/kvm_emulate_insn/enable
>  # cat trace
>  # tracer: nop
>  #
>  # entries-in-buffer/entries-written: 2183/2183   #P:12
>  #
>  #                              _-----=> irqs-off
>  #                             / _----=> need-resched
>  #                            | / _---=> hardirq/softirq
>  #                            || / _--=> preempt-depth
>  #                            ||| /     delay
>  #           TASK-PID   CPU#  ||||    TIMESTAMP  FUNCTION
>  #              | |       |   ||||       |         |
>          qemu-kvm-1782  [002] ...1   140.931636: kvm_emulate_insn: 0:c102fa25:89 10 (prot32)
>          qemu-kvm-1781  [004] ...1   140.931637: kvm_emulate_insn: 0:c102fa25:89 10 (prot32)

Avi, can you give your Acked-by for this change?

-- Steve

> 
> Cc: kvm@vger.kernel.org
> Link: http://lkml.kernel.org/n/tip-wfw6y3b9ugtey8snaow9nmg5@git.kernel.org
> Signed-off-by: Namhyung Kim <namhyung@kernel.org>
> ---
>  arch/x86/kvm/trace.h   |   12 +-----------
>  include/trace/ftrace.h |    1 +
>  2 files changed, 2 insertions(+), 11 deletions(-)
> 
> diff --git a/arch/x86/kvm/trace.h b/arch/x86/kvm/trace.h
> index 911d2641f14c..62d02e3c3ed6 100644
> --- a/arch/x86/kvm/trace.h
> +++ b/arch/x86/kvm/trace.h
> @@ -710,16 +710,6 @@ TRACE_EVENT(kvm_skinit,
>  		  __entry->rip, __entry->slb)
>  );
>  
> -#define __print_insn(insn, ilen) ({		                 \
> -	int i;							 \
> -	const char *ret = p->buffer + p->len;			 \
> -								 \
> -	for (i = 0; i < ilen; ++i)				 \
> -		trace_seq_printf(p, " %02x", insn[i]);		 \
> -	trace_seq_printf(p, "%c", 0);				 \
> -	ret;							 \
> -	})
> -
>  #define KVM_EMUL_INSN_F_CR0_PE (1 << 0)
>  #define KVM_EMUL_INSN_F_EFL_VM (1 << 1)
>  #define KVM_EMUL_INSN_F_CS_D   (1 << 2)
> @@ -786,7 +776,7 @@ TRACE_EVENT(kvm_emulate_insn,
>  
>  	TP_printk("%x:%llx:%s (%s)%s",
>  		  __entry->csbase, __entry->rip,
> -		  __print_insn(__entry->insn, __entry->len),
> +		  __print_hex(__entry->insn, __entry->len),
>  		  __print_symbolic(__entry->flags,
>  				   kvm_trace_symbol_emul_flags),
>  		  __entry->failed ? " failed" : ""
> diff --git a/include/trace/ftrace.h b/include/trace/ftrace.h
> index 769724944fc6..c6bc2faaf261 100644
> --- a/include/trace/ftrace.h
> +++ b/include/trace/ftrace.h
> @@ -571,6 +571,7 @@ static inline void ftrace_test_probe_##call(void)			\
>  
>  #undef __print_flags
>  #undef __print_symbolic
> +#undef __print_hex
>  #undef __get_dynamic_array
>  #undef __get_str
>  

Re: [PATCH 2/4] KVM: Use __print_hex() for kvm_emulate_insn tracepoint

[Avi Kivity]

On 06/27/2012 03:49 PM, Steven Rostedt wrote:
> [ Added Avi]
> 
> On Wed, 2012-06-27 at 09:41 +0900, Namhyung Kim wrote:
>> From: Namhyung Kim <namhyung.kim@lge.com>
>> 
>> The kvm_emulate_insn tracepoint used __print_insn()
>> for printing its instructions. However it makes the
>> format of the event hard to parse as it reveals TP
>> internals.
>> 
>> Fortunately, kernel provides __print_hex for almost
>> same purpose, we can use it instead of open coding
>> it. The user-space can be changed to parse it later.
>> 
>> That means raw kernel tracing will not be affected
>> by this change:
>> 
>>  # cd /sys/kernel/debug/tracing/
>>  # cat events/kvm/kvm_emulate_insn/format
>>  name: kvm_emulate_insn
>>  ID: 29
>>  format:
>> 	...
>>  print fmt: "%x:%llx:%s (%s)%s", REC->csbase, REC->rip, __print_hex(REC->insn, REC->len), \
>>  __print_symbolic(REC->flags, { 0, "real" }, { (1 << 0) | (1 << 1), "vm16" }, \
>>  { (1 << 0), "prot16" }, { (1 << 0) | (1 << 2), "prot32" }, { (1 << 0) | (1 << 3), "prot64" }), \
>>  REC->failed ? " failed" : ""
>> 
>>  # echo 1 > events/kvm/kvm_emulate_insn/enable
>>  # cat trace
>>  # tracer: nop
>>  #
>>  # entries-in-buffer/entries-written: 2183/2183   #P:12
>>  #
>>  #                              _-----=> irqs-off
>>  #                             / _----=> need-resched
>>  #                            | / _---=> hardirq/softirq
>>  #                            || / _--=> preempt-depth
>>  #                            ||| /     delay
>>  #           TASK-PID   CPU#  ||||    TIMESTAMP  FUNCTION
>>  #              | |       |   ||||       |         |
>>          qemu-kvm-1782  [002] ...1   140.931636: kvm_emulate_insn: 0:c102fa25:89 10 (prot32)
>>          qemu-kvm-1781  [004] ...1   140.931637: kvm_emulate_insn: 0:c102fa25:89 10 (prot32)
> 
> Avi, can you give your Acked-by for this change?

Acked-by: Avi Kivity <avi@redhat.com>

Some time ago we discussed moving the trace-cmd plugins to /lib/modules,
which would make this trace display as "mov %edx,(%eax)" instead of "89
10", even for non-trace-cmd users.  Was there any movement on this?

-- 
error compiling committee.c: too many arguments to function

Re: [PATCH 2/4] KVM: Use __print_hex() for kvm_emulate_insn tracepoint

[Steven Rostedt]

On Wed, 2012-06-27 at 15:54 +0300, Avi Kivity wrote:

> Acked-by: Avi Kivity <avi@redhat.com>

Thanks Avi!

> 
> Some time ago we discussed moving the trace-cmd plugins to /lib/modules,
> which would make this trace display as "mov %edx,(%eax)" instead of "89
> 10", even for non-trace-cmd users.  Was there any movement on this?
> 

As a matter of fact ;-)  The trace-cmd libparsevent library has now been
moved to tools/lib/libtraceevent, in which perf now uses. It is just a
matter of time till perf gets the use of the trace-cmd plugins. We just
need to figure out the logistics.

Maybe make a tools/event_plugins ?

Or something to that affect?

-- Steve

Re: [PATCH 2/4] KVM: Use __print_hex() for kvm_emulate_insn tracepoint

[Namhyung Kim]

[CC'ing David]

Hi, Steve

On Wed, 27 Jun 2012 09:20:24 -0400, Steven Rostedt wrote:
> On Wed, 2012-06-27 at 15:54 +0300, Avi Kivity wrote:
>
>> Acked-by: Avi Kivity <avi@redhat.com>
>
> Thanks Avi!
>

Can you give me your ack's too (for this and other ones in the series)?
And if you ok, I can route this and future changes (from anybody) on
libtraceevent through my tree.


>> 
>> Some time ago we discussed moving the trace-cmd plugins to /lib/modules,
>> which would make this trace display as "mov %edx,(%eax)" instead of "89
>> 10", even for non-trace-cmd users.  Was there any movement on this?
>> 
>
> As a matter of fact ;-)  The trace-cmd libparsevent library has now been
> moved to tools/lib/libtraceevent, in which perf now uses. It is just a
> matter of time till perf gets the use of the trace-cmd plugins. We just
> need to figure out the logistics.
>
> Maybe make a tools/event_plugins ?
>
> Or something to that affect?
>

tools/lib/traceevent/plugins ?

Thanks,
Namhyung

Re: [PATCH 2/4] KVM: Use __print_hex() for kvm_emulate_insn tracepoint

[Steven Rostedt]

On Thu, 2012-06-28 at 10:16 +0900, Namhyung Kim wrote:
> [CC'ing David]
> 
> Hi, Steve
> 
> On Wed, 27 Jun 2012 09:20:24 -0400, Steven Rostedt wrote:
> > On Wed, 2012-06-27 at 15:54 +0300, Avi Kivity wrote:
> >
> >> Acked-by: Avi Kivity <avi@redhat.com>
> >
> > Thanks Avi!
> >
> 
> Can you give me your ack's too (for this and other ones in the series)?
> And if you ok, I can route this and future changes (from anybody) on
> libtraceevent through my tree.
> 

Actually, as this patch touches x86 and ftrace, and does not truly
affect the tools directory, I've already added it into my queue for 3.6.

-- Steve

Re: [PATCH 2/4] KVM: Use __print_hex() for kvm_emulate_insn tracepoint

[Namhyung Kim]

On Wed, 27 Jun 2012 21:52:44 -0400, Steven Rostedt wrote:
> On Thu, 2012-06-28 at 10:16 +0900, Namhyung Kim wrote:
>> [CC'ing David]
>> 
>> Hi, Steve
>> 
>> On Wed, 27 Jun 2012 09:20:24 -0400, Steven Rostedt wrote:
>> > On Wed, 2012-06-27 at 15:54 +0300, Avi Kivity wrote:
>> >
>> >> Acked-by: Avi Kivity <avi@redhat.com>
>> >
>> > Thanks Avi!
>> >
>> 
>> Can you give me your ack's too (for this and other ones in the series)?
>> And if you ok, I can route this and future changes (from anybody) on
>> libtraceevent through my tree.
>> 
>
> Actually, as this patch touches x86 and ftrace, and does not truly
> affect the tools directory, I've already added it into my queue for 3.6.
>

Ok, thanks. But how about other ones? Did you add all of 4 into you
queue?

Thanks,
Namhyung

Re: [PATCH 2/4] KVM: Use __print_hex() for kvm_emulate_insn tracepoint

[Steven Rostedt]

On Thu, 2012-06-28 at 10:59 +0900, Namhyung Kim wrote:

> Ok, thanks. But how about other ones? Did you add all of 4 into you
> queue?

Ah, no I didn't. I actually would like Arnaldo to do that.

Arnaldo,

Can you pull patches 1,3 & 4 into your repo, and add my:

Acked-by: Steven Rostedt <rostedt@goodmis.org>

Thanks!

-- Steve

Re: [PATCH 3/4] tools lib traceevent: Use local variable 'field'

[Arnaldo Carvalho de Melo]

Em Wed, Jun 27, 2012 at 09:41:40AM +0900, Namhyung Kim escreveu:
> From: Namhyung Kim <namhyung.kim@lge.com>
> 
> Use local variable 'field' to reduce typing. It is needed
> by later patch not to exceed 80 column.

Thanks, applied to perf/core.

- Arnaldo

Re: [PATCH 4/4] tools lib traceevent: Add support for __print_hex()

[Arnaldo Carvalho de Melo]

Em Wed, Jun 27, 2012 at 09:41:41AM +0900, Namhyung Kim escreveu:
> From: Namhyung Kim <namhyung.kim@lge.com>
> 
> Since the __print_hex() function is used in print fmt now,
> add corresponding parser routines. This makes the output of
> perf script on the kvm_emulate_insn event not to fail any more.

Thanks, applied to perf/core.

- Arnaldo

[tip:perf/core] tracing/kvm: Use __print_hex() for kvm_emulate_insn tracepoint

[tip-bot for Namhyung Kim]

Commit-ID:  b102f1d0f1cd0bb5ec82e5aeb1e33502d6ad6710
Gitweb:     http://git.kernel.org/tip/b102f1d0f1cd0bb5ec82e5aeb1e33502d6ad6710
Author:     Namhyung Kim <namhyung.kim@lge.com>
AuthorDate: Wed, 27 Jun 2012 09:41:39 +0900
Committer:  Steven Rostedt <rostedt@goodmis.org>
CommitDate: Thu, 28 Jun 2012 13:52:15 -0400

tracing/kvm: Use __print_hex() for kvm_emulate_insn tracepoint

The kvm_emulate_insn tracepoint used __print_insn()
for printing its instructions. However it makes the
format of the event hard to parse as it reveals TP
internals.

Fortunately, kernel provides __print_hex for almost
same purpose, we can use it instead of open coding
it. The user-space can be changed to parse it later.

That means raw kernel tracing will not be affected
by this change:

 # cd /sys/kernel/debug/tracing/
 # cat events/kvm/kvm_emulate_insn/format
 name: kvm_emulate_insn
 ID: 29
 format:
	...
 print fmt: "%x:%llx:%s (%s)%s", REC->csbase, REC->rip, __print_hex(REC->insn, REC->len), \
 __print_symbolic(REC->flags, { 0, "real" }, { (1 << 0) | (1 << 1), "vm16" }, \
 { (1 << 0), "prot16" }, { (1 << 0) | (1 << 2), "prot32" }, { (1 << 0) | (1 << 3), "prot64" }), \
 REC->failed ? " failed" : ""

 # echo 1 > events/kvm/kvm_emulate_insn/enable
 # cat trace
 # tracer: nop
 #
 # entries-in-buffer/entries-written: 2183/2183   #P:12
 #
 #                              _-----=> irqs-off
 #                             / _----=> need-resched
 #                            | / _---=> hardirq/softirq
 #                            || / _--=> preempt-depth
 #                            ||| /     delay
 #           TASK-PID   CPU#  ||||    TIMESTAMP  FUNCTION
 #              | |       |   ||||       |         |
         qemu-kvm-1782  [002] ...1   140.931636: kvm_emulate_insn: 0:c102fa25:89 10 (prot32)
         qemu-kvm-1781  [004] ...1   140.931637: kvm_emulate_insn: 0:c102fa25:89 10 (prot32)

Link: http://lkml.kernel.org/n/tip-wfw6y3b9ugtey8snaow9nmg5@git.kernel.org
Link: http://lkml.kernel.org/r/1340757701-10711-2-git-send-email-namhyung@kernel.org

Cc: Arnaldo Carvalho de Melo <acme@ghostprotocols.net>
Cc: Frederic Weisbecker <fweisbec@gmail.com>
Cc: Peter Zijlstra <a.p.zijlstra@chello.nl>
Cc: Ingo Molnar <mingo@kernel.org>
Cc: Namhyung Kim <namhyung.kim@lge.com>
Cc: kvm@vger.kernel.org
Acked-by: Avi Kivity <avi@redhat.com>
Signed-off-by: Namhyung Kim <namhyung@kernel.org>
Signed-off-by: Steven Rostedt <rostedt@goodmis.org>
---
 arch/x86/kvm/trace.h   |   12 +-----------
 include/trace/ftrace.h |    1 +
 2 files changed, 2 insertions(+), 11 deletions(-)

diff --git a/arch/x86/kvm/trace.h b/arch/x86/kvm/trace.h
index 911d264..62d02e3 100644
--- a/arch/x86/kvm/trace.h
+++ b/arch/x86/kvm/trace.h
@@ -710,16 +710,6 @@ TRACE_EVENT(kvm_skinit,
 		  __entry->rip, __entry->slb)
 );
 
-#define __print_insn(insn, ilen) ({		                 \
-	int i;							 \
-	const char *ret = p->buffer + p->len;			 \
-								 \
-	for (i = 0; i < ilen; ++i)				 \
-		trace_seq_printf(p, " %02x", insn[i]);		 \
-	trace_seq_printf(p, "%c", 0);				 \
-	ret;							 \
-	})
-
 #define KVM_EMUL_INSN_F_CR0_PE (1 << 0)
 #define KVM_EMUL_INSN_F_EFL_VM (1 << 1)
 #define KVM_EMUL_INSN_F_CS_D   (1 << 2)
@@ -786,7 +776,7 @@ TRACE_EVENT(kvm_emulate_insn,
 
 	TP_printk("%x:%llx:%s (%s)%s",
 		  __entry->csbase, __entry->rip,
-		  __print_insn(__entry->insn, __entry->len),
+		  __print_hex(__entry->insn, __entry->len),
 		  __print_symbolic(__entry->flags,
 				   kvm_trace_symbol_emul_flags),
 		  __entry->failed ? " failed" : ""
diff --git a/include/trace/ftrace.h b/include/trace/ftrace.h
index 7697249..c6bc2fa 100644
--- a/include/trace/ftrace.h
+++ b/include/trace/ftrace.h
@@ -571,6 +571,7 @@ static inline void ftrace_test_probe_##call(void)			\
 
 #undef __print_flags
 #undef __print_symbolic
+#undef __print_hex
 #undef __get_dynamic_array
 #undef __get_str
 

[tip:perf/core] tools lib traceevent: Use local variable 'field'

[tip-bot for Namhyung Kim]

Commit-ID:  b700807196ac8d87e00fed9fda80ab89b7f56db6
Gitweb:     http://git.kernel.org/tip/b700807196ac8d87e00fed9fda80ab89b7f56db6
Author:     Namhyung Kim <namhyung.kim@lge.com>
AuthorDate: Wed, 27 Jun 2012 09:41:40 +0900
Committer:  Arnaldo Carvalho de Melo <acme@redhat.com>
CommitDate: Fri, 29 Jun 2012 13:28:12 -0300

tools lib traceevent: Use local variable 'field'

Use local variable 'field' to reduce typing. It is needed by later patch
not to exceed 80 column.

Signed-off-by: Namhyung Kim <namhyung@kernel.org>
Cc: Frederic Weisbecker <fweisbec@gmail.com>
Cc: Ingo Molnar <mingo@kernel.org>
Cc: Peter Zijlstra <a.p.zijlstra@chello.nl>
Cc: Steven Rostedt <rostedt@goodmis.org>
Link: http://lkml.kernel.org/r/1340757701-10711-3-git-send-email-namhyung@kernel.org
Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
---
 tools/lib/traceevent/event-parse.c |   19 +++++++++++--------
 1 files changed, 11 insertions(+), 8 deletions(-)

diff --git a/tools/lib/traceevent/event-parse.c b/tools/lib/traceevent/event-parse.c
index b203a50..63d02be 100644
--- a/tools/lib/traceevent/event-parse.c
+++ b/tools/lib/traceevent/event-parse.c
@@ -3214,6 +3214,7 @@ static void print_str_arg(struct trace_seq *s, void *data, int size,
 {
 	struct pevent *pevent = event->pevent;
 	struct print_flag_sym *flag;
+	struct format_field *field;
 	unsigned long long val, fval;
 	unsigned long addr;
 	char *str;
@@ -3228,27 +3229,29 @@ static void print_str_arg(struct trace_seq *s, void *data, int size,
 		print_str_to_seq(s, format, len_arg, arg->atom.atom);
 		return;
 	case PRINT_FIELD:
-		if (!arg->field.field) {
-			arg->field.field = pevent_find_any_field(event, arg->field.name);
-			if (!arg->field.field)
+		field = arg->field.field;
+		if (!field) {
+			field = pevent_find_any_field(event, arg->field.name);
+			if (!field)
 				die("field %s not found", arg->field.name);
+			arg->field.field = field;
 		}
 		/* Zero sized fields, mean the rest of the data */
-		len = arg->field.field->size ? : size - arg->field.field->offset;
+		len = field->size ? : size - field->offset;
 
 		/*
 		 * Some events pass in pointers. If this is not an array
 		 * and the size is the same as long_size, assume that it
 		 * is a pointer.
 		 */
-		if (!(arg->field.field->flags & FIELD_IS_ARRAY) &&
-		    arg->field.field->size == pevent->long_size) {
-			addr = *(unsigned long *)(data + arg->field.field->offset);
+		if (!(field->flags & FIELD_IS_ARRAY) &&
+		    field->size == pevent->long_size) {
+			addr = *(unsigned long *)(data + field->offset);
 			trace_seq_printf(s, "%lx", addr);
 			break;
 		}
 		str = malloc_or_die(len + 1);
-		memcpy(str, data + arg->field.field->offset, len);
+		memcpy(str, data + field->offset, len);
 		str[len] = 0;
 		print_str_to_seq(s, format, len_arg, str);
 		free(str);

[tip:perf/core] tools lib traceevent: Add support for __print_hex( )

[tip-bot for Namhyung Kim]

Commit-ID:  e080e6f1c863242ff709046d0486d09c46dc484a
Gitweb:     http://git.kernel.org/tip/e080e6f1c863242ff709046d0486d09c46dc484a
Author:     Namhyung Kim <namhyung.kim@lge.com>
AuthorDate: Wed, 27 Jun 2012 09:41:41 +0900
Committer:  Arnaldo Carvalho de Melo <acme@redhat.com>
CommitDate: Fri, 29 Jun 2012 13:28:12 -0300

tools lib traceevent: Add support for __print_hex()

Since the __print_hex() function is used in print fmt now, add
corresponding parser routines. This makes the output of perf script on
the kvm_emulate_insn event not to fail any more.

 before:
      kvm_emulate_insn:     [FAILED TO PARSE] rip=3238197797 ...

 after:
      kvm_emulate_insn:     0:c102fa25:89 10 (prot32)

Signed-off-by: Namhyung Kim <namhyung@kernel.org>
Cc: Frederic Weisbecker <fweisbec@gmail.com>
Cc: Ingo Molnar <mingo@kernel.org>
Cc: Peter Zijlstra <a.p.zijlstra@chello.nl>
Cc: Steven Rostedt <rostedt@goodmis.org>
Link: http://lkml.kernel.org/r/1340757701-10711-4-git-send-email-namhyung@kernel.org
Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
---
 tools/lib/traceevent/event-parse.c                 |   75 +++++++++++++++++++-
 tools/lib/traceevent/event-parse.h                 |    7 ++
 .../perf/util/scripting-engines/trace-event-perl.c |    4 +
 .../util/scripting-engines/trace-event-python.c    |    4 +
 4 files changed, 89 insertions(+), 1 deletions(-)

diff --git a/tools/lib/traceevent/event-parse.c b/tools/lib/traceevent/event-parse.c
index 63d02be..b1abd39 100644
--- a/tools/lib/traceevent/event-parse.c
+++ b/tools/lib/traceevent/event-parse.c
@@ -697,6 +697,10 @@ static void free_arg(struct print_arg *arg)
 		free_arg(arg->symbol.field);
 		free_flag_sym(arg->symbol.symbols);
 		break;
+	case PRINT_HEX:
+		free_arg(arg->hex.field);
+		free_arg(arg->hex.size);
+		break;
 	case PRINT_TYPE:
 		free(arg->typecast.type);
 		free_arg(arg->typecast.item);
@@ -2260,6 +2264,45 @@ process_symbols(struct event_format *event, struct print_arg *arg, char **tok)
 }
 
 static enum event_type
+process_hex(struct event_format *event, struct print_arg *arg, char **tok)
+{
+	struct print_arg *field;
+	enum event_type type;
+	char *token;
+
+	memset(arg, 0, sizeof(*arg));
+	arg->type = PRINT_HEX;
+
+	field = alloc_arg();
+	type = process_arg(event, field, &token);
+
+	if (test_type_token(type, token, EVENT_DELIM, ","))
+		goto out_free;
+
+	arg->hex.field = field;
+
+	free_token(token);
+
+	field = alloc_arg();
+	type = process_arg(event, field, &token);
+
+	if (test_type_token(type, token, EVENT_DELIM, ")"))
+		goto out_free;
+
+	arg->hex.size = field;
+
+	free_token(token);
+	type = read_token_item(tok);
+	return type;
+
+ out_free:
+	free_arg(field);
+	free_token(token);
+	*tok = NULL;
+	return EVENT_ERROR;
+}
+
+static enum event_type
 process_dynamic_array(struct event_format *event, struct print_arg *arg, char **tok)
 {
 	struct format_field *field;
@@ -2488,6 +2531,10 @@ process_function(struct event_format *event, struct print_arg *arg,
 		is_symbolic_field = 1;
 		return process_symbols(event, arg, tok);
 	}
+	if (strcmp(token, "__print_hex") == 0) {
+		free_token(token);
+		return process_hex(event, arg, tok);
+	}
 	if (strcmp(token, "__get_str") == 0) {
 		free_token(token);
 		return process_str(event, arg, tok);
@@ -2995,6 +3042,7 @@ eval_num_arg(void *data, int size, struct event_format *event, struct print_arg
 		break;
 	case PRINT_FLAGS:
 	case PRINT_SYMBOL:
+	case PRINT_HEX:
 		break;
 	case PRINT_TYPE:
 		val = eval_num_arg(data, size, event, arg->typecast.item);
@@ -3218,8 +3266,9 @@ static void print_str_arg(struct trace_seq *s, void *data, int size,
 	unsigned long long val, fval;
 	unsigned long addr;
 	char *str;
+	unsigned char *hex;
 	int print;
-	int len;
+	int i, len;
 
 	switch (arg->type) {
 	case PRINT_NULL:
@@ -3284,6 +3333,23 @@ static void print_str_arg(struct trace_seq *s, void *data, int size,
 			}
 		}
 		break;
+	case PRINT_HEX:
+		field = arg->hex.field->field.field;
+		if (!field) {
+			str = arg->hex.field->field.name;
+			field = pevent_find_any_field(event, str);
+			if (!field)
+				die("field %s not found", str);
+			arg->hex.field->field.field = field;
+		}
+		hex = data + field->offset;
+		len = eval_num_arg(data, size, event, arg->hex.size);
+		for (i = 0; i < len; i++) {
+			if (i)
+				trace_seq_putc(s, ' ');
+			trace_seq_printf(s, "%02x", hex[i]);
+		}
+		break;
 
 	case PRINT_TYPE:
 		break;
@@ -4294,6 +4360,13 @@ static void print_args(struct print_arg *args)
 		trace_seq_destroy(&s);
 		printf(")");
 		break;
+	case PRINT_HEX:
+		printf("__print_hex(");
+		print_args(args->hex.field);
+		printf(", ");
+		print_args(args->hex.size);
+		printf(")");
+		break;
 	case PRINT_STRING:
 	case PRINT_BSTRING:
 		printf("__get_str(%s)", args->string.string);
diff --git a/tools/lib/traceevent/event-parse.h b/tools/lib/traceevent/event-parse.h
index ac997bc..5772ad8 100644
--- a/tools/lib/traceevent/event-parse.h
+++ b/tools/lib/traceevent/event-parse.h
@@ -226,6 +226,11 @@ struct print_arg_symbol {
 	struct print_flag_sym	*symbols;
 };
 
+struct print_arg_hex {
+	struct print_arg	*field;
+	struct print_arg	*size;
+};
+
 struct print_arg_dynarray {
 	struct format_field	*field;
 	struct print_arg	*index;
@@ -253,6 +258,7 @@ enum print_arg_type {
 	PRINT_FIELD,
 	PRINT_FLAGS,
 	PRINT_SYMBOL,
+	PRINT_HEX,
 	PRINT_TYPE,
 	PRINT_STRING,
 	PRINT_BSTRING,
@@ -270,6 +276,7 @@ struct print_arg {
 		struct print_arg_typecast	typecast;
 		struct print_arg_flags		flags;
 		struct print_arg_symbol		symbol;
+		struct print_arg_hex		hex;
 		struct print_arg_func		func;
 		struct print_arg_string		string;
 		struct print_arg_op		op;
diff --git a/tools/perf/util/scripting-engines/trace-event-perl.c b/tools/perf/util/scripting-engines/trace-event-perl.c
index b3620fe..02dfa19 100644
--- a/tools/perf/util/scripting-engines/trace-event-perl.c
+++ b/tools/perf/util/scripting-engines/trace-event-perl.c
@@ -209,6 +209,10 @@ static void define_event_symbols(struct event_format *event,
 		define_symbolic_values(args->symbol.symbols, ev_name,
 				       cur_field_name);
 		break;
+	case PRINT_HEX:
+		define_event_symbols(event, ev_name, args->hex.field);
+		define_event_symbols(event, ev_name, args->hex.size);
+		break;
 	case PRINT_BSTRING:
 	case PRINT_DYNAMIC_ARRAY:
 	case PRINT_STRING:
diff --git a/tools/perf/util/scripting-engines/trace-event-python.c b/tools/perf/util/scripting-engines/trace-event-python.c
index a8ca2f8..ce4d1b0 100644
--- a/tools/perf/util/scripting-engines/trace-event-python.c
+++ b/tools/perf/util/scripting-engines/trace-event-python.c
@@ -166,6 +166,10 @@ static void define_event_symbols(struct event_format *event,
 		define_values(PRINT_SYMBOL, args->symbol.symbols, ev_name,
 			      cur_field_name);
 		break;
+	case PRINT_HEX:
+		define_event_symbols(event, ev_name, args->hex.field);
+		define_event_symbols(event, ev_name, args->hex.size);
+		break;
 	case PRINT_STRING:
 		break;
 	case PRINT_TYPE: