lttnganalyses/cli/io.py

   1 # The MIT License (MIT)
   2 #
   3 # Copyright (C) 2015 - Julien Desfossez <jdesfossez@efficios.com>
   4 #               2015 - Antoine Busque <abusque@efficios.com>
   5 #               2015 - Philippe Proulx <pproulx@efficios.com>
   6 #
   7 # Permission is hereby granted, free of charge, to any person obtaining a copy
   8 # of this software and associated documentation files (the "Software"), to deal
   9 # in the Software without restriction, including without limitation the rights
  10 # to use, copy, modify, merge, publish, distribute, sublicense, and/or sell
  11 # copies of the Software, and to permit persons to whom the Software is
  12 # furnished to do so, subject to the following conditions:
  13 #
  14 # The above copyright notice and this permission notice shall be included in
  15 # all copies or substantial portions of the Software.
  16 #
  17 # THE SOFTWARE IS PROVIDED "AS IS", WITHOUT WARRANTY OF ANY KIND, EXPRESS OR
  18 # IMPLIED, INCLUDING BUT NOT LIMITED TO THE WARRANTIES OF MERCHANTABILITY,
  19 # FITNESS FOR A PARTICULAR PURPOSE AND NONINFRINGEMENT. IN NO EVENT SHALL THE
  20 # AUTHORS OR COPYRIGHT HOLDERS BE LIABLE FOR ANY CLAIM, DAMAGES OR OTHER
  21 # LIABILITY, WHETHER IN AN ACTION OF CONTRACT, TORT OR OTHERWISE, ARISING FROM,
  22 # OUT OF OR IN CONNECTION WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS IN THE
  23 # SOFTWARE.
  24
  25 import collections
  26 import operator
  27 import statistics
  28 import sys
  29 from . import mi
  30 from . import termgraph
  31 from ..core import io
  32 from ..common import format_utils
  33 from .command import Command
  34
  35
  36 _UsageTables = collections.namedtuple('_UsageTables', [
  37     'per_proc_read',
  38     'per_proc_write',
  39     'per_file_read',
  40     'per_file_write',
  41     'per_proc_block_read',
  42     'per_proc_block_write',
  43     'per_disk_sector',
  44     'per_disk_request',
  45     'per_disk_rtps',
  46     'per_netif_recv',
  47     'per_netif_send',
  48 ])
  49
  50
  51 class IoAnalysisCommand(Command):
  52     _DESC = """The I/O command."""
  53     _ANALYSIS_CLASS = io.IoAnalysis
  54     _MI_TITLE = 'I/O analysis'
  55     _MI_DESCRIPTION = 'System call/disk latency statistics, system call ' + \
  56                       'latency distribution, system call top latencies, ' + \
  57                       'I/O usage top, and I/O operations log'
  58     _MI_TAGS = [
  59         mi.Tags.IO,
  60         mi.Tags.SYSCALL,
  61         mi.Tags.STATS,
  62         mi.Tags.FREQ,
  63         mi.Tags.LOG,
  64         mi.Tags.TOP,
  65     ]
  66     _MI_TABLE_CLASS_SYSCALL_LATENCY_STATS = 'syscall-latency-stats'
  67     _MI_TABLE_CLASS_PART_LATENCY_STATS = 'disk-latency-stats'
  68     _MI_TABLE_CLASS_FREQ = 'freq'
  69     _MI_TABLE_CLASS_TOP_SYSCALL = 'top-syscall'
  70     _MI_TABLE_CLASS_LOG = 'log'
  71     _MI_TABLE_CLASS_PER_PROCESS_TOP = 'per-process-top'
  72     _MI_TABLE_CLASS_PER_FILE_TOP = 'per-file-top'
  73     _MI_TABLE_CLASS_PER_PROCESS_TOP_BLOCK = 'per-process-top-block'
  74     _MI_TABLE_CLASS_PER_DISK_TOP_SECTOR = 'per-disk-top-sector'
  75     _MI_TABLE_CLASS_PER_DISK_TOP_REQUEST = 'per-disk-top-request'
  76     _MI_TABLE_CLASS_PER_DISK_TOP_RTPS = 'per-disk-top-rps'
  77     _MI_TABLE_CLASS_PER_NETIF_TOP = 'per-netif-top'
  78     _MI_TABLE_CLASSES = [
  79         (
  80             _MI_TABLE_CLASS_SYSCALL_LATENCY_STATS,
  81             'System call latency statistics', [
  82                 ('obj', 'System call category', mi.String),
  83                 ('count', 'Call count', mi.Integer, 'calls'),
  84                 ('min_latency', 'Minimum call latency', mi.Duration),
  85                 ('avg_latency', 'Average call latency', mi.Duration),
  86                 ('max_latency', 'Maximum call latency', mi.Duration),
  87                 ('stdev_latency', 'System call latency standard deviation',
  88                  mi.Duration),
  89             ]
  90         ),
  91         (
  92             _MI_TABLE_CLASS_PART_LATENCY_STATS,
  93             'Partition latency statistics', [
  94                 ('obj', 'Partition', mi.Disk),
  95                 ('count', 'Access count', mi.Integer, 'accesses'),
  96                 ('min_latency', 'Minimum access latency', mi.Duration),
  97                 ('avg_latency', 'Average access latency', mi.Duration),
  98                 ('max_latency', 'Maximum access latency', mi.Duration),
  99                 ('stdev_latency', 'System access latency standard deviation',
 100                  mi.Duration),
 101             ]
 102         ),
 103         (
 104             _MI_TABLE_CLASS_FREQ,
 105             'I/O request latency distribution', [
 106                 ('latency_lower', 'Latency (lower bound)', mi.Duration),
 107                 ('latency_upper', 'Latency (upper bound)', mi.Duration),
 108                 ('count', 'Request count', mi.Integer, 'requests'),
 109             ]
 110         ),
 111         (
 112             _MI_TABLE_CLASS_TOP_SYSCALL,
 113             'Top system call latencies', [
 114                 ('time_range', 'Call time range', mi.TimeRange),
 115                 ('out_of_range', 'System call out of range?', mi.Boolean),
 116                 ('duration', 'Call duration', mi.Duration),
 117                 ('syscall', 'System call', mi.Syscall),
 118                 ('size', 'Read/write size', mi.Size),
 119                 ('process', 'Process', mi.Process),
 120                 ('path', 'File path', mi.Path),
 121                 ('fd', 'File descriptor', mi.Fd),
 122             ]
 123         ),
 124         (
 125             _MI_TABLE_CLASS_LOG,
 126             'I/O operations log', [
 127                 ('time_range', 'Call time range', mi.TimeRange),
 128                 ('out_of_range', 'System call out of range?', mi.Boolean),
 129                 ('duration', 'Call duration', mi.Duration),
 130                 ('syscall', 'System call', mi.Syscall),
 131                 ('size', 'Read/write size', mi.Size),
 132                 ('process', 'Process', mi.Process),
 133                 ('path', 'File path', mi.Path),
 134                 ('fd', 'File descriptor', mi.Fd),
 135             ]
 136         ),
 137         (
 138             _MI_TABLE_CLASS_PER_PROCESS_TOP,
 139             'Per-process top I/O operations', [
 140                 ('process', 'Process', mi.Process),
 141                 ('size', 'Total operations size', mi.Size),
 142                 ('disk_size', 'Disk operations size', mi.Size),
 143                 ('net_size', 'Network operations size', mi.Size),
 144                 ('unknown_size', 'Unknown operations size', mi.Size),
 145             ]
 146         ),
 147         (
 148             _MI_TABLE_CLASS_PER_FILE_TOP,
 149             'Per-file top I/O operations', [
 150                 ('path', 'File path/info', mi.Path),
 151                 ('size', 'Operations size', mi.Size),
 152                 ('fd_owners', 'File descriptor owners', mi.String),
 153             ]
 154         ),
 155         (
 156             _MI_TABLE_CLASS_PER_PROCESS_TOP_BLOCK,
 157             'Per-process top block I/O operations', [
 158                 ('process', 'Process', mi.Process),
 159                 ('size', 'Operations size', mi.Size),
 160             ]
 161         ),
 162         (
 163             _MI_TABLE_CLASS_PER_DISK_TOP_SECTOR,
 164             'Per-disk top sector I/O operations', [
 165                 ('disk', 'Disk', mi.Disk),
 166                 ('count', 'Sector count', mi.Integer, 'sectors'),
 167             ]
 168         ),
 169         (
 170             _MI_TABLE_CLASS_PER_DISK_TOP_REQUEST,
 171             'Per-disk top I/O requests', [
 172                 ('disk', 'Disk', mi.Disk),
 173                 ('count', 'Request count', mi.Integer, 'I/O requests'),
 174             ]
 175         ),
 176         (
 177             _MI_TABLE_CLASS_PER_DISK_TOP_RTPS,
 178             'Per-disk top I/O request time/sector', [
 179                 ('disk', 'Disk', mi.Disk),
 180                 ('rtps', 'Request time/sector', mi.Duration),
 181             ]
 182         ),
 183         (
 184             _MI_TABLE_CLASS_PER_NETIF_TOP,
 185             'Per-network interface top I/O operations', [
 186                 ('netif', 'Network interface', mi.NetIf),
 187                 ('size', 'Operations size', mi.Size),
 188             ]
 189         ),
 190     ]
 191     _LATENCY_STATS_FORMAT = '{:<14} {:>14} {:>14} {:>14} {:>14} {:>14}'
 192     _SECTION_SEPARATOR_STRING = '-' * 89
 193
 194     def _analysis_tick(self, begin_ns, end_ns):
 195         syscall_latency_stats_table = None
 196         disk_latency_stats_table = None
 197         freq_tables = None
 198         top_tables = None
 199         log_table = None
 200         usage_tables = None
 201
 202         if self._args.stats:
 203             syscall_latency_stats_table, disk_latency_stats_table = \
 204                 self._get_latency_stats_result_tables(begin_ns, end_ns)
 205
 206         if self._args.freq:
 207             freq_tables = self._get_freq_result_tables(begin_ns, end_ns)
 208
 209         if self._args.usage:
 210             usage_tables = self._get_usage_result_tables(begin_ns, end_ns)
 211
 212         if self._args.top:
 213             top_tables = self._get_top_result_tables(begin_ns, end_ns)
 214
 215         if self._args.log:
 216             log_table = self._get_log_result_table(begin_ns, end_ns)
 217
 218         if self._mi_mode:
 219             self._mi_append_result_tables([
 220                 log_table,
 221                 syscall_latency_stats_table,
 222                 disk_latency_stats_table,
 223             ])
 224             self._mi_append_result_tables(top_tables)
 225             self._mi_append_result_tables(usage_tables)
 226             self._mi_append_result_tables(freq_tables)
 227         else:
 228             self._print_date(begin_ns, end_ns)
 229
 230             if self._args.usage:
 231                 self._print_usage(usage_tables)
 232
 233             if self._args.stats:
 234                 self._print_latency_stats(syscall_latency_stats_table,
 235                                           disk_latency_stats_table)
 236
 237             if self._args.top:
 238                 self._print_top(top_tables)
 239
 240             if self._args.freq:
 241                 self._print_freq(freq_tables)
 242
 243             if self._args.log:
 244                 self._print_log(log_table)
 245
 246     def _create_summary_result_tables(self):
 247         # TODO: create a summary table here
 248         self._mi_clear_result_tables()
 249
 250     # Filter predicates
 251     def _filter_size(self, size):
 252         if size is None:
 253             return True
 254         if self._args.maxsize is not None and size > self._args.maxsize:
 255             return False
 256         if self._args.minsize is not None and size < self._args.minsize:
 257             return False
 258         return True
 259
 260     def _filter_latency(self, duration):
 261         if self._args.max is not None and duration > self._args.max:
 262             return False
 263         if self._args.min is not None and duration < self._args.min:
 264             return False
 265         return True
 266
 267     def _filter_time_range(self, begin, end):
 268         # Note: we only want to return False only when a request has
 269         # ended and is completely outside the timerange (i.e. begun
 270         # after the end of the time range).
 271         return not (self._args.begin and self._args.end and end and
 272                     begin > self._args.end)
 273
 274     def _filter_io_request(self, io_rq):
 275         return self._filter_size(io_rq.size) and \
 276             self._filter_latency(io_rq.duration) and \
 277             self._filter_time_range(io_rq.begin_ts, io_rq.end_ts)
 278
 279     def _is_io_rq_out_of_range(self, io_rq):
 280         return self._args.begin and io_rq.begin_ts < self._args.begin or \
 281             self._args.end and io_rq.end_ts > self._args.end
 282
 283     def _append_per_proc_read_usage_row(self, proc_stats, result_table):
 284         result_table.append_row(
 285             process=mi.Process(proc_stats.comm, pid=proc_stats.pid,
 286                                tid=proc_stats.tid),
 287             size=mi.Size(proc_stats.total_read),
 288             disk_size=mi.Size(proc_stats.disk_io.read),
 289             net_size=mi.Size(proc_stats.net_io.read),
 290             unknown_size=mi.Size(proc_stats.unk_io.read),
 291         )
 292
 293         return True
 294
 295     def _append_per_proc_write_usage_row(self, proc_stats, result_table):
 296         result_table.append_row(
 297             process=mi.Process(proc_stats.comm, pid=proc_stats.pid,
 298                                tid=proc_stats.tid),
 299             size=mi.Size(proc_stats.total_write),
 300             disk_size=mi.Size(proc_stats.disk_io.write),
 301             net_size=mi.Size(proc_stats.net_io.write),
 302             unknown_size=mi.Size(proc_stats.unk_io.write),
 303         )
 304
 305         return True
 306
 307     def _append_per_proc_block_read_usage_row(self, proc_stats, result_table):
 308         if proc_stats.block_io.read == 0:
 309             return False
 310
 311         if proc_stats.comm:
 312             proc_name = proc_stats.comm
 313         else:
 314             proc_name = None
 315
 316         result_table.append_row(
 317             process=mi.Process(proc_name, pid=proc_stats.pid,
 318                                tid=proc_stats.tid),
 319             size=mi.Size(proc_stats.block_io.read),
 320         )
 321
 322         return True
 323
 324     def _append_per_proc_block_write_usage_row(self, proc_stats, result_table):
 325         if proc_stats.block_io.write == 0:
 326             return False
 327
 328         if proc_stats.comm:
 329             proc_name = proc_stats.comm
 330         else:
 331             proc_name = None
 332
 333         result_table.append_row(
 334             process=mi.Process(proc_name, pid=proc_stats.pid,
 335                                tid=proc_stats.tid),
 336             size=mi.Size(proc_stats.block_io.write),
 337         )
 338
 339         return True
 340
 341     def _append_disk_sector_usage_row(self, disk_stats, result_table):
 342         if disk_stats.total_rq_sectors == 0:
 343             return None
 344
 345         result_table.append_row(
 346             disk=mi.Disk(disk_stats.disk_name),
 347             count=mi.Integer(disk_stats.total_rq_sectors),
 348         )
 349
 350         return True
 351
 352     def _append_disk_request_usage_row(self, disk_stats, result_table):
 353         if disk_stats.rq_count == 0:
 354             return False
 355
 356         result_table.append_row(
 357             disk=mi.Disk(disk_stats.disk_name),
 358             count=mi.Integer(disk_stats.rq_count),
 359         )
 360
 361         return True
 362
 363     def _append_disk_rtps_usage_row(self, disk_stats, result_table):
 364         if disk_stats.rq_count == 0:
 365             return False
 366
 367         avg_latency = (disk_stats.total_rq_duration / disk_stats.rq_count)
 368         result_table.append_row(
 369             disk=mi.Disk(disk_stats.disk_name),
 370             rtps=mi.Duration(avg_latency),
 371         )
 372
 373         return True
 374
 375     def _append_netif_recv_usage_row(self, netif_stats, result_table):
 376         result_table.append_row(
 377             netif=mi.NetIf(netif_stats.name),
 378             size=mi.Size(netif_stats.recv_bytes)
 379         )
 380
 381         return True
 382
 383     def _append_netif_send_usage_row(self, netif_stats, result_table):
 384         result_table.append_row(
 385             netif=mi.NetIf(netif_stats.name),
 386             size=mi.Size(netif_stats.sent_bytes)
 387         )
 388
 389         return True
 390
 391     def _get_file_stats_fd_owners_str(self, file_stats):
 392         fd_by_pid_str = ''
 393
 394         for pid, fd in file_stats.fd_by_pid.items():
 395             comm = self._analysis.tids[pid].comm
 396             fd_by_pid_str += 'fd %d in %s (%s) ' % (fd, comm, pid)
 397
 398         return fd_by_pid_str
 399
 400     def _append_file_read_usage_row(self, file_stats, result_table):
 401         if file_stats.io.read == 0:
 402             return False
 403
 404         fd_owners = self._get_file_stats_fd_owners_str(file_stats)
 405         result_table.append_row(
 406             path=mi.Path(file_stats.filename),
 407             size=mi.Size(file_stats.io.read),
 408             fd_owners=mi.String(fd_owners),
 409         )
 410
 411         return True
 412
 413     def _append_file_write_usage_row(self, file_stats, result_table):
 414         if file_stats.io.write == 0:
 415             return False
 416
 417         fd_owners = self._get_file_stats_fd_owners_str(file_stats)
 418         result_table.append_row(
 419             path=mi.Path(file_stats.filename),
 420             size=mi.Size(file_stats.io.write),
 421             fd_owners=mi.String(fd_owners),
 422         )
 423
 424         return True
 425
 426     def _fill_usage_result_table(self, input_list, append_row_cb,
 427                                  result_table):
 428         count = 0
 429         limit = self._args.limit
 430
 431         for elem in input_list:
 432             if append_row_cb(elem, result_table):
 433                 count += 1
 434
 435                 if limit is not None and count >= limit:
 436                     break
 437
 438     def _fill_per_process_read_usage_result_table(self, result_table):
 439         input_list = sorted(self._analysis.tids.values(),
 440                             key=operator.attrgetter('total_read'),
 441                             reverse=True)
 442         self._fill_usage_result_table(input_list,
 443                                       self._append_per_proc_read_usage_row,
 444                                       result_table)
 445
 446     def _fill_per_process_write_usage_result_table(self, result_table):
 447         input_list = sorted(self._analysis.tids.values(),
 448                             key=operator.attrgetter('total_write'),
 449                             reverse=True)
 450         self._fill_usage_result_table(input_list,
 451                                       self._append_per_proc_write_usage_row,
 452                                       result_table)
 453
 454     def _fill_per_process_block_read_usage_result_table(self, result_table):
 455         input_list = sorted(self._analysis.tids.values(),
 456                             key=operator.attrgetter('block_io.read'),
 457                             reverse=True)
 458         self._fill_usage_result_table(
 459             input_list, self._append_per_proc_block_read_usage_row,
 460             result_table)
 461
 462     def _fill_per_process_block_write_usage_result_table(self, result_table):
 463         input_list = sorted(self._analysis.tids.values(),
 464                             key=operator.attrgetter('block_io.write'),
 465                             reverse=True)
 466         self._fill_usage_result_table(
 467             input_list, self._append_per_proc_block_write_usage_row,
 468             result_table)
 469
 470     def _fill_disk_sector_usage_result_table(self, result_table):
 471         input_list = sorted(self._analysis.disks.values(),
 472                             key=operator.attrgetter('total_rq_sectors'),
 473                             reverse=True)
 474         self._fill_usage_result_table(input_list,
 475                                       self._append_disk_sector_usage_row,
 476                                       result_table)
 477
 478     def _fill_disk_request_usage_result_table(self, result_table):
 479         input_list = sorted(self._analysis.disks.values(),
 480                             key=operator.attrgetter('rq_count'),
 481                             reverse=True)
 482         self._fill_usage_result_table(input_list,
 483                                       self._append_disk_request_usage_row,
 484                                       result_table)
 485
 486     def _fill_disk_rtps_usage_result_table(self, result_table):
 487         input_list = self._analysis.disks.values()
 488         self._fill_usage_result_table(input_list,
 489                                       self._append_disk_rtps_usage_row,
 490                                       result_table)
 491
 492     def _fill_netif_recv_usage_result_table(self, result_table):
 493         input_list = sorted(self._analysis.ifaces.values(),
 494                             key=operator.attrgetter('recv_bytes'),
 495                             reverse=True)
 496         self._fill_usage_result_table(input_list,
 497                                       self._append_netif_recv_usage_row,
 498                                       result_table)
 499
 500     def _fill_netif_send_usage_result_table(self, result_table):
 501         input_list = sorted(self._analysis.ifaces.values(),
 502                             key=operator.attrgetter('sent_bytes'),
 503                             reverse=True)
 504         self._fill_usage_result_table(input_list,
 505                                       self._append_netif_send_usage_row,
 506                                       result_table)
 507
 508     def _fill_file_read_usage_result_table(self, files, result_table):
 509         input_list = sorted(files.values(),
 510                             key=lambda file_stats: file_stats.io.read,
 511                             reverse=True)
 512         self._fill_usage_result_table(input_list,
 513                                       self._append_file_read_usage_row,
 514                                       result_table)
 515
 516     def _fill_file_write_usage_result_table(self, files, result_table):
 517         input_list = sorted(files.values(),
 518                             key=lambda file_stats: file_stats.io.write,
 519                             reverse=True)
 520         self._fill_usage_result_table(input_list,
 521                                       self._append_file_write_usage_row,
 522                                       result_table)
 523
 524     def _fill_file_usage_result_tables(self, read_table, write_table):
 525         files = self._analysis.get_files_stats()
 526         self._fill_file_read_usage_result_table(files, read_table)
 527         self._fill_file_write_usage_result_table(files, write_table)
 528
 529     def _get_usage_result_tables(self, begin, end):
 530         # create result tables
 531         per_proc_read_table = self._mi_create_result_table(
 532             self._MI_TABLE_CLASS_PER_PROCESS_TOP, begin, end, 'read')
 533         per_proc_write_table = self._mi_create_result_table(
 534             self._MI_TABLE_CLASS_PER_PROCESS_TOP, begin, end, 'written')
 535         per_file_read_table = self._mi_create_result_table(
 536             self._MI_TABLE_CLASS_PER_FILE_TOP, begin, end, 'read')
 537         per_file_write_table = self._mi_create_result_table(
 538             self._MI_TABLE_CLASS_PER_FILE_TOP, begin, end, 'written')
 539         per_proc_block_read_table = self._mi_create_result_table(
 540             self._MI_TABLE_CLASS_PER_PROCESS_TOP_BLOCK, begin, end, 'read')
 541         per_proc_block_write_table = self._mi_create_result_table(
 542             self._MI_TABLE_CLASS_PER_PROCESS_TOP_BLOCK, begin, end, 'written')
 543         per_disk_sector_table = self._mi_create_result_table(
 544             self._MI_TABLE_CLASS_PER_DISK_TOP_SECTOR, begin, end)
 545         per_disk_request_table = self._mi_create_result_table(
 546             self._MI_TABLE_CLASS_PER_DISK_TOP_REQUEST, begin, end)
 547         per_disk_rtps_table = self._mi_create_result_table(
 548             self._MI_TABLE_CLASS_PER_DISK_TOP_RTPS, begin, end)
 549         per_netif_recv_table = self._mi_create_result_table(
 550             self._MI_TABLE_CLASS_PER_NETIF_TOP, begin, end, 'received')
 551         per_netif_send_table = self._mi_create_result_table(
 552             self._MI_TABLE_CLASS_PER_NETIF_TOP, begin, end, 'sent')
 553
 554         # fill result tables
 555         self._fill_per_process_read_usage_result_table(per_proc_read_table)
 556         self._fill_per_process_write_usage_result_table(per_proc_write_table)
 557         self._fill_file_usage_result_tables(per_file_read_table,
 558                                             per_file_write_table)
 559         self._fill_per_process_block_read_usage_result_table(
 560             per_proc_block_read_table)
 561         self._fill_per_process_block_write_usage_result_table(
 562             per_proc_block_write_table)
 563         self._fill_disk_sector_usage_result_table(per_disk_sector_table)
 564         self._fill_disk_request_usage_result_table(per_disk_request_table)
 565         self._fill_disk_rtps_usage_result_table(per_disk_rtps_table)
 566         self._fill_netif_recv_usage_result_table(per_netif_recv_table)
 567         self._fill_netif_send_usage_result_table(per_netif_send_table)
 568
 569         return _UsageTables(
 570             per_proc_read=per_proc_read_table,
 571             per_proc_write=per_proc_write_table,
 572             per_file_read=per_file_read_table,
 573             per_file_write=per_file_write_table,
 574             per_proc_block_read=per_proc_block_read_table,
 575             per_proc_block_write=per_proc_block_write_table,
 576             per_disk_sector=per_disk_sector_table,
 577             per_disk_request=per_disk_request_table,
 578             per_disk_rtps=per_disk_rtps_table,
 579             per_netif_recv=per_netif_recv_table,
 580             per_netif_send=per_netif_send_table,
 581         )
 582
 583     def _print_per_proc_io(self, result_table, title):
 584         header_format = '{:<25} {:<10} {:<10} {:<10}'
 585         label_header = header_format.format(
 586             'Process', 'Disk', 'Net', 'Unknown'
 587         )
 588
 589         def get_label(row):
 590             label_format = '{:<25} {:>10} {:>10} {:>10}'
 591             if row.process.pid is None:
 592                 pid_str = 'unknown (tid=%d)' % (row.process.tid)
 593             else:
 594                 pid_str = str(row.process.pid)
 595
 596             label = label_format.format(
 597                 '%s (%s)' % (row.process.name, pid_str),
 598                 format_utils.format_size(row.disk_size.value),
 599                 format_utils.format_size(row.net_size.value),
 600                 format_utils.format_size(row.unknown_size.value)
 601             )
 602
 603             return label
 604
 605         graph = termgraph.BarGraph(
 606             title='Per-process I/O ' + title,
 607             label_header=label_header,
 608             get_value=lambda row: row.size.value,
 609             get_value_str=format_utils.format_size,
 610             get_label=get_label,
 611             data=result_table.rows
 612         )
 613
 614         graph.print_graph()
 615
 616     def _print_per_proc_block_io(self, result_table, title):
 617         def get_label(row):
 618             proc_name = row.process.name
 619
 620             if not proc_name:
 621                 proc_name = 'unknown'
 622
 623             if row.process.pid is None:
 624                 pid_str = 'unknown (tid={})'.format(row.process.tid)
 625             else:
 626                 pid_str = str(row.process.pid)
 627
 628             return '{} (pid={})'.format(proc_name, pid_str)
 629
 630         graph = termgraph.BarGraph(
 631             title='Block I/O ' + title,
 632             label_header='Process',
 633             get_value=lambda row: row.size.value,
 634             get_value_str=format_utils.format_size,
 635             get_label=get_label,
 636             data=result_table.rows
 637         )
 638
 639         graph.print_graph()
 640
 641     def _print_per_disk_sector(self, result_table):
 642         graph = termgraph.BarGraph(
 643             title='Disk Requests Sector Count',
 644             label_header='Disk',
 645             unit='sectors',
 646             get_value=lambda row: row.count.value,
 647             get_label=lambda row: row.disk.name,
 648             data=result_table.rows
 649         )
 650
 651         graph.print_graph()
 652
 653     def _print_per_disk_request(self, result_table):
 654         graph = termgraph.BarGraph(
 655             title='Disk Request Count',
 656             label_header='Disk',
 657             unit='requests',
 658             get_value=lambda row: row.count.value,
 659             get_label=lambda row: row.disk.name,
 660             data=result_table.rows
 661         )
 662
 663         graph.print_graph()
 664
 665     def _print_per_disk_rtps(self, result_table):
 666         graph = termgraph.BarGraph(
 667             title='Disk Request Average Latency',
 668             label_header='Disk',
 669             unit='ms',
 670             get_value=lambda row: row.rtps.value / 1000000,
 671             get_label=lambda row: row.disk.name,
 672             data=result_table.rows
 673         )
 674
 675         graph.print_graph()
 676
 677     def _print_per_netif_io(self, result_table, title):
 678         graph = termgraph.BarGraph(
 679             title='Network ' + title + ' Bytes',
 680             label_header='Interface',
 681             get_value=lambda row: row.size.value,
 682             get_value_str=format_utils.format_size,
 683             get_label=lambda row: row.netif.name,
 684             data=result_table.rows
 685         )
 686
 687         graph.print_graph()
 688
 689     def _print_per_file_io(self, result_table, title):
 690         # FIXME add option to show FD owners
 691         # FIXME why are read and write values the same?
 692         graph = termgraph.BarGraph(
 693             title='Per-file I/O ' + title,
 694             label_header='Path',
 695             get_value=lambda row: row.size.value,
 696             get_value_str=format_utils.format_size,
 697             get_label=lambda row: row.path.path,
 698             data=result_table.rows
 699         )
 700
 701         graph.print_graph()
 702
 703     def _print_usage(self, usage_tables):
 704         self._print_per_proc_io(usage_tables.per_proc_read, 'Read')
 705         self._print_per_proc_io(usage_tables.per_proc_write, 'Write')
 706         self._print_per_file_io(usage_tables.per_file_read, 'Read')
 707         self._print_per_file_io(usage_tables.per_file_write, 'Write')
 708         self._print_per_proc_block_io(usage_tables.per_proc_block_read, 'Read')
 709         self._print_per_proc_block_io(
 710             usage_tables.per_proc_block_write, 'Write'
 711         )
 712         self._print_per_disk_sector(usage_tables.per_disk_sector)
 713         self._print_per_disk_request(usage_tables.per_disk_request)
 714         self._print_per_disk_rtps(usage_tables.per_disk_rtps)
 715         self._print_per_netif_io(usage_tables.per_netif_recv, 'Received')
 716         self._print_per_netif_io(usage_tables.per_netif_send, 'Sent')
 717
 718     def _fill_freq_result_table(self, duration_list, result_table):
 719         if not duration_list:
 720             return
 721
 722         # The number of bins for the histogram
 723         resolution = self._args.freq_resolution
 724
 725         min_duration = min(duration_list)
 726         max_duration = max(duration_list)
 727         # ns to µs
 728         min_duration /= 1000
 729         max_duration /= 1000
 730
 731         step = (max_duration - min_duration) / resolution
 732
 733         if step == 0:
 734             return
 735
 736         buckets = []
 737         values = []
 738
 739         for i in range(resolution):
 740             buckets.append(i * step)
 741             values.append(0)
 742
 743         for duration in duration_list:
 744             duration /= 1000
 745             index = min(int((duration - min_duration) / step), resolution - 1)
 746             values[index] += 1
 747
 748         for index, value in enumerate(values):
 749             result_table.append_row(
 750                 latency_lower=mi.Duration.from_us(index * step + min_duration),
 751                 latency_upper=mi.Duration.from_us((index + 1) * step +
 752                                                   min_duration),
 753                 count=mi.Integer(value),
 754             )
 755
 756     def _get_disk_freq_result_tables(self, begin, end):
 757         result_tables = []
 758
 759         for disk in self._analysis.disks.values():
 760             rq_durations = [rq.duration for rq in disk.rq_list if
 761                             self._filter_io_request(rq)]
 762             subtitle = 'disk: {}'.format(disk.disk_name)
 763             result_table = \
 764                 self._mi_create_result_table(self._MI_TABLE_CLASS_FREQ,
 765                                              begin, end, subtitle)
 766             self._fill_freq_result_table(rq_durations, result_table)
 767             result_tables.append(result_table)
 768
 769         return result_tables
 770
 771     def _get_syscall_freq_result_tables(self, begin, end):
 772         open_table = \
 773             self._mi_create_result_table(self._MI_TABLE_CLASS_FREQ,
 774                                          begin, end, 'open')
 775         read_table = \
 776             self._mi_create_result_table(self._MI_TABLE_CLASS_FREQ,
 777                                          begin, end, 'read')
 778         write_table = \
 779             self._mi_create_result_table(self._MI_TABLE_CLASS_FREQ,
 780                                          begin, end, 'write')
 781         sync_table = \
 782             self._mi_create_result_table(self._MI_TABLE_CLASS_FREQ,
 783                                          begin, end, 'sync')
 784         self._fill_freq_result_table([io_rq.duration for io_rq in
 785                                       self._analysis.open_io_requests if
 786                                       self._filter_io_request(io_rq)],
 787                                      open_table)
 788         self._fill_freq_result_table([io_rq.duration for io_rq in
 789                                       self._analysis.read_io_requests if
 790                                       self._filter_io_request(io_rq)],
 791                                      read_table)
 792         self._fill_freq_result_table([io_rq.duration for io_rq in
 793                                       self._analysis.write_io_requests if
 794                                       self._filter_io_request(io_rq)],
 795                                      write_table)
 796         self._fill_freq_result_table([io_rq.duration for io_rq in
 797                                       self._analysis.sync_io_requests if
 798                                       self._filter_io_request(io_rq)],
 799                                      sync_table)
 800
 801         return [open_table, read_table, write_table, sync_table]
 802
 803     def _get_freq_result_tables(self, begin, end):
 804         syscall_tables = self._get_syscall_freq_result_tables(begin, end)
 805         disk_tables = self._get_disk_freq_result_tables(begin, end)
 806
 807         return syscall_tables + disk_tables
 808
 809     def _print_one_freq(self, result_table):
 810         graph = termgraph.FreqGraph(
 811             data=result_table.rows,
 812             get_value=lambda row: row.count.value,
 813             get_lower_bound=lambda row: row.latency_lower.to_us(),
 814             title='{} {}'.format(result_table.title, result_table.subtitle),
 815             unit='µs'
 816         )
 817
 818         graph.print_graph()
 819
 820     def _print_freq(self, freq_tables):
 821         for freq_table in freq_tables:
 822             self._print_one_freq(freq_table)
 823
 824     def _append_log_row(self, io_rq, result_table):
 825         if io_rq.size is None:
 826             size = mi.Empty()
 827         else:
 828             size = mi.Size(io_rq.size)
 829
 830         tid = io_rq.tid
 831         proc_stats = self._analysis.tids[tid]
 832         proc_name = proc_stats.comm
 833
 834         # TODO: handle fd_in/fd_out for RW type operations
 835         if io_rq.fd is None:
 836             path = mi.Empty()
 837             fd = mi.Empty()
 838         else:
 839             fd = mi.Fd(io_rq.fd)
 840             parent_proc = proc_stats
 841
 842             if parent_proc.pid is not None:
 843                 parent_proc = self._analysis.tids[parent_proc.pid]
 844
 845             fd_stats = parent_proc.get_fd(io_rq.fd, io_rq.end_ts)
 846
 847             if fd_stats is not None:
 848                 path = mi.Path(fd_stats.filename)
 849             else:
 850                 path = mi.Unknown()
 851
 852         result_table.append_row(
 853             time_range=mi.TimeRange(io_rq.begin_ts, io_rq.end_ts),
 854             out_of_range=mi.Boolean(self._is_io_rq_out_of_range(io_rq)),
 855             duration=mi.Duration(io_rq.duration),
 856             syscall=mi.Syscall(io_rq.syscall_name),
 857             size=size,
 858             process=mi.Process(proc_name, tid=tid),
 859             path=path,
 860             fd=fd,
 861         )
 862
 863     def _fill_log_result_table(self, rq_list, sort_key, is_top, result_table):
 864         if not rq_list:
 865             return
 866
 867         count = 0
 868
 869         for io_rq in sorted(rq_list, key=operator.attrgetter(sort_key),
 870                             reverse=is_top):
 871             if is_top and count > self._args.limit:
 872                 break
 873
 874             self._append_log_row(io_rq, result_table)
 875             count += 1
 876
 877     def _fill_log_result_table_from_io_requests(self, io_requests, sort_key,
 878                                                 is_top, result_table):
 879         io_requests = [io_rq for io_rq in io_requests if
 880                        self._filter_io_request(io_rq)]
 881         self._fill_log_result_table(io_requests, sort_key, is_top,
 882                                     result_table)
 883
 884     def _get_top_result_tables(self, begin, end):
 885         open_table = \
 886             self._mi_create_result_table(self._MI_TABLE_CLASS_TOP_SYSCALL,
 887                                          begin, end, 'open')
 888         read_table = \
 889             self._mi_create_result_table(self._MI_TABLE_CLASS_TOP_SYSCALL,
 890                                          begin, end, 'read')
 891         write_table = \
 892             self._mi_create_result_table(self._MI_TABLE_CLASS_TOP_SYSCALL,
 893                                          begin, end, 'write')
 894         sync_table = \
 895             self._mi_create_result_table(self._MI_TABLE_CLASS_TOP_SYSCALL,
 896                                          begin, end, 'sync')
 897         self._fill_log_result_table_from_io_requests(
 898             self._analysis.open_io_requests, 'duration', True, open_table)
 899         self._fill_log_result_table_from_io_requests(
 900             self._analysis.read_io_requests, 'duration', True, read_table)
 901         self._fill_log_result_table_from_io_requests(
 902             self._analysis.write_io_requests, 'duration', True, write_table)
 903         self._fill_log_result_table_from_io_requests(
 904             self._analysis.sync_io_requests, 'duration', True, sync_table)
 905
 906         return [open_table, read_table, write_table, sync_table]
 907
 908     def _print_log_row(self, row):
 909         fmt = '{:<40} {:<16} {:>16} {:>11}  {:<24} {:<8} {:<14}'
 910         time_range_str = format_utils.format_time_range(
 911             row.time_range.begin,
 912             row.time_range.end,
 913             self._args.multi_day,
 914             self._args.gmt
 915         )
 916         duration_str = '%0.03f' % row.duration.to_us()
 917
 918         if type(row.size) is mi.Empty:
 919             size = 'N/A'
 920         else:
 921             size = format_utils.format_size(row.size.value)
 922
 923         tid = row.process.tid
 924         proc_name = row.process.name
 925
 926         if type(row.fd) is mi.Empty:
 927             file_str = 'N/A'
 928         else:
 929             if type(row.path) is mi.Unknown:
 930                 path = 'unknown'
 931             else:
 932                 path = row.path.path
 933
 934             file_str = '%s (fd=%s)' % (path, row.fd.fd)
 935
 936         if row.out_of_range.value:
 937             time_range_str += '*'
 938             duration_str += '*'
 939         else:
 940             time_range_str += ' '
 941             duration_str += ' '
 942
 943         print(fmt.format(time_range_str, row.syscall.name, duration_str,
 944                          size, proc_name, tid, file_str))
 945
 946     def _print_log(self, result_table):
 947         if not result_table.rows:
 948             return
 949
 950         has_out_of_range_rq = False
 951
 952         print()
 953         fmt = '{} {} (usec)'
 954         print(fmt.format(result_table.title, result_table.subtitle))
 955         header_fmt = '{:<20} {:<20} {:<16} {:<23} {:<5} {:<24} {:<8} {:<14}'
 956         print(header_fmt.format(
 957             'Begin', 'End', 'Name', 'Duration (usec)', 'Size', 'Proc', 'PID',
 958             'Filename'))
 959
 960         for row in result_table.rows:
 961             self._print_log_row(row)
 962
 963             if not has_out_of_range_rq and row.out_of_range.value:
 964                 has_out_of_range_rq = True
 965
 966         if has_out_of_range_rq:
 967             print('*: Syscalls started and/or completed outside of the '
 968                   'range specified')
 969
 970     def _print_top(self, top_tables):
 971         for table in top_tables:
 972             self._print_log(table)
 973
 974     def _get_log_result_table(self, begin, end):
 975         log_table = self._mi_create_result_table(self._MI_TABLE_CLASS_LOG,
 976                                                  begin, end)
 977         self._fill_log_result_table_from_io_requests(
 978             self._analysis.io_requests, 'begin_ts', False, log_table)
 979
 980         return log_table
 981
 982     def _append_latency_stats_row(self, obj, rq_durations, result_table):
 983         rq_count = len(rq_durations)
 984         total_duration = sum(rq_durations)
 985
 986         if len(rq_durations) > 0:
 987             min_duration = min(rq_durations)
 988             max_duration = max(rq_durations)
 989         else:
 990             min_duration = 0
 991             max_duration = 0
 992
 993         if rq_count < 2:
 994             stdev = mi.Unknown()
 995         else:
 996             stdev = mi.Duration(statistics.stdev(rq_durations))
 997
 998         if rq_count > 0:
 999             avg = total_duration / rq_count
