Linux程序性能分析（二）--- 实例分析1
PS：要转载请注明出处，本人版权所有。
PS: 这个只是基于《我自己》的理解，
如果和你的原则及想法相冲突，请谅解，勿喷。
环境说明
无
前言
在《Linux程序性能分析（一）---perf原理分析》 https://www.cnblogs.com/Iflyinsky/p/22507762 中，我已经简单分析了perf的工作原理，现在以两篇工作中实际遇到的问题来实际分析。
先来一篇简单的，可以快速上手的。
通过perf分析用户态的程序
本示例是一个典型的技术架构设计与实际落地工程实践取舍的问题，具体是：我们自己根据高通提供的参考代码，实现了一版自己的大模型推理程序，并通过http接口暴露了openai api。在客户的实际使用过程中，发现在没有任何http请求时，这个推理程序会莫名的占用200%左右的cpu，具体如下图：
根据我们之前的经验，直接抓取所有cpu的perf堆栈采样信息，看看到底哪些函数在跑？这次由于我们知道是哪个程序，因此我们直接传入pid来针对程序进行采集：
echo 0 > /proc/sys/kernel/kptr_restrict
echo -1 > /proc/sys/kernel/perf_event_paranoid
perf record -a -g -F 99 -p target_pid -- sleep 5
perf report --no-children --stdio > perf_data.txt
然后我得到了原始堆栈结构：
# To display the perf.data header info, please use --header/--header-only options.
#
#
# Total Lost Samples: 0
#
# Samples: 948 of event 'cycles'
# Event count (approx.): 27416695488
#
# Overhead Command Shared Object Symbol
# ........ ....... ......................... .......................................
#
15.24% api libc.so.6 [.] __aarch64_swp4_rel
|
---__aarch64_swp4_rel
0x781b82d0f0
0x78247231fc
start_thread
thread_start
15.20% api libc.so.6 [.] __aarch64_cas4_acq
|
---__aarch64_cas4_acq
0x781b82d0bc
0x78247231fc
start_thread
thread_start
11.97% api [unknown] [k] 0xffffffe3fcaa3604
|
---0xffffffe3fcaa3604
0xffffffe3fcaa355c
0xffffffe3fe620620
0xffffffe3fe620598
0xffffffe3fca1164c
|
|--8.10%--__GI___lll_lock_wake
| 0x781b82d0f0
| 0x78247231fc
| start_thread
| thread_start
|
--3.87%--__GI___lll_lock_wait
pthread_mutex_lock@@GLIBC_2.17
0x781b82d0bc
0x78247231fc
start_thread
thread_start
6.25% api libc.so.6 [.] __aarch64_swp4_acq
|
---__aarch64_swp4_acq
pthread_mutex_lock@@GLIBC_2.17
0x781b82d0bc
0x78247231fc
start_thread
thread_start
6.11% api [unknown] [k] 0xffffffe3fcc94744
|
---0xffffffe3fcc94744
0xffffffe3fcc93984
0xffffffe3fcc9c010
0xffffffe3fcaa3724
0xffffffe3fcaa3684
0xffffffe3fcaa355c
0xffffffe3fe620620
0xffffffe3fe620598
0xffffffe3fca1164c
__GI___lll_lock_wake
0x781b82d0f0
0x78247231fc
start_thread
thread_start
5.63% api [unknown] [k] 0xffffffe3fcc9470c
|
---0xffffffe3fcc9470c
0xffffffe3fcc93984
0xffffffe3fcc9c010
0xffffffe3fcaa3724
0xffffffe3fcaa3684
0xffffffe3fcaa355c
0xffffffe3fe620620
0xffffffe3fe620598
0xffffffe3fca1164c
__GI___lll_lock_wake
0x781b82d0f0
0x78247231fc
start_thread
thread_start
由于原始堆栈结构里面有很多地址是未知的（因为产品化的so，一般都做了符号管制），这个时候，我们需要从下载和so对应的符号文件（这个需要提前准备，也是一个比较好的生产级产品化做法），然后让AI使用内核地址、so地址去解决对应的符号，得到了下面的符号化的堆栈结构：
# To display the perf.data header info, please use --header/--header-only options.
#
#
# Total Lost Samples: 0
#
# Samples: 948 of event 'cycles'
# Event count (approx.): 27416695488
#
# Overhead Command Shared Object Symbol
# ........ ....... ......................... .......................................
#
15.24% api libc.so.6 [.] __aarch64_swp4_rel
|
---__aarch64_swp4_rel
qualla::ThreadPool::loop+0x160
execute_native_thread_routine
start_thread
thread_start
15.20% api libc.so.6 [.] __aarch64_cas4_acq
|
---__aarch64_cas4_acq
qualla::ThreadPool::loop+0x12c
execute_native_thread_routine
start_thread
thread_start
11.97% api [unknown] [k] el0_svc_common
|
---el0_svc_common+0x38
do_el0_svc+0x28
el0_svc+0x24
el0t_64_sync_handler+0x88
el0t_64_sync+0x1b8
|
|--8.10%--__GI___lll_lock_wake
| qualla::ThreadPool::loop+0x160
| execute_native_thread_routine
| start_thread
| thread_start
|
--3.87%--__GI___lll_lock_wait
pthread_mutex_lock@@GLIBC_2.17
qualla::ThreadPool::loop+0x12c
execute_native_thread_routine
start_thread
thread_start
6.25% api libc.so.6 [.] __aarch64_swp4_acq
|
---__aarch64_swp4_acq
pthread_mutex_lock@@GLIBC_2.17
qualla::ThreadPool::loop+0x12c
execute_native_thread_routine
start_thread
thread_start
6.11% api [unknown] [k] futex_wake
|
---futex_wake+0x190
do_futex+0x1a4
__arm64_sys_futex+0x234
invoke_syscall+0x60
el0_svc_common+0xb8
do_el0_svc+0x28
el0_svc+0x24
el0t_64_sync_handler+0x88
el0t_64_sync+0x1b8
__GI___lll_lock_wake
qualla::ThreadPool::loop+0x160
execute_native_thread_routine
start_thread
thread_start
5.63% api [unknown] [k] futex_wake
|
---futex_wake+0x158
do_futex+0x1a4
__arm64_sys_futex+0x234
invoke_syscall+0x60
el0_svc_common+0xb8
do_el0_svc+0x28
el0_svc+0x24
el0t_64_sync_handler+0x88
el0t_64_sync+0x1b8
__GI___lll_lock_wake
qualla::ThreadPool::loop+0x160
execute_native_thread_routine
start_thread
thread_start
其实通过上面的堆栈，我们马上就看出来了有线程在死循环，并反复的lock/unlock 这个 std::mutex对象。直接根据符号，查看对应的源码，果然，代码里面，为了kvcache的响应及时性，强行死循环运行，避免了sleep/wait/notify等带来的推理时的开销。其他代码示意如下：
std::mutex mtx;
void ThreadPool::loop()
{
std::unique_lock<std::mutex> lock(mtx, std::defer_lock);
while(1){
lock.lock();
// do something
lock.unlock();
}
}
最后，根据实际情况，我们没有改变死循环的核心代码，我们采用的方式是，当有推理任务时，通知线程开始死循环运行，既保证了kvcache的实时性，也保证了模型不推理的情况下，资源占用是比较小的。但是在模型推理时，并没有解决死循环带来的cpu空载开销。然后现在我们再看看cpu的占用情况。
发现在系统空载时，成功解决了问题。
后记
站在这个AI可以帮你自动解决类似问题的时代，手把手实际例子来验证原理是一个有趣的事情，也可以加强对这个的原理理解，使得我更加善于使用AI排查问题。
参考文献
- 无
PS: 请尊重原创，不喜勿喷。
PS: 要转载请注明出处，本人版权所有。
PS: 有问题请留言，看到后我会第一时间回复。
浙公网安备 33010602011771号