RFC [PATCH 0/5] tsc2nsec fixes

RFC [PATCH 0/5] tsc2nsec fixes

[Tzvetomir Stoyanov (VMware)]

Removed the not so stable logic for tsc2nsec offset and replaced it with
trace-cmd library APIs which can be used from the library users to achieve
the same functionality.
These changes ignore the offset, part of the tsc2nsec data written in the
trace file metadata. Is it save to completely remove the offset field and to
break the format of this trace file option?

This is a RFC patchset, additional updates are required in case the changes
are approved:
 - Update trace-cmd documentation.
 - Remove offset field from tsc2nsec structures.

Tzvetomir Stoyanov (VMware) (5):
  trace-cmd: Remove ts offset from tsc2nsec conversion
  trace-cmd library: Remove useless check before applying ts offset
  trace-cmd library: Store the timestamp of the first event when reading
    a trace file
  trace-cmd library: New API for modifyning the timestamp offset
  trace-cmd report: New option --align-ts

 include/trace-cmd/trace-cmd.h |  2 ++
 lib/trace-cmd/trace-input.c   | 39 ++++++++++++++++++++--
 tracecmd/trace-read.c         | 25 ++++++++++++--
 tracecmd/trace-record.c       | 62 -----------------------------------
 tracecmd/trace-usage.c        |  1 +
 5 files changed, 61 insertions(+), 68 deletions(-)

-- 
2.30.2

[PATCH 1/5] trace-cmd: Remove ts offset from tsc2nsec conversion

[Tzvetomir Stoyanov (VMware)]

Do not get, store and use offset when converting TSC to nanoseconds.
The logic for automatically detecting the TSC offset is not stable enough
and could introduce errors, which leads to problems when reading trace
files in some use cases. The offset is not mandatory for tsc2nsec
conversion.

Signed-off-by: Tzvetomir Stoyanov (VMware) <tz.stoyanov@gmail.com>
---
 lib/trace-cmd/trace-input.c |  1 -
 tracecmd/trace-record.c     | 62 -------------------------------------
 2 files changed, 63 deletions(-)

diff --git a/lib/trace-cmd/trace-input.c b/lib/trace-cmd/trace-input.c
index a00fa982..e8a257db 100644
--- a/lib/trace-cmd/trace-input.c
+++ b/lib/trace-cmd/trace-input.c
@@ -1319,7 +1319,6 @@ static unsigned long long timestamp_calc(unsigned long long ts, int cpu,
 		ts *= handle->ts2secs;
 	} else if (handle->tsc_calc.mult) {
 		/* auto calculated TSC clock frequency */
-		ts -= handle->tsc_calc.offset;
 		ts = mul_u64_u32_shr(ts, handle->tsc_calc.mult, handle->tsc_calc.shift);
 	}
 
