def log_irq(self, args): 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(args, i): continue if i.irqclass == IRQ.HARD_IRQ: name = self.state.interrupts["names"][i.nr] irqtype = "IRQ" else: name = IRQ.soft_names[i.nr] irqtype = "SoftIRQ" if i.raise_ts != -1: raise_ts = " (raised at %s)" % \ (ns_to_hour_nsec(i.raise_ts, args.multi_day, args.gmt)) else: raise_ts = "" print(fmt.format(ns_to_hour_nsec(i.start_ts, args.multi_day, args.gmt), ns_to_hour_nsec(i.stop_ts, args.multi_day, args.gmt), "%0.03f" % ((i.stop_ts - i.start_ts) / 1000), "%d" % i.cpu_id, irqtype, i.nr, name + raise_ts))
def log_irq(self, args): 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(args, i): continue if i.irqclass == IRQ.HARD_IRQ: name = self.state.interrupts["names"][i.nr] irqtype = "IRQ" else: name = IRQ.soft_names[i.nr] irqtype = "SoftIRQ" if i.raise_ts != -1: raise_ts = " (raised at %s)" % \ (ns_to_hour_nsec(i.raise_ts, args.multi_day, args.gmt)) else: raise_ts = "" print( fmt.format( ns_to_hour_nsec(i.start_ts, args.multi_day, args.gmt), ns_to_hour_nsec(i.stop_ts, args.multi_day, args.gmt), "%0.03f" % ((i.stop_ts - i.start_ts) / 1000), "%d" % i.cpu_id, irqtype, i.nr, name + raise_ts))
def exit(self, event, started): 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"] current_syscall["iorequest"] = IORequest() current_syscall["iorequest"].iotype = IORequest.IO_SYSCALL if name in Syscalls.OPEN_SYSCALLS: self.add_tid_fd(event, c) ret_string = "%s %s(%s, fd = %d)" % ( ns_to_hour_nsec(current_syscall["start"]), name, current_syscall["filename"], ret) 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"] self.track_rw_latency(name, ret, c, event.timestamp, started, event) elif name in Syscalls.READ_SYSCALLS or name in Syscalls.WRITE_SYSCALLS: self.track_read_write_return(name, ret, c) self.track_rw_latency(name, ret, c, event.timestamp, started, event) elif name in Syscalls.SYNC_SYSCALLS: self.track_rw_latency(name, ret, c, event.timestamp, started, event) self.tids[c.current_tid].current_syscall = {} return ret_string
def writeback_global_dirty_state(self, event): print("%s count : %d, count dirty : %d, nr_dirty : %d, " "nr_writeback : %d, nr_dirtied : %d, nr_written : %d" % (ns_to_hour_nsec(event.timestamp), self.mm["count"], self.mm["dirty"], event["nr_dirty"], event["nr_writeback"], event["nr_dirtied"], event["nr_written"])) self.mm["dirty"] = 0
def output_dump(self, event): # dump events can't fail, and don't have a duration, so ignore if self.args.failed or self.err_number or self.args.duration > 0: return # using tid as variable name for consistency with other events tid = event['pid'] if self.args.tid >= 0 and self.args.tid != tid: return comm = self.state.tids[tid].comm if self.args.pname is not None and self.args.pname != comm: return name = event.name if args.syscall and args.syscall != name: return filename = event['filename'] endtime = event.timestamp if self.args.start and endtime < self.args.start: return if self.args.end and endtime > self.args.end: return if not self.args.unixtime: endtime = ns_to_hour_nsec(endtime) else: endtime = '{:.9f}'.format(endtime / NS_IN_S) if filename.startswith(self.args.prefix) and not self.args.quiet: print(FDInfo.DUMP_FORMAT.format(endtime, comm, tid, name, filename))
def exit(self, event, started): 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"] current_syscall["iorequest"] = IORequest() current_syscall["iorequest"].iotype = IORequest.IO_SYSCALL if name in Syscalls.OPEN_SYSCALLS: self.add_tid_fd(event, c) ret_string = "%s %s(%s, fd = %d)" % (ns_to_hour_nsec( current_syscall["start"]), name, current_syscall["filename"], ret) 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"] self.track_rw_latency(name, ret, c, event.timestamp, started, event) elif name in Syscalls.READ_SYSCALLS or name in Syscalls.WRITE_SYSCALLS: self.track_read_write_return(name, ret, c) self.track_rw_latency(name, ret, c, event.timestamp, started, event) elif name in Syscalls.SYNC_SYSCALLS: self.track_rw_latency(name, ret, c, event.timestamp, started, event) self.tids[c.current_tid].current_syscall = {} return ret_string
def output_dump(self, event): # dump events can't fail, and don't have a duration, so ignore if self.args.failed or self.err_number or self.args.duration > 0: return # using tid as variable name for consistency with other events tid = event['pid'] if self.args.tid >= 0 and self.args.tid != tid: return comm = self.state.tids[tid].comm if self.args.pname is not None and self.args.pname != comm: return name = event.name if args.syscall and args.syscall != name: return filename = event['filename'] endtime = event.timestamp if self.args.start and endtime < self.args.start: return if self.args.end and endtime > self.args.end: return if not self.args.unixtime: endtime = ns_to_hour_nsec(endtime) else: endtime = '{:.9f}'.format(endtime / NS_IN_S) if filename.startswith(self.args.prefix) and not self.args.quiet: print(FDInfo.DUMP_FORMAT.format(endtime, comm, tid, name, filename))
def writeback_global_dirty_state(self, event): print("%s count : %d, count dirty : %d, nr_dirty : %d, " "nr_writeback : %d, nr_dirtied : %d, nr_written : %d" % (ns_to_hour_nsec(event.timestamp), self.mm["count"], self.mm["dirty"], event["nr_dirty"], event["nr_writeback"], event["nr_dirtied"], event["nr_written"])) self.mm["dirty"] = 0
def 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"] current_syscall["iorequest"] = IORequest() current_syscall["iorequest"].iotype = IORequest.IO_SYSCALL current_syscall["iorequest"].name = name if name in SyscallConsts.OPEN_SYSCALLS: self.add_tid_fd(event, c) ret_string = "%s %s(%s, fd = %d)" % ( 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 = IORequest.OP_OPEN self.track_rw_latency(name, ret, c, event.timestamp, event) elif name in SyscallConsts.READ_SYSCALLS or \ name in SyscallConsts.WRITE_SYSCALLS: self.track_read_write_return(name, ret, c) self.track_rw_latency(name, ret, c, event.timestamp, event) elif name in SyscallConsts.SYNC_SYSCALLS: current_syscall["iorequest"].operation = 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 output_perf(self, event, ret): tid = event['prev_tid'] if self.args.tid and str(tid) not in self.args.tid: return pid = self.state.tids[tid].pid if pid == -1: pid = tid comm = self.state.tids[tid].comm if self.args.pname is not None and self.args.pname != comm: return name = event.name if name != 'sched_switch': return endtime = event.timestamp if self.args.start and endtime < self.args.start: return if self.args.end and endtime > self.args.end: return if not self.args.unixtime: endtime = ns_to_hour_nsec(endtime) else: endtime = '{:.9f}'.format(endtime / NS_IN_S) insert = 0 for context in ret.keys(): if context.startswith('perf_'): if self.args.json or self.args.mongo: insert = 1 if not self.args.quiet: print( Perf.PERF_FORMAT.format(endtime, comm, tid, context, ret[context])) if insert: self.log_perf_event_json(endtime, comm, tid, pid, ret)
def output_perf(self, event, ret): tid = event['prev_tid'] if self.args.tid and str(tid) not in self.args.tid: return pid = self.state.tids[tid].pid if pid == -1: pid = tid comm = self.state.tids[tid].comm if self.args.pname is not None and self.args.pname != comm: return name = event.name if name != 'sched_switch': return endtime = event.timestamp if self.args.start and endtime < self.args.start: return if self.args.end and endtime > self.args.end: return if not self.args.unixtime: endtime = ns_to_hour_nsec(endtime) else: endtime = '{:.9f}'.format(endtime / NS_IN_S) insert = 0 for context in ret.keys(): if context.startswith('perf_'): if self.args.json or self.args.mongo: insert = 1 if not self.args.quiet: print(Perf.PERF_FORMAT.format(endtime, comm, tid, context, ret[context])) if insert: self.log_perf_event_json(endtime, comm, tid, pid, ret)
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 if t.pid == -1 and "pid" in event.keys(): t.pid = event["pid"] p = Process() p.tid = t.pid p.pid = t.pid p.comm = t.comm self.tids[p.pid] = p # 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 SyscallConsts.OPEN_SYSCALLS: self.track_open(name, t, event, c) elif name in SyscallConsts.CLOSE_SYSCALLS: ret_string = "%s %s(%d)" % (ns_to_hour_nsec(event.timestamp), name, event["fd"]) self.track_close(name, t, event, c) # when a connect occurs, no new 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" % (get_v4_addr_str(event["v4addr"]), event["dport"]) fd.filename = ipport return ret_string
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 if t.pid == -1 and "pid" in event.keys(): t.pid = event["pid"] p = Process() p.tid = t.pid p.pid = t.pid p.comm = t.comm self.tids[p.pid] = p # 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 Syscalls.OPEN_SYSCALLS: self.track_open(name, t, event, c) elif name in Syscalls.CLOSE_SYSCALLS: ret_string = "%s %s(%d)" % (ns_to_hour_nsec(event.timestamp), name, event["fd"]) self.track_close(name, t, event, c) # when a connect occurs, no new 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" % (get_v4_addr_str(event["v4addr"]), event["dport"]) fd.filename = ipport return ret_string
def run(self, args): """Process the trace""" self.current_sec = 0 self.start_ns = 0 self.end_ns = 0 for event in self.traces.events: if self.start_ns == 0: self.start_ns = event.timestamp if self.trace_start_ts == 0: self.trace_start_ts = event.timestamp self.end_ns = event.timestamp self.trace_end_ts = event.timestamp payload = "" override_tid = 0 if event.name == "sched_switch": self.state.sched.switch(event) elif event.name[0:4] == "sys_" or \ event.name[0:14] == "syscall_entry_": payload = self.state.syscall.entry(event) elif event.name == "exit_syscall" or \ event.name[0:13] == "syscall_exit_": payload = self.state.syscall.exit(event) elif event.name == "block_complete" or \ event.name == "block_rq_complete": self.state.block.complete(event) elif event.name == "block_queue": self.state.block.queue(event) elif event.name == "netif_receive_skb": self.state.net.recv(event) elif event.name == "net_dev_xmit": self.state.net.send(event) elif event.name == "sched_process_fork": self.state.sched.process_fork(event) if int(event["child_tid"]) == int(args.pid): override_tid = 1 payload = "%s created by : %d" % ( ns_to_hour_nsec(event.timestamp), event["parent_tid"]) else: payload = "%s fork child_tid : %d" % ( ns_to_hour_nsec(event.timestamp), event["child_tid"]) elif event.name == "sched_process_exec": payload = "%s exec %s" % ( ns_to_hour_nsec(event.timestamp), event["filename"]) elif event.name == "lttng_statedump_process_state": self.state.statedump.process_state(event) if event["pid"] == int(args.pid): override_tid = 1 payload = "%s existed at statedump" % \ ns_to_hour_nsec(event.timestamp) elif event.name == "lttng_statedump_file_descriptor": self.state.statedump.file_descriptor(event) if event["pid"] == int(args.pid): override_tid = 1 payload = "%s statedump file : %s, fd : %d" % ( ns_to_hour_nsec(event.timestamp), event["filename"], event["fd"]) elif event.name == "lttng_statedump_block_device": self.state.statedump.block_device(event) cpu_id = event["cpu_id"] if cpu_id not in self.state.cpus.keys(): continue c = self.state.cpus[cpu_id] if c.current_tid not in self.state.tids.keys(): continue pid = self.state.tids[c.current_tid].pid if int(args.pid) != pid and override_tid == 0: continue if payload: print("%s" % (payload))
def run(self, args): """Process the trace""" self.current_sec = 0 self.start_ns = 0 self.end_ns = 0 for event in self.traces.events: if self.start_ns == 0: self.start_ns = event.timestamp if self.trace_start_ts == 0: self.trace_start_ts = event.timestamp self.end_ns = event.timestamp self.trace_end_ts = event.timestamp payload = "" override_tid = 0 if event.name == "sched_switch": self.state.sched.switch(event) elif event.name[0:4] == "sys_": payload = self.state.syscall.entry(event) elif event.name == "exit_syscall": payload = self.state.syscall.exit(event, 1) elif event.name == "block_complete" or \ event.name == "block_rq_complete": self.state.block.complete(event) elif event.name == "block_queue": self.state.block.queue(event) elif event.name == "netif_receive_skb": self.state.net.recv(event) elif event.name == "net_dev_xmit": self.state.net.send(event) elif event.name == "sched_process_fork": self.state.sched.process_fork(event) if int(event["child_tid"]) == int(args.pid): override_tid = 1 payload = "%s created by : %d" % ( ns_to_hour_nsec(event.timestamp), event["parent_tid"]) else: payload = "%s fork child_tid : %d" % ( ns_to_hour_nsec(event.timestamp), event["child_tid"]) elif event.name == "sched_process_exec": payload = "%s exec %s" % ( ns_to_hour_nsec(event.timestamp), event["filename"]) elif event.name == "lttng_statedump_process_state": self.state.statedump.process_state(event) if event["pid"] == int(args.pid): override_tid = 1 payload = "%s existed at statedump" % \ ns_to_hour_nsec(event.timestamp) elif event.name == "lttng_statedump_file_descriptor": self.state.statedump.file_descriptor(event) if event["pid"] == int(args.pid): override_tid = 1 payload = "%s statedump file : %s, fd : %d" % ( ns_to_hour_nsec(event.timestamp), event["filename"], event["fd"]) elif event.name == "lttng_statedump_block_device": self.state.statedump.block_device(event) cpu_id = event["cpu_id"] if cpu_id not in self.state.cpus.keys(): continue c = self.state.cpus[cpu_id] if c.current_tid not in self.state.tids.keys(): continue pid = self.state.tids[c.current_tid].pid if int(args.pid) != pid and override_tid == 0: continue if payload: print("%s" % (payload))
def output_fd_event(self, exit_event, entry): ret = exit_event['ret'] failed = ret < 0 if self.args.failed and not failed: return if self.err_number and ret != -err_number: return tid = self.state.cpus[exit_event['cpu_id']].current_tid if self.args.tid >= 0 and self.args.tid != tid: return pid = self.state.tids[tid].pid if pid == -1: pid = tid comm = self.state.tids[tid].comm if self.args.pname is not None and self.args.pname != comm: return filename = entry['filename'] if filename is None: return name = entry['name'] if args.syscall and args.syscall != name: return if self.args.start and entry['start'] < self.args.start: return if self.args.end and exit_event.timestamp > self.args.end: return endtime = exit_event.timestamp if not self.args.unixtime: endtime = ns_to_hour_nsec(endtime) else: endtime = '{:.9f}'.format(endtime / NS_IN_S) duration_ns = (exit_event.timestamp - entry['start']) if self.args.duration > 0 and duration_ns < self.args.duration: return duration = duration_ns / NS_IN_S if self.args.json or self.args.mongo or self.args.graphite or \ self.args.localfile: self.log_fd_event_json(tid, pid, comm, entry, name, duration_ns, filename, ret) if self.is_interactive and failed and not self.args.no_color: sys.stdout.write(FDInfo.FAILURE_RED) if filename.startswith(self.args.prefix) and not self.args.quiet: if not failed: print( FDInfo.SUCCESS_FORMAT.format(endtime, duration, comm, tid, name, ret, filename)) else: try: err_name = errno.errorcode[-ret] print( FDInfo.FAILURE_FORMAT.format(endtime, duration, comm, tid, name, ret, err_name, filename)) except KeyError: print('Invalid error code:', -ret) if self.is_interactive and failed and not self.args.no_color: sys.stdout.write(FDInfo.NORMAL_WHITE)
def track_rw_latency(self, name, ret, c, ts, started, event): current_syscall = self.tids[c.current_tid].current_syscall rq = current_syscall["iorequest"] if rq.size is None or rq.size == 0: rq.duration = (event.timestamp - current_syscall["start"]) else: rq.duration = (event.timestamp - current_syscall["start"]) / rq.size if not self.names: return if "start" not in current_syscall.keys(): return if "fd" in current_syscall.keys(): filename = current_syscall["fd"].filename fd = current_syscall["fd"].fd elif "fd_in" in current_syscall.keys(): filename = current_syscall["fd_in"].filename fd = current_syscall["fd_in"].fd else: filename = "unknown" fd = "" fd.iorequests.append(current_syscall["iorequest"]) if self.latency < 0: return ms = (ts - current_syscall["start"]) / MSEC_PER_NSEC latency = "%0.03f ms" % ms if self.seconds: ts_start = ns_to_sec(current_syscall["start"]) ts_end = ns_to_sec(ts) else: ts_start = ns_to_hour_nsec(current_syscall["start"]) ts_end = ns_to_hour_nsec(ts) procname = self.tids[c.current_tid].comm if name in ["sys_recvmsg", "syscall_entry_recvmsg"]: count = "" elif name in Syscalls.SYNC_SYSCALLS: count = "" else: count = ", count = %s" % (current_syscall["count"]) if self.names and self.latency < 0: self.latency = 0 if self.latency >= 0 and ms > self.latency: if self.names and "all" not in self.names and \ procname not in self.names: return if not started: return if self.latency_hist is not None: if procname not in self.latency_hist.keys(): self.latency_hist[procname] = [] self.latency_hist[procname].append((ts_start, ms)) # pages written during the latency if "pages_written" in current_syscall.keys(): pages = current_syscall["pages_written"] # dirty buffers during the latency if "dirty" in current_syscall.keys(): dirty = current_syscall["dirty"] else: dirty = 0 # alloc pages during the latency if "alloc" in current_syscall.keys(): alloc = current_syscall["alloc"] else: alloc = 0 # wakeup_kswapd during the latency if "page_free" in current_syscall.keys(): freed = current_syscall["page_free"] else: freed = 0 base = "[%s - %s] %s (%d)" % (ts_start, ts_end, procname, c.current_tid) spaces = (41) * " " page_cache = {} print("%s %s(fd = %s <%s>%s) = %d, %s" % (base, name, fd, filename, count, ret, latency)) if alloc > 0: print("%s %d pages allocated during the period" % (spaces, alloc)) if dirty > 0: print("%s %d buffers dirtied during the period" % (spaces, dirty)) if "wakeup_kswapd" in current_syscall.keys(): print("%s woke up kswapd during the period" % (spaces)) # dirty pages up-to now page_cache = self.get_page_queue_stats( self.dirty_pages["pages"]) if "pages_written" in current_syscall.keys(): print("%s %d pages written on disk" % (spaces, pages)) if freed > 0: print("%s freed %d pages from the cache during the period" % (spaces, freed)) if name in Syscalls.SYNC_SYSCALLS: self.syscall_clear_pages(event, name, fd, current_syscall, self.tids[c.current_tid]) if "pages_cleared" in current_syscall.keys(): print("%s %d dirty page(s) were flushed (assuming FIFO):" % (spaces, len(current_syscall["pages_cleared"]))) cleared_pages = self.get_page_queue_stats( current_syscall["pages_cleared"]) self.print_page_table(event, cleared_pages) page_cache = self.get_page_queue_stats( self.dirty_pages["pages"]) # page_cache = self.get_page_queue_stats() if len(page_cache) <= 0: return if "nr_dirty" not in event.keys(): print("%s %d last dirtied filesystem page(s):" % (spaces, len(self.dirty_pages["pages"]))) else: print("%s %d active dirty filesystem page(s) (known):" % (spaces, len(self.dirty_pages["pages"]))) self.print_page_table(event, page_cache)
def track_rw_latency(self, name, ret, c, ts, started, event): current_syscall = self.tids[c.current_tid].current_syscall rq = current_syscall["iorequest"] if rq.size is None or rq.size == 0: rq.duration = (event.timestamp - current_syscall["start"]) else: rq.duration = (event.timestamp - current_syscall["start"])/rq.size if not self.names: return if "start" not in current_syscall.keys(): return if "fd" in current_syscall.keys(): filename = current_syscall["fd"].filename fd = current_syscall["fd"].fd elif "fd_in" in current_syscall.keys(): filename = current_syscall["fd_in"].filename fd = current_syscall["fd_in"].fd else: filename = "unknown" fd = "" fd.iorequests.append(current_syscall["iorequest"]) if self.latency < 0: return ms = (ts - current_syscall["start"]) / MSEC_PER_NSEC latency = "%0.03f ms" % ms if self.seconds: ts_start = ns_to_sec(current_syscall["start"]) ts_end = ns_to_sec(ts) else: ts_start = ns_to_hour_nsec(current_syscall["start"]) ts_end = ns_to_hour_nsec(ts) procname = self.tids[c.current_tid].comm if name in ["sys_recvmsg", "syscall_entry_recvmsg"]: count = "" elif name in Syscalls.SYNC_SYSCALLS: count = "" else: count = ", count = %s" % (current_syscall["count"]) if self.names and self.latency < 0: self.latency = 0 if self.latency >= 0 and ms > self.latency: if self.names and "all" not in self.names and \ procname not in self.names: return if not started: return if self.latency_hist is not None: if procname not in self.latency_hist.keys(): self.latency_hist[procname] = [] self.latency_hist[procname].append((ts_start, ms)) # pages written during the latency if "pages_written" in current_syscall.keys(): pages = current_syscall["pages_written"] # dirty buffers during the latency if "dirty" in current_syscall.keys(): dirty = current_syscall["dirty"] else: dirty = 0 # alloc pages during the latency if "alloc" in current_syscall.keys(): alloc = current_syscall["alloc"] else: alloc = 0 # wakeup_kswapd during the latency if "page_free" in current_syscall.keys(): freed = current_syscall["page_free"] else: freed = 0 base = "[%s - %s] %s (%d)" % (ts_start, ts_end, procname, c.current_tid) spaces = (41) * " " page_cache = {} print("%s %s(fd = %s <%s>%s) = %d, %s" % (base, name, fd, filename, count, ret, latency)) if alloc > 0: print("%s %d pages allocated during the period" % (spaces, alloc)) if dirty > 0: print("%s %d buffers dirtied during the period" % (spaces, dirty)) if "wakeup_kswapd" in current_syscall.keys(): print("%s woke up kswapd during the period" % (spaces)) # dirty pages up-to now page_cache = self.get_page_queue_stats( self.dirty_pages["pages"]) if "pages_written" in current_syscall.keys(): print("%s %d pages written on disk" % (spaces, pages)) if freed > 0: print("%s freed %d pages from the cache during the period" % (spaces, freed)) if name in Syscalls.SYNC_SYSCALLS: self.syscall_clear_pages(event, name, fd, current_syscall, self.tids[c.current_tid]) if "pages_cleared" in current_syscall.keys(): print("%s %d dirty page(s) were flushed (assuming FIFO):" % (spaces, len(current_syscall["pages_cleared"]))) cleared_pages = self.get_page_queue_stats( current_syscall["pages_cleared"]) self.print_page_table(event, cleared_pages) page_cache = self.get_page_queue_stats( self.dirty_pages["pages"]) # page_cache = self.get_page_queue_stats() if len(page_cache) <= 0: return if "nr_dirty" not in event.keys(): print("%s %d last dirtied filesystem page(s):" % (spaces, len(self.dirty_pages["pages"]))) else: print("%s %d active dirty filesystem page(s) (known):" % (spaces, len(self.dirty_pages["pages"]))) self.print_page_table(event, page_cache)
def output_fd_event(self, exit_event, entry): ret = exit_event['ret'] failed = ret < 0 if self.args.failed and not failed: return if self.err_number and ret != -err_number: return tid = self.state.cpus[exit_event['cpu_id']].current_tid if self.args.tid >= 0 and self.args.tid != tid: return pid = self.state.tids[tid].pid if pid == -1: pid = tid comm = self.state.tids[tid].comm if self.args.pname is not None and self.args.pname != comm: return filename = entry['filename'] if filename is None: return name = entry['name'] if args.syscall and args.syscall != name: return if self.args.start and entry['start'] < self.args.start: return if self.args.end and exit_event.timestamp > self.args.end: return endtime = exit_event.timestamp if not self.args.unixtime: endtime = ns_to_hour_nsec(endtime) else: endtime = '{:.9f}'.format(endtime / NS_IN_S) duration_ns = (exit_event.timestamp - entry['start']) if self.args.duration > 0 and duration_ns < self.args.duration: return duration = duration_ns / NS_IN_S if self.args.json or self.args.mongo or self.args.graphite or \ self.args.localfile: self.log_fd_event_json(tid, pid, comm, entry, name, duration_ns, filename, ret) if self.is_interactive and failed and not self.args.no_color: sys.stdout.write(FDInfo.FAILURE_RED) if filename.startswith(self.args.prefix) and not self.args.quiet: if not failed: print(FDInfo.SUCCESS_FORMAT.format(endtime, duration, comm, tid, name, ret, filename)) else: try: err_name = errno.errorcode[-ret] print(FDInfo.FAILURE_FORMAT.format(endtime, duration, comm, tid, name, ret, err_name, filename)) except KeyError: print('Invalid error code:', -ret) if self.is_interactive and failed and not self.args.no_color: sys.stdout.write(FDInfo.NORMAL_WHITE)