ALSA子系統(tǒng) | 一次性能優(yōu)化

Linux內核實戰(zhàn)課

科大訊飛用到我司的一款芯片做識別筆，叫啥阿爾法蛋，一看就不是啥好蛋。。。。。。。

這客戶反饋每次用識別筆去識別文字的時候，啟動的時候概率性會卡住大概一秒鐘的時間才會有語音響起，很影響用戶體驗。

時間比較緊急，快要量產了，客戶希望我在三天內解決，好家伙，我直接好家伙。

（問題是小半年前解的問題了）然后剛剛某寶看下了，這個詞典筆居然賣六百九十九人民幣，哇，搶錢啊。

拿到機器，我先使用tinyplay工具進行測試，發(fā)現(xiàn)現(xiàn)象正常，沒有復現(xiàn)到有這場景，懷疑是不是他們應用這塊調用流程有問題（tinyplay的流程可以參考我這篇文章：Tinyplay流程分析），因為客戶的應用層代碼（算法）是保密的，沒有給到我，就現(xiàn)場吭哧吭哧給我大概講了他們的應用流程。

作為一名合格的驅動工程師，只好發(fā)揮我的主觀能動性了，先從底層查起吧。因為沒有客戶環(huán)境，客戶的固件我也動不了，只好在我們的sdk上編譯出內核鏡像，只燒寫到他們機器的kernel分區(qū)替換內核鏡像作實驗了。

經測試，發(fā)現(xiàn)僅每次播音第一段音頻開始時有此現(xiàn)象，第二次write數(shù)據(jù)時就不會。因為每次僅第一段音頻會卡住等待一小會，加上具體log抓耗時分析，發(fā)現(xiàn)耗時主要在pcm_perpare函數(shù)，猜測：

錯誤關中斷造成的鎖互斥造成的

一開始覺得是不是哪里長時間關了中斷導致響應不及時造成的延時，所以用trace抓了一下數(shù)據(jù)，關于trace使用可以參考我這篇文章：使用trace查看函數(shù)調用關系|分析Linux性能

mount?-t?debugfs?none?/sys/kernel/debug/
cd?/sys/kernel/debug/tracing/
echo?0?>?tracing_on
echo?irqsoff?>?current_tracer
echo?1?>?tracing_on
執(zhí)行客戶程序
echo?0?>?tracing_on

查看結果：

#?tracer:?irqsoff
#
#?irqsoff?latency?trace?v1.1.5?on?4.9.191
#?--------------------------------------------------------------------
#?latency:?628?us,?#286/286,?CPU#0?|?(M:preempt?VP:0,?KP:0,?SP:0?HP:0)
#????-----------------
#????|?task:?swapper-0?(uid:0?nice:0?policy:0?rt_prio:0)
#????-----------------
#??=>?started?at:?__irq_svc
#??=>?ended?at:???__do_softirq
#
#
#??????????????????_------=>?CPU#
#?????????????????/?_-----=>?irqs-off
#????????????????|?/?_----=>?need-resched
#????????????????||?/?_---=>?hardirq/softirq
#????????????????|||?/?_--=>?preempt-depth
#????????????????||||?/?????delay
#??cmd?????pid???|||||?time??|???caller
#????????/??????|||||??????|???/
??<idle>-0???????0d..1????1us?:?__irq_svc
??<idle>-0???????0d..2????2us?:?gic_handle_irq?<-__irq_svc
??<idle>-0???????0d..2????5us?:?__handle_domain_irq?<-gic_handle_irq
??<idle>-0???????0d..2????7us?:?irq_enter?<-__handle_domain_irq
??<idle>-0???????0d..2????8us?:?rcu_irq_enter?<-irq_enter
??<idle>-0???????0d..2???11us?:?__local_bh_disable_ip?<-irq_enter
??<idle>-0???????0d..2???13us?:?tick_irq_enter?<-irq_enter
??<idle>-0???????0d..2???15us?:?ktime_get?<-tick_irq_enter
??<idle>-0???????0d..2???17us?:?arch_counter_read?<-ktime_get
??<idle>-0???????0d..2???19us?:?arch_counter_read_cc?<-arch_counter_read
??<idle>-0???????0d..2???21us?:?update_ts_time_stats.constprop.10?<-tick_irq_enter
??<idle>-0???????0d..2???23us?:?nr_iowait_cpu?<-update_ts_time_stats.constprop.10
??<idle>-0???????0d..2???25us?:?tick_do_update_jiffies64?<-tick_irq_enter
??<idle>-0???????0d..2???27us?:?preempt_count_add?<-tick_do_update_jiffies64
??<idle>-0???????0d..3???30us?:?do_timer?<-tick_do_update_jiffies64
??<idle>-0???????0d..3???34us?:?calc_global_load?<-do_timer
//后面無關省略

我一看，最大中斷延時才628us，那明顯和這個沒關系啊。

那么，會不會是之前猜測到第二點原因呢？trace工具不能很好到抓取鎖和資源到競爭關系，這里需要用到perf工具，關于perf之后我再開一篇文章來闡述使用方法吧，這里使用perf工具分析，發(fā)現(xiàn)沒有發(fā)現(xiàn)鎖競爭出現(xiàn)忙等待到情況啊~~~

