From: Dean Michael Berris <dberris@google.com>
Date: Thu, 31 Aug 2017 01:07:24 +0000 (+0000)
Subject: [XRay][tools] Fix an accounting bug in llvm-xray account
X-Git-Url: https://granicus.if.org/sourcecode?a=commitdiff_plain;h=72cfebd887299b259fea58d689683241b575363c;p=llvm

[XRay][tools] Fix an accounting bug in llvm-xray account

Summary:
Before this patch, llvm-xray account will assume that thread stacks will
not be empty. Unfortunately there are cases where an instrumented
function will see a call to `fork()` which will cause the child process
to not see the start of the function, but only see the end of the
function. The tooling cannot assume that threads will always have
perfect stacks, and so we change it to support this reality.

Reviewers: dblaikie

Subscribers: llvm-commits

Differential Revision: https://reviews.llvm.org/D31870

git-svn-id: https://llvm.org/svn/llvm-project/llvm/trunk@312204 91177308-0d34-0410-b5e6-96231b3b80d8
---

diff --git a/test/tools/llvm-xray/X86/account-empty-stack-error.yaml b/test/tools/llvm-xray/X86/account-empty-stack-error.yaml
new file mode 100644
index 00000000000..d02d070a1f6
--- /dev/null
+++ b/test/tools/llvm-xray/X86/account-empty-stack-error.yaml
@@ -0,0 +1,29 @@
+#RUN: not llvm-xray account %s -o - -m %S/Inputs/simple-instrmap.yaml -d 2>&1 | FileCheck %s
+#RUN: llvm-xray account %s -k -o - -m %S/Inputs/simple-instrmap.yaml -d 2>&1 | FileCheck %s --check-prefix=KEEPGOING
+
+---
+header:
+  version: 1
+  type: 0
+  constant-tsc: true
+  nonstop-tsc: true
+  cycle-frequency: 0
+records:
+# We simulate the case when, for whatever reason, we see that a thread's stack
+# is empty when we see an EXIT record. This can happen for example when an
+# instrumented function does a 'fork()', where the child process will not see
+# the entry record but see the exit record. This is completely valid data,
+# which should be handled with grace (i.e. we treat it as an error, but since
+# the llvm-xray account tool has an option to keep going, gives the user a
+# chance to retry).
+  - { type: 0, func-id: 1, cpu: 1, thread: 1, kind: function-exit, tsc: 10000}
+...
+
+#CHECK:      Error processing record: {{.*}}
+#CHECK-NEXT: Thread ID: 1
+#CHECK-NEXT:   (empty stack)
+#CHECK-NEXT: llvm-xray: Failed accounting function calls in file '{{.*}}'.
+
+#KEEPGOING:      Error processing record: {{.*}}
+#KEEPGOING-NEXT: Thread ID: 1
+#KEEPGOING-NEXT:   (empty stack)
diff --git a/tools/llvm-xray/xray-account.cc b/tools/llvm-xray/xray-account.cc
index 13654c3911f..e97b4d8d1ed 100644
--- a/tools/llvm-xray/xray-account.cc
+++ b/tools/llvm-xray/xray-account.cc
@@ -147,12 +147,13 @@ bool LatencyAccountant::accountRecord(const XRayRecord &Record) {
   auto &ThreadStack = PerThreadFunctionStack[Record.TId];
   switch (Record.Type) {
   case RecordTypes::ENTER: {
-    // Function Enter
     ThreadStack.emplace_back(Record.FuncId, Record.TSC);
     break;
   }
   case RecordTypes::EXIT: {
-    // Function Exit
+    if (ThreadStack.empty())
+      return false;
+
     if (ThreadStack.back().first == Record.FuncId) {
       const auto &Top = ThreadStack.back();
       recordLatency(Top.first, diff(Top.second, Record.TSC));
@@ -407,6 +408,22 @@ void LatencyAccountant::exportStatsAsCSV(raw_ostream &OS,
 
 using namespace llvm::xray;
 
+namespace llvm {
+template <> struct format_provider<llvm::xray::RecordTypes> {
+  static void format(const llvm::xray::RecordTypes &T, raw_ostream &Stream,
+                     StringRef Style) {
+    switch(T) {
+      case RecordTypes::ENTER:
+        Stream << "enter";
+        break;
+      case RecordTypes::EXIT:
+        Stream << "exit";
+        break;
+    }
+  }
+};
+} // namespace llvm
+
 static CommandRegistration Unused(&Account, []() -> Error {
   InstrumentationMap Map;
   if (!AccountInstrMap.empty()) {
@@ -445,11 +462,22 @@ static CommandRegistration Unused(&Account, []() -> Error {
   for (const auto &Record : T) {
     if (FCA.accountRecord(Record))
       continue;
+    errs()
+        << "Error processing record: "
+        << llvm::formatv(
+               R"({{type: {0}; cpu: {1}; record-type: {2}; function-id: {3}; tsc: {4}; thread-id: {5}}})",
+               Record.RecordType, Record.CPU, Record.Type, Record.FuncId,
+               Record.TId)
+        << '\n';
     for (const auto &ThreadStack : FCA.getPerThreadFunctionStack()) {
       errs() << "Thread ID: " << ThreadStack.first << "\n";
+      if (ThreadStack.second.empty()) {
+        errs() << "  (empty stack)\n";
+        continue;
+      }
       auto Level = ThreadStack.second.size();
       for (const auto &Entry : llvm::reverse(ThreadStack.second))
-        errs() << "#" << Level-- << "\t"
+        errs() << "  #" << Level-- << "\t"
                << FuncIdHelper.SymbolOrNumber(Entry.first) << '\n';
     }
     if (!AccountKeepGoing)