[PATCH v7 0/4] libtraceevent: Optimize the print of tep fields

[PATCH v7 0/4] 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 v7:
 - Proper naming (without 'tep' prefix) of the static methods defined
 in the patches.
 - Fixing the 'for' loop in print_selected_fields()
 - 'tep_print_selected_fields()' was renamed to 
 'tep_record_print_selected_fields()'. 'tep_record_print_fields()' was
 added.
 - Adding documentation for the new APIs.

Changes in v6:
 - Cleanup in [PATCH 1/5].
 - Protection against infinite loop in _tep_print_field()
 ([PATCH 4/5]).

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().
 

Yordan Karadzhov (VMware) (4):
  libtraceevent: Improve tep_print_field()
  libtraceevent: Optimize tep_print_fields()
  libtraceevent: Add APIs for printing the fields of a record
  libtraceevent: Add documentation for the new printing APIs

 Documentation/libtraceevent-field_print.txt |  11 +-
 Documentation/libtraceevent.txt             |   2 +
 src/event-parse.c                           | 184 ++++++++++++++++----
 src/event-parse.h                           |   7 +
 4 files changed, 170 insertions(+), 34 deletions(-)

-- 
2.30.2

[PATCH v7 1/4] 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 02ec677..6129a0c 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 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;
@@ -5389,6 +5388,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. */
+	print_field_raw(s, data, field);
+}
+
 void tep_print_fields(struct trace_seq *s, void *data,
 		      int size __maybe_unused, struct tep_event *event)
 {
@@ -5908,35 +5957,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 v7 2/4] 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. For most of the tracing events
the order of fields matches the order of the corresponding format
tokens, however this is not strictly guaranteed. This problem is
addressed by making the loop over the tokens circular.

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

diff --git a/src/event-parse.c b/src/event-parse.c
index 6129a0c..51cb30b 100644
--- a/src/event-parse.c
+++ b/src/event-parse.c
@@ -5391,22 +5391,25 @@ static void 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 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 *start_parse;
 	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)
+	if (!parse || 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) {
+	start_parse = parse;
+	do {
 		if (parse->type == PRINT_FMT_STRING) {
 			int len = strlen(parse->format);
 
@@ -5416,37 +5419,52 @@ 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);
 
  out:
 	/* Not found. */
 	print_field_raw(s, data, field);
 }
 
+void tep_print_field(struct trace_seq *s, void *data,
+		     struct tep_format_field *field)
+{
+	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);
+		print_field(s, data, field, &parse);
 		field = field->next;
 	}
 }
-- 
2.30.2

[PATCH v7 3/4] libtraceevent: Add APIs for printing the fields of a record

[Yordan Karadzhov (VMware)]

The new methods can print all unique data fielsd, or only a subset of
the 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 | 49 +++++++++++++++++++++++++++++++++++++++++++----
 src/event-parse.h |  7 +++++++
 2 files changed, 52 insertions(+), 4 deletions(-)

diff --git a/src/event-parse.c b/src/event-parse.c
index 51cb30b..71a3ccd 100644
--- a/src/event-parse.c
+++ b/src/event-parse.c
@@ -5455,20 +5455,61 @@ void tep_print_field(struct trace_seq *s, void *data,
 	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 <<= 1) {
+		if (field_mask & ignore_mask)
+			continue;
+
 		trace_seq_printf(s, " %s=", field->name);
 		print_field(s, data, field, &parse);
-		field = field->next;
 	}
 }
 
+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);
+}
+
+/**
+ * tep_record_print_selected_fields - print the field name followed by the
+ * record's field value for a selected subset of record fields.
+ * @s: The seq to print to
+ * @record: The record to get the event from
+ * @event: The event that the field is for
+ */
+void tep_record_print_fields(struct trace_seq *s,
+			     struct tep_record *record,
+			     struct tep_event *event)
+{
+	print_selected_fields(s, record->data, event, 0);
+}
+
+/**
+ * tep_record_print_selected_fields - print the field name followed by the
+ * record's field value for a selected subset of record fields.
+ * @s: The seq to print to
+ * @record: The record to get the event from
+ * @event: The event that the field is for
+ * @ignore_mask: Bit mask defining the fields to be ignored
+ */
+void tep_record_print_selected_fields(struct trace_seq *s,
+				      struct tep_record *record,
+				      struct tep_event *event,
+				      unsigned long long ignore_mask)
+{
+	print_selected_fields(s, record->data, event, ignore_mask);
+}
+
 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..08dcbd8 100644