那么問題是出現(xiàn)在哪里呢？只好用老辦法了，查看具體是在哪個函數(shù)最耗時?。?/p>

既然如此到話，prepare下到流程何其多，我們難道要在每個函數(shù)下加打印跟蹤耗時嗎？？？如果這樣做到話，效率也太低了吧，所幸，trace能用到這一點，在asoc代碼里，關鍵到函數(shù)本身已經具備了trace_point了，我們只需開啟trace就能用了??！

mount?-t?debugfs?none?/sys/kernel/debug/
cd?/sys/kernel/debug/tracing/
echo?0?>?tracing_on
echo?asoc?>?set_event
echo?1?>?tracing_on
執(zhí)行客戶程序
echo?0?>?tracing_on
cat?trace

查看結果，有重大發(fā)現(xiàn)！

發(fā)現(xiàn)snd_soc_dapm_done這里居然耗時了900多ms，很可疑，非常可疑。

PS：trace還是比較好用的，還能看到DAPM里各個widget的連接情況。

查找代碼，發(fā)現(xiàn)是在sound/soc/soc-dapm.c文件里的dapm_power_widgets函數(shù)里，這個函數(shù)比較重要，主要是掃描dapm鏈路上widget的path完整性，以便及時給widget上下電。

進一步加打印抓取時間，發(fā)現(xiàn)耗時主要在這個函數(shù)片段：

/*
?*?Scan?each?dapm?widget?for?complete?audio?path.
?*?A?complete?path?is?a?route?that?has?valid?endpoints?i.e.:-
?*
?*??o?DAC?to?output?pin.
?*??o?Input?pin?to?ADC.
?*??o?Input?pin?to?Output?pin?(bypass,?sidetone)
?*??o?DAC?to?ADC?(loopback).
?*/
static?int?dapm_power_widgets(struct?snd_soc_card?*card,?int?event)
{
//......
/*?Run?other?bias?changes?in?parallel?*/
?list_for_each_entry(d,?&card->dapm_list,?list)?{
??if?(d?!=?&card->dapm)
???async_schedule_domain(dapm_pre_sequence_async,?d,
??????&async_domain);
?}
?async_synchronize_full_domain(&async_domain);
//......
trace_snd_soc_dapm_done(card);
return?0;
}

從注釋就可以看出，這里會遍歷audio 路由patch里的dapm widget，設置bias_level。耗時主要在async_synchronize_full_domain函數(shù)，這里就是等待async_schedule_domain函數(shù)里的回調執(zhí)行完畢。

猜測是在系統(tǒng)負載比較重的時候，任務不能及時調度，造成了延時，所以async_synchronize_full_domain函數(shù)才會阻塞等待好幾百ms。通過top命令也證實，在跑這個客戶的應用時，CPU負載一度達到了70+%。

通過git log命令查看歷史提交記錄，發(fā)現(xiàn)這段代碼在2011年由Mark Brown修改，啊，是大佬，不好意思，打擾了。。。。。。

大佬的補丁修改如下：

將之前的一些bias_level操作放到線程里面調度執(zhí)行。

唉，但是我們現(xiàn)在這芯片是單核的啊，系統(tǒng)負載重時，work線程優(yōu)先級低可不就卡在這里了嘛，沒辦法，只要做下小兼容了，在單核系統(tǒng)上就不要放到線程里了吧~

最后問題順利解決。補丁如下：

diff?--git?a/sound/soc/soc-dapm.c?b/sound/soc/soc-dapm.c
index?0b5d132..ab57e90?100644
---?a/sound/soc/soc-dapm.c
+++?b/sound/soc/soc-dapm.c
@@?-1902,11?+1902,15?@@?static?int?dapm_power_widgets(struct?snd_soc_card?*card,?int?event)
????????/*?Run?other?bias?changes?in?parallel?*/
????????list_for_each_entry(d,?&card->dapm_list,?list)?{
????????????????if?(d?!=?&card->dapm)
+#ifdef?CONFIG_SMP
????????????????????????async_schedule_domain(dapm_pre_sequence_async,?d,
????????????????????????????????????????????????&async_domain);
????????}
????????async_synchronize_full_domain(&async_domain);
-
+#else
+???????????????????????dapm_pre_sequence_async(d,?&async_domain);
+???????}
+#endif
????????list_for_each_entry(w,?&down_list,?power_list)?{
????????????????dapm_seq_check_event(card,?w,?SND_SOC_DAPM_WILL_PMD);
????????}
@@?-1926,10?+1930,15?@@?static?int?dapm_power_widgets(struct?snd_soc_card?*card,?int?event)
????????/*?Run?all?the?bias?changes?in?parallel?*/
????????list_for_each_entry(d,?&card->dapm_list,?list)?{
????????????????if?(d?!=?&card->dapm)
-???????????????????????async_schedule_domain(dapm_post_sequence_async,?d,
+#ifdef?CONFIG_SMP
+???????????????????????async_schedule_domain(dapm_pre_sequence_async,?d,
????????????????????????????????????????????????&async_domain);
????????}
????????async_synchronize_full_domain(&async_domain);
+#else
+???????????????????????dapm_pre_sequence_async(d,?&async_domain);
+???????}
+#endif
????????/*?Run?card?bias?changes?at?last?*/
????????dapm_post_sequence_async(&card->dapm,?0);