[PATCH 0/3] Fix overflow when applying tsc2nsec calculations

[PATCH 0/3] Fix overflow when applying tsc2nsec calculations

[Tzvetomir Stoyanov (VMware)]

Verify that applying tsc2nsec corrections on the recorded timestamps will not
cause an overflow. When recording the trace, in case of tsc2nsec clock, get
the first TSC timestamp as offset to be used in tsc2nsec conversion.


Tzvetomir Stoyanov (VMware) (3):
  trace-cmd library: Add new trace-cmd library APIs for guest ts
    corrections
  trace-cmd library: Add check before applying tsc2nsec offset
  trace-cmd: Get the timestamp of the first recorded event as TSC offset

 .../include/private/trace-cmd-private.h       |  18 ++-
 lib/trace-cmd/trace-input.c                   | 116 ++------------
 lib/trace-cmd/trace-timesync.c                | 113 +++++++++++---
 tracecmd/include/trace-local.h                |   1 +
 tracecmd/trace-record.c                       | 146 ++++++++++++++----
 5 files changed, 240 insertions(+), 154 deletions(-)

-- 
2.30.2

[PATCH 1/3] trace-cmd library: Add new trace-cmd library APIs for guest ts corrections

[Tzvetomir Stoyanov (VMware)]

The logic for converting guest to host timestamps is local to the trace-cmd
library and is used only when a trace file is opened. In order to reuse
that logic, a new APIs are added:
 tracecmd_tsync_get_proto_flags()
 tracecmd_tsync_get_offsets()
 tracecmd_guest_ts_calc()
 struct ts_offset_sample
 struct tracecmd_ts_corrections

Signed-off-by: Tzvetomir Stoyanov (VMware) <tz.stoyanov@gmail.com>
---
 .../include/private/trace-cmd-private.h       |  18 ++-
 lib/trace-cmd/trace-input.c                   | 106 ++--------------
 lib/trace-cmd/trace-timesync.c                | 113 ++++++++++++++----
 3 files changed, 116 insertions(+), 121 deletions(-)

diff --git a/lib/trace-cmd/include/private/trace-cmd-private.h b/lib/trace-cmd/include/private/trace-cmd-private.h
index 42e739fa..56f82244 100644
--- a/lib/trace-cmd/include/private/trace-cmd-private.h
+++ b/lib/trace-cmd/include/private/trace-cmd-private.h
@@ -443,6 +443,17 @@ enum tracecmd_time_sync_role {
 /* Timestamp synchronization flags */
 #define TRACECMD_TSYNC_FLAG_INTERPOLATE	0x1
 
+struct ts_offset_sample {
+	long long	time;
+	long long	offset;
+	long long	scaling;
+};
+
+struct tracecmd_ts_corrections {
+	int	ts_samples_count;
+	struct ts_offset_sample	*ts_samples;
+};
+
 void tracecmd_tsync_init(void);
 int tracecmd_tsync_proto_getall(struct tracecmd_tsync_protos **protos, const char *clock, int role);
 bool tsync_proto_is_supported(const char *proto_name);
@@ -456,8 +467,8 @@ tracecmd_tsync_with_guest(unsigned long long trace_id, int loop_interval,
 			  int guest_cpus, const char *proto_name, const char *clock);
 int tracecmd_tsync_with_guest_stop(struct tracecmd_time_sync *tsync);
 int tracecmd_tsync_get_offsets(struct tracecmd_time_sync *tsync, int cpu,
-				int *count, long long **ts,
-				long long **offsets, long long **scalings);
+			       struct tracecmd_ts_corrections *offsets);
+int tracecmd_tsync_get_proto_flags(struct tracecmd_time_sync *tsync, unsigned int *flags);
 int tracecmd_tsync_get_session_params(struct tracecmd_time_sync *tsync,
 				      char **selected_proto,
 				      unsigned int *tsync_port);
@@ -465,6 +476,9 @@ void tracecmd_tsync_free(struct tracecmd_time_sync *tsync);
 int tracecmd_write_guest_time_shift(struct tracecmd_output *handle,
 				    struct tracecmd_time_sync *tsync);
 
+unsigned long long tracecmd_guest_ts_calc(unsigned long long ts,
+					  struct tracecmd_ts_corrections *tsync, int flags);
+
 /* --- Plugin handling --- */
 extern struct tep_plugin_option trace_ftrace_options[];
 
