[Issue] perf report gets stuck at addr2line

[Issue] perf report gets stuck at addr2line

[Changbin Du]

Hello,
I tried perf of mainline built on Ubuntu 20.04 and it gets stuck when reporting.

$ sudo lsb_release -d
Description:    Ubuntu 20.04.6 LTS
$ sudo perf record -g ls
$ perf report --stdio
[stuck]

It seems this addr2line binary was't working as perf expected. I found below
error:
addr2line: addr2line configuration failed

Then I ran addr2line manually:

$ addr2line -v
GNU addr2line (GNU Binutils for Ubuntu) 2.34
Copyright (C) 2020 Free Software Foundation, Inc.
...
$ addr2line -e .debug/.build-id/5e/2fa721660d663f38b6e1aa98d6fa3776974b54/elf -i -f
,
__per_cpu_start
??:?

The addr2line_configure() expects a '?' but we got '_'.

I am not sure whether this is related to Ian's change but it works on v6.3.

-- 
Cheers,
Changbin Du

Re: [Issue] perf report gets stuck at addr2line

[Ian Rogers]

On Thu, Jun 8, 2023 at 8:31 PM Changbin Du <changbin.du@huawei.com> wrote:
>
> Hello,
> I tried perf of mainline built on Ubuntu 20.04 and it gets stuck when reporting.
>
> $ sudo lsb_release -d
> Description:    Ubuntu 20.04.6 LTS
> $ sudo perf record -g ls
> $ perf report --stdio
> [stuck]
>
> It seems this addr2line binary was't working as perf expected. I found below
> error:
> addr2line: addr2line configuration failed
>
> Then I ran addr2line manually:
>
> $ addr2line -v
> GNU addr2line (GNU Binutils for Ubuntu) 2.34
> Copyright (C) 2020 Free Software Foundation, Inc.
> ...
> $ addr2line -e .debug/.build-id/5e/2fa721660d663f38b6e1aa98d6fa3776974b54/elf -i -f
> ,
> __per_cpu_start
> ??:?
>
> The addr2line_configure() expects a '?' but we got '_'.
>
> I am not sure whether this is related to Ian's change but it works on v6.3.

Thanks Changbin,

I see this too:
```
$ addr2line -e vmlinux -f -i
,
__per_cpu_start
./arch/x86/kernel/cpu/common.c:1850
^C
$ llvm-addr2line -e vmlinux -f -i
,
,
$ addr2line -e `which true` -f -i
,
??
??:0
$ nm vmlinux|grep __per_cpu_start
0000000000000000 D __per_cpu_start
```
6.3 was largely the same as 6.2 as Linus asked we let patches bake on
linux-next. So the llvm-addr2line support may not have been there in
6.3. Presumably this is 6.4 you are testing. I think this is a
separate issue to:
https://lore.kernel.org/lkml/20230608061812.3715566-1-irogers@google.com/

We could change the configure for vmlinux, reading it say from
a2l->argv. Perhaps we can use a different sentinel value, but some
experiments there:
```
$ addr2line -e vmlinux -f -i
FFFFFFFFFFFFFFFF
??
??:0
^C
$ llvm-addr2line -e vmlinux -f -i
FFFFFFFFFFFFFFFF
__init_scratch_end
??:0
```
Part of the problem is we need a sentinel value that gives the same
number of lines of output whether it is llvm or binutils.

We could have broken and binutils be the same, but this is still going
to cause issues. The problem is we send ',' to addr2line to detect
when it has finished sending output by it writing out question marks.
binutils addr2line is now not writing the ?s as it looks to turn any
invalid input to 0 and dump the symbol for that. This behavior is
unchanged by my patches, so I suspect the problem has happened from a
kernel change.

Thanks,
Ian

> --
> Cheers,
> Changbin Du

Re: [Issue] perf report gets stuck at addr2line

[Ian Rogers]

On Thu, Jun 8, 2023 at 10:13 PM Ian Rogers <irogers@google.com> wrote:
>
> On Thu, Jun 8, 2023 at 8:31 PM Changbin Du <changbin.du@huawei.com> wrote:
> >
> > Hello,
> > I tried perf of mainline built on Ubuntu 20.04 and it gets stuck when reporting.
> >
> > $ sudo lsb_release -d
> > Description:    Ubuntu 20.04.6 LTS
> > $ sudo perf record -g ls
> > $ perf report --stdio
> > [stuck]
> >
> > It seems this addr2line binary was't working as perf expected. I found below
> > error:
> > addr2line: addr2line configuration failed
> >
> > Then I ran addr2line manually:
> >
> > $ addr2line -v
> > GNU addr2line (GNU Binutils for Ubuntu) 2.34
> > Copyright (C) 2020 Free Software Foundation, Inc.
> > ...
> > $ addr2line -e .debug/.build-id/5e/2fa721660d663f38b6e1aa98d6fa3776974b54/elf -i -f
> > ,
> > __per_cpu_start
> > ??:?
> >
> > The addr2line_configure() expects a '?' but we got '_'.
> >
> > I am not sure whether this is related to Ian's change but it works on v6.3.
>
> Thanks Changbin,
>
> I see this too:
> ```
> $ addr2line -e vmlinux -f -i
> ,
> __per_cpu_start
> ./arch/x86/kernel/cpu/common.c:1850
> ^C
> $ llvm-addr2line -e vmlinux -f -i
> ,
> ,
> $ addr2line -e `which true` -f -i
> ,
> ??
> ??:0
> $ nm vmlinux|grep __per_cpu_start
> 0000000000000000 D __per_cpu_start
> ```
> 6.3 was largely the same as 6.2 as Linus asked we let patches bake on
> linux-next. So the llvm-addr2line support may not have been there in
> 6.3. Presumably this is 6.4 you are testing. I think this is a
> separate issue to:
> https://lore.kernel.org/lkml/20230608061812.3715566-1-irogers@google.com/
>
> We could change the configure for vmlinux, reading it say from
> a2l->argv. Perhaps we can use a different sentinel value, but some
> experiments there:
> ```
> $ addr2line -e vmlinux -f -i
> FFFFFFFFFFFFFFFF
> ??
> ??:0
> ^C
> $ llvm-addr2line -e vmlinux -f -i
> FFFFFFFFFFFFFFFF
> __init_scratch_end
> ??:0
> ```
> Part of the problem is we need a sentinel value that gives the same
> number of lines of output whether it is llvm or binutils.
>
> We could have broken and binutils be the same, but this is still going
> to cause issues. The problem is we send ',' to addr2line to detect
> when it has finished sending output by it writing out question marks.
> binutils addr2line is now not writing the ?s as it looks to turn any
> invalid input to 0 and dump the symbol for that. This behavior is
> unchanged by my patches, so I suspect the problem has happened from a
> kernel change.

Hi Changbin,

I think I found a way around the problem by enabling address dumping
from addr2line. I've sent the patches here:
https://lore.kernel.org/lkml/20230609235419.204624-1-irogers@google.com/
but only lightly tested them. Could you please take a look and send a
Tested-by ?

It is probably too late to get this into 6.4.0, but we can add a Fixes
tag so that it gets picked into 6.4.1. The patches here are on the
perf-tools-next tree targeting Linux 6.5.

Thanks,
Ian


> Thanks,
> Ian
>
> > --
> > Cheers,
> > Changbin Du

Re: [Issue] perf report gets stuck at addr2line

[Changbin Du]

>On Fri, Jun 09, 2023 at 04:58:24PM -0700, Ian Rogers wrote:
> On Thu, Jun 8, 2023 at 10:13 PM Ian Rogers <irogers@google.com> wrote:
>
[snip]
> Hi Changbin,
> 
> I think I found a way around the problem by enabling address dumping
> from addr2line. I've sent the patches here:
> https://lore.kernel.org/lkml/20230609235419.204624-1-irogers@google.com/
> but only lightly tested them. Could you please take a look and send a
> Tested-by ?
> 
> It is probably too late to get this into 6.4.0, but we can add a Fixes
> tag so that it gets picked into 6.4.1. The patches here are on the
> perf-tools-next tree targeting Linux 6.5.
> 
> Thanks,
> Ian
>
Hi Ian,
I applied your patches on mainline, the configuration error is gone, but still
get stuck finally. Here is the back trace.

