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

[dberris]

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.

[dblaikie]

test/tools/llvm-xray/X86/account-empty-stack-error.yaml

16–17

Is the "keep going" functionality sufficiently tested? (Does this new error path present an interesting/new case of "keep going" that's worth testing separately - or is the functionality sufficiently generic that the existing testing covers enough here)

[dberris]

test/tools/llvm-xray/X86/account-empty-stack-error.yaml

16–17

We have a dedicated test that uses -k for account. This particular case isn't so interesting, because we're not attempting to recover or handle it (yet). In the future we may want to indicate in the accounting how many records we've discarded, how many we've deduced tail calls for, etc. -- but that's not so important at the moment than not crashing when we have this situation.

[dberris]

ping?

[dberris]

ping @dblaikie?

[dblaikie]

Please read the mailing list - Phab is not authoritative and doesn't always reflect replies/content on the mailing list.

[dberris]

Update test with the keep-going path along with the non-keep-going test.

[dberris]

test/tools/llvm-xray/X86/account-empty-stack-error.yaml

16–17

I added a test for the keep-going path as well, making sure it works in this path as well.

[dberris]

ping @dblaikie -- I think I've addressed the question you had about the -keep-going mode, with an additional test.

[dberris]

Adding @kpw and @eizan for a couple more sets of eyes to see whether this makes a bit more sense.

[dblaikie]

Looks fine to me

[eizan]

tools/llvm-xray/xray-account.cc

412

This struct doesn't appear to be used anywhere. Do we need it?

[dberris]

tools/llvm-xray/xray-account.cc

412

Ah, yes -- this is a specialization of a type used by the llvm::format(...) library for specifically the RecordTypes enum class.

test/tools/llvm-xray/X86/account-empty-stack-error.yaml

+#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)

tools/llvm-xray/xray-account.cc

if (CurrentMaxTSC == 0)
     CurrentMaxTSC = Record.TSC;
 
   if (Record.TSC < CurrentMaxTSC)
     return false;
 
   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));
       ThreadStack.pop_back();
       break;
     }
 
     if (!DeduceSiblingCalls)
exportStats(Header, [&](int32_t FuncId, size_t Count, const ResultRow &Row) {
     OS << FuncId << ',' << Count << ',' << Row.Min << ',' << Row.Median << ','
        << Row.Pct90 << ',' << Row.Pct99 << ',' << Row.Max << "," << Row.Sum
        << ",\"" << Row.DebugInfo << "\",\"" << Row.Function << "\"\n";
   });
 }
 
 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()) {
     auto InstrumentationMapOrError = loadInstrumentationMap(AccountInstrMap);
     if (!InstrumentationMapOrError)
       return joinErrors(make_error<StringError>(
                             Twine("Cannot open instrumentation map '") +
                                 AccountInstrMap + "'",
return joinErrors(
             Twine("Failed loading input file '") + AccountInput + "'",
             std::make_error_code(std::errc::executable_format_error)),
         TraceOrErr.takeError());
 
   auto &T = *TraceOrErr;
   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)
       return make_error<StringError>(
           Twine("Failed accounting function calls in file '") + AccountInput +
               "'.",
           std::make_error_code(std::errc::executable_format_error));
   }