Skip to content

[BUG][SDW][CML]"SDW_SCP_INTMASK1 write failed:-61" occurred in multi-pipelines stress test. #1637

Closed

Description

@sinahuang

Describe the bug
With “options snd-sof-intel-hda-common sdw_clock_stop_quirks=0x8”, "SDW_SCP_INTMASK1 write failed:-61" occurred when run multipipeline stress test. Test for 500 times issue occured at 190th/191th time.

Note: Function cannot be effected when issue occurred.

To Reproduce
1.Boot up system.
2.Run "./multiplex_pipeline-test.sh pcm0p pcm2p pcm3p pcm5p pcm7p pcm1c pcm4c".

Reproduce rate
2/500

Expected result
No failed occured during multipipeline stress test.

Actual result
"SDW_SCP_INTMASK1 write failed:-61" occurred when run multipipeline stress test.

Dmesg:

[ 2342.226142] intel-sdw sdw-master-2: sdw_handle_slave_status: start
[ 2342.226143] rt1308 sdw:2:25d:1308:0: sdw_modify_slave_status: changing status slave 1 status 0 new status 1
[ 2342.226144] rt1308 sdw:2:25d:1308:0: sdw_modify_slave_status: signaling completion for Slave 1
[ 2342.226180] intel-sdw sdw-master-2: Msg ignored for Slave 1
[ 2342.226185] intel-sdw sdw-master-2: SDW_SCP_INTMASK1 write failed:-61
[ 2342.226186] intel-sdw sdw-master-2: Slave 1 initialization failed: -61
[ 2342.226187] intel-sdw sdw-master-2: Updating Slave 1 status
[ 2342.226189] intel-sdw sdw-master-2: sdw_handle_slave_status: Updating Slave 1 status done
[ 2342.226194] intel-sdw sdw-master-2: intel_startup: SDW2 Pin2: start
[ 2342.226198] intel-sdw sdw-master-2: intel_startup: SDW2 Pin2: done
[ 2342.226200]  SDW2-speakers: ASoC: open FE SDW2-speakers
[ 2342.226202] sof-audio-pci 0000:00:1f.3: pcm: open stream 3 dir 0
[ 2342.226204] sof-audio-pci 0000:00:1f.3: period min 192 max 16384 bytes
[ 2342.226205] sof-audio-pci 0000:00:1f.3: period count 2 max 16
[ 2342.226206] sof-audio-pci 0000:00:1f.3: buffer max 65536 bytes
[ 2342.226212] intel-sdw sdw-master-2: sdw_handle_slave_status: end
[ 2342.226218]  HDMI1: ASoC: found 0 audio playback paths

sof_error_trace:

 CORE  LEVEL      COMP_ID                TIMESTAMP            DELTA                FILE_NAME	CONTENT
    0      1           SA         2927763558.020833              nan      src/lib/agent.c:55  	validate(), ll drift detected, delta = 26086
    0      1           SA         2927878643.854167    115085.835938      src/lib/agent.c:55  	validate(), ll drift detected, delta = 26017
    0      1           SA         2927976236.770833     97592.914062      src/lib/agent.c:55  	validate(), ll drift detected, delta = 26067
    0      1           SA         2927978838.854167      2602.083252      src/lib/agent.c:55  	validate(), ll drift detected, delta = 25930
    0      1           SA         2927981421.875000      2583.020752      src/lib/agent.c:55  	validate(), ll drift detected, delta = 25779
    0      1           SA         2927982738.020833      1316.145874      src/lib/agent.c:55  	validate(), ll drift detected, delta = 25268
    0      1           SA         2928086575.312500    103837.289062      src/lib/agent.c:55  	validate(), ll drift detected, delta = 25759

scripts:
multiplex_pipeline-test.txt

Test recipe

Kernel:https://github.com/thesofproject/linux/tree/integration/soundwire-latest commit: e6392c0
FW: https://github.com/thesofproject/sof/commits/cml-010-drop-stable commit: 5e5f69e
Tplg: Same with FW branch, sof-cml-rt711-rt1308-rt715.tplg
Platform:CML-H Laptop with codec ALC711, 2 x RT1308, RT715 in SDW mode.

190th log.zip

