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>
index | next in thread | raw e-mail
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
home |
help
Want to link to this message? Use this
URL: <https://mail-archive.FreeBSD.org/cgi/mid.cgi?004001c92871$fdec0a10$01000001>