Android 系统负载简介
存在这种情况，平均负载过高的时候，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将显示自上次运行该命令以后的统计信息。用户可以通过指定统计的次数和时间来获得所需的统计信息。
