sigwait延时较大的原因

使用cyclictest对sigwait做了分析，大体如下：

 

命令：trace-cmd start -e all;./cyclictest -p 90 -m -c 0 -i 1000 -a 3 -b 300

 

日志分析：

1）正常的流程

irq_handler_entry -- ktimersoftirq -- cyclictest

2)本例

在测试过程中，来了一个中断，irq_handler_entry:    irq=39 name=nvme0q4

然后进入了该中断的处理线程irq/39-n-131，然后在此期间，时钟中断到时，本来应该切换到ktimersoftirq，但由于irq/39-n-131优先级更高，则irq/39-n-131继续运行，运行了很长时间。

等irq/39-n-131完成任务，让出了cpu，就到了ktimersoftirq -- cyclictest，早已经超时。

 

这个问题类似于优先级的反转。具体信息见下面的日志文件：

====这是一个磁盘的中断
  stress-2161    3d.h.0   776.747814: irq_handler_entry:    irq=39 name=nvme0q4
  stress-2161    3d.h.0   776.747814: irq_handler_exit:     irq=39 ret=handled
  stress-2161    3d.h10   776.747815: sched_waking:         comm=irq/39-nvme0q4 pid=131 prio=49 target_cpu=003
  stress-2161    3dNh20   776.747817: sched_wakeup:         irq/39-nvme0q4:131 [49] success=1 CPU:003
  stress-2161    3dNh.0   776.747818: preempt_enable:       caller=irq_exit+0x30 parent=irq_exit+0x30
  stress-2161    3dN..0   776.747819: irq_enable:           caller=el0_irq_naked+0x5c parent=0xffff000100000000
  stress-2161    3dN..0   776.747820: irq_disable:          caller=do_notify_resume+0x34 parent=work_pending+0x8
  stress-2161    3dN.10   776.747821: preempt_disable:      caller=schedule+0x3c parent=schedule+0x3c
  stress-2161    3dN.10   776.747821: rcu_utilization:      Start context switch
  stress-2161    3dN.10   776.747821: rcu_utilization:      End context switch
  stress-2161    3dN.20   776.747822: sched_stat_runtime:   comm=stress pid=2161 runtime=6375 [ns] vruntime=32989505945 [ns]
  stress-2161    3d..20   776.747824: sched_switch:         stress:2161 [120] R ==> irq/39-nvme0q4:131 [49]

====进入了磁盘处理的中断线程
irq/39-n-131     3d..20   776.747825: irq_enable:           caller=_raw_spin_unlock_irq+0x24 parent=finish_task_switch+0xb8
irq/39-n-131     3d..20   776.747826: irq_disable:          caller=rcu_irq_enter_irqson+0x30 parent=trace_preempt_on+0xcc
irq/39-n-131     3d..20   776.747826: irq_enable:           caller=rcu_irq_enter_irqson+0x40 parent=trace_preempt_on+0xcc
irq/39-n-131     3...10   776.747827: preempt_enable:       caller=schedule+0x4c parent=schedule+0x4c
irq/39-n-131     3d..20   776.747827: irq_disable:          caller=rcu_irq_exit_irqson+0x30 parent=trace_preempt_on+0xf4
......
irq/39-n-131     3d..23   776.748130: irq_disable:          caller=el1_irq+0x7c parent=rcu_irq_exit_irqson+0x44

==============这是一个cyclictest设置的timer，它的中断来了
irq/39-n-131     3d.h23   776.748131: irq_handler_entry:    irq=2 name=arch_timer
irq/39-n-131     3d.h33   776.748132: softirq_raise:        vec=8 [action=HRTIMER]
irq/39-n-131     3d.h23   776.748133: irq_handler_exit:     irq=2 ret=handled

irq/39-n-131     3d..33   776.748134: sched_waking:         comm=ktimersoftd/3 pid=39 prio=98 target_cpu=003
irq/39-n-131     3d..43   776.748134: sched_wakeup:         ktimersoftd/3:39 [98] success=1 CPU:003
原本应该唤醒ktimersoftd，但irq/39-n-131应该使有更高的优先级，所以并没有发生任务切换，irq/39-n-131继续运行

irq/39-n-131     3d..23   776.748135: irq_enable:           caller=el1_irq+0xe4 parent=rcu_irq_exit_irqson+0x44
......
irq/39-n-131     3d..10   776.752538: rcu_utilization:      Start context switch
irq/39-n-131     3d..10   776.752538: rcu_utilization:      End context switch
===直到irq/39-n-131完成了工作

irq/39-n-131     3d..20   776.752540: sched_switch:         irq/39-nvme0q4:131 [49] S ==> ktimersoftd/3:39 [98]

===然后才是ktimerso-39--cyclictest，但已经很晚了
ktimerso-39      3d..20   776.752541: irq_enable:           caller=_raw_spin_unlock_irq+0x24 parent=finish_task_switch+0xb8
......
ktimerso-39      3dN.15   776.752603: rcu_utilization:      Start context switch
ktimerso-39      3dN.15   776.752604: rcu_utilization:      End context switch
ktimerso-39      3d..25   776.752605: sched_switch:         ktimersoftd/3:39 [98] R ==> cyclictest:2132 [9]
cyclicte-2132    3d..20   776.752606: irq_enable:           caller=_raw_spin_unlock_irq+0x24 parent=finish_task_switch+0xb8
cyclicte-2132    3d..20   776.752607: irq_disable:          caller=rcu_irq_enter_irqson+0x30 parent=trace_preempt_on+0xcc
cyclicte-2132    3d..20   776.752608: irq_enable:           caller=rcu_irq_enter_irqson+0x40 parent=trace_preempt_on+0xcc
cyclicte-2132    3...10   776.752608: preempt_enable:       caller=schedule+0x4c parent=schedule+0x4c
cyclicte-2132    3d..20   776.752609: irq_disable:          caller=rcu_irq_exit_irqson+0x30 parent=trace_preempt_on+0xf4
cyclicte-2132    3d..20   776.752609: irq_enable:           caller=rcu_irq_exit_irqson+0x40 parent=trace_preempt_on+0xf4