diff --git a/lib/trace-cmd/trace-input.c b/lib/trace-cmd/trace-input.c
index b17b36e0..974879e8 100644
--- a/lib/trace-cmd/trace-input.c
+++ b/lib/trace-cmd/trace-input.c
@@ -78,12 +78,6 @@ struct input_buffer_instance {
 	size_t			offset;
 };
 
-struct ts_offset_sample {
-	long long	time;
-	long long	offset;
-	long long	scaling;
-};
-
 struct guest_trace_info {
 	struct guest_trace_info	*next;
 	char			*name;
@@ -92,19 +86,12 @@ struct guest_trace_info {
 	int			*cpu_pid;
 };
 
-struct timesync_offsets {
-	int	ts_samples_count;
-	struct ts_offset_sample	*ts_samples;
-};
-
 struct host_trace_info {
-	unsigned long long	peer_trace_id;
-	unsigned int		flags;
-	bool			sync_enable;
-	int			ts_samples_count;
-	struct ts_offset_sample	*ts_samples;
-	int			cpu_count;
-	struct timesync_offsets	*ts_offsets;
+	unsigned long long			peer_trace_id;
+	unsigned int				flags;
+	bool					sync_enable;
+	int					cpu_count;
+	struct tracecmd_ts_corrections		*ts_offsets;
 };
 
 struct tsc2nsec {
@@ -1227,81 +1214,6 @@ static unsigned long long mul_u64_u32_shr(unsigned long long a,
 	return ret;
 }
 
-static inline unsigned long long
-timestamp_correction_calc(unsigned long long ts, unsigned int flags,
-			  struct ts_offset_sample *min,
-			  struct ts_offset_sample *max)
-{
-	long long scaling;
-	long long tscor;
-
-	if (flags & TRACECMD_TSYNC_FLAG_INTERPOLATE) {
-		long long delta = max->time - min->time;
-		long long offset = ((long long)ts - min->time) *
-				   (max->offset - min->offset);
-
-		scaling = (min->scaling + max->scaling) / 2;
-		tscor = min->offset + (offset + delta / 2) / delta;
-
-	} else {
-		scaling = min->scaling;
-		tscor = min->offset;
-	}
-
-	ts *= scaling;
-	if (tscor < 0)
-		return ts - llabs(tscor);
-
-	return ts + tscor;
-}
-
-static unsigned long long timestamp_host_sync(unsigned long long ts, int cpu,
-					      struct tracecmd_input *handle)
-{
-	struct timesync_offsets *tsync;
-	int min, mid, max;
-
-	if (cpu >= handle->host.cpu_count)
-		return ts;
-	tsync = &handle->host.ts_offsets[cpu];
-
-	/* We have one sample, nothing to calc here */
-	if (tsync->ts_samples_count == 1)
-		return ts + tsync->ts_samples[0].offset;
-
-	/* We have two samples, nothing to search here */
-	if (tsync->ts_samples_count == 2)
-		return timestamp_correction_calc(ts, handle->host.flags,
-						 &tsync->ts_samples[0],
-						 &tsync->ts_samples[1]);
-
-	/* We have more than two samples */
-	if (ts <= tsync->ts_samples[0].time)
-		return timestamp_correction_calc(ts, handle->host.flags,
-						 &tsync->ts_samples[0],
-						 &tsync->ts_samples[1]);
-	else if (ts >= tsync->ts_samples[tsync->ts_samples_count-1].time)
-		return timestamp_correction_calc(ts, handle->host.flags,
-						 &tsync->ts_samples[tsync->ts_samples_count-2],
-						 &tsync->ts_samples[tsync->ts_samples_count-1]);
-	min = 0;
-	max = tsync->ts_samples_count-1;
-	mid = (min + max)/2;
-	while (min <= max) {
-		if (ts < tsync->ts_samples[mid].time)
-			max = mid - 1;
-		else if (ts > tsync->ts_samples[mid].time)
-			min = mid + 1;
-		else
-			break;
-		mid = (min + max)/2;
-	}
-
-	return timestamp_correction_calc(ts, handle->host.flags,
-					 &tsync->ts_samples[mid],
-					 &tsync->ts_samples[mid+1]);
-}
-
 static unsigned long long timestamp_calc(unsigned long long ts, int cpu,
 					 struct tracecmd_input *handle)
 {
@@ -1310,8 +1222,8 @@ static unsigned long long timestamp_calc(unsigned long long ts, int cpu,
 		return ts;
 
 	/* Guest trace file, sync with host timestamps */
-	if (handle->host.sync_enable)
-		ts = timestamp_host_sync(ts, cpu, handle);
+	if (handle->host.sync_enable && cpu < handle->host.cpu_count)
+		ts = tracecmd_guest_ts_calc(ts, &handle->host.ts_offsets[cpu], handle->host.flags);
 
 	if (handle->ts2secs) {
 		/* user specified clock frequency */
@@ -2329,7 +2241,7 @@ static int tsync_offset_cmp(const void *a, const void *b)
 	} while (0)
 
 static int tsync_offset_load(struct tep_handle	*tep,
-			     struct timesync_offsets *ts_offsets, char *buf, int size)
+			     struct tracecmd_ts_corrections *ts_offsets, char *buf, int size)
 {
 	int start_size = size;
 	int i, j;
@@ -2357,7 +2269,7 @@ static int tsync_cpu_offsets_load(struct tracecmd_input *handle, char *buf, int
 
 	safe_read(handle->host.cpu_count, 4);
 	handle->host.ts_offsets = calloc(handle->host.cpu_count,
-					 sizeof(struct timesync_offsets));
+					 sizeof(struct tracecmd_ts_corrections));
 	if (!handle->host.ts_offsets)
 		return -ENOMEM;
 	for (i = 0; i < handle->host.cpu_count; i++) {
diff --git a/lib/trace-cmd/trace-timesync.c b/lib/trace-cmd/trace-timesync.c
index 19ca19d7..791a0964 100644
--- a/lib/trace-cmd/trace-timesync.c
+++ b/lib/trace-cmd/trace-timesync.c
@@ -133,36 +133,101 @@ bool __hidden tsync_proto_is_supported(const char *proto_name)
  *
  * @tsync: Pointer to time sync context
  * @cpu: CPU for which to get the calculated offsets
- * @count: Returns the number of calculated time offsets
- * @ts: Array of size @count containing timestamps of callculated offsets
- * @offsets: array of size @count, containing offsets for each timestamp
- * @scalings: array of size @count, containing scaling ratios for each timestamp
+ * @offsets: Returns the calculated timestamp offsets for the given @cpu
  *
  * Retuns -1 in case of an error, or 0 otherwise
  */
 int tracecmd_tsync_get_offsets(struct tracecmd_time_sync *tsync, int cpu,
-			       int *count, long long **ts,
-			       long long **offsets, long long **scalings)
+			       struct tracecmd_ts_corrections *offsets)
 {
 	struct clock_sync_context *tsync_context;
+	int i;
 
 	if (!tsync || !tsync->context)
 		return -1;
 	tsync_context = (struct clock_sync_context *)tsync->context;
 	if (cpu >= tsync_context->cpu_count || !tsync_context->offsets)
 		return -1;
-	if (count)
-		*count = tsync_context->offsets[cpu].sync_count;
-	if (ts)
-		*ts = tsync_context->offsets[cpu].sync_ts;
-	if (offsets)
-		*offsets = tsync_context->offsets[cpu].sync_offsets;
-	if (scalings)
-		*scalings = tsync_context->offsets[cpu].sync_scalings;
+	if (offsets) {
+		offsets->ts_samples = calloc(tsync_context->offsets[cpu].sync_count,
+					     sizeof(struct ts_offset_sample));
+		if (!offsets->ts_samples)
+			return -1;
+		offsets->ts_samples_count = tsync_context->offsets[cpu].sync_count;
+		for (i = 0; i < offsets->ts_samples_count; i++) {
+			offsets->ts_samples[i].time = tsync_context->offsets[cpu].sync_ts[i];
+			offsets->ts_samples[i].offset = tsync_context->offsets[cpu].sync_offsets[i];
+			offsets->ts_samples[i].scaling = tsync_context->offsets[cpu].sync_scalings[i];
+		}
+	}
 
 	return 0;
 }
 
+static inline unsigned long long correction_calc(unsigned long long ts, unsigned int flags,
+						struct ts_offset_sample *min,
+						struct ts_offset_sample *max)
+{
+	long long scaling;
+	long long tscor;
+
+	if (flags & TRACECMD_TSYNC_FLAG_INTERPOLATE) {
+		long long delta = max->time - min->time;
+		long long offset = ((long long)ts - min->time) *
+				   (max->offset - min->offset);
+
+		scaling = (min->scaling + max->scaling) / 2;
+		tscor = min->offset + (offset + delta / 2) / delta;
+
+	} else {
+		scaling = min->scaling;
+		tscor = min->offset;
+	}
+
+	ts *= scaling;
+	if (tscor < 0)
+		return ts - llabs(tscor);
+
+	return ts + tscor;
+}
+
+
+unsigned long long tracecmd_guest_ts_calc(unsigned long long ts,
+					  struct tracecmd_ts_corrections *tsync, int flags)
+{
+	int min, mid, max;
+
+	/* We have one sample, nothing to calc here */
+	if (tsync->ts_samples_count == 1)
+		return ts + tsync->ts_samples[0].offset;
+
+	/* We have two samples, nothing to search here */
+	if (tsync->ts_samples_count == 2)
+		return correction_calc(ts, flags, &tsync->ts_samples[0], &tsync->ts_samples[1]);
+
+	/* We have more than two samples */
+	if (ts <= tsync->ts_samples[0].time)
+		return correction_calc(ts, flags, &tsync->ts_samples[0], &tsync->ts_samples[1]);
+	else if (ts >= tsync->ts_samples[tsync->ts_samples_count-1].time)
+		return correction_calc(ts, flags,
+				       &tsync->ts_samples[tsync->ts_samples_count-2],
+				       &tsync->ts_samples[tsync->ts_samples_count-1]);
+	min = 0;
+	max = tsync->ts_samples_count-1;
+	mid = (min + max)/2;
+	while (min <= max) {
+		if (ts < tsync->ts_samples[mid].time)
+			max = mid - 1;
+		else if (ts > tsync->ts_samples[mid].time)
+			min = mid + 1;
+		else
+			break;
+		mid = (min + max)/2;
+	}
+
+	return correction_calc(ts, flags, &tsync->ts_samples[mid], &tsync->ts_samples[mid+1]);
+}
+
 /**
  * tsync_get_proto_flags - Get protocol flags
  *
@@ -171,8 +236,7 @@ int tracecmd_tsync_get_offsets(struct tracecmd_time_sync *tsync, int cpu,
  *
  * Retuns -1 in case of an error, or 0 otherwise
  */
-static int tsync_get_proto_flags(struct tracecmd_time_sync *tsync,
-				 unsigned int *flags)
+int tracecmd_tsync_get_proto_flags(struct tracecmd_time_sync *tsync, unsigned int *flags)
 {
 	struct tsync_proto *protocol;
 
@@ -924,6 +988,7 @@ error:
 int tracecmd_write_guest_time_shift(struct tracecmd_output *handle,
 				    struct tracecmd_time_sync *tsync)
 {
+	struct clock_sync_context *tsync_context;
 	struct iovec *vector = NULL;
 	unsigned int flags;
 	long long *scalings = NULL;
@@ -934,13 +999,15 @@ int tracecmd_write_guest_time_shift(struct tracecmd_output *handle,
 	int i, j;
 	int ret = -1;
 
-	if (!tsync->vcpu_count)
+	if (!tsync || !tsync->context || !tsync->vcpu_count)
 		return -1;
+	tsync_context = (struct clock_sync_context *)tsync->context;
+
 	vcount = 3 + (4 * tsync->vcpu_count);
 	vector = calloc(vcount, sizeof(struct iovec));
 	if (!vector)
 		return -1;
-	ret = tsync_get_proto_flags(tsync, &flags);
+	ret = tracecmd_tsync_get_proto_flags(tsync, &flags);
 	if (ret < 0)
 		goto out;
 
@@ -952,11 +1019,13 @@ int tracecmd_write_guest_time_shift(struct tracecmd_output *handle,
 	vector[j].iov_len = 4;
 	vector[j++].iov_base = &tsync->vcpu_count;
 	for (i = 0; i < tsync->vcpu_count; i++) {
-		if (j >= vcount)
+		if (j >= vcount || i >= tsync_context->cpu_count)
 			break;
-		ret = tracecmd_tsync_get_offsets(tsync, i, &count,
-						 &ts, &offsets, &scalings);
-		if (ret < 0 || !count || !ts || !offsets || !scalings)
+		count = tsync_context->offsets[i].sync_count;
+		ts = tsync_context->offsets[i].sync_ts;
+		offsets = tsync_context->offsets[i].sync_offsets;
+		scalings = tsync_context->offsets[i].sync_scalings;
+		if (!count || !ts || !offsets || !scalings)
 			break;
 		vector[j].iov_len = 4;
 		vector[j++].iov_base = &count;
-- 
2.30.2

[PATCH] trace-cmd: Suppress trace library warnings

[Tzvetomir Stoyanov (VMware)]

Suppress all warnings from libtraceevent, libtracefs and libtracecmd if
the trace-cmd application does not run in debug mode.

Signed-off-by: Tzvetomir Stoyanov (VMware) <tz.stoyanov@gmail.com>
---
 tracecmd/trace-cmd.c | 17 +++++++++++++++++
 1 file changed, 17 insertions(+)

diff --git a/tracecmd/trace-cmd.c b/tracecmd/trace-cmd.c
index 7376c5a5..7de0671e 100644
--- a/tracecmd/trace-cmd.c
+++ b/tracecmd/trace-cmd.c
@@ -35,6 +35,23 @@ void warning(const char *fmt, ...)
 	fprintf(stderr, "\n");
 }
 
+int tep_vwarning(const char *name, const char *fmt, va_list ap)
+{
+	int ret = errno;
+
+	if (!tracecmd_get_debug())
+		return ret;
+
+	if (errno)
+		perror(name);
+
+	fprintf(stderr, "  ");
+	vfprintf(stderr, fmt, ap);
+	fprintf(stderr, "\n");
+
+	return ret;
+}
+
 void pr_stat(const char *fmt, ...)
 {
 	va_list ap;
-- 
2.30.2

[PATCH 2/3] trace-cmd library: Add check before applying tsc2nsec offset

[Tzvetomir Stoyanov (VMware)]

When converting TSC timestamps to nanoseconds, an offset is used. That
offset is subtracted from each TSC timestamp, before the conversion.
However, if the timestamp is lower that the offset this causes an
overflow, as both timestamp and offset are unsigned long integers. A
check is added to verify the subtraction will not cause an overflow. In
case of an overflow, the timestamp is set to 0 and a warning message is
printed.

Signed-off-by: Tzvetomir Stoyanov (VMware) <tz.stoyanov@gmail.com>
---
 lib/trace-cmd/trace-input.c | 10 ++++++++--
 1 file changed, 8 insertions(+), 2 deletions(-)

diff --git a/lib/trace-cmd/trace-input.c b/lib/trace-cmd/trace-input.c
index 974879e8..991abd5f 100644
--- a/lib/trace-cmd/trace-input.c
+++ b/lib/trace-cmd/trace-input.c
@@ -1230,8 +1230,14 @@ static unsigned long long timestamp_calc(unsigned long long ts, int cpu,
 		ts *= handle->ts2secs;
 	} else if (handle->tsc_calc.mult) {
 		/* auto calculated TSC clock frequency */
-		ts -= handle->tsc_calc.offset;
-		ts = mul_u64_u32_shr(ts, handle->tsc_calc.mult, handle->tsc_calc.shift);
+		if (ts > handle->tsc_calc.offset) {
+			ts -= handle->tsc_calc.offset;
+			ts = mul_u64_u32_shr(ts, handle->tsc_calc.mult, handle->tsc_calc.shift);
+		} else {
+			tracecmd_warning("Timestamp $llu is before the initial offset %llu, set it to 0",
+					 ts, handle->tsc_calc.offset);
+			ts = 0;
+		}
 	}
 
 	/* User specified time offset with --ts-offset or --date options */
-- 
2.30.2

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

[Tzvetomir Stoyanov (VMware)]

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

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
-- 
2.30.2

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

[Steven Rostedt]

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

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

[Steven Rostedt]

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

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

[Tzvetomir Stoyanov]

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
>


-- 
Tzvetomir (Ceco) Stoyanov
VMware Open Source Technology Center