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)