使用ftrace定位xenomai实时内核中断延时的一个实例

1，背景

1）硬件：飞腾ft2000ahk，双核，1.8G

2）软件：

   内核：4.14.4

   桌面：银河麒麟sp2

   实时方案：Xenomai 3.1

3）描述：麒麟内核4.14.4版本加xenomai的实时方案，硬件环境为飞腾ft2000ahk处理器开发板，测试标准是在空载情况下，cyclictest的延时小于50us。

2，问题描述

运行cyclictest -p 90 -m -c 0 -i 10 -n -h 100 -q -l 10000000对系统实时性进行验证，要求系统空载的情况下，所得延时小于50us，但实际测试值通常为60us～100us。

3，Debug过程
1)Ftrace irqsoff
步骤：
echo irqsoff > /sys/kernel/debug/tracing/current_tracer
echo 1 > /sys/kernel/debug/tracing/tracing_on
cyclictest -p 90 -m -c 0 -i 10 -n -h 100 -q -l 10000000
echo 0 > /sys/kernel/debug/tracing/tracing_on
cat /sys/kernel/debug/tracing/trace > xxx.txt
Note：cyclictest测试用例timer周期设置为10us，但时间间隔太短了，日志就不大容易看清楚过程，所以我有时候使用-i 100来调试，这样在log中能够看到清晰的代码过程和时间戳。
 
日志1 -- -i为10us的日志：
<...>-1874    0d..3 13767414us : CoBaLt_clock_nanosleep <-handle_head_syscall
   <...>-1874    0d..3 13767416us : __cobalt_clock_nanosleep <-CoBaLt_clock_nanosleep
   <...>-1874    0d..3 13767417us : ___xnlock_get <-__cobalt_clock_nanosleep
   <...>-1874    0d..3 13767418us : xnthread_suspend <-__cobalt_clock_nanosleep
   <...>-1874    0d..3 13767419us : ___xnlock_get <-xnthread_suspend
   <...>-1874    0d..3 13767420us : xntimer_start <-xnthread_suspend
   <...>-1874    0d..3 13767421us : xnclock_core_ns_to_ticks <-xntimer_start
 
   <...>-1874    0d..3 13767422us : ___xnlock_put <-__cobalt_clock_nanosleep
   <...>-1874    0d..3 13767424us : __ipipe_restore_head <-__cobalt_clock_nanosleep
 
   <...>-1874    0d..3 13767425us : ipipe_fastcall_hook <-el0_svc_naked
   <...>-1874    0d..3 13767427us : handle_head_syscall <-ipipe_fastcall_hook
 
分析（代码流程分析）：
cobalt_clock_nanosleep
    xnthread_suspend
        xntimer_start
            xnclock_core_ns_to_ticks
可以看出来，很多时候，在xntimer_start函数里，由于时间比较短，就直接返回了，这样并没有引起进程上下文的切换。有的时候也会发生进程上下文的切换，切换的过程见100us的日志。
 
日志1 -- -i为100us的日志：
<...>-1874    0d..3 13773888us : CoBaLt_clock_nanosleep <-handle_head_syscall
   <...>-1874    0d..3 13773890us : __cobalt_clock_nanosleep <-CoBaLt_clock_nanosleep
   <...>-1874    0d..3 13773891us : ___xnlock_get <-__cobalt_clock_nanosleep
   <...>-1874    0d..3 13773892us : xnthread_suspend <-__cobalt_clock_nanosleep
   <...>-1874    0d..3 13773893us : ___xnlock_get <-xnthread_suspend
   <...>-1874    0d..3 13773894us : xntimer_start <-xnthread_suspend
   <...>-1874    0d..3 13773895us : xnclock_core_ns_to_ticks <-xntimer_start
   <...>-1874    0d..3 13773896us : xntimer_enqueue_and_program <-xntimer_start
   <...>-1874    0d..3 13773897us : xntimer_heading_p <-xntimer_enqueue_and_program
   <...>-1874    0d..3 13773899us : xnclock_core_local_shot <-xntimer_enqueue_and_program
   <...>-1874    0d..3 13773900us : ipipe_timer_set <-xnclock_core_local_shot
   <...>-1874    0d..3 13773901us : arch_timer_set_next_event_phys <-ipipe_timer_set  
                                     设置时钟硬件寄存器
 
<...>-1874    0d..3 13773902us : ___xnsched_run <-xnthread_suspend
   <...>-1874    0d..3 13773903us : xnarch_escalate <-___xnsched_run
   <...>-1874    0d..3 13773904us : ___xnlock_get <-___xnsched_run
   <...>-1874    0d..3 13773905us : xnsched_pick_next <-___xnsched_run
   <...>-1874    0d..3 13773907us : xnarch_switch_to <-___xnsched_run
   <...>-1874    0d..3 13773908us : fpsimd_thread_switch <-__switch_to
   <...>-1874    0d..3 13773909us : hw_breakpoint_thread_switch <-__switch_to
   <...>-1874    0d..3 13773910us : uao_thread_switch <-__switch_to
                                      切换上下文
 
                                 gic_handle_irq <-el1_irq
         &nbs