[XRay] Implement the `llvm-xray account` subcommand

[dberris]

Summary

This is the third of a multi-part change to implement subcommands for
the llvm-xray tool.

Here we define the account subcommand which does simple function call
accounting, generating basic statistics on function calls we find in an
XRay log/trace. We support text output and csv output for this
subcommand.

Part of this tool will later be turned into a library that could be used for
basic function call accounting.

Depends on D24376.

[dberris]

• Rebase and update implementation.

[dberris]

• Rebase and update implementation.
• Use Error

[dberris]

• Make the number formatting nicer with formatv

[dberris]

• Sorting, Summing, Top N

[dberris]

• Rebase
• Fix tests with format adjustment

[varno]

At line 182-195 the following code I think is simpler and results in the function performing the same work.

if (Parent == ThreadStack.rend())
  return false;
while (ThreadStack.back().FuncId != Record.FuncId) {
  const auto &Top = ThreadStack.back();
  recordLatency(Top.first, diff(Top.second, Record.TSC)):
  ThreadStack.pop_back();
}

[dblaikie]

tools/llvm-xray/xray-account.cc

174–203 ↗

(On Diff #79368)

Might be good (maybe not) to invert this to reduce indentation.

if (first == funcid) {
  ...
  ThreadStack.pop_back();
}
if (!DeduceSiblingCalls)
  return false;
if (Parent == ThreadStack.rend())
  return false;
while (...) {
  ...
}
return true;

316 ↗

(On Diff #79368)

extra semicolon?

324 ↗

(On Diff #79368)

Probably wouldn't bother usind std::advance unless you're writing a generic algorithm or have a non-random iterator you need to stride forward.

Results.erase(Results.begin() + AccountTop.getValue(), Results.end());

seems fine.

332 ↗

(On Diff #79368)

Text isn't an acronym, so probably shouldn't be capitalized here.

378–381 ↗

(On Diff #79368)

Seems a bit weird to put a single static variable in a namespace - maybe just use 'using' decls for the namespace instead?

395 ↗

(On Diff #79368)

No need for "Error(...)" here, this will do, I think:

return std::move(E);

414–421 ↗

(On Diff #79368)

It'd be good if reading were refactored into some utility that would just read the input file in whatever format it was in without every tool having to have explicit support for format specifications.

433 ↗

(On Diff #79368)

reduce indentation:

if (FCA.accountRecord(Record))
  continue;
...

[dberris]

• Address review comments

[dberris]

In D24377#610170, @varno wrote:

At line 182-195 the following code I think is simpler and results in the function performing the same work.

if (Parent == ThreadStack.rend())
  return false;
while (ThreadStack.back().FuncId != Record.FuncId) {
  const auto &Top = ThreadStack.back();
  recordLatency(Top.first, diff(Top.second, Record.TSC)):
  ThreadStack.pop_back();
}

Thanks -- after the refactoring suggested by @dblaikie though this became less of an issue.

tools/llvm-xray/xray-account.cc

316 ↗

(On Diff #79368)

Apparently not, since if I leave this empty I get a warning that the default case is empty.

label at end of compound statement: expected statement

395 ↗

(On Diff #79368)

Apparently no. :(

error: no viable conversion from returned value of type 'typename std::remove_reference<unique_ptr<StringError, default_delete<StringError> > &>::type' (aka 'std::unique_ptr<llvm::StringEr
ror, std::default_delete<llvm::StringError> >') to function return type 'llvm::Error'

[dberris]

• Reduce calls to .pop_back() for simpler code.

[dblaikie]

tools/llvm-xray/xray-account.cc

34 ↗

(On Diff #80376)

Is this necessary/useful?
Is this tested?

Also, I think flags tend to be - not _ separated.

39–42 ↗

(On Diff #80376)

Test coverage?

47–69 ↗

(On Diff #80376)

Having to specify both input files, as well as input and output formats every time seems a bit tedious. Could we detect formats using file magic & perhaps have some way of unifying the two files (the map and the log) in common/some cases?

219–223 ↗

(On Diff #80376)

Might be easier written/read as:

for (auto &a : make_range(I, ThreadStack.end()))
  ...

?

221 ↗

(On Diff #80376)

Capture all by reference for any lambda that doesn't escape its own scope (ie: if the lambda isn't put in a std::function or equivalent, feel free to [&] )

297–300 ↗

(On Diff #80376)

Might be worth a helper function template that takes the non-type template argument to sort by.

399 ↗

(On Diff #80376)

Can skip '()' here, possibly skip '-> Error' too, if you like (see below)

410 ↗

(On Diff #80376)

Do you need the "-> Error" there? (I know the "if every return expression deduces to the same type it can be left implicit" was accepted as a DR to C++11 but not sure it's in all the compilers we support)

(same for the lambda being passed to the Unused variable's ctor too)

tools/llvm-xray/xray-log-reader.h

49 ↗

(On Diff #80376)

Should this perhaps be called "LogInputFormat" (singular rather than plural)?

[dberris]

• Address review comments

[dberris]

tools/llvm-xray/xray-account.cc

34 ↗

(On Diff #80376)

Is this necessary/useful?

Yep -- because we cannot assume that trace files will have perfect information (TSC drift, and unmatched exit records, just some of the errors we encounter) we'd like to allow users to continue despite imperfections.

Is this tested?

It wasn't but now should be. :)

Also, I think flags tend to be - not _ separated.

Done

39–42 ↗

(On Diff #80376)

We have a test for this, which does tail call deduction.

47–69 ↗

(On Diff #80376)

Changed to use the log file detection magic to at least remove the input format specification. I'll need to change the extract logic to also use file type detection magic (will do so in a different patch that makes the instrumentation map extraction a library in LLVM as well) which will greatly simplify this API.

[dberris]

• Commplete sorting support, add more tests

[labath]

Hi,

this is still failing to compile on windows/MSVC. http://lab.llvm.org:8011/builders/lldb-windows7-android/builds/1645/steps/ninja%20build%20local/logs/stdio

The first error seems to be about missing type pid_t.

Could you please look into that?

llvm/trunk/test/tools/llvm-xray/X86/Inputs/simple-instrmap.yaml

+# This is a simple instrumentation map with bogus addresses and offsets, but
+# follow the recommended format.
+---
+- { id: 1, address: 0x1, function: 0x1, kind: function-enter, always-instrument: true}
+- { id: 1, address: 0x2, function: 0x1, kind: function-exit, always-instrument: true}
+- { id: 2, address: 0x2, function: 0x2, kind: function-enter, always-instrument: true}
+- { id: 2, address: 0x3, function: 0x2, kind: function-exit, always-instrument: true}
+- { id: 3, address: 0x3, function: 0x3, kind: function-enter, always-instrument: true}
+- { id: 3, address: 0x4, function: 0x3, kind: function-exit, always-instrument: true}
+...

llvm/trunk/test/tools/llvm-xray/X86/account-deduce-tail-call.yaml

+#RUN: llvm-xray account %s -o - -m %S/Inputs/simple-instrmap.yaml -t yaml -d | FileCheck %s
+---
+header:
+  version: 1
+  type: 0
+  constant-tsc: true
+  nonstop-tsc: true
+  cycle-frequency: 0
+records:
+# Here we reconstruct the following call trace:
+#
+#   f1()
+#     f2()
+#       f3()
+#
+# But we find that we're missing an exit record for f2() because it's
+# tail-called f3(). We make sure that if we see a trace like this that we can
+# deduce tail calls, and account the time (potentially wrongly) to f2() when
+# f1() exits. That is because we don't go back to f3()'s entry record to
+# properly do the math on the timing of f2().
+#
+# Note that by default, tail/sibling call deduction is disabled, and is enabled
+# with a flag "-d" or "-deduce-sibling-calls".
+#
+  - { type: 0, func-id: 1, cpu: 1, thread: 111, kind: function-enter, tsc: 10000 }
+  - { type: 0, func-id: 2, cpu: 1, thread: 111, kind: function-enter, tsc: 10001 }
+  - { type: 0, func-id: 3, cpu: 1, thread: 111, kind: function-enter, tsc: 10002 }
+  - { type: 0, func-id: 3, cpu: 1, thread: 111, kind: function-exit,  tsc: 10003 }
+  - { type: 0, func-id: 1, cpu: 1, thread: 111, kind: function-exit,  tsc: 10004 }
+...
+
+#CHECK:       Functions with latencies: 3
+#CHECK-NEXT:  funcid  count  [ min, med, 90p, 99p, max] sum function
+#CHECK-NEXT:  1 1 [ 4.{{.*}}, 4.{{.*}}, 4.{{.*}}, 4.{{.*}}, 4.{{.*}}] {{.*}} {{.*}}
+#CHECK-NEXT:  2 1 [ 3.{{.*}}, 3.{{.*}}, 3.{{.*}}, 3.{{.*}}, 3.{{.*}}] {{.*}} {{.*}}
+#CHECK-NEXT:  3 1 [ 1.{{.*}}, 1.{{.*}}, 1.{{.*}}, 1.{{.*}}, 1.{{.*}}] {{.*}} {{.*}}

llvm/trunk/test/tools/llvm-xray/X86/account-keep-going.yaml

+#RUN: llvm-xray account %s -o - -m %S/Inputs/simple-instrmap.yaml -t yaml -k | FileCheck %s
+---
+header:
+  version: 1
+  type: 0
+  constant-tsc: true
+  nonstop-tsc: true
+  cycle-frequency: 0
+records:
+# We want to test the case for when we see spurious exits, but keep going
+# anyway ignoring the records in the process.
+  - { type: 0, func-id: 1, cpu: 1, thread: 111, kind: function-enter, tsc: 10000 }
+  - { type: 0, func-id: 2, cpu: 1, thread: 111, kind: function-enter, tsc: 10001 }
+  - { type: 0, func-id: 3, cpu: 1, thread: 111, kind: function-enter, tsc: 10002 }
+  - { type: 0, func-id: 3, cpu: 1, thread: 111, kind: function-exit,  tsc: 10003 }
+  - { type: 0, func-id: 1, cpu: 1, thread: 111, kind: function-exit,  tsc: 10004 }
+...
+#CHECK:       Functions with latencies: 1
+#CHECK-NEXT:  funcid  count  [ min, med, 90p, 99p, max] sum function
+#CHECK-NEXT:  3 1 [ 1.{{.*}}, 1.{{.*}}, 1.{{.*}}, 1.{{.*}}, 1.{{.*}}] {{.*}} {{.*}}

llvm/trunk/test/tools/llvm-xray/X86/account-simple-case.yaml

+#RUN: llvm-xray account %s -o - -m %S/Inputs/simple-instrmap.yaml -t yaml | FileCheck %s
+---
+header:
+  version: 1
+  type: 0
+  constant-tsc: true
+  nonstop-tsc: true
+  cycle-frequency: 2601000000
+records:
+  - { type: 0, func-id: 1, cpu: 1, thread: 111, kind: function-enter,
+    tsc: 10001 }
+  - { type: 0, func-id: 1, cpu: 1, thread: 111, kind: function-exit,
+    tsc: 10100 }
+...
+
+#CHECK:       Functions with latencies: 1
+#CHECK-NEXT:  funcid  count  [ min, med, 90p, 99p, max] sum function
+#CHECK-NEXT:  1 1 [ {{.*}}, {{.*}}, {{.*}}, {{.*}}, {{.*}}] {{.*}} {{.*}}

llvm/trunk/test/tools/llvm-xray/X86/account-simple-sorting.yaml

+#RUN: llvm-xray account %s -o - -m %S/Inputs/simple-instrmap.yaml -t yaml | FileCheck --check-prefix DEFAULT %s
+#RUN: llvm-xray account %s -o - -m %S/Inputs/simple-instrmap.yaml -t yaml -s count | FileCheck --check-prefix COUNT-ASC %s
+#RUN: llvm-xray account %s -o - -m %S/Inputs/simple-instrmap.yaml -t yaml -s min | FileCheck --check-prefix MIN-ASC %s
+#RUN: llvm-xray account %s -o - -m %S/Inputs/simple-instrmap.yaml -t yaml -s max | FileCheck --check-prefix MAX-ASC %s
+#RUN: llvm-xray account %s -o - -m %S/Inputs/simple-instrmap.yaml -t yaml -s sum | FileCheck --check-prefix SUM-ASC %s
+
+#RUN: llvm-xray account %s -o - -m %S/Inputs/simple-instrmap.yaml -t yaml -s count -r dsc | FileCheck --check-prefix COUNT-DSC %s
+#RUN: llvm-xray account %s -o - -m %S/Inputs/simple-instrmap.yaml -t yaml -s min -r dsc | FileCheck --check-prefix MIN-DSC %s
+#RUN: llvm-xray account %s -o - -m %S/Inputs/simple-instrmap.yaml -t yaml -s max -r dsc | FileCheck --check-prefix MAX-DSC %s
+#RUN: llvm-xray account %s -o - -m %S/Inputs/simple-instrmap.yaml -t yaml -s sum -r dsc | FileCheck --check-prefix SUM-DSC %s
+---
+header:
+  version: 1
+  type: 0
+  constant-tsc: true
+  nonstop-tsc: true
+  cycle-frequency: 1
+records:
+  # Function id: 1
+  - { type: 0, func-id: 1, cpu: 1, thread: 111, kind: function-enter,
+    tsc: 10001 }
+  - { type: 0, func-id: 1, cpu: 1, thread: 111, kind: function-exit,
+    tsc: 10100 }
+  - { type: 0, func-id: 1, cpu: 1, thread: 111, kind: function-enter,
+    tsc: 10101 }
+  - { type: 0, func-id: 1, cpu: 1, thread: 111, kind: function-exit,
+    tsc: 10200 }
+  - { type: 0, func-id: 1, cpu: 1, thread: 111, kind: function-enter,
+    tsc: 10201 }
+  - { type: 0, func-id: 1, cpu: 1, thread: 111, kind: function-exit,
+    tsc: 10300 }
+  # Function id: 2
+  - { type: 0, func-id: 2, cpu: 1, thread: 222, kind: function-enter,
+    tsc: 10001 }
+  - { type: 0, func-id: 2, cpu: 1, thread: 222, kind: function-exit,
+    tsc: 10002 }
+  - { type: 0, func-id: 2, cpu: 1, thread: 222, kind: function-enter,
+    tsc: 10101 }
+  - { type: 0, func-id: 2, cpu: 1, thread: 222, kind: function-exit,
+    tsc: 10102 }
+
+#DEFAULT:       Functions with latencies: 2
+#DEFAULT-NEXT:  funcid  count  [ min, med, 90p, 99p, max] sum function
+#DEFAULT-NEXT:  1 3 [{{.*}}, {{.*}}, {{.*}}, {{.*}}, {{.*}}] {{.*}} {{.*}}
+#DEFAULT-NEXT:  2 2 [{{.*}}, {{.*}}, {{.*}}, {{.*}}, {{.*}}] {{.*}} {{.*}}
+
+#COUNT-ASC:       Functions with latencies: 2
+#COUNT-ASC-NEXT:  funcid  count  [ min, med, 90p, 99p, max] sum function
+#COUNT-ASC-NEXT:  2 2 [{{.*}}, {{.*}}, {{.*}}, {{.*}}, {{.*}}] {{.*}} {{.*}}
+#COUNT-ASC-NEXT:  1 3 [{{.*}}, {{.*}}, {{.*}}, {{.*}}, {{.*}}] {{.*}} {{.*}}
+
+#COUNT-DSC:       Functions with latencies: 2
+#COUNT-DSC-NEXT:  funcid  count  [ min, med, 90p, 99p, max] sum function
+#COUNT-DSC-NEXT:  1 3 [{{.*}}, {{.*}}, {{.*}}, {{.*}}, {{.*}}] {{.*}} {{.*}}
+#COUNT-DSC-NEXT:  2 2 [{{.*}}, {{.*}}, {{.*}}, {{.*}}, {{.*}}] {{.*}} {{.*}}
+
+#MIN-ASC:       Functions with latencies: 2
+#MIN-ASC-NEXT:  funcid  count  [ min, med, 90p, 99p, max] sum function
+#MIN-ASC-NEXT:  2 2 [{{.*}}, {{.*}}, {{.*}}, {{.*}}, {{.*}}] {{.*}} {{.*}}
+#MIN-ASC-NEXT:  1 3 [{{.*}}, {{.*}}, {{.*}}, {{.*}}, {{.*}}] {{.*}} {{.*}}
+
+#MIN-DSC:       Functions with latencies: 2
+#MIN-DSC-NEXT:  funcid  count  [ min, med, 90p, 99p, max] sum function
+#MIN-DSC-NEXT:  1 3 [{{.*}}, {{.*}}, {{.*}}, {{.*}}, {{.*}}] {{.*}} {{.*}}
+#MIN-DSC-NEXT:  2 2 [{{.*}}, {{.*}}, {{.*}}, {{.*}}, {{.*}}] {{.*}} {{.*}}
+
+#MAX-ASC:       Functions with latencies: 2
+#MAX-ASC-NEXT:  funcid  count  [ min, med, 90p, 99p, max] sum function
+#MAX-ASC-NEXT:  2 2 [{{.*}}, {{.*}}, {{.*}}, {{.*}}, {{.*}}] {{.*}} {{.*}}
+#MAX-ASC-NEXT:  1 3 [{{.*}}, {{.*}}, {{.*}}, {{.*}}, {{.*}}] {{.*}} {{.*}}
+
+#MAX-DSC:       Functions with latencies: 2
+#MAX-DSC-NEXT:  funcid  count  [ min, med, 90p, 99p, max] sum function
+#MAX-DSC-NEXT:  1 3 [{{.*}}, {{.*}}, {{.*}}, {{.*}}, {{.*}}] {{.*}} {{.*}}
+#MAX-DSC-NEXT:  2 2 [{{.*}}, {{.*}}, {{.*}}, {{.*}}, {{.*}}] {{.*}} {{.*}}
+
+#SUM-ASC:       Functions with latencies: 2
+#SUM-ASC-NEXT:  funcid  count  [ min, med, 90p, 99p, max] sum function
+#SUM-ASC-NEXT:  2 2 [{{.*}}, {{.*}}, {{.*}}, {{.*}}, {{.*}}] {{.*}} {{.*}}
+#SUM-ASC-NEXT:  1 3 [{{.*}}, {{.*}}, {{.*}}, {{.*}}, {{.*}}] {{.*}} {{.*}}
+
+#SUM-DSC:       Functions with latencies: 2
+#SUM-DSC-NEXT:  funcid  count  [ min, med, 90p, 99p, max] sum function
+#SUM-DSC-NEXT:  1 3 [{{.*}}, {{.*}}, {{.*}}, {{.*}}, {{.*}}] {{.*}} {{.*}}
+#SUM-DSC-NEXT:  2 2 [{{.*}}, {{.*}}, {{.*}}, {{.*}}, {{.*}}] {{.*}} {{.*}}

llvm/trunk/tools/llvm-xray/CMakeLists.txt

 set(LLVM_LINK_COMPONENTS
   ${LLVM_TARGETS_TO_BUILD}
   DebugInfoDWARF
   Object
   Support
   Symbolize
   XRay)
 
 set(LLVM_XRAY_TOOLS
   func-id-helper.cc
+  xray-account.cc
   xray-converter.cc
   xray-extract.cc
   xray-extract.cc
   xray-registry.cc)
 
 add_llvm_tool(llvm-xray llvm-xray.cc ${LLVM_XRAY_TOOLS})

llvm/trunk/tools/llvm-xray/xray-account.h

+//===- xray-account.h - XRay Function Call Accounting ---------------------===//
+//
+//                     The LLVM Compiler Infrastructure
+//
+// This file is distributed under the University of Illinois Open Source
+// License. See LICENSE.TXT for details.
+//
+//===----------------------------------------------------------------------===//
+//
+// This file defines the interface for performing some basic function call
+// accounting from an XRay trace.
+//
+//===----------------------------------------------------------------------===//
+#ifndef LLVM_TOOLS_LLVM_XRAY_XRAY_ACCOUNT_H
+#define LLVM_TOOLS_LLVM_XRAY_XRAY_ACCOUNT_H
+
+#include <map>
+#include <utility>
+#include <vector>
+
+#include "func-id-helper.h"
+#include "llvm/Support/raw_ostream.h"
+#include "llvm/XRay/XRayRecord.h"
+
+namespace llvm {
+namespace xray {
+
+class LatencyAccountant {
+public:
+  typedef std::map<int32_t, std::vector<uint64_t>> FunctionLatencyMap;
+  typedef std::map<pid_t, std::pair<uint64_t, uint64_t>> PerThreadMinMaxTSCMap;
+  typedef std::map<uint8_t, std::pair<uint64_t, uint64_t>> PerCPUMinMaxTSCMap;
+  typedef std::vector<std::pair<int32_t, uint64_t>> FunctionStack;
+  typedef std::map<pid_t, FunctionStack> PerThreadFunctionStackMap;
+
+private:
+  PerThreadFunctionStackMap PerThreadFunctionStack;
+  FunctionLatencyMap FunctionLatencies;
+  PerThreadMinMaxTSCMap PerThreadMinMaxTSC;
+  PerCPUMinMaxTSCMap PerCPUMinMaxTSC;
+  FuncIdConversionHelper &FuncIdHelper;
+
+  bool DeduceSiblingCalls = false;
+  uint64_t CurrentMaxTSC = 0;
+
+  void recordLatency(int32_t FuncId, uint64_t Latency) {
+    FunctionLatencies[FuncId].push_back(Latency);
+  }
+
+public:
+  explicit LatencyAccountant(FuncIdConversionHelper &FuncIdHelper,
+                             bool DeduceSiblingCalls)
+      : FuncIdHelper(FuncIdHelper), DeduceSiblingCalls(DeduceSiblingCalls) {}
+
+  const FunctionLatencyMap &getFunctionLatencies() const {
+    return FunctionLatencies;
+  }
+
+  const PerThreadMinMaxTSCMap &getPerThreadMinMaxTSC() const {
+    return PerThreadMinMaxTSC;
+  }
+
+  const PerCPUMinMaxTSCMap &getPerCPUMinMaxTSC() const {
+    return PerCPUMinMaxTSC;
+  }
+
+  /// Returns false in case we fail to account the provided record. This happens
+  /// in the following cases:
+  ///
+  ///   - An exit record does not match any entry records for the same function.
+  ///     If we've been set to deduce sibling calls, we try walking up the stack
+  ///     and recording times for the higher level functions.
+  ///   - A record has a TSC that's before the latest TSC that has been
+  ///     recorded. We still record the TSC for the min-max.
+  ///
+  bool accountRecord(const XRayRecord &Record);
+
+  const FunctionStack *getThreadFunctionStack(pid_t TId) const {
+    auto I = PerThreadFunctionStack.find(TId);
+    if (I == PerThreadFunctionStack.end())
+      return nullptr;
+    return &I->second;
+  }
+
+  const PerThreadFunctionStackMap &getPerThreadFunctionStack() const {
+    return PerThreadFunctionStack;
+  }
+
+  // Output Functions
+  // ================
+
+  void exportStatsAsText(raw_ostream &OS, const XRayFileHeader &Header) const;
+  void exportStatsAsCSV(raw_ostream &OS, const XRayFileHeader &Header) const;
+
+private:
+  // Internal helper to implement common parts of the exportStatsAs...
+  // functions.
+  template <class F> void exportStats(const XRayFileHeader &Header, F fn) const;
+};
+
+} // namespace xray
+} // namespace llvm
+
+#endif // LLVM_TOOLS_LLVM_XRAY_XRAY_ACCOUNT_H

llvm/trunk/tools/llvm-xray/xray-account.cc

+//===- xray-account.h - XRay Function Call Accounting ---------------------===//
+//
+//                     The LLVM Compiler Infrastructure
+//
+// This file is distributed under the University of Illinois Open Source
+// License. See LICENSE.TXT for details.
+//
+//===----------------------------------------------------------------------===//
+//
+// This file implements basic function call accounting from an XRay trace.
+//
+//===----------------------------------------------------------------------===//
+
+#include <algorithm>
+#include <cassert>
+#include <system_error>
+#include <utility>
+
+#include "xray-account.h"
+#include "xray-extract.h"
+#include "xray-registry.h"
+#include "llvm/Support/ErrorHandling.h"
+#include "llvm/Support/FormatVariadic.h"
+#include "llvm/XRay/Trace.h"
+
+using namespace llvm;
+using namespace llvm::xray;
+
+static cl::SubCommand Account("account", "Function call accounting");
+static cl::opt<std::string> AccountInput(cl::Positional,
+                                         cl::desc("<xray log file>"),
+                                         cl::Required, cl::sub(Account));
+static cl::opt<bool>
+    AccountKeepGoing("keep-going", cl::desc("Keep going on errors encountered"),
+                     cl::sub(Account), cl::init(false));
+static cl::alias AccountKeepGoing2("k", cl::aliasopt(AccountKeepGoing),
+                                   cl::desc("Alias for -keep_going"),
+                                   cl::sub(Account));
+static cl::opt<bool> AccountDeduceSiblingCalls(
+    "deduce-sibling-calls",
+    cl::desc("Deduce sibling calls when unrolling function call stacks"),
+    cl::sub(Account), cl::init(false));
+static cl::alias
+    AccountDeduceSiblingCalls2("d", cl::aliasopt(AccountDeduceSiblingCalls),
+                               cl::desc("Alias for -deduce_sibling_calls"),
+                               cl::sub(Account));
+static cl::opt<std::string>
+    AccountOutput("output", cl::value_desc("output file"), cl::init("-"),
+                  cl::desc("output file; use '-' for stdout"),
+                  cl::sub(Account));
+static cl::alias AccountOutput2("o", cl::aliasopt(AccountOutput),
+                                cl::desc("Alias for -output"),
+                                cl::sub(Account));
+enum class AccountOutputFormats { TEXT, CSV };
+static cl::opt<AccountOutputFormats>
+    AccountOutputFormat("format", cl::desc("output format"),
+                        cl::values(clEnumValN(AccountOutputFormats::TEXT,
+                                              "text", "report stats in text"),
+                                   clEnumValN(AccountOutputFormats::CSV, "csv",
+                                              "report stats in csv")),
+                        cl::sub(Account));
+static cl::alias AccountOutputFormat2("f", cl::desc("Alias of -format"),
+                                      cl::aliasopt(AccountOutputFormat),
+                                      cl::sub(Account));
+
+enum class SortField {
+  FUNCID,
+  COUNT,
+  MIN,
+  MED,
+  PCT90,
+  PCT99,
+  MAX,
+  SUM,
+  FUNC,
+};
+
+static cl::opt<SortField> AccountSortOutput(
+    "sort", cl::desc("sort output by this field"), cl::value_desc("field"),
+    cl::sub(Account), cl::init(SortField::FUNCID),
+    cl::values(clEnumValN(SortField::FUNCID, "funcid", "function id"),
+               clEnumValN(SortField::COUNT, "count", "funciton call counts"),
+               clEnumValN(SortField::MIN, "min", "minimum function durations"),
+               clEnumValN(SortField::MED, "med", "median function durations"),
+               clEnumValN(SortField::PCT90, "90p", "90th percentile durations"),
+               clEnumValN(SortField::PCT99, "99p", "99th percentile durations"),
+               clEnumValN(SortField::MAX, "max", "maximum function durations"),
+               clEnumValN(SortField::SUM, "sum", "sum of call durations"),
+               clEnumValN(SortField::FUNC, "func", "function names")));
+static cl::alias AccountSortOutput2("s", cl::aliasopt(AccountSortOutput),
+                                    cl::desc("Alias for -sort"),
+                                    cl::sub(Account));
+
+enum class SortDirection {
+  ASCENDING,
+  DESCENDING,
+};
+static cl::opt<SortDirection> AccountSortOrder(
+    "sortorder", cl::desc("sort ordering"), cl::init(SortDirection::ASCENDING),
+    cl::values(clEnumValN(SortDirection::ASCENDING, "asc", "ascending"),
+               clEnumValN(SortDirection::DESCENDING, "dsc", "descending")),
+    cl::sub(Account));
+static cl::alias AccountSortOrder2("r", cl::aliasopt(AccountSortOrder),
+                                   cl::desc("Alias for -sortorder"),
+                                   cl::sub(Account));
+
+static cl::opt<int> AccountTop("top", cl::desc("only show the top N results"),
+                               cl::value_desc("N"), cl::sub(Account),
+                               cl::init(-1));
+static cl::alias AccountTop2("p", cl::desc("Alias for -top"),
+                             cl::aliasopt(AccountTop), cl::sub(Account));
+
+static cl::opt<std::string>
+    AccountInstrMap("instr_map",
+                    cl::desc("binary with the instrumentation map, or "
+                             "a separate instrumentation map"),
+                    cl::value_desc("binary with xray_instr_map"),
+                    cl::sub(Account), cl::init(""));
+static cl::alias AccountInstrMap2("m", cl::aliasopt(AccountInstrMap),
+                                  cl::desc("Alias for -instr_map"),
+                                  cl::sub(Account));
+static cl::opt<InstrumentationMapExtractor::InputFormats> InstrMapFormat(
+    "instr-map-format", cl::desc("format of instrumentation map"),
+    cl::values(clEnumValN(InstrumentationMapExtractor::InputFormats::ELF, "elf",
+                          "instrumentation map in an ELF header"),
+               clEnumValN(InstrumentationMapExtractor::InputFormats::YAML,
+                          "yaml", "instrumentation map in YAML")),
+    cl::sub(Account), cl::init(InstrumentationMapExtractor::InputFormats::ELF));
+static cl::alias InstrMapFormat2("t", cl::aliasopt(InstrMapFormat),
+                                 cl::desc("Alias for -instr-map-format"),
+                                 cl::sub(Account));
+
+namespace {
+
+template <class T, class U> void setMinMax(std::pair<T, T> &MM, U &&V) {
+  if (MM.first == 0 || MM.second == 0)
+    MM = std::make_pair(std::forward<U>(V), std::forward<U>(V));
+  else
+    MM = std::make_pair(std::min(MM.first, V), std::max(MM.second, V));
+}
+
+template <class T> T diff(T L, T R) { return std::max(L, R) - std::min(L, R); }
+
+} // namespace
+
+bool LatencyAccountant::accountRecord(const XRayRecord &Record) {
+  setMinMax(PerThreadMinMaxTSC[Record.TId], Record.TSC);
+  setMinMax(PerCPUMinMaxTSC[Record.CPU], Record.TSC);
+
+  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.back().first == Record.FuncId) {
+      const auto &Top = ThreadStack.back();
+      recordLatency(Top.first, diff(Top.second, Record.TSC));
+      ThreadStack.pop_back();
+      break;
+    }
+
+    if (!DeduceSiblingCalls)
+      return false;
+
+    // Look for the parent up the stack.
+    auto Parent =
+        std::find_if(ThreadStack.rbegin(), ThreadStack.rend(),
+                     [&](const std::pair<const int32_t, uint64_t> &E) {
+                       return E.first == Record.FuncId;
+                     });
+    if (Parent == ThreadStack.rend())
+      return false;
+
+    // Account time for this apparently sibling call exit up the stack.
+    // Considering the following case:
+    //
+    //   f()
+    //    g()
+    //      h()
+    //
+    // We might only ever see the following entries:
+    //
+    //   -> f()
+    //   -> g()
+    //   -> h()
+    //   <- h()
+    //   <- f()
+    //
+    // Now we don't see the exit to g() because some older version of the XRay
+    // runtime wasn't instrumenting tail exits. If we don't deduce tail calls,
+    // we may potentially never account time for g() -- and this code would have
+    // already bailed out, because `<- f()` doesn't match the current "top" of
+    // stack where we're waiting for the exit to `g()` instead. This is not
+    // ideal and brittle -- so instead we provide a potentially inaccurate
+    // accounting of g() instead, computing it from the exit of f().
+    //
+    // While it might be better that we account the time between `-> g()` and
+    // `-> h()` as the proper accounting of time for g() here, this introduces
+    // complexity to do correctly (need to backtrack, etc.).
+    //
+    // FIXME: Potentially implement the more complex deduction algorithm?
+    auto I = std::next(Parent).base();
+    for (auto &E : make_range(I, ThreadStack.end())) {
+      recordLatency(E.first, diff(E.second, Record.TSC));
+    }
+    ThreadStack.erase(I, ThreadStack.end());
+    break;
+  }
+  }
+
+  return true;
+}
+
+namespace {
+
+// We consolidate the data into a struct which we can output in various forms.
+struct ResultRow {
+  uint64_t Count;
+  double Min;
+  double Median;
+  double Pct90;
+  double Pct99;
+  double Max;
+  double Sum;
+  std::string DebugInfo;
+  std::string Function;
+};
+
+ResultRow getStats(std::vector<uint64_t> &Timings) {
+  assert(!Timings.empty());
+  ResultRow R;
+  R.Sum = std::accumulate(Timings.begin(), Timings.end(), 0.0);
+  auto MinMax = std::minmax_element(Timings.begin(), Timings.end());
+  R.Min = *MinMax.first;
+  R.Max = *MinMax.second;
+  auto MedianOff = Timings.size() / 2;
+  std::nth_element(Timings.begin(), Timings.begin() + MedianOff, Timings.end());
+  R.Median = Timings[MedianOff];
+  auto Pct90Off = std::floor(Timings.size() * 0.9);
+  std::nth_element(Timings.begin(), Timings.begin() + Pct90Off, Timings.end());
+  R.Pct90 = Timings[Pct90Off];
+  auto Pct99Off = std::floor(Timings.size() * 0.99);
+  std::nth_element(Timings.begin(), Timings.begin() + Pct90Off, Timings.end());
+  R.Pct99 = Timings[Pct99Off];
+  R.Count = Timings.size();
+  return R;
+}
+
+} // namespace
+
+template <class F>
+void LatencyAccountant::exportStats(const XRayFileHeader &Header, F Fn) const {
+  using TupleType = std::tuple<int32_t, uint64_t, ResultRow>;
+  std::vector<TupleType> Results;
+  Results.reserve(FunctionLatencies.size());
+  for (auto FT : FunctionLatencies) {
+    const auto &FuncId = FT.first;
+    auto &Timings = FT.second;
+    Results.emplace_back(FuncId, Timings.size(), getStats(Timings));
+    auto &Row = std::get<2>(Results.back());
+    if (Header.CycleFrequency) {
+      double CycleFrequency = Header.CycleFrequency;
+      Row.Min /= CycleFrequency;
+      Row.Median /= CycleFrequency;
+      Row.Pct90 /= CycleFrequency;
+      Row.Pct99 /= CycleFrequency;
+      Row.Max /= CycleFrequency;
+      Row.Sum /= CycleFrequency;
+    }
+
+    Row.Function = FuncIdHelper.SymbolOrNumber(FuncId);
+    Row.DebugInfo = FuncIdHelper.FileLineAndColumn(FuncId);
+  }
+
+  // Sort the data according to user-provided flags.
+  switch (AccountSortOutput) {
+  case SortField::FUNCID:
+    std::sort(Results.begin(), Results.end(),
+              [](const TupleType &L, const TupleType &R) {
+                if (AccountSortOrder == SortDirection::ASCENDING)
+                  return std::get<0>(L) < std::get<0>(R);
+                if (AccountSortOrder == SortDirection::DESCENDING)
+                  return std::get<0>(L) > std::get<0>(R);
+                llvm_unreachable("Unknown sort direction");
+              });
+    break;
+  case SortField::COUNT:
+    std::sort(Results.begin(), Results.end(),
+              [](const TupleType &L, const TupleType &R) {
+                if (AccountSortOrder == SortDirection::ASCENDING)
+                  return std::get<1>(L) < std::get<1>(R);
+                if (AccountSortOrder == SortDirection::DESCENDING)
+                  return std::get<1>(L) > std::get<1>(R);
+                llvm_unreachable("Unknown sort direction");
+              });
+    break;
+  default:
+    // Here we need to look into the ResultRow for the rest of the data that
+    // we want to sort by.
+    std::sort(Results.begin(), Results.end(),
+              [&](const TupleType &L, const TupleType &R) {
+                auto &LR = std::get<2>(L);
+                auto &RR = std::get<2>(R);
+                switch (AccountSortOutput) {
+                case SortField::COUNT:
+                  if (AccountSortOrder == SortDirection::ASCENDING)
+                    return LR.Count < RR.Count;
+                  if (AccountSortOrder == SortDirection::DESCENDING)
+                    return LR.Count > RR.Count;
+                  llvm_unreachable("Unknown sort direction");
+                case SortField::MIN:
+                  if (AccountSortOrder == SortDirection::ASCENDING)
+                    return LR.Min < RR.Min;
+                  if (AccountSortOrder == SortDirection::DESCENDING)
+                    return LR.Min > RR.Min;
+                  llvm_unreachable("Unknown sort direction");
+                case SortField::MED:
+                  if (AccountSortOrder == SortDirection::ASCENDING)
+                    return LR.Median < RR.Median;
+                  if (AccountSortOrder == SortDirection::DESCENDING)
+                    return LR.Median > RR.Median;
+                  llvm_unreachable("Unknown sort direction");
+                case SortField::PCT90:
+                  if (AccountSortOrder == SortDirection::ASCENDING)
+                    return LR.Pct90 < RR.Pct90;
+                  if (AccountSortOrder == SortDirection::DESCENDING)
+                    return LR.Pct90 > RR.Pct90;
+                  llvm_unreachable("Unknown sort direction");
+                case SortField::PCT99:
+                  if (AccountSortOrder == SortDirection::ASCENDING)
+                    return LR.Pct99 < RR.Pct99;
+                  if (AccountSortOrder == SortDirection::DESCENDING)
+                    return LR.Pct99 > RR.Pct99;
+                  llvm_unreachable("Unknown sort direction");
+                case SortField::MAX:
+                  if (AccountSortOrder == SortDirection::ASCENDING)
+                    return LR.Max < RR.Max;
+                  if (AccountSortOrder == SortDirection::DESCENDING)
+                    return LR.Max > RR.Max;
+                  llvm_unreachable("Unknown sort direction");
+                case SortField::SUM:
+                  if (AccountSortOrder == SortDirection::ASCENDING)
+                    return LR.Sum < RR.Sum;
+                  if (AccountSortOrder == SortDirection::DESCENDING)
+                    return LR.Sum > RR.Sum;
+                  llvm_unreachable("Unknown sort direction");
+                default:
+                  llvm_unreachable("Unsupported sort order");
+                }
+              });
+    break;
+  }
+
+  if (AccountTop > 0)
+    Results.erase(Results.begin() + AccountTop.getValue(), Results.end());
+
+  for (const auto &R : Results)
+    Fn(std::get<0>(R), std::get<1>(R), std::get<2>(R));
+}
+
+void LatencyAccountant::exportStatsAsText(raw_ostream &OS,
+                                          const XRayFileHeader &Header) const {
+  OS << "Functions with latencies: " << FunctionLatencies.size() << "\n";
+
+  // We spend some effort to make the text output more readable, so we do the
+  // following formatting decisions for each of the fields:
+  //
+  //   - funcid: 32-bit, but we can determine the largest number and be
+  //   between
+  //     a minimum of 5 characters, up to 9 characters, right aligned.
+  //   - count:  64-bit, but we can determine the largest number and be
+  //   between
+  //     a minimum of 5 characters, up to 9 characters, right aligned.
+  //   - min, median, 90pct, 99pct, max: double precision, but we want to keep
+  //     the values in seconds, with microsecond precision (0.000'001), so we
+  //     have at most 6 significant digits, with the whole number part to be
+  //     at
+  //     least 1 character. For readability we'll right-align, with full 9
+  //     characters each.
+  //   - debug info, function name: we format this as a concatenation of the
+  //     debug info and the function name.
+  //
+  static constexpr char StatsHeaderFormat[] =
+      "{0,+9} {1,+10} [{2,+9}, {3,+9}, {4,+9}, {5,+9}, {6,+9}] {7,+9}";
+  static constexpr char StatsFormat[] =
+      R"({0,+9} {1,+10} [{2,+9:f6}, {3,+9:f6}, {4,+9:f6}, {5,+9:f6}, {6,+9:f6}] {7,+9:f6})";
+  OS << llvm::formatv(StatsHeaderFormat, "funcid", "count", "min", "med", "90p",
+                      "99p", "max", "sum")
+     << llvm::formatv("  {0,-12}\n", "function");
+  exportStats(Header, [&](int32_t FuncId, size_t Count, const ResultRow &Row) {
+    OS << llvm::formatv(StatsFormat, FuncId, Count, Row.Min, Row.Median,
+                        Row.Pct90, Row.Pct99, Row.Max, Row.Sum)
+       << "  " << Row.DebugInfo << ": " << Row.Function << "\n";
+  });
+}
+
+void LatencyAccountant::exportStatsAsCSV(raw_ostream &OS,
+                                         const XRayFileHeader &Header) const {
+  OS << "funcid,count,min,median,90%ile,99%ile,max,sum,debug,function\n";
+  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;
+
+static CommandRegistration Unused(&Account, []() -> Error {
+  int Fd;
+  auto EC = sys::fs::openFileForRead(AccountInput, Fd);
+  if (EC)
+    return make_error<StringError>(
+        Twine("Cannot open file '") + AccountInput + "'", EC);
+
+  Error Err = Error::success();
+  xray::InstrumentationMapExtractor Extractor(AccountInstrMap, InstrMapFormat,
+                                              Err);
+  if (auto E = handleErrors(
+          std::move(Err), [&](std::unique_ptr<StringError> E) -> Error {
+            if (E->convertToErrorCode() == std::errc::no_such_file_or_directory)
+              return Error::success();
+            return Error(std::move(E));
+          }))
+    return E;
+
+  raw_fd_ostream OS(AccountOutput, EC, sys::fs::OpenFlags::F_Text);
+  if (EC)
+    return make_error<StringError>(
+        Twine("Cannot open file '") + AccountOutput + "' for writing.", EC);
+
+  const auto &FunctionAddresses = Extractor.getFunctionAddresses();
+  symbolize::LLVMSymbolizer::Options Opts(
+      symbolize::FunctionNameKind::LinkageName, true, true, false, "");
+  symbolize::LLVMSymbolizer Symbolizer(Opts);
+  llvm::xray::FuncIdConversionHelper FuncIdHelper(AccountInstrMap, Symbolizer,
+                                                  FunctionAddresses);
+  xray::LatencyAccountant FCA(FuncIdHelper, AccountDeduceSiblingCalls);
+  if (auto TraceOrErr = loadTraceFile(AccountInput)) {
+    auto &T = *TraceOrErr;
+    for (const auto &Record : T) {
+      if (FCA.accountRecord(Record))
+        continue;
+      for (const auto &ThreadStack : FCA.getPerThreadFunctionStack()) {
+        errs() << "Thread ID: " << ThreadStack.first << "\n";
+        auto Level = ThreadStack.second.size();
+        for (const auto &Entry : llvm::reverse(ThreadStack.second))
+          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::bad_message));
+    }
+    switch (AccountOutputFormat) {
+    case AccountOutputFormats::TEXT:
+      FCA.exportStatsAsText(OS, T.getFileHeader());
+      break;
+    case AccountOutputFormats::CSV:
+      FCA.exportStatsAsCSV(OS, T.getFileHeader());
+      break;
+    }
+  } else {
+    return joinErrors(
+        make_error<StringError>(
+            Twine("Failed loading input file '") + AccountInput + "'",
+            std::make_error_code(std::errc::protocol_error)),
+        TraceOrErr.takeError());
+  }
+
+  return Error::success();
+});

llvm/trunk/tools/llvm-xray/xray-record-yaml.h

+//===- xray-record-yaml.h - XRay Record YAML Support Definitions ----------===//
+//
+//                     The LLVM Compiler Infrastructure
+//
+// This file is distributed under the University of Illinois Open Source
+// License. See LICENSE.TXT for details.
+//
+//===----------------------------------------------------------------------===//
+//
+// Types and traits specialisations for YAML I/O of XRay log entries.
+//
+//===----------------------------------------------------------------------===//
+#ifndef LLVM_TOOLS_LLVM_XRAY_XRAY_RECORD_YAML_H
+#define LLVM_TOOLS_LLVM_XRAY_XRAY_RECORD_YAML_H
+
+#include <type_traits>
+
+#include "xray-record.h"
+#include "llvm/Support/YAMLTraits.h"
+
+namespace llvm {
+namespace xray {
+
+struct YAMLXRayFileHeader {
+  uint16_t Version;
+  uint16_t Type;
+  bool ConstantTSC;
+  bool NonstopTSC;
+  uint64_t CycleFrequency;
+};
+
+struct YAMLXRayRecord {
+  uint16_t RecordType;
+  uint8_t CPU;
+  RecordTypes Type;
+  int32_t FuncId;
+  std::string Function;
+  uint64_t TSC;
+  uint32_t TId;
+};
+
+struct YAMLXRayTrace {
+  YAMLXRayFileHeader Header;
+  std::vector<YAMLXRayRecord> Records;
+};
+
+using XRayRecordStorage =
+    std::aligned_storage<sizeof(XRayRecord), alignof(XRayRecord)>::type;
+
+} // namespace xray
+
+namespace yaml {
+
+// YAML Traits
+// -----------
+template <> struct ScalarEnumerationTraits<xray::RecordTypes> {
+  static void enumeration(IO &IO, xray::RecordTypes &Type) {
+    IO.enumCase(Type, "function-enter", xray::RecordTypes::ENTER);
+    IO.enumCase(Type, "function-exit", xray::RecordTypes::EXIT);
+  }
+};
+
+template <> struct MappingTraits<xray::YAMLXRayFileHeader> {
+  static void mapping(IO &IO, xray::YAMLXRayFileHeader &Header) {
+    IO.mapRequired("version", Header.Version);
+    IO.mapRequired("type", Header.Type);
+    IO.mapRequired("constant-tsc", Header.ConstantTSC);
+    IO.mapRequired("nonstop-tsc", Header.NonstopTSC);
+    IO.mapRequired("cycle-frequency", Header.CycleFrequency);
+  }
+};
+
+template <> struct MappingTraits<xray::YAMLXRayRecord> {
+  static void mapping(IO &IO, xray::YAMLXRayRecord &Record) {
+    // FIXME: Make this type actually be descriptive
+    IO.mapRequired("type", Record.RecordType);
+    IO.mapRequired("func-id", Record.FuncId);
+    IO.mapOptional("function", Record.Function);
+    IO.mapRequired("cpu", Record.CPU);
+    IO.mapRequired("thread", Record.TId);
+    IO.mapRequired("kind", Record.Type);
+    IO.mapRequired("tsc", Record.TSC);
+  }
+
+  static constexpr bool flow = true;
+};
+
+template <> struct MappingTraits<xray::YAMLXRayTrace> {
+  static void mapping(IO &IO, xray::YAMLXRayTrace &Trace) {
+    // A trace file contains two parts, the header and the list of all the
+    // trace records.
+    IO.mapRequired("header", Trace.Header);
+    IO.mapRequired("records", Trace.Records);
+  }
+};
+
+} // namespace yaml
+} // namespace llvm
+
+LLVM_YAML_IS_SEQUENCE_VECTOR(xray::YAMLXRayRecord) 
+
+#endif // LLVM_TOOLS_LLVM_XRAY_XRAY_RECORD_YAML_H