[PATCH v2 00/18] TSC trace clock to nanosecond conversion

[PATCH v2 00/18] 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.

v2 changes:
 - Added new trace clock "-C tsc2nsec", which does not depend on host-guest
   tracing use case.
 - A few minor improvements and fixes. 

Tzvetomir Stoyanov (VMware) (18):
  trace-cmd: Add initial perf interface in trace-cmd library
  trace-cmd: Extend trace-cmd dump subcommand to display the clock
  trace-cmd: Save only the selected clock in the trace.dat file
  trace-cmd: Add new trace-cmd clock tsc2nsec
  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: Save tsc2nsec clock in trace.dat file
  trace-cmd: Append new options into guest trace file at the end of the
    tracing session
  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
  trace-cmd: Print times in TimeShift options as unsigned in trace-cmd
    dump
  trace-cmd: Use tsc clock for host-guest tracing, if available
  trace-cmd: Get current clock for host-guest tracing session

 Documentation/trace-cmd/trace-cmd-dump.1.txt  |   2 +
 Makefile                                      |   6 +
 lib/trace-cmd/Makefile                        |   3 +
 .../include/private/trace-cmd-private.h       |  22 ++
 lib/trace-cmd/trace-input.c                   | 103 +++--
 lib/trace-cmd/trace-output.c                  |  65 ++-
 lib/trace-cmd/trace-perf.c                    | 105 +++++
 lib/trace-cmd/trace-timesync.c                |   1 -
 tracecmd/include/trace-local.h                |   7 +
 tracecmd/trace-dump.c                         |  55 ++-
 tracecmd/trace-read.c                         |   9 +-
 tracecmd/trace-record.c                       | 372 +++++++++++++++---
 tracecmd/trace-usage.c                        |   1 +
 13 files changed, 649 insertions(+), 102 deletions(-)
 create mode 100644 lib/trace-cmd/trace-perf.c

-- 
2.30.2

[PATCH v2 01/18] 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>
---
 Makefile                                      |   6 +
 lib/trace-cmd/Makefile                        |   3 +
 .../include/private/trace-cmd-private.h       |  17 +++
 lib/trace-cmd/trace-perf.c                    | 105 ++++++++++++++++++
 4 files changed, 131 insertions(+)
 create mode 100644 lib/trace-cmd/trace-perf.c

diff --git a/Makefile b/Makefile
index fae43ff8..1c684af8 100644
--- a/Makefile
+++ b/Makefile
@@ -298,6 +298,12 @@ ifeq ($(VSOCK_DEFINED), 1)
 CFLAGS += -DVSOCK
 endif
 
+PERF_DEFINED := $(shell if (echo "$(pound)include <linux/perf_event.h>" | $(CC) -E - >/dev/null 2>&1) ; then echo 1; else echo 0 ; fi)
+export PERF_DEFINED
+ifeq ($(PERF_DEFINED), 1)
+CFLAGS += -DPERF
+endif
+
 CUNIT_INSTALLED := $(shell if (printf "$(pound)include <CUnit/Basic.h>\n void main(){CU_initialize_registry();}" | $(CC) -o /dev/null -x c - -lcunit >/dev/null 2>&1) ; then echo 1; else echo 0 ; fi)
 export CUNIT_INSTALLED
 
diff --git a/lib/trace-cmd/Makefile b/lib/trace-cmd/Makefile
index 2f553ed5..aa92c8c0 100644
--- a/lib/trace-cmd/Makefile
+++ b/lib/trace-cmd/Makefile
@@ -17,6 +17,9 @@ OBJS += trace-util.o
 OBJS += trace-filter-hash.o
 OBJS += trace-msg.o
 OBJS += trace-plugin.o
+ifeq ($(PERF_DEFINED), 1)
+OBJS += trace-perf.o
+endif
 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 6b32ce58..27f4c9c3 100644
--- a/lib/trace-cmd/include/private/trace-cmd-private.h
+++ b/lib/trace-cmd/include/private/trace-cmd-private.h
@@ -512,5 +512,22 @@ void *tracecmd_record_page(struct tracecmd_input *handle,
 			   struct tep_record *record);
 void *tracecmd_record_offset(struct tracecmd_input *handle,
 			     struct tep_record *record);
