From owner-freebsd-hackers@FreeBSD.ORG Tue Feb 8 00:12:49 2011 Return-Path: Delivered-To: freebsd-hackers@freebsd.org Received: from mx1.freebsd.org (mx1.freebsd.org [IPv6:2001:4f8:fff6::34]) by hub.freebsd.org (Postfix) with ESMTP id EC65A106564A for ; Tue, 8 Feb 2011 00:12:49 +0000 (UTC) (envelope-from dieterbsd@engineer.com) Received: from imr-ma03.mx.aol.com (imr-ma03.mx.aol.com [64.12.206.41]) by mx1.freebsd.org (Postfix) with ESMTP id AAA0B8FC1A for ; Tue, 8 Feb 2011 00:12:49 +0000 (UTC) Received: from imo-da02.mx.aol.com (imo-da02.mx.aol.com [205.188.169.200]) by imr-ma03.mx.aol.com (8.14.1/8.14.1) with ESMTP id p180CZPt008917; Mon, 7 Feb 2011 19:12:35 -0500 Received: from dieterbsd@engineer.com by imo-da02.mx.aol.com (mail_out_v42.9.) id n.f24.5b79d0c (45072); Mon, 7 Feb 2011 19:12:29 -0500 (EST) Received: from smtprly-mc03.mx.aol.com (smtprly-mc03.mx.aol.com [64.12.95.99]) by cia-mc02.mx.aol.com (v129.8) with ESMTP id MAILCIAMC024-d3de4d508a6621c; Mon, 07 Feb 2011 19:12:29 -0500 Received: from web-mmc-m02 (web-mmc-m02.sim.aol.com [64.12.224.135]) by smtprly-mc03.mx.aol.com (v129.8) with ESMTP id MAILSMTPRLYMC038-d3de4d508a6621c; Mon, 07 Feb 2011 19:12:22 -0500 To: freebsd-hackers@freebsd.org Content-Transfer-Encoding: quoted-printable Date: Mon, 07 Feb 2011 19:12:22 -0500 X-AOL-IP: 67.206.164.141 X-MB-Message-Source: WebUI Received: from 67.206.164.141 by web-mmc-m02.sysops.aol.com (64.12.224.135) with HTTP (WebMailUI); Mon, 07 Feb 2011 19:12:22 -0500 MIME-Version: 1.0 From: dieterbsd@engineer.com X-MB-Message-Type: User Content-Type: text/plain; charset="us-ascii"; format=flowed X-Mailer: Mail.com Webmail 33189-STANDARD Message-Id: <8CD953BFE2324E5-1B10-A8CE@web-mmc-m02.sysops.aol.com> X-Spam-Flag: NO X-AOL-SENDER: dieterbsd@engineer.com Cc: Subject: witness Re: Why does printf(9) hang network? X-BeenThere: freebsd-hackers@freebsd.org X-Mailman-Version: 2.1.5 Precedence: list List-Id: Technical Discussions relating to FreeBSD List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , X-List-Received-Date: Tue, 08 Feb 2011 00:12:50 -0000 I received a suggestion to try witness, so I build a kernel with WITNESS, WITNESS_KDB, KDB, DDB, KDB_TRACE, and DDB_NUMSYM. This is my first attempt to use witness, so if I got something wrong let me know. Didn't quite make it all the way up to a multiuser prompt: Starting syslogd. Starting rpcbind. lock order reversal: 1st 0xffffff8029549320 bufwait (bufwait) @=20 /usr/src/sys/kern/vfs_bio.c:2559 2nd 0xffffff000498b000 dirhash (dirhash) @=20 /usr/src/sys/ufs/ufs/ufs_dirhash.c:2 85 KDB: stack backtrace: db_trace_self_wrapper() at 0xffffffff801dab0a =3D=20 db_trace_self_wrapper+0x2a _witness_debugger() at 0xffffffff805a144c =3D _witness_debugger+0x2c witness_checkorder() at 0xffffffff805a24af =3D witness_checkorder+0x66f _sx_xlock() at 0xffffffff8056b6d4 =3D _sx_xlock+0x34 ufsdirhash_acquire() at 0xffffffff8076f833 =3D ufsdirhash_acquire+0x33 ufsdirhash_add() at 0xffffffff8076fd99 =3D ufsdirhash_add+0x19 ufs_direnter() at 0xffffffff80772498 =3D ufs_direnter+0x848 ufs_mkdir() at 0xffffffff807783d6 =3D ufs_mkdir+0x5e6 VOP_MKDIR_APV() at 0xffffffff808650d4 =3D VOP_MKDIR_APV+0x34 kern_mkdirat() at 0xffffffff805eb740 =3D kern_mkdirat+0x270 syscall() at 0xffffffff8081ec5e =3D syscall+0x19e Xfast_syscall() at 0xffffffff80806ab1 =3D Xfast_syscall+0xe1 --- syscall (136, FreeBSD ELF64, mkdir), rip =3D 0x80072c53c, rsp =3D=20 0x7fffffffec88 , rbp =3D 0x7fffffffef66 --- KDB: enter: witness_checkorder [thread pid 1255 tid 100076 ] Stopped at 0xffffffff8059083d =3D kdb_enter+0x3d: movq =20 $0,0x6508a0(%rip ) db> Managed to reboot to single user mode, changed /boot/kernel back to my production kernel, and got another lock order reversal rebooting: # sync # reboot Waiting (max 60 seconds) for system process `vnlru' to stop...done Waiting (max 60 seconds) for system process `bufdaemon' to stop...done Waiting (max 60 seconds) for system process `syncer' to stop... Syncing disks, vnodes remaining...0 done All buffers synced. lock order reversal: 1st 0xffffff0004831448 ufs (ufs) @ /usr/src/sys/kern/vfs_mount.c:1200 2nd 0xffffff0004831d80 devfs (devfs) @=20 /usr/src/sys/kern/vfs_subr.c:2083 KDB: stack backtrace: db_trace_self_wrapper() at 0xffffffff801dab0a =3D=20 db_trace_self_wrapper+0x2a _witness_debugger() at 0xffffffff805a144c =3D _witness_debugger+0x2c witness_checkorder() at 0xffffffff805a24af =3D witness_checkorder+0x66f __lockmgr_args() at 0xffffffff80552054 =3D __lockmgr_args+0xd04 vop_stdlock() at 0xffffffff805d9239 =3D vop_stdlock+0x39 VOP_LOCK1_APV() at 0xffffffff80864f56 =3D VOP_LOCK1_APV+0x46 _vn_lock() at 0xffffffff805f3cc7 =3D _vn_lock+0x47 vget() at 0xffffffff805e8856 =3D vget+0x56 devfs_allocv() at 0xffffffff804fa993 =3D devfs_allocv+0x103 devfs_root() at 0xffffffff804f9268 =3D devfs_root+0x48 dounmount() at 0xffffffff805e3369 =3D dounmount+0x419 vfs_unmountall() at 0xffffffff805e82a2 =3D vfs_unmountall+0x42 boot() at 0xffffffff80564bd3 =3D boot+0x683 reboot() at 0xffffffff80564ef8 =3D reboot+0x68 syscall() at 0xffffffff8081ec5e =3D syscall+0x19e Xfast_syscall() at 0xffffffff80806ab1 =3D Xfast_syscall+0xe1 --- syscall (55, FreeBSD ELF64, reboot), rip =3D 0x80078f83c, rsp =3D=20 0x7fffffffece8 , rbp =3D 0 --- KDB: enter: witness_checkorder [thread pid 35 tid 100073 ] Stopped at 0xffffffff8059083d =3D kdb_enter+0x3d: movq =20 $0,0x6508a0(%rip ) db> lock order reversal: 1st 0xffffff0004831da8 vnode interlock (vnode interlock) @=20 /usr/src/sys/fs/devf s/devfs_vnops.c:349 2nd 0xffffff8000248858 firewire (firewire) @=20 /usr/src/sys/dev/firewire/fwohci.c :2227 KDB: stack backtrace: db_trace_self_wrapper() at 0xffffffff801dab0a =3D=20 db_trace_self_wrapper+0x2a _witness_debugger() at 0xffffffff805a144c =3D _witness_debugger+0x2c witness_checkorder() at 0xffffffff805a24af =3D witness_checkorder+0x66f _mtx_lock_flags() at 0xffffffff80557b52 =3D _mtx_lock_flags+0x32 fwohci_poll() at 0xffffffff8035feb1 =3D fwohci_poll+0x31 dcons_cngetc() at 0xffffffff80303d69 =3D dcons_cngetc+0x59 cncheckc() at 0xffffffff8052d425 =3D cncheckc+0x65 cngetc() at 0xffffffff8052d44c =3D cngetc+0x1c db_readline() at 0xffffffff801d9ef7 =3D db_readline+0x77 db_read_line() at 0xffffffff801da975 =3D db_read_line+0x15 db_command_loop() at 0xffffffff801d8ad8 =3D db_command_loop+0x38 db_trap() at 0xffffffff801daa49 =3D db_trap+0x89 kdb_trap() at 0xffffffff80590665 =3D kdb_trap+0x95 trap() at 0xffffffff8081f200 =3D trap+0x170 calltrap() at 0xffffffff808067d3 =3D calltrap+0x8 --- trap 0x3, rip =3D 0xffffffff8059083d, rsp =3D 0xffffff80405d9710, rbp= =3D=20 0xffffff 80405d9730 --- kdb_enter() at 0xffffffff8059083d =3D kdb_enter+0x3d witness_checkorder() at 0xffffffff805a24af =3D witness_checkorder+0x66f __lockmgr_args() at 0xffffffff80552054 =3D __lockmgr_args+0xd04 vop_stdlock() at 0xffffffff805d9239 =3D vop_stdlock+0x39 VOP_LOCK1_APV() at 0xffffffff80864f56 =3D VOP_LOCK1_APV+0x46 _vn_lock() at 0xffffffff805f3cc7 =3D _vn_lock+0x47 vget() at 0xffffffff805e8856 =3D vget+0x56 devfs_allocv() at 0xffffffff804fa993 =3D devfs_allocv+0x103 devfs_root() at 0xffffffff804f9268 =3D devfs_root+0x48 dounmount() at 0xffffffff805e3369 =3D dounmount+0x419 vfs_unmountall() at 0xffffffff805e82a2 =3D vfs_unmountall+0x42 boot() at 0xffffffff80564bd3 =3D boot+0x683 reboot() at 0xffffffff80564ef8 =3D reboot+0x68 syscall() at 0xffffffff8081ec5e =3D syscall+0x19e Xfast_syscall() at 0xffffffff80806ab1 =3D Xfast_syscall+0xe1 --- syscall (55, FreeBSD ELF64, reboot), rip =3D 0x80078f83c, rsp =3D=20 0x7fffffffece8 , rbp =3D 0 ---