mirror of
https://github.com/xemu-project/xemu.git
synced 2024-11-24 03:59:52 +00:00
b5976c2e46
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.bennee@linaro.org> Signed-off-by: Paolo Bonzini <pbonzini@redhat.com>
100 lines
3.5 KiB
Python
Executable File
100 lines
3.5 KiB
Python
Executable File
#!/usr/bin/env python
|
|
# -*- coding: utf-8 -*-
|
|
#
|
|
# Analyse lock events and compute statistics
|
|
#
|
|
# Author: Alex Bennée <alex.bennee@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"]))
|