唤醒进程（wake_up_process）到进程真正执行延迟较大

瀚海书香

回复 40# humjb_1983

1、__switch_to这个函数统计的800多us，应该是从 <idle>-0    =>  0_main_-680 => <idle>-0 的时间，并非<idle>-0    =>  0_main_-680 的时间。
   也就是说这个800us，包含，从idle切换到A进程+A进程自身的执行时间+A进程重新切换回idle的时间。这800us中，很有可能是A进程自身的执行时间消耗掉了。
   因为这个__switch_to实际是在idle进程的进程上下文中执行的，当idle进程被调度出去(切换到A)，然后重新回到idle进程执行时，返回的地方就是
   __switch_to返回的地方，后面会接着执行finish_task_switch()
    所以，这里统计到的__switch_to的执行时间，个人理解并不代表从idle切换到A的进程上下文切换时间。

@humjb_1983@noted2011
由于ftrace的 function graph的return的时间点通过修改return地址添加trigger来获取，而__switch_to函数会切换栈，那么返回地址可能发生变化，所以__switch_to函数不能使用function graph的tracer

1. 
   
2. /*
   
3. *      switch_to(x,y) should switch tasks from x to y.
   
4. *
   
5. * This could still be optimized:
   
6. * - fold all the options into a flag word and test it with a single test.
   
7. * - could test fs/gs bitsliced
   
8. *
   
9. * Kprobes not supported here. Set the probe on schedule instead.
   
10. * Function graph tracer not supported too.
    
11. */
    
12. __visible __notrace_funcgraph struct task_struct *
    
13. __switch_to(struct task_struct *prev_p, struct task_struct *next_p)
    
