[PATCH] trace-cmd: Fix record --date flag when sending tracing data to a listener

[PATCH] trace-cmd: Fix record --date flag when sending tracing data to a listener

[kaslevs]

From: Slavomir Kaslev <kaslevs@vmware.com>

Currently the `trace-cmd record` --date is not taken into account when tracing
data is sent to a remote host with the -N flag.

This patch fixes this by the writing output buffer options from the recording
side instead of on the listener side.

Signed-off-by: Slavomir Kaslev <kaslevs@vmware.com>
---
 include/trace-cmd/trace-cmd.h |  1 +
 lib/traceevent/event-parse.c  |  2 +-
 tracecmd/trace-output.c       | 11 ++++++-
 tracecmd/trace-record.c       | 60 ++++++++++++++++++++---------------
 4 files changed, 46 insertions(+), 28 deletions(-)

diff --git a/include/trace-cmd/trace-cmd.h b/include/trace-cmd/trace-cmd.h
index 684ddb7..4107fea 100644
--- a/include/trace-cmd/trace-cmd.h
+++ b/include/trace-cmd/trace-cmd.h
@@ -245,6 +245,7 @@ struct tracecmd_option *tracecmd_add_option(struct tracecmd_output *handle,
 					    const void *data);
 struct tracecmd_option *tracecmd_add_buffer_option(struct tracecmd_output *handle,
 						   const char *name, int cpus);
+int tracecmd_write_options(struct tracecmd_output *handle, int cpus);
 int tracecmd_update_option(struct tracecmd_output *handle,
 			   struct tracecmd_option *option, int size,
 			   const void *data);