+#ifdef PERF
+
+#include <linux/perf_event.h>
+
+/* 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
 
 #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.30.2

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

[Steven Rostedt]

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

> +void trace_perf_close(struct trace_perf *perf)
> +{
> +	if (perf->fd >= 0)
> +		close(perf->fd);
> +	perf->fd = -1;
> +	if (perf->mmap)

The above should be:

	if (perf->mmap && perf->mmap != MAP_FAILED)

-- Steve

> +		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;
> +}

[PATCH v2 02/18] trace-cmd: Extend trace-cmd dump subcommand to display the clock

[Tzvetomir Stoyanov (VMware)]

Trace clock, used to record the tracing data is saved in the trace.dat
file. As "trace-cmd dump" command shows the metadata content of the
file, it should display the trace clock also.
Added a new parameter
  "trace-cmd dump --clock"
which shows the clock saved in the file. The clock can be displayed
also with
 "trace-cmd dump --all"

Signed-off-by: Tzvetomir Stoyanov (VMware) <tz.stoyanov@gmail.com>
---
 Documentation/trace-cmd/trace-cmd-dump.1.txt |  2 ++
 tracecmd/trace-dump.c                        | 34 +++++++++++++++++++-
 tracecmd/trace-usage.c                       |  1 +
 3 files changed, 36 insertions(+), 1 deletion(-)

diff --git a/Documentation/trace-cmd/trace-cmd-dump.1.txt b/Documentation/trace-cmd/trace-cmd-dump.1.txt
index 71b8e655..0f8626fa 100644
--- a/Documentation/trace-cmd/trace-cmd-dump.1.txt
+++ b/Documentation/trace-cmd/trace-cmd-dump.1.txt
@@ -46,6 +46,8 @@ OPTIONS
     Print all options, stored in the file.
 *--flyrecord*::
     Print the offset and the size of tracing data per each CPU.
+*--clock*::
+    Print the trace clock, used for timestamp of the tracing events, stored in the file.
 *--all*::
     Print all meta data from the file.
 *--help*::
diff --git a/tracecmd/trace-dump.c b/tracecmd/trace-dump.c
index 6172231e..4bdfd53f 100644
--- a/tracecmd/trace-dump.c
+++ b/tracecmd/trace-dump.c
@@ -24,6 +24,7 @@
 
 static struct tep_handle *tep;
 static unsigned int trace_cpus;
+static int has_clock;
 
 enum dump_items {
 	SUMMARY		= (1 << 0),
@@ -37,6 +38,7 @@ enum dump_items {
 	CMDLINES	= (1 << 8),
 	OPTIONS		= (1 << 9),
 	FLYRECORD	= (1 << 10),
+	CLOCK		= (1 << 11),
 };
 
 enum dump_items verbosity;
@@ -496,7 +498,7 @@ static void dump_options(int fd)
 			die("cannot read the option size");
 
 		count++;
-		if (!DUMP_CHECK(OPTIONS)) {
+		if (!DUMP_CHECK(OPTIONS) && !DUMP_CHECK(CLOCK)) {
 			lseek64(fd, size, SEEK_CUR);
 			continue;
 		}
@@ -512,6 +514,7 @@ static void dump_options(int fd)
 			break;
 		case TRACECMD_OPTION_TRACECLOCK:
 			dump_option_string(fd, size, "TRACECLOCK");
+			has_clock = 1;
 			break;
 		case TRACECMD_OPTION_UNAME:
 			dump_option_string(fd, size, "UNAME");
@@ -556,6 +559,29 @@ static void dump_latency(int fd)
 	do_print(SUMMARY, "\t[Latency tracing data]\n");
 }
 
+static void dump_clock(int fd)
+{
+	long long size;
+	char *clock;
+
+	do_print((SUMMARY | CLOCK), "\t[Tracing clock]\n");
+	if (!has_clock) {
+		do_print((SUMMARY | CLOCK), "\t\t No tracing clock saved in the file\n");
+		return;
+	}
+	if (read_file_number(fd, &size, 8))
+		die("cannot read clock size");
+	clock = calloc(1, size);
+	if (!clock)
+		die("cannot allocate clock %d bytes", size);
+
+	if (read_file_bytes(fd, clock, size))
+		die("cannot read clock %d bytes", size);
+	clock[size] = 0;
+	do_print((SUMMARY | CLOCK), "\t\t%s\n", clock);
+	free(clock);
+}
+
 static void dump_flyrecord(int fd)
 {
 	long long cpu_offset;
@@ -572,6 +598,7 @@ static void dump_flyrecord(int fd)
 		do_print(FLYRECORD, "\t\t %lld %lld\t[offset, size of cpu %d]\n",
 			 cpu_offset, cpu_size, i);
 	}
+	dump_clock(fd);
 }
 
 static void dump_therest(int fd)
@@ -626,6 +653,7 @@ static void dump_file(const char *file)
 }
 
 enum {
+	OPT_clock	= 243,
 	OPT_all		= 244,
 	OPT_summary	= 245,
 	OPT_flyrecord	= 246,
@@ -666,6 +694,7 @@ void trace_dump(int argc, char **argv)
 			{"cmd-lines", no_argument, NULL, OPT_cmd_lines},
 			{"options", no_argument, NULL, OPT_options},
 			{"flyrecord", no_argument, NULL, OPT_flyrecord},
+			{"clock", no_argument, NULL, OPT_clock},
 			{"validate", no_argument, NULL, 'v'},
 			{"help", no_argument, NULL, '?'},
 			{NULL, 0, NULL, 0}
@@ -721,6 +750,9 @@ void trace_dump(int argc, char **argv)
 		case OPT_head_page:
 			verbosity |= HEAD_PAGE;
 			break;
+		case OPT_clock:
+			verbosity |= CLOCK;
+			break;
 		default:
 			usage(argv);
 		}
diff --git a/tracecmd/trace-usage.c b/tracecmd/trace-usage.c
index 1a7abd58..22537d20 100644
--- a/tracecmd/trace-usage.c
+++ b/tracecmd/trace-usage.c
@@ -377,6 +377,7 @@ static struct usage_help usage_help[] = {
 		"          --cmd-lines print information mapping a PID to a process name\n"
 		"          --options print options\n"
 		"          --flyrecord information of offset and count of recorded events per CPU\n"
+		"          --clock trace clock, saved in the file\n"
 		"          -h, --help show usage information\n"
 	},
 	{
-- 
2.30.2

[PATCH v2 03/18] trace-cmd: Save only the selected clock in the trace.dat file

[Tzvetomir Stoyanov (VMware)]

Trace clock, used for curent trace sessions is saved in the trace.dat
file. This information is used when displaying timestamps of the events.
However, only the selected clock is needed.
A new API is added:
 tracecmd_set_out_clock();
that can be used to set the trace clock on the output handle.

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

diff --git a/lib/trace-cmd/include/private/trace-cmd-private.h b/lib/trace-cmd/include/private/trace-cmd-private.h
index 27f4c9c3..a4637046 100644
--- a/lib/trace-cmd/include/private/trace-cmd-private.h
+++ b/lib/trace-cmd/include/private/trace-cmd-private.h
@@ -83,6 +83,7 @@ tracecmd_plugin_context_output(struct trace_plugin_context *trace_context);
 
 void tracecmd_set_quiet(struct tracecmd_output *handle, bool set_quiet);
 bool tracecmd_get_quiet(struct tracecmd_output *handle);
+void tracecmd_set_out_clock(struct tracecmd_output *handle, char *clock);
 
 static inline int tracecmd_host_bigendian(void)
 {
diff --git a/lib/trace-cmd/trace-output.c b/lib/trace-cmd/trace-output.c
index 54ddcb54..5b6bef28 100644
--- a/lib/trace-cmd/trace-output.c
+++ b/lib/trace-cmd/trace-output.c
@@ -59,6 +59,7 @@ struct tracecmd_output {
 	unsigned long		file_state;
 	struct list_head	options;
 	struct tracecmd_msg_handle *msg_handle;
+	char			*trace_clock;
 };
 
 struct list_event {
@@ -118,6 +119,12 @@ void tracecmd_set_quiet(struct tracecmd_output *handle, bool set_quiet)
 		handle->quiet = set_quiet;
 }
 
+void tracecmd_set_out_clock(struct tracecmd_output *handle, char *clock)
+{
+	if (handle && clock)
+		handle->trace_clock = strdup(clock);
+}
+
 /**
  * tracecmd_get_quiet - Get if to print output to the screen
  * Returns non zero, if no output to the screen should be printed
@@ -150,7 +157,7 @@ void tracecmd_output_free(struct tracecmd_output *handle)
 		free(option->data);
 		free(option);
 	}
-
+	free(handle->trace_clock);
 	free(handle);
 }
 
@@ -1359,6 +1366,45 @@ out_free:
 	return NULL;
 }
 
+static int save_clock(struct tracecmd_output *handle, char *clock)
+{
+	unsigned long long endian8;
+	char *str = NULL;
+	int ret;
+
+	ret = asprintf(&str, "[%s]", clock);
+	if (ret < 0)
+		return -1;
+
+	endian8 = convert_endian_8(handle, strlen(str));
+	ret = do_write_check(handle, &endian8, 8);
+	if (ret)
+		goto out;
+	ret = do_write_check(handle, str, strlen(str));
+
+out:
+	free(str);
+	return ret;
+}
+
+static char *get_clock(struct tracecmd_output *handle)
+{
+	struct tracefs_instance *inst;
+
+	if (handle->trace_clock)
+		return handle->trace_clock;
+
+	/* If no clock is set on this handle, get the trace clock of
+	 * the top instance in the handle's tracing dir
+	 * */
+	inst = tracefs_instance_alloc(handle->tracing_dir, NULL);
+	if (!inst)
+		return NULL;
+	handle->trace_clock = tracefs_get_clock(inst);
+	tracefs_instance_free(inst);
+	return handle->trace_clock;
+}
+
 int tracecmd_write_cpu_data(struct tracecmd_output *handle,
 			    int cpus, char * const *cpu_data_files)
 {
@@ -1366,6 +1412,7 @@ int tracecmd_write_cpu_data(struct tracecmd_output *handle,
 	unsigned long long *sizes = NULL;
 	off64_t offset;
 	unsigned long long endian8;
+	char *clock = NULL;
 	off64_t check_size;
 	char *file;
 	struct stat st;
@@ -1403,18 +1450,14 @@ int tracecmd_write_cpu_data(struct tracecmd_output *handle,
 	 * we need to find the size of it before we define the final
 	 * offsets.
 	 */
-	file = get_tracing_file(handle, "trace_clock");
-	if (!file)
+	clock = get_clock(handle);
+	if (!clock)
 		goto out_free;
-
 	/* Save room for storing the size */
 	offset += 8;
-
-	ret = stat(file, &st);
-	if (ret >= 0)
-		offset += get_size(file);
-
-	put_tracing_file(file);
+	offset += strlen(clock);
+	/* 2 bytes for [] around the clock */
+	offset += 2;
 
 	/* Page align offset */
 	offset = (offset + (handle->page_size - 1)) & ~(handle->page_size - 1);
@@ -1439,7 +1482,7 @@ int tracecmd_write_cpu_data(struct tracecmd_output *handle,
 			goto out_free;
 	}
 
-	if (save_tracing_file_data(handle, "trace_clock") < 0)
+	if (save_clock(handle, clock))
 		goto out_free;
 
 	for (i = 0; i < cpus; i++) {
-- 
2.30.2

Re: [PATCH v2 03/18] trace-cmd: Save only the selected clock in the trace.dat file

[Steven Rostedt]

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

> Trace clock, used for curent trace sessions is saved in the trace.dat
> file. This information is used when displaying timestamps of the events.
> However, only the selected clock is needed.
> A new API is added:
>  tracecmd_set_out_clock();
> that can be used to set the trace clock on the output handle.
> 

There's no reason not to have the other clocks in the file. I would
rather keep them as it doesn't hurt to have them right?

The reason for keeping them is when a customer sends you a trace.dat
file (from commands you ask them to run), you can use the trace.dat
file to see what other clocks they have configured in case you want to
have them try another clock in their next recording.

Extra data about the system the trace.dat file was run on is always a
plus.

-- Steve

Re: [PATCH v2 03/18] trace-cmd: Save only the selected clock in the trace.dat file

[Tzvetomir Stoyanov]

On Wed, Mar 24, 2021 at 2:52 AM Steven Rostedt <rostedt@goodmis.org> wrote:
>
> On Mon, 22 Mar 2021 11:59:30 +0200
> "Tzvetomir Stoyanov (VMware)" <tz.stoyanov@gmail.com> wrote:
>
> > Trace clock, used for curent trace sessions is saved in the trace.dat
> > file. This information is used when displaying timestamps of the events.
> > However, only the selected clock is needed.
> > A new API is added:
> >  tracecmd_set_out_clock();
> > that can be used to set the trace clock on the output handle.
> >
>
> There's no reason not to have the other clocks in the file. I would
> rather keep them as it doesn't hurt to have them right?
>
> The reason for keeping them is when a customer sends you a trace.dat
> file (from commands you ask them to run), you can use the trace.dat
> file to see what other clocks they have configured in case you want to
> have them try another clock in their next recording.
>
> Extra data about the system the trace.dat file was run on is always a
> plus.

I'll extend the TRACECMD_OPTION_TRACECLOCK option with all clocks and
will keep the changes from this patch. That way there will be
information for all available clocks from the trace session and the
old versions of trace-cmd will still work.

>
> -- Steve



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

[PATCH v2 04/18] trace-cmd: Add new trace-cmd clock tsc2nsec

[Tzvetomir Stoyanov (VMware)]

A new clock is added to "trace-cmd record" command:
 trace-cmd record -C tsc2nsec ...
which uses x86-tsc ftrace clock and converts the timestamps from tsc to
nanoseconds, using data from perf kernel interface.
A new options is added also:
 trace-cmd record --tsc2nsec ...
which does not change the current trace clock, just convert whatever it
is to nanoseconds, using the same data from perf kernel interface.

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

diff --git a/tracecmd/include/trace-local.h b/tracecmd/include/trace-local.h
index 6e39d27d..7773e9fc 100644
--- a/tracecmd/include/trace-local.h
+++ b/tracecmd/include/trace-local.h
@@ -172,6 +172,7 @@ enum buffer_instance_flags {
 	BUFFER_FL_GUEST		= 1 << 2,
 	BUFFER_FL_AGENT		= 1 << 3,
 	BUFFER_FL_HAS_CLOCK	= 1 << 4,
+	BUFFER_FL_TSC2NSEC	= 1 << 5,
 };
 
 struct func_list {
@@ -199,6 +200,12 @@ struct filter_pids {
 	int exclude;
 };
 
+struct tsc_nsec {
+	int mult;
+	int shift;
+	unsigned long long offset;
+};
+
 struct buffer_instance {
 	struct buffer_instance	*next;
 	char			*name;
diff --git a/tracecmd/trace-record.c b/tracecmd/trace-record.c
index a0eb0385..38edea2c 100644
--- a/tracecmd/trace-record.c
+++ b/tracecmd/trace-record.c
@@ -57,6 +57,8 @@
 #define MAX_LATENCY	"tracing_max_latency"
 #define STAMP		"stamp"
 #define FUNC_STACK_TRACE "func_stack_trace"
+#define TSC_CLOCK	"x86-tsc"
+#define TSCNSEC_CLOCK	"tsc2nsec"
 
 enum trace_type {
 	TRACE_TYPE_RECORD	= 1,
@@ -198,6 +200,7 @@ struct common_record_context {
 	char *date2ts;
 	char *user;
 	int data_flags;
+	struct tsc_nsec tsc2nsec;
 
 	int record_all;
 	int total_disable;
@@ -4443,11 +4446,12 @@ static int find_ts(struct tep_event *event, struct tep_record *record,
 	return 0;
 }
 
-static unsigned long long find_time_stamp(struct tep_handle *tep)
+static unsigned long long find_time_stamp(struct tep_handle *tep,
+					  struct tracefs_instance *instance)
 {
 	unsigned long long ts = 0;
 
-	if (!tracefs_iterate_raw_events(tep, NULL, NULL, 0, find_ts, &ts))
+	if (!tracefs_iterate_raw_events(tep, instance, NULL, 0, find_ts, &ts))
 		return ts;
 
 	return 0;
@@ -4459,52 +4463,59 @@ static char *read_top_file(char *file, int *psize)
 	return tracefs_instance_file_read(top_instance.tracefs, file, psize);
 }
 
+static struct tep_handle *get_ftrace_tep(void)
+{
+	const char *systems[] = {"ftrace", NULL};
+	struct tep_handle *tep;
+	char *buf;
+	int size;
+	int ret;
+
+	tep = tracefs_local_events_system(NULL, systems);
+	if (!tep)
+		return NULL;
+	tep_set_file_bigendian(tep, tracecmd_host_bigendian());
+	buf = read_top_file("events/header_page", &size);
+	if (!buf)
+		goto error;
+	ret = tep_parse_header_page(tep, buf, size, sizeof(unsigned long));
+	free(buf);
+	if (ret < 0)
+		goto error;
+
+	return tep;
+
+error:
+	tep_free(tep);
+	return NULL;
+}
+
 /*
  * Try to write the date into the ftrace buffer and then
  * read it back, mapping the timestamp to the date.
  */
 static char *get_date_to_ts(void)
 {
-	const char *systems[] = {"ftrace", NULL};
+	struct tep_handle *tep;
 	unsigned long long min = -1ULL;
 	unsigned long long diff;
 	unsigned long long stamp;
 	unsigned long long min_stamp;
 	unsigned long long min_ts;
 	unsigned long long ts;
-	struct tep_handle *tep;
 	struct timespec start;
 	struct timespec end;
 	char *date2ts = NULL;
-	char *path;
-	char *buf;
-	int size;
 	int tfd;
-	int ret;
 	int i;
 
 	/* Set up a tep to read the raw format */
-	tep = tracefs_local_events_system(NULL, systems);
+	tep = get_ftrace_tep();
 	if (!tep) {
 		warning("failed to alloc tep, --date ignored");
 		return NULL;
 	}
-
-	tep_set_file_bigendian(tep, tracecmd_host_bigendian());
-
-	buf = read_top_file("events/header_page", &size);
-	if (!buf)
-		goto out_pevent;
-	ret = tep_parse_header_page(tep, buf, size, sizeof(unsigned long));
-	free(buf);
-	if (ret < 0) {
-		warning("Can't parse header page, --date ignored");
-		goto out_pevent;
-	}
-
-	path = tracefs_get_tracing_file("trace_marker");
-	tfd = open(path, O_WRONLY);
-	tracefs_put_tracing_file(path);
+	tfd = tracefs_instance_file_open(NULL, "trace_marker", O_WRONLY);
 	if (tfd < 0) {
 		warning("Can not open 'trace_marker', --date ignored");
 		goto out_pevent;
@@ -4520,7 +4531,7 @@ static char *get_date_to_ts(void)
 		clock_gettime(CLOCK_REALTIME, &end);
 
 		tracecmd_disable_tracing();
-		ts = find_time_stamp(tep);
+		ts = find_time_stamp(tep, NULL);
 		if (!ts)
 			continue;
 
@@ -5381,6 +5392,7 @@ void init_top_instance(void)
 }
 
 enum {
+	OPT_tsc2nsec		= 240,
 	OPT_fork		= 241,
 	OPT_tsyncinterval	= 242,
 	OPT_user		= 243,
@@ -5676,6 +5688,78 @@ check_instance_die(struct buffer_instance *instance, char *param)
 		    tracefs_instance_get_name(instance->tracefs), param);
 }
 
+static bool clock_is_supported(struct tracefs_instance *instance, char *clock)
+{
+	char *all_clocks = NULL;
+	char *ret = NULL;
+
+	all_clocks  = tracefs_instance_file_read(instance, "trace_clock", NULL);
+	if (!all_clocks)
+		return false;
+
+	ret = strstr(all_clocks, clock);
+	free(all_clocks);
+
+	if (ret)
+		return true;
+	return false;
+}
+
+#ifdef PERF
+static int get_tsc_nsec(int *shift, int *mult)
+{
+	static int cpu_shift, cpu_mult;
+	static int supported;
+	int cpus = tracecmd_count_cpus();
+	struct trace_perf perf;
+	int i;
+
+	if (supported)
+		goto out;
+
+	supported = -1;
+	if (trace_perf_init(&perf, 1, 0, getpid()))
+		return -1;
+	if (trace_perf_open(&perf))
+		return -1;
+	cpu_shift = perf.mmap->time_shift;
+	cpu_mult = perf.mmap->time_mult;
+	for (i = 1; i < cpus; i++) {
+		trace_perf_close(&perf);
+		if (trace_perf_init(&perf, 1, i, getpid()))
+			break;
+		if (trace_perf_open(&perf))
+			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;
+
+	supported = 1;
+out:
+	if (supported < 0)
+		return -1;
+
+	if (shift)
+		*shift = cpu_shift;
+	if (mult)
+		*mult = cpu_mult;
+
+	return 0;
+}
+#else
+static int get_tsc_nsec(int *shift, int *mult)
+{
+	return -1;
+}
+#endif
+
 static void parse_record_options(int argc,
 				 char **argv,
 				 enum trace_cmd curr_cmd,
@@ -5725,6 +5809,7 @@ static void parse_record_options(int argc,
 			{"module", required_argument, NULL, OPT_module},
 			{"tsync-interval", required_argument, NULL, OPT_tsyncinterval},
 			{"fork", no_argument, NULL, OPT_fork},
+			{"tsc2nsec", no_argument, NULL, OPT_tsc2nsec},
 			{NULL, 0, NULL, 0}
 		};
 
@@ -5870,7 +5955,15 @@ static void parse_record_options(int argc,
 			break;
 		case 'C':
 			check_instance_die(ctx->instance, "-C");
-			ctx->instance->clock = optarg;
+			if (!strncmp(optarg, TSCNSEC_CLOCK, strlen(TSCNSEC_CLOCK))) {
+				ret = get_tsc_nsec(&ctx->tsc2nsec.shift,
+						   &ctx->tsc2nsec.mult);
+				if (ret || !clock_is_supported(NULL, TSC_CLOCK))
+					die("Clock %s is not supported", optarg);
+				ctx->instance->flags |= BUFFER_FL_TSC2NSEC;
+				ctx->instance->clock = strdup(TSC_CLOCK);
+			} else
+				ctx->instance->clock = optarg;
 			ctx->instance->flags |= BUFFER_FL_HAS_CLOCK;
 			if (is_top_instance(ctx->instance))
 				guest_sync_set = true;
@@ -6125,6 +6218,13 @@ static void parse_record_options(int argc,
 				die("--fork option used for 'start' command only");
 			fork_process = true;
 			break;
+		case OPT_tsc2nsec:
+			ret = get_tsc_nsec(&ctx->tsc2nsec.shift,
+					   &ctx->tsc2nsec.mult);
+			if (ret)
+				die("TSC to nanosecond is not supported");
+			ctx->instance->flags |= BUFFER_FL_TSC2NSEC;
+			break;
 		case OPT_quiet:
 		case 'q':
 			quiet = true;
@@ -6272,6 +6372,66 @@ static bool has_local_instances(void)
 	return false;
 }
 
+/*
+ * Get the current clock value
+ */
+#define CLOCK_INST_NAME	"_clock_instance_"
+static unsigned long long get_clock_now(const char *clock)
+{
+	struct tracefs_instance *ts_instance = NULL;
+	unsigned long long ts = 0;
+	struct tep_handle *tep;
+	int tfd = -1;
+	int ret;
+
+	/* Set up a tep to read the raw format */
+	tep = get_ftrace_tep();
+	if (!tep)
+		return 0;
+	ts_instance = tracefs_instance_create(CLOCK_INST_NAME);
+	if (!ts_instance)
+		goto out;
+	if (clock) {
+		ret = tracefs_instance_file_write(ts_instance, "trace_clock", clock);
+		if (ret < strlen(clock))
+			goto out;
+	}
+	tfd = tracefs_instance_file_open(ts_instance, "trace_marker", O_WRONLY);
+	if (tfd < 0)
+		goto out;
+	tracefs_trace_on(ts_instance);
+	ret = write(tfd, STAMP, 5);
+	tracefs_trace_off(ts_instance);
+	ts = find_time_stamp(tep, ts_instance);
+
+out:
+	if (tfd >= 0)
+		close(tfd);
+	if (ts_instance) {
+		if (tracefs_instance_is_new(ts_instance))
+			tracefs_instance_destroy(ts_instance);
+		tracefs_instance_free(ts_instance);
+	}
+	tep_free(tep);
+
+	return ts;
+}
+
+static void get_tsc_offset(struct common_record_context *ctx)
+{
+	struct buffer_instance *instance;
+
+	for_all_instances(instance) {
+		if (is_guest(instance) || !instance->clock)
+			return;
+
+		ctx->tsc2nsec.offset = get_clock_now(instance->clock);
+		return;
+	}
+
+	ctx->tsc2nsec.offset = get_clock_now(NULL);
+}
+
 /*
  * This function contains common code for the following commands:
  * record, start, stream, profile.
@@ -6330,6 +6490,9 @@ static void record_trace(int argc, char **argv,
 	for_all_instances(instance)
 		set_clock(instance);
 
+	if (ctx->tsc2nsec.mult)
+		get_tsc_offset(ctx);
+
 	/* Record records the date first */
 	if (ctx->date &&
 	    ((IS_RECORD(ctx) && has_local_instances()) || IS_RECORD_AGENT(ctx)))
-- 
2.30.2

Re: [PATCH v2 04/18] trace-cmd: Add new trace-cmd clock tsc2nsec

[Steven Rostedt]

On Mon, 22 Mar 2021 11:59:31 +0200
"Tzvetomir Stoyanov (VMware)" <tz.stoyanov@gmail.com> wrote:
>  
> +static struct tep_handle *get_ftrace_tep(void)
> +{
> +	const char *systems[] = {"ftrace", NULL};
> +	struct tep_handle *tep;
> +	char *buf;
> +	int size;
> +	int ret;
> +
> +	tep = tracefs_local_events_system(NULL, systems);
> +	if (!tep)
> +		return NULL;
> +	tep_set_file_bigendian(tep, tracecmd_host_bigendian());
> +	buf = read_top_file("events/header_page", &size);
> +	if (!buf)
> +		goto error;
> +	ret = tep_parse_header_page(tep, buf, size, sizeof(unsigned long));
> +	free(buf);
> +	if (ret < 0)
> +		goto error;
> +
> +	return tep;
> +
> +error:
> +	tep_free(tep);
> +	return NULL;
> +}
> +
>  /*
>   * Try to write the date into the ftrace buffer and then
>   * read it back, mapping the timestamp to the date.
>   */
>  static char *get_date_to_ts(void)
>  {
> -	const char *systems[] = {"ftrace", NULL};
> +	struct tep_handle *tep;
>  	unsigned long long min = -1ULL;
>  	unsigned long long diff;
>  	unsigned long long stamp;
>  	unsigned long long min_stamp;
>  	unsigned long long min_ts;
>  	unsigned long long ts;
> -	struct tep_handle *tep;
>  	struct timespec start;
>  	struct timespec end;
>  	char *date2ts = NULL;
> -	char *path;
> -	char *buf;
> -	int size;
>  	int tfd;
> -	int ret;
>  	int i;
>  
>  	/* Set up a tep to read the raw format */
> -	tep = tracefs_local_events_system(NULL, systems);
> +	tep = get_ftrace_tep();
>  	if (!tep) {
>  		warning("failed to alloc tep, --date ignored");
>  		return NULL;
>  	}
> -
> -	tep_set_file_bigendian(tep, tracecmd_host_bigendian());
> -
> -	buf = read_top_file("events/header_page", &size);
> -	if (!buf)
> -		goto out_pevent;
> -	ret = tep_parse_header_page(tep, buf, size, sizeof(unsigned long));
> -	free(buf);
> -	if (ret < 0) {
> -		warning("Can't parse header page, --date ignored");
> -		goto out_pevent;
> -	}
> -
> -	path = tracefs_get_tracing_file("trace_marker");
> -	tfd = open(path, O_WRONLY);
> -	tracefs_put_tracing_file(path);
> +	tfd = tracefs_instance_file_open(NULL, "trace_marker", O_WRONLY);

The above looks like a clean up worthy of its own patch ;-)

>  	if (tfd < 0) {
>  		warning("Can not open 'trace_marker', --date ignored");
>  		goto out_pevent;
> @@ -4520,7 +4531,7 @@ static char *get_date_to_ts(void)
>  		clock_gettime(CLOCK_REALTIME, &end);
>  
>  		tracecmd_disable_tracing();
> -		ts = find_time_stamp(tep);
> +		ts = find_time_stamp(tep, NULL);
>  		if (!ts)
>  			continue;
>  
> @@ -5381,6 +5392,7 @@ void init_top_instance(void)
>  }
>  
>  enum {
> +	OPT_tsc2nsec		= 240,
>  	OPT_fork		= 241,
>  	OPT_tsyncinterval	= 242,
>  	OPT_user		= 243,
> @@ -5676,6 +5688,78 @@ check_instance_die(struct buffer_instance *instance, char *param)
>  		    tracefs_instance_get_name(instance->tracefs), param);
>  }
>  
> +static bool clock_is_supported(struct tracefs_instance *instance, char *clock)
> +{
> +	char *all_clocks = NULL;
> +	char *ret = NULL;
> +
> +	all_clocks  = tracefs_instance_file_read(instance, "trace_clock", NULL);
> +	if (!all_clocks)
> +		return false;
> +
> +	ret = strstr(all_clocks, clock);

I think you want to check to make sure that the clock is really a
match. Otherwise if we have a clock called "x86" and another called
"x86-tsc", If you search for "x86" it will say it's a match because it
matched x86-tsc. I think you need to add:

	if (ret &&
	    (ret == all_clocks ||
	     ret[-1] == ' ' ||
	     ret[-1] == '[')) {
		switch (ret[strlen(clock)]) {
		case ' ':
		case '\0':
		case ']':
			break;
		default:
			ret = NULL;
		}
	} else {
		ret = NULL;
	}


> +	free(all_clocks);
> +
> +	if (ret)
> +		return true;
> +	return false;

the above can also be written as:

	return ret != NULL;

> +}
> +
> +#ifdef PERF
> +static int get_tsc_nsec(int *shift, int *mult)
> +{
> +	static int cpu_shift, cpu_mult;
> +	static int supported;
> +	int cpus = tracecmd_count_cpus();
> +	struct trace_perf perf;
> +	int i;
> +
> +	if (supported)
> +		goto out;
> +
> +	supported = -1;
> +	if (trace_perf_init(&perf, 1, 0, getpid()))
> +		return -1;
> +	if (trace_perf_open(&perf))
> +		return -1;
> +	cpu_shift = perf.mmap->time_shift;
> +	cpu_mult = perf.mmap->time_mult;
> +	for (i = 1; i < cpus; i++) {
> +		trace_perf_close(&perf);
> +		if (trace_perf_init(&perf, 1, i, getpid()))
> +			break;
> +		if (trace_perf_open(&perf))
> +			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;
> +
> +	supported = 1;
> +out:
> +	if (supported < 0)
> +		return -1;
> +
> +	if (shift)
> +		*shift = cpu_shift;
> +	if (mult)
> +		*mult = cpu_mult;
> +
> +	return 0;
> +}
> +#else
> +static int get_tsc_nsec(int *shift, int *mult)
> +{
> +	return -1;
> +}
> +#endif
> +
>  static void parse_record_options(int argc,
>  				 char **argv,
>  				 enum trace_cmd curr_cmd,
> @@ -5725,6 +5809,7 @@ static void parse_record_options(int argc,
>  			{"module", required_argument, NULL, OPT_module},
>  			{"tsync-interval", required_argument, NULL, OPT_tsyncinterval},
>  			{"fork", no_argument, NULL, OPT_fork},
> +			{"tsc2nsec", no_argument, NULL, OPT_tsc2nsec},
>  			{NULL, 0, NULL, 0}
>  		};
>  
> @@ -5870,7 +5955,15 @@ static void parse_record_options(int argc,
>  			break;
>  		case 'C':
>  			check_instance_die(ctx->instance, "-C");
> -			ctx->instance->clock = optarg;
> +			if (!strncmp(optarg, TSCNSEC_CLOCK, strlen(TSCNSEC_CLOCK))) {
> +				ret = get_tsc_nsec(&ctx->tsc2nsec.shift,
> +						   &ctx->tsc2nsec.mult);
> +				if (ret || !clock_is_supported(NULL, TSC_CLOCK))
> +					die("Clock %s is not supported", optarg);
> +				ctx->instance->flags |= BUFFER_FL_TSC2NSEC;
> +				ctx->instance->clock = strdup(TSC_CLOCK);
> +			} else
> +				ctx->instance->clock = optarg;

Clock is supported check should also be a separate patch, as it is
unrelated to the tsc2nsec code. That is, it holds its own as a
separate change.

>  			ctx->instance->flags |= BUFFER_FL_HAS_CLOCK;
>  			if (is_top_instance(ctx->instance))
>  				guest_sync_set = true;
> @@ -6125,6 +6218,13 @@ static void parse_record_options(int argc,
>  				die("--fork option used for 'start' command only");
>  			fork_process = true;
>  			break;
> +		case OPT_tsc2nsec:
> +			ret = get_tsc_nsec(&ctx->tsc2nsec.shift,
> +					   &ctx->tsc2nsec.mult);
> +			if (ret)
> +				die("TSC to nanosecond is not supported");
> +			ctx->instance->flags |= BUFFER_FL_TSC2NSEC;
> +			break;
>  		case OPT_quiet:
>  		case 'q':
>  			quiet = true;
> @@ -6272,6 +6372,66 @@ static bool has_local_instances(void)
>  	return false;
>  }
>  
> +/*
> + * Get the current clock value
> + */
> +#define CLOCK_INST_NAME	"_clock_instance_"
> +static unsigned long long get_clock_now(const char *clock)
> +{
> +	struct tracefs_instance *ts_instance = NULL;
> +	unsigned long long ts = 0;
> +	struct tep_handle *tep;
> +	int tfd = -1;
> +	int ret;
> +
> +	/* Set up a tep to read the raw format */
> +	tep = get_ftrace_tep();
> +	if (!tep)
> +		return 0;
> +	ts_instance = tracefs_instance_create(CLOCK_INST_NAME);
> +	if (!ts_instance)
> +		goto out;
> +	if (clock) {
> +		ret = tracefs_instance_file_write(ts_instance, "trace_clock", clock);
> +		if (ret < strlen(clock))
> +			goto out;
> +	}
> +	tfd = tracefs_instance_file_open(ts_instance, "trace_marker", O_WRONLY);
> +	if (tfd < 0)
> +		goto out;
> +	tracefs_trace_on(ts_instance);
> +	ret = write(tfd, STAMP, 5);

If we had the tracefs_print code, we could use that here :-)


> +	tracefs_trace_off(ts_instance);
> +	ts = find_time_stamp(tep, ts_instance);
> +
> +out:
> +	if (tfd >= 0)
> +		close(tfd);

tfd is always < 0 on all jumps to out. The logic works the same as:

	close(tfd);
 out:

And you don't have to initialize tfd to -1 in the beginning either.


> +	if (ts_instance) {
> +		if (tracefs_instance_is_new(ts_instance))
> +			tracefs_instance_destroy(ts_instance);
> +		tracefs_instance_free(ts_instance);
> +	}
> +	tep_free(tep);
> +

Another method for goto's so you don't need the "if (ts_instance)" is to have:

	ts_instance = tracefs_instance_create(CLOCK_INST_NAME);
	if (!ts_instance)
		goto out_free;

	[..]

out:
	if (tracefs_instance_is_new(ts_instance))
		tracefs_instance_destroy(ts_instance);
	tracefs_instance_free(ts_instaence);
out_free:
	tep_free(tep);

The above is done often in the kernel.

-- Steve

> +	return ts;
> +}
> +
> +static void get_tsc_offset(struct common_record_context *ctx)
> +{
> +	struct buffer_instance *instance;
> +
> +	for_all_instances(instance) {
> +		if (is_guest(instance) || !instance->clock)
> +			return;
> +
> +		ctx->tsc2nsec.offset = get_clock_now(instance->clock);
> +		return;
> +	}
> +
> +	ctx->tsc2nsec.offset = get_clock_now(NULL);
> +}
> +
>  /*
>   * This function contains common code for the following commands:
>   * record, start, stream, profile.
> @@ -6330,6 +6490,9 @@ static void record_trace(int argc, char **argv,
>  	for_all_instances(instance)
>  		set_clock(instance);
>  
> +	if (ctx->tsc2nsec.mult)
> +		get_tsc_offset(ctx);
> +
>  	/* Record records the date first */
>  	if (ctx->date &&
>  	    ((IS_RECORD(ctx) && has_local_instances()) || IS_RECORD_AGENT(ctx)))

[PATCH v2 05/18] 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                         | 19 +++++++++++++++++++
 2 files changed, 20 insertions(+)

diff --git a/lib/trace-cmd/include/private/trace-cmd-private.h b/lib/trace-cmd/include/private/trace-cmd-private.h
index a4637046..ce3d8dc0 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 4bdfd53f..31b9d201 100644
--- a/tracecmd/trace-dump.c
+++ b/tracecmd/trace-dump.c
@@ -483,6 +483,22 @@ out:
 	free(buf);
 }
 
+void dump_option_tsc2nsec(int fd, int size)
+{
+	int mult, shift;
+	unsigned long long 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, 8))
+		die("cannot read tsc2nsec offset");
+	do_print(OPTIONS, "%d %d %llu [multiplier, shift, offset]\n", mult, shift, offset);
+}
+
 static void dump_options(int fd)
 {
 	unsigned short option;
@@ -543,6 +559,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.30.2

Re: [PATCH v2 05/18] trace-cmd: Add a new option in trace file metadata for tsc2nsec conversion

[Steven Rostedt]

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

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

Did you forgot to commit something in this patch? because the below
change doesn't match the change log. I was expecting to see the code
that adds the new option, but the code below is only code to have
trace-cmd dump output it.

-- Steve


> Signed-off-by: Tzvetomir Stoyanov (VMware) <tz.stoyanov@gmail.com>
> ---
>  .../include/private/trace-cmd-private.h       |  1 +
>  tracecmd/trace-dump.c                         | 19 +++++++++++++++++++
>  2 files changed, 20 insertions(+)
> 
> diff --git a/lib/trace-cmd/include/private/trace-cmd-private.h b/lib/trace-cmd/include/private/trace-cmd-private.h
> index a4637046..ce3d8dc0 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 4bdfd53f..31b9d201 100644
> --- a/tracecmd/trace-dump.c
> +++ b/tracecmd/trace-dump.c
> @@ -483,6 +483,22 @@ out:
>  	free(buf);
>  }
>  
> +void dump_option_tsc2nsec(int fd, int size)
> +{
> +	int mult, shift;
> +	unsigned long long 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, 8))
> +		die("cannot read tsc2nsec offset");
> +	do_print(OPTIONS, "%d %d %llu [multiplier, shift, offset]\n", mult, shift, offset);
> +}
> +
>  static void dump_options(int fd)
>  {
>  	unsigned short option;
> @@ -543,6 +559,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);

[PATCH v2 06/18] 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 | 32 ++++++++++++++++++++++++++++----
 1 file changed, 28 insertions(+), 4 deletions(-)

diff --git a/tracecmd/trace-record.c b/tracecmd/trace-record.c
index 38edea2c..37a0f486 100644
--- a/tracecmd/trace-record.c
+++ b/tracecmd/trace-record.c
@@ -668,7 +668,24 @@ static void delete_thread_data(void)
 	}
 }
 
-static void host_tsync_complete(struct buffer_instance *instance)
+static void
+add_tsc2nsec(struct tracecmd_output *handle, struct tsc_nsec *tsc2nsec)
+{
+	/* multiplier, shift, offset */
+	struct iovec vector[3];
+
+	vector[0].iov_len = 4;
+	vector[0].iov_base = &tsc2nsec->mult;
+	vector[1].iov_len = 4;
+	vector[1].iov_base = &tsc2nsec->shift;
+	vector[2].iov_len = 8;
+	vector[2].iov_base = &tsc2nsec->offset;
+
+	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;
@@ -682,6 +699,10 @@ static void host_tsync_complete(struct buffer_instance *instance)
 		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_output_close(handle);
 	}
@@ -690,7 +711,7 @@ static void host_tsync_complete(struct buffer_instance *instance)
 	instance->tsync = NULL;
 }
 
-static void tell_guests_to_stop(void)
+static void tell_guests_to_stop(struct common_record_context *ctx)
 {
 	struct buffer_instance *instance;
 
@@ -702,7 +723,7 @@ static void tell_guests_to_stop(void)
 
 	for_all_instances(instance) {
 		if (is_guest(instance))
-			host_tsync_complete(instance);
+			host_tsync_complete(ctx, instance);
 	}
 
 	/* Wait for guests to acknowledge */
@@ -4269,6 +4290,9 @@ static void record_data(struct common_record_context *ctx)
 				add_guest_info(handle, instance);
 		}
 
+		if (ctx->tsc2nsec.mult)
+			add_tsc2nsec(handle, &ctx->tsc2nsec);
+
 		if (tracecmd_write_cmdlines(handle))
 			die("Writing cmdlines");
 
@@ -6573,7 +6597,7 @@ static void record_trace(int argc, char **argv,
 			trace_or_sleep(type, pwait);
 	}
 
-	tell_guests_to_stop();
+	tell_guests_to_stop(ctx);
 	tracecmd_disable_tracing();
 	if (!latency)
 		stop_threads(type);
-- 
2.30.2

[PATCH v2 07/18] 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..ebc28f7b 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;
+	unsigned long long 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 < 16)
+				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, 8);
+			break;
 		default:
 			warning("unknown option %d", option);
 			break;
-- 
2.30.2

[PATCH v2 08/18] trace-cmd: Save tsc2nsec clock in trace.dat file

[Tzvetomir Stoyanov (VMware)]

When tsc2nsec clock is used, save it as selected clock in the trace.dat
file. When reading the file, in case of tsc2nsec clock show timestamps
in usec / nsec.

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

diff --git a/lib/trace-cmd/include/private/trace-cmd-private.h b/lib/trace-cmd/include/private/trace-cmd-private.h
index ce3d8dc0..c33d067a 100644
--- a/lib/trace-cmd/include/private/trace-cmd-private.h
+++ b/lib/trace-cmd/include/private/trace-cmd-private.h
@@ -22,6 +22,8 @@
 #define TRACECMD_ERROR(ret)	((void *)((unsigned long)(ret) | TRACECMD_ERR_MSK))
 #define TRACECMD_PTR2ERR(ptr)	((unisgned long)(ptr) & ~TRACECMD_ERR_MSK)
 
+#define TSCNSEC_CLOCK	"tsc2nsec"
+
 void tracecmd_parse_cmdlines(struct tep_handle *pevent, char *file, int size);
 void tracecmd_parse_proc_kallsyms(struct tep_handle *pevent, char *file, unsigned int size);
 void tracecmd_parse_ftrace_printk(struct tep_handle *pevent, char *file, unsigned int size);
diff --git a/lib/trace-cmd/trace-input.c b/lib/trace-cmd/trace-input.c
index ebc28f7b..67915f25 100644
--- a/lib/trace-cmd/trace-input.c
+++ b/lib/trace-cmd/trace-input.c
@@ -2906,7 +2906,7 @@ static void extract_trace_clock(struct tracecmd_input *handle, char *line)
 	/* Clear usecs if not one of the specified clocks */
 	if (strcmp(clock, "local") && strcmp(clock, "global") &&
 	    strcmp(clock, "uptime") && strcmp(clock, "perf") &&
-	    strncmp(clock, "mono", 4))
+	    strncmp(clock, "mono", 4) && strcmp(clock, TSCNSEC_CLOCK))
 		handle->flags &= ~TRACECMD_FL_IN_USECS;
 }
 