14. {

复制代码

humjb_1983

瀚海书香 发表于 2014-02-19 19:24
回复 40# humjb_1983

@humjb_1983@noted2011

呵呵，瀚海兄的这个很有说服力~，看来确实如此。
建议lz还是直接在相关的关键流程处打点，获取时间差。
另外，之前lz说的情况是延时出现的几率只有万分之几，而你此前采集的数据中的大延时基本都是一致的，所以应该不是问题。

noted2011

瀚海书香 发表于 2014-02-19 19:24
回复 40# humjb_1983

@humjb_1983@noted2011

首先特别感谢大家，特别是瀚海书香 和humjb_1983。
我查看了一下源码，x86_64平台，的确有你说的这个限制__notrace_funcgraph。
忘记之前说我们这个平台用的是powerpc平台，不好意思。我看了一下源代码，powerpc实现的__switch_to没有__notrace_funcgraph。具体代码：

1. 
   
2. struct task_struct *__switch_to(struct task_struct *prev,
   
3.         struct task_struct *new)
   
4. {
   
5.         struct thread_struct *new_thread, *old_thread;
   
6.         unsigned long flags;
   
7.         struct task_struct *last;
   
8. #if defined(CONFIG_PPC64) && defined (CONFIG_PREEMPT_RT)
   
9.         struct ppc64_tlb_batch *batch;
   
10.         int hadbatch;
    
11. #endif
    
12. 
    
13. #ifdef CONFIG_SMP
    
14.         /* avoid complexity of lazy save/restore of fpu
    
15.          * by just saving it every time we switch out if
    
16.          * this task used the fpu during the last quantum.
    
17.          *
    
18.          * If it tries to use the fpu again, it'll trap and
    
19.          * reload its fp regs.  So we don't have to do a restore
    
20.          * every switch, just a save.
    
21.          *  -- Cort
    
22.          */
    
23.         if (prev->thread.regs && (prev->thread.regs->msr & MSR_FP))
    
24.                 giveup_fpu(prev);
    
25. #ifdef CONFIG_ALTIVEC
    
26.         /*
    
27.          * If the previous thread used altivec in the last quantum
    
28.          * (thus changing altivec regs) then save them.
    
29.          * We used to check the VRSAVE register but not all apps
    
30.          * set it, so we don't rely on it now (and in fact we need
    
31.          * to save & restore VSCR even if VRSAVE == 0).  -- paulus
    
32.          *
    
33.          * On SMP we always save/restore altivec regs just to avoid the
    
34.          * complexity of changing processors.
    
35.          *  -- Cort
    
36.          */
    
37.         if (prev->thread.regs && (prev->thread.regs->msr & MSR_VEC))
    
38.                 giveup_altivec(prev);
    
39. #endif /* CONFIG_ALTIVEC */
    
40. #ifdef CONFIG_VSX
    
41.         if (prev->thread.regs && (prev->thread.regs->msr & MSR_VSX))
    
42.                 /* VMX and FPU registers are already save here */
    
43.                 __giveup_vsx(prev);
    
44. #endif /* CONFIG_VSX */
    
45. #ifdef CONFIG_SPE
    
46.         /*
    
47.          * If the previous thread used spe in the last quantum
    
48.          * (thus changing spe regs) then save them.
    
49.          *
    
50.          * On SMP we always save/restore spe regs just to avoid the
    
51.          * complexity of changing processors.
    
52.          */
    
53.         if ((prev->thread.regs && (prev->thread.regs->msr & MSR_SPE)))
    
54.                 giveup_spe(prev);
    
55. #endif /* CONFIG_SPE */
    
56. 
    
57. #else  /* CONFIG_SMP */
    
58. #ifdef CONFIG_ALTIVEC
    
59.         /* Avoid the trap.  On smp this this never happens since
    
60.          * we don't set last_task_used_altivec -- Cort
    
61.          */
    
62.         if (new->thread.regs && last_task_used_altivec == new)
    
63.                 new->thread.regs->msr |= MSR_VEC;
    
64. #endif /* CONFIG_ALTIVEC */
    
65. #ifdef CONFIG_VSX
    
66.         if (new->thread.regs && last_task_used_vsx == new)
    
67.                 new->thread.regs->msr |= MSR_VSX;
    
68. #endif /* CONFIG_VSX */
    
69. #ifdef CONFIG_SPE
    
70.         /* Avoid the trap.  On smp this this never happens since
    
71.          * we don't set last_task_used_spe
    
72.          */
    
73.         if (new->thread.regs && last_task_used_spe == new)
    
74.                 new->thread.regs->msr |= MSR_SPE;
    
75. #endif /* CONFIG_SPE */
    
76. 
    
77. #endif /* CONFIG_SMP */
    
78. 
    
79. #ifdef CONFIG_PPC_ADV_DEBUG_REGS
    
80.         switch_booke_debug_regs(&new->thread);
    
81. #else
    
82.         if (unlikely(__get_cpu_var(current_dabr) != new->thread.dabr))
    
83.                 set_dabr(new->thread.dabr);
    
84. #endif
    
85. 
    
86. 
    
87.         new_thread = &new->thread;
    
88.         old_thread = &current->thread;
    
89. 
    
90. #ifdef CONFIG_PPC64
    
91.         /*
    
92.          * Collect processor utilization data per process
    
93.          */
    
94.         if (firmware_has_feature(FW_FEATURE_SPLPAR)) {
    
95.                 struct cpu_usage *cu = &__get_cpu_var(cpu_usage_array);
    
96.                 long unsigned start_tb, current_tb;
    
97.                 start_tb = old_thread->start_tb;
    
98.                 cu->current_tb = current_tb = mfspr(SPRN_PURR);
    
99.                 old_thread->accum_tb += (current_tb - start_tb);
    
100.                 new_thread->start_tb = current_tb;
     
101.         }
     
102. 
     
103. #ifdef CONFIG_PREEMPT_RT
     
104.         batch = &__get_cpu_var(ppc64_tlb_batch);
     
105.         if (batch->active) {
     
106.                 hadbatch = 1;
     
107.                 if (batch->index) {
     
108.                         __flush_tlb_pending(batch);
     
109.                 }
     
110.                 batch->active = 0;
     
111.         }
     
112. #endif /* #ifdef CONFIG_PREEMPT_RT */
     
113. #endif
     
114. 
     
115.         local_irq_save(flags);
     
116. 
     
117.         account_system_vtime(current);
     
118.         account_process_vtime(current);
     
119.         calculate_steal_time();
     
120. 
     
121.         /*
     
122.          * We can't take a PMU exception inside _switch() since there is a
     
123.          * window where the kernel stack SLB and the kernel stack are out
     
124.          * of sync. Hard disable here.
     
125.          */
     
126.         hard_irq_disable();
     
127.         last = _switch(old_thread, new_thread);
     
128. 
     
129.         local_irq_restore(flags);
     
130. 
     
131. #if defined(CONFIG_PPC64) && defined(CONFIG_PREEMPT_RT)
     
132.         if (hadbatch) {
     
133.                 batch = &__get_cpu_var(ppc64_tlb_batch);
     
134.                 batch->active = 1;
     
135.         }
     
136. #endif
     
137. 
     
138.         return last;
     
139. }
     

复制代码

前期测试的时间不是很长，同时用ftrace又再跟踪了一下，的确__switch_to（<idle>-0    =>  1_l2_Ma-734）有1089.664 us（正常的是800多us），整个syscall(sys_wait_wakeup)的时间有1216.640 us，整个延迟有200多us。因为ftrace的数据量比较大，找到异常的地方不容易，就没有抓取延迟有800多us的。
ftrace的部分测试数据：
1)               |  sys_wait_wakeup() {
1)   0.864 us    |    __osp_int_wake_reg();
1)               |    schedule() {
1)               |      __schedule() {
1)   1.056 us    |        rcu_sched_qs();
1)   0.960 us    |        add_preempt_count();
1)               |        _raw_spin_lock_irq() {
1)               |          __raw_spin_lock_irqsave() {
1)   0.864 us    |            add_preempt_count();
1)   2.688 us    |          }
1)   4.640 us    |        }
1)               |        deactivate_task() {
1)               |          dequeue_task() {
1)               |            dequeue_task_rt() {
1)               |              update_curr_rt() {
1)               |                _raw_spin_lock() {
1)               |                  __raw_spin_lock() {
1)   0.864 us    |                    add_preempt_count();
1)   2.720 us    |                  }
1)   4.480 us    |                }
1)   0.960 us    |                balance_runtime();
1)               |                _raw_spin_unlock() {
1)   0.928 us    |                  sub_preempt_count();
1)   2.720 us    |                }
1) + 12.768 us   |              }
1)               |              __dequeue_rt_entity() {
1)               |                cpupri_set() {
1)               |                  _raw_spin_lock_irqsave() {
1)               |                    __raw_spin_lock_irqsave() {
1)   0.928 us    |                      add_preempt_count();
1)   2.816 us    |                    }
1)   4.512 us    |                  }
1)               |                  _raw_spin_unlock_irqrestore() {
1)   0.864 us    |                    sub_preempt_count();
1)   2.720 us    |                  }
1)               |                  _raw_spin_lock_irqsave() {
1)               |                    __raw_spin_lock_irqsave() {
1)   0.896 us    |                      add_preempt_count();
1)   2.816 us    |                    }
1)   4.544 us    |                  }
1)               |                  _raw_spin_unlock_irqrestore() {
1)   0.832 us    |                    sub_preempt_count();
1)   2.656 us    |                  }
1) + 19.104 us   |                }
1)   0.960 us    |                update_rt_migration();
1) + 22.912 us   |              }
1)   0.928 us    |              dequeue_pushable_task();
1) + 40.256 us   |            }
1) + 42.080 us   |          }
1) + 43.968 us   |        }
1)               |        pre_schedule_rt() {
1)   0.928 us    |          pull_rt_task();
1)   2.720 us    |        }
1)               |        _raw_spin_unlock() {
1)   0.832 us    |          sub_preempt_count();
1)   2.784 us    |        }
1)               |        load_balance() {
1)   1.088 us    |          scale_rt_power();
1)   0.960 us    |          scale_rt_power();
1)   0.960 us    |          scale_rt_power();
1)   0.992 us    |          scale_rt_power();
1)   0.960 us    |          scale_rt_power();
1)   0.960 us    |          scale_rt_power();
1)   0.960 us    |          scale_rt_power();
1)   0.992 us    |          scale_rt_power();
1) + 18.240 us   |        }
1)   0.928 us    |        msecs_to_jiffies();
1)               |        _raw_spin_lock() {
1)               |          __raw_spin_lock() {
1)   0.896 us    |            add_preempt_count();
1)   2.656 us    |          }
1)   4.448 us    |        }
1)               |        put_prev_task_rt() {
1)               |          update_curr_rt() {
1)               |            _raw_spin_lock() {
1)               |              __raw_spin_lock() {
1)   0.928 us    |                add_preempt_count();
1)   2.688 us    |              }
1)   4.448 us    |            }
1)   0.928 us    |            balance_runtime();
1)               |            _raw_spin_unlock() {
1)   0.896 us    |              sub_preempt_count();
1)   2.656 us    |            }
1) + 11.712 us   |          }
1) + 13.504 us   |        }
1)   0.960 us    |        pick_next_task_fair();
1)   0.928 us    |        pick_next_task_rt();
1)   0.928 us    |        pick_next_task_fair();
1)   0.928 us    |        pick_next_task_idle();
1)               |        __switch_to() {
------------------------------------------
1)  1_l2_Ma-734   =>    <idle>-0   
------------------------------------------

