biolatency.py Add -j flag for json output

In it's current form, storing the histogram data and analyzing the same for a large set of machines is difficult.
With this flag, it is possible to store the histogram as a dictionary/json file which can be imported easily to be analyzed with libraries like Pandas. An example output looks like below:

{
    'ts': '2020-12-30 14:49:37', 
    'val_type': 'msecs', 
    'data': 
        [
            {'interval-start': 0, 'interval-end': 1, 'count': 2}, 
            {'interval-start': 2, 'interval-end': 3, 'count': 1}
        ], 
    'flags': 'Sync-Write'
}

man/man8/biolatency.8

@@ -1,4 +1,4 @@
-.TH biolatency 8 "2019-12-12" "USER COMMANDS"
+.TH biolatency 8 "2020-12-30" "USER COMMANDS"
 .SH NAME
 biolatency \- Summarize block device I/O latency as a histogram.
 .SH SYNOPSIS
@@ -36,6 +36,9 @@ Print a histogram per disk device.
 \-F
 Print a histogram per set of I/O flags.
 .TP
+\-j
+Print a histogram dictionary
+.TP
 interval
 Output interval, in seconds.
 .TP
@@ -63,6 +66,10 @@ Include OS queued time in I/O time:
 Show a latency histogram for each disk device separately:
 #
 .B biolatency \-D
+.TP
+Show a latency histogram in a dictionary format:
+#
+.B biolatency \-j
 .SH FIELDS
 .TP
 usecs

tools/biolatency.py

@@ -15,15 +15,17 @@
 from bcc import BPF
 from time import sleep, strftime
 import argparse
+import ctypes as ct
 
 # arguments
 examples = """examples:
- ./biolatency # summarize block I/O latency as a histogram
- ./biolatency 1 10 # print 1 second summaries, 10 times
- ./biolatency -mT 1 # 1s summaries, milliseconds, and timestamps
- ./biolatency -Q # include OS queued time in I/O time
- ./biolatency -D # show each disk device separately
- ./biolatency -F # show I/O flags separately
+ ./biolatency # summarize block I/O latency as a histogram
+ ./biolatency 1 10 # print 1 second summaries, 10 times
+ ./biolatency -mT 1 # 1s summaries, milliseconds, and timestamps
+ ./biolatency -Q # include OS queued time in I/O time
+ ./biolatency -D # show each disk device separately
+ ./biolatency -F # show I/O flags separately
+ ./biolatency -j # print a dictionary
 """
 parser = argparse.ArgumentParser(
  description="Summarize block device I/O latency as a histogram",
@@ -45,9 +47,13 @@
  help="number of outputs")
 parser.add_argument("--ebpf", action="store_true",
  help=argparse.SUPPRESS)
+parser.add_argument("-j", "--json", action="store_true",
+ help="json output")
+
 args = parser.parse_args()
 countdown = int(args.count)
 debug = 0
+
 if args.flags and args.disks:
  print("ERROR: can only use -D or -F. Exiting.")
  exit()
@@ -141,7 +147,8 @@
 b.attach_kprobe(event="blk_account_io_done",
  fn_name="trace_req_done")
 
