Android 系统负载简介

2023-12-16 10:31:28

存在这种情况，平均负载过高的时候，CPU占用和IOwait都是正常

什么是平均负载

使用命令

cat /proc/loadavg
6.00 6.00 6.00 1/721 5555

查看当前系统的平均负载，前三个数分别是 1分钟、5分钟、15分钟的平均进程数。第四个的分子是正在运行的进程数，分母是进程总数；最后一个是最近运行的进程ID号。

或者使用

uptime
08:24:29 up 19:34,  0 users,  load average: 6.00, 6.00, 6.00

命令查看平均负载

08:24:29 //当前时间
up 19:34 //运行时间
0 users //当前的用户数量
load average: 6.00, 6.00, 6.00 //分别是 1分钟、5分钟、15分钟的平均进程数

还可以使用下面这个命令查看

dumpsys cpuinfo

所以什么是平均负载？

简单来说，平均负载是指单位时间内，系统处于可运行状态和不可中断状态的平均进程数，也就是平均活跃进程数，它和 CPU 使用率并没有直接关系。

这里先解释下，可运行状态和不可中断状态这俩词儿。所谓可运行状态的进程，是指正在使用 CPU 或者正在等待 CPU 的进程，也就是我们常用 ps 命令看到的，处于 R 状态（Running 或 Runnable）的进程。
不可中断状态的进程则是正处于内核态关键流程中的进程，并且这些流程是不可打断的，比如最常见的是等待硬件设备的 I/O 响应，也就是我们在 ps 命令中看到的 D 状态（Uninterruptible Sleep，也称为 Disk Sleep）的进程。

把CPU当作一座桥梁，当load 等于1的时候，桥梁上正好有足够的汽车在行驶，当load等于0.5的时候，桥梁上还非常宽松，当load 等于1.7时候，说明已经有超负荷的汽车需要通过桥梁了。

平均负载与 CPU 使用率

现实工作中，我们经常容易把平均负载和 CPU 使用率混淆，所以在这里，我也做一个区分。

可能你会疑惑，既然平均负载代表的是活跃进程数，那平均负载高了，不就意味着 CPU 使用率高吗？

我们还是要回到平均负载的含义上来，平均负载是指单位时间内，处于可运行状态和不可中断状态的进程数。

所以，它不仅包括了正在使用 CPU 的进程，还包括等待 CPU 和等待 I/O 的进程。而 CPU 使用率，是单位时间内 CPU 繁忙情况的统计，跟平均负载并不一定完全对应。

比如：
CPU 密集型进程，使用大量 CPU 会导致平均负载升高，此时这两者是一致的；I/O 密集型进程，等待 I/O 也会导致平均负载升高，但 CPU 使用率不一定很高；大量等待 CPU 的进程调度也会导致平均负载升高，此时的 CPU 使用率也会比较高。

使用 top 命令查看CPU使用情况

Tasks: 250 total,   1 running, 242 sleeping,   0 stopped,   1 zombie
Mem:   2007724k total,   862320k used,  1145404k free,    18576k buffers
Swap:  1505788k total,        0k used,  1505788k free,   415260k cached
400%cpu   2%user   0%nice   1%sys 397%idle   0%iow   0%irq   0%sirq   0%host
  PID USER         PR  NI VIRT  RES  SHR S[%CPU] %MEM     TIME+ ARGS
 5645 root         20   0 6.4M 3.6M 2.9M R  2.3   0.1   0:00.46 top
  515 system       18  -2 1.1G 153M 134M S  0.3   7.7   5:03.83 system_server
  318 shell        20   0  12M 1.2M 1.0M S  0.3   0.0   0:37.92 adbd --root_seclabel=u:r:su:s0
 5642 root          0 -20    0    0    0 S  0.0   0.0   0:00.00 [kworker/u9:1]
 5638 root         20   0    0    0    0 S  0.0   0.0   0:00.00 [kworker/u8:2]
 5614 root          0 -20    0    0    0 S  0.0   0.0   0:00.00 [kworker/u9:0]

可以看到cpu使用率不是很高
但是查看平均负载的时候，就很高

08:44:56 up 19:55,  0 users,  load average: 6.00, 6.00, 6.00

我们是4核CPU，如果平均负载低于4.0就是比较正常的，现在已经远远高于4.0了。

使用 trace 查看 cpuloading

先使用脚本抓取trace文件

get_trace.bat 文件

@echo off
adb root
adb wait-for-device
adb root

