Date: Wed, 7 May 2014 21:39:20 -0700 From: hiren panchasara <hiren.panchasara@gmail.com> To: John Baldwin <jhb@freebsd.org> Cc: freebsd-stable@freebsd.org Subject: Re: stable/10 panic Message-ID: <CALCpEUGxd8KFbjBaXh-N0pzp5YjG6_xqQdXc%2B2Uu%2BvNSA8hXhw@mail.gmail.com> In-Reply-To: <201405071431.38812.jhb@freebsd.org> References: <1398097892.1101.6.camel@powernoodle.corp.yahoo.com> <201405061634.34868.jhb@freebsd.org> <CALCpEUF6TgZgbtt6d=jtJigRLUBj577t4RP23N1VhKf=fArrxQ@mail.gmail.com> <201405071431.38812.jhb@freebsd.org>
next in thread | previous in thread | raw e-mail | index | archive | help
On Wed, May 7, 2014 at 11:31 AM, John Baldwin <jhb@freebsd.org> wrote:
> On Tuesday, May 06, 2014 7:47:05 pm hiren panchasara wrote:
>> On Tue, May 6, 2014 at 1:34 PM, John Baldwin <jhb@freebsd.org> wrote:
>> > On Monday, May 05, 2014 2:46:12 pm Sean Bruno wrote:
>> >> On Mon, 2014-05-05 at 13:48 -0400, John Baldwin wrote:
>> >> > On Monday, April 21, 2014 12:31:32 pm Sean Bruno wrote:
>> >> > > We're seeing this *a lot* on our qmail based hosts during our stable/10
>> >> > > rollout. We're running stable/10 from around svn rev 261579 (mid
>> >> > > february) with one or two patches strewn in.
>> >> > >
>> >> > > sean
>> >> > >
>> >> > >
>> >> > > GNU gdb 6.1.1 [FreeBSD]
>> >> > > Copyright 2004 Free Software Foundation, Inc.
>> >> > > GDB is free software, covered by the GNU General Public License, and you
>> > are
>> >> > > welcome to change it and/or distribute copies of it under certain
>> > conditions.
>> >> > > Type "show copying" to see the conditions.
>> >> > > There is absolutely no warranty for GDB. Type "show warranty" for
>> > details.
>> >> > > This GDB was configured as "amd64-marcel-freebsd"...
>> >> > >
>> >> > > Unread portion of the kernel message buffer:
>> >> > > panic: page fault
>> >> > > cpuid = 5
>> >> > > KDB: stack backtrace:
>> >> > > db_trace_self_wrapper() at db_trace_self_wrapper+0x2b/frame
>> > 0xfffffe048b9b12a0
>> >> > > kdb_backtrace() at kdb_backtrace+0x39/frame 0xfffffe048b9b1350
>> >> > > vpanic() at vpanic+0x126/frame 0xfffffe048b9b1390
>> >> > > panic() at panic+0x43/frame 0xfffffe048b9b13f0
>> >> > > trap_fatal() at trap_fatal+0x3a2/frame 0xfffffe048b9b1450
>> >> > > trap_pfault() at trap_pfault+0x22f/frame 0xfffffe048b9b14f0
>> >> > > trap() at trap+0x670/frame 0xfffffe048b9b1710
>> >> > > calltrap() at calltrap+0x8/frame 0xfffffe048b9b1710
>> >> > > --- trap 0xc, rip = 0xffffffff805e759b, rsp = 0xfffffe048b9b17d0, rbp =
>> > 0xfffffe048b9b17e0 ---
>> >> > > __mtx_assert() at __mtx_assert+0x3b/frame 0xfffffe048b9b17e0
>> >> > > knote() at knote+0x39/frame 0xfffffe048b9b1830
>> >> > > pipeclose() at pipeclose+0xbe/frame 0xfffffe048b9b1860
>> >> >
>> >> > Can you show which line this is via kgdb? Can you also 'p *cpipe'
>> >> > and 'p *ppipe'?
>> >> >
>> >>
>> >>
>> >> Looks like its in here:
>> >> (kgdb) whe
>> >> #0 doadump (textdump=1) at pcpu.h:219
>> >> #1 0xffffffff805fb2a7 in kern_reboot (howto=260)
>> >> at ../../../kern/kern_shutdown.c:452
>> >> #2 0xffffffff805fb7b5 in vpanic (fmt=<value optimized out>, ap=<value
>> >> optimized out>) at ../../../kern/kern_shutdown.c:759
>> >> #3 0xffffffff805fb803 in panic (fmt=<value optimized out>)
>> >> at ../../../kern/kern_shutdown.c:688
>> >> #4 0xffffffff80977852 in trap_fatal (frame=<value optimized out>,
>> >> eva=<value optimized out>) at ../../../amd64/amd64/trap.c:882
>> >> #5 0xffffffff80977a8f in trap_pfault (frame=0x0, usermode=<value
>> >> optimized out>) at ../../../amd64/amd64/trap.c:699
>> >> #6 0xffffffff809772a0 in trap (frame=0xfffffe048c3df6e0)
>> >> at ../../../amd64/amd64/trap.c:463
>> >> #7 0xffffffff8095c7e2 in calltrap ()
>> >> at ../../../amd64/amd64/exception.S:232
>> >> #8 0xffffffff805e759b in __mtx_assert (c=0x18, what=4,
>> >> file=0xffffffff80ca0bcb "../../../kern/kern_event.c", line=1960)
>> >> at ../../../kern/kern_mutex.c:791
>> >> #9 0xffffffff805c2099 in knote (list=0xfffff8003498aae0, hint=0,
>> >> lockflags=1) at ../../../kern/kern_event.c:1822
>> >> #10 0xffffffff806510fe in pipeclose (cpipe=0xfffff8003498aa18)
>> >> at ../../../kern/sys_pipe.c:1655
>> >> #11 0xffffffff80651019 in pipe_dtor (dpipe=<value optimized out>)
>> >> at ../../../kern/sys_pipe.c:395
>> >> #12 0xffffffff80559924 in fifo_close (ap=<value optimized out>)
>> >> at ../../../fs/fifofs/fifo_vnops.c:115
>> >> #13 0xffffffff80a6ba6a in VOP_CLOSE_APV (vop=<value optimized out>,
>> >> a=<value optimized out>) at vnode_if.c:535
>> >> #14 0xffffffff806acc09 in vn_close (vp=0xfffff8032000cce8, flags=6,
>> >> file_cred=0xfffff8040400d200, td=0xfffff804044f9490) at vnode_if.h:225
>> >> #15 0xffffffff806abad8 in vn_closefile (fp=0xfffff803b2f3c410,
>> >> td=0xfffff804044f9490) at ../../../kern/vfs_vnops.c:1481
>> >> #16 0xffffffff805b8789 in _fdrop (fp=0xfffff803b2f3c410, td=0x4) at
>> >> file.h:342
>> >> #17 0xffffffff805bb0e1 in closef (fp=0xfffff803b2f3c410,
>> >> td=0xfffff804044f9490) at ../../../kern/kern_descrip.c:2415
>> >> #18 0xffffffff805b8bf0 in closefp (fdp=0xfffff800263f5000, fd=<value
>> >> optimized out>, fp=0xfffff803b2f3c410, td=0xfffff804044f9490,
>> >> holdleaders=<value optimized out>) at ../../../kern/kern_descrip.c:1257
>> >> #19 0xffffffff80a332b5 in ia32_syscall (frame=0xfffffe048c3dfbc0) at
>> >> subr_syscall.c:135
>> >> #20 0xffffffff8095cdc5 in Xint0x80_syscall () at ia32_exception.S:73
>> >> #21 0x00000000210f7804 in ?? ()
>> >> Previous frame inner to this frame (corrupt stack?)
>> >> Current language: auto; currently minimal
>> >>
>> >>
>> >>
>> >> ----------------
>> >>
>> >> (kgdb) f 10
>> >> #10 0xffffffff806510fe in pipeclose (cpipe=0xfffff8003498aa18)
>> >> at ../../../kern/sys_pipe.c:1655
>> >> 1655 ../../../kern/sys_pipe.c: No such file or directory.
>> >> in ../../../kern/sys_pipe.c
>> >> (kgdb) p *cpipe
>> >> $1 = {pipe_buffer = {cnt = 0, in = 0, out = 0, size = 0, buffer = 0x0},
>> >> pipe_map = {cnt = 0, pos = 0, npages = 0, ms = {0x0 <repeats 17
>> >> times>}}, pipe_sel = {si_tdlist = {tqh_first = 0x0, tqh_last = 0x0},
>> >> si_note = {kl_list = {
>> >> slh_first = 0x0}, kl_lock = 0, kl_unlock = 0, kl_assert_locked =
>> >> 0xffffffff805c25c0 <knlist_mtx_assert_locked>, kl_assert_unlocked =
>> >> 0xffffffff805c25e0 <knlist_mtx_assert_unlocked>, kl_lockarg = 0x0},
>> >> si_mtx = 0x0},
>> >> pipe_atime = {tv_sec = 1399120887, tv_nsec = 0}, pipe_mtime = {tv_sec
>> >> = 1399120887, tv_nsec = 0}, pipe_ctime = {tv_sec = 1399120887, tv_nsec =
>> >> 0}, pipe_sigio = 0x0, pipe_peer = 0xfffff8003498a8b8, pipe_pair =
>> >> 0xfffff8003498a8b8,
>> >> pipe_state = 2432, pipe_busy = 0, pipe_present = 3, pipe_wgen = 0,
>> >> pipe_ino = 4294967295}
>> >>
>> >> (kgdb) p *ppipe
>> >> $2 = {pipe_buffer = {cnt = 0, in = 0, out = 0, size = 0, buffer = 0x0},
>> >> pipe_map = {cnt = 0, pos = 0, npages = 0, ms = {0x0 <repeats 17
>> >> times>}}, pipe_sel = {si_tdlist = {tqh_first = 0x0, tqh_last = 0x0},
>> >> si_note = {kl_list = {
>> >> slh_first = 0x0}, kl_lock = 0, kl_unlock = 0, kl_assert_locked =
>> >> 0xffffffff805c25c0 <knlist_mtx_assert_locked>, kl_assert_unlocked =
>> >> 0xffffffff805c25e0 <knlist_mtx_assert_unlocked>, kl_lockarg = 0x0},
>> >> si_mtx = 0x0},
>> >> pipe_atime = {tv_sec = 1399120887, tv_nsec = 0}, pipe_mtime = {tv_sec
>> >> = 1399120887, tv_nsec = 0}, pipe_ctime = {tv_sec = 1399120887, tv_nsec =
>> >> 0}, pipe_sigio = 0x0, pipe_peer = 0xfffff8003498a8b8, pipe_pair =
>> >> 0xfffff8003498a8b8,
>> >> pipe_state = 2432, pipe_busy = 0, pipe_present = 3, pipe_wgen = 0,
>> >> pipe_ino = 4294967295}
>> >
>> > So the knlist for both of these has already been destroyed (knlist_destroy
>> > clears kl_lock, but not the assert function pointers). Note that pipe_present
>> > is set to PIPE_FINALIZED for both pipes here. Can you do an 'l' at frame
>> > 10 to see exactly which line is being called?
>>
>> #10 0xffffffff806510fe in pipeclose (cpipe=0xfffff8028a6c6730) at
>> ../../../kern/sys_pipe.c:1655
>>
>> (kgdb) frame 10
>> #10 0xffffffff806510fe in pipeclose (cpipe=0xfffff8028a6c6730) at
>> ../../../kern/sys_pipe.c:1655
>> 1655 ../../../kern/sys_pipe.c: No such file or directory.
>> in ../../../kern/sys_pipe.c
>> (kgdb) l
>> 1650 in ../../../kern/sys_pipe.c
>> (kgdb)
>>
>>
>> 1639. /*
>> 1640. * shutdown the pipe
>> 1641. */
>> 1642. static void
>> 1643. pipeclose(cpipe)
>> 1644. struct pipe *cpipe;
>> 1645. {
>> 1646. struct pipepair *pp;
>> 1647. struct pipe *ppipe;
>> 1648.
>> 1649. KASSERT(cpipe != NULL, ("pipeclose: cpipe == NULL"));
>> 1650.
>> 1651. PIPE_LOCK(cpipe);
>> 1652. pipelock(cpipe, 0);
>> 1653. pp = cpipe->pipe_pair;
>> 1654.
>> 1655. pipeselwakeup(cpipe);
>>
>> pipeclose() gets called from pipe_dtor()
>
> Eh, so it seems like pipeclose() has been called twice on the same pipe which
> should never happen.
How did you get to that conclusion?
>
>> 384. void
>> 385. pipe_dtor(struct pipe *dpipe)
>> 386. {
>> 387. ino_t ino;
>> 388.
>> 389. ino = dpipe->pipe_ino;
>> 390. funsetown(&dpipe->pipe_sigio);
>> 391. pipeclose(dpipe); <---------------
>> 392. if (dpipe->pipe_state & PIPE_NAMED) {
>> 393. dpipe = dpipe->pipe_peer;
>> 394. funsetown(&dpipe->pipe_sigio);
>> 395. pipeclose(dpipe);
>> 396. }
>> 397. if (ino != 0 && ino != (ino_t)-1)
>> 398. free_unr(pipeino_unr, ino);
>> 399. }
>>
>> (kgdb) f 11
>> #11 0xffffffff80651019 in pipe_dtor (dpipe=<value optimized out>) at
>> ../../../kern/sys_pipe.c:395
>> 395 ../../../kern/sys_pipe.c: No such file or directory.
>> in ../../../kern/sys_pipe.c
>> (kgdb) p *dpipe
>> $8 = {pipe_buffer = {cnt = 2160683902, in = 4294967295, out =
>> 2165433456, size = 4294967295, buffer = 0xfffff803c220be70 ""},
>> pipe_map = {
>> cnt = 18446735278181777408, pos = 18446735295352500696, npages =
>> -1841788584, ms = {0x0, 0x0, 0xfffff80125a6a798, 0x0,
>> 0xfffff803c2b7b2a0,
>> 0xfffff803c2b7b2c0, 0x0, 0xffffffff80c96b7e, 0x6fb0008, 0x0,
>> 0xfffff80060c08490, 0x1500000000, 0x60, 0xffffffff80cb7fa9, 0x1030000,
>> 0x0, 0x4}},
>> pipe_sel = {si_tdlist = {tqh_first = 0xfffff801cb464068, tqh_last =
>> 0xfffff8020bfa9b10}, si_note = {kl_list = {slh_first =
>> 0xfffff8022bb72648},
>> kl_lock = 0xffffffff80cb7fb9 <global_opts+1769>, kl_unlock =
>> 0x5230000, kl_assert_locked = 0, kl_assert_unlocked = 0x1,
>> kl_lockarg = 0xffffffff81105f80}, si_mtx = 0x0}, pipe_atime =
>> {tv_sec = 0, tv_nsec = 0}, pipe_mtime = {tv_sec = -8788387676160,
>> tv_nsec = -8788387676160}, pipe_ctime = {tv_sec = 0, tv_nsec =
>> -8788387675872}, pipe_sigio = 0x0, pipe_peer = 0x0, pipe_pair = 0x0,
>> pipe_state = 3410379072, pipe_busy = -2047, pipe_present = 0,
>> pipe_wgen = 0, pipe_ino = 0}
>> (kgdb)
>
> This looks like complete garbage, but it should be matching 'cpipe'
> from earlier. Can you 'p dpipe' at this frame?
>
(kgdb) l
390 in ../../../kern/sys_pipe.c
(kgdb) p dpipe
$3 = <value optimized out>
(kgdb) p *dpipe
Cannot access memory at address 0x100000012
(kgdb)
>> which gets called from fifo_cleanup()
>>
>> 106. static void
>> 107. fifo_cleanup(struct vnode *vp)
>> 108. {
>> 109. struct fifoinfo *fip;
>> 110.
>> 111. ASSERT_VOP_ELOCKED(vp, "fifo_cleanup");
>> 112. fip = vp->v_fifoinfo;
>> 113. if (fip->fi_readers == 0 && fip->fi_writers == 0) {
>> 114. vp->v_fifoinfo = NULL;
>> 115. pipe_dtor(fip->fi_pipe); <-----------------------------
>> 116. free(fip, M_VNODE);
>> 117. }
>> 118. }
>>
>> (kgdb) p *fip->fi_pipe
>> $7 = {pipe_buffer = {cnt = 7562869, in = 1701147238, out = 761557858,
>> size = 1970170230,
>> buffer = 0x736265657266006d <Address 0x736265657266006d out of
>> bounds>}, pipe_map = {cnt = 7596447167107706212, pos =
>> 7022344801864938862,
>> npages = 1852402688, ms = {0x78756e696c006d76, 0x696c00646961722d,
>> 0x706177732d78756e, 0x697361622d736d00, 0x6d00617461642d63,
>> 0x61642d6d646c2d73,
>> 0x646c2d736d006174, 0x61646174656d2d6d, 0x65722d736d006174,
>> 0x6e00646576726573, 0x63632d6473627465, 0x64736274656e0064,
>> 0x74656e006467632d,
>> 0x7366662d647362, 0x6c2d64736274656e, 0x736274656e007366,
>> 0x6e00646961722d64}}, pipe_sel = {si_tdlist = {tqh_first =
>> 0x77732d6473627465,
>> tqh_last = 0x7261776d76007061}, si_note = {kl_list = {slh_first
>> = 0x760073666d762d65}, kl_lock = 0x6d762d657261776d, kl_unlock =
>> 0x6d7600676169646b,
>> kl_assert_locked = 0x7365722d65726177, kl_assert_unlocked =
>> 0x6d76006465767265, kl_lockarg = 0x6173762d65726177}, si_mtx =
>> 0x4f4547007264686e},
>> pipe_atime = {tv_sec = 2322261270122749773, tv_nsec =
>> 2675249699185255283}, pipe_mtime = {tv_sec = 8245071809811652723,
>> tv_nsec = 7450486642355495269},
>> pipe_ctime = {tv_sec = 2406159642925495145, tv_nsec =
>> 3399705548884410378}, pipe_sigio = 0x2f6d6f65672f2e2e, pipe_peer =
>> 0x705f672f74726170,
>> pipe_pair = 0x5f6700632e747261, pipe_state = 1953653104, pipe_busy =
>> 1886547807, pipe_present = 7233896, pipe_wgen = 623407909, pipe_ino =
>> 620767603}
>> (kgdb)
>
> This should also be the same pipe, but it has an even different set
> of garbage. Can you 'p *fip'?
kgdb gets confused I believe:
(kgdb) p *fip
Cannot access memory at address 0xa00000001
(kgdb) p *vp
$1 = {v_tag = 0xffffffff80c96b7e "ufs", v_op = 0xffffffff8111e470,
v_data = 0xfffff80334836498, v_mount = 0xfffff80021805000,
v_nmntvnodes = {tqe_next = 0xfffff803345aa760, tqe_prev =
0xfffff803343ee5a8}, v_un = {vu_mount = 0x0, vu_socket = 0x0,
vu_cdev = 0x0, vu_fifoinfo = 0x0}, v_hashlist = {le_next = 0x0,
le_prev = 0xfffffe00012de3e8}, v_cache_src = {lh_first = 0x0},
v_cache_dst = {tqh_first = 0xfffff80334f11d20, tqh_last =
0xfffff80334f11d40}, v_cache_dd = 0x0, v_lock = {lock_object = {
lo_name = 0xffffffff80c96b7e "ufs", lo_flags = 117112840,
lo_data = 0, lo_witness = 0x0}, lk_lock = 18446735279493186704,
lk_exslpfail = 0, lk_timo = 21, lk_pri = 96}, v_interlock =
{lock_object = {lo_name = 0xffffffff80cb7fa9 "vnode interlock",
lo_flags = 16973824, lo_data = 0, lo_witness = 0x0}, mtx_lock =
4}, v_vnlock = 0xfffff803346417c8, v_actfreelist = {
tqe_next = 0xfffff802f3a0c000, tqe_prev = 0xfffff803ab6139f8},
v_bufobj = {bo_lock = {lock_object = {
lo_name = 0xffffffff80cb7fb9 "bufobj interlock", lo_flags =
86179840, lo_data = 0, lo_witness = 0x0}, rw_lock = 1},
bo_ops = 0xffffffff81105f80, bo_object = 0x0, bo_synclist =
{le_next = 0x0, le_prev = 0x0}, bo_private = 0xfffff80334641760,
__bo_vnode = 0xfffff80334641760, bo_clean = {bv_hd = {tqh_first =
0x0, tqh_last = 0xfffff80334641880}, bv_root = {pt_root = 0},
bv_cnt = 0}, bo_dirty = {bv_hd = {tqh_first = 0x0, tqh_last =
0xfffff803346418a0}, bv_root = {pt_root = 0}, bv_cnt = 0},
bo_numoutput = 0, bo_flag = 0, bo_bsize = 16384}, v_pollinfo =
0x0, v_label = 0x0, v_lockf = 0x0, v_rl = {rl_waiters = {
tqh_first = 0x0, tqh_last = 0xfffff803346418e8}, rl_currdep =
0x0}, v_cstart = 0, v_lasta = 0, v_lastw = 0, v_clen = 0,
v_holdcnt = 1, v_usecount = 1, v_iflag = 512, v_vflag = 0,
v_writecount = 0, v_hash = 14592100, v_type = VFIFO}
(kgdb) p *fip
$2 = {fi_pipe = 0xffffffff80c96b7e, fi_readers = -2129533840,
fi_writers = -8782327094120}
(kgdb)
So, first invocation of "(kgdb) p *fip" didn't give me anything but
last one did.
cheers,
Hiren
Want to link to this message? Use this URL: <https://mail-archive.FreeBSD.org/cgi/mid.cgi?CALCpEUGxd8KFbjBaXh-N0pzp5YjG6_xqQdXc%2B2Uu%2BvNSA8hXhw>