Commit | Line | Data |
---|---|---|
4ed24f86 JD |
1 | #!/usr/bin/env python3 |
2 | # | |
3 | # The MIT License (MIT) | |
4 | # | |
a3fa57c0 | 5 | # Copyright (C) 2015 - Julien Desfossez <jdesfossez@efficios.com> |
6cd52af3 | 6 | # 2015 - Antoine Busque <abusque@efficios.com> |
4ed24f86 JD |
7 | # |
8 | # Permission is hereby granted, free of charge, to any person obtaining a copy | |
9 | # of this software and associated documentation files (the "Software"), to deal | |
10 | # in the Software without restriction, including without limitation the rights | |
11 | # to use, copy, modify, merge, publish, distribute, sublicense, and/or sell | |
12 | # copies of the Software, and to permit persons to whom the Software is | |
13 | # furnished to do so, subject to the following conditions: | |
14 | # | |
15 | # The above copyright notice and this permission notice shall be included in | |
16 | # all copies or substantial portions of the Software. | |
17 | # | |
18 | # THE SOFTWARE IS PROVIDED "AS IS", WITHOUT WARRANTY OF ANY KIND, EXPRESS OR | |
19 | # IMPLIED, INCLUDING BUT NOT LIMITED TO THE WARRANTIES OF MERCHANTABILITY, | |
20 | # FITNESS FOR A PARTICULAR PURPOSE AND NONINFRINGEMENT. IN NO EVENT SHALL THE | |
21 | # AUTHORS OR COPYRIGHT HOLDERS BE LIABLE FOR ANY CLAIM, DAMAGES OR OTHER | |
22 | # LIABILITY, WHETHER IN AN ACTION OF CONTRACT, TORT OR OTHERWISE, ARISING FROM, | |
23 | # OUT OF OR IN CONNECTION WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS IN THE | |
24 | # SOFTWARE. | |
25 | ||
a9c9a2a6 | 26 | from .command import Command |
6cd52af3 | 27 | import lttnganalyses.io |
a9c9a2a6 JD |
28 | from linuxautomaton import common, sv |
29 | from ascii_graph import Pyasciigraph | |
30 | import operator | |
31 | import statistics | |
32 | ||
33 | ||
087e5d00 | 34 | class IoAnalysisCommand(Command): |
a9c9a2a6 JD |
35 | _VERSION = '0.1.0' |
36 | _DESC = """The I/O command.""" | |
37 | ||
38 | def __init__(self): | |
39 | super().__init__(self._add_arguments, | |
40 | enable_proc_filter_args=True, | |
41 | enable_max_min_args=True, | |
42 | enable_max_min_size_arg=True, | |
1c0f0e3c | 43 | enable_log_arg=True) |
a9c9a2a6 JD |
44 | |
45 | def _validate_transform_args(self): | |
46 | self._arg_extra = self._args.extra | |
1c0f0e3c JD |
47 | self._arg_usage = self._args.usage |
48 | self._arg_stats = self._args.latencystats | |
275bdbb4 | 49 | self._arg_latencytop = self._args.latencytop |
1c0f0e3c JD |
50 | self._arg_freq = self._args.latencyfreq |
51 | self._arg_freq_resolution = self._args.freq_resolution | |
52 | ||
275bdbb4 | 53 | def _default_args(self, stats, log, freq, usage, latencytop): |
1c0f0e3c JD |
54 | if stats: |
55 | self._arg_stats = True | |
56 | if log: | |
57 | self._arg_log = True | |
58 | if freq: | |
59 | self._arg_freq = True | |
60 | if usage: | |
61 | self._arg_usage = True | |
275bdbb4 JD |
62 | if latencytop: |
63 | self._arg_latencytop = True | |
1c0f0e3c | 64 | |
275bdbb4 JD |
65 | def run(self, stats=False, log=False, freq=False, usage=False, |
66 | latencytop=False): | |
a9c9a2a6 JD |
67 | # parse arguments first |
68 | self._parse_args() | |
69 | # validate, transform and save specific arguments | |
70 | self._validate_transform_args() | |
1c0f0e3c | 71 | # handle the default args for different executables |
275bdbb4 | 72 | self._default_args(stats, log, freq, usage, latencytop) |
a9c9a2a6 JD |
73 | # open the trace |
74 | self._open_trace() | |
75 | # create the appropriate analysis/analyses | |
76 | self._create_analysis() | |
77 | # run the analysis | |
7a68fd89 | 78 | self._run_analysis(self._reset_total, self._refresh) |
a9c9a2a6 | 79 | # print results |
da6d0842 | 80 | self._print_results(self.start_ns, self.trace_end_ts) |
a9c9a2a6 JD |
81 | # close the trace |
82 | self._close_trace() | |
83 | ||
1c0f0e3c JD |
84 | def run_stats(self): |
85 | self.run(stats=True) | |
86 | ||
275bdbb4 JD |
87 | def run_latencytop(self): |
88 | self.run(latencytop=True) | |
89 | ||
1c0f0e3c JD |
90 | def run_log(self): |
91 | self.run(log=True) | |
92 | ||
93 | def run_freq(self): | |
94 | self.run(freq=True) | |
95 | ||
96 | def run_usage(self): | |
97 | self.run(usage=True) | |
98 | ||
a9c9a2a6 | 99 | def _create_analysis(self): |
6cd52af3 | 100 | self._analysis = lttnganalyses.io.IoAnalysis(self.state) |
a9c9a2a6 | 101 | |
a9c9a2a6 | 102 | def _refresh(self, begin, end): |
da6d0842 | 103 | self._print_results(begin, end) |
a9c9a2a6 JD |
104 | self._reset_total(end) |
105 | ||
882fcd19 AB |
106 | # Filter predicates |
107 | def _filter_process(self, proc): | |
108 | if self._arg_proc_list and proc.comm not in self._arg_proc_list: | |
109 | return False | |
110 | if self._arg_pid_list and str(proc.pid) not in self._arg_pid_list: | |
111 | return False | |
112 | return True | |
113 | ||
114 | def _filter_size(self, size): | |
115 | if size is None: | |
116 | return True | |
117 | if self._arg_maxsize is not None and size > self._arg_maxsize: | |
118 | return False | |
119 | if self._arg_minsize is not None and size < self._arg_minsize: | |
120 | return False | |
121 | return True | |
122 | ||
123 | def _filter_latency(self, duration): | |
124 | if self._arg_max is not None and (duration/1000) > self._arg_max: | |
125 | return False | |
126 | if self._arg_min is not None and (duration/1000) < self._arg_min: | |
127 | return False | |
128 | return True | |
129 | ||
88cfa546 AB |
130 | def _print_ascii_graph(self, input_list, get_datum_cb, graph_label, |
131 | graph_args={}): | |
132 | """Print an ascii graph for given data | |
133 | ||
134 | This method wraps the ascii_graph module and facilitates the | |
135 | printing of a graph with a limited number of lines. | |
136 | ||
137 | Args: | |
138 | input_list (list): A list of objects from which the data | |
139 | for the graph will be generated. | |
140 | ||
141 | get_datum_cb (function): function that takes a single | |
142 | object from the input list as an argument, and returns a | |
143 | datum tuple for the graph, of the form (string, int). The | |
144 | string element is printed as is in the graph, and the int | |
145 | is the numeric value corresponding to this graph entry. | |
146 | ||
147 | graph_label (string): Label used to identify the printed | |
148 | graph. | |
149 | ||
150 | graph_args (dict, optional): Dict of keyword args to be | |
151 | passed to the graph() function as is. | |
152 | """ | |
153 | count = 0 | |
154 | limit = self._arg_limit | |
155 | graph = Pyasciigraph() | |
156 | data = [] | |
157 | ||
158 | for elem in input_list: | |
159 | datum = get_datum_cb(elem) | |
160 | if datum is not None: | |
161 | data.append(datum) | |
162 | count += 1 | |
163 | if limit is not None and count >= limit: | |
164 | break | |
165 | ||
166 | for line in graph.graph(graph_label, data, **graph_args): | |
167 | print(line) | |
168 | ||
91765fd2 | 169 | # Stats by files methods |
a9c9a2a6 JD |
170 | def add_fd_dict(self, tid, fd, files): |
171 | if fd.read == 0 and fd.write == 0: | |
172 | return | |
179eb1ff JD |
173 | pid = tid.pid |
174 | if pid is None: | |
175 | pid = 'unknown (tid=%d)' % (tid.tid) | |
176 | else: | |
177 | pid = str(pid) | |
73b71522 AB |
178 | if fd.filename.startswith('pipe') or \ |
179 | fd.filename.startswith('socket') or \ | |
180 | fd.filename.startswith('anon_inode') or \ | |
181 | fd.filename.startswith('unknown'): | |
182 | filename = '%s (%s)' % (fd.filename, tid.comm) | |
a9c9a2a6 | 183 | files[filename] = {} |
73b71522 AB |
184 | files[filename]['read'] = fd.read |
185 | files[filename]['write'] = fd.write | |
186 | files[filename]['name'] = filename | |
179eb1ff JD |
187 | files[filename]['other'] = ['fd %d in %s (%s)' % (fd.fd, |
188 | tid.comm, pid)] | |
a9c9a2a6 JD |
189 | else: |
190 | # merge counters of shared files | |
191 | filename = fd.filename | |
192 | if filename not in files.keys(): | |
193 | files[filename] = {} | |
73b71522 AB |
194 | files[filename]['read'] = fd.read |
195 | files[filename]['write'] = fd.write | |
196 | files[filename]['name'] = filename | |
179eb1ff JD |
197 | files[filename]['other'] = ['fd %d in %s (%s)' % |
198 | (fd.fd, tid.comm, pid)] | |
73b71522 | 199 | files[filename]['tids'] = [tid.tid] |
a9c9a2a6 | 200 | else: |
73b71522 AB |
201 | files[filename]['read'] += fd.read |
202 | files[filename]['write'] += fd.write | |
179eb1ff | 203 | files[filename]['other'].append('fd %d in %s (%s)' % |
a9c9a2a6 | 204 | (fd.fd, tid.comm, |
179eb1ff | 205 | pid)) |
a9c9a2a6 JD |
206 | |
207 | def create_files_dict(self): | |
208 | files = {} | |
209 | for tid in self.state.tids.values(): | |
882fcd19 | 210 | if not self._filter_process(tid): |
a9c9a2a6 JD |
211 | continue |
212 | for fd in tid.fds.values(): | |
213 | self.add_fd_dict(tid, fd, files) | |
214 | for fd in tid.closed_fds.values(): | |
215 | self.add_fd_dict(tid, fd, files) | |
216 | return files | |
217 | ||
91765fd2 AB |
218 | # I/O Top output methods |
219 | def _get_read_datum(self, proc_stats): | |
220 | if not self._filter_process(proc_stats): | |
221 | return None | |
222 | ||
223 | if proc_stats.pid is None: | |
224 | pid_str = 'unknown (tid=%d)' % (proc_stats.tid) | |
225 | else: | |
226 | pid_str = str(proc_stats.pid) | |
227 | ||
228 | format_str = '{:>10} {:<25} {:>9} file {:>9} net {:>9} unknown' | |
229 | output_str = format_str.format( | |
230 | common.convert_size(proc_stats.total_read, padding_after=True), | |
231 | '%s (%s)' % (proc_stats.comm, pid_str), | |
232 | common.convert_size(proc_stats.disk_read, padding_after=True), | |
233 | common.convert_size(proc_stats.net_read, padding_after=True), | |
234 | common.convert_size(proc_stats.unk_read, padding_after=True)) | |
235 | ||
236 | return (output_str, proc_stats.total_read) | |
237 | ||
238 | def _get_write_datum(self, proc_stats): | |
239 | if not self._filter_process(proc_stats): | |
240 | return None | |
241 | ||
242 | if proc_stats.pid is None: | |
243 | pid_str = 'unknown (tid=%d)' % (proc_stats.tid) | |
244 | else: | |
245 | pid_str = str(proc_stats.pid) | |
246 | ||
247 | format_str = '{:>10} {:<25} {:>9} file {:>9} net {:>9} unknown' | |
248 | output_str = format_str.format( | |
249 | common.convert_size(proc_stats.total_write, padding_after=True), | |
250 | '%s (%s)' % (proc_stats.comm, pid_str), | |
251 | common.convert_size(proc_stats.disk_write, padding_after=True), | |
252 | common.convert_size(proc_stats.net_write, padding_after=True), | |
253 | common.convert_size(proc_stats.unk_write, padding_after=True)) | |
254 | ||
255 | return (output_str, proc_stats.total_write) | |
256 | ||
257 | def _get_block_read_datum(self, proc_stats): | |
258 | if not self._filter_process(proc_stats) or proc_stats.block_read == 0: | |
259 | return None | |
260 | ||
261 | comm = proc_stats.comm | |
262 | if not comm: | |
263 | comm = 'unknown' | |
264 | ||
265 | if proc_stats.pid is None: | |
266 | pid_str = 'unknown (tid=%d)' % (proc_stats.tid) | |
267 | else: | |
268 | pid_str = str(proc_stats.pid) | |
269 | ||
270 | format_str = '{:>10} {:<22}' | |
271 | output_str = format_str.format( | |
272 | common.convert_size(proc_stats.block_read, padding_after=True), | |
273 | '%s (pid=%s)' % (comm, pid_str)) | |
274 | ||
275 | return (output_str, proc_stats.block_read) | |
276 | ||
277 | def _get_block_write_datum(self, proc_stats): | |
278 | if not self._filter_process(proc_stats) or \ | |
279 | proc_stats.block_write == 0: | |
280 | return None | |
281 | ||
282 | comm = proc_stats.comm | |
283 | if not comm: | |
284 | comm = 'unknown' | |
285 | ||
286 | if proc_stats.pid is None: | |
287 | pid_str = 'unknown (tid=%d)' % (proc_stats.tid) | |
288 | else: | |
289 | pid_str = str(proc_stats.pid) | |
290 | ||
291 | format_str = '{:>10} {:<22}' | |
292 | output_str = format_str.format( | |
293 | common.convert_size(proc_stats.block_write, padding_after=True), | |
294 | '%s (pid=%s)' % (comm, pid_str)) | |
295 | ||
296 | return (output_str, proc_stats.block_write) | |
297 | ||
298 | def _get_total_rq_sectors_datum(self, disk): | |
299 | if disk.total_rq_sectors == 0: | |
300 | return None | |
301 | ||
302 | return (disk.disk_name, disk.total_rq_sectors) | |
303 | ||
304 | def _get_rq_count_datum(self, disk): | |
305 | if disk.rq_count == 0: | |
306 | return None | |
307 | ||
308 | return (disk.disk_name, disk.rq_count) | |
309 | ||
310 | def _get_avg_disk_latency_datum(self, disk): | |
311 | if disk.rq_count == 0: | |
312 | return None | |
313 | ||
314 | avg_latency = ((disk.total_rq_duration / disk.rq_count) / | |
315 | common.MSEC_PER_NSEC) | |
316 | avg_latency = round(avg_latency, 3) | |
317 | ||
318 | return ('%s' % disk.disk_name, avg_latency) | |
319 | ||
320 | def _get_net_recv_bytes_datum(self, iface): | |
321 | return ('%s %s' % (common.convert_size(iface.recv_bytes), iface.name), | |
322 | iface.recv_bytes) | |
323 | ||
324 | def _get_net_sent_bytes_datum(self, iface): | |
325 | return ('%s %s' % (common.convert_size(iface.sent_bytes), iface.name), | |
326 | iface.sent_bytes) | |
327 | ||
328 | def _output_read(self): | |
329 | input_list = sorted(self._analysis.tids.values(), | |
330 | key=operator.attrgetter('total_read'), | |
331 | reverse=True) | |
332 | label = 'Per-process I/O Read' | |
333 | graph_args = {'with_value': False} | |
334 | self._print_ascii_graph(input_list, self._get_read_datum, label, | |
335 | graph_args) | |
336 | ||
337 | def _output_write(self): | |
338 | input_list = sorted(self._analysis.tids.values(), | |
339 | key=operator.attrgetter('total_write'), | |
340 | reverse=True) | |
341 | label = 'Per-process I/O Write' | |
342 | graph_args = {'with_value': False} | |
343 | self._print_ascii_graph(input_list, self._get_write_datum, label, | |
344 | graph_args) | |
345 | ||
346 | def _output_block_read(self): | |
347 | input_list = sorted(self._analysis.tids.values(), | |
348 | key=operator.attrgetter('block_read'), | |
349 | reverse=True) | |
350 | label = 'Block I/O Read' | |
351 | graph_args = {'with_value': False} | |
352 | self._print_ascii_graph(input_list, self._get_block_read_datum, | |
353 | label, graph_args) | |
354 | ||
355 | def _output_block_write(self): | |
356 | input_list = sorted(self._analysis.tids.values(), | |
357 | key=operator.attrgetter('block_write'), | |
358 | reverse=True) | |
359 | label = 'Block I/O Write' | |
360 | graph_args = {'with_value': False} | |
361 | self._print_ascii_graph(input_list, self._get_block_write_datum, | |
362 | label, graph_args) | |
363 | ||
364 | def _output_total_rq_sectors(self): | |
365 | input_list = sorted(self._analysis.disks.values(), | |
366 | key=operator.attrgetter('total_rq_sectors'), | |
367 | reverse=True) | |
368 | label = 'Disk requests sector count' | |
369 | graph_args = {'unit': ' sectors'} | |
370 | self._print_ascii_graph(input_list, self._get_total_rq_sectors_datum, | |
371 | label, graph_args) | |
372 | ||
373 | def _output_rq_count(self): | |
374 | input_list = sorted(self._analysis.disks.values(), | |
375 | key=operator.attrgetter('rq_count'), | |
376 | reverse=True) | |
377 | label = 'Disk request count' | |
378 | graph_args = {'unit': ' requests'} | |
379 | self._print_ascii_graph(input_list, self._get_rq_count_datum, | |
380 | label, graph_args) | |
381 | ||
382 | def _output_avg_disk_latency(self): | |
383 | input_list = self._analysis.disks.values() | |
384 | label = 'Disk request average latency' | |
385 | graph_args = {'unit': ' ms', 'sort': 2} | |
386 | self._print_ascii_graph(input_list, self._get_avg_disk_latency_datum, | |
387 | label, graph_args) | |
388 | ||
389 | def _output_net_recv_bytes(self): | |
390 | input_list = sorted(self._analysis.ifaces.values(), | |
391 | key=operator.attrgetter('recv_bytes'), | |
392 | reverse=True) | |
393 | label = 'Network received bytes' | |
394 | graph_args = {'with_value': False} | |
395 | self._print_ascii_graph(input_list, self._get_net_recv_bytes_datum, | |
396 | label, graph_args) | |
397 | ||
398 | def _output_net_sent_bytes(self): | |
399 | input_list = sorted(self._analysis.ifaces.values(), | |
400 | key=operator.attrgetter('sent_bytes'), | |
401 | reverse=True) | |
402 | label = 'Network sent bytes' | |
403 | graph_args = {'with_value': False} | |
404 | self._print_ascii_graph(input_list, self._get_net_sent_bytes_datum, | |
405 | label, graph_args) | |
406 | ||
407 | # I/O Top output by file methods | |
408 | def _output_print_file_read(self, files): | |
a9c9a2a6 JD |
409 | count = 0 |
410 | limit = self._arg_limit | |
411 | graph = Pyasciigraph() | |
412 | values = [] | |
413 | sorted_f = sorted(files.items(), key=lambda files: files[1]['read'], | |
414 | reverse=True) | |
415 | for f in sorted_f: | |
73b71522 | 416 | if f[1]['read'] == 0: |
a9c9a2a6 | 417 | continue |
73b71522 | 418 | info_fmt = '{:>10}'.format(common.convert_size(f[1]['read'], |
a9c9a2a6 | 419 | padding_after=True)) |
73b71522 AB |
420 | values.append(('%s %s %s' % (info_fmt, |
421 | f[1]['name'], | |
422 | str(f[1]['other'])[1:-1]), | |
423 | f[1]['read'])) | |
a9c9a2a6 JD |
424 | count = count + 1 |
425 | if limit > 0 and count >= limit: | |
426 | break | |
427 | for line in graph.graph('Files Read', values, sort=2, | |
428 | with_value=False): | |
429 | print(line) | |
430 | ||
91765fd2 | 431 | def _output_print_file_write(self, files): |
a9c9a2a6 JD |
432 | # Compute files read |
433 | count = 0 | |
434 | limit = self._arg_limit | |
435 | graph = Pyasciigraph() | |
436 | values = [] | |
437 | sorted_f = sorted(files.items(), key=lambda files: files[1]['write'], | |
438 | reverse=True) | |
439 | for f in sorted_f: | |
73b71522 | 440 | if f[1]['write'] == 0: |
a9c9a2a6 | 441 | continue |
73b71522 | 442 | info_fmt = '{:>10}'.format(common.convert_size(f[1]['write'], |
a9c9a2a6 | 443 | padding_after=True)) |
73b71522 AB |
444 | values.append(('%s %s %s' % (info_fmt, |
445 | f[1]['name'], | |
446 | str(f[1]['other'])[1:-1]), | |
447 | f[1]['write'])) | |
a9c9a2a6 JD |
448 | count = count + 1 |
449 | if limit > 0 and count >= limit: | |
450 | break | |
451 | for line in graph.graph('Files Write', values, sort=2, | |
452 | with_value=False): | |
453 | print(line) | |
454 | ||
91765fd2 | 455 | def _output_file_read_write(self): |
a9c9a2a6 | 456 | files = self.create_files_dict() |
91765fd2 AB |
457 | self._output_print_file_read(files) |
458 | self._output_print_file_write(files) | |
a9c9a2a6 JD |
459 | |
460 | def iotop_output(self): | |
91765fd2 AB |
461 | self._output_read() |
462 | self._output_write() | |
463 | self._output_file_read_write() | |
464 | self._output_block_read() | |
465 | self._output_block_write() | |
466 | self._output_total_rq_sectors() | |
467 | self._output_rq_count() | |
468 | self._output_avg_disk_latency() | |
469 | self._output_net_recv_bytes() | |
470 | self._output_net_sent_bytes() | |
471 | ||
472 | # IO Latency output methods | |
a9c9a2a6 JD |
473 | def iolatency_freq_histogram(self, _min, _max, res, rq_list, title): |
474 | step = (_max - _min) / res | |
475 | if step == 0: | |
476 | return | |
477 | buckets = [] | |
478 | values = [] | |
479 | graph = Pyasciigraph() | |
480 | for i in range(res): | |
481 | buckets.append(i * step) | |
482 | values.append(0) | |
483 | for i in rq_list: | |
484 | v = i / 1000 | |
485 | b = min(int((v-_min)/step), res - 1) | |
486 | values[b] += 1 | |
487 | g = [] | |
488 | i = 0 | |
489 | for v in values: | |
73b71522 | 490 | g.append(('%0.03f' % (i * step + _min), v)) |
a9c9a2a6 | 491 | i += 1 |
09071fb9 | 492 | for line in graph.graph(title, g, info_before=True, count=True): |
a9c9a2a6 | 493 | print(line) |
73b71522 | 494 | print('') |
a9c9a2a6 JD |
495 | |
496 | def compute_disk_stats(self, dev): | |
497 | _max = 0 | |
2b4a3c12 | 498 | _min = None |
a9c9a2a6 JD |
499 | total = 0 |
500 | values = [] | |
501 | count = len(dev.rq_list) | |
502 | if count == 0: | |
503 | return | |
504 | for rq in dev.rq_list: | |
505 | if rq.duration > _max: | |
506 | _max = rq.duration | |
2b4a3c12 | 507 | if _min is None or rq.duration < _min: |
a9c9a2a6 JD |
508 | _min = rq.duration |
509 | total += rq.duration | |
510 | values.append(rq.duration) | |
511 | if count > 2: | |
512 | stdev = statistics.stdev(values) / 1000 | |
513 | else: | |
73b71522 | 514 | stdev = '?' |
a9c9a2a6 JD |
515 | dev.min = _min / 1000 |
516 | dev.max = _max / 1000 | |
517 | dev.total = total / 1000 | |
518 | dev.count = count | |
519 | dev.rq_values = values | |
520 | dev.stdev = stdev | |
521 | ||
522 | # iolatency functions | |
523 | def iolatency_output_disk(self): | |
524 | for dev in self.state.disks.keys(): | |
525 | d = self.state.disks[dev] | |
526 | if d.max is None: | |
527 | self.compute_disk_stats(d) | |
528 | if d.count is not None: | |
529 | self.iolatency_freq_histogram(d.min, d.max, | |
530 | self._arg_freq_resolution, | |
531 | d.rq_values, | |
73b71522 AB |
532 | 'Frequency distribution for ' |
533 | 'disk %s (usec)' % | |
a9c9a2a6 JD |
534 | (d.prettyname)) |
535 | ||
536 | def iolatency_output(self): | |
537 | self.iolatency_output_disk() | |
538 | ||
a9c9a2a6 JD |
539 | def iostats_minmax(self, duration, current_min, current_max): |
540 | _min = current_min | |
541 | _max = current_max | |
542 | if current_min is None or duration < current_min: | |
543 | _min = duration | |
544 | if duration > current_max: | |
545 | _max = duration | |
546 | return (_min, _max) | |
547 | ||
548 | def iostats_syscalls_line(self, fmt, name, count, _min, _max, total, rq): | |
549 | if count < 2: | |
73b71522 | 550 | stdev = '?' |
a9c9a2a6 | 551 | else: |
73b71522 | 552 | stdev = '%0.03f' % (statistics.stdev(rq) / 1000) |
a9c9a2a6 | 553 | if count < 1: |
73b71522 | 554 | avg = '0.000' |
a9c9a2a6 | 555 | else: |
73b71522 | 556 | avg = '%0.03f' % (total / (count * 1000)) |
a9c9a2a6 JD |
557 | if _min is None: |
558 | _min = 0 | |
73b71522 AB |
559 | _min = '%0.03f' % (_min / 1000) |
560 | _max = '%0.03f' % (_max / 1000) | |
a9c9a2a6 JD |
561 | print(fmt.format(name, count, _min, avg, _max, stdev)) |
562 | ||
563 | def account_syscall_iorequests(self, s, iorequests): | |
564 | for rq in iorequests: | |
565 | # filter out if completely out of range but accept the | |
566 | # union to show the real begin/end time | |
567 | if self._arg_begin and self._arg_end and rq.end and \ | |
568 | rq.begin > self._arg_end: | |
569 | continue | |
570 | if rq.iotype != sv.IORequest.IO_SYSCALL: | |
571 | continue | |
572 | if not self.filter_size(rq.size): | |
573 | continue | |
574 | if not self.filter_latency(rq.duration): | |
575 | continue | |
576 | if rq.operation == sv.IORequest.OP_READ: | |
577 | s.read_count += 1 | |
578 | s.read_total += rq.duration | |
579 | s.read_rq.append(rq.duration) | |
580 | s.all_read.append(rq) | |
581 | s.read_min, s.read_max = self.iostats_minmax( | |
582 | rq.duration, s.read_min, s.read_max) | |
583 | elif rq.operation == sv.IORequest.OP_WRITE: | |
584 | s.write_count += 1 | |
585 | s.write_total += rq.duration | |
586 | s.write_rq.append(rq.duration) | |
587 | s.all_write.append(rq) | |
588 | s.write_min, s.write_max = self.iostats_minmax( | |
589 | rq.duration, s.write_min, s.write_max) | |
590 | elif rq.operation == sv.IORequest.OP_SYNC: | |
591 | s.sync_count += 1 | |
592 | s.sync_total += rq.duration | |
593 | s.sync_rq.append(rq.duration) | |
594 | s.all_sync.append(rq) | |
595 | s.sync_min, s.sync_max = self.iostats_minmax( | |
596 | rq.duration, s.sync_min, s.sync_max) | |
597 | elif rq.operation == sv.IORequest.OP_OPEN: | |
598 | s.open_count += 1 | |
599 | s.open_total += rq.duration | |
600 | s.open_rq.append(rq.duration) | |
601 | s.all_open.append(rq) | |
602 | s.open_min, s.open_max = self.iostats_minmax( | |
603 | rq.duration, s.open_min, s.open_max) | |
604 | ||
605 | def compute_syscalls_latency_stats(self, end_ns): | |
606 | s = sv.Syscalls_stats() | |
607 | for tid in self.state.tids.values(): | |
608 | if not self.filter_process(tid): | |
609 | continue | |
610 | self.account_syscall_iorequests(s, tid.iorequests) | |
611 | for fd in tid.fds.values(): | |
612 | self.account_syscall_iorequests(s, fd.iorequests) | |
613 | for fd in tid.closed_fds.values(): | |
614 | self.account_syscall_iorequests(s, fd.iorequests) | |
615 | return s | |
616 | ||
617 | def iostats_output_syscalls(self): | |
618 | s = self.syscalls_stats | |
73b71522 AB |
619 | print('\nSyscalls latency statistics (usec):') |
620 | fmt = '{:<14} {:>14} {:>14} {:>14} {:>14} {:>14}' | |
621 | print(fmt.format('Type', 'Count', 'Min', 'Average', | |
622 | 'Max', 'Stdev')) | |
623 | print('-' * 89) | |
624 | self.iostats_syscalls_line(fmt, 'Open', s.open_count, s.open_min, | |
a9c9a2a6 | 625 | s.open_max, s.open_total, s.open_rq) |
73b71522 | 626 | self.iostats_syscalls_line(fmt, 'Read', s.read_count, s.read_min, |
a9c9a2a6 | 627 | s.read_max, s.read_total, s.read_rq) |
73b71522 | 628 | self.iostats_syscalls_line(fmt, 'Write', s.write_count, s.write_min, |
a9c9a2a6 | 629 | s.write_max, s.write_total, s.write_rq) |
73b71522 | 630 | self.iostats_syscalls_line(fmt, 'Sync', s.sync_count, s.sync_min, |
a9c9a2a6 JD |
631 | s.sync_max, s.sync_total, s.sync_rq) |
632 | ||
633 | def iolatency_syscalls_output(self): | |
634 | s = self.syscalls_stats | |
73b71522 | 635 | print('') |
a9c9a2a6 JD |
636 | if s.open_count > 0: |
637 | self.iolatency_freq_histogram(s.open_min/1000, s.open_max/1000, | |
638 | self._arg_freq_resolution, s.open_rq, | |
73b71522 | 639 | 'Open latency distribution (usec)') |
a9c9a2a6 JD |
640 | if s.read_count > 0: |
641 | self.iolatency_freq_histogram(s.read_min/1000, s.read_max/1000, | |
642 | self._arg_freq_resolution, s.read_rq, | |
73b71522 | 643 | 'Read latency distribution (usec)') |
a9c9a2a6 JD |
644 | if s.write_count > 0: |
645 | self.iolatency_freq_histogram(s.write_min/1000, s.write_max/1000, | |
646 | self._arg_freq_resolution, | |
647 | s.write_rq, | |
73b71522 | 648 | 'Write latency distribution (usec)') |
a9c9a2a6 JD |
649 | if s.sync_count > 0: |
650 | self.iolatency_freq_histogram(s.sync_min/1000, s.sync_max/1000, | |
651 | self._arg_freq_resolution, s.sync_rq, | |
73b71522 | 652 | 'Sync latency distribution (usec)') |
a9c9a2a6 JD |
653 | |
654 | def iolatency_syscalls_list_output(self, title, rq_list, | |
655 | sortkey, reverse): | |
656 | limit = self._arg_limit | |
657 | count = 0 | |
658 | outrange_legend = False | |
5faa923d | 659 | if not rq_list: |
a9c9a2a6 JD |
660 | return |
661 | print(title) | |
662 | if self._arg_extra: | |
73b71522 AB |
663 | extra_fmt = '{:<48}' |
664 | extra_title = '{:<8} {:<8} {:<8} {:<8} {:<8} {:<8} '.format( | |
665 | 'Dirtied', 'Alloc', 'Free', 'Written', 'Kswap', 'Cleared') | |
a9c9a2a6 | 666 | else: |
73b71522 AB |
667 | extra_fmt = '{:<0}' |
668 | extra_title = '' | |
669 | title_fmt = '{:<19} {:<20} {:<16} {:<23} {:<5} {:<24} {:<8} ' + \ | |
670 | extra_fmt + '{:<14}' | |
671 | fmt = '{:<40} {:<16} {:>16} {:>11} {:<24} {:<8} ' + \ | |
672 | extra_fmt + '{:<14}' | |
673 | print(title_fmt.format('Begin', 'End', 'Name', 'Duration (usec)', | |
674 | 'Size', 'Proc', 'PID', extra_title, 'Filename')) | |
a9c9a2a6 JD |
675 | for rq in sorted(rq_list, |
676 | key=operator.attrgetter(sortkey), reverse=reverse): | |
73b71522 | 677 | # only limit the output if in the 'top' view |
a9c9a2a6 JD |
678 | if reverse and count > limit: |
679 | break | |
680 | if rq.size is None: | |
73b71522 | 681 | size = 'N/A' |
a9c9a2a6 JD |
682 | else: |
683 | size = common.convert_size(rq.size) | |
684 | if self._arg_extra: | |
73b71522 | 685 | extra = '{:<8} {:<8} {:<8} {:<8} {:<8} {:<8} '.format( |
a9c9a2a6 JD |
686 | rq.dirty, rq.page_alloc, rq.page_free, rq.page_written, |
687 | rq.woke_kswapd, rq.page_cleared) | |
688 | else: | |
73b71522 AB |
689 | extra = '' |
690 | name = rq.name.replace('syscall_entry_', '').replace('sys_', '') | |
a9c9a2a6 | 691 | if rq.fd is None: |
73b71522 AB |
692 | filename = 'None' |
693 | fd = 'None' | |
a9c9a2a6 JD |
694 | else: |
695 | filename = rq.fd.filename | |
696 | fd = rq.fd.fd | |
2e781b98 JD |
697 | if rq.proc.pid is None: |
698 | pid = 'unknown (tid=%d)' % (rq.proc.tid) | |
699 | else: | |
700 | pid = rq.proc.pid | |
a9c9a2a6 JD |
701 | end = common.ns_to_hour_nsec(rq.end, self._arg_multi_day, |
702 | self._arg_gmt) | |
703 | ||
73b71522 | 704 | outrange = ' ' |
a9c9a2a6 JD |
705 | duration = rq.duration |
706 | if self._arg_begin and rq.begin < self._arg_begin: | |
73b71522 | 707 | outrange = '*' |
a9c9a2a6 JD |
708 | outrange_legend = True |
709 | if self._arg_end and rq.end > self._arg_end: | |
73b71522 | 710 | outrange = '*' |
a9c9a2a6 JD |
711 | outrange_legend = True |
712 | ||
73b71522 AB |
713 | print(fmt.format('[' + common.ns_to_hour_nsec( |
714 | rq.begin, self._arg_multi_day, self._arg_gmt) + ',' + | |
715 | end + ']' + outrange, | |
a9c9a2a6 | 716 | name, |
73b71522 | 717 | '%0.03f' % (duration/1000) + outrange, |
a9c9a2a6 | 718 | size, rq.proc.comm, |
2e781b98 | 719 | pid, extra, |
73b71522 | 720 | '%s (fd=%s)' % (filename, fd))) |
a9c9a2a6 JD |
721 | count += 1 |
722 | if outrange_legend: | |
73b71522 AB |
723 | print('*: Syscalls started and/or completed outside of the ' |
724 | 'range specified') | |
a9c9a2a6 JD |
725 | |
726 | def iolatency_syscalls_top_output(self): | |
727 | s = self.syscalls_stats | |
728 | self.iolatency_syscalls_list_output( | |
73b71522 AB |
729 | '\nTop open syscall latencies (usec)', s.all_open, |
730 | 'duration', True) | |
a9c9a2a6 | 731 | self.iolatency_syscalls_list_output( |
73b71522 AB |
732 | '\nTop read syscall latencies (usec)', s.all_read, |
733 | 'duration', True) | |
a9c9a2a6 | 734 | self.iolatency_syscalls_list_output( |
73b71522 AB |
735 | '\nTop write syscall latencies (usec)', s.all_write, |
736 | 'duration', True) | |
a9c9a2a6 | 737 | self.iolatency_syscalls_list_output( |
73b71522 AB |
738 | '\nTop sync syscall latencies (usec)', s.all_sync, |
739 | 'duration', True) | |
a9c9a2a6 JD |
740 | |
741 | def iolatency_syscalls_log_output(self): | |
742 | s = self.syscalls_stats | |
743 | self.iolatency_syscalls_list_output( | |
73b71522 | 744 | '\nLog of all I/O system calls', |
a9c9a2a6 | 745 | s.all_open + s.all_read + s.all_write + s.all_sync, |
73b71522 | 746 | 'begin', False) |
a9c9a2a6 JD |
747 | |
748 | # iostats functions | |
749 | def iostats_output_disk(self): | |
750 | # TODO same with network | |
5faa923d | 751 | if not self.state.disks: |
a9c9a2a6 | 752 | return |
73b71522 AB |
753 | print('\nDisk latency statistics (usec):') |
754 | fmt = '{:<14} {:>14} {:>14} {:>14} {:>14} {:>14}' | |
755 | print(fmt.format('Name', 'Count', 'Min', 'Average', 'Max', 'Stdev')) | |
756 | print('-' * 89) | |
a9c9a2a6 JD |
757 | |
758 | for dev in self.state.disks.keys(): | |
759 | d = self.state.disks[dev] | |
760 | if d.max is None: | |
761 | d = self.state.disks[dev] | |
762 | self.compute_disk_stats(d) | |
763 | if d.count is not None: | |
764 | self.iostats_syscalls_line(fmt, d.prettyname, d.count, d.min, | |
765 | d.max, d.total, d.rq_values) | |
766 | ||
767 | def iostats_output(self): | |
768 | self.iostats_output_syscalls() | |
769 | self.iostats_output_disk() | |
770 | ||
da6d0842 | 771 | def _print_results(self, begin_ns, end_ns): |
3664e4b0 | 772 | self._print_date(begin_ns, end_ns) |
1c0f0e3c JD |
773 | if self._arg_usage: |
774 | self.iotop_output() | |
a9c9a2a6 JD |
775 | self.syscalls_stats = self.compute_syscalls_latency_stats(end_ns) |
776 | if self._arg_stats: | |
777 | self.iostats_output() | |
275bdbb4 | 778 | if self._arg_latencytop: |
a9c9a2a6 JD |
779 | self.iolatency_syscalls_top_output() |
780 | if self._arg_freq: | |
781 | self.iolatency_syscalls_output() | |
782 | self.iolatency_output() | |
783 | if self._arg_log: | |
784 | self.iolatency_syscalls_log_output() | |
785 | ||
786 | def _reset_total(self, start_ts): | |
3b1dda96 | 787 | self._analysis.reset() |
a9c9a2a6 JD |
788 | |
789 | def _add_arguments(self, ap): | |
73b71522 | 790 | ap.add_argument('--usage', action='store_true', |
1c0f0e3c | 791 | help='Show the I/O usage') |
73b71522 | 792 | ap.add_argument('--latencystats', action='store_true', |
1c0f0e3c | 793 | help='Show the I/O latency statistics') |
73b71522 | 794 | ap.add_argument('--latencytop', action='store_true', |
275bdbb4 | 795 | help='Show the I/O latency top') |
73b71522 | 796 | ap.add_argument('--latencyfreq', action='store_true', |
1c0f0e3c JD |
797 | help='Show the I/O latency frequency distribution') |
798 | ap.add_argument('--freq-resolution', type=int, default=20, | |
799 | help='Frequency distribution resolution ' | |
800 | '(default 20)') | |
a9c9a2a6 JD |
801 | ap.add_argument('--extra', type=str, default=0, |
802 | help='Show extra information in stats (beta)') | |
a9c9a2a6 JD |
803 | |
804 | ||
805 | # entry point | |
1c0f0e3c | 806 | def runstats(): |
a9c9a2a6 | 807 | # create command |
087e5d00 | 808 | iocmd = IoAnalysisCommand() |
1c0f0e3c JD |
809 | # execute command |
810 | iocmd.run_stats() | |
811 | ||
a9c9a2a6 | 812 | |
275bdbb4 JD |
813 | def runlatencytop(): |
814 | # create command | |
087e5d00 | 815 | iocmd = IoAnalysisCommand() |
275bdbb4 JD |
816 | # execute command |
817 | iocmd.run_latencytop() | |
818 | ||
819 | ||
1c0f0e3c JD |
820 | def runlog(): |
821 | # create command | |
087e5d00 | 822 | iocmd = IoAnalysisCommand() |
1c0f0e3c JD |
823 | # execute command |
824 | iocmd.run_log() | |
825 | ||
826 | ||
827 | def runfreq(): | |
828 | # create command | |
087e5d00 | 829 | iocmd = IoAnalysisCommand() |
1c0f0e3c JD |
830 | # execute command |
831 | iocmd.run_freq() | |
832 | ||
833 | ||
834 | def runusage(): | |
835 | # create command | |
087e5d00 | 836 | iocmd = IoAnalysisCommand() |
a9c9a2a6 | 837 | # execute command |
1c0f0e3c | 838 | iocmd.run_usage() |