[PATCH v5 0/5] libtraceevent: Optimize the print of tep fields

[PATCH v5 0/5] libtraceevent: Optimize the print of tep fields

[Yordan Karadzhov (VMware)]

Provide new capabilities for printing the content of the individual
fields of the event.

Changes in v5:
 - The loop over the tokens in _tep_print_field() is made circular
 in order to support the corner case when the fields and the tokens
 are listed in different order.
 - _tep_print_field() and print_selected_fields() are made "inline"
 in order to help the compiler to optimize out the unused variables
 (suggested by Steven).

Changes in v4:
 - Directly applying the modification in tep_print_field() suggested
 by Steven.
 - Optimizing the loop over the tokens in tep_print_fields().

Steven Rostedt (1):
  libtraceevent: Have all field args point to the field they represent

Yordan Karadzhov (VMware) (4):
  libtraceevent: Add dynamic_offset()
  libtraceevent: Improve tep_print_field()
  libtraceevent: Optimize tep_print_fields()
  libtraceevent: Add tep_print_selected_fields()

 src/event-parse.c | 297 +++++++++++++++++++++++++++++-----------------
 src/event-parse.h |   3 +
 2 files changed, 194 insertions(+), 106 deletions(-)

-- 
2.30.2

[PATCH v5 1/5] libtraceevent: Add dynamic_offset()

[Yordan Karadzhov (VMware)]

The total allocated length of the dynamic array is stored in the top half
of the corresponding 32 bit field and the offset is in the bottom half of
the same field. Since the decoding of the length and offset is performed
in multiple locations is the code, we define a static helper function to
replace/cleanup the existing open coded conversions.

Suggested-by: Steven Rostedt <rostedt@goodmis.org>
Signed-off-by: Yordan Karadzhov (VMware) <y.karadz@gmail.com>
---
 src/event-parse.c | 134 ++++++++++++++++++++++------------------------
 1 file changed, 63 insertions(+), 71 deletions(-)

diff --git a/src/event-parse.c b/src/event-parse.c
index f42ae38..fd6d916 100644
--- a/src/event-parse.c
+++ b/src/event-parse.c
@@ -3858,6 +3858,36 @@ static unsigned long long test_for_symbol(struct tep_handle *tep,
 	return val;
 }
 
