[alsa-devel] [PATCH] ASoC: omap-mcbsp: Add PM QoS support for McBSP to prevent glitches

[Peter Ujfalusi]

On 09/08/16 06:53, Tony Lindgren wrote:
> * Peter Ujfalusi <peter.ujfalusi at ti.com> [160907 07:32]:
>> On 09/06/2016 11:16 PM, Tony Lindgren wrote:
>>> Makes sense. Do you have a formula or updated patch I can test here?
>>> Then we can add comments about the possible unaccounted latencies that
>>> can be worked out as needed.
>>
>> Not yet, but I'll try to come up with something in the coming days.
> 
> OK

I managed to get time for this and it looks like that we only need to block
core OFF for audio. I don't know why C6 ("MPU OFF + CORE RET") with it's 3000
+ 8500 exit latency not causing issues when we have less time from the DMA
request to empty FIFO...

My findings so far:
w/o the QoS patch we will hit core OFF even if we are in element mode in McBSP:
# cat /sys/devices/platform/68000000.ocp/49022000.mcbsp/dma_op_mode
[element] threshold

If I start the playback we will hit core OFF even if the we have DMA request
coming at every sample (every 0.02ms).

With the QoS set to 30ms and:
# cat /sys/devices/platform/68000000.ocp/49022000.mcbsp/dma_op_mode
element [threshold]
# cat /sys/devices/platform/68000000.ocp/49022000.mcbsp/max_tx_thres
1264

# cat /sys/kernel/debug/pm_debug/count; aplay -Dplughw:0,0
media/music/nin-echoplex.wav; cat /sys/kernel/debug/pm_debug/count

core_pwrdm
(ON),OFF:1885,RET:6777,INA:86320,ON:94983,RET-LOGIC-OFF:0,RET-MEMBANK1-OFF:0,RET-MEMBANK2-OFF:0
per_pwrdm (ON),OFF:2507,RET:1518,INA:0,ON:4026,RET-LOGIC-OFF:0,RET-MEMBANK1-OFF:0
mpu_pwrdm
(ON),OFF:80588,RET:7876,INA:97390,ON:185855,RET-LOGIC-OFF:0,RET-MEMBANK1-OFF:0

Playing WAVE 'media/music/nin-echoplex.wav' : Signed 16 bit Little Endian,
Rate 48000 Hz, Stereo

core_pwrdm
(ON),OFF:1885,RET:7860,INA:107434,ON:117180,RET-LOGIC-OFF:0,RET-MEMBANK1-OFF:0,RET-MEMBANK2-OFF:0
per_pwrdm (ON),OFF:2507,RET:1518,INA:0,ON:4026,RET-LOGIC-OFF:0,RET-MEMBANK1-OFF:0
mpu_pwrdm
(ON),OFF:103223,RET:8185,INA:97461,ON:208870,RET-LOGIC-OFF:0,RET-MEMBANK1-OFF:0

We hit C6, but when the DMA request comes we have 16 words in the FIFO (8
samples, 0.16ms of audio). C6 should take 11.5ms to exit...

>> btw: I have tried the idle off on beagbeboard-xm with audio, but even w/o the
>> qos it is not triggering. w/o audio I hit off but if audio is running, not.
> 
> OK yeah figured it out you need to comment out the watch -n5 command
> as that keeps the serial console busy :) I was doing it over ssh earlier
> on the torpedo board.
> 
>> btw2: if you set the qos to 30ms and set the mcbsp2 threshold to 1024 (or
>> leave it as default) do you have audio glitches? I think if we hit C6 we
>> should not be able to wake up in time...
> 
> Not that I've noticed at least with the default fifo size. How can
> I force the threshold to 1024? I tried changing pkt_size for
> omap_mcbsp_set_threshold but not getting any audio.

Based on my experiments the FIFO threshold does not matter as even if we
should not be able to leave from a C state in time, we do leave from the state :o

