under tools/perf/scripts/python/

page-reclaim.py

import os
import sys
import getopt
import signal

signal.signal(signal.SIGPIPE, signal.SIG_DFL)

usage = "usage: perf script report page-reclaim -- [-h] [-p] [-v]\n"

latency_metric = ['total', 'max', 'avg', 'min']
reclaim_path = ['Kswapd', 'Direct']
sync_io = ['async', 'sync']
lru = ['anon', 'file']

class Show:
        DEFAULT = 0 
        PROCCESS = 1 
        VERBOSE = 2 

show_opt = Show.DEFAULT

def ns(sec, nsec):
        return (sec * 1000000000) + nsec

def ns_to_ms(ns):
        return round(ns / 1000000.0, 3)

def print_proc_latency(_list, pid, comm):
        line =  pid.rjust(8)
        line += comm.ljust(12)

        for i, val in enumerate(_list):
                line += str(val).rjust(12)

        print line

def print_stat_list(_list, title, padding):
        width = len(title) + 1
        header = title.ljust(width)
        line = ''.ljust(width)

        for i, val in enumerate(_list):
                header += str(val[0]).rjust(padding)
                line += str(val[1]).rjust(padding)

        print header
        print line

class Trace:
        def __init__(self, secs, nsecs):
                self.begin = ns(secs, nsecs)

        def complete(self, secs, nsecs):
                self.ns = ns(secs, nsecs) - self.begin

class Stat:
        def __init__(self):
                self.stats = {}
                self.stats['file'] = {}
                self.stats['file']['reclaimed'] = 0
                self.stats['file']['scanned'] = 0
                self.stats['file']['sync'] = 0
                self.stats['file']['async'] = 0
                self.stats['anon'] = {}
                self.stats['anon']['reclaimed'] = 0
                self.stats['anon']['scanned'] = 0
                self.stats['anon']['sync'] = 0
                self.stats['anon']['async'] = 0

                # including reclaimed slab caches
                self.stats['reclaimed'] = 0

                # The MAX_ORDER in kernel is configurable
                self.stats['order'] = {}

                self.stats['latency'] = {}
                self.stats['latency']['total'] = 0.0
                self.stats['latency']['max'] = 0.0
                self.stats['latency']['avg'] = 0.0
                self.stats['latency']['min'] = float("inf")
                self.stats['count'] = 0

        def add_latency(self, val, order):
                self.stats['latency']['total'] += val
                _max = self.stats['latency']['max']
                _min = self.stats['latency']['min']
                if val > _max:
                        self.stats['latency']['max'] = val
                if val < _min:
                        self.stats['latency']['min'] = val

                self.stats['count'] += 1

                if self.stats['order'].get(order):
                        self.stats['order'][order] += 1
                else:
                        self.stats['order'].setdefault(order, 1)

        def add_page(self, _lru, scanned, reclaimed):
                self.stats[_lru]['scanned'] += scanned
                self.stats[_lru]['reclaimed'] += reclaimed

        def inc_write_io(self, _lru, _io):
                self.stats[_lru][_io] += 1

        def convert_latency(self):
                count = self.stats['count']
                if count:
                        self.stats['latency']['avg'] =  \
                                self.stats['latency']['total'] / count
                for i, v in self.stats['latency'].items():
                         self.stats['latency'][i] = ns_to_ms(v)

                latency_list = sorted(self.stats['latency'].items(),
                        key=lambda i:latency_metric.index(i[0]))

                return latency_list

        def show_stats(self, key):
                count = self.stats['count']
                print("%s reclaims: %d" % (key, count))

                # Format latency output
                # Print latencys in milliseconds:
                # title total  max  avg  min
                #         val  val  val  val
                latency_list = self.convert_latency()
                print_stat_list(latency_list, key + " latency (ms)", 12)

                for _lru in ['file', 'anon']:
                        for action in ['reclaimed', 'scanned']:
                                print("%s %s %s %d" % (key, _lru, action, self.stats[_lru][action]))
                        for _io in ['sync', 'async']:
                                print("%s %s %s write I/O %d" % (key, _lru, _io, self.stats[_lru][_io]))

                # Format order output
                # Similar with /proc/buddyinfo:
                # title order-N ...
                #       val     ...
                # N.B. order-N is a non-zero value
                order_list = sorted(self.stats['order'].items())
                print_stat_list(order_list, key + ' order', 6)

