From patchwork Fri Aug 9 06:07:42 2019 Content-Type: text/plain; charset="utf-8" MIME-Version: 1.0 Content-Transfer-Encoding: 7bit X-Patchwork-Submitter: =?utf-8?b?SsO8cmdlbiBHcm/Dnw==?= X-Patchwork-Id: 11085383 Return-Path: Received: from mail.wl.linuxfoundation.org (pdx-wl-mail.web.codeaurora.org [172.30.200.125]) by pdx-korg-patchwork-2.web.codeaurora.org (Postfix) with ESMTP id 13B3F1398 for ; Fri, 9 Aug 2019 06:09:13 +0000 (UTC) Received: from mail.wl.linuxfoundation.org (localhost [127.0.0.1]) by mail.wl.linuxfoundation.org (Postfix) with ESMTP id F3F6E28BE1 for ; Fri, 9 Aug 2019 06:09:12 +0000 (UTC) Received: by mail.wl.linuxfoundation.org (Postfix, from userid 486) id E72EF28C1C; Fri, 9 Aug 2019 06:09:12 +0000 (UTC) X-Spam-Checker-Version: SpamAssassin 3.3.1 (2010-03-16) on pdx-wl-mail.web.codeaurora.org X-Spam-Level: X-Spam-Status: No, score=-5.2 required=2.0 tests=BAYES_00,MAILING_LIST_MULTI, RCVD_IN_DNSWL_MED autolearn=ham version=3.3.1 Received: from lists.xenproject.org (lists.xenproject.org [192.237.175.120]) (using TLSv1.2 with cipher AES256-GCM-SHA384 (256/256 bits)) (No client certificate requested) by mail.wl.linuxfoundation.org (Postfix) with ESMTPS id 1452528BE1 for ; Fri, 9 Aug 2019 06:09:12 +0000 (UTC) Received: from localhost ([127.0.0.1] helo=lists.xenproject.org) by lists.xenproject.org with esmtp (Exim 4.89) (envelope-from ) id 1hvy4A-0006br-2a; Fri, 09 Aug 2019 06:07:54 +0000 Received: from us1-rack-dfw2.inumbo.com ([104.130.134.6]) by lists.xenproject.org with esmtp (Exim 4.89) (envelope-from ) id 1hvy48-0006bV-Po for xen-devel@lists.xenproject.org; Fri, 09 Aug 2019 06:07:52 +0000 X-Inumbo-ID: 047873df-ba6c-11e9-8980-bc764e045a96 Received: from mx1.suse.de (unknown [195.135.220.15]) by us1-rack-dfw2.inumbo.com (Halon) with ESMTPS id 047873df-ba6c-11e9-8980-bc764e045a96; Fri, 09 Aug 2019 06:07:51 +0000 (UTC) X-Virus-Scanned: by amavisd-new at test-mx.suse.de Received: from relay2.suse.de (unknown [195.135.220.254]) by mx1.suse.de (Postfix) with ESMTP id CB115B05E; Fri, 9 Aug 2019 06:07:48 +0000 (UTC) From: Juergen Gross To: xen-devel@lists.xenproject.org Date: Fri, 9 Aug 2019 08:07:42 +0200 Message-Id: <20190809060744.8985-4-jgross@suse.com> X-Mailer: git-send-email 2.16.4 In-Reply-To: <20190809060744.8985-1-jgross@suse.com> References: <20190809060744.8985-1-jgross@suse.com> Subject: [Xen-devel] [PATCH v2 3/5] xen: print lock profile info in panic() X-BeenThere: xen-devel@lists.xenproject.org X-Mailman-Version: 2.1.23 Precedence: list List-Id: Xen developer discussion List-Unsubscribe: , List-Post: List-Help: List-Subscribe: , Cc: Juergen Gross , Stefano Stabellini , Wei Liu , Konrad Rzeszutek Wilk , George Dunlap , Andrew Cooper , Ian Jackson , Tim Deegan , Julien Grall , Jan Beulich , Volodymyr Babchuk , =?utf-8?q?Roger_Pau_Monn?= =?utf-8?q?=C3=A9?= MIME-Version: 1.0 Errors-To: xen-devel-bounces@lists.xenproject.org Sender: "Xen-devel" X-Virus-Scanned: ClamAV using ClamSMTP Print the lock profile data when the system crashes and add some more information for each lock data (lock address, cpu holding the lock). While at it use the PRI_stime format specifier for printing time data. This is especially beneficial for watchdog triggered crashes in case of deadlocks. In order to have the cpu holding the lock available let the lock profile config option select DEBUG_LOCKS. As printing the lock profile data will make use of locking, too, we need to disable spinlock debugging before calling spinlock_profile_printall() from panic(). While at it remove a superfluous #ifdef CONFIG_LOCK_PROFILE and rename CONFIG_LOCK_PROFILE to CONFIG_DEBUG_LOCK_PROFILE. Also move the .lockprofile.data section to init area in linker scripts as the data is no longer needed after boot. Signed-off-by: Juergen Gross --- V2: - rename CONFIG_LOCK_PROFILE to CONFIG_DEBUG_LOCK_PROFILE (Jan Beulich) - move .lockprofile.data section to init area in linker scripts - use PRI_stime (Andrew Cooper) - don't print "cpu=4095", but "not locked" (Andrew Cooper) --- xen/Kconfig.debug | 3 ++- xen/arch/arm/xen.lds.S | 13 +++++++------ xen/arch/x86/domain.c | 2 +- xen/arch/x86/xen.lds.S | 13 +++++++------ xen/common/keyhandler.c | 2 +- xen/common/spinlock.c | 33 ++++++++++++++++++--------------- xen/common/sysctl.c | 2 +- xen/drivers/char/console.c | 4 +++- xen/include/xen/spinlock.h | 12 +++++++----- 9 files changed, 47 insertions(+), 37 deletions(-) diff --git a/xen/Kconfig.debug b/xen/Kconfig.debug index 1faaa3ba6a..22573e74db 100644 --- a/xen/Kconfig.debug +++ b/xen/Kconfig.debug @@ -44,8 +44,9 @@ config COVERAGE If unsure, say N here. -config LOCK_PROFILE +config DEBUG_LOCK_PROFILE bool "Lock Profiling" + select DEBUG_LOCKS ---help--- Lock profiling allows you to see how often locks are taken and blocked. You can use serial console to print (and reset) using 'l' and 'L' diff --git a/xen/arch/arm/xen.lds.S b/xen/arch/arm/xen.lds.S index 12c107f45d..ba20e90e83 100644 --- a/xen/arch/arm/xen.lds.S +++ b/xen/arch/arm/xen.lds.S @@ -55,12 +55,6 @@ SECTIONS *(.data.rel.ro) *(.data.rel.ro.*) -#ifdef CONFIG_LOCK_PROFILE - . = ALIGN(POINTER_ALIGN); - __lock_profile_start = .; - *(.lockprofile.data) - __lock_profile_end = .; -#endif . = ALIGN(POINTER_ALIGN); __param_start = .; *(.data.param) @@ -174,6 +168,13 @@ SECTIONS . = ALIGN(4); *(.altinstr_replacement) +#ifdef CONFIG_DEBUG_LOCK_PROFILE + . = ALIGN(POINTER_ALIGN); + __lock_profile_start = .; + *(.lockprofile.data) + __lock_profile_end = .; +#endif + *(.init.data) *(.init.data.rel) *(.init.data.rel.*) diff --git a/xen/arch/x86/domain.c b/xen/arch/x86/domain.c index 5933b3f51b..369e29c12c 100644 --- a/xen/arch/x86/domain.c +++ b/xen/arch/x86/domain.c @@ -305,7 +305,7 @@ struct domain *alloc_domain_struct(void) #endif -#ifndef CONFIG_LOCK_PROFILE +#ifndef CONFIG_DEBUG_LOCK_PROFILE BUILD_BUG_ON(sizeof(*d) > PAGE_SIZE); #endif d = alloc_xenheap_pages(order, MEMF_bits(bits)); diff --git a/xen/arch/x86/xen.lds.S b/xen/arch/x86/xen.lds.S index a73139cd29..7b4fc74973 100644 --- a/xen/arch/x86/xen.lds.S +++ b/xen/arch/x86/xen.lds.S @@ -129,12 +129,6 @@ SECTIONS *(.ex_table.pre) __stop___pre_ex_table = .; -#ifdef CONFIG_LOCK_PROFILE - . = ALIGN(POINTER_ALIGN); - __lock_profile_start = .; - *(.lockprofile.data) - __lock_profile_end = .; -#endif . = ALIGN(POINTER_ALIGN); __param_start = .; *(.data.param) @@ -252,6 +246,13 @@ SECTIONS *(.altinstructions) __alt_instructions_end = .; +#ifdef CONFIG_DEBUG_LOCK_PROFILE + . = ALIGN(POINTER_ALIGN); + __lock_profile_start = .; + *(.lockprofile.data) + __lock_profile_end = .; +#endif + . = ALIGN(8); __ctors_start = .; *(.ctors) diff --git a/xen/common/keyhandler.c b/xen/common/keyhandler.c index 57b360ee4b..c36baa4dff 100644 --- a/xen/common/keyhandler.c +++ b/xen/common/keyhandler.c @@ -62,7 +62,7 @@ static struct keyhandler { KEYHANDLER('P', perfc_reset, "reset performance counters", 0), #endif -#ifdef CONFIG_LOCK_PROFILE +#ifdef CONFIG_DEBUG_LOCK_PROFILE KEYHANDLER('l', spinlock_profile_printall, "print lock profile info", 1), KEYHANDLER('L', spinlock_profile_reset, "reset lock profile info", 0), #endif diff --git a/xen/common/spinlock.c b/xen/common/spinlock.c index 79e70a9947..c4f706c627 100644 --- a/xen/common/spinlock.c +++ b/xen/common/spinlock.c @@ -106,7 +106,7 @@ void spin_debug_disable(void) #endif -#ifdef CONFIG_LOCK_PROFILE +#ifdef CONFIG_DEBUG_LOCK_PROFILE #define LOCK_PROFILE_REL \ if (lock->profile) \ @@ -243,7 +243,7 @@ int _spin_trylock(spinlock_t *lock) old.head_tail, new.head_tail) != old.head_tail ) return 0; got_lock(&lock->debug); -#ifdef CONFIG_LOCK_PROFILE +#ifdef CONFIG_DEBUG_LOCK_PROFILE if (lock->profile) lock->profile->time_locked = NOW(); #endif @@ -258,7 +258,7 @@ int _spin_trylock(spinlock_t *lock) void _spin_barrier(spinlock_t *lock) { spinlock_tickets_t sample; -#ifdef CONFIG_LOCK_PROFILE +#ifdef CONFIG_DEBUG_LOCK_PROFILE s_time_t block = NOW(); #endif @@ -269,7 +269,7 @@ void _spin_barrier(spinlock_t *lock) { while ( observe_head(&lock->tickets) == sample.head ) arch_lock_relax(); -#ifdef CONFIG_LOCK_PROFILE +#ifdef CONFIG_DEBUG_LOCK_PROFILE if ( lock->profile ) { lock->profile->time_block += NOW() - block; @@ -327,7 +327,7 @@ void _spin_unlock_recursive(spinlock_t *lock) } } -#ifdef CONFIG_LOCK_PROFILE +#ifdef CONFIG_DEBUG_LOCK_PROFILE struct lock_profile_anc { struct lock_profile_qhead *head_q; /* first head of this type */ @@ -362,14 +362,19 @@ static void spinlock_profile_iterate(lock_profile_subfunc *sub, void *par) static void spinlock_profile_print_elem(struct lock_profile *data, int32_t type, int32_t idx, void *par) { - if ( type == LOCKPROF_TYPE_GLOBAL ) - printk("%s %s:\n", lock_profile_ancs[type].name, data->name); + struct spinlock *lock = data->lock; + + printk("%s ", lock_profile_ancs[type].name); + if ( type != LOCKPROF_TYPE_GLOBAL ) + printk("%d ", idx); + printk("%s: addr=%p, lockval=%08x, ", data->name, lock, + lock->tickets.head_tail); + if ( lock->debug.cpu == SPINLOCK_NO_CPU ) + printk("not locked\n"); else - printk("%s %d %s:\n", lock_profile_ancs[type].name, idx, data->name); - printk(" lock:%12"PRId64"(%08X:%08X), block:%12"PRId64"(%08X:%08X)\n", - data->lock_cnt, (u32)(data->time_hold >> 32), (u32)data->time_hold, - data->block_cnt, (u32)(data->time_block >> 32), - (u32)data->time_block); + printk("cpu=%d\n", lock->debug.cpu); + printk(" lock:%" PRId64 "(%" PRI_stime "), block:%" PRId64 "(%" PRI_stime ")\n", + data->lock_cnt, data->time_hold, data->block_cnt, data->time_block); } void spinlock_profile_printall(unsigned char key) @@ -488,7 +493,6 @@ void _lock_profile_deregister_struct( spin_unlock(&lock_profile_lock); } -#ifdef CONFIG_LOCK_PROFILE static int __init lock_prof_init(void) { struct lock_profile **q; @@ -507,6 +511,5 @@ static int __init lock_prof_init(void) return 0; } __initcall(lock_prof_init); -#endif -#endif /* LOCK_PROFILE */ +#endif /* CONFIG_DEBUG_LOCK_PROFILE */ diff --git a/xen/common/sysctl.c b/xen/common/sysctl.c index 765effde8d..46aebecbd3 100644 --- a/xen/common/sysctl.c +++ b/xen/common/sysctl.c @@ -119,7 +119,7 @@ long do_sysctl(XEN_GUEST_HANDLE_PARAM(xen_sysctl_t) u_sysctl) break; #endif -#ifdef CONFIG_LOCK_PROFILE +#ifdef CONFIG_DEBUG_LOCK_PROFILE case XEN_SYSCTL_lockprof_op: ret = spinlock_profile_control(&op->u.lockprof_op); break; diff --git a/xen/drivers/char/console.c b/xen/drivers/char/console.c index 1680d078db..404d28a725 100644 --- a/xen/drivers/char/console.c +++ b/xen/drivers/char/console.c @@ -1167,7 +1167,9 @@ void panic(const char *fmt, ...) unsigned long flags; static DEFINE_SPINLOCK(lock); static char buf[128]; - + + spin_debug_disable(); + spinlock_profile_printall('\0'); debugtrace_dump(); /* Protects buf[] and ensure multi-line message prints atomically. */ diff --git a/xen/include/xen/spinlock.h b/xen/include/xen/spinlock.h index dfa0b72f8d..0b010ff6ad 100644 --- a/xen/include/xen/spinlock.h +++ b/xen/include/xen/spinlock.h @@ -1,6 +1,7 @@ #ifndef __SPINLOCK_H__ #define __SPINLOCK_H__ +#include #include #include #include @@ -27,7 +28,7 @@ union lock_debug { }; #define spin_debug_disable() ((void)0) #endif -#ifdef CONFIG_LOCK_PROFILE +#ifdef CONFIG_DEBUG_LOCK_PROFILE #include @@ -73,9 +74,9 @@ struct lock_profile { struct spinlock *lock; /* the lock itself */ u64 lock_cnt; /* # of complete locking ops */ u64 block_cnt; /* # of complete wait for lock */ - s64 time_hold; /* cumulated lock time */ - s64 time_block; /* cumulated wait time */ - s64 time_locked; /* system time of last locking */ + s_time_t time_hold; /* cumulated lock time */ + s_time_t time_block; /* cumulated wait time */ + s_time_t time_locked; /* system time of last locking */ }; struct lock_profile_qhead { @@ -131,6 +132,7 @@ struct lock_profile_qhead { }; #define spin_lock_init_prof(s, l) spin_lock_init(&((s)->l)) #define lock_profile_register_struct(type, ptr, idx, print) #define lock_profile_deregister_struct(type, ptr) +#define spinlock_profile_printall(key) #endif @@ -151,7 +153,7 @@ typedef struct spinlock { u16 recurse_cnt:4; #define SPINLOCK_MAX_RECURSE 0xfu union lock_debug debug; -#ifdef CONFIG_LOCK_PROFILE +#ifdef CONFIG_DEBUG_LOCK_PROFILE struct lock_profile *profile; #endif } spinlock_t;