Activity

  1. added
    bugSomething isn't working
    CMLApplies to Comet Lake platform
    SDWApplies to SoundWire bus for codec connection
    on Dec 18, 2019
  2. sinahuang commented on Dec 18, 2019

    @sinahuang
    Author

    This issue maybe related to #1597

  3. plbossart commented on Dec 19, 2019

    @plbossart
    Member

    @RanderWang @bardliao can you take a look at the log, I find some very odd things

    [ 2338.139435] intel-sdw sdw-master-2: intel_suspend_runtime start
    [ 2338.139444] intel-sdw sdw-master-2: sdw_cdns_clock_stop: start
    [ 2338.139452] intel-sdw sdw-master-2: sdw_cdns_clock_stop: slave attached 1
    
    [ 2338.139799] intel-sdw sdw-master-2: sdw_cdns_clock_stop: end
    [ 2338.139816] intel-sdw sdw-master-2: intel_suspend_runtime done
    
    <<< and here we get a set of interrupts?
    
    [ 2338.139947] intel-sdw sdw-master-2: Parity error
    [ 2338.139957] intel-sdw sdw-master-2: Bus clash for control word
    [ 2338.139961] intel-sdw sdw-master-2: Bus clash for data word
    [ 2338.139993] intel-sdw sdw-master-2: Slave status change
    [ 2338.140011] intel-sdw sdw-master-2: Slave 0 ATTACHED
    [ 2338.140025] intel-sdw sdw-master-2: Slave 0 ALERT
    [ 2338.140028] intel-sdw sdw-master-2: Slave 0 UNATTACHED
    [ 2338.140031] intel-sdw sdw-master-2: Slave 0 reported multiple Status: 15
    [ 2338.140047] intel-sdw sdw-master-2: Slave 0 status updated to 3
    [ 2338.140049] intel-sdw sdw-master-2: Slave 1 ATTACHED
    

    and when we restart the clock we have issues

    [ 2342.225667] intel-sdw sdw-master-2: Slave status change
    [ 2342.225672] intel-sdw sdw-master-2: Slave 0 ATTACHED
    [ 2342.225673] intel-sdw sdw-master-2: sdw_handle_slave_status: start
    [ 2342.225674] intel-sdw sdw-master-2: Slave attached, programming device number
    [ 2342.225676] intel-sdw sdw-master-2: SDW Slave Addr: ffffffffffff
    [ 2342.225677] intel-sdw sdw-master-2: SDW Slave class_id ff, part_id ffff, mfg_id ffff, unique_id f, version f
    [ 2342.225678] intel-sdw sdw-master-2: Slave Entry not found
    

    This looks like a case where the clock is not properly stopped?

  4. added
    SDW_DEVSDW bug reproduced by developers, fix WIP
    on Dec 19, 2019
  5. bardliao commented on Dec 19, 2019

    @bardliao
    Collaborator

    @plbossart My theory is somehow cdns.link_up is still true when the link is powered down. Every register will read as 0xffffffff when the link is powered down. When any interrupt is triggered, we will check each link's irq status and we will get a lot of superfluous irq since we actually read registers when the link is off. I believe that the issue will be solved by

    diff --git a/drivers/soundwire/cadence_master.c b/drivers/soundwire/cadence_master.c
    index cf96532b0a8e..6ac426444fa5 100644
    --- a/drivers/soundwire/cadence_master.c
    +++ b/drivers/soundwire/cadence_master.c
    @@ -752,6 +752,9 @@ irqreturn_t sdw_cdns_irq(int irq, void *dev_id)
    
            int_status = cdns_readl(cdns, CDNS_MCP_INTSTAT);
    
    +       if (int_status == 0xffffffff)
    +               return IRQ_NONE;
    +
            if (!(int_status & CDNS_MCP_INT_IRQ))
                    return IRQ_NONE;
    

    But what I am not clear is that how can cdns.link_up be true when intel_link_power_down() is called and return 0?

  6. plbossart commented on Dec 19, 2019

    @plbossart
    Member

    @bardliao I wonder if the sequences are correct. Somehow we should probably enable the interrupts last, after the bus reset. And conversely when suspending we should disable the interrupts first.

    diff --git a/drivers/soundwire/intel.c b/drivers/soundwire/intel.c
    index 2c505a30df06..1310ba8c9425 100644
    --- a/drivers/soundwire/intel.c
    +++ b/drivers/soundwire/intel.c
    @@ -1589,18 +1589,19 @@ static int intel_suspend_runtime(struct device *dev)
                    intel_shim_wake(sdw, false);
            } else if (clock_stop_quirks & SDW_INTEL_CLK_STOP_BUS_RESET ||
                    !clock_stop_quirks) {
    +
    +               ret = sdw_cdns_enable_interrupt(cdns, false);
    +               if (ret < 0) {
    +                       dev_err(dev, "cannot disable interrupts on suspend\n");
    +                       return ret;
    +               }
    +
                    ret = sdw_cdns_clock_stop(cdns, true);
                    if (ret < 0) {
                            dev_err(dev, "cannot enable clock stop on suspend\n");
                            return ret;
                    }
     
    -               ret = sdw_cdns_enable_interrupt(cdns, false);
    -               if (ret < 0) {
    -                       dev_err(dev, "cannot disable interrupts on suspend\n");
    -                       return ret;
    -               }
    -
                    ret = intel_link_power_down(sdw);
                    if (ret) {
                            dev_err(dev, "Link power down failed: %d", ret);
    @@ -1666,18 +1667,18 @@ static int intel_resume(struct device *dev)
            sdw_clear_slave_status(&sdw->cdns.bus,
                                   SDW_UNATTACH_REQUEST_MASTER_RESET);
     
    -       ret = sdw_cdns_enable_interrupt(cdns, true);
    -       if (ret < 0) {
    -               dev_err(dev, "cannot enable interrupts during resume\n");
    -               return ret;
    -       }
    -
            ret = sdw_cdns_exit_reset(cdns);
            if (ret < 0) {
                    dev_err(dev, "unable to exit bus reset sequence during resume\n");
                    return ret;
            }
     
    +       ret = sdw_cdns_enable_interrupt(cdns, true);
    +       if (ret < 0) {
    +               dev_err(dev, "cannot enable interrupts during resume\n");
    +               return ret;
    +       }
    +
            /*
             * after system resume, the pm_runtime suspend() may kick in
             * during the enumeration, before any children device force the
    @@ -1728,17 +1729,18 @@ static int intel_resume_runtime(struct device *dev)
                    sdw_clear_slave_status(&sdw->cdns.bus,
                                           SDW_UNATTACH_REQUEST_MASTER_RESET);
     
    -               ret = sdw_cdns_enable_interrupt(cdns, true);
    -               if (ret < 0) {
    -                       dev_err(dev, "cannot enable interrupts during resume\n");
    -                       return ret;
    -               }
    -
                    ret = sdw_cdns_exit_reset(cdns);
                    if (ret < 0) {
                            dev_err(dev, "unable to exit bus reset sequence during resume\n");
                            return ret;
                    }
    +
    +               ret = sdw_cdns_enable_interrupt(cdns, true);
    +               if (ret < 0) {
    +                       dev_err(dev, "cannot enable interrupts during resume\n");
    +                       return ret;
    +               }
    +
            } else if (clock_stop_quirks & SDW_INTEL_CLK_STOP_BUS_RESET) {
                    ret = intel_init(sdw);
                    if (ret) {
    @@ -1764,17 +1766,18 @@ static int intel_resume_runtime(struct device *dev)
                            sdw_clear_slave_status(&sdw->cdns.bus, status);
                    }
     
    -               ret = sdw_cdns_enable_interrupt(cdns, true);
    -               if (ret < 0) {
    -                       dev_err(dev, "cannot enable interrupts during resume\n");
    -                       return ret;
    -               }
    -
                    ret = sdw_cdns_clock_restart(cdns, !clock_stop0);
                    if (ret < 0) {
                            dev_err(dev, "unable to restart clock during resume\n");
                            return ret;
                    }
    +
    +               ret = sdw_cdns_enable_interrupt(cdns, true);
    +               if (ret < 0) {
    +                       dev_err(dev, "cannot enable interrupts during resume\n");
    +                       return ret;
    +               }
    +
            } else if (!clock_stop_quirks) {
                    ret = intel_init(sdw);
                    if (ret) {
    @@ -1782,17 +1785,17 @@ static int intel_resume_runtime(struct device *dev)
                            return ret;
                    }
     
    -               ret = sdw_cdns_enable_interrupt(cdns, true);
    -               if (ret < 0) {
    -                       dev_err(dev, "cannot enable interrupts during resume\n");
    -                       return ret;
    -               }
    -
                    ret = sdw_cdns_clock_restart(cdns, false);
                    if (ret < 0) {
                            dev_err(dev, "unable to resume master during resume\n");
                            return ret;
                    }
    +
    +               ret = sdw_cdns_enable_interrupt(cdns, true);
    +               if (ret < 0) {
    +                       dev_err(dev, "cannot enable interrupts during resume\n");
    +                       return ret;
    +               }
            } else {
                    dev_err(dev, "%s clock_stop_quirks %x unsupported\n",
                            __func__, clock_stop_quirks);

    The other mystery in in mode 0x0, why do we power down the link?

    lse if (clock_stop_quirks & SDW_INTEL_CLK_STOP_BUS_RESET ||
    		!clock_stop_quirks) {
    
    		ret = sdw_cdns_enable_interrupt(cdns, false);
    		if (ret < 0) {
    			dev_err(dev, "cannot disable interrupts on suspend\n");
    			return ret;
    		}
    
    		ret = sdw_cdns_clock_stop(cdns, true);
    		if (ret < 0) {
    			dev_err(dev, "cannot enable clock stop on suspend\n");
    			return ret;
    		}
    
    		ret = intel_link_power_down(sdw);
    		if (ret) {
    			dev_err(dev, "Link power down failed: %d", ret);
    			return ret;
    		}
    
    		intel_shim_wake(sdw, true);

    this is fine when we do the complete re-enumeration but I am not sure it's needed or even legit when the DSP remains powered.

  7. plbossart commented on Dec 19, 2019

    @plbossart
    Member
  8. plbossart commented on Dec 19, 2019

    @plbossart
    Member

    @bardliao @RanderWang we could also harden the interrupts.

    a) when we restart the clock, we could read MCP_SlaveIntStat0/MCP_SlaveIntStat1 and write1 to clear the bits. That would make sure we start from a clean state, and not from whatever was in the status before the clock was stopped (if the status is preserved)

    b) the MCP_INSTAT register has reserved values in bits 30:17, so if we detect a one in any of these bits it's a bad interrupt

    c) we should also track MCP_INTSTAT.WakeUp, which tells us when the master left the clock stop mode. That would be really useful since it should come before Slaves can even signal their own status change.

  9. plbossart commented on Dec 19, 2019

    @plbossart
    Member

    @bardliao @sinahuang @RanderWang can you try this #1640

    Completely untested on my side, just ideas to try and make progress

  10. bardliao commented on Dec 19, 2019

    @bardliao
    Collaborator

    @bardliao I wonder if the sequences are correct. Somehow we should probably enable the interrupts last, after the bus reset. And conversely when suspending we should disable the interrupts first.

    @plbossart Sorry, but I think we can't invert the sequence between enable interrupt and clock stop. sdw_slave_clk_stop_callback() will be triggered on the clock stop process, and interrupt is needed for transmission.

  11. YvonneYang2 commented on Dec 19, 2019

    @YvonneYang2

    Issue can be reproduced on CML-U sdw laptop with latest soundwire-latest(121c751) during suspend/resume with aplay0,6 stress test. Run 300 times, failed at 150th time.

    s3_test_150_logger_all.log
    test_150.log

  12. sinahuang commented on Dec 19, 2019

    @sinahuang
    Author

    Verified this issue with soundwire-latest(commit: 121c751 +PR #1640) on CML-H, "IO transfer timed out" occured, failed at 1st time.

    dmesg
    [   15.014013] rt711 sdw:0:25d:711:0: rt711_dev_suspend start
    [   15.014018] rt711 sdw:0:25d:711:0: rt711_dev_suspend end
    [   15.014025] intel-sdw sdw-master-0: intel_suspend_runtime start
    [   15.014033] intel-sdw sdw-master-0: sdw_cdns_clock_stop: start
    [   15.014039] intel-sdw sdw-master-0: sdw_cdns_clock_stop: slave attached 1
    [   15.131896] intel-sdw sdw-master-2: intel_suspend_runtime start
    [   15.131905] intel-sdw sdw-master-2: sdw_cdns_clock_stop: start
    [   15.131913] intel-sdw sdw-master-2: sdw_cdns_clock_stop: slave attached 1
    [   16.475695]  SDW2-speakers: ASoC: pop wq checking: Playback status: inactive waiting: yes
    [   16.475853]  SDW1-speakers: ASoC: pop wq checking: Playback status: inactive waiting: yes
    [   16.667984] intel-sdw sdw-master-3: IO transfer timed out, cmd 3 device 1 addr 45 len 1
    [   16.668001] intel-sdw sdw-master-1: IO transfer timed out, cmd 3 device 1 addr 45 len 1
    [   16.987986]  HDMI3: ASoC: pop wq checking: Playback status: inactive waiting: yes
    [   16.988034]  HDMI2: ASoC: pop wq checking: Playback status: inactive waiting: yes
    [   16.988072]  HDMI1: ASoC: pop wq checking: Playback status: inactive waiting: yes
    [   16.988106]  Headphone: ASoC: pop wq checking: Playback status: inactive waiting: yes
    [   17.051756] intel-sdw sdw-master-0: IO transfer timed out, cmd 3 device 1 addr 45 len 1
    [   17.179839] intel-sdw sdw-master-2: IO transfer timed out, cmd 3 device 1 addr 45 len 1
    [   18.715886] intel-sdw sdw-master-1: IO transfer timed out, cmd 3 device 15 addr 44 len 1
    [   18.716063] intel-sdw sdw-master-1: sdw_cdns_clock_stop: end
    [   18.716074] intel-sdw sdw-master-1: intel_suspend_runtime done
    [   18.716088] intel-sdw sdw-master-3: IO transfer timed out, cmd 3 device 15 addr 44 len 1
    [   18.716097] intel-sdw sdw-master-3: sdw_cdns_clock_stop: end
    [   18.716107] intel-sdw sdw-master-3: intel_suspend_runtime done
    [   19.099936] intel-sdw sdw-master-0: IO transfer timed out, cmd 3 device 15 addr 44 len 1
    [   19.099952] intel-sdw sdw-master-0: sdw_cdns_clock_stop: end
    [   19.099964] intel-sdw sdw-master-0: intel_suspend_runtime done
    [   19.227977] intel-sdw sdw-master-2: IO transfer timed out, cmd 3 device 15 addr 44 len 1
    [   19.227995] intel-sdw sdw-master-2: sdw_cdns_clock_stop: end
    [   19.228007] intel-sdw sdw-master-2: intel_suspend_runtime done
    [   19.228021] sof-audio-pci 0000:00:1f.3: snd_sof_runtime_idle
    [   19.228027] sof-audio-pci 0000:00:1f.3: snd_sof_runtime_suspend
    [   19.228030] sof-audio-pci 0000:00:1f.3: sof_suspend
    [   19.228626] sof-audio-pci 0000:00:1f.3: FW Poll Status: reg=0x20140000 successful
    [   19.273858] sof-audio-pci 0000:00:1f.3: sof_send_pm_ctx_ipc
    [   19.273862] sof-audio-pci 0000:00:1f.3: ipc tx: 0x40010000: GLB_PM_MSG: CTX_SAVE
    [   19.274157] sof-audio-pci 0000:00:1f.3: ipc tx succeeded: 0x40010000: GLB_PM_MSG: CTX_SAVE
    [   19.274268] sof-audio-pci 0000:00:1f.3: FW Poll Status: reg=0x1010f0f successful
    [   19.274273] sof-audio-pci 0000:00:1f.3: FW Poll Status: reg=0xf0f successful
    [   19.274276] sof-audio-pci 0000:00:1f.3: DSP core(s) enabled? 0 : core_mask f
    [   19.274326] sof-audio-pci 0000:00:1f.3: Debug PCIR: 00000000 at  00000044
    [   19.274330] sof-audio-pci 0000:00:1f.3: Debug PCIW: 00000010 at  00000044
    [   24.119934] ax88179_178a 6-2.4.1:1.0 enx000ec6c39730: ax88179 - Link status is: 1
    [   24.127834] IPv6: ADDRCONF(NETDEV_CHANGE): enx000ec6c39730: link becomes ready
    [   26.954221]  HDMI1: ASoC: found 0 audio playback paths
    [   26.954222]  HDMI1: ASoC: HDMI1 no valid playback route
    [   26.954223] sdw_rt711_rt1308_rt715 sdw_rt711_rt1308_rt715: ASoC: find BE for widget HDA0.OUT
    [   26.954224] sdw_rt711_rt1308_rt715 sdw_rt711_rt1308_rt715: ASoC: try BE : ALH2.OUT
    [   26.954225] sdw_rt711_rt1308_rt715 sdw_rt711_rt1308_rt715: ASoC: try BE : (not set)
    [   26.954225] sdw_rt711_rt1308_rt715 sdw_rt711_rt1308_rt715: ASoC: try BE : ALH0x102.OUT
    [   26.954226] sdw_rt711_rt1308_rt715 sdw_rt711_rt1308_rt715: ASoC: try BE : (not set)
    [   26.954226] sdw_rt711_rt1308_rt715 sdw_rt711_rt1308_rt715: ASoC: try BE : HDA0.OUT
    [   26.954227]  HDMI1: connected new DPCM playback path HDMI1 -> iDisp1
    [   26.954232]  HDMI1: ASoC: found 1 new BE paths
    [   26.954233]  iDisp1: ASoC: open playback BE iDisp1
    [   26.965983] sof-audio-pci 0000:00:1f.3: snd_sof_runtime_resume
    [   26.965986] sof-audio-pci 0000:00:1f.3: sof_resume
    [   26.966002] sof-audio-pci 0000:00:1f.3: Debug PCIR: 00000000 at  00000044
    [   26.966006] sof-audio-pci 0000:00:1f.3: Debug PCIR: 00000040 at  00000048
    [   26.966010] sof-audio-pci 0000:00:1f.3: Debug PCIW: 00000000 at  00000048
    [   26.968950] sof-audio-pci 0000:00:1f.3: Debug PCIR: 00000000 at  00000048
    [   26.968953] sof-audio-pci 0000:00:1f.3: Debug PCIW: 00000040 at  00000048
    [   26.968981] sof-audio-pci 0000:00:1f.3: loading firmware
    [   26.968984] sof-audio-pci 0000:00:1f.3: Debug PCIR: 00000002 at  00000048
    [   26.968987] sof-audio-pci 0000:00:1f.3: Debug PCIW: 00000000 at  00000048
    [   26.968991] sof-audio-pci 0000:00:1f.3: Debug PCIR: 00000000 at  00000044
    [   26.968994] sof-audio-pci 0000:00:1f.3: Debug PCIW: 00000004 at  00000044
    
    

    Test recipe

    Kernel:https://github.com/thesofproject/linux/tree/integration/soundwire-latest commit: 121c751 +PR #1640
    FW: https://github.com/thesofproject/sof/commits/cml-010-drop-stable commit: 5e5f69e
    Tplg: Same with FW branch, sof-cml-rt711-rt1308-rt715.tplg
    Platform:CML-H Laptop with codec ALC711, 2 x RT1308, RT715 in SDW mode.

    failed_multipipeline_test_1_all_logger.log
    failed_multipipeline_test_1_dmesg.log
    failed_multipipeline_test_1_logger_error.log

  13. RanderWang commented on Dec 20, 2019

    @RanderWang

    @bardliao I wonder if the sequences are correct. Somehow we should probably enable the interrupts last, after the bus reset. And conversely when suspending we should disable the interrupts first.

    @plbossart Sorry, but I think we can't invert the sequence between enable interrupt and clock stop. sdw_slave_clk_stop_callback() will be triggered on the clock stop process, and interrupt is needed for transmission.

    yes, we need interrupt to do clock stop setting

  14. 37 remaining items

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Metadata

Metadata

Assignees

Labels

CMLApplies to Comet Lake platformSDWApplies to SoundWire bus for codec connectionSDW_DEVSDW bug reproduced by developers, fix WIPbugSomething isn't working

Type

No type

Projects

No projects

    Milestone

    No milestone

    Relationships

    None yet

    Development

    No branches or pull requests

    Issue actions