Linux-Trace-Devel Archive on lore.kernel.org
 help / Atom feed
* [PATCH v3 0/7][POC] trace-cmd: Timetamps sync using PTP-like algorithm, relying on vsock events.
@ 2019-02-08 13:49 Tzvetomir Stoyanov
  2019-02-08 13:49 ` [PATCH v3 1/7] trace-cmd: Implemented new lib API: tracecmd_local_events_system() Tzvetomir Stoyanov
                   ` (6 more replies)
  0 siblings, 7 replies; 13+ messages in thread
From: Tzvetomir Stoyanov @ 2019-02-08 13:49 UTC (permalink / raw)
  To: rostedt; +Cc: linux-trace-devel

[ V3 changes: 
 - Removed any magic constants, used in the PTP-like algorithm, 
   as Slavomir Kaslev suggested.
 - Implemented new algorithm, based on mapping kvm_exit events 
   in host context to vsock_send events in guest context, 
   suggested by Steven Rostedt. 
]

This patch series is a POC for timestamps sync between guest and host machines.
It implelents two algorithms: 
    - PTP-like algorithm, using vsock events for getting the current time.
    - algorithm based on mapping kvm_exit events in host context to vsock_send 
      events in guest context.
Both algorithms run simultaneously, so the results can be easily compared.
The "#if" directive at the end of tracecmd_msg_snd_time_sync() can be used 
to swith between the results of the both algorithms - which one of them to be 
written in the trace file.

The patch series depends on Slavomir's changes, introduced by the patch series
"Add VM kernel tracing over vsockets and FIFOs"


Tzvetomir Stoyanov (7):
  trace-cmd: Implemented new lib API: tracecmd_local_events_system()
  trace-cmd: Added support for negative time offsets in trace.dat file
  trace-cmd: Fixed logic in tracecmd_read_page_record()
  trace-cmd: Added implementation of htonll() and ntohll()
  trace-cmd: Refactored make_instances() and tracecmd_remove_instances()
  trace-cmd: Find and store pids of tasks, which run virtual CPUs of
    given VM
  trace-cmd [POC]: Implemented timestamps synch PTP-like algorithm,
    using vsock events.

 include/trace-cmd/trace-cmd.h  |   8 +-
 lib/trace-cmd/trace-input.c    |  18 +-
 lib/trace-cmd/trace-util.c     |  99 ++++--
 tracecmd/include/trace-local.h |   9 +
 tracecmd/include/trace-msg.h   |  10 +
 tracecmd/trace-listen.c        |   3 +
 tracecmd/trace-msg.c           | 543 ++++++++++++++++++++++++++++++++-
 tracecmd/trace-read.c          |   4 +-
 tracecmd/trace-record.c        | 465 ++++++++++++++++++++++------
 9 files changed, 1020 insertions(+), 139 deletions(-)

-- 
2.20.1


^ permalink raw reply	[flat|nested] 13+ messages in thread

* [PATCH v3 1/7] trace-cmd: Implemented new lib API: tracecmd_local_events_system()
  2019-02-08 13:49 [PATCH v3 0/7][POC] trace-cmd: Timetamps sync using PTP-like algorithm, relying on vsock events Tzvetomir Stoyanov
@ 2019-02-08 13:49 ` Tzvetomir Stoyanov
  2019-02-08 13:49 ` [PATCH v3 2/7] trace-cmd: Added support for negative time offsets in trace.dat file Tzvetomir Stoyanov
                   ` (5 subsequent siblings)
  6 siblings, 0 replies; 13+ messages in thread
From: Tzvetomir Stoyanov @ 2019-02-08 13:49 UTC (permalink / raw)
  To: rostedt; +Cc: linux-trace-devel

The new tracecmd lib API tracecmd_local_events_system() creates
a tep handler and initializes it with the events of the
specified subsystems.

Signed-off-by: Tzvetomir Stoyanov <tstoyanov@vmware.com>
---
 include/trace-cmd/trace-cmd.h |  2 +
 lib/trace-cmd/trace-util.c    | 99 +++++++++++++++++++++++------------
 2 files changed, 68 insertions(+), 33 deletions(-)

diff --git a/include/trace-cmd/trace-cmd.h b/include/trace-cmd/trace-cmd.h
index 84dc95a..3d72430 100644
--- a/include/trace-cmd/trace-cmd.h
+++ b/include/trace-cmd/trace-cmd.h
@@ -32,6 +32,8 @@ void tracecmd_unload_plugins(struct tep_plugin_list *list, struct tep_handle *pe
 char **tracecmd_event_systems(const char *tracing_dir);
 char **tracecmd_system_events(const char *tracing_dir, const char *system);
 struct tep_handle *tracecmd_local_events(const char *tracing_dir);
+struct tep_handle *tracecmd_local_events_system(const char *tracing_dir,
+						char **sys_names);
 int tracecmd_fill_local_events(const char *tracing_dir, struct tep_handle *pevent);
 char **tracecmd_local_plugins(const char *tracing_dir);
 
diff --git a/lib/trace-cmd/trace-util.c b/lib/trace-cmd/trace-util.c
index b5aea39..0e925ed 100644
--- a/lib/trace-cmd/trace-util.c
+++ b/lib/trace-cmd/trace-util.c
@@ -1119,43 +1119,15 @@ static int read_header(struct tep_handle *pevent, const char *events_dir)
 	return ret;
 }
 
-/**
- * tracecmd_local_events - create a pevent from the events on system
- * @tracing_dir: The directory that contains the events.
- *
- * Returns a pevent structure that contains the pevents local to
- * the system.
- */
-struct tep_handle *tracecmd_local_events(const char *tracing_dir)
-{
-	struct tep_handle *pevent = NULL;
-
-	pevent = tep_alloc();
-	if (!pevent)
-		return NULL;
-
-	if (tracecmd_fill_local_events(tracing_dir, pevent)) {
-		tep_free(pevent);
-		pevent = NULL;
-	}
-
-	return pevent;
-}
-
-/**
- * tracecmd_fill_local_events - Fill a pevent with the events on system
- * @tracing_dir: The directory that contains the events.
- * @pevent: Allocated pevent which will be filled
- *
- * Returns whether the operation succeeded
- */
-int tracecmd_fill_local_events(const char *tracing_dir, struct tep_handle *pevent)
+static int tracecmd_fill_local_events_system(const char *tracing_dir,
+					     struct tep_handle *pevent,
+					     char **sys_names)
 {
+	int ret, i, failure = 0;
 	struct dirent *dent;
 	char *events_dir;
 	struct stat st;
 	DIR *dir;
-	int ret, failure = 0;
 
 	if (!tracing_dir)
 		return -1;
@@ -1189,7 +1161,16 @@ int tracecmd_fill_local_events(const char *tracing_dir, struct tep_handle *peven
 		if (strcmp(name, ".") == 0 ||
 		    strcmp(name, "..") == 0)
 			continue;
-
+		if (sys_names) {
+			i = 0;
+			while (sys_names[i]) {
+				if (strcmp(name, sys_names[i]) == 0)
+					break;
+				i++;
+			}
+			if (sys_names[i] == NULL)
+				continue;
+		}
 		sys = append_file(events_dir, name);
 		ret = stat(sys, &st);
 		if (ret < 0 || !S_ISDIR(st.st_mode)) {
@@ -1217,6 +1198,58 @@ int tracecmd_fill_local_events(const char *tracing_dir, struct tep_handle *peven
 	return ret;
 }
 
+/**
+ * tracecmd_local_events_system - create a tep from the events of the specified subsystem.
+ *
+ * @tracing_dir: The directory that contains the events.
+ * @sys_name: Array of system names, to load the events from.
+ * The last element from the array must be NULL
+ *
+ * Returns a tep structure that contains the tep local to
+ * the system.
+ */
+struct tep_handle *tracecmd_local_events_system(const char *tracing_dir,
+						char **sys_names)
+{
+	struct tep_handle *tep = NULL;
+
+	tep = tep_alloc();
+	if (!tep)
+		return NULL;
+
+	if (tracecmd_fill_local_events_system(tracing_dir, tep, sys_names)) {
+		tep_free(tep);
+		tep = NULL;
+	}
+
+	return tep;
+}
+
+/**
+ * tracecmd_local_events - create a pevent from the events on system
+ * @tracing_dir: The directory that contains the events.
+ *
+ * Returns a pevent structure that contains the pevents local to
+ * the system.
+ */
+struct tep_handle *tracecmd_local_events(const char *tracing_dir)
+{
+	return tracecmd_local_events_system(tracing_dir, NULL);
+}
+
+/**
+ * tracecmd_fill_local_events - Fill a pevent with the events on system
+ * @tracing_dir: The directory that contains the events.
+ * @pevent: Allocated pevent which will be filled
+ *
+ * Returns whether the operation succeeded
+ */
+int tracecmd_fill_local_events(const char *tracing_dir,
+			       struct tep_handle *pevent)
+{
+	return tracecmd_fill_local_events_system(tracing_dir, pevent, NULL);
+}
+
 /**
  * tracecmd_local_plugins - returns an array of available tracer plugins
  * @tracing_dir: The directory that contains the tracing directory
-- 
2.20.1


^ permalink raw reply	[flat|nested] 13+ messages in thread

* [PATCH v3 2/7] trace-cmd: Added support for negative time offsets in trace.dat file
  2019-02-08 13:49 [PATCH v3 0/7][POC] trace-cmd: Timetamps sync using PTP-like algorithm, relying on vsock events Tzvetomir Stoyanov
  2019-02-08 13:49 ` [PATCH v3 1/7] trace-cmd: Implemented new lib API: tracecmd_local_events_system() Tzvetomir Stoyanov
@ 2019-02-08 13:49 ` Tzvetomir Stoyanov
  2019-02-08 21:39   ` Steven Rostedt
  2019-02-08 13:49 ` [PATCH v3 3/7] trace-cmd: Fixed logic in tracecmd_read_page_record() Tzvetomir Stoyanov
                   ` (4 subsequent siblings)
  6 siblings, 1 reply; 13+ messages in thread
From: Tzvetomir Stoyanov @ 2019-02-08 13:49 UTC (permalink / raw)
  To: rostedt; +Cc: linux-trace-devel

When synchronizing timestamps between different machines, there are cases
when the time offset is negative. This patch changes the way time offset is
written and read from trace.dat file - as signed decimal, instead of hex.

Signed-off-by: Tzvetomir Stoyanov <tstoyanov@vmware.com>
---
 include/trace-cmd/trace-cmd.h |   2 +-
 lib/trace-cmd/trace-input.c   |   6 +-
 tracecmd/trace-read.c         |   4 +-
 tracecmd/trace-record.c       | 120 +++++++++++++++++-----------------
 4 files changed, 66 insertions(+), 66 deletions(-)

diff --git a/include/trace-cmd/trace-cmd.h b/include/trace-cmd/trace-cmd.h
index 3d72430..b2ff6f9 100644
--- a/include/trace-cmd/trace-cmd.h
+++ b/include/trace-cmd/trace-cmd.h
@@ -126,7 +126,7 @@ int tracecmd_is_buffer_instance(struct tracecmd_input *handle);
 void tracecmd_create_top_instance(char *name);
 void tracecmd_remove_instances(void);
 
