This patchset is part of the patchset "extend task comm from 16 to 24"[1].
Now we have different opinion that dynamically allocates memory to store
kthread's long name into a separate pointer, so I decide to take the useful
cleanups apart from the original patchset and send it separately[2].
These useful cleanups can make the usage around task comm less
error-prone. Furthermore, it will be useful if we want to extend task
comm in the future.
[1]. https://lore.kernel.org/lkml/20211101060419.4682-1-laoar.shao@gmail.com/
[2]. https://lore.kernel.org/lkml/CALOAHbAx55AUo3bm8ZepZSZnw7A08cvKPdPyNTf=E_tPqmw5hw@mail.gmail.com/
Changes since v1:
- improve the subject and description
- add comment to explain the hard-coded 16 in patch #4
Cc: Mathieu Desnoyers <mathieu.desnoyers@efficios.com>
Cc: Arnaldo Carvalho de Melo <redacted>
Cc: Alexei Starovoitov <redacted>
Cc: Andrii Nakryiko <redacted>
Cc: Michal Miroslaw <mirq-linux@rere.qmqm.pl>
Cc: Peter Zijlstra <peterz@infradead.org>
Cc: Steven Rostedt <rostedt@goodmis.org>
Cc: Matthew Wilcox <willy@infradead.org>
Cc: David Hildenbrand <redacted>
Cc: Al Viro <viro@zeniv.linux.org.uk>
Cc: Kees Cook <redacted>
Cc: Petr Mladek <pmladek@suse.com>
Yafang Shao (7):
fs/exec: replace strlcpy with strscpy_pad in __set_task_comm
fs/exec: replace strncpy with strscpy_pad in __get_task_comm
drivers/infiniband: replace open-coded string copy with get_task_comm
fs/binfmt_elf: replace open-coded string copy with get_task_comm
samples/bpf/test_overhead_kprobe_kern: replace bpf_probe_read_kernel
with bpf_probe_read_kernel_str to get task comm
tools/bpf/bpftool/skeleton: replace bpf_probe_read_kernel with
bpf_probe_read_kernel_str to get task comm
tools/testing/selftests/bpf: replace open-coded 16 with TASK_COMM_LEN
drivers/infiniband/hw/qib/qib.h | 2 +-
drivers/infiniband/hw/qib/qib_file_ops.c | 2 +-
fs/binfmt_elf.c | 2 +-
fs/exec.c | 5 +++--
include/linux/elfcore-compat.h | 5 +++++
include/linux/elfcore.h | 5 +++++
include/linux/sched.h | 9 +++++++--
samples/bpf/offwaketime_kern.c | 4 ++--
samples/bpf/test_overhead_kprobe_kern.c | 11 ++++++-----
samples/bpf/test_overhead_tp_kern.c | 5 +++--
tools/bpf/bpftool/skeleton/pid_iter.bpf.c | 4 ++--
.../testing/selftests/bpf/progs/test_stacktrace_map.c | 6 +++---
tools/testing/selftests/bpf/progs/test_tracepoint.c | 6 +++---
13 files changed, 42 insertions(+), 24 deletions(-)
--
2.17.1
strlcpy() can trigger out-of-bound reads on the source string[1], we'd
better use strscpy() instead. To make it be robust against full
tsk->comm copies that got noticed in other places, we should make sure
it's zero padded.
[1] https://github.com/KSPP/linux/issues/89
Signed-off-by: Yafang Shao <redacted>
Reviewed-by: Kees Cook <redacted>
Reviewed-by: David Hildenbrand <redacted>
Cc: Mathieu Desnoyers <mathieu.desnoyers@efficios.com>
Cc: Arnaldo Carvalho de Melo <redacted>
Cc: Alexei Starovoitov <redacted>
Cc: Andrii Nakryiko <redacted>
Cc: Michal Miroslaw <mirq-linux@rere.qmqm.pl>
Cc: Peter Zijlstra <peterz@infradead.org>
Cc: Steven Rostedt <rostedt@goodmis.org>
Cc: Matthew Wilcox <willy@infradead.org>
Cc: David Hildenbrand <redacted>
Cc: Al Viro <viro@zeniv.linux.org.uk>
Cc: Kees Cook <redacted>
Cc: Petr Mladek <pmladek@suse.com>
---
fs/exec.c | 2 +-
1 file changed, 1 insertion(+), 1 deletion(-)
If the dest buffer size is smaller than sizeof(tsk->comm), the buffer
will be without null ternimator, that may cause problem. Using
strscpy_pad() instead of strncpy() in __get_task_comm() can make the string
always nul ternimated and zero padded.
Suggested-by: Kees Cook <redacted>
Suggested-by: Steven Rostedt <rostedt@goodmis.org>
Signed-off-by: Yafang Shao <redacted>
Reviewed-by: Kees Cook <redacted>
Reviewed-by: David Hildenbrand <redacted>
Cc: Mathieu Desnoyers <mathieu.desnoyers@efficios.com>
Cc: Arnaldo Carvalho de Melo <redacted>
Cc: Alexei Starovoitov <redacted>
Cc: Andrii Nakryiko <redacted>
Cc: Michal Miroslaw <mirq-linux@rere.qmqm.pl>
Cc: Peter Zijlstra <peterz@infradead.org>
Cc: Steven Rostedt <rostedt@goodmis.org>
Cc: Matthew Wilcox <willy@infradead.org>
Cc: David Hildenbrand <redacted>
Cc: Al Viro <viro@zeniv.linux.org.uk>
Cc: Kees Cook <redacted>
Cc: Petr Mladek <pmladek@suse.com>
---
fs/exec.c | 3 ++-
1 file changed, 2 insertions(+), 1 deletion(-)
bpf_probe_read_kernel_str() will add a nul terminator to the dst, then
we don't care about if the dst size is big enough. This patch also
replaces the hard-coded 16 with TASK_COMM_LEN to make it grepable.
Signed-off-by: Yafang Shao <redacted>
Reviewed-by: Kees Cook <redacted>
Acked-by: Andrii Nakryiko <andrii@kernel.org>
Reviewed-by: David Hildenbrand <redacted>
Cc: Mathieu Desnoyers <mathieu.desnoyers@efficios.com>
Cc: Arnaldo Carvalho de Melo <redacted>
Cc: Alexei Starovoitov <redacted>
Cc: Andrii Nakryiko <redacted>
Cc: Michal Miroslaw <mirq-linux@rere.qmqm.pl>
Cc: Peter Zijlstra <peterz@infradead.org>
Cc: Steven Rostedt <rostedt@goodmis.org>
Cc: Matthew Wilcox <willy@infradead.org>
Cc: David Hildenbrand <redacted>
Cc: Al Viro <viro@zeniv.linux.org.uk>
Cc: Kees Cook <redacted>
Cc: Petr Mladek <pmladek@suse.com>
---
samples/bpf/offwaketime_kern.c | 4 ++--
samples/bpf/test_overhead_kprobe_kern.c | 11 ++++++-----
samples/bpf/test_overhead_tp_kern.c | 5 +++--
3 files changed, 11 insertions(+), 9 deletions(-)
bpf_probe_read_kernel_str() will add a nul terminator to the dst, then
we don't care about if the dst size is big enough.
Signed-off-by: Yafang Shao <redacted>
Acked-by: Andrii Nakryiko <andrii@kernel.org>
Reviewed-by: David Hildenbrand <redacted>
Cc: Mathieu Desnoyers <mathieu.desnoyers@efficios.com>
Cc: Arnaldo Carvalho de Melo <redacted>
Cc: Alexei Starovoitov <redacted>
Cc: Andrii Nakryiko <redacted>
Cc: Michal Miroslaw <mirq-linux@rere.qmqm.pl>
Cc: Peter Zijlstra <peterz@infradead.org>
Cc: Steven Rostedt <rostedt@goodmis.org>
Cc: Matthew Wilcox <willy@infradead.org>
Cc: David Hildenbrand <redacted>
Cc: Al Viro <viro@zeniv.linux.org.uk>
Cc: Kees Cook <redacted>
Cc: Petr Mladek <pmladek@suse.com>
---
tools/bpf/bpftool/skeleton/pid_iter.bpf.c | 4 ++--
1 file changed, 2 insertions(+), 2 deletions(-)
It is better to use get_task_comm() instead of the open coded string
copy as we do in other places.
struct elf_prpsinfo is used to dump the task information in userspace
coredump or kernel vmcore. Below is the verification of vmcore,
crash> ps
PID PPID CPU TASK ST %MEM VSZ RSS COMM
0 0 0 ffffffff9d21a940 RU 0.0 0 0 [swapper/0]
It works well as expected.
Some comments are added to explain why we use the hard-coded 16.
Suggested-by: Kees Cook <redacted>
Signed-off-by: Yafang Shao <redacted>
Reviewed-by: David Hildenbrand <redacted>
Cc: Mathieu Desnoyers <mathieu.desnoyers@efficios.com>
Cc: Arnaldo Carvalho de Melo <redacted>
Cc: Andrii Nakryiko <redacted>
Cc: Michal Miroslaw <mirq-linux@rere.qmqm.pl>
Cc: Peter Zijlstra <peterz@infradead.org>
Cc: Steven Rostedt <rostedt@goodmis.org>
Cc: Matthew Wilcox <willy@infradead.org>
Cc: David Hildenbrand <redacted>
Cc: Al Viro <viro@zeniv.linux.org.uk>
Cc: Kees Cook <redacted>
Cc: Petr Mladek <pmladek@suse.com>
---
fs/binfmt_elf.c | 2 +-
include/linux/elfcore-compat.h | 5 +++++
include/linux/elfcore.h | 5 +++++
3 files changed, 11 insertions(+), 1 deletion(-)
@@ -65,6 +65,11 @@ struct elf_prpsinfo__kernel_gid_tpr_gid;pid_tpr_pid,pr_ppid,pr_pgrp,pr_sid;/* Lots missing */+/*+*Thehard-coded16isderivedfromTASK_COMM_LEN,butitcan'tbe+*changedasitisexposedtouserspace.We'dbettermakeithard-coded+*here.+*/charpr_fname[16];/* filename of executable */charpr_psargs[ELF_PRARGSZ];/* initial part of arg list */};
We'd better use the helper get_task_comm() rather than the open-coded
strlcpy() to get task comm. As the comment above the hard-coded 16, we
can replace it with TASK_COMM_LEN.
Signed-off-by: Yafang Shao <redacted>
Acked-by: Dennis Dalessandro <dennis.dalessandro@cornelisnetworks.com>
Reviewed-by: David Hildenbrand <redacted>
Cc: Mathieu Desnoyers <mathieu.desnoyers@efficios.com>
Cc: Arnaldo Carvalho de Melo <redacted>
Cc: Alexei Starovoitov <redacted>
Cc: Andrii Nakryiko <redacted>
Cc: Michal Miroslaw <mirq-linux@rere.qmqm.pl>
Cc: Peter Zijlstra <peterz@infradead.org>
Cc: Steven Rostedt <rostedt@goodmis.org>
Cc: Matthew Wilcox <willy@infradead.org>
Cc: David Hildenbrand <redacted>
Cc: Al Viro <viro@zeniv.linux.org.uk>
Cc: Kees Cook <redacted>
Cc: Petr Mladek <pmladek@suse.com>
---
drivers/infiniband/hw/qib/qib.h | 2 +-
drivers/infiniband/hw/qib/qib_file_ops.c | 2 +-
2 files changed, 2 insertions(+), 2 deletions(-)
@@ -196,7 +196,7 @@ struct qib_ctxtdata {pid_tpid;pid_tsubpid[QLOGIC_IB_MAX_SUBCTXT];/* same size as task_struct .comm[], command that opened context */-charcomm[16];+charcomm[TASK_COMM_LEN];/* pkeys set by this use of this ctxt */u16pkeys[4];/* so file ops can get at unit */
As the sched:sched_switch tracepoint args are derived from the kernel,
we'd better make it same with the kernel. So the macro TASK_COMM_LEN is
converted to type enum, then all the BPF programs can get it through BTF.
The BPF program which wants to use TASK_COMM_LEN should include the header
vmlinux.h. Regarding the test_stacktrace_map and test_tracepoint, as the
type defined in linux/bpf.h are also defined in vmlinux.h, so we don't
need to include linux/bpf.h again.
Signed-off-by: Yafang Shao <redacted>
Acked-by: Andrii Nakryiko <andrii@kernel.org>
Acked-by: David Hildenbrand <redacted>
Cc: Mathieu Desnoyers <mathieu.desnoyers@efficios.com>
Cc: Arnaldo Carvalho de Melo <redacted>
Cc: Andrii Nakryiko <redacted>
Cc: Michal Miroslaw <mirq-linux@rere.qmqm.pl>
Cc: Peter Zijlstra <peterz@infradead.org>
Cc: Steven Rostedt <rostedt@goodmis.org>
Cc: Matthew Wilcox <willy@infradead.org>
Cc: David Hildenbrand <redacted>
Cc: Al Viro <viro@zeniv.linux.org.uk>
Cc: Kees Cook <redacted>
Cc: Petr Mladek <pmladek@suse.com>
---
include/linux/sched.h | 9 +++++++--
tools/testing/selftests/bpf/progs/test_stacktrace_map.c | 6 +++---
tools/testing/selftests/bpf/progs/test_tracepoint.c | 6 +++---
3 files changed, 13 insertions(+), 8 deletions(-)
@@ -41,11 +41,11 @@ struct {/* taken from /sys/kernel/debug/tracing/events/sched/sched_switch/format */structsched_switch_args{unsignedlonglongpad;-charprev_comm[16];+charprev_comm[TASK_COMM_LEN];intprev_pid;intprev_prio;longlongprev_state;-charnext_comm[16];+charnext_comm[TASK_COMM_LEN];intnext_pid;intnext_prio;};
@@ -65,6 +65,11 @@ struct elf_prpsinfo__kernel_gid_tpr_gid;pid_tpr_pid,pr_ppid,pr_pgrp,pr_sid;/* Lots missing */+/*+*Thehard-coded16isderivedfromTASK_COMM_LEN,butitcan'tbe+*changedasitisexposedtouserspace.We'dbettermakeithard-coded+*here.+*/charpr_fname[16];/* filename of executable */charpr_psargs[ELF_PRARGSZ];/* initial part of arg list */};
Hi Steven,
TASK_COMM_LEN_16 is a good idea, but not all hard-coded 16 can be
replaced by this macro (which is defined in include/sched.h).
For example, the comm[16] in include/uapi/linux/cn_proc.h can't be
replaced as it is a uapi header which can't include linux/sched.h.
That's why I prefer to keep the hard-coded 16 as-is.
There are three options,
- option 1
comment on all the hard-coded 16 to explain why it is hard-coded
- option 2
replace the hard-coded 16 that can be replaced and comment on the
others which can't be replaced.
- option 3
replace the hard-coded 16 that can be replaced and specifically
define TASK_COMM_LEN_16 in other files which can't include
linux/sched.h.
Which one do you prefer ?
@@ -65,6 +65,11 @@ struct elf_prpsinfo__kernel_gid_tpr_gid;pid_tpr_pid,pr_ppid,pr_pgrp,pr_sid;/* Lots missing */+/*+*Thehard-coded16isderivedfromTASK_COMM_LEN,butitcan'tbe+*changedasitisexposedtouserspace.We'dbettermakeithard-coded+*here.+*/charpr_fname[16];/* filename of executable */charpr_psargs[ELF_PRARGSZ];/* initial part of arg list */};
From: Steven Rostedt <rostedt@goodmis.org> Date: 2021-11-30 14:22:49
On Tue, 30 Nov 2021 11:01:27 +0800
Yafang Shao [off-list ref] wrote:
There are three options,
- option 1
comment on all the hard-coded 16 to explain why it is hard-coded
- option 2
replace the hard-coded 16 that can be replaced and comment on the
others which can't be replaced.
- option 3
replace the hard-coded 16 that can be replaced and specifically
define TASK_COMM_LEN_16 in other files which can't include
linux/sched.h.
Which one do you prefer ?
Option 3. Since TASK_COMM_LEN_16 is, by it's name, already hard coded to
16, it doesn't really matter if you define it in more than one location.
Or we could define it in another header that include/sched.h can include.
The idea of having TASK_COMM_LEN_16 is to easily grep for it, and also know
exactly what it is used for when people see it being used.
-- Steve
On Tue, Nov 30, 2021 at 10:22 PM Steven Rostedt [off-list ref] wrote:
On Tue, 30 Nov 2021 11:01:27 +0800
Yafang Shao [off-list ref] wrote:
quoted
There are three options,
- option 1
comment on all the hard-coded 16 to explain why it is hard-coded
- option 2
replace the hard-coded 16 that can be replaced and comment on the
others which can't be replaced.
- option 3
replace the hard-coded 16 that can be replaced and specifically
define TASK_COMM_LEN_16 in other files which can't include
linux/sched.h.
Which one do you prefer ?
Option 3. Since TASK_COMM_LEN_16 is, by it's name, already hard coded to
16, it doesn't really matter if you define it in more than one location.
Or we could define it in another header that include/sched.h can include.
The idea of having TASK_COMM_LEN_16 is to easily grep for it, and also know
exactly what it is used for when people see it being used.
I will send a separate patch (or patchset) to replace all the old
hard-coded 16 with TASK_COMM_LEN_16 based on the -mm tree.
--
Thanks
Yafang
From: John Stultz <jstultz@google.com> Date: 2023-02-08 21:56:11
On Sat, Nov 20, 2021 at 11:27:38AM +0000, Yafang Shao wrote:
As the sched:sched_switch tracepoint args are derived from the kernel,
we'd better make it same with the kernel. So the macro TASK_COMM_LEN is
converted to type enum, then all the BPF programs can get it through BTF.
The BPF program which wants to use TASK_COMM_LEN should include the header
vmlinux.h. Regarding the test_stacktrace_map and test_tracepoint, as the
type defined in linux/bpf.h are also defined in vmlinux.h, so we don't
need to include linux/bpf.h again.
Signed-off-by: Yafang Shao <redacted>
Acked-by: Andrii Nakryiko <andrii@kernel.org>
Acked-by: David Hildenbrand <redacted>
Cc: Mathieu Desnoyers <mathieu.desnoyers@efficios.com>
Cc: Arnaldo Carvalho de Melo <redacted>
Cc: Andrii Nakryiko <redacted>
Cc: Michal Miroslaw <mirq-linux@rere.qmqm.pl>
Cc: Peter Zijlstra <peterz@infradead.org>
Cc: Steven Rostedt <rostedt@goodmis.org>
Cc: Matthew Wilcox <willy@infradead.org>
Cc: David Hildenbrand <redacted>
Cc: Al Viro <viro@zeniv.linux.org.uk>
Cc: Kees Cook <redacted>
Cc: Petr Mladek <pmladek@suse.com>
---
include/linux/sched.h | 9 +++++++--
tools/testing/selftests/bpf/progs/test_stacktrace_map.c | 6 +++---
tools/testing/selftests/bpf/progs/test_tracepoint.c | 6 +++---
3 files changed, 13 insertions(+), 8 deletions(-)
Hey all,
I know this is a little late, but I recently got a report that
this change was causiing older versions of perfetto to stop
working.
Apparently newer versions of perfetto has worked around this
via the following changes:
https://android.googlesource.com/platform/external/perfetto/+/c717c93131b1b6e3705a11092a70ac47c78b731d%5E%21/https://android.googlesource.com/platform/external/perfetto/+/160a504ad5c91a227e55f84d3e5d3fe22af7c2bb%5E%21/
But for older versions of perfetto, reverting upstream commit
3087c61ed2c4 ("tools/testing/selftests/bpf: replace open-coded 16
with TASK_COMM_LEN") is necessary to get it back to working.
I haven't dug very far into the details, and obviously this doesn't
break with the updated perfetto, but from a high level this does
seem to be a breaking-userland regression.
So I wanted to reach out to see if there was more context for this
breakage? I don't want to raise a unnecessary stink if this was
an unfortuante but forced situation.
thanks
-john
On Wed, Feb 8, 2023 at 2:01 PM John Stultz [off-list ref] wrote:
On Sat, Nov 20, 2021 at 11:27:38AM +0000, Yafang Shao wrote:
quoted
As the sched:sched_switch tracepoint args are derived from the kernel,
we'd better make it same with the kernel. So the macro TASK_COMM_LEN is
converted to type enum, then all the BPF programs can get it through BTF.
The BPF program which wants to use TASK_COMM_LEN should include the header
vmlinux.h. Regarding the test_stacktrace_map and test_tracepoint, as the
type defined in linux/bpf.h are also defined in vmlinux.h, so we don't
need to include linux/bpf.h again.
Signed-off-by: Yafang Shao <redacted>
Acked-by: Andrii Nakryiko <andrii@kernel.org>
Acked-by: David Hildenbrand <redacted>
Cc: Mathieu Desnoyers <mathieu.desnoyers@efficios.com>
Cc: Arnaldo Carvalho de Melo <redacted>
Cc: Andrii Nakryiko <redacted>
Cc: Michal Miroslaw <mirq-linux@rere.qmqm.pl>
Cc: Peter Zijlstra <peterz@infradead.org>
Cc: Steven Rostedt <rostedt@goodmis.org>
Cc: Matthew Wilcox <willy@infradead.org>
Cc: David Hildenbrand <redacted>
Cc: Al Viro <viro@zeniv.linux.org.uk>
Cc: Kees Cook <redacted>
Cc: Petr Mladek <pmladek@suse.com>
---
include/linux/sched.h | 9 +++++++--
tools/testing/selftests/bpf/progs/test_stacktrace_map.c | 6 +++---
tools/testing/selftests/bpf/progs/test_tracepoint.c | 6 +++---
3 files changed, 13 insertions(+), 8 deletions(-)
Hey all,
I know this is a little late, but I recently got a report that
this change was causiing older versions of perfetto to stop
working.
Apparently newer versions of perfetto has worked around this
via the following changes:
https://android.googlesource.com/platform/external/perfetto/+/c717c93131b1b6e3705a11092a70ac47c78b731d%5E%21/https://android.googlesource.com/platform/external/perfetto/+/160a504ad5c91a227e55f84d3e5d3fe22af7c2bb%5E%21/
But for older versions of perfetto, reverting upstream commit
3087c61ed2c4 ("tools/testing/selftests/bpf: replace open-coded 16
with TASK_COMM_LEN") is necessary to get it back to working.
I haven't dug very far into the details, and obviously this doesn't
break with the updated perfetto, but from a high level this does
seem to be a breaking-userland regression.
So I wanted to reach out to see if there was more context for this
breakage? I don't want to raise a unnecessary stink if this was
an unfortuante but forced situation.
Let me understand what you're saying...
The commit 3087c61ed2c4 did
-/* Task command name length: */
-#define TASK_COMM_LEN 16
+/*
+ * Define the task command name length as enum, then it can be visible to
+ * BPF programs.
+ */
+enum {
+ TASK_COMM_LEN = 16,
+};
and that caused:
cat /sys/kernel/debug/tracing/events/task/task_newtask/format
to print
field:char comm[TASK_COMM_LEN]; offset:12; size:16; signed:0;
instead of
field:char comm[16]; offset:12; size:16; signed:0;
so the ftrace parsing android tracing tool had to do:
- if (Match(type_and_name.c_str(), R"(char [a-zA-Z_]+\[[0-9]+\])")) {
+ if (Match(type_and_name.c_str(),
+ R"(char [a-zA-Z_][a-zA-Z_0-9]*\[[a-zA-Z_0-9]+\])")) {
to workaround this change.
Right?
And what are you proposing?
From: John Stultz <jstultz@google.com> Date: 2023-02-09 00:54:19
On Wed, Feb 8, 2023 at 4:11 PM Alexei Starovoitov
[off-list ref] wrote:
On Wed, Feb 8, 2023 at 2:01 PM John Stultz [off-list ref] wrote:
quoted
On Sat, Nov 20, 2021 at 11:27:38AM +0000, Yafang Shao wrote:
quoted
As the sched:sched_switch tracepoint args are derived from the kernel,
we'd better make it same with the kernel. So the macro TASK_COMM_LEN is
converted to type enum, then all the BPF programs can get it through BTF.
The BPF program which wants to use TASK_COMM_LEN should include the header
vmlinux.h. Regarding the test_stacktrace_map and test_tracepoint, as the
type defined in linux/bpf.h are also defined in vmlinux.h, so we don't
need to include linux/bpf.h again.
Signed-off-by: Yafang Shao <redacted>
Acked-by: Andrii Nakryiko <andrii@kernel.org>
Acked-by: David Hildenbrand <redacted>
Cc: Mathieu Desnoyers <mathieu.desnoyers@efficios.com>
Cc: Arnaldo Carvalho de Melo <redacted>
Cc: Andrii Nakryiko <redacted>
Cc: Michal Miroslaw <mirq-linux@rere.qmqm.pl>
Cc: Peter Zijlstra <peterz@infradead.org>
Cc: Steven Rostedt <rostedt@goodmis.org>
Cc: Matthew Wilcox <willy@infradead.org>
Cc: David Hildenbrand <redacted>
Cc: Al Viro <viro@zeniv.linux.org.uk>
Cc: Kees Cook <redacted>
Cc: Petr Mladek <pmladek@suse.com>
---
include/linux/sched.h | 9 +++++++--
tools/testing/selftests/bpf/progs/test_stacktrace_map.c | 6 +++---
tools/testing/selftests/bpf/progs/test_tracepoint.c | 6 +++---
3 files changed, 13 insertions(+), 8 deletions(-)
Hey all,
I know this is a little late, but I recently got a report that
this change was causiing older versions of perfetto to stop
working.
Apparently newer versions of perfetto has worked around this
via the following changes:
https://android.googlesource.com/platform/external/perfetto/+/c717c93131b1b6e3705a11092a70ac47c78b731d%5E%21/https://android.googlesource.com/platform/external/perfetto/+/160a504ad5c91a227e55f84d3e5d3fe22af7c2bb%5E%21/
But for older versions of perfetto, reverting upstream commit
3087c61ed2c4 ("tools/testing/selftests/bpf: replace open-coded 16
with TASK_COMM_LEN") is necessary to get it back to working.
I haven't dug very far into the details, and obviously this doesn't
break with the updated perfetto, but from a high level this does
seem to be a breaking-userland regression.
So I wanted to reach out to see if there was more context for this
breakage? I don't want to raise a unnecessary stink if this was
an unfortuante but forced situation.
Let me understand what you're saying...
The commit 3087c61ed2c4 did
-/* Task command name length: */
-#define TASK_COMM_LEN 16
+/*
+ * Define the task command name length as enum, then it can be visible to
+ * BPF programs.
+ */
+enum {
+ TASK_COMM_LEN = 16,
+};
and that caused:
cat /sys/kernel/debug/tracing/events/task/task_newtask/format
to print
field:char comm[TASK_COMM_LEN]; offset:12; size:16; signed:0;
instead of
field:char comm[16]; offset:12; size:16; signed:0;
so the ftrace parsing android tracing tool had to do:
- if (Match(type_and_name.c_str(), R"(char [a-zA-Z_]+\[[0-9]+\])")) {
+ if (Match(type_and_name.c_str(),
+ R"(char [a-zA-Z_][a-zA-Z_0-9]*\[[a-zA-Z_0-9]+\])")) {
to workaround this change.
Right?
I believe so.
And what are you proposing?
I'm not proposing anything. I was just wanting to understand more
context around this, as it outwardly appears to be a user-breaking
change, and that is usually not done, so I figured it was an issue
worth raising.
If the debug/tracing/*/format output is in the murky not-really-abi
space, that's fine, but I wanted to know if this was understood as
something that may require userland updates or if this was a
unexpected side-effect.
thanks
-john
On Wed, Feb 8, 2023 at 4:11 PM Alexei Starovoitov
[off-list ref] wrote:
quoted
On Wed, Feb 8, 2023 at 2:01 PM John Stultz [off-list ref] wrote:
quoted
On Sat, Nov 20, 2021 at 11:27:38AM +0000, Yafang Shao wrote:
quoted
As the sched:sched_switch tracepoint args are derived from the kernel,
we'd better make it same with the kernel. So the macro TASK_COMM_LEN is
converted to type enum, then all the BPF programs can get it through BTF.
The BPF program which wants to use TASK_COMM_LEN should include the header
vmlinux.h. Regarding the test_stacktrace_map and test_tracepoint, as the
type defined in linux/bpf.h are also defined in vmlinux.h, so we don't
need to include linux/bpf.h again.
Signed-off-by: Yafang Shao <redacted>
Acked-by: Andrii Nakryiko <andrii@kernel.org>
Acked-by: David Hildenbrand <redacted>
Cc: Mathieu Desnoyers <mathieu.desnoyers@efficios.com>
Cc: Arnaldo Carvalho de Melo <redacted>
Cc: Andrii Nakryiko <redacted>
Cc: Michal Miroslaw <mirq-linux@rere.qmqm.pl>
Cc: Peter Zijlstra <peterz@infradead.org>
Cc: Steven Rostedt <rostedt@goodmis.org>
Cc: Matthew Wilcox <willy@infradead.org>
Cc: David Hildenbrand <redacted>
Cc: Al Viro <viro@zeniv.linux.org.uk>
Cc: Kees Cook <redacted>
Cc: Petr Mladek <pmladek@suse.com>
---
include/linux/sched.h | 9 +++++++--
tools/testing/selftests/bpf/progs/test_stacktrace_map.c | 6 +++---
tools/testing/selftests/bpf/progs/test_tracepoint.c | 6 +++---
3 files changed, 13 insertions(+), 8 deletions(-)
Hey all,
I know this is a little late, but I recently got a report that
this change was causiing older versions of perfetto to stop
working.
Apparently newer versions of perfetto has worked around this
via the following changes:
https://android.googlesource.com/platform/external/perfetto/+/c717c93131b1b6e3705a11092a70ac47c78b731d%5E%21/https://android.googlesource.com/platform/external/perfetto/+/160a504ad5c91a227e55f84d3e5d3fe22af7c2bb%5E%21/
But for older versions of perfetto, reverting upstream commit
3087c61ed2c4 ("tools/testing/selftests/bpf: replace open-coded 16
with TASK_COMM_LEN") is necessary to get it back to working.
I haven't dug very far into the details, and obviously this doesn't
break with the updated perfetto, but from a high level this does
seem to be a breaking-userland regression.
So I wanted to reach out to see if there was more context for this
breakage? I don't want to raise a unnecessary stink if this was
an unfortuante but forced situation.
Let me understand what you're saying...
The commit 3087c61ed2c4 did
-/* Task command name length: */
-#define TASK_COMM_LEN 16
+/*
+ * Define the task command name length as enum, then it can be visible to
+ * BPF programs.
+ */
+enum {
+ TASK_COMM_LEN = 16,
+};
and that caused:
cat /sys/kernel/debug/tracing/events/task/task_newtask/format
to print
field:char comm[TASK_COMM_LEN]; offset:12; size:16; signed:0;
instead of
field:char comm[16]; offset:12; size:16; signed:0;
so the ftrace parsing android tracing tool had to do:
- if (Match(type_and_name.c_str(), R"(char [a-zA-Z_]+\[[0-9]+\])")) {
+ if (Match(type_and_name.c_str(),
+ R"(char [a-zA-Z_][a-zA-Z_0-9]*\[[a-zA-Z_0-9]+\])")) {
to workaround this change.
Right?
I believe so.
quoted
And what are you proposing?
I'm not proposing anything. I was just wanting to understand more
context around this, as it outwardly appears to be a user-breaking
change, and that is usually not done, so I figured it was an issue
worth raising.
If the debug/tracing/*/format output is in the murky not-really-abi
space, that's fine, but I wanted to know if this was understood as
something that may require userland updates or if this was a
unexpected side-effect.
If you are looking at the root cause in the kernel code generating this:
kernel/trace/trace_events.c:f_show()
/*
* Smartly shows the array type(except dynamic array).
* Normal:
* field:TYPE VAR
* If TYPE := TYPE[LEN], it is shown:
* field:TYPE VAR[LEN]
*/
where it uses the content of field->type (a string) to format the VAR[LEN] part.
This in turn is the result of the definition of the
struct trace_event_fields done in:
include/trace/trace_events.h at stage 4, thus with the context of those macros defined:
include/trace/stages/stage4_event_fields.h:
#undef __array
#define __array(_type, _item, _len) { \
.type = #_type"["__stringify(_len)"]", .name = #_item, \
.size = sizeof(_type[_len]), .align = ALIGN_STRUCTFIELD(_type), \
.is_signed = is_signed_type(_type), .filter_type = FILTER_OTHER },
I suspect the real culprit here is the use of __stringify(_len), which happens to work
on macros, but not on enum labels.
One possible solution to make this more robust would be to extend
struct trace_event_fields with one more field that indicates the length
of an array as an actual integer, without storing it in its stringified
form in the type, and do the formatting in f_show where it belongs.
This way everybody can stay happy and no ABI is broken.
Thoughts ?
Thanks,
Mathieu
--
Mathieu Desnoyers
EfficiOS Inc.
https://www.efficios.com
From: Steven Rostedt <rostedt@goodmis.org> Date: 2023-02-09 02:29:11
On Wed, 8 Feb 2023 16:54:03 -0800
John Stultz [off-list ref] wrote:
quoted
Let me understand what you're saying...
The commit 3087c61ed2c4 did
-/* Task command name length: */
-#define TASK_COMM_LEN 16
+/*
+ * Define the task command name length as enum, then it can be visible to
+ * BPF programs.
+ */
+enum {
+ TASK_COMM_LEN = 16,
+};
and that caused:
cat /sys/kernel/debug/tracing/events/task/task_newtask/format
to print
field:char comm[TASK_COMM_LEN]; offset:12; size:16; signed:0;
Yes because there's no easy way to automatically convert an enum to a
number. And this has been a macro for a very long time (so it works,
because macros convert to numbers).
And this breaks much more than android. It will break trace-cmd, rasdaemon
and perf (if it's not using BTF). This change very much "Breaks userspace!"
And requires a kernel workaround, not a user space one.
quoted
instead of
field:char comm[16]; offset:12; size:16; signed:0;
so the ftrace parsing android tracing tool had to do:
- if (Match(type_and_name.c_str(), R"(char [a-zA-Z_]+\[[0-9]+\])")) {
+ if (Match(type_and_name.c_str(),
+ R"(char [a-zA-Z_][a-zA-Z_0-9]*\[[a-zA-Z_0-9]+\])")) {
to workaround this change.
Right?
I believe so.
quoted
And what are you proposing?
I'm not proposing anything. I was just wanting to understand more
context around this, as it outwardly appears to be a user-breaking
change, and that is usually not done, so I figured it was an issue
worth raising.
If the debug/tracing/*/format output is in the murky not-really-abi
space, that's fine, but I wanted to know if this was understood as
something that may require userland updates or if this was a
unexpected side-effect.
Linus has already said that /sys/kernel/tracing/* is an ABI (fyi, getting
to the tracing directory via debugfs is obsolete).
Usually, when a trace event uses an enum, it can do:
TRACE_DEFINE_ENUM(TASK_COMM_LEN);
But that's a very common define. It would require it updated for every trace
event, or the change needs to be reverted.
Not sure why BTF needs it like this, because it hasn't changed in years.
Can't it just hard code it?
For ftrace to change it, it requires reading the format files at boot up
and replacing the enums with the numbers, which does impact start up.
-- Steve
From: Steven Rostedt <rostedt@goodmis.org> Date: 2023-02-09 02:34:00
On Wed, 8 Feb 2023 21:28:58 -0500
Steven Rostedt [off-list ref] wrote:
And this breaks much more than android. It will break trace-cmd, rasdaemon
and perf (if it's not using BTF). This change very much "Breaks userspace!"
And requires a kernel workaround, not a user space one.
OK, so it doesn't break perf, trace-cmd and rasdaemon, because the enum is
only needed in the print_fmt part. It can handle it in the field portion.
That is:
system: sched
name: sched_switch
ID: 285
format:
field:unsigned short common_type; offset:0; size:2; signed:0;
field:unsigned char common_flags; offset:2; size:1; signed:0;
field:unsigned char common_preempt_count; offset:3; size:1; signed:0;
field:int common_pid; offset:4; size:4; signed:1;
field:char prev_comm[TASK_COMM_LEN]; offset:8; size:16; signed:0;
^^^^^^^^^^^^^^ ^^
is ignored is used
field:pid_t prev_pid; offset:24; size:4; signed:1;
field:int prev_prio; offset:28; size:4; signed:1;
field:long prev_state; offset:32; size:8; signed:1;
field:char next_comm[TASK_COMM_LEN]; offset:40; size:16; signed:0;
field:pid_t next_pid; offset:56; size:4; signed:1;
field:int next_prio; offset:60; size:4; signed:1;
print fmt: "prev_comm=%s prev_pid=%d prev_prio=%d prev_state=%s%s ==> next_comm=%s next_pid=%d next_prio=%d", REC->prev_comm, REC->prev_pid, REC->prev_prio, (REC->prev_state & ((((0x00000000 | 0x00000001 | 0x00000002 | 0x00000004 | 0x00000008 | 0x00000010 | 0x00000020 | 0x00000040) + 1) << 1) - 1)) ? __print_flags(REC->prev_state & ((((0x00000000 | 0x00000001 | 0x00000002 | 0x00000004 | 0x00000008 | 0x00000010 | 0x00000020 | 0x00000040) + 1) << 1) - 1), "|", { 0x00000001, "S" }, { 0x00000002, "D" }, { 0x00000004, "T" }, { 0x00000008, "t" }, { 0x00000010, "X" }, { 0x00000020, "Z" }, { 0x00000040, "P" }, { 0x00000080, "I" }) : "R", REC->prev_state & (((0x00000000 | 0x00000001 | 0x00000002 | 0x00000004 | 0x00000008 | 0x00000010 | 0x00000020 | 0x00000040) + 1) << 1) ? "+" : "", REC->next_comm, REC->next_pid, REC->next_prio
^^^^^^^
Is what requires the conversions. So I take that back. It only breaks
perfetto, and that's because it writes its own parser and doesn't use
libtraceevent.
-- Steve
On Thu, Feb 9, 2023 at 10:07 AM Mathieu Desnoyers
[off-list ref] wrote:
On 2023-02-08 19:54, John Stultz wrote:
quoted
On Wed, Feb 8, 2023 at 4:11 PM Alexei Starovoitov
[off-list ref] wrote:
quoted
On Wed, Feb 8, 2023 at 2:01 PM John Stultz [off-list ref] wrote:
quoted
On Sat, Nov 20, 2021 at 11:27:38AM +0000, Yafang Shao wrote:
quoted
As the sched:sched_switch tracepoint args are derived from the kernel,
we'd better make it same with the kernel. So the macro TASK_COMM_LEN is
converted to type enum, then all the BPF programs can get it through BTF.
The BPF program which wants to use TASK_COMM_LEN should include the header
vmlinux.h. Regarding the test_stacktrace_map and test_tracepoint, as the
type defined in linux/bpf.h are also defined in vmlinux.h, so we don't
need to include linux/bpf.h again.
Signed-off-by: Yafang Shao <redacted>
Acked-by: Andrii Nakryiko <andrii@kernel.org>
Acked-by: David Hildenbrand <redacted>
Cc: Mathieu Desnoyers <mathieu.desnoyers@efficios.com>
Cc: Arnaldo Carvalho de Melo <redacted>
Cc: Andrii Nakryiko <redacted>
Cc: Michal Miroslaw <mirq-linux@rere.qmqm.pl>
Cc: Peter Zijlstra <peterz@infradead.org>
Cc: Steven Rostedt <rostedt@goodmis.org>
Cc: Matthew Wilcox <willy@infradead.org>
Cc: David Hildenbrand <redacted>
Cc: Al Viro <viro@zeniv.linux.org.uk>
Cc: Kees Cook <redacted>
Cc: Petr Mladek <pmladek@suse.com>
---
include/linux/sched.h | 9 +++++++--
tools/testing/selftests/bpf/progs/test_stacktrace_map.c | 6 +++---
tools/testing/selftests/bpf/progs/test_tracepoint.c | 6 +++---
3 files changed, 13 insertions(+), 8 deletions(-)
Hey all,
I know this is a little late, but I recently got a report that
this change was causiing older versions of perfetto to stop
working.
Apparently newer versions of perfetto has worked around this
via the following changes:
https://android.googlesource.com/platform/external/perfetto/+/c717c93131b1b6e3705a11092a70ac47c78b731d%5E%21/https://android.googlesource.com/platform/external/perfetto/+/160a504ad5c91a227e55f84d3e5d3fe22af7c2bb%5E%21/
But for older versions of perfetto, reverting upstream commit
3087c61ed2c4 ("tools/testing/selftests/bpf: replace open-coded 16
with TASK_COMM_LEN") is necessary to get it back to working.
I haven't dug very far into the details, and obviously this doesn't
break with the updated perfetto, but from a high level this does
seem to be a breaking-userland regression.
So I wanted to reach out to see if there was more context for this
breakage? I don't want to raise a unnecessary stink if this was
an unfortuante but forced situation.
Let me understand what you're saying...
The commit 3087c61ed2c4 did
-/* Task command name length: */
-#define TASK_COMM_LEN 16
+/*
+ * Define the task command name length as enum, then it can be visible to
+ * BPF programs.
+ */
+enum {
+ TASK_COMM_LEN = 16,
+};
and that caused:
cat /sys/kernel/debug/tracing/events/task/task_newtask/format
to print
field:char comm[TASK_COMM_LEN]; offset:12; size:16; signed:0;
instead of
field:char comm[16]; offset:12; size:16; signed:0;
so the ftrace parsing android tracing tool had to do:
- if (Match(type_and_name.c_str(), R"(char [a-zA-Z_]+\[[0-9]+\])")) {
+ if (Match(type_and_name.c_str(),
+ R"(char [a-zA-Z_][a-zA-Z_0-9]*\[[a-zA-Z_0-9]+\])")) {
to workaround this change.
Right?
I believe so.
quoted
And what are you proposing?
I'm not proposing anything. I was just wanting to understand more
context around this, as it outwardly appears to be a user-breaking
change, and that is usually not done, so I figured it was an issue
worth raising.
If the debug/tracing/*/format output is in the murky not-really-abi
space, that's fine, but I wanted to know if this was understood as
something that may require userland updates or if this was a
unexpected side-effect.
If you are looking at the root cause in the kernel code generating this:
kernel/trace/trace_events.c:f_show()
/*
* Smartly shows the array type(except dynamic array).
* Normal:
* field:TYPE VAR
* If TYPE := TYPE[LEN], it is shown:
* field:TYPE VAR[LEN]
*/
where it uses the content of field->type (a string) to format the VAR[LEN] part.
This in turn is the result of the definition of the
struct trace_event_fields done in:
include/trace/trace_events.h at stage 4, thus with the context of those macros defined:
include/trace/stages/stage4_event_fields.h:
#undef __array
#define __array(_type, _item, _len) { \
.type = #_type"["__stringify(_len)"]", .name = #_item, \
.size = sizeof(_type[_len]), .align = ALIGN_STRUCTFIELD(_type), \
.is_signed = is_signed_type(_type), .filter_type = FILTER_OTHER },
I suspect the real culprit here is the use of __stringify(_len), which happens to work
on macros, but not on enum labels.
One possible solution to make this more robust would be to extend
struct trace_event_fields with one more field that indicates the length
of an array as an actual integer, without storing it in its stringified
form in the type, and do the formatting in f_show where it belongs.
This way everybody can stay happy and no ABI is broken.
Thoughts ?
Many thanks for the detailed analysis. Seems it can work.
Hi John,
Could you pls. try the attached fix ? I have verified it in my test env.
--
Regards
Yafang
On Thu, Feb 09, 2023 at 02:20:36PM +0800, Yafang Shao wrote:
[...]
Hi Yafang,
Many thanks for the detailed analysis. Seems it can work.
Hi John,
Could you pls. try the attached fix ? I have verified it in my test env.
I tested the patch on my environment where I found the issue with newer
kernels + older Perfetto. The patch does improve things so that's nice.
It goes from "not working at all" to "mostly working but missing data"
compared to what happens if I just revert 3087c61ed2c48548b74dd343a5209b87082c682d.
I'm just an end user so can't really speak to the underlying causes but
for those more familiar with how Perfetto works this is what I'm getting:
Error stats for this trace:
name idx source value
---------------------------------------- ---------------------------------------- ---------------------------------------- ----------------------------------------
mismatched_sched_switch_tids [NULL] analysis 11101
systrace_parse_failure [NULL] analysis 19040
The trace explorer window ends up containing the ftrace-specific tracks
but missing the tracks related to Android-specific callbacks and such.
Debug stats below in case they're relevant:
Name Value Type
android_br_parse_errors 0 error (trace)
android_log_format_invalid 0 error (trace)
android_log_num_failed 0 error (trace)
android_log_num_skipped 0 info (trace)
android_log_num_total 0 info (trace)
clock_sync_cache_miss 181 info (analysis)
clock_sync_failure 0 error (analysis)
compact_sched_has_parse_errors 0 error (trace)
compact_sched_switch_skipped 0 info (analysis)
compact_sched_waking_skipped 0 info (analysis)
counter_events_out_of_order 0 error (analysis)
deobfuscate_location_parse_error 0 error (trace)
empty_chrome_metadata 0 error (trace)
energy_breakdown_missing_values 0 error (analysis)
energy_descriptor_invalid 0 error (analysis)
energy_uid_breakdown_missing_values 0 error (analysis)
flow_duplicate_id 0 error (trace)
flow_end_without_start 0 info (trace)
flow_invalid_id 0 error (trace)
flow_no_enclosing_slice 0 error (trace)
flow_step_without_start 0 info (trace)
flow_without_direction 0 error (trace)
frame_timeline_event_parser_errors 0 info (analysis)
ftrace_bundle_tokenizer_errors 0 error (analysis)
ftrace_cpu_bytes_read_begin[0] 0 info (trace)
ftrace_cpu_bytes_read_begin[1] 264 info (trace)
ftrace_cpu_bytes_read_begin[2] 0 info (trace)
ftrace_cpu_bytes_read_begin[3] 224 info (trace)
ftrace_cpu_bytes_read_begin[4] 0 info (trace)
ftrace_cpu_bytes_read_begin[5] 0 info (trace)
ftrace_cpu_bytes_read_begin[6] 0 info (trace)
ftrace_cpu_bytes_read_begin[7] 0 info (trace)
ftrace_cpu_bytes_read_delta[0] 6919836 info (trace)
ftrace_cpu_bytes_read_delta[1] 7197556 info (trace)
ftrace_cpu_bytes_read_delta[2] 6381828 info (trace)
ftrace_cpu_bytes_read_delta[3] 5988336 info (trace)
ftrace_cpu_bytes_read_delta[4] 5933528 info (trace)
ftrace_cpu_bytes_read_delta[5] 4858400 info (trace)
ftrace_cpu_bytes_read_delta[6] 6175260 info (trace)
ftrace_cpu_bytes_read_delta[7] 4633460 info (trace)
ftrace_cpu_bytes_read_end[0] 6919836 info (trace)
ftrace_cpu_bytes_read_end[1] 7197820 info (trace)
ftrace_cpu_bytes_read_end[2] 6381828 info (trace)
ftrace_cpu_bytes_read_end[3] 5988560 info (trace)
ftrace_cpu_bytes_read_end[4] 5933528 info (trace)
ftrace_cpu_bytes_read_end[5] 4858400 info (trace)
ftrace_cpu_bytes_read_end[6] 6175260 info (trace)
ftrace_cpu_bytes_read_end[7] 4633460 info (trace)
ftrace_cpu_commit_overrun_begin[0] 0 info (trace)
ftrace_cpu_commit_overrun_begin[1] 0 info (trace)
ftrace_cpu_commit_overrun_begin[2] 0 info (trace)
ftrace_cpu_commit_overrun_begin[3] 0 info (trace)
ftrace_cpu_commit_overrun_begin[4] 0 info (trace)
ftrace_cpu_commit_overrun_begin[5] 0 info (trace)
ftrace_cpu_commit_overrun_begin[6] 0 info (trace)
ftrace_cpu_commit_overrun_begin[7] 0 info (trace)
ftrace_cpu_commit_overrun_delta[0] 0 error (trace)
ftrace_cpu_commit_overrun_delta[1] 0 error (trace)
ftrace_cpu_commit_overrun_delta[2] 0 error (trace)
ftrace_cpu_commit_overrun_delta[3] 0 error (trace)
ftrace_cpu_commit_overrun_delta[4] 0 error (trace)
ftrace_cpu_commit_overrun_delta[5] 0 error (trace)
ftrace_cpu_commit_overrun_delta[6] 0 error (trace)
ftrace_cpu_commit_overrun_delta[7] 0 error (trace)
ftrace_cpu_commit_overrun_end[0] 0 info (trace)
ftrace_cpu_commit_overrun_end[1] 0 info (trace)
ftrace_cpu_commit_overrun_end[2] 0 info (trace)
ftrace_cpu_commit_overrun_end[3] 0 info (trace)
ftrace_cpu_commit_overrun_end[4] 0 info (trace)
ftrace_cpu_commit_overrun_end[5] 0 info (trace)
ftrace_cpu_commit_overrun_end[6] 0 info (trace)
ftrace_cpu_commit_overrun_end[7] 0 info (trace)
ftrace_cpu_dropped_events_begin[0] 0 info (trace)
ftrace_cpu_dropped_events_begin[1] 0 info (trace)
ftrace_cpu_dropped_events_begin[2] 0 info (trace)
ftrace_cpu_dropped_events_begin[3] 0 info (trace)
ftrace_cpu_dropped_events_begin[4] 0 info (trace)
ftrace_cpu_dropped_events_begin[5] 0 info (trace)
ftrace_cpu_dropped_events_begin[6] 0 info (trace)
ftrace_cpu_dropped_events_begin[7] 0 info (trace)
ftrace_cpu_dropped_events_delta[0] 0 error (trace)
ftrace_cpu_dropped_events_delta[1] 0 error (trace)
ftrace_cpu_dropped_events_delta[2] 0 error (trace)
ftrace_cpu_dropped_events_delta[3] 0 error (trace)
ftrace_cpu_dropped_events_delta[4] 0 error (trace)
ftrace_cpu_dropped_events_delta[5] 0 error (trace)
ftrace_cpu_dropped_events_delta[6] 0 error (trace)
ftrace_cpu_dropped_events_delta[7] 0 error (trace)
ftrace_cpu_dropped_events_end[0] 0 info (trace)
ftrace_cpu_dropped_events_end[1] 0 info (trace)
ftrace_cpu_dropped_events_end[2] 0 info (trace)
ftrace_cpu_dropped_events_end[3] 0 info (trace)
ftrace_cpu_dropped_events_end[4] 0 info (trace)
ftrace_cpu_dropped_events_end[5] 0 info (trace)
ftrace_cpu_dropped_events_end[6] 0 info (trace)
ftrace_cpu_dropped_events_end[7] 0 info (trace)
ftrace_cpu_entries_begin[0] 0 info (trace)
ftrace_cpu_entries_begin[1] 6 info (trace)
ftrace_cpu_entries_begin[2] 0 info (trace)
ftrace_cpu_entries_begin[3] 5 info (trace)
ftrace_cpu_entries_begin[4] 0 info (trace)
ftrace_cpu_entries_begin[5] 0 info (trace)
ftrace_cpu_entries_begin[6] 0 info (trace)
ftrace_cpu_entries_begin[7] 0 info (trace)
ftrace_cpu_entries_delta[0] 6 info (trace)
ftrace_cpu_entries_delta[1] -6 info (trace)
ftrace_cpu_entries_delta[2] 0 info (trace)
ftrace_cpu_entries_delta[3] 2 info (trace)
ftrace_cpu_entries_delta[4] 0 info (trace)
ftrace_cpu_entries_delta[5] 0 info (trace)
ftrace_cpu_entries_delta[6] 0 info (trace)
ftrace_cpu_entries_delta[7] 0 info (trace)
ftrace_cpu_entries_end[0] 6 info (trace)
ftrace_cpu_entries_end[1] 0 info (trace)
ftrace_cpu_entries_end[2] 0 info (trace)
ftrace_cpu_entries_end[3] 7 info (trace)
ftrace_cpu_entries_end[4] 0 info (trace)
ftrace_cpu_entries_end[5] 0 info (trace)
ftrace_cpu_entries_end[6] 0 info (trace)
ftrace_cpu_entries_end[7] 0 info (trace)
ftrace_cpu_now_ts_begin[0] 93305027000 info (trace)
ftrace_cpu_now_ts_begin[1] 93305103000 info (trace)
ftrace_cpu_now_ts_begin[2] 93305159000 info (trace)
ftrace_cpu_now_ts_begin[3] 93305207000 info (trace)
ftrace_cpu_now_ts_begin[4] 93305262000 info (trace)
ftrace_cpu_now_ts_begin[5] 93305312000 info (trace)
ftrace_cpu_now_ts_begin[6] 93305362000 info (trace)
ftrace_cpu_now_ts_begin[7] 93305411000 info (trace)
ftrace_cpu_now_ts_end[0] 282906571000 info (trace)
ftrace_cpu_now_ts_end[1] 282906676000 info (trace)
ftrace_cpu_now_ts_end[2] 282906738000 info (trace)
ftrace_cpu_now_ts_end[3] 282906803000 info (trace)
ftrace_cpu_now_ts_end[4] 282906863000 info (trace)
ftrace_cpu_now_ts_end[5] 282906925000 info (trace)
ftrace_cpu_now_ts_end[6] 282906987000 info (trace)
ftrace_cpu_now_ts_end[7] 282907048000 info (trace)
ftrace_cpu_oldest_event_ts_begin[0] 0 info (trace)
ftrace_cpu_oldest_event_ts_begin[1] 93304642000 info (trace)
ftrace_cpu_oldest_event_ts_begin[2] 0 info (trace)
ftrace_cpu_oldest_event_ts_begin[3] 93304876000 info (trace)
ftrace_cpu_oldest_event_ts_begin[4] 0 info (trace)
ftrace_cpu_oldest_event_ts_begin[5] 0 info (trace)
ftrace_cpu_oldest_event_ts_begin[6] 0 info (trace)
ftrace_cpu_oldest_event_ts_begin[7] 0 info (trace)
ftrace_cpu_oldest_event_ts_end[0] 282905715000 info (trace)
ftrace_cpu_oldest_event_ts_end[1] 282903723000 info (trace)
ftrace_cpu_oldest_event_ts_end[2] 282903881000 info (trace)
ftrace_cpu_oldest_event_ts_end[3] 282816175000 info (trace)
ftrace_cpu_oldest_event_ts_end[4] 282896619000 info (trace)
ftrace_cpu_oldest_event_ts_end[5] 282884168000 info (trace)
ftrace_cpu_oldest_event_ts_end[6] 282783221000 info (trace)
ftrace_cpu_oldest_event_ts_end[7] 282880081000 info (trace)
ftrace_cpu_overrun_begin[0] 0 info (trace)
ftrace_cpu_overrun_begin[1] 0 info (trace)
ftrace_cpu_overrun_begin[2] 0 info (trace)
ftrace_cpu_overrun_begin[3] 0 info (trace)
ftrace_cpu_overrun_begin[4] 0 info (trace)
ftrace_cpu_overrun_begin[5] 0 info (trace)
ftrace_cpu_overrun_begin[6] 0 info (trace)
ftrace_cpu_overrun_begin[7] 0 info (trace)
ftrace_cpu_overrun_delta[0]help_outline 0 data_loss (trace)
ftrace_cpu_overrun_delta[1]help_outline 0 data_loss (trace)
ftrace_cpu_overrun_delta[2]help_outline 0 data_loss (trace)
ftrace_cpu_overrun_delta[3]help_outline 0 data_loss (trace)
ftrace_cpu_overrun_delta[4]help_outline 0 data_loss (trace)
ftrace_cpu_overrun_delta[5]help_outline 0 data_loss (trace)
ftrace_cpu_overrun_delta[6]help_outline 0 data_loss (trace)
ftrace_cpu_overrun_delta[7]help_outline 0 data_loss (trace)
ftrace_cpu_overrun_end[0] 0 info (trace)
ftrace_cpu_overrun_end[1] 0 info (trace)
ftrace_cpu_overrun_end[2] 0 info (trace)
ftrace_cpu_overrun_end[3] 0 info (trace)
ftrace_cpu_overrun_end[4] 0 info (trace)
ftrace_cpu_overrun_end[5] 0 info (trace)
ftrace_cpu_overrun_end[6] 0 info (trace)
ftrace_cpu_overrun_end[7] 0 info (trace)
ftrace_cpu_read_events_begin[0] 0 info (trace)
ftrace_cpu_read_events_begin[1] 0 info (trace)
ftrace_cpu_read_events_begin[2] 0 info (trace)
ftrace_cpu_read_events_begin[3] 0 info (trace)
ftrace_cpu_read_events_begin[4] 0 info (trace)
ftrace_cpu_read_events_begin[5] 0 info (trace)
ftrace_cpu_read_events_begin[6] 0 info (trace)
ftrace_cpu_read_events_begin[7] 0 info (trace)
ftrace_cpu_read_events_delta[0] 454848 info (trace)
ftrace_cpu_read_events_delta[1] 453484 info (trace)
ftrace_cpu_read_events_delta[2] 386290 info (trace)
ftrace_cpu_read_events_delta[3] 356432 info (trace)
ftrace_cpu_read_events_delta[4] 393337 info (trace)
ftrace_cpu_read_events_delta[5] 325244 info (trace)
ftrace_cpu_read_events_delta[6] 392637 info (trace)
ftrace_cpu_read_events_delta[7] 350623 info (trace)
ftrace_cpu_read_events_end[0] 454848 info (trace)
ftrace_cpu_read_events_end[1] 453484 info (trace)
ftrace_cpu_read_events_end[2] 386290 info (trace)
ftrace_cpu_read_events_end[3] 356432 info (trace)
ftrace_cpu_read_events_end[4] 393337 info (trace)
ftrace_cpu_read_events_end[5] 325244 info (trace)
ftrace_cpu_read_events_end[6] 392637 info (trace)
ftrace_cpu_read_events_end[7] 350623 info (trace)
ftrace_packet_before_tracing_starthelp_outline 0 info (analysis)
ftrace_setup_errorshelp_outline 0 error (trace)
fuchsia_invalid_event 0 error (analysis)
fuchsia_non_numeric_counters 0 error (analysis)
fuchsia_timestamp_overflow 0 error (analysis)
game_intervention_has_parse_errorshelp_outline 0 error (trace)
game_intervention_has_read_errorshelp_outline 0 error (trace)
gpu_counters_invalid_spec 0 error (analysis)
gpu_counters_missing_spec 0 error (analysis)
gpu_render_stage_parser_errors 0 error (analysis)
graphics_frame_event_parser_errors 0 info (analysis)
guess_trace_type_duration_ns 7654 info (analysis)
heap_graph_non_finalized_graph 0 error (trace)
heapprofd_missing_packet 0 error (trace)
heapprofd_non_finalized_profile 0 error (trace)
interned_data_tokenizer_errors 0 info (analysis)
invalid_clock_snapshots 0 error (analysis)
invalid_cpu_times 0 error (analysis)
json_display_time_unithelp_outline 0 info (trace)
json_parser_failure 0 error (trace)
json_tokenizer_failure 0 error (trace)
meminfo_unknown_keys 0 error (analysis)
memory_snapshot_parser_failure 0 error (analysis)
metatrace_overruns 0 error (trace)
mismatched_sched_switch_tids 11101 error (analysis)
misplaced_end_event 0 data_loss (analysis)
mm_unknown_type 0 error (analysis)
ninja_parse_errors 0 error (trace)
packages_list_has_parse_errors 0 error (trace)
packages_list_has_read_errors 0 error (trace)
parse_trace_duration_ns 1780589548 info (analysis)
perf_samples_skipped 0 info (trace)
perf_samples_skipped_dataloss 0 data_loss (trace)
power_rail_unknown_index 0 error (trace)
proc_stat_unknown_counters 0 error (analysis)
process_tracker_errors 0 error (analysis)
rss_stat_negative_size 0 info (analysis)
rss_stat_unknown_keys 0 error (analysis)
rss_stat_unknown_thread_for_mm_id 0 info (analysis)
sched_switch_out_of_order 0 error (analysis)
sched_waking_out_of_order 0 error (analysis)
slice_out_of_order 0 error (analysis)
sorter_push_event_out_of_orderhelp_outline 0 error (trace)
stackprofile_invalid_callstack_id 0 error (trace)
stackprofile_invalid_frame_id 0 error (trace)
stackprofile_invalid_mapping_id 0 error (trace)
stackprofile_invalid_string_id 0 error (trace)
stackprofile_parser_error 0 error (trace)
symbolization_tmp_build_id_not_foundhelp_outline 0 error (analysis)
systrace_parse_failure 19040 error (analysis)
task_state_invalid 0 error (analysis)
thread_time_in_state_out_of_order 0 error (analysis)
thread_time_in_state_unknown_cpu_freq 0 error (analysis)
tokenizer_skipped_packets 0 info (analysis)
traced_buf_abi_violations[0] 0 data_loss (trace)
traced_buf_abi_violations[1] 0 data_loss (trace)
traced_buf_buffer_size[0] 534773760 info (trace)
traced_buf_buffer_size[1] 2097152 info (trace)
traced_buf_bytes_overwritten[0] 0 info (trace)
traced_buf_bytes_overwritten[1] 0 info (trace)
traced_buf_bytes_read[0] 78929920 info (trace)
traced_buf_bytes_read[1] 425984 info (trace)
traced_buf_bytes_written[0] 78962688 info (trace)
traced_buf_bytes_written[1] 425984 info (trace)
traced_buf_chunks_committed_out_of_order[0] 0 info (trace)
traced_buf_chunks_committed_out_of_order[1] 0 info (trace)
traced_buf_chunks_discarded[0] 0 info (trace)
traced_buf_chunks_discarded[1] 0 info (trace)
traced_buf_chunks_overwritten[0] 0 info (trace)
traced_buf_chunks_overwritten[1] 0 info (trace)
traced_buf_chunks_read[0] 2428 info (trace)
traced_buf_chunks_read[1] 13 info (trace)
traced_buf_chunks_rewritten[0] 6 info (trace)
traced_buf_chunks_rewritten[1] 0 info (trace)
traced_buf_chunks_written[0] 2429 info (trace)
traced_buf_chunks_written[1] 13 info (trace)
traced_buf_padding_bytes_cleared[0] 0 info (trace)
traced_buf_padding_bytes_cleared[1] 0 info (trace)
traced_buf_padding_bytes_written[0] 0 info (trace)
traced_buf_padding_bytes_written[1] 0 info (trace)
traced_buf_patches_failed[0] 0 data_loss (trace)
traced_buf_patches_failed[1] 0 data_loss (trace)
traced_buf_patches_succeeded[0] 5633 info (trace)
traced_buf_patches_succeeded[1] 8 info (trace)
traced_buf_readaheads_failed[0] 115 info (trace)
traced_buf_readaheads_failed[1] 18 info (trace)
traced_buf_readaheads_succeeded[0] 2257 info (trace)
traced_buf_readaheads_succeeded[1] 6 info (trace)
traced_buf_trace_writer_packet_loss[0] 0 data_loss (trace)
traced_buf_trace_writer_packet_loss[1] 0 data_loss (trace)
traced_buf_write_wrap_count[0] 0 info (trace)
traced_buf_write_wrap_count[1] 0 info (trace)
traced_chunks_discarded 0 info (trace)
traced_data_sources_registered 16 info (trace)
traced_data_sources_seen 6 info (trace)
traced_final_flush_failed 0 data_loss (trace)
traced_final_flush_succeeded 0 info (trace)
traced_flushes_failed 0 data_loss (trace)
traced_flushes_requested 0 info (trace)
traced_flushes_succeeded 0 info (trace)
traced_patches_discarded 0 info (trace)
traced_producers_connected 3 info (trace)
traced_producers_seen 3 info (trace)
traced_total_buffers 2 info (trace)
traced_tracing_sessions 1 info (trace)
track_event_dropped_packets_outside_of_range_of_interesthelp_outline 0 info (analysis)
track_event_parser_errors 0 info (analysis)
track_event_thread_invalid_endhelp_outline 0 error (trace)
track_event_tokenizer_errors 0 info (analysis)
truncated_sys_write_durationhelp_outline 0 data_loss (analysis)
unknown_extension_fieldshelp_outline 0 error (trace)
vmstat_unknown_keys 0 error (analysis)
vulkan_allocations_invalid_string_id 0 error (trace)
On Thu, Feb 9, 2023 at 10:28 PM Kajetan Puchalski
[off-list ref] wrote:
On Thu, Feb 09, 2023 at 02:20:36PM +0800, Yafang Shao wrote:
[...]
Hi Yafang,
quoted
Many thanks for the detailed analysis. Seems it can work.
Hi John,
Could you pls. try the attached fix ? I have verified it in my test env.
I tested the patch on my environment where I found the issue with newer
kernels + older Perfetto. The patch does improve things so that's nice.
Thanks for the test. I don't have Perfetto in hand, so I haven't
verify Perfetto.
It goes from "not working at all" to "mostly working but missing data"
compared to what happens if I just revert 3087c61ed2c48548b74dd343a5209b87082c682d.
Do you mean there are no errors at all if revert
3087c61ed2c48548b74dd343a5209b87082c682d ?
I'm just an end user so can't really speak to the underlying causes but
for those more familiar with how Perfetto works this is what I'm getting:
On Thu, Feb 09, 2023 at 11:37:44PM +0800, Yafang Shao wrote:
quoted
It goes from "not working at all" to "mostly working but missing data"
compared to what happens if I just revert 3087c61ed2c48548b74dd343a5209b87082c682d.
Do you mean there are no errors at all if revert
3087c61ed2c48548b74dd343a5209b87082c682d ?
Correct yes, the revert makes it work perfectly.
quoted
I'm just an end user so can't really speak to the underlying causes but
for those more familiar with how Perfetto works this is what I'm getting:
As I said not really sure why it's happening but there's definitely an
issue somewhere.
I'm hoping someone more familiar with how Perfetto works might have an
idea.
quoted
Error stats for this trace:
name idx source value
---------------------------------------- ---------------------------------------- ---------------------------------------- ----------------------------------------
mismatched_sched_switch_tids [NULL] analysis 11101
systrace_parse_failure [NULL] analysis 19040
The trace explorer window ends up containing the ftrace-specific tracks
but missing the tracks related to Android-specific callbacks and such.
Debug stats below in case they're relevant:
Name Value Type
android_br_parse_errors 0 error (trace)
android_log_format_invalid 0 error (trace)
android_log_num_failed 0 error (trace)
android_log_num_skipped 0 info (trace)
android_log_num_total 0 info (trace)
clock_sync_cache_miss 181 info (analysis)
clock_sync_failure 0 error (analysis)
compact_sched_has_parse_errors 0 error (trace)
compact_sched_switch_skipped 0 info (analysis)
compact_sched_waking_skipped 0 info (analysis)
counter_events_out_of_order 0 error (analysis)
deobfuscate_location_parse_error 0 error (trace)
empty_chrome_metadata 0 error (trace)
energy_breakdown_missing_values 0 error (analysis)
energy_descriptor_invalid 0 error (analysis)
energy_uid_breakdown_missing_values 0 error (analysis)
flow_duplicate_id 0 error (trace)
flow_end_without_start 0 info (trace)
flow_invalid_id 0 error (trace)
flow_no_enclosing_slice 0 error (trace)
flow_step_without_start 0 info (trace)
flow_without_direction 0 error (trace)
frame_timeline_event_parser_errors 0 info (analysis)
ftrace_bundle_tokenizer_errors 0 error (analysis)
ftrace_cpu_bytes_read_begin[0] 0 info (trace)
ftrace_cpu_bytes_read_begin[1] 264 info (trace)
ftrace_cpu_bytes_read_begin[2] 0 info (trace)
ftrace_cpu_bytes_read_begin[3] 224 info (trace)
ftrace_cpu_bytes_read_begin[4] 0 info (trace)
ftrace_cpu_bytes_read_begin[5] 0 info (trace)
ftrace_cpu_bytes_read_begin[6] 0 info (trace)
ftrace_cpu_bytes_read_begin[7] 0 info (trace)
ftrace_cpu_bytes_read_delta[0] 6919836 info (trace)
ftrace_cpu_bytes_read_delta[1] 7197556 info (trace)
ftrace_cpu_bytes_read_delta[2] 6381828 info (trace)
ftrace_cpu_bytes_read_delta[3] 5988336 info (trace)
ftrace_cpu_bytes_read_delta[4] 5933528 info (trace)
ftrace_cpu_bytes_read_delta[5] 4858400 info (trace)
ftrace_cpu_bytes_read_delta[6] 6175260 info (trace)
ftrace_cpu_bytes_read_delta[7] 4633460 info (trace)
ftrace_cpu_bytes_read_end[0] 6919836 info (trace)
ftrace_cpu_bytes_read_end[1] 7197820 info (trace)
ftrace_cpu_bytes_read_end[2] 6381828 info (trace)
ftrace_cpu_bytes_read_end[3] 5988560 info (trace)
ftrace_cpu_bytes_read_end[4] 5933528 info (trace)
ftrace_cpu_bytes_read_end[5] 4858400 info (trace)
ftrace_cpu_bytes_read_end[6] 6175260 info (trace)
ftrace_cpu_bytes_read_end[7] 4633460 info (trace)
ftrace_cpu_commit_overrun_begin[0] 0 info (trace)
ftrace_cpu_commit_overrun_begin[1] 0 info (trace)
ftrace_cpu_commit_overrun_begin[2] 0 info (trace)
ftrace_cpu_commit_overrun_begin[3] 0 info (trace)
ftrace_cpu_commit_overrun_begin[4] 0 info (trace)
ftrace_cpu_commit_overrun_begin[5] 0 info (trace)
ftrace_cpu_commit_overrun_begin[6] 0 info (trace)
ftrace_cpu_commit_overrun_begin[7] 0 info (trace)
ftrace_cpu_commit_overrun_delta[0] 0 error (trace)
ftrace_cpu_commit_overrun_delta[1] 0 error (trace)
ftrace_cpu_commit_overrun_delta[2] 0 error (trace)
ftrace_cpu_commit_overrun_delta[3] 0 error (trace)
ftrace_cpu_commit_overrun_delta[4] 0 error (trace)
ftrace_cpu_commit_overrun_delta[5] 0 error (trace)
ftrace_cpu_commit_overrun_delta[6] 0 error (trace)
ftrace_cpu_commit_overrun_delta[7] 0 error (trace)
ftrace_cpu_commit_overrun_end[0] 0 info (trace)
ftrace_cpu_commit_overrun_end[1] 0 info (trace)
ftrace_cpu_commit_overrun_end[2] 0 info (trace)
ftrace_cpu_commit_overrun_end[3] 0 info (trace)
ftrace_cpu_commit_overrun_end[4] 0 info (trace)
ftrace_cpu_commit_overrun_end[5] 0 info (trace)
ftrace_cpu_commit_overrun_end[6] 0 info (trace)
ftrace_cpu_commit_overrun_end[7] 0 info (trace)
ftrace_cpu_dropped_events_begin[0] 0 info (trace)
ftrace_cpu_dropped_events_begin[1] 0 info (trace)
ftrace_cpu_dropped_events_begin[2] 0 info (trace)
ftrace_cpu_dropped_events_begin[3] 0 info (trace)
ftrace_cpu_dropped_events_begin[4] 0 info (trace)
ftrace_cpu_dropped_events_begin[5] 0 info (trace)
ftrace_cpu_dropped_events_begin[6] 0 info (trace)
ftrace_cpu_dropped_events_begin[7] 0 info (trace)
ftrace_cpu_dropped_events_delta[0] 0 error (trace)
ftrace_cpu_dropped_events_delta[1] 0 error (trace)
ftrace_cpu_dropped_events_delta[2] 0 error (trace)
ftrace_cpu_dropped_events_delta[3] 0 error (trace)
ftrace_cpu_dropped_events_delta[4] 0 error (trace)
ftrace_cpu_dropped_events_delta[5] 0 error (trace)
ftrace_cpu_dropped_events_delta[6] 0 error (trace)
ftrace_cpu_dropped_events_delta[7] 0 error (trace)
ftrace_cpu_dropped_events_end[0] 0 info (trace)
ftrace_cpu_dropped_events_end[1] 0 info (trace)
ftrace_cpu_dropped_events_end[2] 0 info (trace)
ftrace_cpu_dropped_events_end[3] 0 info (trace)
ftrace_cpu_dropped_events_end[4] 0 info (trace)
ftrace_cpu_dropped_events_end[5] 0 info (trace)
ftrace_cpu_dropped_events_end[6] 0 info (trace)
ftrace_cpu_dropped_events_end[7] 0 info (trace)
ftrace_cpu_entries_begin[0] 0 info (trace)
ftrace_cpu_entries_begin[1] 6 info (trace)
ftrace_cpu_entries_begin[2] 0 info (trace)
ftrace_cpu_entries_begin[3] 5 info (trace)
ftrace_cpu_entries_begin[4] 0 info (trace)
ftrace_cpu_entries_begin[5] 0 info (trace)
ftrace_cpu_entries_begin[6] 0 info (trace)
ftrace_cpu_entries_begin[7] 0 info (trace)
ftrace_cpu_entries_delta[0] 6 info (trace)
ftrace_cpu_entries_delta[1] -6 info (trace)
ftrace_cpu_entries_delta[2] 0 info (trace)
ftrace_cpu_entries_delta[3] 2 info (trace)
ftrace_cpu_entries_delta[4] 0 info (trace)
ftrace_cpu_entries_delta[5] 0 info (trace)
ftrace_cpu_entries_delta[6] 0 info (trace)
ftrace_cpu_entries_delta[7] 0 info (trace)
ftrace_cpu_entries_end[0] 6 info (trace)
ftrace_cpu_entries_end[1] 0 info (trace)
ftrace_cpu_entries_end[2] 0 info (trace)
ftrace_cpu_entries_end[3] 7 info (trace)
ftrace_cpu_entries_end[4] 0 info (trace)
ftrace_cpu_entries_end[5] 0 info (trace)
ftrace_cpu_entries_end[6] 0 info (trace)
ftrace_cpu_entries_end[7] 0 info (trace)
ftrace_cpu_now_ts_begin[0] 93305027000 info (trace)
ftrace_cpu_now_ts_begin[1] 93305103000 info (trace)
ftrace_cpu_now_ts_begin[2] 93305159000 info (trace)
ftrace_cpu_now_ts_begin[3] 93305207000 info (trace)
ftrace_cpu_now_ts_begin[4] 93305262000 info (trace)
ftrace_cpu_now_ts_begin[5] 93305312000 info (trace)
ftrace_cpu_now_ts_begin[6] 93305362000 info (trace)
ftrace_cpu_now_ts_begin[7] 93305411000 info (trace)
ftrace_cpu_now_ts_end[0] 282906571000 info (trace)
ftrace_cpu_now_ts_end[1] 282906676000 info (trace)
ftrace_cpu_now_ts_end[2] 282906738000 info (trace)
ftrace_cpu_now_ts_end[3] 282906803000 info (trace)
ftrace_cpu_now_ts_end[4] 282906863000 info (trace)
ftrace_cpu_now_ts_end[5] 282906925000 info (trace)
ftrace_cpu_now_ts_end[6] 282906987000 info (trace)
ftrace_cpu_now_ts_end[7] 282907048000 info (trace)
ftrace_cpu_oldest_event_ts_begin[0] 0 info (trace)
ftrace_cpu_oldest_event_ts_begin[1] 93304642000 info (trace)
ftrace_cpu_oldest_event_ts_begin[2] 0 info (trace)
ftrace_cpu_oldest_event_ts_begin[3] 93304876000 info (trace)
ftrace_cpu_oldest_event_ts_begin[4] 0 info (trace)
ftrace_cpu_oldest_event_ts_begin[5] 0 info (trace)
ftrace_cpu_oldest_event_ts_begin[6] 0 info (trace)
ftrace_cpu_oldest_event_ts_begin[7] 0 info (trace)
ftrace_cpu_oldest_event_ts_end[0] 282905715000 info (trace)
ftrace_cpu_oldest_event_ts_end[1] 282903723000 info (trace)
ftrace_cpu_oldest_event_ts_end[2] 282903881000 info (trace)
ftrace_cpu_oldest_event_ts_end[3] 282816175000 info (trace)
ftrace_cpu_oldest_event_ts_end[4] 282896619000 info (trace)
ftrace_cpu_oldest_event_ts_end[5] 282884168000 info (trace)
ftrace_cpu_oldest_event_ts_end[6] 282783221000 info (trace)
ftrace_cpu_oldest_event_ts_end[7] 282880081000 info (trace)
ftrace_cpu_overrun_begin[0] 0 info (trace)
ftrace_cpu_overrun_begin[1] 0 info (trace)
ftrace_cpu_overrun_begin[2] 0 info (trace)
ftrace_cpu_overrun_begin[3] 0 info (trace)
ftrace_cpu_overrun_begin[4] 0 info (trace)
ftrace_cpu_overrun_begin[5] 0 info (trace)
ftrace_cpu_overrun_begin[6] 0 info (trace)
ftrace_cpu_overrun_begin[7] 0 info (trace)
ftrace_cpu_overrun_delta[0]help_outline 0 data_loss (trace)
ftrace_cpu_overrun_delta[1]help_outline 0 data_loss (trace)
ftrace_cpu_overrun_delta[2]help_outline 0 data_loss (trace)
ftrace_cpu_overrun_delta[3]help_outline 0 data_loss (trace)
ftrace_cpu_overrun_delta[4]help_outline 0 data_loss (trace)
ftrace_cpu_overrun_delta[5]help_outline 0 data_loss (trace)
ftrace_cpu_overrun_delta[6]help_outline 0 data_loss (trace)
ftrace_cpu_overrun_delta[7]help_outline 0 data_loss (trace)
ftrace_cpu_overrun_end[0] 0 info (trace)
ftrace_cpu_overrun_end[1] 0 info (trace)
ftrace_cpu_overrun_end[2] 0 info (trace)
ftrace_cpu_overrun_end[3] 0 info (trace)
ftrace_cpu_overrun_end[4] 0 info (trace)
ftrace_cpu_overrun_end[5] 0 info (trace)
ftrace_cpu_overrun_end[6] 0 info (trace)
ftrace_cpu_overrun_end[7] 0 info (trace)
ftrace_cpu_read_events_begin[0] 0 info (trace)
ftrace_cpu_read_events_begin[1] 0 info (trace)
ftrace_cpu_read_events_begin[2] 0 info (trace)
ftrace_cpu_read_events_begin[3] 0 info (trace)
ftrace_cpu_read_events_begin[4] 0 info (trace)
ftrace_cpu_read_events_begin[5] 0 info (trace)
ftrace_cpu_read_events_begin[6] 0 info (trace)
ftrace_cpu_read_events_begin[7] 0 info (trace)
ftrace_cpu_read_events_delta[0] 454848 info (trace)
ftrace_cpu_read_events_delta[1] 453484 info (trace)
ftrace_cpu_read_events_delta[2] 386290 info (trace)
ftrace_cpu_read_events_delta[3] 356432 info (trace)
ftrace_cpu_read_events_delta[4] 393337 info (trace)
ftrace_cpu_read_events_delta[5] 325244 info (trace)
ftrace_cpu_read_events_delta[6] 392637 info (trace)
ftrace_cpu_read_events_delta[7] 350623 info (trace)
ftrace_cpu_read_events_end[0] 454848 info (trace)
ftrace_cpu_read_events_end[1] 453484 info (trace)
ftrace_cpu_read_events_end[2] 386290 info (trace)
ftrace_cpu_read_events_end[3] 356432 info (trace)
ftrace_cpu_read_events_end[4] 393337 info (trace)
ftrace_cpu_read_events_end[5] 325244 info (trace)
ftrace_cpu_read_events_end[6] 392637 info (trace)
ftrace_cpu_read_events_end[7] 350623 info (trace)
ftrace_packet_before_tracing_starthelp_outline 0 info (analysis)
ftrace_setup_errorshelp_outline 0 error (trace)
fuchsia_invalid_event 0 error (analysis)
fuchsia_non_numeric_counters 0 error (analysis)
fuchsia_timestamp_overflow 0 error (analysis)
game_intervention_has_parse_errorshelp_outline 0 error (trace)
game_intervention_has_read_errorshelp_outline 0 error (trace)
gpu_counters_invalid_spec 0 error (analysis)
gpu_counters_missing_spec 0 error (analysis)
gpu_render_stage_parser_errors 0 error (analysis)
graphics_frame_event_parser_errors 0 info (analysis)
guess_trace_type_duration_ns 7654 info (analysis)
heap_graph_non_finalized_graph 0 error (trace)
heapprofd_missing_packet 0 error (trace)
heapprofd_non_finalized_profile 0 error (trace)
interned_data_tokenizer_errors 0 info (analysis)
invalid_clock_snapshots 0 error (analysis)
invalid_cpu_times 0 error (analysis)
json_display_time_unithelp_outline 0 info (trace)
json_parser_failure 0 error (trace)
json_tokenizer_failure 0 error (trace)
meminfo_unknown_keys 0 error (analysis)
memory_snapshot_parser_failure 0 error (analysis)
metatrace_overruns 0 error (trace)
mismatched_sched_switch_tids 11101 error (analysis)
misplaced_end_event 0 data_loss (analysis)
mm_unknown_type 0 error (analysis)
ninja_parse_errors 0 error (trace)
packages_list_has_parse_errors 0 error (trace)
packages_list_has_read_errors 0 error (trace)
parse_trace_duration_ns 1780589548 info (analysis)
perf_samples_skipped 0 info (trace)
perf_samples_skipped_dataloss 0 data_loss (trace)
power_rail_unknown_index 0 error (trace)
proc_stat_unknown_counters 0 error (analysis)
process_tracker_errors 0 error (analysis)
rss_stat_negative_size 0 info (analysis)
rss_stat_unknown_keys 0 error (analysis)
rss_stat_unknown_thread_for_mm_id 0 info (analysis)
sched_switch_out_of_order 0 error (analysis)
sched_waking_out_of_order 0 error (analysis)
slice_out_of_order 0 error (analysis)
sorter_push_event_out_of_orderhelp_outline 0 error (trace)
stackprofile_invalid_callstack_id 0 error (trace)
stackprofile_invalid_frame_id 0 error (trace)
stackprofile_invalid_mapping_id 0 error (trace)
stackprofile_invalid_string_id 0 error (trace)
stackprofile_parser_error 0 error (trace)
symbolization_tmp_build_id_not_foundhelp_outline 0 error (analysis)
systrace_parse_failure 19040 error (analysis)
task_state_invalid 0 error (analysis)
thread_time_in_state_out_of_order 0 error (analysis)
thread_time_in_state_unknown_cpu_freq 0 error (analysis)
tokenizer_skipped_packets 0 info (analysis)
traced_buf_abi_violations[0] 0 data_loss (trace)
traced_buf_abi_violations[1] 0 data_loss (trace)
traced_buf_buffer_size[0] 534773760 info (trace)
traced_buf_buffer_size[1] 2097152 info (trace)
traced_buf_bytes_overwritten[0] 0 info (trace)
traced_buf_bytes_overwritten[1] 0 info (trace)
traced_buf_bytes_read[0] 78929920 info (trace)
traced_buf_bytes_read[1] 425984 info (trace)
traced_buf_bytes_written[0] 78962688 info (trace)
traced_buf_bytes_written[1] 425984 info (trace)
traced_buf_chunks_committed_out_of_order[0] 0 info (trace)
traced_buf_chunks_committed_out_of_order[1] 0 info (trace)
traced_buf_chunks_discarded[0] 0 info (trace)
traced_buf_chunks_discarded[1] 0 info (trace)
traced_buf_chunks_overwritten[0] 0 info (trace)
traced_buf_chunks_overwritten[1] 0 info (trace)
traced_buf_chunks_read[0] 2428 info (trace)
traced_buf_chunks_read[1] 13 info (trace)
traced_buf_chunks_rewritten[0] 6 info (trace)
traced_buf_chunks_rewritten[1] 0 info (trace)
traced_buf_chunks_written[0] 2429 info (trace)
traced_buf_chunks_written[1] 13 info (trace)
traced_buf_padding_bytes_cleared[0] 0 info (trace)
traced_buf_padding_bytes_cleared[1] 0 info (trace)
traced_buf_padding_bytes_written[0] 0 info (trace)
traced_buf_padding_bytes_written[1] 0 info (trace)
traced_buf_patches_failed[0] 0 data_loss (trace)
traced_buf_patches_failed[1] 0 data_loss (trace)
traced_buf_patches_succeeded[0] 5633 info (trace)
traced_buf_patches_succeeded[1] 8 info (trace)
traced_buf_readaheads_failed[0] 115 info (trace)
traced_buf_readaheads_failed[1] 18 info (trace)
traced_buf_readaheads_succeeded[0] 2257 info (trace)
traced_buf_readaheads_succeeded[1] 6 info (trace)
traced_buf_trace_writer_packet_loss[0] 0 data_loss (trace)
traced_buf_trace_writer_packet_loss[1] 0 data_loss (trace)
traced_buf_write_wrap_count[0] 0 info (trace)
traced_buf_write_wrap_count[1] 0 info (trace)
traced_chunks_discarded 0 info (trace)
traced_data_sources_registered 16 info (trace)
traced_data_sources_seen 6 info (trace)
traced_final_flush_failed 0 data_loss (trace)
traced_final_flush_succeeded 0 info (trace)
traced_flushes_failed 0 data_loss (trace)
traced_flushes_requested 0 info (trace)
traced_flushes_succeeded 0 info (trace)
traced_patches_discarded 0 info (trace)
traced_producers_connected 3 info (trace)
traced_producers_seen 3 info (trace)
traced_total_buffers 2 info (trace)
traced_tracing_sessions 1 info (trace)
track_event_dropped_packets_outside_of_range_of_interesthelp_outline 0 info (analysis)
track_event_parser_errors 0 info (analysis)
track_event_thread_invalid_endhelp_outline 0 error (trace)
track_event_tokenizer_errors 0 info (analysis)
truncated_sys_write_durationhelp_outline 0 data_loss (analysis)
unknown_extension_fieldshelp_outline 0 error (trace)
vmstat_unknown_keys 0 error (analysis)
vulkan_allocations_invalid_string_id 0 error (trace)
On Thu, Feb 9, 2023 at 10:28 PM Kajetan Puchalski
[off-list ref] wrote:
quoted
On Thu, Feb 09, 2023 at 02:20:36PM +0800, Yafang Shao wrote:
[...]
Hi Yafang,
quoted
Many thanks for the detailed analysis. Seems it can work.
Hi John,
Could you pls. try the attached fix ? I have verified it in my test env.
I tested the patch on my environment where I found the issue with newer
kernels + older Perfetto. The patch does improve things so that's nice.
Thanks for the test. I don't have Perfetto in hand, so I haven't
verify Perfetto.
FWIW, perfetto is not android specific and can run on normal linux distro setup
(which I do but haven't noticed this breakage).
It's easy to download the latest release (including for android though I never
tried that) from github
https://github.com/google/perfetto/releases
Kajetan might try to see if he can pick the latest version which IIUC contains
a workaround.
If this simple patch can be tweaked to make it work again against older
versions that'd be nice though.
HTH.
Cheers
--
Qais Yousef
From: Steven Rostedt <rostedt@goodmis.org> Date: 2023-02-11 19:00:22
On Wed, 8 Feb 2023 21:33:43 -0500
Steven Rostedt [off-list ref] wrote:
OK, so it doesn't break perf, trace-cmd and rasdaemon, because the enum is
only needed in the print_fmt part. It can handle it in the field portion.
That is:
system: sched
name: sched_switch
ID: 285
format:
field:unsigned short common_type; offset:0; size:2; signed:0;
field:unsigned char common_flags; offset:2; size:1; signed:0;
field:unsigned char common_preempt_count; offset:3; size:1; signed:0;
field:int common_pid; offset:4; size:4; signed:1;
field:char prev_comm[TASK_COMM_LEN]; offset:8; size:16; signed:0;
^^^^^^^^^^^^^^ ^^
is ignored is used
field:pid_t prev_pid; offset:24; size:4; signed:1;
field:int prev_prio; offset:28; size:4; signed:1;
field:long prev_state; offset:32; size:8; signed:1;
field:char next_comm[TASK_COMM_LEN]; offset:40; size:16; signed:0;
field:pid_t next_pid; offset:56; size:4; signed:1;
field:int next_prio; offset:60; size:4; signed:1;
print fmt: "prev_comm=%s prev_pid=%d prev_prio=%d prev_state=%s%s ==> next_comm=%s next_pid=%d next_prio=%d", REC->prev_comm, REC->prev_pid, REC->prev_prio, (REC->prev_state & ((((0x00000000 | 0x00000001 | 0x00000002 | 0x00000004 | 0x00000008 | 0x00000010 | 0x00000020 | 0x00000040) + 1) << 1) - 1)) ? __print_flags(REC->prev_state & ((((0x00000000 | 0x00000001 | 0x00000002 | 0x00000004 | 0x00000008 | 0x00000010 | 0x00000020 | 0x00000040) + 1) << 1) - 1), "|", { 0x00000001, "S" }, { 0x00000002, "D" }, { 0x00000004, "T" }, { 0x00000008, "t" }, { 0x00000010, "X" }, { 0x00000020, "Z" }, { 0x00000040, "P" }, { 0x00000080, "I" }) : "R", REC->prev_state & (((0x00000000 | 0x00000001 | 0x00000002 | 0x00000004 | 0x00000008 | 0x00000010 | 0x00000020 | 0x00000040) + 1) << 1) ? "+" : "", REC->next_comm, REC->next_pid, REC->next_prio
^^^^^^^
Is what requires the conversions. So I take that back. It only breaks
perfetto, and that's because it writes its own parser and doesn't use
libtraceevent.
Actually, there are cases that this needs to be a number, as b3bc8547d3be6
("tracing: Have TRACE_DEFINE_ENUM affect trace event types as well") made
it update fields as well as the printk fmt.
I think because libtraceevent noticed that it was a "char" array, it just
defaults to "size". But this does have meaning for all other types, and I
can see other parsers requiring that.
-- Steve
On Sun, Feb 12, 2023 at 12:51 AM Qais Yousef [off-list ref] wrote:
On 02/09/23 23:37, Yafang Shao wrote:
quoted
On Thu, Feb 9, 2023 at 10:28 PM Kajetan Puchalski
[off-list ref] wrote:
quoted
On Thu, Feb 09, 2023 at 02:20:36PM +0800, Yafang Shao wrote:
[...]
Hi Yafang,
quoted
Many thanks for the detailed analysis. Seems it can work.
Hi John,
Could you pls. try the attached fix ? I have verified it in my test env.
I tested the patch on my environment where I found the issue with newer
kernels + older Perfetto. The patch does improve things so that's nice.
Thanks for the test. I don't have Perfetto in hand, so I haven't
verify Perfetto.
FWIW, perfetto is not android specific and can run on normal linux distro setup
(which I do but haven't noticed this breakage).
It's easy to download the latest release (including for android though I never
tried that) from github
https://github.com/google/perfetto/releases
Thanks for the information. I will try to run it on my test env.
I suspect the "systrace_parse_failure" error is caused by the field we
introduced into struct ftrace_event_field in the proposed patch, but I
haven't taken a deep look at the perfetto src code yet.
Kajetan might try to see if he can pick the latest version which IIUC contains
a workaround.
If this simple patch can be tweaked to make it work again against older
versions that'd be nice though.
HTH.
Cheers
--
Qais Yousef
On Sun, Feb 12, 2023 at 3:00 AM Steven Rostedt [off-list ref] wrote:
On Wed, 8 Feb 2023 21:33:43 -0500
Steven Rostedt [off-list ref] wrote:
quoted
OK, so it doesn't break perf, trace-cmd and rasdaemon, because the enum is
only needed in the print_fmt part. It can handle it in the field portion.
That is:
system: sched
name: sched_switch
ID: 285
format:
field:unsigned short common_type; offset:0; size:2; signed:0;
field:unsigned char common_flags; offset:2; size:1; signed:0;
field:unsigned char common_preempt_count; offset:3; size:1; signed:0;
field:int common_pid; offset:4; size:4; signed:1;
field:char prev_comm[TASK_COMM_LEN]; offset:8; size:16; signed:0;
^^^^^^^^^^^^^^ ^^
is ignored is used
field:pid_t prev_pid; offset:24; size:4; signed:1;
field:int prev_prio; offset:28; size:4; signed:1;
field:long prev_state; offset:32; size:8; signed:1;
field:char next_comm[TASK_COMM_LEN]; offset:40; size:16; signed:0;
field:pid_t next_pid; offset:56; size:4; signed:1;
field:int next_prio; offset:60; size:4; signed:1;
print fmt: "prev_comm=%s prev_pid=%d prev_prio=%d prev_state=%s%s ==> next_comm=%s next_pid=%d next_prio=%d", REC->prev_comm, REC->prev_pid, REC->prev_prio, (REC->prev_state & ((((0x00000000 | 0x00000001 | 0x00000002 | 0x00000004 | 0x00000008 | 0x00000010 | 0x00000020 | 0x00000040) + 1) << 1) - 1)) ? __print_flags(REC->prev_state & ((((0x00000000 | 0x00000001 | 0x00000002 | 0x00000004 | 0x00000008 | 0x00000010 | 0x00000020 | 0x00000040) + 1) << 1) - 1), "|", { 0x00000001, "S" }, { 0x00000002, "D" }, { 0x00000004, "T" }, { 0x00000008, "t" }, { 0x00000010, "X" }, { 0x00000020, "Z" }, { 0x00000040, "P" }, { 0x00000080, "I" }) : "R", REC->prev_state & (((0x00000000 | 0x00000001 | 0x00000002 | 0x00000004 | 0x00000008 | 0x00000010 | 0x00000020 | 0x00000040) + 1) << 1) ? "+" : "", REC->next_comm, REC->next_pid, REC->next_prio
^^^^^^^
Is what requires the conversions. So I take that back. It only breaks
perfetto, and that's because it writes its own parser and doesn't use
libtraceevent.
Actually, there are cases that this needs to be a number, as b3bc8547d3be6
("tracing: Have TRACE_DEFINE_ENUM affect trace event types as well") made
it update fields as well as the printk fmt.
It seems that TRACE_DEFINE_ENUM(TASK_COMM_LEN) in the trace events
header files would be a better fix.
I think because libtraceevent noticed that it was a "char" array, it just
defaults to "size". But this does have meaning for all other types, and I
can see other parsers requiring that.
-- Steve
From: Steven Rostedt <rostedt@goodmis.org> Date: 2023-02-12 03:45:18
On Sun, 12 Feb 2023 11:38:52 +0800
Yafang Shao [off-list ref] wrote:
quoted
Actually, there are cases that this needs to be a number, as b3bc8547d3be6
("tracing: Have TRACE_DEFINE_ENUM affect trace event types as well") made
it update fields as well as the printk fmt.
It seems that TRACE_DEFINE_ENUM(TASK_COMM_LEN) in the trace events
header files would be a better fix.
NACK! I much prefer the proper fix that adds the length.
-- Steve
From: Namhyung Kim <hidden> Date: 2023-02-13 17:43:41
Hi Steve,
On Sat, Feb 11, 2023 at 8:07 PM Steven Rostedt [off-list ref] wrote:
On Sun, 12 Feb 2023 11:38:52 +0800
Yafang Shao [off-list ref] wrote:
quoted
quoted
Actually, there are cases that this needs to be a number, as b3bc8547d3be6
("tracing: Have TRACE_DEFINE_ENUM affect trace event types as well") made
it update fields as well as the printk fmt.
It seems that TRACE_DEFINE_ENUM(TASK_COMM_LEN) in the trace events
header files would be a better fix.
NACK! I much prefer the proper fix that adds the length.
Can we just have both enum and macro at the same time?
I guess the enum would fill the BTF and the macro would provide
backward compatibility.
Thanks,
Namhyung
Hi Steve,
On Sat, Feb 11, 2023 at 8:07 PM Steven Rostedt [off-list ref] wrote:
quoted
On Sun, 12 Feb 2023 11:38:52 +0800
Yafang Shao [off-list ref] wrote:
quoted
quoted
Actually, there are cases that this needs to be a number, as b3bc8547d3be6
("tracing: Have TRACE_DEFINE_ENUM affect trace event types as well") made
it update fields as well as the printk fmt.
It seems that TRACE_DEFINE_ENUM(TASK_COMM_LEN) in the trace events
header files would be a better fix.
NACK! I much prefer the proper fix that adds the length.
Can we just have both enum and macro at the same time?
I guess the enum would fill the BTF and the macro would provide
backward compatibility.