From owner-freebsd-questions@FreeBSD.ORG Tue Oct 7 11:57:52 2008 Return-Path: Delivered-To: freebsd-questions@freebsd.org Received: from mx1.freebsd.org (mx1.freebsd.org [IPv6:2001:4f8:fff6::34]) by hub.freebsd.org (Postfix) with ESMTP id 049D81065692 for ; Tue, 7 Oct 2008 11:57:52 +0000 (UTC) (envelope-from jdc@koitsu.dyndns.org) Received: from QMTA03.emeryville.ca.mail.comcast.net (qmta03.emeryville.ca.mail.comcast.net [76.96.30.32]) by mx1.freebsd.org (Postfix) with ESMTP id D9DD48FC21 for ; Tue, 7 Oct 2008 11:57:51 +0000 (UTC) (envelope-from jdc@koitsu.dyndns.org) Received: from OMTA09.emeryville.ca.mail.comcast.net ([76.96.30.20]) by QMTA03.emeryville.ca.mail.comcast.net with comcast id PmYH1a00C0S2fkCA3nxrH0; Tue, 07 Oct 2008 11:57:51 +0000 Received: from koitsu.dyndns.org ([69.181.141.110]) by OMTA09.emeryville.ca.mail.comcast.net with comcast id Pnxo1a00R2P6wsM8VnxpSF; Tue, 07 Oct 2008 11:57:49 +0000 X-Authority-Analysis: v=1.0 c=1 a=j1-vOjvzWS4A:10 a=qbkBlHUnetAA:10 a=QycZ5dHgAAAA:8 a=830efeqVd1-BpMj3v6YA:9 a=OaTEfa5PdL42xPuouuoA:7 a=_rQjeZhtyJV0AH9nAlltBONLT1IA:4 a=EoioJ0NPDVgA:10 a=LY0hPdMaydYA:10 Received: by icarus.home.lan (Postfix, from userid 1000) id 7D66EC9419; Tue, 7 Oct 2008 04:57:48 -0700 (PDT) Date: Tue, 7 Oct 2008 04:57:48 -0700 From: Jeremy Chadwick To: ???? Message-ID: <20081007115748.GA48154@icarus.home.lan> References: <004001c92871$fdec0a10$01000001@china.huawei.com> MIME-Version: 1.0 Content-Type: text/plain; charset=us-ascii Content-Disposition: inline In-Reply-To: <004001c92871$fdec0a10$01000001@china.huawei.com> User-Agent: Mutt/1.5.18 (2008-05-17) Cc: freebsd-net@FreeBSD.org, freebsd-questions@freebsd.org, freebsd-threads@freebsd.org Subject: Re: kernel profiling: spinlock_exit consumes 36% CPU time. X-BeenThere: freebsd-questions@freebsd.org X-Mailman-Version: 2.1.5 Precedence: list List-Id: User questions List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , X-List-Received-Date: Tue, 07 Oct 2008 11:57:53 -0000 On Tue, Oct 07, 2008 at 07:44:00PM +0800, ???? wrote: > Hi, folks, > > I did kernel profiling when a single thread client sends UDP packets to a > single thread server on the same machine. > > In the output kernel profile, the first few kernel functions that consumes > the most CPU time are listed below: > > granularity: each sample hit covers 16 byte(s) for 0.01% of 25.68 seconds > > % cumulative self self total > time seconds seconds calls ms/call ms/call name > 42.4 10.88 10.88 0 100.00% __mcount [1] > 36.1 20.14 9.26 17937541 0.00 0.00 spinlock_exit [4] > 4.2 21.22 1.08 3145728 0.00 0.00 in_cksum_skip [40] > 1.8 21.68 0.45 7351987 0.00 0.00 generic_copyin [43] > 1.1 21.96 0.29 3146028 0.00 0.00 generic_copyout [48] > 1.0 22.21 0.24 2108904 0.00 0.00 Xint0x80_syscall [3] > 0.8 22.42 0.21 6292131 0.00 0.00 uma_zalloc_arg [46] > 0.8 22.62 0.20 1048576 0.00 0.00 soreceive_generic [9] > 0.7 22.80 0.19 3145852 0.00 0.00 free [47] > 0.6 22.96 0.15 6292172 0.00 0.00 uma_zfree_arg [52] > 0.6 23.10 0.14 5243413 0.00 0.00 generic_bzero [53] > 0.5 23.23 0.14 1048581 0.00 0.00 ip_output [23] > 0.5 23.36 0.13 4221855 0.00 0.00 generic_bcopy [57] > 0.4 23.47 0.11 36865859 0.00 0.00 critical_enter [61] > 0.4 23.57 0.10 36865859 0.00 0.00 critical_exit [62] > 0.4 23.67 0.09 17937541 0.00 0.00 spinlock_enter [63] > 0.4 23.76 0.09 1048582 0.00 0.00 udp_input [21] > 0.3 23.85 0.09 2108904 0.00 0.00 syscall [5] > 0.3 23.93 0.08 1048587 0.00 0.00 ip_input [20] > 0.3 24.00 0.07 2097156 0.00 0.00 getsock [65] > 0.3 24.07 0.07 1048576 0.00 0.00 udp_send [22] > > It is very strange that spinlock_exit consumes over 36% CPU time while it > seems a very simple function. > > For clarity, I paste the code of spinlock_exit here: > > void > spinlock_exit(void) > { > struct thread *td; > > td = curthread; > critical_exit(); > td->td_md.md_spinlock_count--; > if (td->td_md.md_spinlock_count == 0) > intr_restore(td->td_md.md_saved_flags); > } > > Since critical_exit consumes only 0.4% CPU time, does this mean the rest of > spinlock_exit consume ~36% CPU time? > > Am I missing something? Could anybody help me understand this? Many thanks. > > BTW, the kernel is compiled with SMP and PREEMPTION disabled. The scheduler > is ULE. What FreeBSD version, and what build date of the kernel? -- | Jeremy Chadwick jdc at parodius.com | | Parodius Networking http://www.parodius.com/ | | UNIX Systems Administrator Mountain View, CA, USA | | Making life hard for others since 1977. PGP: 4BD6C0CB |