Re: [PATCH v5 9/9] trace-cmd [POC]: Implemented timestamps synch PTP-like algorithm, using vsock events.

[Slavomir Kaslev <kaslevs@vmware.com>]

Some minor comments inline since we discussed the more major issues with patches 8 and 9 offline already.

On Fri, Mar 08, 2019 at 03:44:23PM +0200, Tzvetomir Stoyanov wrote:
> 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.

This patch needs a new commit message since it's not doing anything resembling PTP anymore.

> 
> Signed-off-by: Tzvetomir Stoyanov <tstoyanov@vmware.com>
> ---
>  include/trace-cmd/trace-cmd.h  |   9 +
>  tracecmd/Makefile              |   1 +
>  tracecmd/include/trace-local.h |  50 +++
>  tracecmd/trace-msg.c           | 284 ++++++++++++++-
>  tracecmd/trace-record.c        |  72 +++-
>  tracecmd/trace-timesync.c      | 622 +++++++++++++++++++++++++++++++++
>  6 files changed, 1024 insertions(+), 14 deletions(-)
>  create mode 100644 tracecmd/trace-timesync.c
> 
> diff --git a/include/trace-cmd/trace-cmd.h b/include/trace-cmd/trace-cmd.h
> index cea6bb9..dbfbe14 100644
> --- a/include/trace-cmd/trace-cmd.h
> +++ b/include/trace-cmd/trace-cmd.h
> @@ -352,6 +352,15 @@ int tracecmd_msg_recv_trace_resp(struct tracecmd_msg_handle *msg_handle,
>  				 int *nr_cpus, int *page_size,
>  				 unsigned int **ports, bool *use_fifos);
>  
> +struct tracecmd_clock_sync;
> +
> +int tracecmd_msg_rcv_time_sync(struct tracecmd_msg_handle *msg_handle,
> +			       struct tracecmd_clock_sync *clock_sync,
> +			       long long *toffset, long long *ts_offset);
> +int tracecmd_msg_snd_time_sync(struct tracecmd_msg_handle *msg_handle,
> +			       struct tracecmd_clock_sync *clock_sync,
> +			       long long *toffset, long long *ts_offset);
> +
>  /* --- Plugin handling --- */
>  extern struct tep_plugin_option trace_ftrace_options[];
>  
> diff --git a/tracecmd/Makefile b/tracecmd/Makefile
> index d3e3080..8a73bf7 100644
> --- a/tracecmd/Makefile
> +++ b/tracecmd/Makefile
> @@ -32,6 +32,7 @@ TRACE_CMD_OBJS += trace-list.o
>  TRACE_CMD_OBJS += trace-output.o
>  TRACE_CMD_OBJS += trace-usage.o
>  TRACE_CMD_OBJS += trace-msg.o
> +TRACE_CMD_OBJS += trace-timesync.o
>  
>  ifeq ($(VSOCK_DEFINED), 1)
>  TRACE_CMD_OBJS += trace-agent.o
> diff --git a/tracecmd/include/trace-local.h b/tracecmd/include/trace-local.h
> index 62f5e47..ba0b06d 100644
> --- a/tracecmd/include/trace-local.h
> +++ b/tracecmd/include/trace-local.h
> @@ -214,6 +214,11 @@ struct buffer_instance {
>  	int			port;
>  	int			*fds;
>  	bool			use_fifos;
> +
> +	struct tracecmd_clock_sync *clock_sync;
> +	int			time_sync_count;
> +	long long		*time_sync_ts;
> +	long long		*time_sync_ofssets;
>  };
>  
>  extern struct buffer_instance top_instance;
> @@ -227,6 +232,37 @@ extern struct buffer_instance *first_instance;
>  #define is_agent(instance)	((instance)->flags & BUFFER_FL_AGENT)
>  #define is_guest(instance)	((instance)->flags & BUFFER_FL_GUEST)
>  
> +struct tracecmd_ftrace_param {
> +	char	*file;
> +	char	*set;
> +	char	*reset;
> +};
> +
> +struct tracecmd_event_hit {
> +	int			id;
> +	int			cpu;
> +	int			pid;
> +	unsigned long long	ts;
> +};
> +
> +enum clock_sync_conext {
> +	CLOCK_KVM_X86_VSOCK_HOST,
> +	CLOCK_KVM_X86_VSOCK_GUEST,
> +	CLOCK_CONTEXT_MAX,
> +};

I don't think those should be exposed since they are not generic and are not used outside of time synchronization code.

