From patchwork Tue Oct 31 11:27:12 2017 Content-Type: text/plain; charset="utf-8" MIME-Version: 1.0 Content-Transfer-Encoding: 8bit X-Patchwork-Submitter: Pavel Dovgalyuk X-Patchwork-Id: 117593 Delivered-To: patch@linaro.org Received: by 10.140.22.164 with SMTP id 33csp3791245qgn; Tue, 31 Oct 2017 04:40:01 -0700 (PDT) X-Google-Smtp-Source: ABhQp+RoR0a1bfG78dYuiLR9Z4OBYYKhF+KczTPSB1hSwOqSvmjs4Aj6LcJe4vwacyLcWdjQEzks X-Received: by 10.13.250.4 with SMTP id k4mr969369ywf.32.1509450001439; Tue, 31 Oct 2017 04:40:01 -0700 (PDT) ARC-Seal: i=1; a=rsa-sha256; t=1509450001; cv=none; d=google.com; s=arc-20160816; b=Lz/N3wkgFl3pJhkdZbpKmNl+Wrh5pzqsI5ijPIbcQol4FVm/V8bCR55dVL7Vy5/dMP GdssBDz7T7tB1gVWzLoUkU+SbbNOaBBhaEqS8rLhAI848AQAWnViJZWxlyPC/gRdthQ8 f5dIQ/opge4KDEHprdp16rCrCf/YdlPiUoEF1DEJWIZDFgKnUDA8dCGuBuMXLRgRuK89 zNFt0vbf4LefM3ClKgBKY2F+uMLpHOupACPThyNJK8UYGia3R0xG1cOaXU1TeVhIjQI3 X8Sq80sA93oCq/sFxhVhrffM31bj2VNaTMHR4FTeJAxw3VeUlw+hJvleeg6O5f6+2d1z LngA== 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:user-agent:references :in-reply-to:message-id:date:to:from:arc-authentication-results; bh=aT+AWYNLUZIktc+qFKMvvIRgCCvYlgEwbMv7GDlIC3k=; b=qyScuKi9KW2Gdejyoh3BlG9qKGaSsXCQiRda5aer/AOBZZQZ37DJzovA3mrb4BuYlF cOYRwavt1oZ2jksS0De2IQBTgDGN/Z0grc0+CxS00quFUiwyfOet5lOAWYoRSX53AFMA Rudy+eFoFNHaFk6fIFr1ExDZO6fLNoDhfs+pdtkKoDutuPbEwiYcYYK7qdu1wlE5JE8R n8uyRDMP89MgbRN7UwkOqDurKAPYObYORKcaXWrT0+S4clQ/cdSxViyAkAK62UkR2ShT ys+NSkxP15JpYa+Tf5eNuHrARtKXFJYEYH2wCpFQBjA0OLclQeMCyPWiA6e0xbFAT/LN gj3w== ARC-Authentication-Results: i=1; mx.google.com; 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 Return-Path: Received: from lists.gnu.org (lists.gnu.org. [2001:4830:134:3::11]) by mx.google.com with ESMTPS id j141si349178ybg.303.2017.10.31.04.40.01 for (version=TLS1 cipher=AES128-SHA bits=128/128); Tue, 31 Oct 2017 04:40:01 -0700 (PDT) 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; 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 Received: from localhost ([::1]:44932 helo=lists.gnu.org) by lists.gnu.org with esmtp (Exim 4.71) (envelope-from ) id 1e9Utl-0006UV-0T for patch@linaro.org; Tue, 31 Oct 2017 07:40:01 -0400 Received: from eggs.gnu.org ([2001:4830:134:3::10]:51335) by lists.gnu.org with esmtp (Exim 4.71) (envelope-from ) id 1e9UhO-0004TD-FI for qemu-devel@nongnu.org; Tue, 31 Oct 2017 07:27:15 -0400 Received: from Debian-exim by eggs.gnu.org with spam-scanned (Exim 4.71) (envelope-from ) id 1e9UhM-00016k-Bx for qemu-devel@nongnu.org; Tue, 31 Oct 2017 07:27:14 -0400 Received: from mail.ispras.ru ([83.149.199.45]:45498) by eggs.gnu.org with esmtp (Exim 4.71) (envelope-from ) id 1e9UhM-00015h-0e for qemu-devel@nongnu.org; Tue, 31 Oct 2017 07:27:12 -0400 Received: from [127.0.1.1] (unknown [85.142.117.226]) by mail.ispras.ru (Postfix) with ESMTPSA id 2874E54006A; Tue, 31 Oct 2017 14:27:11 +0300 (MSK) From: Pavel Dovgalyuk To: qemu-devel@nongnu.org Date: Tue, 31 Oct 2017 14:27:12 +0300 Message-ID: <20171031112712.10516.27701.stgit@pasha-VirtualBox> In-Reply-To: <20171031112457.10516.8971.stgit@pasha-VirtualBox> References: <20171031112457.10516.8971.stgit@pasha-VirtualBox> User-Agent: StGit/0.17.1-dirty MIME-Version: 1.0 X-detected-operating-system: by eggs.gnu.org: GNU/Linux 3.x [fuzzy] X-Received-From: 83.149.199.45 Subject: [Qemu-devel] [RFC PATCH 24/26] 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: kwolf@redhat.com, peter.maydell@linaro.org, pavel.dovgaluk@ispras.ru, mst@redhat.com, jasowang@redhat.com, quintela@redhat.com, zuban32s@gmail.com, maria.klimushenkova@ispras.ru, dovgaluk@ispras.ru, kraxel@redhat.com, boost.lists@gmail.com, pbonzini@redhat.com, alex.bennee@linaro.org 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 --- 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..b72c951 --- /dev/null +++ b/scripts/analyse-locks-simpletrace.py @@ -0,0 +1,99 @@ +#!/usr/bin/env python +# -*- coding: utf-8 -*- +# +# Analyse lock events and +# +# 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"]))