From owner-freebsd-stable@FreeBSD.ORG Mon Nov 13 00:40:59 2006 Return-Path: X-Original-To: freebsd-stable@freebsd.org Delivered-To: freebsd-stable@freebsd.org Received: from mx1.FreeBSD.org (mx1.freebsd.org [216.136.204.125]) by hub.freebsd.org (Postfix) with ESMTP id 3355B16A492; Mon, 13 Nov 2006 00:40:59 +0000 (UTC) (envelope-from mike@sentex.net) Received: from smarthost2.sentex.ca (smarthost2.sentex.ca [205.211.164.50]) by mx1.FreeBSD.org (Postfix) with ESMTP id 69EC743D6E; Mon, 13 Nov 2006 00:40:57 +0000 (GMT) (envelope-from mike@sentex.net) Received: from lava.sentex.ca (pyroxene.sentex.ca [199.212.134.18]) by smarthost2.sentex.ca (8.13.8/8.13.8) with ESMTP id kAD0euPP019886; Sun, 12 Nov 2006 19:40:56 -0500 (EST) (envelope-from mike@sentex.net) Received: from mdt-xp.sentex.net (simeon.sentex.ca [192.168.43.27]) by lava.sentex.ca (8.13.6/8.13.3) with ESMTP id kAD0etbp040637 (version=TLSv1/SSLv3 cipher=DHE-RSA-AES256-SHA bits=256 verify=NO); Sun, 12 Nov 2006 19:40:55 -0500 (EST) (envelope-from mike@sentex.net) Message-Id: <200611130040.kAD0etbp040637@lava.sentex.ca> X-Mailer: QUALCOMM Windows Eudora Version 7.1.0.9 Date: Sun, 12 Nov 2006 19:40:45 -0500 To: Scott Long From: Mike Tancsa In-Reply-To: <45574ECA.4080207@samsco.org> References: <2a41acea0611081719h31be096eu614d2f2325aff511@mail.gmail.com> <200611091536.kA9FaltD018819@lava.sentex.ca> <45534E76.6020906@samsco.org> <200611092200.kA9M0q1E020473@lava.sentex.ca> <200611102004.kAAK4iO9027778@lava.sentex.ca> <2a41acea0611101400w5b8cef40ob84ed6de181f3e2c@mail.gmail.com> <200611102221.kAAML6ol028630@lava.sentex.ca> <455570D8.6070000@samsco.org> <200611120412.kAC4CuIB035746@lava.sentex.ca> <45574ECA.4080207@samsco.org> Mime-Version: 1.0 Content-Type: text/plain; charset="us-ascii"; format=flowed Cc: freebsd-net , glebius@freebsd.org, freebsd-stable@freebsd.org, Jack Vogel Subject: Re: Proposed 6.2 em RELEASE patch X-BeenThere: freebsd-stable@freebsd.org X-Mailman-Version: 2.1.5 Precedence: list List-Id: Production branch of FreeBSD source code List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , X-List-Received-Date: Mon, 13 Nov 2006 00:40:59 -0000 At 11:41 AM 11/12/2006, Scott Long wrote: >Mike Tancsa wrote: >>At 01:42 AM 11/11/2006, Scott Long wrote: >>driver. What will help me is if you can hook up a serial console to >>>your machine and see if it can be made to drop to the debugger while it >>>is under load and otherwise unresponsive. If you can, getting a process >>>dump might help confirm where each CPU is spending its time. >> >>./netblast 192.168.88.218 500 110 1000 >>I compiled in the various debugging options and on the serial >>console I get a few >>Expensive timeout(9) function: 0xc0601e48(0) 0.024135749 s >>and the serial console > >One CPU seems to be stuck in softclock. My guess here is that there >is significant lock contention. Please try the following: > >1. Use addr2line or gdb on the kernel to find out what function is at >0xc0601e48 (the address that was printed above). This address will >change every time you recompile the kernel, so you'll need to reacquire >it from the console each time. # addr2line 0xc0601e48 -e kernel.debug -f nfsrv_timer /usr/src/sys/nfsserver/nfs_srvsock.c:809 # and # addr2line 0xc0561444 -e kernel.debug -f sleepq_timeout /usr/src/sys/kern/subr_sleepqueue.c:724 I dont have any nfs activity on the box >2. Try compiling in WITNESS and running the test as before, then break >into the debugger as before. Run 'show locks'. I'm not sure how >fruitful this will be, WITNESS might make it unbearably slow. It was in that kernel already All it would generally show is exclusive spin mutex sio r = 0 (0xc07c81c0) locked @ /usr/src/sys/dev/sio/sio.c:1390 But I did notice in /var/log/kernel Nov 12 00:04:09 R2 kernel: exclusive spin mutex sio r = 0 (0xc07c81c0) locked @ /usr/src/sys/dev/sio/sio.c:1390 Nov 12 00:04:09 R2 kernel: exclusive sleep mutex em1 (network driver) r = 0 (0xc64bc9d4) locked @ /usr/src/sys/dev/ em/if_em.c:3569 Nov 12 00:04:09 R2 kernel: exclusive spin mutex sio r = 0 (0xc07c81c0) locked @ /usr/src/sys/dev/sio/sio.c:1390 Nov 12 19:27:39 R2 kernel: KDB: enter: Line break on console Nov 12 19:27:39 R2 kernel: exclusive spin mutex sio r = 0 (0xc07c81c0) locked @ /usr/src/sys/dev/sio/sio.c:1390 Nov 12 19:28:13 R2 kernel: KDB: enter: Line break on console Nov 12 19:28:13 R2 kernel: exclusive spin mutex sio r = 0 (0xc07c81c0) locked @ /usr/src/sys/dev/sio/sio.c:1390 Nov 12 19:31:37 R2 kernel: KDB: enter: Line break on console Nov 12 19:31:37 R2 kernel: exclusive spin mutex sio r = 0 (0xc07c81c0) locked @ /usr/src/sys/dev/sio/sio.c:1390 Nov 12 19:34:22 R2 kernel: KDB: enter: Line break on console Nov 12 19:34:22 R2 kernel: exclusive spin mutex sio r = 0 (0xc07c81c0) locked @ /usr/src/sys/dev/sio/sio.c:1390 >3. Turn on MUTEX_PROFILING according to the text in /sys/conf/NOTES and >the man page by the same name. >4. Remove ADAPTIVE_GIANT from your config and retest. If that doesn't >show a difference, then try setting NO_ADAPTIVE_MUTEXES. OK, did this recompiling without WITNESS and INVARIANTS and took out ADAPTIVE_GIANT as instructed in the man pages # sysctl -a | grep mutex debug.mutex.prof.enable: 1 debug.mutex.prof.acquisitions: 584672946 debug.mutex.prof.records: 450 debug.mutex.prof.maxrecords: 1000 debug.mutex.prof.rejected: 0 debug.mutex.prof.hashsize: 1009 debug.mutex.prof.collisions: 75 debug.mutex.prof.stats: 10 1263 226 5 0 0 /usr/src/sys/kern/sys_pipe.c:1345 (pipe mutex) 3 682 369 1 13 6908 /usr/src/sys/vm/vm_fault.c:851 (vm page queue mutex) 10 2256 623 3 23 15 /usr/src/sys/i386/i386/pmap.c:1891 (vm page queue mutex) 120 883 401 2 15 26 /usr/src/sys/vm/vm_fault.c:909 (vm page queue mutex) 25 25 1 25 0 0 /usr/src/sys/i386/i386/pmap.c:2572 (vm page queue mutex) 19 169 33 5 1 1 /usr/src/sys/vm/vm_object.c:1801 (vm page queue mutex) 4 24 9 2 0 0 /usr/src/sys/vm/vm_object.c:646 (vm page queue mutex) 3 23 8 2 1 1 /usr/src/sys/kern/vfs_bio.c:3384 (vm page queue mutex) 2 12 6 2 0 0 /usr/src/sys/vm/vm_pageout.c:1511 (vm page queue mutex) 4 120 44 2 0 0 /usr/src/sys/kern/vfs_bio.c:3315 (vm page queue mutex) 3 100 44 2 0 0 /usr/src/sys/kern/vfs_bio.c:3120 (vm page queue mutex) 3 9 4 2 0 0 /usr/src/sys/kern/vfs_bio.c:3577 (vm page queue mutex) 1 1 1 1 0 4 /usr/src/sys/kern/sys_pipe.c:1270 (pipe mutex) 2 16 8 2 0 0 /usr/src/sys/vm/vm_page.c:1481 (vm page queue mutex) 2 8 4 2 0 0 /usr/src/sys/kern/kern_exec.c:871 (vm page queue mutex) 145 713 14 50 5 4 /usr/src/sys/vm/vm_map.c:1504 (vm page queue mutex) 2 7 4 1 0 0 /usr/src/sys/vm/vm_glue.c:273 (vm page queue mutex) 2 8 4 2 0 0 /usr/src/sys/vm/vm_glue.c:309 (vm page queue mutex) 2 8 4 2 0 0 /usr/src/sys/kern/kern_exec.c:893 (vm page queue mutex) 36 357 42 8 2 1 /usr/src/sys/i386/i386/pmap.c:1624 (vm page queue mutex) 5 152 64 2 2 2 /usr/src/sys/vm/vm_fault.c:346 (vm page queue mutex) 2 61 24 2 2 1 /usr/src/sys/vm/vm_fault.c:136 (vm page queue mutex) 5 48 10 4 0 2 /usr/src/sys/i386/i386/pmap.c:1782 (vm page queue mutex) 11 1451 193 7 24 13 /usr/src/sys/vm/vm_fault.c:1009 (vm page queue mutex) 3 3868 1692 2 8 4 /usr/src/sys/kern/sys_pipe.c:993 (pipe mutex) 6 4681 1692 2 46 6 /usr/src/sys/kern/sys_pipe.c:1145 (pipe mutex) 2 643 372 1 0 0 /usr/src/sys/vm/vm_fault.c:1092 (vm page queue mutex) 3 3235 1648 1 5 44 /usr/src/sys/kern/sys_pipe.c:591 (pipe mutex) 5 4235 1647 2 2 2 /usr/src/sys/kern/sys_pipe.c:628 (pipe mutex) 1 331 222 1 0 0 /usr/src/sys/vm/vm_kern.c:367 (vm page queue mutex) 2 337 222 1 0 0 /usr/src/sys/vm/vm_kern.c:404 (vm page queue mutex) debug.mutex.prof.reset: 0 >Thanks, > >Scott