* [PATCH 1/3] trace-cmd library: Add new trace-cmd library APIs for guest ts corrections
2021-04-15 8:15 [PATCH 0/3] Fix overflow when applying tsc2nsec calculations Tzvetomir Stoyanov (VMware)
@ 2021-04-15 8:15 ` Tzvetomir Stoyanov (VMware)
2021-04-15 8:15 ` [PATCH] trace-cmd: Suppress trace library warnings Tzvetomir Stoyanov (VMware)
` (2 subsequent siblings)
3 siblings, 0 replies; 8+ messages in thread
From: Tzvetomir Stoyanov (VMware) @ 2021-04-15 8:15 UTC (permalink / raw)
To: rostedt; +Cc: linux-trace-devel
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
^ permalink raw reply related [flat|nested] 8+ messages in thread
* [PATCH 3/3] trace-cmd: Get the timestamp of the first recorded event as TSC offset
2021-04-15 8:15 [PATCH 0/3] Fix overflow when applying tsc2nsec calculations Tzvetomir Stoyanov (VMware)
` (2 preceding siblings ...)
2021-04-15 8:15 ` [PATCH 2/3] trace-cmd library: Add check before applying tsc2nsec offset Tzvetomir Stoyanov (VMware)
@ 2021-04-15 8:15 ` Tzvetomir Stoyanov (VMware)
2021-04-15 21:18 ` Steven Rostedt
3 siblings, 1 reply; 8+ messages in thread
From: Tzvetomir Stoyanov (VMware) @ 2021-04-15 8:15 UTC (permalink / raw)
To: rostedt; +Cc: linux-trace-devel
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
^ permalink raw reply related [flat|nested] 8+ messages in thread