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

[Dean Michael Berris via llvm-commits]

Author: dberris
Date: Wed Aug 30 18:07:24 2017
New Revision: 312204

URL: http://llvm.org/viewvc/llvm-project?rev=312204&view=rev
Log:
[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

Added:
    llvm/trunk/test/tools/llvm-xray/X86/account-empty-stack-error.yaml
Modified:
    llvm/trunk/tools/llvm-xray/xray-account.cc

Added: llvm/trunk/test/tools/llvm-xray/X86/account-empty-stack-error.yaml
URL: http://llvm.org/viewvc/llvm-project/llvm/trunk/test/tools/llvm-xray/X86/account-empty-stack-error.yaml?rev=312204&view=auto
==============================================================================
--- llvm/trunk/test/tools/llvm-xray/X86/account-empty-stack-error.yaml (added)
+++ llvm/trunk/test/tools/llvm-xray/X86/account-empty-stack-error.yaml Wed Aug 30 18:07:24 2017
@@ -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)

Modified: llvm/trunk/tools/llvm-xray/xray-account.cc
URL: http://llvm.org/viewvc/llvm-project/llvm/trunk/tools/llvm-xray/xray-account.cc?rev=312204&r1=312203&r2=312204&view=diff
==============================================================================
--- llvm/trunk/tools/llvm-xray/xray-account.cc (original)
+++ llvm/trunk/tools/llvm-xray/xray-account.cc Wed Aug 30 18:07:24 2017
@@ -147,12 +147,13 @@ bool LatencyAccountant::accountRecord(co
   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
 
 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(&Accou
   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)