diff --git a/lib/traceevent/event-parse.c b/lib/traceevent/event-parse.c
index 078ed5e..2e8031c 100644
--- a/lib/traceevent/event-parse.c
+++ b/lib/traceevent/event-parse.c
@@ -5411,7 +5411,7 @@ void tep_event_info(struct trace_seq *s, struct tep_event_format *event,
 
 static bool is_timestamp_in_us(char *trace_clock, bool use_trace_clock)
 {
-	if (!use_trace_clock)
+	if (!trace_clock || !use_trace_clock)
 		return true;
 
 	if (!strcmp(trace_clock, "local") || !strcmp(trace_clock, "global")
diff --git a/tracecmd/trace-output.c b/tracecmd/trace-output.c
index 99493e6..a846379 100644
--- a/tracecmd/trace-output.c
+++ b/tracecmd/trace-output.c
@@ -973,6 +973,15 @@ static int add_options(struct tracecmd_output *handle)
 	return 0;
 }
 
+int tracecmd_write_options(struct tracecmd_output *handle, int cpus)
+{
+	cpus = convert_endian_4(handle, cpus);
+	if (do_write_check(handle, &cpus, 4))
+		return -1;
+
+	return add_options(handle);
+}
+
 int tracecmd_update_option(struct tracecmd_output *handle,
 			   struct tracecmd_option *option, int size,
 			   const void *data)
@@ -1264,7 +1273,7 @@ int tracecmd_attach_cpu_data_fd(int fd, int cpus, char * const *cpu_data_files)
 	handle->page_size = tracecmd_page_size(ihandle);
 	list_head_init(&handle->options);
 
-	if (tracecmd_append_cpu_data(handle, cpus, cpu_data_files) >= 0)
+	if (__tracecmd_append_cpu_data(handle, cpus, cpu_data_files) >= 0)
 		ret = 0;
 
 	tracecmd_output_close(handle);
diff --git a/tracecmd/trace-record.c b/tracecmd/trace-record.c
index 6dd2ac0..e1e2f43 100644
--- a/tracecmd/trace-record.c
+++ b/tracecmd/trace-record.c
@@ -2877,8 +2877,10 @@ again:
 	return msg_handle;
 }
 
+static void add_options(struct tracecmd_output *handle, char *date2ts, int flags);
+
 static struct tracecmd_msg_handle *
-setup_connection(struct buffer_instance *instance)
+setup_connection(struct buffer_instance *instance, char *date2ts, int flags)
 {
 	struct tracecmd_msg_handle *msg_handle;
 	struct tracecmd_output *network_handle;
@@ -2886,13 +2888,17 @@ setup_connection(struct buffer_instance *instance)
 	msg_handle = setup_network();
 
 	/* Now create the handle through this socket */
-	if (msg_handle->version == V2_PROTOCOL) {
+	if (msg_handle->version == V2_PROTOCOL)
 		network_handle = tracecmd_create_init_fd_msg(msg_handle, listed_events);
-		tracecmd_msg_finish_sending_metadata(msg_handle);
-	} else
+	else
 		network_handle = tracecmd_create_init_fd_glob(msg_handle->fd,
 							      listed_events);
 
+	add_options(network_handle, date2ts, flags);
+	tracecmd_write_options(network_handle, instance->cpu_count);
+	if (msg_handle->version == V2_PROTOCOL)
+		tracecmd_msg_finish_sending_metadata(msg_handle);
+
 	instance->network_handle = network_handle;
 
 	/* OK, we are all set, let'r rip! */
@@ -2907,7 +2913,7 @@ static void finish_network(struct tracecmd_msg_handle *msg_handle)
 	free(host);
 }
 
-void start_threads(enum trace_type type, int global)
+void start_threads(enum trace_type type, int global, char *date2ts, int flags)
 {
 	struct buffer_instance *instance;
 	int *brass = NULL;
@@ -2929,7 +2935,7 @@ void start_threads(enum trace_type type, int global)
 		int x, pid;
 
 		if (host) {
-			instance->msg_handle = setup_connection(instance);
+			instance->msg_handle = setup_connection(instance, date2ts, flags);
 			if (!instance->msg_handle)
 				die("Failed to make connection");
 		}
@@ -3083,6 +3089,26 @@ enum {
 	DATA_FL_OFFSET		= 2,
 };
 
+static void add_options(struct tracecmd_output *handle, char *date2ts, int flags)
+{
+	int type = 0;
+
+	if (date2ts) {
+		if (flags & DATA_FL_DATE)
+			type = TRACECMD_OPTION_DATE;
+		else if (flags & DATA_FL_OFFSET)
+			type = TRACECMD_OPTION_OFFSET;
+	}
+
+	if (type)
+		tracecmd_add_option(handle, type, strlen(date2ts)+1, date2ts);
+
+	tracecmd_add_option(handle, TRACECMD_OPTION_TRACECLOCK, 0, NULL);
+	add_option_hooks(handle);
+	add_uname(handle);
+
+}
+
 static void record_data(char *date2ts, int flags)
 {
 	struct tracecmd_option **buffer_options;
@@ -3138,18 +3164,7 @@ static void record_data(char *date2ts, int flags)
 		if (!handle)
 			die("Error creating output file");
 
-		if (date2ts) {
-			int type = 0;
-
-			if (flags & DATA_FL_DATE)
-				type = TRACECMD_OPTION_DATE;
-			else if (flags & DATA_FL_OFFSET)
-				type = TRACECMD_OPTION_OFFSET;
-
-			if (type)
-				tracecmd_add_option(handle, type,
-						    strlen(date2ts)+1, date2ts);
-		}
+		add_options(handle, date2ts, flags);
 
 		/* Only record the top instance under TRACECMD_OPTION_CPUSTAT*/
 		if (!no_top_instance() && !top_instance.msg_handle) {
@@ -3160,13 +3175,6 @@ static void record_data(char *date2ts, int flags)
 						    s[i].len+1, s[i].buffer);
 		}
 
-		tracecmd_add_option(handle, TRACECMD_OPTION_TRACECLOCK,
-				    0, NULL);
-
-		add_option_hooks(handle);
-
-		add_uname(handle);
-
 		if (buffers) {
 			buffer_options = malloc(sizeof(*buffer_options) * buffers);
 			if (!buffer_options)
@@ -4974,7 +4982,7 @@ static void record_trace(int argc, char **argv,
 	if (type & (TRACE_TYPE_RECORD | TRACE_TYPE_STREAM)) {
 		signal(SIGINT, finish);
 		if (!latency)
-			start_threads(type, ctx->global);
+			start_threads(type, ctx->global, ctx->date2ts, ctx->data_flags);
 	} else {
 		update_task_filter();
 		tracecmd_enable_tracing();
-- 
2.19.1

Re: [PATCH] trace-cmd: Fix record --date flag when sending tracing data to a listener

[Steven Rostedt]

On Wed, 14 Nov 2018 17:43:28 +0200
kaslevs@vmware.com wrote:

> From: Slavomir Kaslev <kaslevs@vmware.com>
> 
> Currently the `trace-cmd record` --date is not taken into account when tracing
> data is sent to a remote host with the -N flag.
> 
> This patch fixes this by the writing output buffer options from the recording
> side instead of on the listener side.
> 
> Signed-off-by: Slavomir Kaslev <kaslevs@vmware.com>
> ---
>

I don't see anything too wrong with it, accept the following test broke:

 $ git checkout trace-cmd-v2.6
 $ make
 $ sudo cp trace-cmd /usr/local/bin/trace-cmd-v2.6
 $ git checkout origin/master
 $ patch -p1 < this.patch
 $ make
 $ trace-cmd-v2.6 listen -p 12345

In another terminal:

 $ sudo trace-cmd record -N 127.0.0.1:12345 -e sched sleep 1
trace-cmd: No such file or directory
  Cannot handle the protocol


Remember, we need to remain backward compatible. We also need to test
this code running as a listener, and the trace-cmd-v2.6 (and earlier)
as the recorder.

-- Steve

Re: [PATCH] trace-cmd: Fix record --date flag when sending tracing data to a listener

[Slavomir Kaslev]

On Mon, Nov 26, 2018 at 8:06 PM Steven Rostedt <rostedt@goodmis.org> wrote:
>
> On Wed, 14 Nov 2018 17:43:28 +0200
> kaslevs@vmware.com wrote:
>
> > From: Slavomir Kaslev <kaslevs@vmware.com>
> >
> > Currently the `trace-cmd record` --date is not taken into account when tracing
> > data is sent to a remote host with the -N flag.
> >
> > This patch fixes this by the writing output buffer options from the recording
> > side instead of on the listener side.
> >
> > Signed-off-by: Slavomir Kaslev <kaslevs@vmware.com>
> > ---
> >
>
> I don't see anything too wrong with it, accept the following test broke:
>
>  $ git checkout trace-cmd-v2.6
>  $ make
>  $ sudo cp trace-cmd /usr/local/bin/trace-cmd-v2.6
>  $ git checkout origin/master
>  $ patch -p1 < this.patch
>  $ make
>  $ trace-cmd-v2.6 listen -p 12345
>
> In another terminal:
>
>  $ sudo trace-cmd record -N 127.0.0.1:12345 -e sched sleep 1
> trace-cmd: No such file or directory
>   Cannot handle the protocol
>
>
> Remember, we need to remain backward compatible. We also need to test
> this code running as a listener, and the trace-cmd-v2.6 (and earlier)
> as the recorder.

This is a design bug (the best kind), metadata should really be written from the
recording side and not from the listener. A backward compatible fix should have
the newer recorder and listener detect they're talking to an older version and
fallback to broken behavior. This implies a new protocol version or extending
MSG_TINIT/MSG_RINIT so that we can infer the behavior on the other side and
fallback to being broken when necessary.

What would you suggest?

--
Slavi

Re: [PATCH] trace-cmd: Fix record --date flag when sending tracing data to a listener

[Steven Rostedt]

On Tue, 27 Nov 2018 10:15:55 +0000
Slavomir Kaslev <kaslevs@vmware.com> wrote:

> On Mon, Nov 26, 2018 at 8:06 PM Steven Rostedt <rostedt@goodmis.org> wrote:
> >
> > On Wed, 14 Nov 2018 17:43:28 +0200
> > kaslevs@vmware.com wrote:
> >  
> > > From: Slavomir Kaslev <kaslevs@vmware.com>
> > >
> > > Currently the `trace-cmd record` --date is not taken into account when tracing
> > > data is sent to a remote host with the -N flag.
> > >
> > > This patch fixes this by the writing output buffer options from the recording
> > > side instead of on the listener side.
> > >
> > > Signed-off-by: Slavomir Kaslev <kaslevs@vmware.com>
> > > ---
> > >  
> >
> > I don't see anything too wrong with it, accept the following test broke:
> >
> >  $ git checkout trace-cmd-v2.6
> >  $ make
> >  $ sudo cp trace-cmd /usr/local/bin/trace-cmd-v2.6
> >  $ git checkout origin/master
> >  $ patch -p1 < this.patch
> >  $ make
> >  $ trace-cmd-v2.6 listen -p 12345
> >
> > In another terminal:
> >
> >  $ sudo trace-cmd record -N 127.0.0.1:12345 -e sched sleep 1
> > trace-cmd: No such file or directory
> >   Cannot handle the protocol
> >
> >
> > Remember, we need to remain backward compatible. We also need to test
> > this code running as a listener, and the trace-cmd-v2.6 (and earlier)
> > as the recorder.  
> 
> This is a design bug (the best kind), metadata should really be written from the
> recording side and not from the listener. A backward compatible fix should have
> the newer recorder and listener detect they're talking to an older version and
> fallback to broken behavior. 

Yes, that's what we need to do.

> This implies a new protocol version or extending
> MSG_TINIT/MSG_RINIT so that we can infer the behavior on the other side and
> fallback to being broken when necessary.
> 
> What would you suggest?

Let me take a deeper look at it. This reminds me of the time I
added the hack to distinguish between V1 and V2. (see commit
cc042aba4a97ae).

-- Steve

Re: [PATCH] trace-cmd: Fix record --date flag when sending tracing data to a listener

[Steven Rostedt]

On Tue, 27 Nov 2018 10:15:55 +0000
Slavomir Kaslev <kaslevs@vmware.com> wrote:

> > I don't see anything too wrong with it, accept the following test broke:
> >
> >  $ git checkout trace-cmd-v2.6
> >  $ make
> >  $ sudo cp trace-cmd /usr/local/bin/trace-cmd-v2.6
> >  $ git checkout origin/master
> >  $ patch -p1 < this.patch
> >  $ make
> >  $ trace-cmd-v2.6 listen -p 12345
> >
> > In another terminal:
> >
> >  $ sudo trace-cmd record -N 127.0.0.1:12345 -e sched sleep 1
> > trace-cmd: No such file or directory
> >   Cannot handle the protocol
> >
> >
> > Remember, we need to remain backward compatible. We also need to test
> > this code running as a listener, and the trace-cmd-v2.6 (and earlier)
> > as the recorder.  
> 
> This is a design bug (the best kind), metadata should really be written from the
> recording side and not from the listener. A backward compatible fix should have
> the newer recorder and listener detect they're talking to an older version and
> fallback to broken behavior. This implies a new protocol version or extending
> MSG_TINIT/MSG_RINIT so that we can infer the behavior on the other side and
> fallback to being broken when necessary.

Agreed.

> 
> What would you suggest?

I just want to stress that I feel as strong for backward compatibility
as Linus feels for not breaking user space. That is, I'll go without a
fix if it breaks backward compatibility. 

But the really good news is, your code didn't break backward
compatibility. It uncovered a bug :-) :-) :-)

The failure of the old code is that it looked at buf[0] without
initializing it. The fix is this:

diff --git a/tracecmd/trace-record.c b/tracecmd/trace-record.c
index e1e2f433..143793da 100644
--- a/tracecmd/trace-record.c
+++ b/tracecmd/trace-record.c
@@ -2775,6 +2775,8 @@ static void check_protocol_version(struct tracecmd_msg_handle *msg_handle)
 	 */
 	write(fd, V2_CPU, sizeof(V2_CPU));
 
+	buf[0] = 0;
+
 	/* read a reply message */
 	n = read(fd, buf, BUFSIZ);
 

That said, I have one minor nit with the patch. I'll reply to the patch
itself.

Thanks!

-- Steve

Re: [PATCH] trace-cmd: Fix record --date flag when sending tracing data to a listener

[Slavomir Kaslev]

On Wed, Nov 28, 2018 at 5:19 AM Steven Rostedt <rostedt@goodmis.org> wrote:
>
> On Tue, 27 Nov 2018 10:15:55 +0000
> Slavomir Kaslev <kaslevs@vmware.com> wrote:
>
> > > I don't see anything too wrong with it, accept the following test broke:
> > >
> > >  $ git checkout trace-cmd-v2.6
> > >  $ make
> > >  $ sudo cp trace-cmd /usr/local/bin/trace-cmd-v2.6
> > >  $ git checkout origin/master
> > >  $ patch -p1 < this.patch
> > >  $ make
> > >  $ trace-cmd-v2.6 listen -p 12345
> > >
> > > In another terminal:
> > >
> > >  $ sudo trace-cmd record -N 127.0.0.1:12345 -e sched sleep 1
> > > trace-cmd: No such file or directory
> > >   Cannot handle the protocol
> > >
> > >
> > > Remember, we need to remain backward compatible. We also need to test
> > > this code running as a listener, and the trace-cmd-v2.6 (and earlier)
> > > as the recorder.
> >
> > This is a design bug (the best kind), metadata should really be written from the
> > recording side and not from the listener. A backward compatible fix should have
> > the newer recorder and listener detect they're talking to an older version and
> > fallback to broken behavior. This implies a new protocol version or extending
> > MSG_TINIT/MSG_RINIT so that we can infer the behavior on the other side and
> > fallback to being broken when necessary.
>
> Agreed.
>
> >
> > What would you suggest?
>
> I just want to stress that I feel as strong for backward compatibility
> as Linus feels for not breaking user space. That is, I'll go without a
> fix if it breaks backward compatibility.
>
> But the really good news is, your code didn't break backward
> compatibility. It uncovered a bug :-) :-) :-)
>
> The failure of the old code is that it looked at buf[0] without
> initializing it. The fix is this:
>
> diff --git a/tracecmd/trace-record.c b/tracecmd/trace-record.c
> index e1e2f433..143793da 100644
> --- a/tracecmd/trace-record.c
> +++ b/tracecmd/trace-record.c
> @@ -2775,6 +2775,8 @@ static void check_protocol_version(struct tracecmd_msg_handle *msg_handle)
>          */
>         write(fd, V2_CPU, sizeof(V2_CPU));
>
> +       buf[0] = 0;
> +
>         /* read a reply message */
>         n = read(fd, buf, BUFSIZ);
>

