[PATCH v4 0/7][POC] trace-cmd: Timetamps sync between host and guest machines, relying on vsock events.

[PATCH v4 0/7][POC] trace-cmd: Timetamps sync between host and guest machines, relying on vsock events.

[Tzvetomir Stoyanov]

[
 V4 changes:
  - Removed the implementation of PTP-like algorithm. The current 
    logic relies on matching time stamps of kvm_exit/virtio_transport_recv_pkt
    events on host to virtio_transport_alloc_pkt/vp_notify events on guest.
  - Rebased to Slavomir's v7 "Add VM kernel tracing over vsockets and FIFOs" 
    patch series.
  - Decreased the time synch probes from 5000 to 300.
  - Addressed Steven Rostedt comments.
  - Code cleanup. 

 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.

 V2 changes:
  - Addressed Steven Rostedt comments.
  - Modified PTP-like timestamps sync algorithm to gain more accuracy, with the
    help of Yordan Karadzhov and Slavomir Kaslev.
]

This patch series is a POC for timestamps sync between guest and host machines.
The algorithm relies on matching time stamps of guest and host vsock events.

The patch series depends on Slavomir's changes, introduced by the v7 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: Fix tracecmd_read_page_record() to read more than one event
  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 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 |  16 ++
 tracecmd/include/trace-msg.h   |  10 +
 tracecmd/trace-listen.c        |   3 +
 tracecmd/trace-msg.c           | 477 ++++++++++++++++++++++++++++++++-
 tracecmd/trace-read.c          |   4 +-
 tracecmd/trace-record.c        | 267 +++++++++++++++---
 9 files changed, 816 insertions(+), 86 deletions(-)

-- 
2.20.1

[PATCH v4 1/7] trace-cmd: Implemented new lib API: tracecmd_local_events_system()

[Tzvetomir Stoyanov]

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 27ba89d..0067882 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

Re: [PATCH v4 1/7] trace-cmd: Implemented new lib API: tracecmd_local_events_system()

[Slavomir Kaslev]

On Fri, Feb 22, 2019 at 04:28:30PM +0200, Tzvetomir Stoyanov wrote:
> 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 27ba89d..0067882 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);

Can we have sys_names be `const char **` to imply that it's not getting modified
in here?

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

I think this would be better done in a separate function, say:

static bool contains(const char *name, const char **names)
{
	while (*names) {
		if (strcmp(name, *names++) == 0)
			return true;
	}
	return false;
}

and then simply have

if (sys_names && !contains(name, sys_names))
	continue;

here.

>  		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
> 

Re: [PATCH v4 1/7] trace-cmd: Implemented new lib API: tracecmd_local_events_system()

[Steven Rostedt]

On Fri, 22 Feb 2019 17:51:04 +0200
Slavomir Kaslev <kaslevs@vmware.com> wrote:

> > @@ -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;
> > +		}  
> 
> I think this would be better done in a separate function, say:
> 
> static bool contains(const char *name, const char **names)
> {
> 	while (*names) {
> 		if (strcmp(name, *names++) == 0)
> 			return true;
> 	}
> 	return false;
> }
> 
> and then simply have
> 
> if (sys_names && !contains(name, sys_names))
> 	continue;

Actually, I would argue just to make it a for loop.

	for (i = 0; sys_names[i]; i++) {
		if (strcmp(name, sys_names[i]) == 0)
			goto found;
	}
	continue;
found:

But if you really want the helper function, then have it check
sys_names too.

static bool contains(const char *name, const char * const * names)
{
	if (!names)
		return false;
	for (; *names; names++)
		if (strcmp(name, *names) == 0)
			return true;
	return false;
}

	if (!contains(name, sys_names))

-- Steve

> 
> here.
> 
> >  		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;
> >  }

[PATCH v4 2/7] trace-cmd: Added support for negative time offsets in trace.dat file

[Tzvetomir Stoyanov]

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 ++--
 3 files changed, 6 insertions(+), 6 deletions(-)

diff --git a/include/trace-cmd/trace-cmd.h b/include/trace-cmd/trace-cmd.h
index 0067882..3f0ab4f 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 34a8301..be6720c 100644
--- a/lib/trace-cmd/trace-input.c
+++ b/lib/trace-cmd/trace-input.c
@@ -91,7 +91,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;
@@ -2082,7 +2082,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;
 }
@@ -2099,7 +2099,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;
-- 
2.20.1

