Date: Wed, 08 Oct 2008 15:11:40 +0800 From: =?gb2312?B?x/G9ow==?= <qj@huawei.com> To: 'Jeremy Chadwick' <koitsu@FreeBSD.org> Cc: freebsd-net@FreeBSD.org, freebsd-questions@freebsd.org, freebsd-threads@freebsd.org Subject: RE: kernel profiling: spinlock_exit consumes 36% CPU time. Message-ID: <000301c92915$1cd0ae60$01000001@china.huawei.com> In-Reply-To: <20081007115748.GA48154@icarus.home.lan>
next in thread | previous in thread | raw e-mail | index | archive | help
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 |
Want to link to this message? Use this URL: <https://mail-archive.FreeBSD.org/cgi/mid.cgi?000301c92915$1cd0ae60$01000001>