1) ! 131.456 us  |    } /* __switch_to */
1)               |    finish_task_switch() {
1)               |      _raw_spin_unlock() {
1)   0.896 us    |        sub_preempt_count();
1)   2.688 us    |      }
1)   4.480 us    |    }
1)   0.992 us    |    sub_preempt_count();
1) ! 156.544 us  |  } /* __schedule */
1)   1.056 us    |  add_preempt_count();
1)               |  tick_nohz_stop_sched_tick() {
1)               |    ktime_get() {
1)   1.728 us    |      ktime_add_ns();
1)   3.680 us    |    }
1)   0.960 us    |    timekeeping_max_deferment();
1)   0.960 us    |    rcu_needs_cpu();
1)   0.960 us    |    printk_needs_cpu();
1)               |    get_next_timer_interrupt() {
1)               |      rt_spin_trylock() {
1)   0.928 us    |        rt_mutex_trylock();
1)   2.752 us    |      }
1)   0.960 us    |      rt_spin_unlock();
1)               |      hrtimer_get_next_event() {
1)               |        _raw_spin_lock_irqsave() {
1)               |          __raw_spin_lock_irqsave() {
1)   0.896 us    |            add_preempt_count();
1)   2.784 us    |          }
1)   4.608 us    |        }
1)               |        _raw_spin_unlock_irqrestore() {
1)   0.896 us    |          sub_preempt_count();
1)   2.784 us    |        }
1) + 10.112 us   |      }
1) + 20.224 us   |    }
1)   0.960 us    |    ktime_add_ns();
1)   1.184 us    |    select_nohz_load_balancer();
1)   1.184 us    |    rcu_enter_nohz();
1)               |    hrtimer_start() {
1)               |      __hrtimer_start_range_ns() {
1)               |        lock_hrtimer_base() {
1)               |          _raw_spin_lock_irqsave() {
1)               |            __raw_spin_lock_irqsave() {
1)   0.896 us    |              add_preempt_count();
1)   2.752 us    |            }
1)   4.480 us    |          }
1)   6.240 us    |        }
1)               |        __remove_hrtimer() {
1)               |          hrtimer_force_reprogram() {
1)               |            tick_program_event() {
1)               |              tick_dev_program_event() {
1)               |                ktime_get() {
1)   0.864 us    |                  ktime_add_ns();
1)   2.816 us    |                }
1)   1.056 us    |                clockevents_program_event();
1)   6.592 us    |              }
1)   8.320 us    |            }
1) + 10.144 us   |          }
1) + 12.224 us   |        }
1)   1.024 us    |        ktime_add_ns();
1)   0.960 us    |        ktime_add_safe();
1)   1.024 us    |        enqueue_hrtimer();
1)               |        hrtimer_reprogram() {
1)               |          tick_program_event() {
1)               |            tick_dev_program_event() {
1)               |              ktime_get() {
1)   0.928 us    |                ktime_add_ns();
1)   2.752 us    |              }
1)   0.992 us    |              clockevents_program_event();
1)   6.496 us    |            }
1)   8.256 us    |          }
1) + 10.112 us   |        }
1)               |        _raw_spin_unlock_irqrestore() {
1)   0.864 us    |          sub_preempt_count();
1)   2.720 us    |        }
1) + 41.600 us   |      }
1) + 43.392 us   |    }
1) + 82.976 us   |  }
1)               |  doorbell_exception() {
1)   0.864 us    |    smp_message_recv();
1)   3.008 us    |  }
1)               |  tick_nohz_restart_sched_tick() {
1)               |    ktime_get() {
1)   0.928 us    |      ktime_add_ns();
1)   3.040 us    |    }
1)   0.960 us    |    tick_nohz_stop_idle();
1)   1.056 us    |    rcu_exit_nohz();
1)   1.152 us    |    select_nohz_load_balancer();
1)   1.056 us    |    tick_do_update_jiffies64();
1)               |    account_idle_ticks() {
1)   0.960 us    |      account_idle_time();
1)   2.752 us    |    }
1)               |    hrtimer_cancel() {
1)               |      hrtimer_try_to_cancel() {
1)               |        lock_hrtimer_base() {
1)               |          _raw_spin_lock_irqsave() {
1)               |            __raw_spin_lock_irqsave() {
1)   0.896 us    |              add_preempt_count();
1)   2.720 us    |            }
1)   5.248 us    |          }
1)   7.008 us    |        }
1)               |        __remove_hrtimer() {
1)               |          hrtimer_force_reprogram() {
1)               |            tick_program_event() {
1)               |              tick_dev_program_event() {
1)               |                ktime_get() {
1)   0.896 us    |                  ktime_add_ns();
1)   2.720 us    |                }
1)   1.024 us    |                clockevents_program_event();
1)   6.400 us    |              }
1)   8.128 us    |            }
1)   9.920 us    |          }
1) + 11.744 us   |        }
1)               |        _raw_spin_unlock_irqrestore() {
1)   0.864 us    |          sub_preempt_count();
1)   0.928 us    |          preempt_schedule();
1)   4.512 us    |        }
1) + 26.912 us   |      }
1) + 28.768 us   |    }
1)               |    hrtimer_forward() {
1)   0.928 us    |      ktime_add_safe();
1)   0.960 us    |      ktime_add_safe();
1)   4.736 us    |    }
1)               |    hrtimer_start_range_ns() {
1)               |      __hrtimer_start_range_ns() {
1)               |        lock_hrtimer_base() {
1)               |          _raw_spin_lock_irqsave() {
1)               |            __raw_spin_lock_irqsave() {
1)   0.864 us    |              add_preempt_count();
1)   2.688 us    |            }
1)   4.448 us    |          }
1)   6.208 us    |        }
1)   0.960 us    |        ktime_add_ns();
1)   0.960 us    |        ktime_add_safe();
1)   1.024 us    |        enqueue_hrtimer();
1)               |        hrtimer_reprogram() {
1)               |          tick_program_event() {
1)               |            tick_dev_program_event() {
1)               |              ktime_get() {
1)   0.960 us    |                ktime_add_ns();
1)   2.720 us    |              }
1)   0.992 us    |              clockevents_program_event();
1)   6.464 us    |            }
1)   8.256 us    |          }
1) + 10.080 us   |        }
1)               |        _raw_spin_unlock_irqrestore() {
1)   0.896 us    |          sub_preempt_count();
1)   0.928 us    |          preempt_schedule();
1)   4.576 us    |        }
1) + 30.144 us   |      }
1) + 31.936 us   |    }
1) + 84.864 us   |  }
1)   1.056 us    |  sub_preempt_count();
1)               |  __schedule() {
1)   1.024 us    |    rcu_sched_qs();
1)   0.960 us    |    add_preempt_count();
1)               |    _raw_spin_lock_irq() {
1)               |      __raw_spin_lock_irqsave() {
1)   0.896 us    |        add_preempt_count();
1)   2.816 us    |      }
1)   4.608 us    |    }
1)   0.928 us    |    put_prev_task_idle();
1)               |    pick_next_task_rt() {
1)   0.928 us    |      dequeue_pushable_task();
1)   2.848 us    |    }
1)               |    __switch_to() {
------------------------------------------
1)    <idle>-0    =>  1_l2_Ma-734  
------------------------------------------

