[Stress test]: fail to boot firmware after unloading and reloading SOF modules 55 times on BYT-nocodec #676

Activity

1. Jiangxinx

   added

   bugSomething isn't workingSomething isn't working

   BYTApplies to Baytrail platformApplies to Baytrail platform

   on Feb 26, 2019
2. juimonen commented on Feb 26, 2019

   

   juimonen

   on Feb 26, 2019

   More actions

   As I read the logs (and tested with my own minnow) we lose 1 component connect ipc message for timeout. At least for me the dsp or kernel doesn't crash, for some reason the message is not ever read in dsp (or by dsp) and kernel times out, but boot continues normally.
3. juimonen commented on Feb 26, 2019

   

   juimonen

   on Feb 26, 2019

   More actions

   So for some reason the transfer is jammed, I get the jam in different place than the attached log, but anyway mechanism seems to be the same. You see in the logger huge delta in the timestamps when nothing is happening in the DSP -> we get timeout in driver side -> after erro processing we can again send and dsp is responding.
4. juimonen commented on Feb 26, 2019

   

   juimonen

   on Feb 26, 2019

   More actions

   @plbossart @ranj063 any idea about this thing in byt? I saw you had some recent commits to ipc/doorbell.
5. plbossart commented on Feb 26, 2019

   

   plbossart

   on Feb 26, 2019

   Member

   More actions

   @juimonen it's been an issue with BYT since I came back at the end of October, and no one seems to care but you and me... I have never been able to get the same reliability as Up2 for the module load/unload test, and even for regular playback I routinely get these IPC timeouts.
6. wenqingfu

   assigned

   juimonen

   on Feb 26, 2019
7. wenqingfu commented on Feb 26, 2019

   

   wenqingfu

   on Feb 26, 2019

   More actions

   no one seems to care but you and me...

   not entirely true. @juimonen and @wenqingfu knew what happened. let's actively work on Minnow Board platform related bug from now on, and don't let Up2 fall like it. There are even some double-digit number issues still standing while our latest issue/PR number is close to 700 at the moment. cannot live with this anymore.

   I bet $5 it's a driver code bug in IPC.
8. juimonen commented on Feb 28, 2019

   

   juimonen

   on Feb 28, 2019

   More actions

   so always when the timeout happens, dsp is sending some message to host before acking the message host had just sent. So the flow is 1) host->sends (wait for dsp ack) 2) dsp receives and processes 3) dsp sends different message than ack to host (like trace or stream position). 4) host never receives interrupt for the message it sent.
   So somehow the dsp sending message to host when host is waiting for ack loses the interrupt.
9. plbossart commented on Feb 28, 2019

   

   plbossart

   on Feb 28, 2019

   Member

   More actions

   Thanks @juimonen. This could be a case of a deadlock, with both sides waiting for an ack. Wondering if this is tied to the lock protection of the IPC bits that seems a bit flaky.
10. xiulipan commented on Mar 1, 2019

    

    xiulipan

    on Mar 1, 2019

    More actions

    @juimonen @plbossart

    So the flow is 1) host->sends (wait for dsp ack) 2) dsp receives and processes 3) dsp sends different message than ack to host (like trace or stream position). 4) host never receives interrupt for the message it sent.

    This sound like similar to me for some IPC timeout issues on APL that have been fixed. Maybe the BYT part have some different IPC regs.

    @juimonen For APL bug, we can try to increase the reproduce rate by enable TRACEV.

    @RanderWang @keyonjie What do you think?
11. juimonen commented on Mar 1, 2019

    

    juimonen

    on Mar 1, 2019

    More actions

    Don't know if this helps, but here's the trace from fw and host side (my comments included). I don't
    know if the trace messages are in exact execution order. It seems that this a case of simultaneous send from both sides...

    FW:

    WFX
    schedule()
    WFE
    dw-dma: 0 channel work
    dw-dma: 0 channel 0 block end
    WFX
    ipc: msg tx -> 0x90020000 /* we send a trace message to host /
    schedule()
    WFE
    ipc: irq isr 0x2 / we receive the core enable message /
    _schedule_task()
    schedule()
    scheduler_run()
    schedule_edf()
    schedule_task_running()
    ipc: pm core mask 0x1 -> enable
    schedule_task_complete() / this should trigger interrupt in host, but it is not happening /
    WFX
    schedule()
    WFE
    ipc: irq isr 0x1 / we receive ack from host to trace msg send in the beginning */
    ipc: not rx -> 0x90020000
    WFX
    schedule()

    DRIVER:

    ipc tx: 0x40070000: GLB_PM_MSG: CORE_ENABLE /* send message to dsp and start wait for ack /
    ipc rx: 0x90020000: GLB_TRACE_MSG / we receive a lot of trace messages /
    ipc rx done: 0x90020000: GLB_TRACE_MSG
    ipc rx: 0x90020000: GLB_TRACE_MSG
    ipc rx done: 0x90020000: GLB_TRACE_MSG
    ipc rx: 0x90020000: GLB_TRACE_MSG
    ipc rx done: 0x90020000: GLB_TRACE_MSG
    ipc rx: 0x90020000: GLB_TRACE_MSG
    ipc rx done: 0x90020000: GLB_TRACE_MSG
    ipc rx: 0x90020000: GLB_TRACE_MSG
    ipc rx done: 0x90020000: GLB_TRACE_MSG
    ipc rx: 0x90020000: GLB_TRACE_MSG
    ipc rx done: 0x90020000: GLB_TRACE_MSG
    ipc rx: 0x90020000: GLB_TRACE_MSG
    ipc rx done: 0x90020000: GLB_TRACE_MSG
    ipc rx: 0x90020000: GLB_TRACE_MSG
    ipc rx done: 0x90020000: GLB_TRACE_MSG
    ipc rx: 0x90020000: GLB_TRACE_MSG
    ipc rx done: 0x90020000: GLB_TRACE_MSG
    ipc rx: 0x90020000: GLB_TRACE_MSG
    ipc rx done: 0x90020000: GLB_TRACE_MSG
    error: ipc timed out for 0x40070000 size 0xc / never get the ack to tx, so we timeout and error */
    error: unexpected fault 0x90020000 trace 0x40070000
    error: waking up any trace sleepers
    error: core enable ipc failure
    error: DSP failed to add widget id 0 type 32 name : PIPELINE.2.SSP2.IN stream SSP2.IN reply 0
    ASoC: failed to load widget PIPELINE.2.SSP2.IN
    error: tplg component load failed -110