diff --git a/tracecmd/trace-record.c b/tracecmd/trace-record.c
index 37a0f486..9ae6e032 100644
--- a/tracecmd/trace-record.c
+++ b/tracecmd/trace-record.c
@@ -58,7 +58,6 @@
 #define STAMP		"stamp"
 #define FUNC_STACK_TRACE "func_stack_trace"
 #define TSC_CLOCK	"x86-tsc"
-#define TSCNSEC_CLOCK	"tsc2nsec"
 
 enum trace_type {
 	TRACE_TYPE_RECORD	= 1,
@@ -4168,7 +4167,8 @@ static void write_guest_file(struct buffer_instance *instance)
 	handle = tracecmd_get_output_handle_fd(fd);
 	if (!handle)
 		die("error writing to %s", file);
-
+	if (instance->flags & BUFFER_FL_TSC2NSEC)
+		tracecmd_set_out_clock(handle, TSCNSEC_CLOCK);
 	temp_files = malloc(sizeof(*temp_files) * cpu_count);
 	if (!temp_files)
 		die("failed to allocate temp_files for %d cpus",
@@ -4290,9 +4290,10 @@ static void record_data(struct common_record_context *ctx)
 				add_guest_info(handle, instance);
 		}
 
-		if (ctx->tsc2nsec.mult)
+		if (ctx->tsc2nsec.mult) {
 			add_tsc2nsec(handle, &ctx->tsc2nsec);
-
+			tracecmd_set_out_clock(handle, TSCNSEC_CLOCK);
+		}
 		if (tracecmd_write_cmdlines(handle))
 			die("Writing cmdlines");
 
-- 
2.30.2

Re: [PATCH v2 08/18] trace-cmd: Save tsc2nsec clock in trace.dat file

[Steven Rostedt]

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

> @@ -4168,7 +4167,8 @@ static void write_guest_file(struct buffer_instance *instance)
>  	handle = tracecmd_get_output_handle_fd(fd);
>  	if (!handle)
>  		die("error writing to %s", file);
> -
> +	if (instance->flags & BUFFER_FL_TSC2NSEC)
> +		tracecmd_set_out_clock(handle, TSCNSEC_CLOCK);
>  	temp_files = malloc(sizeof(*temp_files) * cpu_count);
>  	if (!temp_files)
>  		die("failed to allocate temp_files for %d cpus",
> @@ -4290,9 +4290,10 @@ static void record_data(struct common_record_context *ctx)
>  				add_guest_info(handle, instance);
>  		}
>  
> -		if (ctx->tsc2nsec.mult)
> +		if (ctx->tsc2nsec.mult) {
>  			add_tsc2nsec(handle, &ctx->tsc2nsec);
> -
> +			tracecmd_set_out_clock(handle, TSCNSEC_CLOCK);
> +		}
>  		if (tracecmd_write_cmdlines(handle))
>  			die("Writing cmdlines");
>  

OK, I see why you wanted to clean up the writing of all clocks. But I
still find that information valuable as for the reasons I stated in the
other email. I wonder if we can still read all the clocks, parse them
out (remove the '[' and ']') and have tracecmd_set_out_clock() still
write them. Hmm? Or at least save them in a new option (like I save
uname).

-- Steve

Re: [PATCH v2 08/18] trace-cmd: Save tsc2nsec clock in trace.dat file

[Tzvetomir Stoyanov]

On Wed, Mar 24, 2021 at 3:34 AM Steven Rostedt <rostedt@goodmis.org> wrote:
>
> On Mon, 22 Mar 2021 11:59:35 +0200
> "Tzvetomir Stoyanov (VMware)" <tz.stoyanov@gmail.com> wrote:
>
> > @@ -4168,7 +4167,8 @@ static void write_guest_file(struct buffer_instance *instance)
> >       handle = tracecmd_get_output_handle_fd(fd);
> >       if (!handle)
> >               die("error writing to %s", file);
> > -
> > +     if (instance->flags & BUFFER_FL_TSC2NSEC)
> > +             tracecmd_set_out_clock(handle, TSCNSEC_CLOCK);
> >       temp_files = malloc(sizeof(*temp_files) * cpu_count);
> >       if (!temp_files)
> >               die("failed to allocate temp_files for %d cpus",
> > @@ -4290,9 +4290,10 @@ static void record_data(struct common_record_context *ctx)
> >                               add_guest_info(handle, instance);
> >               }
> >
> > -             if (ctx->tsc2nsec.mult)
> > +             if (ctx->tsc2nsec.mult) {
> >                       add_tsc2nsec(handle, &ctx->tsc2nsec);
> > -
> > +                     tracecmd_set_out_clock(handle, TSCNSEC_CLOCK);
> > +             }
> >               if (tracecmd_write_cmdlines(handle))
> >                       die("Writing cmdlines");
> >
>
> OK, I see why you wanted to clean up the writing of all clocks. But I
> still find that information valuable as for the reasons I stated in the
> other email. I wonder if we can still read all the clocks, parse them
> out (remove the '[' and ']') and have tracecmd_set_out_clock() still
> write them. Hmm? Or at least save them in a new option (like I save
> uname).

The TRACECMD_OPTION_TRACECLOCK option can be extended to hold the
content of the "trace_clock" file. It is an empty option now, adding
more bytes will not break the old logic.

>
> -- Steve



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

[PATCH v2 09/18] 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 4c03052d..0097ce15 100644
--- a/lib/trace-cmd/trace-timesync.c
+++ b/lib/trace-cmd/trace-timesync.c
@@ -834,7 +834,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 9ae6e032..54e4b6de 100644
--- a/tracecmd/trace-record.c
+++ b/tracecmd/trace-record.c
@@ -703,6 +703,7 @@ static void host_tsync_complete(struct common_record_context *ctx,
 			add_tsc2nsec(handle, &ctx->tsc2nsec);
 
 		tracecmd_write_guest_time_shift(handle, instance->tsync);
+		tracecmd_append_options(handle);
 		tracecmd_output_close(handle);
 	}
 
-- 
2.30.2

[PATCH v2 10/18] 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 67915f25..be8a7919 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.30.2

[PATCH v2 11/18] 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 be8a7919..dfbe4af6 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.30.2

Re: [PATCH v2 11/18] trace-cmd: Perform all timestamp corrections in a single function

[Steven Rostedt]

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

> 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 be8a7919..dfbe4af6 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;
> +}

