Skip site navigation (1)Skip section navigation (2)
Date:      Wed, 17 Dec 2014 09:55:09 +1030
From:      Shane Ambler <BSD@ShaneWare.Biz>
To:        John Baldwin <jhb@freebsd.org>, freebsd-stable@freebsd.org
Cc:        Alexander Motin <mav@freebsd.org>, hselasky@freebsd.org, mjg@freebsd.org, Shane Ambler <FreeBSD@shaneware.biz>
Subject:   Re: Help debugging stable/10
Message-ID:  <5490BF55.3020108@ShaneWare.Biz>
In-Reply-To: <201412161129.57704.jhb@freebsd.org>
References:  <5488F58D.7060708@ShaneWare.Biz> <201412161129.57704.jhb@freebsd.org>

next in thread | previous in thread | raw e-mail | index | archive | help
On 17/12/2014 02:59, John Baldwin wrote:
> On Wednesday, December 10, 2014 8:38:21 pm Shane Ambler wrote:
>> Since upgrading to 10.1 (RC2) I have had trouble getting uptimes greater
>> than 1 day. I have little experience debugging the OS so could use some
>> help.
>>
>> # uname -a
>> FreeBSD leader.local 10.1-STABLE FreeBSD 10.1-STABLE #0 r275364: Tue Dec
>> 2 08:13:06 ACDT 2014
>> root@leader.local:/usr/obj/usr/src-stable/sys/GENERIC amd64
>>
>> This is on an ASUS P8H61-M LE/USB3 corei5 8GB with 3x 2TB Seagate drives
>> in raidz.
>> Full backtraces and dmesg at http://shaneware.biz/freebsddebugdata/
>>
>> The thing that breaks which forces me to reset the machine is that I am
>> unable to start new processes. Existing processes continue to work I
>> just can't start new ones. Some simple commands do work but top ps
>> procstat usbconfig all fail to start. I have been able use script to
>> get some backtraces from kgdb before restarting.
>
> It looks like your processes are hanging on a global lock used by sysctl(3).
> That would explain hangs in top/ps/procstat as they all use sysctls.  For
> example:
>
> Thread 709 (Thread 101172):
> #0  sched_switch (td=0xfffff8006cccd490, newtd=<value optimized out>, flags=<value optimized out>)
>      at /usr/src-stable/sys/kern/sched_ule.c:1945
> #1  0xffffffff80933801 in mi_switch (flags=260, newtd=0x0) at /usr/src-stable/sys/kern/kern_synch.c:493
> #2  0xffffffff8097110a in sleepq_wait (wchan=0x0, pri=0) at /usr/src-stable/sys/kern/subr_sleepqueue.c:617
> #3  0xffffffff8093284a in _sx_xlock_hard (sx=0xffffffff8157adc0, tid=18446735279441892496,
>      opts=<value optimized out>, file=0x0, line=0) at /usr/src-stable/sys/kern/kern_sx.c:681
> #4  0xffffffff80936004 in userland_sysctl (td=<value optimized out>, name=0xfffffe021e889930, namelen=3,
>      old=<value optimized out>, oldlenp=<value optimized out>, inkernel=<value optimized out>,
>      new=<value optimized out>, newlen=<value optimized out>, retval=<value optimized out>, flags=0) at sx.h:152
> #5  0xffffffff80935e64 in sys___sysctl (td=0xfffff8006cccd490, uap=0xfffffe021e889a40)
>      at /usr/src-stable/sys/kern/kern_sysctl.c:1536
> #6  0xffffffff80d29c51 in amd64_syscall (td=0xfffff8006cccd490, traced=0) at subr_syscall.c:134
> #7  0xffffffff80d0eceb in Xfast_syscall () at /usr/src-stable/sys/amd64/amd64/exception.S:391
> #8  0x0000000800b6e64a in ?? ()
> Previous frame inner to this frame (corrupt stack?)
> ---Type <return> to continue, or q <return> to quit---
>
> To hang like this means that some sysctl handler is running for a long time.
>
> Looking in your traces, this appears to be the problematic sysctl:
>
> Thread 397 (Thread 100422):
> #0  sched_switch (td=0xfffff8001049f920, newtd=<value optimized out>, flags=<value optimized out>)
>      at /usr/src-stable/sys/kern/sched_ule.c:1945
> #1  0xffffffff80933801 in mi_switch (flags=260, newtd=0x0) at /usr/src-stable/sys/kern/kern_synch.c:493
> #2  0xffffffff8097189a in sleepq_timedwait (wchan=0x0, pri=0) at /usr/src-stable/sys/kern/subr_sleepqueue.c:652
> #3  0xffffffff8093320e in _sleep (ident=<value optimized out>, lock=<value optimized out>,
>      priority=<value optimized out>, wmesg=<value optimized out>, sbt=<value optimized out>, pr=<value optimized out>,
>      flags=<value optimized out>) at /usr/src-stable/sys/kern/kern_synch.c:251
> #4  0xffffffff80891ae3 in g_waitfor_event (func=<value optimized out>, arg=<value optimized out>,
>      flag=<value optimized out>) at /usr/src-stable/sys/geom/geom_event.c:427
> #5  0xffffffff808933d9 in sysctl_kern_geom_conftxt (oidp=<value optimized out>, arg1=<value optimized out>,
>      arg2=<value optimized out>, req=0xfffffe021dc13868) at /usr/src-stable/sys/geom/geom_kern.c:169
> #6  0xffffffff80935a9e in sysctl_root (arg1=<value optimized out>, arg2=<value optimized out>)
>      at /usr/src-stable/sys/kern/kern_sysctl.c:1500
> #7  0xffffffff80936078 in userland_sysctl (td=<value optimized out>, name=0xfffffe021dc13930,
>      namelen=<value optimized out>, old=<value optimized out>, oldlenp=<value optimized out>,
>      inkernel=<value optimized out>, new=<value optimized out>, newlen=<value optimized out>,
>      retval=<value optimized out>, flags=0) at /usr/src-stable/sys/kern/kern_sysctl.c:1610
> #8  0xffffffff80935e64 in sys___sysctl (td=0xfffff8001049f920, uap=0xfffffe021dc13a40)
>      at /usr/src-stable/sys/kern/kern_sysctl.c:1536
> #9  0xffffffff80d29c51 in amd64_syscall (td=0xfffff8001049f920, traced=0) at subr_syscall.c:134
> #10 0xffffffff80d0eceb in Xfast_syscall () at /usr/src-stable/sys/amd64/amd64/exception.S:391
> #11 0x00000008019c864a in ?? ()
> Previous frame inner to this frame (corrupt stack?)
>
> (Note that HEAD has some changes by mjg@ (cc'd) to allow concurrent sysctls
> that would at least make this less painful.)
>
> The root issue is why is geom hanging.  Hmm, that thread is also stuck on an
> sx lock:
>
> Thread 259 (Thread 100015):
> #0  sched_switch (td=0xfffff80005170000, newtd=<value optimized out>, flags=<value optimized out>)
>      at /usr/src-stable/sys/kern/sched_ule.c:1945
> #1  0xffffffff80933801 in mi_switch (flags=260, newtd=0x0) at /usr/src-stable/sys/kern/kern_synch.c:493
> #2  0xffffffff8097110a in sleepq_wait (wchan=0x0, pri=0) at /usr/src-stable/sys/kern/subr_sleepqueue.c:617
> #3  0xffffffff8093284a in _sx_xlock_hard (sx=0xffffffff816451e0, tid=18446735277701922816,
>      opts=<value optimized out>, file=0x0, line=0) at /usr/src-stable/sys/kern/kern_sx.c:681
> #4  0xffffffff808912b2 in g_run_events () at sx.h:152
> #5  0xffffffff808fad3a in fork_exit (callout=0xffffffff80893240 <g_event_procbody>, arg=0x0, frame=0xfffffe01ef98aac0)
>      at /usr/src-stable/sys/kern/kern_fork.c:996
> #6  0xffffffff80d0ef3e in fork_trampoline () at /usr/src-stable/sys/amd64/amd64/exception.S:606
> #7  0x0000000000000000 in ?? ()
>
> That is probably g_topology_lock.  If so, it is held by this thread
> (g_dev_open() grabs it around g_access()):
>
> Thread 673 (Thread 101936):
> #0  sched_switch (td=0xfffff80162200490, newtd=<value optimized out>, flags=<value optimized out>)
>      at /usr/src-stable/sys/kern/sched_ule.c:1945
> #1  0xffffffff80933801 in mi_switch (flags=260, newtd=0x0) at /usr/src-stable/sys/kern/kern_synch.c:493
> #2  0xffffffff8097110a in sleepq_wait (wchan=0x0, pri=0) at /usr/src-stable/sys/kern/subr_sleepqueue.c:617
> #3  0xffffffff80933227 in _sleep (ident=<value optimized out>, lock=<value optimized out>,
>      priority=<value optimized out>, wmesg=<value optimized out>, sbt=<value optimized out>, pr=<value optimized out>,
>      flags=<value optimized out>) at /usr/src-stable/sys/kern/kern_synch.c:255
> #4  0xffffffff8030b9b3 in daopen (dp=<value optimized out>) at /usr/src-stable/sys/cam/scsi/scsi_da.c:1295
> #5  0xffffffff8089013b in g_disk_access (pp=0xfffff800097f4c00, r=<value optimized out>, w=<value optimized out>,
>      e=<value optimized out>) at /usr/src-stable/sys/geom/geom_disk.c:136
> #6  0xffffffff80894f3e in g_access (cp=0xfffff800097f2e00, dcr=1, dcw=0, dce=0)
>      at /usr/src-stable/sys/geom/geom_subr.c:913
> #7  0xffffffff8088df12 in g_dev_open (dev=<value optimized out>, flags=<value optimized out>,
>      fmt=<value optimized out>, td=<value optimized out>) at /usr/src-stable/sys/geom/geom_dev.c:361
> #8  0xffffffff808180f2 in devfs_open (ap=<value optimized out>) at /usr/src-stable/sys/fs/devfs/devfs_vnops.c:1086
> ---Type <return> to continue, or q <return> to quit---
> #9  0xffffffff80e44fd1 in VOP_OPEN_APV (vop=<value optimized out>, a=<value optimized out>) at vnode_if.c:469
> #10 0xffffffff809d9bb4 in vn_open_vnode (vp=0xfffff8017d14d000, fmode=1, cred=0xfffff8000c2e4b00,
>      td=0xfffff80162200490, fp=0xfffff80081060230) at vnode_if.h:196
> #11 0xffffffff809d97ac in vn_open_cred (ndp=0xfffffe021e97b880, flagp=0xfffffe021e97b95c,
>      cmode=<value optimized out>, vn_open_flags=<value optimized out>, cred=0x0, fp=0xfffff80081060230)
>      at /usr/src-stable/sys/kern/vfs_vnops.c:256
> #12 0xffffffff809d2def in kern_openat (td=0xfffff80162200490, fd=-100,
>      path=0x7fffffffe99e <Error reading address 0x7fffffffe99e: Bad address>, pathseg=UIO_USERSPACE, flags=1,
>      mode=<value optimized out>) at /usr/src-stable/sys/kern/vfs_syscalls.c:1091
> #13 0xffffffff80d29c51 in amd64_syscall (td=0xfffff80162200490, traced=0) at subr_syscall.c:134
> #14 0xffffffff80d0eceb in Xfast_syscall () at /usr/src-stable/sys/amd64/amd64/exception.S:391
> #15 0x0000000800f8dcea in ?? ()
> Previous frame inner to this frame (corrupt stack?)
>
> Line 1295 of scsi_da.c in a stable/10 checkout of today is this:
>
>          /* Wait for the disk size update.  */
>          error = cam_periph_sleep(periph, &softc->disk->d_mediasize, PRIBIO,
>              "dareprobe", 0);
>
> To be stuck here means that the request dareprobe() queued is stuck behind
> some other request on the device.  Looking in your traces, there are several
> threads all waiting for an ioctl() to a passX device to complete:
>
> Thread 432 (Thread 100542):
> #0  sched_switch (td=0xfffff801acb8a920, newtd=<value optimized out>, flags=<value optimized out>)
>      at /usr/src-stable/sys/kern/sched_ule.c:1945
> #1  0xffffffff80933801 in mi_switch (flags=260, newtd=0x0) at /usr/src-stable/sys/kern/kern_synch.c:493
> #2  0xffffffff8097110a in sleepq_wait (wchan=0x0, pri=0) at /usr/src-stable/sys/kern/subr_sleepqueue.c:617
> #3  0xffffffff80933227 in _sleep (ident=<value optimized out>, lock=<value optimized out>,
>      priority=<value optimized out>, wmesg=<value optimized out>, sbt=<value optimized out>, pr=<value optimized out>,
>      flags=<value optimized out>) at /usr/src-stable/sys/kern/kern_synch.c:255
> ---Type <return> to continue, or q <return> to quit---
> #4  0xffffffff802ddc0e in cam_periph_runccb (ccb=0xfffff80187888000, error_routine=0xffffffff8030d2a0 <passerror>,
>      camflags=CAM_RETRY_SELTO, sense_flags=18, ds=0xfffff8000984fa20) at /usr/src-stable/sys/cam/cam_periph.c:969
> #5  0xffffffff8030d233 in passdoioctl (dev=<value optimized out>, cmd=<value optimized out>,
>      addr=0xfffff800b50f4800 "", flag=<value optimized out>, td=<value optimized out>)
>      at /usr/src-stable/sys/cam/scsi/scsi_pass.c:680
> #6  0xffffffff8030cf32 in passioctl (dev=0xfffff80009835e00, cmd=3302496258, addr=0xfffff800b50f4800 "", flag=3,
>      td=0xfffff801acb8a920) at /usr/src-stable/sys/cam/scsi/scsi_pass.c:533
> #7  0xffffffff80819a99 in devfs_ioctl_f (fp=0xfffff800b5d6f320, com=3302496258, data=0xfffff800b50f4800,
>      cred=<value optimized out>, td=0xfffff801acb8a920) at /usr/src-stable/sys/fs/devfs/devfs_vnops.c:759
> #8  0xffffffff8097d865 in kern_ioctl (td=0xfffff801acb8a920, fd=<value optimized out>, com=0) at file.h:320
> #9  0xffffffff8097d560 in sys_ioctl (td=0xfffff801acb8a920, uap=0xfffffe021de9aa40)
>      at /usr/src-stable/sys/kern/sys_generic.c:718
> #10 0xffffffff80d29c51 in amd64_syscall (td=0xfffff801acb8a920, traced=0) at subr_syscall.c:134
> #11 0xffffffff80d0eceb in Xfast_syscall () at /usr/src-stable/sys/amd64/amd64/exception.S:391
> #12 0x0000000800ff3f7a in ?? ()
> Previous frame inner to this frame (corrupt stack?)
>
> I suspect the daopen() is hanging on the disk associated with the given
> passX device.
>
> Are you running smartd or anything else that accesses passX devices?
>
> Also, do you have a coredump from this or were you just running kgdb against
> the live system?  If you have a coredump you can run ps against it (or use
> some kgdb macros I have) to see the command name of the process doing the
> passX ioctls.  We could also see which passX devices were blocking to see if
> this is related to either AHCI or USB.  Also, do you possibly have any errors
> in your dmesg from the disk devices?
>

