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 = 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 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