kernel profiling: spinlock_exit consumes 36% CPU time.

[邱剑]

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 邱剑 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]
>
> 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