1) ! 1089.664 us |        } /* __switch_to */
1)               |        finish_task_switch() {
1)               |          _raw_spin_unlock() {
1)   0.896 us    |            sub_preempt_count();
1)   2.688 us    |          }
1)   4.608 us    |        }
1)   0.992 us    |        sub_preempt_count();
1) ! 1209.248 us |      } /* __schedule */
1) ! 1211.072 us |    } /* schedule */
1)   0.928 us    |    __osp_int_wake_unreg();
1) ! 1216.640 us |  } /* sys_wait_wakeup */
1)               |  sys_wait_wakeup() {
1)   0.896 us    |    __osp_int_wake_reg();
1)               |    schedule() {
1)               |      __schedule() {
1)   1.056 us    |        rcu_sched_qs();
1)   0.992 us    |        add_preempt_count();
1)               |        _raw_spin_lock_irq() {
1)               |          __raw_spin_lock_irqsave() {
1)   0.864 us    |            add_preempt_count();
1)   2.688 us    |          }
1)   4.480 us    |        }
1)               |        deactivate_task() {
1)               |          dequeue_task() {
1)               |            dequeue_task_rt() {
1)               |              update_curr_rt() {
1)               |                _raw_spin_lock() {
1)               |                  __raw_spin_lock() {
1)   0.896 us    |                    add_preempt_count();
1)   2.720 us    |                  }
1)   4.480 us    |                }
1)   0.960 us    |                balance_runtime();
1)               |                _raw_spin_unlock() {
1)   0.864 us    |                  sub_preempt_count();
1)   2.720 us    |                }
1) + 11.968 us   |              }
1)               |              __dequeue_rt_entity() {
1)               |                cpupri_set() {
1)               |                  _raw_spin_lock_irqsave() {
1)               |                    __raw_spin_lock_irqsave() {
1)   0.928 us    |                      add_preempt_count();
1)   2.784 us    |                    }
1)   4.544 us    |                  }
1)               |                  _raw_spin_unlock_irqrestore() {
1)   0.864 us    |                    sub_preempt_count();
1)   2.816 us    |                  }
1)               |                  _raw_spin_lock_irqsave() {
1)               |                    __raw_spin_lock_irqsave() {
1)   0.896 us    |                      add_preempt_count();
1)   2.784 us    |                    }
1)   4.608 us    |                  }
1)               |                  _raw_spin_unlock_irqrestore() {
1)   0.864 us    |                    sub_preempt_count();
1)   2.688 us    |                  }
1) + 19.264 us   |                }
1)   0.960 us    |                update_rt_migration();
1) + 23.072 us   |              }
1)   0.960 us    |              dequeue_pushable_task();
1) + 39.648 us   |            }
1) + 41.440 us   |          }
1) + 43.296 us   |        }
1)               |        pre_schedule_rt() {
1)   0.928 us    |          pull_rt_task();
1)   2.752 us    |        }
1)               |        _raw_spin_unlock() {
1)   0.832 us    |          sub_preempt_count();
1)   2.656 us    |        }
1)               |        load_balance() {
1)   0.928 us    |          scale_rt_power();
1)   0.960 us    |          scale_rt_power();
1)   0.992 us    |          scale_rt_power();
1)   0.960 us    |          scale_rt_power();
1)   0.960 us    |          scale_rt_power();
1)   0.896 us    |          scale_rt_power();
1)   1.056 us    |          scale_rt_power();
1)   0.960 us    |          scale_rt_power();
1)               |          double_rq_lock() {
1)               |            _raw_spin_lock() {
1)               |              __raw_spin_lock() {
1)   0.864 us    |                add_preempt_count();
1)   2.656 us    |              }
1)   4.480 us    |            }
1)               |            _raw_spin_lock() {
1)               |              __raw_spin_lock() {
1)   0.864 us    |                add_preempt_count();
1)   2.656 us    |              }
1)   4.448 us    |            }
1) + 11.840 us   |          }
1)               |          double_rq_unlock() {
1)               |            _raw_spin_unlock() {
1)   0.864 us    |              sub_preempt_count();
1)   2.656 us    |            }
1)               |            _raw_spin_unlock() {
1)   1.696 us    |              sub_preempt_count();
1)   3.520 us    |            }
1)   8.864 us    |          }
1)   0.992 us    |          scale_rt_power();
1)   0.992 us    |          scale_rt_power();
1)   0.960 us    |          scale_rt_power();
1)   0.992 us    |          scale_rt_power();
1)   0.960 us    |          scale_rt_power();
1)   0.928 us    |          scale_rt_power();
1)   0.992 us    |          scale_rt_power();
1)   0.992 us    |          scale_rt_power();
1) + 58.112 us   |        }
1)   0.960 us    |        msecs_to_jiffies();
1)               |        _raw_spin_lock() {
1)               |          __raw_spin_lock() {
1)   0.896 us    |            add_preempt_count();
1)   2.688 us    |          }
1)   4.512 us    |        }
1)               |        put_prev_task_rt() {
1)               |          update_curr_rt() {
1)               |            _raw_spin_lock() {
1)               |              __raw_spin_lock() {
1)   0.928 us    |                add_preempt_count();
1)   2.688 us    |              }
1)   4.416 us    |            }
1)   0.928 us    |            balance_runtime();
1)               |            _raw_spin_unlock() {
1)   0.896 us    |              sub_preempt_count();
1)   2.688 us    |            }
1) + 11.744 us   |          }
1) + 13.568 us   |        }
1)   0.992 us    |        pick_next_task_fair();
1)   0.960 us    |        pick_next_task_rt();
1)   0.928 us    |        pick_next_task_fair();
1)   0.928 us    |        pick_next_task_idle();
1)               |        __switch_to() {
------------------------------------------
1)  1_l2_Ma-734   =>    <idle>-0   
------------------------------------------

