From owner-freebsd-threads@FreeBSD.ORG Tue Oct 7 11:54:11 2008 Return-Path: Delivered-To: freebsd-threads@freebsd.org Received: from mx1.freebsd.org (mx1.freebsd.org [IPv6:2001:4f8:fff6::34]) by hub.freebsd.org (Postfix) with ESMTP id 67C501065693; Tue, 7 Oct 2008 11:54:11 +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 095B98FC17; Tue, 7 Oct 2008 11:54:10 +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 <0K8D00BEE9XGRL@szxga02-in.huawei.com>; Tue, 07 Oct 2008 19:44:05 +0800 (CST) Received: from huawei.com ([172.24.1.18]) by szxga02-in.huawei.com (iPlanet Messaging Server 5.2 HotFix 2.14 (built Aug 8 2006)) with ESMTP id <0K8D00H4R9XGTN@szxga02-in.huawei.com>; Tue, 07 Oct 2008 19:44:04 +0800 (CST) Received: from q00130354 ([10.111.9.38]) by szxml03-in.huawei.com (iPlanet Messaging Server 5.2 HotFix 2.14 (built Aug 8 2006)) with ESMTPA id <0K8D00GJZ9XDFL@szxml03-in.huawei.com>; Tue, 07 Oct 2008 19:44:04 +0800 (CST) Date: Tue, 07 Oct 2008 19:44:00 +0800 From: =?gb2312?B?x/G9ow==?= To: freebsd-questions@freebsd.org Message-id: <004001c92871$fdec0a10$01000001@china.huawei.com> MIME-version: 1.0 X-MIMEOLE: Produced By Microsoft MimeOLE V6.00.2900.3350 X-Mailer: Microsoft Office Outlook 11 Thread-index: Ackocf2blBPcE5DVRuCv/5eRYj2bEg== Content-Type: text/plain; charset=gb2312 Content-Transfer-Encoding: 7BIT X-Content-Filtered-By: Mailman/MimeDel 2.1.5 Cc: freebsd-net@FreeBSD.org, freebsd-threads@freebsd.org Subject: kernel profiling: spinlock_exit consumes 36% CPU time. X-BeenThere: freebsd-threads@freebsd.org X-Mailman-Version: 2.1.5 Precedence: list List-Id: Threading on FreeBSD List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , X-List-Received-Date: Tue, 07 Oct 2008 11:54:11 -0000 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. Best regards, Qiu Jian