diff --git a/tracecmd/trace-record.c b/tracecmd/trace-record.c
index fd03a605..d732b394 100644
--- a/tracecmd/trace-record.c
+++ b/tracecmd/trace-record.c
@@ -6483,65 +6483,6 @@ 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;
-	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);
-	close(tfd);
-
-out:
-	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)
-			continue;
-
-		ctx->tsc2nsec.offset = get_clock_now(instance->clock);
-		return;
-	}
-
-	ctx->tsc2nsec.offset = get_clock_now(NULL);
-}
-
 static void set_tsync_params(struct common_record_context *ctx)
 {
 	struct buffer_instance *instance;
@@ -6566,7 +6507,6 @@ static void set_tsync_params(struct common_record_context *ctx)
 				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 { /* Use the current clock of the first host instance */
 			clock = get_trace_clock(true);
@@ -6661,8 +6601,6 @@ 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 &&
-- 
2.30.2

[PATCH 2/5] trace-cmd library: Remove useless check before applying ts offset

[Tzvetomir Stoyanov (VMware)]

Checking if offset is non-zero before adding to the timestamp is useless,
as adding 0 will not change the timestamp.

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

diff --git a/lib/trace-cmd/trace-input.c b/lib/trace-cmd/trace-input.c
index e8a257db..bacf9ccf 100644
--- a/lib/trace-cmd/trace-input.c
+++ b/lib/trace-cmd/trace-input.c
@@ -1323,8 +1323,7 @@ static unsigned long long timestamp_calc(unsigned long long ts, int cpu,
 	}
 
 	/* User specified time offset with --ts-offset or --date options */
-	if (handle->ts_offset)
-		ts += handle->ts_offset;
+	ts += handle->ts_offset;
 
 	return ts;
 }
-- 
2.30.2

[PATCH 3/5] trace-cmd library: Store the timestamp of the first event when reading a trace file

[Tzvetomir Stoyanov (VMware)]

When reading a trace file, detect and store the timestamp of the first
recorded event. A new API is introduced to get the first ts from an input
handler:
 tracecmd_get_first_ts()
The first ts can be used by the library users to align timestamps of the
events, when displaying them.

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

diff --git a/include/trace-cmd/trace-cmd.h b/include/trace-cmd/trace-cmd.h
index 162cd318..022720b0 100644
--- a/include/trace-cmd/trace-cmd.h
+++ b/include/trace-cmd/trace-cmd.h
@@ -37,6 +37,7 @@ int tracecmd_get_guest_cpumap(struct tracecmd_input *handle,
 			      unsigned long long trace_id,
 			      const char **name,
 			      int *vcpu_count, const int **cpu_pid);
+unsigned long long tracecmd_get_first_ts(struct tracecmd_input *handle);
 int tracecmd_buffer_instances(struct tracecmd_input *handle);
 const char *tracecmd_buffer_instance_name(struct tracecmd_input *handle, int indx);
 struct tracecmd_input *tracecmd_buffer_instance_handle(struct tracecmd_input *handle, int indx);
diff --git a/lib/trace-cmd/trace-input.c b/lib/trace-cmd/trace-input.c
index bacf9ccf..284f25e8 100644
--- a/lib/trace-cmd/trace-input.c
+++ b/lib/trace-cmd/trace-input.c
@@ -61,6 +61,7 @@ struct cpu_data {
 	unsigned long long	offset;
 	unsigned long long	size;
 	unsigned long long	timestamp;
+	unsigned long long	first_ts;
 	struct list_head	page_maps;
 	struct page_map		*page_map;
 	struct page		**pages;
@@ -2273,6 +2274,7 @@ static int init_cpu(struct tracecmd_input *handle, int cpu)
 
 	if (update_page_info(handle, cpu))
 		goto fail;
+	cpu_data->first_ts = cpu_data->timestamp;
 
 	return 0;
  fail:
@@ -4072,6 +4074,27 @@ unsigned long long tracecmd_get_traceid(struct tracecmd_input *handle)
 	return handle->trace_id;
 }
 
+/**
+ * tracecmd_get_first_ts - get the timestamp of the first recorded event
+ * @handle: input handle for the trace.dat file
+ *
+ * Returns the timestamp of the first recorded event
+ */
+unsigned long long tracecmd_get_first_ts(struct tracecmd_input *handle)
+{
+	unsigned long long ts = 0;
+	bool first = true;
+	int i;
+
+	for (i = 0; i < handle->cpus; i++) {
+		if (first || ts > handle->cpu_data[i].first_ts)
+			ts = handle->cpu_data[i].first_ts;
+		first = false;
+	}
+
+	return ts;
+}
+
 /**
  * tracecmd_get_guest_cpumap - get the mapping of guest VCPU to host process
  * @handle: input handle for the trace.dat file
-- 
2.30.2

[PATCH 4/5] trace-cmd library: New API for modifyning the timestamp offset

[Tzvetomir Stoyanov (VMware)]

New API is introduced, it can be used to add value to the offset
which will be applied to the timestamps of all events from given
trace file:
 tracecmd_add_ts_offset()

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

diff --git a/include/trace-cmd/trace-cmd.h b/include/trace-cmd/trace-cmd.h
index 022720b0..7305487c 100644
--- a/include/trace-cmd/trace-cmd.h
+++ b/include/trace-cmd/trace-cmd.h
@@ -38,6 +38,7 @@ int tracecmd_get_guest_cpumap(struct tracecmd_input *handle,
 			      const char **name,
 			      int *vcpu_count, const int **cpu_pid);
 unsigned long long tracecmd_get_first_ts(struct tracecmd_input *handle);
+void tracecmd_add_ts_offset(struct tracecmd_input *handle, long long offset);
 int tracecmd_buffer_instances(struct tracecmd_input *handle);
 const char *tracecmd_buffer_instance_name(struct tracecmd_input *handle, int indx);
 struct tracecmd_input *tracecmd_buffer_instance_handle(struct tracecmd_input *handle, int indx);
diff --git a/lib/trace-cmd/trace-input.c b/lib/trace-cmd/trace-input.c
index 284f25e8..6adc8bfa 100644
--- a/lib/trace-cmd/trace-input.c
+++ b/lib/trace-cmd/trace-input.c
@@ -2291,6 +2291,18 @@ void tracecmd_set_ts_offset(struct tracecmd_input *handle,
 	handle->ts_offset = offset;
 }
 
+/**
+ * tracecmd_add_ts_offset - Add value to the offset which will be applied to the timestamps of all
+ *			    events from given trace file
+ * @handle: input handle to the trace.dat file
+ * @offset: value, that will be added to the offset
+ */
+void tracecmd_add_ts_offset(struct tracecmd_input *handle,
+			    long long offset)
+{
+	handle->ts_offset += offset;
+}
+
 void tracecmd_set_ts2secs(struct tracecmd_input *handle,
 			 unsigned long long hz)
 {
-- 
2.30.2

[PATCH 5/5] trace-cmd report: New option --align-ts

[Tzvetomir Stoyanov (VMware)]

A new option is added:
 trace-cmd report --align-ts
It shows timestamps aligned to the first recorded event.

Signed-off-by: Tzvetomir Stoyanov (VMware) <tz.stoyanov@gmail.com>
---
 tracecmd/trace-read.c  | 25 ++++++++++++++++++++++---
 tracecmd/trace-usage.c |  1 +
 2 files changed, 23 insertions(+), 3 deletions(-)

diff --git a/tracecmd/trace-read.c b/tracecmd/trace-read.c
index d962b671..4a7bdb9c 100644
--- a/tracecmd/trace-read.c
+++ b/tracecmd/trace-read.c
@@ -1192,14 +1192,16 @@ enum output_type {
 };
 
 static void read_data_info(struct list_head *handle_list, enum output_type otype,
-			   int global)
+			   int global, int align_ts)
 {
+	unsigned long long ts, first_ts;
 	struct handle_list *handles;
 	struct handle_list *last_handle;
 	struct tep_record *record;
 	struct tep_record *last_record;
 	struct tep_handle *pevent;
 	struct tep_event *event;
+	int first = 1;
 	int ret;
 
 	list_for_each_entry(handles, handle_list, list) {
@@ -1218,7 +1220,12 @@ static void read_data_info(struct list_head *handle_list, enum output_type otype
 		ret = tracecmd_init_data(handles->handle);
 		if (ret < 0)
 			die("failed to init data");
-
+		if (align_ts) {
+			ts = tracecmd_get_first_ts(handles->handle);
+			if (first || first_ts > ts)
+				first_ts = ts;
+			first = 0;
+		}
 		print_handle_file(handles);
 		printf("cpus=%d\n", cpus);
 
@@ -1286,6 +1293,12 @@ static void read_data_info(struct list_head *handle_list, enum output_type otype
 	if (otype != OUTPUT_NORMAL)
 		return;
 
+	if (align_ts) {
+		list_for_each_entry(handles, handle_list, list) {
+			tracecmd_add_ts_offset(handles->handle, -first_ts);
+		}
+	}
+
 	do {
 		last_handle = NULL;
 		last_record = NULL;
@@ -1485,6 +1498,7 @@ static void add_hook(const char *arg)
 }
 
 enum {
+	OPT_align_ts	= 235,
 	OPT_raw_ts	= 236,
 	OPT_version	= 237,
 	OPT_tscheck	= 238,
@@ -1536,6 +1550,7 @@ void trace_report (int argc, char **argv)
 	int nanosec = 0;
 	int no_date = 0;
 	int raw_ts = 0;
+	int align_ts = 0;
 	int global = 0;
 	int neg = 0;
 	int ret = 0;
@@ -1578,6 +1593,7 @@ void trace_report (int argc, char **argv)
 			{"ts-diff", no_argument, NULL, OPT_tsdiff},
 			{"ts-check", no_argument, NULL, OPT_tscheck},
 			{"raw-ts", no_argument, NULL, OPT_raw_ts},
+			{"align-ts", no_argument, NULL, OPT_align_ts},
 			{"help", no_argument, NULL, '?'},
 			{NULL, 0, NULL, 0}
 		};
@@ -1753,6 +1769,9 @@ void trace_report (int argc, char **argv)
 		case OPT_raw_ts:
 			raw_ts = 1;
 			break;
+		case OPT_align_ts:
+			align_ts = 1;
+			break;
 		default:
 			usage(argv);
 		}
@@ -1883,7 +1902,7 @@ void trace_report (int argc, char **argv)
 	/* and version overrides uname! */
 	if (show_version)
 		otype = OUTPUT_VERSION_ONLY;
-	read_data_info(&handle_list, otype, global);
+	read_data_info(&handle_list, otype, global, align_ts);
 
 	list_for_each_entry(handles, &handle_list, list) {
 		tracecmd_close(handles->handle);
diff --git a/tracecmd/trace-usage.c b/tracecmd/trace-usage.c
index 98247074..97b3aec0 100644
--- a/tracecmd/trace-usage.c
+++ b/tracecmd/trace-usage.c
@@ -234,6 +234,7 @@ static struct usage_help usage_help[] = {
 		"          --ts-diff Show the delta timestamp between events.\n"
 		"          --ts-check Check to make sure no time stamp on any CPU goes backwards.\n"
 		"          --raw-ts Display raw timestamps, without any corrections.\n"
+		"          --align-ts Display timestamps aligned to the first event.\n"
 	},
 	{
 		"stream",
-- 
2.30.2