Hi Steve,
Sorry, it took me some time to get a 32-bit x86 system up and running
here in order to build and test things on i386. These patches pass
both selftests and the synth_event_gen_test testing, although the bug
where (null) prints after every integer field in the trace output is
still there and is there even before these or yesterday's patches - I
have a suspicion it's been there for awhile but nobody looked at
synthetic event trace output on i386. In any case, I'm going to
continue looking into that - it's a weird situation where nothing gets
put in the final %s in the format string on i386 so shows as (null),
even though it looks like it's there. Anyway..
Here are 3 bugfix patches, the first of which fixes the bug seen by
the test robot, and the other two are patches that fix a couple things
I noticed when doing the first patch.
The previous patch I sent, changing u64 to long for the test robot bug
did fix that problem too, but on i386 systems that would reduce every
field to 32 bits, which isn't what we want either. The new patch
doesn't change the code in synth_event_trace() - it still uses u64
just like synth_event_trace_array() which takes an array of u64.
Without any further information such as a format string, I don't know
of a better way to deal with the varargs version, other than require
it get passed what it expects, u64 params.
The second patch adds the same endianness fix as for
trace_event_raw_event_synth(), and the last one just adds back a
missing check fot synth_event_trace() and synth_event_trace_array().
Thanks,
Tom
The following changes since commit 359c92c02bfae1a6f1e8e37c298e518fd256642c:
Merge tag 'dax-fixes-5.6-rc1' of git://git.kernel.org/pub/scm/linux/kernel/git/nvdimm/nvdimm (2020-02-11 16:52:08 -0800)
are available in the git repository at:
git://git.kernel.org/pub/scm/linux/kernel/git/zanussi/linux-trace.git ftrace/synth-event-gen-fixes2-v1
Tom Zanussi (3):
tracing: Make sure synth_event_trace() example always uses u64
tracing: Make synth_event trace functions endian-correct
tracing: Check that number of vals matches number of synth event
fields
kernel/trace/synth_event_gen_test.c | 34 +++++++++----------
kernel/trace/trace_events_hist.c | 68 ++++++++++++++++++++++++++++++++++---
2 files changed, 81 insertions(+), 21 deletions(-)
--
2.14.1
synth_event_trace(), synth_event_trace_array() and
__synth_event_add_val() write directly into the trace buffer and need
to take endianness into account, like trace_event_raw_event_synth()
does.
Signed-off-by: Tom Zanussi <[email protected]>
---
kernel/trace/trace_events_hist.c | 62 +++++++++++++++++++++++++++++++++++++---
1 file changed, 58 insertions(+), 4 deletions(-)
diff --git a/kernel/trace/trace_events_hist.c b/kernel/trace/trace_events_hist.c
index 483b3fd1094f..913760d2d505 100644
--- a/kernel/trace/trace_events_hist.c
+++ b/kernel/trace/trace_events_hist.c
@@ -1898,7 +1898,25 @@ int synth_event_trace(struct trace_event_file *file, unsigned int n_vals, ...)
strscpy(str_field, str_val, STR_VAR_LEN_MAX);
n_u64 += STR_VAR_LEN_MAX / sizeof(u64);
} else {
- state.entry->fields[n_u64] = val;
+ struct synth_field *field = state.event->fields[i];
+
+ switch (field->size) {
+ case 1:
+ *(u8 *)&state.entry->fields[n_u64] = (u8)val;
+ break;
+
+ case 2:
+ *(u16 *)&state.entry->fields[n_u64] = (u16)val;
+ break;
+
+ case 4:
+ *(u32 *)&state.entry->fields[n_u64] = (u32)val;
+ break;
+
+ default:
+ state.entry->fields[n_u64] = val;
+ break;
+ }
n_u64++;
}
}
@@ -1950,7 +1968,26 @@ int synth_event_trace_array(struct trace_event_file *file, u64 *vals,
strscpy(str_field, str_val, STR_VAR_LEN_MAX);
n_u64 += STR_VAR_LEN_MAX / sizeof(u64);
} else {
- state.entry->fields[n_u64] = vals[i];
+ struct synth_field *field = state.event->fields[i];
+ u64 val = vals[i];
+
+ switch (field->size) {
+ case 1:
+ *(u8 *)&state.entry->fields[n_u64] = (u8)val;
+ break;
+
+ case 2:
+ *(u16 *)&state.entry->fields[n_u64] = (u16)val;
+ break;
+
+ case 4:
+ *(u32 *)&state.entry->fields[n_u64] = (u32)val;
+ break;
+
+ default:
+ state.entry->fields[n_u64] = val;
+ break;
+ }
n_u64++;
}
}
@@ -2069,8 +2106,25 @@ static int __synth_event_add_val(const char *field_name, u64 val,
str_field = (char *)&entry->fields[field->offset];
strscpy(str_field, str_val, STR_VAR_LEN_MAX);
- } else
- entry->fields[field->offset] = val;
+ } else {
+ switch (field->size) {
+ case 1:
+ *(u8 *)&trace_state->entry->fields[field->offset] = (u8)val;
+ break;
+
+ case 2:
+ *(u16 *)&trace_state->entry->fields[field->offset] = (u16)val;
+ break;
+
+ case 4:
+ *(u32 *)&trace_state->entry->fields[field->offset] = (u32)val;
+ break;
+
+ default:
+ trace_state->entry->fields[field->offset] = val;
+ break;
+ }
+ }
out:
return ret;
}
--
2.14.1
Commit 7276531d4036('tracing: Consolidate trace() functions')
inadvertently dropped the synth_event_trace() and
synth_event_trace_array() checks that verify the number of values
passed in matches the number of fields in the synthetic event being
traced, so add them back.
Signed-off-by: Tom Zanussi <[email protected]>
---
kernel/trace/trace_events_hist.c | 6 ++++++
1 file changed, 6 insertions(+)
diff --git a/kernel/trace/trace_events_hist.c b/kernel/trace/trace_events_hist.c
index 913760d2d505..d931f1404505 100644
--- a/kernel/trace/trace_events_hist.c
+++ b/kernel/trace/trace_events_hist.c
@@ -1885,6 +1885,9 @@ int synth_event_trace(struct trace_event_file *file, unsigned int n_vals, ...)
return ret;
}
+ if (n_vals != state.event->n_fields)
+ return -EINVAL;
+
va_start(args, n_vals);
for (i = 0, n_u64 = 0; i < state.event->n_fields; i++) {
u64 val;
@@ -1960,6 +1963,9 @@ int synth_event_trace_array(struct trace_event_file *file, u64 *vals,
return ret;
}
+ if (n_vals != state.event->n_fields)
+ return -EINVAL;
+
for (i = 0, n_u64 = 0; i < state.event->n_fields; i++) {
if (state.event->fields[i]->is_string) {
char *str_val = (char *)(long)vals[i];
--
2.14.1
synth_event_trace() is the varargs version of synth_event_trace_array(),
which takes an array of u64, as do synth_event_add_val() et al.
To not only be consistent with those, but also to address the fact
that synth_event_trace() expects every arg to be of the same type
since it doesn't also pass in e.g. a format string, the caller needs
to make sure all args are of the same type, u64. u64 is used because
it needs to accomodate the largest type available in synthetic events,
which is u64.
This fixes the bug reported by the kernel test robot/Rong Chen as
reported here:
https://lore.kernel.org/lkml/20200212113444.GS12867@shao2-debian/
Reported-by: kernel test robot <[email protected]>
Signed-off-by: Tom Zanussi <[email protected]>
---
kernel/trace/synth_event_gen_test.c | 34 +++++++++++++++++-----------------
1 file changed, 17 insertions(+), 17 deletions(-)
diff --git a/kernel/trace/synth_event_gen_test.c b/kernel/trace/synth_event_gen_test.c
index 4aefe003cb7c..6866280a9b10 100644
--- a/kernel/trace/synth_event_gen_test.c
+++ b/kernel/trace/synth_event_gen_test.c
@@ -111,11 +111,11 @@ static int __init test_gen_synth_cmd(void)
/* Create some bogus values just for testing */
vals[0] = 777; /* next_pid_field */
- vals[1] = (u64)"hula hoops"; /* next_comm_field */
+ vals[1] = (u64)(long)"hula hoops"; /* next_comm_field */
vals[2] = 1000000; /* ts_ns */
vals[3] = 1000; /* ts_ms */
vals[4] = smp_processor_id(); /* cpu */
- vals[5] = (u64)"thneed"; /* my_string_field */
+ vals[5] = (u64)(long)"thneed"; /* my_string_field */
vals[6] = 598; /* my_int_field */
/* Now generate a gen_synth_test event */
@@ -218,11 +218,11 @@ static int __init test_empty_synth_event(void)
/* Create some bogus values just for testing */
vals[0] = 777; /* next_pid_field */
- vals[1] = (u64)"tiddlywinks"; /* next_comm_field */
+ vals[1] = (u64)(long)"tiddlywinks"; /* next_comm_field */
vals[2] = 1000000; /* ts_ns */
vals[3] = 1000; /* ts_ms */
vals[4] = smp_processor_id(); /* cpu */
- vals[5] = (u64)"thneed_2.0"; /* my_string_field */
+ vals[5] = (u64)(long)"thneed_2.0"; /* my_string_field */
vals[6] = 399; /* my_int_field */
/* Now trace an empty_synth_test event */
@@ -290,11 +290,11 @@ static int __init test_create_synth_event(void)
/* Create some bogus values just for testing */
vals[0] = 777; /* next_pid_field */
- vals[1] = (u64)"tiddlywinks"; /* next_comm_field */
+ vals[1] = (u64)(long)"tiddlywinks"; /* next_comm_field */
vals[2] = 1000000; /* ts_ns */
vals[3] = 1000; /* ts_ms */
vals[4] = smp_processor_id(); /* cpu */
- vals[5] = (u64)"thneed"; /* my_string_field */
+ vals[5] = (u64)(long)"thneed"; /* my_string_field */
vals[6] = 398; /* my_int_field */
/* Now generate a create_synth_test event */
@@ -330,7 +330,7 @@ static int __init test_add_next_synth_val(void)
goto out;
/* next_comm_field */
- ret = synth_event_add_next_val((u64)"slinky", &trace_state);
+ ret = synth_event_add_next_val((u64)(long)"slinky", &trace_state);
if (ret)
goto out;
@@ -350,7 +350,7 @@ static int __init test_add_next_synth_val(void)
goto out;
/* my_string_field */
- ret = synth_event_add_next_val((u64)"thneed_2.01", &trace_state);
+ ret = synth_event_add_next_val((u64)(long)"thneed_2.01", &trace_state);
if (ret)
goto out;
@@ -396,12 +396,12 @@ static int __init test_add_synth_val(void)
if (ret)
goto out;
- ret = synth_event_add_val("next_comm_field", (u64)"silly putty",
+ ret = synth_event_add_val("next_comm_field", (u64)(long)"silly putty",
&trace_state);
if (ret)
goto out;
- ret = synth_event_add_val("my_string_field", (u64)"thneed_9",
+ ret = synth_event_add_val("my_string_field", (u64)(long)"thneed_9",
&trace_state);
if (ret)
goto out;
@@ -423,13 +423,13 @@ static int __init test_trace_synth_event(void)
/* Trace some bogus values just for testing */
ret = synth_event_trace(create_synth_test, 7, /* number of values */
- 444, /* next_pid_field */
- (u64)"clackers", /* next_comm_field */
- 1000000, /* ts_ns */
- 1000, /* ts_ms */
- smp_processor_id(), /* cpu */
- (u64)"Thneed", /* my_string_field */
- 999); /* my_int_field */
+ (u64)444, /* next_pid_field */
+ (u64)(long)"clackers", /* next_comm_field */
+ (u64)1000000, /* ts_ns */
+ (u64)1000, /* ts_ms */
+ (u64)smp_processor_id(),/* cpu */
+ (u64)(long)"Thneed", /* my_string_field */
+ (u64)999); /* my_int_field */
return ret;
}
--
2.14.1
Hi Steve,
I apparently tested the wrong patches, and while I think patch 1 and 3
are ok, I'm seeing a problem with patch 2 (then endian changes). Will
send a v2 as soon as I can.
Tom
On Thu, 2020-02-13 at 16:16 -0600, Tom Zanussi wrote:
> Hi Steve,
>
> Sorry, it took me some time to get a 32-bit x86 system up and running
> here in order to build and test things on i386. These patches pass
> both selftests and the synth_event_gen_test testing, although the bug
> where (null) prints after every integer field in the trace output is
> still there and is there even before these or yesterday's patches - I
> have a suspicion it's been there for awhile but nobody looked at
> synthetic event trace output on i386. In any case, I'm going to
> continue looking into that - it's a weird situation where nothing
> gets
> put in the final %s in the format string on i386 so shows as (null),
> even though it looks like it's there. Anyway..
>
> Here are 3 bugfix patches, the first of which fixes the bug seen by
> the test robot, and the other two are patches that fix a couple
> things
> I noticed when doing the first patch.
>
> The previous patch I sent, changing u64 to long for the test robot
> bug
> did fix that problem too, but on i386 systems that would reduce every
> field to 32 bits, which isn't what we want either. The new patch
> doesn't change the code in synth_event_trace() - it still uses u64
> just like synth_event_trace_array() which takes an array of u64.
> Without any further information such as a format string, I don't know
> of a better way to deal with the varargs version, other than require
> it get passed what it expects, u64 params.
>
> The second patch adds the same endianness fix as for
> trace_event_raw_event_synth(), and the last one just adds back a
> missing check fot synth_event_trace() and synth_event_trace_array().
>
> Thanks,
>
> Tom
>
> The following changes since commit
> 359c92c02bfae1a6f1e8e37c298e518fd256642c:
>
> Merge tag 'dax-fixes-5.6-rc1' of
> git://git.kernel.org/pub/scm/linux/kernel/git/nvdimm/nvdimm (2020-02-
> 11 16:52:08 -0800)
>
> are available in the git repository at:
>
> git://git.kernel.org/pub/scm/linux/kernel/git/zanussi/linux-
> trace.git ftrace/synth-event-gen-fixes2-v1
>
> Tom Zanussi (3):
> tracing: Make sure synth_event_trace() example always uses u64
> tracing: Make synth_event trace functions endian-correct
> tracing: Check that number of vals matches number of synth event
> fields
>
> kernel/trace/synth_event_gen_test.c | 34 +++++++++----------
> kernel/trace/trace_events_hist.c | 68
> ++++++++++++++++++++++++++++++++++---
> 2 files changed, 81 insertions(+), 21 deletions(-)
>
On Thu, 13 Feb 2020 17:36:14 -0600
Tom Zanussi <[email protected]> wrote:
> Hi Steve,
>
> I apparently tested the wrong patches, and while I think patch 1 and 3
> are ok, I'm seeing a problem with patch 2 (then endian changes). Will
> send a v2 as soon as I can.
>
Due to other priorities, I haven't had a chance to look at theses yet.
So no hurry.
-- Steve