rem set size
adb shell "echo 16384 > /sys/kernel/debug/tracing/buffer_size_kb"
rem set or use debug method
adb shell "echo nop > /sys/kernel/debug/tracing/current_tracer"
rem set debug event
adb shell "echo 'sched_switch sched_wakeup sched_wakeup_new' > /sys/kernel/debug/tracing/set_event"
rem enable debug
rem adb shell "echo 1 > /sys/kernel/debug/tracing/tracing_enabled >nul 2>&1"
rem stop debug
adb shell "echo 0 > /sys/kernel/debug/tracing/tracing_on"
rem clear debug data 
adb shell "echo > /sys/kernel/debug/tracing/trace"

rem wait user to start
echo press any key to start ...
pause

rem start debug
adb shell "echo 1 > /sys/kernel/debug/tracing/tracing_on"

rem wait user to stop
echo press any key to stop ...
pause

rem stop debug
adb shell "echo 0 > /sys/kernel/debug/tracing/tracing_on"

echo pull debug data start ...
adb pull /sys/kernel/debug/tracing/trace sys_ftrace_data
echo pull debug data end

pause

获取到的 systrace 文件可用 chrome://tracing 查看

使用命令查看系统的D进程

最简单的是使用 ps -ef | grep " D" 过滤 D 状态进程。
使用如下命令查看D进程的backtrace

echo w > proc/sysrq-trigger

关于 sysrq-trigger 的说明百度有惊喜。

然后查看内核日志，可以看到如下关键信息：

