addr2line reports incorrect line numbers

[igrr]

In some cases xtensa-{esp32,lx106}-elf-addr2line reports line numbers which don't match the source code. If the same address is passed into gdb, gdb reports correct line number.

Example (with xtensa-esp32-elf):

xtensa-esp32-elf-addr2line -pfia -e unit-test-app.elf <<<"0x400859b1"
0x400859b1: spi_flash_read at /Users/ivan/e/esp-idf/components/spi_flash/./flash_ops.c:521

xtensa-esp32-elf-gdb unit-test-app.elf -ex "l *0x400859b1" -ex "q"
GNU gdb (crosstool-NG crosstool-ng-1.22.0-70-gfa0bad1) 7.10
<snip>
0x400859b1 is in spi_flash_read (/Users/ivan/e/esp-idf/components/spi_flash/./flash_ops.c:454).
449	/Users/ivan/e/esp-idf/components/spi_flash/./flash_ops.c: No such file or directory.

This address was part of a backtrace; based on the context i see that 454 is the correct line.

unit-test-app.zip

[jcmvbkbc]

I've taken a look into it. It goes into the generic DWARF handling by the generic ELF BFD, i.e. it doesn't look xtensa-specific to me. I'll look at it a bit more.

[igrr]

I've started looking into this as well. Both gdb and addr2line use very similar code to parse DWARF information:
gdb: dwarf_decode_line_1 in dwarf2read.c
addr2line: decode_line_info in dwarf2.c

It wasn't easy to figure out if there are any differences in logic at this stage, so I have traced the calls to dwarf_record_line_1 (gdb has a run time flag for this) and add_line_info. As far as i can tell, both tools get the same (correct!) line numbers at this stage.

So it seems that the issue with addr2line is somewhere in _bfd_dwarf2_find_nearest_line.
It might be some time before I get a chance to work on this again, so wanted to save the context here.

[igrr]

it doesn't look xtensa-specific to me

I still don't know why this is observed on xtensa but not on x86_64 and arm (with gcc 5.2), but I have figured out a small test case. It turns out that the use of -ffunction-sections and --gc-sections is what triggers the issue.

In the attached test, run make check, setting PREFIX to the toolchain triple:

$ make check PREFIX=xtensa-esp32-elf-
xtensa-esp32-elf-gcc -ffunction-sections -g -O0 -c -o main.o main.c
xtensa-esp32-elf-gcc -ffunction-sections -g -O0 -c -o tools.o tools.c
xtensa-esp32-elf-gcc -g -O0 -Wl,--gc-sections -e entry -nostdlib -o test main.o tools.o
xtensa-esp32-elf-nm test | grep print | cut -d ' ' -f1 | xtensa-esp32-elf-addr2line -pfia -e test
0x0040005c: print at /Users/ivan/e/ESPTools/addr2line_test/tools.c:22
$ make clean
rm -f main.o tools.o  test
$ make check PREFIX=xtensa-lx106-elf-
xtensa-lx106-elf-gcc -ffunction-sections -g -O0 -c -o main.o main.c
xtensa-lx106-elf-gcc -ffunction-sections -g -O0 -c -o tools.o tools.c
xtensa-lx106-elf-gcc -g -O0 -Wl,--gc-sections -e entry -nostdlib -o test main.o tools.o
xtensa-lx106-elf-nm test | grep print | cut -d ' ' -f1 | xtensa-lx106-elf-addr2line -pfia -e test
0x0040007c: print at /Users/ivan/e/ESPTools/addr2line_test/tools.c:22
$ make clean
rm -f main.o tools.o  test
$ make check PREFIX=arm-none-eabi-
arm-none-eabi-gcc -ffunction-sections -g -O0 -c -o main.o main.c
arm-none-eabi-gcc -ffunction-sections -g -O0 -c -o tools.o tools.c
arm-none-eabi-gcc -g -O0 -Wl,--gc-sections -e entry -nostdlib -o test main.o tools.o
arm-none-eabi-nm test | grep print | cut -d ' ' -f1 | arm-none-eabi-addr2line -pfia -e test
0x0000801c: print at /Users/ivan/e/ESPTools/addr2line_test/tools.c:12

Function print is in tools.c:12, so the result produced by arm-none-eabi-addr2line is correct.

addr2line_test.zip

Edit:

Looks like the logic in bfd/dwarf2.c:add_line_info breaks with the following line info (generated by xtensa-esp32-elf):

0x00000000  [   7, 0] NS uri: "addr2line_test/tools.c"
0x00000000  [   8, 0] NS
0x00000000  [   9, 0] NS
0x00000000  [   9, 0] NS ET
0x0040005c  [  12, 0] NS
0x00400063  [  13, 0] NS
0x00400068  [  14, 0] NS
0x00400073  [  15, 0] NS
0x00400079  [  13, 0] NS
0x0040007e  [  17, 0] NS
0x00400082  [  17, 0] NS ET
0x00000000  [  20, 0] NS
0x00000000  [  21, 0] NS
0x00000000  [  22, 0] NS
0x00000000  [  22, 0] NS ET
0x00400084  [  25, 0] NS
0x00400089  [  26, 0] NS
0x00400091  [  27, 0] NS
0x00400095  [  27, 0] NS ET

In this case, only lines 22 and 27 end up being recorded.

It doesn't break for the following debug info (produced by arm-none-eabi):

0x00000000  [   7, 0] NS uri: "addr2line_test/tools.c"
0x00000008  [   8, 0] NS
0x00000010  [   9, 0] NS
0x00000024  [   9, 0] NS ET
0x0000801c  [  12, 0] NS
0x0000802c  [  13, 0] NS
0x00008030  [  14, 0] NS
0x00008040  [  15, 0] NS
0x0000804c  [  13, 0] NS
0x00008058  [  17, 0] NS
0x00008068  [  17, 0] NS ET
0x00000000  [  20, 0] NS
0x00000008  [  21, 0] NS
0x00000010  [  22, 0] NS
0x00000024  [  22, 0] NS ET
0x00008068  [  25, 0] NS
0x00008070  [  26, 0] NS
0x00008078  [  27, 0] NS
0x0000808c  [  27, 0] NS ET

Notable is the following comment in add_line_info:

/* Find the correct location for 'info'.  Normally we will receive
 new line_info data 1) in order and 2) with increasing VMAs.
 However some compilers break the rules (cf. decode_line_info) and
 so we include some heuristics for quickly finding the correct
 location for 'info'. In particular, these heuristics optimize for
 the common case in which the VMA sequence that we receive is a
 list of locally sorted VMAs such as
   p...z a...j  (where a < j < p < z)

 Note: table->lcl_head is used to head an *actual* or *possible*
 sub-sequence within the list (such as a...j) that is not directly
 headed by table->last_line

 Note: we may receive duplicate entries from 'decode_line_info'.  */