1000         else:
1001             avg = 0
1002
1003         result_table.append_row(
1004             obj=obj,
1005             count=mi.Integer(rq_count),
1006             min_latency=mi.Duration(min_duration),
1007             avg_latency=mi.Duration(avg),
1008             max_latency=mi.Duration(max_duration),
1009             stdev_latency=stdev,
1010         )
1011
1012     def _append_latency_stats_row_from_requests(self, obj, io_requests,
1013                                                 result_table):
1014         rq_durations = [io_rq.duration for io_rq in io_requests if
1015                         self._filter_io_request(io_rq)]
1016         self._append_latency_stats_row(obj, rq_durations, result_table)
1017
1018     def _get_syscall_latency_stats_result_table(self, begin, end):
1019         result_table = self._mi_create_result_table(
1020             self._MI_TABLE_CLASS_SYSCALL_LATENCY_STATS, begin, end)
1021         append_fn = self._append_latency_stats_row_from_requests
1022         append_fn(mi.String('Open'), self._analysis.open_io_requests,
1023                   result_table)
1024         append_fn(mi.String('Read'), self._analysis.read_io_requests,
1025                   result_table)
1026         append_fn(mi.String('Write'), self._analysis.write_io_requests,
1027                   result_table)
1028         append_fn(mi.String('Sync'), self._analysis.sync_io_requests,
1029                   result_table)
1030
1031         return result_table
1032
1033     def _get_disk_latency_stats_result_table(self, begin, end):
1034         if not self._analysis.disks:
1035             return
1036
1037         result_table = self._mi_create_result_table(
1038             self._MI_TABLE_CLASS_PART_LATENCY_STATS, begin, end)
1039
1040         for disk in self._analysis.disks.values():
1041             if disk.rq_count:
1042                 rq_durations = [rq.duration for rq in disk.rq_list if
1043                                 self._filter_io_request(rq)]
1044                 disk = mi.Disk(disk.disk_name)
1045                 self._append_latency_stats_row(disk, rq_durations,
1046                                                result_table)
1047
1048         return result_table
1049
1050     def _get_latency_stats_result_tables(self, begin, end):
1051         syscall_tbl = self._get_syscall_latency_stats_result_table(begin, end)
1052         disk_tbl = self._get_disk_latency_stats_result_table(begin, end)
1053
1054         return syscall_tbl, disk_tbl
1055
1056     def _print_latency_stats_row(self, row):
1057         if type(row.stdev_latency) is mi.Unknown:
1058             stdev = '?'
1059         else:
1060             stdev = '%0.03f' % row.stdev_latency.to_us()
1061
1062         avg = '%0.03f' % row.avg_latency.to_us()
1063         min_duration = '%0.03f' % row.min_latency.to_us()
1064         max_duration = '%0.03f' % row.max_latency.to_us()
1065
1066         print(IoAnalysisCommand._LATENCY_STATS_FORMAT.format(
1067             str(row.obj), row.count.value, min_duration,
1068             avg, max_duration, stdev))
1069
1070     def _print_syscall_latency_stats(self, stats_table):
1071         print('\nSyscalls latency statistics (usec):')
1072         print(IoAnalysisCommand._LATENCY_STATS_FORMAT.format(
1073             'Type', 'Count', 'Min', 'Average', 'Max', 'Stdev'))
1074         print(IoAnalysisCommand._SECTION_SEPARATOR_STRING)
1075
1076         for row in stats_table.rows:
1077             self._print_latency_stats_row(row)
1078
1079     def _print_disk_latency_stats(self, stats_table):
1080         if not stats_table.rows:
1081             return
1082
1083         print('\nDisk latency statistics (usec):')
1084         print(IoAnalysisCommand._LATENCY_STATS_FORMAT.format(
1085             'Name', 'Count', 'Min', 'Average', 'Max', 'Stdev'))
1086         print(IoAnalysisCommand._SECTION_SEPARATOR_STRING)
1087
1088         for row in stats_table.rows:
1089             self._print_latency_stats_row(row)
1090
1091     def _print_latency_stats(self, syscall_latency_stats_table,
1092                              disk_latency_stats_table):
1093         self._print_syscall_latency_stats(syscall_latency_stats_table)
1094         self._print_disk_latency_stats(disk_latency_stats_table)
1095
1096     def _add_arguments(self, ap):
1097         Command._add_proc_filter_args(ap)
1098         Command._add_min_max_args(ap)
1099         Command._add_log_args(
1100             ap, help='Output the I/O requests in chronological order')
1101         Command._add_top_args(
1102             ap, help='Output the top I/O latencies by category')
1103         Command._add_stats_args(ap, help='Output the I/O latency statistics')
1104         Command._add_freq_args(
1105             ap, help='Output the I/O latency frequency distribution')
1106         ap.add_argument('--usage', action='store_true',
1107                         help='Output the I/O usage')
1108         ap.add_argument('--minsize', type=float,
1109                         help='Filter out, I/O operations working with '
1110                         'less that minsize bytes')
1111         ap.add_argument('--maxsize', type=float,
1112                         help='Filter out, I/O operations working with '
1113                         'more that maxsize bytes')
1114
1115
1116 def _run(mi_mode):
1117     iocmd = IoAnalysisCommand(mi_mode=mi_mode)
1118     iocmd.run()
1119
1120
1121 def _runstats(mi_mode):
1122     sys.argv.insert(1, '--stats')
1123     _run(mi_mode)
1124
1125
1126 def _runlog(mi_mode):
1127     sys.argv.insert(1, '--log')
1128     _run(mi_mode)
1129
1130
1131 def _runfreq(mi_mode):
1132     sys.argv.insert(1, '--freq')
1133     _run(mi_mode)
1134
1135
1136 def _runlatencytop(mi_mode):
1137     sys.argv.insert(1, '--top')
1138     _run(mi_mode)
1139
1140
1141 def _runusage(mi_mode):
1142     sys.argv.insert(1, '--usage')
1143     _run(mi_mode)
1144
1145
1146 def runstats():
1147     _runstats(mi_mode=False)
1148
1149
1150 def runlog():
1151     _runlog(mi_mode=False)
1152
1153
1154 def runfreq():
1155     _runfreq(mi_mode=False)
1156
1157
1158 def runlatencytop():
1159     _runlatencytop(mi_mode=False)
1160
1161
1162 def runusage():
1163     _runusage(mi_mode=False)
1164
1165
1166 def runstats_mi():
1167     _runstats(mi_mode=True)
1168
1169
1170 def runlog_mi():
1171     _runlog(mi_mode=True)
1172
1173
1174 def runfreq_mi():
1175     _runfreq(mi_mode=True)
1176
1177
1178 def runlatencytop_mi():
1179     _runlatencytop(mi_mode=True)
1180
1181
1182 def runusage_mi():
1183     _runusage(mi_mode=True)