[BUG]
For btrfs related events, there is a field for fsid, but perf never
parse it correctly.
# perf trace -e btrfs:qgroup_meta_convert xfs_io -f -c "pwrite 0 4k" \
/mnt/btrfs/file1
0.000 xfs_io/77915 btrfs:qgroup_meta_reserve:(nil)U: refroot=5(FS_TREE) type=0x0 diff=2
^^^^^^ Not a correct UUID
...
[CAUSE]
The pretty_print() function doesn't handle the %pU format correctly.
In fact it doesn't handle %pU as uuid at all.
[FIX]
Add a new function, print_uuid_arg(), to handle %pU correctly.
Now perf trace can at least print fsid correctly:
0.000 xfs_io/79619 btrfs:qgroup_meta_reserve:23ad1511-dd83-47d4-a79c-e96625a15a6e refroot=5(FS_TREE) type=0x0 diff=2
Signed-off-by: Qu Wenruo <[email protected]>
---
Changelog:
v2:
- Use more comment explaining the finetunings we skipped for %pU*
- Extra check for the field before reading the data
- Use more elegant way to output uuid string
v3:
- Use a even more elegant way to output uuid string
---
tools/lib/traceevent/event-parse.c | 51 ++++++++++++++++++++++++++++++
1 file changed, 51 insertions(+)
diff --git a/tools/lib/traceevent/event-parse.c b/tools/lib/traceevent/event-parse.c
index d948475585ce..a71f4a86b6ca 100644
--- a/tools/lib/traceevent/event-parse.c
+++ b/tools/lib/traceevent/event-parse.c
@@ -18,6 +18,7 @@
#include <errno.h>
#include <stdint.h>
#include <limits.h>
+#include <linux/uuid.h>
#include <linux/time64.h>
#include <netinet/in.h>
@@ -4508,6 +4509,40 @@ get_bprint_format(void *data, int size __maybe_unused,
return format;
}
+static void print_uuid_arg(struct trace_seq *s, void *data, int size,
+ struct tep_event *event, struct tep_print_arg *arg)
+{
+ unsigned char *buf;
+ int i;
+
+ if (arg->type != TEP_PRINT_FIELD) {
+ trace_seq_printf(s, "ARG TYPE NOT FIELID but %d", arg->type);
+ return;
+ }
+
+ if (!arg->field.field) {
+ arg->field.field = tep_find_any_field(event, arg->field.name);
+ if (!arg->field.field) {
+ do_warning("%s: field %s not found",
+ __func__, arg->field.name);
+ return;
+ }
+ }
+ if (arg->field.field->size < 16) {
+ trace_seq_printf(s, "INVALID UUID: size have %u expect 16",
+ arg->field.field->size);
+ return;
+ }
+ buf = data + arg->field.field->offset;
+
+ for (i = 0; i < 8; i++) {
+ trace_seq_printf(s, "%02x", buf[2 * i]);
+ trace_seq_printf(s, "%02x", buf[2 * i + 1]);
+ if (1 <= i && i <= 4)
+ trace_seq_putc(s, '-');
+ }
+}
+
static void print_mac_arg(struct trace_seq *s, int mac, void *data, int size,
struct tep_event *event, struct tep_print_arg *arg)
{
@@ -5074,6 +5109,22 @@ static void pretty_print(struct trace_seq *s, void *data, int size, struct tep_e
arg = arg->next;
break;
}
+ } else if (*ptr == 'U') {
+ /*
+ * %pU has several finetunings variants
+ * like %pUb and %pUL.
+ * Here we ignore them, default to
+ * byte-order no endian, lower case
+ * letters.
+ */
+ if (isalpha(ptr[1]))
+ ptr += 2;
+ else
+ ptr++;
+
+ print_uuid_arg(s, data, size, event, arg);
+ arg = arg->next;
+ break;
}
/* fall through */
--
2.23.0
On Mon, 21 Oct 2019 17:47:30 +0800
Qu Wenruo <[email protected]> wrote:
> +static void print_uuid_arg(struct trace_seq *s, void *data, int size,
> + struct tep_event *event, struct tep_print_arg *arg)
> +{
> + unsigned char *buf;
> + int i;
> +
> + if (arg->type != TEP_PRINT_FIELD) {
> + trace_seq_printf(s, "ARG TYPE NOT FIELID but %d", arg->type);
> + return;
> + }
> +
> + if (!arg->field.field) {
> + arg->field.field = tep_find_any_field(event, arg->field.name);
> + if (!arg->field.field) {
> + do_warning("%s: field %s not found",
> + __func__, arg->field.name);
> + return;
> + }
> + }
> + if (arg->field.field->size < 16) {
> + trace_seq_printf(s, "INVALID UUID: size have %u expect 16",
> + arg->field.field->size);
> + return;
> + }
> + buf = data + arg->field.field->offset;
> +
> + for (i = 0; i < 8; i++) {
> + trace_seq_printf(s, "%02x", buf[2 * i]);
> + trace_seq_printf(s, "%02x", buf[2 * i + 1]);
> + if (1 <= i && i <= 4)
I'm fine with this patch except for one nit. The above is hard to read
(in my opinion), and I absolutely hate the "constant" compare to
"variable" notation. Please change the above to:
if (i >= 1 && i <= 4)
Thanks,
-- Steve
> + trace_seq_putc(s, '-');
> + }
> +}
> +
On 2019/10/21 下午9:56, Steven Rostedt wrote:
> On Mon, 21 Oct 2019 17:47:30 +0800
> Qu Wenruo <[email protected]> wrote:
>
>> +static void print_uuid_arg(struct trace_seq *s, void *data, int size,
>> + struct tep_event *event, struct tep_print_arg *arg)
>> +{
>> + unsigned char *buf;
>> + int i;
>> +
>> + if (arg->type != TEP_PRINT_FIELD) {
>> + trace_seq_printf(s, "ARG TYPE NOT FIELID but %d", arg->type);
>> + return;
>> + }
>> +
>> + if (!arg->field.field) {
>> + arg->field.field = tep_find_any_field(event, arg->field.name);
>> + if (!arg->field.field) {
>> + do_warning("%s: field %s not found",
>> + __func__, arg->field.name);
>> + return;
>> + }
>> + }
>> + if (arg->field.field->size < 16) {
>> + trace_seq_printf(s, "INVALID UUID: size have %u expect 16",
>> + arg->field.field->size);
>> + return;
>> + }
>> + buf = data + arg->field.field->offset;
>> +
>> + for (i = 0; i < 8; i++) {
>> + trace_seq_printf(s, "%02x", buf[2 * i]);
>> + trace_seq_printf(s, "%02x", buf[2 * i + 1]);
>> + if (1 <= i && i <= 4)
>
> I'm fine with this patch except for one nit. The above is hard to read
> (in my opinion), and I absolutely hate the "constant" compare to
> "variable" notation. Please change the above to:
>
> if (i >= 1 && i <= 4)
Isn't this ( 1 <= i && i <= 4 ) easier to find out the lower and upper
boundary? only two numbers, both at the end of the expression.
I feel that ( i >= 1 && i <= 4 ) easier to write, but takes me extra
half second to read, thus I changed to the current one.
Thanks,
Qu
>
> Thanks,
>
> -- Steve
>
>> + trace_seq_putc(s, '-');
>> + }
>> +}
>> +
On Mon, 21 Oct 2019 22:03:21 +0800
Qu Wenruo <[email protected]> wrote:
> On 2019/10/21 下午9:56, Steven Rostedt wrote:
> > On Mon, 21 Oct 2019 17:47:30 +0800
> > Qu Wenruo <[email protected]> wrote:
> >
> >> +static void print_uuid_arg(struct trace_seq *s, void *data, int size,
> >> + struct tep_event *event, struct tep_print_arg *arg)
> >> +{
> >> + unsigned char *buf;
> >> + int i;
> >> +
> >> + if (arg->type != TEP_PRINT_FIELD) {
> >> + trace_seq_printf(s, "ARG TYPE NOT FIELID but %d", arg->type);
> >> + return;
> >> + }
> >> +
> >> + if (!arg->field.field) {
> >> + arg->field.field = tep_find_any_field(event, arg->field.name);
> >> + if (!arg->field.field) {
> >> + do_warning("%s: field %s not found",
> >> + __func__, arg->field.name);
> >> + return;
> >> + }
> >> + }
> >> + if (arg->field.field->size < 16) {
> >> + trace_seq_printf(s, "INVALID UUID: size have %u expect 16",
> >> + arg->field.field->size);
> >> + return;
> >> + }
> >> + buf = data + arg->field.field->offset;
> >> +
> >> + for (i = 0; i < 8; i++) {
> >> + trace_seq_printf(s, "%02x", buf[2 * i]);
> >> + trace_seq_printf(s, "%02x", buf[2 * i + 1]);
> >> + if (1 <= i && i <= 4)
> >
> > I'm fine with this patch except for one nit. The above is hard to read
> > (in my opinion), and I absolutely hate the "constant" compare to
> > "variable" notation. Please change the above to:
> >
> > if (i >= 1 && i <= 4)
>
> Isn't this ( 1 <= i && i <= 4 ) easier to find out the lower and upper
> boundary? only two numbers, both at the end of the expression.
I don't read it like that.
>
> I feel that ( i >= 1 && i <= 4 ) easier to write, but takes me extra
> half second to read, thus I changed to the current one.
How do you read it in English?
"If one is less than or equal to i and i is less than or equal to
four."
Or
"If i is greater than or equal to one and i is less than or equal to
four."
?
I read it the second way, and I believe most English speakers read it
that way too.
It took me a minute or two to understand the original method, because
my mind likes to take a variable and keep it on the same side of the
comparison, and the variable should always be first.
-- Steve
On 2019/10/21 下午10:24, Steven Rostedt wrote:
> On Mon, 21 Oct 2019 22:03:21 +0800
> Qu Wenruo <[email protected]> wrote:
>
>> On 2019/10/21 下午9:56, Steven Rostedt wrote:
>>> On Mon, 21 Oct 2019 17:47:30 +0800
>>> Qu Wenruo <[email protected]> wrote:
>>>
>>>> +static void print_uuid_arg(struct trace_seq *s, void *data, int size,
>>>> + struct tep_event *event, struct tep_print_arg *arg)
>>>> +{
>>>> + unsigned char *buf;
>>>> + int i;
>>>> +
>>>> + if (arg->type != TEP_PRINT_FIELD) {
>>>> + trace_seq_printf(s, "ARG TYPE NOT FIELID but %d", arg->type);
>>>> + return;
>>>> + }
>>>> +
>>>> + if (!arg->field.field) {
>>>> + arg->field.field = tep_find_any_field(event, arg->field.name);
>>>> + if (!arg->field.field) {
>>>> + do_warning("%s: field %s not found",
>>>> + __func__, arg->field.name);
>>>> + return;
>>>> + }
>>>> + }
>>>> + if (arg->field.field->size < 16) {
>>>> + trace_seq_printf(s, "INVALID UUID: size have %u expect 16",
>>>> + arg->field.field->size);
>>>> + return;
>>>> + }
>>>> + buf = data + arg->field.field->offset;
>>>> +
>>>> + for (i = 0; i < 8; i++) {
>>>> + trace_seq_printf(s, "%02x", buf[2 * i]);
>>>> + trace_seq_printf(s, "%02x", buf[2 * i + 1]);
>>>> + if (1 <= i && i <= 4)
>>>
>>> I'm fine with this patch except for one nit. The above is hard to read
>>> (in my opinion), and I absolutely hate the "constant" compare to
>>> "variable" notation. Please change the above to:
>>>
>>> if (i >= 1 && i <= 4)
>>
>> Isn't this ( 1 <= i && i <= 4 ) easier to find out the lower and upper
>> boundary? only two numbers, both at the end of the expression.
>
> I don't read it like that.
>
>>
>> I feel that ( i >= 1 && i <= 4 ) easier to write, but takes me extra
>> half second to read, thus I changed to the current one.
>
> How do you read it in English?
How about mathematics interval?
i in [1, 4].
It looks way easier and simpler no matter what language you speak.
Thanks,
Qu
>
> "If one is less than or equal to i and i is less than or equal to
> four."
>
> Or
>
> "If i is greater than or equal to one and i is less than or equal to
> four."
>
> ?
>
> I read it the second way, and I believe most English speakers read it
> that way too.
>
> It took me a minute or two to understand the original method, because
> my mind likes to take a variable and keep it on the same side of the
> comparison, and the variable should always be first.
>
> -- Steve
>
>
On Mon, 21 Oct 2019 22:30:37 +0800
Qu Wenruo <[email protected]> wrote:
> > How do you read it in English?
>
> How about mathematics interval?
>
> i in [1, 4].
>
> It looks way easier and simpler no matter what language you speak.
But C doesn't accept that syntax ;-)
-- Steve
FYI, we noticed the following commit (built with gcc-7):
commit: b28d7df1d3335311d1eefe7af091f7e5e20e33bb ("[PATCH v3] tools/lib/traceevent, perf tools: Handle %pU format correctly")
url: https://github.com/0day-ci/linux/commits/Qu-Wenruo/tools-lib-traceevent-perf-tools-Handle-pU-format-correctly/20191024-110530
in testcase: perf-sanity-tests
with following parameters:
perf_compiler: gcc
ucode: 0x27
on test machine: 8 threads Intel(R) Core(TM) i7-4770 CPU @ 3.40GHz with 8G memory
caused below changes (please refer to attached dmesg/kmsg for entire log/backtrace):
If you fix the issue, kindly add following tag
Reported-by: kernel test robot <[email protected]>
2019-10-28 13:36:56 make ARCH= -C /usr/src/perf_selftests-x86_64-rhel-7.6-b28d7df1d3335311d1eefe7af091f7e5e20e33bb/tools/perf
make: Entering directory '/usr/src/perf_selftests-x86_64-rhel-7.6-b28d7df1d3335311d1eefe7af091f7e5e20e33bb/tools/perf'
BUILD: Doing 'make [33m-j8[m' parallel build
HOSTCC fixdep.o
HOSTLD fixdep-in.o
LINK fixdep
diff -u tools/include/uapi/linux/kvm.h include/uapi/linux/kvm.h
diff -u tools/include/uapi/linux/sched.h include/uapi/linux/sched.h
diff -u tools/arch/x86/include/uapi/asm/svm.h arch/x86/include/uapi/asm/svm.h
diff -u tools/arch/x86/include/uapi/asm/vmx.h arch/x86/include/uapi/asm/vmx.h
Auto-detecting system features:
... dwarf: [ [32mon[m ]
... dwarf_getlocations: [ [32mon[m ]
... glibc: [ [32mon[m ]
... gtk2: [ [31mOFF[m ]
... libaudit: [ [32mon[m ]
... libbfd: [ [32mon[m ]
... libcap: [ [31mOFF[m ]
... libelf: [ [32mon[m ]
... libnuma: [ [32mon[m ]
... numa_num_possible_cpus: [ [32mon[m ]
... libperl: [ [31mOFF[m ]
... libpython: [ [32mon[m ]
... libcrypto: [ [31mOFF[m ]
... libunwind: [ [32mon[m ]
... libdw-dwarf-unwind: [ [32mon[m ]
... zlib: [ [32mon[m ]
... lzma: [ [32mon[m ]
... get_cpuid: [ [32mon[m ]
... bpf: [ [32mon[m ]
... libaio: [ [32mon[m ]
... libzstd: [ [32mon[m ]
... disassembler-four-args: [ [31mOFF[m ]
GEN common-cmds.h
CC exec-cmd.o
CC fd/array.o
CC event-parse.o
CC event-plugin.o
CC core.o
MKDIR staticobjs/
CC staticobjs/libbpf.o
CC cpumap.o
LD fd/libapi-in.o
CC threadmap.o
CC fs/fs.o
CC evsel.o
CC help.o
/usr/src/perf_selftests-x86_64-rhel-7.6-b28d7df1d3335311d1eefe7af091f7e5e20e33bb/tools/build/Makefile.build:96: recipe for target 'event-parse.o' failed
Makefile:141: recipe for target 'libtraceevent-in.o' failed
Makefile.perf:734: recipe for target '/usr/src/perf_selftests-x86_64-rhel-7.6-b28d7df1d3335311d1eefe7af091f7e5e20e33bb/tools/lib/traceevent/libtraceevent.a' failed
CC evlist.o
CC fs/tracing_path.o
MKDIR staticobjs/
CC staticobjs/bpf.o
CC staticobjs/nlattr.o
CC zalloc.o
CC xyarray.o
LD fs/libapi-in.o
CC cpu.o
CC debug.o
CC pager.o
CC lib.o
CC staticobjs/btf.o
CC str_error_r.o
CC parse-options.o
CC run-command.o
LD libperf-in.o
LD libapi-in.o
AR libperf.a
CC staticobjs/libbpf_errno.o
CC staticobjs/str_error.o
AR libapi.a
CC staticobjs/netlink.o
CC sigchain.o
CC staticobjs/bpf_prog_linfo.o
CC staticobjs/libbpf_probes.o
CC staticobjs/xsk.o
CC staticobjs/hashmap.o
CC staticobjs/btf_dump.o
CC subcmd-config.o
LD staticobjs/libbpf-in.o
LINK libbpf.a
LD libsubcmd-in.o
AR libsubcmd.a
Makefile.perf:220: recipe for target 'sub-make' failed
Makefile:69: recipe for target 'all' failed
make: Leaving directory '/usr/src/perf_selftests-x86_64-rhel-7.6-b28d7df1d3335311d1eefe7af091f7e5e20e33bb/tools/perf'
To reproduce:
git clone https://github.com/intel/lkp-tests.git
cd lkp-tests
bin/lkp install job.yaml # job file is attached in this email
bin/lkp run job.yaml
Thanks,
Oliver Sang