ceph/src/seastar/scripts/stall-analyser.py

   1 #!/usr/bin/env python
   2
   3 import argparse
   4 import sys
   5 import re
   6
   7 import addr2line
   8
   9 parser = argparse.ArgumentParser(formatter_class=argparse.RawDescriptionHelpFormatter,
  10     description='A reactor stall backtrace graph analyser.',
  11     epilog="""
  12 stall-analyser helps analyze a series of reactor-stall backtraces using a graph.
  13 Each node in the graph includes:
  14   `addr` - a program address
  15 Each link in the graph includes:
  16   `total` - the total sum of stalls, in milliseconds
  17             of all reactor stalls that pass via this caller/callee link.
  18   `count` - number of backtraces going through the link.
  19
  20 When printed, the graph is traversed in descending `total` order
  21 to emphasize stall backtraces that are frequent and long.
  22
  23 Each node in the printed output is preceded with [level#index pct%],
  24 where `level` is the level of that node in the graph (0 are root nodes),
  25 `index` is the index in the parent node's list of callers/callees, and
  26 `pct` is the percantage of this link's `total` time relative to
  27 its siblings.
  28
  29 When given an executable, addresses are decoding using `addr2line`
  30 """)
  31 parser.add_argument('--address-threshold', default='0x100000000',
  32                     help='Skip common backtrace prefix terminated by one or more addresses greater or equal to the threshold (0=disabled)')
  33 parser.add_argument('-e', '--executable',
  34                     help='Decode addresses to lines using given executable')
  35 parser.add_argument('-f', '--full-function-names', action='store_const', const=True, default=False,
  36                     help="When demangling C++ function names, display all information, including the type of the function's parameters. Otherwise, they are omitted (see `c++filt(1) -p`).")
  37 parser.add_argument('-w', '--width', type=int, default=None,
  38                     help='Smart trim of long lines to width characters (0=disabled)')
  39 parser.add_argument('-d', '--direction', choices=['bottom-up', 'top-down'], default='bottom-up',
  40                     help='Print graph bottom-up (default, callees first) or top-down (callers first)')
  41 parser.add_argument('-m', '--minimum', type=int, default=None,
  42                     help='Process only stalls lasting the given time, in milliseconds, or longer')
  43 parser.add_argument('-b', '--branch-threshold', type=float, default=0.05,
  44                     help='Drop branches responsible for less than this threshold relative to the previous level, not global. (default 5%%)')
  45 parser.add_argument('file', nargs='?',
  46                     help='File containing reactor stall backtraces. Read from stdin if missing.')
  47
  48 args = parser.parse_args()
  49
  50 resolver = addr2line.BacktraceResolver(executable=args.executable, concise=not args.full_function_names) if args.executable else None
  51
  52 class Node:
  53     def __init__(self, addr:str):
  54         self.addr = addr
  55         self.callers = {}
  56         self.callees = {}
  57         self.printed = False
  58
  59     def __repr__(self):
  60         return f"Node({self.addr})"
  61
  62     class Link:
  63         def __init__(self, node, t:int):
  64             self.node = node
  65             self.total = t
  66             self.count = 1
  67
  68         def __eq__(self, other):
  69             return self.total == other.total and self.count == other.count
  70
  71         def __ne__(self, other):
  72             return not (self == other)
  73
  74         def __lt__(self, other):
  75             return self.total < other.total or self.total == other.total and self.count < other.count
  76
  77         def add(self, t:int):
  78             self.total += t
  79             self.count += 1
  80
  81     def link_caller(self, t:int, n):
  82         if n.addr in self.callers:
  83             link = self.callers[n.addr]
  84             link.add(t)
  85             n.callees[self.addr].add(t)
  86         else:
  87             self.callers[n.addr] = self.Link(n, t)
  88             n.callees[self.addr] = self.Link(self, t)
  89         return n
  90
  91     def unlink_caller(self, addr:str):
  92         link = self.callers.pop(addr)
  93         link.node.callees.pop(self.addr)
  94
  95     def link_callee(self, t:int, n):
  96         if n.addr in self.callees:
  97             link = self.callees[n.addr]
  98             link.add(t)
  99             n.callers[self.addr].add(t)
 100         else:
 101             self.callees[n.addr] = self.Link(n, t)
 102             n.callers[self.addr] = self.Link(self, t)
 103         return n
 104
 105     def unlink_callee(self, addr:str):
 106         link = self.callees.pop(addr)
 107         link.node.callers.pop(self.addr)
 108
 109     def sorted_links(self, links:list, descending=True):
 110         return sorted([l for l in links if l.node.addr], reverse=descending)
 111
 112     def sorted_callers(self, descending=True):
 113         return self.sorted_links(self.callers.values(), descending)
 114
 115     def sorted_callees(self, descending=True):
 116         return self.sorted_links(self.callees.values(), descending)
 117
 118 class Graph:
 119     def __init__(self):
 120         # Each node in the tree contains:
 121         self.count = 0
 122         self.total = 0
 123         self.nodes = {}
 124         self.tail = Node('')
 125         self.head = Node('')
 126
 127     def add(self, prev:Node, t:int, addr:str):
 128         if addr in self.nodes:
 129             n = self.nodes[addr]
 130         else:
 131             n = Node(addr)
 132             self.nodes[addr] = n
 133         if prev:
 134             if prev.addr in self.head.callees:
 135                 self.head.unlink_callee(prev.addr)
 136             prev.link_caller(t, n)
 137             if addr in self.tail.callers:
 138                 self.tail.unlink_caller(addr)
 139         elif not n.callees or addr in self.tail.callers:
 140             self.tail.link_caller(t, n)
 141         return n
 142
 143     def add_head(self, t:int, n:Node):
 144         self.head.link_callee(t, n)
 145
 146     def smart_print(self, lines:str, width:int):
 147         def _print(l:str, width:int):
 148             if not width or len(l) <= width:
 149                 print(l)
 150                 return
 151             i = l.rfind(" at ")
 152             if i < 0:
 153                 print(l[:width])
 154                 return
 155             sfx = l[i:]
 156             w = width - len(sfx) - 3
 157             if w > 0:
 158                 pfx = l[:w]
 159             else:
 160                 pfx = ""
 161             print(f"{pfx}...{sfx}")
 162         for l in lines.splitlines():
 163             if l:
 164                 _print(l, width)
 165
 166     def print_graph(self, direction:str):
 167         top_down = (direction == 'top-down')
 168         print(f"""
 169 This graph is printed in {direction} order, where {'callers' if top_down else 'callees'} are printed first.
 170 Use --direction={'bottom-up' if top_down else 'top-down'} to print {'callees' if top_down else 'callers'} first.
 171
 172 [level#index/out_of pct%] below denotes:
 173   level  - nesting level in the graph
 174   index  - index of node among to its siblings
 175   out_of - number of siblings
 176   pct    - percentage of total stall time of this call relative to its siblings
 177 """)
 178         varargs = vars(args)
 179         clopts = ""
 180         for k in varargs.keys():
 181             val = varargs[k]
 182             opt = re.sub('_', '-', k)
 183             if val is None:
 184                 continue
 185             elif not isinstance(val, bool):
 186                 clopts += f" --{opt}={val}"
 187             elif val:
 188                 clopts += f" --{opt}"
 189         print(f"Command line options:{clopts}\n")
 190
 191         def _prefix(prefix_list:list):
 192             prefix = ''
 193             for p in prefix_list:
 194                 prefix += p
 195             return prefix
 196
 197         def _recursive_print_graph(n:Node, total:int=0, count:int=0, level:int=-1, idx:int=0, out_of:int=0, rel:float=1.0, prefix_list=[], skip_stats=False):
 198             nonlocal top_down
 199             if level >= 0:
 200                 avg = round(total / count) if count else 0
 201                 prefix = _prefix(prefix_list)
 202                 p = '+' if idx == 1 or idx == out_of else '|'
 203                 p += '+'
 204                 l = f"[{level}#{idx}/{out_of} {round(100*rel)}%]"
 205                 cont_indent = len(l) + 1
 206                 if skip_stats:
 207                     l = f"{' ' * (len(l)-2)} -"
 208                     stats = ''
 209                 else:
 210                     stats = f" total={total} count={count} avg={avg}"
 211                 l = f"{prefix}{p}{l} addr={n.addr}{stats}"
 212                 p = "| "
 213                 if resolver:
 214                     lines = resolver.resolve_address(n.addr).splitlines()
 215                     if len(lines) == 1:
 216                         li = lines[0]
 217                         if li.startswith("??"):
 218                             l += f": {lines[0]}"
 219                         else:
 220                             l += f":\n{prefix}{p}{' '*cont_indent}{li.strip()}"
 221                     else:
 222                         l += ":\n"
 223                         if top_down:
 224                             lines.reverse()
 225                         for li in lines:
 226                             l += f"{prefix}{p}{' '*cont_indent}{li.strip()}\n"
 227                 width = args.width or 0
 228                 self.smart_print(l, width)
 229                 if n.printed:
 230                     print(f"{prefix}-> continued at addr={n.addr} above")
 231                     return
 232                 n.printed = True
 233             next = n.sorted_callees() if top_down else n.sorted_callers()
 234             if not next:
 235                 return
 236             link = next[0]
 237             if level >= 0 and len(next) == 1 and link.total == total and link.count == count:
 238                 _recursive_print_graph(link.node, link.total, link.count, level, idx, out_of, rel, prefix_list, skip_stats=True)
 239             else:
 240                 total = sum(link.total for link in next)
 241                 next_prefix_list = prefix_list + ["| " if idx < out_of else "  "] if level >= 0 else []
 242                 i = 1
 243                 last_idx = len(next)
 244                 omitted_idx = 0
 245                 omitted_total = 0
 246                 omitted_count = 0
 247                 for link in next:
 248                     rel = link.total / total
 249                     if rel < args.branch_threshold:
 250                         if not omitted_idx:
 251                             omitted_idx = i
 252                         omitted_total += link.total
 253                         omitted_count += link.count
 254                     else:
 255                         _recursive_print_graph(link.node, link.total, link.count, level + 1, i, last_idx, rel, next_prefix_list)
 256                     i += 1
 257                 if omitted_idx:
 258                     prefix = _prefix(next_prefix_list)
 259                     p = '++'
 260                     rel = omitted_total / total
 261                     avg = round(omitted_total / omitted_count) if count else 0
 262                     l = f"[{level+1}#{omitted_idx}/{last_idx} {round(100*rel)}%]"
 263                     print(f"{prefix}{p}{l} {last_idx - omitted_idx + 1} more branches total={omitted_total} count={omitted_count} avg={avg}")
 264
 265         r = self.head if top_down else self.tail
 266         _recursive_print_graph(r)
 267
 268 graph = Graph()
 269
 270 # process each backtrace and insert it to the tree
 271 #
 272 # The backtraces are assumed to be in bottom-up order, i.e.
 273 # the first address indicates the innermost frame and the last
 274 # address is in the outermost, in calling order.
 275 #
 276 # This helps identifying closely related reactor stalls
 277 # where a code path that stalls may be called from multiple
 278 # call sites.
 279 def process_graph(t: int, trace: list[str]):
 280     n = None
 281     for addr in trace:
 282         n = graph.add(n, t, addr)
 283     graph.add_head(t, n)
 284
 285 address_threshold = int(args.address_threshold, 0)
 286 tally = {}
 287
 288 def print_stats(tally:dict, tmin):
 289     data = []
 290     total_time = 0
 291     total_count = 0
 292     processed_count = 0
 293     min_time = 1000000
 294     max_time = 0
 295     median = None
 296     p95 = None
 297     p99 = None
 298     p999 = None
 299     for t in sorted(tally.keys()):
 300         count = tally[t]
 301         data.append((t, count))
 302         total_time += t * count
 303         if t < min_time:
 304             min_time = t
 305         if t > max_time:
 306             max_time = t
 307         total_count += count
 308         if t >= tmin:
 309             processed_count += count
 310     running_count = 0
 311     for (t, count) in data:
 312         running_count += count
 313         if median is None and running_count >= total_count / 2:
 314             median = t
 315         elif p95 is None and running_count >= (total_count * 95) / 100:
 316             p95 = t
 317         elif p99 is None and running_count >= (total_count * 99) / 100:
 318             p99 = t
 319         elif p999 is None and running_count >= (total_count * 999) / 1000:
 320             p999 = t
 321     print(f"Processed {total_count} stalls lasting a total of {total_time} milliseconds.")
 322     if tmin:
 323         print(f"Of which, {processed_count} lasted {tmin} milliseconds or longer.")
 324     avg_time = total_time / total_count if total_count else 0
 325     print(f"min={min_time} avg={avg_time:.1f} median={median} p95={p95} p99={p99} p999={p999} max={max_time}")
 326
 327 input = open(args.file) if args.file else sys.stdin
 328 count = 0
 329 comment = re.compile('^\s*#')
 330 pattern = re.compile('Reactor stall')
 331 for s in input:
 332     if comment.search(s) or not pattern.search(s):
 333         continue
 334     count += 1
 335     trace = s.split()
 336     for i in range(0, len(trace)):
 337         if trace[i] == 'Reactor':
 338             i += 3
 339             break
 340     t = int(trace[i])
 341     tally[t] = tally.pop(t, 0) + 1
 342     trace = trace[i + 6:]
 343     # The address_threshold typically indicates a library call
 344     # and the backtrace up-to and including it are usually of
 345     # no interest as they all contain the stall backtrace geneneration code, e.g.:
 346     #  seastar::internal::cpu_stall_detector::generate_trace
 347     # void seastar::backtrace<seastar::backtrace_buffer::append_backtrace_oneline()::{lambda(seastar::frame)#1}>(seastar::backt>
 348     #  (inlined by) seastar::backtrace_buffer::append_backtrace_oneline() at ./build/release/seastar/./seastar/src/core/reactor.cc:771
 349     #  (inlined by) seastar::print_with_backtrace(seastar::backtrace_buffer&, bool) at ./build/release/seastar/./seastar/src/core/reactor.cc>
 350     # seastar::internal::cpu_stall_detector::generate_trace() at ./build/release/seastar/./seastar/src/core/reactor.cc:1257
 351     # seastar::internal::cpu_stall_detector::maybe_report() at ./build/release/seastar/./seastar/src/core/reactor.cc:1103
 352     #  (inlined by) seastar::internal::cpu_stall_detector::on_signal() at ./build/release/seastar/./seastar/src/core/reactor.cc:1117
 353     #  (inlined by) seastar::reactor::block_notifier(int) at ./build/release/seastar/./seastar/src/core/reactor.cc:1240
 354     # ?? ??:0
 355     if address_threshold:
 356         for i in range(0, len(trace)):
 357             if int(trace[i], 0) >= address_threshold:
 358                 while int(trace[i], 0) >= address_threshold:
 359                     i += 1
 360                 trace = trace[i:]
 361                 break
 362     tmin = args.minimum or 0
 363     if t >= tmin:
 364         process_graph(t, trace)
 365
 366 try:
 367     print_stats(tally, tmin)
 368     graph.print_graph(args.direction)
 369 except BrokenPipeError:
 370     pass