perf kmem --page stat and gpf_flags translation

[Michael Petlan <mpetlan@redhat.com>]

Hello Steve and others,

We have found out that perf kmem --page stat sometimes fails like the
following:

# perf kmem --page stat
0x2aa28 [0x8]: failed to process type: 68 [Operation not permitted]
error during process events: -1

This seem to happen on s390x KVM machines.

When we tried to investigate for the reasons, it seems that the problem
is caused by incorrect/unexpected translation of gpf_flags for event
kmem:mm_page_alloc.

# perf script
perf   96553 [003] 100299.663963: kmem:mm_page_alloc: page=0x1a8f9 pfn=0x1a8f9 order=0 migratetype=0 gfp_flags=0x500cc2
perf   96553 [003] 100299.663995: kmem:mm_page_alloc: page=0x1bc3f pfn=0x1bc3f order=0 migratetype=0 gfp_flags=0x40cc0
perf   96553 [003] 100299.664001: kmem:mm_page_alloc: page=0x1a9d9 pfn=0x1a9d9 order=0 migratetype=0 gfp_flags=0x40cc0
perf   96553 [003] 100299.664011: kmem:mm_page_alloc: page=0x1788b pfn=0x1788b order=0 migratetype=0 gfp_flags=0x40cc0
perf   96553 [003] 100299.664023: kmem:mm_page_alloc: page=0x17993 pfn=0x17993 order=0 migratetype=0 gfp_flags=0xcc0

On another machine to be compared against, we get the gfp_flags
translated as following:

[...]
perf 1440545 [007] 37432230.091272: kmem:mm_page_alloc: page=0x10d876 pfn=0x10d876 order=0 migratetype=0 gfp_flags=GFP_HIGHUSER|__GFP_ACCOUNT
[...]

When we dig into the translation process, we get into libtraceevent (which
we have in 1.8.2 version), we get into:

     4796 static void print_str_arg(struct trace_seq *s, void *data, int size,
     4797                           struct tep_event *event, const char *format,
     4798                           int len_arg, struct tep_print_arg *arg)
     4799 {
[...]
     4876         case TEP_PRINT_FLAGS:
     4877                 val = eval_num_arg(data, size, event, arg->flags.field);
     4878                 print = 0;
B+   4879                 for (flag = arg->flags.flags; flag; flag = flag->next) {
     4880                         fval = eval_flag(flag->value);
  >  4881                         if (!val && fval < 0) {
     4882                                 print_str_to_seq(s, format, len_arg, flag->str);
     4883                                 break;
     4884                         }
     4885                         if (fval > 0 && (val & fval) == fval) {
b+   4886                                 if (print && arg->flags.delim)
     4887                                         trace_seq_puts(s, arg->flags.delim);
     4888                                 print_str_to_seq(s, format, len_arg, flag->str);
     4889                                 print = 1;
     4890                                 val &= ~fval;
     4891                         }
     4892                 }
b+   4893                 if (val) {
     4894                         if (print && arg->flags.delim)
     4895                                 trace_seq_puts(s, arg->flags.delim);
     4896                         trace_seq_printf(s, "0x%llx", val);
     4897                 }
     4898                 break;

Here in the for loop, we try to apply all the known GFP flags to the
value and if it matches, the flag name is added to the resulting string.
If it does not match (line 4885), finally a fallback solution is used
and the hex number is printed (line 4896).

The reason why it does not match any GPF flag is because the values seem
to be incorrect, so while val == 0x500cc2, the values in flags are 0 or 1:

(gdb) p *flag
$53 = {next = 0x15c3020, value = 0x15c34a0 "1", str = 0x15c2dd0 "GFP_HIGHUSER"}
(gdb) p *flag->next
$54 = {next = 0x15c3ce0, value = 0x15c3740 "1", str = 0x15c3c20 "GFP_USER"}
(gdb) p *flag->next->next
$55 = {next = 0x15c32c0, value = 0x15c2e30 "1", str = 0x15c3800 "GFP_KERNEL_ACCOUNT"}
[...]

which is obviously wrong. On the other machine the values made more sense:

(gdb) p *flag->next->next->next
$133 = {next = 0xee5630, value = 0xee57b0 "1051842", str = 0xee5930 "GFP_HIGHUSER"}
(gdb) p *flag->next->next->next->next
$134 = {next = 0xee5c90, value = 0xee5690 "1051840", str = 0xee62d0 "GFP_USER"}
(gdb) p *flag->next->next->next->next->next
$135 = {next = 0xee5990, value = 0xee5270 "4197568", str = 0xee60f0 "GFP_KERNEL_ACCOUNT"}

...

I am wondering where these values come from and where they are possibly
incorrectly set.

Any ideas?

Thanks!

Michael