[PATCH v4 3/7] trace-cmd: Fix tracecmd_read_page_record() to read more than one event

[Tzvetomir Stoyanov]

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 be6720c..0a6e820 100644
--- a/lib/trace-cmd/trace-input.c
+++ b/lib/trace-cmd/trace-input.c
@@ -1679,18 +1679,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

Re: [PATCH v4 3/7] trace-cmd: Fix tracecmd_read_page_record() to read more than one event

[Slavomir Kaslev]

On Fri, Feb 22, 2019 at 04:28:32PM +0200, Tzvetomir Stoyanov wrote:
> 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 be6720c..0a6e820 100644
> --- a/lib/trace-cmd/trace-input.c
> +++ b/lib/trace-cmd/trace-input.c
> @@ -1679,18 +1679,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);

Looks good to me with a nit: the following check is not necessary

> +			if (ptr == last_record->data)
> +				break;

since the `while ()` condition above will be already false if this holds. Or am
I missing something here?

Thank you,

-- Slavi

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

[PATCH v4 4/7] trace-cmd: Added implementation of htonll() and ntohll()

[Tzvetomir Stoyanov]

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

[PATCH v4 5/7] trace-cmd: Refactored make_instances() and tracecmd_remove_instances()

[Tzvetomir Stoyanov]

In order to reuse the code which creates / deletes tracing instances,
these two functions are refactotred. A new ones are implemented:
make_instance() and tracecmd_remove_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 ef6319f..c57ed6b 100644
--- a/tracecmd/trace-record.c
+++ b/tracecmd/trace-record.c
@@ -4316,49 +4316,57 @@ static void clear_func_filters(void)
 	}
 }
 
-static void make_instances(void)
+static void make_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 (is_guest(instance))
 			continue;
+		make_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_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 (is_guest(instance) || (instance->flags & BUFFER_FL_KEEP))
 			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_instance(instance);
 	}
 }
 
-- 
2.20.1

[PATCH v4 6/7] trace-cmd: Find and store pids of tasks, which run virtual CPUs of given VM

[Tzvetomir Stoyanov]

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 d7bdb1f..ef6848f 100644
--- a/tracecmd/include/trace-local.h
+++ b/tracecmd/include/trace-local.h
@@ -236,6 +236,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 c57ed6b..59f0197 100644
--- a/tracecmd/trace-record.c
+++ b/tracecmd/trace-record.c
@@ -2752,6 +2752,7 @@ struct guest {
 	char *name;
 	int cid;
 	int pid;
+	int cpu_pid[VCPUS_MAX];
 };
 
 static struct guest *guests;
@@ -2772,9 +2773,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;
@@ -2830,6 +2832,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");
@@ -2875,6 +2920,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

Re: [PATCH v4 6/7] trace-cmd: Find and store pids of tasks, which run virtual CPUs of given VM

[Slavomir Kaslev]

On Fri, Feb 22, 2019 at 04:28:35PM +0200, Tzvetomir Stoyanov wrote:
> 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 d7bdb1f..ef6848f 100644
> --- a/tracecmd/include/trace-local.h
> +++ b/tracecmd/include/trace-local.h
> @@ -236,6 +236,9 @@ void show_instance_file(struct buffer_instance *instance, const char *name);
>  
>  int count_cpus(void);
>  
> +#define VCPUS_MAX	256

Is VCPUS_MAX intended to be used somewhere outside of trace-record.c? If not, I
think we should keep it there locally and not expose it.

> +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 c57ed6b..59f0197 100644
> --- a/tracecmd/trace-record.c
> +++ b/tracecmd/trace-record.c
> @@ -2752,6 +2752,7 @@ struct guest {
>  	char *name;
>  	int cid;
>  	int pid;
> +	int cpu_pid[VCPUS_MAX];
>  };
>  
>  static struct guest *guests;
> @@ -2772,9 +2773,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;
> @@ -2830,6 +2832,49 @@ static void read_qemu_guests(void)
>  		if (!is_qemu)
>  			goto next;
>  

I think the following section should go into separate function since this one is
already getting too long. Then here we can just do:

		read_qemu_guest_vcpus(&guest);

Where read_qemu_guest_vcpus can be something like that:

