From owner-freebsd-net@FreeBSD.ORG Fri Oct 10 15:58:05 2014 Return-Path: Delivered-To: freebsd-net@freebsd.org Received: from mx1.freebsd.org (mx1.freebsd.org [8.8.178.115]) (using TLSv1.2 with cipher AECDH-AES256-SHA (256/256 bits)) (No client certificate requested) by hub.freebsd.org (Postfix) with ESMTPS id D88D552B for ; Fri, 10 Oct 2014 15:58:05 +0000 (UTC) Received: from bigwig.baldwin.cx (bigwig.baldwin.cx [IPv6:2001:470:1f11:75::1]) (using TLSv1 with cipher DHE-RSA-CAMELLIA256-SHA (256/256 bits)) (Client did not present a certificate) by mx1.freebsd.org (Postfix) with ESMTPS id B01B4C4F for ; Fri, 10 Oct 2014 15:58:05 +0000 (UTC) Received: from ralph.baldwin.cx (pool-173-70-85-31.nwrknj.fios.verizon.net [173.70.85.31]) by bigwig.baldwin.cx (Postfix) with ESMTPSA id 26E0AB91F; Fri, 10 Oct 2014 11:58:01 -0400 (EDT) From: John Baldwin To: Jason Wolfe Subject: Re: ixgbe(4) spin lock held too long Date: Fri, 10 Oct 2014 11:53:30 -0400 Message-ID: <3567780.Mf6fMnzmYG@ralph.baldwin.cx> User-Agent: KMail/4.12.5 (FreeBSD/10.1-BETA2; KDE/4.12.5; amd64; ; ) In-Reply-To: References: <1410203348.1343.1.camel@bruno> <2077446.sYcZo9xEXb@ralph.baldwin.cx> MIME-Version: 1.0 Content-Transfer-Encoding: 7Bit Content-Type: text/plain; charset="us-ascii" X-Greylist: Sender succeeded SMTP AUTH, not delayed by milter-greylist-4.2.7 (bigwig.baldwin.cx); Fri, 10 Oct 2014 11:58:01 -0400 (EDT) Cc: Sean Bruno , freebsd-net@freebsd.org X-BeenThere: freebsd-net@freebsd.org X-Mailman-Version: 2.1.18-1 Precedence: list List-Id: Networking and TCP/IP with FreeBSD List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , X-List-Received-Date: Fri, 10 Oct 2014 15:58:05 -0000 On Thursday, October 09, 2014 02:31:32 PM Jason Wolfe wrote: > On Wed, Oct 8, 2014 at 12:29 PM, John Baldwin wrote: > > My only other thought is if a direct timeout routine ran for a long time. > > > > I just committed a change to current that can let you capture KTR traces > > of > > callout routines for use with schedgraph (r272757). Unfortunately, > > enabling KTR_SCHED can be slow. If you are up for trying it, I do think > > that > > building a kernel with KTR and KTR_SCHED enabled (KTR_COMPILE=KTR_SCHED > > and > > KTR_MASK=KTR_SCHED) with the kernel part of the commit I referenced above > > applied is the best bet to figure out why it is spinning so long. If you > > can > > try that (and if it doesn't slow things down too much) and get a panic > > with > > those options enabled, then capture the output of > > 'ktrdump -e /path/to/kernel -m /var/crash/vmcore.X -ct', we can use > > Src/tools/sched/schedgraph.py to look at that output to get a picture of > > what > > was going on just prior to the crash. > > > > -- > > John Baldwin > > As luck would have it.. caught one of the boxes with the new KTR > code/options after only an hour. Crashed in the same way w tid 100003 and > looking the same in callout_process > > spin lock 0xffffffff81262d00 (callout) held by 0xfffff800151fe000 (tid > 100003) too long > spin lock 0xffffffff81262d00 (callout) held by 0xfffff800151fe000 (tid > 100003) too long > > #4 0xffffffff8070d6fa in callout_process (now=7915682202423) at > /usr/src/sys/kern/kern_ > timeout.c:490 > > The ktrdump oddly only seems to have the last 702, though debug.ktr.entries > is set to 1024. It appears the buffer may also start after 100003 had > already hung? I've bumped debug.ktr.entries up in case we don't have > enough history here. > > http://nitrology.com/ktrdump-spinlock.txt Hmm, schedgraph.py chokes on this, but it's a bit interesting. It seems that in this time sample, CPUs 1, 2, 4, and 5 were constantly running ixgbe interrupt handlers. No actual thread state changes are logged (which is why schedgraph choked). Try setting the sysctl 'net.inet.tcp.per_cpu_timers' to 1 and see if that makes a difference. I'm guessing they are all contending on the default callout lock which is causing your headache. -- John Baldwin