1) ! 171.392 us  |    } /* __switch_to */
1)               |    finish_task_switch() {
1)               |      _raw_spin_unlock() {
1)   0.928 us    |        sub_preempt_count();
1)   2.688 us    |      }
1)   4.544 us    |    }
1)   0.992 us    |    sub_preempt_count();
1) ! 196.416 us  |  } /* __schedule */
1)   1.024 us    |  add_preempt_count();
1)               |  tick_nohz_stop_sched_tick() {
1)               |    ktime_get() {
1)   0.992 us    |      ktime_add_ns();
1)   3.008 us    |    }
1)   1.056 us    |    timekeeping_max_deferment();
1)   0.960 us    |    rcu_needs_cpu();
1)   0.960 us    |    printk_needs_cpu();
1)               |    get_next_timer_interrupt() {
1)               |      rt_spin_trylock() {
1)   0.928 us    |        rt_mutex_trylock();
1)   2.688 us    |      }
1)   0.960 us    |      rt_spin_unlock();
1)               |      hrtimer_get_next_event() {
1)               |        _raw_spin_lock_irqsave() {
1)               |          __raw_spin_lock_irqsave() {
1)   0.928 us    |            add_preempt_count();
1)   2.912 us    |          }
1)   4.640 us    |        }
1)               |        _raw_spin_unlock_irqrestore() {
1)   0.864 us    |          sub_preempt_count();
1)   2.752 us    |        }
1) + 10.240 us   |      }
1) + 20.384 us   |    }
1)   0.928 us    |    ktime_add_ns();
1)   1.216 us    |    select_nohz_load_balancer();
1)   1.024 us    |    rcu_enter_nohz();
1)               |    hrtimer_start() {
1)               |      __hrtimer_start_range_ns() {
1)               |        lock_hrtimer_base() {
1)               |          _raw_spin_lock_irqsave() {
1)               |            __raw_spin_lock_irqsave() {
1)   1.696 us    |              add_preempt_count();
1)   3.552 us    |            }
1)   5.312 us    |          }
1)   7.104 us    |        }
1)               |        __remove_hrtimer() {
1)               |          hrtimer_force_reprogram() {
1)               |            tick_program_event() {
1)               |              tick_dev_program_event() {
1)               |                ktime_get() {
1)   0.896 us    |                  ktime_add_ns();
1)   2.848 us    |                }
1)   1.088 us    |                clockevents_program_event();
1)   6.560 us    |              }
1)   8.352 us    |            }
1) + 10.208 us   |          }
1) + 12.192 us   |        }
1)   0.960 us    |        ktime_add_ns();
1)   0.960 us    |        ktime_add_safe();
1)   1.056 us    |        enqueue_hrtimer();
1)               |        hrtimer_reprogram() {
1)               |          tick_program_event() {
1)               |            tick_dev_program_event() {
1)               |              ktime_get() {
1)   0.896 us    |                ktime_add_ns();
1)   2.752 us    |              }
1)   1.024 us    |              clockevents_program_event();
1)   6.464 us    |            }
1)   8.192 us    |          }
1) + 10.080 us   |        }
1)               |        _raw_spin_unlock_irqrestore() {
1)   0.864 us    |          sub_preempt_count();
1)   2.720 us    |        }
1) + 42.624 us   |      }
1) + 44.576 us   |    }
1) + 83.488 us   |  }
1)               |  doorbell_exception() {
1)   1.024 us    |    smp_message_recv();
1)   3.168 us    |  }
1)               |  tick_nohz_restart_sched_tick() {
1)               |    ktime_get() {
1)   0.928 us    |      ktime_add_ns();
1)   2.976 us    |    }
1)   0.992 us    |    tick_nohz_stop_idle();
1)   1.056 us    |    rcu_exit_nohz();
1)   1.088 us    |    select_nohz_load_balancer();
1)   1.056 us    |    tick_do_update_jiffies64();
1)               |    account_idle_ticks() {
1)   0.928 us    |      account_idle_time();
1)   2.720 us    |    }
1)               |    hrtimer_cancel() {
1)               |      hrtimer_try_to_cancel() {
1)               |        lock_hrtimer_base() {
1)               |          _raw_spin_lock_irqsave() {
1)               |            __raw_spin_lock_irqsave() {
1)   0.864 us    |              add_preempt_count();
1)   2.720 us    |            }
1)   4.544 us    |          }
1)   6.272 us    |        }
1)               |        __remove_hrtimer() {
1)               |          hrtimer_force_reprogram() {
1)               |            tick_program_event() {
1)               |              tick_dev_program_event() {
1)               |                ktime_get() {
1)   0.864 us    |                  ktime_add_ns();
1)   2.752 us    |                }
1)   0.992 us    |                clockevents_program_event();
1)   6.368 us    |              }
1)   8.128 us    |            }
1)   9.952 us    |          }
1) + 11.840 us   |        }
1)               |        _raw_spin_unlock_irqrestore() {
1)   0.832 us    |          sub_preempt_count();
1)   0.896 us    |          preempt_schedule();
1)   4.544 us    |        }
1) + 26.304 us   |      }
1) + 28.128 us   |    }
1)               |    hrtimer_forward() {
1)   0.928 us    |      ktime_add_safe();
1)   0.960 us    |      ktime_add_safe();
1)   4.608 us    |    }
1)               |    hrtimer_start_range_ns() {
1)               |      __hrtimer_start_range_ns() {
1)               |        lock_hrtimer_base() {
1)               |          _raw_spin_lock_irqsave() {
1)               |            __raw_spin_lock_irqsave() {
1)   0.864 us    |              add_preempt_count();
1)   3.488 us    |            }
1)   5.248 us    |          }
1)   7.072 us    |        }
1)   0.928 us    |        ktime_add_ns();
1)   0.928 us    |        ktime_add_safe();
1)   1.056 us    |        enqueue_hrtimer();
1)               |        hrtimer_reprogram() {
1)               |          tick_program_event() {
1)               |            tick_dev_program_event() {
1)               |              ktime_get() {
1)   0.928 us    |                ktime_add_ns();
1)   2.752 us    |              }
1)   1.024 us    |              clockevents_program_event();
1)   6.464 us    |            }
1)   8.256 us    |          }
1) + 10.080 us   |        }
1)               |        _raw_spin_unlock_irqrestore() {
1)   0.928 us    |          sub_preempt_count();
1)   0.928 us    |          preempt_schedule();
1)   4.512 us    |        }
1) + 30.816 us   |      }
1) + 32.608 us   |    }
1) + 84.576 us   |  }
1)   1.088 us    |  sub_preempt_count();
1)               |  __schedule() {
1)   0.992 us    |    rcu_sched_qs();
1)   0.960 us    |    add_preempt_count();
1)               |    _raw_spin_lock_irq() {
1)               |      __raw_spin_lock_irqsave() {
1)   0.896 us    |        add_preempt_count();
1)   2.816 us    |      }
1)   4.608 us    |    }
1)   0.928 us    |    put_prev_task_idle();
1)               |    pick_next_task_rt() {
1)   0.928 us    |      dequeue_pushable_task();
1)   2.848 us    |    }
1)               |    __switch_to() {
------------------------------------------
1)    <idle>-0    =>  1_l2_Ma-734  
------------------------------------------

