From owner-freebsd-net@FreeBSD.ORG Wed Oct 8 07:13:10 2008 Return-Path: Delivered-To: freebsd-net@FreeBSD.org Received: from mx1.freebsd.org (mx1.freebsd.org [IPv6:2001:4f8:fff6::34]) by hub.freebsd.org (Postfix) with ESMTP id 23D7110656D9; Wed, 8 Oct 2008 07:13:10 +0000 (UTC) (envelope-from qj@huawei.com) Received: from szxga02-in.huawei.com (szxga02-in.huawei.com [119.145.14.65]) by mx1.freebsd.org (Postfix) with ESMTP id CD7FD8FC2F; Wed, 8 Oct 2008 07:13:09 +0000 (UTC) (envelope-from qj@huawei.com) Received: from huawei.com (szxga02-in [172.24.2.6]) by szxga02-in.huawei.com (iPlanet Messaging Server 5.2 HotFix 2.14 (built Aug 8 2006)) with ESMTP id <0K8E00L7NRZK4Y@szxga02-in.huawei.com>; Wed, 08 Oct 2008 15:11:44 +0800 (CST) Received: from huawei.com ([172.24.1.12]) by szxga02-in.huawei.com (iPlanet Messaging Server 5.2 HotFix 2.14 (built Aug 8 2006)) with ESMTP id <0K8E00IHGRZKD4@szxga02-in.huawei.com>; Wed, 08 Oct 2008 15:11:44 +0800 (CST) Received: from q00130354 ([10.111.9.38]) by szxml05-in.huawei.com (iPlanet Messaging Server 5.2 HotFix 2.14 (built Aug 8 2006)) with ESMTPA id <0K8E00A8ZRZFIX@szxml05-in.huawei.com>; Wed, 08 Oct 2008 15:11:44 +0800 (CST) Date: Wed, 08 Oct 2008 15:11:40 +0800 From: =?gb2312?B?x/G9ow==?= In-reply-to: <20081007115748.GA48154@icarus.home.lan> To: 'Jeremy Chadwick' Message-id: <000301c92915$1cd0ae60$01000001@china.huawei.com> MIME-version: 1.0 X-MIMEOLE: Produced By Microsoft MimeOLE V6.00.2900.3350 X-Mailer: Microsoft Office Outlook 11 Content-type: text/plain; charset=gb2312 Content-transfer-encoding: 7BIT Thread-index: AckodL2oSBjwz6W/R9ecg3XW/kxmlwAoABWQ 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-net@freebsd.org X-Mailman-Version: 2.1.5 Precedence: list List-Id: Networking and TCP/IP with FreeBSD List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , X-List-Received-Date: Wed, 08 Oct 2008 07:13:10 -0000 Forgot to meantion that the test is based on FreeBSD kernel 7.0 2000807 snapshot. The kernel was compiled with a modified version of GENERIC configuration. With SMP and PREEMPTION disabled and kernel profiling enabled. -----Original Message----- From: Jeremy Chadwick [mailto:koitsu@FreeBSD.org] Sent: Tuesday, October 07, 2008 7:58 PM To: ???? Cc: freebsd-questions@freebsd.org; freebsd-net@FreeBSD.org; freebsd-threads@freebsd.org Subject: Re: kernel profiling: spinlock_exit consumes 36% CPU time. 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 |