why does this irqsoff tracer output show interrupts disabled between irq to softirq transition?

why does this irqsoff tracer output show interrupts disabled between irq to softirq transition?

[Joel Fernandes]

Hi,

I am using the irqsoff tracer on a (slightly old) kernel and I am seeing something like this. 
As you can see, after servicing the hrtimer_interrupt, and calling irq_exit(), a softirq runs.

But the softirq (which happens to be run_timer_softirq) is being called with interrupts 
disabled, - but from my understanding, interrupts are to remain enabled during softirq 
operation (unless ofcourse a spinlock is shared between a softirq and an irq handler and 
someone calls spinlock_irq_save).

So considering this, does the below makes sense?  Thanks for any insight!


  mmcqd/0-1435    0d.h1  182us : preempt_count_add <-_raw_spin_lock
  mmcqd/0-1435    0d.h2  182us : enqueue_hrtimer <-__run_hrtimer
  mmcqd/0-1435    0d.h2  183us : _raw_spin_unlock <-hrtimer_interrupt
  mmcqd/0-1435    0d.h2  183us : preempt_count_sub <-_raw_spin_unlock
  mmcqd/0-1435    0d.h1  184us : tick_program_event <-hrtimer_interrupt
  mmcqd/0-1435    0d.h1  184us : clockevents_program_event <-tick_program_event
  mmcqd/0-1435    0d.h1  184us : ktime_get <-clockevents_program_event
  mmcqd/0-1435    0d.h1  185us : lapic_next_deadline <-clockevents_program_event
  mmcqd/0-1435    0d.h1  186us : irq_exit <-smp_apic_timer_interrupt
  mmcqd/0-1435    0d.h1  186us : irqtime_account_irq <-irq_exit
  mmcqd/0-1435    0d.h1  187us : preempt_count_sub <-irq_exit
  mmcqd/0-1435    0d..1  187us : __do_softirq <-irq_exit
  mmcqd/0-1435    0d..1  188us : msecs_to_jiffies <-__do_softirq
  mmcqd/0-1435    0d..1  188us : irqtime_account_irq <-__do_softirq
  mmcqd/0-1435    0d..1  188us : __local_bh_disable_ip <-__do_softirq
  mmcqd/0-1435    0d.s1  190us : preempt_count_add <-_raw_spin_lock_irq
  mmcqd/0-1435    0d.s2  191us+: _raw_spin_unlock_irq <-run_timer_softirq
  mmcqd/0-1435    0d.s1  194us : preempt_count_add <-_raw_read_lock_irqsave
  mmcqd/0-1435    0d.s2  195us+: _raw_read_unlock_irqrestore <-cpufreq_cpu_get
  mmcqd/0-1435    0d.s1  201us : preempt_count_add <-_raw_spin_lock_irqsave
  mmcqd/0-1435    0d.s2  202us : _raw_spin_unlock_irqrestore <-cpufreq_stats_update
  mmcqd/0-1435    0d.s1  203us : preempt_count_add <-_raw_spin_lock_irqsave
  mmcqd/0-1435    0d.s2  203us+: _raw_spin_unlock_irqrestore <-cpufreq_stat_notifier_trans
  mmcqd/0-1435    0d.s1  205us : preempt_count_add <-_raw_spin_lock_irqsave
  mmcqd/0-1435    0d.s2  205us : detach_if_pending <-mod_timer_pinned
  mmcqd/0-1435    0d.s2  206us : internal_add_timer <-mod_timer_pinned
  mmcqd/0-1435    0d.s2  207us : __internal_add_timer <-internal_add_timer

Re: why does this irqsoff tracer output show interrupts disabled between irq to softirq transition?

[Joel Fernandes]

