[Bug translator/27984] New: stap skipping partially-inlined instance, but it is not inline function actually

[Bug translator/27984] New: stap skipping partially-inlined instance, but it is not inline function actually

[zhuizhuhaomeng at gmail dot com]

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

            Bug ID: 27984
           Summary: stap skipping partially-inlined instance, but it is
                    not inline function actually
           Product: systemtap
           Version: unspecified
            Status: UNCONFIRMED
          Severity: normal
          Priority: P2
         Component: translator
          Assignee: systemtap at sourceware dot org
          Reporter: zhuizhuhaomeng at gmail dot com
  Target Milestone: ---

Created attachment 13495
  --> https://sourceware.org/bugzilla/attachment.cgi?id=13495&action=edit
the object file of libssl.so

The stap script:

probe
process("/usr/local/openresty/openssl/lib/libssl.so.1.1").function("tls_process_client_hello")
{
    var_pid = pid();
    printf("%ld\n", var_pid);
}


The build steps:
time /usr/bin/stap --sysroot=/tmp/stap-job1/sysroot -vvvvv \
        -p2 \
        -d "/usr/local/openresty/openssl/lib/libssl.so.1.1" --disable-cache \
        "test.stp"

how to reproduce it:
download the attachment, and decompress to /tmp director.
enter into the /tmp/stap-job1 direcotry and run sh make.sh.



