Date: Sat, 1 Aug 2009 17:53:01 +0300 From: Kostik Belousov <kostikbel@gmail.com> To: Thomas Backman <serenity@exscape.org> Cc: freebsd-fs@freebsd.org, FreeBSD current <freebsd-current@freebsd.org> Subject: Re: Samba + ZFS panic w/ DEBUG_VFS_LOCKS Message-ID: <20090801145301.GE1884@deviant.kiev.zoral.com.ua> In-Reply-To: <4B49A2A0-2437-48A4-9047-80267BD4148F@exscape.org> References: <4B49A2A0-2437-48A4-9047-80267BD4148F@exscape.org>
next in thread | previous in thread | raw e-mail | index | archive | help
--JoaBr9Q1T6GV3lOg
Content-Type: text/plain; charset=us-ascii
Content-Disposition: inline
Content-Transfer-Encoding: quoted-printable
On Sat, Aug 01, 2009 at 12:57:29PM +0200, Thomas Backman wrote:
> I just installed samba (ports/net/samba3) on my test machine to see if =
=20
> some simple media streaming from ZFS would work. It did not; smbd =20
> didn't even start before it panicked... At "Starting smdb" I got the =20
> following panic:
>=20
> (Note: I haven't tried without DEBUG_VFS_LOCKS yet. I do suppose that =20
> it's not supposed to panic even with rigorous debugging enabled, =20
> though!)
>=20
> Unread portion of the kernel message buffer:
> KDB: stack backtrace:
> db_trace_self_wrapper() at db_trace_self_wrapper+0x2a
> vfs_badlock() at vfs_badlock+0x95
> assert_vop_elocked() at assert_vop_elocked+0x64
> VOP_PUTPAGES_APV() at VOP_PUTPAGES_APV+0x5b
> vnode_pager_putpages() at vnode_pager_putpages+0xa9
> vm_pageout_flush() at vm_pageout_flush+0xd1
> vm_object_page_collect_flush() at vm_object_page_collect_flush+0x2f0
> vm_object_page_clean() at vm_object_page_clean+0x143
> fsync() at fsync+0x121
> syscall() at syscall+0x28f
> Xfast_syscall() at Xfast_syscall+0xe1
> --- syscall (95, FreeBSD ELF64, fsync), rip =3D 0x801064dac, rsp =3D =20
> 0x7fffffffe5d8, rbp =3D 0x801336480 ---
> VOP_PUTPAGES: 0xffffff0007649588 is not exclusive locked but should be
> KDB: enter: lock violation
>=20
> 0xffffff0007649588: tag zfs, type VREG
> usecount 2, writecount 1, refcount 3 mountedhere 0
> flags (VI_OBJDIRTY)
> v_object 0xffffff000ee6c000 ref 1 pages 2
> lock type zfs: SHARED (count 1)
> panic: from debugger
> cpuid =3D 0
> KDB: stack backtrace:
> Uptime: 17h10m52s
> Physical memory: 2034 MB
> Dumping 1723 MB: ...
>=20
> at /usr/src/sys/amd64/amd64/trap.c:613
> #9 0xffffffff8057eda7 in calltrap ()
> at /usr/src/sys/amd64/amd64/exception.S:224
> #10 0xffffffff8036c8ad in kdb_enter (why=3D0xffffffff80613fd5 "vfslock",
> msg=3D0xa <Address 0xa out of bounds>) at cpufunc.h:63
> #11 0xffffffff803cb3a4 in assert_vop_elocked (vp=3D0xffffff0007649588,
> str=3D0xffffffff80642728 "VOP_PUTPAGES")
> at /usr/src/sys/kern/vfs_subr.c:3722
> #12 0xffffffff805c80eb in VOP_PUTPAGES_APV (vop=3D0xffffffff807a07c0, =
=20
> a=3D0xffffff803eb72730) at vnode_if.c:2664
> #13 0xffffffff80572cd9 in vnode_pager_putpages =20
> (object=3D0xffffff000ee6c000,
> m=3D0xffffff803eb72830, count=3D8192, sync=3D12, =20
> rtvals=3D0xffffff803eb727a0)
> at vnode_if.h:1169
> #14 0xffffffff8056d601 in vm_pageout_flush (mc=3D0xffffff803eb72830, =20
> count=3D2,
> flags=3D12) at vm_pager.h:148
> #15 0xffffffff80568e30 in vm_object_page_collect_flush (
> object=3D0xffffff000ee6c000, p=3DVariable "p" is not available.
> ) at /usr/src/sys/vm/vm_object.c:1032
> #16 0xffffffff80569023 in vm_object_page_clean =20
> (object=3D0xffffff000ee6c000,
> start=3D0, end=3DVariable "end" is not available.
> ) at /usr/src/sys/vm/vm_object.c:844
> #17 0xffffffff803d3bd1 in fsync (td=3D0xffffff0027f45000, uap=3DVariable =
=20
> "uap" is not available.
> )
> at /usr/src/sys/kern/vfs_syscalls.c:3519#18 0xffffffff80598e7f in =20
> syscall (frame=3D0xffffff803eb72c80) at /usr/src/sys/amd64/amd64/=20
> trap.c:984#19 0xffffffff8057f081 in Xfast_syscall ()
> at /usr/src/sys/amd64/amd64/exception.S:373
> #20 0x0000000801064dac in ?? ()
> Previous frame inner to this frame (corrupt stack?)
>=20
> (kgdb) fr 11
> #11 0xffffffff803cb3a4 in assert_vop_elocked (vp=3D0xffffff0007649588, =
=20
> str=3D0xffffffff80642728 "VOP_PUTPAGES")
> at /usr/src/sys/kern/vfs_subr.c:3722
> 3722 vfs_badlock("is not exclusive locked but =20
> should be", str, vp);
> (kgdb) p *vp
> $1 =3D {v_type =3D VREG, v_tag =3D 0xffffffff80b59327 "zfs", v_op =3D =20
> 0xffffffff80b5dee0, v_data =3D 0xffffff00052cb758,
> v_mount =3D 0xffffff00018392f0, v_nmntvnodes =3D {tqe_next =3D 0x0, =20
> tqe_prev =3D 0xffffff006895b028}, v_un =3D {vu_mount =3D 0x0, vu_socket =
=3D 0x0,
> vu_cdev =3D 0x0, vu_fifoinfo =3D 0x0, vu_yield =3D 0}, v_hashlist =3D=
=20
> {le_next =3D 0x0, le_prev =3D 0x0}, v_hash =3D 0, v_cache_src =3D {
> lh_first =3D 0x0}, v_cache_dst =3D {tqh_first =3D 0x0, tqh_last =3D =
=20
> 0xffffff00076495e8}, v_cache_dd =3D 0x0, v_cstart =3D 0, v_lasta =3D 0,
> v_lastw =3D 0, v_clen =3D 0, v_lock =3D {lock_object =3D {lo_name =3D =
=20
> 0xffffffff80b59327 "zfs", lo_flags =3D 91947008, lo_data =3D 0,
> lo_witness =3D 0x0}, lk_lock =3D 17, lk_timo =3D 51, lk_pri =3D 80}=
, =20
> v_interlock =3D {lock_object =3D {
> lo_name =3D 0xffffffff80614670 "vnode interlock", lo_flags =3D =20
> 16973824, lo_data =3D 0, lo_witness =3D 0x0}, mtx_lock =3D 4},
> v_vnlock =3D 0xffffff0007649620, v_holdcnt =3D 3, v_usecount =3D 2, =20
> v_iflag =3D 1024, v_vflag =3D 0, v_writecount =3D 1, v_freelist =3D {
> tqe_next =3D 0x0, tqe_prev =3D 0x0}, v_bufobj =3D {bo_mtx =3D =20
> {lock_object =3D {lo_name =3D 0xffffffff80614680 "bufobj interlock",
> lo_flags =3D 16973824, lo_data =3D 0, lo_witness =3D 0x0}, mtx_lo=
ck =20
> =3D 4}, bo_clean =3D {bv_hd =3D {tqh_first =3D 0x0,
> tqh_last =3D 0xffffff00076496c0}, bv_root =3D 0x0, bv_cnt =3D 0},=
=20
> bo_dirty =3D {bv_hd =3D {tqh_first =3D 0x0, tqh_last =3D 0xffffff00076496=
e0},
> bv_root =3D 0x0, bv_cnt =3D 0}, bo_numoutput =3D 0, bo_flag =3D 0, =
=20
> bo_ops =3D 0xffffffff8079d620, bo_bsize =3D 131072,
> bo_object =3D 0xffffff000ee6c000, bo_synclist =3D {le_next =3D 0x0, =
=20
> le_prev =3D 0x0}, bo_private =3D 0xffffff0007649588,
> __bo_vnode =3D 0xffffff0007649588}, v_pollinfo =3D 0x0, v_label =3D =
=20
> 0x0, v_lockf =3D 0xffffff000d402600}
>=20
> (kgdb) fr 17
> #17 0xffffffff803d3bd1 in fsync (td=3D0xffffff0027f45000, uap=3DVariable =
=20
> "uap" is not available.
> ) at /usr/src/sys/kern/vfs_syscalls.c:3519
> 3519 vn_finished_write(mp);
> (kgdb) p *mp
> $2 =3D {mnt_mtx =3D {lock_object =3D {lo_name =3D 0xffffffff80613905 "str=
uct =20
> mount mtx", lo_flags =3D 16973824, lo_data =3D 0, lo_witness =3D 0x0},
> mtx_lock =3D 4}, mnt_gen =3D 1, mnt_list =3D {tqe_next =3D =20
> 0xffffff0001bf75e0, tqe_prev =3D 0xffffff0001839608}, mnt_op =3D =20
> 0xffffffff80b5de40,
> mnt_vfc =3D 0xffffffff80b5dde0, mnt_vnodecovered =3D =20
> 0xffffff0001ae6000, mnt_syncer =3D 0xffffff0001be2760, mnt_ref =3D 14897,=
=20
> mnt_nvnodelist =3D {
> tqh_first =3D 0xffffff0001be2b10, tqh_last =3D 0xffffff00076495b0}, =
=20
> mnt_nvnodelistsize =3D 7449, mnt_writeopcount =3D 1,
> mnt_kern_flag =3D 1610612864, mnt_flag =3D 268439552, mnt_xflag =3D 0, =
=20
> mnt_noasync =3D 0, mnt_opt =3D 0xffffff00017f1830, mnt_optnew =3D 0x0,
> mnt_maxsymlinklen =3D 0, mnt_stat =3D {f_version =3D 537068824, f_type =
=3D =20
> 4, f_flags =3D 268439552, f_bsize =3D 131072, f_iosize =3D 131072,
> f_blocks =3D 485196, f_bfree =3D 475793, f_bavail =3D 475793, f_files=
=3D =20
> 529171, f_ffree =3D 475793, f_syncwrites =3D 0, f_asyncwrites =3D 0,
> f_syncreads =3D 0, f_asyncreads =3D 0, f_spare =3D {0, 0, 0, 0, 0, 0,=
=20
> 0, 0, 0, 0}, f_namemax =3D 255, f_owner =3D 0, f_fsid =3D {val =3D {59119=
8578,
> -1876274428}}, f_charspare =3D '\0' <repeats 79 times>, =20
> f_fstypename =3D "zfs", '\0' <repeats 12 times>,
> f_mntfromname =3D "tank/usr", '\0' <repeats 79 times>, f_mntonname =
=20
> =3D "/usr", '\0' <repeats 83 times>}, mnt_cred =3D 0xffffff0001be0e00,
> mnt_data =3D 0xffffff0001a89000, mnt_time =3D 0, mnt_iosize_max =3D =20
> 65536, mnt_export =3D 0x0, mnt_label =3D 0x0, mnt_hashseed =3D 2610436692,
> mnt_lockref =3D 0, mnt_secondary_writes =3D 0, mnt_secondary_accwrites =
=20
> =3D 0, mnt_susp_owner =3D 0x0, mnt_gjprovider =3D 0x0, mnt_explock =3D {
> lock_object =3D {lo_name =3D 0xffffffff80613916 "explock", lo_flags =
=3D =20
> 91422720, lo_data =3D 0, lo_witness =3D 0x0}, lk_lock =3D 1, lk_timo =3D =
0,
> lk_pri =3D 80}}
>=20
> # uname -a
> FreeBSD chaos.exscape.org 8.0-BETA2 FreeBSD 8.0-BETA2 #7 r195910M: Thu =
=20
> Jul 30 19:03:33 CEST 2009 root@chaos.exscape.org:/usr/obj/usr/src/=20
> sys/DTRACE amd64
>=20
> As I said, DEBUG_VFS_LOCKS in enabled.
> Should I disabled DEBUG_VFS_LOCKS and consider this "normal" (if it =20
> doesn't still panic, that is), or is this a real issue?
> (Note that while *mp points to /usr, FWIW, /usr is not shared by =20
> samba, nor is any FS below it. Also note that my debugging skills are =20
> at an early stage... so the info provided may be useless.)
It does not matter whether the zfs is accessed by samba. Panic
happens when you do fsync(2) on a vnode that has its vm object
marked as dirty, and VFS_DEBUG_LOCKS is configured.
The workaround is to disable VFS_DEBUG_LOCKS. Since vnode_pager_generic_put=
pages seems to work with shared vnode lock as far as VOP_WRITE works right =
with shared lock, change sys/kern/vnode_if.src, line 475 from
%% putpages vp E E E
to
%% putpages vp L L L
--JoaBr9Q1T6GV3lOg
Content-Type: application/pgp-signature
Content-Disposition: inline
-----BEGIN PGP SIGNATURE-----
Version: GnuPG v1.4.9 (FreeBSD)
iEYEARECAAYFAkp0Vs0ACgkQC3+MBN1Mb4iXWQCfSvJ5g6W/YqD+gFMdnJXQ+IX9
/SQAnj+H+cNU8V5EQcOit2OpemYVGycP
=j2WY
-----END PGP SIGNATURE-----
--JoaBr9Q1T6GV3lOg--
Want to link to this message? Use this URL: <https://mail-archive.FreeBSD.org/cgi/mid.cgi?20090801145301.GE1884>