1) ! 846.400 us  |        } /* __switch_to */
1)               |        finish_task_switch() {
1)               |          _raw_spin_unlock() {
1)   0.896 us    |            sub_preempt_count();
1)   2.688 us    |          }
1)   4.544 us    |        }
1)   0.992 us    |        sub_preempt_count();
1) ! 1004.864 us |      } /* __schedule */
1) ! 1006.720 us |    } /* schedule */
1)   0.896 us    |    __osp_int_wake_unreg();
1) ! 1012.384 us |  } /* sys_wait_wakeup */

humjb_1983

如我之前所说，__switch_to本身涉及上下文切换，使用ftrace统计可能本身并不准确，当然，ppc架构我不熟~，不确认__switch_to中是否有阻塞点，建议还是手工打点为好~

noted2011

humjb_1983 发表于 2014-02-21 15:05
如我之前所说，__switch_to本身涉及上下文切换，使用ftrace统计可能本身并不准确，当然，ppc架构我不熟~，不 ...

我在内核代码syscall(就是sys_wait_wakeup)的入口处记录一个时间T1，syscall的末尾处记录一个时间T2，T2-T1有大于1500us的情况，内核统计的wakeup花费的时间在几十us之内，时间主要消耗在唤醒进程A之后，到进程A真正执行这段时间较长，也就是调度这块。从ftrace的统计和我自己加的统计的结果是比较接近的，而整个调度里上下文切换消耗的时间比较多。