This fix does work and recorder fallbacks to protocol v1 when talking
with v2.6 listener.

The resulting trace file fails to parse though

kaslevs@box:~/tmp$ tc report -i trace.localhost:39754.dat
  failed to init data

because both the recorder and the listener wrote options to the .dat file.

So we still have to detect that the listener end is an older version
and fallback to old behavior in the recorder.

Our current protocol doesn't allow to easily add new fields to
messages because the size of messages is hard coded in the executable.
Thus extending

struct tracecmd_msg_rinit {
        be32 cpus;
} __attribute__((packed));

or reusing bits from .cpus will not fly.

Alternatively, we can add tracecmd_msg_rinit2 with which the listener
(new versions) responds depending on the options set in
tracecmd_msg_tinit by the recorder (when the recorder is new version
too).

>
> That said, I have one minor nit with the patch. I'll reply to the patch
> itself.
>
> Thanks!
>
> -- Steve
>

Re: [PATCH] trace-cmd: Fix record --date flag when sending tracing data to a listener

[Slavomir Kaslev]

On Fri, Nov 30, 2018 at 2:33 PM Slavomir Kaslev <kaslevs@vmware.com> wrote:
>
> On Wed, Nov 28, 2018 at 5:19 AM Steven Rostedt <rostedt@goodmis.org> wrote:
> >
> > On Tue, 27 Nov 2018 10:15:55 +0000
> > Slavomir Kaslev <kaslevs@vmware.com> wrote:
> >
> > > > I don't see anything too wrong with it, accept the following test broke:
> > > >
> > > >  $ git checkout trace-cmd-v2.6
> > > >  $ make
> > > >  $ sudo cp trace-cmd /usr/local/bin/trace-cmd-v2.6
> > > >  $ git checkout origin/master
> > > >  $ patch -p1 < this.patch
> > > >  $ make
> > > >  $ trace-cmd-v2.6 listen -p 12345
> > > >
> > > > In another terminal:
> > > >
> > > >  $ sudo trace-cmd record -N 127.0.0.1:12345 -e sched sleep 1
> > > > trace-cmd: No such file or directory
> > > >   Cannot handle the protocol
> > > >
> > > >
> > > > Remember, we need to remain backward compatible. We also need to test
> > > > this code running as a listener, and the trace-cmd-v2.6 (and earlier)
> > > > as the recorder.
> > >
> > > This is a design bug (the best kind), metadata should really be written from the
> > > recording side and not from the listener. A backward compatible fix should have
> > > the newer recorder and listener detect they're talking to an older version and
> > > fallback to broken behavior. This implies a new protocol version or extending
> > > MSG_TINIT/MSG_RINIT so that we can infer the behavior on the other side and
> > > fallback to being broken when necessary.
> >
> > Agreed.
> >
> > >
> > > What would you suggest?
> >
> > I just want to stress that I feel as strong for backward compatibility
> > as Linus feels for not breaking user space. That is, I'll go without a
> > fix if it breaks backward compatibility.
> >
> > But the really good news is, your code didn't break backward
> > compatibility. It uncovered a bug :-) :-) :-)
> >
> > The failure of the old code is that it looked at buf[0] without
> > initializing it. The fix is this:
> >
> > diff --git a/tracecmd/trace-record.c b/tracecmd/trace-record.c
> > index e1e2f433..143793da 100644
> > --- a/tracecmd/trace-record.c
> > +++ b/tracecmd/trace-record.c
> > @@ -2775,6 +2775,8 @@ static void check_protocol_version(struct tracecmd_msg_handle *msg_handle)
> >          */
> >         write(fd, V2_CPU, sizeof(V2_CPU));
> >
> > +       buf[0] = 0;
> > +
> >         /* read a reply message */
> >         n = read(fd, buf, BUFSIZ);
> >
>
> This fix does work and recorder fallbacks to protocol v1 when talking
> with v2.6 listener.
>
> The resulting trace file fails to parse though
>
> kaslevs@box:~/tmp$ tc report -i trace.localhost:39754.dat
>   failed to init data
>
> because both the recorder and the listener wrote options to the .dat file.
>
> So we still have to detect that the listener end is an older version
> and fallback to old behavior in the recorder.
>
> Our current protocol doesn't allow to easily add new fields to
> messages because the size of messages is hard coded in the executable.
> Thus extending
>
> struct tracecmd_msg_rinit {
>         be32 cpus;
> } __attribute__((packed));
>
> or reusing bits from .cpus will not fly.
>
> Alternatively, we can add tracecmd_msg_rinit2 with which the listener
> (new versions) responds depending on the options set in
> tracecmd_msg_tinit by the recorder (when the recorder is new version
> too).

