Tracing USDTs in executables compiled with -pie

[zilder]

Hi,

I have a problems tracing tracepoints in postgres built with -pie flag. This is how postgres is configured:

./configure --enable-dtrace --enable-cassert --enable-debug CFLAGS='-ggdb -g3 -O0 -pie' --prefix=$HOME/pg10

I can see tracepoints embedded using readelf. Let's say I want to trace transaction start event.

readelf -n ~/pg10/bin/postgres
...
  stapsdt              0x0000003d	NT_STAPSDT (SystemTap probe descriptors)
    Provider: postgresql
    Name: transaction__start
    Location: 0x000000000017e272, Base: 0x00000000008d3911, Semaphore: 0x0000000000998f68
    Arguments: 4@%eax
...

There is a simple script I use to trace event:

#!/usr/bin/env python

from bcc import BPF, USDT
import sys

if len(sys.argv) < 2:
    print("USAGE: {0} PID".format(sys.argv[0]))
    exit()
pid = sys.argv[1]

prog = """
#include <uapi/linux/ptrace.h>
int do_trace(struct pt_regs *ctx) {
    bpf_trace_printk("Hello, transaction__start\\n");
    return 0;
};
"""

u = USDT(pid=int(pid))
u.enable_probe(probe="transaction__start", fn_name="do_trace")

for p in u.enumerate_probes():
    print('{}\t0x{:02x}'.format(p.name, p.semaphore))
print("Active probes: ", u.enumerate_active_probes())

b = BPF(text=prog, usdt_contexts=[u])
b.trace_print()

When I run script I get this (output was truncated):

sudo ./pg.py 32737
...
b'transaction__start'	0x998f68
b'transaction__commit'	0x998f6a
b'transaction__abort'	0x998f6c
...
Active probes:  []

32737 here is the PID of postgres backend that handles connection from psql in a separate terminal. So bcc can see those probes in executable, but none of transactions were actually traced. And note that enumerate_active_probes() doesn't return any probes.
I inspected bcc with gdb and found two things in enable_probe call.

1. in_shared_object() returns true even though it is an executable binary file. readelf shows the same thing:

readelf -h ~/pg10/bin/postgres
ELF Header:
  Magic:   7f 45 4c 46 02 01 01 00 00 00 00 00 00 00 00 00 
  Class:                             ELF64
  Data:                              2's complement, little endian
  Version:                           1 (current)
  OS/ABI:                            UNIX - System V
  ABI Version:                       0
  Type:                              DYN (Shared object file)
...

Apparently, compiling executable with -pie makes it shared object. I'm not sure how to calculate actual address of semaphore in position independent executable (I would appreciate if you could share some good article about it). That leads to...

2. We get address of semaphore from bcc_resolve_global_address() and then try to read it from the running process in add_to_semaphore() and get EIO error here:

::read(memfd, &original, 2) != 2) {

It seems that bcc_resolve_global_address() returns incorrect address. (Btw, maybe it makes sense to print some kind of warning if we failed to increment semaphore).

On the other hand if executable was built with -no-pie that it works fine:

sudo ./pg.py 9748
Active probes:  [(b'/home/zilder/pg10/bin/postgres', b'do_trace', 5534303, 9748)]
b'        postgres-9748  [000] ...2 12738.623855: 0: Hello, transaction__start'
b'        postgres-9748  [002] ...2 12739.983981: 0: Hello, transaction__start'
b'        postgres-9748  [002] ...2 12740.719722: 0: Hello, transaction__start'

And it also has EXEC type:

readelf -h ~/pg10/bin/postgres
ELF Header:
  Magic:   7f 45 4c 46 02 01 01 00 00 00 00 00 00 00 00 00 
  Class:                             ELF64
  Data:                              2's complement, little endian
  Version:                           1 (current)
  OS/ABI:                            UNIX - System V
  ABI Version:                       0
  Type:                              EXEC (Executable file)
...

I'm not sure if this is a bug of bcc or I just miss something and do something wrong. If you need more information from me I'd be happy to assist.

[palmtenor]

@zilder : Good debugging! Here are some ideas:

• It is the correct behavior for in_shared_object() to return true as long as the ELF is of type ET_DYN. It basically tells us to use the addresses read from the note directly, or use it with load offsets. In your case even though it's an "executable", we still need to add the load offset to the addresses
• You mentioned bcc_resolve_global_address() returns "incorrect address", can you elaborate a bit more? What did it return and what you think the return value should be? Also, it would be useful if you can post the content of the /proc/PID/maps of the Process for debugging.

[zilder]

@palmtenor
Thanks for the answer. By “incorrect address” I meant address that points to not readable memory (at least not from bcc) because read returns -1 and errno==EIO. Unfortunately I have no idea hot to calculate semaphore address for PIE. I’ll send you info you requested as soon as I get to the office where I left my linux laptop, hopefully tomorrow.

[palmtenor]

Cool, other than /proc/PID/maps of your Process, can you also include result of readelf -WS YOUR_BINARY, and ideally input and output of bcc_resolve_global_address()? Thanks!

[zilder]

Ok, values within bcc_resolve_global_address():

bcc_resolve_global_addr (pid=10802, module=0x558231e97e30 "/home/zilder/pg10/bin/postgres", address=10063720, 
    global=0x7ffea83ff740) at /home/zilder/projects/bcc/src/cc/bcc_syms.cc:441
...
(gdb) p/x mod.start
$3 = 0x5631b4dca000
(gdb) p/x mod.file_offset
$4 = 0xa9000
(gdb) p/x address
$5 = 0x998f68

Result of *global = mod.start + mod.file_offset + address:

(gdb) p/x *global
$6 = 0x5631b580bf68

Contents of /proc/10802/maps:

5631b4d21000-5631b4dca000 r--p 00000000 103:03 49684366                  /home/zilder/pg10/bin/postgres
5631b4dca000-5631b53fe000 r-xp 000a9000 103:03 49684366                  /home/zilder/pg10/bin/postgres
5631b53fe000-5631b568b000 r--p 006dd000 103:03 49684366                  /home/zilder/pg10/bin/postgres
5631b568c000-5631b56ad000 r--p 0096a000 103:03 49684366                  /home/zilder/pg10/bin/postgres
5631b56ad000-5631b56ba000 rw-p 0098b000 103:03 49684366                  /home/zilder/pg10/bin/postgres
5631b56ba000-5631b572f000 rw-p 00000000 00:00 0 
5631b6a02000-5631b6a4c000 rw-p 00000000 00:00 0                          [heap]
5631b6a4c000-5631b6ad4000 rw-p 00000000 00:00 0                          [heap]
7faaf549c000-7faaf54fe000 rw-p 00000000 00:00 0 
7faaf54fe000-7faafe2a0000 rw-s 00000000 00:05 134295                     /dev/zero (deleted)
7faafe2a0000-7faafe2a2000 r--p 00000000 103:02 1997594                   /usr/lib/libnss_myhostname.so.2
7faafe2a2000-7faafe2ab000 r-xp 00002000 103:02 1997594                   /usr/lib/libnss_myhostname.so.2
7faafe2ab000-7faafe2b0000 r--p 0000b000 103:02 1997594                   /usr/lib/libnss_myhostname.so.2
7faafe2b0000-7faafe2b3000 r--p 0000f000 103:02 1997594                   /usr/lib/libnss_myhostname.so.2
7faafe2b3000-7faafe2b4000 rw-p 00012000 103:02 1997594                   /usr/lib/libnss_myhostname.so.2
7faafe2b4000-7faafe2ba000 r--p 00000000 103:02 1997595                   /usr/lib/libnss_mymachines.so.2
7faafe2ba000-7faafe2e5000 r-xp 00006000 103:02 1997595                   /usr/lib/libnss_mymachines.so.2
7faafe2e5000-7faafe2f4000 r--p 00031000 103:02 1997595                   /usr/lib/libnss_mymachines.so.2
7faafe2f4000-7faafe2f7000 r--p 0003f000 103:02 1997595                   /usr/lib/libnss_mymachines.so.2
7faafe2f7000-7faafe2f8000 rw-p 00042000 103:02 1997595                   /usr/lib/libnss_mymachines.so.2
7faafe2f8000-7faafe2f9000 rw-p 00000000 00:00 0 
7faafe2f9000-7faafe2fc000 r--p 00000000 103:02 1969054                   /usr/lib/libnss_files-2.28.so
7faafe2fc000-7faafe303000 r-xp 00003000 103:02 1969054                   /usr/lib/libnss_files-2.28.so
7faafe303000-7faafe306000 r--p 0000a000 103:02 1969054                   /usr/lib/libnss_files-2.28.so
7faafe306000-7faafe307000 r--p 0000c000 103:02 1969054                   /usr/lib/libnss_files-2.28.so
7faafe307000-7faafe308000 rw-p 0000d000 103:02 1969054                   /usr/lib/libnss_files-2.28.so
7faafe308000-7faafe30e000 rw-p 00000000 00:00 0 
7faafe30e000-7faafe5f4000 r--p 00000000 103:02 2004296                   /usr/lib/locale/locale-archive
7faafe5f4000-7faafe5f6000 rw-p 00000000 00:00 0 
7faafe5f6000-7faafe618000 r--p 00000000 103:02 1969017                   /usr/lib/libc-2.28.so
7faafe618000-7faafe763000 r-xp 00022000 103:02 1969017                   /usr/lib/libc-2.28.so
7faafe763000-7faafe7af000 r--p 0016d000 103:02 1969017                   /usr/lib/libc-2.28.so
7faafe7af000-7faafe7b0000 ---p 001b9000 103:02 1969017                   /usr/lib/libc-2.28.so
7faafe7b0000-7faafe7b4000 r--p 001b9000 103:02 1969017                   /usr/lib/libc-2.28.so
7faafe7b4000-7faafe7b6000 rw-p 001bd000 103:02 1969017                   /usr/lib/libc-2.28.so
7faafe7b6000-7faafe7ba000 rw-p 00000000 00:00 0 
7faafe7ba000-7faafe7c7000 r--p 00000000 103:02 1969032                   /usr/lib/libm-2.28.so
7faafe7c7000-7faafe868000 r-xp 0000d000 103:02 1969032                   /usr/lib/libm-2.28.so
7faafe868000-7faafe93d000 r--p 000ae000 103:02 1969032                   /usr/lib/libm-2.28.so
7faafe93d000-7faafe93e000 r--p 00182000 103:02 1969032                   /usr/lib/libm-2.28.so
7faafe93e000-7faafe93f000 rw-p 00183000 103:02 1969032                   /usr/lib/libm-2.28.so
7faafe93f000-7faafe940000 r--p 00000000 103:02 1969026                   /usr/lib/libdl-2.28.so
7faafe940000-7faafe941000 r-xp 00001000 103:02 1969026                   /usr/lib/libdl-2.28.so
7faafe941000-7faafe942000 r--p 00002000 103:02 1969026                   /usr/lib/libdl-2.28.so
7faafe942000-7faafe943000 r--p 00002000 103:02 1969026                   /usr/lib/libdl-2.28.so
7faafe943000-7faafe944000 rw-p 00003000 103:02 1969026                   /usr/lib/libdl-2.28.so
7faafe944000-7faafe946000 r--p 00000000 103:02 1969071                   /usr/lib/librt-2.28.so
7faafe946000-7faafe94a000 r-xp 00002000 103:02 1969071                   /usr/lib/librt-2.28.so
7faafe94a000-7faafe94c000 r--p 00006000 103:02 1969071                   /usr/lib/librt-2.28.so
7faafe94c000-7faafe94d000 r--p 00007000 103:02 1969071                   /usr/lib/librt-2.28.so
7faafe94d000-7faafe94e000 rw-p 00008000 103:02 1969071                   /usr/lib/librt-2.28.so
7faafe94e000-7faafe954000 r--p 00000000 103:02 1969063                   /usr/lib/libpthread-2.28.so
7faafe954000-7faafe963000 r-xp 00006000 103:02 1969063                   /usr/lib/libpthread-2.28.so
7faafe963000-7faafe969000 r--p 00015000 103:02 1969063                   /usr/lib/libpthread-2.28.so
7faafe969000-7faafe96a000 r--p 0001a000 103:02 1969063                   /usr/lib/libpthread-2.28.so
7faafe96a000-7faafe96b000 rw-p 0001b000 103:02 1969063                   /usr/lib/libpthread-2.28.so
7faafe96b000-7faafe971000 rw-p 00000000 00:00 0 
7faafe985000-7faafe987000 rw-s 00000000 00:17 134297                     /dev/shm/PostgreSQL.781622498
7faafe987000-7faafe988000 rw-s 00000000 00:05 1114116                    /SYSV0052e2c1 (deleted)
7faafe988000-7faafe98a000 r--p 00000000 103:02 1969006                   /usr/lib/ld-2.28.so
7faafe98a000-7faafe9a9000 r-xp 00002000 103:02 1969006                   /usr/lib/ld-2.28.so
7faafe9a9000-7faafe9b1000 r--p 00021000 103:02 1969006                   /usr/lib/ld-2.28.so
7faafe9b1000-7faafe9b2000 r--p 00028000 103:02 1969006                   /usr/lib/ld-2.28.so
7faafe9b2000-7faafe9b3000 rw-p 00029000 103:02 1969006                   /usr/lib/ld-2.28.so
7faafe9b3000-7faafe9b4000 rw-p 00000000 00:00 0 
7ffc5fb97000-7ffc5fbb8000 rw-p 00000000 00:00 0                          [stack]
7ffc5fbe9000-7ffc5fbec000 r--p 00000000 00:00 0                          [vvar]
7ffc5fbec000-7ffc5fbee000 r-xp 00000000 00:00 0                          [vdso]

Results of readelf:

readelf -WS ~/pg10/bin/postgres
There are 41 section headers, starting at offset 0x1e0b120:

Section Headers:
  [Nr] Name              Type            Address          Off    Size   ES Flg Lk Inf Al
  [ 0]                   NULL            0000000000000000 000000 000000 00      0   0  0
  [ 1] .interp           PROGBITS        00000000000002a8 0002a8 00001c 00   A  0   0  1
  [ 2] .note.ABI-tag     NOTE            00000000000002c4 0002c4 000020 00   A  0   0  4
  [ 3] .note.gnu.build-id NOTE            00000000000002e4 0002e4 000024 00   A  0   0  4
  [ 4] .gnu.hash         GNU_HASH        0000000000000308 000308 01251c 00   A  5   0  8
  [ 5] .dynsym           DYNSYM          0000000000012828 012828 033390 18   A  6   1  8
  [ 6] .dynstr           STRTAB          0000000000045bb8 045bb8 025d33 00   A  0   0  1
  [ 7] .gnu.version      VERSYM          000000000006b8ec 06b8ec 00444c 02   A  5   0  2
  [ 8] .gnu.version_r    VERNEED         000000000006fd38 06fd38 000110 00   A  6   5  8
  [ 9] .rela.dyn         RELA            000000000006fe48 06fe48 037860 18   A  5   0  8
  [10] .rela.plt         RELA            00000000000a76a8 0a76a8 0015f0 18  AI  5  25  8
  [11] .init             PROGBITS        00000000000a9000 0a9000 00001b 00  AX  0   0  4
  [12] .plt              PROGBITS        00000000000a9020 0a9020 000eb0 10  AX  0   0 16
  [13] .plt.got          PROGBITS        00000000000a9ed0 0a9ed0 000010 08  AX  0   0  8
  [14] .text             PROGBITS        00000000000a9ee0 0a9ee0 632865 00  AX  0   0 16
  [15] .fini             PROGBITS        00000000006dc748 6dc748 00000d 00  AX  0   0  4
  [16] .rodata           PROGBITS        00000000006dd000 6dd000 1f6911 00   A  0   0 32
  [17] .stapsdt.base     PROGBITS        00000000008d3911 8d3911 000001 00   A  0   0  1
  [18] .eh_frame_hdr     PROGBITS        00000000008d3914 8d3914 01d76c 00   A  0   0  4
  [19] .eh_frame         PROGBITS        00000000008f1080 8f1080 078ad0 00   A  0   0  8
  [20] .init_array       INIT_ARRAY      000000000096b2d0 96a2d0 000008 08  WA  0   0  8
  [21] .fini_array       FINI_ARRAY      000000000096b2d8 96a2d8 000008 08  WA  0   0  8
  [22] .data.rel.ro      PROGBITS        000000000096b2e0 96a2e0 020a80 00  WA  0   0 32
  [23] .dynamic          DYNAMIC         000000000098bd60 98ad60 000230 10  WA  6   0  8
  [24] .got              PROGBITS        000000000098bf90 98af90 000058 08  WA  0   0  8
  [25] .got.plt          PROGBITS        000000000098c000 98b000 000768 08  WA  0   0  8
  [26] .data             PROGBITS        000000000098c780 98b780 00c7e8 00  WA  0   0 32
  [27] .probes           PROGBITS        0000000000998f68 997f68 000072 00  WA  0   0  2
  [28] .bss              NOBITS          0000000000998fe0 997fda 0746f0 00  WA  0   0 32
  [29] .comment          PROGBITS        0000000000000000 997fda 00002b 01  MS  0   0  1
  [30] .note.stapsdt     NOTE            0000000000000000 998008 001d28 00      0   0  4
  [31] .debug_aranges    PROGBITS        0000000000000000 999d30 007e40 00      0   0  1
  [32] .debug_info       PROGBITS        0000000000000000 9a1b70 c25419 00      0   0  1
  [33] .debug_abbrev     PROGBITS        0000000000000000 15c6f89 09052d 00      0   0  1
  [34] .debug_line       PROGBITS        0000000000000000 16574b6 3fb0f1 00      0   0  1
  [35] .debug_str        PROGBITS        0000000000000000 1a525a7 110178 01  MS  0   0  1
  [36] .debug_ranges     PROGBITS        0000000000000000 1b6271f 007ad0 00      0   0  1
  [37] .debug_macro      PROGBITS        0000000000000000 1b6a1ef 1c9b65 00      0   0  1
  [38] .symtab           SYMTAB          0000000000000000 1d33d58 0804d8 18     39 13157  8
  [39] .strtab           STRTAB          0000000000000000 1db4230 056d58 00      0   0  1
  [40] .shstrtab         STRTAB          0000000000000000 1e0af88 000193 00      0   0  1
Key to Flags:
  W (write), A (alloc), X (execute), M (merge), S (strings), I (info),
  L (link order), O (extra OS processing required), G (group), T (TLS),
  C (compressed), x (unknown), o (OS specific), E (exclude),
  l (large), p (processor specific)

[palmtenor]

OK, looks like we used the first loaded section of the file, where what we should actually be doing is to find the section that the offset is actually in. I can try fix that.

Meanwhile should it be address - mod.file_offset + mod.start? @goldshtn did I make a silly mistake in #1364? I confused myself...

[brendangregg]

FWIW, we hit this in bpftrace as well: bpftrace/bpftrace#75

[palmtenor]

@zilder , can you try if following patch works?

diff --git a/src/cc/bcc_syms.cc b/src/cc/bcc_syms.cc
index a52e3f4..c933380 100644
--- a/src/cc/bcc_syms.cc
+++ b/src/cc/bcc_syms.cc
@@ -422,16 +422,18 @@ void bcc_symcache_refresh(void *resolver) {

 struct mod_st {
   const char *name;
-  uint64_t start;
-  uint64_t file_offset;
+  uint64_t file_addr;
+  uint64_t global_addr;
 };

 static int _find_module(const char *modname, uint64_t start, uint64_t end,
                         uint64_t offset, bool, void *p) {
   struct mod_st *mod = (struct mod_st *)p;
-  if (!strcmp(modname, mod->name)) {
-    mod->start = start;
-    mod->file_offset = offset;
+  uint64_t mod_size = (end - start);
+  if (!strcmp(modname, mod->name) &&
+      mod->file_addr >= offset &&
+      mod->file_addr < offset + mod_size) {
+    mod->global_addr = mod->file_addr - offset + start;
     return -1;
   }
   return 0;
@@ -439,12 +441,12 @@ static int _find_module(const char *modname, uint64_t start, uint64_t end,

 int bcc_resolve_global_addr(int pid, const char *module, const uint64_t address,
                             uint64_t *global) {
-  struct mod_st mod = {module, 0x0};
+  struct mod_st mod = {module, address, 0x0};
   if (bcc_procutils_each_module(pid, _find_module, &mod) < 0 ||
-      mod.start == 0x0)
+      mod.global_addr == 0x0)
     return -1;

-  *global = mod.start + mod.file_offset + address;
+  *global = mod.global_addr;
   return 0;
 }

[myllynen]

FWIW, we're seeing something perhaps related on Fedora 29, there the patch proposal didn't solve that issue. See https://bugzilla.redhat.com/show_bug.cgi?id=1634684. Thanks.

[zilder]

@palmtenor, patch applied but doesn't work. The condition in _find_module fails:

Breakpoint 1, _find_module (modname=0x7fffadb975b2 "/home/zilder/pg10/bin/postgres", 
    start=94773641064448, end=94773647568896, offset=692224, p=0x7fffadb985e0)
    at /home/zilder/projects/bcc/src/cc/bcc_syms.cc:431
431	  struct mod_st *mod = (struct mod_st *)p;
(gdb) n
432	  uint64_t mod_size = (end - start);
(gdb) 
433	  if (!strcmp(modname, mod->name) &&
(gdb) 
434	      mod->file_addr >= offset &&
(gdb) 
433	  if (!strcmp(modname, mod->name) &&
(gdb) 
435	      mod->file_addr < offset + mod_size) {
(gdb) 
434	      mod->file_addr >= offset &&
(gdb) p/x mod->file_addr
$1 = 0x998f68
(gdb) p/x offset
$2 = 0xa9000
(gdb) p/x mod_size
$3 = 0x634000
(gdb) n
439	  return 0;

[palmtenor]

I kind of understand the issue with Python, but not quite with the one @zilder provided since it doesn't have a load offset that would make current calculation incorrect. Regardlessly I'll try to put up a patch to fix some known issue including missing out non-executable sections and load offset, and we can see if that fixes the issue or there are more things to be discovered.

[zilder]

@palmtenor,
I think I see the problem. bcc_procutils_each_module retrieves address of the first executable section of binary and its offset from the base address. In my case:

~ vim /proc/21637/maps
555c54d44000-555c54df3000 r--p 00000000 103:03 49418776                  /home/zilder/pg11/bin/postgres
555c54df3000-555c55479000 r-xp 000af000 103:03 49418776                  /home/zilder/pg11/bin/postgres
555c55479000-555c55729000 r--p 00735000 103:03 49418776                  /home/zilder/pg11/bin/postgres
...

it is 0x555c54df3000 and 0xaf000 respectively. But the address of semaphore in bcc is calculated as:

*global = mod.start + mod.file_offset + address;

while it actually should be calculated as:

*global = mod.start - mod.file_offset + address;

There is a patch:

diff --git a/src/cc/bcc_syms.cc b/src/cc/bcc_syms.cc
index a52e3f4..be9781a 100644
--- a/src/cc/bcc_syms.cc
+++ b/src/cc/bcc_syms.cc
@@ -444,7 +444,7 @@ int bcc_resolve_global_addr(int pid, const char *module, const uint64_t address,
       mod.start == 0x0)
     return -1;
 
-  *global = mod.start + mod.file_offset + address;
+  *global = mod.start - mod.file_offset + address;
   return 0;
 }

It solved the problem for me. But I haven't yet tested it with shared libraries.

@brendangregg, @myllynen,
Can you please try this patch with your cases?

If it works, I'll create a pull request. Thanks!

[myllynen]

I'm happy to confirm this fixes the issue on Fedora 29! Thanks a lot!

[yonghong-song]

Thanks @zilder could you send a pull request? Looks like the change is good?

[zilder]

@myllynen, thanks for testing!

@yonghong-song, done.