diff mbox series

[3/3] trace-cmd: Get the timestamp of the first recorded event as TSC offset

Message ID 20210415081527.3483835-5-tz.stoyanov@gmail.com (mailing list archive)
State Superseded
Headers show
Series Fix overflow when applying tsc2nsec calculations | expand

Commit Message

Tzvetomir Stoyanov (VMware) April 15, 2021, 8:15 a.m. UTC 
When converting TSC timestamps to nanoseconds, an offset is used. That
offset is subtracted from each TSC timestamp, before the conversion. At
the end of the trace, the lowest recorded TSC timestamp is selected as
TSC offset, that will be used for tsc2nsec conversion.

Signed-off-by: Tzvetomir Stoyanov (VMware) <tz.stoyanov@gmail.com>
---
 tracecmd/include/trace-local.h |   1 +
 tracecmd/trace-record.c        | 146 ++++++++++++++++++++++++++-------
 2 files changed, 116 insertions(+), 31 deletions(-)

Comments

Steven Rostedt April 15, 2021, 9:18 p.m. UTC | #1 
On Thu, 15 Apr 2021 11:15:27 +0300
"Tzvetomir Stoyanov (VMware)" <tz.stoyanov@gmail.com> wrote:


> @@ -4183,7 +4156,100 @@ static void add_options(struct tracecmd_output *handle, struct common_record_con
>  	free(clocks);
>  }
>  
> -static void write_guest_file(struct buffer_instance *instance)
> +int get_first_ts(char *file, unsigned long long *ts)

		 const char *file,

