Commit e85a11d5 authored by Kenny Yu's avatar Kenny Yu Committed by Facebook GitHub Bot

Print async stack trace in signal handler

Summary:
If there is an active async operation on the current thread, then the signal
handler will also print the async stack trace as well. Note that an async stack
trace can have a mix of both non-async and async frames. This is an example
of what an async stack trace might print:

```
funcF      <- non async, top of stack
funcE      <- non async
co_funcD   <- async
funcC      <- non async, blocking call. Second async stack root here
co_funcB   <- async
co_funcA   <- async
main       <- non async. First async stack root here
```

If there is no async operation in progress, there is no change in behavior
(only normal stack trace is printed).

This also adds a helper `getAsyncStackTraceStr()` to easily dump
the async stack trace on demand. This helper is NOT async-signal-safe
and is only meant for debugging purposes.

Reviewed By: yfeldblum, andriigrynenko

Differential Revision: D26661006

fbshipit-source-id: f6e913910eb45c438a3e1e29d231e224eed15ef2
parent 47667233
...@@ -39,19 +39,17 @@ class AsyncStackTraceAwaitable { ...@@ -39,19 +39,17 @@ class AsyncStackTraceAwaitable {
} }
FOLLY_NOINLINE std::vector<std::uintptr_t> await_resume() { FOLLY_NOINLINE std::vector<std::uintptr_t> await_resume() {
std::vector<std::uintptr_t> result; static constexpr size_t maxFrames = 100;
auto addIP = [&](void* ip) { std::array<std::uintptr_t, maxFrames> result;
result.push_back(reinterpret_cast<std::uintptr_t>(ip));
};
addIP(FOLLY_ASYNC_STACK_RETURN_ADDRESS()); result[0] =
reinterpret_cast<std::uintptr_t>(FOLLY_ASYNC_STACK_RETURN_ADDRESS());
auto numFrames = getAsyncStackTraceFromInitialFrame(
initialFrame_, result.data() + 1, maxFrames - 1);
auto* frame = initialFrame_; return std::vector<std::uintptr_t>(
while (frame != nullptr) { std::make_move_iterator(result.begin()),
addIP(frame->getReturnAddress()); std::make_move_iterator(result.begin()) + numFrames + 1);
frame = frame->getParentFrame();
}
return result;
} }
private: private:
......
...@@ -21,6 +21,7 @@ ...@@ -21,6 +21,7 @@
#include <folly/CppAttributes.h> #include <folly/CppAttributes.h>
#include <folly/Portability.h> #include <folly/Portability.h>
#include <folly/portability/Config.h> #include <folly/portability/Config.h>
#include <folly/tracing/AsyncStack.h>
#if FOLLY_HAVE_LIBUNWIND #if FOLLY_HAVE_LIBUNWIND
// Must be first to ensure that UNW_LOCAL_ONLY is defined // Must be first to ensure that UNW_LOCAL_ONLY is defined
...@@ -121,6 +122,12 @@ ssize_t getStackTraceInPlace( ...@@ -121,6 +122,12 @@ ssize_t getStackTraceInPlace(
#endif // FOLLY_HAVE_LIBUNWIND #endif // FOLLY_HAVE_LIBUNWIND
// Helper struct for manually walking the stack using stack frame pointers
struct StackFrame {
StackFrame* parentFrame;
void* returnAddress;
};
} // namespace } // namespace
ssize_t getStackTraceSafe( ssize_t getStackTraceSafe(
...@@ -162,5 +169,43 @@ ssize_t getStackTraceHeap( ...@@ -162,5 +169,43 @@ ssize_t getStackTraceHeap(
return -1; return -1;
#endif #endif
} }
ssize_t getAsyncStackTraceSafe(uintptr_t* addresses, size_t maxAddresses) {
size_t numFrames = 0;
const auto* asyncStackRoot = tryGetCurrentAsyncStackRoot();
// If we have no async stack root, this should return no frames.
// If we do have a stack root, also include the current return address.
if (asyncStackRoot != nullptr && numFrames < maxAddresses) {
addresses[numFrames++] = (uintptr_t)FOLLY_ASYNC_STACK_RETURN_ADDRESS();
}
for (const auto* normalStackFrame =
(StackFrame*)FOLLY_ASYNC_STACK_FRAME_POINTER();
normalStackFrame != nullptr && asyncStackRoot != nullptr &&
numFrames < maxAddresses;
normalStackFrame = normalStackFrame->parentFrame) {
// Walk the normal stack to find the caller of the frame that holds the
// AsyncStackRoot. If the caller holds the AsyncStackRoot, then the
// current frame is part of an async operation, and we should get the
// async stack trace before adding the current frame.
if (normalStackFrame->parentFrame ==
asyncStackRoot->getStackFramePointer()) {
// Follow the async stack trace starting from the root
numFrames += getAsyncStackTraceFromInitialFrame(
asyncStackRoot->getTopFrame(),
&addresses[numFrames],
maxAddresses - numFrames);
// There could be more related work at the next async stack root.
// Anything after the stack frame containing the last async stack root
// is potentially unrelated to the current async stack.
asyncStackRoot = asyncStackRoot->getNextRoot();
if (asyncStackRoot == nullptr) {
break;
}
}
addresses[numFrames++] = (uintptr_t)normalStackFrame->returnAddress;
}
return numFrames;
}
} // namespace symbolizer } // namespace symbolizer
} // namespace folly } // namespace folly
...@@ -58,5 +58,27 @@ ssize_t getStackTraceSafe(uintptr_t* addresses, size_t maxAddresses); ...@@ -58,5 +58,27 @@ ssize_t getStackTraceSafe(uintptr_t* addresses, size_t maxAddresses);
* avoids large stack allocations. * avoids large stack allocations.
*/ */
ssize_t getStackTraceHeap(uintptr_t* addresses, size_t maxAddresses); ssize_t getStackTraceHeap(uintptr_t* addresses, size_t maxAddresses);
/**
* Get the current async stack trace into addresses, which has room for at least
* maxAddresses frames. If no async operation is progress, then this will
* write 0 frames.
*
* This will include both async and non-async frames. For example, the stack
* trace could look something like this:
*
* funcD <-- non-async, current top of stack
* funcC <-- non-async
* co_funcB <-- async
* co_funcA <-- async
* main <-- non-async, root of async stack
*
* Returns the number of frames written in the array.
* Returns -1 on failure.
*
* Async-signal-safe, but likely slower.
*/
ssize_t getAsyncStackTraceSafe(uintptr_t* addresses, size_t maxAddresses);
} // namespace symbolizer } // namespace symbolizer
} // namespace folly } // namespace folly
...@@ -32,9 +32,11 @@ ...@@ -32,9 +32,11 @@
#include <folly/experimental/symbolizer/LineReader.h> #include <folly/experimental/symbolizer/LineReader.h>
#include <folly/experimental/symbolizer/detail/Debug.h> #include <folly/experimental/symbolizer/detail/Debug.h>
#include <folly/lang/SafeAssert.h> #include <folly/lang/SafeAssert.h>
#include <folly/lang/ToAscii.h>
#include <folly/portability/Config.h> #include <folly/portability/Config.h>
#include <folly/portability/SysMman.h> #include <folly/portability/SysMman.h>
#include <folly/portability/Unistd.h> #include <folly/portability/Unistd.h>
#include <folly/tracing/AsyncStack.h>
#if FOLLY_HAVE_SWAPCONTEXT #if FOLLY_HAVE_SWAPCONTEXT
// folly/portability/Config.h (thus features.h) must be included // folly/portability/Config.h (thus features.h) must be included
...@@ -53,6 +55,38 @@ ...@@ -53,6 +55,38 @@
namespace folly { namespace folly {
namespace symbolizer { namespace symbolizer {
namespace {
template <typename PrintFunc>
void printAsyncStackInfo(PrintFunc print) {
char buf[to_ascii_size_max<16, uint64_t>()];
auto printHex = [&print, &buf](uint64_t val) {
print("0x");
print(StringPiece(buf, to_ascii_lower<16>(buf, val)));
};
// Print async stack trace, if available
const auto* asyncStackRoot = tryGetCurrentAsyncStackRoot();
const auto* asyncStackFrame =
asyncStackRoot ? asyncStackRoot->getTopFrame() : nullptr;
print("\n");
print("*** Check failure async stack trace: ***\n");
print("*** First async stack root: ");
printHex((uint64_t)asyncStackRoot);
print(", normal stack frame pointer holding async stack root: ");
printHex(
asyncStackRoot ? (uint64_t)asyncStackRoot->getStackFramePointer() : 0);
print(", return address: ");
printHex(asyncStackRoot ? (uint64_t)asyncStackRoot->getReturnAddress() : 0);
print(" ***\n");
print("*** First async stack frame pointer: ");
printHex((uint64_t)asyncStackFrame);
print(", return address: ");
printHex(asyncStackFrame ? (uint64_t)asyncStackFrame->getReturnAddress() : 0);
print(", async stack trace: ***\n");
}
} // namespace
#if FOLLY_HAVE_ELF && FOLLY_HAVE_DWARF #if FOLLY_HAVE_ELF && FOLLY_HAVE_DWARF
namespace { namespace {
...@@ -243,10 +277,8 @@ void FastStackTracePrinter::printStackTrace(bool symbolize) { ...@@ -243,10 +277,8 @@ void FastStackTracePrinter::printStackTrace(bool symbolize) {
SCOPE_EXIT { printer_->flush(); }; SCOPE_EXIT { printer_->flush(); };
FrameArray<kMaxStackTraceDepth> addresses; FrameArray<kMaxStackTraceDepth> addresses;
auto printStack = [this, &addresses, &symbolize] {
if (!getStackTraceSafe(addresses)) { if (symbolize) {
printer_->print("(error retrieving stack trace)\n");
} else if (symbolize) {
symbolizer_.symbolize(addresses); symbolizer_.symbolize(addresses);
// Skip the top 2 frames: // Skip the top 2 frames:
...@@ -261,6 +293,20 @@ void FastStackTracePrinter::printStackTrace(bool symbolize) { ...@@ -261,6 +293,20 @@ void FastStackTracePrinter::printStackTrace(bool symbolize) {
printer_->print("\n"); printer_->print("\n");
} }
} }
};
if (!getStackTraceSafe(addresses)) {
printer_->print("(error retrieving stack trace)\n");
} else {
printStack();
}
addresses.frameCount = 0;
if (!getAsyncStackTraceSafe(addresses) || addresses.frameCount == 0) {
return;
}
printAsyncStackInfo([this](auto sp) { printer_->print(sp); });
printStack();
} }
void FastStackTracePrinter::flush() { void FastStackTracePrinter::flush() {
...@@ -337,6 +383,43 @@ void SafeStackTracePrinter::printStackTrace(bool symbolize) { ...@@ -337,6 +383,43 @@ void SafeStackTracePrinter::printStackTrace(bool symbolize) {
} else { } else {
printUnsymbolizedStackTrace(); printUnsymbolizedStackTrace();
} }
addresses_->frameCount = 0;
if (!getAsyncStackTraceSafe(*addresses_) || addresses_->frameCount == 0) {
return;
}
printAsyncStackInfo([this](auto sp) { print(sp); });
if (symbolize) {
printSymbolizedStackTrace();
} else {
printUnsymbolizedStackTrace();
}
}
std::string getAsyncStackTraceStr() {
#if FOLLY_HAVE_ELF && FOLLY_HAVE_DWARF
// Get and symbolize stack trace
constexpr size_t kMaxStackTraceDepth = 100;
FrameArray<kMaxStackTraceDepth> addresses;
if (!getAsyncStackTraceSafe(addresses)) {
return "";
} else {
ElfCache elfCache;
Symbolizer symbolizer(&elfCache);
symbolizer.symbolize(addresses);
StringSymbolizePrinter printer;
printer.println(addresses);
return printer.str();
}
#else
return "";
#endif // FOLLY_HAVE_ELF && FOLLY_HAVE_DWARF
} }
#if FOLLY_HAVE_SWAPCONTEXT #if FOLLY_HAVE_SWAPCONTEXT
......
...@@ -87,6 +87,14 @@ inline bool getStackTraceHeap(FrameArray<N>& fa) { ...@@ -87,6 +87,14 @@ inline bool getStackTraceHeap(FrameArray<N>& fa) {
return detail::fixFrameArray(fa, getStackTraceHeap(fa.addresses, N)); return detail::fixFrameArray(fa, getStackTraceHeap(fa.addresses, N));
} }
template <size_t N>
FOLLY_ALWAYS_INLINE bool getAsyncStackTraceSafe(FrameArray<N>& fa);
template <size_t N>
inline bool getAsyncStackTraceSafe(FrameArray<N>& fa) {
return detail::fixFrameArray(fa, getAsyncStackTraceSafe(fa.addresses, N));
}
#if FOLLY_HAVE_ELF && FOLLY_HAVE_DWARF #if FOLLY_HAVE_ELF && FOLLY_HAVE_DWARF
class Symbolizer { class Symbolizer {
...@@ -236,6 +244,14 @@ class SafeStackTracePrinter { ...@@ -236,6 +244,14 @@ class SafeStackTracePrinter {
std::unique_ptr<FrameArray<kMaxStackTraceDepth>> addresses_; std::unique_ptr<FrameArray<kMaxStackTraceDepth>> addresses_;
}; };
/**
* Gets the async stack trace for the current thread and returns a string
* representation. Convenience function meant for debugging and logging.
*
* NOT async-signal-safe.
*/
std::string getAsyncStackTraceStr();
#if FOLLY_HAVE_SWAPCONTEXT #if FOLLY_HAVE_SWAPCONTEXT
/** /**
......
...@@ -21,8 +21,12 @@ ...@@ -21,8 +21,12 @@
#include <folly/CPortability.h> #include <folly/CPortability.h>
#include <folly/FileUtil.h> #include <folly/FileUtil.h>
#include <folly/Range.h> #include <folly/Range.h>
#include <folly/experimental/coro/BlockingWait.h>
#include <folly/experimental/coro/Task.h>
#include <folly/portability/GTest.h> #include <folly/portability/GTest.h>
#include <glog/logging.h>
namespace folly { namespace folly {
namespace symbolizer { namespace symbolizer {
namespace test { namespace test {
...@@ -41,6 +45,19 @@ void callback2() { ...@@ -41,6 +45,19 @@ void callback2() {
print("Callback2\n"); print("Callback2\n");
} }
[[noreturn]] FOLLY_NOINLINE void funcC() {
LOG(FATAL) << "Die";
}
FOLLY_NOINLINE folly::coro::Task<void> co_funcB() {
funcC();
co_return;
}
FOLLY_NOINLINE folly::coro::Task<void> co_funcA() {
co_await co_funcB();
}
} // namespace } // namespace
TEST(SignalHandler, Simple) { TEST(SignalHandler, Simple) {
...@@ -67,6 +84,43 @@ TEST(SignalHandler, Simple) { ...@@ -67,6 +84,43 @@ TEST(SignalHandler, Simple) {
"Callback2\n" "Callback2\n"
".*"); ".*");
} }
TEST(SignalHandler, AsyncStackTraceSimple) {
addFatalSignalCallback(callback1);
addFatalSignalCallback(callback2);
installFatalSignalHandler();
installFatalSignalCallbacks();
EXPECT_DEATH(
folly::coro::blockingWait(co_funcA()),
"\\*\\*\\* Aborted at [0-9]+ \\(Unix time, try 'date -d @[0-9]+'\\) "
"\\*\\*\\*\n"
"\\*\\*\\* Signal 6 \\(SIGABRT\\) \\(0x[0-9a-f]+\\) received by PID [0-9]+ "
"\\(pthread TID 0x[0-9a-f]+\\) \\(linux TID [0-9]+\\) .*, "
"stack trace: \\*\\*\\*\n"
".*\n"
".* @ [0-9a-f]+.* folly::symbolizer::test::SignalHandler"
"_AsyncStackTraceSimple_Test::TestBody\\(\\).*\n"
".*\n"
".* @ [0-9a-f]+.* main.*\n"
".*\n"
"\\*\\*\\* Check failure async stack trace: \\*\\*\\*\n"
"\\*\\*\\* First async stack root.* \\*\\*\\*\n"
"\\*\\*\\* First async stack frame pointer.* \\*\\*\\*\n"
".*\n"
".* @ [0-9a-f]+.* folly::symbolizer::test::\\(anonymous namespace\\)"
"::funcC.*\n"
".*\n"
".* @ [0-9a-f]+.* folly::symbolizer::test::\\(anonymous namespace\\)"
"::co_funcB.*\n"
".*\n"
".* @ [0-9a-f]+.* folly::symbolizer::test::\\(anonymous namespace\\)"
"::co_funcA.*\n"
".*\n"
"Callback1\n"
"Callback2\n"
".*");
}
} // namespace test } // namespace test
} // namespace symbolizer } // namespace symbolizer
} // namespace folly } // namespace folly
......
...@@ -17,6 +17,8 @@ ...@@ -17,6 +17,8 @@
#include <cstring> #include <cstring>
#include <folly/experimental/TestUtil.h> #include <folly/experimental/TestUtil.h>
#include <folly/experimental/coro/BlockingWait.h>
#include <folly/experimental/coro/Task.h>
#include <folly/experimental/symbolizer/StackTrace.h> #include <folly/experimental/symbolizer/StackTrace.h>
#include <folly/experimental/symbolizer/Symbolizer.h> #include <folly/experimental/symbolizer/Symbolizer.h>
#include <folly/test/TestUtils.h> #include <folly/test/TestUtils.h>
...@@ -234,3 +236,94 @@ TEST(StackTraceTest, TerseFileAndLineStackTracePrinterOutput) { ...@@ -234,3 +236,94 @@ TEST(StackTraceTest, TerseFileAndLineStackTracePrinterOutput) {
ASSERT_TRUE(match); ASSERT_TRUE(match);
} }
namespace {
void verifyAsyncStackTraces() {
constexpr size_t kMaxAddresses = 100;
FrameArray<kMaxAddresses> fa;
CHECK(getAsyncStackTraceSafe(fa));
CHECK_GT(fa.frameCount, 0);
Symbolizer symbolizer;
symbolizer.symbolize(fa);
symbolizer::StringSymbolizePrinter printer;
printer.println(fa);
auto stackTraceStr = printer.str();
if (VLOG_IS_ON(1)) {
VLOG(1) << "getAsyncStackTrace\n" << stackTraceStr;
}
// These functions should appear in this relative order
std::vector<std::string> funcNames{
"funcF",
"funcE",
"co_funcD",
"co_funcC",
"funcB2_blocking",
"funcB1",
"co_funcB0",
"co_funcA2",
"co_funcA1",
"co_funcA0",
};
std::vector<size_t> positions;
for (const auto& funcName : funcNames) {
SCOPED_TRACE(funcName);
auto pos = stackTraceStr.find(funcName);
ASSERT_NE(pos, std::string::npos);
positions.push_back(pos);
}
for (size_t i = 0; i < positions.size() - 1; ++i) {
ASSERT_LT(positions[i], positions[i + 1]);
}
}
FOLLY_NOINLINE void funcF() {
verifyAsyncStackTraces();
}
FOLLY_NOINLINE void funcE() {
funcF();
}
FOLLY_NOINLINE folly::coro::Task<void> co_funcD() {
funcE();
co_return;
}
FOLLY_NOINLINE folly::coro::Task<void> co_funcC() {
co_await co_funcD();
}
FOLLY_NOINLINE void funcB2_blocking() {
// This should trigger a new AsyncStackRoot
folly::coro::blockingWait(co_funcC());
}
FOLLY_NOINLINE void funcB1() {
funcB2_blocking();
}
FOLLY_NOINLINE folly::coro::Task<void> co_funcB0() {
funcB1();
co_return;
}
FOLLY_NOINLINE folly::coro::Task<void> co_funcA2() {
co_await co_funcB0();
}
FOLLY_NOINLINE folly::coro::Task<void> co_funcA1() {
co_await co_funcA2();
}
FOLLY_NOINLINE folly::coro::Task<void> co_funcA0() {
co_await co_funcA1();
}
} // namespace
TEST(StackTraceTest, AsyncStackTraceSimple) {
folly::coro::blockingWait(co_funcA0());
}
...@@ -67,6 +67,19 @@ inline void popAsyncStackFrameCallee( ...@@ -67,6 +67,19 @@ inline void popAsyncStackFrameCallee(
calleeFrame.stackRoot = nullptr; calleeFrame.stackRoot = nullptr;
} }
inline size_t getAsyncStackTraceFromInitialFrame(
folly::AsyncStackFrame* initialFrame,
std::uintptr_t* addresses,
size_t maxAddresses) {
size_t numFrames = 0;
for (auto* frame = initialFrame; frame != nullptr && numFrames < maxAddresses;
frame = frame->getParentFrame()) {
addresses[numFrames++] =
reinterpret_cast<std::uintptr_t>(frame->getReturnAddress());
}
return numFrames;
}
#if FOLLY_HAS_COROUTINES #if FOLLY_HAS_COROUTINES
template <typename Promise> template <typename Promise>
......
...@@ -18,6 +18,7 @@ ...@@ -18,6 +18,7 @@
#include <atomic> #include <atomic>
#include <cassert> #include <cassert>
#include <cstdint>
#include <folly/CPortability.h> #include <folly/CPortability.h>
#include <folly/CppAttributes.h> #include <folly/CppAttributes.h>
...@@ -251,6 +252,16 @@ void popAsyncStackFrameCallee(folly::AsyncStackFrame& calleeFrame) noexcept; ...@@ -251,6 +252,16 @@ void popAsyncStackFrameCallee(folly::AsyncStackFrame& calleeFrame) noexcept;
// you should also never activate this frame. // you should also never activate this frame.
AsyncStackFrame& getDetachedRootAsyncStackFrame() noexcept; AsyncStackFrame& getDetachedRootAsyncStackFrame() noexcept;
// Given an initial AsyncStackFrame, this will write `addresses` with
// the return addresses of the frames in this async stack trace, up to
// `maxAddresses` written.
// This assumes `addresses` has `maxAddresses` allocated space available.
// Returns the number of frames written.
size_t getAsyncStackTraceFromInitialFrame(
folly::AsyncStackFrame* initialFrame,
std::uintptr_t* addresses,
size_t maxAddresses);
#if FOLLY_HAS_COROUTINES #if FOLLY_HAS_COROUTINES
// Resume the specified coroutine after installing a new AsyncStackRoot // Resume the specified coroutine after installing a new AsyncStackRoot
......
Markdown is supported
0%
or
You are about to add 0 people to the discussion. Proceed with caution.
Finish editing this message first!
Please register or to comment