[CPU] 一起内核线程异常占用CPU资源的排查过程

1、软硬件环境

        硬件： NXP LS1043A  4核 cortex-A53

        软件： linux 5.10.35

2、问题现象

      最近有个产品要把内核从4.19升级到 5.10.35版本，产品在内核版本4.19工作正常，升级到5.10.35以后，产品在不接任何外设，不跑应用程序的情况下，发现会有1个核完全被内核异常占用掉，系统启动后，异常现象一直持续。

3、排查过程

单从故障现象看，我们无法判断出具体是那一块的问题。首先看下是否有异常的内核参数。答案是没有。

a. perf top 抓函数热点

尝试用perf top 抓函数热点，看下具体是哪个函数在消耗该CPU的时间

 可以看到内核在不停的在 _raw_spin_unlock_irq  与_raw_spin_unlock_irqrestore 之间 频繁调用。

现在我们已经确定了该CPU在频繁调用 _raw_spin_unlock_irq   函数，但是我们依然无法判断出具体是那一块的问题。

b. ftrace 查看 _raw_spin_unlock_irq   上层调用栈

cd /sys/kernel/debug/tracing/
echo 0 > tracing_on

echo _raw_spin_unlock_irq > set_ftrace_filter
echo function > current_tracer 

echo 1 > options/func_stack_trace

# 过滤下pid, 因为调用_raw_spin_unlock_irq 的线程比较多
echo 57 > set_ftrace_pid

> trace #清除 trace 内容
echo 1 > tracing_on && sleep 1 && echo 0 > tracing_on

 从结果上来，是和usb 有关系，这个我们可以简单的使用内核参数关掉usb功能验证一下

把USB 关掉验证一下，正常了。

cat /proc/cmdline

console=ttyS0,115200 root=/dev/mmcblk0p1 rootwait rw usbcore.nousb

这就说明是usb的问题，但是我们还是没有定位到USB的具体问题。

c. 使用function_graph功能 统计每个函数的执行时间 做一个排序

echo 1 >  ./function_profile_enabled

# 等过2分钟再查看统计 
cat ./trace_stat/function0 | head -100

不过在执行过程中，发现

 应该是该选择没有打开

 重新编译内核后，查看结果 猜测是跟 usb suspend 有关系

d  这里也可以使用火焰图来分析

top 命令可以看到内核线程pid为54 

 然后执行下面命令来获取 perf采集数据

perf record -F 99 -p 54 -g -- sleep 60

record：表示采集系统事件，没有采用 -e 执行采集事件，则默认采集 cycles（即 CPU clock 周期）。

-F 99：指定采样频率为 99Hz（每秒99次），如果 99次都返回同一个函数名, 那就说明 CPU 这一秒钟都在执行同一个函数，可能存在性能问题。

-p 54：指定进程号，对某一个进程分析。

-g：表示记录调用栈。

sleep 60：表示持续 60 秒

 可以使用下面命令来简单查看 perf.data内容

perf report -n --stdio

root@localhost:~# perf report -n --stdio
# To display the perf.data header info, please use --header/--header-only options.
#
#
# Total Lost Samples: 0
#
# Samples: 3K of event 'cycles:ppp'
# Event count (approx.): 53389208829
#
# Children      Self       Samples  Command         Shared Object      Symbol                                 
# ........  ........  ............  ..............  .................  .......................................
#
   100.00%     0.00%             0  kworker/1:1+pm  [kernel.kallsyms]  [k] worker_thread                      
            |
            ---worker_thread
               |          
               |--99.98%-- process_one_work
               |          |          
               |          |--56.49%-- pm_runtime_work
               |          |          |          
               |          |          |--55.14%-- rpm_idle
               |          |          |          |          
               |          |          |          |--55.09%-- __rpm_callback
               |          |          |          |          |          
               |          |          |          |          |--53.69%-- usb_runtime_idle
               |          |          |          |          |          |          
               |          |          |          |          |          |--53.51%-- __pm_runtime_suspend
               |          |          |          |          |          |          |          
               |          |          |          |          |          |          |--51.24%-- rpm_suspend
               |          |          |          |          |          |          |          rpm_callback
               |          |          |          |          |          |          |          |          
               |          |          |          |          |          |          |          |--51.22%-- __rpm_callback
               |          |          |          |          |          |          |          |          |          
               |          |          |          |          |          |          |          |          |--49.52%-- usb_runtime_suspend
               |          |          |          |          |          |          |          |          |          |          
               |          |          |          |          |          |          |          |          |          |--49.44%-- usb_suspend_both
               |          |          |          |          |          |          |          |          |          |          |          
               |          |          |          |          |          |          |          |          |          |          |--25.99%-- hub_suspend
               |          |          |          |          |          |          |          |          |          |          |          |          
               |          |          |          |          |          |          |          |          |          |          |          |--16.46%-- set_port_feature
               |          |          |          |          |          |          |          |          |          |          |          |          |          
               |          |          |          |          |          |          |          |          |          |          |          |          |--16.39%-- usb_control_msg
               |          |          |          |          |          |          |          |          |          |          |          |          |          |          
               |          |          |          |          |          |          |          |          |          |          |          |          |          |--13.27%-- usb_

 由于这个结果不是很直观，需要我们生产火焰图来进一步来观察

生成火焰图

首先使用 perf script 工具对上面生成的 perf.data 进行解析，先下载我们需要的脚本。

git clone https://github.com/brendangregg/FlameGraph.git 

# 生成折叠后的调用栈
perf script -i perf.data &> perf.unfold

# 生成火焰图
./FlameGraph/stackcollapse-perf.pl perf.unfold &> perf.folded

# 生成svg
./FlameGraph/flamegraph.pl perf.folded > perf.svg

上述三条命令，也可以通过下面的管道命令来操作： 

perf script | FlameGraph/stackcollapse-perf.pl | FlameGraph/flamegraph.pl > perf.svg

我们将生成的SVG拷贝到电脑上，用浏览器打开，可以清晰的看到函数的调用情况！ 

 函数从下往上调用。左右是条件分支。

从火焰图上更加清晰的可以看到 _raw_spin_unlock_irq  所以的调用流程和条件分支。更有利于我们判断问题！

4 尝试解决

 从上面的分析，看着是卡在usb suspend， 这里尝试将usb autosuspend给关闭掉试试

默认是下面的值

# cat /sys/bus/usb/devices/usb1/power/control

auto

改成 如下，系统CPU资源变成正常

echo on > /sys/bus/usb/devices/usb1/power/control
echo on > /sys/bus/usb/devices/usb2/power/control
echo on > /sys/bus/usb/devices/usb3/power/control
echo on > /sys/bus/usb/devices/usb4/power/control
echo on > /sys/bus/usb/devices/usb5/power/control
echo on > /sys/bus/usb/devices/usb6/power/control

top 和 perf top 均显示正常。