-void tracecmd_set_ts_offset(struct tracecmd_input *handle, unsigned long long offset);
+void tracecmd_set_ts_offset(struct tracecmd_input *handle, long long offset);
 void tracecmd_set_ts2secs(struct tracecmd_input *handle, unsigned long long hz);
 
 void tracecmd_print_events(struct tracecmd_input *handle, const char *regex);
diff --git a/lib/trace-cmd/trace-input.c b/lib/trace-cmd/trace-input.c
index b628570..33ad7d1 100644
--- a/lib/trace-cmd/trace-input.c
+++ b/lib/trace-cmd/trace-input.c
@@ -100,7 +100,7 @@ struct tracecmd_input {
 	bool			read_page;
 	bool			use_pipe;
 	struct cpu_data 	*cpu_data;
-	unsigned long long	ts_offset;
+	long long		ts_offset;
 	double			ts2secs;
 	char *			cpustats;
 	char *			uname;
@@ -2091,7 +2091,7 @@ static int init_cpu(struct tracecmd_input *handle, int cpu)
 }
 
 void tracecmd_set_ts_offset(struct tracecmd_input *handle,
-			    unsigned long long offset)
+			    long long offset)
 {
 	handle->ts_offset = offset;
 }
@@ -2108,7 +2108,7 @@ void tracecmd_set_ts2secs(struct tracecmd_input *handle,
 
 static int handle_options(struct tracecmd_input *handle)
 {
-	unsigned long long offset;
+	long long offset;
 	unsigned short option;
 	unsigned int size;
 	char *cpustats = NULL;
diff --git a/tracecmd/trace-read.c b/tracecmd/trace-read.c
index 804022a..e309672 100644
--- a/tracecmd/trace-read.c
+++ b/tracecmd/trace-read.c
@@ -58,7 +58,7 @@ static struct list_head handle_list;
 struct input_files {
 	struct list_head	list;
 	const char		*file;
-	unsigned long long	tsoffset;
+	long long		tsoffset;
 	unsigned long long	ts2secs;
 };
 static struct list_head input_files;
@@ -1413,7 +1413,7 @@ void trace_report (int argc, char **argv)
 	struct input_files *inputs;
 	struct handle_list *handles;
 	enum output_type otype;
-	unsigned long long tsoffset = 0;
+	long long tsoffset = 0;
 	unsigned long long ts2secs = 0;
 	unsigned long long ts2sc;
 	int show_stat = 0;
diff --git a/tracecmd/trace-record.c b/tracecmd/trace-record.c
index 43d782e..01b360a 100644
--- a/tracecmd/trace-record.c
+++ b/tracecmd/trace-record.c
@@ -203,6 +203,12 @@ enum trace_cmd {
 	CMD_record_agent,
 };
 
+enum {
+	DATA_FL_NONE		= 0,
+	DATA_FL_DATE		= 1,
+	DATA_FL_OFFSET		= 2,
+};
+
 struct common_record_context {
 	enum trace_cmd curr_cmd;
 	struct buffer_instance *instance;
@@ -3234,7 +3240,60 @@ again:
 	return msg_handle;
 }
 
-static void add_options(struct tracecmd_output *handle, struct common_record_context *ctx);
+static void add_option_hooks(struct tracecmd_output *handle)
+{
+	struct hook_list *hook;
+	int len;
+
+	for (hook = hooks; hook; hook = hook->next) {
+		len = strlen(hook->hook);
+		tracecmd_add_option(handle, TRACECMD_OPTION_HOOK,
+				    len + 1, hook->hook);
+	}
+}
+
+static void add_uname(struct tracecmd_output *handle)
+{
+	struct utsname buf;
+	char *str;
+	int len;
+	int ret;
+
+	ret = uname(&buf);
+	/* if this fails for some reason, just ignore it */
+	if (ret < 0)
+		return;
+
+	len = strlen(buf.sysname) + strlen(buf.nodename) +
+		strlen(buf.release) + strlen(buf.machine) + 4;
+	str = malloc(len);
+	if (!str)
+		return;
+	sprintf(str, "%s %s %s %s", buf.sysname, buf.nodename, buf.release, buf.machine);
+	tracecmd_add_option(handle, TRACECMD_OPTION_UNAME, len, str);
+	free(str);
+}
+
+static void add_options(struct tracecmd_output *handle,
+			struct common_record_context *ctx)
+{
+	int type = 0;
+
+	if (ctx->date2ts) {
+		if (ctx->data_flags & DATA_FL_DATE)
+			type = TRACECMD_OPTION_DATE;
+		else if (ctx->data_flags & DATA_FL_OFFSET)
+			type = TRACECMD_OPTION_OFFSET;
+	}
+
+	if (type)
+		tracecmd_add_option(handle, type,
+				    strlen(ctx->date2ts)+1, ctx->date2ts);
+
+	tracecmd_add_option(handle, TRACECMD_OPTION_TRACECLOCK, 0, NULL);
+	add_option_hooks(handle);
+	add_uname(handle);
+}
 
 static struct tracecmd_msg_handle *
 setup_connection(struct buffer_instance *instance, struct common_record_context *ctx)
@@ -3505,40 +3564,6 @@ add_buffer_stat(struct tracecmd_output *handle, struct buffer_instance *instance
 				    instance->s_save[i].buffer);
 }
 
-static void add_option_hooks(struct tracecmd_output *handle)
-{
-	struct hook_list *hook;
-	int len;
-
-	for (hook = hooks; hook; hook = hook->next) {
-		len = strlen(hook->hook);
-		tracecmd_add_option(handle, TRACECMD_OPTION_HOOK,
-				    len + 1, hook->hook);
-	}
-}
-
-static void add_uname(struct tracecmd_output *handle)
-{
-	struct utsname buf;
-	char *str;
-	int len;
-	int ret;
-
-	ret = uname(&buf);
-	/* if this fails for some reason, just ignore it */
-	if (ret < 0)
-		return;
-
-	len = strlen(buf.sysname) + strlen(buf.nodename) +
-		strlen(buf.release) + strlen(buf.machine) + 4;
-	str = malloc(len);
-	if (!str)
-		return;
-	sprintf(str, "%s %s %s %s", buf.sysname, buf.nodename, buf.release, buf.machine);
-	tracecmd_add_option(handle, TRACECMD_OPTION_UNAME, len, str);
-	free(str);
-}
-
 static void print_stat(struct buffer_instance *instance)
 {
 	int cpu;
@@ -3553,31 +3578,6 @@ static void print_stat(struct buffer_instance *instance)
 		trace_seq_do_printf(&instance->s_print[cpu]);
 }
 
-enum {
-	DATA_FL_NONE		= 0,
-	DATA_FL_DATE		= 1,
-	DATA_FL_OFFSET		= 2,
-};
-
-static void add_options(struct tracecmd_output *handle, struct common_record_context *ctx)
-{
-	int type = 0;
-
-	if (ctx->date2ts) {
-		if (ctx->data_flags & DATA_FL_DATE)
-			type = TRACECMD_OPTION_DATE;
-		else if (ctx->data_flags & DATA_FL_OFFSET)
-			type = TRACECMD_OPTION_OFFSET;
-	}
-
-	if (type)
-		tracecmd_add_option(handle, type, strlen(ctx->date2ts)+1, ctx->date2ts);
-
-	tracecmd_add_option(handle, TRACECMD_OPTION_TRACECLOCK, 0, NULL);
-	add_option_hooks(handle);
-	add_uname(handle);
-}
-
 static void write_guest_file(struct buffer_instance *instance)
 {
 	struct tracecmd_output *handle;
-- 
2.20.1


^ permalink raw reply	[flat|nested] 13+ messages in thread

* [PATCH v3 3/7] trace-cmd: Fixed logic in tracecmd_read_page_record()
  2019-02-08 13:49 [PATCH v3 0/7][POC] trace-cmd: Timetamps sync using PTP-like algorithm, relying on vsock events Tzvetomir Stoyanov
  2019-02-08 13:49 ` [PATCH v3 1/7] trace-cmd: Implemented new lib API: tracecmd_local_events_system() Tzvetomir Stoyanov
  2019-02-08 13:49 ` [PATCH v3 2/7] trace-cmd: Added support for negative time offsets in trace.dat file Tzvetomir Stoyanov
@ 2019-02-08 13:49 ` Tzvetomir Stoyanov
  2019-02-08 22:08   ` Steven Rostedt
  2019-02-08 13:49 ` [PATCH v3 4/7] trace-cmd: Added implementation of htonll() and ntohll() Tzvetomir Stoyanov
                   ` (3 subsequent siblings)
  6 siblings, 1 reply; 13+ messages in thread
From: Tzvetomir Stoyanov @ 2019-02-08 13:49 UTC (permalink / raw)
  To: rostedt; +Cc: linux-trace-devel

Fixed the logic in tracecmd_read_page_record() when
searching for the next event in the event from the
ring buffer. In the current logic, in the case when
last_record is not NULL (we are searching for the second one)
the check "if (ptr != last_record->data)" always fails.

Signed-off-by: Tzvetomir Stoyanov <tstoyanov@vmware.com>
---
 lib/trace-cmd/trace-input.c | 12 ++++++++----
 1 file changed, 8 insertions(+), 4 deletions(-)

diff --git a/lib/trace-cmd/trace-input.c b/lib/trace-cmd/trace-input.c
index 33ad7d1..5d64ca8 100644
--- a/lib/trace-cmd/trace-input.c
+++ b/lib/trace-cmd/trace-input.c
@@ -1688,18 +1688,22 @@ tracecmd_read_page_record(struct tep_handle *pevent, void *page, int size,
 			goto out_free;
 		}
 
-		do {
+		ptr = kbuffer_read_event(kbuf, &ts);
+		while (ptr < last_record->data) {
 			ptr = kbuffer_next_event(kbuf, NULL);
 			if (!ptr)
 				break;
-		} while (ptr < last_record->data);
+			if (ptr == last_record->data)
+				break;
+		}
 		if (ptr != last_record->data) {
 			warning("tracecmd_read_page_record: could not find last_record");
 			goto out_free;
 		}
-	}
+		ptr = kbuffer_next_event(kbuf, &ts);
+	} else
+		ptr = kbuffer_read_event(kbuf, &ts);
 
-	ptr = kbuffer_read_event(kbuf, &ts);
 	if (!ptr)
 		goto out_free;
 
-- 
2.20.1


^ permalink raw reply	[flat|nested] 13+ messages in thread

* [PATCH v3 4/7] trace-cmd: Added implementation of htonll() and ntohll()
  2019-02-08 13:49 [PATCH v3 0/7][POC] trace-cmd: Timetamps sync using PTP-like algorithm, relying on vsock events Tzvetomir Stoyanov
                   ` (2 preceding siblings ...)
  2019-02-08 13:49 ` [PATCH v3 3/7] trace-cmd: Fixed logic in tracecmd_read_page_record() Tzvetomir Stoyanov
