Skip to content

Stress test : Keeping pause/resume or XRUN injection can causes DSP panic when playback or capture  #272

Closed
Closed
Stress test : Keeping pause/resume or XRUN injection can causes DSP panic when playback or capture #272
Assignees
xiulipan
Labels
APLApplies to Apollolake platformP2Critical bugs or normal featuresbugSomething isn't working as expectedduplicateThis issue or pull request already exists

Description

@ZhendanYang
ZhendanYang
opened on Aug 29, 2018

Summary:
Keep pressing space key for pause/resume or inject XRUN when playback or capture can cause ipc error, dsp panic, ipc time out.

Repreduce steps:

  1. aplay -D hw:0,0 -c 2 -r 48000 -f s16_le music.wav --period-size=192 --buffer-size=384 -vv -i
  2. press space key until input/output error
  3. dmesg

Environment:
sof-dev : f9c923e5ca9b38df7ddc71f26b55eb2bd1ffed46
sof :
matser branch : f10b52f
stable 1.2 branch: 7346243
glk-003-drop-stable branch: 0ead9e7
soft : 41861aa
tplg :
sof-apl-nocodec.tplg on apl
test-ssp2-mclk-0-I2S-volume-s16le-s16le-48k-19200k-codec.tplg on byt
test-ssp0-mclk-0-I2S-volume-s16le-s16le-48k-24000k-nocodec.tplg on cnl

When I git revert commit df0d701 in sof-master, this issue disappears.

Logs:
on up^2:
dmesg-apl.log
rmbox-apl.log
rmbox-t-apl.log

on cnl:
dmesg-cnl.log
rmbox-cnl.log
rmbox-t-cnl.log

on byt:
dmesg-byt.log
rmbox-byt.log
rmbox-t-byt.log

Activity

  1. ZhendanYang
    added
    bugSomething isn't working as expected
    APLApplies to Apollolake platform
    BYTApplies to Baytrail platform
    CNLApplies to Cannonlake platform
    regression
    P1Blocker bugs or important features
    on Aug 29, 2018

  2. lgirdwood commented on Aug 29, 2018

    @lgirdwood
    lgirdwood
    on Aug 29, 2018
    Member

    It's a (NULL + 0x40) pointer deref at run level 5, probably in the scheduler.

  3. lgirdwood
    assigned
    xiulipan
    on Aug 29, 2018

  4. xiulipan commented on Aug 29, 2018

    @xiulipan
    xiulipan
    on Aug 29, 2018
    Contributor

    @lgirdwood
    Yes, this panic bugs seems come back.
    Since we implement IPC message with scheduler I believe this is related to scheduler.

  5. lgirdwood commented on Aug 29, 2018

    @lgirdwood
    lgirdwood
    on Aug 29, 2018
    Member

    @xiulipan I've spotted a possible race we need to resolve in scheduler. We need to add a check to make sure we are not appending a task to the list twice. We should check the schedule list for the task and only re append the task if it's not present. Atm we add the task to the list regardless in _schedule_task().

  6. xiulipan commented on Aug 30, 2018

    @xiulipan
    xiulipan
    on Aug 30, 2018
    Contributor

    @lgirdwood
    Yes, this is what @RanderWang and I have found yesterday. But test with the patch seems have no help to this regression.
    We also find that edf_get_next and reschedule have some problem.

    static inline struct task *edf_get_next(uint64_t current,
	struct task *ignore)
{
...
int reschedule = 0;
...
	} else {
			/* missed scheduling - will be rescheduled */
			trace_pipe_error("ed!");

			/* have we already tried to rescheule ? */
			if (reschedule++) // What is this check for? If reschedule is 0 we should reschedule?
				edf_reschedule(task, current);
			else {
				/* reschedule failed */
				list_item_del(&task->list);
				task->state = TASK_STATE_CANCEL;
			}
		}
	spin_unlock_irq(&sch->lock, flags);
	return next_task;
}

  7. xiulipan commented on Aug 30, 2018

    @xiulipan
    xiulipan
    on Aug 30, 2018
    Contributor

    @lgirdwood

    Use XCC we get some panic that seems we have idle for too long time.

    @@ -283,7 +283,15 @@ static void queue_reschedule(struct work_queue *queue)
 static void queue_run(void *data)
 {
        struct work_queue *queue = (struct work_queue *)data;
+       struct list_item *wlist;
        uint32_t flags;
+
+       trace_error(TRACE_CLASS_WAIT ,"qrr");
+       list_for_item(wlist, &queue->work) {
+               trace_error_value((uint32_t)wlist);
+       }

    0xf10 [83.166189] delta [0.734977] wait qrr // log in queue_run. IRQ happens.
    0xf20 [83.166190] delta [0.000001] value 0x00000000be046898
    0xf30 [83.166192] delta [0.000001] value 0x00000000be046abc
    0xf40 [83.908383] delta [0.742191] wait qrr
    0xf50 [83.908384] delta [0.000001] value 0x00000000be046898
    0xf60 [83.908385] delta [0.000001] value 0x00000000be046abc
    0xf70 [83.908390] delta [0.000005] sa tim //idle timeout?
    0xf80 [83.908391] delta [0.000001] value 0x0000000000d9701e

    I think we may hint this bug because we are not in WFI of the src/tasks/audio.c But in wait_for_completion_timeout(&dd->complete); in dai_comp_trigger.

  8. lgirdwood commented on Aug 30, 2018

    @lgirdwood
    lgirdwood
    on Aug 30, 2018
    Member

    @xiulipan scheduler runs at highest IRQ level, so it cant be preempted by dai_trigger(). It can schedule dai_trigger() to be run, but at a lower IRQ level.

    Can you try the following.

    diff --git a/src/lib/schedule.c b/src/lib/schedule.c
index b98934d2..8eb84c09 100644
--- a/src/lib/schedule.c
+++ b/src/lib/schedule.c
@@ -197,6 +197,7 @@ static struct task *schedule_edf(void)
                /* yes, run current task */
                task->start = current;
                task->state = TASK_STATE_RUNNING;
+               list_item_del(&task->list);
                arch_run_task(task);
        }

    can you also change the scheduler error trace to use trace_error() too.

     Exception Cause: LoadStorePIFDataErrorCause, Synchronous PIF data error during LoadStore access
