From nobody@FreeBSD.org Mon Feb 11 10:42:56 2008 Return-Path: Received: from mx1.freebsd.org (mx1.freebsd.org [IPv6:2001:4f8:fff6::34]) by hub.freebsd.org (Postfix) with ESMTP id 2218316A419 for ; Mon, 11 Feb 2008 10:42:56 +0000 (UTC) (envelope-from nobody@FreeBSD.org) Received: from www.freebsd.org (www.freebsd.org [IPv6:2001:4f8:fff6::21]) by mx1.freebsd.org (Postfix) with ESMTP id 08D8613C457 for ; Mon, 11 Feb 2008 10:42:56 +0000 (UTC) (envelope-from nobody@FreeBSD.org) Received: from www.freebsd.org (localhost [127.0.0.1]) by www.freebsd.org (8.14.2/8.14.2) with ESMTP id m1BAegU1099693 for ; Mon, 11 Feb 2008 10:40:42 GMT (envelope-from nobody@www.freebsd.org) Received: (from nobody@localhost) by www.freebsd.org (8.14.2/8.14.1/Submit) id m1BAegMv099692; Mon, 11 Feb 2008 10:40:42 GMT (envelope-from nobody) Message-Id: <200802111040.m1BAegMv099692@www.freebsd.org> Date: Mon, 11 Feb 2008 10:40:42 GMT From: Henri Hennebert To: freebsd-gnats-submit@FreeBSD.org Subject: LOR opensolaris_vfs.c:206 and kern_resource.c:1273 - 7.0-RC2 X-Send-Pr-Version: www-3.1 X-GNATS-Notify: >Number: 120529 >Category: kern >Synopsis: [zfs] [lor] LOR opensolaris_vfs.c:206 and kern_resource.c:1273 - 7.0-RC2 >Confidential: no >Severity: non-critical >Priority: medium >Responsible: pjd >State: closed >Quarter: >Keywords: >Date-Required: >Class: sw-bug >Submitter-Id: current-users >Arrival-Date: Mon Feb 11 10:50:01 UTC 2008 >Closed-Date: Sat Mar 08 00:46:19 UTC 2008 >Last-Modified: Sun Feb 15 19:05:30 UTC 2009 >Originator: Henri Hennebert >Release: FreeBSD 7.0-RC2 >Organization: >Environment: FreeBSD morzine.restart.bel 7.0-RC2 FreeBSD 7.0-RC2 #0: Thu Feb 7 19:39:23 CET 2008 root@morzine.restart.bel:/usr/obj/usr/src/sys/MORZINE i386 >Description: During heavy io activity between 4 zpools -- one on a usb disk -- I get in log/messages: At Feb 10 12:23:26 lock order reversal: 1st 0xa8157804 struct mount mtx (struct mount mtx) @ /usr/src/sys/modules/zfs/../../compat/opensolaris/kern/opensolaris_vfs.c:206 2nd 0xa54f0010 sleep mtxpool (sleep mtxpool) @ /usr/src/sys/kern/kern_resource.c:1273 KDB: stack backtrace: db_trace_self_wrapper(a07d3fd1,f9b3773c,a05ca405,a07d5389,a54f0010,...) at db_trace_self_wrapper+0x26 kdb_backtrace(a07d5389,a54f0010,a07d135c,a07d135c,a07d1914,...) at kdb_backtrace+0x29 witness_checkorder(a54f0010,9,a07d1914,4f9,38,...) at witness_checkorder+0x5e5 _mtx_lock_flags(a54f0010,0,a07d1914,4f9,a8232a00,...) at _mtx_lock_flags+0x34 uifree(a5522020,adfbdbb0,a81577d4,f9b377d8,a098cebf,...) at uifree+0x2d crfree(a8232a00,0,a0a049bc,ce,c2,...) at crfree+0x27 domount(a822e880,adfbdbb0,a0a09ae1,ac7a5b20,f9b37814,...) at domount+0x1ff zfsctl_snapdir_lookup(f9b37aa0,f9b37a58,2,a8aeb770,f9b37ac0,...) at zfsctl_snapdir_lookup+0x362 VOP_LOOKUP_APV(a0a0daa0,f9b37aa0,a822e880,a07d9b3e,19b,...) at VOP_LOOKUP_APV+0x46 lookup(f9b37ba8,a07d9b3e,c6,bf,a691602c,...) at lookup+0x57e namei(f9b37ba8,2,281d5000,a058de02,a085d434,...) at namei+0x2bb kern_stat(a822e880,282226c4,0,f9b37c18,a07e7092,...) at kern_stat+0x3d stat(a822e880,f9b37cfc,8,a822e880,a080c060,...) at stat+0x2f syscall(f9b37d38) at syscall+0x2b3 Xint0x80_syscall() at Xint0x80_syscall+0x20 --- syscall (188, FreeBSD ELF32, stat), eip = 0x281b632b, esp = 0x9fbfe8ec, ebp = 0x9fbfe9f8 --- uma_zalloc_arg: zone "256" with the following non-sleepable locks held: exclusive sleep mutex struct mount mtx r = 0 (0xa8157804) locked @ /usr/src/sys/modules/zfs/../../compat/opensolaris/kern/opensolaris_vfs.c:206 KDB: stack backtrace: db_trace_self_wrapper(a07d3fd1,f9b376ec,a05ca76d,a07d4342,f9b37700,...) at db_trace_self_wrapper+0x26 kdb_backtrace(a07d4342,f9b37700,4,1,0,...) at kdb_backtrace+0x29 witness_warn(5,0,a07ea73d,a07e6167,a822e880,...) at witness_warn+0x1cd uma_zalloc_arg(a18671e0,0,102,a81577d4,adfbdbb0,...) at uma_zalloc_arg+0x34 malloc(a0,a0811ba0,102,a81577d4,f9b37794,...) at malloc+0x51 crget(a8232a00,a0811ba0,a81577d4,f9b377d8,a098cecc,...) at crget+0x23 crdup(a5520700,0,a0a049bc,ce,c2,...) at crdup+0xc domount(a822e880,adfbdbb0,a0a09ae1,ac7a5b20,f9b37814,...) at domount+0x20c zfsctl_snapdir_lookup(f9b37aa0,f9b37a58,2,a8aeb770,f9b37ac0,...) at zfsctl_snapdir_lookup+0x362 VOP_LOOKUP_APV(a0a0daa0,f9b37aa0,a822e880,a07d9b3e,19b,...) at VOP_LOOKUP_APV+0x46 lookup(f9b37ba8,a07d9b3e,c6,bf,a691602c,...) at lookup+0x57e namei(f9b37ba8,2,281d5000,a058de02,a085d434,...) at namei+0x2bb kern_stat(a822e880,282226c4,0,f9b37c18,a07e7092,...) at kern_stat+0x3d stat(a822e880,f9b37cfc,8,a822e880,a080c060,...) at stat+0x2f syscall(f9b37d38) at syscall+0x2b3 Xint0x80_syscall() at Xint0x80_syscall+0x20 --- syscall (188, FreeBSD ELF32, stat), eip = 0x281b632b, esp = 0x9fbfe8ec, ebp = 0x9fbfe9f8 --- At Feb 10 12:24:25 uma_zalloc_arg: zone "256" with the following non-sleepable locks held: exclusive sleep mutex struct mount mtx r = 0 (0xa815e804) locked @ /usr/src/sys/modules/zfs/../../compat/opensolaris/kern/opensolaris_vfs.c:206 KDB: stack backtrace: db_trace_self_wrapper(a07d3fd1,f9b376ec,a05ca76d,a07d4342,f9b37700,...) at db_trace_self_wrapper+0x26 kdb_backtrace(a07d4342,f9b37700,4,1,0,...) at kdb_backtrace+0x29 witness_warn(5,0,a07ea73d,a07e6167,a822e880,...) at witness_warn+0x1cd uma_zalloc_arg(a18671e0,0,102,a815e7d4,b39fe330,...) at uma_zalloc_arg+0x34 malloc(a0,a0811ba0,102,a815e7d4,f9b37794,...) at malloc+0x51 crget(a8021700,a0811ba0,a815e7d4,f9b377d8,a098cecc,...) at crget+0x23 crdup(a5520700,0,a0a049bc,ce,c2,...) at crdup+0xc domount(a822e880,b39fe330,a0a09ae1,ab5f08a0,f9b37814,...) at domount+0x20c zfsctl_snapdir_lookup(f9b37aa0,f9b37a58,2,b0a11aa0,f9b37ac0,...) at zfsctl_snapdir_lookup+0x362 VOP_LOOKUP_APV(a0a0daa0,f9b37aa0,a822e880,a07d9b3e,2a9,...) at VOP_LOOKUP_APV+0x46 lookup(f9b37ba8,a07d9b3e,c6,bf,a691602c,...) at lookup+0x57e namei(f9b37ba8,2,281d5000,a058de02,a085d434,...) at namei+0x2bb kern_stat(a822e880,282226c8,0,f9b37c18,a07e7092,...) at kern_stat+0x3d stat(a822e880,f9b37cfc,8,a822e880,a080c060,...) at stat+0x2f syscall(f9b37d38) at syscall+0x2b3 Xint0x80_syscall() at Xint0x80_syscall+0x20 --- syscall (188, FreeBSD ELF32, stat), eip = 0x281b632b, esp = 0x9fbfe8ec, ebp = 0x9fbfe9f8 --- At Feb 10 12:44:33 uma_zalloc_arg: zone "256" with the following non-sleepable locks held: exclusive sleep mutex struct mount mtx r = 0 (0xa75a22cc) locked @ /usr/src/sys/modules/zfs/../../compat/opensolaris/kern/opensolaris_vfs.c:206 KDB: stack backtrace: db_trace_self_wrapper(a07d3fd1,f9b376ec,a05ca76d,a07d4342,f9b37700,...) at db_trace_self_wrapper+0x26 kdb_backtrace(a07d4342,f9b37700,4,1,0,...) at kdb_backtrace+0x29 witness_warn(5,0,a07ea73d,a07e6167,a822e880,...) at witness_warn+0x1cd uma_zalloc_arg(a18671e0,0,102,a75a229c,ab89f440,...) at uma_zalloc_arg+0x34 malloc(a0,a0811ba0,102,a75a229c,f9b37794,...) at malloc+0x51 crget(a7a57b00,a0811ba0,a75a229c,f9b377d8,a098cecc,...) at crget+0x23 crdup(a5520700,0,a0a049bc,ce,c2,...) at crdup+0xc domount(a822e880,ab89f440,a0a09ae1,ac7a54e0,f9b37814,...) at domount+0x20c zfsctl_snapdir_lookup(f9b37aa0,f9b37a58,2,a81e7440,f9b37ac0,...) at zfsctl_snapdir_lookup+0x362 VOP_LOOKUP_APV(a0a0daa0,f9b37aa0,a822e880,a07d9b3e,2a9,...) at VOP_LOOKUP_APV+0x46 lookup(f9b37ba8,a07d9b3e,c6,bf,a691602c,...) at lookup+0x57e namei(f9b37ba8,2,281d5000,a058de02,a085d434,...) at namei+0x2bb kern_stat(a822e880,282226c8,0,f9b37c18,a07e7092,...) at kern_stat+0x3d stat(a822e880,f9b37cfc,8,a822e880,a080c060,...) at stat+0x2f syscall(f9b37d38) at syscall+0x2b3 Xint0x80_syscall() at Xint0x80_syscall+0x20 --- syscall (188, FreeBSD ELF32, stat), eip = 0x281b632b, esp = 0x9fbfe8ec, ebp = 0x9fbfe9f8 --- At Feb 10 12:45:59 uma_zalloc_arg: zone "256" with the following non-sleepable locks held: exclusive sleep mutex struct mount mtx r = 0 (0xa815e2cc) locked @ /usr/src/sys/modules/zfs/../../compat/opensolaris/kern/opensolaris_vfs.c:206 KDB: stack backtrace: db_trace_self_wrapper(a07d3fd1,f9b376ec,a05ca76d,a07d4342,f9b37700,...) at db_trace_self_wrapper+0x26 kdb_backtrace(a07d4342,f9b37700,4,1,0,...) at kdb_backtrace+0x29 witness_warn(5,0,a07ea73d,a07e6167,a822e880,...) at witness_warn+0x1cd uma_zalloc_arg(a18671e0,0,102,a815e29c,af419220,...) at uma_zalloc_arg+0x34 malloc(a0,a0811ba0,102,a815e29c,f9b37794,...) at malloc+0x51 crget(a7e4d400,a0811ba0,a815e29c,f9b377d8,a098cecc,...) at crget+0x23 crdup(a5520700,0,a0a049bc,ce,c2,...) at crdup+0xc domount(a822e880,af419220,a0a09ae1,ad8b6de0,f9b37814,...) at domount+0x20c zfsctl_snapdir_lookup(f9b37aa0,f9b37a58,2,aa178330,f9b37ac0,...) at zfsctl_snapdir_lookup+0x362 VOP_LOOKUP_APV(a0a0daa0,f9b37aa0,a822e880,a07d9b3e,2a9,...) at VOP_LOOKUP_APV+0x46 lookup(f9b37ba8,a07d9b3e,c6,bf,a691602c,...) at lookup+0x57e namei(f9b37ba8,2,281d5000,a058de02,a085d434,...) at namei+0x2bb kern_stat(a822e880,282226d0,0,f9b37c18,a07e7092,...) at kern_stat+0x3d stat(a822e880,f9b37cfc,8,a822e880,a080c060,...) at stat+0x2f syscall(f9b37d38) at syscall+0x2b3 Xint0x80_syscall() at Xint0x80_syscall+0x20 --- syscall (188, FreeBSD ELF32, stat), eip = 0x281b632b, esp = 0x9fbfe8ec, ebp = 0x9fbfe9f8 --- At Feb 10 13:10:03 uma_zalloc_arg: zone "256" with the following non-sleepable locks held: exclusive sleep mutex struct mount mtx r = 0 (0xa8157aa0) locked @ /usr/src/sys/modules/zfs/../../compat/opensolaris/kern/opensolaris_vfs.c:206 KDB: stack backtrace: db_trace_self_wrapper(a07d3fd1,f9b376ec,a05ca76d,a07d4342,f9b37700,...) at db_trace_self_wrapper+0x26 kdb_backtrace(a07d4342,f9b37700,4,1,0,...) at kdb_backtrace+0x29 witness_warn(5,0,a07ea73d,a07e6167,a822e880,...) at witness_warn+0x1cd uma_zalloc_arg(a18671e0,0,102,a8157a70,afc33dd0,...) at uma_zalloc_arg+0x34 malloc(a0,a0811ba0,102,a8157a70,f9b37794,...) at malloc+0x51 crget(a7a39700,a0811ba0,a8157a70,f9b377d8,a098cecc,...) at crget+0x23 crdup(a5520700,0,a0a049bc,ce,c2,...) at crdup+0xc domount(a822e880,afc33dd0,a0a09ae1,afb38060,f9b37814,...) at domount+0x20c zfsctl_snapdir_lookup(f9b37aa0,f9b37a58,2,ab2ee000,f9b37ac0,...) at zfsctl_snapdir_lookup+0x362 VOP_LOOKUP_APV(a0a0daa0,f9b37aa0,a822e880,a07d9b3e,2a9,...) at VOP_LOOKUP_APV+0x46 lookup(f9b37ba8,a07d9b3e,c6,bf,a691602c,...) at lookup+0x57e namei(f9b37ba8,2,281d5000,a058de02,a085d434,...) at namei+0x2bb kern_stat(a822e880,282226c8,0,f9b37c18,a07e7092,...) at kern_stat+0x3d stat(a822e880,f9b37cfc,8,a822e880,a080c060,...) at stat+0x2f syscall(f9b37d38) at syscall+0x2b3 Xint0x80_syscall() at Xint0x80_syscall+0x20 --- syscall (188, FreeBSD ELF32, stat), eip = 0x281b632b, esp = 0x9fbfe8ec, ebp = 0x9fbfe9f8 --- >How-To-Repeat: I believe with heavy io activities... >Fix: >Release-Note: >Audit-Trail: From: Henri Hennebert To: bug-followup@FreeBSD.org, hlh@restart.be Cc: Subject: Re: kern/120529: LOR opensolaris_vfs.c:206 and kern_resource.c:1273 - 7.0-RC2 Date: Wed, 20 Feb 2008 14:34:26 +0100 I encounter later a problem maybe related: zfs snapshot pool0@snap1 zfs list NAME USED AVAIL REFER MOUNTPOINT pool0 13.8G 32.7G 16.5M legacy pool0@snap1 41K - 16.5M - pool0/home 1.57G 32.7G 1.57G /home <--- clip---> ls /.zfs/snapshot/snap1 error message complaining about snapshot (sorry I don't write it down :-/ ) - anyway, the snapshot is not accessible. In /var/log/messages I have: uma_zalloc_arg: zone "256" with the following non-sleepable locks held: exclusive sleep mutex struct mount mtx r = 0 (0xa815eaa0) locked @ /usr/src/sys/modules/zfs/../../compat/opensolaris/kern/opensolaris_vfs.c:206 KDB: stack backtrace: db_trace_self_wrapper(a07d3fd1,f96df6ec,a05ca76d,a07d4342,f96df700,...) at db_trace_self_wrapper+0x26 kdb_backtrace(a07d4342,f96df700,4,1,0,...) at kdb_backtrace+0x29 witness_warn(5,0,a07ea73d,a07e6167,a61b9000,...) at witness_warn+0x1cd uma_zalloc_arg(a18671e0,0,102,a815ea70,aa840bb0,...) at uma_zalloc_arg+0x34 malloc(a0,a0811ba0,102,a815ea70,f96df794,...) at malloc+0x51 crget(a8da9300,a0811ba0,a815ea70,f96df7d8,a098cecc,...) at crget+0x23 crdup(a5520700,0,a0a049bc,ce,c2,...) at crdup+0xc domount(a61b9000,aa840bb0,a0a09ae1,a6c5edc0,f96df814,...) at domount+0x20c zfsctl_snapdir_lookup(f96dfaa0,f96dfa58,2,b111acc0,f96dfac0,...) at zfsctl_snapdir_lookup+0x362 VOP_LOOKUP_APV(a0a0daa0,f96dfaa0,a61b9000,a07d9b3e,19b,...) at VOP_LOOKUP_APV+0x46 lookup(f96dfb48,a07d9b3e,c6,bf,a99db82c,...) at lookup+0x57e namei(f96dfb48,a61b9000,a085d434,a61b9000,f96dfb4c,...) at namei+0x2bb kern_lstat(a61b9000,2821c268,0,f96dfc18,a07e7092,...) at kern_lstat+0x4f lstat(a61b9000,f96dfcfc,8,a07d5fca,a080c090,...) at lstat+0x2f syscall(f96dfd38) at syscall+0x2b3 Xint0x80_syscall() at Xint0x80_syscall+0x20 --- syscall (190, FreeBSD ELF32, lstat), eip = 0x281a230b, esp = 0x9fbfe55c, ebp = 0x9fbfe5e8 --- uma_zalloc_arg: zone "256" with the following non-sleepable locks held: exclusive sleep mutex struct mount mtx r = 0 (0xa815e2cc) locked @ /usr/src/sys/modules/zfs/../../compat/opensolaris/kern/opensolaris_vfs.c:206 KDB: stack backtrace: db_trace_self_wrapper(a07d3fd1,f99ae6ec,a05ca76d,a07d4342,f99ae700,...) at db_trace_self_wrapper+0x26 kdb_backtrace(a07d4342,f99ae700,4,1,0,...) at kdb_backtrace+0x29 witness_warn(5,0,a07ea73d,a07e6167,a65cfcc0,...) at witness_warn+0x1cd uma_zalloc_arg(a18671e0,0,102,a815e29c,aea94cc0,...) at uma_zalloc_arg+0x34 malloc(a0,a0811ba0,102,a815e29c,f99ae794,...) at malloc+0x51 crget(a714f500,a0811ba0,a815e29c,f99ae7d8,a098cecc,...) at crget+0x23 crdup(a5520700,0,a0a049bc,ce,c2,...) at crdup+0xc domount(a65cfcc0,aea94cc0,a0a09ae1,ae11acc0,f99ae814,...) at domount+0x20c zfsctl_snapdir_lookup(f99aeaa0,f99aea58,2,b039c660,f99aeac0,...) at zfsctl_snapdir_lookup+0x362 VOP_LOOKUP_APV(a0a0daa0,f99aeaa0,a65cfcc0,a07d9b3e,2a9,...) at VOP_LOOKUP_APV+0x46 lookup(f99aeb48,a07d9b3e,c6,bf,a668b12c,...) at lookup+0x57e namei(f99aeb48,f99aeb50,a058debd,a085d434,8,...) at namei+0x2bb kern_lstat(a65cfcc0,28453ca0,0,f99aec18,a07e7092,...) at kern_lstat+0x4f lstat(a65cfcc0,f99aecfc,8,a07d679d,a080c090,...) at lstat+0x2f syscall(f99aed38) at syscall+0x2b3 Xint0x80_syscall() at Xint0x80_syscall+0x20 --- syscall (190, FreeBSD ELF32, lstat), eip = 0x2831230b, esp = 0x9fbfe9ac, ebp = 0x9fbfea38 --- uma_zalloc_arg: zone "256" with the following non-sleepable locks held: exclusive sleep mutex struct mount mtx r = 0 (0xa815eaa0) locked @ /usr/src/sys/modules/zfs/../../compat/opensolaris/kern/opensolaris_vfs.c:206 KDB: stack backtrace: db_trace_self_wrapper(a07d3fd1,f99ae6ec,a05ca76d,a07d4342,f99ae700,...) at db_trace_self_wrapper+0x26 kdb_backtrace(a07d4342,f99ae700,4,1,0,...) at kdb_backtrace+0x29 witness_warn(5,0,a07ea73d,a07e6167,a65cfcc0,...) at witness_warn+0x1cd uma_zalloc_arg(a18671e0,0,102,a815ea70,aca7e990,...) at uma_zalloc_arg+0x34 malloc(a0,a0811ba0,102,a815ea70,f99ae794,...) at malloc+0x51 crget(a9186800,a0811ba0,a815ea70,f99ae7d8,a098cecc,...) at crget+0x23 crdup(a5520700,0,a0a049bc,ce,c2,...) at crdup+0xc domount(a65cfcc0,aca7e990,a0a09ae1,adf54260,f99ae814,...) at domount+0x20c zfsctl_snapdir_lookup(f99aeaa0,f99aea58,2,af0eb660,f99aeac0,...) at zfsctl_snapdir_lookup+0x362 VOP_LOOKUP_APV(a0a0daa0,f99aeaa0,a65cfcc0,a07d9b3e,2a9,...) at VOP_LOOKUP_APV+0x46 lookup(f99aeb48,a07d9b3e,c6,bf,a668b12c,...) at lookup+0x57e namei(f99aeb48,f99aeb50,a058debd,a085d434,8,...) at namei+0x2bb kern_lstat(a65cfcc0,28453c80,0,f99aec18,a07e7092,...) at kern_lstat+0x4f lstat(a65cfcc0,f99aecfc,8,a07d679d,a080c090,...) at lstat+0x2f syscall(f99aed38) at syscall+0x2b3 Xint0x80_syscall() at Xint0x80_syscall+0x20 --- syscall (190, FreeBSD ELF32, lstat), eip = 0x2831230b, esp = 0x9fbfe9ac, ebp = 0x9fbfea38 --- Henri Responsible-Changed-From-To: freebsd-bugs->pjd Responsible-Changed-By: rwatson Responsible-Changed-When: Fri Mar 7 18:23:32 UTC 2008 Responsible-Changed-Why: Over to ZFS maintainer. http://www.freebsd.org/cgi/query-pr.cgi?pr=120529 State-Changed-From-To: open->closed State-Changed-By: pjd State-Changed-When: sob 8 mar 00:45:28 2008 UTC State-Changed-Why: This bug was fixed long time ago in HEAD, but the fix is not yet MFCed. http://www.freebsd.org/cgi/query-pr.cgi?pr=120529 >Unformatted: