[Date Prev][Date Next][Thread Prev][Thread Next][Date Index][Thread Index]
[Qemu-devel] [PULL 51/51] scripts/analyse-locks-simpletrace.py: script t
From: |
Paolo Bonzini |
Subject: |
[Qemu-devel] [PULL 51/51] scripts/analyse-locks-simpletrace.py: script to analyse lock times |
Date: |
Tue, 16 Jan 2018 15:17:33 +0100 |
From: Alex Bennée <address@hidden>
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 <address@hidden>
Signed-off-by: Paolo Bonzini <address@hidden>
---
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 <address@hidden>
+#
+
+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
- [Qemu-devel] [PULL 36/51] cpus: unify qemu_*_wait_io_event, (continued)
- [Qemu-devel] [PULL 36/51] cpus: unify qemu_*_wait_io_event, Paolo Bonzini, 2018/01/16
- [Qemu-devel] [PULL 41/51] chardev: Clean up previous patch indentation, Paolo Bonzini, 2018/01/16
- [Qemu-devel] [PULL 38/51] net: Drop unusual use of do { } while (0);, Paolo Bonzini, 2018/01/16
- [Qemu-devel] [PULL 39/51] mips: Tweak location of ';' in macros, Paolo Bonzini, 2018/01/16
- [Qemu-devel] [PULL 40/51] chardev: Use goto/label instead of do/break/while(0), Paolo Bonzini, 2018/01/16
- [Qemu-devel] [PULL 42/51] tests: Avoid 'do/while(false); ' in vhost-user-bridge, Paolo Bonzini, 2018/01/16
- [Qemu-devel] [PULL 43/51] maint: Fix macros with broken 'do/while(0); ' usage, Paolo Bonzini, 2018/01/16
- [Qemu-devel] [PULL 45/51] cpu_physical_memory_sync_dirty_bitmap: Another alignment fix, Paolo Bonzini, 2018/01/16
- [Qemu-devel] [PULL 44/51] checkpatch: Enforce proper do/while (0) style, Paolo Bonzini, 2018/01/16
- [Qemu-devel] [PULL 47/51] find_ram_offset: Align ram_addr_t allocation on long boundaries, Paolo Bonzini, 2018/01/16
- [Qemu-devel] [PULL 51/51] scripts/analyse-locks-simpletrace.py: script to analyse lock times,
Paolo Bonzini <=
- [Qemu-devel] [PULL 49/51] cpu: flush TB cache when loading VMState, Paolo Bonzini, 2018/01/16
- [Qemu-devel] [PULL 46/51] find_ram_offset: Add comments and tracing, Paolo Bonzini, 2018/01/16
- [Qemu-devel] [PULL 50/51] util/qemu-thread-*: add qemu_lock, locked and unlock trace events, Paolo Bonzini, 2018/01/16
- [Qemu-devel] [PULL 48/51] block/iscsi: fix initialization of iTask in iscsi_co_get_block_status, Paolo Bonzini, 2018/01/16
- Re: [Qemu-devel] [PULL v4 00/51] Misc patches for 2018-01-12, no-reply, 2018/01/16
- Re: [Qemu-devel] [PULL v4 00/51] Misc patches for 2018-01-12, Peter Maydell, 2018/01/16