I like to save on extra variables ;-)

static unsigned long long timestamp_calc(unsigned long long ts,
					 struct tracecmd_input *handle)
{
	ts = timestamp_correct(ts, handle);

	if (handle->ts2secs)
		ts *= handle->ts2secs;

	return ts;
}


-- Steve

[PATCH v2 12/18] 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 | 29 +++++++++++++++++++++++++----
 1 file changed, 25 insertions(+), 4 deletions(-)

diff --git a/lib/trace-cmd/trace-input.c b/lib/trace-cmd/trace-input.c
index dfbe4af6..7ac81809 100644
--- a/lib/trace-cmd/trace-input.c
+++ b/lib/trace-cmd/trace-input.c
@@ -1196,6 +1196,23 @@ static void free_next(struct tracecmd_input *handle, int cpu)
 	tracecmd_free_record(record);
 }
 
+/* This functions was taken from the Linux kernel */
+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 inline unsigned long long
 timestamp_correction_calc(unsigned long long ts, unsigned int flags,
 			  struct ts_offset_sample *min,
@@ -1279,14 +1296,18 @@ static unsigned long long timestamp_correct(unsigned long long ts,
 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 -= handle->tsc_calc.offset;
+		t = mul_u64_u32_shr(t, handle->tsc_calc.mult, handle->tsc_calc.shift);
+	}
 
-	return tstamp;
+	return t;
 }
 
 /*
-- 
2.30.2

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

[Steven Rostedt]

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

> @@ -1279,14 +1296,18 @@ static unsigned long long timestamp_correct(unsigned long long ts,
>  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 -= handle->tsc_calc.offset;
> +		t = mul_u64_u32_shr(t, handle->tsc_calc.mult, handle->tsc_calc.shift);
> +	}
>  
> -	return tstamp;
> +	return t;
>  }
>  

Like I said, I like to save on extra variables ;-)

static unsigned long long timestamp_calc(unsigned long long ts,
					 struct tracecmd_input *handle)
{
	ts = timestamp_correct(ts, handle);

	if (handle->ts2secs)
		ts *= handle->ts2secs;
	else if (handle->tsc_calc.mult) {
		ts -= handle->tsc_calc.offset;
		ts = mul_u64_u32_shr(t, handle->tsc_calc.mult, handle->tsc_calc.shift);
	}

	return ts;
}

-- Steve

[PATCH v2 13/18] 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 7ac81809..5d03cd00 100644
--- a/lib/trace-cmd/trace-input.c
+++ b/lib/trace-cmd/trace-input.c
@@ -1241,21 +1241,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;
@@ -1296,17 +1287,26 @@ static unsigned long long timestamp_correct(unsigned long long ts,
 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 -= handle->tsc_calc.offset;
 		t = mul_u64_u32_shr(t, handle->tsc_calc.mult, handle->tsc_calc.shift);
 	}
 
+	/* User specified time offset with --ts-offset or --date options */
+	if (handle->ts_offset)
+		t += handle->ts_offset;
+
 	return t;
 }
 
