Create a "fast" stack trace printer that caches symbol lookups.

Summary: Create a "fast" stack trace printer that caches symbol lookups.

Reviewed By: yfeldblum

Differential Revision: D6000178

fbshipit-source-id: e81be1db21cfcd2cd26524c9ef6262337153ae36

folly/experimental/symbolizer/SignalHandler.cpp

@@ -33,7 +33,6 @@
 #include <folly/ScopeGuard.h>
 #include <folly/experimental/symbolizer/ElfCache.h>
 #include <folly/experimental/symbolizer/Symbolizer.h>
-#include <folly/portability/PThread.h>
 #include <folly/portability/SysSyscall.h>
 #include <folly/portability/Unistd.h>
 
@@ -128,7 +127,7 @@ void callPreviousSignalHandler(int signum) {
 // in our signal handler at a time.
 //
 // Leak it so we don't have to worry about destruction order
-StackTracePrinter* gStackTracePrinter = new StackTracePrinter();
+SafeStackTracePrinter* gStackTracePrinter = new SafeStackTracePrinter();
 
 void printDec(uint64_t val) {
   char buf[20];

folly/experimental/symbolizer/Symbolizer.cpp

@@ -79,8 +79,15 @@ void SymbolizedFrame::set(
   Dwarf(file.get()).findAddress(address, location, mode);
 }
 
-Symbolizer::Symbolizer(ElfCacheBase* cache, Dwarf::LocationInfoMode mode)
-    : cache_(cache ? cache : defaultElfCache()), mode_(mode) {}
+Symbolizer::Symbolizer(
+    ElfCacheBase* cache,
+    Dwarf::LocationInfoMode mode,
+    size_t symbolCacheSize)
+    : cache_(cache ? cache : defaultElfCache()), mode_(mode) {
+  if (symbolCacheSize > 0) {
+    symbolCache_.emplace(folly::in_place, symbolCacheSize);
+  }
+}
 
 void Symbolizer::symbolize(
     const uintptr_t* addresses,
@@ -139,12 +146,29 @@ void Symbolizer::symbolize(
       }
 
       auto const addr = addresses[i];
+      if (symbolCache_) {
+        // Need a write lock, because EvictingCacheMap brings found item to
+        // front of eviction list.
+        auto lockedSymbolCache = symbolCache_->wlock();
+
+        auto const iter = lockedSymbolCache->find(addr);
+        if (iter != lockedSymbolCache->end()) {
+          frame = iter->second;
+          continue;
+        }
+      }
+
       // Get the unrelocated, ELF-relative address.
       auto const adjusted = addr - base;
 
       if (elfFile->getSectionContainingAddress(adjusted)) {
         frame.set(elfFile, adjusted, mode_);
         --remaining;
+        if (symbolCache_) {
+          // frame may already have been set here.  That's ok, we'll just
+          // overwrite, which doesn't cause a correctness problem.
+          symbolCache_->wlock()->set(addr, frame);
+        }
       }
     }
   }
@@ -378,7 +402,9 @@ void StringSymbolizePrinter::doPrint(StringPiece sp) {
   buf_.append(sp.data(), sp.size());
 }
 
-StackTracePrinter::StackTracePrinter(size_t minSignalSafeElfCacheSize, int fd)
+SafeStackTracePrinter::SafeStackTracePrinter(
+    size_t minSignalSafeElfCacheSize,
+    int fd)
     : fd_(fd),
       elfCache_(std::max(countLoadedElfFiles(), minSignalSafeElfCacheSize)),
       printer_(
@@ -387,12 +413,12 @@ StackTracePrinter::StackTracePrinter(size_t minSignalSafeElfCacheSize, int fd)
           size_t(64) << 10), // 64KiB
       addresses_(std::make_unique<FrameArray<kMaxStackTraceDepth>>()) {}
 
-void StackTracePrinter::flush() {
+void SafeStackTracePrinter::flush() {
   printer_.flush();
   fsyncNoInt(fd_);
 }
 
-void StackTracePrinter::printStackTrace(bool symbolize) {
+void SafeStackTracePrinter::printStackTrace(bool symbolize) {
   SCOPE_EXIT {
     flush();
   };
@@ -408,7 +434,7 @@ void StackTracePrinter::printStackTrace(bool symbolize) {
 
     // Skip the top 2 frames:
     // getStackTraceSafe
-    // StackTracePrinter::printStackTrace (here)
+    // SafeStackTracePrinter::printStackTrace (here)
     //
     // Leaving signalHandler on the stack for clarity, I think.
     printer_.println(*addresses_, 2);
@@ -422,5 +448,51 @@ void StackTracePrinter::printStackTrace(bool symbolize) {
   }
 }
 
+FastStackTracePrinter::FastStackTracePrinter(
+    std::unique_ptr<SymbolizePrinter> printer,
+    size_t elfCacheSize,
+    size_t symbolCacheSize)
+    : elfCache_(
+          elfCacheSize == 0
+              ? nullptr
+              : new ElfCache{std::max(countLoadedElfFiles(), elfCacheSize)}),
+      printer_(std::move(printer)),
+      symbolizer_(
+          elfCache_ ? elfCache_.get() : defaultElfCache(),
+          Dwarf::LocationInfoMode::FULL,
+          symbolCacheSize) {}
+
+FastStackTracePrinter::~FastStackTracePrinter() {}
+
+void FastStackTracePrinter::printStackTrace(bool symbolize) {
+  SCOPE_EXIT {
+    printer_->flush();
+  };
+
+  FrameArray<kMaxStackTraceDepth> addresses;
+
+  if (!getStackTraceSafe(addresses)) {
+    printer_->print("(error retrieving stack trace)\n");
+  } else if (symbolize) {
+    symbolizer_.symbolize(addresses);
+
+    // Skip the top 2 frames:
+    // getStackTraceSafe
+    // FastStackTracePrinter::printStackTrace (here)
+    printer_->println(addresses, 2);
+  } else {
+    printer_->print("(safe mode, symbolizer not available)\n");
+    AddressFormatter formatter;
+    for (size_t i = 0; i < addresses.frameCount; ++i) {
+      printer_->print(formatter.format(addresses.addresses[i]));
+      printer_->print("\n");
+    }
+  }
+}
+
+void FastStackTracePrinter::flush() {
+  printer_->flush();
+}
+
 } // namespace symbolizer
 } // namespace folly

folly/experimental/symbolizer/Symbolizer.h

@@ -22,8 +22,11 @@
 #include <string>
 
 #include <folly/FBString.h>
+#include <folly/Optional.h>
 #include <folly/Range.h>
 #include <folly/String.h>
+#include <folly/Synchronized.h>
+#include <folly/container/EvictingCacheMap.h>
 #include <folly/experimental/symbolizer/Dwarf.h>
 #include <folly/experimental/symbolizer/Elf.h>
 #include <folly/experimental/symbolizer/ElfCache.h>
@@ -122,8 +125,8 @@ class Symbolizer {
 
   explicit Symbolizer(
       ElfCacheBase* cache,
-      Dwarf::LocationInfoMode mode = kDefaultLocationInfoMode);
-
+      Dwarf::LocationInfoMode mode = kDefaultLocationInfoMode,
+      size_t symbolCacheSize = 0);
   /**
    * Symbolize given addresses.
    */
@@ -148,6 +151,9 @@ class Symbolizer {
  private:
   ElfCacheBase* const cache_;
   const Dwarf::LocationInfoMode mode_;
+
+  using SymbolCache = EvictingCacheMap<uintptr_t, SymbolizedFrame>;
+  folly::Optional<Synchronized<SymbolCache>> symbolCache_;
 };
 
 /**
@@ -209,6 +215,12 @@ class SymbolizePrinter {
     }
   }
 
+  /**
+   * If output buffered inside this class, send it to the output stream, so that
+   * any output done in other ways appears after this.
+   */
+  virtual void flush() {}
+
   virtual ~SymbolizePrinter() {}
 
   enum Options {
@@ -276,7 +288,7 @@ class FDSymbolizePrinter : public SymbolizePrinter {
  public:
   explicit FDSymbolizePrinter(int fd, int options = 0, size_t bufferSize = 0);
   ~FDSymbolizePrinter() override;
-  void flush();
+  virtual void flush() override;
 
  private:
   void doPrint(StringPiece sp) override;
@@ -328,7 +340,7 @@ class StringSymbolizePrinter : public SymbolizePrinter {
  * descriptor is more important than performance.
  *
  * Make sure to create one of these on startup, not in the signal handler, as
- * the constructo allocates on the heap, whereas the other methods don't.  Best
+ * the constructor allocates on the heap, whereas the other methods don't.  Best
  * practice is to just leak this object, rather than worry about destruction
  * order.
  *
@@ -336,11 +348,11 @@ class StringSymbolizePrinter : public SymbolizePrinter {
  * threads at the same time, you need to do your own locking to ensure you don't
  * call these methods from multiple threads.  They are signal safe, however.
  */
-class StackTracePrinter {
+class SafeStackTracePrinter {
  public:
   static constexpr size_t kDefaultMinSignalSafeElfCacheSize = 500;
 
-  explicit StackTracePrinter(
+  explicit SafeStackTracePrinter(
       size_t minSignalSafeElfCacheSize = kDefaultMinSignalSafeElfCacheSize,
       int fd = STDERR_FILENO);
 
@@ -348,6 +360,9 @@ class StackTracePrinter {
    * Only allocates on the stack and is signal-safe but not thread-safe.  Don't
    * call printStackTrace() on the same StackTracePrinter object from multiple
    * threads at the same time.
+   *
+   * This is NOINLINE to make sure it shows up in the stack we grab, which makes
+   * it easy to skip printing it.
    */
   FOLLY_NOINLINE void printStackTrace(bool symbolize);
 
@@ -367,5 +382,38 @@ class StackTracePrinter {
   std::unique_ptr<FrameArray<kMaxStackTraceDepth>> addresses_;
 };
 
+/**
+ * Use this class to print a stack trace from normal code.  It will malloc and
+ * won't flush or sync.
+ *
+ * These methods are thread safe, through locking.  However, they are not signal
+ * safe.
+ */
+class FastStackTracePrinter {
+ public:
+  static constexpr size_t kDefaultSymbolCacheSize = 10000;
+
+  explicit FastStackTracePrinter(
+      std::unique_ptr<SymbolizePrinter> printer,
+      size_t elfCacheSize = 0, // 0 means "use the default elf cache instance."
+      size_t symbolCacheSize = kDefaultSymbolCacheSize);
+
+  ~FastStackTracePrinter();
+
+  /**
+   * This is NOINLINE to make sure it shows up in the stack we grab, which makes
+   * it easy to skip printing it.
+   */
+  FOLLY_NOINLINE void printStackTrace(bool symbolize);
+
+  void flush();
+
+ private:
+  static constexpr size_t kMaxStackTraceDepth = 100;
+
+  const std::unique_ptr<ElfCache> elfCache_;
+  const std::unique_ptr<SymbolizePrinter> printer_;
+  Symbolizer symbolizer_;
+};
 } // namespace symbolizer
 } // namespace folly

folly/experimental/symbolizer/test/StackTraceTest.cpp

@@ -14,6 +14,9 @@
  * limitations under the License.
  */
 
+#include <cstring>
+
+#include <folly/experimental/TestUtil.h>
 #include <folly/experimental/symbolizer/StackTrace.h>
 #include <folly/experimental/symbolizer/Symbolizer.h>
 
@@ -88,3 +91,75 @@ TEST(StackTraceTest, Signal) {
   raise(SIGUSR1);
   EXPECT_TRUE(handled);
 }
+
+ssize_t read_all(int fd, uint8_t* buffer, size_t size) {
+  uint8_t* pos = buffer;
+  ssize_t bytes_read;
+  do {
+    bytes_read = read(fd, pos, size);
+    if (bytes_read < 0) {
+      if (errno == EAGAIN || errno == EWOULDBLOCK || errno == EINTR) {
+        continue;
+      }
+      return bytes_read;
+    }
+
+    pos += bytes_read;
+    size -= bytes_read;
+  } while (bytes_read > 0 && size > 0);
+
+  return pos - buffer;
+}
+
+// Returns the position in the file after done reading.
+off_t get_stack_trace(int fd, size_t file_pos, uint8_t* buffer, size_t count) {
+  off_t rv = lseek(fd, file_pos, SEEK_SET);
+  assert(rv == (off_t)file_pos);
+
+  // Subtract 1 from size of buffer to hold nullptr.
+  ssize_t bytes_read = read_all(fd, buffer, count - 1);
+  assert(bytes_read > 0);
+  buffer[bytes_read] = '\0';
+  return lseek(fd, 0, SEEK_CUR);
+}
+
+template <class StackTracePrinter>
+void testStackTracePrinter(StackTracePrinter& printer, int fd) {
+  ASSERT_GT(fd, 0);
+
+  printer.printStackTrace(true);
+  printer.flush();
+
+  std::array<uint8_t, 4000> first;
+  off_t pos = get_stack_trace(fd, 0, first.data(), first.size());
+  ASSERT_GT(pos, 0);
+
+  printer.printStackTrace(true);
+  printer.flush();
+
+  std::array<uint8_t, 4000> second;
+  get_stack_trace(fd, pos, second.data(), second.size());
+
+  // The first two lines refer to this stack frame, which is different in the
+  // two cases, so strip those off.  The rest should be equal.
+  ASSERT_STREQ(
+      strchr(strchr((const char*)first.data(), '\n') + 1, '\n') + 1,
+      strchr(strchr((const char*)second.data(), '\n') + 1, '\n') + 1);
+}
+
+TEST(StackTraceTest, SafeStackTracePrinter) {
+  test::TemporaryFile file;
+
+  SafeStackTracePrinter printer{10, file.fd()};
+
+  testStackTracePrinter<SafeStackTracePrinter>(printer, file.fd());
+}
+
+TEST(StackTraceTest, FastStackTracePrinter) {
+  test::TemporaryFile file;
+
+  FastStackTracePrinter printer{
+      std::make_unique<FDSymbolizePrinter>(file.fd())};
+
+  testStackTracePrinter<FastStackTracePrinter>(printer, file.fd());
+}

folly/experimental/symbolizer/test/SymbolizerTest.cpp

@@ -53,10 +53,10 @@ TEST(Symbolizer, Single) {
   }
 }
 
-FrameArray<100> goldenFrames;
+FrameArray<100>* framesToFill{nullptr};
 
 int comparator(const void* ap, const void* bp) {
-  getStackTrace(goldenFrames);
+  getStackTrace(*framesToFill);
 
   int a = *static_cast<const int*>(ap);
   int b = *static_cast<const int*>(bp);
@@ -66,10 +66,12 @@ int comparator(const void* ap, const void* bp) {
 // Test stack frames...
 FOLLY_NOINLINE void bar();
 
-void bar() {
+void bar(FrameArray<100>& frames) {
+  framesToFill = &frames;
   int a[2] = {1, 2};
   // Use qsort, which is in a different library
   qsort(a, 2, sizeof(int), comparator);
+  framesToFill = nullptr;
 }
 
 class ElfCacheTest : public testing::Test {
@@ -78,8 +80,10 @@ class ElfCacheTest : public testing::Test {
 };
 
 // Capture "golden" stack trace with default-configured Symbolizer
+FrameArray<100> goldenFrames;
+
 void ElfCacheTest::SetUp() {
-  bar();
+  bar(goldenFrames);
   Symbolizer symbolizer;
   symbolizer.symbolize(goldenFrames);
   // At least 3 stack frames from us + getStackTrace()
@@ -114,6 +118,22 @@ TEST_F(ElfCacheTest, SignalSafeElfCache) {
     runElfCacheTest(symbolizer);
   }
 }
+
+TEST(SymbolizerTest, SymbolCache) {
+  Symbolizer symbolizer(nullptr, Dwarf::LocationInfoMode::FULL, 100);
+
+  FrameArray<100> frames;
+  bar(frames);
+  symbolizer.symbolize(frames);
+
+  FrameArray<100> frames2;
+  bar(frames2);
+  symbolizer.symbolize(frames2);
+  for (size_t i = 0; i < frames.frameCount; i++) {
+    EXPECT_STREQ(frames.frames[i].name, frames2.frames[i].name);
+  }
+}
+
 } // namespace test
 } // namespace symbolizer
 } // namespace folly