[   11.511728] sof-audio sof-audio: EXCCAUSE 0x0000000d EXCVADDR 0x00000040 PS       0x00070025

    The NULL pointer deref is always at offset 0x40. What happens if you add some padding uint32_t to the start of the scheduler and workq structures. Does the 0x40 change ?

    Finally is the EPC5 program counter value consistent in the same function ?

  9. xiulipan commented on Aug 30, 2018

    @xiulipan
    xiulipan
    on Aug 30, 2018
    Contributor

    @lgirdwood
    I will try.
    Now I found that there are also some error in queue work. That will hold the DMA-trace and I am debug into it.

  10. lgirdwood commented on Aug 30, 2018

    @lgirdwood
    lgirdwood
    on Aug 30, 2018
    Member

    @xiulipan agreed, workq may have the error instead or alongside the scheduler.

  11. 40 remaining items

  12. xiulipan commented on Sep 6, 2018

    @xiulipan
    xiulipan
    on Sep 6, 2018
    Contributor

    @lgirdwood
    Test with removing the wait_for_interrupt the panic is gone.
    May have some noise issue with pipeline xrun recovery.

  13. xiulipan
    closed this as completedon Sep 6, 2018
  14. xiulipan
    reopened this on Sep 6, 2018

  15. xiulipan commented on Sep 6, 2018

    @xiulipan
    xiulipan
    on Sep 6, 2018
    Contributor

    @lgirdwood

    • To fix waiti bugs. we need

    #284 #314

    • For list item,
    1. we may need some unification about how to refine the list_item_del. We may need to init every item at each del. list: added list_item_del_init #303 or list: refine list_item_del to avoid make list corruption #300
    2. fix some potential bugs in scheduler  #313 for some potential bugs.

    With all these patches now the #272 and #210 should all be fixed.
    But now have some xrun inside firmware.
    And pipeline xrun recovery will have some noise.
    @ZhendanYang @keqiaozhang
    Please report new bugs about noise after all patches are merged and test.

    0x1de0 [519.288077] delta [7.678624] dai xro
    0x1df0 [519.289141] delta [0.001064] dai xro
    0x1e00 [519.289158] delta [0.000017] pipe pxr
    0x1e10 [526.598085] delta [7.308927] dai xro
    0x1e20 [526.599149] delta [0.001064] dai xro
    0x1e30 [526.599166] delta [0.000017] pipe pxr
    0x1e40 [550.429521] delta [23.830355] dai xro
    0x1e50 [550.430585] delta [0.001064] dai xro
    0x1e60 [550.430601] delta [0.000017] pipe pxr
    0x1e70 [551.177593] delta [0.746991] dai xro
    0x1e80 [551.178657] delta [0.001064] dai xro
    0x1e90 [551.178674] delta [0.000017] pipe pxr

  16. lgirdwood commented on Sep 6, 2018

    @lgirdwood
    lgirdwood
    on Sep 6, 2018
    Member

    @cujomalainey patches above now being merged, should be fully validated next week.

  17. ZhendanYang commented on Sep 10, 2018

    @ZhendanYang
    ZhendanYang
    on Sep 10, 2018
    Author

    This issue can't be reproduced on APL and CNL with stable-1.2 branch(commit 251e68f)

    on APL and CNL with master branch(commit: 7abb55f): no more DSP panic, instead of ipc timeout:

    [ 1895.936287] sof-audio sof-audio: error: ipc timed out for 0x60040000 size 0xc
    [ 1895.936312] sof-audio sof-audio: status: fw entered - code 00000005
    [ 1895.936430] sof-audio sof-audio: error: unexpected fault 0x00000000 trace 0x00004000
    [ 1895.936436] sof-audio sof-audio: error: waking up any trace sleepers
    [ 1895.936460] Passthrough: ASoC: trigger FE failed -110
    [ 1895.936472] sof-audio sof-audio: pcm: trigger stream 0 dir 0 cmd 0
    [ 1896.256303] sof-audio sof-audio: error: ipc timed out for 0x60050000 size 0xc
    [ 1896.256321] sof-audio sof-audio: status: fw entered - code 00000005
    [ 1896.256463] sof-audio sof-audio: error: unexpected fault 0x00000000 trace 0x00004000
    [ 1896.256468] sof-audio sof-audio: error: waking up any trace sleepers
    [ 1896.256487] Passthrough: ASoC: trigger FE failed -110
    [ 1896.604457] sof-audio sof-audio: ipc rx: 0x90020000
    [ 1896.604551] sof-audio sof-audio: ipc rx done: 0x90020000
    [ 1897.604542] sof-audio sof-audio: ipc rx: 0x90020000
    [ 1897.604638] sof-audio sof-audio: ipc rx done: 0x90020000
    [ 1898.272253] sof-audio sof-audio: pcm: free stream 0 dir 0
    [ 1898.592284] sof-audio sof-audio: error: ipc timed out for 0x60030000 size 0xc
    [ 1898.592307] sof-audio sof-audio: status: fw entered - code 00000005
    [ 1898.592424] sof-audio sof-audio: error: unexpected fault 0x00000000 trace 0x00004000
    [ 1898.592429] sof-audio sof-audio: error: waking up any trace sleepers

    Test on BYT is blocked by #274 .
    Test on glk-003 branch is blocked by #263 .

  18. mengdonglin
    removed
    CNLApplies to Cannonlake platform
    br-master
    on Sep 10, 2018

  19. mengdonglin commented on Sep 10, 2018

    @mengdonglin
    mengdonglin
    on Sep 10, 2018
    Collaborator

    CNL has no DSP panic now. Will create new bug track IPC timeout.

  20. lgirdwood commented on Sep 10, 2018

    @lgirdwood
    lgirdwood
    on Sep 10, 2018
    Member

    CNL has different IPC IP compared to APL so could also be driver bug.

  21. xiulipan
    removed
    br-1.2
    on Sep 11, 2018
  22. xiulipan
    removed this from the 1.2 milestone on Sep 11, 2018
  23. ZhendanYang
    removed
    BYTApplies to Baytrail platform
    on Sep 17, 2018

  24. mengdonglin commented on Sep 17, 2018

    @mengdonglin
    mengdonglin
    on Sep 17, 2018
    Collaborator

    Close this issue because all generic fixes on glk-003 branch have been merged by master. So testing with master branch will be okay for mature platforms. glk release branch does not focus on compatibility across platforms.

    @ZhendanYang Please re-open this issue if it can be reproduce by master branch and use br-master to track it. Thanks!

  25. mengdonglin
    closed this as completedon Sep 17, 2018
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Metadata

Metadata

Assignees

Labels

APLApplies to Apollolake platformP2Critical bugs or normal featuresbugSomething isn't working as expectedduplicateThis issue or pull request already exists

Type

No type

Projects

No projects

    Milestone

    No milestone

    Relationships

    None yet

    Development

    No branches or pull requests

    Issue actions