^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1) #!/usr/bin/env python
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 2) # SPDX-License-Identifier: GPL-2.0-only
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 3) #
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 4) # show_deltas: Read list of printk messages instrumented with
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 5) # time data, and format with time deltas.
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 6) #
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 7) # Also, you can show the times relative to a fixed point.
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 8) #
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 9) # Copyright 2003 Sony Corporation
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 10) #
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 11)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 12) import sys
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 13) import string
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 14)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 15) def usage():
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 16) print ("""usage: show_delta [<options>] <filename>
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 17)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 18) This program parses the output from a set of printk message lines which
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 19) have time data prefixed because the CONFIG_PRINTK_TIME option is set, or
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 20) the kernel command line option "time" is specified. When run with no
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 21) options, the time information is converted to show the time delta between
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 22) each printk line and the next. When run with the '-b' option, all times
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 23) are relative to a single (base) point in time.
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 24)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 25) Options:
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 26) -h Show this usage help.
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 27) -b <base> Specify a base for time references.
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 28) <base> can be a number or a string.
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 29) If it is a string, the first message line
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 30) which matches (at the beginning of the
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 31) line) is used as the time reference.
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 32)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 33) ex: $ dmesg >timefile
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 34) $ show_delta -b NET4 timefile
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 35)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 36) will show times relative to the line in the kernel output
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 37) starting with "NET4".
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 38) """)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 39) sys.exit(1)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 40)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 41) # returns a tuple containing the seconds and text for each message line
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 42) # seconds is returned as a float
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 43) # raise an exception if no timing data was found
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 44) def get_time(line):
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 45) if line[0]!="[":
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 46) raise ValueError
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 47)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 48) # split on closing bracket
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 49) (time_str, rest) = string.split(line[1:],']',1)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 50) time = string.atof(time_str)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 51)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 52) #print "time=", time
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 53) return (time, rest)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 54)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 55)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 56) # average line looks like:
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 57) # [ 0.084282] VFS: Mounted root (romfs filesystem) readonly
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 58) # time data is expressed in seconds.useconds,
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 59) # convert_line adds a delta for each line
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 60) last_time = 0.0
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 61) def convert_line(line, base_time):
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 62) global last_time
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 63)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 64) try:
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 65) (time, rest) = get_time(line)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 66) except:
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 67) # if any problem parsing time, don't convert anything
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 68) return line
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 69)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 70) if base_time:
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 71) # show time from base
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 72) delta = time - base_time
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 73) else:
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 74) # just show time from last line
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 75) delta = time - last_time
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 76) last_time = time
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 77)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 78) return ("[%5.6f < %5.6f >]" % (time, delta)) + rest
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 79)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 80) def main():
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 81) base_str = ""
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 82) filein = ""
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 83) for arg in sys.argv[1:]:
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 84) if arg=="-b":
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 85) base_str = sys.argv[sys.argv.index("-b")+1]
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 86) elif arg=="-h":
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 87) usage()
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 88) else:
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 89) filein = arg
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 90)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 91) if not filein:
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 92) usage()
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 93)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 94) try:
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 95) lines = open(filein,"r").readlines()
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 96) except:
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 97) print ("Problem opening file: %s" % filein)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 98) sys.exit(1)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 99)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 100) if base_str:
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 101) print ('base= "%s"' % base_str)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 102) # assume a numeric base. If that fails, try searching
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 103) # for a matching line.
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 104) try:
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 105) base_time = float(base_str)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 106) except:
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 107) # search for line matching <base> string
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 108) found = 0
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 109) for line in lines:
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 110) try:
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 111) (time, rest) = get_time(line)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 112) except:
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 113) continue
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 114) if string.find(rest, base_str)==1:
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 115) base_time = time
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 116) found = 1
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 117) # stop at first match
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 118) break
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 119) if not found:
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 120) print ('Couldn\'t find line matching base pattern "%s"' % base_str)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 121) sys.exit(1)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 122) else:
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 123) base_time = 0.0
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 124)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 125) for line in lines:
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 126) print (convert_line(line, base_time),)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 127)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 128) main()