Linux 程序性能分析实例：用 perf 定位内核态 CPU 高负载的 GPS 服务
Linux程序性能分析（二）--- 实例分析2（内核态） - SkyOnSky
一台魔改 Android 系统刷机后发热严重，htop 显示最大核 cpu7 内核负载极高而用户态占用很少，作者用 perf record 采样 cycles 堆栈定位到 loc-mq-thread、Ipc-_hub.socket 等线程在反复收发 socket。
PS：要转载请注明出处，本人版权所有。
PS: 这个只是基于《我自己》的理解，
如果和你的原则及想法相冲突，请谅解，勿喷。
环境说明
无
前言
本文是本系列的终章，前面的文章是：
- 《Linux程序性能分析（一）---perf原理分析》 https://www.cnblogs.com/Iflyinsky/p/22507762
- 《Linux程序性能分析（二）--- 实例分析1（用户态）》 https://www.cnblogs.com/Iflyinsky/p/23432260
现在，我们来上点难度，来分析分析一些系统的奇奇怪怪的问题。
系统实例分析
此魔改android系统刷机之后的系统发热特别严重，经过htop查看（如下图），发现其cpu7（这个开发板的最大核）内核工作负载极高，但是我们看用户态的cpu的占用，是极少的。下面我们尝试分析一下，为什么内核负载这么高。（这里提前说明，从htop来看，就可以猜是跟gps服务相关，最终结果就是跟这个gps服务有关系，只是形成了连锁反应）
先使用这个来解锁抓取内核符号地址：
echo 0 > /proc/sys/kernel/kptr_restrict
echo -1 > /proc/sys/kernel/perf_event_paranoid
然后使用如下命令抓取cpu7的cycle堆栈采用信息：
perf record -c 7 -g -F 99 -- sleep 5
然后使用如下命令查看当前采样到的堆栈：
perf report --no-children --stdio > perf_data.txt
由于当前这个系统，perf命令无法自动的（有些时候）解析/proc/kallsyms里面的内核符号，因此，我让ai帮我自动解析内核符号(其实就是对应内核符号地址），分别得到的结果如下：
# To display the perf.data header info, please use --header/--header-only options.
#
#
# Total Lost Samples: 0
#
# Samples: 1K of event 'cycles'
# Event count (approx.): 22049604146
#
# Overhead Command Shared Object Symbol
# ........ ............... ........................ ......................................
#
8.89% loc-mq-thread [unknown] [k] 0xffffffd1b00a30b0
|
---0xffffffd1b00a30b0
0xffffffd1aedb57c8
0xffffffd1aedb5ae4
|
--8.79%--0xffffffd1aeca1618
0xffffffd1b088f350
6.79% Ipc-_hub.socket [unknown] [k] 0xffffffd1b00a30b0
|
---0xffffffd1b00a30b0
0xffffffd1aedb57c8
0xffffffd1aedb5ae4
|
--6.61%--0xffffffd1aeca1618
0xffffffd1b088f350
5.55% logd.reader.per [unknown] [k] 0xffffffd1b00a30b0
|
---0xffffffd1b00a30b0
0xffffffd1aedb57c8
0xffffffd1aedb5ae4
0xffffffd1aeca1618
0xffffffd1b088f350
4.93% crash_dump64 [unknown] [k] 0xffffffd1b00a30b0
|
---0xffffffd1b00a30b0
0xffffffd1aedb57c8
0xffffffd1aedb5ae4
|
--4.84%--0xffffffd1aeca1618
0xffffffd1b088f350
4.28% loc-mq-thread [unknown] [k] 0xffffffd1aed9b898
|
---0xffffffd1aed9b898
0xffffffd1b085e80c
|
|--2.42%--0xffffffd1b085eec4
| |
| --2.36%--0xffffffd1b08693bc
| 0xffffffd1b0311c3c
| 0xffffffd1b05af88c
| 0xffffffd1b05b3bc0
| 0xffffffd1b02ef450
| 0xffffffd1b02ef2ec
| 0xffffffd1b02ef088
| 0xffffffd1aeca365c
| 0xffffffd1aeca35bc
| 0xffffffd1aeca3494
| 0xffffffd1b0809838
| 0xffffffd1b08097b0
| 0xffffffd1aec1164c
| 0x78d0e05c4c
| 0x6253244850
| 0x62532449b0
| 0x78d0e19a54
| 0x78d0db33ec
| 0
|
--1.84%--0xffffffd1b085e14c
0xffffffd1aedd54dc
0xffffffd1b02f8860
0xffffffd1b05b06f8
0xffffffd1b02eb780
0xffffffd1af160f98
0xffffffd1af160ae8
0xffffffd1af1607ec
0xffffffd1af160638
0xffffffd1aeca365c
0xffffffd1aeca35bc
0xffffffd1aeca3494
0xffffffd1b0809838
0xffffffd1b08097b0
0xffffffd1aec1164c
|
--0.51%--0x7cab9b608c
0x7cafe8e70c
0x7cafe8e620
0x7cafe8ea34
0x7cafe8ecc0
0x7cae5a3604
0x7cae5a5fc0
0x79ac72bb6c
0x79ac72b43c
0x79ac72a634
0x79ac72ec94
0x79ac7352b8
0x79ac732100
0x79ac88bd98
0x7cae5975e4
0x7cae596ea4
0x7cab9caa54
0x7cab9643ec
0
... ...
# To display the perf.data header info, please use --header/--header-only options.
#
#
# Total Lost Samples: 0
#
# Samples: 1K of event 'cycles'
# Event count (approx.): 22049604146
#
# Overhead Command Shared Object Symbol
# ........ ............... ........................ ......................................
#
8.89% loc-mq-thread [unknown] [k] cpuidle_enter_state+0x3b4
|
---cpuidle_enter_state+0x3b4
do_idle+0x300
cpu_startup_entry+0x84
|
--8.79%--secondary_start_kernel+0x294
__secondary_switched+0x9c
6.79% Ipc-_hub.socket [unknown] [k] cpuidle_enter_state+0x3b4
|
---cpuidle_enter_state+0x3b4
do_idle+0x300
cpu_startup_entry+0x84
|
--6.61%--secondary_start_kernel+0x294
__secondary_switched+0x9c
5.55% logd.reader.per [unknown] [k] cpuidle_enter_state+0x3b4
|
---cpuidle_enter_state+0x3b4
do_idle+0x300
cpu_startup_entry+0x84
secondary_start_kernel+0x294
__secondary_switched+0x9c
4.93% crash_dump64 [unknown] [k] cpuidle_enter_state+0x3b4
|
---cpuidle_enter_state+0x3b4
do_idle+0x300
cpu_startup_entry+0x84
|
--4.84%--secondary_start_kernel+0x294
__secondary_switched+0x9c
4.28% loc-mq-thread [unknown] [k] finish_task_switch+0xc4
|
---finish_task_switch+0xc4
__schedule+0x698
|
|--2.42%--schedule+0x150
| |
| --2.36%--schedule_timeout+0x48
| __skb_wait_for_more_packets+0xe0
| __unix_dgram_recvmsg+0xe0
| unix_dgram_recvmsg+0x68
| ____sys_recvmsg+0x150
| ___sys_recvmsg+0x240
| __arm64_sys_recvmsg+0x158
| invoke_syscall+0x60
| el0_svc_common+0xb8
| do_el0_svc+0x28
| el0_svc+0x24
| el0t_64_sync_handler+0x88
| el0t_64_sync+0x1b8
| 0x78d0e05c4c
| 0x6253244850
| 0x62532449b0
| 0x78d0e19a54
| 0x78d0db33ec
| 0
|
--1.84%--preempt_schedule_common+0x30
__wake_up_sync_key+0x12c
sock_def_readable+0xe8
unix_dgram_sendmsg+0x6bc
sock_write_iter+0x14c
do_iter_readv_writev+0x15c
do_iter_write+0x104
do_writev+0x1a4
__arm64_sys_writev+0x24
invoke_syscall+0x60
el0_svc_common+0xb8
do_el0_svc+0x28
el0_svc+0x24
el0t_64_sync_handler+0x88
el0t_64_sync+0x1b8
|
--0.51%--0x7cab9b608c
0x7cafe8e70c
0x7cafe8e620
0x7cafe8ea34
0x7cafe8ecc0
0x7cae5a3604
0x7cae5a5fc0
0x79ac72bb6c
0x79ac72b43c
0x79ac72a634
0x79ac72ec94
0x79ac7352b8
0x79ac732100
0x79ac88bd98
0x7cae5975e4
0x7cae596ea4
0x7cab9caa54
0x7cab9643ec
0
... ...
通过上面的采样堆栈可知道，大部分的消耗都跑到了如下几个名字的程序上面去了：loc-mq-thread、Ipc-_hub.socket、logd.reader.per、crash_dump64 等，如果对android比较熟悉，我们可以先排除logd.reader.per、crash_dump64 ，因为他们两个是自动dump错误，logcat日志相关的内容（从这里其实可以猜到，有程序在疯狂crash 和 打印日志，logcat也证明了这一点）。
剩下的两个loc-mq-thread、Ipc-_hub.socket，我们仔细分析后可以发现，loc-mq-thread在疯狂的循环发送接收socket。后面我们需要定位哪些程序会设置这两个线程名字：
- 首先通过线程名字（/proc/pid/task/tid/comm）得到了对于的pid
- 通过全局搜索程序、so，查询到loc-mq-thread在/vendor/lib64/libloc_base_util.so和/vendor/lib/libloc_base_util.so，然后通过遍历当前所有进程的映射信息(/proc/pid/maps)，查看哪些程序加载了libloc_base_util.so，然后也得到了一堆pid。
- 将上面得到的所有pid使用ps来查询，定位出几个程序，他们分别是：
gps 2014 1 0 08:48:48 ? 00:00:02 loc_launcher
gps 5559 5288 0 08:49:02 ? 00:00:00 loc_launcher
gps 2011 1 0 08:48:49 ? 00:00:00 mlid
gps 2311 2014 0 08:48:49 ? 00:00:09 lowi-server
很遗憾，上面我通过相关查找的时候，会发现一些pid是固定的，一些pid 经常变，这意味着这些pid反复的在创建、退出。这个时候再次引入perf来查看（通过内核在exec的地方埋点，我们可以看到程序启动的一些基本信息），得到了一个有趣的信息：
# sched:sched_process_exec/sched:sched_process_fork可以采集程序通过execve/fork等系统调用时，一些信息
perf record -e sched:sched_process_exec -e sched:sched_process_fork -a -g -- sleep 5
perf script -G > perf_data_process.txt
perf_data_process.txt
android.hardwar 0 [002] 34346.923171: sched:sched_process_exec: filename=/vendor/bin/hw/android.hardware.gnss-aidl-service-qti pid=26140 old_pid=26140
android.hardwar 0 [005] 34346.943460: sched:sched_process_fork: comm=android.hardwar pid=26140 child_comm=android.hardwar child_pid=26141
binder:26140_1 0 [002] 34346.943799: sched:sched_process_fork: comm=binder:26140_1 pid=26141 child_comm=binder:26140_1 child_pid=26142
binder:26140_3 0 [005] 34346.944315: sched:sched_process_fork: comm=binder:26140_2 pid=26140 child_comm=binder:26140_2 child_pid=26143
Loc_hal_worker 0 [005] 34346.947791: sched:sched_process_fork: comm=binder:26140_2 pid=26140 child_comm=binder:26140_2 child_pid=26144
LocApiMsgTask 0 [005] 34346.947937: sched:sched_process_fork: comm=binder:26140_2 pid=26140 child_comm=binder:26140_2 child_pid=26145
LocApiMsgTask 0 [005] 34346.947968: sched:sched_process_fork: comm=binder:26140_2 pid=26140 child_comm=binder:26140_2 child_pid=26146
LocTimerMsgTask 0 [005] 34346.948486: sched:sched_process_fork: comm=binder:26140_2 pid=26140 child_comm=binder:26140_2 child_pid=26147
LocTimerMsgTask 0 [005] 34346.948554: sched:sched_process_fork: comm=binder:26140_2 pid=26140 child_comm=binder:26140_2 child_pid=26148
Ipc-/socket_hal 0 [000] 34346.949242: sched:sched_process_fork: comm=LocApiMsgTask pid=26144 child_comm=LocApiMsgTask child_pid=26149
Ipc-/socket_hal 0 [005] 34346.949923: sched:sched_process_fork: comm=binder:26140_2 pid=26140 child_comm=binder:26140_2 child_pid=26150
Ipc-/socket_hal 0 [005] 34346.951218: sched:sched_process_fork: comm=binder:26140_2 pid=26140 child_comm=binder:26140_2 child_pid=26151
Ipc-api_service 0 [001] 34346.951481: sched:sched_process_fork: comm=binder:26140_2 pid=26150 child_comm=binder:26140_2 child_pid=26152
Ipc-api_service 0 [002] 34346.955169: sched:sched_process_fork: comm=Loc_hal_worker pid=26143 child_comm=Loc_hal_worker child_pid=26153
Ipc-_hub.socket 0 [007] 34347.548339: sched:sched_process_fork: comm=Loc_hal_worker pid=26143 child_comm=Loc_hal_worker child_pid=26154
loc-mq-thread 0 [007] 34347.548415: sched:sched_process_fork: comm=Loc_hal_worker pid=26143 child_comm=Loc_hal_worker child_pid=26155
... ...
到这里，我通过抓取execve/fork系统调用，居然一次就找到了我们上面关注的内容，那么可以看到，android.hardware.gnss-aidl-service-qti 反复创建退出（上面其实抓到了多组sched:sched_process_exec: filename=/vendor/bin/hw/android.hardware.gnss-aidl-service-qti），再结合logcat，基本可以确认就是android.hardware.gnss-aidl-service-qti 反复重启导致的。
由于android.hardware.gnss-aidl-service-qti启动的时候会自动崩溃，但是这个服务会被android的服务管理器自动反复的拉起来，导致了这个坑人的问题。此外，这是android release系统，无法通过adb shell关闭这些服务，经过查询资料，发现了一个新的想法（以前真没这样用过），就是发送STOP信号冻结这个进程，只要进程不退出，android的服务管理就不会反复拉起这个进程。
kill -STOP `pidof android.hardware.gnss-aidl-service-qti`
然后我们再次查看下图，发现我们关心的问题就解决了。后续将这个问题反馈给系统组，由系统组去解决问题即可。
后记
linux kernel中其实有许多的埋点，可以通过perf的帮助自行查看，通过一些组合命令，可以实现一些不错的效果。例如实时监控系统里面创建哪些程序（名字、路径等等信息）。
在现在这个时代，已经不是古法排查、古法编程时代了，但是你只要掌握方向，给AI进行提示，依然可以提升你的分析、处理问题的能力。
参考文献
- 无
打赏、订阅、收藏、丢香蕉、硬币，请关注公众号（攻城狮的搬砖之路）
PS: 请尊重原创，不喜勿喷。
PS: 要转载请注明出处，本人版权所有。
PS: 有问题请留言，看到后我会第一时间回复。
来源：博客园 · cnblogs.com