ceph/src/seastar/scripts/io-trace-parse.py

   1 #!/bin/env python3
   2 #
   3 # Script to parse IO trace logs and show some stats
   4 #
   5
   6 import sys
   7 import statistics
   8
   9
  10 # prints average, .99 quantile and maximum value for an array
  11 def print_stat_line(what, st):
  12     def q99(arr):
  13         return statistics.quantiles(arr, n=100)[-1]
  14
  15     print("\t{:18}: avg:{:12.6f}  .99:{:12.6f}  max:{:12.6f}".format(what,
  16           statistics.fmean(st), q99(st), max(st)))
  17
  18
  19 # Inc/Dec counter that also collects its value history
  20 class counter:
  21     def __init__(self):
  22         self._v = 0
  23         self._stat = []
  24
  25     def inc(self):
  26         self._v += 1
  27         self._stat.append(self._v)
  28
  29     def dec(self):
  30         self._v -= 1
  31         self._stat.append(self._v)
  32
  33     def stat(self):
  34         return self._stat
  35
  36
  37 class req:
  38     def __init__(self, rqlen):
  39         self.len = rqlen
  40         self.queue = None
  41         self.submit = None
  42         self.complete = None
  43
  44
  45 # Timings for requests
  46 class req_stat:
  47     def __init__(self):
  48         self.qtimes = []        # time in queue
  49         self.xtimes = []        # time in disk
  50         self.latencies = []     # sum of the above
  51         self.delays = []        # time between submits
  52         self.prev = None        # helper for the above
  53         self.in_queue = counter()
  54         self.in_disk = counter()
  55
  56     def queue(self, rq):
  57         self.in_queue.inc()
  58
  59     def submit(self, rq):
  60         if self.prev:
  61             self.delays.append(rq.submit - self.prev)
  62         self.prev = rq.submit
  63         self.qtimes.append(rq.submit - rq.queue)
  64         self.in_queue.dec()
  65         self.in_disk.inc()
  66
  67     def complete(self, rq):
  68         self.xtimes.append(rq.complete - rq.submit)
  69         self.latencies.append(rq.complete - rq.queue)
  70         self.in_disk.dec()
  71
  72     def show(self, rqlen):
  73         print("{}k requests".format(int(rqlen/1024)))
  74         print("\ttotal: {}".format(len(self.latencies)))
  75         print_stat_line('in queue usec', self.qtimes)
  76         print_stat_line('      `- num ', self.in_queue.stat())
  77         print_stat_line('in disk usec', self.xtimes)
  78         print_stat_line('     `- num ', self.in_disk.stat())
  79         print_stat_line('latency', self.latencies)
  80         print_stat_line('period', self.delays)
  81
  82
  83 # Stats for a device. Umbrella-object for the above stats
  84 class device_stat:
  85     def __init__(self):
  86         self.reqs = {}          # collection of req's
  87         self.req_stats = {}     # statistics by request size
  88         self.in_queue = counter()
  89         self.in_disk = counter()
  90
  91     def queue(self, rqid, ts, rqlen):
  92         rq = req(rqlen)
  93         self.reqs[rqid] = rq
  94         rq.queue = ts
  95         if rq.len not in self.req_stats:
  96             self.req_stats[rq.len] = req_stat()
  97         st = self.req_stats[rq.len]
  98         st.queue(rq)
  99         self.in_queue.inc()
 100
 101     def submit(self, rqid, ts):
 102         rq = self.reqs[rqid]
 103         rq.submit = ts
 104         st = self.req_stats[rq.len]
 105         st.submit(rq)
 106         self.in_queue.dec()
 107         self.in_disk.inc()
 108
 109     def complete(self, rqid, ts):
 110         rq = self.reqs[rqid]
 111         rq.complete = ts
 112         st = self.req_stats[rq.len]
 113         st.complete(rq)
 114         del self.reqs[rqid]
 115         self.in_disk.dec()
 116
 117     def _show_req_stats(self):
 118         for rlen in self.req_stats:
 119             st = self.req_stats[rlen]
 120             st.show(rlen)
 121
 122     def _show_queue_stats(self):
 123         print("queue")
 124         print_stat_line('in queue num:', self.in_queue.stat())
 125         print_stat_line('in disk num:', self.in_disk.stat())
 126
 127     def show(self, devid):
 128         print("{}".format(devid).center(80, "-"))
 129         self._show_req_stats()
 130         self._show_queue_stats()
 131
 132
 133 class parser:
 134     def __init__(self, f):
 135         self._file = f
 136         self._dev_stats = {}
 137
 138     def _get_dev_stats(self, devid):
 139         if devid not in self._dev_stats:
 140             self._dev_stats[devid] = device_stat()
 141
 142         return self._dev_stats[devid]
 143
 144     def _parse_req_event(self, ln):
 145         req_id = ln[10]
 146         ts = float(ln[1])
 147         st = self._get_dev_stats(int(ln[7]))
 148
 149         if ln[11] == 'queue':
 150             st.queue(req_id, ts, int(ln[13]))
 151         elif ln[11] == 'submit':
 152             st.submit(req_id, ts)
 153         elif ln[11] == 'complete':
 154             st.complete(req_id, ts)
 155
 156     def _parse_line(self, ln):
 157         if ln[4] == 'io':
 158             if ln[9] == 'req':
 159                 self._parse_req_event(ln)
 160
 161     def parse(self):
 162         for ln in self._file:
 163             if ln.startswith('TRACE'):
 164                 self._parse_line(ln.strip().split())
 165
 166         return self._dev_stats
 167
 168
 169 if __name__ == "__main__":
 170     p = parser(sys.stdin)
 171     stats = p.parse()
 172     for devid in stats:
 173         stats[devid].show(devid)