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

Linux內(nèi)核實(shí)戰(zhàn)課

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

這客戶反饋每次用識(shí)別筆去識(shí)別文字的時(shí)候，啟動(dòng)的時(shí)候概率性會(huì)卡住大概一秒鐘的時(shí)間才會(huì)有語(yǔ)音響起，很影響用戶體驗(yàn)。

時(shí)間比較緊急，快要量產(chǎn)了，客戶希望我在三天內(nèi)解決，好家伙，我直接好家伙。

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

拿到機(jī)器，我先使用tinyplay工具進(jìn)行測(cè)試，發(fā)現(xiàn)現(xiàn)象正常，沒(méi)有復(fù)現(xiàn)到有這場(chǎng)景，懷疑是不是他們應(yīng)用這塊調(diào)用流程有問(wèn)題（tinyplay的流程可以參考我這篇文章：Tinyplay流程分析），因?yàn)榭蛻舻?a class="article-link" target="_blank" href="/baike/1555864.html">應(yīng)用層代碼（算法）是保密的，沒(méi)有給到我，就現(xiàn)場(chǎng)吭哧吭哧給我大概講了他們的應(yīng)用流程。

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

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

錯(cuò)誤關(guān)中斷造成的鎖互斥造成的

一開始覺(jué)得是不是哪里長(zhǎng)時(shí)間關(guān)了中斷導(dǎo)致響應(yīng)不及時(shí)造成的延時(shí)，所以用trace抓了一下數(shù)據(jù)，關(guān)于trace使用可以參考我這篇文章：使用trace查看函數(shù)調(diào)用關(guān)系|分析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

查看結(jié)果：

#?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
//后面無(wú)關(guān)省略

我一看，最大中斷延時(shí)才628us，那明顯和這個(gè)沒(méi)關(guān)系啊。

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

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

既然如此到話，prepare下到流程何其多，我們難道要在每個(gè)函數(shù)下加打印跟蹤耗時(shí)嗎？？？如果這樣做到話，效率也太低了吧，所幸，trace能用到這一點(diǎn)，在asoc代碼里，關(guān)鍵到函數(shù)本身已經(jīng)具備了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

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

發(fā)現(xiàn)snd_soc_dapm_done這里居然耗時(shí)了900多ms，很可疑，非?？梢伞?/p>

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

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

進(jìn)一步加打印抓取時(shí)間，發(fā)現(xiàn)耗時(shí)主要在這個(gè)函數(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;
}

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

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

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

大佬的補(bǔ)丁修改如下：

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

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

最后問(wèn)題順利解決。補(bǔ)丁如下：

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);