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")