ubuntu-boot team mailing list archive

[Scott James Remnant <scott@xxxxxxxxxxxxx>]

Attached is my script for parsing udev log files and interpreting
various bits of data from it.  This can be used to debug problems, and
also consider boot performance.

Missing UEVENT:

  These are things that udev did that have no corresponding kernel
  event, in theory this should never happen, but it does from time to
  time -- I assume it's simply a monitoring bug.

  Shows the time since start that udev finished processing the event. 

Missing UDEV:

  This is most useful when dealing with bug reports, if something has a
  UEVENT but no UDEV, then udev failed to process the event.  This can
  be due to OPTIONS+="last_rule", a broken GOTO="..." or a udev timeout

  Shows the time since start that the kernel sent the event.


Events:

  The events processed; shows the time since start that the kernel sent
  the event, the time since start that udev finished processing the
  event, and thus the time that the event took to process.

  This is sorted, so the top ones are the most trivial, the bottom took
  the longest - though this can be because udev was locked processing
  other events (the first, usually)


Statistics can be found near the bottom of the output.

Scott
-- 
Scott James Remnant
scott@xxxxxxxxxxxxx

#!/usr/bin/env python

import os
import sys
import math


def main(args):
    for filename in args:
        uevents, udevs = parse(filename)
        results = process(uevents, udevs)

        min_time = lowest(results)
        max_what = max(len(what) for what, uevent, udev in results)

        missing_uevent = sorted([ (what, uevent, udev)
                                  for what, uevent, udev in results
                                  if uevent is None ],
                                key=lambda x: x[2]['time'])
        if len(missing_uevent):
            print "Missing UEVENT"
            print "--------------"

            print "%-*s  %-8s" % (max_what, "WHAT", "UDEV")

            for what, uevent, udev in missing_uevent:
                print "%-*s  %5.2f" % (max_what, what, udev['time'] - min_time, )

            print

        missing_udev = sorted([ (what, uevent, udev)
                                for what, uevent, udev in results
                                if udev is None ],
                              key=lambda x: x[1]['time'])
        if len(missing_udev):
            print "Missing UDEV"
            print "--------------"

            print "%-*s  %-8s" % (max_what, "WHAT", "UEVENT")

            for what, uevent, udev in missing_udev:
                print "%-*s  %5.2f" % (max_what, what, uevent['time'] - min_time, )

            print

        events = sorted([ (what, uevent, udev)
                          for what, uevent, udev in results
                          if uevent is not None and udev is not None ],
                        key=lambda x: (x[2]['time'] - x[1]['time'], x[2]['time'], x[1]['time'])
        if len(events):
            print "Events"
            print "------"

            print "%-*s  %-8s  %-8s  %-8s" % (max_what, "WHAT", "UEVENT", "UDEV", "TIME")

            occurences = {}
            total_time = 0
            for what, uevent, udev in events:
                print "%-*s  %5.2f  %5.2f  %5.2f" % (max_what, what,
                                                     uevent['time'] - min_time,
                                                     udev['time'] - min_time,
                                                     udev['time'] - uevent['time'],)

                total_time += udev['time'] - uevent['time']

                mode_time = "%5.2f" % (udev['time'] - uevent['time'], )
                if mode_time not in occurences:
                    occurences[mode_time] = 0
                occurences[mode_time] += 1

            print

            mean = total_time / len(events)

            median_what, median_uevent, median_udev = events[len(events) // 2]
            median = median_udev['time'] - median_uevent['time']

            mode = sorted(occurences.items(), key=lambda x: x[-1])[-1][0]

            print "MEAN   %5.2f" % mean
            print "MEDIAN %5.2f" % median
            print "MODE   %s" % mode

            total_deviation = 0
            for what, uevent, udev in events:
                deviation = udev['time'] - uevent['time'] - mean

                total_deviation += math.pow(deviation, 2)

            std_deviation = math.sqrt(total_deviation / len(events))

            print "STDDEV %5.2f" % std_deviation

def parse(filename):
    uevents = {}
    udevs = {}

    event = None

    f = open(filename, "r")
    try:
        for line in f:
            if line.startswith("UEVENT"):
                eventlist = uevents
            elif line.startswith("UDEV"):
                eventlist = udevs
            elif not len(line.rstrip("\n")):
                event = None
            elif event:
                event['env'] += line
            else:
                continue

            try:
                time_start = line.index("[")
                time_end = line.index("]")

                time = float(line[time_start+1:time_end])

                what = line[time_end+1:].lstrip().rstrip("\n")
            except:
                continue


            event = {
                'what': what,
                'time': time,
                'env': [],
                }

            if what not in eventlist:
                eventlist[what] = []
            eventlist[what].append(event)
    finally:
        f.close()

    return uevents, udevs

def process(uevents, udevs):
    results = []

    for what in uevents.keys():
        for uevent in uevents[what]:
            try:
                udev = udevs[what].pop(0)
            except IndexError:
                udev = None

            results.append(( what, uevent, udev ))

    for what in udevs.keys():
        for udev in udevs[what]:
            results.append(( what, None, udev ))

    results.sort(key=lambda x: x[1] and x[1]['time'] or None)

    return results

def lowest(results):
    min_uevent_time = min(uevent['time'] for what, uevent, udev in results
                          if uevent is not None)
    min_udev_time = min(udev['time'] for what, uevent, udev in results
                        if udev is not None)

    if min_udev_time is None:
        return min_uevent_time
    elif min_uevent_time is None:
        return min_udev_time
    else:
        return min(min_uevent_time, min_udev_time)


if __name__ == "__main__":
    main(sys.argv[1:])

Attachment: signature.asc
Description: This is a digitally signed message part