> +
> +struct tracecmd_clock_sync {
> +	enum clock_sync_conext		clock_context_id;
> +	struct tracecmd_ftrace_param	*ftrace_params;
> +	struct tracecmd_event_hit	*events;
> +	struct tep_handle		*tep;
> +	struct buffer_instance		*vinst;
> +	unsigned int			local_cid;
> +	unsigned int			local_port;
> +	unsigned int			remote_cid;
> +	unsigned int			remote_port;
> +};
> +
>  struct buffer_instance *create_instance(const char *name);
>  void add_instance(struct buffer_instance *instance, int cpu_count);
>  char *get_instance_file(struct buffer_instance *instance, const char *file);
> @@ -235,6 +271,20 @@ void update_first_instance(struct buffer_instance *instance, int topt);
>  void show_instance_file(struct buffer_instance *instance, const char *name);
>  
>  int count_cpus(void);
> +
> +struct tracecmd_clock_sync*
> +tracecmd_clock_context_init(struct tracecmd_msg_handle *msg_handle,
> +			    const char *clock_str,
> +			    enum clock_sync_conext id);
> +void tracecmd_clock_context_free(struct tracecmd_clock_sync *clock_context);
> +int tracecmd_clock_find_event(struct tracecmd_clock_sync *clock, int cpu,
> +			      struct tracecmd_event_hit *event);
> +
> +void tracecmd_clock_synch_enable(struct tracecmd_clock_sync *clock_context);
> +void tracecmd_clock_synch_disable(struct tracecmd_clock_sync *clock_context);
> +
> +void sync_time_with_host_v3(struct buffer_instance *instance);
> +void sync_time_with_guest_v3(struct buffer_instance *instance);
>  void write_tracing_on(struct buffer_instance *instance, int on);
>  char *get_instance_dir(struct buffer_instance *instance);
>  int write_instance_file(struct buffer_instance *instance,
> diff --git a/tracecmd/trace-msg.c b/tracecmd/trace-msg.c
> index 065a01e..0f1f071 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>

This last #include is not necessary.

>  
>  #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,9 @@ 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 tracecmd_msg_opt {
>  	be32 size;
>  	be32 opt_cmd;
> @@ -76,6 +85,16 @@ struct tracecmd_msg_trace_resp {
>  	be32 page_size;
>  } __attribute__((packed));
>  
> +struct tracecmd_msg_tsync_stop {
> +	long long offset;
> +	long long ts_offset;
> +} __attribute__((packed));
> +
> +struct tracecmd_msg_tsync_pkt {
> +	u64 tlocal;
> +} __attribute__((packed));
> +
> +
>  struct tracecmd_msg_header {
>  	be32	size;
>  	be32	cmd;
> @@ -83,14 +102,18 @@ 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(TSYNC_START,	  8,	0),					\
> +	C(TSYNC_STOP,	  9,	sizeof(struct tracecmd_msg_tsync_stop)),\
> +	C(TSYNC_REQ,	  10,	sizeof(struct tracecmd_msg_tsync_pkt)),	\
> +	C(TSYNC_RESP,	  11,	sizeof(struct tracecmd_msg_tsync_pkt)),
>  
>  #undef C
>  #define C(a,b,c)	MSG_##a = b
> @@ -120,10 +143,13 @@ 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_tsync_stop		ts_stop;
> +		struct tracecmd_msg_tsync_pkt		ts_req;
> +		struct tracecmd_msg_tsync_pkt		ts_resp;
>  	};
>  	union {
>  		struct tracecmd_msg_opt		*opt;
> @@ -859,6 +885,240 @@ out:
>  	return ret;
>  }
>  
> +int tracecmd_msg_rcv_time_sync(struct tracecmd_msg_handle *msg_handle,
> +			       struct tracecmd_clock_sync *clock_context,
> +			       long long *toffset, long long *ts_offset)
> +{
> +	struct tracecmd_event_hit event;
> +	struct tracecmd_msg msg;
> +	int cpu_pid, ret;
> +
> +	if (clock_context == NULL || msg_handle == NULL)
> +		return 0;
> +
> +	if (toffset)
> +		*toffset = 0;
> +
> +	ret = tracecmd_msg_recv(msg_handle->fd, &msg);
> +	if (ret < 0 || ntohl(msg.hdr.cmd) == MSG_TSYNC_STOP)
> +		return 0;
> +	if (ntohl(msg.hdr.cmd) != MSG_TSYNC_START) {
> +		tracecmd_msg_init(MSG_NOT_SUPP, &msg);
> +		tracecmd_msg_send(msg_handle->fd, &msg);

Can you switch this below to the helper function?

	tracecmd_msg_send_notsupp(msg_handle);

> +		return 0;
> +	}
> +
> +	tracecmd_msg_init(MSG_TSYNC_START, &msg);
> +	tracecmd_msg_send(msg_handle->fd, &msg);
> +	tracecmd_clock_synch_enable(clock_context);
> +
> +	do {
> +		memset(&event, 0, sizeof(event));
> +		ret = tracecmd_msg_recv(msg_handle->fd, &msg);
> +		if (ret < 0 || ntohl(msg.hdr.cmd) == MSG_TSYNC_STOP)
> +			break;
> +		if (ntohl(msg.hdr.cmd) != MSG_TSYNC_REQ) {
> +			tracecmd_msg_init(MSG_NOT_SUPP, &msg);
> +			tracecmd_msg_send(msg_handle->fd, &msg);
> +			break;
> +		}
> +		ret = tracecmd_msg_recv(msg_handle->fd, &msg);
> +		if (ret < 0 || ntohl(msg.hdr.cmd) == MSG_TSYNC_STOP)
> +			break;
> +		if (ntohl(msg.hdr.cmd) != MSG_TSYNC_REQ) {
> +			tracecmd_msg_init(MSG_NOT_SUPP, &msg);
> +			tracecmd_msg_send(msg_handle->fd, &msg);
> +			break;
> +		}
> +		/* Get kvm_exit events related to the corresponding VCPU */
> +		cpu_pid = get_guest_vcpu_pid(clock_context->remote_cid,
> +					     ntohll(msg.ts_req.tlocal));
> +		tracecmd_clock_find_event(clock_context, cpu_pid, &event);
> +		tracecmd_msg_init(MSG_TSYNC_RESP, &msg);
> +		msg.ts_resp.tlocal = htonll(event.ts);
> +		tracecmd_msg_send(msg_handle->fd, &msg);
> +	} while (true);
> +	tracecmd_clock_synch_disable(clock_context);
> +
> +	if (ret >= 0 && ntohl(msg.hdr.cmd) == MSG_TSYNC_STOP) {
> +		if (toffset)
> +			*toffset = ntohll(msg.ts_stop.offset);
> +		if (ts_offset)
> +			*ts_offset = ntohll(msg.ts_stop.ts_offset);
> +	}
> +
> +	msg_free(&msg);
> +	return 0;
> +}
> +
> +//#define TSYNC_DEBUG
> +int tracecmd_msg_snd_time_sync(struct tracecmd_msg_handle *msg_handle,
> +			       struct tracecmd_clock_sync *clock_context,
> +			       long long *toffset, long long *ts_offset)
> +{
> +	struct tracecmd_event_hit event;
> +	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;
> +	long long ts_local = 0;
> +	int k = 0, n, ret = 0;
> +	long long tresch = 0;
> +	long long offset = 0;
> +	long long *ts_locals;
> +	long long *offsets;
> +	long long m_t1 = 0;
> +	long long s_t2 = 0;
> +	int probes = 0;
> +#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
> +
> +	if (clock_context == NULL || msg_handle == NULL)
> +		return 0;
> +
> +	if (toffset == NULL) {
> +		/* No time sync needed, inform the client */
> +		msg_req.ts_stop.offset = 0;
> +		msg_req.ts_stop.ts_offset = 0;
> +		tracecmd_msg_init(MSG_TSYNC_STOP, &msg_req);
> +		tracecmd_msg_send(msg_handle->fd, &msg_req);
> +		return 0;
> +	}
> +
> +	*toffset = 0;
> +	offsets = calloc(sizeof(long long), TSYNC_TRIES);
> +	ts_locals = calloc(sizeof(long long), TSYNC_TRIES);
> +	if (!offsets || !ts_locals) {
> +		free(offsets);
> +		free(ts_locals);
> +		return 0;
> +	}
> +
> +	tracecmd_msg_init(MSG_TSYNC_START, &msg_req);
> +	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_TSYNC_START) {
> +		free(offsets);
> +		free(ts_locals);
> +		return 0;
> +	}
> +
> +#ifdef TSYNC_DEBUG
> +	sprintf(buff, "s-cid%d.txt", clock_context->remote_cid);
> +	iFd = open(buff, O_CREAT|O_WRONLY|O_TRUNC, 0644);
> +	clock_gettime(CLOCK_MONOTONIC, &tsStart);
> +#endif
> +	tracecmd_clock_synch_enable(clock_context);
> +	do {
> +		memset(&msg_resp, 0, sizeof(msg_resp));
> +		memset(&event, 0, sizeof(event));
> +		tracecmd_msg_init(MSG_TSYNC_REQ, &msg_req);
> +		tracecmd_msg_send(msg_handle->fd, &msg_req);
> +		/* Get the ts and CPU of the sent event */
> +		tracecmd_clock_find_event(clock_context, -1, &event);
> +
> +		tracecmd_msg_init(MSG_TSYNC_REQ, &msg_req);
> +		msg_req.ts_req.tlocal = event.cpu;
> +		msg_req.ts_req.tlocal = htonll(msg_req.ts_req.tlocal);
> +		tracecmd_msg_send(msg_handle->fd, &msg_req);
> +		ret = tracecmd_msg_recv(msg_handle->fd, &msg_resp);
> +		if (ret < 0)
> +			break;
> +		if (ntohl(msg_resp.hdr.cmd) != MSG_TSYNC_RESP) {
> +			tracecmd_msg_init(MSG_NOT_SUPP, &msg_req);
> +			tracecmd_msg_send(msg_handle->fd, &msg_req);
> +			break;
> +		}
> +		m_t1 = event.ts;
> +		s_t2 = htonll(msg_resp.ts_resp.tlocal); /* Client rcv 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;
> +		ts_locals[probes] = 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
> +	tracecmd_clock_synch_disable(clock_context);
> +

Can you split the part that processes the events from the one that collects them and make this function shorter and simpler?

> +	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;
> +	tresch = 0;
> +	for (n = 0; n < TSYNC_TRIES; n++) {
> +		if (offsets[n] &&
> +		    (!tresch || tresch > llabs(offset-offsets[n]))) {
> +			tresch = llabs(offset-offsets[n]);
> +			ts_local = ts_locals[n];
> +		}
> +	}
> +
> +	tracecmd_msg_init(MSG_TSYNC_STOP, &msg_req);
> +	msg_req.ts_stop.offset = htonll(offset);
> +	msg_req.ts_stop.ts_offset = htonll(ts_local);
> +	tracecmd_msg_send(msg_handle->fd, &msg_req);
> +
> +	msg_free(&msg_req);
> +	msg_free(&msg_resp);
> +	free(offsets);
> +	free(ts_locals);
> +
> +	if (toffset)
> +		*toffset = offset;
> +	if (ts_offset)
> +		*ts_offset = ts_local;
> +
> +#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",
> +		offset, duration,
> +		clock_context->vinst->clock?clock_context->vinst->clock:"default",
> +		probes);
> +	printf("\t good probes: %d / %d, threshold %lld ns, 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 d9e9c69..f07eb4d 100644
> --- a/tracecmd/trace-record.c
> +++ b/tracecmd/trace-record.c
> @@ -210,6 +210,8 @@ struct common_record_context {
>  	char *date2ts;
>  	char *max_graph_depth;
>  	int data_flags;
> +	int time_shift_count;
> +	struct tracecmd_option *time_shift_option;
>  
>  	int record_all;
>  	int total_disable;
> @@ -649,11 +651,20 @@ static void tell_guests_to_stop(void)
>  	for_all_instances(instance) {
>  		if (is_guest(instance)) {
>  			tracecmd_msg_send_close_msg(instance->msg_handle);
> -			tracecmd_msg_handle_close(instance->msg_handle);
>  		}
>  	}
>  }
>  
> +static void close_guests_handle(void)
> +{
> +	struct buffer_instance *instance;
> +
> +	for_all_instances(instance) {
> +		if (is_guest(instance))
> +			tracecmd_msg_handle_close(instance->msg_handle);
> +	}
> +}
> +
>  static void stop_threads(enum trace_type type)
>  {
>  	struct timeval tv = { 0, 0 };
> @@ -3417,6 +3428,8 @@ static void connect_to_agent(struct buffer_instance *instance)
>  
>  	/* the msg_handle now points to the guest fd */
>  	instance->msg_handle = msg_handle;
> +
> +	sync_time_with_guest_v3(instance);
>  }
>  
>  static void setup_guest(struct buffer_instance *instance)
> @@ -3441,10 +3454,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_host_v3(instance);
> +
>  	network_handle = tracecmd_create_init_fd_msg(instance->msg_handle,
>  						     listed_events);
>  	add_options(network_handle, ctx);
> @@ -5619,6 +5635,42 @@ static bool has_local_instances(void)
>  	return false;
>  }
>  
> +//#define TSYNC_DEBUG
> +static void write_guest_time_shift(struct buffer_instance *instance)
> +{
> +	struct tracecmd_output *handle;
> +	struct iovec vector[3];
> +	char *file;
> +	int fd;
> +
> +	if (!instance->time_sync_count)
> +		return;
> +
> +	file = get_guest_file(output_file, instance->name);
> +	fd = open(file, O_RDWR);
> +	if (fd < 0)
> +		die("error opening %s", file);
> +	put_temp_file(file);
> +	handle = tracecmd_get_output_handle_fd(fd);
> +	vector[0].iov_len = sizeof(instance->time_sync_count);
> +	vector[0].iov_base = &instance->time_sync_count;
> +	vector[1].iov_len = sizeof(long long) * instance->time_sync_count;
> +	vector[1].iov_base = instance->time_sync_ts;
> +	vector[2].iov_len = sizeof(long long) * instance->time_sync_count;
> +	vector[2].iov_base = instance->time_sync_ofssets;
> +	tracecmd_add_option_v(handle, TRACECMD_OPTION_TIME_SHIFT, vector, 3);
> +	tracecmd_append_options(handle);
> +	tracecmd_output_close(handle);
> +#ifdef TSYNC_DEBUG
> +	if (instance->time_sync_count > 1)
> +		printf("\n\rDetected %lld ns ts offset drift in %lld ns for guest %s\n\r",
> +			instance->time_sync_ofssets[instance->time_sync_count-1] -
> +			instance->time_sync_ofssets[0],
> +			instance->time_sync_ts[instance->time_sync_count-1]-
> +			instance->time_sync_ts[0], instance->name);
> +#endif
> +}
> +
>  /*
>   * This function contains common code for the following commands:
>   * record, start, stream, profile.
> @@ -5738,6 +5790,22 @@ static void record_trace(int argc, char **argv,
>  	if (!latency)
>  		wait_threads();
>  
> +	if (ctx->instance && is_agent(ctx->instance)) {
> +		sync_time_with_host_v3(ctx->instance);
> +		tracecmd_clock_context_free(ctx->instance->clock_sync);
> +		ctx->instance->clock_sync = NULL;
> +	} else {
> +		for_all_instances(instance) {
> +			if (is_guest(instance)) {
> +				sync_time_with_guest_v3(instance);
> +				write_guest_time_shift(instance);
> +				tracecmd_clock_context_free(instance->clock_sync);
> +				instance->clock_sync = NULL;
> +			}
> +		}
> +	}
> +	close_guests_handle();
> +
>  	if (IS_RECORD(ctx)) {
>  		record_data(ctx);
>  		delete_thread_data();
> diff --git a/tracecmd/trace-timesync.c b/tracecmd/trace-timesync.c
> new file mode 100644
> index 0000000..f8366ed
> --- /dev/null
> +++ b/tracecmd/trace-timesync.c
> @@ -0,0 +1,622 @@
> +// SPDX-License-Identifier: GPL-2.0
> +/*
> + * Copyright (C) 2019, VMware, Tzvetomir Stoyanov <tstoyanov@vmware.com>
> + *
> + */
> +
> +#include <fcntl.h>
> +#include <stdlib.h>
> +#include <unistd.h>
> +#include <arpa/inet.h>
> +#include <linux/vm_sockets.h>
> +#include "trace-local.h"
> +
> +static int clock_sync_x86_host_init(struct tracecmd_clock_sync *clock_context);
> +static int clock_sync_x86_host_free(struct tracecmd_clock_sync *clock_context);
> +static int clock_sync_x86_host_find_events(struct tracecmd_clock_sync *clock,
> +				    int cpu, struct tracecmd_event_hit *event);
> +static int clock_sync_x86_guest_init(struct tracecmd_clock_sync *clock_context);
> +static int clock_sync_x86_guest_free(struct tracecmd_clock_sync *clock_context);
> +static int clock_sync_x86_guest_find_events(struct tracecmd_clock_sync *clock,
> +					    int pid,
> +					    struct tracecmd_event_hit *event);
> +
> +struct tracecmd_event_descr {
> +	char			*system;
> +	char			*name;
> +};
> +
> +struct {
> +	char *systems[3];
> +	struct tracecmd_ftrace_param ftrace_params[5];
> +	struct tracecmd_event_descr events[3];
> +	int (*clock_sync_init)(struct tracecmd_clock_sync *clock_context);
> +	int (*clock_sync_free)(struct tracecmd_clock_sync *clock_context);
> +	int (*clock_sync_find_events)(struct tracecmd_clock_sync *clock_context,
> +				      int pid,
> +				      struct tracecmd_event_hit *event);
> +} static clock_sync[CLOCK_CONTEXT_MAX] = {
> +	{ /* CLOCK_KVM_X86_VSOCK_HOST */
> +	  .systems = {"vsock", "ftrace", NULL},
> +	  .ftrace_params = {
> +	  {"set_ftrace_filter", "vmx_read_l1_tsc_offset\nsvm_read_l1_tsc_offset", "\0"},
> +	  {"current_tracer", "function", "nop"},
> +	  {"events/vsock/virtio_transport_recv_pkt/enable", "1", "0"},
> +	  {"events/vsock/virtio_transport_recv_pkt/filter", NULL, "\0"},
> +	  {NULL, NULL, NULL} },
> +	  .events = {
> +	  {.system = "ftrace", .name = "function"},
> +	  {.system = "vsock", .name = "virtio_transport_recv_pkt"},
> +	  {.system = NULL, .name = NULL} },
> +	 clock_sync_x86_host_init,
> +	 clock_sync_x86_host_free,
> +	 clock_sync_x86_host_find_events,
> +	},
> +
> +	{ /* CLOCK_KVM_X86_VSOCK_GUEST */
> +	 .systems = { "vsock", "ftrace", NULL},
> +	 .ftrace_params = {
> +	  {"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", NULL, "\0"},
> +	  {NULL, NULL, NULL},
> +	  },
> +	  .events = {
> +	  {.system = "vsock", .name = "virtio_transport_alloc_pkt"},
> +	  {.system = "ftrace", .name = "function"},
> +	  {.system = NULL, .name = NULL}
> +	 },
> +	  clock_sync_x86_guest_init,
> +	  clock_sync_x86_guest_free,
> +	  clock_sync_x86_guest_find_events,
> +	}
> +};
> +
> +static int clock_sync_x86_host_init(struct tracecmd_clock_sync *clock_context)
> +{
> +	char vsock_filter[255];
> +
> +	snprintf(vsock_filter, 255,
> +		"src_cid==%u && src_port==%u && dst_cid==%u && dst_port==%u && len!=0",
> +		clock_context->remote_cid, clock_context->remote_port,
> +		clock_context->local_cid, clock_context->local_port);
> +
> +	clock_context->ftrace_params[3].set = strdup(vsock_filter);
> +	return 1;
> +}
> +
> +static int clock_sync_x86_host_free(struct tracecmd_clock_sync *clock_context)
> +{
> +	free(clock_context->ftrace_params[3].set);
> +	clock_context->ftrace_params[3].set = NULL;
> +	return 1;
> +}
> +
> +static int clock_sync_x86_guest_init(struct tracecmd_clock_sync *clock_context)
> +{
> +	char vsock_filter[255];
> +
> +	snprintf(vsock_filter, 255,
> +		"src_cid==%u && src_port==%u && dst_cid==%u && dst_port==%u && len!=0",
> +		clock_context->local_cid, clock_context->local_port,
> +		clock_context->remote_cid, clock_context->remote_port);
> +
> +	clock_context->ftrace_params[3].set = strdup(vsock_filter);
> +	return 1;
> +}
> +
> +static int clock_sync_x86_guest_free(struct tracecmd_clock_sync *clock_context)
> +{
> +	free(clock_context->ftrace_params[3].set);
> +	clock_context->ftrace_params[3].set = NULL;
> +	return 1;
> +}
> +
> +#define EVENTS_CHUNK	10
> +static int
> +get_events_in_page(struct tep_handle *tep, void *page,
> +		    int size, int cpu, struct tracecmd_event_hit **events,
> +		    int *events_count, int *events_size)
> +{
> +	struct tracecmd_event_hit *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 tracecmd_event_hit));
> +		*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 tracecmd_event_hit));
> +				if (events_array) {
> +					*events = events_array;
> +					(*events_size) += EVENTS_CHUNK;
> +				}