Thanks for looking at this.

I updated a few days ago -
FreeBSD leader.local 10.1-STABLE FreeBSD 10.1-STABLE #0 r275731: Sat
Dec 13 08:36:29 ACDT 2014 
root@leader.local:/usr/obj/usr/src/sys/GENERIC  amd64


I haven't got any core dumps as I only get to the stage of no process
creation (yesterday I had it freeze completely) leaving no choice but
to reset. I leave a root terminal open so that I can run kgdb before
resetting.

I have sysutils/smartmontools installed but I'm not running smartd,
I just have the smart status in daily logs.

I'll vote for USB - I have two USB memsticks that I use almost daily -
previously (since 10.1RC2) I have had trouble with them. Failure to get
the dev entries created, followed with no console messages of device
insert/remove. I had noticed this before being unable to create
processes so wasn't sure which came first. usbconfig was sometimes the
first process I noticed failure to run. I haven't seen this for a
while, so not in stable, maybe in release but definitely in RC 2-4

I think it was in RC3 I got errors of -
xptioctl: pass driver is not in the kernel
xptioctl: put "device pass" in your kernel config file
a couple of times with the USB memstick - again not recently.

Before release I had an issue with constant zfs writes - I haven't been
able to re-create a lockup since RC4 so don't know if that is related.
https://bugs.freebsd.org/bugzilla/show_bug.cgi?id=194654

