From owner-svn-src-head@freebsd.org Sat Aug 15 19:45:50 2020 Return-Path: Delivered-To: svn-src-head@mailman.nyi.freebsd.org Received: from mx1.freebsd.org (mx1.freebsd.org [IPv6:2610:1c1:1:606c::19:1]) by mailman.nyi.freebsd.org (Postfix) with ESMTP id C4CF837CA2F; Sat, 15 Aug 2020 19:45:50 +0000 (UTC) (envelope-from cem@FreeBSD.org) Received: from mxrelay.nyi.freebsd.org (mxrelay.nyi.freebsd.org [IPv6:2610:1c1:1:606c::19:3]) (using TLSv1.3 with cipher TLS_AES_256_GCM_SHA384 (256/256 bits) key-exchange X25519 server-signature RSA-PSS (4096 bits) server-digest SHA256 client-signature RSA-PSS (4096 bits) client-digest SHA256) (Client CN "mxrelay.nyi.freebsd.org", Issuer "Let's Encrypt Authority X3" (verified OK)) by mx1.freebsd.org (Postfix) with ESMTPS id 4BTW4t4n1qz4fJC; Sat, 15 Aug 2020 19:45:50 +0000 (UTC) (envelope-from cem@FreeBSD.org) Received: from repo.freebsd.org (repo.freebsd.org [IPv6:2610:1c1:1:6068::e6a:0]) (using TLSv1.2 with cipher ECDHE-RSA-AES256-GCM-SHA384 (256/256 bits)) (Client did not present a certificate) by mxrelay.nyi.freebsd.org (Postfix) with ESMTPS id 875C8244E0; Sat, 15 Aug 2020 19:45:50 +0000 (UTC) (envelope-from cem@FreeBSD.org) Received: from repo.freebsd.org ([127.0.1.37]) by repo.freebsd.org (8.15.2/8.15.2) with ESMTP id 07FJjojh032666; Sat, 15 Aug 2020 19:45:50 GMT (envelope-from cem@FreeBSD.org) Received: (from cem@localhost) by repo.freebsd.org (8.15.2/8.15.2/Submit) id 07FJjo8r032665; Sat, 15 Aug 2020 19:45:50 GMT (envelope-from cem@FreeBSD.org) Message-Id: <202008151945.07FJjo8r032665@repo.freebsd.org> X-Authentication-Warning: repo.freebsd.org: cem set sender to cem@FreeBSD.org using -f From: Conrad Meyer Date: Sat, 15 Aug 2020 19:45:50 +0000 (UTC) To: src-committers@freebsd.org, svn-src-all@freebsd.org, svn-src-head@freebsd.org Subject: svn commit: r364261 - head/sys/kern X-SVN-Group: head X-SVN-Commit-Author: cem X-SVN-Commit-Paths: head/sys/kern X-SVN-Commit-Revision: 364261 X-SVN-Commit-Repository: base MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit X-BeenThere: svn-src-head@freebsd.org X-Mailman-Version: 2.1.33 Precedence: list List-Id: SVN commit messages for the src tree for head/-current List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , X-List-Received-Date: Sat, 15 Aug 2020 19:45:50 -0000 Author: cem Date: Sat Aug 15 19:45:50 2020 New Revision: 364261 URL: https://svnweb.freebsd.org/changeset/base/364261 Log: witness(4): Print stack of prior observed lock order on reversal The first time Witness observes a lock order between two locks, it records the caller's stack. On detected reversal, print out that previous observed stack. It is quite possible that the reported "LOR" is the correct ordering, and the violation was the observed earlier ordering. Reviewed by: mjg Differential Revision: https://reviews.freebsd.org/D26070 Modified: head/sys/kern/subr_witness.c Modified: head/sys/kern/subr_witness.c ============================================================================== --- head/sys/kern/subr_witness.c Sat Aug 15 18:46:26 2020 (r364260) +++ head/sys/kern/subr_witness.c Sat Aug 15 19:45:50 2020 (r364261) @@ -338,6 +338,7 @@ static void witness_ddb_display_list(int(*prnt)(const static void witness_ddb_level_descendants(struct witness *parent, int l); static void witness_ddb_list(struct thread *td); #endif +static void witness_enter_debugger(const char *msg); static void witness_debugger(int cond, const char *msg); static void witness_free(struct witness *m); static struct witness *witness_get(void); @@ -358,6 +359,8 @@ static struct witness_lock_order_data *witness_lock_or static void witness_list_lock(struct lock_instance *instance, int (*prnt)(const char *fmt, ...)); static int witness_output(const char *fmt, ...) __printflike(1, 2); +static int witness_output_drain(void *arg __unused, const char *data, + int len); static int witness_voutput(const char *fmt, va_list ap) __printflike(1, 0); static void witness_setflag(struct lock_object *lock, int flag, int set); @@ -1281,6 +1284,8 @@ witness_checkorder(struct lock_object *lock, int flags for (j = 0, lle = lock_list; lle != NULL; lle = lle->ll_next) { for (i = lle->ll_count - 1; i >= 0; i--, j++) { + struct stack pstack; + bool pstackv, trace; MPASS(j < LOCK_CHILDCOUNT * LOCK_NCHILDREN); lock1 = &lle->ll_children[i]; @@ -1367,6 +1372,19 @@ witness_checkorder(struct lock_object *lock, int flags */ if (blessed(w, w1)) goto out; + + trace = atomic_load_int(&witness_trace); + if (trace) { + struct witness_lock_order_data *data; + + pstackv = false; + data = witness_lock_order_get(w, w1); + if (data != NULL) { + stack_copy(&data->wlod_stack, + &pstack); + pstackv = true; + } + } mtx_unlock_spin(&w_mtx); #ifdef WITNESS_NO_VNODE @@ -1413,28 +1431,60 @@ witness_checkorder(struct lock_object *lock, int flags i--; } while (i >= 0); if (i < 0) { - witness_output(" 1st %p %s (%s) @ %s:%d\n", + witness_output(" 1st %p %s (%s, %s) @ %s:%d\n", lock1->li_lock, lock1->li_lock->lo_name, - w1->w_name, fixup_filename(lock1->li_file), + w1->w_name, w1->w_class->lc_name, + fixup_filename(lock1->li_file), lock1->li_line); - witness_output(" 2nd %p %s (%s) @ %s:%d\n", lock, - lock->lo_name, w->w_name, - fixup_filename(file), line); + witness_output(" 2nd %p %s (%s, %s) @ %s:%d\n", + lock, lock->lo_name, w->w_name, + w->w_class->lc_name, fixup_filename(file), + line); } else { - witness_output(" 1st %p %s (%s) @ %s:%d\n", + struct witness *w2 = lock2->li_lock->lo_witness; + + witness_output(" 1st %p %s (%s, %s) @ %s:%d\n", lock2->li_lock, lock2->li_lock->lo_name, - lock2->li_lock->lo_witness->w_name, + w2->w_name, w2->w_class->lc_name, fixup_filename(lock2->li_file), lock2->li_line); - witness_output(" 2nd %p %s (%s) @ %s:%d\n", + witness_output(" 2nd %p %s (%s, %s) @ %s:%d\n", lock1->li_lock, lock1->li_lock->lo_name, - w1->w_name, fixup_filename(lock1->li_file), + w1->w_name, w1->w_class->lc_name, + fixup_filename(lock1->li_file), lock1->li_line); - witness_output(" 3rd %p %s (%s) @ %s:%d\n", lock, + witness_output(" 3rd %p %s (%s, %s) @ %s:%d\n", lock, lock->lo_name, w->w_name, - fixup_filename(file), line); + w->w_class->lc_name, fixup_filename(file), + line); } - witness_debugger(1, __func__); + if (trace) { + char buf[64]; + struct sbuf sb; + + sbuf_new(&sb, buf, sizeof(buf), SBUF_FIXEDLEN); + sbuf_set_drain(&sb, witness_output_drain, + NULL); + + if (pstackv) { + sbuf_printf(&sb, + "lock order %s -> %s established at:\n", + w->w_name, w1->w_name); + stack_sbuf_print_flags(&sb, &pstack, + M_NOWAIT, STACK_SBUF_FMT_LONG); + } + + sbuf_printf(&sb, + "lock order %s -> %s attempted at:\n", + w1->w_name, w->w_name); + stack_save(&pstack); + stack_sbuf_print_flags(&sb, &pstack, M_NOWAIT, + STACK_SBUF_FMT_LONG); + + sbuf_finish(&sb); + sbuf_delete(&sb); + } + witness_enter_debugger(__func__); return; } } @@ -3085,6 +3135,12 @@ witness_debugger(int cond, const char *msg) sbuf_finish(&sb); } + witness_enter_debugger(msg); +} + +static void +witness_enter_debugger(const char *msg) +{ #ifdef KDB if (witness_kdb) kdb_enter(KDB_WHY_WITNESS, msg);