From owner-freebsd-questions@FreeBSD.ORG Wed Oct 8 07:51:53 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 E9A061065686; Wed, 8 Oct 2008 07:51:53 +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 A07F58FC1B; Wed, 8 Oct 2008 07:51:53 +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 <0K8E00LF6TUE4Y@szxga02-in.huawei.com>; Wed, 08 Oct 2008 15:51:51 +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 <0K8E0089STUEOM@szxga02-in.huawei.com>; Wed, 08 Oct 2008 15:51:50 +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 <0K8E00A5FTUBIX@szxml05-in.huawei.com>; Wed, 08 Oct 2008 15:51:50 +0800 (CST) Date: Wed, 08 Oct 2008 15:51:48 +0800 From: =?gb2312?B?x/G9ow==?= In-reply-to: <200810070938.04673.jhb@freebsd.org> To: 'John Baldwin' , freebsd-threads@freebsd.org Message-id: <000a01c9291a$b81fa560$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: quoted-printable Thread-index: Ackoh6RcgD3LVNMBRcCYxgZdMuMjiAAjXuVw X-Mailman-Approved-At: Wed, 08 Oct 2008 11:30:16 +0000 Cc: freebsd-net@freebsd.org, freebsd-questions@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: Wed, 08 Oct 2008 07:51:54 -0000 Many thanks for the information. Could we say that interrupt handlers consumed ~36% execution time? Is this number too high? Is it possible that we abuse the use of = critical sections in kernel? Looking forward to your options. Many thanks. Qiu Jian On Tuesday 07 October 2008 07:44:00 am =C7=F1=BD=A3 wrote: > Hi, folks, > =20 > I did kernel profiling when a single thread client sends UDP packets=20 > to a single thread server on the same machine. > =20 > In the output kernel profile, the first few kernel functions that=20 > consumes the most CPU time are listed below: > =20 > granularity: each sample hit covers 16 byte(s) for 0.01% of 25.68=20 > seconds >=20 > % 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] > > It is very strange that spinlock_exit consumes over 36% CPU time while = > it seems a very simple function. It's because the intr_restore() re-enables interrupts and the resulting = time spent executing the handlers for any pending interrupts are attributed = to spinlock_exit(). -- John Baldwin