def list_cpu_load(args):
load_per_cpu = {}
max_cpu = 0
n_defined = 0
with get_trace_reader(args) as reader:
for t in reader.get_traces():
if t.name == "sched_load":
if not t.cpu in load_per_cpu:
n_defined += 1
load_per_cpu[t.cpu] = t.data[0]
max_cpu = max(max_cpu, t.cpu)
if args.cpus:
if n_defined < args.cpus:
continue
if max_cpu >= args.cpus:
raise Exception('Encountered CPU with id=%d but user claimed there are %d CPUs' % (max_cpu, args.cpus))
if args.format == 'csv':
sys.stdout.write(trace.format_time(t.time))
for id in range(max_cpu + 1):
sys.stdout.write(',')
if id in load_per_cpu:
sys.stdout.write('%d' % load_per_cpu[id])
else:
sys.stdout.write('%-20s' % trace.format_time(t.time))
for id in range(max_cpu + 1):
if id in load_per_cpu:
sys.stdout.write('%3d' % load_per_cpu[id])
else:
sys.stdout.write('%3s' % '')
sys.stdout.write('\n')
def list_cpu_load(args):
load_per_cpu = {}
max_cpu = 0
n_defined = 0
with get_trace_reader(args) as reader:
for t in reader.get_traces():
if t.name == "sched_load":
if not t.cpu in load_per_cpu:
n_defined += 1
load_per_cpu[t.cpu] = t.data[0]
max_cpu = max(max_cpu, t.cpu)
if args.cpus:
if n_defined < args.cpus:
continue
if max_cpu >= args.cpus:
raise Exception('Encountered CPU with id=%d but user claimed there are %d CPUs' % (max_cpu, args.cpus))
if args.format == 'csv':
sys.stdout.write(trace.format_time(t.time))
for id in range(max_cpu + 1):
sys.stdout.write(',')
if id in load_per_cpu:
sys.stdout.write('%d' % load_per_cpu[id])
else:
sys.stdout.write('%-20s' % trace.format_time(t.time))
for id in range(max_cpu + 1):
if id in load_per_cpu:
sys.stdout.write('%3d' % load_per_cpu[id])
else:
sys.stdout.write('%3s' % '')
sys.stdout.write('\n')
def list_timed(args):
bt_formatter = get_backtrace_formatter(args)
time_range = get_time_range(args)
with get_trace_reader(args) as reader:
timed_traces = prof.get_timed_traces(reader.get_traces(), time_range)
if args.sort:
if args.sort == 'duration':
order = -1
elif args.sort == 'time':
order = 1
timed_traces = sorted(timed_traces, key=lambda timed: order * getattr(timed, args.sort))
for timed in timed_traces:
t = timed.trace
print '0x%016x %-15s %2d %20s %7s %-20s %s%s' % (
t.thread.ptr,
t.thread.name,
t.cpu,
trace.format_time(t.time),
trace.format_duration(timed.duration),
t.name,
trace.Trace.format_data(t),
bt_formatter(t.backtrace))
def list_timed(args):
bt_formatter = get_backtrace_formatter(args)
time_range = get_time_range(args)
with get_trace_reader(args) as reader:
timed_traces = prof.get_timed_traces(reader.get_traces(), time_range)
if args.sort:
if args.sort == 'duration':
order = -1
elif args.sort == 'time':
order = 1
timed_traces = sorted(timed_traces, key=lambda timed: order * getattr(timed, args.sort))
for timed in timed_traces:
t = timed.trace
print '0x%016x %-15s %2d %20s %7s %-20s %s%s' % (
t.thread.ptr,
t.thread.name,
t.cpu,
trace.format_time(t.time),
trace.format_duration(timed.duration),
t.name,
trace.Trace.format_data(t),
bt_formatter(t.backtrace))
def list_timed(args):
bt_formatter = get_backtrace_formatter(args)
time_range = get_time_range(args)
with get_trace_reader(args) as reader:
timed_traces = get_timed_traces(reader.get_traces(), time_range)
if args.sort:
if args.sort == "duration":
order = -1
elif args.sort == "time":
order = 1
timed_traces = sorted(timed_traces, key=lambda timed: order * getattr(timed, args.sort))
for timed in timed_traces:
t = timed.trace
print "0x%016x %2d %20s %7s %-20s %s%s" % (
t.thread,
t.cpu,
trace.format_time(t.time),
trace.format_duration(timed.duration),
t.name,
t.format_data(),
bt_formatter(t.backtrace),
)
def trace_function(indent, annotation, data):
fn, caller = data
try:
block = gdb.block_for_pc(to_int(fn))
fn_name = block.function.print_name
except:
fn_name = "???"
out_func("0x%016x %2d %19s %s %s %s\n" % (thread, cpu, format_time(time), indent, annotation, fn_name))
def trace_function(indent, annotation, data):
fn, caller = data
try:
block = gdb.block_for_pc(long(fn))
fn_name = block.function.print_name
except:
fn_name = '???'
out_func('0x%016x %2d %19s %s %s %s\n'
% (thread,
cpu,
format_time(time),
indent,
annotation,
fn_name,
))
def trace_function(indent, annotation, data):
fn, caller = data
try:
block = gdb.block_for_pc(long(fn))
fn_name = block.function.print_name
except:
fn_name = '???'
out_func('0x%016x %2d %19s %s %s %s\n' % (
thread,
cpu,
format_time(time),
indent,
annotation,
fn_name,
))
def dump_timed_trace(out_func, filter=None, sort=False):
bt_formatter = BacktraceFormatter(syminfo)
traces = ifilter(filter, all_traces())
timed_traces = get_timed_traces(traces)
if sort:
timed_traces = sorted(timed_traces, key=lambda timed: -timed.duration)
for timed in timed_traces:
trace = timed.trace
out_func('0x%016x %2d %20s %7s %-20s %s%s\n'
% (trace.thread,
trace.cpu,
format_time(trace.time),
format_duration(timed.duration),
trace.name,
trace.format_data(),
bt_formatter(trace.backtrace),
))
def list_wakeup_latency(args):
bt_formatter = get_backtrace_formatter(args)
time_range = get_time_range(args)
class WaitingThread:
def __init__(self):
self.wait = None
self.wake = None
waiting = defaultdict(WaitingThread)
def format_wakeup_latency(nanos):
return "%4.6f" % (float(nanos) / 1e6)
if not args.no_header:
print '%-18s %-15s %3s %20s %13s %9s %s' % (
"THREAD", "THREAD-NAME", "CPU", "TIMESTAMP[s]", "WAKEUP[ms]", "WAIT[ms]", "BACKTRACE"
)
with get_trace_reader(args) as reader:
for t in reader.get_traces():
if t.name == "sched_wait":
waiting[t.thread.ptr].wait = t
elif t.name == "sched_wake":
thread_id = t.data[0]
if waiting[thread_id].wait:
waiting[thread_id].wake = t
elif t.name == "sched_wait_ret":
waiting_thread = waiting.pop(t.thread.ptr, None)
if waiting_thread and waiting_thread.wake:
# See https://github.com/cloudius-systems/osv/issues/295
if t.cpu == waiting_thread.wait.cpu:
wakeup_delay = t.time - waiting_thread.wake.time
wait_time = t.time - waiting_thread.wait.time
print '0x%016x %-15s %3d %20s %13s %9s %s' % (
t.thread.ptr,
t.thread.name,
t.cpu,
trace.format_time(t.time),
format_wakeup_latency(wakeup_delay),
trace.format_duration(wait_time),
bt_formatter(t.backtrace))
def list_wakeup_latency(args):
bt_formatter = get_backtrace_formatter(args)
time_range = get_time_range(args)
class WaitingThread:
def __init__(self):
self.wait = None
self.wake = None
waiting = defaultdict(WaitingThread)
def format_wakeup_latency(nanos):
return "%4.6f" % (float(nanos) / 1e6)
if not args.no_header:
print '%-18s %-15s %3s %20s %13s %9s %s' % (
"THREAD", "THREAD-NAME", "CPU", "TIMESTAMP[s]", "WAKEUP[ms]", "WAIT[ms]", "BACKTRACE"
)
with get_trace_reader(args) as reader:
for t in reader.get_traces():
if t.name == "sched_wait":
waiting[t.thread.ptr].wait = t
elif t.name == "sched_wake":
thread_id = t.data[0]
if waiting[thread_id].wait:
waiting[thread_id].wake = t
elif t.name == "sched_wait_ret":
waiting_thread = waiting.pop(t.thread.ptr, None)
if waiting_thread and waiting_thread.wake:
# See https://github.com/cloudius-systems/osv/issues/295
if t.cpu == waiting_thread.wait.cpu:
wakeup_delay = t.time - waiting_thread.wake.time
wait_time = t.time - waiting_thread.wait.time
print '0x%016x %-15s %3d %20s %13s %9s %s' % (
t.thread.ptr,
t.thread.name,
t.cpu,
trace.format_time(t.time),
format_wakeup_latency(wakeup_delay),
trace.format_duration(wait_time),
bt_formatter(t.backtrace))
def print_summary(args, printer=sys.stdout.write):
time_range = get_time_range(args)
timed_producer = prof.timed_trace_producer()
timed_samples = []
count_per_tp = defaultdict(lambda: 0)
count = 0
min_time = None
max_time = None
class CpuTimeRange:
def __init__(self):
self.min = None
self.max = None
def update(self, time):
if self.min is None or time < self.min:
self.min = time
if self.max is None or time > self.max:
self.max = time
cpu_time_ranges = defaultdict(CpuTimeRange)
with get_trace_reader(args) as reader:
for t in reader.get_traces():
if t.time in time_range:
cpu_time_ranges[t.cpu].update(t.time)
count += 1
count_per_tp[t.tp] += 1
if not min_time:
min_time = t.time
else:
min_time = min(min_time, t.time)
if not max_time:
max_time = t.time
else:
max_time = max(max_time, t.time)
if args.timed:
timed = timed_producer(t)
if timed:
timed_samples.append(timed)
if args.timed:
timed_samples.extend((timed_producer.finish()))
if count == 0:
print("No samples")
return
print("Collected %d samples spanning %s" %
(count, prof.format_time(max_time - min_time)))
print("\nTime ranges:\n")
for cpu, r in sorted(list(cpu_time_ranges.items()),
key=lambda c_r: c_r[1].min):
print(" CPU 0x%02d: %s - %s = %10s" % (cpu, trace.format_time(
r.min), trace.format_time(r.max), prof.format_time(r.max - r.min)))
max_name_len = reduce(max,
[len(tp.name) for tp in iter(count_per_tp.keys())])
format = " %%-%ds %%8s" % (max_name_len)
print("\nTracepoint statistics:\n")
print(format % ("name", "count"))
print(format % ("----", "-----"))
for tp, count in sorted(iter(count_per_tp.items()),
key=lambda tp_count: tp_count[0].name):
print(format % (tp.name, count))
if args.timed:
format = " %-20s %8s %8s %8s %8s %8s %8s %8s %15s"
print("\nTimed tracepoints [ms]:\n")
timed_samples = [
t for t in timed_samples if t.time_range.intersection(time_range)
]
if not timed_samples:
print(" None")
else:
print(format % ("name", "count", "min", "50%", "90%", "99%",
"99.9%", "max", "total"))
print(format % ("----", "-----", "---", "---", "---", "---",
"-----", "---", "-----"))
for name, traces in get_timed_traces_per_function(
timed_samples).items():
samples = sorted(
list((t.time_range.intersection(time_range).length()
for t in traces)))
print(format %
(name, len(samples),
format_duration(get_percentile(samples, 0)),
format_duration(get_percentile(samples, 0.5)),
format_duration(get_percentile(samples, 0.9)),
format_duration(get_percentile(samples, 0.99)),
format_duration(get_percentile(samples, 0.999)),
format_duration(get_percentile(
samples, 1)), format_duration(sum(samples))))
print()
def print_summary(args, printer=sys.stdout.write):
time_range = get_time_range(args)
timed_producer = prof.timed_trace_producer()
timed_samples = []
count_per_tp = defaultdict(lambda: 0)
count = 0
min_time = None
max_time = None
class CpuTimeRange:
def __init__(self):
self.min = None
self.max = None
def update(self, time):
if self.min is None or time < self.min:
self.min = time
if self.max is None or time > self.max:
self.max = time
cpu_time_ranges = defaultdict(CpuTimeRange)
with get_trace_reader(args) as reader:
for t in reader.get_traces():
if t.time in time_range:
cpu_time_ranges[t.cpu].update(t.time)
count += 1
count_per_tp[t.tp] += 1
if not min_time:
min_time = t.time
else:
min_time = min(min_time, t.time)
max_time = max(max_time, t.time)
if args.timed:
timed = timed_producer(t)
if timed:
timed_samples.append(timed)
if args.timed:
timed_samples.extend((timed_producer.finish()))
if count == 0:
print "No samples"
return
print "Collected %d samples spanning %s" % (count, prof.format_time(max_time - min_time))
print "\nTime ranges:\n"
for cpu, r in sorted(cpu_time_ranges.items(), key=lambda (c, r): r.min):
print " CPU 0x%02d: %s - %s = %10s" % (cpu,
trace.format_time(r.min),
trace.format_time(r.max),
prof.format_time(r.max - r.min))
max_name_len = reduce(max, map(lambda tp: len(tp.name), count_per_tp.iterkeys()))
format = " %%-%ds %%8s" % (max_name_len)
print "\nTracepoint statistics:\n"
print format % ("name", "count")
print format % ("----", "-----")
for tp, count in sorted(count_per_tp.iteritems(), key=lambda (tp, count): tp.name):
print format % (tp.name, count)
if args.timed:
format = " %-20s %8s %8s %8s %8s %8s %8s %8s %15s"
print "\nTimed tracepoints [ms]:\n"
timed_samples = filter(lambda t: t.time_range.intersection(time_range), timed_samples)
if not timed_samples:
print " None"
else:
print format % ("name", "count", "min", "50%", "90%", "99%", "99.9%", "max", "total")
print format % ("----", "-----", "---", "---", "---", "---", "-----", "---", "-----")
for name, traces in get_timed_traces_per_function(timed_samples).iteritems():
samples = sorted(list((t.time_range.intersection(time_range).length() for t in traces)))
print format % (
name,
len(samples),
format_duration(get_percentile(samples, 0)),
format_duration(get_percentile(samples, 0.5)),
format_duration(get_percentile(samples, 0.9)),
format_duration(get_percentile(samples, 0.99)),
format_duration(get_percentile(samples, 0.999)),
format_duration(get_percentile(samples, 1)),
format_duration(sum(samples)))
print
