find latency sources -- 一次实时指标调试的过程

1，环境

1）硬件： 联志通达开发板，rk3399处理器，arm64，六核

2）内核：4.4.131 内核 + 4.4.131 preempt rt patch

2，问题描述

在使用cyclictest测试系统实时指标的过程中，偶然发现，插拔usb设备，比如u盘或者usb键鼠，会导致cyclictest max latency突然从原来的50us左右增加到200+us，甚至更多。

3，调试过程

1）初步分析，怀疑是xhci在中断处理时关掉了外部中断，从而导致了hrtimer中断的延时。但是，理论上来讲，打了preempt rt patch以后，绝大多数设备的中断都会变成threaded irq handler，即所有顶半部的处理都放到了内核线程中，中断上下文只占用了极少的时间。但是，申请中断时，使用了IRQF_NO_THREAD这个flag，handler还是会在中断上下文运行，所以值得怀疑。（后来通过log的信息，并不是这个猜测）

2）ftrace event

命令：trace-cmd start -e all;cyclictest -p 90 -m -c 0 -i 100 -n -h 100 -q -l 1000000 -a 5 -b 100

日志：

systemd--2600    5....0  1643.841101: sys_enter:            NR 35 (ffffffffffffff9c, 7ff350fa00, 0, 7ff350fa15, 753a7373616c632b, 6373696d627300)

==============在NR35这个系统调用190us之后，时钟中断才到，晚了150us左右，除此之外，没有其他的信息

 

systemd--2600    5d.h10  1643.841291: irq_handler_entry:    irq=3 name=arch_timer
systemd--2600    5d.h20  1643.841293: hrtimer_cancel:       hrtimer=0xffffffc0f1167da0
systemd--2600    5d.h10  1643.841293: hrtimer_expire_entry: hrtimer=0xffffffc0f1167da0 now=1643679890901 function=hrtimer_wakeup/0x0
systemd--2600    5d.h20  1643.841294: sched_waking:         comm=cyclictest pid=2545 prio=9 target_cpu=005
systemd--2600    5dNh30  1643.841296: sched_wakeup:         cyclictest:2545 [9] success=1 CPU:005
systemd--2600    5dNh10  1643.841297: hrtimer_expire_exit:  hrtimer=0xffffffc0f1167da0
systemd--2600    5dNh10  1643.841298: irq_handler_exit:     irq=3 ret=handled
systemd--2600    5.N.10  1643.841299: rcu_utilization:      Start context switch
systemd--2600    5.N.10  1643.841300: rcu_utilization:      End context switch
systemd--2600    5dN.20  1643.841301: sched_stat_runtime:   comm=systemd-udevd pid=2600 runtime=258417 [ns] vruntime=51035757707 [ns]
systemd--2600    5dN.20  1643.841302: sched_contrib_scale_f: cpu=5 freq_scale_factor=1024 cpu_scale_factor=1024
systemd--2600    5dN.20  1643.841302: sched_contrib_scale_f: cpu=5 freq_scale_factor=1024 cpu_scale_factor=1024
systemd--2600    5dN.20  1643.841303: sched_load_avg_cpu:   cpu=5 load_avg=1067 util_avg=176 util_avg_pelt=176 util_avg_walt=0
systemd--2600    5dN.20  1643.841304: sched_load_avg_task:  comm=systemd-udevd pid=2600 cpu=5 load_avg=1002 util_avg=134 util_avg_pelt=134 util_avg_walt=0 load_sum=48336347 util_sum=6867550 period_contrib=507
systemd--2600    5d..20  1643.841304: sched_switch:         systemd-udevd:2600 [120] R ==> cyclictest:2545 [9]
cyclicte-2545    5....0  1643.841307: sys_exit:             NR 115 = 0
cyclicte-2545    5....0  1643.841325: sys_enter:            NR 64 (5, 7fa008d500, 21, 7fa008cf08, 2, 7fa008ce00)
cyclicte-2545    5....1  1643.841330: print:                0xffffffc0001471f4s: hit latency threshold (190 > 100)

在NR35这个系统调用190us之后，时钟中断才到，晚了150us左右，除此之外，没有其他的信息。而且，systemd--2600这个线程只有在usb插拔事件的时候才调用该系统调用，其余时间没有调用过。

尝试使用ftrace function打印出更多函数调用的信息，不只何故，联志通达的内核只能输出ftrace event的信息，可能是trace-cmd跟该内核有不兼容的地方。

2）ftrace preemptirqsoff

在代码中找到NR35的系统调用是unlinkat，在该函数中使用trace_printk向ftrace ring buffer中输出一些调试信息，同时，打开内核的preempt irq off选项，然后使用命令“cyclictest -p 90 -m -c 0 -i 100 -n -h 100 -q -l 1000000 -b 100 -a 5 -f -B”，其中-f为打开function, -B为打开preemptirqsoff. 输出信息如下：

.........................

systemd--2140    5d...2.. 2016us : __of_find_property <-__of_device_is_compatible
systemd--2140    5d...2.. 2017us : __of_find_all_nodes <-of_find_compatible_node
systemd--2140    5d...2.. 2018us : __of_device_is_compatible <-of_find_compatible_node
systemd--2140    5d...2.. 2019us : __of_find_property <-__of_device_is_compatible
systemd--2140    5d...2.. 2021us : __of_find_all_nodes <-of_find_compatible_node
systemd--2140    5d...2.. 2022us : __of_device_is_compatible <-of_find_compatible_node
systemd--2140    5d...2.. 2022us : __of_find_property <-__of_device_is_compatible
systemd--2140    5d...2.. 2024us : __of_find_all_nodes <-of_find_compatible_node
systemd--2140    5d...2.. 2025us : _raw_spin_unlock_irqrestore <-of_find_compatible_node

.........................................

systemd--2140    5d...2.. 2026us : do_raw_spin_unlock <-_raw_spin_unlock_irqrestore
systemd--2140    5d...2.. 2027us : gic_handle_irq <-el1_irq
systemd--2140    5d...2.. 2027us : __handle_domain_irq <-gic_handle_irq

...........................

systemd--2140    5dnL.2.. 2219us : rcu_irq_exit <-irq_exit
systemd--2140    5.nL.2.. 2220us : preempt_count_sub <-_raw_spin_unlock_irqrestore
systemd--2140    5.nL.1.. 2221us+: _raw_spin_unlock_irqrestore <-of_find_compatible_node
systemd--2140    5.nL.1.. 2246us : trace_preempt_on <-of_find_compatible_node
systemd--2140    5.nL.1.. 2250us : <stack trace>
 => trace_preempt_on
 => preempt_count_sub
 => _raw_spin_unlock_irqrestore
 => of_find_compatible_node
 => SyS_unlinkat
 => el0_svc_naked

可见unlinkat在调用of_find_compatible_node的过程在，使用了raw_spinlock，导致了中断关闭，今儿导致了时钟中断的延迟。

对比vanilla kernel的namei.c中的unlinkat和联志通达代码中的unlinkat，发现vanilla kernel中没有调用of_find_compatible_node，而联志通达增加了额外的逻辑，调用了of_find_compatible_node。

4，解决

将联志通达unlinkat的逻辑恢复到vanilla kernel的逻辑，即取消of_find_compatible_node，现象消失，max latency恢复正常范围。而且，usb键鼠，u盘工作正常。

5，下一步

了解一下systemd与usb设备插拔相关流程的逻辑，了解一下联志通达增加of_find_compatible_node逻辑背后的需求，然后找到更合理的解决方案