[PATCH 00/12] TSC trace clock to nanosecond conversion

[PATCH 00/12] TSC trace clock to nanosecond conversion

[Tzvetomir Stoyanov (VMware)]

Added new logic for converting TSC event's timestamps to nanoseconds. This
trace clock is used by default in host-guest tracing session in combination
with KVM time sync plugin. The parameters for conversion are retrieved by
the perf kernel interface.
New option is added to "trace-cmd report" command to force displaying raw
time stamps from the trace file, without any corrections to the time stamps.

These changes depend on "Refactoring and improvements of time sync logic"
patch set.

Tzvetomir Stoyanov (VMware) (12):
  trace-cmd: Add initial perf interface in trace-cmd library
  trace-cmd: Add logic for TSC to nanosecond conversion
  trace-cmd: Append new options into guest trace file at the end of the
    tracing session
  trace-cmd: Add a new option in trace file metadata for tsc2nsec
    conversion
  trace-cmd: Save information for tsc to nanoseconds conversion in trace
    file
  trace-cmd: Read information for tsc to nanoseconds conversion from
    trace file
  trace-cmd: Remove unneeded multiply in events timestamp reading
  trace-cmd: Perform all timestamp corrections in a single function
  trace-cmd: Convert tsc timestamps to nanosecods when reading trace
    data from a file
  trace-cmd: Set order and priorities when applying timestamp
    corrections
  trace-cmd: Add a new flag to disable any timestamp corrections
  trace-cmd: Add new parameter "--raw-ts" to "trace-cmd report" command

 lib/trace-cmd/Makefile                        |   1 +
 .../include/private/trace-cmd-private.h       |  16 ++
 lib/trace-cmd/trace-input.c                   |  96 ++++++++---
 lib/trace-cmd/trace-perf.c                    | 105 ++++++++++++
 lib/trace-cmd/trace-timesync.c                |   1 -
 tracecmd/include/trace-local.h                |   7 +
 tracecmd/trace-dump.c                         |  18 ++
 tracecmd/trace-read.c                         |   9 +-
 tracecmd/trace-record.c                       | 155 +++++++++++++++---
 9 files changed, 358 insertions(+), 50 deletions(-)
 create mode 100644 lib/trace-cmd/trace-perf.c

-- 
2.29.2

[PATCH 01/12] trace-cmd: Add initial perf interface in trace-cmd library

[Tzvetomir Stoyanov (VMware)]

Add new trace-cmd library internal APIs for working with perf. These
initial APIs offer only basic functionality - init, open and close a
perf session:
  trace_perf_init();
  trace_perf_close();
  trace_perf_open();

Signed-off-by: Tzvetomir Stoyanov (VMware) <tz.stoyanov@gmail.com>
---
 lib/trace-cmd/Makefile                        |   1 +
 .../include/private/trace-cmd-private.h       |  14 +++
 lib/trace-cmd/trace-perf.c                    | 105 ++++++++++++++++++
 3 files changed, 120 insertions(+)
 create mode 100644 lib/trace-cmd/trace-perf.c

diff --git a/lib/trace-cmd/Makefile b/lib/trace-cmd/Makefile
index 2f553ed5..03d1a30c 100644
--- a/lib/trace-cmd/Makefile
+++ b/lib/trace-cmd/Makefile
@@ -17,6 +17,7 @@ OBJS += trace-util.o
 OBJS += trace-filter-hash.o
 OBJS += trace-msg.o
 OBJS += trace-plugin.o
+OBJS += trace-perf.o
 OBJS += trace-timesync.o
 
 # Additional util objects
diff --git a/lib/trace-cmd/include/private/trace-cmd-private.h b/lib/trace-cmd/include/private/trace-cmd-private.h
index 37c9a82a..27a96c12 100644
--- a/lib/trace-cmd/include/private/trace-cmd-private.h
+++ b/lib/trace-cmd/include/private/trace-cmd-private.h
@@ -8,6 +8,7 @@
 
 #include <fcntl.h> /* for iovec */
 #include <sys/types.h>
+#include <linux/perf_event.h> /* for perf types */
 #include "traceevent/event-parse.h"
 #include "trace-cmd/trace-cmd.h"
 
