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

PATCH In review [email protected] 2 participants 8 messages Nov 15, 2018 – Dec 1, 2018

lore

Share & tools

lore

[email protected]

author

2018-11-15 01:47 UTC #0 lore raw

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

From: Slavomir Kaslev <[email protected]>

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 <[email protected]>

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

include/trace-cmd/trace-cmd.h +1 -0

index 684ddb7..4107fea 100644
@@ -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);

lib/traceevent/event-parse.c +1 -1

index 078ed5e..2e8031c 100644
@@ -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")

tracecmd/trace-output.c +10 -1

index 99493e6..a846379 100644
@@ -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);

tracecmd/trace-record.c +34 ~~-26~~

113 lines not on this page · raw message

Signature · 1 line

2.19.1

Steven Rostedt

2018-11-27 05:00 UTC #1 lore raw

Quoted 11 lines · On Wed, 14 Nov 2018 17:43:28 +0200 [email protected] wrote:

From: Slavomir Kaslev <[email protected]>
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 <[email protected]>
---

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

Slavomir Kaslev

author

2018-11-27 21:13 UTC #2 lore raw

Quoted 28 lines · Steven Rostedt

Quoted 11 lines · On Wed, 14 Nov 2018 17:43:28 +0200 [email protected] wrote:
From: Slavomir Kaslev <[email protected]>
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 <[email protected]>
---
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:

Quoted 8 lines

 $ 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

Steven Rostedt

2018-11-28 00:52 UTC #3 lore raw

Quoted 34 lines · On Tue, 27 Nov 2018 10:15:55 +0000 Slavomir Kaslev <[email protected]> wrote:

Quoted 33 lines · Steven Rostedt
Quoted 11 lines · On Wed, 14 Nov 2018 17:43:28 +0200 [email protected] wrote:
From: Slavomir Kaslev <[email protected]>
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 <[email protected]>
---
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

Quoted 8 lines

Quoted 3 lines
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.

Quoted 5 lines

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

Steven Rostedt

2018-11-28 14:19 UTC #4 lore raw

In reply to Slavomir Kaslev

Quoted 21 lines · On Tue, 27 Nov 2018 10:15:55 +0000 Slavomir Kaslev <[email protected]> wrote:

Quoted 12 lines
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:
Quoted 8 lines
 $ 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.

Quoted 6 lines

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.

Quoted 2 lines

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:

tracecmd/trace-record.c +2 -0

index e1e2f433..143793da 100644
@@ -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

Slavomir Kaslev

author

2018-11-30 23:42 UTC #5 lore raw

Quoted 52 lines · Steven Rostedt

Quoted 21 lines · On Tue, 27 Nov 2018 10:15:55 +0000 Slavomir Kaslev <[email protected]> wrote:
Quoted 12 lines
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:
Quoted 8 lines
 $ 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.
Quoted 6 lines
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.
Quoted 2 lines
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:
tracecmd/trace-record.c +0 -0
index e1e2f433..143793da 100644

tracecmd/trace-record.c static void check_protocol_version(struct tracecmd_msg_handle *msg_handle) · line 2782

Quoted 8 lines

tracecmd/trace-record.c +2 -0

@@ -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).

Quoted 8 lines

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

Slavomir Kaslev

author

2018-12-01 00:29 UTC #6 lore raw

Quoted 84 lines · Slavomir Kaslev

Quoted 52 lines · Steven Rostedt
Quoted 21 lines · On Tue, 27 Nov 2018 10:15:55 +0000 Slavomir Kaslev <[email protected]> wrote:
Quoted 12 lines
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:
Quoted 8 lines
 $ 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.
Quoted 6 lines
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.
Quoted 2 lines
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:
tracecmd/trace-record.c +0 -0
index e1e2f433..143793da 100644
tracecmd/trace-record.c static void check_protocol_version(struct tracecmd_msg_handle *msg_handle) · line 2782
Quoted 8 lines
tracecmd/trace-record.c +2 -0
@@ -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));

Quoted 6 lines

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

Steven Rostedt

2018-11-28 14:21 UTC #7 lore raw

In reply to [email protected]

Hi Slavomir,

One minor nit of this patch.

lib/traceevent/event-parse.c void tep_event_info(struct trace_seq *s, struct tep_event_format *event, · line 5417

Quoted 13 lines · On Wed, 14 Nov 2018 17:43:28 +0200 [email protected] wrote:

lib/traceevent/event-parse.c +1 -1

index 078ed5e..2e8031c 100644
@@ -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