The patch generates the following warning when the playback is stopped:
[  115.726531]
[  115.728149] =================================
[  115.732727] [ INFO: inconsistent lock state ]
[  115.737304] 4.8.0-rc3-next-20160825-00064-g957cf3635c39-dirty #1450 Not tainted
[  115.744964] ---------------------------------
[  115.749542] inconsistent {SOFTIRQ-ON-W} -> {IN-SOFTIRQ-W} usage.
[  115.755859] swapper/0/0 [HC0[0]:SC1[1]:HE0:SE0] takes:
[  115.761230]  ((&(&req->work)->work)){+.?...}, at: [<c0152fe0>]
flush_work+0x0/0x260
[  115.769348] {SOFTIRQ-ON-W} state was registered at:
[  115.774475]   [<c015301c>] flush_work+0x3c/0x260
[  115.779357]   [<c0155b74>] __cancel_work_timer+0x90/0x1c0
[  115.785034]   [<c01999c8>] pm_qos_update_request+0x28/0x54
[  115.790802]   [<c01549ec>] process_one_work+0x1fc/0x770
[  115.796295]   [<c0154f98>] worker_thread+0x38/0x550
[  115.801452]   [<c015b0b8>] kthread+0xd4/0xf0
[  115.805969]   [<c0107910>] ret_from_fork+0x14/0x24
[  115.811004] irq event stamp: 191097
[  115.814666] hardirqs last  enabled at (191096): [<c07f8fb8>]
_raw_spin_unlock_irq+0x24/0x2c
[  115.823455] hardirqs last disabled at (191097): [<c0663f30>]
_snd_pcm_stream_lock_irqsave+0x2c/0x40
[  115.832977] softirqs last  enabled at (191090): [<c013e5dc>]
irq_enter+0x68/0x84
[  115.840759] softirqs last disabled at (191091): [<c013e6b8>]
irq_exit+0xc0/0x134
[  115.848541]
[  115.848541] other info that might help us debug this:
[  115.855407]  Possible unsafe locking scenario:
[  115.855407]
[  115.861602]        CPU0
[  115.864166]        ----
[  115.866760]   lock((&(&req->work)->work));
[  115.871063]   <Interrupt>
[  115.873809]     lock((&(&req->work)->work));
[  115.878326]
[  115.878326]  *** DEADLOCK ***
[  115.878326]
[  115.884552] 2 locks held by swapper/0/0:
[  115.888671]  #0:  (snd_pcm_link_rwlock){...-..}, at: [<c0663e9c>]
snd_pcm_stream_lock+0x20/0x50
[  115.897857]  #1:  (&(&substream->self_group.lock)->rlock){..-...}, at:
[<c0663f38>] _snd_pcm_stream_lock_irqsave+0x34/0x40
[  115.909515]
[  115.909515] stack backtrace:
[  115.914123] CPU: 0 PID: 0 Comm: swapper/0 Not tainted
4.8.0-rc3-next-20160825-00064-g957cf3635c39-dirty #1450
[  115.924530] Hardware name: Generic OMAP36xx (Flattened Device Tree)
[  115.931121] [<c0110128>] (unwind_backtrace) from [<c010c2c0>]
(show_stack+0x10/0x14)
[  115.939270] [<c010c2c0>] (show_stack) from [<c048c120>] (dump_stack+0xb0/0xe4)
[  115.946868] [<c048c120>] (dump_stack) from [<c0192708>]
(print_usage_bug+0x1e0/0x2d4)
[  115.955108] [<c0192708>] (print_usage_bug) from [<c0192d7c>]
(mark_lock+0x580/0x6c4)
[  115.963256] [<c0192d7c>] (mark_lock) from [<c0193a38>]
(__lock_acquire+0x5a8/0x187c)
[  115.971374] [<c0193a38>] (__lock_acquire) from [<c0195128>]
(lock_acquire+0xd0/0x238)
[  115.979614] [<c0195128>] (lock_acquire) from [<c015301c>]
(flush_work+0x3c/0x260)
[  115.987487] [<c015301c>] (flush_work) from [<c0155b74>]
(__cancel_work_timer+0x90/0x1c0)
[  115.996002] [<c0155b74>] (__cancel_work_timer) from [<c0199ad8>]
(pm_qos_remove_request+0x28/0x1c8)
[  116.005523] [<c0199ad8>] (pm_qos_remove_request) from [<c0684634>]
(omap_mcbsp_dai_trigger+0x70/0x8c)
[  116.015197] [<c0684634>] (omap_mcbsp_dai_trigger) from [<c067baa8>]
(soc_pcm_trigger+0xd0/0x11c)
[  116.024414] [<c067baa8>] (soc_pcm_trigger) from [<c0663be0>]
(snd_pcm_do_stop+0x50/0x54)
[  116.032928] [<c0663be0>] (snd_pcm_do_stop) from [<c06639c4>]
(snd_pcm_action_single+0x38/0x80)
[  116.041961] [<c06639c4>] (snd_pcm_action_single) from [<c066aa4c>]
(snd_pcm_update_state+0xd0/0x100)
[  116.051574] [<c066aa4c>] (snd_pcm_update_state) from [<c066ac20>]
(snd_pcm_update_hw_ptr0+0x1a4/0x3ac)
[  116.061340] [<c066ac20>] (snd_pcm_update_hw_ptr0) from [<c066ae9c>]
(snd_pcm_period_elapsed+0x74/0xb4)
[  116.071136] [<c066ae9c>] (snd_pcm_period_elapsed) from [<c04e63f8>]
(vchan_complete+0x190/0x1a4)
[  116.080352] [<c04e63f8>] (vchan_complete) from [<c013ee68>]
(tasklet_action+0x88/0x128)
[  116.088775] [<c013ee68>] (tasklet_action) from [<c013dee0>]
(__do_softirq+0xc4/0x55c)
[  116.096984] [<c013dee0>] (__do_softirq) from [<c013e6b8>] (irq_exit+0xc0/0x134)
[  116.104675] [<c013e6b8>] (irq_exit) from [<c01a17a8>]
(__handle_domain_irq+0x6c/0xe0)
[  116.112884] [<c01a17a8>] (__handle_domain_irq) from [<c07f96b0>]
(__irq_svc+0x70/0x98)
[  116.121215] [<c07f96b0>] (__irq_svc) from [<c0613808>]
(cpuidle_enter_state+0x15c/0x464)
[  116.129699] [<c0613808>] (cpuidle_enter_state) from [<c0187788>]
(cpu_startup_entry+0x2b8/0x3e0)
[  116.138946] [<c0187788>] (cpu_startup_entry) from [<c0b00c1c>]
(start_kernel+0x340/0x3b4)

There is one more issue: if we have playback and capture running at the same
time and you stop one of them. It will remove the QoS and the remaining stream
might break.

-- 
Péter