From nobody Thu Nov 6 03:04:50 2025 Delivered-To: importer@patchew.org Received-SPF: pass (zoho.com: domain of gnu.org designates 208.118.235.17 as permitted sender) client-ip=208.118.235.17; envelope-from=qemu-devel-bounces+importer=patchew.org@nongnu.org; helo=lists.gnu.org; Authentication-Results: mx.zoho.com; spf=pass (zoho.com: domain of gnu.org designates 208.118.235.17 as permitted sender) smtp.mailfrom=qemu-devel-bounces+importer=patchew.org@nongnu.org; Return-Path: Received: from lists.gnu.org (lists.gnu.org [208.118.235.17]) by mx.zohomail.com with SMTPS id 14939799602951020.4323253116404; Fri, 5 May 2017 03:26:00 -0700 (PDT) Received: from localhost ([::1]:46098 helo=lists.gnu.org) by lists.gnu.org with esmtp (Exim 4.71) (envelope-from ) id 1d6aQw-0004PM-NF for importer@patchew.org; Fri, 05 May 2017 06:25:58 -0400 Received: from eggs.gnu.org ([2001:4830:134:3::10]:47093) by lists.gnu.org with esmtp (Exim 4.71) (envelope-from ) id 1d6aFG-0002Ka-LW for qemu-devel@nongnu.org; Fri, 05 May 2017 06:13:55 -0400 Received: from Debian-exim by eggs.gnu.org with spam-scanned (Exim 4.71) (envelope-from ) id 1d6aFE-0006e4-VD for qemu-devel@nongnu.org; Fri, 05 May 2017 06:13:54 -0400 Received: from mx1.redhat.com ([209.132.183.28]:43650) by eggs.gnu.org with esmtps (TLS1.0:DHE_RSA_AES_256_CBC_SHA1:32) (Exim 4.71) (envelope-from ) id 1d6aFE-0006dn-Lv for qemu-devel@nongnu.org; Fri, 05 May 2017 06:13:52 -0400 Received: from int-mx10.intmail.prod.int.phx2.redhat.com (int-mx10.intmail.prod.int.phx2.redhat.com [10.5.11.23]) (using TLSv1.2 with cipher ECDHE-RSA-AES256-GCM-SHA384 (256/256 bits)) (No client certificate requested) by mx1.redhat.com (Postfix) with ESMTPS id AFC48C04B945; Fri, 5 May 2017 10:13:51 +0000 (UTC) Received: from donizetti.redhat.com (ovpn-116-145.ams2.redhat.com [10.36.116.145]) by int-mx10.intmail.prod.int.phx2.redhat.com (8.14.4/8.14.4) with ESMTP id v45ADbkR026855; Fri, 5 May 2017 06:13:50 -0400 DMARC-Filter: OpenDMARC Filter v1.3.2 mx1.redhat.com AFC48C04B945 Authentication-Results: ext-mx07.extmail.prod.ext.phx2.redhat.com; dmarc=none (p=none dis=none) header.from=redhat.com Authentication-Results: ext-mx07.extmail.prod.ext.phx2.redhat.com; spf=pass smtp.mailfrom=pbonzini@redhat.com DKIM-Filter: OpenDKIM Filter v2.11.0 mx1.redhat.com AFC48C04B945 From: Paolo Bonzini To: qemu-devel@nongnu.org Date: Fri, 5 May 2017 12:13:26 +0200 Message-Id: <20170505101337.4650-11-pbonzini@redhat.com> In-Reply-To: <20170505101337.4650-1-pbonzini@redhat.com> References: <20170505101337.4650-1-pbonzini@redhat.com> X-Scanned-By: MIMEDefang 2.68 on 10.5.11.23 X-Greylist: Sender IP whitelisted, not delayed by milter-greylist-4.5.16 (mx1.redhat.com [10.5.110.31]); Fri, 05 May 2017 10:13:51 +0000 (UTC) X-detected-operating-system: by eggs.gnu.org: GNU/Linux 2.2.x-3.x [generic] [fuzzy] X-Received-From: 209.132.183.28 Subject: [Qemu-devel] [PULL 10/21] trace: add qemu mutex lock and unlock trace events 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: Jose Ricardo Ziviani Errors-To: qemu-devel-bounces+importer=patchew.org@nongnu.org Sender: "Qemu-devel" X-ZohoMail: RSF_0 Z_629925259 SPT_0 Content-Transfer-Encoding: quoted-printable MIME-Version: 1.0 Content-Type: text/plain; charset="utf-8" From: Jose Ricardo Ziviani These trace events were very useful to help me to understand and find a reordering issue in vfio, for example: qemu_mutex_lock locked mutex 0x10905ad8 vfio_region_write (0001:03:00.0:region1+0xc0, 0x2020c, 4) qemu_mutex_unlock unlocked mutex 0x10905ad8 qemu_mutex_lock locked mutex 0x10905ad8 vfio_region_write (0001:03:00.0:region1+0xc4, 0xa0000, 4) qemu_mutex_unlock unlocked mutex 0x10905ad8 that also helped me to see the desired result after the fix: qemu_mutex_lock locked mutex 0x10905ad8 vfio_region_write (0001:03:00.0:region1+0xc0, 0x2000c, 4) vfio_region_write (0001:03:00.0:region1+0xc4, 0xb0000, 4) qemu_mutex_unlock unlocked mutex 0x10905ad8 So it could be a good idea to have these traces implemented. It's worth mentioning that they should be surgically enabled during the debugging, otherwise it can flood the trace logs with lock/unlock messages. How to use it: trace-event qemu_mutex_lock on|off trace-event qemu_mutex_unlock on|off or trace-event qemu_mutex* on|off Signed-off-by: Jose Ricardo Ziviani Message-Id: <1493054398-26013-1-git-send-email-joserz@linux.vnet.ibm.com> Reviewed-by: Fam Zheng [Also handle trylock, cond_wait and win32; trace "unlocked" while still in the critical section, so that "unlocked" always comes before the next "locked" tracepoint. - Paolo] Signed-off-by: Paolo Bonzini --- util/qemu-thread-posix.c | 18 +++++++++++++++++- util/qemu-thread-win32.c | 11 ++++++++++- util/trace-events | 4 ++++ 3 files changed, 31 insertions(+), 2 deletions(-) diff --git a/util/qemu-thread-posix.c b/util/qemu-thread-posix.c index 73e3a0edf5..eacd99e497 100644 --- a/util/qemu-thread-posix.c +++ b/util/qemu-thread-posix.c @@ -14,6 +14,7 @@ #include "qemu/thread.h" #include "qemu/atomic.h" #include "qemu/notify.h" +#include "trace.h" =20 static bool name_threads; =20 @@ -60,17 +61,30 @@ void qemu_mutex_lock(QemuMutex *mutex) err =3D pthread_mutex_lock(&mutex->lock); if (err) error_exit(err, __func__); + + trace_qemu_mutex_locked(mutex); } =20 int qemu_mutex_trylock(QemuMutex *mutex) { - return pthread_mutex_trylock(&mutex->lock); + int err; + + err =3D pthread_mutex_trylock(&mutex->lock); + if (err =3D=3D 0) { + trace_qemu_mutex_locked(mutex); + return 0; + } + if (err !=3D EBUSY) { + error_exit(err, __func__); + } + return -EBUSY; } =20 void qemu_mutex_unlock(QemuMutex *mutex) { int err; =20 + trace_qemu_mutex_unlocked(mutex); err =3D pthread_mutex_unlock(&mutex->lock); if (err) error_exit(err, __func__); @@ -130,7 +144,9 @@ void qemu_cond_wait(QemuCond *cond, QemuMutex *mutex) { int err; =20 + trace_qemu_mutex_unlocked(mutex); err =3D pthread_cond_wait(&cond->cond, &mutex->lock); + trace_qemu_mutex_locked(mutex); if (err) error_exit(err, __func__); } diff --git a/util/qemu-thread-win32.c b/util/qemu-thread-win32.c index 59befd5202..653f29f442 100644 --- a/util/qemu-thread-win32.c +++ b/util/qemu-thread-win32.c @@ -19,6 +19,7 @@ #include "qemu-common.h" #include "qemu/thread.h" #include "qemu/notify.h" +#include "trace.h" #include =20 static bool name_threads; @@ -55,6 +56,7 @@ void qemu_mutex_destroy(QemuMutex *mutex) void qemu_mutex_lock(QemuMutex *mutex) { AcquireSRWLockExclusive(&mutex->lock); + trace_qemu_mutex_locked(mutex); } =20 int qemu_mutex_trylock(QemuMutex *mutex) @@ -62,11 +64,16 @@ int qemu_mutex_trylock(QemuMutex *mutex) int owned; =20 owned =3D TryAcquireSRWLockExclusive(&mutex->lock); - return !owned; + if (owned) { + trace_qemu_mutex_locked(mutex); + return 0; + } + return -EBUSY; } =20 void qemu_mutex_unlock(QemuMutex *mutex) { + trace_qemu_mutex_unlocked(mutex); ReleaseSRWLockExclusive(&mutex->lock); } =20 @@ -118,7 +125,9 @@ void qemu_cond_broadcast(QemuCond *cond) =20 void qemu_cond_wait(QemuCond *cond, QemuMutex *mutex) { + trace_qemu_mutex_unlocked(mutex); SleepConditionVariableSRW(&cond->var, &mutex->lock, INFINITE, 0); + trace_qemu_mutex_locked(mutex); } =20 void qemu_sem_init(QemuSemaphore *sem, int init) diff --git a/util/trace-events b/util/trace-events index b44ef4f895..fa540c620b 100644 --- a/util/trace-events +++ b/util/trace-events @@ -55,3 +55,7 @@ lockcnt_futex_wait_prepare(const void *lockcnt, int expec= ted, int new) "lockcnt lockcnt_futex_wait(const void *lockcnt, int val) "lockcnt %p waiting on %d" lockcnt_futex_wait_resume(const void *lockcnt, int new) "lockcnt %p after = wait: %d" lockcnt_futex_wake(const void *lockcnt) "lockcnt %p waking up one waiter" + +# util/qemu-thread-posix.c +qemu_mutex_locked(void *lock) "locked mutex %p" +qemu_mutex_unlocked(void *lock) "unlocked mutex %p" --=20 2.12.2