12. RanderWang commented on Mar 4, 2019

    

    RanderWang

    on Mar 4, 2019

    More actions

    @juimonen @plbossart

    So the flow is 1) host->sends (wait for dsp ack) 2) dsp receives and processes 3) dsp sends different message than ack to host (like trace or stream position). 4) host never receives interrupt for the message it sent.

    This sound like similar to me for some IPC timeout issues on APL that have been fixed. Maybe the BYT part have some different IPC regs.

    @juimonen For APL bug, we can try to increase the reproduce rate by enable TRACEV.

    @RanderWang @keyonjie What do you think?

    which bug and the root reason ?
13. Jiangxinx commented on Mar 4, 2019

    

    Jiangxinx

    on Mar 4, 2019

    Last edited by Jiangxinx

    Author

    More actions

    Passed on the daily test.

    Test steps:

    1.sudo ./sof_bootloop.sh 100

    Env:
    sof master: 24e241b
    kernel sof-dev: cf5978a
    tplg: sof-byt-nocodec.tplg
14. juimonen commented on Mar 7, 2019

    

    juimonen

    on Mar 7, 2019

    More actions

    @wenqingfu I've been trying to debug this many days with not too much luck. @keyonjie spotted a issue of not properly masking and overwriting some send registers, but that didn't help. At this point I would really wait for @lyakh #695 and test with that one.

    The problem is very reproducible and relates to simultaneous send from fw and driver. It is either a deadlock or wrong interrupt clearance.
15. lyakh commented on Mar 7, 2019

    

    lyakh

    on Mar 7, 2019

    Collaborator

    More actions

    ipc: msg tx -> 0x90020000 /* we send a trace message to host /

    isn't this a recursive endless IPC flood? In the IPC-sending routine we print a trace, which is sent via IPC, which prints a trace, which is sent via IPC?...
16. juimonen commented on Mar 7, 2019

    

    juimonen

    on Mar 7, 2019

    More actions

    @lyakh not totally sure why this has many messages , but I've been able to reproduce this many times with just 1 msg to both directions. I think the byt/minnow is much slower than other platforms, so it is very visible here. I think I got it much rarer when I reduce the logging...
17. lyakh commented on Mar 7, 2019

    

    lyakh

    on Mar 7, 2019

    Collaborator

    More actions

    I think it is rather important to find out whether we really have recursive tracing here. @lgirdwood is there anything that prevents such recursion?
18. juimonen commented on Mar 11, 2019

    

    juimonen

    on Mar 11, 2019

    More actions

    #695 seems to fix this. I've run the bootloop script already twice without errors...
19. plbossart commented on Mar 11, 2019

    

    plbossart

    on Mar 11, 2019

    Member

    More actions

    #695 seems to fix this. I've run the bootloop script already twice without errors...

    that's impressive, i've never been able to run that script to completion, IPC errors always happened after 50-80 cycles of unload/reload.

    What we need to check now is it #695 doesn't impact concurrency. It may solve serialization or missed messages, but we want to make sure there isn't a regression when we try multiple streams precisely because of a strong serialization.
20. lyakh commented on Mar 11, 2019

    

    lyakh

    on Mar 11, 2019

    Collaborator

    More actions

    @plbossart FWIW I ran parallel capture and playback with that series on UP² with nocodec, but by all means it should be tested further, also on real hardware.
21. plbossart commented on Mar 15, 2019

    

    plbossart

    on Mar 15, 2019

    Member

    More actions

    @Jiangxinx is this bug still current or can it be closed?
22. Jiangxinx commented on Mar 18, 2019

    

    Jiangxinx

    on Mar 18, 2019

    Author

    More actions

    Passed on daily test.
23. Jiangxinx

    closed this as completedon Mar 18, 2019