Date: Tue, 07 Oct 2008 19:44:00 +0800 From: =?gb2312?B?x/G9ow==?= <qj@huawei.com> To: freebsd-questions@freebsd.org Cc: freebsd-net@FreeBSD.org, freebsd-threads@freebsd.org Subject: kernel profiling: spinlock_exit consumes 36% CPU time. Message-ID: <004001c92871$fdec0a10$01000001@china.huawei.com>
next in thread | raw e-mail | index | archive | help
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
Want to link to this message? Use this URL: <https://mail-archive.FreeBSD.org/cgi/mid.cgi?004001c92871$fdec0a10$01000001>