[Bug translator/25193] New: Incorrect reporting of line information for stap -v -L 'process("/usr/bin/ld.gold").statement("*@*:*")'

[Bug translator/25193] New: Incorrect reporting of line information for stap -v -L 'process("/usr/bin/ld.gold").statement("*@*:*")'

[wcohen at redhat dot com]

https://sourceware.org/bugzilla/show_bug.cgi?id=25193

            Bug ID: 25193
           Summary: Incorrect reporting of line information for stap -v -L
                    'process("/usr/bin/ld.gold").statement("*@*:*")'
           Product: systemtap
           Version: unspecified
            Status: NEW
          Severity: normal
          Priority: P2
         Component: translator
          Assignee: systemtap at sourceware dot org
          Reporter: wcohen at redhat dot com
  Target Milestone: ---

The mechanism determining the line number from the debuginfo is getting the
line information incorrect.  This was observed on Fedora 30 with
binutils-2.31.1-29.fc30.x86_64:

stap -v -L 'process("/usr/bin/ld.gold").statement("*@*:*")'

Provides a huge number of statements at line 128 for different files.  It turns
out this is due to gcc c++ compiler inlining line 128 from
/usr/include/c++/9/ext/new_allocator.h in many different places.  The line 128
makes sense for the new_allocator.h head file but not for the other statement
probe points at the same instruction:

process("/usr/bin/ld.gold").statement("Abbrev_code@/usr/src/debug/binutils-2.31.1-29.fc30.x86_64/gold/dwarf_reader.h:128")
/* pc=.dynamic+0x189925 */ $this:struct Abbrev_code* const
process("/usr/bin/ld.gold").statement("_M_deallocate@/usr/include/c++/9/bits/stl_vector.h:128")
/* pc=.dynamic+0x189925 */ $this:struct
_Vector_base<gold::Dwarf_abbrev_table::Attribute,
std::allocator<gold::Dwarf_abbrev_table::Attribute> >* const $__n:size_t
$__p:pointer
process("/usr/bin/ld.gold").statement("deallocate@/usr/include/c++/9/bits/alloc_traits.h:128")
/* pc=.dynamic+0x189925 */ $__a:allocator_type& $__n:size_type $__p:pointer
process("/usr/bin/ld.gold").statement("deallocate@/usr/include/c++/9/ext/new_allocator.h:128")
/* pc=.dynamic+0x189925 */ $this:class
new_allocator<gold::Dwarf_abbrev_table::Attribute>* const $__p:pointer
process("/usr/bin/ld.gold").statement("do_get_abbrev@/usr/src/debug/binutils-2.31.1-29.fc30.x86_64/gold/dwarf_reader.cc:128")
/* pc=.dynamic+0x189925 */ $len:size_t $nextcode:uint64_t $this:class
Dwarf_abbrev_table* const $code:unsigned int
process("/usr/bin/ld.gold").statement("reserve@/usr/include/c++/9/bits/vector.tcc:128")
/* pc=.dynamic+0x189925 */ $__old_size:size_type const $__tmp:pointer
$__n:size_type $this:class vector<gold::Dwarf_abbrev_table::Attribute,
std::allocator<gold::Dwarf_abbrev_table::Attribute> >* const


According to "readelf --wide -wLK 
/usr/lib/debug/usr/bin/ld.gold-2.31.1-29.fc30.x86_64.debug" it maps to the
following:

/usr/include/c++/9/bits/alloc_traits.h:
alloc_traits.h                               469            0x189925

/usr/include/c++/9/ext/new_allocator.h:
new_allocator.h                              119            0x189925       1
new_allocator.h                              128            0x189925       2

It appears that stap is always using the last view's line number information
regardless of the view. 

fche suggested that the problem might be in tapsets.cxx:query_srcfile_line.

-- 
You are receiving this mail because:
You are the assignee for the bug.

[Bug translator/25193] Incorrect reporting of line information for stap -v -L 'process("/usr/bin/ld.gold").statement("*@*:*")'

[wcohen at redhat dot com]

https://sourceware.org/bugzilla/show_bug.cgi?id=25193

--- Comment #1 from William Cohen <wcohen at redhat dot com> ---
Created attachment 12526
  --> https://sourceware.org/bugzilla/attachment.cgi?id=12526&action=edit