Another option is to fix the protocol itself to be future proof and
allow adding new message fields without breaking old versions. In
other words, make each command write it's .size on the wire instead of
having it hard-coded (the current .size in tracecmd_msg_header bounds
the whole message (command and additional data) and doesn't allow to
differentiate between different versions of say the tracecmd_msg_rinit
command).

Re: [PATCH] trace-cmd: Fix record --date flag when sending tracing data to a listener

[Steven Rostedt]

Hi Slavomir,

One minor nit of this patch.

On Wed, 14 Nov 2018 17:43:28 +0200
kaslevs@vmware.com wrote:

> diff --git a/lib/traceevent/event-parse.c b/lib/traceevent/event-parse.c
> index 078ed5e..2e8031c 100644
> --- a/lib/traceevent/event-parse.c
> +++ b/lib/traceevent/event-parse.c
> @@ -5411,7 +5411,7 @@ void tep_event_info(struct trace_seq *s, struct tep_event_format *event,
>  
>  static bool is_timestamp_in_us(char *trace_clock, bool use_trace_clock)
>  {
> -	if (!use_trace_clock)
> +	if (!trace_clock || !use_trace_clock)
>  		return true;
>  
>  	if (!strcmp(trace_clock, "local") || !strcmp(trace_clock, "global")

This should be a separate patch, and it needs to be pushed to the Linux
kernel. Can you work with Tzvetomir in doing it?

Thanks!

-- Steve