class Vmscan:
        events = {}
        stat = {}
        stat['Direct'] = Stat()
        stat['Kswapd'] = Stat()
        # for re-wake the kswapd
        rewake = 0

        @classmethod
        def direct_begin(cls, pid, comm, start_secs, start_nsecs, order):
                event = cls.events.get(pid)
                if event is None:
                        #new vmscan instance
                        event = cls.events[pid] = Vmscan(comm, pid)
                event.vmscan_trace_begin(start_secs, start_nsecs, order, 1)

        @classmethod
        def direct_end(cls, pid, secs, nsecs, reclaimed):
                event = cls.events.get(pid)
                if event and event.tracing():
                        event.vmscan_trace_end(secs, nsecs)

        @classmethod
        def kswapd_wake(cls, pid, comm, start_secs, start_nsecs, order):
                event = cls.events.get(pid)
                if event is None:
                        # new vmscan instance
                        event = cls.events[pid] = Vmscan(comm, pid)

                if event.tracing() is False:
                        event.vmscan_trace_begin(start_secs, start_nsecs, order, 0)
                # kswapd is already running
                else:
                        cls.rewake_kswapd(order)

        @classmethod
        def rewake_kswapd(cls, order):
                cls.rewake += 1

        @classmethod
        def show_rewakes(cls):
                print "kswapd re-wakes %d" % (cls.rewake)

        @classmethod
        def kswapd_sleep(cls, pid, secs, nsecs):
                event = cls.events.get(pid)
                if event and event.tracing():
                        event.vmscan_trace_end(secs, nsecs)

        @classmethod
        def shrink_inactive(cls, pid, scanned, reclaimed, flags):
                event = cls.events.get(pid)
                if event and event.tracing():
                        # RECLAIM_WB_ANON 0x1
                        # RECLAIM_WB_FILE 0x2
                        _type = (flags & 0x2) >> 1
                        event.process_lru(lru[_type], scanned, reclaimed)

        @classmethod
        def writepage(cls, pid, flags):
                event = cls.events.get(pid)
                if event and event.tracing():
                        # RECLAIM_WB_ANON 0x1
                        # RECLAIM_WB_FILE 0x2
                        # RECLAIM_WB_SYNC 0x4
                        # RECLAIM_WB_ASYNC 0x8
                        _type = (flags & 0x2) >> 1
                        _io = (flags & 0x4) >> 2

                        event.process_writepage(lru[_type], sync_io[_io])

        @classmethod
        def iterate_proc(cls):
                if show_opt != Show.DEFAULT:
                        print("\nPer process latency (ms):")
                        print_proc_latency(latency_metric, 'pid', '[comm]')

                        if show_opt == Show.VERBOSE:
                                print("%20s  %s" % ('timestamp','latency(ns)'))

                        for i in cls.events:
                                yield cls.events[i]

        def __init__(self, comm, pid):
                self.comm = comm
                self.pid = pid
                self.trace = None
                self._list = []
                self.stat = Stat()
                self.direct = 0
                self.order = 0

        def vmscan_trace_begin(self, secs, nsecs, order, direct):
                self.trace = Trace(secs, nsecs)
                self.direct = direct
                self.order = order

        def vmscan_trace_end(self, secs, nsecs):
                path = reclaim_path[self.direct]
                self.trace.complete(secs, nsecs)

                Vmscan.stat[path].add_latency(self.trace.ns, self.order)
                if show_opt != Show.DEFAULT:
                        self.stat.add_latency(self.trace.ns, self.order)
                        if show_opt == Show.VERBOSE:
                                self._list.append(self.trace)

                self.trace = None
        def process_lru(self, lru, scanned, reclaimed):
                path = reclaim_path[self.direct]
                Vmscan.stat[path].add_page(lru, scanned, reclaimed)

        def process_writepage(self, lru, io):
                path = reclaim_path[self.direct]
                Vmscan.stat[path].inc_write_io(lru, io)

        def tracing(self):
                return self.trace != None

        def display_proc(self):
                self.stat.convert_latency()
                print_proc_latency(sorted(self.stat.stats['latency'].itervalues(),
                                          reverse=True),
                                   str(self.pid),
                                   '[' +self.comm[0:10] + ']')

        def display_proc_detail(self):
                if show_opt == Show.VERBOSE:
                        for i, v in enumerate(self._list):
                                print("%20d: %d" % (v.begin, v.ns))