--- a/src/event-parse.h
+++ b/src/event-parse.h
@@ -545,6 +545,13 @@ 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_record_print_fields(struct trace_seq *s,
+			     struct tep_record *record,
+			     struct tep_event *event);
+void tep_record_print_selected_fields(struct trace_seq *s,
+				      struct tep_record *record,
+				      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

Re: [PATCH v7 3/4] libtraceevent: Add APIs for printing the fields of a record

[Steven Rostedt]

On Mon, 23 Aug 2021 12:56:17 +0300
"Yordan Karadzhov (VMware)" <y.karadz@gmail.com> wrote:

> The new methods can print all unique data fielsd, or only a subset of
> the fields of the trace event. The print format is derived from the
> parsing tokens (tep_print_parse objects) of the event.

The more I look at this, the more I think we should have a
"selected_fields" mask, and not a ignored mask. At least for the API.
The internal functions can stay the same. That is, the internal
functions have the ignored_mask.

> 
> Signed-off-by: Yordan Karadzhov (VMware) <y.karadz@gmail.com>
> ---


> +/**
> + * tep_record_print_selected_fields - print the field name followed by the

I think the above should be "tep_record_print_fields" ?

> + * record's field value for a selected subset of record fields.
> + * @s: The seq to print to
> + * @record: The record to get the event from
> + * @event: The event that the field is for
> + */
> +void tep_record_print_fields(struct trace_seq *s,
> +			     struct tep_record *record,
> +			     struct tep_event *event)
> +{
> +	print_selected_fields(s, record->data, event, 0);
> +}
> +
> +/**
> + * tep_record_print_selected_fields - print the field name followed by the
> + * record's field value for a selected subset of record fields.
> + * @s: The seq to print to
> + * @record: The record to get the event from
> + * @event: The event that the field is for
> + * @ignore_mask: Bit mask defining the fields to be ignored

change to:

      @select_mask: Bit mask defining the fields to record

> + */
> +void tep_record_print_selected_fields(struct trace_seq *s,
> +				      struct tep_record *record,
> +				      struct tep_event *event,
> +				      unsigned long long ignore_mask)

				      unsigned long long select_mask)