-- 
2.30.2

Re: [PATCH v2 13/18] trace-cmd: Set order and priorities when applying timestamp corrections

[Steven Rostedt]

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

> @@ -1296,17 +1287,26 @@ static unsigned long long timestamp_correct(unsigned long long ts,
>  static unsigned long long timestamp_calc(unsigned long long ts,
>  					 struct tracecmd_input *handle)
>  {
> -	unsigned long long t;
> +	unsigned long long t = ts;

OK, now you are just wasting away extra variables!!!! ;-)

Just use ts, no need to create a local variable. It's OK to reuse the
parameters. gcc will just do it for you anyway.

-- Steve

>  
> -	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 -= handle->tsc_calc.offset;
>  		t = mul_u64_u32_shr(t, handle->tsc_calc.mult, handle->tsc_calc.shift);
>  	}
>  
> +	/* User specified time offset with --ts-offset or --date options */
> +	if (handle->ts_offset)
> +		t += handle->ts_offset;
> +
>  	return t;
>  }
>  

[PATCH v2 14/18] 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 c33d067a..fdca7494 100644
--- a/lib/trace-cmd/include/private/trace-cmd-private.h
+++ b/lib/trace-cmd/include/private/trace-cmd-private.h
@@ -134,6 +134,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 5d03cd00..88007cde 100644
--- a/lib/trace-cmd/trace-input.c
+++ b/lib/trace-cmd/trace-input.c
@@ -1289,6 +1289,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)
@@ -2604,7 +2607,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 */
@@ -2616,7 +2620,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;
@@ -2631,7 +2635,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);
@@ -2710,7 +2714,7 @@ static int handle_options(struct tracecmd_input *handle)
 			trace_guest_load(handle, buf, size);
 			break;
 		case TRACECMD_OPTION_TSC2NSEC:
