From 359d5106a2ff4ffa2ba129ec8f54743c341dabfc Mon Sep 17 00:00:00 2001 From: Koki Sanagi Date: Mon, 23 Aug 2010 18:47:09 +0900 Subject: perf: Add a script to show packets processing Add a perf script which shows packets processing and processed time. It helps us to investigate networking or network devices. If you want to use it, install perf and record perf.data like following. If you set script, perf gathers records until it ends. If not, you must Ctrl-C to stop recording. And if you want a report from record, If you use some options, you can limit the output. Option is below. tx: show only tx packets processing rx: show only rx packets processing dev=: show processing on this device debug: work with debug mode. It shows buffer status. For example, if you want to show received packets processing associated with eth4, 106133.171439sec cpu=0 irq_entry(+0.000msec irq=24:eth4) | softirq_entry(+0.006msec) | |---netif_receive_skb(+0.010msec skb=f2d15900 len=100) | | | skb_copy_datagram_iovec(+0.039msec 10291::10291) | napi_poll_exit(+0.022msec eth4) This perf script helps us to analyze the processing time of a transmit/receive sequence. Signed-off-by: Koki Sanagi Acked-by: David S. Miller Cc: Neil Horman Cc: Mathieu Desnoyers Cc: Kaneshige Kenji Cc: Izumo Taku Cc: Kosaki Motohiro Cc: Lai Jiangshan Cc: Scott Mcmillan Cc: Steven Rostedt Cc: Eric Dumazet Cc: Tom Zanussi LKML-Reference: <4C72439D.3040001@jp.fujitsu.com> Signed-off-by: Frederic Weisbecker --- tools/perf/scripts/python/bin/netdev-times-record | 8 + tools/perf/scripts/python/bin/netdev-times-report | 5 + tools/perf/scripts/python/netdev-times.py | 464 ++++++++++++++++++++++ 3 files changed, 477 insertions(+) create mode 100644 tools/perf/scripts/python/bin/netdev-times-record create mode 100644 tools/perf/scripts/python/bin/netdev-times-report create mode 100644 tools/perf/scripts/python/netdev-times.py (limited to 'tools/perf/scripts/python') diff --git a/tools/perf/scripts/python/bin/netdev-times-record b/tools/perf/scripts/python/bin/netdev-times-record new file mode 100644 index 000000000000..d931a828126b --- /dev/null +++ b/tools/perf/scripts/python/bin/netdev-times-record @@ -0,0 +1,8 @@ +#!/bin/bash +perf record -a -e net:net_dev_xmit -e net:net_dev_queue \ + -e net:netif_receive_skb -e net:netif_rx \ + -e skb:consume_skb -e skb:kfree_skb \ + -e skb:skb_copy_datagram_iovec -e napi:napi_poll \ + -e irq:irq_handler_entry -e irq:irq_handler_exit \ + -e irq:softirq_entry -e irq:softirq_exit \ + -e irq:softirq_raise $@ diff --git a/tools/perf/scripts/python/bin/netdev-times-report b/tools/perf/scripts/python/bin/netdev-times-report new file mode 100644 index 000000000000..c3d0a638123d --- /dev/null +++ b/tools/perf/scripts/python/bin/netdev-times-report @@ -0,0 +1,5 @@ +#!/bin/bash +# description: display a process of packet and processing time +# args: [tx] [rx] [dev=] [debug] + +perf trace -s ~/libexec/perf-core/scripts/python/netdev-times.py $@ diff --git a/tools/perf/scripts/python/netdev-times.py b/tools/perf/scripts/python/netdev-times.py new file mode 100644 index 000000000000..9aa0a32972e8 --- /dev/null +++ b/tools/perf/scripts/python/netdev-times.py @@ -0,0 +1,464 @@ +# Display a process of packets and processed time. +# It helps us to investigate networking or network device. +# +# options +# tx: show only tx chart +# rx: show only rx chart +# dev=: show only thing related to specified device +# debug: work with debug mode. It shows buffer status. + +import os +import sys + +sys.path.append(os.environ['PERF_EXEC_PATH'] + \ + '/scripts/python/Perf-Trace-Util/lib/Perf/Trace') + +from perf_trace_context import * +from Core import * +from Util import * + +all_event_list = []; # insert all tracepoint event related with this script +irq_dic = {}; # key is cpu and value is a list which stacks irqs + # which raise NET_RX softirq +net_rx_dic = {}; # key is cpu and value include time of NET_RX softirq-entry + # and a list which stacks receive +receive_hunk_list = []; # a list which include a sequence of receive events +rx_skb_list = []; # received packet list for matching + # skb_copy_datagram_iovec + +buffer_budget = 65536; # the budget of rx_skb_list, tx_queue_list and + # tx_xmit_list +of_count_rx_skb_list = 0; # overflow count + +tx_queue_list = []; # list of packets which pass through dev_queue_xmit +of_count_tx_queue_list = 0; # overflow count + +tx_xmit_list = []; # list of packets which pass through dev_hard_start_xmit +of_count_tx_xmit_list = 0; # overflow count + +tx_free_list = []; # list of packets which is freed + +# options +show_tx = 0; +show_rx = 0; +dev = 0; # store a name of device specified by option "dev=" +debug = 0; + +# indices of event_info tuple +EINFO_IDX_NAME= 0 +EINFO_IDX_CONTEXT=1 +EINFO_IDX_CPU= 2 +EINFO_IDX_TIME= 3 +EINFO_IDX_PID= 4 +EINFO_IDX_COMM= 5 + +# Calculate a time interval(msec) from src(nsec) to dst(nsec) +def diff_msec(src, dst): + return (dst - src) / 1000000.0 + +# Display a process of transmitting a packet +def print_transmit(hunk): + if dev != 0 and hunk['dev'].find(dev) < 0: + return + print "%7s %5d %6d.%06dsec %12.3fmsec %12.3fmsec" % \ + (hunk['dev'], hunk['len'], + nsecs_secs(hunk['queue_t']), + nsecs_nsecs(hunk['queue_t'])/1000, + diff_msec(hunk['queue_t'], hunk['xmit_t']), + diff_msec(hunk['xmit_t'], hunk['free_t'])) + +# Format for displaying rx packet processing +PF_IRQ_ENTRY= " irq_entry(+%.3fmsec irq=%d:%s)" +PF_SOFT_ENTRY=" softirq_entry(+%.3fmsec)" +PF_NAPI_POLL= " napi_poll_exit(+%.3fmsec %s)" +PF_JOINT= " |" +PF_WJOINT= " | |" +PF_NET_RECV= " |---netif_receive_skb(+%.3fmsec skb=%x len=%d)" +PF_NET_RX= " |---netif_rx(+%.3fmsec skb=%x)" +PF_CPY_DGRAM= " | skb_copy_datagram_iovec(+%.3fmsec %d:%s)" +PF_KFREE_SKB= " | kfree_skb(+%.3fmsec location=%x)" +PF_CONS_SKB= " | consume_skb(+%.3fmsec)" + +# Display a process of received packets and interrputs associated with +# a NET_RX softirq +def print_receive(hunk): + show_hunk = 0 + irq_list = hunk['irq_list'] + cpu = irq_list[0]['cpu'] + base_t = irq_list[0]['irq_ent_t'] + # check if this hunk should be showed + if dev != 0: + for i in range(len(irq_list)): + if irq_list[i]['name'].find(dev) >= 0: + show_hunk = 1 + break + else: + show_hunk = 1 + if show_hunk == 0: + return + + print "%d.%06dsec cpu=%d" % \ + (nsecs_secs(base_t), nsecs_nsecs(base_t)/1000, cpu) + for i in range(len(irq_list)): + print PF_IRQ_ENTRY % \ + (diff_msec(base_t, irq_list[i]['irq_ent_t']), + irq_list[i]['irq'], irq_list[i]['name']) + print PF_JOINT + irq_event_list = irq_list[i]['event_list'] + for j in range(len(irq_event_list)): + irq_event = irq_event_list[j] + if irq_event['event'] == 'netif_rx': + print PF_NET_RX % \ + (diff_msec(base_t, irq_event['time']), + irq_event['skbaddr']) + print PF_JOINT + print PF_SOFT_ENTRY % \ + diff_msec(base_t, hunk['sirq_ent_t']) + print PF_JOINT + event_list = hunk['event_list'] + for i in range(len(event_list)): + event = event_list[i] + if event['event_name'] == 'napi_poll': + print PF_NAPI_POLL % \ + (diff_msec(base_t, event['event_t']), event['dev']) + if i == len(event_list) - 1: + print "" + else: + print PF_JOINT + else: + print PF_NET_RECV % \ + (diff_msec(base_t, event['event_t']), event['skbaddr'], + event['len']) + if 'comm' in event.keys(): + print PF_WJOINT + print PF_CPY_DGRAM % \ + (diff_msec(base_t, event['comm_t']), + event['pid'], event['comm']) + elif 'handle' in event.keys(): + print PF_WJOINT + if event['handle'] == "kfree_skb": + print PF_KFREE_SKB % \ + (diff_msec(base_t, + event['comm_t']), + event['location']) + elif event['handle'] == "consume_skb": + print PF_CONS_SKB % \ + diff_msec(base_t, + event['comm_t']) + print PF_JOINT + +def trace_begin(): + global show_tx + global show_rx + global dev + global debug + + for i in range(len(sys.argv)): + if i == 0: + continue + arg = sys.argv[i] + if arg == 'tx': + show_tx = 1 + elif arg =='rx': + show_rx = 1 + elif arg.find('dev=',0, 4) >= 0: + dev = arg[4:] + elif arg == 'debug': + debug = 1 + if show_tx == 0 and show_rx == 0: + show_tx = 1 + show_rx = 1 + +def trace_end(): + # order all events in time + all_event_list.sort(lambda a,b :cmp(a[EINFO_IDX_TIME], + b[EINFO_IDX_TIME])) + # process all events + for i in range(len(all_event_list)): + event_info = all_event_list[i] + name = event_info[EINFO_IDX_NAME] + if name == 'irq__softirq_exit': + handle_irq_softirq_exit(event_info) + elif name == 'irq__softirq_entry': + handle_irq_softirq_entry(event_info) + elif name == 'irq__softirq_raise': + handle_irq_softirq_raise(event_info) + elif name == 'irq__irq_handler_entry': + handle_irq_handler_entry(event_info) + elif name == 'irq__irq_handler_exit': + handle_irq_handler_exit(event_info) + elif name == 'napi__napi_poll': + handle_napi_poll(event_info) + elif name == 'net__netif_receive_skb': + handle_netif_receive_skb(event_info) + elif name == 'net__netif_rx': + handle_netif_rx(event_info) + elif name == 'skb__skb_copy_datagram_iovec': + handle_skb_copy_datagram_iovec(event_info) + elif name == 'net__net_dev_queue': + handle_net_dev_queue(event_info) + elif name == 'net__net_dev_xmit': + handle_net_dev_xmit(event_info) + elif name == 'skb__kfree_skb': + handle_kfree_skb(event_info) + elif name == 'skb__consume_skb': + handle_consume_skb(event_info) + # display receive hunks + if show_rx: + for i in range(len(receive_hunk_list)): + print_receive(receive_hunk_list[i]) + # display transmit hunks + if show_tx: + print " dev len Qdisc " \ + " netdevice free" + for i in range(len(tx_free_list)): + print_transmit(tx_free_list[i]) + if debug: + print "debug buffer status" + print "----------------------------" + print "xmit Qdisc:remain:%d overflow:%d" % \ + (len(tx_queue_list), of_count_tx_queue_list) + print "xmit netdevice:remain:%d overflow:%d" % \ + (len(tx_xmit_list), of_count_tx_xmit_list) + print "receive:remain:%d overflow:%d" % \ + (len(rx_skb_list), of_count_rx_skb_list) + +# called from perf, when it finds a correspoinding event +def irq__softirq_entry(name, context, cpu, sec, nsec, pid, comm, vec): + if symbol_str("irq__softirq_entry", "vec", vec) != "NET_RX": + return + event_info = (name, context, cpu, nsecs(sec, nsec), pid, comm, vec) + all_event_list.append(event_info) + +def irq__softirq_exit(name, context, cpu, sec, nsec, pid, comm, vec): + if symbol_str("irq__softirq_entry", "vec", vec) != "NET_RX": + return + event_info = (name, context, cpu, nsecs(sec, nsec), pid, comm, vec) + all_event_list.append(event_info) + +def irq__softirq_raise(name, context, cpu, sec, nsec, pid, comm, vec): + if symbol_str("irq__softirq_entry", "vec", vec) != "NET_RX": + return + event_info = (name, context, cpu, nsecs(sec, nsec), pid, comm, vec) + all_event_list.append(event_info) + +def irq__irq_handler_entry(name, context, cpu, sec, nsec, pid, comm, + irq, irq_name): + event_info = (name, context, cpu, nsecs(sec, nsec), pid, comm, + irq, irq_name) + all_event_list.append(event_info) + +def irq__irq_handler_exit(name, context, cpu, sec, nsec, pid, comm, irq, ret): + event_info = (name, context, cpu, nsecs(sec, nsec), pid, comm, irq, ret) + all_event_list.append(event_info) + +def napi__napi_poll(name, context, cpu, sec, nsec, pid, comm, napi, dev_name): + event_info = (name, context, cpu, nsecs(sec, nsec), pid, comm, + napi, dev_name) + all_event_list.append(event_info) + +def net__netif_receive_skb(name, context, cpu, sec, nsec, pid, comm, skbaddr, + skblen, dev_name): + event_info = (name, context, cpu, nsecs(sec, nsec), pid, comm, + skbaddr, skblen, dev_name) + all_event_list.append(event_info) + +def net__netif_rx(name, context, cpu, sec, nsec, pid, comm, skbaddr, + skblen, dev_name): + event_info = (name, context, cpu, nsecs(sec, nsec), pid, comm, + skbaddr, skblen, dev_name) + all_event_list.append(event_info) + +def net__net_dev_queue(name, context, cpu, sec, nsec, pid, comm, + skbaddr, skblen, dev_name): + event_info = (name, context, cpu, nsecs(sec, nsec), pid, comm, + skbaddr, skblen, dev_name) + all_event_list.append(event_info) + +def net__net_dev_xmit(name, context, cpu, sec, nsec, pid, comm, + skbaddr, skblen, rc, dev_name): + event_info = (name, context, cpu, nsecs(sec, nsec), pid, comm, + skbaddr, skblen, rc ,dev_name) + all_event_list.append(event_info) + +def skb__kfree_skb(name, context, cpu, sec, nsec, pid, comm, + skbaddr, protocol, location): + event_info = (name, context, cpu, nsecs(sec, nsec), pid, comm, + skbaddr, protocol, location) + all_event_list.append(event_info) + +def skb__consume_skb(name, context, cpu, sec, nsec, pid, comm, skbaddr): + event_info = (name, context, cpu, nsecs(sec, nsec), pid, comm, + skbaddr) + all_event_list.append(event_info) + +def skb__skb_copy_datagram_iovec(name, context, cpu, sec, nsec, pid, comm, + skbaddr, skblen): + event_info = (name, context, cpu, nsecs(sec, nsec), pid, comm, + skbaddr, skblen) + all_event_list.append(event_info) + +def handle_irq_handler_entry(event_info): + (name, context, cpu, time, pid, comm, irq, irq_name) = event_info + if cpu not in irq_dic.keys(): + irq_dic[cpu] = [] + irq_record = {'irq':irq, 'name':irq_name, 'cpu':cpu, 'irq_ent_t':time} + irq_dic[cpu].append(irq_record) + +def handle_irq_handler_exit(event_info): + (name, context, cpu, time, pid, comm, irq, ret) = event_info + if cpu not in irq_dic.keys(): + return + irq_record = irq_dic[cpu].pop() + if irq != irq_record['irq']: + return + irq_record.update({'irq_ext_t':time}) + # if an irq doesn't include NET_RX softirq, drop. + if 'event_list' in irq_record.keys(): + irq_dic[cpu].append(irq_record) + +def handle_irq_softirq_raise(event_info): + (name, context, cpu, time, pid, comm, vec) = event_info + if cpu not in irq_dic.keys() \ + or len(irq_dic[cpu]) == 0: + return + irq_record = irq_dic[cpu].pop() + if 'event_list' in irq_record.keys(): + irq_event_list = irq_record['event_list'] + else: + irq_event_list = [] + irq_event_list.append({'time':time, 'event':'sirq_raise'}) + irq_record.update({'event_list':irq_event_list}) + irq_dic[cpu].append(irq_record) + +def handle_irq_softirq_entry(event_info): + (name, context, cpu, time, pid, comm, vec) = event_info + net_rx_dic[cpu] = {'sirq_ent_t':time, 'event_list':[]} + +def handle_irq_softirq_exit(event_info): + (name, context, cpu, time, pid, comm, vec) = event_info + irq_list = [] + event_list = 0 + if cpu in irq_dic.keys(): + irq_list = irq_dic[cpu] + del irq_dic[cpu] + if cpu in net_rx_dic.keys(): + sirq_ent_t = net_rx_dic[cpu]['sirq_ent_t'] + event_list = net_rx_dic[cpu]['event_list'] + del net_rx_dic[cpu] + if irq_list == [] or event_list == 0: + return + rec_data = {'sirq_ent_t':sirq_ent_t, 'sirq_ext_t':time, + 'irq_list':irq_list, 'event_list':event_list} + # merge information realted to a NET_RX softirq + receive_hunk_list.append(rec_data) + +def handle_napi_poll(event_info): + (name, context, cpu, time, pid, comm, napi, dev_name) = event_info + if cpu in net_rx_dic.keys(): + event_list = net_rx_dic[cpu]['event_list'] + rec_data = {'event_name':'napi_poll', + 'dev':dev_name, 'event_t':time} + event_list.append(rec_data) + +def handle_netif_rx(event_info): + (name, context, cpu, time, pid, comm, + skbaddr, skblen, dev_name) = event_info + if cpu not in irq_dic.keys() \ + or len(irq_dic[cpu]) == 0: + return + irq_record = irq_dic[cpu].pop() + if 'event_list' in irq_record.keys(): + irq_event_list = irq_record['event_list'] + else: + irq_event_list = [] + irq_event_list.append({'time':time, 'event':'netif_rx', + 'skbaddr':skbaddr, 'skblen':skblen, 'dev_name':dev_name}) + irq_record.update({'event_list':irq_event_list}) + irq_dic[cpu].append(irq_record) + +def handle_netif_receive_skb(event_info): + global of_count_rx_skb_list + + (name, context, cpu, time, pid, comm, + skbaddr, skblen, dev_name) = event_info + if cpu in net_rx_dic.keys(): + rec_data = {'event_name':'netif_receive_skb', + 'event_t':time, 'skbaddr':skbaddr, 'len':skblen} + event_list = net_rx_dic[cpu]['event_list'] + event_list.append(rec_data) + rx_skb_list.insert(0, rec_data) + if len(rx_skb_list) > buffer_budget: + rx_skb_list.pop() + of_count_rx_skb_list += 1 + +def handle_net_dev_queue(event_info): + global of_count_tx_queue_list + + (name, context, cpu, time, pid, comm, + skbaddr, skblen, dev_name) = event_info + skb = {'dev':dev_name, 'skbaddr':skbaddr, 'len':skblen, 'queue_t':time} + tx_queue_list.insert(0, skb) + if len(tx_queue_list) > buffer_budget: + tx_queue_list.pop() + of_count_tx_queue_list += 1 + +def handle_net_dev_xmit(event_info): + global of_count_tx_xmit_list + + (name, context, cpu, time, pid, comm, + skbaddr, skblen, rc, dev_name) = event_info + if rc == 0: # NETDEV_TX_OK + for i in range(len(tx_queue_list)): + skb = tx_queue_list[i] + if skb['skbaddr'] == skbaddr: + skb['xmit_t'] = time + tx_xmit_list.insert(0, skb) + del tx_queue_list[i] + if len(tx_xmit_list) > buffer_budget: + tx_xmit_list.pop() + of_count_tx_xmit_list += 1 + return + +def handle_kfree_skb(event_info): + (name, context, cpu, time, pid, comm, + skbaddr, protocol, location) = event_info + for i in range(len(tx_queue_list)): + skb = tx_queue_list[i] + if skb['skbaddr'] == skbaddr: + del tx_queue_list[i] + return + for i in range(len(tx_xmit_list)): + skb = tx_xmit_list[i] + if skb['skbaddr'] == skbaddr: + skb['free_t'] = time + tx_free_list.append(skb) + del tx_xmit_list[i] + return + for i in range(len(rx_skb_list)): + rec_data = rx_skb_list[i] + if rec_data['skbaddr'] == skbaddr: + rec_data.update({'handle':"kfree_skb", + 'comm':comm, 'pid':pid, 'comm_t':time}) + del rx_skb_list[i] + return + +def handle_consume_skb(event_info): + (name, context, cpu, time, pid, comm, skbaddr) = event_info + for i in range(len(tx_xmit_list)): + skb = tx_xmit_list[i] + if skb['skbaddr'] == skbaddr: + skb['free_t'] = time + tx_free_list.append(skb) + del tx_xmit_list[i] + return + +def handle_skb_copy_datagram_iovec(event_info): + (name, context, cpu, time, pid, comm, skbaddr, skblen) = event_info + for i in range(len(rx_skb_list)): + rec_data = rx_skb_list[i] + if skbaddr == rec_data['skbaddr']: + rec_data.update({'handle':"skb_copy_datagram_iovec", + 'comm':comm, 'pid':pid, 'comm_t':time}) + del rx_skb_list[i] + return -- cgit v1.2.3 From 44e668c6faa9a6c477a32788e7e88f0754c54a4e Mon Sep 17 00:00:00 2001 From: Ben Hutchings Date: Sun, 10 Oct 2010 16:10:03 +0100 Subject: perf trace: Use $PERF_EXEC_PATH in canned report scripts Set $PERF_EXEC_PATH before starting the record and report scripts, and make them use it where necessary. Cc: Ingo Molnar Cc: Paul Mackerras Cc: Peter Zijlstra LKML-Reference: <1286723403.2955.205.camel@localhost> Signed-off-by: Ben Hutchings Signed-off-by: Arnaldo Carvalho de Melo --- tools/perf/scripts/python/bin/failed-syscalls-by-pid-report | 2 +- tools/perf/scripts/python/bin/netdev-times-report | 2 +- tools/perf/scripts/python/bin/sched-migration-report | 2 +- tools/perf/scripts/python/bin/sctop-report | 2 +- tools/perf/scripts/python/bin/syscall-counts-by-pid-report | 2 +- tools/perf/scripts/python/bin/syscall-counts-report | 2 +- 6 files changed, 6 insertions(+), 6 deletions(-) (limited to 'tools/perf/scripts/python') diff --git a/tools/perf/scripts/python/bin/failed-syscalls-by-pid-report b/tools/perf/scripts/python/bin/failed-syscalls-by-pid-report index 30293545fcc2..03587021463d 100644 --- a/tools/perf/scripts/python/bin/failed-syscalls-by-pid-report +++ b/tools/perf/scripts/python/bin/failed-syscalls-by-pid-report @@ -7,4 +7,4 @@ if [ $# -gt 0 ] ; then shift fi fi -perf trace $@ -s ~/libexec/perf-core/scripts/python/failed-syscalls-by-pid.py $comm +perf trace $@ -s "$PERF_EXEC_PATH"/scripts/python/failed-syscalls-by-pid.py $comm diff --git a/tools/perf/scripts/python/bin/netdev-times-report b/tools/perf/scripts/python/bin/netdev-times-report index c3d0a638123d..4ad361b31249 100644 --- a/tools/perf/scripts/python/bin/netdev-times-report +++ b/tools/perf/scripts/python/bin/netdev-times-report @@ -2,4 +2,4 @@ # description: display a process of packet and processing time # args: [tx] [rx] [dev=] [debug] -perf trace -s ~/libexec/perf-core/scripts/python/netdev-times.py $@ +perf trace -s "$PERF_EXEC_PATH"/scripts/python/netdev-times.py $@ diff --git a/tools/perf/scripts/python/bin/sched-migration-report b/tools/perf/scripts/python/bin/sched-migration-report index 61d05f72e443..df1791f07c24 100644 --- a/tools/perf/scripts/python/bin/sched-migration-report +++ b/tools/perf/scripts/python/bin/sched-migration-report @@ -1,3 +1,3 @@ #!/bin/bash # description: sched migration overview -perf trace $@ -s ~/libexec/perf-core/scripts/python/sched-migration.py +perf trace $@ -s "$PERF_EXEC_PATH"/scripts/python/sched-migration.py diff --git a/tools/perf/scripts/python/bin/sctop-report b/tools/perf/scripts/python/bin/sctop-report index b01c842ae7b4..36b409c05e50 100644 --- a/tools/perf/scripts/python/bin/sctop-report +++ b/tools/perf/scripts/python/bin/sctop-report @@ -21,4 +21,4 @@ elif [ "$n_args" -gt 0 ] ; then interval=$1 shift fi -perf trace $@ -s ~/libexec/perf-core/scripts/python/sctop.py $comm $interval +perf trace $@ -s "$PERF_EXEC_PATH"/scripts/python/sctop.py $comm $interval diff --git a/tools/perf/scripts/python/bin/syscall-counts-by-pid-report b/tools/perf/scripts/python/bin/syscall-counts-by-pid-report index 9e9d8ddd72ce..4eb88c9fc83c 100644 --- a/tools/perf/scripts/python/bin/syscall-counts-by-pid-report +++ b/tools/perf/scripts/python/bin/syscall-counts-by-pid-report @@ -7,4 +7,4 @@ if [ $# -gt 0 ] ; then shift fi fi -perf trace $@ -s ~/libexec/perf-core/scripts/python/syscall-counts-by-pid.py $comm +perf trace $@ -s "$PERF_EXEC_PATH"/scripts/python/syscall-counts-by-pid.py $comm diff --git a/tools/perf/scripts/python/bin/syscall-counts-report b/tools/perf/scripts/python/bin/syscall-counts-report index dc076b618796..cb2f9c5cf17e 100644 --- a/tools/perf/scripts/python/bin/syscall-counts-report +++ b/tools/perf/scripts/python/bin/syscall-counts-report @@ -7,4 +7,4 @@ if [ $# -gt 0 ] ; then shift fi fi -perf trace $@ -s ~/libexec/perf-core/scripts/python/syscall-counts.py $comm +perf trace $@ -s "$PERF_EXEC_PATH"/scripts/python/syscall-counts.py $comm -- cgit v1.2.3 From 6cc7361440e499abb3a30cdbcfedad03e43c92ae Mon Sep 17 00:00:00 2001 From: Arnaldo Carvalho de Melo Date: Mon, 25 Oct 2010 15:15:10 -0200 Subject: perf python scripting: Improve the failed-syscalls-by-pid script . Print message at script start telling how to get te summary . Print the syscall name using the audit-lib-python package, if installed . Print the errno string . Accept both pid (if numeric) or COMM name Now it looks like this: [root@emilia ~]# perf trace failed-syscalls-by-pid Press control+C to stop and show the summary ^C syscall errors: comm [pid] count ------------------------------ ---------- automount [1670] syscall: futex err = ETIMEDOUT 39 irqbalance [1462] syscall: openat err = ENOENT 4 perf [7888] syscall: lseek err = ESPIPE 1 syscall: open err = ENOENT 24 perf [7889] syscall: ioctl err = EINVAL 1 syscall: readlink err = EINVAL 2 syscall: open err = ENOENT 389 syscall: stat err = ENOENT 141 syscall: lseek err = ESPIPE 3 [root@emilia ~]# [root@emilia ~]# perf trace failed-syscalls-by-pid 1670 Press control+C to stop and show the summary ^C syscall errors: comm [pid] count ------------------------------ ---------- automount [1670] syscall: futex err = ETIMEDOUT 2 [root@emilia ~]# [root@emilia ~]# [root@emilia ~]# [root@emilia ~]# perf trace failed-syscalls-by-pid automount Press control+C to stop and show the summary ^C syscall errors for automount: comm [pid] count ------------------------------ ---------- automount [1669] syscall: futex err = ETIMEDOUT 1 automount [1670] syscall: futex err = ETIMEDOUT 5 [root@emilia ~]# Cc: David S. Miller Cc: Frederic Weisbecker Cc: Ingo Molnar Cc: Mike Galbraith Cc: Paul Mackerras Cc: Peter Zijlstra Cc: Stephane Eranian Cc: Tom Zanussi LKML-Reference: Signed-off-by: Arnaldo Carvalho de Melo --- .../python/Perf-Trace-Util/lib/Perf/Trace/Util.py | 37 ++++++++++++++++++++++ .../perf/scripts/python/failed-syscalls-by-pid.py | 21 +++++++----- 2 files changed, 50 insertions(+), 8 deletions(-) (limited to 'tools/perf/scripts/python') diff --git a/tools/perf/scripts/python/Perf-Trace-Util/lib/Perf/Trace/Util.py b/tools/perf/scripts/python/Perf-Trace-Util/lib/Perf/Trace/Util.py index 9689bc0acd9f..9d15f484308c 100644 --- a/tools/perf/scripts/python/Perf-Trace-Util/lib/Perf/Trace/Util.py +++ b/tools/perf/scripts/python/Perf-Trace-Util/lib/Perf/Trace/Util.py @@ -6,6 +6,8 @@ # Public License ("GPL") version 2 as published by the Free Software # Foundation. +import errno, os + NSECS_PER_SEC = 1000000000 def avg(total, n): @@ -26,3 +28,38 @@ def nsecs_str(nsecs): def clear_term(): print("\x1b[H\x1b[2J") + +audit_package_warned = False + +try: + import audit + machine_to_id = { + 'x86_64': audit.MACH_86_64, + 'alpha' : audit.MACH_ALPHA, + 'armeb' : audit.MACH_ARMEB, + 'ia64' : audit.MACH_IA64, + 'ppc' : audit.MACH_PPC, + 'ppc64' : audit.MACH_PPC64, + 's390' : audit.MACH_S390, + 's390x' : audit.MACH_S390X, + 'i386' : audit.MACH_X86, + 'i586' : audit.MACH_X86, + 'i686' : audit.MACH_X86, + } + machine_id = machine_to_id[os.uname()[4]] +except: + if not audit_package_warned: + audit_package_warned = True + print "Install the audit-libs-python package to get syscall names" + +def syscall_name(id): + try: + return audit.audit_syscall_to_name(id, machine_id) + except: + return str(id) + +def strerror(nr): + try: + return errno.errorcode[abs(nr)] + except: + return "Unknown %d errno" % nr diff --git a/tools/perf/scripts/python/failed-syscalls-by-pid.py b/tools/perf/scripts/python/failed-syscalls-by-pid.py index 0ca02278fe69..acd7848717b3 100644 --- a/tools/perf/scripts/python/failed-syscalls-by-pid.py +++ b/tools/perf/scripts/python/failed-syscalls-by-pid.py @@ -13,21 +13,26 @@ sys.path.append(os.environ['PERF_EXEC_PATH'] + \ from perf_trace_context import * from Core import * +from Util import * -usage = "perf trace -s syscall-counts-by-pid.py [comm]\n"; +usage = "perf trace -s syscall-counts-by-pid.py [comm|pid]\n"; for_comm = None +for_pid = None if len(sys.argv) > 2: sys.exit(usage) if len(sys.argv) > 1: - for_comm = sys.argv[1] + try: + for_pid = int(sys.argv[1]) + except: + for_comm = sys.argv[1] syscalls = autodict() def trace_begin(): - pass + print "Press control+C to stop and show the summary" def trace_end(): print_error_totals() @@ -35,9 +40,9 @@ def trace_end(): def raw_syscalls__sys_exit(event_name, context, common_cpu, common_secs, common_nsecs, common_pid, common_comm, id, ret): - if for_comm is not None: - if common_comm != for_comm: - return + if (for_comm and common_comm != for_comm) or \ + (for_pid and common_pid != for_pid ): + return if ret < 0: try: @@ -62,7 +67,7 @@ def print_error_totals(): print "\n%s [%d]\n" % (comm, pid), id_keys = syscalls[comm][pid].keys() for id in id_keys: - print " syscall: %-16d\n" % (id), + print " syscall: %-16s\n" % syscall_name(id), ret_keys = syscalls[comm][pid][id].keys() for ret, val in sorted(syscalls[comm][pid][id].iteritems(), key = lambda(k, v): (v, k), reverse = True): - print " err = %-20d %10d\n" % (ret, val), + print " err = %-20s %10d\n" % (strerror(ret), val), -- cgit v1.2.3 From 6545aaa561b5678c497e94dea22cb2d1af1d6859 Mon Sep 17 00:00:00 2001 From: Arnaldo Carvalho de Melo Date: Mon, 25 Oct 2010 17:11:25 -0200 Subject: perf python scripting: Improve the syscalls-counts script . Print message at script start telling how to get te summary . Print the syscall name Now it looks like this: [root@emilia ~]# perf trace syscall-counts Press control+C to stop and show the summary ^C syscall events: event count ---------------------------------------- ----------- read 102752 open 1293 close 878 write 319 stat 185 fstat 149 getdents 116 mmap 98 brk 80 rt_sigaction 66 munmap 42 mprotect 24 lseek 21 lstat 7 rt_sigprocmask 4 futex 3 statfs 3 ioctl 3 readlink 2 select 2 getegid 1 geteuid 1 getgid 1 getuid 1 getrlimit 1 fcntl 1 uname 1 [root@emilia ~]# Cc: David S. Miller Cc: Frederic Weisbecker Cc: Ingo Molnar Cc: Mike Galbraith Cc: Paul Mackerras Cc: Peter Zijlstra Cc: Stephane Eranian Cc: Tom Zanussi LKML-Reference: Signed-off-by: Arnaldo Carvalho de Melo --- tools/perf/scripts/python/syscall-counts.py | 5 +++-- 1 file changed, 3 insertions(+), 2 deletions(-) (limited to 'tools/perf/scripts/python') diff --git a/tools/perf/scripts/python/syscall-counts.py b/tools/perf/scripts/python/syscall-counts.py index f977e85ff049..ea183dc82d29 100644 --- a/tools/perf/scripts/python/syscall-counts.py +++ b/tools/perf/scripts/python/syscall-counts.py @@ -13,6 +13,7 @@ sys.path.append(os.environ['PERF_EXEC_PATH'] + \ from perf_trace_context import * from Core import * +from Util import syscall_name usage = "perf trace -s syscall-counts.py [comm]\n"; @@ -27,7 +28,7 @@ if len(sys.argv) > 1: syscalls = autodict() def trace_begin(): - pass + print "Press control+C to stop and show the summary" def trace_end(): print_syscall_totals() @@ -55,4 +56,4 @@ def print_syscall_totals(): for id, val in sorted(syscalls.iteritems(), key = lambda(k, v): (v, k), \ reverse = True): - print "%-40d %10d\n" % (id, val), + print "%-40s %10d\n" % (syscall_name(id), val), -- cgit v1.2.3 From 2e7d1e3fb8043380a2fc5d759eb357bf05acf935 Mon Sep 17 00:00:00 2001 From: Arnaldo Carvalho de Melo Date: Mon, 25 Oct 2010 18:39:20 -0200 Subject: perf python scripting: print the syscall name on sctop [root@emilia tmp]# perf trace sctop 1 syscall events: event count ---------------------------------------- ---------- read 215400 futex 4029 write 376 brk 33 rt_sigprocmask 24 select 17 lseek 2 fsync 1 ^C[root@emilia tmp]# Cc: David S. Miller Cc: Frederic Weisbecker Cc: Ingo Molnar Cc: Mike Galbraith Cc: Paul Mackerras Cc: Peter Zijlstra Cc: Stephane Eranian Cc: Tom Zanussi LKML-Reference: Signed-off-by: Arnaldo Carvalho de Melo --- tools/perf/scripts/python/sctop.py | 7 ++----- 1 file changed, 2 insertions(+), 5 deletions(-) (limited to 'tools/perf/scripts/python') diff --git a/tools/perf/scripts/python/sctop.py b/tools/perf/scripts/python/sctop.py index 6cafad40c296..547cbe99de68 100644 --- a/tools/perf/scripts/python/sctop.py +++ b/tools/perf/scripts/python/sctop.py @@ -8,10 +8,7 @@ # will be refreshed every [interval] seconds. The default interval is # 3 seconds. -import thread -import time -import os -import sys +import os, sys, thread, time sys.path.append(os.environ['PERF_EXEC_PATH'] + \ '/scripts/python/Perf-Trace-Util/lib/Perf/Trace') @@ -71,7 +68,7 @@ def print_syscall_totals(interval): for id, val in sorted(syscalls.iteritems(), key = lambda(k, v): (v, k), \ reverse = True): try: - print "%-40d %10d\n" % (id, val), + print "%-40s %10d\n" % (syscall_name(id), val), except TypeError: pass syscalls.clear() -- cgit v1.2.3 From a64fa198ba1cd232871710c37476e006ed5516ed Mon Sep 17 00:00:00 2001 From: Arnaldo Carvalho de Melo Date: Mon, 25 Oct 2010 18:44:09 -0200 Subject: perf python scripting: Improve the syscalls-by-pid script . Print message at script start telling how to get te summary . Print the syscall names . Accept both pid (if numeric) or COMM name Now it looks like this: [root@emilia tmp]# perf trace syscall-counts-by-pid Press control+C to stop and show the summary ^C syscall events by comm/pid: comm [pid]/syscalls count ---------------------------------------- ---------- automount [1670] futex 2 sshd [2322] rt_sigprocmask 4 select 2 write 1 read 1 perf [15178] read 2506 open 794 close 769 write 240 getdents 112 lseek 16 stat 9 perf_counter_open 5 fcntl 5 mmap 5 statfs 2 perf [15179] read 56701 open 499 stat 176 fstat 149 close 109 mmap 98 brk 75 rt_sigaction 66 munmap 42 mprotect 24 lstat 7 lseek 5 getdents 4 ioctl 3 readlink 2 futex 1 statfs 1 getegid 1 geteuid 1 getgid 1 getuid 1 getrlimit 1 fcntl 1 uname 1 write 1 [root@emilia tmp]# fg -bash: fg: current: no such job [root@emilia tmp]# perf trace syscall-counts-by-pid 2322 Press control+C to stop and show the summary ^C syscall events by comm/pid: comm [pid]/syscalls count ---------------------------------------- ---------- sshd [2322] rt_sigprocmask 4 select 2 write 1 read 1 [root@emilia tmp]# perf trace syscall-counts-by-pid sshd Press control+C to stop and show the summary ^C syscall events for sshd: comm [pid]/syscalls count ---------------------------------------- ---------- sshd [2322] rt_sigprocmask 4 select 2 write 1 read 1 [root@emilia tmp]# Cc: David S. Miller Cc: Frederic Weisbecker Cc: Ingo Molnar Cc: Mike Galbraith Cc: Paul Mackerras Cc: Peter Zijlstra Cc: Stephane Eranian Cc: Tom Zanussi LKML-Reference: Signed-off-by: Arnaldo Carvalho de Melo --- tools/perf/scripts/python/syscall-counts-by-pid.py | 21 +++++++++++++-------- 1 file changed, 13 insertions(+), 8 deletions(-) (limited to 'tools/perf/scripts/python') diff --git a/tools/perf/scripts/python/syscall-counts-by-pid.py b/tools/perf/scripts/python/syscall-counts-by-pid.py index af722d6a4b3f..d1ee3ec10cf2 100644 --- a/tools/perf/scripts/python/syscall-counts-by-pid.py +++ b/tools/perf/scripts/python/syscall-counts-by-pid.py @@ -5,29 +5,33 @@ # Displays system-wide system call totals, broken down by syscall. # If a [comm] arg is specified, only syscalls called by [comm] are displayed. -import os -import sys +import os, sys sys.path.append(os.environ['PERF_EXEC_PATH'] + \ '/scripts/python/Perf-Trace-Util/lib/Perf/Trace') from perf_trace_context import * from Core import * +from Util import syscall_name usage = "perf trace -s syscall-counts-by-pid.py [comm]\n"; for_comm = None +for_pid = None if len(sys.argv) > 2: sys.exit(usage) if len(sys.argv) > 1: - for_comm = sys.argv[1] + try: + for_pid = int(sys.argv[1]) + except: + for_comm = sys.argv[1] syscalls = autodict() def trace_begin(): - pass + print "Press control+C to stop and show the summary" def trace_end(): print_syscall_totals() @@ -35,9 +39,10 @@ def trace_end(): def raw_syscalls__sys_enter(event_name, context, common_cpu, common_secs, common_nsecs, common_pid, common_comm, id, args): - if for_comm is not None: - if common_comm != for_comm: - return + + if (for_comm and common_comm != for_comm) or \ + (for_pid and common_pid != for_pid ): + return try: syscalls[common_comm][common_pid][id] += 1 except TypeError: @@ -61,4 +66,4 @@ def print_syscall_totals(): id_keys = syscalls[comm][pid].keys() for id, val in sorted(syscalls[comm][pid].iteritems(), \ key = lambda(k, v): (v, k), reverse = True): - print " %-38d %10d\n" % (id, val), + print " %-38s %10d\n" % (syscall_name(id), val), -- cgit v1.2.3 From 7f6c1bd50d73d12f8b4ea09edb4515997f6527f5 Mon Sep 17 00:00:00 2001 From: Arnaldo Carvalho de Melo Date: Mon, 25 Oct 2010 22:12:01 -0200 Subject: perf python scripting: Support fedora 11 (audit 1.7.17) Where we don't have the audit.MACH_ARMEB constant. Cc: David S. Miller Cc: Frederic Weisbecker Cc: Ingo Molnar Cc: Mike Galbraith Cc: Paul Mackerras Cc: Peter Zijlstra Cc: Stephane Eranian Cc: Tom Zanussi LKML-Reference: Signed-off-by: Arnaldo Carvalho de Melo --- tools/perf/scripts/python/Perf-Trace-Util/lib/Perf/Trace/Util.py | 5 ++++- 1 file changed, 4 insertions(+), 1 deletion(-) (limited to 'tools/perf/scripts/python') diff --git a/tools/perf/scripts/python/Perf-Trace-Util/lib/Perf/Trace/Util.py b/tools/perf/scripts/python/Perf-Trace-Util/lib/Perf/Trace/Util.py index 9d15f484308c..99ff1b7a0d2c 100644 --- a/tools/perf/scripts/python/Perf-Trace-Util/lib/Perf/Trace/Util.py +++ b/tools/perf/scripts/python/Perf-Trace-Util/lib/Perf/Trace/Util.py @@ -36,7 +36,6 @@ try: machine_to_id = { 'x86_64': audit.MACH_86_64, 'alpha' : audit.MACH_ALPHA, - 'armeb' : audit.MACH_ARMEB, 'ia64' : audit.MACH_IA64, 'ppc' : audit.MACH_PPC, 'ppc64' : audit.MACH_PPC64, @@ -46,6 +45,10 @@ try: 'i586' : audit.MACH_X86, 'i686' : audit.MACH_X86, } + try: + machine_to_id['armeb'] = audit.MACH_ARMEB + except: + pass machine_id = machine_to_id[os.uname()[4]] except: if not audit_package_warned: -- cgit v1.2.3 From 22d0594b31046793dfb58b7ce866d7cb0a9862e5 Mon Sep 17 00:00:00 2001 From: Arnaldo Carvalho de Melo Date: Tue, 26 Oct 2010 15:21:15 -0200 Subject: perf python scripting: Fixup cut'n'paste error in sctop script Cc: Frederic Weisbecker Cc: Ingo Molnar Cc: Mike Galbraith Cc: Paul Mackerras Cc: Peter Zijlstra Cc: Stephane Eranian Cc: Tom Zanussi LKML-Reference: Signed-off-by: Arnaldo Carvalho de Melo --- tools/perf/scripts/python/sctop.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) (limited to 'tools/perf/scripts/python') diff --git a/tools/perf/scripts/python/sctop.py b/tools/perf/scripts/python/sctop.py index 547cbe99de68..7a6ec2c7d8ab 100644 --- a/tools/perf/scripts/python/sctop.py +++ b/tools/perf/scripts/python/sctop.py @@ -17,7 +17,7 @@ from perf_trace_context import * from Core import * from Util import * -usage = "perf trace -s syscall-counts.py [comm] [interval]\n"; +usage = "perf trace -s sctop.py [comm] [interval]\n"; for_comm = None default_interval = 3 -- cgit v1.2.3 From 00204c3396469f407bac56e1475ea16e4a279b13 Mon Sep 17 00:00:00 2001 From: Arnaldo Carvalho de Melo Date: Tue, 26 Oct 2010 17:07:33 -0200 Subject: perf python scripting: Add futex-contention script The equivalent to this SystemTAP script: http://sourceware.org/systemtap/wiki/WSFutexContention [root@doppio ~]# perf trace futex-contention Press control+C to stop and show the summary ^Cnpviewer.bin[15242] lock 7f0a8be19104 contended 29 times, 72806 avg ns npviewer.bin[15242] lock 7f0a8be19130 contended 2 times, 1355 avg ns synergyc[17245] lock f127f4 contended 1 times, 1830569 avg ns firefox[15116] lock 7f2b7238af0c contended 168 times, 1230390 avg ns synergyc[17245] lock f2fc20 contended 1 times, 33149 avg ns npviewer.bin[15255] lock 7f0a8be19074 contended 155 times, 73047 avg ns npviewer.bin[15255] lock 7f0a8be190a0 contended 127 times, 7088 avg ns synergyc[17247] lock f12854 contended 1 times, 46741 avg ns synergyc[17245] lock f12610 contended 1 times, 7358 avg ns [root@doppio ~]# Cc: Frederic Weisbecker Cc: Mike Galbraith Cc: Paul Mackerras Cc: Peter Zijlstra Cc: Stephane Eranian Cc: Tom Zanussi LKML-Reference: Signed-off-by: Arnaldo Carvalho de Melo --- .../python/Perf-Trace-Util/lib/Perf/Trace/Util.py | 18 ++++++++ .../scripts/python/bin/futex-contention-record | 2 + .../scripts/python/bin/futex-contention-report | 4 ++ tools/perf/scripts/python/futex-contention.py | 50 ++++++++++++++++++++++ 4 files changed, 74 insertions(+) create mode 100644 tools/perf/scripts/python/bin/futex-contention-record create mode 100644 tools/perf/scripts/python/bin/futex-contention-report create mode 100644 tools/perf/scripts/python/futex-contention.py (limited to 'tools/perf/scripts/python') diff --git a/tools/perf/scripts/python/Perf-Trace-Util/lib/Perf/Trace/Util.py b/tools/perf/scripts/python/Perf-Trace-Util/lib/Perf/Trace/Util.py index 99ff1b7a0d2c..13cc02b5893a 100644 --- a/tools/perf/scripts/python/Perf-Trace-Util/lib/Perf/Trace/Util.py +++ b/tools/perf/scripts/python/Perf-Trace-Util/lib/Perf/Trace/Util.py @@ -8,6 +8,12 @@ import errno, os +FUTEX_WAIT = 0 +FUTEX_WAKE = 1 +FUTEX_PRIVATE_FLAG = 128 +FUTEX_CLOCK_REALTIME = 256 +FUTEX_CMD_MASK = ~(FUTEX_PRIVATE_FLAG | FUTEX_CLOCK_REALTIME) + NSECS_PER_SEC = 1000000000 def avg(total, n): @@ -26,6 +32,18 @@ def nsecs_str(nsecs): str = "%5u.%09u" % (nsecs_secs(nsecs), nsecs_nsecs(nsecs)), return str +def add_stats(dict, key, value): + if not dict.has_key(key): + dict[key] = (value, value, value, 1) + else: + min, max, avg, count = dict[key] + if value < min: + min = value + if value > max: + max = value + avg = (avg + value) / 2 + dict[key] = (min, max, avg, count + 1) + def clear_term(): print("\x1b[H\x1b[2J") diff --git a/tools/perf/scripts/python/bin/futex-contention-record b/tools/perf/scripts/python/bin/futex-contention-record new file mode 100644 index 000000000000..5ecbb433caf4 --- /dev/null +++ b/tools/perf/scripts/python/bin/futex-contention-record @@ -0,0 +1,2 @@ +#!/bin/bash +perf record -a -e syscalls:sys_enter_futex -e syscalls:sys_exit_futex $@ diff --git a/tools/perf/scripts/python/bin/futex-contention-report b/tools/perf/scripts/python/bin/futex-contention-report new file mode 100644 index 000000000000..c8268138fb7e --- /dev/null +++ b/tools/perf/scripts/python/bin/futex-contention-report @@ -0,0 +1,4 @@ +#!/bin/bash +# description: futext contention measurement + +perf trace $@ -s "$PERF_EXEC_PATH"/scripts/python/futex-contention.py diff --git a/tools/perf/scripts/python/futex-contention.py b/tools/perf/scripts/python/futex-contention.py new file mode 100644 index 000000000000..11e70a388d41 --- /dev/null +++ b/tools/perf/scripts/python/futex-contention.py @@ -0,0 +1,50 @@ +# futex contention +# (c) 2010, Arnaldo Carvalho de Melo +# Licensed under the terms of the GNU GPL License version 2 +# +# Translation of: +# +# http://sourceware.org/systemtap/wiki/WSFutexContention +# +# to perf python scripting. +# +# Measures futex contention + +import os, sys +sys.path.append(os.environ['PERF_EXEC_PATH'] + '/scripts/python/Perf-Trace-Util/lib/Perf/Trace') +from Util import * + +process_names = {} +thread_thislock = {} +thread_blocktime = {} + +lock_waits = {} # long-lived stats on (tid,lock) blockage elapsed time +process_names = {} # long-lived pid-to-execname mapping + +def syscalls__sys_enter_futex(event, ctxt, cpu, s, ns, tid, comm, + nr, uaddr, op, val, utime, uaddr2, val3): + cmd = op & FUTEX_CMD_MASK + if cmd != FUTEX_WAIT: + return # we don't care about originators of WAKE events + + process_names[tid] = comm + thread_thislock[tid] = uaddr + thread_blocktime[tid] = nsecs(s, ns) + +def syscalls__sys_exit_futex(event, ctxt, cpu, s, ns, tid, comm, + nr, ret): + if thread_blocktime.has_key(tid): + elapsed = nsecs(s, ns) - thread_blocktime[tid] + add_stats(lock_waits, (tid, thread_thislock[tid]), elapsed) + del thread_blocktime[tid] + del thread_thislock[tid] + +def trace_begin(): + print "Press control+C to stop and show the summary" + +def trace_end(): + for (tid, lock) in lock_waits: + min, max, avg, count = lock_waits[tid, lock] + print "%s[%d] lock %x contended %d times, %d avg ns" % \ + (process_names[tid], tid, lock, count, avg) + -- cgit v1.2.3