From: Alex Bennée <alex.ben...@linaro.org>
This script allows analysis of mutex acquisition and hold times based
on a trace file. Given a trace control file of:
qemu_mutex_lock
qemu_mutex_locked
qemu_mutex_unlock
And running with:
$QEMU $QEMU_ARGS -trace events=./lock-trace
You can analyse the results with:
./scripts/analyse-locks-simpletrace.py trace-events-all ./trace-21812
Signed-off-by: Alex Bennée <alex.ben...@linaro.org>
Signed-off-by: Paolo Bonzini <pbonz...@redhat.com>
---
scripts/analyse-locks-simpletrace.py | 99 ++++++++++++++++++++++++++++++++++++
1 file changed, 99 insertions(+)
create mode 100755 scripts/analyse-locks-simpletrace.py
diff --git a/scripts/analyse-locks-simpletrace.py
b/scripts/analyse-locks-simpletrace.py
new file mode 100755
index 0000000..101e84d
--- /dev/null
+++ b/scripts/analyse-locks-simpletrace.py
@@ -0,0 +1,99 @@
+#!/usr/bin/env python
+# -*- coding: utf-8 -*-
+#
+# Analyse lock events and compute statistics
+#
+# Author: Alex Bennée <alex.ben...@linaro.org>
+#
+
+import os
+import simpletrace
+import argparse
+import numpy as np
+
+class MutexAnalyser(simpletrace.Analyzer):
+ "A simpletrace Analyser for checking locks."
+
+ def __init__(self):
+ self.locks = 0
+ self.locked = 0
+ self.unlocks = 0
+ self.mutex_records = {}
+
+ def _get_mutex(self, mutex):
+ if not mutex in self.mutex_records:
+ self.mutex_records[mutex] = {"locks": 0,
+ "lock_time": 0,
+ "acquire_times": [],
+ "locked": 0,
+ "locked_time": 0,
+ "held_times": [],
+ "unlocked": 0}
+
+ return self.mutex_records[mutex]
+
+ def qemu_mutex_lock(self, timestamp, mutex, filename, line):
+ self.locks += 1
+ rec = self._get_mutex(mutex)
+ rec["locks"] += 1
+ rec["lock_time"] = timestamp[0]
+ rec["lock_loc"] = (filename, line)
+
+ def qemu_mutex_locked(self, timestamp, mutex, filename, line):
+ self.locked += 1
+ rec = self._get_mutex(mutex)
+ rec["locked"] += 1
+ rec["locked_time"] = timestamp[0]
+ acquire_time = rec["locked_time"] - rec["lock_time"]
+ rec["locked_loc"] = (filename, line)
+ rec["acquire_times"].append(acquire_time)
+
+ def qemu_mutex_unlock(self, timestamp, mutex, filename, line):
+ self.unlocks += 1
+ rec = self._get_mutex(mutex)
+ rec["unlocked"] += 1
+ held_time = timestamp[0] - rec["locked_time"]
+ rec["held_times"].append(held_time)
+ rec["unlock_loc"] = (filename, line)
+
+
+def get_args():
+ "Grab options"
+ parser = argparse.ArgumentParser()
+ parser.add_argument("--output", "-o", type=str, help="Render plot to file")
+ parser.add_argument("events", type=str, help='trace file read from')
+ parser.add_argument("tracefile", type=str, help='trace file read from')
+ return parser.parse_args()
+
+if __name__ == '__main__':
+ args = get_args()
+
+ # Gather data from the trace
+ analyser = MutexAnalyser()
+ simpletrace.process(args.events, args.tracefile, analyser)
+
+ print ("Total locks: %d, locked: %d, unlocked: %d" %
+ (analyser.locks, analyser.locked, analyser.unlocks))
+
+ # Now dump the individual lock stats
+ for key, val in sorted(analyser.mutex_records.iteritems(),
+ key=lambda (k,v): v["locks"]):
+ print ("Lock: %#x locks: %d, locked: %d, unlocked: %d" %
+ (key, val["locks"], val["locked"], val["unlocked"]))
+
+ acquire_times = np.array(val["acquire_times"])
+ if len(acquire_times) > 0:
+ print (" Acquire Time: min:%d median:%d avg:%.2f max:%d" %
+ (acquire_times.min(), np.median(acquire_times),
+ acquire_times.mean(), acquire_times.max()))
+
+ held_times = np.array(val["held_times"])
+ if len(held_times) > 0:
+ print (" Held Time: min:%d median:%d avg:%.2f max:%d" %
+ (held_times.min(), np.median(held_times),
+ held_times.mean(), held_times.max()))
+
+ # Check if any locks still held
+ if val["locks"] > val["locked"]:
+ print (" LOCK HELD (%s:%s)" % (val["locked_loc"]))
+ print (" BLOCKED (%s:%s)" % (val["lock_loc"]))
--
1.8.3.1