-			if (size < 16)
+			if (size < 16 || (handle->flags & TRACECMD_FL_RAW_TS))
 				break;
 			handle->tsc_calc.mult = tep_read_number(handle->pevent,
 								buf, 4);
-- 
2.30.2

Re: [PATCH v2 14/18] trace-cmd: Add a new flag to disable any timestamp corrections

[Steven Rostedt]

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

> 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 c33d067a..fdca7494 100644
> --- a/lib/trace-cmd/include/private/trace-cmd-private.h
> +++ b/lib/trace-cmd/include/private/trace-cmd-private.h
> @@ -134,6 +134,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 5d03cd00..88007cde 100644
> --- a/lib/trace-cmd/trace-input.c
> +++ b/lib/trace-cmd/trace-input.c
> @@ -1289,6 +1289,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)
> @@ -2604,7 +2607,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;

These are flags, let's use them as such:

			if (handle->flags &
			    (TRACECMD_FL_IGNORE_DATE | TRACECMD_FL_RAW_TS))
				break;

>  			offset = strtoll(buf, NULL, 0);
>  			/* Convert from micro to nano */
> @@ -2616,7 +2620,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)

Why do we not break here for IGNORE_DATE?

>  				break;
>  			offset = strtoll(buf, NULL, 0);
>  			handle->ts_offset += offset;
> @@ -2631,7 +2635,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))