humjb_1983

你这里的T2-T1应该是从wakeup-》A进程执行-》返回wakeup的时间吧？
能否在wakeup时记录T1，在A进程真正执行时记录T2.那么此时T2-T1才是真正的调度延时吧？

Dsheng

       __set_current_state(TASK_INTERRUPTIBLE);
       schedule();
之后进程A被踢出rq1，等到wakeup将其挂入rq1，如果rq1里面已经有进程B，（也是99优先级，并且早于进程B），那么需要等待一段时间才会执行进程A。除此之外，可能还有 其他的99优先级线程，如迁移线程。

switch_to的时间肯定很短的，都是us级别的吧。

mordorwww

有没有把同核上的另外一个进程弄死后
看再出现调度延迟不

linuxfellow

花了一点时间对ftrace结果简单分析了一下：

0)               |              int_wake_dl() {
0)               |                wake_up_process() {
1)   4.672 us    |    }
0)               |                  try_to_wake_up() {
1)               |    hrtimer_start_range_ns() {
0)   0.864 us    |                    add_preempt_count();
1)               |      __hrtimer_start_range_ns() {
1)               |        lock_hrtimer_base() {
0)               |                    task_rq_lock() {
1)               |          _raw_spin_lock_irqsave() {
1)               |            __raw_spin_lock_irqsave() {
0)               |                      _raw_spin_lock() {
1)   0.832 us    |              add_preempt_count();
0)               |                        __raw_spin_lock() {
0)   0.864 us    |                          add_preempt_count();
1)   2.720 us    |            }
1)   4.480 us    |          }
0)   2.752 us    |                        }
1)   6.272 us    |        }
0)   5.216 us    |                      }
1)   0.960 us    |        ktime_add_ns();
0)   7.168 us    |                    }
0)   1.024 us    |                    select_task_rq_rt();
1)   0.928 us    |        ktime_add_safe();
0)               |                    _raw_spin_unlock() {
1)   0.960 us    |        enqueue_hrtimer();
0)   0.896 us    |                      sub_preempt_count();
1)               |        hrtimer_reprogram() {
0)   0.896 us    |                      preempt_schedule();
1)               |          tick_program_event() {
1)               |            tick_dev_program_event() {
0)   4.512 us    |                    }
1)               |              ktime_get() {
0)               |                    _raw_spin_lock() {
1)   0.896 us    |                ktime_add_ns();
0)               |                      __raw_spin_lock() {
0)   0.928 us    |                        add_preempt_count();
1)   2.880 us    |              }
1)   1.024 us    |              clockevents_program_event();
0)   2.688 us    |                      }
0)   4.480 us    |                    }
1)   6.560 us    |            }
0)               |                    activate_task() {
1)   8.320 us    |          }
0)               |                      enqueue_task() {
1) + 10.176 us   |        }
0)               |                        enqueue_task_rt() {
1)               |        _raw_spin_unlock_irqrestore() {
0)               |                          cpupri_set() {
1)   0.896 us    |          sub_preempt_count();
0)               |                            _raw_spin_lock_irqsave() {
0)               |                              __raw_spin_lock_irqsave() {
1)   0.928 us    |          preempt_schedule();
0)   0.896 us    |                                add_preempt_count();
1)   4.672 us    |        }
1) + 30.176 us   |      }
0)   2.688 us    |                              }
0)   4.480 us    |                            }
1) + 31.968 us   |    }
1) + 84.480 us   |  }
0)               |                            _raw_spin_unlock_irqrestore() {
1)   1.088 us    |  sub_preempt_count();
0)   0.896 us    |                              sub_preempt_count();
0)   0.928 us    |                              preempt_schedule();

