Skip to content

[BUG][TGL][SDW][CI]Msg NACK received, trf on Slave 1 failed #2534

New issue
New issue
Closed
Closed
[BUG][TGL][SDW][CI]Msg NACK received, trf on Slave 1 failed#2534
Labels
P2Critical bugs or normal featuresSDWApplies to SoundWire bus for codec connectionTGLApplies to Tiger Lake platformbugSomething isn't workingfix submittedFix submitted but not merged yet

Description

@aiChaoSONG
aiChaoSONG
opened on Oct 26, 2020

In daily test report 594 on TGL SDW Chromebook, below error observed from dmesg in suspend-resume test:

kernel: [ 8742.635561] intel-sdw intel-sdw.0: Msg ignored for Slave 1
kernel: [ 8742.635622] intel-sdw intel-sdw.0: Msg Ack not received
kernel: [ 8742.635622] intel-sdw intel-sdw.0: Msg ignored for Slave 1
kernel: [ 8742.635706] intel-sdw intel-sdw.0: Msg Ack not received
kernel: [ 8742.635706] intel-sdw intel-sdw.0: Msg NACK received
kernel: [ 8742.635707] intel-sdw intel-sdw.0: Msg NACKed for Slave 1
kernel: [ 8742.635708] soundwire sdw-master-0: trf on Slave 1 failed:-5

Recipe:
Kernel: topic/sof-dev d0a335d
SOF : master e04610b
TPLG: sof-tgl-sdw-max98373-rt5682-4ch.tplg
Platform: TGL Chrome book proto2

Activity

  1. plbossart commented on Oct 26, 2020

    @plbossart
    plbossart
    on Oct 26, 2020
    Member

    @aiChaoSONG there's nothing we can do without the full dmesg. Can this be extracted?
    An NAK usually means the bus is not functional at all and devices receive data that's not correct (e.g. with a parity error)

  2. aiChaoSONG commented on Oct 27, 2020

    @aiChaoSONG
    aiChaoSONG
    on Oct 27, 2020
    Author

    @plbossart #2522, #2533 and this issue is from the same report. Please check #2522 to read the whole story.

  3. keyonjie
    added
    codecCodec HW or driver restriction
    P3Low-impact bugs or features
    on Nov 2, 2020

  4. keyonjie commented on Nov 2, 2020

    @keyonjie
    keyonjie
    on Nov 2, 2020

    @naveen-manohar FYI.

  5. mengdonglin
    added
    SDWApplies to SoundWire bus for codec connection
    TGLApplies to Tiger Lake platform
    on Nov 2, 2020
  6. plbossart
    removed
    codecCodec HW or driver restriction
    on Nov 5, 2020
  7. mengdonglin
    added
    MAX98373Issues with Max98373 codec
    on Nov 9, 2020

  8. plbossart commented on Nov 10, 2020

    @plbossart
    plbossart
    on Nov 10, 2020
    Member

    @aiChaoSONG it does not appear to be the 'same story'. I see in daily test 706 that all SoundWire platforms pass except the Volteer platform for the suspend-resume case.

  9. aiChaoSONG commented on Nov 11, 2020

    @aiChaoSONG
    aiChaoSONG
    on Nov 11, 2020
    Author

    @plbossart This may be related to MAX98373 codec, as we discussed in PRC bug scrub.

  10. plbossart commented on Nov 11, 2020

    @plbossart
    plbossart
    on Nov 11, 2020
    Member

    @plbossart This may be related to MAX98373 codec, as we discussed in PRC bug scrub.

    There is one of the two amps that appears to lose sync, but that shouldn't be fatal. I added traces in #2559, I think we need to have a better diagnosis, it's not just the codec but the bus management that seems problematic.

  11. mengdonglin
    added
    bugSomething isn't working
    on Nov 13, 2020

  12. bardliao commented on Nov 13, 2020

    @bardliao
    bardliao
    on Nov 13, 2020
    Collaborator

    @plbossart @RanderWang From the dmesg on daily report 727, it looks like someone tried to access sdw bus 0 Slave 1 before it is enumerated. Question is who/where did it? The other interesting thing is sdw bus 0 Slave 1 is rt5682, not max98373 and rt5682 is the only codec on sdw bus 0.

    dmesg 
    kernel: [ 8706.640056] intel-sdw intel-sdw.1: intel_resume: pm_runtime status was suspended, forcing active