And why did we change the code for IGNORE_DATE here too?

-- Steve

>  				break;
>  			handle->host.peer_trace_id = tep_read_number(handle->pevent,
>  								     buf, 8);
> @@ -2710,7 +2714,7 @@ static int handle_options(struct tracecmd_input *handle)
>  			trace_guest_load(handle, buf, size);
>  			break;
>  		case TRACECMD_OPTION_TSC2NSEC:
> -			if (size < 16)
> +			if (size < 16 || (handle->flags & TRACECMD_FL_RAW_TS))
>  				break;
>  			handle->tsc_calc.mult = tep_read_number(handle->pevent,
>  								buf, 4);

Re: [PATCH v2 14/18] trace-cmd: Add a new flag to disable any timestamp corrections

[Tzvetomir Stoyanov]

On Wed, Mar 24, 2021 at 3:49 AM Steven Rostedt <rostedt@goodmis.org> wrote:
>
> On Mon, 22 Mar 2021 11:59:41 +0200
> "Tzvetomir Stoyanov (VMware)" <tz.stoyanov@gmail.com> wrote:
>
> > 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 c33d067a..fdca7494 100644
> > --- a/lib/trace-cmd/include/private/trace-cmd-private.h
> > +++ b/lib/trace-cmd/include/private/trace-cmd-private.h
> > @@ -134,6 +134,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 5d03cd00..88007cde 100644
> > --- a/lib/trace-cmd/trace-input.c
> > +++ b/lib/trace-cmd/trace-input.c
> > @@ -1289,6 +1289,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)
> > @@ -2604,7 +2607,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;
>
> These are flags, let's use them as such:
>
>                         if (handle->flags &
>                             (TRACECMD_FL_IGNORE_DATE | TRACECMD_FL_RAW_TS))
>                                 break;
>
> >                       offset = strtoll(buf, NULL, 0);
> >                       /* Convert from micro to nano */
> > @@ -2616,7 +2620,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)
>
> Why do we not break here for IGNORE_DATE?
>
> >                               break;
> >                       offset = strtoll(buf, NULL, 0);
> >                       handle->ts_offset += offset;
> > @@ -2631,7 +2635,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))
>
> And why did we change the code for IGNORE_DATE here too?

When we discuss the priorities of the various time sync options, I
understood that the "--nodate" should affect the "--date" option only.
For all other time sync options, the new flag should be used. That's
why I changed IGNORE_DATE to RAW_TS in these two places.

>
> -- Steve
>
> >                               break;
> >                       handle->host.peer_trace_id = tep_read_number(handle->pevent,
> >                                                                    buf, 8);
> > @@ -2710,7 +2714,7 @@ static int handle_options(struct tracecmd_input *handle)
> >                       trace_guest_load(handle, buf, size);
> >                       break;
> >               case TRACECMD_OPTION_TSC2NSEC:
> > -                     if (size < 16)
> > +                     if (size < 16 || (handle->flags & TRACECMD_FL_RAW_TS))
> >                               break;
> >                       handle->tsc_calc.mult = tep_read_number(handle->pevent,
> >                                                               buf, 4);
>


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

Re: [PATCH v2 14/18] trace-cmd: Add a new flag to disable any timestamp corrections

[Steven Rostedt]

On Wed, 24 Mar 2021 14:10:56 +0200
Tzvetomir Stoyanov <tz.stoyanov@gmail.com> wrote:

> > And why did we change the code for IGNORE_DATE here too?  
> 
> When we discuss the priorities of the various time sync options, I
> understood that the "--nodate" should affect the "--date" option only.
> For all other time sync options, the new flag should be used. That's
> why I changed IGNORE_DATE to RAW_TS in these two places.

I kind of remember that, but as it's unrelated to this patch, let's make
that a separate change, as it doesn't match the change log.

Thanks!

-- Steve

[PATCH v2 15/18] 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>
---
 lib/trace-cmd/trace-input.c | 4 ++++
 tracecmd/trace-read.c       | 9 ++++++++-
 2 files changed, 12 insertions(+), 1 deletion(-)

diff --git a/lib/trace-cmd/trace-input.c b/lib/trace-cmd/trace-input.c
index 88007cde..256431f0 100644
--- a/lib/trace-cmd/trace-input.c
+++ b/lib/trace-cmd/trace-input.c
@@ -2934,6 +2934,10 @@ static void extract_trace_clock(struct tracecmd_input *handle, char *line)
 	if (!clock)
 		return;
 
