1#!/usr/bin/env python3 2# -*- coding: utf-8 -*- 3# 4# Analyse lock events and compute statistics 5# 6# Author: Alex Bennée <alex.bennee@linaro.org> 7# 8 9import simpletrace 10import argparse 11import numpy as np 12 13class MutexAnalyser(simpletrace.Analyzer): 14 "A simpletrace Analyser for checking locks." 15 16 def __init__(self): 17 self.locks = 0 18 self.locked = 0 19 self.unlocks = 0 20 self.mutex_records = {} 21 22 def _get_mutex(self, mutex): 23 if not mutex in self.mutex_records: 24 self.mutex_records[mutex] = {"locks": 0, 25 "lock_time": 0, 26 "acquire_times": [], 27 "locked": 0, 28 "locked_time": 0, 29 "held_times": [], 30 "unlocked": 0} 31 32 return self.mutex_records[mutex] 33 34 def qemu_mutex_lock(self, timestamp, mutex, filename, line): 35 self.locks += 1 36 rec = self._get_mutex(mutex) 37 rec["locks"] += 1 38 rec["lock_time"] = timestamp[0] 39 rec["lock_loc"] = (filename, line) 40 41 def qemu_mutex_locked(self, timestamp, mutex, filename, line): 42 self.locked += 1 43 rec = self._get_mutex(mutex) 44 rec["locked"] += 1 45 rec["locked_time"] = timestamp[0] 46 acquire_time = rec["locked_time"] - rec["lock_time"] 47 rec["locked_loc"] = (filename, line) 48 rec["acquire_times"].append(acquire_time) 49 50 def qemu_mutex_unlock(self, timestamp, mutex, filename, line): 51 self.unlocks += 1 52 rec = self._get_mutex(mutex) 53 rec["unlocked"] += 1 54 held_time = timestamp[0] - rec["locked_time"] 55 rec["held_times"].append(held_time) 56 rec["unlock_loc"] = (filename, line) 57 58 59def get_args(): 60 "Grab options" 61 parser = argparse.ArgumentParser() 62 parser.add_argument("--output", "-o", type=str, help="Render plot to file") 63 parser.add_argument("events", type=str, help='trace file read from') 64 parser.add_argument("tracefile", type=str, help='trace file read from') 65 return parser.parse_args() 66 67if __name__ == '__main__': 68 args = get_args() 69 70 # Gather data from the trace 71 analyser = MutexAnalyser() 72 simpletrace.process(args.events, args.tracefile, analyser) 73 74 print ("Total locks: %d, locked: %d, unlocked: %d" % 75 (analyser.locks, analyser.locked, analyser.unlocks)) 76 77 # Now dump the individual lock stats 78 for key, val in sorted(analyser.mutex_records.items(), 79 key=lambda k_v: k_v[1]["locks"]): 80 print ("Lock: %#x locks: %d, locked: %d, unlocked: %d" % 81 (key, val["locks"], val["locked"], val["unlocked"])) 82 83 acquire_times = np.array(val["acquire_times"]) 84 if len(acquire_times) > 0: 85 print (" Acquire Time: min:%d median:%d avg:%.2f max:%d" % 86 (acquire_times.min(), np.median(acquire_times), 87 acquire_times.mean(), acquire_times.max())) 88 89 held_times = np.array(val["held_times"]) 90 if len(held_times) > 0: 91 print (" Held Time: min:%d median:%d avg:%.2f max:%d" % 92 (held_times.min(), np.median(held_times), 93 held_times.mean(), held_times.max())) 94 95 # Check if any locks still held 96 if val["locks"] > val["locked"]: 97 print (" LOCK HELD (%s:%s)" % (val["locked_loc"])) 98 print (" BLOCKED (%s:%s)" % (val["lock_loc"])) 99