> +{

Since print_selected_fields() will still have the ignore_mask, you can
have:

	unsigned long long ignore_mask = ~select_mask;


> +	print_selected_fields(s, record->data, event, ignore_mask);

The above would remain the same.

-- Steve

> +}
> +
>  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..08dcbd8 100644
> --- a/src/event-parse.h
> +++ b/src/event-parse.h
> @@ -545,6 +545,13 @@ 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_record_print_fields(struct trace_seq *s,
> +			     struct tep_record *record,
> +			     struct tep_event *event);
> +void tep_record_print_selected_fields(struct trace_seq *s,
> +				      struct tep_record *record,
> +				      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,

[PATCH v7 4/4] libtraceevent: Add documentation for the new printing APIs

[Yordan Karadzhov (VMware)]

'tep_record_print_fields()' and 'tep_record_print_selected_fields()'
are documented.

Signed-off-by: Yordan Karadzhov (VMware) <y.karadz@gmail.com>
---
 Documentation/libtraceevent-field_print.txt | 11 ++++++++++-
 Documentation/libtraceevent.txt             |  2 ++
 2 files changed, 12 insertions(+), 1 deletion(-)

diff --git a/Documentation/libtraceevent-field_print.txt b/Documentation/libtraceevent-field_print.txt
index 2c2cf6c..2b001e3 100644
--- a/Documentation/libtraceevent-field_print.txt
+++ b/Documentation/libtraceevent-field_print.txt
@@ -3,7 +3,7 @@ libtraceevent(3)
 
 NAME
 ----
-tep_print_field, tep_print_fields, tep_print_num_field, tep_print_func_field -
+tep_print_field, tep_print_fields, tep_record_print_fields, tep_record_print_selected_fields, tep_print_num_field, tep_print_func_field -
 Print the field content.
 
 SYNOPSIS
@@ -15,6 +15,8 @@ SYNOPSIS
 
 void *tep_print_field*(struct trace_seq pass:[*]_s_, void pass:[*]_data_, struct tep_format_field pass:[*]_field_);
 void *tep_print_fields*(struct trace_seq pass:[*]_s_, void pass:[*]_data_, int _size_, struct tep_event pass:[*]_event_);
+void *tep_record_print_fields*(struct trace_seq pass:[*]_s_, struct tep_record pass:[*]_record_, struct tep_event pass:[*]_event_);
+void *tep_record_print_selected_fields*(struct trace_seq pass:[*]_s_, struct tep_record pass:[*]_record_, struct tep_event pass:[*]_event_, int _ignore_mask_);
 int *tep_print_num_field*(struct trace_seq pass:[*]_s_, const char pass:[*]_fmt_, struct tep_event pass:[*]_event_, const char pass:[*]_name_, struct tep_record pass:[*]_record_, int _err_);
 int *tep_print_func_field*(struct trace_seq pass:[*]_s_, const char pass:[*]_fmt_, struct tep_event pass:[*]_event_, const char pass:[*]_name_, struct tep_record pass:[*]_record_, int _err_);
 --
@@ -35,6 +37,13 @@ value according to the field's type:
 It iterates all fields of the _event_, and calls _tep_print_field()_ for each of
 them.
 
+The _tep_print_selected_fields()_ prints the field's name followed by its value
+for all record's field.
+
+The _tep_print_selected_fields()_ prints the field's name followed by its value
+for selected subset of record field. The fields to be excluded from printing
+are defined by the _ignore_mask_ bit mask.
+
 The _tep_print_num_field()_ function prints a numeric field with given format
 string. A search is performed in the _event_ for a field with _name_. If such
 field is found, its value is extracted from the _record_ and is printed in the
diff --git a/Documentation/libtraceevent.txt b/Documentation/libtraceevent.txt
index d42b5c9..2d7318e 100644
--- a/Documentation/libtraceevent.txt
+++ b/Documentation/libtraceevent.txt
@@ -78,6 +78,8 @@ APIs related to fields from event's format files:
 Event fields printing:
 	void *tep_print_field*(struct trace_seq pass:[*]_s_, void pass:[*]_data_, struct tep_format_field pass:[*]_field_);
 	void *tep_print_fields*(struct trace_seq pass:[*]_s_, void pass:[*]_data_, int _size_, struct tep_event pass:[*]_event_);
+	void *tep_record_print_fields*(struct trace_seq pass:[*]_s_, struct tep_record pass:[*]_record_, struct tep_event pass:[*]_event_);
+	void *tep_record_print_selected_fields*(struct trace_seq pass:[*]_s_, struct tep_record pass:[*]_record_, struct tep_event pass:[*]_event_, int _ignore_mask_);
 	int *tep_print_num_field*(struct trace_seq pass:[*]_s_, const char pass:[*]_fmt_, struct tep_event pass:[*]_event_, const char pass:[*]_name_, struct tep_record pass:[*]_record_, int _err_);
 	int *tep_print_func_field*(struct trace_seq pass:[*]_s_, const char pass:[*]_fmt_, struct tep_event pass:[*]_event_, const char pass:[*]_name_, struct tep_record pass:[*]_record_, int _err_);
 
-- 
2.30.2

Re: [PATCH v7 0/4] libtraceevent: Optimize the print of tep fields

[Steven Rostedt]

On Mon, 23 Aug 2021 12:56:14 +0300
"Yordan Karadzhov (VMware)" <y.karadz@gmail.com> wrote:


> Yordan Karadzhov (VMware) (4):
>   libtraceevent: Improve tep_print_field()
>   libtraceevent: Optimize tep_print_fields()

I accepted the first two patches. I had a comment for the one below.

-- Steve

>   libtraceevent: Add APIs for printing the fields of a record
>   libtraceevent: Add documentation for the new printing APIs
> 
>  Documentation/libtraceevent-field_print.txt |  11 +-
>  Documentation/libtraceevent.txt             |   2 +
>  src/event-parse.c                           | 184 ++++++++++++++++----
>  src/event-parse.h                           |   7 +
>  4 files changed, 170 insertions(+), 34 deletions(-)
>