From e61fbe91e7b4b5e02e9b8598e0b94bc12d174e82 Mon Sep 17 00:00:00 2001 From: Konrad Sztyber Date: Thu, 27 May 2021 18:27:57 +0200 Subject: [PATCH] scripts/trace: qpair annotations This patch adds support for annotating qpairs. The raw pointer values are replaced with a list of various properties of a qpair collected by the bpftrace script. A line like this: `0 2856282624.000 RDMA_REQ_NEW id: r3256 qpair: 0x26ba550` becomes (the line was only broken here): `0 2856282502.669 RDMA_REQ_NEW id: r3256 qpair(ptr=0x26ba550, thread=2, qid=0, \ subnqn=nqn.2016-06.io.spdk:cnode1, \ hostnqn=nqn.2014-08.org.nvmexpress:uuid:729783b4ab38485d8d767b7741108a8)` To annotate a trace, one first needs to enable and record the DTrace probes: ``` $ scripts/bpf/trace.py --record `pidof spdk_tgt` > bpftraces ^C ``` Of course, the probe events are only recorded when the script is executing, so in order to generate the annotations properly, it must be started before the annotated objects are created. For instance, for NVMeoF, it needs to be running before a connection is made. After the BPF probes are recored, the traces can be annotated: ``` $ build/bin/spdk_trace -p `pidof spdk_tgt` -s spdk_tgt -j | \ scripts/bpf/trace.py -b bpftraces ``` For now, the script only annotates traces from the rdma module, as it's the only one with tracpoints recording qpair pointers now, but it could be extended to support more tracepoints. Similarly, more objects could be annotated in the future by extending the `SPDKObject` class and defining additional DTrace probe points. Signed-off-by: Konrad Sztyber Change-Id: I2225f4b1ab266b41af561b5e7d942411cd0c13c1 Reviewed-on: https://review.spdk.io/gerrit/c/spdk/spdk/+/8107 Tested-by: SPDK CI Jenkins Reviewed-by: Jim Harris Reviewed-by: Tomasz Zawadzki --- scripts/bpf/trace.py | 126 ++++++++++++++++++++++++++++++++++++++++--- 1 file changed, 119 insertions(+), 7 deletions(-) diff --git a/scripts/bpf/trace.py b/scripts/bpf/trace.py index 450016134c..e4b7985c6c 100755 --- a/scripts/bpf/trace.py +++ b/scripts/bpf/trace.py @@ -1,7 +1,8 @@ #!/usr/bin/env python3 from argparse import ArgumentParser -from dataclasses import dataclass +from dataclasses import dataclass, field +from itertools import islice from typing import Dict, List, TypeVar import json import os @@ -10,6 +11,8 @@ import subprocess import sys import tempfile +TSC_MAX = (1 << 64) - 1 + @dataclass class DTraceArgument: @@ -166,6 +169,7 @@ class Trace: """Stores, parses, and prints out SPDK traces""" def __init__(self, file): self._json = json.load(file) + self._objects = [] self._argfmt = {TracepointArgument.TYPE_PTR: lambda a: f'0x{a:x}'} self.tpoints = {t.id: t for t in self._parse_tpoints()} self.tsc_rate = self._json['tsc_rate'] @@ -192,13 +196,30 @@ class Trace: for entry in self._json.get('entries', []): yield self._parse_entry(entry) + def _annotate_args(self, entry): + annotations = {} + for obj in self._objects: + current = obj.annotate(entry) + if current is None: + continue + annotations.update(current) + return annotations + def _format_args(self, entry): + annotations = self._annotate_args(entry) args = [] for arg, (name, value) in zip(entry.tpoint.args, entry.args.items()): - args.append('{}: {}'.format(name, self._argfmt.get(arg.argtype, - lambda a: a)(value))) + annot = annotations.get(name) + if annot is not None: + args.append('{}({})'.format(name, ', '.join(f'{n}={v}' for n, v in annot.items()))) + else: + args.append('{}: {}'.format(name, self._argfmt.get(arg.argtype, + lambda a: a)(value))) return args + def register_object(self, obj): + self._objects.append(obj) + def print(self): def get_us(tsc, off): return ((tsc - off) * 10 ** 6) / self.tsc_rate @@ -223,7 +244,90 @@ class Trace: print(' '.join([*filter(lambda f: f is not None, fields)]).rstrip()) -def build_dtrace(): +class SPDKObject: + """Describes a specific type of an SPDK objects (e.g. qpair, thread, etc.)""" + @dataclass + class Lifetime: + """Describes a lifetime and properites of a particular SPDK object.""" + begin: int + end: int + ptr: int + properties: dict = field(default_factory=dict) + + def __init__(self, trace: Trace, tpoints: List[str]): + self.tpoints = {} + for name in tpoints: + tpoint = next((t for t in trace.tpoints.values() if t.name == name), None) + if tpoint is None: + # Some tpoints might be undefined if configured without specific subystems + continue + self.tpoints[tpoint.id] = tpoint + + def _annotate(self, entry: TraceEntry): + """Abstract annotation method to be implemented by subclasses.""" + raise NotImplementedError() + + def annotate(self, entry: TraceEntry): + """Annotates a tpoint entry and returns a dict indexed by argname with values representing + various object properites. For instance, {"qpair": {"qid": 1, "subnqn": "nqn"}} could be + returned to annotate an argument called "qpair" with two items: "qid" and "subnqn". + """ + if entry.tpoint.id not in self.tpoints: + return None + return self._annotate(entry) + + +class QPair(SPDKObject): + def __init__(self, trace: Trace, dtrace: DTrace): + super().__init__(trace, tpoints=[ + 'RDMA_REQ_NEW', + 'RDMA_REQ_NEED_BUFFER', + 'RDMA_REQ_TX_PENDING_C2H', + 'RDMA_REQ_TX_PENDING_H2C', + 'RDMA_REQ_TX_H2C', + 'RDMA_REQ_RDY_TO_EXECUTE', + 'RDMA_REQ_EXECUTING', + 'RDMA_REQ_EXECUTED', + 'RDMA_REQ_RDY_TO_COMPL', + 'RDMA_REQ_COMPLETING_C2H', + 'RDMA_REQ_COMPLETING', + 'RDMA_REQ_COMPLETED']) + self._objects = [] + self._find_objects(dtrace.entries) + + def _find_objects(self, dprobes): + def probe_match(probe, other): + return probe.args['qpair'] == other.args['qpair'] + + for i, dprobe in enumerate(dprobes): + if dprobe.name != 'nvmf_poll_group_add_qpair': + continue + # We've found a new qpair, now find the probe indicating its destruction + last_idx, last = next((((i + j + 1), d) for j, d in enumerate(islice(dprobes, i, None)) + if d.name == 'nvmf_poll_group_remove_qpair' and + probe_match(d, dprobe)), (None, None)) + obj = SPDKObject.Lifetime(begin=dprobe.args['tsc'], + end=last.args['tsc'] if last is not None else TSC_MAX, + ptr=dprobe.args['qpair'], + properties={'ptr': hex(dprobe.args['qpair']), + 'thread': dprobe.args['thread']}) + for other in filter(lambda p: probe_match(p, dprobe), dprobes[i:last_idx]): + if other.name == 'nvmf_ctrlr_add_qpair': + for prop in ['qid', 'subnqn', 'hostnqn']: + obj.properties[prop] = other.args[prop] + self._objects.append(obj) + + def _annotate(self, entry): + qpair = entry.args.get('qpair') + if qpair is None: + return None + for obj in self._objects: + if obj.ptr == qpair and obj.begin <= entry.tsc <= obj.end: + return {'qpair': obj.properties} + return None + + +def build_dtrace(file=None): return DTrace([ DTraceProbe( name='nvmf_poll_group_add_qpair', @@ -241,7 +345,14 @@ def build_dtrace(): DTraceArgument(name='qpair', pos=1, type=int), DTraceArgument(name='qid', pos=2, type=int), DTraceArgument(name='subnqn', pos=3, type=str), - DTraceArgument(name='hostnqn', pos=4, type=str)])]) + DTraceArgument(name='hostnqn', pos=4, type=str)])], file) + + +def print_trace(trace_file, dtrace_file): + dtrace = build_dtrace(dtrace_file) + trace = Trace(trace_file) + trace.register_object(QPair(trace, dtrace)) + trace.print() def main(argv): @@ -250,6 +361,7 @@ def main(argv): help='JSON-formatted trace file produced by spdk_trace app') parser.add_argument('-g', '--generate', help='Generate bpftrace script', action='store_true') parser.add_argument('-r', '--record', help='Record BPF traces on PID', metavar='PID', type=int) + parser.add_argument('-b', '--bpftrace', help='BPF trace script to use for annotations') args = parser.parse_args(argv) if args.generate: @@ -257,8 +369,8 @@ def main(argv): elif args.record: build_dtrace().record(args.record) else: - file = open(args.input, 'r') if args.input is not None else sys.stdin - Trace(file).print() + print_trace(open(args.input, 'r') if args.input is not None else sys.stdin, + open(args.bpftrace) if args.bpftrace is not None else None) if __name__ == '__main__':