dwarf_builder::build for
/tmp/stap-job1/sysroot/usr/local/openresty/openssl/lib/libssl.so.1.1
parse 'tls_process_client_hello', func 'tls_process_client_hello'
pattern '/tmp/stap-job1/sysroot/usr/local/openresty/openssl/lib/libssl.so.1.1'
matches module
'/tmp/stap-job1/sysroot/usr/local/openresty/openssl/lib/libssl.so.1.1'
focused on module
'/tmp/stap-job1/sysroot/usr/local/openresty/openssl/lib/libssl.so.1.1' =
[0x10000-0xa59b0, bias 0 file
/tmp/stap-job1/sysroot/usr/local/openresty/openssl/lib/libssl.so.1.1 ELF
machine |x86_64 (code 62)
focused on module
'/tmp/stap-job1/sysroot/usr/local/openresty/openssl/lib/libssl.so.1.1'
module function cache
/tmp/stap-job1/sysroot/usr/local/openresty/openssl/lib/libssl.so.1.1 size 1785
module function cache
/tmp/stap-job1/sysroot/usr/local/openresty/openssl/lib/libssl.so.1.1 hit
tls_process_client_hello
selected function tls_process_client_hello
skipping partially-inlined instance state_machine.part.0 at 0x61b70
suggesting 1898 dwarf functions from modules:
/tmp/stap-job1/sysroot/usr/local/openresty/openssl/lib/libssl.so.1.1
semantic error: while resolving probe point: identifier 'process' at
test.stp:2:7
   thrown from: elaborate.cxx:1067
        source: probe
process("/usr/local/openresty/openssl/lib/libssl.so.1.1").function("tls_process_client_hello")
{
                      ^

semantic error: while resolving probe point: identifier 'process' at :2:7
   thrown from: elaborate.cxx:1067
        source: probe
process("/usr/local/openresty/openssl/lib/libssl.so.1.1").function("tls_process_client_hello")
{
                      ^

semantic error: no match (similar functions: tls_process_client_hello,
tls_post_process_client_hello, tls_process_server_hello,
tls_early_post_process_client_hello, tls_process_cert_verify)
   thrown from: tapsets.cxx:8883
deleting module_cache

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

[Bug translator/27984] stap skipping partially-inlined instance, but it is not inline function actually

[wcohen at redhat dot com]

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

William Cohen <wcohen at redhat dot com> changed:

           What    |Removed                     |Added
----------------------------------------------------------------------------
     Ever confirmed|0                           |1
                 CC|                            |wcohen at redhat dot com
             Status|UNCONFIRMED                 |NEW
   Last reconfirmed|                            |2021-07-14

--- Comment #1 from William Cohen <wcohen at redhat dot com> ---
What specific compiler and openssl source were used to create the reproducer?

If tls_process_client_hello is really a partially inlined function, then it
should be skipped and the probe be place in the inlined piece of
tls_process_client_hello.  However, there doesn't seem to rest of the function
listed as a regular function (DW_TAG_subprogram) or inlined
(DW_TAG_inlined_subroutine) in the debuginfo,but there is a
DW_TAG_GNU_call_site:

$ llvm-dwarfdump  --name=tls_process_client_hello
stap-job1/sysroot/usr/local/openresty/openssl/lib/libssl.so.1.1 
stap-job1/sysroot/usr/local/openresty/openssl/lib/libssl.so.1.1:        file
format elf64-x86-64

0x001069fb: DW_TAG_subprogram
              DW_AT_external    (true)
              DW_AT_name        ("tls_process_client_hello")
              DW_AT_decl_file  
("/tmp/openssl-OpenSSL_1_1_1g/ssl/statem/statem_srvr.c")
              DW_AT_decl_line   (1383)
              DW_AT_decl_column (0x14)
              DW_AT_prototyped  (true)
              DW_AT_type        (0x000ffac0 "MSG_PROCESS_RETURN")
              DW_AT_low_pc      (0x0000000000061b70)
              DW_AT_high_pc     (0x000000000006253e)
              DW_AT_frame_base  (DW_OP_call_frame_cfa)
              DW_AT_GNU_all_call_sites  (true)
              DW_AT_sibling     (0x001081b4)

0x001084cd: DW_TAG_GNU_call_site
              DW_AT_low_pc      (0x0000000000065195)
              DW_AT_GNU_tail_call       (true)
              DW_AT_abstract_origin     (0x001069fb "tls_process_client_hello")

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

[Bug translator/27984] stap skipping partially-inlined instance, but it is not inline function actually

[wcohen at redhat dot com]

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

--- Comment #2 from William Cohen <wcohen at redhat dot com> ---
The function tls_process_client_hello is clearly not partially inlined as would
expect a ".part." in the name from nm if it was:

$ nm stap-job1/sysroot/usr/local/openresty/openssl/lib/libssl.so.1.1  | grep "
t "|grep tls_process_client_hello
0000000000061b70 t tls_process_client_hello

List of functions that have partial inlined code:

$ nm stap-job1/sysroot/usr/local/openresty/openssl/lib/libssl.so.1.1  | grep "
t "|grep "part"
0000000000038c70 t dup_ca_names.part.0
0000000000041f80 t serverinfo_process_buffer.part.0
0000000000036b30 t ssl_conf_cmd_lookup.part.0
0000000000051540 t state_machine.part.0
0000000000067f50 t tls12_sigalg_allowed.part.0
0000000000066570 t tls1_check_pkey_comp.part.0
0000000000066aa0 t tls1_check_sig_alg.part.0

Systemtap is getting the test abour line tapsets.cxx:2288 wrong.

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

[Bug translator/27984] stap skipping partially-inlined instance, but it is not inline function actually

[lijunlong at openresty dot com]

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

lijunlong <lijunlong at openresty dot com> changed:

           What    |Removed                     |Added
----------------------------------------------------------------------------
                 CC|                            |lijunlong at openresty dot com

--- Comment #3 from lijunlong <lijunlong at openresty dot com> ---
value of DW_AT_producer from the debuginfo shows that it was build with "GNU
C17 9.3.0 -m64 -mtune=generic -march=x86-64 -g -O3 -fPIC"

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

[Bug translator/27984] stap skipping partially-inlined instance, but it is not inline function actually

[lijunlong at openresty dot com]

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

--- Comment #4 from lijunlong <lijunlong at openresty dot com> ---
openssl version:

https://www.openssl.org/source/old/1.1.1/openssl-1.1.1g.tar.gz

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

[Bug translator/27984] stap skipping partially-inlined instance, but it is not inline function actually

[wcohen at redhat dot com]

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

--- Comment #5 from William Cohen <wcohen at redhat dot com> ---
There is something odd happening in the mapping of the address back to a name. 
The address 0x61b70 appears to be the correct address for
tls_process_client_hello according to nm, but the search is mapping it to
instance state_machine.part.0, 0000000000051540.  Systemtap keys off the
".part." in the name to determine that it is an inlined function.  Due to the
name mix up in this case systemtap incorrectly determines 0x61b70 is a
partially-inlined function.

Have been using rr (rr-project.org) to work backwards and determine why
dwfl_module_addrinfo is returning the wrong symbol name. The actual selection
of "state_machine.part.0" is occurs in the last line of 
__libdwfl_getsym@dwarf_module_getsym.c:197.

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

[Bug translator/27984] stap skipping partially-inlined instance, but it is not inline function actually

[wcohen at redhat dot com]

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

--- Comment #6 from William Cohen <wcohen at redhat dot com> ---
The dwf_module_addrinfo lookup is not working. Any partially-inlined functions
in the code might cause random exclusions of valid functions as observed. Added
the following diagnostic print to see what  dwfl_module_addrinfo() was
returning for each of the tests to verify it matched up with the expected
function name:

diff --git a/tapsets.cxx b/tapsets.cxx
index 20e0cb68f..9d4fd7389 100644
--- a/tapsets.cxx
+++ b/tapsets.cxx
@@ -2283,6 +2283,9 @@ query_dwarf_func (Dwarf_Die * func, dwarf_query * q)
               const char *name = dwfl_module_addrinfo (q->dw.module, entrypc,
                                                        &off, &sym, NULL, NULL,
NULL);

+             if (q->sess.verbose>2)
+                     clog << _F("%s = dwfl_module_addrinfo(%p)\n",
+                                name, (void*)entrypc);
               if (name != NULL && strstr(name, ".part.") != NULL)
                 {
                   if (q->sess.verbose>2)

Then ran to see what were the results for the program having the issues:

~/research/profiling/systemtap_write/install/stap
--sysroot=/tmp/stap-job1/sysroot -vvv -L 
'process("/usr/local/openresty/openssl/lib/libssl.so.1.1").function("*").call'
>& detailed_funct_entry.log 

Lots of places didn't find an entry at all:

selected function BIO_new_ssl
(null) = dwfl_module_addrinfo(0x1f760)
selected function BIO_new_ssl_connect
(null) = dwfl_module_addrinfo(0x1f7e0)
selected function ssl_puts
(null) = dwfl_module_addrinfo(0x1ed10)
selected function ssl_new
(null) = dwfl_module_addrinfo(0x1ed40)

Other places different name return than expected:

selected function ssl3_handshake_write
_init = dwfl_module_addrinfo(0x2d000)

selected function ssl3_ctrl
ssl_new = dwfl_module_addrinfo(0x2ed90)

selected function ssl3_send_alert
dtls1_start_timer = dwfl_module_addrinfo(0x2fe00)
selected function ssl3_do_change_cipher_spec
dtls1_clear = dwfl_module_addrinfo(0x2fd50)
selected function ssl3_dispatch_alert
dtls1_get_timeout = dwfl_module_addrinfo(0x2ff00)

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

[Bug translator/27984] stap skipping partially-inlined instance, but it is not inline function actually

[wcohen at redhat dot com]

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

--- Comment #7 from William Cohen <wcohen at redhat dot com> ---
There is a test of the partial-inline checks in systemtap.  Ran it with on
systemtap with the additional diagnostic prints:

sudo make installcheck  RUNTESTFLAGS="--debug
systemtap.base/partial-inline.exp"

The test passes.  Looking at probing the executable partial-inline.exp with:

~/research/profiling/systemtap_write/install/bin//stap  -vvv -L 
'process("./partial-inline.exe").function("*").call' >&
more_detailed_partial-inline.log

can see that the expected names are found:

selected function foo
foo.part.0 = dwfl_module_addrinfo(0x401170)
skipping partially-inlined instance foo.part.0 at 0x401170
selected function main
main = dwfl_module_addrinfo(0x401050)

Extracted from nm:

0000000000401050 T main
0000000000401170 t foo.part.0

Suspect the problem in this PR is due to the code being probed in a library.

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

[Bug translator/27984] stap skipping partially-inlined instance, but it is not inline function actually

[wcohen at redhat dot com]

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

--- Comment #8 from William Cohen <wcohen at redhat dot com> ---
To better check what was going on I added the following patch to see what
offsets were being used and found that the libssl.so.1.1 library had a bias of
0x10000 for the addresses:

diff --git a/tapsets.cxx b/tapsets.cxx
index 20e0cb68f..251e2a4b6 100644
--- a/tapsets.cxx
+++ b/tapsets.cxx
@@ -2280,9 +2280,14 @@ query_dwarf_func (Dwarf_Die * func, dwarf_query * q)
               // up the ELF symbol name and rely on a heuristic.
               GElf_Sym sym;
               GElf_Off off = 0;
-              const char *name = dwfl_module_addrinfo (q->dw.module, entrypc,
+             Dwarf_Addr bias = 0x10000;
+
+             const char *name = dwfl_module_addrinfo (q->dw.module, entrypc +
bias,
                                                        &off, &sym, NULL, NULL,
NULL);

+             if (q->sess.verbose>2)
+                     clog << _F("%s = dwfl_module_addrinfo(entrypc=%p,
off=%p)\n",
+                                name, (void*)entrypc, (void*) off);
               if (name != NULL && strstr(name, ".part.") != NULL)
                 {
                   if (q->sess.verbose>2)



With this patch see that the code is finding the correct function names for the
library functions:

focused on module
'/tmp/stap-job1/sysroot/usr/local/openresty/openssl/lib/libssl.so.1.1'
selected function BIO_new_ssl
BIO_new_ssl = dwfl_module_addrinfo(entrypc=0x1f760, off=(nil))
selected function BIO_new_ssl_connect
BIO_new_ssl_connect = dwfl_module_addrinfo(entrypc=0x1f7e0, off=(nil))
selected function ssl_puts
ssl_puts = dwfl_module_addrinfo(entrypc=0x1ed10, off=(nil))
selected function ssl_new
ssl_new = dwfl_module_addrinfo(entrypc=0x1ed40, off=(nil))
selected function BIO_ssl_shutdown
BIO_ssl_shutdown = dwfl_module_addrinfo(entrypc=0x1f960, off=(nil))
selected function ssl_callback_ctrl
ssl_callback_ctrl = dwfl_module_addrinfo(entrypc=0x1ecd0, off=(nil))

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

[Bug translator/27984] stap skipping partially-inlined instance, but it is not inline function actually

[wcohen at redhat dot com]

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

--- Comment #9 from William Cohen <wcohen at redhat dot com> ---
Frank suggested dw.mod_info->bias as a possible place to get the information
about the bias.  However, the value doesn't appear to be set to the correct
value. It was 0.  Ironically, if one manually adds the expected bias (0x10000)
needed for the reproducer and provide a variable to store the returned bias in
the last arg of dwfl_module_addrinfo() like the patche below, the function
returns the expected bias:

diff --git a/tapsets.cxx b/tapsets.cxx
index 20e0cb68f..4f8d31c5f 100644
--- a/tapsets.cxx
+++ b/tapsets.cxx
@@ -2280,9 +2280,17 @@ query_dwarf_func (Dwarf_Die * func, dwarf_query * q)
               // up the ELF symbol name and rely on a heuristic.
               GElf_Sym sym;
               GElf_Off off = 0;
-              const char *name = dwfl_module_addrinfo (q->dw.module, entrypc,
-                                                       &off, &sym, NULL, NULL,
NULL);
+             // The following seems to be 0
+             // Dwarf_Addr bias = q->dw.mod_info->bias;
+             Dwarf_Addr bias = 0x10000;
+             Dwarf_Addr ret_bias = 0;

+             const char *name = dwfl_module_addrinfo (q->dw.module, entrypc +
bias,
+                                                       &off, &sym, NULL, NULL,
&ret_bias);
+
+             if (q->sess.verbose>2)
+                     clog << _F("%s = dwfl_module_addrinfo(entrypc=%p + %p,
off=%p, ret_bias=%p)\n",
+                                name, (void*)entrypc, (void *)bias, (void*)
off, (void*) ret_bias);
               if (name != NULL && strstr(name, ".part.") != NULL)
                 {
                   if (q->sess.verbose>2)

selected function BIO_new_ssl
BIO_new_ssl = dwfl_module_addrinfo(entrypc=0x1f760 + 0x10000, off=(nil),
ret_bias=0x10000)
selected function BIO_new_ssl_connect
BIO_new_ssl_connect = dwfl_module_addrinfo(entrypc=0x1f7e0 + 0x10000,
off=(nil), ret_bias=0x10000)
selected function ssl_puts
ssl_puts = dwfl_module_addrinfo(entrypc=0x1ed10 + 0x10000, off=(nil),
ret_bias=0x10000)

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

[Bug translator/27984] stap skipping partially-inlined instance, but it is not inline function actually

[mark at klomp dot org]

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

Mark Wielaard <mark at klomp dot org> changed:

           What    |Removed                     |Added
----------------------------------------------------------------------------
                 CC|                            |mark at klomp dot org

--- Comment #10 from Mark Wielaard <mark at klomp dot org> ---
Note that since the main executable code addresses, the debuginfo addresses and
symbols might come from different files they could have different biases.

/* Return the name of the module, and for each non-null argument store
   interesting details: *USERDATA is a location for storing your own
   pointer, **USERDATA is initially null; *START and *END give the address
   range covered by the module; *DWBIAS is the address bias for debugging
   information, and *SYMBIAS for symbol table entries (either is -1 if not
   yet accessed); *MAINFILE is the name of the ELF file, and *DEBUGFILE the
   name of the debuginfo file (might be equal to *MAINFILE; either is null
   if not yet accessed).  */
extern const char *dwfl_module_info (Dwfl_Module *mod, void ***userdata,
                                     Dwarf_Addr *start, Dwarf_Addr *end,
                                     Dwarf_Addr *dwbias, Dwarf_Addr *symbias,
                                     const char **mainfile,
                                     const char **debugfile);

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

[Bug translator/27984] stap skipping partially-inlined instance, but it is not inline function actually

[lijunlong at openresty dot com]

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

--- Comment #11 from lijunlong <lijunlong at openresty dot com> ---
so can we get the bias from dwfl_module_getelf (q->dw.module, &bias)?

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

[Bug translator/27984] stap skipping partially-inlined instance, but it is not inline function actually

[wcohen at redhat dot com]

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

William Cohen <wcohen at redhat dot com> changed:

           What    |Removed                     |Added
----------------------------------------------------------------------------
           Assignee|systemtap at sourceware dot org    |wcohen at redhat dot com

--- Comment #12 from William Cohen <wcohen at redhat dot com> ---
Created attachment 13560
  --> https://sourceware.org/bugzilla/attachment.cgi?id=13560&action=edit
Proposed patch to address PR27984

The suggestion in the previous comment has been adapted into a patch to address
the problem.  Could you give that a try and verify that it addresses the issue?

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