#0  0x00001522c92bc392 in __libc_read (fd=..., buf=..., nbytes=...) at ../sysdeps/unix/sysv/linux/read.c:26
#1  0x0000559e6bd0fdfb in read (__nbytes=..., __buf=..., __fd=...) at /usr/include/x86_64-linux-gnu/bits/unistd.h:44
#2  io__get_char (io=...) at /work/linux/tools/perf/libapi/include/api/io.h:50
#3  io__getline (line_len_out=..., line_out=..., io=...) at /work/linux/tools/perf/libapi/include/api/io.h:129
#4  read_addr2line_record (io=..., style=..., function=..., filename=..., line_nr=...) at util/srcline.c:523
#5  0x0000559e6bd111b4 in addr2line (dso_name=..., addr=..., file=..., line_nr=..., dso=..., unwind_inlines=..., node=..., sym=...) at util/srcline.c:722
#6  0x0000559e6bd11e77 in addr2inlines (sym=..., dso=..., addr=..., dso_name=...) at util/srcline.c:773
#7  dso__parse_addr_inlines (dso=..., addr=..., sym=...) at util/srcline.c:950
#8  0x0000559e6bcc1de7 in append_inlines (cursor=..., ms=..., ip=...) at util/machine.c:3085
#9  0x0000559e6bcc24e6 in add_callchain_ip (thread=..., cursor=..., parent=..., root_al=..., cpumode=..., ip=..., branch=..., flags=..., iter=..., branch_from=...) at util/machine.c:2375
#10 0x0000559e6bcc3c1a in thread__resolve_callchain_sample (thread=..., cursor=..., evsel=..., sample=..., parent=..., root_al=..., max_stack=...) at util/machine.c:3055
#11 0x0000559e6bcbe817 in sample__resolve_callchain (sample=..., cursor=..., parent=..., evsel=..., al=..., max_stack=...) at util/callchain.c:1098
#12 0x0000559e6bcfb8c0 in hist_entry_iter__add (iter=..., al=..., max_stack_depth=..., arg=...) at util/hist.c:1222
#13 0x0000559e6bbc9951 in process_sample_event (tool=..., event=..., sample=..., evsel=..., machine=...) at builtin-report.c:330
#14 0x0000559e6bcd0193 in perf_session__deliver_event (session=..., event=..., tool=..., file_offset=..., file_path=...) at util/session.c:1645
#15 0x0000559e6bcd5226 in do_flush (show_progress=..., oe=...) at util/ordered-events.c:245
#16 __ordered_events__flush (oe=..., how=..., timestamp=...) at util/ordered-events.c:324
#17 0x0000559e6bcd5a19 in __ordered_events__flush (timestamp=..., how=..., oe=...) at util/ordered-events.c:340
#18 ordered_events__flush (how=..., oe=...) at util/ordered-events.c:342
#19 ordered_events__flush (oe=..., how=...) at util/ordered-events.c:340
#20 0x0000005b0000006e in ?? ()
#21 0x68f3206410bcae00 in ?? ()
#22 0x0000000000000000 in ?? ()

> 
> > Thanks,
> > Ian
> >
> > > --
> > > Cheers,
> > > Changbin Du

-- 
Cheers,
Changbin Du

Re: [Issue] perf report gets stuck at addr2line

[Ian Rogers]

On Sun, Jun 11, 2023 at 7:14 PM Changbin Du <changbin.du@huawei.com> wrote:
>
> >On Fri, Jun 09, 2023 at 04:58:24PM -0700, Ian Rogers wrote:
> > On Thu, Jun 8, 2023 at 10:13 PM Ian Rogers <irogers@google.com> wrote:
> >
> [snip]
> > Hi Changbin,
> >
> > I think I found a way around the problem by enabling address dumping
> > from addr2line. I've sent the patches here:
> > https://lore.kernel.org/lkml/20230609235419.204624-1-irogers@google.com/
> > but only lightly tested them. Could you please take a look and send a
> > Tested-by ?
> >
> > It is probably too late to get this into 6.4.0, but we can add a Fixes
> > tag so that it gets picked into 6.4.1. The patches here are on the
> > perf-tools-next tree targeting Linux 6.5.
> >
> > Thanks,
> > Ian
> >
> Hi Ian,
> I applied your patches on mainline, the configuration error is gone, but still
> get stuck finally. Here is the back trace.
>
> #0  0x00001522c92bc392 in __libc_read (fd=..., buf=..., nbytes=...) at ../sysdeps/unix/sysv/linux/read.c:26
> #1  0x0000559e6bd0fdfb in read (__nbytes=..., __buf=..., __fd=...) at /usr/include/x86_64-linux-gnu/bits/unistd.h:44
> #2  io__get_char (io=...) at /work/linux/tools/perf/libapi/include/api/io.h:50
> #3  io__getline (line_len_out=..., line_out=..., io=...) at /work/linux/tools/perf/libapi/include/api/io.h:129
> #4  read_addr2line_record (io=..., style=..., function=..., filename=..., line_nr=...) at util/srcline.c:523
> #5  0x0000559e6bd111b4 in addr2line (dso_name=..., addr=..., file=..., line_nr=..., dso=..., unwind_inlines=..., node=..., sym=...) at util/srcline.c:722
> #6  0x0000559e6bd11e77 in addr2inlines (sym=..., dso=..., addr=..., dso_name=...) at util/srcline.c:773
> #7  dso__parse_addr_inlines (dso=..., addr=..., sym=...) at util/srcline.c:950
> #8  0x0000559e6bcc1de7 in append_inlines (cursor=..., ms=..., ip=...) at util/machine.c:3085
> #9  0x0000559e6bcc24e6 in add_callchain_ip (thread=..., cursor=..., parent=..., root_al=..., cpumode=..., ip=..., branch=..., flags=..., iter=..., branch_from=...) at util/machine.c:2375
> #10 0x0000559e6bcc3c1a in thread__resolve_callchain_sample (thread=..., cursor=..., evsel=..., sample=..., parent=..., root_al=..., max_stack=...) at util/machine.c:3055
> #11 0x0000559e6bcbe817 in sample__resolve_callchain (sample=..., cursor=..., parent=..., evsel=..., al=..., max_stack=...) at util/callchain.c:1098
> #12 0x0000559e6bcfb8c0 in hist_entry_iter__add (iter=..., al=..., max_stack_depth=..., arg=...) at util/hist.c:1222
> #13 0x0000559e6bbc9951 in process_sample_event (tool=..., event=..., sample=..., evsel=..., machine=...) at builtin-report.c:330
> #14 0x0000559e6bcd0193 in perf_session__deliver_event (session=..., event=..., tool=..., file_offset=..., file_path=...) at util/session.c:1645
> #15 0x0000559e6bcd5226 in do_flush (show_progress=..., oe=...) at util/ordered-events.c:245
> #16 __ordered_events__flush (oe=..., how=..., timestamp=...) at util/ordered-events.c:324
> #17 0x0000559e6bcd5a19 in __ordered_events__flush (timestamp=..., how=..., oe=...) at util/ordered-events.c:340
> #18 ordered_events__flush (how=..., oe=...) at util/ordered-events.c:342
> #19 ordered_events__flush (oe=..., how=...) at util/ordered-events.c:340
> #20 0x0000005b0000006e in ?? ()
> #21 0x68f3206410bcae00 in ?? ()
> #22 0x0000000000000000 in ?? ()

Thanks Changbin, the backtrace shows that perf thinks addr2line is
going to write more output. These patches will cause an eventual
timeout:
https://lore.kernel.org/lkml/20230608061812.3715566-2-irogers@google.com/
I'm not sure how this situation can arise. Presumably you are using
binutils addr2line. Can you use gdb to work out what dso is causing
addr2line to stop like this? My guess would be vmlinux. If you can
find the dso and the address that was requested from addr2line, should
be in frame 5 in your backtrace, you can repeat the query on the
command line to see what addr2line is doing. Hopefully then we can
figure out why this caused the sentinel to be broken - the sentinel
needs to have address 0 or ',' if LLVM addr2line, or have a filename
line number of "??:0".

Thanks,
Ian

> >
> > > Thanks,
> > > Ian
> > >
> > > > --
> > > > Cheers,
> > > > Changbin Du
>
> --
> Cheers,
> Changbin Du

Re: [Issue] perf report gets stuck at addr2line

[Changbin Du]