Reallocating in chunks only reduces the number of realloc() calls by constant. If this is performance critical, let's do exponential buffer growth so that we call realloc() only log(#events) times. Otherwise, let's just not bother and call realloc() each time which is also (empirically) linear but with higher constant factor.

> +			}
> +
> +			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)++;
> +				cnt++;
> +			}
> +		}
> +		last_record = record;
> +	}
> +	free_record(last_record);
> +
> +	return cnt;
> +}
> +
> +static int sync_events_cmp(const void *a, const void *b)
> +{
> +	const struct tracecmd_event_hit *ea = (const struct tracecmd_event_hit *)a;
> +	const struct tracecmd_event_hit *eb = (const struct tracecmd_event_hit *)b;
> +
> +	if (ea->ts > eb->ts)
> +		return 1;
> +	if (ea->ts < eb->ts)
> +		return -1;
> +	return 0;
> +}
> +
> +static int find_sync_events(struct tep_handle *pevent,
> +			    struct tracecmd_event_hit *recorded,
> +			    int rsize, struct tracecmd_event_hit *events)
> +{
> +	int i = 0, j = 0;
> +
> +	while (i < rsize) {
> +		if (!events[j].ts && events[j].id == recorded[i].id &&
> +		    (events[j].pid < 0 || 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 < 0 || events[j-1].pid == recorded[i].pid)) {
> +			events[j-1].cpu = recorded[i].cpu;
> +			events[j-1].ts = recorded[i].ts;
> +		}
> +		i++;
> +	}
> +	return j;
> +}
> +
> +//#define TSYNC_RBUFFER_DEBUG
> +static int find_raw_events(struct tep_handle *tep,
> +		    struct buffer_instance *instance,
> +		    struct tracecmd_event_hit *events)
> +{
> +	struct tracecmd_event_hit *events_array = NULL;
> +	int events_count = 0;
> +	int events_size = 0;
> +	struct dirent *dent;
> +	unsigned int p_size;
> +	int ts = 0;
> +	void *page;
> +	char *path;
> +	char *file;
> +	DIR *dir;
> +	int cpu;
> +	int len;
> +	int fd;
> +	int r;
> +
> +	p_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(p_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, p_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 pid %d\n\r",
> +			events[len].id,  events[len].cpu,
> +			events[len].ts, events[len].pid);
> +		len++;
> +	}
> +#endif
> +
> +	free(events_array);
> +	free(file);
> +	free(page);
> +	closedir(dir);
> +
> + out:
> +	tracecmd_put_tracing_file(path);
> +	return r;
> +}
> +
> +static int clock_sync_x86_host_find_events(struct tracecmd_clock_sync *clock,
> +					   int pid,
> +					   struct tracecmd_event_hit *event)
> +{
> +	int ret;
> +
> +	clock->events[0].pid = pid;
> +	ret = find_raw_events(clock->tep, clock->vinst, clock->events);
> +	event->ts = clock->events[0].ts;
> +	event->cpu = clock->events[0].cpu;
> +	return ret;
> +
> +}
> +
> +static int clock_sync_x86_guest_find_events(struct tracecmd_clock_sync *clock,
> +					    int pid,
> +					    struct tracecmd_event_hit *event)
> +{
> +	int ret;
> +
> +	ret = find_raw_events(clock->tep, clock->vinst, clock->events);
> +	event->ts = clock->events[1].ts;
> +	event->cpu = clock->events[0].cpu;
> +	return ret;
> +
> +}
> +
> +static void tracecmd_clock_sync_reset(struct tracecmd_clock_sync *clock_context)
> +{
> +	int i = 0;
> +
> +	while (clock_context->events[i].id) {
> +		clock_context->events[i].cpu = 0;
> +		clock_context->events[i].ts = 0;
> +		clock_context->events[i].pid = -1;
> +		i++;
> +	}
> +}
> +
> +int tracecmd_clock_find_event(struct tracecmd_clock_sync *clock, int pid,
> +			      struct tracecmd_event_hit *event)
> +{
> +	int ret = 0;
> +	int id;
> +
> +	if (clock == NULL ||
> +	    clock->clock_context_id >= CLOCK_CONTEXT_MAX)
> +		return 0;
> +
> +	id = clock->clock_context_id;
> +	if (clock_sync[id].clock_sync_find_events)
> +		ret = clock_sync[id].clock_sync_find_events(clock, pid, event);
> +
> +	tracecmd_clock_sync_reset(clock);
> +	return ret;
> +}
> +
> +static void clock_context_copy(struct tracecmd_clock_sync *clock_context,
> +			       struct tracecmd_ftrace_param *params,
> +			       struct tracecmd_event_descr *events)
> +{
> +	int i;
> +
> +	i = 0;
> +	while (params[i].file)
> +		i++;
> +	clock_context->ftrace_params = calloc(i+1, sizeof(struct tracecmd_ftrace_param));
> +	i = 0;
> +	while (params[i].file) {
> +		clock_context->ftrace_params[i].file = strdup(params[i].file);
> +		if (params[i].set)
> +			clock_context->ftrace_params[i].set = strdup(params[i].set);
> +		if (params[i].reset)
> +			clock_context->ftrace_params[i].reset = strdup(params[i].reset);
> +		i++;
> +	}
> +
> +	i = 0;
> +	while (events[i].name)
> +		i++;
> +	clock_context->events = calloc(i+1, sizeof(struct tracecmd_event_hit));
> +}
> +
> +void trace_instance_reset(struct buffer_instance *vinst)
> +{
> +	write_instance_file(vinst, "trace", "\0", NULL);
> +}
> +
> +static struct buffer_instance *
> +clock_synch_create_instance(const char *clock, unsigned int cid)
> +{
> +	struct buffer_instance *vinst;
> +	char inst_name[256];
> +
> +	snprintf(inst_name, 256, "clock_synch-%d", cid);
> +
> +	vinst = create_instance(strdup(inst_name));
> +	tracecmd_init_instance(vinst);
> +	vinst->cpu_count = tracecmd_local_cpu_count();
> +	tracecmd_make_instance(vinst);
> +	trace_instance_reset(vinst);
> +	if (clock)
> +		vinst->clock = strdup(clock);
> +	tracecmd_set_clock(vinst);
> +	return vinst;
> +}
> +
> +static 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;
> +}
> +
> +static 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;
> +	}
> +}
> +
> +struct tracecmd_clock_sync*
> +tracecmd_clock_context_init(struct tracecmd_msg_handle *msg_handle,
> +			    const char *clock_str,
> +			    enum clock_sync_conext id)
> +{
> +	struct tracecmd_clock_sync *clock_context;
> +	struct tep_event *event;
> +	unsigned int i = 0;
> +
> +	switch (id) {
> +#ifdef VSOCK
> +	case CLOCK_KVM_X86_VSOCK_HOST:
> +	case CLOCK_KVM_X86_VSOCK_GUEST:
> +		break;
> +#endif
> +	default: /* not supported clock sync context */
> +		return NULL;
> +	}
> +
> +	if (id >= CLOCK_CONTEXT_MAX || NULL == msg_handle)
> +		return NULL;
> +	clock_context = calloc(1, sizeof(struct tracecmd_clock_sync));
> +	if (!clock_context)
> +		return NULL;
> +	clock_context->clock_context_id = id;
> +	clock_context_copy(clock_context,
> +			   clock_sync[id].ftrace_params, clock_sync[id].events);
> +
> +	get_vsocket_params(msg_handle->fd,
> +			   &(clock_context->local_cid),
> +			   &(clock_context->local_port),
> +			   &(clock_context->remote_cid),
> +			   &(clock_context->remote_port));
> +
> +	if (clock_sync[id].clock_sync_init)
> +		clock_sync[id].clock_sync_init(clock_context);
> +
> +	clock_context->vinst = clock_synch_create_instance(clock_str, clock_context->remote_cid);
> +	clock_context->tep = clock_synch_get_tep(clock_context->vinst,
> +						 clock_sync[id].systems);
> +	i = 0;
> +	while (clock_sync[id].events[i].name) {
> +		event = tep_find_event_by_name(clock_context->tep,
> +					       clock_sync[id].events[i].system,
> +					       clock_sync[id].events[i].name);
> +		if (!event)
> +			break;
> +		clock_context->events[i].id = event->id;
> +		i++;
> +	}
> +	return clock_context;
> +
> +}
> +
> +void tracecmd_clock_context_free(struct tracecmd_clock_sync *clock_context)
> +{
> +	int i;
> +
> +	if (clock_context == NULL ||
> +	    clock_context->clock_context_id >= CLOCK_CONTEXT_MAX)
> +		return;
> +	if (clock_sync[clock_context->clock_context_id].clock_sync_free)
> +		clock_sync[clock_context->clock_context_id].clock_sync_free(clock_context);
> +
> +	i = 0;
> +	while (clock_context->ftrace_params[i].file) {
> +		free(clock_context->ftrace_params[i].file);
> +		free(clock_context->ftrace_params[i].set);
> +		free(clock_context->ftrace_params[i].reset);
> +		i++;
> +	}
> +	free(clock_context->ftrace_params);
> +	free(clock_context->events);
> +	tracecmd_remove_instance(clock_context->vinst);
> +	/* todo: clean up the instance */
> +	tep_free(clock_context->tep);
> +	free(clock_context);
> +}
> +
> +void sync_time_with_host_v3(struct buffer_instance *instance)
> +{
> +	long long ts_local = 0;
> +	long long toffset = 0;
> +
> +	if (instance->clock_sync == NULL)
> +		instance->clock_sync = tracecmd_clock_context_init(instance->msg_handle,
> +					instance->clock, CLOCK_KVM_X86_VSOCK_GUEST);
> +
> +	tracecmd_msg_snd_time_sync(instance->msg_handle, instance->clock_sync,
> +				   &toffset, &ts_local);
> +}
> +
> +void sync_time_with_guest_v3(struct buffer_instance *instance)
> +{
> +	long long ts_local = 0;
> +	long long toffset = 0;

How about switching throughout `ts_local` and `toffset` to `guest_timestamp` and `guest_offset` respectively? I think it will make the code easier to read.

> +	long long *sync_array_ts;
> +	long long *sync_array_ofs;
> +
> +	if (instance->clock_sync == NULL)
> +		instance->clock_sync = tracecmd_clock_context_init(instance->msg_handle,
> +						top_instance.clock, CLOCK_KVM_X86_VSOCK_HOST);
> +
> +	tracecmd_msg_rcv_time_sync(instance->msg_handle,
> +				   instance->clock_sync, &toffset, &ts_local);
> +
> +	sync_array_ts = realloc(instance->time_sync_ts,
> +			    (instance->time_sync_count+1)*sizeof(long long));
> +	sync_array_ofs = realloc(instance->time_sync_ofssets,
> +			    (instance->time_sync_count+1)*sizeof(long long));
> +
> +	if (sync_array_ts && sync_array_ofs) {
> +		sync_array_ts[instance->time_sync_count] = ts_local;
> +		sync_array_ofs[instance->time_sync_count] = toffset;
> +		instance->time_sync_count++;
> +		instance->time_sync_ts = sync_array_ts;
> +		instance->time_sync_ofssets = sync_array_ofs;
> +
> +	} else {
> +		free(sync_array_ts);
> +		free(sync_array_ofs);
> +	}
> +}
> +
> +static void set_clock_synch_events(struct buffer_instance *instance,
> +				   struct tracecmd_ftrace_param *params,
> +				   bool enable)
> +{
> +	int i = 0;
> +
> +	if (!enable)
> +		write_tracing_on(instance, 0);
> +
> +	while (params[i].file) {
> +		if (enable && params[i].set) {
> +			write_instance_file(instance, params[i].file,
> +					params[i].set, NULL);
> +		}
> +		if (!enable && params[i].reset)
> +			write_instance_file(instance, params[i].file,
> +					params[i].reset, NULL);
> +		i++;
> +	}
> +
> +	if (enable)
> +		write_tracing_on(instance, 1);
> +}
> +
> +void tracecmd_clock_synch_enable(struct tracecmd_clock_sync *clock_context)
> +{
> +	set_clock_synch_events(clock_context->vinst,
> +			       clock_context->ftrace_params, true);
> +}
> +
> +void tracecmd_clock_synch_disable(struct tracecmd_clock_sync *clock_context)
> +{
> +	set_clock_synch_events(clock_context->vinst,
> +			       clock_context->ftrace_params, false);
> +}
> -- 
> 2.20.1
>