workerd: macOS symbolication does not work

[ohodson]

Symbolication with llvm-symbolizer was enabled for the workerd github runners in test.yml in #1247.

Shortly after, it was suspended for macOS in commit ad20f5e in PR #1283 when additional build configurations were added because it leads to test timeouts. The symbol search process appears to be slow / misconfigured and the CPU and storage capabilities of the free-tier github runners are limited.

We've had issues with macOS, symbols for LLVM, and bazel build. workerd explicitly sets a source-map for debugging. The problem in this ticket is likely related.

I've spent a day or two looking into this, but have not cracked it. This ticket is just to track that we have a problem here. The next step is to collect fs activity from llvm-symbolizer, macOS is very different from Linux / Windows; procmon on windows is king :-). For macOS, it looks like it needs System Integrity Protection turning off and then finding a dtrace based tool for the fs activity (opensnoop or some-such).

It would also be good to fix this as a reasonable proportion of workerd users have macOS machines and they have no chance of reporting stack traces even if they want to.

A couple of related observations:

1. macOS has it's own backtrace_symbols function. This might be more expedient to use since it should give meaningful stacks without needing to run an additional tool.

2. llvm-symbolizer has a --filter-markup option that consumes symbolizer markup. This probably post-dates the code used in workerd (capnproto) and might make things marginally cleaner.

[ohodson]

It looks like fs_usage will trace file open events.

Crude approach, in terminal session 1 run:

# addr.txt is generated from a workerd crash (just a list of addresses, one per line, each starting 0x...).
workerd % (sleep 60; cat addr.txt ) | $(brew --prefix llvm@15)/bin/llvm-symbolizer --obj=./bazel-bin/src/workerd/server/workerd --verbose

Whilst that command is sleeping, use another terminal session to run fs_usage:

orion@LY4QWFNYJH:workerd % ps -eaf | grep llvm
  502 96657 88050   0  4:26pm ttys001    0:00.00 grep llvm
  502 96630 88092   0  4:26pm ttys003    0:00.01 /opt/homebrew/opt/llvm@15/bin/llvm-symbolizer --obj=./bazel-bin/src/workerd/server/workerd --verbose
orion@LY4QWFNYJH:workerd % sudo fs_usage -f pathname 96630
16:27:16.547638  open              F=3        (R__________X)  /private/var/tmp/_bazel_orion/0126d6c634aca3f3b55777a59ff39b0e/execroot/workerd/bazel-out/darwin_arm64-dbg/bin/src/workerd/server/workerd                                                                                       0.000149   llvm-symbolizer.5446225
16:27:16.568909  close             F=3                                                                                                                                                                                                                                                        0.000018   llvm-symbolizer.5446225
16:27:16.569000  open                   [  2] (R__________X)  /private/var/tmp/_bazel_orion/0126d6c634aca3f3b55777a59ff39b0e/execroot/workerd/bazel-out/darwin_arm64-dbg/bin/src/workerd/server/workerd.dSYM>>>>>>>>>>                                                                        0.000023   llvm-symbolizer.5446225

llvm-symbolizer is looking for .dSYM files. It seems we have enough debug info in the workerd binary for effective debugging in lldb, but either need that info in separate .dSYM files, or are lacking info for symbolication.

There is -gsplit-dwarf, though ld on macOS doesn't appear to support that (man ld). See also refs to -gsplit-dwarf in https://bazel.build/docs/cc-toolchain-config-reference.

[ohodson]

This might be as simple as running dsymutil on the workerd binary.

BTW, interesting background on dSYM in https://wiki.dwarfstd.org/Apple%27s_%22Lazy%22_DWARF_Scheme.md. Useful to read before https://lldb.llvm.org/use/symbols.html#symbols-on-macos.

---

Update: definitely looks as simple as running dsymutil on the workerd binary, but running dsymutil is quite expensive and consumes a surprising amount of disk for a debug build.

% time dsymutil /Volumes/Source/workerd/bazel-bin/src/workerd/server/workerd                                                
dsymutil /Volumes/Source/workerd/bazel-bin/src/workerd/server/workerd  81.19s user 3.44s system 161% cpu 52.329 total

% du -h -s /Volumes/Source/workerd/bazel-bin/src/workerd/server/workerd     
348M    /Volumes/Source/workerd/bazel-bin/src/workerd/server/workerd

% du -h -s /Volumes/Source/workerd/bazel-bin/src/workerd/server/workerd.dSYM 
1.2G    /Volumes/Source/workerd/bazel-bin/src/workerd/server/workerd.dSYM

% (brew --prefix llvm@15)/bin/llvm-symbolizer --obj /Volumes/Source/workerd/bazel-bin/src/workerd/server/workerd < addr.txt
workerd::server::Server::test(workerd::jsg::V8System&, workerd::server::config::Config::Reader, kj::StringPtr, kj::StringPtr) (.resume)
./src/workerd/server/server.c++:3362:15

workerd::server::CliMain::test()::'lambda'(workerd::jsg::V8System&, workerd::server::config::Config::Reader)::operator()(workerd::jsg::V8System&, workerd::server::config::Config::Reader) const::'lambda'(bool)::operator()(bool) const
./src/workerd/server/workerd.c++:1061:0

