On 09/08/16 06:53, Tony Lindgren wrote:
> * Peter Ujfalusi <peter.ujfalusi@xxxxxx> [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
_______________________________________________
Alsa-devel mailing list
Alsa-devel@xxxxxxxxxxxxxxxx
http://mailman.alsa-project.org/mailman/listinfo/alsa-devel