On 03/01/16 21:37, Joel Fernandes wrote:
> Hi,
>
> I am using the irqsoff tracer on a (slightly old) kernel and I am seeing something like this.
> As you can see, after servicing the hrtimer_interrupt, and calling irq_exit(), a softirq runs.
>
> But the softirq (which happens to be run_timer_softirq) is being called with interrupts
> disabled, - but from my understanding, interrupts are to remain enabled during softirq
> operation (unless ofcourse a spinlock is shared between a softirq and an irq handler and
> someone calls spinlock_irq_save).
>
> So considering this, does the below makes sense?  Thanks for any insight!
>
>
>   mmcqd/0-1435    0d.h1  182us : preempt_count_add <-_raw_spin_lock
>   mmcqd/0-1435    0d.h2  182us : enqueue_hrtimer <-__run_hrtimer
>   mmcqd/0-1435    0d.h2  183us : _raw_spin_unlock <-hrtimer_interrupt
>   mmcqd/0-1435    0d.h2  183us : preempt_count_sub <-_raw_spin_unlock
>   mmcqd/0-1435    0d.h1  184us : tick_program_event <-hrtimer_interrupt
>   mmcqd/0-1435    0d.h1  184us : clockevents_program_event <-tick_program_event
>   mmcqd/0-1435    0d.h1  184us : ktime_get <-clockevents_program_event
>   mmcqd/0-1435    0d.h1  185us : lapic_next_deadline <-clockevents_program_event
>   mmcqd/0-1435    0d.h1  186us : irq_exit <-smp_apic_timer_interrupt
>   mmcqd/0-1435    0d.h1  186us : irqtime_account_irq <-irq_exit
>   mmcqd/0-1435    0d.h1  187us : preempt_count_sub <-irq_exit
>   mmcqd/0-1435    0d..1  187us : __do_softirq <-irq_exit
>   mmcqd/0-1435    0d..1  188us : msecs_to_jiffies <-__do_softirq
>   mmcqd/0-1435    0d..1  188us : irqtime_account_irq <-__do_softirq
>   mmcqd/0-1435    0d..1  188us : __local_bh_disable_ip <-__do_softirq
>   mmcqd/0-1435    0d.s1  190us : preempt_count_add <-_raw_spin_lock_irq
>   mmcqd/0-1435    0d.s2  191us+: _raw_spin_unlock_irq <-run_timer_softirq
>   mmcqd/0-1435    0d.s1  194us : preempt_count_add <-_raw_read_lock_irqsave
>   mmcqd/0-1435    0d.s2  195us+: _raw_read_unlock_irqrestore <-cpufreq_cpu_get
>   mmcqd/0-1435    0d.s1  201us : preempt_count_add <-_raw_spin_lock_irqsave
>   mmcqd/0-1435    0d.s2  202us : _raw_spin_unlock_irqrestore <-cpufreq_stats_update
>   mmcqd/0-1435    0d.s1  203us : preempt_count_add <-_raw_spin_lock_irqsave
>   mmcqd/0-1435    0d.s2  203us+: _raw_spin_unlock_irqrestore <-cpufreq_stat_notifier_trans
>   mmcqd/0-1435    0d.s1  205us : preempt_count_add <-_raw_spin_lock_irqsave
>   mmcqd/0-1435    0d.s2  205us : detach_if_pending <-mod_timer_pinned
>   mmcqd/0-1435    0d.s2  206us : internal_add_timer <-mod_timer_pinned
>   mmcqd/0-1435    0d.s2  207us : __internal_add_timer <-internal_add_timer

Sorry about the noise. I believe I was using 'preemptirqsoff' tracer and in this path 
preemption was off (preempt count was non zero), so even if the interrupts were reenabled 
before the softirq, the tracer would continue to trace.

I guess the 'd' is a bit misleading in the trace I provided above, because it didn't show the 
'd' go away in the softirq path, but I suppose no function was traced after the interrupts 
re-enabled before the softirq and then a spinlock_irq was called in the softirq path so the 'd' 
continue to persist.

Thanks,

Joel