scripts/seastar-addr2line hangs on I/O

[vladzcloudius]

HEAD: ff24926fe4374995abcfb606ef880e146eb40647 OS: Ubuntu 24.04 binutils version: 2.42-4ubuntu2.3 LLVM version: 18.0-59~exp2 Python version: 3.12.3-0ubuntu2

Description

The most trivial invocation of seastar-addr2line hangs on I/O (using addr2line from binutils gives the same result):

$ echo "0x0000000002eebcb2" | strace /opt/scylladb/seastar/scripts/seastar-addr2line -b 3 -e /var/lib/binaries/2021.1.20-0.20230604.0f9b75eaf1.amd64/deb-relocatable/scylla.debug --addr2line llvm-addr2line
write(4, "0x0000000002eebcb2\n0x0\n", 23) = 23
read(5, "0x2eebcb2: void seastar::backtra"..., 8192) = 257
read(5, "0x0: auto seastar::internal::do_"..., 8192) = 281
read(5, 
<here the program hangs forever>

Interrupting it prints the following:

main()
  File "/opt/scylladb/seastar/scripts/seastar-addr2line", line 503, in main
    with BacktraceResolver(
  File "/opt/scylladb/seastar/scripts/addr2line.py", line 387, in __exit__
    self._print_current_backtrace()
  File "/opt/scylladb/seastar/scripts/addr2line.py", line 452, in _print_current_backtrace
    self._print_resolved_address(module, addr)
  File "/opt/scylladb/seastar/scripts/addr2line.py", line 403, in _print_resolved_address
    sys.stdout.write(self.resolve_address(address, module))
                     ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/opt/scylladb/seastar/scripts/addr2line.py", line 397, in resolve_address
    resolved_address = self._get_resolver_for_module(module)(address)
                       ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/opt/scylladb/seastar/scripts/addr2line.py", line 140, in __call__
    return self._read_resolved_address()
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/opt/scylladb/seastar/scripts/addr2line.py", line 123, in _read_resolved_address
    line = self._output.readline()
           ^^^^^^^^^^^^^^^^^^^^^^^
KeyboardInterrupt

At the same time using llvm-addr2line directly works just fine:

$ llvm-addr2line -e /var/lib/binaries/2021.1.20-0.20230604.0f9b75eaf1.amd64/deb-relocatable/scylla.debug 0x0000000002eebcb2
./build/release/seastar/./seastar/include/seastar/util/backtrace.hh:59

[vladzcloudius]

A quick review of the code of addr2line.py explains the issue. The corresponding code ignores the explicit warning from the Python doc pages:

While the code in question has multiple calls like these: https://github.com/scylladb/seastar/blob/master/scripts/addr2line.py#L102

[bhalevy]

The problem is only with llvm-addr2line, right? The command you quoted works for me with /usr/bin/addr2line

$ addr2line --version
GNU addr2line version 2.41-38.fc40

[vladzcloudius]

The problem is only with llvm-addr2line, right? The command you quoted works for me with /usr/bin/addr2line

$ addr2line --version
GNU addr2line version 2.41-38.fc40

No, the problem reproduces with both addr2line and with llvm-addr2line. As I mentioned above, the issue is not with the application you invoke from Python but rather with the way you treat its stdin and stdout pipes of the corresponding subprocess.Popen object.

[michoecho]

The problem isn't with the pipes.

Starting addr2line is expensive (it needs to do some parsing on the queried executable on startup), so it's a common technique (used also e.g. by perf) to start addr2line once and use it like a server — send an address via an input pipe, read the output via the output pipe, repeat many times.

But addr2line can print multiple output lines per each input line (because of function inlining). So if you want to use addr2line in "server" mode, you need some way to determine the end of output for the currently-decoded address, to know when to stop reading from the pipe. And the trick here is to send some garbage that will result in one, unique output line.

So after sending an address line for decoding, seastar-addr2line follows it with 0x0\n and expects addr2line to emit the decoding results and follow them with 0x0: ?? at ??.

But in this case, unexpectedly, addr2line decodes 0x0 into 0x0: auto seastar::internal::do_with_impl... instead of 0x0: ?? at ??, so addr2line.py keeps waiting for the delimiter line forever.

You can see it in your strace too:

$ echo "0x0000000002eebcb2" | strace /opt/scylladb/seastar/scripts/seastar-addr2line -b 3 -e /var/lib/binaries/2021.1.20-0.20230604.0f9b75eaf1.amd64/deb-relocatable/scylla.debug --addr2line llvm-addr2line
write(4, "0x0000000002eebcb2\n0x0\n", 23) = 23
read(5, "0x2eebcb2: void seastar::backtra"..., 8192) = 257
read(5, "0x0: auto seastar::internal::do_"..., 8192) = 281
read(5, 
<here the program hangs forever>

In other words, it's this specific Scylla executable that breaks the 0x0 delimiter hack in the script. Normally 0x0 shouldn't be decoded to any symbols, yet here it is.

[michoecho]

The corresponding code ignores the explicit warning from the Python doc pages:

It doesn't ignore the warning. It just aren't applicable here.

The python docs warn you against creating a pipe cycle, because you can end up with process A sleeping until some bytes are read by process B, while process B is waiting until some bytes are read by process A. So in general calling write() on child stdin, while you are also responsible for draining its stdout, is a bad practice.

But the protocol we are following in this case avoids the issue, because we only send one address at a time (which is guaranteed to fit in the buffer of a Linux pipe), and then we fully drain the stdout of the child before adding more input. So there is never a situation when we are trying to send more input to a child which is trying to add more output.

And communicate() (which handles both pipes in one Python call) can't be used here because it sends data, closes the child's stdin and waits for the child to end. That's not what we want, we want to send some data to it multiple times and manually delimit corresponding parts of its output.

[vladzcloudius]

The corresponding code ignores the explicit warning from the Python doc pages:

It doesn't ignore the warning. It just aren't applicable here.

The python docs warn you against creating a pipe cycle, because you can end up with process A sleeping until some bytes are read by process B, while process B is waiting until some bytes are read by process A. So in general calling write() on child stdin, while you are also responsible for draining its stdout, is a bad practice.

But the protocol we are following in this case avoids the issue, because we only send one address at a time (which is guaranteed to fit in the buffer of a Linux pipe),

Is it? I don't think you can universally guarantee it.

and then we fully drain the stdout of the child before adding more input. So there is never a situation when we are trying to send more input to a child which is trying to add more output.

And communicate() (which handles both pipes in one Python call) can't be used here because it sends data, closes the child's stdin and waits for the child to end. That's not what we want, we want to send some data to it multiple times and manually delimit corresponding parts of its output.

I understand that this is what you want. The question is why did we have to go down to hacks instead of not to?

The hack used by seastar-addr2line is totally empiric (you simply "know" that this is what you saw is the result of a zero-address decodding with some version of addr2line) but I doubt it's documented anywhere and/or addr2line has any obligations about it.

BTW the output of the binutils for 0x0 is

$ addr2line.binutils -Cfpia -e /var/lib/binaries/2021.1.20-0.20230604.0f9b75eaf1.amd64/deb-relocatable/scylla.debug 0x0
0x0000000000000000: ?? ??:0
$ echo "" | addr2line.binutils -Cfpia -e /var/lib/binaries/2021.1.20-0.20230604.0f9b75eaf1.amd64/deb-relocatable/scylla.debug
0x0000000000000000: ?? ??:0

Which seems to be exactly what seastar-addr2line expects:

dummy_pattern = re.compile(
        r"(.*0x0000000000000000: \?\? \?\?:0\n)"  # addr2line pattern
        r"|"
        r"(.*0x0: \?\? at .*\n)"  # llvm-addr2line pattern
    )

However the script hangs exactly the same way:

$ echo "0x0000000002eebcb2" | strace /opt/scylladb/seastar/scripts/seastar-addr2line -b 3 -e /var/lib/binaries/2021.1.20-0.20230604.0f9b75eaf1.amd64/deb-relocatable/scylla.debug --addr2line addr2line.binutils
...
write(4, "\n", 1)                       = 1
read(5, "0x0000000000000000: ?? ??:0\n", 8192) = 28
read(0, "0x0000000002eebcb2\n", 8192)   = 19
read(0, "", 8192)                       = 0
write(1, "[Backtrace #0]\n", 15[Backtrace #0]
)        = 15
write(4, "0x0000000002eebcb2\n0x0\n", 23) = 23
read(5, 
< here it hangs>

And when I interrupt it:

strace: Process 48255 detached
Traceback (most recent call last):
  File "/opt/scylladb/seastar/scripts/seastar-addr2line", line 526, in <module>

    main()
  File "/opt/scylladb/seastar/scripts/seastar-addr2line", line 503, in main
vladz@trace-decoder:~$     with BacktraceResolver(
  File "/opt/scylladb/seastar/scripts/addr2line.py", line 387, in __exit__
    self._print_current_backtrace()
  File "/opt/scylladb/seastar/scripts/addr2line.py", line 452, in _print_current_backtrace
    self._print_resolved_address(module, addr)
  File "/opt/scylladb/seastar/scripts/addr2line.py", line 403, in _print_resolved_address
    sys.stdout.write(self.resolve_address(address, module))
                     ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/opt/scylladb/seastar/scripts/addr2line.py", line 397, in resolve_address
    resolved_address = self._get_resolver_for_module(module)(address)
                       ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/opt/scylladb/seastar/scripts/addr2line.py", line 140, in __call__
    return self._read_resolved_address()
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/opt/scylladb/seastar/scripts/addr2line.py", line 118, in _read_resolved_address
    first = self._output.readline()
            ^^^^^^^^^^^^^^^^^^^^^^^
KeyboardInterrupt

So, @michoecho your assumption about it being either about specific Scylla binary or addr2line in general seems baseless. They behave exactly as seastar-addr2line expects.

On top of that a similar assumption (a.k.a. as "hack") at the line 57 in the scripts/addr2line.py about llvm-addr2line output for a "newline" and/or address 0x0 doesn't hold the water either:

$ echo "" | llvm-addr2line -Cfpia -e /var/lib/binaries/2021.1.20-0.20230604.0f9b75eaf1.amd64/deb-relocatable/scylla.debug
llvm-addr2line: error: no module offset has been specified
?? at ??:0

$ echo "0x0" | llvm-addr2line -Cfpia -e /var/lib/binaries/2021.1.20-0.20230604.0f9b75eaf1.amd64/deb-relocatable/scylla.debug
0x0: auto seastar::internal::do_with_impl<unsigned long, seastar::data_source_impl::skip(unsigned long)::'lambda'(unsigned long&)>(unsigned long&&, seastar::data_source_impl::skip(unsigned long)::'lambda'(unsigned long&)&&) at /usr/include/boost/function/function_template.hpp:883

And for a different Scylla binary:

$ echo "" | llvm-addr2line -Cfpia -e /var/lib/binaries/2023.1.8-0.20240502.c7683a2891c6.amd64/deb-relocatable/scylla.debug
llvm-addr2line: error: no module offset has been specified
?? at ??:0
$ echo "0x0" | llvm-addr2line -Cfpia -e /var/lib/binaries/2023.1.8-0.20240502.c7683a2891c6.amd64/deb-relocatable/scylla.debug
0x0: alloc::collections::btree::navigate::_$LT$impl$u20$alloc..collections..btree..node..NodeRef$LT$BorrowType$C$K$C$V$C$alloc..collections..btree..node..marker..LeafOrInternal$GT$$GT$::first_leaf_edge::hd14c3c21ca7ee100 at /builddir/build/BUILD/rustc-1.74.0-src/library/core/src/error.rs:184
 (inlined by) alloc::collections::btree::navigate::LazyLeafRange$LT$alloc..collections..btree..node..marker..Dying$C$K$C$V$GT$::take_front::hf7e32abc401dfde2 at /builddir/build/BUILD/rustc-1.74.0-src/library/alloc/src/collections/btree/navigate.rs:188

[vladzcloudius]

The problem is only with llvm-addr2line, right? The command you quoted works for me with /usr/bin/addr2line

$ addr2line --version
GNU addr2line version 2.41-38.fc40

The version that comes with U24.04 is newer than the one you have on your Fedora. 2.42 vs 2.41. So, it's not exactly comparable. Try Fedora 41 maybe to get more up to date binutils.

[vladzcloudius]

I think I know what's the pickle:

• llvm-addr2line support in seastar-addr2line is totally broken for reasons I explained above.
• addr2line (version is referenced in the opening message) on the other hand for addresses that are not 0x0 (e.g. 0x0000000002eebcb2) starts doing something very long (the corresponding strace would be too long to attach here) which effectively never ends. And I confirmed that this happens with at least two scylla binaries I referenced in my posts above.

The latter means that seastar-addr2line (or addr2line for the matter) can't be used with Scylla with (at least) inbox U24.04 binutils.

If I was willing to fix this I'd stop relying on undocumented empiric hacks.

But addr2line can print multiple output lines per each input line (because of function inlining). So if you want to use addr2line in "server" mode, you need some way to determine the end of output for the currently-decoded address, to know when to stop reading from the pipe. And the trick here is to send some garbage that will result in one, unique output line.

A standard way of handling such situations is to use non-blocking read, @michoecho. You can read some discussion about non-blocking reads in Python here for example: https://stackoverflow.com/questions/39948588/non-blocking-file-read

[vladzcloudius]

I see that the the "??: 0“ at the end of the line is kinda documented in the addr2line man page.

Maybe simply fixing the "dummy_pattern" and feeding an empty line instead of a "0x0" can be a simple fix.

[travisdowns]

A standard way of handling such situations is to use non-blocking read, @michoecho. You can read some discussion about non-blocking reads in Python here for example: https://stackoverflow.com/questions/39948588/non-blocking-file-read

Sorry how would that help?

If the addr2line process is not outputting anything (i.e., the non-blocking read returns EAGAIN or whatever), you can't tell if that's because it is still churning away trying to decode the address (this can take over 1 minute on some addr2line versions and binaries) or because it has output all the frames and is "done".

[vladzcloudius]

A standard way of handling such situations is to use non-blocking read, @michoecho. You can read some discussion about non-blocking reads in Python here for example: https://stackoverflow.com/questions/39948588/non-blocking-file-read

Sorry how would that help?

If the addr2line process is not outputting anything (i.e., the non-blocking read returns EAGAIN or whatever), you can't tell if that's because it is still churning away trying to decode the address (this can take over 1 minute on some addr2line versions and binaries) or because it has output all the frames and is "done".

That's a valid point. I never encountered such a long delays with llvm-addr2line during a single address decoding. I assumed that the only challenge here is a possibly large amount of the output (e.g. due to inlining).

I did see that the binutils addr2line however which effectively got into some seemingly endless rather busy loop on U24 with Scylla (I think I mentioned this above). But for that case it wouldn't matter how you read.

Anyway, on the PR above we seem to have progressed in working around the issue with llvm-addr2line.

The addr2line and Scylla on U24 part doesn't seem to be related to the script - there is something wrong with addr2line (of a given version - 2.42) decoding Scylla addresses. And this deserves a separate attention.

[travisdowns]

That's a valid point. I never encountered such a long delays with llvm-addr2line during a single address decoding.

I only saw it that slow with binutils. A single address could take a minute or more, because it reads in the whole debug info for the underlying object file which could be very large, e.g., symbols originating in reactor.cc took a long time. We are using -minline-threshold=2500 which makes this much worse.

During that part it would do some O(n^2) loop on the number of debug entries (of some type) which could be in the millions for highly inlined seastar application. Even when you don't hit that it's a low slower, which is why I added llvm-addr2line support (this also lets you decode binaries with newer DWARF versions). This one was at least partly fixed in later binutils versions.

The addr2line and Scylla on U24 part doesn't seem to be related to the script - there is something wrong with addr2line (of a given version - 2.42) decoding Scylla addresses. And this deserves a separate attention.

I see. I have had success filing bugs against binutils for these issues, but in any case you still need to work around them in the meantime.