kernel: [ 8706.640215] max98373 sdw:1:19f:8373:0:7: sdw_modify_slave_status: initializing completion for Slave 1
kernel: [ 8706.640217] max98373 sdw:1:19f:8373:0:3: sdw_modify_slave_status: initializing completion for Slave 2
kernel: [ 8706.640326] cdns_fill_msg_resp: 13 callbacks suppressed
kernel: [ 8706.640329] intel-sdw intel-sdw.0: Msg Ack not received
kernel: [ 8706.640329] cdns_fill_msg_resp: 3 callbacks suppressed
kernel: [ 8706.640330] intel-sdw intel-sdw.0: Msg ignored for Slave 1
kernel: [ 8706.640387] intel-sdw intel-sdw.0: Msg Ack not received
kernel: [ 8706.640388] intel-sdw intel-sdw.0: Msg ignored for Slave 1
kernel: [ 8706.640415] sof-audio-pci 0000:00:1f.3: ipc rx: 0x90020000: GLB_TRACE_MSG
kernel: [ 8706.640424] sof-audio-pci 0000:00:1f.3: ipc rx done: 0x90020000: GLB_TRACE_MSG
kernel: [ 8706.640433] intel-sdw intel-sdw.0: Msg Ack not received
kernel: [ 8706.640433] intel-sdw intel-sdw.0: Msg ignored for Slave 1
kernel: [ 8706.640492] intel-sdw intel-sdw.0: Msg Ack not received
kernel: [ 8706.640493] intel-sdw intel-sdw.0: Msg ignored for Slave 1
kernel: [ 8706.640554] intel-sdw intel-sdw.0: Msg Ack not received
kernel: [ 8706.640555] intel-sdw intel-sdw.0: Msg ignored for Slave 1
kernel: [ 8706.640617] intel-sdw intel-sdw.0: Msg Ack not received
kernel: [ 8706.640619] intel-sdw intel-sdw.0: Msg ignored for Slave 1
kernel: [ 8706.640683] intel-sdw intel-sdw.0: Msg Ack not received
kernel: [ 8706.640685] intel-sdw intel-sdw.0: Msg ignored for Slave 1
kernel: [ 8706.640748] intel-sdw intel-sdw.0: Msg Ack not received
kernel: [ 8706.640750] intel-sdw intel-sdw.0: Msg ignored for Slave 1
kernel: [ 8706.640808] intel-sdw intel-sdw.0: Msg Ack not received
kernel: [ 8706.640809] intel-sdw intel-sdw.0: Msg ignored for Slave 1
kernel: [ 8706.640909] intel-sdw intel-sdw.0: Msg Ack not received
kernel: [ 8706.640911] intel-sdw intel-sdw.0: Msg NACK received
kernel: [ 8706.640912] intel-sdw intel-sdw.0: Msg NACKed for Slave 1
kernel: [ 8706.640913] soundwire sdw-master-0: trf on Slave 1 failed:-5
kernel: [ 8706.640934] intel-sdw intel-sdw.0: Slave status change
kernel: [ 8706.640942] soundwire sdw-master-0: Slave attached, programming device number
kernel: [ 8706.640970] intel-sdw intel-sdw.0: Msg ignored for Slave 1
kernel: [ 8706.641193] intel-sdw intel-sdw.1: Slave status change
kernel: [ 8706.641196] soundwire sdw-master-1: Slave attached, programming device number
kernel: [ 8706.641200] soundwire sdw-master-0: No more devices to enumerate
kernel: [ 8706.641226] intel-sdw intel-sdw.0: Slave status change
kernel: [ 8706.641360] soundwire sdw-master-1: SDW Slave Addr: 27019f837300
kernel: [ 8706.641364] soundwire sdw-master-1: SDW Slave class_id 0, part_id 8373, mfg_id 19f, unique_id 7, version 2
kernel: [ 8706.641364] soundwire sdw-master-1: Slave already registered, reusing dev_num:1
kernel: [ 8706.641381] intel-sdw intel-sdw.0: Slave status change
kernel: [ 8706.641385] soundwire sdw-master-0: Slave attached, programming device number
kernel: [ 8706.641606] soundwire sdw-master-1: SDW Slave Addr: 23019f837300
kernel: [ 8706.641607] soundwire sdw-master-1: SDW Slave class_id 0, part_id 8373, mfg_id 19f, unique_id 3, version 2
kernel: [ 8706.641607] soundwire sdw-master-1: Slave already registered, reusing dev_num:2
kernel: [ 8706.641653] soundwire sdw-master-0: SDW Slave Addr: 20025d568200
kernel: [ 8706.641654] soundwire sdw-master-0: SDW Slave class_id 0, part_id 5682, mfg_id 25d, unique_id 0, version 2
kernel: [ 8706.641655] soundwire sdw-master-0: Slave already registered, reusing dev_num:1
kernel: [ 8706.641816] soundwire sdw-master-1: No more devices to enumerate
kernel: [ 8706.641836] intel-sdw intel-sdw.1: Slave status change
kernel: [ 8706.641840] max98373 sdw:1:19f:8373:0:7: sdw_modify_slave_status: signaling completion for Slave 1
kernel: [ 8706.641962] max98373 sdw:1:19f:8373:0:3: sdw_modify_slave_status: signaling completion for Slave 2
kernel: [ 8706.642013] soundwire sdw-master-0: No more devices to enumerate
kernel: [ 8706.642040] intel-sdw intel-sdw.0: Slave status change
kernel: [ 8706.642065] rt5682 sdw:0:25d:5682:0: sdw_modify_slave_status: signaling completion for Slave 1
kernel: [ 8706.687923] intel-sdw intel-sdw.0: Slave status change
kernel: [ 8706.688311] intel-sdw intel-sdw.0: Slave status change

  13. plbossart commented on Nov 13, 2020

    @plbossart
    plbossart
    on Nov 13, 2020
    Member

    @bardliao in this case there's a NAK while trying to read rt5682 devID registers, but that's not a problem. The device will be enumerated later.
    This is relatively strange to me that we have issues for either rt5682 (NAK) or max98373 (bus clash or parity issues), that's inconsistent.

  14. 5 remaining items

  15. plbossart commented on Nov 17, 2020

    @plbossart
    plbossart
    on Nov 17, 2020
    Member

    @plbossart I think the NAK and the Parity errors are different issue.
    For the parity error issue, should we add below on max98373 codec, too?

    prop->quirks = SDW_SLAVE_QUIRKS_INVALID_INITIAL_PARITY

    I thought about this, but on my DUT the parity error was primarily from rt5682-sdw & dint observe with max98373-sdw, so ignored.

    The rt5682 already has the SDW_SLAVE_QUIRKS_INVALID_INITIAL_PARITY quirk, so if you get a parity error from that device, it's a real one - not a fake issue after a hardware reset.

    I don't know if the max98373 has the same issue, it's be surprising given that these codecs have nothing in common.

  16. mengdonglin
    added
    P2Critical bugs or normal features
    and removed
    P3Low-impact bugs or features
    MAX98373Issues with Max98373 codec
    on Nov 18, 2020

  17. RanderWang commented on Nov 18, 2020

    @RanderWang
    RanderWang
    on Nov 18, 2020

    reproduced with daily build 11/06. It seems be difficult to reproduce NAck with latest driver. And 5682 was enumerated later.

    [ 8741.049583] intel-sdw intel-sdw.0: intel_resume: pm_runtime status was suspended, forcing active