以上部分应该主要在硬时钟中断子程序执行。 total 248.064   wake_up_process() 在硬时钟中断里调用；调用后，硬时钟中断子程序还花了248.06us用于处理更新时钟等其他事情才返回。返回时调用__schedule(); 下面开始才是调度器本身开销
1)               |  __schedule() {
1)   1.024 us    |    rcu_sched_qs();
0)   4.512 us    |                            }
0)               |                            _raw_spin_lock_irqsave() {
1)   0.992 us    |    add_preempt_count();
0)               |                              __raw_spin_lock_irqsave() {
0)   0.896 us    |                                add_preempt_count();
1)               |    _raw_spin_lock_irq() {
1)               |      __raw_spin_lock_irqsave() {
0)   2.688 us    |                              }
1)   0.896 us    |        add_preempt_count();
0)   4.512 us    |                            }
0)               |                            _raw_spin_unlock_irqrestore() {
0)   0.928 us    |                              sub_preempt_count();
1)   2.816 us    |      }
1)   5.408 us    |    }
0)   0.896 us    |                              preempt_schedule();
1)   0.896 us    |    put_prev_task_idle();
0)   4.640 us    |                            }
0) + 22.656 us   |                          }

1)               |    pick_next_task_rt() {
0)   0.928 us    |                          update_rt_migration();
1)   0.896 us    |      dequeue_pushable_task();
0) + 26.496 us   |                        }
1)   2.944 us    |    }
0) + 28.320 us   |      
                       }
Total:  113.344   从调用__schedule()到选中下一个实时进程花的时间是113.344us
1)               |    __switch_to() {
0) + 30.144 us   |                    }
0)   0.896 us    |                    preempt_schedule();
__switch_to  花的时间是31us

moonsunearth

core1上的进程A的优先级最高，是99。
--------------------------------------------------
lz你这里搞错了吧，99在实时进程中是最低优先级