Much smaller reproduer example with multiple line views for the same
instruction

multiple_views.cc is a much smaller reproducer which systemtap generates very
odd list of probe points for individual instructions.

$ rpm -q gcc systemtap elfutils
gcc-10.1.1-1.fc32.x86_64
systemtap-4.3-1.202005111542.fc32.x86_64
elfutils-0.179-2.fc32pr25549.x86_64
$ g++ -g -O2 -o multiple_views multiple_views.cc
$stap -v -L 'process("./multiple_views").statement("*@*:*")' >&
multiple_views.stap_out
$ cat multiple_views.stap_out |grep -o -e 'pc=.absolute+0x[[:alnum:]]\+' |sort
|uniq -c |sort -nr|more
     14 pc=.absolute+0x10ef
      7 pc=.absolute+0x10e6
      7 pc=.absolute+0x10dd
      5 pc=.absolute+0x10d8
      5 pc=.absolute+0x10c1
      5 pc=.absolute+0x10b8
      4 pc=.absolute+0x10fd
      3 pc=.absolute+0x10cf
      2 pc=.absolute+0x10f3
      2 pc=.absolute+0x10e1
      2 pc=.absolute+0x10b0
      1 pc=.absolute+0x1105
      1 pc=.absolute+0x10c0

There are a lot of probes (14) on 0x10ef.  Look at the "readelf
--debug-dump=decodedline multiple_views" for the 0x10ef instruction there are 6
views:

/usr/include/c++/10/bits/basic_string.h:
basic_string.h                               214            0x4010dd           
   x
basic_string.h                               182            0x4010dd       1   
   x
basic_string.h                               187            0x4010dd       2
basic_string.h                              6463            0x4010e1        
basic_string.h                               183            0x4010e6        
basic_string.h                               183            0x4010ef        
basic_string.h                               186            0x4010ef       1   
   x
basic_string.h                               186            0x4010ef       2

/usr/include/c++/10/bits/char_traits.h:
char_traits.h                                321            0x4010ef       3   
   x
char_traits.h                                322            0x4010ef       4   
   x
char_traits.h                                322            0x4010ef       5
char_traits.h                                322            0x4010f3        

Sorting by line number makes it a bit more obvious that systemtap is getting
something wrong as it is very unlikely that multiple files would end up having
the same line number for the same instruction:

$ grep 0x10ef multiple_views.stap_out |sort -t: -k2n
process("/home/wcohen/multiple_views").statement("assign@/usr/include/c++/10/bits/char_traits.h:186")
/* pc=.absolute+0x10ef */ $__c1:char_type&
process("/home/wcohen/multiple_views").statement("basic_string@/usr/include/c++/10/bits/basic_string.h:186")
/* pc=.absolute+0x10ef */ $__s:char const* $this:class basic_string<char,
std::char_traits<char>, std::allocator<char> >* const
process("/home/wcohen/multiple_views").statement("main@/home/wcohen/multiple_views.cc:186")
/* pc=.absolute+0x10ef */ $argc:int $argv:char** $a:string
process("/home/wcohen/multiple_views").statement("_M_construct_aux<char
const*>@/usr/include/c++/10/bits/basic_string.h:186") /* pc=.absolute+0x10ef */
$__end:char const* $__beg:char const* $this:class basic_string<char,
std::char_traits<char>, std::allocator<char> >* const
process("/home/wcohen/multiple_views").statement("_M_construct<char
const*>@/usr/include/c++/10/bits/basic_string.h:186") /* pc=.absolute+0x10ef */
$__end:char const* $__beg:char const* $this:class basic_string<char,
std::char_traits<char>, std::allocator<char> >* const
process("/home/wcohen/multiple_views").statement("_M_construct<char
const*>@/usr/include/c++/10/bits/basic_string.tcc:186") /* pc=.absolute+0x10ef
*/ $__dnew:size_type $__end:char const* $__beg:char const* $this:class
basic_string<char, std::char_traits<char>, std::allocator<char> >* const
process("/home/wcohen/multiple_views").statement("_M_set_length@/usr/include/c++/10/bits/basic_string.h:186")
/* pc=.absolute+0x10ef */ $__n:size_type $this:class basic_string<char,
std::char_traits<char>, std::allocator<char> >* const
process("/home/wcohen/multiple_views").statement("assign@/usr/include/c++/10/bits/char_traits.h:322")
/* pc=.absolute+0x10ef */ $__c1:char_type&
process("/home/wcohen/multiple_views").statement("basic_string@/usr/include/c++/10/bits/basic_string.h:322")
/* pc=.absolute+0x10ef */ $__s:char const* $this:class basic_string<char,
std::char_traits<char>, std::allocator<char> >* const
process("/home/wcohen/multiple_views").statement("main@/home/wcohen/multiple_views.cc:322")
/* pc=.absolute+0x10ef */ $argc:int $argv:char** $a:string
process("/home/wcohen/multiple_views").statement("_M_construct_aux<char
const*>@/usr/include/c++/10/bits/basic_string.h:322") /* pc=.absolute+0x10ef */
$__end:char const* $__beg:char const* $this:class basic_string<char,
std::char_traits<char>, std::allocator<char> >* const
process("/home/wcohen/multiple_views").statement("_M_construct<char
const*>@/usr/include/c++/10/bits/basic_string.h:322") /* pc=.absolute+0x10ef */
$__end:char const* $__beg:char const* $this:class basic_string<char,
std::char_traits<char>, std::allocator<char> >* const
process("/home/wcohen/multiple_views").statement("_M_construct<char
const*>@/usr/include/c++/10/bits/basic_string.tcc:322") /* pc=.absolute+0x10ef
*/ $__dnew:size_type $__end:char const* $__beg:char const* $this:class
basic_string<char, std::char_traits<char>, std::allocator<char> >* const
process("/home/wcohen/multiple_views").statement("_M_set_length@/usr/include/c++/10/bits/basic_string.h:322")
/* pc=.absolute+0x10ef */ $__n:size_type $this:class basic_string<char,
std::char_traits<char>, std::allocator<char> >* const

-- 
You are receiving this mail because:
You are the assignee for the bug.

[Bug translator/25193] Incorrect reporting of line information for stap -v -L 'process("/usr/bin/ld.gold").statement("*@*:*")'

[wcohen at redhat dot com]

https://sourceware.org/bugzilla/show_bug.cgi?id=25193

--- Comment #2 from William Cohen <wcohen at redhat dot com> ---
Note for focusing on function main there is no non exist line location like:

process("/home/wcohen/multiple_views").statement("main@/home/wcohen/multiple_views.cc:322")
/* pc=.absolute+0x10ef */ $argc:int $argv:char** $a:string

The probe points look reasonable on executable lines of code:

$ stap -v -L 'process("./multiple_views").statement("main@*:*")'
Pass 1: parsed user script and 502 library scripts using
442600virt/212240res/12836shr/199240data kb, in 440usr/70sys/507real ms.
process("/home/wcohen/multiple_views").statement("main@/home/wcohen/multiple_views.cc:10")
/* pc=.absolute+0x10fd */ $argc:int $argv:char** $a:string
process("/home/wcohen/multiple_views").statement("main@/home/wcohen/multiple_views.cc:11")
/* pc=.absolute+0x1105 */ $argc:int $argv:char** $a:string
process("/home/wcohen/multiple_views").statement("main@/home/wcohen/multiple_views.cc:7")
/* pc=.absolute+0x10c0 */ $argc:int $argv:char** $a:string
process("/home/wcohen/multiple_views").statement("main@/home/wcohen/multiple_views.cc:9")
/* pc=.absolute+0x10f3 */ $argc:int $argv:char** $a:string
Pass 2: analyzed script: 4 probes, 0 functions, 0 embeds, 0 globals using
451432virt/222616res/14036shr/208072data kb, in 40usr/0sys/59real ms.

-- 
You are receiving this mail because:
You are the assignee for the bug.

[Bug translator/25193] Incorrect reporting of line information for stap -v -L 'process("/usr/bin/ld.gold").statement("*@*:*")'

[wcohen at redhat dot com]

https://sourceware.org/bugzilla/show_bug.cgi?id=25193

--- Comment #3 from William Cohen <wcohen at redhat dot com> ---
Here is what happening:

1) dwflpp.cxx template iterate_over_srcfile_lines focuses on individual srcfile
it uses collect_all_lines (dwflpp.cxx:1914) to generate a vector of the
addresses (variable matching_lines). The elements of matching_lines includes
information about the file, line, column
2) However, the loop dwflpp.cxx:1972 doesn't pass that file information.
3) Instead tapsets.cxx query_srcfile_line tries to infer/regenerate it from the
address by seeing if the address are contained in any of the elements of bfis.
4) query_srcfile_line mis-matches as the criteria ends up being whether the 
address is contained within the items returned by q->filtered_all() rather than
the function/line/source file match up.
5) The lineno passed into query_srcfile_line() is paired with unrelated
functions and file names as observed in the example causing the reproducer to
list lines that do not exist in reality.

-- 
You are receiving this mail because:
You are the assignee for the bug.

[Bug translator/25193] Incorrect reporting of line information for stap -v -L 'process("/usr/bin/ld.gold").statement("*@*:*")'

[wcohen at redhat dot com]

https://sourceware.org/bugzilla/show_bug.cgi?id=25193

--- Comment #4 from William Cohen <wcohen at redhat dot com> ---
Maybe adjust the filtering done by filter_all() to limit search to functions in
the file being examined by  query_srcfile_line().  However, this approach might
end up missing functions like  PR25972.

-- 
You are receiving this mail because:
You are the assignee for the bug.

[Bug translator/25193] Incorrect reporting of line information for stap -v -L 'process("/usr/bin/ld.gold").statement("*@*:*")'

[wcohen at redhat dot com]

https://sourceware.org/bugzilla/show_bug.cgi?id=25193

--- Comment #5 from William Cohen <wcohen at redhat dot com> ---
GDB has some ability to provide backtraces that include inlined functions. 
Should see how gdb is able to get that information about source line and
function name.

Used following to find an inlined function to set a breakpoint on: 
$  stap -v -L 'process("./multiple_views").function("*").inline'


$ gdb multiple_views 
...
(gdb) break _M_set_length
Breakpoint 1 at 0x4010dd: file /usr/include/c++/10/bits/basic_string.h, line
214.
(gdb) run
Starting program: /home/wcohen/multiple_views 
Missing separate debuginfo for /lib64/libstdc++.so.6
Try: dnf --enablerepo='*debug*' install
/usr/lib/debug/.build-id/7a/fd1ced0ad3b1fdfe1b121ae292881439af5e57.debug

Breakpoint 1, std::__cxx11::basic_string<char, std::char_traits<char>,
std::allocator<char> >::_M_set_length (__n=12, 
    this=0x7fffffffd7d0) at /usr/include/c++/10/bits/basic_string.h:217
217             traits_type::assign(_M_data()[__n], _CharT());
(gdb) where
#0  std::__cxx11::basic_string<char, std::char_traits<char>,
std::allocator<char> >::_M_set_length (__n=12, 
    this=0x7fffffffd7d0) at /usr/include/c++/10/bits/basic_string.h:217
#1  std::__cxx11::basic_string<char, std::char_traits<char>,
std::allocator<char> >::_M_construct<char const*> (
    __end=0x40201c "", __beg=0x402010 "hello world\n", this=0x7fffffffd7d0) at
/usr/include/c++/10/bits/basic_string.tcc:232
#2  std::__cxx11::basic_string<char, std::char_traits<char>,
std::allocator<char> >::_M_construct_aux<char const*> (
    __end=0x40201c "", __beg=0x402010 "hello world\n", this=0x7fffffffd7d0) at
/usr/include/c++/10/bits/basic_string.h:247
#3  std::__cxx11::basic_string<char, std::char_traits<char>,
std::allocator<char> >::_M_construct<char const*> (
    __end=0x40201c "", __beg=0x402010 "hello world\n", this=0x7fffffffd7d0) at
/usr/include/c++/10/bits/basic_string.h:266
#4  std::__cxx11::basic_string<char, std::char_traits<char>,
std::allocator<char> >::basic_string (__a=..., 
    __s=0x402010 "hello world\n", this=0x7fffffffd7d0) at
/usr/include/c++/10/bits/basic_string.h:527
#5  main (argc=<optimized out>, argv=<optimized out>) at multiple_views.cc:8
(gdb) p/x $pc
$1 = 0x4010dd

-- 
You are receiving this mail because:
You are the assignee for the bug.