find_slow_boot.py

# Search nova-compute.log for ports that took a long time
# to receive the network-vif-plugged- event from neutron.
# python find_slow_boot.py /var/log/nov/nova-compute.log | sort -k 3

import datetime
import re
import sys

if len(sys.argv) == 2:
    log_file = sys.argv[1]
else:
    print("Usage: python find_slow_boot.py /tmp/nova-compute.log")
    sys.exit()

PAT = re.compile('network-vif-plugged-([0-9a-f]{8}-[0-9a-f]{4}-[0-9a-f]{4}-[0-9a-f]{4}-[0-9a-f]{12})')

def get_uuid(line):
    match = PAT.search(line)
    return match.group(1)

def get_dt(line):
    dt_str = line[:23]
    return datetime.datetime.strptime(dt_str, "%Y-%m-%d %H:%M:%S.%f")

with open(log_file) as f:
    lines = f.readlines()

ports = {}
for line in lines:
    # line = line.strip('\n')
    if "Preparing to wait for external event network-vif-plugged-" in line:
        port = get_uuid(line)
        dt = get_dt(line)
        ports[port] = {'start': dt, 'end': None}
    if "Received event network-vif-plugged-" in line:
        port = get_uuid(line)
        if port in ports:
            dt = get_dt(line)
            ports[port]['end'] = dt

for port_id, stats in ports.iteritems():
    if not stats.get('end'):
        continue
    delta = stats['end'] - stats['start']
    if delta > datetime.timedelta(minutes=1):
        # print port_id, port['start'], port['end'], delta
        print port_id, stats['start'].strftime("%H:%M:%S"), stats['end'].strftime("%H:%M:%S"), int(delta.total_seconds())