[ 8741.049586] intel-sdw intel-sdw.0: intel_link_power_up: powering up all links
[ 8741.049587] intel-sdw intel-sdw.0: intel_link_power_up: first link up, programming SYNCPRD
[ 8741.049920] rt5682 sdw:0:25d:5682:0: sdw_modify_slave_status: initializing completion for Slave 1
[ 8741.050065] intel-sdw intel-sdw.1: intel_resume: pm_runtime status was suspended, forcing active
[ 8741.050285] max98373 sdw:1:19f:8373:0:7: sdw_modify_slave_status: initializing completion for Slave 1
[ 8741.050286] max98373 sdw:1:19f:8373:0:3: sdw_modify_slave_status: initializing completion for Slave 2
[ 8741.050507] cdns_fill_msg_resp: 14 callbacks suppressed
[ 8741.050508] intel-sdw intel-sdw.0: Msg Ack not received
[ 8741.050508] cdns_fill_msg_resp: 4 callbacks suppressed
[ 8741.050509] intel-sdw intel-sdw.0: Msg ignored for Slave 1
[ 8741.050571] intel-sdw intel-sdw.0: Msg Ack not received
[ 8741.050571] intel-sdw intel-sdw.0: Msg ignored for Slave 1
[ 8741.050639] intel-sdw intel-sdw.0: Msg Ack not received
[ 8741.050639] intel-sdw intel-sdw.0: Msg ignored for Slave 1
[ 8741.050708] intel-sdw intel-sdw.0: Msg Ack not received
[ 8741.050709] intel-sdw intel-sdw.0: Msg ignored for Slave 1
[ 8741.050823] intel-sdw intel-sdw.0: Msg Ack not received
[ 8741.050823] intel-sdw intel-sdw.0: Msg NACK received
[ 8741.050824] intel-sdw intel-sdw.0: Msg NACKed for Slave 1
[ 8741.050824] soundwire sdw-master-0: trf on Slave 1 failed:-5
[ 8741.050828] intel-sdw intel-sdw.0: Slave status change
[ 8741.050838] soundwire sdw-master-0: Slave attached, programming device number
[ 8741.050884] intel-sdw intel-sdw.0: Msg Ack not received
[ 8741.050885] intel-sdw intel-sdw.0: Msg ignored for Slave 1
[ 8741.050954] intel-sdw intel-sdw.0: Msg Ack not received
[ 8741.050954] intel-sdw intel-sdw.0: Msg ignored for Slave 1
[ 8741.051127] intel-sdw intel-sdw.0: Msg Ack not received
[ 8741.051128] intel-sdw intel-sdw.0: Msg Ack not received
[ 8741.051129] intel-sdw intel-sdw.0: Msg Ack not received
[ 8741.051130] intel-sdw intel-sdw.0: Msg ignored for Slave 0
[ 8741.051133] soundwire sdw-master-0: No more devices to enumerate
[ 8741.051157] intel-sdw intel-sdw.0: Slave status change
[ 8741.051211] intel-sdw intel-sdw.0: Msg ignored for Slave 1
[ 8741.051266] intel-sdw intel-sdw.0: Msg ignored for Slave 1
[ 8741.051268] intel-sdw intel-sdw.0: Slave status change
[ 8741.051271] soundwire sdw-master-0: Slave attached, programming device number
[ 8741.051334] intel-sdw intel-sdw.0: Msg ignored for Slave 1
[ 8741.051470] intel-sdw intel-sdw.1: Slave status change
[ 8741.051474] soundwire sdw-master-1: Slave attached, programming device number
[ 8741.051591] soundwire sdw-master-0: SDW Slave Addr: 20025d568200
[ 8741.051592] soundwire sdw-master-0: SDW Slave class_id 0, part_id 5682, mfg_id 25d, unique_id 0, version 2
[ 8741.051592] soundwire sdw-master-0: Slave already registered, reusing dev_num:1

  18. bardliao commented on Nov 19, 2020

    @bardliao
    bardliao
    on Nov 19, 2020
    Collaborator
    kernel: [ 8506.696984] intel-sdw intel-sdw.0: Msg NACK received, cmd 0
