Am I reading this wrong? Is this really 12ms to acquire a spin_lock? What could cause this?

mpstat shows about 48% of time spent in softirqs

Please help me understand what might cause this.

Just switched from an older kernel version where didn't have this issue.




# tracer: irqsoff
#
irqsoff latency trace v1.1.5 on 2.6.27
--------------------------------------------------------------------
latency: 12217 us, #12/12, CPU#6 | (M:server VP:0, KP:0, SP:0 HP:0 #P:8)
-----------------
| task: swapper-0 (uid:0 nice:0 policy:0 rt_prio:0)
-----------------
=> started at: __wake_up_sync+0x2e/0x70 <ffffffff8023280e>
=> ended at: __wake_up_sync+0x55/0x70 <ffffffff80232835>

<idle> 0 6 11 00000000 00000000 [d3174fac] 0.000ms (+0.000ms): _spin_lock_irqsave+0x22/0x50 <ffffffff806deca2> (__wake_up_sync+0x2e/0x70 <ffffffff8023280e>)
<idle> 0 6 11 00000000 00000001 [d3174fac] 0.000ms (+0.000ms): ep_poll_callback+0x14/0xf0 <ffffffff802dfbe4> (__wake_up_common+0x5a/0x90 <ffffffff8023126a>)
<idle> 0 6 11 00000000 00000002 [d3174fac] 0.000ms (+0.000ms): _spin_lock_irqsave+0x11/0x50 <ffffffff806dec91> (ep_poll_callback+0x29/0xf0 <ffffffff802dfbf9>)
<idle> 0 6 11 00000000 00000003 [d3174fac] 0.000ms (+12.218ms): _spin_lock+0x4/0x20 <ffffffff806de864> (task_rq_lock+0x54/0xa0 <ffffffff802329f4>)
<idle> 0 6 11 00000000 00000004 [d3177f66] 12.218ms (+0.000ms): native_smp_send_reschedule+0x4/0x60 <ffffffff8021f944> (resched_task+0x68/0x80 <ffffffff80230648>)
<idle> 0 6 11 00000000 00000005 [d3177f66] 12.218ms (+0.000ms): flat_send_IPI_mask+0x14/0xa0 <ffffffff80225b04> (native_smp_send_reschedule+0x3f/0x60 <ffffffff8021f97f>)
<idle> 0 6 11 00000000 00000006 [d3177f66] 12.218ms (+0.000ms): apic_wait_icr_idle+0x4/0x30 <ffffffff80220244> (flat_send_IPI_mask+0x31/0xa0 <ffffffff80225b21>)
<idle> 0 6 11 00000000 00000007 [d3177f66] 12.218ms (+0.000ms): _spin_unlock_irqrestore+0x9/0x40 <ffffffff806deb19> (try_to_wake_up+0x134/0x1f0 <ffffffff80237594>)
<idle> 0 6 11 00000000 00000008 [d3177f66] 12.218ms (+0.000ms): _spin_unlock_irqrestore+0x9/0x40 <ffffffff806deb19> (ep_poll_callback+0x40/0xf0 <ffffffff802dfc10>)
<idle> 0 6 11 00000000 00000009 [d3177f66] 12.218ms (+0.000ms): _spin_unlock_irqrestore+0x9/0x40 <ffffffff806deb19> (__wake_up_sync+0x55/0x70 <ffffffff80232835>)
<idle> 0 6 11 00000000 0000000a [d3177f66] 12.218ms (+0.000ms): _spin_unlock_irqrestore+0x1d/0x40 <ffffffff806deb2d> (__wake_up_sync+0x55/0x70 <ffffffff80232835>)
<idle> 0 6 11 00000000 0000000b [d3177f66] 12.218ms (+0.000ms): trace_hardirqs_on+0x10e/0x140 <ffffffff8027d15e> (__wake_up_sync+0x55/0x70 <ffffffff80232835>)