1//===- xray-account.h - XRay Function Call Accounting ---------------------===//
2//
3// Part of the LLVM Project, under the Apache License v2.0 with LLVM Exceptions.
4// See https://llvm.org/LICENSE.txt for license information.
5// SPDX-License-Identifier: Apache-2.0 WITH LLVM-exception
6//
7//===----------------------------------------------------------------------===//
8//
9// This file implements basic function call accounting from an XRay trace.
10//
11//===----------------------------------------------------------------------===//
12
13#include <algorithm>
14#include <cassert>
15#include <numeric>
16#include <system_error>
17#include <utility>
18
19#include "xray-account.h"
20#include "xray-registry.h"
21#include "llvm/Support/ErrorHandling.h"
22#include "llvm/Support/FormatVariadic.h"
23#include "llvm/XRay/InstrumentationMap.h"
24#include "llvm/XRay/Trace.h"
25
26#include <cmath>
27
28using namespace llvm;
29using namespace llvm::xray;
30
31static cl::SubCommand Account("account", "Function call accounting");
32static cl::opt<std::string> AccountInput(cl::Positional,
33                                         cl::desc("<xray log file>"),
34                                         cl::Required, cl::sub(Account));
35static cl::opt<bool>
36    AccountKeepGoing("keep-going", cl::desc("Keep going on errors encountered"),
37                     cl::sub(Account), cl::init(false));
38static cl::alias AccountKeepGoing2("k", cl::aliasopt(AccountKeepGoing),
39                                   cl::desc("Alias for -keep_going"));
40static cl::opt<bool> AccountRecursiveCallsOnly(
41    "recursive-calls-only", cl::desc("Only count the calls that are recursive"),
42    cl::sub(Account), cl::init(false));
43static cl::opt<bool> AccountDeduceSiblingCalls(
44    "deduce-sibling-calls",
45    cl::desc("Deduce sibling calls when unrolling function call stacks"),
46    cl::sub(Account), cl::init(false));
47static cl::alias
48    AccountDeduceSiblingCalls2("d", cl::aliasopt(AccountDeduceSiblingCalls),
49                               cl::desc("Alias for -deduce_sibling_calls"));
50static cl::opt<std::string>
51    AccountOutput("output", cl::value_desc("output file"), cl::init("-"),
52                  cl::desc("output file; use '-' for stdout"),
53                  cl::sub(Account));
54static cl::alias AccountOutput2("o", cl::aliasopt(AccountOutput),
55                                cl::desc("Alias for -output"));
56enum class AccountOutputFormats { TEXT, CSV };
57static cl::opt<AccountOutputFormats>
58    AccountOutputFormat("format", cl::desc("output format"),
59                        cl::values(clEnumValN(AccountOutputFormats::TEXT,
60                                              "text", "report stats in text"),
61                                   clEnumValN(AccountOutputFormats::CSV, "csv",
62                                              "report stats in csv")),
63                        cl::sub(Account));
64static cl::alias AccountOutputFormat2("f", cl::desc("Alias of -format"),
65                                      cl::aliasopt(AccountOutputFormat));
66
67enum class SortField {
68  FUNCID,
69  COUNT,
70  MIN,
71  MED,
72  PCT90,
73  PCT99,
74  MAX,
75  SUM,
76  FUNC,
77};
78
79static cl::opt<SortField> AccountSortOutput(
80    "sort", cl::desc("sort output by this field"), cl::value_desc("field"),
81    cl::sub(Account), cl::init(SortField::FUNCID),
82    cl::values(clEnumValN(SortField::FUNCID, "funcid", "function id"),
83               clEnumValN(SortField::COUNT, "count", "function call counts"),
84               clEnumValN(SortField::MIN, "min", "minimum function durations"),
85               clEnumValN(SortField::MED, "med", "median function durations"),
86               clEnumValN(SortField::PCT90, "90p", "90th percentile durations"),
87               clEnumValN(SortField::PCT99, "99p", "99th percentile durations"),
88               clEnumValN(SortField::MAX, "max", "maximum function durations"),
89               clEnumValN(SortField::SUM, "sum", "sum of call durations"),
90               clEnumValN(SortField::FUNC, "func", "function names")));
91static cl::alias AccountSortOutput2("s", cl::aliasopt(AccountSortOutput),
92                                    cl::desc("Alias for -sort"));
93
94enum class SortDirection {
95  ASCENDING,
96  DESCENDING,
97};
98static cl::opt<SortDirection> AccountSortOrder(
99    "sortorder", cl::desc("sort ordering"), cl::init(SortDirection::ASCENDING),
100    cl::values(clEnumValN(SortDirection::ASCENDING, "asc", "ascending"),
101               clEnumValN(SortDirection::DESCENDING, "dsc", "descending")),
102    cl::sub(Account));
103static cl::alias AccountSortOrder2("r", cl::aliasopt(AccountSortOrder),
104                                   cl::desc("Alias for -sortorder"));
105
106static cl::opt<int> AccountTop("top", cl::desc("only show the top N results"),
107                               cl::value_desc("N"), cl::sub(Account),
108                               cl::init(-1));
109static cl::alias AccountTop2("p", cl::desc("Alias for -top"),
110                             cl::aliasopt(AccountTop));
111
112static cl::opt<std::string>
113    AccountInstrMap("instr_map",
114                    cl::desc("binary with the instrumentation map, or "
115                             "a separate instrumentation map"),
116                    cl::value_desc("binary with xray_instr_map"),
117                    cl::sub(Account), cl::init(""));
118static cl::alias AccountInstrMap2("m", cl::aliasopt(AccountInstrMap),
119                                  cl::desc("Alias for -instr_map"));
120
121namespace {
122
123template <class T, class U> void setMinMax(std::pair<T, T> &MM, U &&V) {
124  if (MM.first == 0 || MM.second == 0)
125    MM = std::make_pair(std::forward<U>(V), std::forward<U>(V));
126  else
127    MM = std::make_pair(std::min(MM.first, V), std::max(MM.second, V));
128}
129
130template <class T> T diff(T L, T R) { return std::max(L, R) - std::min(L, R); }
131
132} // namespace
133
134using RecursionStatus = LatencyAccountant::FunctionStack::RecursionStatus;
135RecursionStatus &RecursionStatus::operator++() {
136  auto Depth = Bitfield::get<RecursionStatus::Depth>(Storage);
137  assert(Depth >= 0 && Depth < std::numeric_limits<decltype(Depth)>::max());
138  ++Depth;
139  Bitfield::set<RecursionStatus::Depth>(Storage, Depth); // ++Storage
140  // Did this function just (maybe indirectly) call itself the first time?
141  if (!isRecursive() && Depth == 2) // Storage == 2  /  Storage s> 1
142    Bitfield::set<RecursionStatus::IsRecursive>(Storage,
143                                                true); // Storage |= INT_MIN
144  return *this;
145}
146RecursionStatus &RecursionStatus::operator--() {
147  auto Depth = Bitfield::get<RecursionStatus::Depth>(Storage);
148  assert(Depth > 0);
149  --Depth;
150  Bitfield::set<RecursionStatus::Depth>(Storage, Depth); // --Storage
151  // Did we leave a function that previouly (maybe indirectly) called itself?
152  if (isRecursive() && Depth == 0) // Storage == INT_MIN
153    Bitfield::set<RecursionStatus::IsRecursive>(Storage, false); // Storage = 0
154  return *this;
155}
156bool RecursionStatus::isRecursive() const {
157  return Bitfield::get<RecursionStatus::IsRecursive>(Storage); // Storage s< 0
158}
159
160bool LatencyAccountant::accountRecord(const XRayRecord &Record) {
161  setMinMax(PerThreadMinMaxTSC[Record.TId], Record.TSC);
162  setMinMax(PerCPUMinMaxTSC[Record.CPU], Record.TSC);
163
164  if (CurrentMaxTSC == 0)
165    CurrentMaxTSC = Record.TSC;
166
167  if (Record.TSC < CurrentMaxTSC)
168    return false;
169
170  auto &ThreadStack = PerThreadFunctionStack[Record.TId];
171  if (RecursiveCallsOnly && !ThreadStack.RecursionDepth)
172    ThreadStack.RecursionDepth.emplace();
173  switch (Record.Type) {
174  case RecordTypes::CUSTOM_EVENT:
175  case RecordTypes::TYPED_EVENT:
176    // TODO: Support custom and typed event accounting in the future.
177    return true;
178  case RecordTypes::ENTER:
179  case RecordTypes::ENTER_ARG: {
180    ThreadStack.Stack.emplace_back(Record.FuncId, Record.TSC);
181    if (ThreadStack.RecursionDepth)
182      ++(*ThreadStack.RecursionDepth)[Record.FuncId];
183    break;
184  }
185  case RecordTypes::EXIT:
186  case RecordTypes::TAIL_EXIT: {
187    if (ThreadStack.Stack.empty())
188      return false;
189
190    if (ThreadStack.Stack.back().first == Record.FuncId) {
191      const auto &Top = ThreadStack.Stack.back();
192      if (!ThreadStack.RecursionDepth ||
193          (*ThreadStack.RecursionDepth)[Top.first].isRecursive())
194        recordLatency(Top.first, diff(Top.second, Record.TSC));
195      if (ThreadStack.RecursionDepth)
196        --(*ThreadStack.RecursionDepth)[Top.first];
197      ThreadStack.Stack.pop_back();
198      break;
199    }
200
201    if (!DeduceSiblingCalls)
202      return false;
203
204    // Look for the parent up the stack.
205    auto Parent =
206        llvm::find_if(llvm::reverse(ThreadStack.Stack),
207                      [&](const std::pair<const int32_t, uint64_t> &E) {
208                        return E.first == Record.FuncId;
209                      });
210    if (Parent == ThreadStack.Stack.rend())
211      return false;
212
213    // Account time for this apparently sibling call exit up the stack.
214    // Considering the following case:
215    //
216    //   f()
217    //    g()
218    //      h()
219    //
220    // We might only ever see the following entries:
221    //
222    //   -> f()
223    //   -> g()
224    //   -> h()
225    //   <- h()
226    //   <- f()
227    //
228    // Now we don't see the exit to g() because some older version of the XRay
229    // runtime wasn't instrumenting tail exits. If we don't deduce tail calls,
230    // we may potentially never account time for g() -- and this code would have
231    // already bailed out, because `<- f()` doesn't match the current "top" of
232    // stack where we're waiting for the exit to `g()` instead. This is not
233    // ideal and brittle -- so instead we provide a potentially inaccurate
234    // accounting of g() instead, computing it from the exit of f().
235    //
236    // While it might be better that we account the time between `-> g()` and
237    // `-> h()` as the proper accounting of time for g() here, this introduces
238    // complexity to do correctly (need to backtrack, etc.).
239    //
240    // FIXME: Potentially implement the more complex deduction algorithm?
241    auto R = make_range(std::next(Parent).base(), ThreadStack.Stack.end());
242    for (auto &E : R) {
243      if (!ThreadStack.RecursionDepth ||
244          (*ThreadStack.RecursionDepth)[E.first].isRecursive())
245        recordLatency(E.first, diff(E.second, Record.TSC));
246    }
247    for (auto &Top : reverse(R)) {
248      if (ThreadStack.RecursionDepth)
249        --(*ThreadStack.RecursionDepth)[Top.first];
250      ThreadStack.Stack.pop_back();
251    }
252    break;
253  }
254  }
255
256  return true;
257}
258
259namespace {
260
261// We consolidate the data into a struct which we can output in various forms.
262struct ResultRow {
263  uint64_t Count;
264  double Min;
265  double Median;
266  double Pct90;
267  double Pct99;
268  double Max;
269  double Sum;
270  std::string DebugInfo;
271  std::string Function;
272};
273
274ResultRow getStats(MutableArrayRef<uint64_t> Timings) {
275  assert(!Timings.empty());
276  ResultRow R;
277  R.Sum = std::accumulate(Timings.begin(), Timings.end(), 0.0);
278  auto MinMax = std::minmax_element(Timings.begin(), Timings.end());
279  R.Min = *MinMax.first;
280  R.Max = *MinMax.second;
281  R.Count = Timings.size();
282
283  auto MedianOff = Timings.size() / 2;
284  std::nth_element(Timings.begin(), Timings.begin() + MedianOff, Timings.end());
285  R.Median = Timings[MedianOff];
286
287  auto Pct90Off = std::floor(Timings.size() * 0.9);
288  std::nth_element(Timings.begin(), Timings.begin() + (uint64_t)Pct90Off,
289                   Timings.end());
290  R.Pct90 = Timings[Pct90Off];
291
292  auto Pct99Off = std::floor(Timings.size() * 0.99);
293  std::nth_element(Timings.begin(), Timings.begin() + (uint64_t)Pct99Off,
294                   Timings.end());
295  R.Pct99 = Timings[Pct99Off];
296  return R;
297}
298
299} // namespace
300
301using TupleType = std::tuple<int32_t, uint64_t, ResultRow>;
302
303template <typename F>
304static void sortByKey(std::vector<TupleType> &Results, F Fn) {
305  bool ASC = AccountSortOrder == SortDirection::ASCENDING;
306  llvm::sort(Results, [=](const TupleType &L, const TupleType &R) {
307    return ASC ? Fn(L) < Fn(R) : Fn(L) > Fn(R);
308  });
309}
310
311template <class F>
312void LatencyAccountant::exportStats(const XRayFileHeader &Header, F Fn) const {
313  std::vector<TupleType> Results;
314  Results.reserve(FunctionLatencies.size());
315  for (auto FT : FunctionLatencies) {
316    const auto &FuncId = FT.first;
317    auto &Timings = FT.second;
318    Results.emplace_back(FuncId, Timings.size(), getStats(Timings));
319    auto &Row = std::get<2>(Results.back());
320    if (Header.CycleFrequency) {
321      double CycleFrequency = Header.CycleFrequency;
322      Row.Min /= CycleFrequency;
323      Row.Median /= CycleFrequency;
324      Row.Pct90 /= CycleFrequency;
325      Row.Pct99 /= CycleFrequency;
326      Row.Max /= CycleFrequency;
327      Row.Sum /= CycleFrequency;
328    }
329
330    Row.Function = FuncIdHelper.SymbolOrNumber(FuncId);
331    Row.DebugInfo = FuncIdHelper.FileLineAndColumn(FuncId);
332  }
333
334  // Sort the data according to user-provided flags.
335  switch (AccountSortOutput) {
336  case SortField::FUNCID:
337    sortByKey(Results, [](const TupleType &X) { return std::get<0>(X); });
338    break;
339  case SortField::COUNT:
340    sortByKey(Results, [](const TupleType &X) { return std::get<1>(X); });
341    break;
342  case SortField::MIN:
343    sortByKey(Results, [](const TupleType &X) { return std::get<2>(X).Min; });
344    break;
345  case SortField::MED:
346    sortByKey(Results, [](const TupleType &X) { return std::get<2>(X).Median; });
347    break;
348  case SortField::PCT90:
349    sortByKey(Results, [](const TupleType &X) { return std::get<2>(X).Pct90; });
350    break;
351  case SortField::PCT99:
352    sortByKey(Results, [](const TupleType &X) { return std::get<2>(X).Pct99; });
353    break;
354  case SortField::MAX:
355    sortByKey(Results, [](const TupleType &X) { return std::get<2>(X).Max; });
356    break;
357  case SortField::SUM:
358    sortByKey(Results, [](const TupleType &X) { return std::get<2>(X).Sum; });
359    break;
360  case SortField::FUNC:
361    llvm_unreachable("Not implemented");
362  }
363
364  if (AccountTop > 0) {
365    auto MaxTop =
366        std::min(AccountTop.getValue(), static_cast<int>(Results.size()));
367    Results.erase(Results.begin() + MaxTop, Results.end());
368  }
369
370  for (const auto &R : Results)
371    Fn(std::get<0>(R), std::get<1>(R), std::get<2>(R));
372}
373
374void LatencyAccountant::exportStatsAsText(raw_ostream &OS,
375                                          const XRayFileHeader &Header) const {
376  OS << "Functions with latencies: " << FunctionLatencies.size() << "\n";
377
378  // We spend some effort to make the text output more readable, so we do the
379  // following formatting decisions for each of the fields:
380  //
381  //   - funcid: 32-bit, but we can determine the largest number and be
382  //   between
383  //     a minimum of 5 characters, up to 9 characters, right aligned.
384  //   - count:  64-bit, but we can determine the largest number and be
385  //   between
386  //     a minimum of 5 characters, up to 9 characters, right aligned.
387  //   - min, median, 90pct, 99pct, max: double precision, but we want to keep
388  //     the values in seconds, with microsecond precision (0.000'001), so we
389  //     have at most 6 significant digits, with the whole number part to be
390  //     at
391  //     least 1 character. For readability we'll right-align, with full 9
392  //     characters each.
393  //   - debug info, function name: we format this as a concatenation of the
394  //     debug info and the function name.
395  //
396  static constexpr char StatsHeaderFormat[] =
397      "{0,+9} {1,+10} [{2,+9}, {3,+9}, {4,+9}, {5,+9}, {6,+9}] {7,+9}";
398  static constexpr char StatsFormat[] =
399      R"({0,+9} {1,+10} [{2,+9:f6}, {3,+9:f6}, {4,+9:f6}, {5,+9:f6}, {6,+9:f6}] {7,+9:f6})";
400  OS << llvm::formatv(StatsHeaderFormat, "funcid", "count", "min", "med", "90p",
401                      "99p", "max", "sum")
402     << llvm::formatv("  {0,-12}\n", "function");
403  exportStats(Header, [&](int32_t FuncId, size_t Count, const ResultRow &Row) {
404    OS << llvm::formatv(StatsFormat, FuncId, Count, Row.Min, Row.Median,
405                        Row.Pct90, Row.Pct99, Row.Max, Row.Sum)
406       << "  " << Row.DebugInfo << ": " << Row.Function << "\n";
407  });
408}
409
410void LatencyAccountant::exportStatsAsCSV(raw_ostream &OS,
411                                         const XRayFileHeader &Header) const {
412  OS << "funcid,count,min,median,90%ile,99%ile,max,sum,debug,function\n";
413  exportStats(Header, [&](int32_t FuncId, size_t Count, const ResultRow &Row) {
414    OS << FuncId << ',' << Count << ',' << Row.Min << ',' << Row.Median << ','
415       << Row.Pct90 << ',' << Row.Pct99 << ',' << Row.Max << "," << Row.Sum
416       << ",\"" << Row.DebugInfo << "\",\"" << Row.Function << "\"\n";
417  });
418}
419
420using namespace llvm::xray;
421
422namespace llvm {
423template <> struct format_provider<llvm::xray::RecordTypes> {
424  static void format(const llvm::xray::RecordTypes &T, raw_ostream &Stream,
425                     StringRef Style) {
426    switch (T) {
427    case RecordTypes::ENTER:
428      Stream << "enter";
429      break;
430    case RecordTypes::ENTER_ARG:
431      Stream << "enter-arg";
432      break;
433    case RecordTypes::EXIT:
434      Stream << "exit";
435      break;
436    case RecordTypes::TAIL_EXIT:
437      Stream << "tail-exit";
438      break;
439    case RecordTypes::CUSTOM_EVENT:
440      Stream << "custom-event";
441      break;
442    case RecordTypes::TYPED_EVENT:
443      Stream << "typed-event";
444      break;
445    }
446  }
447};
448} // namespace llvm
449
450static CommandRegistration Unused(&Account, []() -> Error {
451  InstrumentationMap Map;
452  if (!AccountInstrMap.empty()) {
453    auto InstrumentationMapOrError = loadInstrumentationMap(AccountInstrMap);
454    if (!InstrumentationMapOrError)
455      return joinErrors(make_error<StringError>(
456                            Twine("Cannot open instrumentation map '") +
457                                AccountInstrMap + "'",
458                            std::make_error_code(std::errc::invalid_argument)),
459                        InstrumentationMapOrError.takeError());
460    Map = std::move(*InstrumentationMapOrError);
461  }
462
463  std::error_code EC;
464  raw_fd_ostream OS(AccountOutput, EC, sys::fs::OpenFlags::OF_TextWithCRLF);
465  if (EC)
466    return make_error<StringError>(
467        Twine("Cannot open file '") + AccountOutput + "' for writing.", EC);
468
469  const auto &FunctionAddresses = Map.getFunctionAddresses();
470  symbolize::LLVMSymbolizer Symbolizer;
471  llvm::xray::FuncIdConversionHelper FuncIdHelper(AccountInstrMap, Symbolizer,
472                                                  FunctionAddresses);
473  xray::LatencyAccountant FCA(FuncIdHelper, AccountRecursiveCallsOnly,
474                              AccountDeduceSiblingCalls);
475  auto TraceOrErr = loadTraceFile(AccountInput);
476  if (!TraceOrErr)
477    return joinErrors(
478        make_error<StringError>(
479            Twine("Failed loading input file '") + AccountInput + "'",
480            std::make_error_code(std::errc::executable_format_error)),
481        TraceOrErr.takeError());
482
483  auto &T = *TraceOrErr;
484  for (const auto &Record : T) {
485    if (FCA.accountRecord(Record))
486      continue;
487    errs()
488        << "Error processing record: "
489        << llvm::formatv(
490               R"({{type: {0}; cpu: {1}; record-type: {2}; function-id: {3}; tsc: {4}; thread-id: {5}; process-id: {6}}})",
491               Record.RecordType, Record.CPU, Record.Type, Record.FuncId,
492               Record.TSC, Record.TId, Record.PId)
493        << '\n';
494    for (const auto &ThreadStack : FCA.getPerThreadFunctionStack()) {
495      errs() << "Thread ID: " << ThreadStack.first << "\n";
496      if (ThreadStack.second.Stack.empty()) {
497        errs() << "  (empty stack)\n";
498        continue;
499      }
500      auto Level = ThreadStack.second.Stack.size();
501      for (const auto &Entry : llvm::reverse(ThreadStack.second.Stack))
502        errs() << "  #" << Level-- << "\t"
503               << FuncIdHelper.SymbolOrNumber(Entry.first) << '\n';
504    }
505    if (!AccountKeepGoing)
506      return make_error<StringError>(
507          Twine("Failed accounting function calls in file '") + AccountInput +
508              "'.",
509          std::make_error_code(std::errc::executable_format_error));
510  }
511  switch (AccountOutputFormat) {
512  case AccountOutputFormats::TEXT:
513    FCA.exportStatsAsText(OS, T.getFileHeader());
514    break;
515  case AccountOutputFormats::CSV:
516    FCA.exportStatsAsCSV(OS, T.getFileHeader());
517    break;
518  }
519
520  return Error::success();
521});
522