static void read_qemu_guest_vcpus(struct guest *guest)
{
	struct dirent *entry;
	char path[PATH_MAX];
	size_t buf_len = 0;
	char *buf = NULL;
	int vcpu;
	DIR *dir;
	FILE *f;

	snprintf(path, sizeof(path), "/proc/%d/task", guest->pid);
	dir = opendir(path);
	if (!dir)
		return;

	for (entry = readdir(dir); entry; entry = readdir(dir)) {
		if (!(entry->d_type == DT_DIR && is_digits(entry->d_name)))
			continue;

		snprintf(path, sizeof(path), "/proc/%d/task/%s/comm",
			 guest->pid, entry->d_name);
		f = fopen(path, "r");
		if (!f)
			continue;

		if (getline(&buf, &buf_len, f) < 0)
			goto next;

		if (strncmp(buf, "CPU ", 4) != 0)
			goto next;

		vcpu = atoi(buf + 4);
		if (!(vcpu >= 0 && vcpu < VCPUS_MAX))
			goto next;

		guest->cpu_pid[vcpu] = atoi(entry->d_name);

next:
		fclose(f);
	}

	free(buf);
}

Thank you,

-- Slavi

> +		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");
> @@ -2875,6 +2920,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
> 

Re: [PATCH v4 6/7] trace-cmd: Find and store pids of tasks, which run virtual CPUs of given VM

[Steven Rostedt]

On Fri, 22 Feb 2019 19:07:09 +0200
Slavomir Kaslev <kaslevs@vmware.com> wrote:

> I think the following section should go into separate function since this one is
> already getting too long. Then here we can just do:

Thanks for reviewing these Slavomir.

Tvzetomir, can you update the patch series and send out a new version
with these updates when you get a chance.

Thanks!

-- Steve

[PATCH v4 7/7] trace-cmd [POC]: Implemented timestamps synch algorithm, using vsock events.

[Tzvetomir Stoyanov]

This is a POC patch, implementing an 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 |  13 +
 tracecmd/trace-listen.c        |   3 +
 tracecmd/trace-msg.c           | 477 ++++++++++++++++++++++++++++++++-
 tracecmd/trace-record.c        | 156 ++++++++++-
 5 files changed, 634 insertions(+), 19 deletions(-)

diff --git a/include/trace-cmd/trace-cmd.h b/include/trace-cmd/trace-cmd.h
index 3f0ab4f..5469dee 100644
--- a/include/trace-cmd/trace-cmd.h
+++ b/include/trace-cmd/trace-cmd.h
@@ -346,6 +346,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);
+
 /* --- Plugin handling --- */
 extern struct tep_plugin_option trace_ftrace_options[];
 
diff --git a/tracecmd/include/trace-local.h b/tracecmd/include/trace-local.h
index ef6848f..948cb06 100644
--- a/tracecmd/include/trace-local.h
+++ b/tracecmd/include/trace-local.h
@@ -236,6 +236,19 @@ void show_instance_file(struct buffer_instance *instance, const char *name);
 
 int count_cpus(void);
 