-print("Tracing block device I/O... Hit Ctrl-C to end.")
+if not args.json:
+ print("Tracing block device I/O... Hit Ctrl-C to end.")
 
 # see blk_fill_rwbs():
 req_opf = {
@@ -193,6 +200,68 @@ def flags_print(flags):
  desc = "NoWait-" + desc
  return desc
 
+
+def _print_json_hist(vals, val_type, section_bucket=None):
+ hist_list = []
+ max_nonzero_idx = 0
+ for i in range(len(vals)):
+ if vals[i] != 0:
+ max_nonzero_idx = i
+ index = 1
+ prev = 0
+ for i in range(len(vals)):
+ if i != 0 and i <= max_nonzero_idx:
+ index = index * 2
+
+ list_obj = {}
+ list_obj['interval-start'] = prev
+ list_obj['interval-end'] = int(index) - 1
+ list_obj['count'] = int(vals[i])
+
+ hist_list.append(list_obj)
+
+ prev = index
+ histogram = {"ts": strftime("%Y-%m-%d %H:%M:%S"), "val_type": val_type, "data": hist_list}
+ if section_bucket:
+ histogram[section_bucket[0]] = section_bucket[1]
+ print(histogram)
+
+
+def print_json_hist(self, val_type="value", section_header="Bucket ptr",
+ section_print_fn=None, bucket_fn=None, bucket_sort_fn=None):
+ log2_index_max = 65 # this is a temporary workaround. Variable available in table.py
+ if isinstance(self.Key(), ct.Structure):
+ tmp = {}
+ f1 = self.Key._fields_[0][0]
+ f2 = self.Key._fields_[1][0]
+
+ if f2 == '__pad_1' and len(self.Key._fields_) == 3:
+ f2 = self.Key._fields_[2][0]
+ for k, v in self.items():
+ bucket = getattr(k, f1)
+ if bucket_fn:
+ bucket = bucket_fn(bucket)
+ vals = tmp[bucket] = tmp.get(bucket, [0] * log2_index_max)
+ slot = getattr(k, f2)
+ vals[slot] = v.value
+ buckets = list(tmp.keys())
+ if bucket_sort_fn:
+ buckets = bucket_sort_fn(buckets)
+ for bucket in buckets:
+ vals = tmp[bucket]
+ if section_print_fn:
+ section_bucket = (section_header, section_print_fn(bucket))
+ else:
+ section_bucket = (section_header, bucket)
+ _print_json_hist(vals, val_type, section_bucket)
+
+ else:
+ vals = [0] * log2_index_max
+ for k, v in self.items():
+ vals[k.value] = v.value
+ _print_json_hist(vals, val_type)
+
+
 # output
 exiting = 0 if args.interval else 1
 dist = b.get_table("dist")
@@ -203,15 +272,29 @@ def flags_print(flags):
  exiting = 1
 
  print()
- if args.timestamp:
- print("%-8s\n" % strftime("%H:%M:%S"), end="")
+ if args.json:
+ if args.timestamp:
+ print("%-8s\n" % strftime("%H:%M:%S"), end="")
+
+ if args.flags:
+ print_json_hist(dist, label, "flags", flags_print)
+
+ else:
+ print_json_hist(dist, label)
 
- if args.flags:
- dist.print_log2_hist(label, "flags", flags_print)
  else:
- dist.print_log2_hist(label, "disk")
+ if args.timestamp:
+ print("%-8s\n" % strftime("%H:%M:%S"), end="")
+
+ if args.flags:
+ dist.print_log2_hist(label, "flags", flags_print)
+
+ else:
+ dist.print_log2_hist(label, "disk")
+
  dist.clear()
 
  countdown -= 1
  if exiting or countdown == 0:
  exit()
+

tools/biolatency_example.txt

@@ -292,11 +292,42 @@ flags = Priority-Metadata-Write
 These can be handled differently by the storage device, and this mode lets us
 examine their performance in isolation.
 
+The -j option prints a dictionary of the histogram.
+For example:
+
+# ./biolatency.py -j
+^C
+{'ts': '2020-12-30 14:33:03', 'val_type': 'usecs', 'data': [{'interval-start': 0, 'interval-end': 1, 'count': 0}, {'interval-start': 2, 'interval-end': 3, 'count': 0}, {'interval-start': 4, 'interval-end': 7, 'count': 0}, {'interval-start': 8, 'interval-end': 15, 'count': 0}, {'interval-start': 16, 'interval-end': 31, 'count': 0}, {'interval-start': 32, 'interval-end': 63, 'count': 2}, {'interval-start': 64, 'interval-end': 127, 'count': 75}, {'interval-start': 128, 'interval-end': 255, 'count': 7}, {'interval-start': 256, 'interval-end': 511, 'count': 0}, {'interval-start': 512, 'interval-end': 1023, 'count': 6}, {'interval-start': 1024, 'interval-end': 2047, 'count': 3}, {'interval-start': 2048, 'interval-end': 4095, 'count': 31}]}
+
+the key `data` is the list of the log2 histogram intervals. The `interval-start` and `interval-end` define the
+latency bucket and `count` is the number of I/O's that lie in that latency range.
+
+# ./biolatency.py -jF
+^C
+{'ts': '2020-12-30 14:37:59', 'val_type': 'usecs', 'data': [{'interval-start': 0, 'interval-end': 1, 'count': 0}, {'interval-start': 2, 'interval-end': 3, 'count': 0}, {'interval-start': 4, 'interval-end': 7, 'count': 0}, {'interval-start': 8, 'interval-end': 15, 'count': 0}, {'interval-start': 16, 'interval-end': 31, 'count': 1}, {'interval-start': 32, 'interval-end': 63, 'count': 1}, {'interval-start': 64, 'interval-end': 127, 'count': 0}, {'interval-start': 128, 'interval-end': 255, 'count': 0}, {'interval-start': 256, 'interval-end': 511, 'count': 0}, {'interval-start': 512, 'interval-end': 1023, 'count': 0}, {'interval-start': 1024, 'interval-end': 2047, 'count': 2}], 'flags': 'Sync-Write'}
+{'ts': '2020-12-30 14:37:59', 'val_type': 'usecs', 'data': [{'interval-start': 0, 'interval-end': 1, 'count': 0}, {'interval-start': 2, 'interval-end': 3, 'count': 0}, {'interval-start': 4, 'interval-end': 7, 'count': 0}, {'interval-start': 8, 'interval-end': 15, 'count': 0}, {'interval-start': 16, 'interval-end': 31, 'count': 0}, {'interval-start': 32, 'interval-end': 63, 'count': 0}, {'interval-start': 64, 'interval-end': 127, 'count': 0}, {'interval-start': 128, 'interval-end': 255, 'count': 2}, {'interval-start': 256, 'interval-end': 511, 'count': 0}, {'interval-start': 512, 'interval-end': 1023, 'count': 2}, {'interval-start': 1024, 'interval-end': 2047, 'count': 1}], 'flags': 'Unknown'}
+{'ts': '2020-12-30 14:37:59', 'val_type': 'usecs', 'data': [{'interval-start': 0, 'interval-end': 1, 'count': 0}, {'interval-start': 2, 'interval-end': 3, 'count': 0}, {'interval-start': 4, 'interval-end': 7, 'count': 0}, {'interval-start': 8, 'interval-end': 15, 'count': 0}, {'interval-start': 16, 'interval-end': 31, 'count': 0}, {'interval-start': 32, 'interval-end': 63, 'count': 0}, {'interval-start': 64, 'interval-end': 127, 'count': 0}, {'interval-start': 128, 'interval-end': 255, 'count': 0}, {'interval-start': 256, 'interval-end': 511, 'count': 0}, {'interval-start': 512, 'interval-end': 1023, 'count': 0}, {'interval-start': 1024, 'interval-end': 2047, 'count': 1}], 'flags': 'Write'}
+{'ts': '2020-12-30 14:37:59', 'val_type': 'usecs', 'data': [{'interval-start': 0, 'interval-end': 1, 'count': 0}, {'interval-start': 2, 'interval-end': 3, 'count': 0}, {'interval-start': 4, 'interval-end': 7, 'count': 0}, {'interval-start': 8, 'interval-end': 15, 'count': 0}, {'interval-start': 16, 'interval-end': 31, 'count': 0}, {'interval-start': 32, 'interval-end': 63, 'count': 0}, {'interval-start': 64, 'interval-end': 127, 'count': 0}, {'interval-start': 128, 'interval-end': 255, 'count': 0}, {'interval-start': 256, 'interval-end': 511, 'count': 0}, {'interval-start': 512, 'interval-end': 1023, 'count': 4}], 'flags': 'Flush'}
+
+The -j option used with -F prints a histogram dictionary per set of I/O flags.
+
+# ./biolatency.py -jD
+^C
+{'ts': '2020-12-30 14:40:00', 'val_type': 'usecs', 'data': [{'interval-start': 0, 'interval-end': 1, 'count': 0}, {'interval-start': 2, 'interval-end': 3, 'count': 0}, {'interval-start': 4, 'interval-end': 7, 'count': 0}, {'interval-start': 8, 'interval-end': 15, 'count': 0}, {'interval-start': 16, 'interval-end': 31, 'count': 0}, {'interval-start': 32, 'interval-end': 63, 'count': 1}, {'interval-start': 64, 'interval-end': 127, 'count': 1}, {'interval-start': 128, 'interval-end': 255, 'count': 1}, {'interval-start': 256, 'interval-end': 511, 'count': 1}, {'interval-start': 512, 'interval-end': 1023, 'count': 6}, {'interval-start': 1024, 'interval-end': 2047, 'count': 1}, {'interval-start': 2048, 'interval-end': 4095, 'count': 3}], 'Bucket ptr': b'sda'}
+
+The -j option used with -D prints a histogram dictionary per disk device.
+
+# ./biolatency.py -jm
+^C
+{'ts': '2020-12-30 14:42:03', 'val_type': 'msecs', 'data': [{'interval-start': 0, 'interval-end': 1, 'count': 11}, {'interval-start': 2, 'interval-end': 3, 'count': 3}]}
+
+The -j with -m prints a millisecond histogram dictionary. The `value_type` key is set to msecs.
 
 USAGE message:
 
 # ./biolatency -h
-usage: biolatency [-h] [-T] [-Q] [-m] [-D] [-F] [interval] [count]
+usage: biolatency.py [-h] [-T] [-Q] [-m] [-D] [-F] [-j]
+ [interval] [count]
 
 Summarize block device I/O latency as a histogram
 
@@ -311,11 +342,13 @@ optional arguments:
  -m, --milliseconds millisecond histogram
  -D, --disks print a histogram per disk device
  -F, --flags print a histogram per set of I/O flags
+ -j, --json json output
 
 examples:
- ./biolatency # summarize block I/O latency as a histogram
- ./biolatency 1 10 # print 1 second summaries, 10 times
- ./biolatency -mT 1 # 1s summaries, milliseconds, and timestamps
- ./biolatency -Q # include OS queued time in I/O time
- ./biolatency -D # show each disk device separately
- ./biolatency -F # show I/O flags separately
+ ./biolatency # summarize block I/O latency as a histogram
+ ./biolatency 1 10 # print 1 second summaries, 10 times
+ ./biolatency -mT 1 # 1s summaries, milliseconds, and timestamps
+ ./biolatency -Q # include OS queued time in I/O time
+ ./biolatency -D # show each disk device separately
+ ./biolatency -F # show I/O flags separately
+ ./biolatency -j # print a dictionary