@ 2019-02-08 13:49 ` Tzvetomir Stoyanov
  2019-02-08 13:49 ` [PATCH v3 5/7] trace-cmd: Refactored make_instances() and tracecmd_remove_instances() Tzvetomir Stoyanov
                   ` (2 subsequent siblings)
  6 siblings, 0 replies; 13+ messages in thread
From: Tzvetomir Stoyanov @ 2019-02-08 13:49 UTC (permalink / raw)
  To: rostedt; +Cc: linux-trace-devel

Added implementation of htonll() and ntohll() as
macros, if they are not already defined.

Signed-off-by: Tzvetomir Stoyanov <tstoyanov@vmware.com>
---
 tracecmd/include/trace-msg.h | 10 ++++++++++
 1 file changed, 10 insertions(+)

diff --git a/tracecmd/include/trace-msg.h b/tracecmd/include/trace-msg.h
index b7fe10b..445f799 100644
--- a/tracecmd/include/trace-msg.h
+++ b/tracecmd/include/trace-msg.h
@@ -15,4 +15,14 @@ extern unsigned int page_size;
 void plog(const char *fmt, ...);
 void pdie(const char *fmt, ...);
 
+#ifndef htonll
+# if __BYTE_ORDER == __LITTLE_ENDIAN
+#define htonll(x) __bswap_64(x)
+#define ntohll(x) __bswap_64(x)
+#else
+#define htonll(x) (x)
+#define ntohll(x) (x)
+#endif
+#endif
+
 #endif /* _TRACE_MSG_H_ */
-- 
2.20.1


^ permalink raw reply	[flat|nested] 13+ messages in thread

* [PATCH v3 5/7] trace-cmd: Refactored make_instances() and tracecmd_remove_instances()
  2019-02-08 13:49 [PATCH v3 0/7][POC] trace-cmd: Timetamps sync using PTP-like algorithm, relying on vsock events Tzvetomir Stoyanov
                   ` (3 preceding siblings ...)
  2019-02-08 13:49 ` [PATCH v3 4/7] trace-cmd: Added implementation of htonll() and ntohll() Tzvetomir Stoyanov
@ 2019-02-08 13:49 ` Tzvetomir Stoyanov
  2019-02-08 22:11   ` Steven Rostedt
  2019-02-08 22:44   ` Steven Rostedt
  2019-02-08 13:49 ` [PATCH v3 6/7] trace-cmd: Find and store pids of tasks, which run virtual CPUs of given VM Tzvetomir Stoyanov
  2019-02-08 13:49 ` [PATCH v3 7/7] trace-cmd [POC]: Implemented timestamps synch PTP-like algorithm, using vsock events Tzvetomir Stoyanov
  6 siblings, 2 replies; 13+ messages in thread
From: Tzvetomir Stoyanov @ 2019-02-08 13:49 UTC (permalink / raw)
  To: rostedt; +Cc: linux-trace-devel

In order to reuse the code which creates / deletes tracing instances,
these two functions are refactotred. A new ones are implemented:
make_one_instances() and tracecmd_remove_one_instance().

Signed-off-by: Tzvetomir Stoyanov <tstoyanov@vmware.com>
---
 tracecmd/trace-record.c | 54 +++++++++++++++++++++++------------------
 1 file changed, 31 insertions(+), 23 deletions(-)

diff --git a/tracecmd/trace-record.c b/tracecmd/trace-record.c
index 01b360a..e1ad797 100644
--- a/tracecmd/trace-record.c
+++ b/tracecmd/trace-record.c
@@ -4304,49 +4304,57 @@ static void clear_func_filters(void)
 	}
 }
 
-static void make_instances(void)
+static void make_one_instance(struct buffer_instance *instance)
 {
-	struct buffer_instance *instance;
 	struct stat st;
 	char *path;
 	int ret;
 
+	path = get_instance_dir(instance);
+	ret = stat(path, &st);
+	if (ret < 0) {
+		ret = mkdir(path, 0777);
+		if (ret < 0)
+			die("mkdir %s", path);
+	} else
+		/* Don't delete instances that already exist */
+		instance->flags |= BUFFER_FL_KEEP;
+	tracecmd_put_tracing_file(path);
+
+}
+
+static void make_instances(void)
+{
+	struct buffer_instance *instance;
+
 	for_each_instance(instance) {
 		if (instance->flags & BUFFER_FL_GUEST)
 			continue;
+		make_one_instance(instance);
+	}
+}
 
-		path = get_instance_dir(instance);
-		ret = stat(path, &st);
-		if (ret < 0) {
-			ret = mkdir(path, 0777);
-			if (ret < 0)
-				die("mkdir %s", path);
-		} else
-			/* Don't delete instances that already exist */
-			instance->flags |= BUFFER_FL_KEEP;
-		tracecmd_put_tracing_file(path);
+static void tracecmd_remove_one_instance(struct buffer_instance *instance)
+{
+	char *path;
+
+	if (instance->tracing_on_fd > 0) {
+		close(instance->tracing_on_fd);
+		instance->tracing_on_fd = 0;
 	}
+	path = get_instance_dir(instance);
+	tracecmd_put_tracing_file(path);
 }
 
 void tracecmd_remove_instances(void)
 {
 	struct buffer_instance *instance;
-	char *path;
-	int ret;
 
 	for_each_instance(instance) {
 		/* Only delete what we created */
 		if (instance->flags & (BUFFER_FL_KEEP | BUFFER_FL_GUEST))
 			continue;
-		if (instance->tracing_on_fd > 0) {
-			close(instance->tracing_on_fd);
-			instance->tracing_on_fd = 0;
-		}
-		path = get_instance_dir(instance);
-		ret = rmdir(path);
-		if (ret < 0)
-			die("rmdir %s", path);
-		tracecmd_put_tracing_file(path);
+		tracecmd_remove_one_instance(instance);
 	}
 }
 
-- 
2.20.1


^ permalink raw reply	[flat|nested] 13+ messages in thread

* [PATCH v3 6/7] trace-cmd: Find and store pids of tasks, which run virtual CPUs of given VM
  2019-02-08 13:49 [PATCH v3 0/7][POC] trace-cmd: Timetamps sync using PTP-like algorithm, relying on vsock events Tzvetomir Stoyanov
                   ` (4 preceding siblings ...)
  2019-02-08 13:49 ` [PATCH v3 5/7] trace-cmd: Refactored make_instances() and tracecmd_remove_instances() Tzvetomir Stoyanov
@ 2019-02-08 13:49 ` Tzvetomir Stoyanov
  2019-02-08 13:49 ` [PATCH v3 7/7] trace-cmd [POC]: Implemented timestamps synch PTP-like algorithm, using vsock events Tzvetomir Stoyanov
  6 siblings, 0 replies; 13+ messages in thread
From: Tzvetomir Stoyanov @ 2019-02-08 13:49 UTC (permalink / raw)
  To: rostedt; +Cc: linux-trace-devel

In order to match host and guest events, a mapping between guest VCPU
and the host task, running this VCPU is needed. Extended existing
struct guest to hold such mapping and added logic in read_qemu_guests()
function to initialize it. Implemented a new internal API,
get_guest_vcpu_pids(), to retrieve VCPU-task mapping for given VM.

Signed-off-by: Tzvetomir Stoyanov <tstoyanov@vmware.com>
---
 tracecmd/include/trace-local.h |  3 ++
 tracecmd/trace-record.c        | 57 +++++++++++++++++++++++++++++++++-
 2 files changed, 59 insertions(+), 1 deletion(-)

diff --git a/tracecmd/include/trace-local.h b/tracecmd/include/trace-local.h
index 8bf7c8e..4f6e239 100644
--- a/tracecmd/include/trace-local.h
+++ b/tracecmd/include/trace-local.h
@@ -233,6 +233,9 @@ void show_instance_file(struct buffer_instance *instance, const char *name);
 
 int count_cpus(void);
 
+#define VCPUS_MAX	256
+int *get_guest_vcpu_pids(int cid);
+
 /* No longer in event-utils.h */
 void __noreturn die(const char *fmt, ...); /* Can be overriden */
 void *malloc_or_die(unsigned int size); /* Can be overridden */
diff --git a/tracecmd/trace-record.c b/tracecmd/trace-record.c
index e1ad797..ab3f97e 100644
--- a/tracecmd/trace-record.c
+++ b/tracecmd/trace-record.c
@@ -2754,6 +2754,7 @@ struct guest {
 	char *name;
 	int cid;
 	int pid;
+	int cpu_pid[VCPUS_MAX];
 };
 
 static struct guest *guests;
@@ -2774,9 +2775,10 @@ static char *get_qemu_guest_name(char *arg)
 static void read_qemu_guests(void)
 {
 	static bool initialized;
+	struct dirent *entry_t;
 	struct dirent *entry;
 	char path[PATH_MAX];
-	DIR *dir;
+	DIR *dir, *dir_t;
 
 	if (initialized)
 		return;
@@ -2832,6 +2834,49 @@ static void read_qemu_guests(void)
 		if (!is_qemu)
 			goto next;
 
+		snprintf(path, sizeof(path), "/proc/%s/task", entry->d_name);
+		dir_t = opendir(path);
+		if (dir_t) {
+			unsigned int vcpu;
+			char *buf = NULL;
+			char *cpu_str;
+			FILE *ft;
+			size_t n;
+			int j;
+
+			for (entry_t = readdir(dir_t); entry_t; entry_t = readdir(dir_t)) {
+				if (!(entry_t->d_type == DT_DIR &&
+				    is_digits(entry_t->d_name)))
+					continue;
+				snprintf(path, sizeof(path),
+					 "/proc/%s/task/%s/comm",
+					 entry->d_name, entry_t->d_name);
+				ft = fopen(path, "r");
+				if (!ft)
+					continue;
+				getline(&buf, &n, ft);
+				if (buf && strncmp(buf, "CPU ", 4) == 0) {
+					cpu_str = buf;
+					while (*cpu_str != '\0' &&
+						isdigit(*cpu_str) == 0)
+						cpu_str++;
+					if (*cpu_str != '\0') {
+						j = 0;
+						while (cpu_str[j] != '\0' &&
+						       isdigit(cpu_str[j]) != 0)
+							j++;
+						cpu_str[j] = '\0';
+						vcpu = atoi(cpu_str);
+						if (vcpu < VCPUS_MAX)
+							guest.cpu_pid[vcpu] = atoi(entry_t->d_name);
+					}
+				}
+				free(buf);
+				fclose(ft);
+				buf = NULL;
+			}
+		}
+
 		guests = realloc(guests, (guests_len + 1) * sizeof(*guests));
 		if (!guests)
 			die("Can not allocate guest buffer");
@@ -2877,6 +2922,16 @@ static char *parse_guest_name(char *guest, int *cid, int *port)
 	return guest;
 }
 
