pr_emerg耗时，影响性能原理排查

概述

本文涉及到的性能debug方式如下：

1. ftrace的使用。
2. lock contention/lockdep的使用。

一、 问题来源以及debug思路

“在调试 vdsp的dvfs,发现notify执行dvfs callback的时候callback中执行会很慢，两条log之间什么都不作，耗时都可能在8ms左右，固定cpu/ddr频率也不没效果。”

debug思路如下:

1. 确认在何种情况下导致的？
2. 耗时原因,怀疑是持锁时间过长导致的？
3. 开启debug feature定位原因。

二、问题复现

从camera owner提供的log来看，可以确定是pr_emerg答应log方式导致耗时较长，去掉这个log也验证了是其导致的。这一个类型log一般使用在kernel panic或者串口log中。按照之前的项目经验才确定是这种导致的性能下降，但是一直没有去深究为何？
在任意位置添加如下的log：

trace_printk("samarxie  11111\n");  
pr_emerg("samarxie func=%s enter\n",__func__);  
trace_printk("samarxie  22222\n");  
pr_err("samarxie pr_err====\n");  
trace_printk("samarxie  33333\n");  
pr_emerg("samarxie func=%s exit\n",__func__);  
trace_printk("samarxie  44444\n");  

只要编译KO或者bootimage刷入手机看log输出即可。
正常情况是所有log出现的时间顺序应该间隔非常短,在us级别.但是从正常的log看,信息如下:

<0>[  373.701444] c0 samarxie func=dbs_check_cpu_xxx enter  
<3>[  373.706543] c0 samarxie pr_err====  
<0>[  373.706565] c0 samarxie func=dbs_check_cpu_xxx exit

可以看到

pr_emerg("samarxie func=%s enter\n",__func__);  
pr_err("samarxie pr_err====\n"); 

这两个log时间耗时很长.
从trace可以看到如下信息:

sh-8278  [000] ..s.   373.701427: dbs_check_cpu_xxx: samarxie  11111    
sh-8278  [000] ..s.   373.706538: dbs_check_cpu_xxx: samarxie  22222 

也是耗时这么长时间。
所以可以确定是pr_emerg的使用导致耗时过长,并且会影响性能.但是为何呢?pr_emerg是log level为0,而我们平台的log level=1就会往串口输出数据。

#define pr_emerg(fmt, ...) \
	printk(KERN_EMERG pr_fmt(fmt), ##__VA_ARGS__)

#define KERN_EMERG	KERN_SOH "0"	/* system is unusable */

三、开启lock dep/debug config进行debug

我继续check到底是哪里耗时这么长呢?开启lock trace debug feature,具体开启如下的config：

#  
# Lock Debugging (spinlocks, mutexes, etc...)  
#  
-# CONFIG_DEBUG_RT_MUTEXES is not set  
-# CONFIG_DEBUG_SPINLOCK is not set  
-# CONFIG_DEBUG_MUTEXES is not set  
-# CONFIG_DEBUG_WW_MUTEX_SLOWPATH is not set  
-# CONFIG_DEBUG_LOCK_ALLOC is not set  
-# CONFIG_PROVE_LOCKING is not set  
-# CONFIG_LOCK_STAT is not set  
+CONFIG_DEBUG_RT_MUTEXES=y  
+CONFIG_DEBUG_SPINLOCK=y  
+CONFIG_DEBUG_MUTEXES=y  
+CONFIG_DEBUG_WW_MUTEX_SLOWPATH=y  
+CONFIG_DEBUG_LOCK_ALLOC=y  
+CONFIG_PROVE_LOCKING=y  
+CONFIG_LOCKDEP=y  
+CONFIG_LOCK_STAT=y  
+CONFIG_DEBUG_LOCKDEP=y  

开启上面的之后,我们就可以trace lock的情况了.
在sys/kernel/debug/tracing/event/lock/目录下存在如下的event:

/sys/kernel/debug/tracing/events/lock # ls -l  
total 0  
-rw-r--r-- 1 root root 0 1970-01-01 08:00 enable  
-rw-r--r-- 1 root root 0 1970-01-01 08:00 filter  
drwxr-xr-x 2 root root 0 1970-01-01 08:00 lock_acquire  
drwxr-xr-x 2 root root 0 1970-01-01 08:00 lock_acquired  
drwxr-xr-x 2 root root 0 1970-01-01 08:00 lock_contended  
drwxr-xr-x 2 root root 0 1970-01-01 08:00 lock_release  

之后使用如下的ftrace脚本,抓取复现场景的信息即可：

#!/bin/bash  
adb root  
adb remount  
#low memory,buffer size should be little. otherwise lose trace event  
adb shell "echo 60000 > /d/tracing/buffer_size_kb"  
  
#adb shell "echo sched_switch sched_wakeup sched_waking > /d/tracing/set_event"  
adb shell "echo lock> /d/tracing/set_event"  
  
adb shell "echo > /d/tracing/trace"  
adb shell "echo 0 > /d/tracing/tracing_on"  
sleep 1  
  
echo "start fetch trace informantion $1s"  
adb shell "echo 1 > /d/tracing/tracing_on"  
  
#set fetch trace timeout  
echo "do anything"  
sleep $1  
  
adb shell "echo 0 > /d/tracing/tracing_on"  
echo "fetch trace informantion end"  
echo "save trace to /data/trace.txt file"  
adb shell "cat /d/tracing/trace > /data/trace.txt"  
echo "all fetch over!"  
echo "start pull file in current dir"  
time=`date '+%T'`  
adb pull /data/trace.txt $time-trace.txt  
echo "pull file name is $time-trace.txt"  

就可以看到,是console_lock一直持锁导致的:

sh-8278  [000] .