# Wake kswpad request
class Wakeup:
        wakes = 0
        orders = {}

        @classmethod
        def wakeup_kswapd(cls, order):
                cls.wakes += 1

                if cls.orders.get(order):
                        cls.orders[order] += 1
                else:
                        cls.orders.setdefault(order, 1)

        @classmethod
        def show_wakes(cls):
                print("Wake kswapd requests %d" % (cls.wakes))

                order_list = sorted(cls.orders.items())
                print_stat_list(order_list, 'Wake order', 6)

def trace_end():
        Vmscan.stat['Direct'].show_stats('Direct')
        Wakeup.show_wakes()
        print ''

        Vmscan.stat['Kswapd'].show_stats('Kswapd')
        Vmscan.show_rewakes()

        # show process details if requested
        for i in Vmscan.iterate_proc():
                i.display_proc(),
                i.display_proc_detail()

# These definations must be in sync with the vmscan tracepoints.
def vmscan__mm_vmscan_direct_reclaim_begin(event_name, context, common_cpu,
        common_secs, common_nsecs, common_pid, common_comm,
        common_callchain, order, gfp_flags):

        Vmscan.direct_begin(common_pid, common_comm, common_secs,
                             common_nsecs, order)

def vmscan__mm_vmscan_direct_reclaim_end(event_name, context, common_cpu,
        common_secs, common_nsecs, common_pid, common_comm,
        common_callchain, nr_reclaimed):

        Vmscan.direct_end(common_pid, common_secs, common_nsecs, nr_reclaimed)

def vmscan__mm_vmscan_kswapd_wake(event_name, context, common_cpu,
        common_secs, common_nsecs, common_pid, common_comm,
        common_callchain, nid, zid, order):

        Vmscan.kswapd_wake(common_pid, common_comm, common_secs, common_nsecs, order)

def vmscan__mm_vmscan_kswapd_sleep(event_name, context, common_cpu,
        common_secs, common_nsecs, common_pid, common_comm,
        common_callchain, nid):

        Vmscan.kswapd_sleep(common_pid, common_secs, common_nsecs)

def vmscan__mm_vmscan_wakeup_kswapd(event_name, context, common_cpu,
        common_secs, common_nsecs, common_pid, common_comm,
        common_callchain, nid, zid, order, gfp_flags):

        Wakeup.wakeup_kswapd(order)

def vmscan__mm_vmscan_lru_shrink_inactive(event_name, context, common_cpu,
        common_secs, common_nsecs, common_pid, common_comm,
        common_callchain, nid, nr_scanned, nr_reclaimed, nr_dirty,
        nr_writeback, nr_congested, nr_immediate, nr_activate_anon,
        nr_activate_file, nr_ref_keep, nr_unmap_fail, priority, flags):

        Vmscan.shrink_inactive(common_pid, nr_scanned, nr_reclaimed, flags)

def vmscan__mm_vmscan_writepage(event_name, context, common_cpu,
        common_secs, common_nsecs, common_pid, common_comm,
        common_callchain, pfn, reclaim_flags):

        Vmscan.writepage(common_pid, reclaim_flags)

def print_help():
        global usage
        print(usage)
        print(" -p    show process latency (ms)")
        print(" -v    show process latency (ns) with timestamp")

def option_parse():
        try:
                opts, args = getopt.getopt(sys.argv[1:], "pvh")
        except getopt.GetoptError:
                print('Bad option!')
                exit(1)

        global show_opt
        for opt, arg in opts:
                if opt == "-h":
                        print_help()
                        exit(0)
                elif opt == "-p":
                        show_opt = Show.PROCCESS
                elif opt == '-v':
                        show_opt = Show.VERBOSE
option_parse()