scripts to examine aio_flush and low-level request completion times for librbd

check_flushes.py

#!/usr/bin/python

from datetime import datetime
import re
import sys

class Transaction(object):
    def __init__(self, addr, start):
        self.comp_addr = addr
        self.start = start
    def set_end(self, end):
        self.end = end
        self.duration = (self.end - self.start).total_seconds()

def main():
    in_flight = {}
    durations = []
    time_format = '%Y-%m-%d %H:%M:%S.%f'
    with file(sys.argv[1], 'r') as f:
        for line in f.readlines():
            if 'librbd: aio_flush' in line:
                comp_addr = line.split()[8]
                assert comp_addr not in in_flight
                start = datetime.strptime(line[:26], time_format)
                in_flight[comp_addr] = Transaction(comp_addr, start)
            elif 'complete_request' in line:
                comp_addr = line.split()[6]
                if comp_addr in in_flight:
                    trans = in_flight[comp_addr]
                    trans.set_end(datetime.strptime(line[:26], time_format))
                    durations.append((trans.comp_addr, trans.duration))
                    del in_flight[comp_addr]

            #else:
                #print 'unmatched line:', line
    for comp_addr, trans in in_flight.iteritems():
        print 'unfinished flush at', comp_addr, 'started at', trans.start
    durations.sort(key=lambda x: x[1], reverse=True)
    print
    print '10 longest requests:'
    for i in range(10):
        print i + 1, durations[i][1], durations[i][0]

if __name__ == '__main__':
    main()

check_requests.py

#!/usr/bin/python

from datetime import datetime
import re
import sys

class Transaction(object):
    def __init__(self, tid, start):
        self.tid = tid
        self.start = start
    def set_end(self, end):
        self.end = end
        self.duration = (self.end - self.start).total_seconds()

def main():
    in_flight = {}
    durations = []
    time_format = '%Y-%m-%d %H:%M:%S.%f'
    with file(sys.argv[1], 'r') as f:
        for line in f.readlines():
            if '-->' in line and 'osd_op' in line:
                tid = re.search('osd_op\(.*:(\d+)', line).group(1)
                start = datetime.strptime(line[:26], time_format)
                if tid in in_flight:
                    print 'resent', tid
                else:
                    in_flight[tid] = Transaction(tid, start)
            elif '<==' in line and 'osd_op_reply' in line:
                tid = re.search('osd_op_reply\((\d+)', line).group(1)
                if tid in in_flight:
                    trans = in_flight[tid]
                    trans.set_end(datetime.strptime(line[:26], time_format))
                    durations.append((trans.tid, trans.duration))
                    del in_flight[tid]
                else:
                    print tid
                    print 'dup reply', tid
            #else:
                #print 'unmatched line:', line
    for tid in in_flight:
        print 'unacked request', tid
    durations.sort(key=lambda x: x[1], reverse=True)
    print
    print '10 longest requests:'
    for i in range(10):
        print i + 1, durations[i][1], durations[i][0]

if __name__ == '__main__':
    main()