From patchwork Tue Jan 16 14:17:33 2018 Content-Type: text/plain; charset="utf-8" MIME-Version: 1.0 Content-Transfer-Encoding: 8bit X-Patchwork-Submitter: Paolo Bonzini X-Patchwork-Id: 124727 Delivered-To: patch@linaro.org Received: by 10.46.64.148 with SMTP id r20csp1042453lje; Tue, 16 Jan 2018 07:02:11 -0800 (PST) X-Google-Smtp-Source: ACJfBotgt5nhEFr0v5/zdc94XAntiAuA8un5t8ti+M99xlQU7JcVzVl+/nwguNPq8NPtBTiFjgJQ X-Received: by 10.37.161.201 with SMTP id a67mr5844132ybi.250.1516114931430; Tue, 16 Jan 2018 07:02:11 -0800 (PST) ARC-Seal: i=1; a=rsa-sha256; t=1516114931; cv=none; d=google.com; s=arc-20160816; b=A0yNWrGT2qxJHpTSBaSSq+uuZrZUROxWgdY3F1A/IkDCmEuaZf1teu94fdWXS5Optj Tr+koc8TNja3CNPtqmKvGHtUvBdD9f+CG6Aya2FMcbqKuG9cxDGqJ0EDmGyAsHBLHkn2 gq79vua3h1W5024WKu4HcwaY5b83UEbuGlAum/3R0rqvd8JoPsJ1C46MXprhxdSP320v saq5LRy+ZTm2QdfFDtql5a6tpGCFfDuITwpvzUAk36tpnaZ6GVK3vjwb6pAFtvdeh2IR kDA/PxDeSnVswqzSP9CRDDz4+OjUmriRGOZAHBmcGI60GCL56e8cyS6WQtNtql+xVK5p ZXcg== ARC-Message-Signature: i=1; a=rsa-sha256; c=relaxed/relaxed; d=google.com; s=arc-20160816; h=sender:errors-to:cc:list-subscribe:list-help:list-post:list-archive :list-unsubscribe:list-id:precedence:subject :content-transfer-encoding:mime-version:references:in-reply-to :message-id:date:to:from:dkim-signature:arc-authentication-results; bh=XVXpTNERZuDfLChI1As/F3vkRhV3SxX66Rw2nV7mweQ=; b=wnTrStGXkmh0xDBebtgWWeI335h5xY4aEekp+SjOgvcAen3NbMDng9wEpNNsO2v/3O b9OMYT53NIUpIAEB4LFcwvevBDZJ0UpPDe0kxfRxYrn26PyiJIdAcTBAfNKjgJSNOc4q rUl9iGnTPKgQAtLElBLL6Alomr/Vz3K2l48kRLwTb7Jnt3Obtkqa+Av4V1/G5fpVJUEc TthKn0xi+dIgoJDMpMBu9RzyVkTzKwF/GCh1SD8G5vuAar/HH3VGB/ZxmSEX68SiDDCf 7CIH0ua84wlujH5kATtTh/nDxZW1sOrqMVCtTSAYHHWzPziYyuTqHwNITcP7/Gqyvxgs ySIw== ARC-Authentication-Results: i=1; mx.google.com; dkim=fail header.i=@gmail.com header.s=20161025 header.b=CgqjTBV7; spf=pass (google.com: domain of qemu-devel-bounces+patch=linaro.org@nongnu.org designates 2001:4830:134:3::11 as permitted sender) smtp.mailfrom=qemu-devel-bounces+patch=linaro.org@nongnu.org; dmarc=fail (p=NONE sp=NONE dis=NONE) header.from=redhat.com Return-Path: Received: from lists.gnu.org (lists.gnu.org. [2001:4830:134:3::11]) by mx.google.com with ESMTPS id 67si523109ybh.375.2018.01.16.07.02.11 for (version=TLS1 cipher=AES128-SHA bits=128/128); Tue, 16 Jan 2018 07:02:11 -0800 (PST) Received-SPF: pass (google.com: domain of qemu-devel-bounces+patch=linaro.org@nongnu.org designates 2001:4830:134:3::11 as permitted sender) client-ip=2001:4830:134:3::11; Authentication-Results: mx.google.com; dkim=fail header.i=@gmail.com header.s=20161025 header.b=CgqjTBV7; spf=pass (google.com: domain of qemu-devel-bounces+patch=linaro.org@nongnu.org designates 2001:4830:134:3::11 as permitted sender) smtp.mailfrom=qemu-devel-bounces+patch=linaro.org@nongnu.org; dmarc=fail (p=NONE sp=NONE dis=NONE) header.from=redhat.com Received: from localhost ([::1]:39493 helo=lists.gnu.org) by lists.gnu.org with esmtp (Exim 4.71) (envelope-from ) id 1ebSkc-0005Fs-Lt for patch@linaro.org; Tue, 16 Jan 2018 10:02:10 -0500 Received: from eggs.gnu.org ([2001:4830:134:3::10]:51079) by lists.gnu.org with esmtp (Exim 4.71) (envelope-from ) id 1ebS4m-0003ma-8Y for qemu-devel@nongnu.org; Tue, 16 Jan 2018 09:18:57 -0500 Received: from Debian-exim by eggs.gnu.org with spam-scanned (Exim 4.71) (envelope-from ) id 1ebS4l-0005bc-5p for qemu-devel@nongnu.org; Tue, 16 Jan 2018 09:18:56 -0500 Received: from mail-wm0-x22b.google.com ([2a00:1450:400c:c09::22b]:43932) by eggs.gnu.org with esmtps (TLS1.0:RSA_AES_128_CBC_SHA1:16) (Exim 4.71) (envelope-from ) id 1ebS4k-0005at-Sp for qemu-devel@nongnu.org; Tue, 16 Jan 2018 09:18:55 -0500 Received: by mail-wm0-x22b.google.com with SMTP id g1so8680182wmg.2 for ; Tue, 16 Jan 2018 06:18:54 -0800 (PST) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=gmail.com; s=20161025; h=sender:from:to:cc:subject:date:message-id:in-reply-to:references :mime-version:content-transfer-encoding; bh=XVXpTNERZuDfLChI1As/F3vkRhV3SxX66Rw2nV7mweQ=; b=CgqjTBV7fSXrWaNcAw6gHWMpYypGtqVSiV9f/RqpHjsIBhes0aeMzuAZGBYcA09PrD gfZG7sVgl10jn1ObMX5sTPrhlF0YKKi62Luf9cMiFtA3D045uRZSfUI4LDwpwcQ7qsnu UqGObHg2Pd3XweLffo3d/T7qKcc+V0umEVQF6gFsM0g+4Ph/q/lqRcESLQiSRjdfx5Eh yPr0xBLdjnMFlqubqXuPZqjGng8t1OTpQW+RRPZ3C9dzR2dBPIrtDScy58Roeb3qeeYc 0INq3/GueLaqZUOQQGydbDNLFDXy+WTw05KFFn6cGk5CJ8q+oCA1x9GVFFNqBPYrZiRh LCRA== X-Google-DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=1e100.net; s=20161025; h=x-gm-message-state:sender:from:to:cc:subject:date:message-id :in-reply-to:references:mime-version:content-transfer-encoding; bh=XVXpTNERZuDfLChI1As/F3vkRhV3SxX66Rw2nV7mweQ=; b=sjZeOHSivcjDCw4GtIJVQYDaG2Rnx3C98rT/HNdxN1N0Swkq70OLorHnSgApEFTRR9 1CT+SSYUQwcf3mPTB6L63xEBuzhIWtrvBAXIThULXFLhSNbm0gUlgtjM18A2EtC9n8iF 7vtshLdxl64JoLKheychYBH3LSsAGAHOp3lsVugb9KCu9+ehHOrkrFfGJTfFosWTXI5t OiTsK+DXewYzEq3SPia1Gm9LMpPdh39oam7/5lyyfadyo+tRCIJOxZTKYX/bpQ50vYUh Ue5zJo92YQcTGxwvVWxgqItgcnhuH1rB+AzI4+mWP5TBdwg/f86INN4601+7kwyuXiNB xV4w== X-Gm-Message-State: AKwxytfChN/EFNdCe3WqD1AFEhOyArFktLu2GivwdC0r6UBOP+t/aut7 i3Dm6klH3nY6o+/UTVn/HmDazqb7 X-Received: by 10.28.148.150 with SMTP id w144mr13241278wmd.0.1516112333559; Tue, 16 Jan 2018 06:18:53 -0800 (PST) Received: from 640k.lan (dynamic-adsl-78-12-229-84.clienti.tiscali.it. [78.12.229.84]) by smtp.gmail.com with ESMTPSA id u10sm1537758wrg.6.2018.01.16.06.18.51 (version=TLS1_2 cipher=ECDHE-RSA-AES128-GCM-SHA256 bits=128/128); Tue, 16 Jan 2018 06:18:52 -0800 (PST) From: Paolo Bonzini To: qemu-devel@nongnu.org Date: Tue, 16 Jan 2018 15:17:33 +0100 Message-Id: <1516112253-14480-52-git-send-email-pbonzini@redhat.com> X-Mailer: git-send-email 1.8.3.1 In-Reply-To: <1516112253-14480-1-git-send-email-pbonzini@redhat.com> References: <1516112253-14480-1-git-send-email-pbonzini@redhat.com> MIME-Version: 1.0 X-detected-operating-system: by eggs.gnu.org: Genre and OS details not recognized. X-Received-From: 2a00:1450:400c:c09::22b Subject: [Qemu-devel] [PULL 51/51] scripts/analyse-locks-simpletrace.py: script to analyse lock times X-BeenThere: qemu-devel@nongnu.org X-Mailman-Version: 2.1.21 Precedence: list List-Id: List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , Cc: =?utf-8?q?Alex_Benn=C3=A9e?= Errors-To: qemu-devel-bounces+patch=linaro.org@nongnu.org Sender: "Qemu-devel" From: Alex Bennée 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 Signed-off-by: Paolo Bonzini --- scripts/analyse-locks-simpletrace.py | 99 ++++++++++++++++++++++++++++++++++++ 1 file changed, 99 insertions(+) create mode 100755 scripts/analyse-locks-simpletrace.py -- 1.8.3.1 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 +# + +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"]))