kj::_::convertToReturn(kj::_::ExceptionOr<kj::_::Void>&&)
./bazel-out/darwin_arm64-dbg/bin/external/capnp-cpp/src/kj/_virtual_includes/kj-async/kj/async-inl.h:108:5

kj::Promise<void>::wait(kj::WaitScope&, kj::SourceLocation)
./bazel-out/darwin_arm64-dbg/bin/external/capnp-cpp/src/kj/_virtual_includes/kj-async/kj/async-inl.h:1360:10

void workerd::server::CliMain::serveImpl<workerd::server::CliMain::test()::'lambda'(workerd::jsg::V8System&, workerd::server::config::Config::Reader)>(workerd::server::CliMain::test()::'lambda'(workerd::jsg::V8System&, workerd::server::config::Config::Reader)&&)
./src/workerd/server/workerd.c++:1035:15

workerd::server::CliMain::test()
./src/workerd/server/workerd.c++:1057:5

auto workerd::server::CliMain::getTest()::'lambda1'(auto&, auto&&...)::operator()<workerd::server::CliMain>(auto&, auto&&...)
./src/workerd/server/workerd.c++:659:27

auto kj::_::BoundMethod<workerd::server::CliMain&, workerd::server::CliMain::getTest()::'lambda1'(auto&, auto&&...), workerd::server::CliMain::getTest()::'lambda2'(auto&, auto&&...)>::operator()<>()
./bazel-out/darwin_arm64-dbg/bin/external/capnp-cpp/src/kj/_virtual_includes/kj/kj/function.h:263:12

kj::MainBuilder::Validity auto workerd::server::cliMethod<kj::_::BoundMethod<workerd::server::CliMain&, workerd::server::CliMain::getTest()::'lambda1'(auto&, auto&&...), workerd::server::CliMain::getTest()::'lambda2'(auto&, auto&&...)>>(auto&&)::'lambda'(auto&&...)::operator()<>('lambda'(auto&&...))
./src/workerd/server/workerd.c++:92:7

kj::Function<kj::MainBuilder::Validity ()>::Impl<auto workerd::server::cliMethod<kj::_::BoundMethod<workerd::server::CliMain&, workerd::server::CliMain::getTest()::'lambda1'(auto&, auto&&...), workerd::server::CliMain::getTest()::'lambda2'(auto&, auto&&...)>>(auto&&)::'lambda'(auto&&...)>::operator()()
./bazel-out/darwin_arm64-dbg/bin/external/capnp-cpp/src/kj/_virtual_includes/kj/kj/function.h:142:14

kj::Function<kj::MainBuilder::Validity ()>::operator()()
./external/capnp-cpp/src/kj/function.h:119:12

kj::MainBuilder::MainImpl::operator()(kj::StringPtr, kj::ArrayPtr<kj::StringPtr const>)
./external/capnp-cpp/src/kj/main.c++:612:5

kj::Function<void (kj::StringPtr, kj::ArrayPtr<kj::StringPtr const>)>::Impl<kj::MainBuilder::MainImpl>::operator()(kj::StringPtr, kj::ArrayPtr<kj::StringPtr const>)
./external/capnp-cpp/src/kj/function.h:142:14

kj::Function<void (kj::StringPtr, kj::ArrayPtr<kj::StringPtr const>)>::operator()(kj::StringPtr, kj::ArrayPtr<kj::StringPtr const>)
./external/capnp-cpp/src/kj/function.h:119:12

kj::MainBuilder::MainImpl::operator()(kj::StringPtr, kj::ArrayPtr<kj::StringPtr const>)
./external/capnp-cpp/src/kj/main.c++:510:9

kj::Function<void (kj::StringPtr, kj::ArrayPtr<kj::StringPtr const>)>::Impl<kj::MainBuilder::MainImpl>::operator()(kj::StringPtr, kj::ArrayPtr<kj::StringPtr const>)
./external/capnp-cpp/src/kj/function.h:142:14

kj::Function<void (kj::StringPtr, kj::ArrayPtr<kj::StringPtr const>)>::operator()(kj::StringPtr, kj::ArrayPtr<kj::StringPtr const>)
./external/capnp-cpp/src/kj/function.h:119:12

kj::runMainAndExit(kj::ProcessContext&, kj::Function<void (kj::StringPtr, kj::ArrayPtr<kj::StringPtr const>)>&&, int, char**)::$_0::operator()() const
./external/capnp-cpp/src/kj/main.c++:219:5

kj::Maybe<kj::Exception> kj::runCatchingExceptions<kj::runMainAndExit(kj::ProcessContext&, kj::Function<void (kj::StringPtr, kj::ArrayPtr<kj::StringPtr const>)>&&, int, char**)::$_0>(kj::runMainAndExit(kj::ProcessContext&, kj::Function<void (kj::StringPtr, kj::ArrayPtr<kj::StringPtr const>)>&&, int, char**)::$_0&&)
./external/capnp-cpp/src/kj/exception.h:339:5

kj::runMainAndExit(kj::ProcessContext&, kj::Function<void (kj::StringPtr, kj::ArrayPtr<kj::StringPtr const>)>&&, int, char**)
./external/capnp-cpp/src/kj/main.c++:219:5

main
./src/workerd/server/workerd.c++:1311:10

??
??:0:0