[ 6619.317533] (0)[1621:sh]  task                PC stack   pid father
[ 6619.317562] (0)[1621:sh]GCPU            D c0b6f590     0    25      2 0x00000000
[ 6619.317576] (0)[1621:sh]Backtrace: 
[ 6619.317585] (0)[1621:sh][<c0b6f244>] (__schedule) from [<c0b6faa0>] (schedule+0x54/0xc4)
[ 6619.317609] (0)[1621:sh] r10:c1103948 r9:00000201 r8:c1103948 r7:c1103948
[ 6619.317627] (0)[1621:sh][<c0b6fa4c>] (schedule) from [<c0b72e4c>] (schedule_timeout+0x178/0x264)
[ 6619.317644] (0)[1621:sh] r4:7fffffff r3:dc8ba692
[ 6619.317655] (0)[1621:sh][<c0b72cd4>] (schedule_timeout) from [<c0b71bfc>] (__down+0x78/0xc4)
[ 6619.317670] (0)[1621:sh] r10:c1103948 r9:00000201 r8:c1103948 r7:00000002
[ 6619.317687] (0)[1621:sh][<c0b71b84>] (__down) from [<c018d2d0>] (down+0x4c/0x60)
[ 6619.317705] (0)[1621:sh] r8:d038de88 r7:ffff1234 r6:c1103948 r5:d038ddcc
[ 6619.317721] (0)[1621:sh][<c018d284>] (down) from [<c070d630>] (KREE_ServSemaphoreDown+0x14/0x1c)
[ 6619.317740] (0)[1621:sh] r4:c0cc5fd8
[ 6619.317748] (0)[1621:sh][<c070d61c>] (KREE_ServSemaphoreDown) from [<c070bcf8>] (tz_service_call+0x74/0xc4)
[ 6619.317767] (0)[1621:sh][<c070bc84>] (tz_service_call) from [<c070bf30>] (KREE_TeeServiceCall+0xe8/0x290)
[ 6619.317781] (0)[1621:sh] r7:00000002 r6:00000001 r5:00000002 r4:00000000
[ 6619.317799] (0)[1621:sh][<c070be48>] (KREE_TeeServiceCall) from [<c070c120>] (kree_thread_function+0x48/0x64)
[ 6619.317814] (0)[1621:sh] r10:00000000 r9:00000000 r8:00000000 r7:c070c0d8
[ 6619.317831] (0)[1621:sh][<c070c0d8>] (kree_thread_function) from [<c0148aec>] (kthread+0x114/0x12c)
[ 6619.317849] (0)[1621:sh] r5:d0354d40 r4:00000000
[ 6619.317862] (0)[1621:sh][<c01489d8>] (kthread) from [<c0108730>] (ret_from_fork+0x14/0x24)
[ 6619.317908] (0)[1621:sh]fuse_log        D c0b6f590     0    78      2 0x00000000
[ 6619.317922] (0)[1621:sh]Backtrace: 
[ 6619.317930] (0)[1621:sh][<c0b6f244>] (__schedule) from [<c0b6faa0>] (schedule+0x54/0xc4)
[ 6619.317945] (0)[1621:sh] r10:00000000 r9:00000000 r8:00000000 r7:c0392b8c
[ 6619.317963] (0)[1621:sh][<c0b6fa4c>] (schedule) from [<c0148aa8>] (kthread+0xd0/0x12c)
[ 6619.317977] (0)[1621:sh] r4:00000000 r3:cf9032c0
[ 6619.317989] (0)[1621:sh][<c01489d8>] (kthread) from [<c0108730>] (ret_from_fork+0x14/0x24)
[ 6619.318020] (0)[1621:sh]hang_detect     D c0b6f590     0   124      2 0x00000000
[ 6619.318034] (0)[1621:sh]Backtrace: 
[ 6619.318043] (0)[1621:sh][<c0b6f244>] (__schedule) from [<c0b6faa0>] (schedule+0x54/0xc4)
[ 6619.318137] (0)[1621:sh] r10:00000001 r9:c1102100 r8:df5ebb80 r7:c1103948
[ 6619.318162] (0)[1621:sh][<c0b6fa4c>] (schedule) from [<c0b72e1c>] (schedule_timeout+0x148/0x264)
[ 6619.318180] (0)[1621:sh] r4:001cfb65 r3:00000000
[ 6619.318190] (0)[1621:sh][<c0b72cd4>] (schedule_timeout) from [<c01ad908>] (msleep+0x34/0x40)
[ 6619.318209] (0)[1621:sh] r10:00000000 r9:c116e0a4 r8:cfb7dedc r7:c116e158
[ 6619.318228] (0)[1621:sh][<c01ad8d4>] (msleep) from [<c0733f5c>] (hang_detect_thread+0x94/0x318)
[ 6619.318244] (0)[1621:sh] r5:c116e158 r4:c1483ba8
[ 6619.318255] (0)[1621:sh][<c0733ec8>] (hang_detect_thread) from [<c0148aec>] (kthread+0x114/0x12c)
[ 6619.318270] (0)[1621:sh] r10:00000000 r9:00000000 r8:00000000 r7:c0733ec8
[ 6619.318286] (0)[1621:sh][<c01489d8>] (kthread) from [<c0108730>] (ret_from_fork+0x14/0x24)
[ 6619.318320] (0)[1621:sh]mt_gpufreq_inpu D c0b6f590     0   164      2 0x00000000
[ 6619.318333] (0)[1621:sh]Backtrace: 
[ 6619.318340] (0)[1621:sh][<c0b6f244>] (__schedule) from [<c0b6faa0>] (schedule+0x54/0xc4)
[ 6619.318354] (0)[1621:sh] r10:00000000 r9:00000000 r8:00000000 r7:c0512ebc
[ 6619.318370] (0)[1621:sh][<c0b6fa4c>] (schedule) from [<c0148aa8>] (kthread+0xd0/0x12c)
[ 6619.318384] (0)[1621:sh] r4:00000000 r3:cf825e40
[ 6619.318395] (0)[1621:sh][<c01489d8>] (kthread) from [<c0108730>] (ret_from_fork+0x14/0x24)
[ 6619.318412] (0)[1621:sh]display_esd_che D c0b6f590     0   169      2 0x00000000
[ 6619.318424] (0)[1621:sh]Backtrace: 
[ 6619.318432] (0)[1621:sh][<c0b6f244>] (__schedule) from [<c0b6faa0>] (schedule+0x54/0xc4)
[ 6619.318446] (0)[1621:sh] r10:00000000 r9:00000000 r8:00000000 r7:c0620888
[ 6619.318463] (0)[1621:sh][<c0b6fa4c>] (schedule) from [<c0148aa8>] (kthread+0xd0/0x12c)
[ 6619.318477] (0)[1621:sh] r4:00000000 r3:cfbfe580
[ 6619.318487] (0)[1621:sh][<c01489d8>] (kthread) from [<c0108730>] (ret_from_fork+0x14/0x24)
[ 6619.318510] (0)[1621:sh]entropy_thread  D c0b6f590     0   182      2 0x00000000
[ 6619.318523] (0)[1621:sh]Backtrace: 
[ 6619.318531] (0)[1621:sh][<c0b6f244>] (__schedule) from [<c0b6faa0>] (schedule+0x54/0xc4)
[ 6619.318545] (0)[1621:sh] r10:c1103948 r9:00020107 r8:c1103948 r7:c1103948
[ 6619.318562] (0)[1621:sh][<c0b6fa4c>] (schedule) from [<c0b72e4c>] (schedule_timeout+0x178/0x264)
[ 6619.318577] (0)[1621:sh] r4:7fffffff r3:dc8ba692
[ 6619.318587] (0)[1621:sh][<c0b72cd4>] (schedule_timeout) from [<c0b71bfc>] (__down+0x78/0xc4)
[ 6619.318602] (0)[1621:sh] r10:c1103948 r9:00020107 r8:c1103948 r7:00000002
[ 6619.318619] (0)[1621:sh][<c0b71b84>] (__down) from [<c018d2d0>] (down+0x4c/0x60)
[ 6619.318634] (0)[1621:sh] r8:ced01e68 r7:0000002d r6:c1103948 r5:ced01dac
[ 6619.318651] (0)[1621:sh][<c018d284>] (down) from [<c070d630>] (KREE_ServSemaphoreDown+0x14/0x1c)
[ 6619.318666] (0)[1621:sh] r4:c0cc5fd8
[ 6619.318674] (0)[1621:sh][<c070d61c>] (KREE_ServSemaphoreDown) from [<c070bcf8>] (tz_service_call+0x74/0xc4)
[ 6619.318689] (0)[1621:sh][<c070bc84>] (tz_service_call) from [<c070bf30>] (KREE_TeeServiceCall+0xe8/0x290)
[ 6619.318703] (0)[1621:sh] r7:00000002 r6:00000001 r5:00000003 r4:00000000
[ 6619.318720] (0)[1621:sh][<c070be48>] (KREE_TeeServiceCall) from [<c070e418>] (entropy_thread+0xfc/0x228)
[ 6619.318734] (0)[1621:sh] r10:00000000 r9:00000000 r8:00000000 r7:c1103948
[ 6619.318751] (0)[1621:sh][<c070e31c>] (entropy_thread) from [<c0148aec>] (kthread+0x114/0x12c)
[ 6619.318765] (0)[1621:sh] r7:c070e31c r6:00000000 r5:cf703080 r4:00000000
[ 6619.318781] (0)[1621:sh][<c01489d8>] (kthread) from [<c0108730>] (ret_from_fork+0x14/0x24)
[ 6619.318999] (0)[1621:sh]Sched Debug Version: v0.11, 4.4.146 #10
[ 6619.319008] (0)[1621:sh]ktime                                   : 6619310.281712
[ 6619.319016] (0)[1621:sh]sched_clk                               : 6619318.998704
[ 6619.319024] (0)[1621:sh]cpu_clk                                 : 6619318.998857
[ 6619.319032] (0)[1621:sh]jiffies                                 : 1895794
[ 6619.319040] (0)[1621:sh]
[ 6619.319045] (0)[1621:sh]sysctl_sched
[ 6619.319052] (0)[1621:sh]  .sysctl_sched_latency                    : 10.000000
[ 6619.319060] (0)[1621:sh]  .sysctl_sched_min_granularity            : 2.250000
[ 6619.319068] (0)[1621:sh]  .sysctl_sched_wakeup_granularity         : 2.000000
[ 6619.319076] (0)[1621:sh]  .sysctl_sched_child_runs_first           : 0
[ 6619.319084] (0)[1621:sh]  .sysctl_sched_features                   : 36667
[ 6619.319091] (0)[1621:sh]  .sysctl_sched_tunable_scaling            : 0 (none)
[ 6619.319099] (0)[1621:sh]

从日志里面可以看到有6个进程属于D进程状态，这几个进程一直在等待事件，导致CPU负载过高，但是实际上又没有使用CPU，所以CPU使用率并不高。

使用命令查看我们系统的D进程

比较有用的命令记录

top
vmstat (很有用）
pidstat （https://github.com/weiqifa0/pidstat/blob/main/README.md）
pidstat主要用于监控全部或指定进程占用系统资源的情况，如CPU，内存、设备IO、任务切换、线程等。pidstat首次运行时显示自系统启动开始的各项统计信息，之后运行pidstat将显示自上次运行该命令以后的统计信息。用户可以通过指定统计的次数和时间来获得所需的统计信息。

参考链接

https://mp.weixin.qq.com/s/oBj8N7b3Rj19Bwgp69bzAg

码农公寓