+struct clock_synch_event_descr {
+	char *file;
+	char *set;
+	char *reset;
+};
+struct buffer_instance *clock_synch_enable(char *clock, unsigned int cid,
+					   struct clock_synch_event_descr *events);
+void clock_synch_disable(struct buffer_instance *instance,
+			 struct clock_synch_event_descr *events);
+struct tep_handle *clock_synch_get_tep(struct buffer_instance *instance,
+				       char **systems);
+void get_vsocket_params(int fd, unsigned int *lcid, unsigned int *lport,
+			unsigned int *rcid, unsigned 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 8bd7bad..7103a88 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 065a01e..fddd327 100644
--- a/tracecmd/trace-msg.c
+++ b/tracecmd/trace-msg.c
@@ -18,16 +18,22 @@
 #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"
 #include "trace-msg.h"
 
+typedef __u16 u16;
+typedef __s16 s16;
 typedef __u32 u32;
 typedef __be32 be32;
+typedef __u64 u64;
+typedef __s64 s64;
 
 static inline void dprint(const char *fmt, ...)
 {
@@ -50,6 +56,16 @@ static inline void dprint(const char *fmt, ...)
 
 unsigned int page_size;
 
+/* Try a few times to get an accurate time sync */
+#define TSYNC_TRIES 300
+
+struct clock_synch_event {
+	int			id;
+	int			cpu;
+	int			pid;
+	unsigned long long	ts;
+};
+
 struct tracecmd_msg_opt {
 	be32 size;
 	be32 opt_cmd;
@@ -76,6 +92,15 @@ 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_ts;
+	u16 tlocal_cpu;
+} __attribute__((packed));
+
 struct tracecmd_msg_header {
 	be32	size;
 	be32	cmd;
@@ -83,14 +108,16 @@ 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(NOT_SUPP,	5,	0),					\
-	C(TRACE_REQ,	6,	sizeof(struct tracecmd_msg_trace_req)),	\
-	C(TRACE_RESP,	7,	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(NOT_SUPP,	  5,	0),					\
+	C(TRACE_REQ,	  6,	sizeof(struct tracecmd_msg_trace_req)),	\
+	C(TRACE_RESP,	  7,	sizeof(struct tracecmd_msg_trace_resp)),\
+	C(TIME_SYNC_INIT, 8,	sizeof(struct tracecmd_msg_time_sync_init)),\
+	C(TIME_SYNC,	  9,	sizeof(struct tracecmd_msg_time_sync)),
 
 #undef C
 #define C(a,b,c)	MSG_##a = b
@@ -120,10 +147,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;
@@ -859,6 +888,430 @@ 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-1].pid || events[j-1].pid == recorded[i].pid)) {
+			events[j-1].cpu = recorded[i].cpu;
+			events[j-1].ts = recorded[i].ts;
+		}
+		i++;
+	}
+	return j;
+}
+
+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();
+#ifdef TSYNC_RBUFFER_DEBUG
+	file = get_instance_file(instance, "trace");
+	if (!file)
+		return ts;
+	{
+		char *buf = NULL;
+		FILE *fp;
+		size_t n;
+		int r;
+
+		printf("Events:\n\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 /* TSYNC_RBUFFER_DEBUG */
+	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]);
+		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);
+#ifdef TSYNC_RBUFFER_DEBUG
+	len = 0;
+	while (events[len].id) {
+		printf("Found %d @ cpu %d: %lld\n\r",
+			events[len].id,  events[len].cpu, events[len].ts);
+		len++;
+	}
+#endif
+	free(events_array);
+	free(file);
+	free(page);
+	closedir(dir);
+
+ out:
+	tracecmd_put_tracing_file(path);
+	return r;
+}
+
+int tracecmd_msg_rcv_time_sync(struct tracecmd_msg_handle *msg_handle)
+{
+	unsigned int lcid, lport, rcid, rport;
+	struct clock_synch_event events[3];
+	struct buffer_instance *vinst;
+	char vsock_rx_filter[255];
+	struct tep_event *event;
+	struct tracecmd_msg msg;
+	struct tep_handle *tep;
+	int *cpu_pid = NULL;
+	int ret, cpu;
+	char *clock;
+	char *systems[] = {"vsock", "kvm", NULL};
+	struct clock_synch_event_descr events_descr[] = {
+		{"events/kvm/kvm_exit/enable", "1", "0"},
+		{"events/vsock/virtio_transport_recv_pkt/enable", "1", "0"},
+		{"events/vsock/virtio_transport_recv_pkt/filter", vsock_rx_filter, "\0"},
+		{NULL, NULL, NULL}
+	};
+
+	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)*3);
+
+	rcid = 0;
+	get_vsocket_params(msg_handle->fd, &lcid, &lport, &rcid, &rport);
+	if (rcid)
+		cpu_pid = get_guest_vcpu_pids(rcid);
+	snprintf(vsock_rx_filter, 255,
+		"src_cid==%u && src_port==%u && dst_cid==%u && dst_port==%u && len!=0",
+		rcid, rport, lcid, lport);
+
+	vinst = clock_synch_enable(clock, rcid, events_descr);
+	tep = clock_synch_get_tep(vinst, systems);
+	event = tep_find_event_by_name(tep, "kvm", "kvm_exit");
+	if (event)
+		events[0].id = event->id;
+	event = tep_find_event_by_name(tep, "vsock", "virtio_transport_recv_pkt");
+	if (event)
+		events[1].id = event->id;
+	tracecmd_msg_init(MSG_TIME_SYNC_INIT, &msg);
+	tracecmd_msg_send(msg_handle->fd, &msg);
+
+	do {
+		events[0].ts = 0;	/* kvm exit ts */
+		events[0].pid = 0;
+		events[1].ts = 0;	/* vsock receive ts */
+		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;
+		/* Get kvm_exit events related to the corresponding VCPU */
+		cpu = ntohs(msg.time_sync.tlocal_cpu);
+		if (cpu_pid && cpu < VCPUS_MAX)
+			events[0].pid = cpu_pid[cpu];
+		ret = clock_synch_find_events(tep, vinst, events);
+		tracecmd_msg_init(MSG_TIME_SYNC, &msg);
+		msg.time_sync.tlocal_ts = htonll(events[0].ts);
+		tracecmd_msg_send(msg_handle->fd, &msg);
+	} while (true);
+	clock_synch_disable(vinst, events_descr);
+	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[3];
+	struct tracecmd_msg msg_resp;
+	struct tracecmd_msg msg_req;
+	int sync_loop = TSYNC_TRIES;
+	long long min = 0, max = 0;
+	long long  offset_av = 0;
+	struct tep_event *event;
+	struct tep_handle *tep;
+	int k = 0, n, ret = 0;
+	long long tresch = 0;
+	long long offset = 0;
+	long long m_t1 = 0;
+	long long s_t2 = 0;
+	long long *offsets;
+	int probes = 0;
+	char *clock;
+	char vsock_tx_filter[255];
+	unsigned int lcid, lport, rcid, rport;
+	char *systems[] = {"vsock", "ftrace", NULL};
+	struct clock_synch_event_descr events_descr[] = {
+		{"set_ftrace_filter", "vp_notify", "\0"},
+		{"current_tracer", "function", "nop"},
+		{"events/vsock/virtio_transport_alloc_pkt/enable", "1", "0"},
+		{"events/vsock/virtio_transport_alloc_pkt/filter", vsock_tx_filter, "\0"},
+		{NULL, NULL, NULL}
+	};
+#ifdef TSYNC_DEBUG
+/* Write all ts in a file, used to analyze the raw data */
+	struct timespec tsStart, tsEnd;
+	int zm = 0, zs = 0;
+	long long duration;
+	char buff[256];
+	int iFd;
+#endif
+
+	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);
+	if (!offsets)
+		return 0;
+
+	strncpy(msg_req.time_sync_init.clock, clock, 32);
+	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);
+		return 0;
+	}
+	get_vsocket_params(msg_handle->fd, &lcid, &lport, &rcid, &rport);
+	snprintf(vsock_tx_filter, 255,
+		"src_cid==%u && src_port==%u && dst_cid==%u && dst_port==%u && len!=0",
+		lcid, lport, rcid, rport);
+
+	memset(events_s, 0, sizeof(struct clock_synch_event)*3);
+	vinst = clock_synch_enable(clock_str, rcid, events_descr);
+	tep = clock_synch_get_tep(vinst, systems);
+	event = tep_find_event_by_name(tep, "vsock", "virtio_transport_alloc_pkt");
+	if (event)
+		events_s[0].id = event->id;
+	event = tep_find_event_by_name(tep, "ftrace", "function");
+	if (event)
+		events_s[1].id = event->id;
+
+	*toffset = 0;
+#ifdef TSYNC_DEBUG
+	sprintf(buff, "s-%s.txt", clock);
+	iFd = open(buff, O_CREAT|O_WRONLY|O_TRUNC, 0644);
+	clock_gettime(CLOCK_MONOTONIC, &tsStart);
+#endif
+	do {
+		memset(&msg_resp, 0, sizeof(msg_resp));
+		events_s[0].ts = 0;	/* vsock send ts */
+		events_s[0].cpu = 0;
+		events_s[1].ts = 0;	/* vp_notify ts */
+		events_s[1].cpu = 0;
+		tracecmd_msg_init(MSG_TIME_SYNC, &msg_req);
+		tracecmd_msg_send(msg_handle->fd, &msg_req);
+		/* Get the ts and CPU of the sent event */
+		clock_synch_find_events(tep, vinst, events_s);
+		tracecmd_msg_init(MSG_TIME_SYNC, &msg_req);
+		msg_req.time_sync.tlocal_ts = htonll(events_s[0].ts);
+		msg_req.time_sync.tlocal_cpu = htons(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;
+		m_t1 = events_s[1].ts;
+		s_t2 = htonll(msg_resp.time_sync.tlocal_ts); /* Client kvm exit ts */
+#ifdef TSYNC_DEBUG
+		if (!s_t2)
+			zs++;
+		if (!m_t1)
+			zm++;
+#endif
+		if (!s_t2 || !m_t1)
+			continue;
+		offsets[probes] = s_t2 - m_t1;
+		offset_av += offsets[probes];
+		if (!min || min > llabs(offsets[probes]))
+			min = llabs(offsets[probes]);
+		if (!max || max < llabs(offsets[probes]))
+			max = llabs(offsets[probes]);
+		probes++;
+#ifdef TSYNC_DEBUG
+		sprintf(buff, "%lld %lld\n", m_t1, s_t2);
+		write(iFd, buff, strlen(buff));
+#endif
+	} while (--sync_loop);
+
+#ifdef TSYNC_DEBUG
+	clock_gettime(CLOCK_MONOTONIC, &tsEnd);
+	close(iFd);
+#endif
+	clock_synch_disable(vinst, events_descr);
+	if (probes)
+		offset_av /= (long long)probes;
+	tresch = (long long)((max - min)/10);
+	for (n = 0; n < TSYNC_TRIES; n++) {
+		/* filter the offsets with deviation up to 10% */
+		if (offsets[n] &&
+		    llabs(offsets[n] - offset_av) < tresch) {
+			offset += offsets[n];
+			k++;
+		}
+	}
+	if (k)
+		offset /= (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);
+
+	*toffset = offset;
+
+#ifdef TSYNC_DEBUG
+	duration = tsEnd.tv_sec * 1000000000LL;
+	duration += tsEnd.tv_nsec;
+	duration -= (tsStart.tv_sec * 1000000000LL);
+	duration -= tsStart.tv_nsec;
+
+	printf("\n selected: %lld (in %lld ns), used %s clock, %d probes\n\r",
+		*toffset, duration, clock, probes);
+	printf("\t good probes: %d / %d, threshold %lld, Zm %d, Zs %d\n\r",
+			k, TSYNC_TRIES, tresch, zm, zs);
+#endif
+	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 59f0197..21be253 100644
--- a/tracecmd/trace-record.c
+++ b/tracecmd/trace-record.c
@@ -224,6 +224,12 @@ struct common_record_context {
 	int run_command;
 };
 
+enum {
+	DATA_FL_NONE		= 0,
+	DATA_FL_DATE		= 1,
+	DATA_FL_OFFSET		= 2,
+};
+
 static void add_reset_file(const char *file, const char *val, int prio)
 {
 	struct reset_file *reset;
@@ -3215,6 +3221,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);
+	/* 21 digits + \0 */
+	ctx->date2ts = malloc(22);
+	if (ctx->date2ts) {
+		snprintf(ctx->date2ts, 22, "%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;
@@ -3406,6 +3445,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)
@@ -3430,10 +3471,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);
@@ -3620,12 +3664,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;
@@ -5895,3 +5933,107 @@ int trace_record_agent(struct tracecmd_msg_handle *msg_handle,
 	free(argv_plus);
 	return 0;
 }
+
+void get_vsocket_params(int fd, unsigned int *lcid, unsigned int *lport,
+			unsigned int *rcid, unsigned 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(struct buffer_instance *instance,
+				   struct clock_synch_event_descr *events,
+				   bool enable)
+{
+	int i = 0;
+
+	if (!enable)
+		write_tracing_on(instance, 0);
+
+	while (events[i].file) {
+		if (enable && events[i].set)
+			write_instance_file(instance, events[i].file,
+					    events[i].set, NULL);
+		if (!enable && events[i].reset)
+			write_instance_file(instance, events[i].file,
+					    events[i].reset, NULL);
+		i++;
+	}
+
+	if (enable)
+		write_tracing_on(instance, 1);
+}
+
+static void vsock_trace_reset(struct buffer_instance *vinst)
+{
+	write_instance_file(vinst, "trace", "\0", NULL);
+}
+
+struct tep_handle *clock_synch_get_tep(struct buffer_instance *instance, char **systems)
+{
+	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(char *clock, unsigned int cid,
+					   struct clock_synch_event_descr *events)
+{
+	struct buffer_instance *vinst;
+	char inst_name[256];
+
+	snprintf(inst_name, 256, "clock_synch-%d", cid);
+
+	vinst = create_instance(strdup(inst_name));
+	init_instance(vinst);
+	vinst->cpu_count = local_cpu_count;
+	make_instance(vinst);
+	vsock_trace_reset(vinst);
+	if (clock)
+		vinst->clock = strdup(clock);
+	set_clock(vinst);
+	set_clock_synch_events(vinst, events, true);
+	return vinst;
+}
+
+void clock_synch_disable(struct buffer_instance *instance,
+			 struct clock_synch_event_descr *events)
+{
+	set_clock_synch_events(instance, events, false);
+	tracecmd_remove_instance(instance);
+	/* todo: clean up the instance */
+}
-- 
2.20.1