kernel: [ 8506.696985] intel-sdw intel-sdw.0: Msg NACKed for Slave 1
kernel: [ 8506.696986] soundwire sdw-master-0: trf on Slave 1 failed:-5 write addr 3008 count 1
kernel: [ 8506.697014] intel-sdw intel-sdw.0: Slave status change
kernel: [ 8506.697018] soundwire sdw-master-0: Slave attached, programming device number

    addr 3008 is RT5682_SDW_CMD which is used by rt5682_sdw_read() and rt5682_sdw_write(). After adding some more trace, I got

    [  36.308361] bard: rt5682_resume
[   36.308498] intel-sdw intel-sdw.0: Msg ignored for Slave 1
[   36.308500] rt5682 sdw:0:25d:5682:0: [rt5682_sdw_write] 0008 <= 000f failed -61
[   36.308500] rt5682 sdw:0:25d:5682:0: Unable to sync register 0x8. -61
[   36.308811] OOM killer enabled.
[   36.308811] Restarting tasks ...
[   36.308825] intel-sdw intel-sdw.0: Slave status change
[   36.308834] soundwire sdw-master-0: Slave attached, programming device number
[   36.309026] soundwire sdw-master-0: SDW Slave Addr: 20025d568200
[   36.309026] soundwire sdw-master-0: SDW Slave class_id 0, part_id 5682, mfg_id 25d, unique_id 0, version 2
[   36.309027] soundwire sdw-master-0: Slave already registered, reusing dev_num:1
[   36.309722] done.
[   36.309853] intel-sdw intel-sdw.0: Msg ignored for Slave 0
[   36.309854] soundwire sdw-master-0: No more devices to enumerate
[   36.309889] intel-sdw intel-sdw.0: Slave status change
[   36.309893] rt5682 sdw:0:25d:5682:0: sdw_modify_slave_status: signaling completion for Slave 1
[   36.310035] intel-sdw intel-sdw.0: Slave status change
[   36.310040] rt5682 sdw:0:25d:5682:0: bard: rt5682_dev_resume start
[   36.310042] rt5682 sdw:0:25d:5682:0: bard: rt5682_dev_resume regmap_sync
[   36.330948] PM: suspend exit
[   36.437508] rt5682 sdw:0:25d:5682:0: bard: rt5682_dev_resume end
[   36.437885] intel-sdw intel-sdw.0: Slave status change
[   40.188381] intel-sdw intel-sdw.0: intel_link_power_down: powering down all links

    Note that I didn't reproduce the issue with above log and I removed some irrelevant log.
    What I see from the log is that rt5682_resume is invoked before Slave attached, programming device number. And we call regcache_sync(rt5682->regmap) in rt5682_resume(). In other words, the driver tries to do IO transfer before the Slave is enumerated which looks wrong to me. We usually get Msg ignored for Slave 1 for this, but for some reason we get NAK occasionally. Maybe the NAK error happens if we try to access the Slave while it is during the attach process. So, IMHO, we should prevent any function from accessing sdw Slave before it is assigned a device number. And we can check if it can fix the NAK issue.

  19. RanderWang commented on Nov 19, 2020

    @RanderWang
    RanderWang
    on Nov 19, 2020

    Great @bardliao ! it is caused by ASoC resume function. I tried to reproduce this bug to get call stack to find who write register but I can't reproduce it. You show the simplest way to find hint. We all ignore the "intel-sdw intel-sdw.0: Msg ignored for Slave 1". I learned so much from you finding. Thanks !

  20. RanderWang commented on Nov 19, 2020

    @RanderWang
    RanderWang
    on Nov 19, 2020

    And if it is dev_dbg instead of dev_dbg_ratelimited in cdns_fill_msg, we should get a batch of ignore message. So dev_dbg_ratelimited sometimes hide bugs.

  21. plbossart commented on Nov 19, 2020

    @plbossart
    plbossart
    on Nov 19, 2020
    Member

    Nice progress @bardliao, but I am confused. Why is the rt5682_resume() function used?

    it should be

    rt5682_dev_resume(struct device *dev)

    linux/sound/soc/codecs/rt5682-sdw.c

    Line 732 in cfa9a86

    static int __maybe_unused rt5682_dev_resume(struct device *dev)

  22. plbossart commented on Nov 19, 2020

    @plbossart
    plbossart
    on Nov 19, 2020
    Member

    I think I know what's happening...

    the SoundWire card is instantiated with a platform device, which is a child of the PCI device. The platform driver (machine driver) relies on the classic snd_soc_pm_ops. When the card resumes, it will call a workqueue which will resume the components, and for rt5682 the component driver exposes the rt5682_resume function.

    The rt5682 device is a child of the PCI device, and it has its own resume function.

    So I guess what happens is that when the card resumes, the component resume may happen before the device resume.

    I think the only way to fix this is to take an explicit reference with pm_runtime_get_sync() so that the component resume only happens after the device resume is complete.

  23. aiChaoSONG commented on Nov 23, 2020

    @aiChaoSONG
    aiChaoSONG
    on Nov 23, 2020
    Author

    Not reproduced on: 2020/11/23 UTC+8

  24. bardliao commented on Nov 23, 2020

    @bardliao
    bardliao
    on Nov 23, 2020
    Collaborator

    I checked all Realtek sdw codecs and max89373 and it seems snd_soc_pm_ops is not used on those codec drivers.

  25. mengdonglin
    added
    fix submittedFix submitted but not merged yet
    on Nov 25, 2020

  26. plbossart commented on Dec 11, 2020

    @plbossart
    plbossart
    on Dec 11, 2020
    Member

    Fixed by #2567

  27. plbossart
    closed this as completedon Dec 11, 2020
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Metadata

Metadata

Assignees

No one assigned

    Labels

    P2Critical bugs or normal featuresSDWApplies to SoundWire bus for codec connectionTGLApplies to Tiger Lake platformbugSomething isn't workingfix submittedFix submitted but not merged yet

    Type

    No type

    Projects

    No projects

      Milestone

      No milestone

      Relationships

      None yet

      Development

      No branches or pull requests

      Issue actions