+	/* Clear usecs if raw timestamps are requested */
+	if (handle->flags & TRACECMD_FL_RAW_TS)
+		handle->flags &= ~TRACECMD_FL_IN_USECS;
+
 	/* Clear usecs if not one of the specified clocks */
 	if (strcmp(clock, "local") && strcmp(clock, "global") &&
 	    strcmp(clock, "uptime") && strcmp(clock, "perf") &&
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.30.2

[PATCH v2 16/18] trace-cmd: Print times in TimeShift options as unsigned in trace-cmd dump

[Tzvetomir Stoyanov (VMware)]

Fixed "trace-cmd dump" subcommand to print unsigned times from
Time Shift option in a trace.dat file.

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

diff --git a/tracecmd/trace-dump.c b/tracecmd/trace-dump.c
index 31b9d201..f5b864f7 100644
--- a/tracecmd/trace-dump.c
+++ b/tracecmd/trace-dump.c
@@ -373,7 +373,7 @@ static void dump_option_timeshift(int fd, int size)
 {
 	long long *scalings = NULL;
 	long long *offsets = NULL;
-	long long *times = NULL;
+	unsigned long long *times = NULL;
 	long long trace_id;
 	unsigned int count;
 	unsigned int flags;
-- 
2.30.2

[PATCH v2 17/18] trace-cmd: Use tsc clock for host-guest tracing, if available

[Tzvetomir Stoyanov (VMware)]

In a host-guest tracing session, if there is no user configured tracing
clock, use TSC by default if following conditions are met:
  - tsc-x86 trace clock is available on the host
  - params for tsc to nanosecond conversion can be retrieved using
    perf interface of the Liunx kernel - miltiplier and shift

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

diff --git a/tracecmd/trace-record.c b/tracecmd/trace-record.c
index 54e4b6de..552be914 100644
--- a/tracecmd/trace-record.c
+++ b/tracecmd/trace-record.c
@@ -198,8 +198,10 @@ struct common_record_context {
 	const char *output;
 	char *date2ts;
 	char *user;
+	const char *clock;
 	int data_flags;
 	struct tsc_nsec tsc2nsec;
+	int tsync_loop_interval;
 
 	int record_all;
 	int total_disable;
@@ -3708,7 +3710,8 @@ static int open_guest_fifos(const char *guest, int **fds)
 	return i;
 }
 
-static int host_tsync(struct buffer_instance *instance,
+static int host_tsync(struct common_record_context *ctx,
+		      struct buffer_instance *instance,
 		      unsigned int tsync_port, char *proto)
 {
 	struct trace_guest *guest;
@@ -3723,14 +3726,15 @@ static int host_tsync(struct buffer_instance *instance,
 						    instance->tsync_loop_interval,
 						    instance->cid, tsync_port,
 						    guest->pid, guest->cpu_max,
-						    proto, top_instance.clock);
+						    proto, ctx->clock);
 	if (!instance->tsync)
 		return -1;
 
 	return 0;
 }
 
-static void connect_to_agent(struct buffer_instance *instance)
+static void connect_to_agent(struct common_record_context *ctx,
+			     struct buffer_instance *instance)
 {
 	struct tracecmd_tsync_protos *protos = NULL;
 	int sd, ret, nr_fifos, nr_cpus, page_size;
@@ -3783,7 +3787,7 @@ static void connect_to_agent(struct buffer_instance *instance)
 			printf("Negotiated %s time sync protocol with guest %s\n",
 				tsync_protos_reply,
 				instance->name);
-			host_tsync(instance, tsync_port, tsync_protos_reply);
+			host_tsync(ctx, instance, tsync_port, tsync_protos_reply);
 		} else
 			warning("Failed to negotiate timestamps synchronization with the guest");
 	}
@@ -3862,7 +3866,7 @@ void start_threads(enum trace_type type, struct common_record_context *ctx)
 	for_all_instances(instance) {
 		/* Start the connection now to find out how many CPUs we need */
 		if (is_guest(instance))
-			connect_to_agent(instance);
+			connect_to_agent(ctx, instance);
 		total_cpu_count += instance->cpu_count;
 	}
 
@@ -4128,6 +4132,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)
@@ -5801,7 +5806,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;
 
@@ -5936,6 +5940,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':
@@ -5988,11 +5993,13 @@ static void parse_record_options(int argc,
 					die("Clock %s is not supported", optarg);
 				ctx->instance->flags |= BUFFER_FL_TSC2NSEC;
 				ctx->instance->clock = strdup(TSC_CLOCK);
+				if (!ctx->instance->clock)
+					die("Cannot allocate instance clock");
 			} else
 				ctx->instance->clock = optarg;
 			ctx->instance->flags |= BUFFER_FL_HAS_CLOCK;
-			if (is_top_instance(ctx->instance))
-				guest_sync_set = true;
+			if (!ctx->clock && !is_guest(ctx->instance))
+				ctx->clock = ctx->instance->clock;
 			break;
 		case 'v':
 			negative = 1;
@@ -6236,8 +6243,7 @@ static void parse_record_options(int argc,
 			break;
 		case OPT_tsyncinterval:
 			cmd_check_die(ctx, CMD_set, *(argv+1), "--tsync-interval");
-			top_instance.tsync_loop_interval = atoi(optarg);
-			guest_sync_set = true;
+			ctx->tsync_loop_interval = atoi(optarg);
 			break;
 		case OPT_fork:
 			if (!IS_START(ctx))
@@ -6271,26 +6277,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,
@@ -6458,6 +6444,56 @@ static void get_tsc_offset(struct common_record_context *ctx)
 	ctx->tsc2nsec.offset = get_clock_now(NULL);
 }
 
+static void set_tsync_params(struct common_record_context *ctx)
+{
+	const char *clock = ctx->clock;
+	struct buffer_instance *instance;
+	int shift, mult;
+	bool force_tsc = false;
+
+	/*
+	 * If no clock is configured &&
+	 * KVM time sync protocol is available &&
+	 * tsc-x86 clock is supported &&
+	 * 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") &&
+	    clock_is_supported(NULL, TSC_CLOCK) &&
+	    !get_tsc_nsec(&shift, &mult) && mult) {
+		clock = TSC_CLOCK;
+		ctx->tsc2nsec.mult = mult;
+		ctx->tsc2nsec.shift = shift;
+		ctx->tsc2nsec.offset = get_clock_now(TSC_CLOCK);
+		force_tsc = true;
+	}
+
+	if (!clock && !ctx->tsync_loop_interval)
+		return;
+	for_all_instances(instance) {
+		if (clock && !(instance->flags & BUFFER_FL_HAS_CLOCK)) {
+			/* use the same clock in all tracing peers */
+			if (is_guest(instance)) {
+				if (!instance->clock) {
+					instance->clock = strdup(clock);
+					if (!instance->clock)
+						die("Can not allocate instance clock");
+				}
+				add_argv(instance, (char *)instance->clock, true);
+				add_argv(instance, "-C", true);
+				if (ctx->tsc2nsec.mult)
+					instance->flags |= BUFFER_FL_TSC2NSEC;
+			} else if (force_tsc && !instance->clock) {
+				instance->clock = strdup(clock);
+				if (!instance->clock)
+					die("Can not allocate instance clock");
+			}
+		}
+		instance->tsync_loop_interval = ctx->tsync_loop_interval;
+	}
+}
+
 /*
  * This function contains common code for the following commands:
  * record, start, stream, profile.
@@ -6487,6 +6523,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_tsync_params(ctx);
+
 	make_instances();
 
 	/* Save the state of tracing_on before starting */
-- 
2.30.2

[PATCH v2 18/18] trace-cmd: Get current clock for host-guest tracing session

[Tzvetomir Stoyanov (VMware)]

In host-guest tracing session, all peers should use the same tracing
clock. If there is no user configured trace clock, the current logic
assumes "local" clock for the session. This could be wrong, as other
clock than "local" could be already configured on the host, before
running trace-cmd. The default clock for host-guest tracing session
should be rertieved from the host's "trace_clock" file.

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

diff --git a/tracecmd/trace-record.c b/tracecmd/trace-record.c
index 552be914..d0591e26 100644
--- a/tracecmd/trace-record.c
+++ b/tracecmd/trace-record.c
@@ -6446,11 +6446,12 @@ static void get_tsc_offset(struct common_record_context *ctx)
 
 static void set_tsync_params(struct common_record_context *ctx)
 {
-	const char *clock = ctx->clock;
 	struct buffer_instance *instance;
 	int shift, mult;
 	bool force_tsc = false;
+	char *clock = NULL;
 
+	if (!ctx->clock) {
 	/*
 	 * If no clock is configured &&
 	 * KVM time sync protocol is available &&
@@ -6459,18 +6460,35 @@ static void set_tsync_params(struct common_record_context *ctx)
 	 * 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") &&
-	    clock_is_supported(NULL, TSC_CLOCK) &&
-	    !get_tsc_nsec(&shift, &mult) && mult) {
-		clock = TSC_CLOCK;
-		ctx->tsc2nsec.mult = mult;
-		ctx->tsc2nsec.shift = shift;
-		ctx->tsc2nsec.offset = get_clock_now(TSC_CLOCK);
-		force_tsc = true;
+		if (tsync_proto_is_supported("kvm") &&
+		    clock_is_supported(NULL, TSC_CLOCK) &&
+		    !get_tsc_nsec(&shift, &mult) && mult) {
+			clock = strdup(TSC_CLOCK);
+			if (!clock)
+				die("Cannot not allocate clock");
+			ctx->tsc2nsec.mult = mult;
+			ctx->tsc2nsec.shift = shift;
+			ctx->tsc2nsec.offset = get_clock_now(TSC_CLOCK);
+			force_tsc = true;
+		} else {
+		/*
+		 * Else, use the current clock of the first host instance
+		 */
+			for_all_instances(instance) {
+				if (is_guest(instance))
+					continue;
+				clock = tracefs_get_clock(instance->tracefs);
+				break;
+			}
+		}
+	} else {
+		clock = strdup(ctx->clock);
+		if (!clock)
+			die("Cannot not allocate clock");
 	}
 
 	if (!clock && !ctx->tsync_loop_interval)
-		return;
+		goto out;
 	for_all_instances(instance) {
 		if (clock && !(instance->flags & BUFFER_FL_HAS_CLOCK)) {
 			/* use the same clock in all tracing peers */
@@ -6492,6 +6510,8 @@ static void set_tsync_params(struct common_record_context *ctx)
 		}
 		instance->tsync_loop_interval = ctx->tsync_loop_interval;
 	}
+out:
+	free(clock);
 }
 
 /*
-- 
2.30.2

Re: [PATCH v2 18/18] trace-cmd: Get current clock for host-guest tracing session

[Steven Rostedt]

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

> In host-guest tracing session, all peers should use the same tracing
> clock. If there is no user configured trace clock, the current logic
> assumes "local" clock for the session. This could be wrong, as other
> clock than "local" could be already configured on the host, before
> running trace-cmd. The default clock for host-guest tracing session
> should be rertieved from the host's "trace_clock" file.

I need more time to review the last two patches, but feel free to send
a new version of this patch series before I do so.

Thanks!

-- Steve