> +{
> +	enum kbuffer_long_size long_size;
> +	enum kbuffer_endian endian;
> +	struct kbuffer *kbuf = NULL;
> +	int psize, rsize;
> +	char *page = NULL;
> +	int ret = -1;
> +	char *data;
> +	int fd;
> +
> +	fd = open(file, O_RDONLY);
> +	if (fd < 0)
> +		return -1;
> +
> +	psize = getpagesize();
> +	page = calloc(1, psize);
> +	if (!page)
> +		goto error;
> +
> +	rsize = read(fd, page, psize);
> +	if (rsize <= 0)
> +		goto error;
> +

vvvvvvvvvvvvvvvvvvvvvvvvvvvvvvv

> +	if (tracecmd_host_bigendian())
> +		endian = KBUFFER_ENDIAN_BIG;
> +	else
> +		endian = KBUFFER_ENDIAN_LITTLE;
> +	if (sizeof(long) == 8)
> +		long_size = KBUFFER_LSIZE_8;
> +	else
> +		long_size = KBUFFER_LSIZE_4;
> +
> +	kbuf = kbuffer_alloc(long_size, endian);
> +	if (!kbuf)
> +		goto error;

^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^

The above should be moved into the calling function. The
kbuffer_load_subbuffer() will reset the kbuf. No need to constantly
allocate it and set it up each time.


> +
> +	kbuffer_load_subbuffer(kbuf, page);
> +	if (kbuffer_subbuffer_size(kbuf) > rsize)
> +		goto error;
> +
> +	data = kbuffer_read_event(kbuf, ts);
> +	if (!data)
> +		goto error;
> +
> +	ret = 0;
> +error:
> +	if (kbuf)
> +		kbuffer_free(kbuf);
> +	free(page);
> +	close(fd);
> +	return ret;
> +}
> +
> +void get_first_ts_instance(struct buffer_instance *instance)
> +{
> +	struct tracecmd_ts_corrections corrections;
> +	unsigned long long first_ts = 0;

I wouldn't use first_ts as the check to start. What happens if the first_ts
is actually zero?

use bool first = true; or something.

> +	unsigned long long ts;
> +	unsigned int flags;
> +	int first_ts_cpu;
> +	char *file;
> +	int ret;
> +	int i;
> +

	if (tracecmd_host_bigendian())
		endian = KBUFFER_ENDIAN_BIG;
	else
		endian = KBUFFER_ENDIAN_LITTLE;
	if (sizeof(long) == 8)
		long_size = KBUFFER_LSIZE_8;
	else
		long_size = KBUFFER_LSIZE_4;

	kbuf = kbuffer_alloc(long_size, endian);
	if (!kbuf)
		goto return;

And shouldn't this be returning these errors? Do we really want to continue
if this doesn't work?

> +	for (i = 0; i < instance->cpu_count; i++) {
> +		file = get_temp_file(instance, i);
> +		if (!file)
> +			continue;
> +		if (!get_first_ts(file, &ts)) {

		if (!get_first_ts(kbuf, file, &ts)) {

> +			if (!first_ts || ts < first_ts) {

			if (first || ts < first_ts) {
				first = false;

> +				first_ts = ts;
> +				first_ts_cpu = i;
> +			}
> +		}
> +		put_temp_file(file);
> +	}

No need to check if kbuf is not NULL, kbuffer_free() handles that.

	kbuffer_free(kbuf);


> +	if (first_ts) {

	if (!first) {

> +		if (is_guest(instance)) {
> +			ret = tracecmd_tsync_get_proto_flags(instance->tsync, &flags);
> +			if (ret)
> +				return;
> +			ret =  tracecmd_tsync_get_offsets(instance->tsync, first_ts_cpu, &corrections);
> +			if (ret)
> +				return;
> +			instance->first_ts = tracecmd_guest_ts_calc(first_ts, &corrections, flags);
> +			free(corrections.ts_samples);
> +		} else  {
> +			instance->first_ts = first_ts;
> +		}
> +	}
> +}
> +
> +static void write_guest_file(struct common_record_context *ctx, struct buffer_instance *instance)
>  {
>  	struct tracecmd_output *handle;
>  	int cpu_count = instance->cpu_count;
> @@ -4201,6 +4267,12 @@ static void write_guest_file(struct buffer_instance *instance)
>  		die("error writing to %s", file);
>  	if (instance->flags & BUFFER_FL_TSC2NSEC)
>  		tracecmd_set_out_clock(handle, TSCNSEC_CLOCK);
> +
> +	if (ctx->tsc2nsec.mult)
> +		add_tsc2nsec(handle, &ctx->tsc2nsec);
> +	tracecmd_write_guest_time_shift(handle, instance->tsync);
> +	tracecmd_append_options(handle);
> +
>  	temp_files = malloc(sizeof(*temp_files) * cpu_count);
>  	if (!temp_files)
>  		die("failed to allocate temp_files for %d cpus",
> @@ -4219,6 +4291,9 @@ static void write_guest_file(struct buffer_instance *instance)
>  	for (i = 0; i < cpu_count; i++)
>  		put_temp_file(temp_files[i]);
>  	free(temp_files);
> +
> +	tracecmd_tsync_free(instance->tsync);
> +	instance->tsync = NULL;
>  }
>  
>  static void record_data(struct common_record_context *ctx)
> @@ -4231,9 +4306,18 @@ static void record_data(struct common_record_context *ctx)
>  	char **temp_files;
>  	int i;
>  
> +	if (ctx->tsc2nsec.mult) {
> +		for_all_instances(instance) {
> +			get_first_ts_instance(instance);

Should check the return code, and at least warn if it fails. As it is done
after the recording, we don't want to die. But at least let the user know
something went wrong.

-- Steve

> +			if (instance->first_ts &&
> +			    (!ctx->tsc2nsec.offset || ctx->tsc2nsec.offset > instance->first_ts))
> +				ctx->tsc2nsec.offset = instance->first_ts;
> +		}
> +	}
> +
>  	for_all_instances(instance) {
>  		if (is_guest(instance))
> -			write_guest_file(instance);
> +			write_guest_file(ctx, instance);
>  		else if (host && instance->msg_handle)
>  			finish_network(instance->msg_handle);
>  		else
Steven Rostedt April 15, 2021, 9:25 p.m. UTC | #2 
On Thu, 15 Apr 2021 17:18:45 -0400
Steven Rostedt <rostedt@goodmis.org> wrote:

> 	if (!kbuf)
> 		goto return;

And that was suppose to be "return;" not "goto return;" :-p

-- Steve
Tzvetomir Stoyanov (VMware) April 16, 2021, 4:41 a.m. UTC | #3 
On Fri, Apr 16, 2021 at 12:18 AM Steven Rostedt <rostedt@goodmis.org> wrote:
>
[...]
> >  static void record_data(struct common_record_context *ctx)
> > @@ -4231,9 +4306,18 @@ static void record_data(struct common_record_context *ctx)
> >       char **temp_files;
> >       int i;
> >
> > +     if (ctx->tsc2nsec.mult) {
> > +             for_all_instances(instance) {
> > +                     get_first_ts_instance(instance);
>
> Should check the return code, and at least warn if it fails. As it is done
> after the recording, we don't want to die. But at least let the user know
> something went wrong.
>
> -- Steve
>
> > +                     if (instance->first_ts &&

I'll add return code and will check it instead of that
"instance->first_ts". Failing to get the first ts could be a normal
case, if there are no events recorded in that instance.

> > +                         (!ctx->tsc2nsec.offset || ctx->tsc2nsec.offset > instance->first_ts))
> > +                             ctx->tsc2nsec.offset = instance->first_ts;
> > +             }
> > +     }
> > +
> >       for_all_instances(instance) {
> >               if (is_guest(instance))
> > -                     write_guest_file(instance);
> > +                     write_guest_file(ctx, instance);
> >               else if (host && instance->msg_handle)
> >                       finish_network(instance->msg_handle);
> >               else
>
diff mbox series

Patch

diff --git a/tracecmd/include/trace-local.h b/tracecmd/include/trace-local.h
index 1218de12..d504ea14 100644
--- a/tracecmd/include/trace-local.h
+++ b/tracecmd/include/trace-local.h
@@ -213,6 +213,7 @@  struct buffer_instance {
 	char			*name;
 	struct tracefs_instance	*tracefs;
 	unsigned long long	trace_id;
+	unsigned long long	first_ts;
 	char			*cpumask;
 	char			*output_file;
 	struct event_list	*events;
diff --git a/tracecmd/trace-record.c b/tracecmd/trace-record.c
index fd03a605..a7093fa2 100644
--- a/tracecmd/trace-record.c
+++ b/tracecmd/trace-record.c
@@ -40,6 +40,7 @@ 
 #ifdef VSOCK
 #include <linux/vm_sockets.h>
 #endif
+#include <traceevent/kbuffer.h>
 
 #include "tracefs.h"
 #include "version.h"
@@ -685,34 +686,6 @@  add_tsc2nsec(struct tracecmd_output *handle, struct tsc_nsec *tsc2nsec)
 	tracecmd_add_option_v(handle, TRACECMD_OPTION_TSC2NSEC, vector, 3);
 }
 
-static void host_tsync_complete(struct common_record_context *ctx,
-				struct buffer_instance *instance)
-{
-	struct tracecmd_output *handle = NULL;
-	int fd = -1;
-	int ret;
-
-	ret = tracecmd_tsync_with_guest_stop(instance->tsync);
-	if (!ret) {
-		fd = open(instance->output_file, O_RDWR);
-		if (fd < 0)
-			die("error opening %s", instance->output_file);
-		handle = tracecmd_get_output_handle_fd(fd);
-		if (!handle)
-			die("cannot create output handle");
-
-		if (ctx->tsc2nsec.mult)
-			add_tsc2nsec(handle, &ctx->tsc2nsec);
-
-		tracecmd_write_guest_time_shift(handle, instance->tsync);
-		tracecmd_append_options(handle);
-		tracecmd_output_close(handle);
-	}
-
-	tracecmd_tsync_free(instance->tsync);
-	instance->tsync = NULL;
-}
-
 static void tell_guests_to_stop(struct common_record_context *ctx)
 {
 	struct buffer_instance *instance;
@@ -725,7 +698,7 @@  static void tell_guests_to_stop(struct common_record_context *ctx)
 
 	for_all_instances(instance) {
 		if (is_guest(instance))
-			host_tsync_complete(ctx, instance);
+			tracecmd_tsync_with_guest_stop(instance->tsync);
 	}
 
 	/* Wait for guests to acknowledge */
@@ -4183,7 +4156,100 @@  static void add_options(struct tracecmd_output *handle, struct common_record_con
 	free(clocks);
 }
 
-static void write_guest_file(struct buffer_instance *instance)
+int get_first_ts(char *file, unsigned long long *ts)
+{
+	enum kbuffer_long_size long_size;
+	enum kbuffer_endian endian;
+	struct kbuffer *kbuf = NULL;
+	int psize, rsize;
+	char *page = NULL;
+	int ret = -1;
+	char *data;
+	int fd;
+
+	fd = open(file, O_RDONLY);
+	if (fd < 0)
+		return -1;
+
+	psize = getpagesize();
+	page = calloc(1, psize);
+	if (!page)
+		goto error;
+
+	rsize = read(fd, page, psize);
+	if (rsize <= 0)
+		goto error;
+
+	if (tracecmd_host_bigendian())
+		endian = KBUFFER_ENDIAN_BIG;
+	else
+		endian = KBUFFER_ENDIAN_LITTLE;
+	if (sizeof(long) == 8)
+		long_size = KBUFFER_LSIZE_8;
+	else
+		long_size = KBUFFER_LSIZE_4;
+
+	kbuf = kbuffer_alloc(long_size, endian);
+	if (!kbuf)
+		goto error;
+
+	kbuffer_load_subbuffer(kbuf, page);
+	if (kbuffer_subbuffer_size(kbuf) > rsize)
+		goto error;
+
+	data = kbuffer_read_event(kbuf, ts);
+	if (!data)
+		goto error;
+
+	ret = 0;
+error:
+	if (kbuf)
+		kbuffer_free(kbuf);
+	free(page);
+	close(fd);
+	return ret;
+}
+
+void get_first_ts_instance(struct buffer_instance *instance)
+{
+	struct tracecmd_ts_corrections corrections;
+	unsigned long long first_ts = 0;
+	unsigned long long ts;
+	unsigned int flags;
+	int first_ts_cpu;
+	char *file;
+	int ret;
+	int i;
+
+	for (i = 0; i < instance->cpu_count; i++) {
+		file = get_temp_file(instance, i);
+		if (!file)
+			continue;
+		if (!get_first_ts(file, &ts)) {
+			if (!first_ts || ts < first_ts) {
+				first_ts = ts;
+				first_ts_cpu = i;
+			}
+		}
+		put_temp_file(file);
+	}
+	if (first_ts) {
+		if (is_guest(instance)) {
+			ret = tracecmd_tsync_get_proto_flags(instance->tsync, &flags);
+			if (ret)
+				return;
+			ret =  tracecmd_tsync_get_offsets(instance->tsync, first_ts_cpu, &corrections);
+			if (ret)
+				return;
+			instance->first_ts = tracecmd_guest_ts_calc(first_ts, &corrections, flags);
+			free(corrections.ts_samples);
+		} else  {
+			instance->first_ts = first_ts;
+		}
+	}
+}
+
+static void write_guest_file(struct common_record_context *ctx, struct buffer_instance *instance)
 {
 	struct tracecmd_output *handle;
 	int cpu_count = instance->cpu_count;
@@ -4201,6 +4267,12 @@  static void write_guest_file(struct buffer_instance *instance)
 		die("error writing to %s", file);
 	if (instance->flags & BUFFER_FL_TSC2NSEC)
 		tracecmd_set_out_clock(handle, TSCNSEC_CLOCK);
+
+	if (ctx->tsc2nsec.mult)
+		add_tsc2nsec(handle, &ctx->tsc2nsec);
+	tracecmd_write_guest_time_shift(handle, instance->tsync);
+	tracecmd_append_options(handle);
+
 	temp_files = malloc(sizeof(*temp_files) * cpu_count);
 	if (!temp_files)
 		die("failed to allocate temp_files for %d cpus",
@@ -4219,6 +4291,9 @@  static void write_guest_file(struct buffer_instance *instance)
 	for (i = 0; i < cpu_count; i++)
 		put_temp_file(temp_files[i]);
 	free(temp_files);
+
+	tracecmd_tsync_free(instance->tsync);
+	instance->tsync = NULL;
 }
 
 static void record_data(struct common_record_context *ctx)
@@ -4231,9 +4306,18 @@  static void record_data(struct common_record_context *ctx)
 	char **temp_files;
 	int i;
 
+	if (ctx->tsc2nsec.mult) {
+		for_all_instances(instance) {
+			get_first_ts_instance(instance);
+			if (instance->first_ts &&
+			    (!ctx->tsc2nsec.offset || ctx->tsc2nsec.offset > instance->first_ts))
+				ctx->tsc2nsec.offset = instance->first_ts;
+		}
+	}
+
 	for_all_instances(instance) {
 		if (is_guest(instance))
-			write_guest_file(instance);
+			write_guest_file(ctx, instance);
 		else if (host && instance->msg_handle)
 			finish_network(instance->msg_handle);
 		else