+int *get_guest_vcpu_pids(int cid)
+{
+	int i;
+
+	for (i = 0; i < guests_len; i++)
+		if (cid == guests[i].cid)
+			return guests[i].cpu_pid;
+	return NULL;
+}
+
 static void set_prio(int prio)
 {
 	struct sched_param sp;
-- 
2.20.1


^ permalink raw reply	[flat|nested] 13+ messages in thread

* [PATCH v3 7/7] trace-cmd [POC]: Implemented timestamps synch PTP-like algorithm, using vsock events.
  2019-02-08 13:49 [PATCH v3 0/7][POC] trace-cmd: Timetamps sync using PTP-like algorithm, relying on vsock events Tzvetomir Stoyanov
                   ` (5 preceding siblings ...)
  2019-02-08 13:49 ` [PATCH v3 6/7] trace-cmd: Find and store pids of tasks, which run virtual CPUs of given VM Tzvetomir Stoyanov
@ 2019-02-08 13:49 ` Tzvetomir Stoyanov
  6 siblings, 0 replies; 13+ messages in thread
From: Tzvetomir Stoyanov @ 2019-02-08 13:49 UTC (permalink / raw)
  To: rostedt; +Cc: linux-trace-devel

This is a POC patch, implementing a PTP-like algorithm
for syncing timestamps between host and guest machines,
using vsock trace events to catch the host / guest time.

Signed-off-by: Tzvetomir Stoyanov <tstoyanov@vmware.com>
---
 include/trace-cmd/trace-cmd.h  |   4 +
 tracecmd/include/trace-local.h |   6 +
 tracecmd/trace-listen.c        |   3 +
 tracecmd/trace-msg.c           | 543 ++++++++++++++++++++++++++++++++-
 tracecmd/trace-record.c        | 234 +++++++++++++-
 5 files changed, 778 insertions(+), 12 deletions(-)

diff --git a/include/trace-cmd/trace-cmd.h b/include/trace-cmd/trace-cmd.h
index b2ff6f9..b54ff18 100644
--- a/include/trace-cmd/trace-cmd.h
+++ b/include/trace-cmd/trace-cmd.h
@@ -351,6 +351,10 @@ int tracecmd_msg_recv_trace_resp(struct tracecmd_msg_handle *msg_handle,
 				 int *nr_cpus, int *page_size,
 				 unsigned int **ports, bool *use_fifos);
 
+int tracecmd_msg_rcv_time_sync(struct tracecmd_msg_handle *msg_handle);
+int tracecmd_msg_snd_time_sync(struct tracecmd_msg_handle *msg_handle,
+			       char *clock_str, long long *toffset);
+
 int tracecmd_msg_wait_close(struct tracecmd_msg_handle *msg_handle);
 
 /* --- Plugin handling --- */
diff --git a/tracecmd/include/trace-local.h b/tracecmd/include/trace-local.h
index 4f6e239..424986c 100644
--- a/tracecmd/include/trace-local.h
+++ b/tracecmd/include/trace-local.h
@@ -233,6 +233,12 @@ void show_instance_file(struct buffer_instance *instance, const char *name);
 
 int count_cpus(void);
 
+struct buffer_instance *clock_synch_enable(int fd, char *clock,
+					   int *tx_event, int *rx_event,
+					   int *kvm_exit);
+void clock_synch_disable(int fd, struct buffer_instance *instance);
+struct tep_handle *clock_synch_get_tep(struct buffer_instance *instance);
+void get_vsocket_params(int fd, int *lcid, int *lport, int *rcid, int *rport);
 #define VCPUS_MAX	256
 int *get_guest_vcpu_pids(int cid);
 
diff --git a/tracecmd/trace-listen.c b/tracecmd/trace-listen.c
index 9b50147..7783a68 100644
--- a/tracecmd/trace-listen.c
+++ b/tracecmd/trace-listen.c
@@ -404,6 +404,9 @@ static int communicate_with_client(struct tracecmd_msg_handle *msg_handle)
 
 		msg_handle->version = V3_PROTOCOL;
 
+		/* time sync with the v3 client */
+		tracecmd_msg_rcv_time_sync(msg_handle);
+
 		/* read the CPU count, the page size, and options */
 		if ((pagesize = tracecmd_msg_initial_setting(msg_handle)) < 0)
 			goto out;
diff --git a/tracecmd/trace-msg.c b/tracecmd/trace-msg.c
index c28d294..433814e 100644
--- a/tracecmd/trace-msg.c
+++ b/tracecmd/trace-msg.c
@@ -18,9 +18,11 @@
 #include <stdarg.h>
 #include <string.h>
 #include <unistd.h>
+#include <time.h>
 #include <arpa/inet.h>
 #include <sys/types.h>
 #include <linux/types.h>
+#include <linux/vm_sockets.h>
 
 #include "trace-cmd-local.h"
 #include "trace-local.h"
@@ -28,6 +30,8 @@
 
 typedef __u32 u32;
 typedef __be32 be32;
+typedef __u64 u64;
+typedef __s64 s64;
 
 static inline void dprint(const char *fmt, ...)
 {
@@ -50,11 +54,22 @@ static inline void dprint(const char *fmt, ...)
 
 unsigned int page_size;
 
+/* Try a few times to get an accurate time sync */
+#define TSYNC_TRIES 5000
+
 struct tracecmd_msg_server {
 	struct tracecmd_msg_handle handle;
 	int			done;
 };
 
+struct clock_synch_event {
+
+	int				id;
+	int				cpu;
+	int				pid;
+	unsigned long long		ts;
+};
+
 static struct tracecmd_msg_server *
 make_server(struct tracecmd_msg_handle *msg_handle)
 {
@@ -91,6 +106,19 @@ struct tracecmd_msg_trace_resp {
 	be32 page_size;
 } __attribute__((packed));
 
+struct tracecmd_msg_time_sync_init {
+	char clock[32];
+} __attribute__((packed));
+
+struct tracecmd_msg_time_sync {
+	u64 tlocal_rx;
+	u32 tlocal_rx_cpu;
+	u64 tlocal_kvmex;
+	u64 tlocal_kvmex_cpu;
+	u64 tlocal_tx;
+	u32 tlocal_tx_cpu;
+} __attribute__((packed));
+
 struct tracecmd_msg_header {
 	be32	size;
 	be32	cmd;
@@ -98,13 +126,15 @@ struct tracecmd_msg_header {
 } __attribute__((packed));
 
 #define MSG_MAP								\
-	C(CLOSE,	0,	0),					\
-	C(TINIT,	1,	sizeof(struct tracecmd_msg_tinit)),	\
-	C(RINIT,	2,	sizeof(struct tracecmd_msg_rinit)),	\
-	C(SEND_DATA,	3,	0),					\
-	C(FIN_DATA,	4,	0),					\
-	C(TRACE_REQ,	5,	sizeof(struct tracecmd_msg_trace_req)),	\
-	C(TRACE_RESP,	6,	sizeof(struct tracecmd_msg_trace_resp)),
+	C(CLOSE,		0, 0),					\
+	C(TINIT,		1, sizeof(struct tracecmd_msg_tinit)),	\
+	C(RINIT,		2, sizeof(struct tracecmd_msg_rinit)),	\
+	C(SEND_DATA,		3, 0),					\
+	C(FIN_DATA,		4, 0),					\
+	C(TRACE_REQ,		5, sizeof(struct tracecmd_msg_trace_req)),\
+	C(TRACE_RESP,		6, sizeof(struct tracecmd_msg_trace_resp)),\
+	C(TIME_SYNC_INIT,	7, sizeof(struct tracecmd_msg_time_sync_init)),\
+	C(TIME_SYNC,		8, sizeof(struct tracecmd_msg_time_sync)),
 
 #undef C
 #define C(a,b,c)	MSG_##a = b
@@ -134,10 +164,12 @@ static const char *cmd_to_name(int cmd)
 struct tracecmd_msg {
 	struct tracecmd_msg_header		hdr;
 	union {
-		struct tracecmd_msg_tinit	tinit;
-		struct tracecmd_msg_rinit	rinit;
-		struct tracecmd_msg_trace_req	trace_req;
-		struct tracecmd_msg_trace_resp	trace_resp;
+		struct tracecmd_msg_tinit		tinit;
+		struct tracecmd_msg_rinit		rinit;
+		struct tracecmd_msg_trace_req		trace_req;
+		struct tracecmd_msg_trace_resp		trace_resp;
+		struct tracecmd_msg_time_sync_init	time_sync_init;
+		struct tracecmd_msg_time_sync		time_sync;
 	};
 	union {
 		struct tracecmd_msg_opt		*opt;
@@ -832,6 +864,495 @@ out:
 	return ret;
 }
 
+#define EVENTS_CHUNK	10
+static int
+get_events_in_page(struct tep_handle *tep, void *page,
+		    int size, int cpu, struct clock_synch_event **events,
+		    int *events_count, int *events_size)
+{
+	struct clock_synch_event *events_array = NULL;
+	struct tep_record *last_record = NULL;
+	struct tep_event *event = NULL;
+	struct tep_record *record;
+	int id, cnt = 0;
+
+	if (size <= 0)
+		return 0;
+
+	if (*events == NULL) {
+		*events = malloc(EVENTS_CHUNK*sizeof(struct clock_synch_event));
+		*events_size = EVENTS_CHUNK;
+		*events_count = 0;
+	}
+
+	while (true) {
+		event = NULL;
+		record = tracecmd_read_page_record(tep, page, size,
+						   last_record);
+		if (!record)
+			break;
+		free_record(last_record);
+		id = tep_data_type(tep, record);
+		event = tep_data_event_from_type(tep, id);
+		if (event) {
+			if (*events_count >= *events_size) {
+				events_array = realloc(*events,
+					(*events_size + EVENTS_CHUNK)*sizeof(struct clock_synch_event));
+				if (events_array) {
+					*events = events_array;
+					(*events_size) += EVENTS_CHUNK;
+				}
+			}
+
+			if (*events_count < *events_size) {
+				(*events)[*events_count].ts = record->ts;
+				(*events)[*events_count].cpu = cpu;
+				(*events)[*events_count].id = id;
+				(*events)[*events_count].pid = tep_data_pid(tep, record);
+				(*events_count)++;
+			}
+		}
+		last_record = record;
+	}
+	free_record(last_record);
+
+	return cnt;
+}
+
+static int
+find_sync_events(struct tep_handle *pevent, struct clock_synch_event *recorded,
+		 int rsize, struct clock_synch_event *events)
+{
+	int i = 0, j = 0;
+
+	while (i < rsize) {
+		if (!events[j].ts && events[j].id == recorded[i].id &&
+			(!events[j].pid || events[j].pid == recorded[i].pid)) {
+			events[j].cpu = recorded[i].cpu;
+			events[j].ts = recorded[i].ts;
+			j++;
+		} else if (j > 0 && events[j-1].id == recorded[i].id &&
+			  (!events[j].pid || events[j].pid == recorded[i].pid)) {
+			events[j-1].cpu = recorded[i].cpu;
+			events[j-1].ts = recorded[i].ts;
+		}
+		i++;
+	}
+	return j;
+}
+
+
+static int
+find_events_in_page(struct tep_handle *pevent, void *page,
+		    int size, int cpu, struct clock_synch_event *events)
+{
+	struct tep_record *last_record = NULL;
+	struct tep_event *event = NULL;
+	struct tep_record *record;
+	int id, i, j, cnt = 0;
+
+	if (size <= 0)
+		return 0;
+	for (i = 0; events[i].id; i++) {
+		if (!events[i].ts)
+			cnt++;
+	}
+
+	while (true) {
+		event = NULL;
+		record = tracecmd_read_page_record(pevent, page, size,
+						   last_record);
+		if (!record)
+			break;
+		free_record(last_record);
+		id = tep_data_type(pevent, record);
+		for (i = 0; events[i].id; i++)
+			if (!events[i].ts && events[i].id == id) {
+				event = tep_data_event_from_type(pevent, id);
+				break;
+			}
+		if (event) {
+			for (j = 0; j < i; j++)
+				if (events[j].ts && events[j].ts > record->ts)
+					break;
+			if (j == i) {
+				events[i].ts = record->ts;
+				cnt--;
+			}
+		}
+		last_record = record;
+	}
+	free_record(last_record);
+
+	return cnt;
+}
+
+static int sync_events_cmp(const void *a, const void *b)
+{
+	const struct clock_synch_event *ea = (const struct clock_synch_event *)a;
+	const struct clock_synch_event *eb = (const struct clock_synch_event *)b;
+
+	if (ea->ts > eb->ts)
+		return 1;
+	if (ea->ts < eb->ts)
+		return -1;
+	return 0;
+}
+
+
+static int clock_synch_find_events(struct tep_handle *tep,
+				   struct buffer_instance *instance,
+				   struct clock_synch_event *events)
+{
+	struct clock_synch_event *events_array = NULL;
+	int events_count = 0;
+	int events_size = 0;
+	struct dirent *dent;
+	int ts = 0;
+	void *page;
+	char *path;
+	char *file;
+	DIR *dir;
+	int cpu;
+	int len;
+	int fd;
+	int r;
+
+	page_size = getpagesize();
+#if 0
+	file = get_instance_file(instance, "trace");
+	if (!file)
+		return ts;
+	{
+		char *buf = NULL;
+		FILE *fp;
+		size_t n;
+		int r;
+
+		fp = fopen(file, "r");
+		while ((r = getline(&buf, &n, fp)) >= 0) {
+
+			if (buf[0] != '#')
+				printf("%s", buf);
+
+			free(buf);
+			buf = NULL;
+		}
+		fclose(fp);
+	}
+	tracecmd_put_tracing_file(file);
+#endif
+	path = get_instance_file(instance, "per_cpu");
+	if (!path)
+		return ts;
+
+	dir = opendir(path);
+	if (!dir)
+		goto out;
+
+	len = strlen(path);
+	file = malloc(len + strlen("trace_pipe_raw") + 32);
+	page = malloc(page_size);
+	if (!file || !page)
+		die("Failed to allocate time_stamp info");
+
+	while ((dent = readdir(dir))) {
+
+		const char *name = dent->d_name;
+
+		if (strncmp(name, "cpu", 3) != 0)
+			continue;
+		cpu = atoi(&name[3]);
+#if 0
+		{
+			char *buf = NULL;
+			FILE *fp;
+			size_t n;
+			int r;
+
+			printf("Buff [%s]:\n\r", name);
+			sprintf(file, "%s/%s/trace", path, name);
+			fp = fopen(file, "r");
+			while ((r = getline(&buf, &n, fp)) >= 0) {
+					if (buf[0] != '#')
+						printf("%s", buf);
+
+					free(buf);
+					buf = NULL;
+			}
+			printf("[Buff %s end]\n\r", name);
+		}
+#endif
+
+		sprintf(file, "%s/%s/trace_pipe_raw", path, name);
+		fd = open(file, O_RDONLY | O_NONBLOCK);
+		if (fd < 0)
+			continue;
+		do {
+			r = read(fd, page, page_size);
+			if (r > 0) {
+				get_events_in_page(tep, page, r, cpu,
+						   &events_array, &events_count,
+						   &events_size);
+			}
+		} while (r > 0);
+		close(fd);
+	}
+
+	qsort(events_array, events_count, sizeof(*events_array), sync_events_cmp);
+	r = find_sync_events(tep, events_array, events_count, events);
+
+	free(events_array);
+
+	free(file);
+	free(page);
+	closedir(dir);
+
+ out:
+	tracecmd_put_tracing_file(path);
+	return r;
+}
+
+extern struct tep_handle *clock_synch_get_tep(struct buffer_instance *instance);
+
+int tracecmd_msg_rcv_time_sync(struct tracecmd_msg_handle *msg_handle)
+{
+	struct clock_synch_event events[4];
+	struct buffer_instance *vinst;
+	struct tracecmd_msg msg;
+	struct tep_handle *tep;
+	int *cpu_pid = NULL;
+	int guest_cid = 0;
+	char *clock;
+	int ret;
+
+	ret = tracecmd_msg_recv(msg_handle->fd, &msg);
+	if (ret < 0 || ntohl(msg.hdr.cmd) != MSG_TIME_SYNC_INIT)
+		return 0;
+	if (!msg.time_sync_init.clock[0])
+		return 0;
+	clock = strdup(msg.time_sync_init.clock);
+	memset(events, 0, sizeof(struct clock_synch_event)*4);
+
+	get_vsocket_params(msg_handle->fd, NULL, NULL, &guest_cid, NULL);
+	if (guest_cid)
+		cpu_pid = get_guest_vcpu_pids(guest_cid);
+
+	vinst = clock_synch_enable(msg_handle->fd, clock,
+				   &events[2].id, &events[1].id, &events[0].id);
+	tep = clock_synch_get_tep(vinst);
+	tracecmd_msg_init(MSG_TIME_SYNC_INIT, &msg);
+	tracecmd_msg_send(msg_handle->fd, &msg);
+
+	do {
+		events[0].ts = 0;	/* kvm exit event */
+		events[1].ts = 0;	/* vsock receive event */
+		events[2].ts = 0;	/* vsock send event */
+		ret = tracecmd_msg_recv(msg_handle->fd, &msg);
+		if (ret < 0 || ntohl(msg.hdr.cmd) != MSG_TIME_SYNC)
+			break;
+		ret = tracecmd_msg_recv(msg_handle->fd, &msg);
+		if (ret < 0 || ntohl(msg.hdr.cmd) != MSG_TIME_SYNC)
+			break;
+		tracecmd_msg_send(msg_handle->fd, &msg);
+		/* Get kvm_exit events related to the corresponding VCPU */
+		if (cpu_pid && ntohl(msg.time_sync.tlocal_tx_cpu) < VCPUS_MAX)
+			events[0].pid = cpu_pid[ntohl(msg.time_sync.tlocal_tx_cpu)];
+		ret = clock_synch_find_events(tep, vinst, events);
+		tracecmd_msg_init(MSG_TIME_SYNC, &msg);
+		msg.time_sync.tlocal_tx = htonll(events[2].ts);
+		msg.time_sync.tlocal_tx_cpu = htonl(events[2].cpu);
+		msg.time_sync.tlocal_rx = htonll(events[1].ts);
+		msg.time_sync.tlocal_rx_cpu = htonl(events[1].cpu);
+		msg.time_sync.tlocal_kvmex = htonll(events[0].ts);
+		msg.time_sync.tlocal_kvmex_cpu = htonl(events[0].cpu);
+
+		tracecmd_msg_send(msg_handle->fd, &msg);
+	} while (true);
+	clock_synch_disable(msg_handle->fd, vinst);
+	msg_free(&msg);
+	tep_free(tep);
+	free(clock);
+	return 0;
+}
+
+int tracecmd_msg_snd_time_sync(struct tracecmd_msg_handle *msg_handle,
+			       char *clock_str, long long *toffset)
+{
+	static struct buffer_instance *vinst;
+	struct clock_synch_event events_s[2];
+	struct clock_synch_event events[4];
+	long long *kvm_offsets, kvm_offset_av = 0;
+	int j = 0, i = 0, k = 0, ret = 0;
+	long long min_p = 0, max_p = 0;
+	long long min_kvm = 0, max_kvm = 0;
+	long long *offsets, *replies;
+	struct tracecmd_msg msg_resp;
+	struct tracecmd_msg msg_req;
+	int sync_loop = TSYNC_TRIES;
+	long long ms_diff, sm_diff;
+	long long kvm_tresch = 0;
+	struct tep_handle *tep;
+	long long m_t1, m_t4;
+	long long s_t2, s_t3;
+	long long ptp_offs = 0;
+	long long ptp_tresch = 0;
+	long long kvm_offs = 0;
+	long long repl_av = 0;
+	long long s_t2_kvm = 0;
+	char *clock;
+	char *str_offs = NULL;
+/* Write all ts in a file, used to analyze the raw data */
+int iFd;
+char buff[256];
+
+	clock = clock_str;
+	if (!clock)
+		clock = "local";
+
+	tracecmd_msg_init(MSG_TIME_SYNC_INIT, &msg_req);
+	if (toffset == NULL) {
+		msg_req.time_sync_init.clock[0] = 0;
+		tracecmd_msg_send(msg_handle->fd, &msg_req);
+		return 0;
+	}
+	offsets = calloc(sizeof(long long), TSYNC_TRIES);
+	replies = calloc(sizeof(long long), TSYNC_TRIES);
+	kvm_offsets = calloc(sizeof(long long), TSYNC_TRIES);
+	if (!offsets || !replies || !kvm_offsets) {
+		free(offsets);
+		free(replies);
+		free(kvm_offsets);
+		return 0;
+	}
+
+	strncpy(msg_req.time_sync_init.clock, clock, 16);
+	tracecmd_msg_send(msg_handle->fd, &msg_req);
+	ret = tracecmd_msg_recv(msg_handle->fd, &msg_resp);
+	if (ret < 0 || ntohl(msg_resp.hdr.cmd) != MSG_TIME_SYNC_INIT) {
+		free(offsets);
+		free(replies);
+		free(kvm_offsets);
+		return 0;
+	}
+	memset(events, 0, sizeof(struct clock_synch_event)*4);
+	memset(events_s, 0, sizeof(struct clock_synch_event)*2);
+	vinst = clock_synch_enable(msg_handle->fd, clock_str,
+				   &events[0].id, &events[1].id, NULL);
+	events[2].id = events[1].id;
+	events_s[0].id = events[0].id;
+	tep = clock_synch_get_tep(vinst);
+	*toffset = 0;
+
+sprintf(buff, "s-%s.txt", clock);
+iFd = open(buff, O_CREAT|O_WRONLY|O_TRUNC, 0644);
+
+	do {
+		memset(&msg_resp, 0, sizeof(msg_resp));
+		events[0].ts = 0;	/* vsock send event */
+		events[1].ts = 0;	/* vsock receive event */
+		events[2].ts = 0;	/* vsock receive event */
+		events_s[0].ts = 0;	/* vsock send event */
+		tracecmd_msg_init(MSG_TIME_SYNC, &msg_req);
+
+		tracecmd_msg_send(msg_handle->fd, &msg_req);
+		/* Get the ts and CPU of the send event */
+		clock_synch_find_events(tep, vinst, events_s);
+		tracecmd_msg_init(MSG_TIME_SYNC, &msg_req);
+		msg_req.time_sync.tlocal_tx = htonll(events_s[0].ts);
+		msg_req.time_sync.tlocal_tx_cpu = htonl(events_s[0].cpu);
+		tracecmd_msg_send(msg_handle->fd, &msg_req);
+
+		ret = tracecmd_msg_recv(msg_handle->fd, &msg_resp);
+		if (ret < 0 || ntohl(msg_resp.hdr.cmd) != MSG_TIME_SYNC)
+			break;
+		ret = tracecmd_msg_recv(msg_handle->fd, &msg_resp);
+		if (ret < 0 || ntohl(msg_resp.hdr.cmd) != MSG_TIME_SYNC)
+			break;
+		ret = clock_synch_find_events(tep, vinst, events);
+		m_t1 = events[0].ts; /* Server vsock send ts */
+		m_t4 = events[1].ts; /* Server vsock receive ts */
+		s_t2 = htonll(msg_resp.time_sync.tlocal_rx); /* Client vsock receive ts */
+		s_t3 = ntohll(msg_resp.time_sync.tlocal_tx); /* Client vsock send ts */
+		s_t2_kvm = htonll(msg_resp.time_sync.tlocal_kvmex); /* Client kvm exit ts */
+		if (!m_t1 || !m_t4 || !s_t2 || !s_t3 || !s_t2_kvm)
+			continue;
+		if (m_t1 >= m_t4 || s_t2 >= s_t3)
+			continue;
+		/* PTP calc*/
+		ms_diff = s_t2 - m_t1;
+		sm_diff = m_t4 - s_t3;
+		offsets[i] = (ms_diff - sm_diff)/2;
+		replies[i] = llabs(sm_diff);
+		repl_av += replies[i];
+		if (!min_p || min_p > replies[i])
+			min_p = replies[i];
+		if (!max_p || max_p < replies[i])
+			max_p = replies[i];
+
+		/* KVM calc*/
+		kvm_offsets[i] = s_t2_kvm - m_t1;
+		kvm_offset_av += kvm_offsets[i];
+		if (!min_kvm || min_kvm > llabs(kvm_offsets[i]))
+			min_kvm = llabs(kvm_offsets[i]);
+		if (!max_kvm || max_kvm < llabs(kvm_offsets[i]))
+			max_kvm = llabs(kvm_offsets[i]);
+		i++;
+sprintf(buff, "%lld %lld %lld %lld %lld\n", m_t1, s_t2, s_t3, m_t4, s_t2_kvm);
+write(iFd, buff, strlen(buff));
+	} while (--sync_loop);
+close(iFd);
+	clock_synch_disable(msg_handle->fd, vinst);
+	repl_av /= (long long)i;
+	ptp_tresch = (long long)((max_p - min_p)/10);
+	kvm_offset_av /= (long long)i;
+	kvm_tresch = (long long)((max_kvm - min_kvm)/10);
+	for (i = 0; i < TSYNC_TRIES; i++) {
+		/* PTP: filter the replies with deviation up to 10% */
+		if (replies[i] && llabs(replies[i] - repl_av) < ptp_tresch) {
+			ptp_offs += offsets[i];
+			j++;
+		}
+		/* KVM: filter the offsets with deviation up to 10% */
+		if (kvm_offsets[i] &&
+		    llabs(kvm_offsets[i] - kvm_offset_av) < kvm_tresch) {
+			kvm_offs += kvm_offsets[i];
+			k++;
+		}
+	}
+	if (j)
+		ptp_offs /= (long long)j;
+	if (k)
+		kvm_offs /= (long long)k;
+
+	tracecmd_msg_init(MSG_TIME_SYNC_INIT, &msg_req);
+	msg_req.time_sync_init.clock[0] = 0;
+	tracecmd_msg_send(msg_handle->fd, &msg_req);
+
+	msg_free(&msg_req);
+	msg_free(&msg_resp);
+	free(offsets);
+	free(replies);
+	free(kvm_offsets);
+#if 1
+	/* Write PTP offset in the trace file */
+	*toffset = ptp_offs;
+	str_offs = "PTP";
+#else
+	/* Write KVM offset in the trace file */
+	*toffset = kvm_offs;
+	str_offs = "KVM";
+#endif
+	printf("\n selected: %lld (%s offset), delta %lld, used clock %s\n\r",
+		*toffset, str_offs, ptp_offs-kvm_offs, clock);
+	printf("\t PTP: %lld, good probes: %d, threshold %lld\n\r",
+		ptp_offs, j, ptp_tresch);
+	printf("\t KVM: %lld, good probes: %d, threshold %lld\n\r",
+			kvm_offs, k, kvm_tresch);
+
+	return 0;
+}
+
 static int make_trace_resp(struct tracecmd_msg *msg, int page_size, int nr_cpus,
 			   unsigned int *ports, bool use_fifos)
 {
diff --git a/tracecmd/trace-record.c b/tracecmd/trace-record.c
index ab3f97e..b170b6e 100644
--- a/tracecmd/trace-record.c
+++ b/tracecmd/trace-record.c
@@ -3216,6 +3216,39 @@ static void check_protocol_version(struct tracecmd_msg_handle *msg_handle)
 	}
 }
 
+static void sync_time_with_listener_v3(struct tracecmd_msg_handle *msg_handle,
+				       struct common_record_context *ctx)
+{
+	struct buffer_instance	*instance;
+	long long toffset = 0;
+	char *clock = NULL;
+
+	instance = ctx->instance;
+	while (instance) {
+		clock = instance->clock;
+		if (clock)
+			break;
+		instance = instance->next;
+	}
+
+	if (ctx->data_flags & DATA_FL_DATE ||
+	    ctx->data_flags & DATA_FL_OFFSET) {
+		tracecmd_msg_snd_time_sync(msg_handle, clock, NULL);
+		return;
+	}
+
+	tracecmd_msg_snd_time_sync(msg_handle, clock, &toffset);
+
+	free(ctx->date2ts);
+	/* 20 digits + \0 */
+	ctx->date2ts = malloc(21);
+	if (ctx->date2ts) {
+		snprintf(ctx->date2ts, 21, "%lld", toffset);
+		ctx->data_flags |= DATA_FL_OFFSET;
+	}
+
+}
+
 static struct tracecmd_msg_handle *setup_network(struct buffer_instance *instance)
 {
 	struct tracecmd_msg_handle *msg_handle = NULL;
@@ -3453,6 +3486,8 @@ static void connect_to_agent(struct buffer_instance *instance)
 
 	/* the msg_handle now points to the guest fd */
 	instance->msg_handle = msg_handle;
+
+	tracecmd_msg_rcv_time_sync(msg_handle);
 }
 
 static void setup_guest(struct buffer_instance *instance)
@@ -3477,10 +3512,13 @@ static void setup_guest(struct buffer_instance *instance)
 	close(fd);
 }
 
-static void setup_agent(struct buffer_instance *instance, struct common_record_context *ctx)
+static void setup_agent(struct buffer_instance *instance,
+			struct common_record_context *ctx)
 {
 	struct tracecmd_output *network_handle;
 
+	sync_time_with_listener_v3(instance->msg_handle, ctx);
+
 	network_handle = tracecmd_create_init_fd_msg(instance->msg_handle,
 						     listed_events);
 	add_options(network_handle, ctx);
@@ -5879,3 +5917,197 @@ int trace_record_agent(struct tracecmd_msg_handle *msg_handle,
 	free(argv_plus);
 	return 0;
 }
+
+void get_vsocket_params(int fd, int *lcid,
+			int *lport, int *rcid, int *rport)
+{
+	struct sockaddr_vm addr;
+	socklen_t addr_len = sizeof(addr);
+
+	if (lcid || lport) {
+		memset(&addr, 0, sizeof(addr));
+		if (getsockname(fd, (struct sockaddr *)&addr, &addr_len))
+			return;
+		if (addr.svm_family != AF_VSOCK)
+			return;
+		if (lport)
+			*lport = addr.svm_port;
+		if (lcid)
+			*lcid = addr.svm_cid;
+	}
+
+	if (rcid || rport) {
+		memset(&addr, 0, sizeof(addr));
+		addr_len = sizeof(addr);
+		if (getpeername(fd, (struct sockaddr *)&addr, &addr_len))
+			return;
+		if (addr.svm_family != AF_VSOCK)
+			return;
+
+		if (rport)
+			*rport = addr.svm_port;
+		if (rcid)
+			*rcid = addr.svm_cid;
+	}
+}
+
+static void set_clock_synch_events(int cfd, struct buffer_instance *instance,
+				   bool enable, int *tx_event, int *rx_event,
+				   int *kvm_exit)
+{
+	int lcid, lport, rcid, rport;
+	char buffer[255];
+	FILE *fp;
+	char *path;
+	int fd;
+
+	path = get_instance_file(instance, "events/vsock/enable");
+	fd = open(path, O_WRONLY);
+	if (fd < 0)
+		return;
+	if (enable)
+		write(fd, "1", 2);
+	else
+		write(fd, "0", 2);
+	close(fd);
+	tracecmd_put_tracing_file(path);
+#if 1
+	/* Filter EPT_MISCONFIG exit reason */
+	snprintf(buffer, 255, "exit_reason==49");
+	path = get_instance_file(instance,
+				 "events/kvm/kvm_exit/filter");
+	fd = open(path, O_WRONLY);
+	if (fd > 0) {
+		write(fd, buffer, strlen(buffer)+1);
+		close(fd);
+	}
+	tracecmd_put_tracing_file(path);
+
+
+	path = get_instance_file(instance, "events/kvm/kvm_exit/enable");
+	fd = open(path, O_WRONLY);
+	if (fd > 0) {
+		if (enable)
+			write(fd, "1", 2);
+		else
+			write(fd, "0", 2);
+		close(fd);
+	}
+	tracecmd_put_tracing_file(path);
+	if (kvm_exit) {
+		path = get_instance_file(instance,
+					 "events/kvm/kvm_exit/id");
+		fp = fopen(path, "r");
+		if (fp) {
+			fgets(buffer, 255, (FILE *) fp);
+			*kvm_exit = atoi(buffer);
+			fclose(fp);
+		}
+		tracecmd_put_tracing_file(path);
+	}
+#endif
+
+	if (enable) {
+		get_vsocket_params(cfd, &lcid, &lport, &rcid, &rport);
+
+		snprintf(buffer, 255,
+			"src_cid==%d && src_port==%d && dst_cid==%d && dst_port==%d && len!=0",
+			rcid, rport, lcid, lport);
+		path = get_instance_file(instance,
+					 "events/vsock/virtio_transport_recv_pkt/filter");
+		fd = open(path, O_WRONLY);
+		write(fd, buffer, strlen(buffer)+1);
+		close(fd);
+		tracecmd_put_tracing_file(path);
+
+		snprintf(buffer, 255,
+			"src_cid==%d && src_port==%d && dst_cid==%d && dst_port==%d && len!=0",
+			lcid, lport, rcid, rport);
+		path = get_instance_file(instance,
+					 "events/vsock/virtio_transport_alloc_pkt/filter");
+		fd = open(path, O_WRONLY);
+		write(fd, buffer, strlen(buffer)+1);
+		close(fd);
+		tracecmd_put_tracing_file(path);
+
+		if (tx_event) {
+			path = get_instance_file(instance,
+						 "events/vsock/virtio_transport_alloc_pkt/id");
+			fp = fopen(path, "r");
+			fgets(buffer, 255, (FILE *) fp);
+			*tx_event = atoi(buffer);
+			fclose(fp);
+			tracecmd_put_tracing_file(path);
+		}
+		if (rx_event) {
+			path = get_instance_file(instance,
+						 "events/vsock/virtio_transport_recv_pkt/id");
+			fp = fopen(path, "r");
+			fgets(buffer, 255, (FILE *) fp);
+			*rx_event = atoi(buffer);
+			fclose(fp);
+			tracecmd_put_tracing_file(path);
+		}
+	}
+
+	path = get_instance_file(instance, "events/vsock/enable");
+
+	if (enable)
+		write_tracing_on(instance, 1);
+	else
+		write_tracing_on(instance, 0);
+}
+
+static void vsock_trace_reset(struct buffer_instance *vinst)
+{
+	char *path;
+	int fd;
+
+	path = get_instance_file(vinst, "trace");
+	fd = open(path, O_WRONLY);
+	tracecmd_put_tracing_file(path);
+	write(fd, "0", 2);
+	close(fd);
+}
+
+struct tep_handle *clock_synch_get_tep(struct buffer_instance *instance)
+{
+	char *systems[] = {"vsock", "kvm", NULL};
+	struct tep_handle *tep = NULL;
+	char *path;
+
+	path = get_instance_dir(instance);
+	tep = tracecmd_local_events_system(path, systems);
+	tracecmd_put_tracing_file(path);
+
+	tep_set_file_bigendian(tep, tracecmd_host_bigendian());
+	tep_set_host_bigendian(tep, tracecmd_host_bigendian());
+
+	return tep;
+}
+
+struct buffer_instance *clock_synch_enable(int fd, char *clock,
+					   int *tx_event, int *rx_event,
+					   int *kvm_exit)
+{
+	struct buffer_instance *vinst;
+	char inst_name[256];
+
+	snprintf(inst_name, 256, "clock_synch-%d", rand()%100);
+	vinst = create_instance(strdup(inst_name));
+	init_instance(vinst);
+	vinst->cpu_count = local_cpu_count;
+	make_one_instance(vinst);
+	vsock_trace_reset(vinst);
+	vinst->clock = strdup(clock);
+	set_clock(vinst);
+	set_clock_synch_events(fd, vinst, true, tx_event, rx_event, kvm_exit);
+	return vinst;
+}
+
+void clock_synch_disable(int fd, struct buffer_instance *instance)
+{
+	set_clock_synch_events(fd, instance, false, NULL, NULL, NULL);
+	tracecmd_remove_one_instance(instance);
+	/* todo: clean up the instance */
+}
-- 
2.20.1


^ permalink raw reply	[flat|nested] 13+ messages in thread

* Re: [PATCH v3 2/7] trace-cmd: Added support for negative time offsets in trace.dat file
  2019-02-08 13:49 ` [PATCH v3 2/7] trace-cmd: Added support for negative time offsets in trace.dat file Tzvetomir Stoyanov
@ 2019-02-08 21:39   ` Steven Rostedt
  0 siblings, 0 replies; 13+ messages in thread
From: Steven Rostedt @ 2019-02-08 21:39 UTC (permalink / raw)
  To: Tzvetomir Stoyanov; +Cc: linux-trace-devel

On Fri,  8 Feb 2019 15:49:13 +0200
Tzvetomir Stoyanov <tstoyanov@vmware.com> wrote:

> When synchronizing timestamps between different machines, there are cases
> when the time offset is negative. This patch changes the way time offset is
> written and read from trace.dat file - as signed decimal, instead of hex.
> 
> Signed-off-by: Tzvetomir Stoyanov <tstoyanov@vmware.com>
> ---
>  include/trace-cmd/trace-cmd.h |   2 +-
>  lib/trace-cmd/trace-input.c   |   6 +-
>  tracecmd/trace-read.c         |   4 +-
>  tracecmd/trace-record.c       | 120 +++++++++++++++++-----------------
>  4 files changed, 66 insertions(+), 66 deletions(-)

Can you break this patch into two. One that moves the code around, and
the other that makes the changes. It's easier to review and see what
changed that way.

Thanks!

-- Steve

> 
> diff --git a/include/trace-cmd/trace-cmd.h b/include/trace-cmd/trace-cmd.h
> index 3d72430..b2ff6f9 100644
> --- a/include/trace-cmd/trace-cmd.h
> +++ b/include/trace-cmd/trace-cmd.h
> @@ -126,7 +126,7 @@ int tracecmd_is_buffer_instance(struct tracecmd_input *handle);
>  void tracecmd_create_top_instance(char *name);
>  void tracecmd_remove_instances(void);
>  
> -void tracecmd_set_ts_offset(struct tracecmd_input *handle, unsigned long long offset);
> +void tracecmd_set_ts_offset(struct tracecmd_input *handle, long long offset);
>  void tracecmd_set_ts2secs(struct tracecmd_input *handle, unsigned long long hz);
>  
>  void tracecmd_print_events(struct tracecmd_input *handle, const char *regex);
> diff --git a/lib/trace-cmd/trace-input.c b/lib/trace-cmd/trace-input.c
> index b628570..33ad7d1 100644
> --- a/lib/trace-cmd/trace-input.c
> +++ b/lib/trace-cmd/trace-input.c
> @@ -100,7 +100,7 @@ struct tracecmd_input {
>  	bool			read_page;
>  	bool			use_pipe;
>  	struct cpu_data 	*cpu_data;
> -	unsigned long long	ts_offset;
> +	long long		ts_offset;
>  	double			ts2secs;
>  	char *			cpustats;
>  	char *			uname;
> @@ -2091,7 +2091,7 @@ static int init_cpu(struct tracecmd_input *handle, int cpu)
>  }
>  
>  void tracecmd_set_ts_offset(struct tracecmd_input *handle,
> -			    unsigned long long offset)
> +			    long long offset)
>  {
>  	handle->ts_offset = offset;
>  }
> @@ -2108,7 +2108,7 @@ void tracecmd_set_ts2secs(struct tracecmd_input *handle,
>  
>  static int handle_options(struct tracecmd_input *handle)
>  {
> -	unsigned long long offset;
> +	long long offset;
>  	unsigned short option;
>  	unsigned int size;
>  	char *cpustats = NULL;
> diff --git a/tracecmd/trace-read.c b/tracecmd/trace-read.c
> index 804022a..e309672 100644
> --- a/tracecmd/trace-read.c
> +++ b/tracecmd/trace-read.c
> @@ -58,7 +58,7 @@ static struct list_head handle_list;
>  struct input_files {
>  	struct list_head	list;
>  	const char		*file;
> -	unsigned long long	tsoffset;
> +	long long		tsoffset;
>  	unsigned long long	ts2secs;
>  };
>  static struct list_head input_files;
> @@ -1413,7 +1413,7 @@ void trace_report (int argc, char **argv)
>  	struct input_files *inputs;
>  	struct handle_list *handles;
>  	enum output_type otype;
> -	unsigned long long tsoffset = 0;
> +	long long tsoffset = 0;
>  	unsigned long long ts2secs = 0;
>  	unsigned long long ts2sc;
>  	int show_stat = 0;
> diff --git a/tracecmd/trace-record.c b/tracecmd/trace-record.c
> index 43d782e..01b360a 100644
> --- a/tracecmd/trace-record.c
> +++ b/tracecmd/trace-record.c
> @@ -203,6 +203,12 @@ enum trace_cmd {
>  	CMD_record_agent,
>  };
>  
> +enum {
> +	DATA_FL_NONE		= 0,
> +	DATA_FL_DATE		= 1,
> +	DATA_FL_OFFSET		= 2,
> +};
> +
>  struct common_record_context {
>  	enum trace_cmd curr_cmd;
>  	struct buffer_instance *instance;
> @@ -3234,7 +3240,60 @@ again:
>  	return msg_handle;
>  }
>  
> -static void add_options(struct tracecmd_output *handle, struct common_record_context *ctx);
> +static void add_option_hooks(struct tracecmd_output *handle)
> +{
> +	struct hook_list *hook;
> +	int len;
> +
> +	for (hook = hooks; hook; hook = hook->next) {
> +		len = strlen(hook->hook);
> +		tracecmd_add_option(handle, TRACECMD_OPTION_HOOK,
> +				    len + 1, hook->hook);
> +	}
> +}
> +
> +static void add_uname(struct tracecmd_output *handle)
> +{
> +	struct utsname buf;
> +	char *str;
> +	int len;
> +	int ret;
> +
> +	ret = uname(&buf);
> +	/* if this fails for some reason, just ignore it */
> +	if (ret < 0)
> +		return;
> +
> +	len = strlen(buf.sysname) + strlen(buf.nodename) +
> +		strlen(buf.release) + strlen(buf.machine) + 4;
> +	str = malloc(len);
> +	if (!str)
> +		return;
> +	sprintf(str, "%s %s %s %s", buf.sysname, buf.nodename, buf.release, buf.machine);
> +	tracecmd_add_option(handle, TRACECMD_OPTION_UNAME, len, str);
> +	free(str);
> +}
> +
> +static void add_options(struct tracecmd_output *handle,
> +			struct common_record_context *ctx)
> +{
> +	int type = 0;
> +
> +	if (ctx->date2ts) {
> +		if (ctx->data_flags & DATA_FL_DATE)
> +			type = TRACECMD_OPTION_DATE;
> +		else if (ctx->data_flags & DATA_FL_OFFSET)
> +			type = TRACECMD_OPTION_OFFSET;
> +	}
> +
> +	if (type)
> +		tracecmd_add_option(handle, type,
> +				    strlen(ctx->date2ts)+1, ctx->date2ts);
> +
> +	tracecmd_add_option(handle, TRACECMD_OPTION_TRACECLOCK, 0, NULL);
> +	add_option_hooks(handle);
> +	add_uname(handle);
> +}
>  
>  static struct tracecmd_msg_handle *
>  setup_connection(struct buffer_instance *instance, struct common_record_context *ctx)
> @@ -3505,40 +3564,6 @@ add_buffer_stat(struct tracecmd_output *handle, struct buffer_instance *instance
>  				    instance->s_save[i].buffer);
>  }
>  
> -static void add_option_hooks(struct tracecmd_output *handle)
> -{
> -	struct hook_list *hook;
> -	int len;
> -
> -	for (hook = hooks; hook; hook = hook->next) {
> -		len = strlen(hook->hook);
> -		tracecmd_add_option(handle, TRACECMD_OPTION_HOOK,
> -				    len + 1, hook->hook);
> -	}
> -}
> -
> -static void add_uname(struct tracecmd_output *handle)
> -{
> -	struct utsname buf;
> -	char *str;
> -	int len;
> -	int ret;
> -
> -	ret = uname(&buf);
> -	/* if this fails for some reason, just ignore it */
> -	if (ret < 0)
> -		return;
> -
> -	len = strlen(buf.sysname) + strlen(buf.nodename) +
> -		strlen(buf.release) + strlen(buf.machine) + 4;
> -	str = malloc(len);
> -	if (!str)
> -		return;
> -	sprintf(str, "%s %s %s %s", buf.sysname, buf.nodename, buf.release, buf.machine);
> -	tracecmd_add_option(handle, TRACECMD_OPTION_UNAME, len, str);
> -	free(str);
> -}
> -
>  static void print_stat(struct buffer_instance *instance)
>  {
>  	int cpu;
> @@ -3553,31 +3578,6 @@ static void print_stat(struct buffer_instance *instance)
>  		trace_seq_do_printf(&instance->s_print[cpu]);
>  }
>  
> -enum {
> -	DATA_FL_NONE		= 0,
> -	DATA_FL_DATE		= 1,
> -	DATA_FL_OFFSET		= 2,
> -};
> -
> -static void add_options(struct tracecmd_output *handle, struct common_record_context *ctx)
> -{
> -	int type = 0;
> -
> -	if (ctx->date2ts) {
> -		if (ctx->data_flags & DATA_FL_DATE)
> -			type = TRACECMD_OPTION_DATE;
> -		else if (ctx->data_flags & DATA_FL_OFFSET)
> -			type = TRACECMD_OPTION_OFFSET;
> -	}
> -
> -	if (type)
> -		tracecmd_add_option(handle, type, strlen(ctx->date2ts)+1, ctx->date2ts);
> -
> -	tracecmd_add_option(handle, TRACECMD_OPTION_TRACECLOCK, 0, NULL);
> -	add_option_hooks(handle);
> -	add_uname(handle);
> -}
> -
>  static void write_guest_file(struct buffer_instance *instance)
>  {
>  	struct tracecmd_output *handle;


^ permalink raw reply	[flat|nested] 13+ messages in thread

* Re: [PATCH v3 3/7] trace-cmd: Fixed logic in tracecmd_read_page_record()
  2019-02-08 13:49 ` [PATCH v3 3/7] trace-cmd: Fixed logic in tracecmd_read_page_record() Tzvetomir Stoyanov
@ 2019-02-08 22:08   ` Steven Rostedt
  0 siblings, 0 replies; 13+ messages in thread
From: Steven Rostedt @ 2019-02-08 22:08 UTC (permalink / raw)
  To: Tzvetomir Stoyanov; +Cc: linux-trace-devel

On Fri,  8 Feb 2019 15:49:14 +0200
Tzvetomir Stoyanov <tstoyanov@vmware.com> wrote:

> Fixed the logic in tracecmd_read_page_record() when
> searching for the next event in the event from the
> ring buffer. In the current logic, in the case when
> last_record is not NULL (we are searching for the second one)
> the check "if (ptr != last_record->data)" always fails.
> 

Nice catch.

Let's change the change log and subject:

Subject trace-cmd: Fix tracecmd_read_page_record() to read more than one event

 The kbuffer_next_event() will return the next event on the sub buffer.
 If we pass in the last_record to tracecmd_read_page_record(), it
 initializes the sub buffer, and by calling kbuffer_next_event()
 (instead of kbuffer_read_event()), the second event on the sub buffer
 is returned. This causes the match of the last_record not to match if
 the last_record happens to be the first event on the sub buffer.


> Signed-off-by: Tzvetomir Stoyanov <tstoyanov@vmware.com>
> ---
>  lib/trace-cmd/trace-input.c | 12 ++++++++----
>  1 file changed, 8 insertions(+), 4 deletions(-)
> 
> diff --git a/lib/trace-cmd/trace-input.c b/lib/trace-cmd/trace-input.c
> index 33ad7d1..5d64ca8 100644
> --- a/lib/trace-cmd/trace-input.c
> +++ b/lib/trace-cmd/trace-input.c
> @@ -1688,18 +1688,22 @@ tracecmd_read_page_record(struct tep_handle *pevent, void *page, int size,
>  			goto out_free;
>  		}
>  
> -		do {
> +		ptr = kbuffer_read_event(kbuf, &ts);
> +		while (ptr < last_record->data) {
>  			ptr = kbuffer_next_event(kbuf, NULL);
>  			if (!ptr)
>  				break;
> -		} while (ptr < last_record->data);
> +			if (ptr == last_record->data)
> +				break;
> +		}
>  		if (ptr != last_record->data) {
>  			warning("tracecmd_read_page_record: could not find last_record");
>  			goto out_free;
>  		}
> -	}
> +		ptr = kbuffer_next_event(kbuf, &ts);
> +	} else
> +		ptr = kbuffer_read_event(kbuf, &ts);
>  
> -	ptr = kbuffer_read_event(kbuf, &ts);

Also, instead of the above "} else" clause, we can just move the

	ptr = kbuffer_read_event(kbuf, &ts);

before the if condition testing last_record.

-- Steve

>  	if (!ptr)
>  		goto out_free;
>  


^ permalink raw reply	[flat|nested] 13+ messages in thread

* Re: [PATCH v3 5/7] trace-cmd: Refactored make_instances() and tracecmd_remove_instances()
  2019-02-08 13:49 ` [PATCH v3 5/7] trace-cmd: Refactored make_instances() and tracecmd_remove_instances() Tzvetomir Stoyanov
@ 2019-02-08 22:11   ` Steven Rostedt
  2019-02-08 22:44   ` Steven Rostedt
  1 sibling, 0 replies; 13+ messages in thread
From: Steven Rostedt @ 2019-02-08 22:11 UTC (permalink / raw)
  To: Tzvetomir Stoyanov; +Cc: linux-trace-devel

On Fri,  8 Feb 2019 15:49:16 +0200
Tzvetomir Stoyanov <tstoyanov@vmware.com> wrote:

> In order to reuse the code which creates / deletes tracing instances,
> these two functions are refactotred. A new ones are implemented:
> make_one_instances() and tracecmd_remove_one_instance().
> 

Note, I still prefer just dropping the "s":

	make_instances() (more than one)
	make_instance() (just one)

-- Steve

^ permalink raw reply	[flat|nested] 13+ messages in thread

* Re: [PATCH v3 5/7] trace-cmd: Refactored make_instances() and tracecmd_remove_instances()
  2019-02-08 13:49 ` [PATCH v3 5/7] trace-cmd: Refactored make_instances() and tracecmd_remove_instances() Tzvetomir Stoyanov
  2019-02-08 22:11   ` Steven Rostedt
@ 2019-02-08 22:44   ` Steven Rostedt
  2019-02-08 22:46     ` Steven Rostedt
  1 sibling, 1 reply; 13+ messages in thread
From: Steven Rostedt @ 2019-02-08 22:44 UTC (permalink / raw)
  To: Tzvetomir Stoyanov; +Cc: linux-trace-devel

On Fri,  8 Feb 2019 15:49:16 +0200
Tzvetomir Stoyanov <tstoyanov@vmware.com> wrote:

> +static void tracecmd_remove_one_instance(struct buffer_instance *instance)
> +{
> +	char *path;
> +
> +	if (instance->tracing_on_fd > 0) {
> +		close(instance->tracing_on_fd);
> +		instance->tracing_on_fd = 0;

Also note that uninitialized file descriptors should be a negative
number (-1), because zero is a valid descriptor value.

-- Steve

>  	}
> +	path = get_instance_dir(instance);
> +	tracecmd_put_tracing_file(path);
>  }
>  

^ permalink raw reply	[flat|nested] 13+ messages in thread

* Re: [PATCH v3 5/7] trace-cmd: Refactored make_instances() and tracecmd_remove_instances()
  2019-02-08 22:44   ` Steven Rostedt
@ 2019-02-08 22:46     ` Steven Rostedt
  0 siblings, 0 replies; 13+ messages in thread
From: Steven Rostedt @ 2019-02-08 22:46 UTC (permalink / raw)
  To: Tzvetomir Stoyanov; +Cc: linux-trace-devel

On Fri, 8 Feb 2019 17:44:09 -0500
Steven Rostedt <rostedt@goodmis.org> wrote:

> On Fri,  8 Feb 2019 15:49:16 +0200
> Tzvetomir Stoyanov <tstoyanov@vmware.com> wrote:
> 
> > +static void tracecmd_remove_one_instance(struct buffer_instance *instance)
> > +{
> > +	char *path;
> > +
> > +	if (instance->tracing_on_fd > 0) {
> > +		close(instance->tracing_on_fd);
> > +		instance->tracing_on_fd = 0;  
> 
> Also note that uninitialized file descriptors should be a negative
> number (-1), because zero is a valid descriptor value.

Bah, nevermind. Looks like I was a bit more lenient back in the day...

d56f30679 trace-record.c          (Steven Rostedt (Red Hat)    2013-03-06 11:31:39 -0500 1938)  /* OK, we keep zero for stdin */
d56f30679 trace-record.c          (Steven Rostedt (Red Hat)    2013-03-06 11:31:39 -0500 1939)  if (fd > 0)
6e7c1dd76 trace-record.c          (Steven Rostedt              2011-02-23 13:28:04 -0500 1940)          return fd;


  ;-)

-- Steve


^ permalink raw reply	[flat|nested] 13+ messages in thread

end of thread, back to index

Thread overview: 13+ messages (download: mbox.gz / follow: Atom feed)
-- links below jump to the message on this page --
2019-02-08 13:49 [PATCH v3 0/7][POC] trace-cmd: Timetamps sync using PTP-like algorithm, relying on vsock events Tzvetomir Stoyanov
2019-02-08 13:49 ` [PATCH v3 1/7] trace-cmd: Implemented new lib API: tracecmd_local_events_system() Tzvetomir Stoyanov
2019-02-08 13:49 ` [PATCH v3 2/7] trace-cmd: Added support for negative time offsets in trace.dat file Tzvetomir Stoyanov
2019-02-08 21:39   ` Steven Rostedt
2019-02-08 13:49 ` [PATCH v3 3/7] trace-cmd: Fixed logic in tracecmd_read_page_record() Tzvetomir Stoyanov
2019-02-08 22:08   ` Steven Rostedt
2019-02-08 13:49 ` [PATCH v3 4/7] trace-cmd: Added implementation of htonll() and ntohll() Tzvetomir Stoyanov
2019-02-08 13:49 ` [PATCH v3 5/7] trace-cmd: Refactored make_instances() and tracecmd_remove_instances() Tzvetomir Stoyanov
2019-02-08 22:11   ` Steven Rostedt
2019-02-08 22:44   ` Steven Rostedt
2019-02-08 22:46     ` Steven Rostedt
2019-02-08 13:49 ` [PATCH v3 6/7] trace-cmd: Find and store pids of tasks, which run virtual CPUs of given VM Tzvetomir Stoyanov
2019-02-08 13:49 ` [PATCH v3 7/7] trace-cmd [POC]: Implemented timestamps synch PTP-like algorithm, using vsock events Tzvetomir Stoyanov

Linux-Trace-Devel Archive on lore.kernel.org

Archives are clonable:
	git clone --mirror https://lore.kernel.org/linux-trace-devel/0 linux-trace-devel/git/0.git

	# If you have public-inbox 1.1+ installed, you may
	# initialize and index your mirror using the following commands:
	public-inbox-init -V2 linux-trace-devel linux-trace-devel/ https://lore.kernel.org/linux-trace-devel \
		linux-trace-devel@vger.kernel.org linux-trace-devel@archiver.kernel.org
	public-inbox-index linux-trace-devel


Newsgroup available over NNTP:
	nntp://nntp.lore.kernel.org/org.kernel.vger.linux-trace-devel


AGPL code for this site: git clone https://public-inbox.org/ public-inbox