@@ -513,4 +514,17 @@ void *tracecmd_record_page(struct tracecmd_input *handle,
 void *tracecmd_record_offset(struct tracecmd_input *handle,
 			     struct tep_record *record);
 
+/* trace-cmd Perf */
+struct trace_perf {
+	int fd;
+	int cpu;
+	int pid;
+	int pages;
+	struct perf_event_attr pe;
+	struct perf_event_mmap_page *mmap;
+};
+int trace_perf_init(struct trace_perf *perf, int pages, int cpu, int pid);
+int trace_perf_open(struct trace_perf *perf);
+void trace_perf_close(struct trace_perf *perf);
+
 #endif /* _TRACE_CMD_PRIVATE_H */
diff --git a/lib/trace-cmd/trace-perf.c b/lib/trace-cmd/trace-perf.c
new file mode 100644
index 00000000..f3ee692d
--- /dev/null
+++ b/lib/trace-cmd/trace-perf.c
@@ -0,0 +1,105 @@
+// SPDX-License-Identifier: LGPL-2.1
+/*
+ * Copyright (C) 2021, VMware, Tzvetomir Stoyanov <tz.stoyanov@gmail.com>
+ *
+ */
+#include <unistd.h>
+#include <sys/syscall.h>
+#include <sys/mman.h>
+
+#include "trace-cmd-private.h"
+
+static void default_perf_init_pe(struct perf_event_attr *pe)
+{
+	pe->type = PERF_TYPE_SOFTWARE;
+	pe->sample_type = PERF_SAMPLE_CPU;
+	pe->size = sizeof(struct perf_event_attr);
+	pe->config = PERF_COUNT_HW_CPU_CYCLES;
+	pe->disabled = 1;
+	pe->exclude_kernel = 1;
+	pe->freq = 1;
+	pe->sample_freq = 1000;
+	pe->inherit = 1;
+	pe->mmap = 1;
+	pe->comm = 1;
+	pe->task = 1;
+	pe->precise_ip = 1;
+	pe->sample_id_all = 1;
+	pe->read_format = PERF_FORMAT_ID |
+			PERF_FORMAT_TOTAL_TIME_ENABLED |
+			PERF_FORMAT_TOTAL_TIME_RUNNING;
+}
+
+/**
+ * trace_perf_init - Initialize perf context
+ *
+ * @perf: structure, representing perf context, that will be initialized.
+ * @pages: Number of perf memory mapped pages.
+ * @cpu: CPU number, associated with this perf context.
+ * @pid: PID, associated with this perf context.
+ *
+ * The perf context in initialized with default values. The caller can set
+ * custom perf parameters in perf->pe, before calling trace_perf_open() API.
+ *
+ * Returns 0 on success, or -1 in case of an error.
+ *
+ */
+int trace_perf_init(struct trace_perf *perf, int pages, int cpu, int pid)
+{
+	if (!perf)
+		return -1;
+
+	memset(perf, 0, sizeof(struct trace_perf));
+	default_perf_init_pe(&perf->pe);
+	perf->cpu = cpu;
+	perf->pages = pages;
+	perf->pid = pid;
+	perf->fd = -1;
+
+	return 0;
+}
+
+/**
+ * trace_perf_close - Close perf session
+ *
+ * @perf: structure, representing context of a running perf session, opened
+ *	  with trace_perf_open()
+ *
+ */
+void trace_perf_close(struct trace_perf *perf)
+{
+	if (perf->fd >= 0)
+		close(perf->fd);
+	perf->fd = -1;
+	if (perf->mmap)
+		munmap(perf->mmap, (perf->pages + 1) * getpagesize());
+	perf->mmap = NULL;
+}
+
+/**
+ * trace_perf_open - Open perf session
+ *
+ * @perf: structure, representing perf context that will be opened. It must be
+ *	  initialized with trace_perf_init().
+ *
+ * Returns 0 on success, or -1 in case of an error. In case of success, the
+ * session must be closed with trace_perf_close()
+ */
+int trace_perf_open(struct trace_perf *perf)
+{
+	perf->fd = syscall(__NR_perf_event_open, &perf->pe, perf->pid, perf->cpu, -1, 0);
+	if (perf->fd < 0)
+		return -1;
+	fcntl(perf->fd, F_SETFL, O_NONBLOCK);
+
+	perf->mmap = mmap(NULL, (perf->pages + 1) * getpagesize(),
+			  PROT_READ | PROT_WRITE, MAP_SHARED, perf->fd, 0);
+	if (perf->mmap == MAP_FAILED)
+		goto error;
+
+	return 0;
+
+error:
+	trace_perf_close(perf);
+	return -1;
+}
-- 
2.29.2

Re: [PATCH 01/12] trace-cmd: Add initial perf interface in trace-cmd library

[Steven Rostedt]

On Mon, 15 Mar 2021 08:18:21 +0200
"Tzvetomir Stoyanov (VMware)" <tz.stoyanov@gmail.com> wrote:

> +static void default_perf_init_pe(struct perf_event_attr *pe)
> +{
> +	pe->type = PERF_TYPE_SOFTWARE;
> +	pe->sample_type = PERF_SAMPLE_CPU;
> +	pe->size = sizeof(struct perf_event_attr);
> +	pe->config = PERF_COUNT_HW_CPU_CYCLES;
> +	pe->disabled = 1;
> +	pe->exclude_kernel = 1;
> +	pe->freq = 1;
> +	pe->sample_freq = 1000;
> +	pe->inherit = 1;
> +	pe->mmap = 1;
> +	pe->comm = 1;
> +	pe->task = 1;
> +	pe->precise_ip = 1;
> +	pe->sample_id_all = 1;

I tried to compile this on an old system and it fails to compile. We'll
need to add a compile time check if the perf functions are supported by the
user space, as trace-cmd should still build on these systems.

  COMPILE FPIC           trace-perf.o
trace-perf.c: In function ‘default_perf_init_pe’:
trace-perf.c:26: error: ‘struct perf_event_attr’ has no member named ‘precise_ip’
trace-perf.c:27: error: ‘struct perf_event_attr’ has no member named ‘sample_id_all’
make[1]: *** [/work/git/trace-cmd.git/lib/trace-cmd/trace-perf.o] Error 1


-- Steve


> +	pe->read_format = PERF_FORMAT_ID |
> +			PERF_FORMAT_TOTAL_TIME_ENABLED |
> +			PERF_FORMAT_TOTAL_TIME_RUNNING;
> +}

[PATCH 02/12] trace-cmd: Add logic for TSC to nanosecond conversion

[Tzvetomir Stoyanov (VMware)]

Added new logic to get multiplier and shift for converting TSC trace clock
to nanoseconds, using perf kernel interface. The new logic is used only in
host - guest tracing use case, when the user did not specify any tracing
clock and KVM time sync plugin is available. Then the x86-tsc clock is
auto selected for the current tracing session. There is one limitation -
per CPU multiplier or shift is not supported.

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

diff --git a/tracecmd/include/trace-local.h b/tracecmd/include/trace-local.h
index 6e39d27d..8a88ab9c 100644
--- a/tracecmd/include/trace-local.h
+++ b/tracecmd/include/trace-local.h
@@ -199,6 +199,12 @@ struct filter_pids {
 	int exclude;
 };
 
+struct tsc_nsec {
+	int mult;
+	int shift;
+	int offset;
+};
+
 struct buffer_instance {
 	struct buffer_instance	*next;
 	char			*name;
@@ -234,6 +240,7 @@ struct buffer_instance {
 	int			get_procmap;
 
 	const char		*clock;
+	struct tsc_nsec		tsc2nsec;
 	unsigned int		*client_ports;
 
 	struct trace_seq	*s_save;
diff --git a/tracecmd/trace-record.c b/tracecmd/trace-record.c
index a0eb0385..117e4f17 100644
--- a/tracecmd/trace-record.c
+++ b/tracecmd/trace-record.c
@@ -57,6 +57,7 @@
 #define MAX_LATENCY	"tracing_max_latency"
 #define STAMP		"stamp"
 #define FUNC_STACK_TRACE "func_stack_trace"
+#define TSC_CLOCK	"x86-tsc"
 
 enum trace_type {
 	TRACE_TYPE_RECORD	= 1,
@@ -4104,6 +4105,7 @@ enum {
 	DATA_FL_NONE		= 0,
 	DATA_FL_DATE		= 1,
 	DATA_FL_OFFSET		= 2,
+	DATA_FL_GUEST		= 4,
 };
 
 static void add_options(struct tracecmd_output *handle, struct common_record_context *ctx)
@@ -5676,6 +5678,100 @@ check_instance_die(struct buffer_instance *instance, char *param)
 		    tracefs_instance_get_name(instance->tracefs), param);
 }
 
+static int get_tsc_nsec(int *shift, int *mult, int *offset)
+{
+	int cpus = tracecmd_count_cpus();
+	int cpu_shift, cpu_mult, cpu_offset;
+	struct trace_perf perf;
+	int ret;
+	int i;
+
+	ret = trace_perf_init(&perf, 1, 0, getpid());
+	if (!ret)
+		ret = trace_perf_open(&perf);
+	if (ret)
+		return ret;
+	cpu_shift = perf.mmap->time_shift;
+	cpu_mult = perf.mmap->time_mult;
+	/* ToDo set the offset, should we use perf.mmap->time_offset ? */
+	cpu_offset = 0;
+	for (i = 1; i < cpus; i++) {
+		trace_perf_close(&perf);
+		ret = trace_perf_init(&perf, 1, i, getpid());
+		if (!ret)
+			ret = trace_perf_open(&perf);
+		if (ret)
+			break;
+		if (perf.mmap->time_shift != cpu_shift ||
+		    perf.mmap->time_mult != cpu_mult) {
+			warning("Found different TSC multiplier and shift for CPU %d: %d;%d instead of %d;%d",
+				i, perf.mmap->time_mult, perf.mmap->time_shift, cpu_mult, cpu_shift);
+			break;
+		}
+	}
+	trace_perf_close(&perf);
+	if (i < cpus)
+		return -1;
+
+	*shift = cpu_shift;
+	*mult = cpu_mult;
+	*offset = cpu_offset;
+
+	return 0;
+}
+
+static void set_vsync_clock(void)
+{
+	const char *clock = top_instance.clock;
+	struct buffer_instance *instance;
+	bool tsc2nsec = false;
+	int shift, mult, offset;
+
+	/*
+	 * If no clock is specified for the top trace instance AND
+	 * KVM time sync protocol is available AND
+	 * TSC to nsec multiplier and shift are available:
+	 * force using the x86-tsc clock for this host-guest tracing session
+	 * and store TSC to nsec multiplier and shift.
+	 */
+	if (!clock && tsync_proto_is_supported("kvm") &&
+	    !get_tsc_nsec(&shift, &mult, &offset) && mult) {
+		top_instance.clock = strdup(TSC_CLOCK);
+		if (!top_instance.clock)
+			die("Could not allocate top instance clock");
+		clock = top_instance.clock;
+		top_instance.tsc2nsec.mult = mult;
+		top_instance.tsc2nsec.shift = shift;
+		top_instance.tsc2nsec.offset = offset;
+		tsc2nsec = true;
+	}
+
+	if (!clock && !top_instance.tsync_loop_interval)
+		return;
+	for_all_instances(instance) {
+		if (clock) {
+			/* use the same clock in all tracing peers */
+			if (is_guest(instance) &&
+			    !(instance->flags & BUFFER_FL_HAS_CLOCK)) {
+				add_argv(instance,
+					 (char *)top_instance.clock, true);
+				add_argv(instance, "-C", true);
+				if (!instance->clock) {
+					instance->clock = strdup((char *)top_instance.clock);
+					if (!instance->clock)
+						die("Could not allocate instance clock");
+				}
+				if (tsc2nsec) {
+					instance->tsc2nsec.mult = mult;
+					instance->tsc2nsec.shift = shift;
+					instance->tsc2nsec.offset = offset;
+				}
+			}
+		}
+		instance->tsync_loop_interval = top_instance.tsync_loop_interval;
+	}
+}
+
 static void parse_record_options(int argc,
 				 char **argv,
 				 enum trace_cmd curr_cmd,
@@ -5691,7 +5787,6 @@ static void parse_record_options(int argc,
 	int name_counter = 0;
 	int negative = 0;
 	struct buffer_instance *instance, *del_list = NULL;
-	bool guest_sync_set = false;
 	int do_children = 0;
 	int fpids_count = 0;
 
@@ -5825,6 +5920,7 @@ static void parse_record_options(int argc,
 			ctx->instance->port = port;
 			ctx->instance->name = name;
 			add_instance(ctx->instance, 0);
+			ctx->data_flags |= DATA_FL_GUEST;
 			break;
 		}
 		case 'F':
@@ -5872,8 +5968,6 @@ static void parse_record_options(int argc,
 			check_instance_die(ctx->instance, "-C");
 			ctx->instance->clock = optarg;
 			ctx->instance->flags |= BUFFER_FL_HAS_CLOCK;
-			if (is_top_instance(ctx->instance))
-				guest_sync_set = true;
 			break;
 		case 'v':
 			negative = 1;
@@ -6118,7 +6212,6 @@ static void parse_record_options(int argc,
 		case OPT_tsyncinterval:
 			cmd_check_die(ctx, CMD_set, *(argv+1), "--tsync-interval");
 			top_instance.tsync_loop_interval = atoi(optarg);
-			guest_sync_set = true;
 			break;
 		case OPT_fork:
 			if (!IS_START(ctx))
@@ -6145,26 +6238,6 @@ static void parse_record_options(int argc,
 				add_argv(instance, "--date", true);
 		}
 	}
-	if (guest_sync_set) {
-	/* If -C is specified, prepend clock to all guest VM flags */
-		for_all_instances(instance) {
-			if (top_instance.clock) {
-				if (is_guest(instance) &&
-				    !(instance->flags & BUFFER_FL_HAS_CLOCK)) {
-					add_argv(instance,
-						 (char *)top_instance.clock,
-						 true);
-					add_argv(instance, "-C", true);
-					if (!instance->clock) {
-						instance->clock = strdup((char *)top_instance.clock);
-						if (!instance->clock)
-							die("Could not allocate instance clock");
-					}
-				}
-			}
-			instance->tsync_loop_interval = top_instance.tsync_loop_interval;
-		}
-	}
 
 	if (!ctx->filtered && ctx->instance->filter_mod)
 		add_func(&ctx->instance->filter_funcs,
@@ -6301,6 +6374,9 @@ static void record_trace(int argc, char **argv,
 	if (!ctx->output)
 		ctx->output = DEFAULT_INPUT_FILE;
 
+	if (ctx->data_flags & DATA_FL_GUEST)
+		set_vsync_clock();
+
 	make_instances();
 
 	/* Save the state of tracing_on before starting */
-- 
2.29.2

Re: [PATCH 02/12] trace-cmd: Add logic for TSC to nanosecond conversion

[Steven Rostedt]

On Mon, 15 Mar 2021 08:18:22 +0200
"Tzvetomir Stoyanov (VMware)" <tz.stoyanov@gmail.com> wrote:

> Added new logic to get multiplier and shift for converting TSC trace clock
> to nanoseconds, using perf kernel interface. The new logic is used only in
> host - guest tracing use case, when the user did not specify any tracing
> clock and KVM time sync plugin is available. Then the x86-tsc clock is
> auto selected for the current tracing session. There is one limitation -
> per CPU multiplier or shift is not supported.

I would break this up into two patches. One that adds the perf mult shift
logic, and even allow users to use it! As TSC clocks are still faster than
the local clock (as the local clock needs to do the multiplier and shift at
every event while recording). It would be a feature to have this:

 trace-cmd record --tsc2nsec ...

Where it would use -C x86-tsc clock (or perhaps this can work for other
architectures), and then use the perf multi/shift to determine the
nanoseconds.

I would get this working first, before trying to use that for guests and
hosts.


> 
> Signed-off-by: Tzvetomir Stoyanov (VMware) <tz.stoyanov@gmail.com>
> ---
>  tracecmd/include/trace-local.h |   7 ++
>  tracecmd/trace-record.c        | 124 ++++++++++++++++++++++++++-------
>  2 files changed, 107 insertions(+), 24 deletions(-)
> 
> diff --git a/tracecmd/include/trace-local.h b/tracecmd/include/trace-local.h
> index 6e39d27d..8a88ab9c 100644
> --- a/tracecmd/include/trace-local.h
> +++ b/tracecmd/include/trace-local.h
> @@ -199,6 +199,12 @@ struct filter_pids {
>  	int exclude;
>  };
>  
> +struct tsc_nsec {
> +	int mult;
> +	int shift;
> +	int offset;

The above is twelve bytes in size (even on 64 bit machines).

> +};
> +
>  struct buffer_instance {
>  	struct buffer_instance	*next;
>  	char			*name;
> @@ -234,6 +240,7 @@ struct buffer_instance {
>  	int			get_procmap;
>  
>  	const char		*clock;
> +	struct tsc_nsec		tsc2nsec;
>  	unsigned int		*client_ports;

You put the twelve byte structure between two pointers. That's going to
guarantee a 4 byte hole on 64 bit machines.

You want to try to keep pointers together, and keep 4 byte in pairs such
that the other fields can line up on 8 byte alignment.


>  
>  	struct trace_seq	*s_save;
> diff --git a/tracecmd/trace-record.c b/tracecmd/trace-record.c
> index a0eb0385..117e4f17 100644
> --- a/tracecmd/trace-record.c
> +++ b/tracecmd/trace-record.c
> @@ -57,6 +57,7 @@
>  #define MAX_LATENCY	"tracing_max_latency"
>  #define STAMP		"stamp"
>  #define FUNC_STACK_TRACE "func_stack_trace"
> +#define TSC_CLOCK	"x86-tsc"
>  
>  enum trace_type {
>  	TRACE_TYPE_RECORD	= 1,
> @@ -4104,6 +4105,7 @@ enum {
>  	DATA_FL_NONE		= 0,
>  	DATA_FL_DATE		= 1,
>  	DATA_FL_OFFSET		= 2,
> +	DATA_FL_GUEST		= 4,
>  };
>  
>  static void add_options(struct tracecmd_output *handle, struct common_record_context *ctx)
> @@ -5676,6 +5678,100 @@ check_instance_die(struct buffer_instance *instance, char *param)
>  		    tracefs_instance_get_name(instance->tracefs), param);
>  }
>  
> +static int get_tsc_nsec(int *shift, int *mult, int *offset)
> +{
> +	int cpus = tracecmd_count_cpus();
> +	int cpu_shift, cpu_mult, cpu_offset;
> +	struct trace_perf perf;
> +	int ret;
> +	int i;
> +
> +	ret = trace_perf_init(&perf, 1, 0, getpid());
> +	if (!ret)
> +		ret = trace_perf_open(&perf);
> +	if (ret)
> +		return ret;
> +	cpu_shift = perf.mmap->time_shift;
> +	cpu_mult = perf.mmap->time_mult;
> +	/* ToDo set the offset, should we use perf.mmap->time_offset ? */
> +	cpu_offset = 0;

As discussed, may just be creating an instance, setting the clock to
x86-tsc (we'll need to make this arch independent when other archs have
similar functionality), write to the trace marker, then read it, and use
that timestamp as a starting point.

> +	for (i = 1; i < cpus; i++) {
> +		trace_perf_close(&perf);
> +		ret = trace_perf_init(&perf, 1, i, getpid());
> +		if (!ret)

I would just add:
		if (ret)
			break;

And not have the next call done in the if statement. That's awkward to read.

> +			ret = trace_perf_open(&perf);
> +		if (ret)
> +			break;
> +		if (perf.mmap->time_shift != cpu_shift ||
> +		    perf.mmap->time_mult != cpu_mult) {
> +			warning("Found different TSC multiplier and shift for CPU %d: %d;%d instead of %d;%d",
> +				i, perf.mmap->time_mult, perf.mmap->time_shift, cpu_mult, cpu_shift);
> +			break;
> +		}
> +	}
> +	trace_perf_close(&perf);
> +	if (i < cpus)
> +		return -1;
> +
> +	*shift = cpu_shift;
> +	*mult = cpu_mult;
> +	*offset = cpu_offset;
> +
> +	return 0;
> +}
> +
> +static void set_vsync_clock(void)
> +{
> +	const char *clock = top_instance.clock;
> +	struct buffer_instance *instance;
> +	bool tsc2nsec = false;
> +	int shift, mult, offset;
> +
> +	/*
> +	 * If no clock is specified for the top trace instance AND
> +	 * KVM time sync protocol is available AND
> +	 * TSC to nsec multiplier and shift are available:
> +	 * force using the x86-tsc clock for this host-guest tracing session
> +	 * and store TSC to nsec multiplier and shift.
> +	 */
> +	if (!clock && tsync_proto_is_supported("kvm") &&
> +	    !get_tsc_nsec(&shift, &mult, &offset) && mult) {
> +		top_instance.clock = strdup(TSC_CLOCK);
> +		if (!top_instance.clock)
> +			die("Could not allocate top instance clock");
> +		clock = top_instance.clock;

Why is this using the top_instance? What if the user had done:

 # trace-cmd record -B host -e kvm -e sched -A guest -e sched


-- Steve


> +		top_instance.tsc2nsec.mult = mult;
> +		top_instance.tsc2nsec.shift = shift;
> +		top_instance.tsc2nsec.offset = offset;
> +		tsc2nsec = true;
> +	}
> +
> +	if (!clock && !top_instance.tsync_loop_interval)
> +		return;
> +	for_all_instances(instance) {
> +		if (clock) {
> +			/* use the same clock in all tracing peers */
> +			if (is_guest(instance) &&
> +			    !(instance->flags & BUFFER_FL_HAS_CLOCK)) {
> +				add_argv(instance,
> +					 (char *)top_instance.clock, true);
> +				add_argv(instance, "-C", true);
> +				if (!instance->clock) {
> +					instance->clock = strdup((char *)top_instance.clock);
> +					if (!instance->clock)
> +						die("Could not allocate instance clock");
> +				}
> +				if (tsc2nsec) {
> +					instance->tsc2nsec.mult = mult;
> +					instance->tsc2nsec.shift = shift;
> +					instance->tsc2nsec.offset = offset;
> +				}
> +			}
> +		}
> +		instance->tsync_loop_interval = top_instance.tsync_loop_interval;
> +	}
> +}
> +
>  static void parse_record_options(int argc,
>  				 char **argv,
>  				 enum trace_cmd curr_cmd,
> @@ -5691,7 +5787,6 @@ static void parse_record_options(int argc,
>  	int name_counter = 0;
>  	int negative = 0;
>  	struct buffer_instance *instance, *del_list = NULL;
> -	bool guest_sync_set = false;
>  	int do_children = 0;
>  	int fpids_count = 0;
>  
> @@ -5825,6 +5920,7 @@ static void parse_record_options(int argc,
>  			ctx->instance->port = port;
>  			ctx->instance->name = name;
>  			add_instance(ctx->instance, 0);
> +			ctx->data_flags |= DATA_FL_GUEST;
>  			break;
>  		}
>  		case 'F':
> @@ -5872,8 +5968,6 @@ static void parse_record_options(int argc,
>  			check_instance_die(ctx->instance, "-C");
>  			ctx->instance->clock = optarg;
>  			ctx->instance->flags |= BUFFER_FL_HAS_CLOCK;
> -			if (is_top_instance(ctx->instance))
> -				guest_sync_set = true;
>  			break;
>  		case 'v':
>  			negative = 1;
> @@ -6118,7 +6212,6 @@ static void parse_record_options(int argc,
>  		case OPT_tsyncinterval:
>  			cmd_check_die(ctx, CMD_set, *(argv+1), "--tsync-interval");
>  			top_instance.tsync_loop_interval = atoi(optarg);
> -			guest_sync_set = true;
>  			break;
>  		case OPT_fork:
>  			if (!IS_START(ctx))
> @@ -6145,26 +6238,6 @@ static void parse_record_options(int argc,
>  				add_argv(instance, "--date", true);
>  		}
>  	}
> -	if (guest_sync_set) {
> -	/* If -C is specified, prepend clock to all guest VM flags */
> -		for_all_instances(instance) {
> -			if (top_instance.clock) {
> -				if (is_guest(instance) &&
> -				    !(instance->flags & BUFFER_FL_HAS_CLOCK)) {
> -					add_argv(instance,
> -						 (char *)top_instance.clock,
> -						 true);
> -					add_argv(instance, "-C", true);
> -					if (!instance->clock) {
> -						instance->clock = strdup((char *)top_instance.clock);
> -						if (!instance->clock)
> -							die("Could not allocate instance clock");
> -					}
> -				}
> -			}
> -			instance->tsync_loop_interval = top_instance.tsync_loop_interval;
> -		}
> -	}
>  
>  	if (!ctx->filtered && ctx->instance->filter_mod)
>  		add_func(&ctx->instance->filter_funcs,
> @@ -6301,6 +6374,9 @@ static void record_trace(int argc, char **argv,
>  	if (!ctx->output)
>  		ctx->output = DEFAULT_INPUT_FILE;
>  
> +	if (ctx->data_flags & DATA_FL_GUEST)
> +		set_vsync_clock();
> +
>  	make_instances();
>  
>  	/* Save the state of tracing_on before starting */

Re: [PATCH 02/12] trace-cmd: Add logic for TSC to nanosecond conversion

[Tzvetomir Stoyanov]

On Tue, Mar 16, 2021 at 11:17 PM Steven Rostedt <rostedt@goodmis.org> wrote:
>
> On Mon, 15 Mar 2021 08:18:22 +0200
> "Tzvetomir Stoyanov (VMware)" <tz.stoyanov@gmail.com> wrote:
>
> > Added new logic to get multiplier and shift for converting TSC trace clock
> > to nanoseconds, using perf kernel interface. The new logic is used only in
> > host - guest tracing use case, when the user did not specify any tracing
> > clock and KVM time sync plugin is available. Then the x86-tsc clock is
> > auto selected for the current tracing session. There is one limitation -
> > per CPU multiplier or shift is not supported.
>
> I would break this up into two patches. One that adds the perf mult shift
> logic, and even allow users to use it! As TSC clocks are still faster than
> the local clock (as the local clock needs to do the multiplier and shift at
> every event while recording). It would be a feature to have this:
>
>  trace-cmd record --tsc2nsec ...

As the tracing clock is per instance, does it mean this flag should
also be per instance ? I think the below commands should be valid:
   trace-cmd record --tsc2nsec -B foo -C mono  <-- use tsc-x86 clock +
tsc2nsec for the top instance and mono clock for instance foo
   trace-cmd record -C mono -B foo --tsc2nsec  <-- use mono clock for
the top instance and tsc-x86 clock + tsc2nsec clock for instance foo
or even more confusing:
   trace-cmd record -C x86-tsc -B foo --tsc2nsec  <-- use tsc-x86
clock for the top instance and tsc-x86 clock + tsc2nsec clock for
instance foo
This will require changes in the trace.dat file format. The problem is
that tsc2nsec multiplier, shift and offset are stored as an option in
the trace.dat file. Options are global, not per instance. When reading
the file, how to determine events in which instance should be affected
by this option ? We should either add options per instance, or somehow
encode the instance scope of each option.

>
> Where it would use -C x86-tsc clock (or perhaps this can work for other
> architectures), and then use the perf multi/shift to determine the
> nanoseconds.
>
> I would get this working first, before trying to use that for guests and
> hosts.
>
>
> >
> > Signed-off-by: Tzvetomir Stoyanov (VMware) <tz.stoyanov@gmail.com>
> > ---
> >  tracecmd/include/trace-local.h |   7 ++
> >  tracecmd/trace-record.c        | 124 ++++++++++++++++++++++++++-------
> >  2 files changed, 107 insertions(+), 24 deletions(-)
> >
> > diff --git a/tracecmd/include/trace-local.h b/tracecmd/include/trace-local.h
> > index 6e39d27d..8a88ab9c 100644
> > --- a/tracecmd/include/trace-local.h
> > +++ b/tracecmd/include/trace-local.h
> > @@ -199,6 +199,12 @@ struct filter_pids {
> >       int exclude;
> >  };
> >
> > +struct tsc_nsec {
> > +     int mult;
> > +     int shift;
> > +     int offset;
>
> The above is twelve bytes in size (even on 64 bit machines).
>
> > +};
> > +
> >  struct buffer_instance {
> >       struct buffer_instance  *next;
> >       char                    *name;
> > @@ -234,6 +240,7 @@ struct buffer_instance {
> >       int                     get_procmap;
> >
> >       const char              *clock;
> > +     struct tsc_nsec         tsc2nsec;
> >       unsigned int            *client_ports;
>
> You put the twelve byte structure between two pointers. That's going to
> guarantee a 4 byte hole on 64 bit machines.
>
> You want to try to keep pointers together, and keep 4 byte in pairs such
> that the other fields can line up on 8 byte alignment.
>
>
> >
> >       struct trace_seq        *s_save;
> > diff --git a/tracecmd/trace-record.c b/tracecmd/trace-record.c
> > index a0eb0385..117e4f17 100644
> > --- a/tracecmd/trace-record.c
> > +++ b/tracecmd/trace-record.c
> > @@ -57,6 +57,7 @@
> >  #define MAX_LATENCY  "tracing_max_latency"
> >  #define STAMP                "stamp"
> >  #define FUNC_STACK_TRACE "func_stack_trace"
> > +#define TSC_CLOCK    "x86-tsc"
> >
> >  enum trace_type {
> >       TRACE_TYPE_RECORD       = 1,
> > @@ -4104,6 +4105,7 @@ enum {
> >       DATA_FL_NONE            = 0,
> >       DATA_FL_DATE            = 1,
> >       DATA_FL_OFFSET          = 2,
> > +     DATA_FL_GUEST           = 4,
> >  };
> >
> >  static void add_options(struct tracecmd_output *handle, struct common_record_context *ctx)
> > @@ -5676,6 +5678,100 @@ check_instance_die(struct buffer_instance *instance, char *param)
> >                   tracefs_instance_get_name(instance->tracefs), param);
> >  }
> >
> > +static int get_tsc_nsec(int *shift, int *mult, int *offset)
> > +{
> > +     int cpus = tracecmd_count_cpus();
> > +     int cpu_shift, cpu_mult, cpu_offset;
> > +     struct trace_perf perf;
> > +     int ret;
> > +     int i;
> > +
> > +     ret = trace_perf_init(&perf, 1, 0, getpid());
> > +     if (!ret)
> > +             ret = trace_perf_open(&perf);
> > +     if (ret)
> > +             return ret;
> > +     cpu_shift = perf.mmap->time_shift;
> > +     cpu_mult = perf.mmap->time_mult;
> > +     /* ToDo set the offset, should we use perf.mmap->time_offset ? */
> > +     cpu_offset = 0;
>
> As discussed, may just be creating an instance, setting the clock to
> x86-tsc (we'll need to make this arch independent when other archs have
> similar functionality), write to the trace marker, then read it, and use
> that timestamp as a starting point.
>
> > +     for (i = 1; i < cpus; i++) {
> > +             trace_perf_close(&perf);
> > +             ret = trace_perf_init(&perf, 1, i, getpid());
> > +             if (!ret)
>
> I would just add:
>                 if (ret)
>                         break;
>
> And not have the next call done in the if statement. That's awkward to read.
>
> > +                     ret = trace_perf_open(&perf);
> > +             if (ret)
> > +                     break;
> > +             if (perf.mmap->time_shift != cpu_shift ||
> > +                 perf.mmap->time_mult != cpu_mult) {
> > +                     warning("Found different TSC multiplier and shift for CPU %d: %d;%d instead of %d;%d",
> > +                             i, perf.mmap->time_mult, perf.mmap->time_shift, cpu_mult, cpu_shift);
> > +                     break;
> > +             }
> > +     }
> > +     trace_perf_close(&perf);
> > +     if (i < cpus)
> > +             return -1;
> > +
> > +     *shift = cpu_shift;
> > +     *mult = cpu_mult;
> > +     *offset = cpu_offset;
> > +
> > +     return 0;
> > +}
> > +
> > +static void set_vsync_clock(void)
> > +{
> > +     const char *clock = top_instance.clock;
> > +     struct buffer_instance *instance;
> > +     bool tsc2nsec = false;
> > +     int shift, mult, offset;
> > +
> > +     /*
> > +      * If no clock is specified for the top trace instance AND
> > +      * KVM time sync protocol is available AND
> > +      * TSC to nsec multiplier and shift are available:
> > +      * force using the x86-tsc clock for this host-guest tracing session
> > +      * and store TSC to nsec multiplier and shift.
> > +      */
> > +     if (!clock && tsync_proto_is_supported("kvm") &&
> > +         !get_tsc_nsec(&shift, &mult, &offset) && mult) {
> > +             top_instance.clock = strdup(TSC_CLOCK);
> > +             if (!top_instance.clock)
> > +                     die("Could not allocate top instance clock");
> > +             clock = top_instance.clock;
>
> Why is this using the top_instance? What if the user had done:
>
>  # trace-cmd record -B host -e kvm -e sched -A guest -e sched

You are right, that command is valid. The problem is that guest
timestamps can be synchronized with one clock only. If there are two
instances on the host, each with a different clock, the
synchronization will not work. That's why I look at the top instance
clock only, which is wrong. I'll change that logic to take the first
configured host trace clock, i.e. in case of multiple host instances
with multiple trace clocks, the first wins.

>
>
> -- Steve
>
>
> > +             top_instance.tsc2nsec.mult = mult;
> > +             top_instance.tsc2nsec.shift = shift;
> > +             top_instance.tsc2nsec.offset = offset;
> > +             tsc2nsec = true;
> > +     }
> > +
> > +     if (!clock && !top_instance.tsync_loop_interval)
> > +             return;
> > +     for_all_instances(instance) {
> > +             if (clock) {
> > +                     /* use the same clock in all tracing peers */
> > +                     if (is_guest(instance) &&
> > +                         !(instance->flags & BUFFER_FL_HAS_CLOCK)) {
> > +                             add_argv(instance,
> > +                                      (char *)top_instance.clock, true);
> > +                             add_argv(instance, "-C", true);
> > +                             if (!instance->clock) {
> > +                                     instance->clock = strdup((char *)top_instance.clock);
> > +                                     if (!instance->clock)
> > +                                             die("Could not allocate instance clock");
> > +                             }
> > +                             if (tsc2nsec) {
> > +                                     instance->tsc2nsec.mult = mult;
> > +                                     instance->tsc2nsec.shift = shift;
> > +                                     instance->tsc2nsec.offset = offset;
> > +                             }
> > +                     }
> > +             }
> > +             instance->tsync_loop_interval = top_instance.tsync_loop_interval;
> > +     }
> > +}
> > +
> >  static void parse_record_options(int argc,
> >                                char **argv,
> >                                enum trace_cmd curr_cmd,
> > @@ -5691,7 +5787,6 @@ static void parse_record_options(int argc,
> >       int name_counter = 0;
> >       int negative = 0;
> >       struct buffer_instance *instance, *del_list = NULL;
> > -     bool guest_sync_set = false;
> >       int do_children = 0;
> >       int fpids_count = 0;
> >
> > @@ -5825,6 +5920,7 @@ static void parse_record_options(int argc,
> >                       ctx->instance->port = port;
> >                       ctx->instance->name = name;
> >                       add_instance(ctx->instance, 0);
> > +                     ctx->data_flags |= DATA_FL_GUEST;
> >                       break;
> >               }
> >               case 'F':
> > @@ -5872,8 +5968,6 @@ static void parse_record_options(int argc,
> >                       check_instance_die(ctx->instance, "-C");
> >                       ctx->instance->clock = optarg;
> >                       ctx->instance->flags |= BUFFER_FL_HAS_CLOCK;
> > -                     if (is_top_instance(ctx->instance))
> > -                             guest_sync_set = true;
> >                       break;
> >               case 'v':
> >                       negative = 1;
> > @@ -6118,7 +6212,6 @@ static void parse_record_options(int argc,
> >               case OPT_tsyncinterval:
> >                       cmd_check_die(ctx, CMD_set, *(argv+1), "--tsync-interval");
> >                       top_instance.tsync_loop_interval = atoi(optarg);
> > -                     guest_sync_set = true;
> >                       break;
> >               case OPT_fork:
> >                       if (!IS_START(ctx))
> > @@ -6145,26 +6238,6 @@ static void parse_record_options(int argc,
> >                               add_argv(instance, "--date", true);
> >               }
> >       }
> > -     if (guest_sync_set) {
> > -     /* If -C is specified, prepend clock to all guest VM flags */
> > -             for_all_instances(instance) {
> > -                     if (top_instance.clock) {
> > -                             if (is_guest(instance) &&
> > -                                 !(instance->flags & BUFFER_FL_HAS_CLOCK)) {
> > -                                     add_argv(instance,
> > -                                              (char *)top_instance.clock,
> > -                                              true);
> > -                                     add_argv(instance, "-C", true);
> > -                                     if (!instance->clock) {
> > -                                             instance->clock = strdup((char *)top_instance.clock);
> > -                                             if (!instance->clock)
> > -                                                     die("Could not allocate instance clock");
> > -                                     }
> > -                             }
> > -                     }
> > -                     instance->tsync_loop_interval = top_instance.tsync_loop_interval;
> > -             }
> > -     }
> >
> >       if (!ctx->filtered && ctx->instance->filter_mod)
> >               add_func(&ctx->instance->filter_funcs,
> > @@ -6301,6 +6374,9 @@ static void record_trace(int argc, char **argv,
> >       if (!ctx->output)
> >               ctx->output = DEFAULT_INPUT_FILE;
> >
> > +     if (ctx->data_flags & DATA_FL_GUEST)
> > +             set_vsync_clock();
> > +
> >       make_instances();
> >
> >       /* Save the state of tracing_on before starting */
>


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

Re: [PATCH 02/12] trace-cmd: Add logic for TSC to nanosecond conversion

[Steven Rostedt]

On Wed, 17 Mar 2021 11:57:31 +0200
Tzvetomir Stoyanov <tz.stoyanov@gmail.com> wrote:

> > I would break this up into two patches. One that adds the perf mult shift
> > logic, and even allow users to use it! As TSC clocks are still faster than
> > the local clock (as the local clock needs to do the multiplier and shift at
> > every event while recording). It would be a feature to have this:
> >
> >  trace-cmd record --tsc2nsec ...  
> 
> As the tracing clock is per instance, does it mean this flag should
> also be per instance ? I think the below commands should be valid:
>    trace-cmd record --tsc2nsec -B foo -C mono  <-- use tsc-x86 clock +
> tsc2nsec for the top instance and mono clock for instance foo
>    trace-cmd record -C mono -B foo --tsc2nsec  <-- use mono clock for
> the top instance and tsc-x86 clock + tsc2nsec clock for instance foo
> or even more confusing:
>    trace-cmd record -C x86-tsc -B foo --tsc2nsec  <-- use tsc-x86
> clock for the top instance and tsc-x86 clock + tsc2nsec clock for
> instance foo

I just remembered that I previously discussed making the "tsc2nsec" into a
clock type from the perspective of the user (not the trace file). That is,
not to have --tsc2nsec, but instead to have:

 trace-cmd record -C tsc2nsec

And see if there's a tsc clock and the perf interface is available with the
multiplier and shift, and if not, it would return an error just like if you
said "-C foo". I also remember saying that we should have trace-cmd list
show it as well if it is available.

 # trace-cmd list -C
[local] global counter uptime perf mono mono_raw boot x86-tsc tsc2nsec

That is, tack on at the end " tsc2nsec" if we find that it is available.

> This will require changes in the trace.dat file format. The problem is
> that tsc2nsec multiplier, shift and offset are stored as an option in
> the trace.dat file. Options are global, not per instance. When reading
> the file, how to determine events in which instance should be affected
> by this option ? We should either add options per instance, or somehow
> encode the instance scope of each option.

Your right. And I just tried this:

 # trace-cmd record -C x86-tsc -e sched -B foo -C local -e sched sleep 1

And it appears to ignore the -C local. Which I think is the right thing to
do ;-)

Yeah, we should only support one clock for all instances. And keep this as
a global option. We may in the future have instance options, but that will
come as a separate "option" :-)


> > > +static void set_vsync_clock(void)
> > > +{
> > > +     const char *clock = top_instance.clock;
> > > +     struct buffer_instance *instance;
> > > +     bool tsc2nsec = false;
> > > +     int shift, mult, offset;
> > > +
> > > +     /*
> > > +      * If no clock is specified for the top trace instance AND
> > > +      * KVM time sync protocol is available AND
> > > +      * TSC to nsec multiplier and shift are available:
> > > +      * force using the x86-tsc clock for this host-guest tracing session
> > > +      * and store TSC to nsec multiplier and shift.
> > > +      */
> > > +     if (!clock && tsync_proto_is_supported("kvm") &&
> > > +         !get_tsc_nsec(&shift, &mult, &offset) && mult) {
> > > +             top_instance.clock = strdup(TSC_CLOCK);
> > > +             if (!top_instance.clock)
> > > +                     die("Could not allocate top instance clock");
> > > +             clock = top_instance.clock;  
> >
> > Why is this using the top_instance? What if the user had done:
> >
> >  # trace-cmd record -B host -e kvm -e sched -A guest -e sched  
> 
> You are right, that command is valid. The problem is that guest
> timestamps can be synchronized with one clock only. If there are two
> instances on the host, each with a different clock, the
> synchronization will not work. That's why I look at the top instance
> clock only, which is wrong. I'll change that logic to take the first
> configured host trace clock, i.e. in case of multiple host instances
> with multiple trace clocks, the first wins.
> 


The code should just use the first instance available. Not about being
global, but because I want trace-cmd to not interfere with the top instance
if it is not specified on the command line. That way we can have this:

 # trace-cmd record -e all

in one window, and in another window:

 # trace-cmd record -B guest -e kvm -A guest -e all

and that recorder not do anything to bother the first one. That is, we
should only touch the top instance if it is explicitly specified.


-- Steve

Re: [PATCH 02/12] trace-cmd: Add logic for TSC to nanosecond conversion

[Tzvetomir Stoyanov]

On Wed, Mar 17, 2021 at 11:49 PM Steven Rostedt <rostedt@goodmis.org> wrote:
>
> On Wed, 17 Mar 2021 11:57:31 +0200
> Tzvetomir Stoyanov <tz.stoyanov@gmail.com> wrote:
>
> > > I would break this up into two patches. One that adds the perf mult shift
> > > logic, and even allow users to use it! As TSC clocks are still faster than
> > > the local clock (as the local clock needs to do the multiplier and shift at
> > > every event while recording). It would be a feature to have this:
> > >
> > >  trace-cmd record --tsc2nsec ...
> >
> > As the tracing clock is per instance, does it mean this flag should
> > also be per instance ? I think the below commands should be valid:
> >    trace-cmd record --tsc2nsec -B foo -C mono  <-- use tsc-x86 clock +
> > tsc2nsec for the top instance and mono clock for instance foo
> >    trace-cmd record -C mono -B foo --tsc2nsec  <-- use mono clock for
> > the top instance and tsc-x86 clock + tsc2nsec clock for instance foo
> > or even more confusing:
> >    trace-cmd record -C x86-tsc -B foo --tsc2nsec  <-- use tsc-x86
> > clock for the top instance and tsc-x86 clock + tsc2nsec clock for
> > instance foo
>
> I just remembered that I previously discussed making the "tsc2nsec" into a
> clock type from the perspective of the user (not the trace file). That is,
> not to have --tsc2nsec, but instead to have:
>
>  trace-cmd record -C tsc2nsec
>
> And see if there's a tsc clock and the perf interface is available with the
> multiplier and shift, and if not, it would return an error just like if you
> said "-C foo". I also remember saying that we should have trace-cmd list
> show it as well if it is available.
>
>  # trace-cmd list -C
> [local] global counter uptime perf mono mono_raw boot x86-tsc tsc2nsec
>
> That is, tack on at the end " tsc2nsec" if we find that it is available.
>
> > This will require changes in the trace.dat file format. The problem is
> > that tsc2nsec multiplier, shift and offset are stored as an option in
> > the trace.dat file. Options are global, not per instance. When reading
> > the file, how to determine events in which instance should be affected
> > by this option ? We should either add options per instance, or somehow
> > encode the instance scope of each option.
>
> Your right. And I just tried this:
>
>  # trace-cmd record -C x86-tsc -e sched -B foo -C local -e sched sleep 1
>
> And it appears to ignore the -C local. Which I think is the right thing to
> do ;-)

According to the code, trace-cmd supports clock per instance. And it
works, I tried this:

#trace-cmd record -C x86-tsc -e irq -B foo -C local -e sched sleep 1

and got different clocks:
             <...>-290676 [006]1956659520918: softirq_exit:        ....
foo:       zoom-10894 [004]112198623756671: sched_switch:  ....

although I cannot imagine a use case for this. It will be weird to
visualise this by KerneShark.

I think that we should introduce options per instance now,  as "-C
tsc2nsec" cannot be implemented without it.
I see two possible ways to implement it:
 1. Break the current trace.dat file format by adding metadata for
each instance.
 2. Keep the current format and use nested options -  that's it, just
another option "OPTION_INSTANCE". It will hold instance name and all
options, specific for that instance, using the current options format.

But there is one question, valid for both ways: What should be the
scope for the global options ? Apply them only on the top instance, or
they should be common for all instances ?

>
> Yeah, we should only support one clock for all instances. And keep this as
> a global option. We may in the future have instance options, but that will
> come as a separate "option" :-)
>
>
> > > > +static void set_vsync_clock(void)
> > > > +{
> > > > +     const char *clock = top_instance.clock;
> > > > +     struct buffer_instance *instance;
> > > > +     bool tsc2nsec = false;
> > > > +     int shift, mult, offset;
> > > > +
> > > > +     /*
> > > > +      * If no clock is specified for the top trace instance AND
> > > > +      * KVM time sync protocol is available AND
> > > > +      * TSC to nsec multiplier and shift are available:
> > > > +      * force using the x86-tsc clock for this host-guest tracing session
> > > > +      * and store TSC to nsec multiplier and shift.
> > > > +      */
> > > > +     if (!clock && tsync_proto_is_supported("kvm") &&
> > > > +         !get_tsc_nsec(&shift, &mult, &offset) && mult) {
> > > > +             top_instance.clock = strdup(TSC_CLOCK);
> > > > +             if (!top_instance.clock)
> > > > +                     die("Could not allocate top instance clock");
> > > > +             clock = top_instance.clock;
> > >
> > > Why is this using the top_instance? What if the user had done:
> > >
> > >  # trace-cmd record -B host -e kvm -e sched -A guest -e sched
> >
> > You are right, that command is valid. The problem is that guest
> > timestamps can be synchronized with one clock only. If there are two
> > instances on the host, each with a different clock, the
> > synchronization will not work. That's why I look at the top instance
> > clock only, which is wrong. I'll change that logic to take the first
> > configured host trace clock, i.e. in case of multiple host instances
> > with multiple trace clocks, the first wins.
> >
>
>
> The code should just use the first instance available. Not about being
> global, but because I want trace-cmd to not interfere with the top instance
> if it is not specified on the command line. That way we can have this:
>
>  # trace-cmd record -e all
>
> in one window, and in another window:
>
>  # trace-cmd record -B guest -e kvm -A guest -e all
>
> and that recorder not do anything to bother the first one. That is, we
> should only touch the top instance if it is explicitly specified.
>
>
> -- Steve



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

Re: [PATCH 02/12] trace-cmd: Add logic for TSC to nanosecond conversion

[Steven Rostedt]

On Thu, 18 Mar 2021 05:42:47 +0200
Tzvetomir Stoyanov <tz.stoyanov@gmail.com> wrote:
> >
> > Your right. And I just tried this:
> >
> >  # trace-cmd record -C x86-tsc -e sched -B foo -C local -e sched sleep 1
> >
> > And it appears to ignore the -C local. Which I think is the right thing to
> > do ;-)  
> 
> According to the code, trace-cmd supports clock per instance. And it
> works, I tried this:
> 
> #trace-cmd record -C x86-tsc -e irq -B foo -C local -e sched sleep 1
> 
> and got different clocks:
>              <...>-290676 [006]1956659520918: softirq_exit:        ....
> foo:       zoom-10894 [004]112198623756671: sched_switch:  ....

Strange, I'll look at that again. It the report looked intermixed on my end
and seemed like it ignored the local clock.

> 
> although I cannot imagine a use case for this. It will be weird to
> visualise this by KerneShark.

Something I don't think we need to worry about now.

> 
> I think that we should introduce options per instance now,  as "-C
> tsc2nsec" cannot be implemented without it.
> I see two possible ways to implement it:
>  1. Break the current trace.dat file format by adding metadata for
> each instance.
>  2. Keep the current format and use nested options -  that's it, just
> another option "OPTION_INSTANCE". It will hold instance name and all
> options, specific for that instance, using the current options format.

Actually, we could simply extend the TRACECMD_OPTION_BUFFER. The way
options were designed was to be able to extend them. When an option is
read, it reads both the type and the size, and will skip over the size to
find the next option. If we extend the buffer option to include instance
options, all we need to do is check the size of the buffer option if it has
another item in it after the location of the buffer.

I'll look more into the code on this.

> 
> But there is one question, valid for both ways: What should be the
> scope for the global options ? Apply them only on the top instance, or
> they should be common for all instances ?

The way I usually handle this is, options are by default set for all
instances, and then the buffer instance can just override the defaults.

-- Steve

[PATCH 03/12] trace-cmd: Append new options into guest trace file at the end of the tracing session

[Tzvetomir Stoyanov (VMware)]

Moved the logic for appending new options into guest trace file from
tracecmd_write_guest_time_shift() to host_tsync_complete() context.
The guest time shift may not be the only option to append, the right
place for this logic is when the tracing session is completed.

Signed-off-by: Tzvetomir Stoyanov (VMware) <tz.stoyanov@gmail.com>
---
 lib/trace-cmd/trace-timesync.c | 1 -
 tracecmd/trace-record.c        | 1 +
 2 files changed, 1 insertion(+), 1 deletion(-)

diff --git a/lib/trace-cmd/trace-timesync.c b/lib/trace-cmd/trace-timesync.c
index 5995551e..85a57f23 100644
--- a/lib/trace-cmd/trace-timesync.c
+++ b/lib/trace-cmd/trace-timesync.c
@@ -840,7 +840,6 @@ int tracecmd_write_guest_time_shift(struct tracecmd_output *handle,
 	vector[5].iov_len = 8 * count;
 	vector[5].iov_base = scalings;
 	tracecmd_add_option_v(handle, TRACECMD_OPTION_TIME_SHIFT, vector, 6);
-	tracecmd_append_options(handle);
 #ifdef TSYNC_DEBUG
 	if (count > 1)
 		printf("Got %d timestamp synch samples in %lld ns trace\n\r",
diff --git a/tracecmd/trace-record.c b/tracecmd/trace-record.c
index 117e4f17..b064a1ff 100644
--- a/tracecmd/trace-record.c
+++ b/tracecmd/trace-record.c
@@ -681,6 +681,7 @@ static void host_tsync_complete(struct buffer_instance *instance)
 		if (!handle)
 			die("cannot create output handle");
 		tracecmd_write_guest_time_shift(handle, instance->tsync);
+		tracecmd_append_options(handle);
 		tracecmd_output_close(handle);
 	}
 
-- 
2.29.2

[PATCH 04/12] trace-cmd: Add a new option in trace file metadata for tsc2nsec conversion

[Tzvetomir Stoyanov (VMware)]

A new option is added in the trace.dat file for holding the multiplier
and shift, used for converting TSC trace clock to nanoseconds.

Signed-off-by: Tzvetomir Stoyanov (VMware) <tz.stoyanov@gmail.com>
---
 .../include/private/trace-cmd-private.h        |  1 +
 tracecmd/trace-dump.c                          | 18 ++++++++++++++++++
 2 files changed, 19 insertions(+)

diff --git a/lib/trace-cmd/include/private/trace-cmd-private.h b/lib/trace-cmd/include/private/trace-cmd-private.h
index 27a96c12..e2ea0dd0 100644
--- a/lib/trace-cmd/include/private/trace-cmd-private.h
+++ b/lib/trace-cmd/include/private/trace-cmd-private.h
@@ -125,6 +125,7 @@ enum {
 	TRACECMD_OPTION_TRACEID,
 	TRACECMD_OPTION_TIME_SHIFT,
 	TRACECMD_OPTION_GUEST,
+	TRACECMD_OPTION_TSC2NSEC,
 };
 
 enum {
diff --git a/tracecmd/trace-dump.c b/tracecmd/trace-dump.c
index 6172231e..86524d0f 100644
--- a/tracecmd/trace-dump.c
+++ b/tracecmd/trace-dump.c
@@ -481,6 +481,21 @@ out:
 	free(buf);
 }
 
+void dump_option_tsc2nsec(int fd, int size)
+{
+	int mult, shift, offset;
+
+	do_print(OPTIONS, "\n\t\t[Option TSC2NSEC, %d bytes]\n", size);
+
+	if (read_file_number(fd, &mult, 4))
+		die("cannot read tsc2nsec multiplier");
+	if (read_file_number(fd, &shift, 4))
+		die("cannot read tsc2nsec shift");
+	if (read_file_number(fd, &offset, 4))
+		die("cannot read tsc2nsec offset");
+	do_print(OPTIONS, "%d %d %d [multiplier, shift, offset]\n", mult, shift, offset);
+}
+
 static void dump_options(int fd)
 {
 	unsigned short option;
@@ -540,6 +555,9 @@ static void dump_options(int fd)
 		case TRACECMD_OPTION_GUEST:
 			dump_option_guest(fd, size);
 			break;
+		case TRACECMD_OPTION_TSC2NSEC:
+			dump_option_tsc2nsec(fd, size);
+			break;
 		default:
 			do_print(OPTIONS, " %d %d\t[Unknown option, size - skipping]\n",
 				 option, size);
-- 
2.29.2

[PATCH 05/12] trace-cmd: Save information for tsc to nanoseconds conversion in trace file

[Tzvetomir Stoyanov (VMware)]

Store multiplier and shift, required for TSC clock to nanosecond
conversion in the metadata of the trace file.

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

diff --git a/tracecmd/trace-record.c b/tracecmd/trace-record.c
index b064a1ff..30d3ed89 100644
--- a/tracecmd/trace-record.c
+++ b/tracecmd/trace-record.c
@@ -666,6 +666,17 @@ static void delete_thread_data(void)
 	}
 }
 
+static void
+add_tsc2nsec(struct tracecmd_output *handle, struct buffer_instance *instance)
+{
+	int array[] = { instance->tsc2nsec.mult,
+			instance->tsc2nsec.shift,
+			instance->tsc2nsec.offset};
+
+	tracecmd_add_option(handle, TRACECMD_OPTION_TSC2NSEC,
+			    sizeof(array), array);
+}
+
 static void host_tsync_complete(struct buffer_instance *instance)
 {
 	struct tracecmd_output *handle = NULL;
@@ -680,6 +691,16 @@ static void host_tsync_complete(struct buffer_instance *instance)
 		handle = tracecmd_get_output_handle_fd(fd);
 		if (!handle)
 			die("cannot create output handle");
+
+		/*
+		 * If TSC is used as current trace clock and there is
+		 * information for tsc to nanosecond conversion, store it
+		 * in the trace file
+		 */
+		if (instance->tsc2nsec.mult && instance->clock &&
+		    !strncmp(top_instance.clock, TSC_CLOCK, strlen(TSC_CLOCK)))
+			add_tsc2nsec(handle, instance);
+
 		tracecmd_write_guest_time_shift(handle, instance->tsync);
 		tracecmd_append_options(handle);
 		tracecmd_output_close(handle);
@@ -4269,6 +4290,15 @@ static void record_data(struct common_record_context *ctx)
 				add_guest_info(handle, instance);
 		}
 
+		/*
+		 * If  TSC is used as current trace clock and there is
+		 * information for tsc to nanosecond conversion, store it
+		 * in the trace file
+		 */
+		if (top_instance.tsc2nsec.mult && top_instance.clock &&
+		    !strncmp(top_instance.clock, TSC_CLOCK, strlen(TSC_CLOCK)))
+			add_tsc2nsec(handle, &top_instance);
+
 		if (tracecmd_write_cmdlines(handle))
 			die("Writing cmdlines");
 
-- 
2.29.2

[PATCH 06/12] trace-cmd: Read information for tsc to nanoseconds conversion from trace file

[Tzvetomir Stoyanov (VMware)]

Read multiplier and shift, required for TSC clock to nanosecond
conversion from the metadata of the trace file and save them in
the tracecmd input file handler.

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

diff --git a/lib/trace-cmd/trace-input.c b/lib/trace-cmd/trace-input.c
index 2093a3dc..1e925f45 100644
--- a/lib/trace-cmd/trace-input.c
+++ b/lib/trace-cmd/trace-input.c
@@ -99,6 +99,12 @@ struct host_trace_info {
 	struct ts_offset_sample	*ts_samples;
 };
 
+struct tsc2nsec {
+	int	mult;
+	int	shift;
+	int	offset;
+};
+
 struct tracecmd_input {
 	struct tep_handle	*pevent;
 	unsigned long		file_state;
@@ -118,6 +124,8 @@ struct tracecmd_input {
 	bool			use_pipe;
 	struct cpu_data 	*cpu_data;
 	long long		ts_offset;
+	struct tsc2nsec		tsc_calc;
+
 	struct host_trace_info	host;
 	double			ts2secs;
 	char *			cpustats;
@@ -2674,6 +2682,16 @@ static int handle_options(struct tracecmd_input *handle)
 		case TRACECMD_OPTION_GUEST:
 			trace_guest_load(handle, buf, size);
 			break;
+		case TRACECMD_OPTION_TSC2NSEC:
+			if (size != 12)
+				break;
+			handle->tsc_calc.mult = tep_read_number(handle->pevent,
+								buf, 4);
+			handle->tsc_calc.shift = tep_read_number(handle->pevent,
+								 buf + 4, 4);
+			handle->tsc_calc.offset = tep_read_number(handle->pevent,
+								  buf + 8, 4);
+			break;
 		default:
 			warning("unknown option %d", option);
 			break;
-- 
2.29.2

[PATCH 07/12] trace-cmd: Remove unneeded multiply in events timestamp reading

[Tzvetomir Stoyanov (VMware)]

When the event timestamp is converted to seconds, the local variable
that holds this timestamp is converted to seconds also. As this
variable is not used in the function later, this conversion in not
needed.

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

diff --git a/lib/trace-cmd/trace-input.c b/lib/trace-cmd/trace-input.c
index 1e925f45..5384ad90 100644
--- a/lib/trace-cmd/trace-input.c
+++ b/lib/trace-cmd/trace-input.c
@@ -1932,10 +1932,8 @@ read_again:
 
 	handle->cpu_data[cpu].timestamp = timestamp_correct(ts, handle);
 
-	if (handle->ts2secs) {
+	if (handle->ts2secs)
 		handle->cpu_data[cpu].timestamp *= handle->ts2secs;
-		ts *= handle->ts2secs;
-	}
 
 	index = kbuffer_curr_offset(kbuf);
 
-- 
2.29.2

[PATCH 08/12] trace-cmd: Perform all timestamp corrections in a single function

[Tzvetomir Stoyanov (VMware)]

When reading event timestamps from a trace file, there could be various
corrections depending on the metadata information from the file. Move
all logic that performs timestamp calculations in a single function.

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

diff --git a/lib/trace-cmd/trace-input.c b/lib/trace-cmd/trace-input.c
index 5384ad90..65081007 100644
--- a/lib/trace-cmd/trace-input.c
+++ b/lib/trace-cmd/trace-input.c
@@ -1276,6 +1276,19 @@ static unsigned long long timestamp_correct(unsigned long long ts,
 					 &host->ts_samples[mid+1]);
 }
 
+static unsigned long long timestamp_calc(unsigned long long ts,
+					 struct tracecmd_input *handle)
+{
+	unsigned long long tstamp;
+
+	tstamp = timestamp_correct(ts, handle);
+
+	if (handle->ts2secs)
+		tstamp *= handle->ts2secs;
+
+	return tstamp;
+}
+
 /*
  * Page is mapped, now read in the page header info.
  */
@@ -1297,10 +1310,8 @@ static int update_page_info(struct tracecmd_input *handle, int cpu)
 		    kbuffer_subbuffer_size(kbuf));
 		return -1;
 	}
-	handle->cpu_data[cpu].timestamp = timestamp_correct(kbuffer_timestamp(kbuf), handle);
-
-	if (handle->ts2secs)
-		handle->cpu_data[cpu].timestamp *= handle->ts2secs;
+	handle->cpu_data[cpu].timestamp = timestamp_calc(kbuffer_timestamp(kbuf),
+							 handle);
 
 	return 0;
 }
@@ -1930,10 +1941,7 @@ read_again:
 		goto read_again;
 	}
 
-	handle->cpu_data[cpu].timestamp = timestamp_correct(ts, handle);
-
-	if (handle->ts2secs)
-		handle->cpu_data[cpu].timestamp *= handle->ts2secs;
+	handle->cpu_data[cpu].timestamp = timestamp_calc(ts, handle);
 
 	index = kbuffer_curr_offset(kbuf);
 
-- 
2.29.2

[PATCH 09/12] trace-cmd: Convert tsc timestamps to nanosecods when reading trace data from a file

[Tzvetomir Stoyanov (VMware)]

If there is information for TSC to nanoseconds conversion in the trace
file metadata, use it to recalculate the timestamps of all events.

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

diff --git a/lib/trace-cmd/trace-input.c b/lib/trace-cmd/trace-input.c
index 65081007..dc9ac1d3 100644
--- a/lib/trace-cmd/trace-input.c
+++ b/lib/trace-cmd/trace-input.c
@@ -1276,17 +1276,37 @@ static unsigned long long timestamp_correct(unsigned long long ts,
 					 &host->ts_samples[mid+1]);
 }
 
+static unsigned long long mul_u64_u32_shr(unsigned long long a,
+					  unsigned long long mul, unsigned int shift)
+{
+	unsigned int ah, al;
+	unsigned long long ret;
+
+	al = a;
+	ah = a >> 32;
+
+	ret = (al * mul) >> shift;
+	if (ah)
+		ret += (ah * mul) << (32 - shift);
+
+	return ret;
+}
+
 static unsigned long long timestamp_calc(unsigned long long ts,
 					 struct tracecmd_input *handle)
 {
-	unsigned long long tstamp;
+	unsigned long long t;
 
-	tstamp = timestamp_correct(ts, handle);
+	t = timestamp_correct(ts, handle);
 
 	if (handle->ts2secs)
-		tstamp *= handle->ts2secs;
+		t *= handle->ts2secs;
+	else if (handle->tsc_calc.mult) {
+		t = mul_u64_u32_shr(t, handle->tsc_calc.mult, handle->tsc_calc.shift);
+		t += handle->tsc_calc.offset;
+	}
 
-	return tstamp;
+	return t;
 }
 
 /*
-- 
2.29.2

Re: [PATCH 09/12] trace-cmd: Convert tsc timestamps to nanosecods when reading trace data from a file

[Steven Rostedt]

On Mon, 15 Mar 2021 08:18:29 +0200
"Tzvetomir Stoyanov (VMware)" <tz.stoyanov@gmail.com> wrote:

> If there is information for TSC to nanoseconds conversion in the trace
> file metadata, use it to recalculate the timestamps of all events.
> 
> Signed-off-by: Tzvetomir Stoyanov (VMware) <tz.stoyanov@gmail.com>
> ---
>  lib/trace-cmd/trace-input.c | 28 ++++++++++++++++++++++++----
>  1 file changed, 24 insertions(+), 4 deletions(-)
> 
> diff --git a/lib/trace-cmd/trace-input.c b/lib/trace-cmd/trace-input.c
> index 65081007..dc9ac1d3 100644
> --- a/lib/trace-cmd/trace-input.c
> +++ b/lib/trace-cmd/trace-input.c
> @@ -1276,17 +1276,37 @@ static unsigned long long timestamp_correct(unsigned long long ts,
>  					 &host->ts_samples[mid+1]);
>  }
>  

I would add a comment saying that the below function was taken from the
Linux kernel.

-- Steve

> +static unsigned long long mul_u64_u32_shr(unsigned long long a,
> +					  unsigned long long mul, unsigned int shift)
> +{
> +	unsigned int ah, al;
> +	unsigned long long ret;
> +
> +	al = a;
> +	ah = a >> 32;
> +
> +	ret = (al * mul) >> shift;
> +	if (ah)
> +		ret += (ah * mul) << (32 - shift);
> +
> +	return ret;
> +}
> +
>  static unsigned long long timestamp_calc(unsigned long long ts,
>  					 struct tracecmd_input *handle)
>  {
> -	unsigned long long tstamp;
> +	unsigned long long t;
>  
> -	tstamp = timestamp_correct(ts, handle);
> +	t = timestamp_correct(ts, handle);
>  
>  	if (handle->ts2secs)
> -		tstamp *= handle->ts2secs;
> +		t *= handle->ts2secs;
> +	else if (handle->tsc_calc.mult) {
> +		t = mul_u64_u32_shr(t, handle->tsc_calc.mult, handle->tsc_calc.shift);
> +		t += handle->tsc_calc.offset;
> +	}
>  
> -	return tstamp;
> +	return t;
>  }
>  
>  /*

[PATCH 10/12] trace-cmd: Set order and priorities when applying timestamp corrections

[Tzvetomir Stoyanov (VMware)]

There are multiple options that affect the event's timestamps while
recording trace or displaying the trace file. Some of these options can
be used together and the order and priorities for all of them should be
strictly defined:
 trace-cmd record --date , --ts-offset - only one of these can be used
 trace-cmd record host-guest trace - guest timestamps are auto
synchronized with host time stamps. If no trace clock is set by the user
and "kvm" synch plugin is available, then "x86-tsc" trace clock is used
and tsc timestamps are converted to nanoseconds in both host and guest
trace events.
 trace-cmd report --ts-offset, --ts2secs, --nodate

Event timestamps corrections are applied in this order, when the trace
file is opened for reading:
 1. If it is a guest trace file and there is information for
    synchronization with the host events and is this synchronization is
    enabled: synchronize guest events with host events.
 2. If the user has specified --ts2secs, apply it.
 3. If the user has not specified --ts2secs and there is information in
    the trace file metadata for tsc to nanosecond conversion, apply it.
 4. If the user has specified --ts-offset or --date, apply it. The
    offsets specified by "report" command have higher priority that the
    offsets specified by "record" command.

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

diff --git a/lib/trace-cmd/trace-input.c b/lib/trace-cmd/trace-input.c
index dc9ac1d3..1cffa0f5 100644
--- a/lib/trace-cmd/trace-input.c
+++ b/lib/trace-cmd/trace-input.c
@@ -1224,21 +1224,12 @@ timestamp_correction_calc(unsigned long long ts, unsigned int flags,
 	return ts + tscor;
 }
 
-static unsigned long long timestamp_correct(unsigned long long ts,
-					    struct tracecmd_input *handle)
+static unsigned long long timestamp_host_sync(unsigned long long ts,
+					      struct tracecmd_input *handle)
 {
 	struct host_trace_info	*host = &handle->host;
 	int min, mid, max;
 
-	if (handle->flags & TRACECMD_FL_IGNORE_DATE)
-		return ts;
-
-	if (handle->ts_offset)
-		return ts + handle->ts_offset;
-
-	if (!host->sync_enable)
-		return ts;
-
 	/* We have one sample, nothing to calc here */
 	if (host->ts_samples_count == 1)
 		return ts + host->ts_samples[0].offset;
@@ -1295,17 +1286,26 @@ static unsigned long long mul_u64_u32_shr(unsigned long long a,
 static unsigned long long timestamp_calc(unsigned long long ts,
 					 struct tracecmd_input *handle)
 {
-	unsigned long long t;
+	unsigned long long t = ts;
 
-	t = timestamp_correct(ts, handle);
 
-	if (handle->ts2secs)
+	/* Guest trace file, sync with host timestamps */
+	if (handle->host.sync_enable)
+		t = timestamp_host_sync(ts, handle);
+
+	if (handle->ts2secs) {
+		/* user specified clock frequency */
 		t *= handle->ts2secs;
-	else if (handle->tsc_calc.mult) {
+	} else if (handle->tsc_calc.mult) {
+		/* auto calculated TSC clock frequency */
 		t = mul_u64_u32_shr(t, handle->tsc_calc.mult, handle->tsc_calc.shift);
 		t += handle->tsc_calc.offset;
 	}
 
+	/* User specified time offset with --ts-offset or --date options */
+	if (handle->ts_offset)
+		t += handle->ts_offset;
+
 	return t;
 }
 
-- 
2.29.2

Re: [PATCH 10/12] trace-cmd: Set order and priorities when applying timestamp corrections

[Steven Rostedt]

On Mon, 15 Mar 2021 08:18:30 +0200
"Tzvetomir Stoyanov (VMware)" <tz.stoyanov@gmail.com> wrote:

> There are multiple options that affect the event's timestamps while
> recording trace or displaying the trace file. Some of these options can
> be used together and the order and priorities for all of them should be
> strictly defined:
>  trace-cmd record --date , --ts-offset - only one of these can be used
>  trace-cmd record host-guest trace - guest timestamps are auto
> synchronized with host time stamps. If no trace clock is set by the user
> and "kvm" synch plugin is available, then "x86-tsc" trace clock is used
> and tsc timestamps are converted to nanoseconds in both host and guest
> trace events.
>  trace-cmd report --ts-offset, --ts2secs, --nodate
> 
> Event timestamps corrections are applied in this order, when the trace
> file is opened for reading:
>  1. If it is a guest trace file and there is information for
>     synchronization with the host events and is this synchronization is
>     enabled: synchronize guest events with host events.
>  2. If the user has specified --ts2secs, apply it.
>  3. If the user has not specified --ts2secs and there is information in
>     the trace file metadata for tsc to nanosecond conversion, apply it.
>  4. If the user has specified --ts-offset or --date, apply it. The
>     offsets specified by "report" command have higher priority that the
>     offsets specified by "record" command.
> 

I'll have to play with this a bit, but for now this looks fine.

-- Steve

[PATCH 11/12] trace-cmd: Add a new flag to disable any timestamp corrections

[Tzvetomir Stoyanov (VMware)]

A new flag is added in the trace-cmd library for controlling events
timestamp corrections while reading a trace file. If the flag is set,
all timestamps are displayed as-is from the trace file.
   TRACECMD_FL_RAW_TS
The flag can be modified with these APIs:
  tracecmd_set_flag()
  tracecmd_clear_flag()

Signed-off-by: Tzvetomir Stoyanov (VMware) <tz.stoyanov@gmail.com>
---
 lib/trace-cmd/include/private/trace-cmd-private.h |  1 +
 lib/trace-cmd/trace-input.c                       | 12 ++++++++----
 2 files changed, 9 insertions(+), 4 deletions(-)

diff --git a/lib/trace-cmd/include/private/trace-cmd-private.h b/lib/trace-cmd/include/private/trace-cmd-private.h
index e2ea0dd0..98616c76 100644
--- a/lib/trace-cmd/include/private/trace-cmd-private.h
+++ b/lib/trace-cmd/include/private/trace-cmd-private.h
@@ -132,6 +132,7 @@ enum {
 	TRACECMD_FL_IGNORE_DATE		= (1 << 0),
 	TRACECMD_FL_BUFFER_INSTANCE	= (1 << 1),
 	TRACECMD_FL_IN_USECS		= (1 << 2),
+	TRACECMD_FL_RAW_TS		= (1 << 3),
 };
 
 struct tracecmd_ftrace {
diff --git a/lib/trace-cmd/trace-input.c b/lib/trace-cmd/trace-input.c
index 1cffa0f5..b53c1932 100644
--- a/lib/trace-cmd/trace-input.c
+++ b/lib/trace-cmd/trace-input.c
@@ -1288,6 +1288,9 @@ static unsigned long long timestamp_calc(unsigned long long ts,
 {
 	unsigned long long t = ts;
 
+	/* do not modify raw timestamps */
+	if (handle->flags & TRACECMD_FL_RAW_TS)
+		return ts;
 
 	/* Guest trace file, sync with host timestamps */
 	if (handle->host.sync_enable)
@@ -2603,7 +2606,8 @@ static int handle_options(struct tracecmd_input *handle)
 			 * gtod. It is stored as ASCII with '0x'
 			 * appended.
 			 */
-			if (handle->flags & TRACECMD_FL_IGNORE_DATE)
+			if ((handle->flags & TRACECMD_FL_IGNORE_DATE) ||
+			    (handle->flags & TRACECMD_FL_RAW_TS))
 				break;
 			offset = strtoll(buf, NULL, 0);
 			/* Convert from micro to nano */
@@ -2615,7 +2619,7 @@ static int handle_options(struct tracecmd_input *handle)
 			 * Similar to date option, but just adds an
 			 * offset to the timestamp.
 			 */
-			if (handle->flags & TRACECMD_FL_IGNORE_DATE)
+			if (handle->flags & TRACECMD_FL_RAW_TS)
 				break;
 			offset = strtoll(buf, NULL, 0);
 			handle->ts_offset += offset;
@@ -2630,7 +2634,7 @@ static int handle_options(struct tracecmd_input *handle)
 			 * long long array of size [count] of timestamp offsets.
 			 * long long array of size [count] of timestamp scaling ratios.*
 			 */
-			if (size < 16 || handle->flags & TRACECMD_FL_IGNORE_DATE)
+			if (size < 16 || (handle->flags & TRACECMD_FL_RAW_TS))
 				break;
 			handle->host.peer_trace_id = tep_read_number(handle->pevent,
 								     buf, 8);
@@ -2709,7 +2713,7 @@ static int handle_options(struct tracecmd_input *handle)
 			trace_guest_load(handle, buf, size);
 			break;
 		case TRACECMD_OPTION_TSC2NSEC:
-			if (size != 12)
+			if (size != 12 || (handle->flags & TRACECMD_FL_RAW_TS))
 				break;
 			handle->tsc_calc.mult = tep_read_number(handle->pevent,
 								buf, 4);
-- 
2.29.2

[PATCH 12/12] trace-cmd: Add new parameter "--raw-ts" to "trace-cmd report" command

[Tzvetomir Stoyanov (VMware)]

"trace-cmd report --raw-ts" disables all corrections of event timestamps
from the trace file.

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

diff --git a/tracecmd/trace-read.c b/tracecmd/trace-read.c
index 22e8635c..1b99db1d 100644
--- a/tracecmd/trace-read.c
+++ b/tracecmd/trace-read.c
@@ -1484,6 +1484,7 @@ static void add_hook(const char *arg)
 }
 
 enum {
+	OPT_raw_ts	= 236,
 	OPT_version	= 237,
 	OPT_tscheck	= 238,
 	OPT_tsdiff	= 239,
@@ -1533,6 +1534,7 @@ void trace_report (int argc, char **argv)
 	int print_events = 0;
 	int nanosec = 0;
 	int no_date = 0;
+	int raw_ts = 0;
 	int global = 0;
 	int neg = 0;
 	int ret = 0;
@@ -1574,6 +1576,7 @@ void trace_report (int argc, char **argv)
 			{"ts2secs", required_argument, NULL, OPT_ts2secs},
 			{"ts-diff", no_argument, NULL, OPT_tsdiff},
 			{"ts-check", no_argument, NULL, OPT_tscheck},
+			{"raw-ts", no_argument, NULL, OPT_raw_ts},
 			{"help", no_argument, NULL, '?'},
 			{NULL, 0, NULL, 0}
 		};
@@ -1746,6 +1749,9 @@ void trace_report (int argc, char **argv)
 		case OPT_tscheck:
 			tscheck = 1;
 			break;
+		case OPT_raw_ts:
+			raw_ts = 1;
+			break;
 		default:
 			usage(argv);
 		}
@@ -1777,7 +1783,8 @@ void trace_report (int argc, char **argv)
 
 		if (no_date)
 			tracecmd_set_flag(handle, TRACECMD_FL_IGNORE_DATE);
-
+		if (raw_ts)
+			tracecmd_set_flag(handle, TRACECMD_FL_RAW_TS);
 		page_size = tracecmd_page_size(handle);
 
 		if (show_page_size) {
-- 
2.29.2

Re: [PATCH 12/12] trace-cmd: Add new parameter "--raw-ts" to "trace-cmd report" command

[Steven Rostedt]

On Mon, 15 Mar 2021 08:18:32 +0200
"Tzvetomir Stoyanov (VMware)" <tz.stoyanov@gmail.com> wrote:

> "trace-cmd report --raw-ts" disables all corrections of event timestamps
> from the trace file.
> 
> Signed-off-by: Tzvetomir Stoyanov (VMware) <tz.stoyanov@gmail.com>
> ---
> 

The rest looks fine.

Thanks Tzvetomir!

-- Steve