+#define TEP_OFFSET_LEN_MASK		0xffff
+#define TEP_LEN_SHIFT			16
+
+static void dynamic_offset(struct tep_handle *tep, int size, void *data,
+			   unsigned int *offset, unsigned int *len)
+{
+	unsigned long long val;
+
+	/*
+	 * The total allocated length of the dynamic array is
+	 * stored in the top half of the field and the offset
+	 * is in the bottom half of the 32 bit field.
+	 */
+	val = tep_read_number(tep, data, size);
+
+	if (offset)
+		*offset = (unsigned int)(val & TEP_OFFSET_LEN_MASK);
+	if (len)
+		*len = (unsigned int)((val >> TEP_LEN_SHIFT) & TEP_OFFSET_LEN_MASK);
+}
+
+static inline void dynamic_offset_field(struct tep_handle *tep,
+					struct tep_format_field *field,
+					void *data,
+					unsigned int *offset,
+					unsigned int *len)
+{
+	dynamic_offset(tep, field->size, data + field->offset, offset, len);
+}
+
 static unsigned long long
 eval_num_arg(void *data, int size, struct tep_event *event, struct tep_print_arg *arg)
 {
@@ -3866,7 +3896,7 @@ eval_num_arg(void *data, int size, struct tep_event *event, struct tep_print_arg
 	unsigned long long left, right;
 	struct tep_print_arg *typearg = NULL;
 	struct tep_print_arg *larg;
-	unsigned long offset;
+	unsigned int offset;
 	unsigned int field_size;
 
 	switch (arg->type) {
@@ -3930,18 +3960,11 @@ eval_num_arg(void *data, int size, struct tep_event *event, struct tep_print_arg
 
 			switch (larg->type) {
 			case TEP_PRINT_DYNAMIC_ARRAY:
-				offset = tep_read_number(tep,
-						   data + larg->dynarray.field->offset,
-						   larg->dynarray.field->size);
+				dynamic_offset_field(tep, larg->dynarray.field, data,
+						     &offset, NULL);
+				offset += right;
 				if (larg->dynarray.field->elementsize)
 					field_size = larg->dynarray.field->elementsize;
-				/*
-				 * The actual length of the dynamic array is stored
-				 * in the top half of the field, and the offset
-				 * is in the bottom half of the 32 bit field.
-				 */
-				offset &= 0xffff;
-				offset += right;
 				break;
 			case TEP_PRINT_FIELD:
 				if (!larg->field.field) {
@@ -4060,27 +4083,14 @@ eval_num_arg(void *data, int size, struct tep_event *event, struct tep_print_arg
 		}
 		break;
 	case TEP_PRINT_DYNAMIC_ARRAY_LEN:
-		offset = tep_read_number(tep,
-					 data + arg->dynarray.field->offset,
-					 arg->dynarray.field->size);
-		/*
-		 * The total allocated length of the dynamic array is
-		 * stored in the top half of the field, and the offset
-		 * is in the bottom half of the 32 bit field.
-		 */
-		val = (unsigned long long)(offset >> 16);
+		dynamic_offset_field(tep, arg->dynarray.field, data,
+				     NULL, &field_size);
+		val = (unsigned long long) field_size;
 		break;
 	case TEP_PRINT_DYNAMIC_ARRAY:
 		/* Without [], we pass the address to the dynamic data */
-		offset = tep_read_number(tep,
-					 data + arg->dynarray.field->offset,
-					 arg->dynarray.field->size);
-		/*
-		 * The total allocated length of the dynamic array is
-		 * stored in the top half of the field, and the offset
-		 * is in the bottom half of the 32 bit field.
-		 */
-		offset &= 0xffff;
+		dynamic_offset_field(tep, arg->dynarray.field, data,
+				     &offset, NULL);
 		val = (unsigned long long)((unsigned long)data + offset);
 		break;
 	default: /* not sure what to do there */
@@ -4209,12 +4219,13 @@ static void print_str_arg(struct trace_seq *s, void *data, int size,
 	struct tep_print_flag_sym *flag;
 	struct tep_format_field *field;
 	struct printk_map *printk;
+	unsigned int offset, len;
 	long long val, fval;
 	unsigned long long addr;
 	char *str;
 	unsigned char *hex;
 	int print;
-	int i, len;
+	int i;
 
 	switch (arg->type) {
 	case TEP_PRINT_NULL:
@@ -4318,11 +4329,9 @@ static void print_str_arg(struct trace_seq *s, void *data, int size,
 	case TEP_PRINT_HEX:
 	case TEP_PRINT_HEX_STR:
 		if (arg->hex.field->type == TEP_PRINT_DYNAMIC_ARRAY) {
-			unsigned long offset;
-			offset = tep_read_number(tep,
-				data + arg->hex.field->dynarray.field->offset,
-				arg->hex.field->dynarray.field->size);
-			hex = data + (offset & 0xffff);
+			dynamic_offset_field(tep, arg->hex.field->dynarray.field, data,
+				             &offset, NULL);
+			hex = data + offset;
 		} else {
 			field = arg->hex.field->field.field;
 			if (!field) {
@@ -4347,13 +4356,9 @@ static void print_str_arg(struct trace_seq *s, void *data, int size,
 		int el_size;
 
 		if (arg->int_array.field->type == TEP_PRINT_DYNAMIC_ARRAY) {
-			unsigned long offset;
-			struct tep_format_field *field =
-				arg->int_array.field->dynarray.field;
-			offset = tep_read_number(tep,
-						 data + field->offset,
-						 field->size);
-			num = data + (offset & 0xffff);
+			dynamic_offset_field(tep, arg->int_array.field->dynarray.field, data,
+					     &offset, NULL);
+			num = data + offset;
 		} else {
 			field = arg->int_array.field->field.field;
 			if (!field) {
@@ -4393,42 +4398,33 @@ static void print_str_arg(struct trace_seq *s, void *data, int size,
 	case TEP_PRINT_TYPE:
 		break;
 	case TEP_PRINT_STRING: {
-		int str_offset;
-		int len;
-
 		if (arg->string.offset == -1) {
 			struct tep_format_field *f;
 
 			f = tep_find_any_field(event, arg->string.string);
 			arg->string.offset = f->offset;
 		}
-		str_offset = data2host4(tep, *(unsigned int *)(data + arg->string.offset));
-		len = (str_offset >> 16) & 0xffff;
+		dynamic_offset(tep, 4, data + arg->string.offset, &offset, &len);
 		/* Do not attempt to save zero length dynamic strings */
 		if (!len)
 			break;
-		str_offset &= 0xffff;
-		print_str_to_seq(s, format, len_arg, ((char *)data) + str_offset);
+		offset &= TEP_OFFSET_LEN_MASK;
+		print_str_to_seq(s, format, len_arg, ((char *)data) + offset);
 		break;
 	}
 	case TEP_PRINT_BSTRING:
 		print_str_to_seq(s, format, len_arg, arg->string.string);
 		break;
 	case TEP_PRINT_BITMASK: {
-		int bitmask_offset;
-		int bitmask_size;
-
 		if (arg->bitmask.offset == -1) {
 			struct tep_format_field *f;
 
 			f = tep_find_any_field(event, arg->bitmask.bitmask);
 			arg->bitmask.offset = f->offset;
 		}
-		bitmask_offset = data2host4(tep, *(unsigned int *)(data + arg->bitmask.offset));
-		bitmask_size = bitmask_offset >> 16;
-		bitmask_offset &= 0xffff;
+		dynamic_offset(tep, 4, data + arg->bitmask.offset, &offset, &len);
 		print_bitmask_to_seq(tep, s, format, len_arg,
-				     data + bitmask_offset, bitmask_size);
+				     data + offset, len);
 		break;
 	}
 	case TEP_PRINT_OP:
@@ -5271,13 +5267,12 @@ static int print_raw_buff_arg(struct trace_seq *s, const char *ptr,
 			      void *data, int size, struct tep_event *event,
 			      struct tep_print_arg *arg, int print_len)
 {
+	unsigned int offset, arr_len;
 	int plen = print_len;
 	char *delim = " ";
 	int ret = 0;
 	char *buf;
 	int i;
-	unsigned long offset;
-	int arr_len;
 
 	switch (*(ptr + 1)) {
 	case 'C':
@@ -5304,11 +5299,9 @@ static int print_raw_buff_arg(struct trace_seq *s, const char *ptr,
 		return ret;
 	}
 
-	offset = tep_read_number(event->tep,
-				 data + arg->dynarray.field->offset,
-				 arg->dynarray.field->size);
-	arr_len = (unsigned long long)(offset >> 16);
-	buf = data + (offset & 0xffff);
+	dynamic_offset_field(event->tep, arg->dynarray.field, data,
+			     &offset, &arr_len);
+	buf = data + offset;
 
 	if (arr_len < plen)
 		plen = arr_len;
@@ -5336,19 +5329,18 @@ static int is_printable_array(char *p, unsigned int len)
 void tep_print_field(struct trace_seq *s, void *data,
 		     struct tep_format_field *field)
 {
-	unsigned long long val;
-	unsigned int offset, len, i;
 	struct tep_handle *tep = field->event->tep;
+	unsigned int offset, len, i;
+	unsigned long long val;
 
 	if (field->flags & TEP_FIELD_IS_ARRAY) {
-		offset = field->offset;
-		len = field->size;
 		if (field->flags & TEP_FIELD_IS_DYNAMIC) {
-			val = tep_read_number(tep, data + offset, len);
-			offset = val;
-			len = offset >> 16;
-			offset &= 0xffff;
+			dynamic_offset_field(tep, field, data, &offset, &len);
+		} else {
+			offset = field->offset;
+			len = field->size;
 		}
+
 		if (field->flags & TEP_FIELD_IS_STRING &&
 		    is_printable_array(data + offset, len)) {
 			trace_seq_printf(s, "%s", (char *)data + offset);
-- 
2.30.2

Re: [PATCH v5 1/5] libtraceevent: Add dynamic_offset()

[Steven Rostedt]

On Wed, 11 Aug 2021 15:11:59 +0300
"Yordan Karadzhov (VMware)" <y.karadz@gmail.com> wrote:


> @@ -4060,27 +4083,14 @@ eval_num_arg(void *data, int size, struct tep_event *event, struct tep_print_arg
>  		}
>  		break;
>  	case TEP_PRINT_DYNAMIC_ARRAY_LEN:
> -		offset = tep_read_number(tep,
> -					 data + arg->dynarray.field->offset,
> -					 arg->dynarray.field->size);
> -		/*
> -		 * The total allocated length of the dynamic array is
> -		 * stored in the top half of the field, and the offset
> -		 * is in the bottom half of the 32 bit field.
> -		 */
> -		val = (unsigned long long)(offset >> 16);
> +		dynamic_offset_field(tep, arg->dynarray.field, data,
> +				     NULL, &field_size);
> +		val = (unsigned long long) field_size;

The typecast is not needed: val = field_size; is good enough.

>  		break;
>  	case TEP_PRINT_DYNAMIC_ARRAY:
>  		/* Without [], we pass the address to the dynamic data */
> -		offset = tep_read_number(tep,
> -					 data + arg->dynarray.field->offset,
> -					 arg->dynarray.field->size);
> -		/*
> -		 * The total allocated length of the dynamic array is
> -		 * stored in the top half of the field, and the offset
> -		 * is in the bottom half of the 32 bit field.
> -		 */
> -		offset &= 0xffff;
> +		dynamic_offset_field(tep, arg->dynarray.field, data,
> +				     &offset, NULL);
>  		val = (unsigned long long)((unsigned long)data + offset);

Same here: val = (unsigned long)data + offset;

>  		break;
>  	default: /* not sure what to do there */
> @@ -4209,12 +4219,13 @@ static void print_str_arg(struct trace_seq *s, void *data, int size,
>  	struct tep_print_flag_sym *flag;
>  	struct tep_format_field *field;
>  	struct printk_map *printk;
> +	unsigned int offset, len;
>  	long long val, fval;
>  	unsigned long long addr;
>  	char *str;
>  	unsigned char *hex;
>  	int print;
> -	int i, len;
> +	int i;
>  
>  	switch (arg->type) {
>  	case TEP_PRINT_NULL:
> @@ -4318,11 +4329,9 @@ static void print_str_arg(struct trace_seq *s, void *data, int size,
>  	case TEP_PRINT_HEX:
>  	case TEP_PRINT_HEX_STR:
>  		if (arg->hex.field->type == TEP_PRINT_DYNAMIC_ARRAY) {
> -			unsigned long offset;
> -			offset = tep_read_number(tep,
> -				data + arg->hex.field->dynarray.field->offset,
> -				arg->hex.field->dynarray.field->size);
> -			hex = data + (offset & 0xffff);
> +			dynamic_offset_field(tep, arg->hex.field->dynarray.field, data,
> +				             &offset, NULL);

The above is a nice cleanup!

> +			hex = data + offset;
>  		} else {
>  			field = arg->hex.field->field.field;
>  			if (!field) {
> @@ -4347,13 +4356,9 @@ static void print_str_arg(struct trace_seq *s, void *data, int size,
>  		int el_size;
>  
>  		if (arg->int_array.field->type == TEP_PRINT_DYNAMIC_ARRAY) {
> -			unsigned long offset;
> -			struct tep_format_field *field =
> -				arg->int_array.field->dynarray.field;
> -			offset = tep_read_number(tep,
> -						 data + field->offset,
> -						 field->size);
> -			num = data + (offset & 0xffff);
> +			dynamic_offset_field(tep, arg->int_array.field->dynarray.field, data,
> +					     &offset, NULL);
> +			num = data + offset;
>  		} else {
>  			field = arg->int_array.field->field.field;
>  			if (!field) {
> @@ -4393,42 +4398,33 @@ static void print_str_arg(struct trace_seq *s, void *data, int size,
>  	case TEP_PRINT_TYPE:
>  		break;
>  	case TEP_PRINT_STRING: {
> -		int str_offset;
> -		int len;
> -
>  		if (arg->string.offset == -1) {
>  			struct tep_format_field *f;
>  
>  			f = tep_find_any_field(event, arg->string.string);
>  			arg->string.offset = f->offset;
>  		}
> -		str_offset = data2host4(tep, *(unsigned int *)(data + arg->string.offset));
> -		len = (str_offset >> 16) & 0xffff;
> +		dynamic_offset(tep, 4, data + arg->string.offset, &offset, &len);
>  		/* Do not attempt to save zero length dynamic strings */
>  		if (!len)
>  			break;
> -		str_offset &= 0xffff;
> -		print_str_to_seq(s, format, len_arg, ((char *)data) + str_offset);
> +		offset &= TEP_OFFSET_LEN_MASK;

Isn't the above redundant? Doesn't the dynamic_offset() do the masking?

> +		print_str_to_seq(s, format, len_arg, ((char *)data) + offset);
>  		break;
>  	}
>  	case TEP_PRINT_BSTRING:
>  		print_str_to_seq(s, format, len_arg, arg->string.string);
>  		break;
>  	case TEP_PRINT_BITMASK: {
> -		int bitmask_offset;
> -		int bitmask_size;
> -
>  		if (arg->bitmask.offset == -1) {
>  			struct tep_format_field *f;
>  
>  			f = tep_find_any_field(event, arg->bitmask.bitmask);
>  			arg->bitmask.offset = f->offset;
>  		}
> -		bitmask_offset = data2host4(tep, *(unsigned int *)(data + arg->bitmask.offset));
> -		bitmask_size = bitmask_offset >> 16;
> -		bitmask_offset &= 0xffff;
> +		dynamic_offset(tep, 4, data + arg->bitmask.offset, &offset, &len);
>  		print_bitmask_to_seq(tep, s, format, len_arg,
> -				     data + bitmask_offset, bitmask_size);
> +				     data + offset, len);
>  		break;
>  	}
>  	case TEP_PRINT_OP:
> @@ -5271,13 +5267,12 @@ static int print_raw_buff_arg(struct trace_seq *s, const char *ptr,
>  			      void *data, int size, struct tep_event *event,
>  			      struct tep_print_arg *arg, int print_len)
>  {
> +	unsigned int offset, arr_len;
>  	int plen = print_len;
>  	char *delim = " ";
>  	int ret = 0;
>  	char *buf;
>  	int i;
> -	unsigned long offset;
> -	int arr_len;
>  
>  	switch (*(ptr + 1)) {
>  	case 'C':
> @@ -5304,11 +5299,9 @@ static int print_raw_buff_arg(struct trace_seq *s, const char *ptr,
>  		return ret;
>  	}
>  
> -	offset = tep_read_number(event->tep,
> -				 data + arg->dynarray.field->offset,
> -				 arg->dynarray.field->size);
> -	arr_len = (unsigned long long)(offset >> 16);
> -	buf = data + (offset & 0xffff);
> +	dynamic_offset_field(event->tep, arg->dynarray.field, data,
> +			     &offset, &arr_len);
> +	buf = data + offset;
>  
>  	if (arr_len < plen)
>  		plen = arr_len;
> @@ -5336,19 +5329,18 @@ static int is_printable_array(char *p, unsigned int len)
>  void tep_print_field(struct trace_seq *s, void *data,
>  		     struct tep_format_field *field)
>  {
> -	unsigned long long val;
> -	unsigned int offset, len, i;
>  	struct tep_handle *tep = field->event->tep;
> +	unsigned int offset, len, i;
> +	unsigned long long val;
>  
>  	if (field->flags & TEP_FIELD_IS_ARRAY) {
> -		offset = field->offset;
> -		len = field->size;
>  		if (field->flags & TEP_FIELD_IS_DYNAMIC) {
> -			val = tep_read_number(tep, data + offset, len);
> -			offset = val;
> -			len = offset >> 16;
> -			offset &= 0xffff;
> +			dynamic_offset_field(tep, field, data, &offset, &len);
> +		} else {
> +			offset = field->offset;
> +			len = field->size;
>  		}
> +

No need to add this blank line. The rest of the function doesn't have
them, so I would keep it consistent and not add one.

But the rest looks good.

-- Steve


>  		if (field->flags & TEP_FIELD_IS_STRING &&
>  		    is_printable_array(data + offset, len)) {
>  			trace_seq_printf(s, "%s", (char *)data + offset);

[PATCH v5 2/5] libtraceevent: Have all field args point to the field they represent

[Yordan Karadzhov (VMware)]

From: Steven Rostedt <rostedt@goodmis.org>

In order to have tep_print_field() print the field closer to the way it
is printed via the "pretty_print" method, all field args, must keep a
pointer to the field it represents.

Signed-off-by: Steven Rostedt (VMware) <rostedt@goodmis.org>
---
 src/event-parse.c | 4 ++--
 1 file changed, 2 insertions(+), 2 deletions(-)

diff --git a/src/event-parse.c b/src/event-parse.c
index fd6d916..1a8cc54 100644
--- a/src/event-parse.c
+++ b/src/event-parse.c
@@ -2334,12 +2334,12 @@ process_entry(struct tep_event *event __maybe_unused, struct tep_print_arg *arg,
 	arg->type = TEP_PRINT_FIELD;
 	arg->field.name = field;
 
+	arg->field.field = tep_find_any_field(event, arg->field.name);
+
 	if (is_flag_field) {
-		arg->field.field = tep_find_any_field(event, arg->field.name);
 		arg->field.field->flags |= TEP_FIELD_IS_FLAG;
 		is_flag_field = 0;
 	} else if (is_symbolic_field) {
-		arg->field.field = tep_find_any_field(event, arg->field.name);
 		arg->field.field->flags |= TEP_FIELD_IS_SYMBOLIC;
 		is_symbolic_field = 0;
 	}
-- 
2.30.2

[PATCH v5 3/5] libtraceevent: Improve tep_print_field()

[Yordan Karadzhov (VMware)]

The existing method tep_print_fields() gets upgraded to use the
printing formats provided by the tokens.

Suggested-by: Steven Rostedt <rostedt@goodmis.org>
Signed-off-by: Yordan Karadzhov (VMware) <y.karadz@gmail.com>
---
 src/event-parse.c | 115 +++++++++++++++++++++++++++++++++++-----------
 1 file changed, 87 insertions(+), 28 deletions(-)

diff --git a/src/event-parse.c b/src/event-parse.c
index 1a8cc54..9399555 100644
--- a/src/event-parse.c
+++ b/src/event-parse.c
@@ -3913,7 +3913,6 @@ eval_num_arg(void *data, int size, struct tep_event *event, struct tep_print_arg
 			arg->field.field = tep_find_any_field(event, arg->field.name);
 			if (!arg->field.field)
 				goto out_warning_field;
-			
 		}
 		/* must be a number */
 		val = tep_read_number(tep, data + arg->field.field->offset,
@@ -5326,8 +5325,8 @@ static int is_printable_array(char *p, unsigned int len)
 	return 1;
 }
 
-void tep_print_field(struct trace_seq *s, void *data,
-		     struct tep_format_field *field)
+static void tep_print_field_raw(struct trace_seq *s, void *data,
+			     struct tep_format_field *field)
 {
 	struct tep_handle *tep = field->event->tep;
 	unsigned int offset, len, i;
@@ -5390,6 +5389,56 @@ void tep_print_field(struct trace_seq *s, void *data,
 	}
 }
 
+static int print_parse_data(struct tep_print_parse *parse, struct trace_seq *s,
+			    void *data, int size, struct tep_event *event);
+
+void tep_print_field(struct trace_seq *s, void *data,
+		     struct tep_format_field *field)
+{
+	struct tep_event *event = field->event;
+	struct tep_print_parse *parse;
+	bool has_0x;
+
+	parse = event->print_fmt.print_cache;
+
+	if (event->flags & TEP_EVENT_FL_FAILED)
+		goto out;
+
+	if (field->flags & (TEP_FIELD_IS_ARRAY || TEP_FIELD_IS_STRING))
+		goto out;
+
+	for (;parse; parse = parse->next) {
+		if (parse->type == PRINT_FMT_STRING) {
+			int len = strlen(parse->format);
+
+			if (len > 1 &&
+			    strcmp(parse->format + (len -2), "0x") == 0)
+				has_0x = true;
+			else
+				has_0x = false;
+
+			continue;
+		}
+
+		if (!parse->arg ||
+		    parse->arg->type != TEP_PRINT_FIELD ||
+		    parse->arg->field.field != field) {
+			has_0x = false;
+			continue;
+		}
+
+		if (has_0x)
+			trace_seq_puts(s, "0x");
+
+		print_parse_data(parse, s, data, field->size, event);
+		return;
+	}
+
+ out:
+	/* Not found. */
+	tep_print_field_raw(s, data, field);
+}
+
 void tep_print_fields(struct trace_seq *s, void *data,
 		      int size __maybe_unused, struct tep_event *event)
 {
@@ -5909,35 +5958,45 @@ parse_args(struct tep_event *event, const char *format, struct tep_print_arg *ar
 	return parse_ret;
 }
 
-static void print_event_cache(struct tep_print_parse *parse, struct trace_seq *s,
-			      void *data, int size, struct tep_event *event)
+static int print_parse_data(struct tep_print_parse *parse, struct trace_seq *s,
+			    void *data, int size, struct tep_event *event)
 {
 	int len_arg;
 
+	if (parse->len_as_arg)
+		len_arg = eval_num_arg(data, size, event, parse->len_as_arg);
+
+	switch (parse->type) {
+	case PRINT_FMT_ARG_DIGIT:
+		print_arg_number(s, parse->format,
+				 parse->len_as_arg ? len_arg : -1, data,
+				 size, parse->ls, event, parse->arg);
+		break;
+	case PRINT_FMT_ARG_POINTER:
+		print_arg_pointer(s, parse->format,
+				  parse->len_as_arg ? len_arg : 1,
+				  data, size, event, parse->arg);
+		break;
+	case PRINT_FMT_ARG_STRING:
+		print_arg_string(s, parse->format,
+				 parse->len_as_arg ? len_arg : -1,
+				 data, size, event, parse->arg);
+		break;
+	case PRINT_FMT_STRING:
+	default:
+		trace_seq_printf(s, "%s", parse->format);
+		/* Return 1 on non field. */
+		return 1;
+	}
+	/* Return 0 on field being processed. */
+	return 0;
+}
+
+static void print_event_cache(struct tep_print_parse *parse, struct trace_seq *s,
+			      void *data, int size, struct tep_event *event)
+{
 	while (parse) {
-		if (parse->len_as_arg)
-			len_arg = eval_num_arg(data, size, event, parse->len_as_arg);
-		switch (parse->type) {
-		case PRINT_FMT_ARG_DIGIT:
-			print_arg_number(s, parse->format,
-					parse->len_as_arg ? len_arg : -1, data,
-					 size, parse->ls, event, parse->arg);
-			break;
-		case PRINT_FMT_ARG_POINTER:
-			print_arg_pointer(s, parse->format,
-					  parse->len_as_arg ? len_arg : 1,
-					  data, size, event, parse->arg);
-			break;
-		case PRINT_FMT_ARG_STRING:
-			print_arg_string(s, parse->format,
-					 parse->len_as_arg ? len_arg : -1,
-					 data, size, event, parse->arg);
-			break;
-		case PRINT_FMT_STRING:
-		default:
-			trace_seq_printf(s, "%s", parse->format);
-			break;
-		}
+		print_parse_data(parse, s, data, size, event);
 		parse = parse->next;
 	}
 }
-- 
2.30.2

[PATCH v5 4/5] libtraceevent: Optimize tep_print_fields()

[Yordan Karadzhov (VMware)]

The current implementation of tep_print_fields() loops over all
individual fields of the event and calls tep_print_field() for
each one. In the same time inside tep_print_field() we loop over
the list of all tokens of the printing format descriptor in order
to determine how the current field must be printed (its own
appropriate printing format). The problem is that in this second
loop over the tokens we always start from the very first token
and this can be quite inefficient for example in a case of a
kprobe that has a large number of fields. This patch optimizes
tep_print_fields(), allowing the traverse of the list of tokens
to continue from the place reached when we searched for the
format of the previous field.

Signed-off-by: Yordan Karadzhov (VMware) <y.karadz@gmail.com>
---
 src/event-parse.c | 30 +++++++++++++++++++++++-------
 1 file changed, 23 insertions(+), 7 deletions(-)

diff --git a/src/event-parse.c b/src/event-parse.c
index 9399555..7831e74 100644
--- a/src/event-parse.c
+++ b/src/event-parse.c
@@ -5392,14 +5392,15 @@ static void tep_print_field_raw(struct trace_seq *s, void *data,
 static int print_parse_data(struct tep_print_parse *parse, struct trace_seq *s,
 			    void *data, int size, struct tep_event *event);
 
-void tep_print_field(struct trace_seq *s, void *data,
-		     struct tep_format_field *field)
+void static inline _tep_print_field(struct trace_seq *s, void *data,
+				    struct tep_format_field *field,
+				    struct tep_print_parse **parse_ptr)
 {
 	struct tep_event *event = field->event;
 	struct tep_print_parse *parse;
 	bool has_0x;
 
-	parse = event->print_fmt.print_cache;
+	parse = parse_ptr ? *parse_ptr : event->print_fmt.print_cache;
 
 	if (event->flags & TEP_EVENT_FL_FAILED)
 		goto out;
@@ -5407,7 +5408,7 @@ void tep_print_field(struct trace_seq *s, void *data,
 	if (field->flags & (TEP_FIELD_IS_ARRAY || TEP_FIELD_IS_STRING))
 		goto out;
 
-	for (;parse; parse = parse->next) {
+	while (parse) {
 		if (parse->type == PRINT_FMT_STRING) {
 			int len = strlen(parse->format);
 
@@ -5417,21 +5418,29 @@ void tep_print_field(struct trace_seq *s, void *data,
 			else
 				has_0x = false;
 
-			continue;
+			goto next;
 		}
 
 		if (!parse->arg ||
 		    parse->arg->type != TEP_PRINT_FIELD ||
 		    parse->arg->field.field != field) {
 			has_0x = false;
-			continue;
+			goto next;
 		}
 
 		if (has_0x)
 			trace_seq_puts(s, "0x");
 
 		print_parse_data(parse, s, data, field->size, event);
+
+		if (parse_ptr)
+			*parse_ptr = parse->next;
+
 		return;
+
+ next:
+		parse = parse->next ? parse->next :
+				      event->print_fmt.print_cache;
 	}
 
  out:
@@ -5439,15 +5448,22 @@ void tep_print_field(struct trace_seq *s, void *data,
 	tep_print_field_raw(s, data, field);
 }
 
+void tep_print_field(struct trace_seq *s, void *data,
+		     struct tep_format_field *field)
+{
+	_tep_print_field(s, data, field, NULL);
+}
+
 void tep_print_fields(struct trace_seq *s, void *data,
 		      int size __maybe_unused, struct tep_event *event)
 {
+	struct tep_print_parse *parse = event->print_fmt.print_cache;
 	struct tep_format_field *field;
 
 	field = event->format.fields;
 	while (field) {
 		trace_seq_printf(s, " %s=", field->name);
-		tep_print_field(s, data, field);
+		_tep_print_field(s, data, field, &parse);
 		field = field->next;
 	}
 }
-- 
2.30.2

Re: [PATCH v5 4/5] libtraceevent: Optimize tep_print_fields()

[Steven Rostedt]

On Wed, 11 Aug 2021 15:12:02 +0300
"Yordan Karadzhov (VMware)" <y.karadz@gmail.com> wrote:

> The current implementation of tep_print_fields() loops over all
> individual fields of the event and calls tep_print_field() for
> each one. In the same time inside tep_print_field() we loop over
> the list of all tokens of the printing format descriptor in order
> to determine how the current field must be printed (its own
> appropriate printing format). The problem is that in this second
> loop over the tokens we always start from the very first token
> and this can be quite inefficient for example in a case of a
> kprobe that has a large number of fields. This patch optimizes
> tep_print_fields(), allowing the traverse of the list of tokens
> to continue from the place reached when we searched for the
> format of the previous field.
> 
> Signed-off-by: Yordan Karadzhov (VMware) <y.karadz@gmail.com>
> ---
>  src/event-parse.c | 30 +++++++++++++++++++++++-------
>  1 file changed, 23 insertions(+), 7 deletions(-)
> 
> diff --git a/src/event-parse.c b/src/event-parse.c
> index 9399555..7831e74 100644
> --- a/src/event-parse.c
> +++ b/src/event-parse.c
> @@ -5392,14 +5392,15 @@ static void tep_print_field_raw(struct trace_seq *s, void *data,
>  static int print_parse_data(struct tep_print_parse *parse, struct trace_seq *s,
>  			    void *data, int size, struct tep_event *event);
>  
> -void tep_print_field(struct trace_seq *s, void *data,
> -		     struct tep_format_field *field)
> +void static inline _tep_print_field(struct trace_seq *s, void *data,
> +				    struct tep_format_field *field,
> +				    struct tep_print_parse **parse_ptr)
>  {
>  	struct tep_event *event = field->event;
>  	struct tep_print_parse *parse;
>  	bool has_0x;
>  
> -	parse = event->print_fmt.print_cache;
> +	parse = parse_ptr ? *parse_ptr : event->print_fmt.print_cache;
>  
>  	if (event->flags & TEP_EVENT_FL_FAILED)
>  		goto out;
> @@ -5407,7 +5408,7 @@ void tep_print_field(struct trace_seq *s, void *data,
>  	if (field->flags & (TEP_FIELD_IS_ARRAY || TEP_FIELD_IS_STRING))
>  		goto out;
>  
> -	for (;parse; parse = parse->next) {
> +	while (parse) {

If the parse field is not found, this will loop forever. We need this:

	struct tep_print_parse *start_parse;

	start_parse = parse;
	do {

>  		if (parse->type == PRINT_FMT_STRING) {
>  			int len = strlen(parse->format);
>  
> @@ -5417,21 +5418,29 @@ void tep_print_field(struct trace_seq *s, void *data,
>  			else
>  				has_0x = false;
>  
> -			continue;
> +			goto next;
>  		}
>  
>  		if (!parse->arg ||
>  		    parse->arg->type != TEP_PRINT_FIELD ||
>  		    parse->arg->field.field != field) {
>  			has_0x = false;
> -			continue;
> +			goto next;
>  		}
>  
>  		if (has_0x)
>  			trace_seq_puts(s, "0x");
>  
>  		print_parse_data(parse, s, data, field->size, event);
> +
> +		if (parse_ptr)
> +			*parse_ptr = parse->next;
> +
>  		return;
> +
> + next:
> +		parse = parse->next ? parse->next :
> +				      event->print_fmt.print_cache;

	} while (parse != start_parse);

-- Steve


>  	}
>  
>   out:
> @@ -5439,15 +5448,22 @@ void tep_print_field(struct trace_seq *s, void *data,
>  	tep_print_field_raw(s, data, field);
>  }
>  
> +void tep_print_field(struct trace_seq *s, void *data,
> +		     struct tep_format_field *field)
> +{
> +	_tep_print_field(s, data, field, NULL);
> +}
> +
>  void tep_print_fields(struct trace_seq *s, void *data,
>  		      int size __maybe_unused, struct tep_event *event)
>  {
> +	struct tep_print_parse *parse = event->print_fmt.print_cache;
>  	struct tep_format_field *field;
>  
>  	field = event->format.fields;
>  	while (field) {
>  		trace_seq_printf(s, " %s=", field->name);
> -		tep_print_field(s, data, field);
> +		_tep_print_field(s, data, field, &parse);
>  		field = field->next;
>  	}
>  }

[PATCH v5 5/5] libtraceevent: Add tep_print_selected_fields()

[Yordan Karadzhov (VMware)]

The new method can print only a subset of the unique data fields of
the trace event. The print format is derived from the parsing tokens
(tep_print_parse objects) of the event.

Signed-off-by: Yordan Karadzhov (VMware) <y.karadz@gmail.com>
---
 src/event-parse.c | 26 ++++++++++++++++++++++----
 src/event-parse.h |  3 +++
 2 files changed, 25 insertions(+), 4 deletions(-)

diff --git a/src/event-parse.c b/src/event-parse.c
index 7831e74..3b93138 100644
--- a/src/event-parse.c
+++ b/src/event-parse.c
@@ -5454,20 +5454,38 @@ void tep_print_field(struct trace_seq *s, void *data,
 	_tep_print_field(s, data, field, NULL);
 }
 
-void tep_print_fields(struct trace_seq *s, void *data,
-		      int size __maybe_unused, struct tep_event *event)
+static inline void
+print_selected_fields(struct trace_seq *s, void *data,
+		      struct tep_event *event,
+		      unsigned long long ignore_mask)
 {
 	struct tep_print_parse *parse = event->print_fmt.print_cache;
 	struct tep_format_field *field;
+	unsigned long long field_mask = 1;
 
 	field = event->format.fields;
-	while (field) {
+	for (;field; field = field->next, field_mask *= 2) {
+		if (field_mask & ignore_mask)
+			continue;
+
 		trace_seq_printf(s, " %s=", field->name);
 		_tep_print_field(s, data, field, &parse);
-		field = field->next;
 	}
 }
 
+void tep_print_selected_fields(struct trace_seq *s, void *data,
+			       struct tep_event *event,
+			       unsigned long long ignore_mask)
+{
+	print_selected_fields(s, data, event, ignore_mask);
+}
+
+void tep_print_fields(struct trace_seq *s, void *data,
+		      int size __maybe_unused, struct tep_event *event)
+{
+	print_selected_fields(s, data, event, 0);
+}
+
 static int print_function(struct trace_seq *s, const char *format,
 			  void *data, int size, struct tep_event *event,
 			  struct tep_print_arg *arg)
diff --git a/src/event-parse.h b/src/event-parse.h
index d4a876f..e3638cf 100644
--- a/src/event-parse.h
+++ b/src/event-parse.h
@@ -545,6 +545,9 @@ int tep_cmdline_pid(struct tep_handle *tep, struct tep_cmdline *cmdline);
 
 void tep_print_field(struct trace_seq *s, void *data,
 		     struct tep_format_field *field);
+void tep_print_selected_fields(struct trace_seq *s, void *data,
+			       struct tep_event *event,
+			       unsigned long long ignore_mask);
 void tep_print_fields(struct trace_seq *s, void *data,
 		      int size __maybe_unused, struct tep_event *event);
 int tep_strerror(struct tep_handle *tep, enum tep_errno errnum,
-- 
2.30.2