On Sun, Jun 11, 2023 at 09:05:24PM -0700, Ian Rogers wrote:
> On Sun, Jun 11, 2023 at 7:14 PM Changbin Du <changbin.du@huawei.com> wrote:
> >
> > >On Fri, Jun 09, 2023 at 04:58:24PM -0700, Ian Rogers wrote:
> > > On Thu, Jun 8, 2023 at 10:13 PM Ian Rogers <irogers@google.com> wrote:
> > >
> > [snip]
> > > Hi Changbin,
> > >
> > > I think I found a way around the problem by enabling address dumping
> > > from addr2line. I've sent the patches here:
> > > https://lore.kernel.org/lkml/20230609235419.204624-1-irogers@google.com/
> > > but only lightly tested them. Could you please take a look and send a
> > > Tested-by ?
> > >
> > > It is probably too late to get this into 6.4.0, but we can add a Fixes
> > > tag so that it gets picked into 6.4.1. The patches here are on the
> > > perf-tools-next tree targeting Linux 6.5.
> > >
> > > Thanks,
> > > Ian
> > >
> > Hi Ian,
> > I applied your patches on mainline, the configuration error is gone, but still
> > get stuck finally. Here is the back trace.
> >
> > #0  0x00001522c92bc392 in __libc_read (fd=..., buf=..., nbytes=...) at ../sysdeps/unix/sysv/linux/read.c:26
> > #1  0x0000559e6bd0fdfb in read (__nbytes=..., __buf=..., __fd=...) at /usr/include/x86_64-linux-gnu/bits/unistd.h:44
> > #2  io__get_char (io=...) at /work/linux/tools/perf/libapi/include/api/io.h:50
> > #3  io__getline (line_len_out=..., line_out=..., io=...) at /work/linux/tools/perf/libapi/include/api/io.h:129
> > #4  read_addr2line_record (io=..., style=..., function=..., filename=..., line_nr=...) at util/srcline.c:523
> > #5  0x0000559e6bd111b4 in addr2line (dso_name=..., addr=..., file=..., line_nr=..., dso=..., unwind_inlines=..., node=..., sym=...) at util/srcline.c:722
> > #6  0x0000559e6bd11e77 in addr2inlines (sym=..., dso=..., addr=..., dso_name=...) at util/srcline.c:773
> > #7  dso__parse_addr_inlines (dso=..., addr=..., sym=...) at util/srcline.c:950
> > #8  0x0000559e6bcc1de7 in append_inlines (cursor=..., ms=..., ip=...) at util/machine.c:3085
> > #9  0x0000559e6bcc24e6 in add_callchain_ip (thread=..., cursor=..., parent=..., root_al=..., cpumode=..., ip=..., branch=..., flags=..., iter=..., branch_from=...) at util/machine.c:2375
> > #10 0x0000559e6bcc3c1a in thread__resolve_callchain_sample (thread=..., cursor=..., evsel=..., sample=..., parent=..., root_al=..., max_stack=...) at util/machine.c:3055
> > #11 0x0000559e6bcbe817 in sample__resolve_callchain (sample=..., cursor=..., parent=..., evsel=..., al=..., max_stack=...) at util/callchain.c:1098
> > #12 0x0000559e6bcfb8c0 in hist_entry_iter__add (iter=..., al=..., max_stack_depth=..., arg=...) at util/hist.c:1222
> > #13 0x0000559e6bbc9951 in process_sample_event (tool=..., event=..., sample=..., evsel=..., machine=...) at builtin-report.c:330
> > #14 0x0000559e6bcd0193 in perf_session__deliver_event (session=..., event=..., tool=..., file_offset=..., file_path=...) at util/session.c:1645
> > #15 0x0000559e6bcd5226 in do_flush (show_progress=..., oe=...) at util/ordered-events.c:245
> > #16 __ordered_events__flush (oe=..., how=..., timestamp=...) at util/ordered-events.c:324
> > #17 0x0000559e6bcd5a19 in __ordered_events__flush (timestamp=..., how=..., oe=...) at util/ordered-events.c:340
> > #18 ordered_events__flush (how=..., oe=...) at util/ordered-events.c:342
> > #19 ordered_events__flush (oe=..., how=...) at util/ordered-events.c:340
> > #20 0x0000005b0000006e in ?? ()
> > #21 0x68f3206410bcae00 in ?? ()
> > #22 0x0000000000000000 in ?? ()
> 
> Thanks Changbin, the backtrace shows that perf thinks addr2line is
> going to write more output. These patches will cause an eventual
> timeout:
> https://lore.kernel.org/lkml/20230608061812.3715566-2-irogers@google.com/
> I'm not sure how this situation can arise. Presumably you are using
> binutils addr2line. Can you use gdb to work out what dso is causing
> addr2line to stop like this? My guess would be vmlinux. If you can
> find the dso and the address that was requested from addr2line, should
> be in frame 5 in your backtrace, you can repeat the query on the
> command line to see what addr2line is doing. Hopefully then we can
> figure out why this caused the sentinel to be broken - the sentinel
> needs to have address 0 or ',' if LLVM addr2line, or have a filename
> line number of "??:0".
>
I am using binutils addr2line. It's vmlinux causes addr2line stuck. I added some
logs in perf as below.

$ ./perf --no-pager report --stdio
# To display the perf.data header info, please use --header/--header-only options.
#
addr2line: /home/changbin/.debug/.build-id/5e/2fa721660d663f38b6e1aa98d6fa3776974b54/elf, addr ffffffff81e000aa
subprocess: addr2line -e /home/changbin/.debug/.build-id/5e/2fa721660d663f38b6e1aa98d6fa3776974b54/elf -a -i -f
read_addr2line_record
io__getline: start
io__getline: 0xffffffff81e000aa

io__getline: start
io__getline: entry_SYSCALL_64_after_hwframe

io__getline: start
io__getline: ??:?

read_addr2line_record
io__getline: start
io__getline: 0x0000000000000000

io__getline: start
io__getline: __per_cpu_start

io__getline: start
io__getline: ??:?

read_addr2line_record
io__getline: start
[stuck]

> Thanks,
> Ian
> 
> > >
> > > > Thanks,
> > > > Ian
> > > >
> > > > > --
> > > > > Cheers,
> > > > > Changbin Du
> >
> > --
> > Cheers,
> > Changbin Du

-- 
Cheers,
Changbin Du

Re: [Issue] perf report gets stuck at addr2line

[Changbin Du]

Attach the debug patch:

diff --git a/tools/lib/api/io.h b/tools/lib/api/io.h
index d5e8cf0dada0..0793c03e7933 100644
--- a/tools/lib/api/io.h
+++ b/tools/lib/api/io.h
@@ -123,6 +123,7 @@ static inline ssize_t io__getline(struct io *io, char **line_out, size_t *line_l
        size_t line_len = 0;
        int ch = 0;

+       printf("io__getline: start\n");
        /* TODO: reuse previously allocated memory. */
        free(*line_out);
        while (ch != '\n') {
@@ -151,6 +152,7 @@ static inline ssize_t io__getline(struct io *io, char **line_out, size_t *line_l
        line_len += buf_pos;
        *line_out = line;
        *line_len_out = line_len;
+       printf("io__getline: %s\n", line);
        return line_len;
 err_out:
        free(line);
diff --git a/tools/perf/util/srcline.c b/tools/perf/util/srcline.c
index 638527c8be58..1b1d9b6605e9 100644
--- a/tools/perf/util/srcline.c
+++ b/tools/perf/util/srcline.c
@@ -416,6 +416,8 @@ static struct child_process *addr2line_subprocess_init(const char *addr2line_pat
                return NULL;
        }

+       printf("subprocess: addr2line -e %s -a -i -f\n", binary_path);
+
        a2l->pid = -1;
        a2l->in = -1;
        a2l->out = -1;
@@ -467,7 +469,7 @@ static enum a2l_style addr2line_configure(struct child_process *a2l, const char
                        lines = 3;
                } else {
                        if (!symbol_conf.disable_add2line_warn) {
-                               char *output;
+                               char *output = NULL;
                                size_t output_len;

                                io__getline(&io, &output, &output_len);
@@ -516,6 +518,7 @@ static int read_addr2line_record(struct io *io,
        if (line_nr != NULL)
                *line_nr = 0;

+       printf("read_addr2line_record\n");
        /*
         * Read the first line. Without an error this will be either an address
         * like 0x1234 or for llvm-addr2line the sentinal ',' character.
@@ -632,6 +635,8 @@ static int addr2line(const char *dso_name, u64 addr,
        struct io io;
        enum a2l_style a2l_style;

+       printf("addr2line: %s, addr %lx\n", dso_name, addr);
+
        if (!a2l) {
                if (!filename__has_section(dso_name, ".debug_line"))
                        goto out;


On Mon, Jun 12, 2023 at 09:10:42PM +0800, Changbin Du wrote:
> On Sun, Jun 11, 2023 at 09:05:24PM -0700, Ian Rogers wrote:
> > On Sun, Jun 11, 2023 at 7:14 PM Changbin Du <changbin.du@huawei.com> wrote:
> > >
> > > >On Fri, Jun 09, 2023 at 04:58:24PM -0700, Ian Rogers wrote:
> > > > On Thu, Jun 8, 2023 at 10:13 PM Ian Rogers <irogers@google.com> wrote:
> > > >
> > > [snip]
> > > > Hi Changbin,
> > > >
> > > > I think I found a way around the problem by enabling address dumping
> > > > from addr2line. I've sent the patches here:
> > > > https://lore.kernel.org/lkml/20230609235419.204624-1-irogers@google.com/
> > > > but only lightly tested them. Could you please take a look and send a
> > > > Tested-by ?
> > > >
> > > > It is probably too late to get this into 6.4.0, but we can add a Fixes
> > > > tag so that it gets picked into 6.4.1. The patches here are on the
> > > > perf-tools-next tree targeting Linux 6.5.
> > > >
> > > > Thanks,
> > > > Ian
> > > >
> > > Hi Ian,
> > > I applied your patches on mainline, the configuration error is gone, but still
> > > get stuck finally. Here is the back trace.
> > >
> > > #0  0x00001522c92bc392 in __libc_read (fd=..., buf=..., nbytes=...) at ../sysdeps/unix/sysv/linux/read.c:26
> > > #1  0x0000559e6bd0fdfb in read (__nbytes=..., __buf=..., __fd=...) at /usr/include/x86_64-linux-gnu/bits/unistd.h:44
> > > #2  io__get_char (io=...) at /work/linux/tools/perf/libapi/include/api/io.h:50
> > > #3  io__getline (line_len_out=..., line_out=..., io=...) at /work/linux/tools/perf/libapi/include/api/io.h:129
> > > #4  read_addr2line_record (io=..., style=..., function=..., filename=..., line_nr=...) at util/srcline.c:523
> > > #5  0x0000559e6bd111b4 in addr2line (dso_name=..., addr=..., file=..., line_nr=..., dso=..., unwind_inlines=..., node=..., sym=...) at util/srcline.c:722
> > > #6  0x0000559e6bd11e77 in addr2inlines (sym=..., dso=..., addr=..., dso_name=...) at util/srcline.c:773
> > > #7  dso__parse_addr_inlines (dso=..., addr=..., sym=...) at util/srcline.c:950
> > > #8  0x0000559e6bcc1de7 in append_inlines (cursor=..., ms=..., ip=...) at util/machine.c:3085
> > > #9  0x0000559e6bcc24e6 in add_callchain_ip (thread=..., cursor=..., parent=..., root_al=..., cpumode=..., ip=..., branch=..., flags=..., iter=..., branch_from=...) at util/machine.c:2375
> > > #10 0x0000559e6bcc3c1a in thread__resolve_callchain_sample (thread=..., cursor=..., evsel=..., sample=..., parent=..., root_al=..., max_stack=...) at util/machine.c:3055
> > > #11 0x0000559e6bcbe817 in sample__resolve_callchain (sample=..., cursor=..., parent=..., evsel=..., al=..., max_stack=...) at util/callchain.c:1098
> > > #12 0x0000559e6bcfb8c0 in hist_entry_iter__add (iter=..., al=..., max_stack_depth=..., arg=...) at util/hist.c:1222
> > > #13 0x0000559e6bbc9951 in process_sample_event (tool=..., event=..., sample=..., evsel=..., machine=...) at builtin-report.c:330
> > > #14 0x0000559e6bcd0193 in perf_session__deliver_event (session=..., event=..., tool=..., file_offset=..., file_path=...) at util/session.c:1645
> > > #15 0x0000559e6bcd5226 in do_flush (show_progress=..., oe=...) at util/ordered-events.c:245
> > > #16 __ordered_events__flush (oe=..., how=..., timestamp=...) at util/ordered-events.c:324
> > > #17 0x0000559e6bcd5a19 in __ordered_events__flush (timestamp=..., how=..., oe=...) at util/ordered-events.c:340
> > > #18 ordered_events__flush (how=..., oe=...) at util/ordered-events.c:342
> > > #19 ordered_events__flush (oe=..., how=...) at util/ordered-events.c:340
> > > #20 0x0000005b0000006e in ?? ()
> > > #21 0x68f3206410bcae00 in ?? ()
> > > #22 0x0000000000000000 in ?? ()
> > 
> > Thanks Changbin, the backtrace shows that perf thinks addr2line is
> > going to write more output. These patches will cause an eventual
> > timeout:
> > https://lore.kernel.org/lkml/20230608061812.3715566-2-irogers@google.com/
> > I'm not sure how this situation can arise. Presumably you are using
> > binutils addr2line. Can you use gdb to work out what dso is causing
> > addr2line to stop like this? My guess would be vmlinux. If you can
> > find the dso and the address that was requested from addr2line, should
> > be in frame 5 in your backtrace, you can repeat the query on the
> > command line to see what addr2line is doing. Hopefully then we can
> > figure out why this caused the sentinel to be broken - the sentinel
> > needs to have address 0 or ',' if LLVM addr2line, or have a filename
> > line number of "??:0".
> >
> I am using binutils addr2line. It's vmlinux causes addr2line stuck. I added some
> logs in perf as below.
> 
> $ ./perf --no-pager report --stdio
> # To display the perf.data header info, please use --header/--header-only options.
> #
> addr2line: /home/changbin/.debug/.build-id/5e/2fa721660d663f38b6e1aa98d6fa3776974b54/elf, addr ffffffff81e000aa
> subprocess: addr2line -e /home/changbin/.debug/.build-id/5e/2fa721660d663f38b6e1aa98d6fa3776974b54/elf -a -i -f
> read_addr2line_record
> io__getline: start
> io__getline: 0xffffffff81e000aa
> 
> io__getline: start
> io__getline: entry_SYSCALL_64_after_hwframe
> 
> io__getline: start
> io__getline: ??:?
> 
> read_addr2line_record
> io__getline: start
> io__getline: 0x0000000000000000
> 
> io__getline: start
> io__getline: __per_cpu_start
> 
> io__getline: start
> io__getline: ??:?
> 
> read_addr2line_record
> io__getline: start
> [stuck]
> 
> > Thanks,
> > Ian
> > 
> > > >
> > > > > Thanks,
> > > > > Ian
> > > > >
> > > > > > --
> > > > > > Cheers,
> > > > > > Changbin Du
> > >
> > > --
> > > Cheers,
> > > Changbin Du
> 
> -- 
> Cheers,
> Changbin Du

-- 
Cheers,
Changbin Du

Re: [Issue] perf report gets stuck at addr2line

[Ian Rogers]

On Mon, Jun 12, 2023 at 6:18 AM Changbin Du <changbin.du@huawei.com> wrote:
>
> Attach the debug patch:
>
> diff --git a/tools/lib/api/io.h b/tools/lib/api/io.h
> index d5e8cf0dada0..0793c03e7933 100644
> --- a/tools/lib/api/io.h
> +++ b/tools/lib/api/io.h
> @@ -123,6 +123,7 @@ static inline ssize_t io__getline(struct io *io, char **line_out, size_t *line_l
>         size_t line_len = 0;
>         int ch = 0;
>
> +       printf("io__getline: start\n");
>         /* TODO: reuse previously allocated memory. */
>         free(*line_out);
>         while (ch != '\n') {
> @@ -151,6 +152,7 @@ static inline ssize_t io__getline(struct io *io, char **line_out, size_t *line_l
>         line_len += buf_pos;
>         *line_out = line;
>         *line_len_out = line_len;
> +       printf("io__getline: %s\n", line);
>         return line_len;
>  err_out:
>         free(line);
> diff --git a/tools/perf/util/srcline.c b/tools/perf/util/srcline.c
> index 638527c8be58..1b1d9b6605e9 100644
> --- a/tools/perf/util/srcline.c
> +++ b/tools/perf/util/srcline.c
> @@ -416,6 +416,8 @@ static struct child_process *addr2line_subprocess_init(const char *addr2line_pat
>                 return NULL;
>         }
>
> +       printf("subprocess: addr2line -e %s -a -i -f\n", binary_path);
> +
>         a2l->pid = -1;
>         a2l->in = -1;
>         a2l->out = -1;
> @@ -467,7 +469,7 @@ static enum a2l_style addr2line_configure(struct child_process *a2l, const char
>                         lines = 3;
>                 } else {
>                         if (!symbol_conf.disable_add2line_warn) {
> -                               char *output;
> +                               char *output = NULL;
>                                 size_t output_len;
>
>                                 io__getline(&io, &output, &output_len);
> @@ -516,6 +518,7 @@ static int read_addr2line_record(struct io *io,
>         if (line_nr != NULL)
>                 *line_nr = 0;
>
> +       printf("read_addr2line_record\n");
>         /*
>          * Read the first line. Without an error this will be either an address
>          * like 0x1234 or for llvm-addr2line the sentinal ',' character.
> @@ -632,6 +635,8 @@ static int addr2line(const char *dso_name, u64 addr,
>         struct io io;
>         enum a2l_style a2l_style;
>
> +       printf("addr2line: %s, addr %lx\n", dso_name, addr);
> +
>         if (!a2l) {
>                 if (!filename__has_section(dso_name, ".debug_line"))
>                         goto out;
>
>
> On Mon, Jun 12, 2023 at 09:10:42PM +0800, Changbin Du wrote:
> > On Sun, Jun 11, 2023 at 09:05:24PM -0700, Ian Rogers wrote:
> > > On Sun, Jun 11, 2023 at 7:14 PM Changbin Du <changbin.du@huawei.com> wrote:
> > > >
> > > > >On Fri, Jun 09, 2023 at 04:58:24PM -0700, Ian Rogers wrote:
> > > > > On Thu, Jun 8, 2023 at 10:13 PM Ian Rogers <irogers@google.com> wrote:
> > > > >
> > > > [snip]
> > > > > Hi Changbin,
> > > > >
> > > > > I think I found a way around the problem by enabling address dumping
> > > > > from addr2line. I've sent the patches here:
> > > > > https://lore.kernel.org/lkml/20230609235419.204624-1-irogers@google.com/
> > > > > but only lightly tested them. Could you please take a look and send a
> > > > > Tested-by ?
> > > > >
> > > > > It is probably too late to get this into 6.4.0, but we can add a Fixes
> > > > > tag so that it gets picked into 6.4.1. The patches here are on the
> > > > > perf-tools-next tree targeting Linux 6.5.
> > > > >
> > > > > Thanks,
> > > > > Ian
> > > > >
> > > > Hi Ian,
> > > > I applied your patches on mainline, the configuration error is gone, but still
> > > > get stuck finally. Here is the back trace.
> > > >
> > > > #0  0x00001522c92bc392 in __libc_read (fd=..., buf=..., nbytes=...) at ../sysdeps/unix/sysv/linux/read.c:26
> > > > #1  0x0000559e6bd0fdfb in read (__nbytes=..., __buf=..., __fd=...) at /usr/include/x86_64-linux-gnu/bits/unistd.h:44
> > > > #2  io__get_char (io=...) at /work/linux/tools/perf/libapi/include/api/io.h:50
> > > > #3  io__getline (line_len_out=..., line_out=..., io=...) at /work/linux/tools/perf/libapi/include/api/io.h:129
> > > > #4  read_addr2line_record (io=..., style=..., function=..., filename=..., line_nr=...) at util/srcline.c:523
> > > > #5  0x0000559e6bd111b4 in addr2line (dso_name=..., addr=..., file=..., line_nr=..., dso=..., unwind_inlines=..., node=..., sym=...) at util/srcline.c:722
> > > > #6  0x0000559e6bd11e77 in addr2inlines (sym=..., dso=..., addr=..., dso_name=...) at util/srcline.c:773
> > > > #7  dso__parse_addr_inlines (dso=..., addr=..., sym=...) at util/srcline.c:950
> > > > #8  0x0000559e6bcc1de7 in append_inlines (cursor=..., ms=..., ip=...) at util/machine.c:3085
> > > > #9  0x0000559e6bcc24e6 in add_callchain_ip (thread=..., cursor=..., parent=..., root_al=..., cpumode=..., ip=..., branch=..., flags=..., iter=..., branch_from=...) at util/machine.c:2375
> > > > #10 0x0000559e6bcc3c1a in thread__resolve_callchain_sample (thread=..., cursor=..., evsel=..., sample=..., parent=..., root_al=..., max_stack=...) at util/machine.c:3055
> > > > #11 0x0000559e6bcbe817 in sample__resolve_callchain (sample=..., cursor=..., parent=..., evsel=..., al=..., max_stack=...) at util/callchain.c:1098
> > > > #12 0x0000559e6bcfb8c0 in hist_entry_iter__add (iter=..., al=..., max_stack_depth=..., arg=...) at util/hist.c:1222
> > > > #13 0x0000559e6bbc9951 in process_sample_event (tool=..., event=..., sample=..., evsel=..., machine=...) at builtin-report.c:330
> > > > #14 0x0000559e6bcd0193 in perf_session__deliver_event (session=..., event=..., tool=..., file_offset=..., file_path=...) at util/session.c:1645
> > > > #15 0x0000559e6bcd5226 in do_flush (show_progress=..., oe=...) at util/ordered-events.c:245
> > > > #16 __ordered_events__flush (oe=..., how=..., timestamp=...) at util/ordered-events.c:324
> > > > #17 0x0000559e6bcd5a19 in __ordered_events__flush (timestamp=..., how=..., oe=...) at util/ordered-events.c:340
> > > > #18 ordered_events__flush (how=..., oe=...) at util/ordered-events.c:342
> > > > #19 ordered_events__flush (oe=..., how=...) at util/ordered-events.c:340
> > > > #20 0x0000005b0000006e in ?? ()
> > > > #21 0x68f3206410bcae00 in ?? ()
> > > > #22 0x0000000000000000 in ?? ()
> > >
> > > Thanks Changbin, the backtrace shows that perf thinks addr2line is
> > > going to write more output. These patches will cause an eventual
> > > timeout:
> > > https://lore.kernel.org/lkml/20230608061812.3715566-2-irogers@google.com/
> > > I'm not sure how this situation can arise. Presumably you are using
> > > binutils addr2line. Can you use gdb to work out what dso is causing
> > > addr2line to stop like this? My guess would be vmlinux. If you can
> > > find the dso and the address that was requested from addr2line, should
> > > be in frame 5 in your backtrace, you can repeat the query on the
> > > command line to see what addr2line is doing. Hopefully then we can
> > > figure out why this caused the sentinel to be broken - the sentinel
> > > needs to have address 0 or ',' if LLVM addr2line, or have a filename
> > > line number of "??:0".
> > >
> > I am using binutils addr2line. It's vmlinux causes addr2line stuck. I added some
> > logs in perf as below.
> >
> > $ ./perf --no-pager report --stdio
> > # To display the perf.data header info, please use --header/--header-only options.
> > #
> > addr2line: /home/changbin/.debug/.build-id/5e/2fa721660d663f38b6e1aa98d6fa3776974b54/elf, addr ffffffff81e000aa
> > subprocess: addr2line -e /home/changbin/.debug/.build-id/5e/2fa721660d663f38b6e1aa98d6fa3776974b54/elf -a -i -f
> > read_addr2line_record
> > io__getline: start
> > io__getline: 0xffffffff81e000aa
> >
> > io__getline: start
> > io__getline: entry_SYSCALL_64_after_hwframe
> >
> > io__getline: start
> > io__getline: ??:?
> >
> > read_addr2line_record
> > io__getline: start
> > io__getline: 0x0000000000000000
> >
> > io__getline: start
> > io__getline: __per_cpu_start
> >
> > io__getline: start
> > io__getline: ??:?
> >
> > read_addr2line_record
> > io__getline: start
> > [stuck]

Thanks Changbin, this should have hit the 0x0...0 sentinel match:

https://lore.kernel.org/lkml/20230609235419.204624-2-irogers@google.com/
+ } else {
+ int zero_count = 0, non_zero_count = 0;
+
+ /* The address should always start 0x. */
+ if (line_len < 2 || line[0] != '0' || line[1] != 'x')
+ goto error;
+
+ for (size_t i = 2; i < line_len; i++) {
+ if (line[i] == '0')
+ zero_count++;
+ else
+ non_zero_count++;
+ }
+ if (!non_zero_count) {
+ int ch;
+
+ if (!zero_count) {
+ /* Line was erroneous just '0x'. */
+ goto error;
+ }
+ /*
+ * Line was 0x0..0, the sentinel for binutils. Remove
+ * the function and filename lines.
+ */
+ zfree(&line);
+ do {
+ ch = io__get_char(io);
+ } while (ch > 0 && ch != '\n');
+ do {
+ ch = io__get_char(io);
+ } while (ch > 0 && ch != '\n');
+ return 0;
+ }
  }

That doesn't use io__getline - so we've not matched the 0x0...0 case
to terminate the records. Could you add some logging/debug?

Thanks,
Ian

> > > Thanks,
> > > Ian
> > >
> > > > >
> > > > > > Thanks,
> > > > > > Ian
> > > > > >
> > > > > > > --
> > > > > > > Cheers,
> > > > > > > Changbin Du
> > > >
> > > > --
> > > > Cheers,
> > > > Changbin Du
> >
> > --
> > Cheers,
> > Changbin Du
>
> --
> Cheers,
> Changbin Du

Re: [Issue] perf report gets stuck at addr2line

[Changbin Du]

On Mon, Jun 12, 2023 at 08:55:14AM -0700, Ian Rogers wrote:
> On Mon, Jun 12, 2023 at 6:18 AM Changbin Du <changbin.du@huawei.com> wrote:
> 
> Thanks Changbin, this should have hit the 0x0...0 sentinel match:
> 
> https://lore.kernel.org/lkml/20230609235419.204624-2-irogers@google.com/
> + } else {
> + int zero_count = 0, non_zero_count = 0;
> +
> + /* The address should always start 0x. */
> + if (line_len < 2 || line[0] != '0' || line[1] != 'x')
> + goto error;
> +
> + for (size_t i = 2; i < line_len; i++) {
> + if (line[i] == '0')
> + zero_count++;
> + else
> + non_zero_count++;
> + }
> + if (!non_zero_count) {
> + int ch;
> +
> + if (!zero_count) {
> + /* Line was erroneous just '0x'. */
> + goto error;
> + }
> + /*
> + * Line was 0x0..0, the sentinel for binutils. Remove
> + * the function and filename lines.
> + */
> + zfree(&line);
> + do {
> + ch = io__get_char(io);
> + } while (ch > 0 && ch != '\n');
> + do {
> + ch = io__get_char(io);
> + } while (ch > 0 && ch != '\n');
> + return 0;
> + }
>   }
> 
> That doesn't use io__getline - so we've not matched the 0x0...0 case
> to terminate the records. Could you add some logging/debug?
>
I printed every charactor got by io__get_char(), based on previous debug change.
Please see logs below.

# To display the perf.data header info, please use --header/--header-only options.
#
addr2line: /home/changbin/.debug/.build-id/5e/2fa721660d663f38b6e1aa98d6fa3776974b54/elf, addr ffffffff81e000aa
subprocess: addr2line -e /home/changbin/.debug/.build-id/5e/2fa721660d663f38b6e1aa98d6fa3776974b54/elf -a -i -f
io__get_char: '0'
io__get_char: 'x'
io__get_char: '0'
io__get_char: '0'
io__get_char: '0'
io__get_char: '0'
io__get_char: '0'
io__get_char: '0'
io__get_char: '0'
io__get_char: '0'
io__get_char: '0'
io__get_char: '0'
io__get_char: '0'
io__get_char: '0'
io__get_char: '0'
io__get_char: '0'
io__get_char: '0'
io__get_char: '0'
io__get_char: '
'
io__get_char: '_'
io__get_char: '_'
io__get_char: 'p'
io__get_char: 'e'
io__get_char: 'r'
io__get_char: '_'
io__get_char: 'c'
io__get_char: 'p'
io__get_char: 'u'
io__get_char: '_'
io__get_char: 's'
io__get_char: 't'
io__get_char: 'a'
io__get_char: 'r'
io__get_char: 't'
io__get_char: '
'
io__get_char: '?'
io__get_char: '?'
io__get_char: ':'
io__get_char: '?'
io__get_char: '
'
read_addr2line_record
io__getline: start
io__get_char: '0'
io__get_char: 'x'
io__get_char: 'f'
io__get_char: 'f'
io__get_char: 'f'
io__get_char: 'f'
io__get_char: 'f'
io__get_char: 'f'
io__get_char: 'f'
io__get_char: 'f'
io__get_char: '8'
io__get_char: '1'
io__get_char: 'e'
io__get_char: '0'
io__get_char: '0'
io__get_char: '0'
io__get_char: 'a'
io__get_char: 'a'
io__get_char: '
'
io__getline: 0xffffffff81e000aa

io__getline: start
io__get_char: 'e'
io__get_char: 'n'
io__get_char: 't'
io__get_char: 'r'
io__get_char: 'y'
io__get_char: '_'
io__get_char: 'S'
io__get_char: 'Y'
io__get_char: 'S'
io__get_char: 'C'
io__get_char: 'A'
io__get_char: 'L'
io__get_char: 'L'
io__get_char: '_'
io__get_char: '6'
io__get_char: '4'
io__get_char: '_'
io__get_char: 'a'
io__get_char: 'f'
io__get_char: 't'
io__get_char: 'e'
io__get_char: 'r'
io__get_char: '_'
io__get_char: 'h'
io__get_char: 'w'
io__get_char: 'f'
io__get_char: 'r'
io__get_char: 'a'
io__get_char: 'm'
io__get_char: 'e'
io__get_char: '
'
io__getline: entry_SYSCALL_64_after_hwframe

io__getline: start
io__get_char: '?'
io__get_char: '?'
io__get_char: ':'
io__get_char: '?'
io__get_char: '
'
io__getline: ??:?

read_addr2line_record
io__getline: start
io__get_char: '0'
io__get_char: 'x'
io__get_char: '0'
io__get_char: '0'
io__get_char: '0'
io__get_char: '0'
io__get_char: '0'
io__get_char: '0'
io__get_char: '0'
io__get_char: '0'
io__get_char: '0'
io__get_char: '0'
io__get_char: '0'
io__get_char: '0'
io__get_char: '0'
io__get_char: '0'
io__get_char: '0'
io__get_char: '0'
io__get_char: '
'
io__getline: 0x0000000000000000

io__getline: start
io__get_char: '_'
io__get_char: '_'
io__get_char: 'p'
io__get_char: 'e'
io__get_char: 'r'
io__get_char: '_'
io__get_char: 'c'
io__get_char: 'p'
io__get_char: 'u'
io__get_char: '_'
io__get_char: 's'
io__get_char: 't'
io__get_char: 'a'
io__get_char: 'r'
io__get_char: 't'
io__get_char: '
'
io__getline: __per_cpu_start

io__getline: start
io__get_char: '?'
io__get_char: '?'
io__get_char: ':'
io__get_char: '?'
io__get_char: '
'
io__getline: ??:?

read_addr2line_record
io__getline: start
[stuck]

> Thanks,
> Ian
> 
> > > > Thanks,
> > > > Ian
> > > >
> > > > > >
> > > > > > > Thanks,
> > > > > > > Ian
> > > > > > >
> > > > > > > > --
> > > > > > > > Cheers,
> > > > > > > > Changbin Du
> > > > >
> > > > > --
> > > > > Cheers,
> > > > > Changbin Du
> > >
> > > --
> > > Cheers,
> > > Changbin Du
> >
> > --
> > Cheers,
> > Changbin Du

-- 
Cheers,
Changbin Du

Re: [Issue] perf report gets stuck at addr2line

[Ian Rogers]

On Mon, Jun 12, 2023 at 7:20 PM Changbin Du <changbin.du@huawei.com> wrote:
>
> On Mon, Jun 12, 2023 at 08:55:14AM -0700, Ian Rogers wrote:
> > On Mon, Jun 12, 2023 at 6:18 AM Changbin Du <changbin.du@huawei.com> wrote:
> >
> > Thanks Changbin, this should have hit the 0x0...0 sentinel match:
> >
> > https://lore.kernel.org/lkml/20230609235419.204624-2-irogers@google.com/
> > + } else {
> > + int zero_count = 0, non_zero_count = 0;
> > +
> > + /* The address should always start 0x. */
> > + if (line_len < 2 || line[0] != '0' || line[1] != 'x')
> > + goto error;
> > +
> > + for (size_t i = 2; i < line_len; i++) {
> > + if (line[i] == '0')
> > + zero_count++;
> > + else
> > + non_zero_count++;
> > + }
> > + if (!non_zero_count) {
> > + int ch;
> > +
> > + if (!zero_count) {
> > + /* Line was erroneous just '0x'. */
> > + goto error;
> > + }
> > + /*
> > + * Line was 0x0..0, the sentinel for binutils. Remove
> > + * the function and filename lines.
> > + */
> > + zfree(&line);
> > + do {
> > + ch = io__get_char(io);
> > + } while (ch > 0 && ch != '\n');
> > + do {
> > + ch = io__get_char(io);
> > + } while (ch > 0 && ch != '\n');
> > + return 0;
> > + }
> >   }
> >
> > That doesn't use io__getline - so we've not matched the 0x0...0 case
> > to terminate the records. Could you add some logging/debug?
> >
> I printed every charactor got by io__get_char(), based on previous debug change.
> Please see logs below.
>
> # To display the perf.data header info, please use --header/--header-only options.
> #
> addr2line: /home/changbin/.debug/.build-id/5e/2fa721660d663f38b6e1aa98d6fa3776974b54/elf, addr ffffffff81e000aa
> subprocess: addr2line -e /home/changbin/.debug/.build-id/5e/2fa721660d663f38b6e1aa98d6fa3776974b54/elf -a -i -f
> io__get_char: '0'
> io__get_char: 'x'
> io__get_char: '0'
> io__get_char: '0'
> io__get_char: '0'
> io__get_char: '0'
> io__get_char: '0'
> io__get_char: '0'
> io__get_char: '0'
> io__get_char: '0'
> io__get_char: '0'
> io__get_char: '0'
> io__get_char: '0'
> io__get_char: '0'
> io__get_char: '0'
> io__get_char: '0'
> io__get_char: '0'
> io__get_char: '0'
> io__get_char: '
> '
> io__get_char: '_'
> io__get_char: '_'
> io__get_char: 'p'
> io__get_char: 'e'
> io__get_char: 'r'
> io__get_char: '_'
> io__get_char: 'c'
> io__get_char: 'p'
> io__get_char: 'u'
> io__get_char: '_'
> io__get_char: 's'
> io__get_char: 't'
> io__get_char: 'a'
> io__get_char: 'r'
> io__get_char: 't'
> io__get_char: '
> '
> io__get_char: '?'
> io__get_char: '?'
> io__get_char: ':'
> io__get_char: '?'
> io__get_char: '
> '
> read_addr2line_record
> io__getline: start
> io__get_char: '0'
> io__get_char: 'x'
> io__get_char: 'f'
> io__get_char: 'f'
> io__get_char: 'f'
> io__get_char: 'f'
> io__get_char: 'f'
> io__get_char: 'f'
> io__get_char: 'f'
> io__get_char: 'f'
> io__get_char: '8'
> io__get_char: '1'
> io__get_char: 'e'
> io__get_char: '0'
> io__get_char: '0'
> io__get_char: '0'
> io__get_char: 'a'
> io__get_char: 'a'
> io__get_char: '
> '
> io__getline: 0xffffffff81e000aa
>
> io__getline: start
> io__get_char: 'e'
> io__get_char: 'n'
> io__get_char: 't'
> io__get_char: 'r'
> io__get_char: 'y'
> io__get_char: '_'
> io__get_char: 'S'
> io__get_char: 'Y'
> io__get_char: 'S'
> io__get_char: 'C'
> io__get_char: 'A'
> io__get_char: 'L'
> io__get_char: 'L'
> io__get_char: '_'
> io__get_char: '6'
> io__get_char: '4'
> io__get_char: '_'
> io__get_char: 'a'
> io__get_char: 'f'
> io__get_char: 't'
> io__get_char: 'e'
> io__get_char: 'r'
> io__get_char: '_'
> io__get_char: 'h'
> io__get_char: 'w'
> io__get_char: 'f'
> io__get_char: 'r'
> io__get_char: 'a'
> io__get_char: 'm'
> io__get_char: 'e'
> io__get_char: '
> '
> io__getline: entry_SYSCALL_64_after_hwframe
>
> io__getline: start
> io__get_char: '?'
> io__get_char: '?'
> io__get_char: ':'
> io__get_char: '?'
> io__get_char: '
> '
> io__getline: ??:?
>
> read_addr2line_record
> io__getline: start
> io__get_char: '0'
> io__get_char: 'x'
> io__get_char: '0'
> io__get_char: '0'
> io__get_char: '0'
> io__get_char: '0'
> io__get_char: '0'
> io__get_char: '0'
> io__get_char: '0'
> io__get_char: '0'
> io__get_char: '0'
> io__get_char: '0'
> io__get_char: '0'
> io__get_char: '0'
> io__get_char: '0'
> io__get_char: '0'
> io__get_char: '0'
> io__get_char: '0'
> io__get_char: '
> '
> io__getline: 0x0000000000000000
>
> io__getline: start
> io__get_char: '_'
> io__get_char: '_'
> io__get_char: 'p'
> io__get_char: 'e'
> io__get_char: 'r'
> io__get_char: '_'
> io__get_char: 'c'
> io__get_char: 'p'
> io__get_char: 'u'
> io__get_char: '_'
> io__get_char: 's'
> io__get_char: 't'
> io__get_char: 'a'
> io__get_char: 'r'
> io__get_char: 't'
> io__get_char: '
> '
> io__getline: __per_cpu_start
>
> io__getline: start
> io__get_char: '?'
> io__get_char: '?'
> io__get_char: ':'
> io__get_char: '?'
> io__get_char: '
> '
> io__getline: ??:?
>
> read_addr2line_record
> io__getline: start
> [stuck]


Cool. Looks like the terminating '\n' is the issue. It is specified to
be part of getline. Can you tweak:

+ if (line[i] == '0')
+ zero_count++;
+ else
+ non_zero_count++;

to be:

+ if (line[i] == '0')
+ zero_count++;
+ else if (line[i] != '\n')
+ non_zero_count++;

Thanks,
Ian

> > Thanks,
> > Ian
> >
> > > > > Thanks,
> > > > > Ian
> > > > >
> > > > > > >
> > > > > > > > Thanks,
> > > > > > > > Ian
> > > > > > > >
> > > > > > > > > --
> > > > > > > > > Cheers,
> > > > > > > > > Changbin Du
> > > > > >
> > > > > > --
> > > > > > Cheers,
> > > > > > Changbin Du
> > > >
> > > > --
> > > > Cheers,
> > > > Changbin Du
> > >
> > > --
> > > Cheers,
> > > Changbin Du
>
> --
> Cheers,
> Changbin Du

Re: [Issue] perf report gets stuck at addr2line

[Changbin Du]

On Mon, Jun 12, 2023 at 07:25:41PM -0700, Ian Rogers wrote:
> On Mon, Jun 12, 2023 at 7:20 PM Changbin Du <changbin.du@huawei.com> wrote:
> >
> > On Mon, Jun 12, 2023 at 08:55:14AM -0700, Ian Rogers wrote:
> > > On Mon, Jun 12, 2023 at 6:18 AM Changbin Du <changbin.du@huawei.com> wrote:
> > >
> > > Thanks Changbin, this should have hit the 0x0...0 sentinel match:
> > >
> > > https://lore.kernel.org/lkml/20230609235419.204624-2-irogers@google.com/
> > > + } else {
> > > + int zero_count = 0, non_zero_count = 0;
> > > +
> > > + /* The address should always start 0x. */
> > > + if (line_len < 2 || line[0] != '0' || line[1] != 'x')
> > > + goto error;
> > > +
> > > + for (size_t i = 2; i < line_len; i++) {
> > > + if (line[i] == '0')
> > > + zero_count++;
> > > + else
> > > + non_zero_count++;
> > > + }
> > > + if (!non_zero_count) {
> > > + int ch;
> > > +
> > > + if (!zero_count) {
> > > + /* Line was erroneous just '0x'. */
> > > + goto error;
> > > + }
> > > + /*
> > > + * Line was 0x0..0, the sentinel for binutils. Remove
> > > + * the function and filename lines.
> > > + */
> > > + zfree(&line);
> > > + do {
> > > + ch = io__get_char(io);
> > > + } while (ch > 0 && ch != '\n');
> > > + do {
> > > + ch = io__get_char(io);
> > > + } while (ch > 0 && ch != '\n');
> > > + return 0;
> > > + }
> > >   }
> > >
> > > That doesn't use io__getline - so we've not matched the 0x0...0 case
> > > to terminate the records. Could you add some logging/debug?
> > >
> > I printed every charactor got by io__get_char(), based on previous debug change.
> > Please see logs below.
> >
> > # To display the perf.data header info, please use --header/--header-only options.
> > #
> > addr2line: /home/changbin/.debug/.build-id/5e/2fa721660d663f38b6e1aa98d6fa3776974b54/elf, addr ffffffff81e000aa
> > subprocess: addr2line -e /home/changbin/.debug/.build-id/5e/2fa721660d663f38b6e1aa98d6fa3776974b54/elf -a -i -f
> > io__get_char: '0'
> > io__get_char: 'x'
> > io__get_char: '0'
> > io__get_char: '0'
> > io__get_char: '0'
> > io__get_char: '0'
> > io__get_char: '0'
> > io__get_char: '0'
> > io__get_char: '0'
> > io__get_char: '0'
> > io__get_char: '0'
> > io__get_char: '0'
> > io__get_char: '0'
> > io__get_char: '0'
> > io__get_char: '0'
> > io__get_char: '0'
> > io__get_char: '0'
> > io__get_char: '0'
> > io__get_char: '
> > '
> > io__get_char: '_'
> > io__get_char: '_'
> > io__get_char: 'p'
> > io__get_char: 'e'
> > io__get_char: 'r'
> > io__get_char: '_'
> > io__get_char: 'c'
> > io__get_char: 'p'
> > io__get_char: 'u'
> > io__get_char: '_'
> > io__get_char: 's'
> > io__get_char: 't'
> > io__get_char: 'a'
> > io__get_char: 'r'
> > io__get_char: 't'
> > io__get_char: '
> > '
> > io__get_char: '?'
> > io__get_char: '?'
> > io__get_char: ':'
> > io__get_char: '?'
> > io__get_char: '
> > '
> > read_addr2line_record
> > io__getline: start
> > io__get_char: '0'
> > io__get_char: 'x'
> > io__get_char: 'f'
> > io__get_char: 'f'
> > io__get_char: 'f'
> > io__get_char: 'f'
> > io__get_char: 'f'
> > io__get_char: 'f'
> > io__get_char: 'f'
> > io__get_char: 'f'
> > io__get_char: '8'
> > io__get_char: '1'
> > io__get_char: 'e'
> > io__get_char: '0'
> > io__get_char: '0'
> > io__get_char: '0'
> > io__get_char: 'a'
> > io__get_char: 'a'
> > io__get_char: '
> > '
> > io__getline: 0xffffffff81e000aa
> >
> > io__getline: start
> > io__get_char: 'e'
> > io__get_char: 'n'
> > io__get_char: 't'
> > io__get_char: 'r'
> > io__get_char: 'y'
> > io__get_char: '_'
> > io__get_char: 'S'
> > io__get_char: 'Y'
> > io__get_char: 'S'
> > io__get_char: 'C'
> > io__get_char: 'A'
> > io__get_char: 'L'
> > io__get_char: 'L'
> > io__get_char: '_'
> > io__get_char: '6'
> > io__get_char: '4'
> > io__get_char: '_'
> > io__get_char: 'a'
> > io__get_char: 'f'
> > io__get_char: 't'
> > io__get_char: 'e'
> > io__get_char: 'r'
> > io__get_char: '_'
> > io__get_char: 'h'
> > io__get_char: 'w'
> > io__get_char: 'f'
> > io__get_char: 'r'
> > io__get_char: 'a'
> > io__get_char: 'm'
> > io__get_char: 'e'
> > io__get_char: '
> > '
> > io__getline: entry_SYSCALL_64_after_hwframe
> >
> > io__getline: start
> > io__get_char: '?'
> > io__get_char: '?'
> > io__get_char: ':'
> > io__get_char: '?'
> > io__get_char: '
> > '
> > io__getline: ??:?
> >
> > read_addr2line_record
> > io__getline: start
> > io__get_char: '0'
> > io__get_char: 'x'
> > io__get_char: '0'
> > io__get_char: '0'
> > io__get_char: '0'
> > io__get_char: '0'
> > io__get_char: '0'
> > io__get_char: '0'
> > io__get_char: '0'
> > io__get_char: '0'
> > io__get_char: '0'
> > io__get_char: '0'
> > io__get_char: '0'
> > io__get_char: '0'
> > io__get_char: '0'
> > io__get_char: '0'
> > io__get_char: '0'
> > io__get_char: '0'
> > io__get_char: '
> > '
> > io__getline: 0x0000000000000000
> >
> > io__getline: start
> > io__get_char: '_'
> > io__get_char: '_'
> > io__get_char: 'p'
> > io__get_char: 'e'
> > io__get_char: 'r'
> > io__get_char: '_'
> > io__get_char: 'c'
> > io__get_char: 'p'
> > io__get_char: 'u'
> > io__get_char: '_'
> > io__get_char: 's'
> > io__get_char: 't'
> > io__get_char: 'a'
> > io__get_char: 'r'
> > io__get_char: 't'
> > io__get_char: '
> > '
> > io__getline: __per_cpu_start
> >
> > io__getline: start
> > io__get_char: '?'
> > io__get_char: '?'
> > io__get_char: ':'
> > io__get_char: '?'
> > io__get_char: '
> > '
> > io__getline: ??:?
> >
> > read_addr2line_record
> > io__getline: start
> > [stuck]
> 
> 
> Cool. Looks like the terminating '\n' is the issue. It is specified to
> be part of getline. Can you tweak:
> 
> + if (line[i] == '0')
> + zero_count++;
> + else
> + non_zero_count++;
> 
> to be:
> 
> + if (line[i] == '0')
> + zero_count++;
> + else if (line[i] != '\n')
> + non_zero_count++;
>
Wonderful, this works. The issue is gone with this change. :)

> Thanks,
> Ian
> 
> > > Thanks,
> > > Ian
> > >
> > > > > > Thanks,
> > > > > > Ian
> > > > > >
> > > > > > > >
> > > > > > > > > Thanks,
> > > > > > > > > Ian
> > > > > > > > >
> > > > > > > > > > --
> > > > > > > > > > Cheers,
> > > > > > > > > > Changbin Du
> > > > > > >
> > > > > > > --
> > > > > > > Cheers,
> > > > > > > Changbin Du
> > > > >
> > > > > --
> > > > > Cheers,
> > > > > Changbin Du
> > > >
> > > > --
> > > > Cheers,
> > > > Changbin Du
> >
> > --
> > Cheers,
> > Changbin Du

-- 
Cheers,
Changbin Du

Re: [Issue] perf report gets stuck at addr2line

[Ian Rogers]

On Mon, Jun 12, 2023 at 7:32 PM Changbin Du <changbin.du@huawei.com> wrote:
>
> On Mon, Jun 12, 2023 at 07:25:41PM -0700, Ian Rogers wrote:
> > On Mon, Jun 12, 2023 at 7:20 PM Changbin Du <changbin.du@huawei.com> wrote:
> > >
> > > On Mon, Jun 12, 2023 at 08:55:14AM -0700, Ian Rogers wrote:
> > > > On Mon, Jun 12, 2023 at 6:18 AM Changbin Du <changbin.du@huawei.com> wrote:
> > > >
> > > > Thanks Changbin, this should have hit the 0x0...0 sentinel match:
> > > >
> > > > https://lore.kernel.org/lkml/20230609235419.204624-2-irogers@google.com/
> > > > + } else {
> > > > + int zero_count = 0, non_zero_count = 0;
> > > > +
> > > > + /* The address should always start 0x. */
> > > > + if (line_len < 2 || line[0] != '0' || line[1] != 'x')
> > > > + goto error;
> > > > +
> > > > + for (size_t i = 2; i < line_len; i++) {
> > > > + if (line[i] == '0')
> > > > + zero_count++;
> > > > + else
> > > > + non_zero_count++;
> > > > + }
> > > > + if (!non_zero_count) {
> > > > + int ch;
> > > > +
> > > > + if (!zero_count) {
> > > > + /* Line was erroneous just '0x'. */
> > > > + goto error;
> > > > + }
> > > > + /*
> > > > + * Line was 0x0..0, the sentinel for binutils. Remove
> > > > + * the function and filename lines.
> > > > + */
> > > > + zfree(&line);
> > > > + do {
> > > > + ch = io__get_char(io);
> > > > + } while (ch > 0 && ch != '\n');
> > > > + do {
> > > > + ch = io__get_char(io);
> > > > + } while (ch > 0 && ch != '\n');
> > > > + return 0;
> > > > + }
> > > >   }
> > > >
> > > > That doesn't use io__getline - so we've not matched the 0x0...0 case
> > > > to terminate the records. Could you add some logging/debug?
> > > >
> > > I printed every charactor got by io__get_char(), based on previous debug change.
> > > Please see logs below.
> > >
> > > # To display the perf.data header info, please use --header/--header-only options.
> > > #
> > > addr2line: /home/changbin/.debug/.build-id/5e/2fa721660d663f38b6e1aa98d6fa3776974b54/elf, addr ffffffff81e000aa
> > > subprocess: addr2line -e /home/changbin/.debug/.build-id/5e/2fa721660d663f38b6e1aa98d6fa3776974b54/elf -a -i -f
> > > io__get_char: '0'
> > > io__get_char: 'x'
> > > io__get_char: '0'
> > > io__get_char: '0'
> > > io__get_char: '0'
> > > io__get_char: '0'
> > > io__get_char: '0'
> > > io__get_char: '0'
> > > io__get_char: '0'
> > > io__get_char: '0'
> > > io__get_char: '0'
> > > io__get_char: '0'
> > > io__get_char: '0'
> > > io__get_char: '0'
> > > io__get_char: '0'
> > > io__get_char: '0'
> > > io__get_char: '0'
> > > io__get_char: '0'
> > > io__get_char: '
> > > '
> > > io__get_char: '_'
> > > io__get_char: '_'
> > > io__get_char: 'p'
> > > io__get_char: 'e'
> > > io__get_char: 'r'
> > > io__get_char: '_'
> > > io__get_char: 'c'
> > > io__get_char: 'p'
> > > io__get_char: 'u'
> > > io__get_char: '_'
> > > io__get_char: 's'
> > > io__get_char: 't'
> > > io__get_char: 'a'
> > > io__get_char: 'r'
> > > io__get_char: 't'
> > > io__get_char: '
> > > '
> > > io__get_char: '?'
> > > io__get_char: '?'
> > > io__get_char: ':'
> > > io__get_char: '?'
> > > io__get_char: '
> > > '
> > > read_addr2line_record
> > > io__getline: start
> > > io__get_char: '0'
> > > io__get_char: 'x'
> > > io__get_char: 'f'
> > > io__get_char: 'f'
> > > io__get_char: 'f'
> > > io__get_char: 'f'
> > > io__get_char: 'f'
> > > io__get_char: 'f'
> > > io__get_char: 'f'
> > > io__get_char: 'f'
> > > io__get_char: '8'
> > > io__get_char: '1'
> > > io__get_char: 'e'
> > > io__get_char: '0'
> > > io__get_char: '0'
> > > io__get_char: '0'
> > > io__get_char: 'a'
> > > io__get_char: 'a'
> > > io__get_char: '
> > > '
> > > io__getline: 0xffffffff81e000aa
> > >
> > > io__getline: start
> > > io__get_char: 'e'
> > > io__get_char: 'n'
> > > io__get_char: 't'
> > > io__get_char: 'r'
> > > io__get_char: 'y'
> > > io__get_char: '_'
> > > io__get_char: 'S'
> > > io__get_char: 'Y'
> > > io__get_char: 'S'
> > > io__get_char: 'C'
> > > io__get_char: 'A'
> > > io__get_char: 'L'
> > > io__get_char: 'L'
> > > io__get_char: '_'
> > > io__get_char: '6'
> > > io__get_char: '4'
> > > io__get_char: '_'
> > > io__get_char: 'a'
> > > io__get_char: 'f'
> > > io__get_char: 't'
> > > io__get_char: 'e'
> > > io__get_char: 'r'
> > > io__get_char: '_'
> > > io__get_char: 'h'
> > > io__get_char: 'w'
> > > io__get_char: 'f'
> > > io__get_char: 'r'
> > > io__get_char: 'a'
> > > io__get_char: 'm'
> > > io__get_char: 'e'
> > > io__get_char: '
> > > '
> > > io__getline: entry_SYSCALL_64_after_hwframe
> > >
> > > io__getline: start
> > > io__get_char: '?'
> > > io__get_char: '?'
> > > io__get_char: ':'
> > > io__get_char: '?'
> > > io__get_char: '
> > > '
> > > io__getline: ??:?
> > >
> > > read_addr2line_record
> > > io__getline: start
> > > io__get_char: '0'
> > > io__get_char: 'x'
> > > io__get_char: '0'
> > > io__get_char: '0'
> > > io__get_char: '0'
> > > io__get_char: '0'
> > > io__get_char: '0'
> > > io__get_char: '0'
> > > io__get_char: '0'
> > > io__get_char: '0'
> > > io__get_char: '0'
> > > io__get_char: '0'
> > > io__get_char: '0'
> > > io__get_char: '0'
> > > io__get_char: '0'
> > > io__get_char: '0'
> > > io__get_char: '0'
> > > io__get_char: '0'
> > > io__get_char: '
> > > '
> > > io__getline: 0x0000000000000000
> > >
> > > io__getline: start
> > > io__get_char: '_'
> > > io__get_char: '_'
> > > io__get_char: 'p'
> > > io__get_char: 'e'
> > > io__get_char: 'r'
> > > io__get_char: '_'
> > > io__get_char: 'c'
> > > io__get_char: 'p'
> > > io__get_char: 'u'
> > > io__get_char: '_'
> > > io__get_char: 's'
> > > io__get_char: 't'
> > > io__get_char: 'a'
> > > io__get_char: 'r'
> > > io__get_char: 't'
> > > io__get_char: '
> > > '
> > > io__getline: __per_cpu_start
> > >
> > > io__getline: start
> > > io__get_char: '?'
> > > io__get_char: '?'
> > > io__get_char: ':'
> > > io__get_char: '?'
> > > io__get_char: '
> > > '
> > > io__getline: ??:?
> > >
> > > read_addr2line_record
> > > io__getline: start
> > > [stuck]
> >
> >
> > Cool. Looks like the terminating '\n' is the issue. It is specified to
> > be part of getline. Can you tweak:
> >
> > + if (line[i] == '0')
> > + zero_count++;
> > + else
> > + non_zero_count++;
> >
> > to be:
> >
> > + if (line[i] == '0')
> > + zero_count++;
> > + else if (line[i] != '\n')
> > + non_zero_count++;
> >
> Wonderful, this works. The issue is gone with this change. :)

Cool. I'll send out a new patch set. Thanks,
Ian

> > Thanks,
> > Ian
> >
> > > > Thanks,
> > > > Ian
> > > >
> > > > > > > Thanks,
> > > > > > > Ian
> > > > > > >
> > > > > > > > >
> > > > > > > > > > Thanks,
> > > > > > > > > > Ian
> > > > > > > > > >
> > > > > > > > > > > --
> > > > > > > > > > > Cheers,
> > > > > > > > > > > Changbin Du
> > > > > > > >
> > > > > > > > --
> > > > > > > > Cheers,
> > > > > > > > Changbin Du
> > > > > >
> > > > > > --
> > > > > > Cheers,
> > > > > > Changbin Du
> > > > >
> > > > > --
> > > > > Cheers,
> > > > > Changbin Du
> > >
> > > --
> > > Cheers,
> > > Changbin Du
>
> --
> Cheers,
> Changbin Du