def log_irq(self):
fmt = "[{:<18}, {:<18}] {:>15} {:>4} {:<9} {:>4} {:<22}"
title_fmt = "{:<20} {:<19} {:>15} {:>4} {:<9} {:>4} {:<22}"
print(
title_fmt.format("Begin", "End", "Duration (us)", "CPU", "Type",
"#", "Name"))
for i in self.state.interrupts["irq-list"]:
if not self.filter_irq(i):
continue
if i.irqclass == sv.IRQ.HARD_IRQ:
name = self.state.interrupts["names"][i.nr]
irqtype = "IRQ"
else:
name = sv.IRQ.soft_names[i.nr]
irqtype = "SoftIRQ"
if i.raise_ts != -1:
raise_ts = " (raised at %s)" % \
(common.ns_to_hour_nsec(i.raise_ts,
self._arg_multi_day,
self._arg_gmt))
else:
raise_ts = ""
print(
fmt.format(
common.ns_to_hour_nsec(i.start_ts, self._arg_multi_day,
self._arg_gmt),
common.ns_to_hour_nsec(i.stop_ts, self._arg_multi_day,
self._arg_gmt),
"%0.03f" % ((i.stop_ts - i.start_ts) / 1000),
"%d" % i.cpu_id, irqtype, i.nr, name + raise_ts))
def _print_results(self, begin_ns, end_ns, final=0):
count = 0
limit = self._arg_limit
print('Timerange: [%s, %s]' % (
common.ns_to_hour_nsec(begin_ns, gmt=self._arg_gmt,
multi_day=True),
common.ns_to_hour_nsec(end_ns, gmt=self._arg_gmt,
multi_day=True)))
print("Per-TID syscalls usage")
for tid in sorted(self.state.tids.values(),
key=operator.attrgetter('total_syscalls'),
reverse=True):
if not self.filter_process(tid):
continue
print("%s (%d), %d syscalls:" % (tid.comm, tid.pid,
tid.total_syscalls))
for syscall in sorted(tid.syscalls.values(),
key=operator.attrgetter('count'),
reverse=True):
print("- %s : %d" % (syscall.name, syscall.count))
count = count + 1
if limit > 0 and count >= limit:
break
print("")
print("\nTotal syscalls: %d" % (self.state.syscalls["total"]))
def _print_results(self, begin_ns, end_ns, final=0):
count = 0
limit = self._arg_limit
graph = Pyasciigraph()
values = []
self.state = self._automaton.state
alloc = 0
freed = 0
print('Timerange: [%s, %s]' %
(common.ns_to_hour_nsec(
begin_ns, gmt=self._arg_gmt, multi_day=True),
common.ns_to_hour_nsec(
end_ns, gmt=self._arg_gmt, multi_day=True)))
for tid in sorted(self.state.tids.values(),
key=operator.attrgetter('allocated_pages'),
reverse=True):
if not self.filter_process(tid):
continue
values.append(
("%s (%d)" % (tid.comm, tid.tid), tid.allocated_pages))
count = count + 1
if limit > 0 and count >= limit:
break
for line in graph.graph("Per-TID Memory Allocations",
values,
unit=" pages"):
print(line)
values = []
count = 0
for tid in sorted(self.state.tids.values(),
key=operator.attrgetter('freed_pages'),
reverse=True):
if not self.filter_process(tid):
continue
values.append(("%s (%d)" % (tid.comm, tid.tid), tid.freed_pages))
count = count + 1
freed += tid.freed_pages
if limit > 0 and count >= limit:
break
for line in graph.graph("Per-TID Memory Deallocation",
values,
unit=" pages"):
print(line)
for tid in sorted(self.state.tids.values(),
key=operator.attrgetter('allocated_pages'),
reverse=True):
if not self.filter_process(tid):
continue
alloc += tid.allocated_pages
for tid in sorted(self.state.tids.values(),
key=operator.attrgetter('freed_pages'),
reverse=True):
if not self.filter_process(tid):
continue
freed += tid.freed_pages
print("\nTotal memory usage:\n- %d pages allocated\n- %d pages freed" %
(alloc, freed))
def _print_results(self, begin_ns, end_ns, final=0):
print('Timerange: [%s, %s]' %
(common.ns_to_hour_nsec(
begin_ns, gmt=self._arg_gmt, multi_day=True),
common.ns_to_hour_nsec(
end_ns, gmt=self._arg_gmt, multi_day=True)))
strformat = "{:<28} {:>14} {:>14} {:>14} {:>12} {:>10} {:<14}"
print("Per-TID syscalls statistics (usec)")
for tid in sorted(self.state.tids.values(),
key=operator.attrgetter('total_syscalls'),
reverse=True):
if not self.filter_process(tid):
continue
if tid.total_syscalls == 0:
continue
print(
strformat.format("%s (%d)" % (tid.comm, tid.pid), "Count",
"Min", "Average", "Max", "Stdev",
"Return values"))
for syscall in sorted(tid.syscalls.values(),
key=operator.attrgetter('count'),
reverse=True):
sysvalues = []
rets = {}
for s in syscall.rq:
sysvalues.append(s.duration)
if s.ret >= 0:
key = "success"
else:
#key = errno.errorcode[-s.ret]
default = 'default' #hack to avoid the KeyError
key = errno.errorcode.get(-s.ret, default)
if key in rets.keys():
rets[key] += 1
else:
rets[key] = 1
if syscall.min is None:
syscallmin = "?"
else:
syscallmin = "%0.03f" % (syscall.min / 1000)
syscallmax = "%0.03f" % (syscall.max / 1000)
syscallavg = "%0.03f" % \
(syscall.total_duration/(syscall.count*1000))
if len(sysvalues) > 2:
stdev = "%0.03f" % (statistics.stdev(sysvalues) / 1000)
else:
stdev = "?"
name = syscall.name.replace("syscall_entry_", "")
name = name.replace("sys_", "")
print(
strformat.format(" - " + name, syscall.count, syscallmin,
syscallavg, syscallmax, stdev, str(rets)))
print(
strformat.format("Total:", tid.total_syscalls, "", "", "", "",
""))
print("-" * 113)
print("\nTotal syscalls: %d" % (self.state.syscalls["total"]))
def track_fds(self, name, event, cpu_id):
# we don't know which process is currently on this CPU
ret_string = ""
if cpu_id not in self.cpus:
return
c = self.cpus[cpu_id]
if c.current_tid == -1:
return
t = self.tids[c.current_tid]
# check if we can fix the pid from a context
self._fix_context_pid(event, t)
# if it's a thread, we want the parent
if t.pid != -1 and t.tid != t.pid:
t = self.tids[t.pid]
if name in sv.SyscallConsts.OPEN_SYSCALLS:
self.track_open(name, t, event, c)
elif name in sv.SyscallConsts.CLOSE_SYSCALLS:
ret_string = "%s %s(%d)" % \
(common.ns_to_hour_nsec(event.timestamp),
name, event["fd"])
self.track_close(name, t, event, c)
# when a connect occurs, no new sv.FD is returned, but we can fix
# the "filename" if we have the destination info
elif name in ["sys_connect", "syscall_entry_connect"] \
and "family" in event.keys():
if event["family"] == socket.AF_INET:
fd = self.get_fd(t, event["fd"])
ipport = "%s:%d" % (common.get_v4_addr_str(
event["v4addr"]), event["dport"])
fd.filename = ipport
return ret_string
def _print_results(self, begin_ns, end_ns, final=0):
print('Timerange: [%s, %s]' % (
common.ns_to_hour_nsec(begin_ns, gmt=self._arg_gmt,
multi_day=True),
common.ns_to_hour_nsec(end_ns, gmt=self._arg_gmt,
multi_day=True)))
if self._arg_usage:
self.iotop_output()
self.syscalls_stats = self.compute_syscalls_latency_stats(end_ns)
if self._arg_stats:
self.iostats_output()
self.iolatency_syscalls_top_output()
if self._arg_freq:
self.iolatency_syscalls_output()
self.iolatency_output()
if self._arg_log:
self.iolatency_syscalls_log_output()
def _print_results(self, begin_ns, end_ns, final=0):
# print('event count: {}'.format(self._analysis.event_count))
count = 0
limit = self._arg_limit
total_ns = end_ns - begin_ns
graph = Pyasciigraph()
values = []
print('Timerange: [%s, %s]' %
(common.ns_to_hour_nsec(
begin_ns, gmt=self._arg_gmt, multi_day=True),
common.ns_to_hour_nsec(
end_ns, gmt=self._arg_gmt, multi_day=True)))
for tid in sorted(self.state.tids.values(),
key=operator.attrgetter('cpu_ns'),
reverse=True):
if self._arg_proc_list and tid.comm not in self._arg_proc_list:
continue
if tid.tid == 0:
continue
pc = float("%0.02f" % ((tid.cpu_ns * 100) / total_ns))
if tid.migrate_count > 0:
migrations = ", %d migrations" % (tid.migrate_count)
else:
migrations = ""
values.append(("%s (%d)%s" % (tid.comm, tid.tid, migrations), pc))
count = count + 1
if limit > 0 and count >= limit:
break
for line in graph.graph("Per-TID CPU Usage", values, unit=" %"):
print(line)
values = []
total_cpu_pc = 0
for cpu in sorted(self.state.cpus.values(),
key=operator.attrgetter('cpu_ns'),
reverse=True):
cpu_pc = float("%0.02f" % cpu.cpu_pc)
total_cpu_pc += cpu_pc
values.append(("CPU %d" % cpu.cpu_id, cpu_pc))
for line in graph.graph("Per-CPU Usage", values, unit=" %"):
print(line)
print("\nTotal CPU Usage: %0.02f%%\n" %
(total_cpu_pc / len(self.state.cpus.keys())))
def _print_stats(self, begin_ns, end_ns, final):
if self._arg_no_progress:
clear_screen = ""
else:
clear_screen = "\r" + self.pbar.term_width * " " + "\r"
date = 'Timerange: [%s, %s]' % (
common.ns_to_hour_nsec(begin_ns, gmt=self._arg_gmt,
multi_day=True),
common.ns_to_hour_nsec(end_ns, gmt=self._arg_gmt,
multi_day=True))
print(clear_screen + date)
if self._arg_irq_filter_list is not None:
header = ""
header += '{:<52} {:<12}\n'.format("Hard IRQ", "Duration (us)")
header += '{:<22} {:<14} {:<12} {:<12} {:<10} ' \
'{:<12}\n'.format("", "count", "min", "avg", "max",
"stdev")
header += ('-'*82 + "|")
self.print_irq_stats(self.state.interrupts["hard-irqs"],
self.state.interrupts["names"],
self._arg_irq_filter_list, header)
print("")
if self._arg_softirq_filter_list is not None:
header = ""
header += '{:<52} {:<52} {:<12}\n'.format("Soft IRQ",
"Duration (us)",
"Raise latency (us)")
header += '{:<22} {:<14} {:<12} {:<12} {:<10} {:<4} {:<3} {:<14} '\
'{:<12} {:<12} {:<10} ' \
'{:<12}\n'.format("", "count", "min", "avg", "max",
"stdev", " |", "count", "min",
"avg", "max", "stdev")
header += '-' * 82 + "|" + '-' * 60
self.print_irq_stats(self.state.interrupts["soft-irqs"],
sv.IRQ.soft_names,
self._arg_softirq_filter_list,
header)
print("")
def _process_syscall_exit(self, event):
cpu_id = event["cpu_id"]
ret_string = ""
if cpu_id not in self.cpus:
return
c = self.cpus[cpu_id]
if c.current_tid == -1:
return
current_syscall = self.tids[c.current_tid].current_syscall
if len(current_syscall.keys()) == 0:
return
name = current_syscall["name"]
ret = event["ret"]
self._per_tid_syscall_exit(name, ret, event, c)
if name not in sv.SyscallConsts.IO_SYSCALLS:
return
current_syscall["iorequest"] = sv.IORequest()
current_syscall["iorequest"].iotype = sv.IORequest.IO_SYSCALL
current_syscall["iorequest"].name = name
if name in sv.SyscallConsts.OPEN_SYSCALLS:
self.add_tid_fd(event, c)
ret_string = "%s %s(%s, fd = %d)" % (common.ns_to_hour_nsec(
current_syscall["start"]), name, current_syscall["filename"],
ret)
if ret < 0:
return ret_string
t = self.tids[c.current_tid]
current_syscall["fd"] = self.get_fd(t, ret)
current_syscall["count"] = 0
current_syscall["fd"].fdtype = current_syscall["fdtype"]
current_syscall["iorequest"].operation = sv.IORequest.OP_OPEN
self.track_rw_latency(name, ret, c, event.timestamp, event)
elif name in sv.SyscallConsts.READ_SYSCALLS or \
name in sv.SyscallConsts.WRITE_SYSCALLS:
self.track_read_write_return(name, ret, c)
self.track_rw_latency(name, ret, c, event.timestamp, event)
elif name in sv.SyscallConsts.SYNC_SYSCALLS:
current_syscall["iorequest"].operation = sv.IORequest.OP_SYNC
self.track_rw_latency(name, ret, c, event.timestamp, event)
if name in ["sys_sync", "syscall_entry_sync"]:
t = self.tids[c.current_tid]
t.iorequests.append(current_syscall["iorequest"])
self.tids[c.current_tid].current_syscall = {}
if self.tids[c.current_tid] in self.pending_syscalls:
self.pending_syscalls.remove(self.tids[c.current_tid])
return ret_string
def iolatency_syscalls_list_output(self, title, rq_list,
sortkey, reverse):
limit = self._arg_limit
count = 0
outrange_legend = False
if len(rq_list) == 0:
return
print(title)
if self._arg_extra:
extra_fmt = "{:<48}"
extra_title = "{:<8} {:<8} {:<8} {:<8} {:<8} {:<8} ".format(
"Dirtied", "Alloc", "Free", "Written", "Kswap", "Cleared")
else:
extra_fmt = "{:<0}"
extra_title = ""
title_fmt = "{:<19} {:<20} {:<16} {:<23} {:<5} {:<24} {:<8} " + \
extra_fmt + "{:<14}"
fmt = "{:<40} {:<16} {:>16} {:>11} {:<24} {:<8} " + \
extra_fmt + "{:<14}"
print(title_fmt.format("Begin", "End", "Name", "Duration (usec)",
"Size", "Proc", "PID", extra_title, "Filename"))
for rq in sorted(rq_list,
key=operator.attrgetter(sortkey), reverse=reverse):
# only limit the output if in the "top" view
if reverse and count > limit:
break
if rq.size is None:
size = "N/A"
else:
size = common.convert_size(rq.size)
if self._arg_extra:
extra = "{:<8} {:<8} {:<8} {:<8} {:<8} {:<8} ".format(
rq.dirty, rq.page_alloc, rq.page_free, rq.page_written,
rq.woke_kswapd, rq.page_cleared)
else:
extra = ""
name = rq.name.replace("syscall_entry_", "").replace("sys_", "")
if rq.fd is None:
filename = "None"
fd = "None"
else:
filename = rq.fd.filename
fd = rq.fd.fd
end = common.ns_to_hour_nsec(rq.end, self._arg_multi_day,
self._arg_gmt)
outrange = " "
duration = rq.duration
if self._arg_begin and rq.begin < self._arg_begin:
outrange = "*"
outrange_legend = True
if self._arg_end and rq.end > self._arg_end:
outrange = "*"
outrange_legend = True
print(fmt.format("[" + common.ns_to_hour_nsec(
rq.begin, self._arg_multi_day, self._arg_gmt) + "," +
end + "]" + outrange,
name,
"%0.03f" % (duration/1000) + outrange,
size, rq.proc.comm,
rq.proc.pid, extra,
"%s (fd=%s)" % (filename, fd)))
count += 1
if outrange_legend:
print("*: Syscalls started and/or completed outside of the "
"range specified")