I'm not seeing any device errors in dmesg, log/messages or log/console.log

Someone had mentioned lockups with latest nvidia driver that going back
to the previous had fixed, I am getting some x related crashes so was
going to look at that.

Dec 17 03:21:16 leader kernel: pid 62431 (xcmmtst_big), uid 0: exited on 
signal 10 (core dumped)
Dec 17 03:22:11 leader kernel: pid 69694 (xprobe_gas_x8632), uid 0: 
exited on signal 11 (core dumped)
Dec 17 03:22:11 leader kernel: pid 69779 (xprobe_3dnow), uid 0: exited 
on signal 4 (core dumped)
Dec 17 03:22:42 leader kernel: pid 78410 (xprobe_gas_x8632), uid 0: 
exited on signal 11 (core dumped)
Dec 17 03:22:43 leader kernel: pid 78554 (xprobe_3dnow), uid 0: exited 
on signal 4 (core dumped)
Dec 17 03:46:21 leader kernel: pid 40770 (xdfc), uid 0: exited on signal 
10 (core dumped)
Dec 17 03:46:26 leader kernel: pid 41000 (xdmmtst), uid 0: exited on 
signal 10 (core dumped)
Dec 17 03:50:55 leader kernel: pid 52533 (xdfc), uid 0: exited on signal 
10 (core dumped)
Dec 17 03:51:30 leader kernel: pid 54062 (xdfc), uid 0: exited on signal 
11 (core dumped)


I could run a build of kernel and world with debugging or (is it 
witness?) for a few days if that would help get more info.


-- 
FreeBSD - the place to B...Software Developing

Shane Ambler




Want to link to this message? Use this URL: <https://mail-archive.FreeBSD.org/cgi/mid.cgi?5490BF55.3020108>