Re: [tracing] trying to make sense of trace output, can't figure out where time is going

[Mike Galbraith <umgwanakikbuti@gmail.com>]

On Wed, 2014-09-03 at 15:07 -0600, Chris Friesen wrote:

> kvm-23696   4d...3.. 507584570us : sched_switch: prev_comm=kvm prev_pid=23696 prev_prio=120 prev_state=R+ ==> next_comm=ksoftirqd/4 next_pid=80 next_prio=98
> ksoftirq-80      4....111 507584570us!: softirq_entry: vec=1 [action=TIMER]

> I'm trying to figure out what would cause that jump between the first
> two ksoftirqd logs.
> 
> Some stuff in /proc/cmdline that might be relevent (it's a bit of a mishmash,
> I know):
> 
> intel_iommu=off isolcpus=1-15 rcu_nocbs=1-15 irqaffinity=0
> intel_idle.max_cstate=0 processor.max_cstate=1 idle=poll
> 
> 
> In the BIOS we've disabled speedstep, CPU C states, and NMI on
> error.
> 
> Is there a different tracer that would give more insight?  The irqs-off or
> preemption-off tracers perhaps?

I'd try to take a snapshot with the function tracer.  Add a couple
trace_printk()s, set a tracing_off() trap for TIMER sirq processing
taking ages, stare at resulting 8x10 color glossy.

-Mike