Skip to content

[CML] Random IPC time out issues #1254

Closed
Closed
[CML] Random IPC time out issues#1254
Assignees
keyonjiebkokoszx
Labels
CMLApplies to Comet Lake platformHDAApplies to HD-Audio bus for codec connectionIPC timeoutIPC timeout observedP1Blocker bugs or important featuresbugSomething isn't working as expected
Milestone
1.3

Description

@stevyan
stevyan
opened on Apr 11, 2019

Describe the bug
topology load failed sometimes when pulseaudio active;

** Reproduce rate ~70% when PulseAudio is active, ~30-40% when PulseAudio is disabled.
To Reproduce
aplay -l

Expected behavior
list all the playback pcm pipelines;

Actual behavior
no sound card found

Environment
Kernel: rander/cml-validation-branch (topic/sof-dev 58d1b6b + issue 767 regression fix + DMIC patch)
Firmware: master ed6ac05 (revert the commit f5e7843)
Topology: rander/cml-validation-branch (master 742f83b + DMIC topology support patch )
Reproducibility Rate: 7/10

dmesg log

[    9.540286] sof-audio-pci 0000:00:1f.3: ipc tx: 0x80010000: GLB_DAI_MSG: CONFIG
[    9.844356] sof-audio-pci 0000:00:1f.3: error: ipc timed out for 0x80010000 size 120
[    9.844455] sof-audio-pci 0000:00:1f.3: status: fw entered - code 00000005
[    9.844744] sof-audio-pci 0000:00:1f.3: error: unexpected fault 0x00000000 trace 0x00004000
[    9.844821] sof-audio-pci 0000:00:1f.3: error: waking up any trace sleepers
[    9.844889] sof-audio-pci 0000:00:1f.3: error: failed to set DAI config for direction:0 of HDA dai 2
[    9.844972] sof-audio-pci 0000:00:1f.3: error: failed to process hda dai link Digital Playback and Capture
[    9.845060] sof-audio-pci 0000:00:1f.3: ASoC: physical link loading failed
[    9.845203] sof-audio-pci 0000:00:1f.3: FW Poll Status: reg=0x1010f0f successful
[    9.845209] sof-audio-pci 0000:00:1f.3: FW Poll Status: reg=0xf0f successful
[    9.845212] sof-audio-pci 0000:00:1f.3: DSP core(s) enabled? 0 : core_mask 1
[    9.845220] sof-audio-pci 0000:00:1f.3: FW Poll Status: reg=0xf0f successful
[    9.845225] sof-audio-pci 0000:00:1f.3: FW Poll Status: reg=0xf0f successful
[    9.845228] sof-audio-pci 0000:00:1f.3: DSP core(s) enabled? 0 : core_mask 1
[    9.845235] sof-audio-pci 0000:00:1f.3: FW Poll Status: reg=0xf0f successful
[    9.845240] sof-audio-pci 0000:00:1f.3: FW Poll Status: reg=0xf0f successful
[    9.845243] sof-audio-pci 0000:00:1f.3: DSP core(s) enabled? 0 : core_mask 1
[    9.845251] sof-audio-pci 0000:00:1f.3: FW Poll Status: reg=0xf0f successful
[    9.845256] sof-audio-pci 0000:00:1f.3: FW Poll Status: reg=0xf0f successful
[    9.845259] sof-audio-pci 0000:00:1f.3: DSP core(s) enabled? 0 : core_mask 1
[    9.845267] sof-audio-pci 0000:00:1f.3: FW Poll Status: reg=0xf0f successful
[    9.845285] sof-audio-pci 0000:00:1f.3: FW Poll Status: reg=0xf0f successful
[    9.845289] sof-audio-pci 0000:00:1f.3: DSP core(s) enabled? 0 : core_mask 1
[    9.845297] sof-audio-pci 0000:00:1f.3: FW Poll Status: reg=0xf0f successful
[    9.845302] sof-audio-pci 0000:00:1f.3: FW Poll Status: reg=0xf0f successful
[    9.845305] sof-audio-pci 0000:00:1f.3: DSP core(s) enabled? 0 : core_mask 1
[    9.845314] sof-audio-pci 0000:00:1f.3: FW Poll Status: reg=0xf0f successful
[    9.845319] sof-audio-pci 0000:00:1f.3: FW Poll Status: reg=0xf0f successful
[    9.845322] sof-audio-pci 0000:00:1f.3: DSP core(s) enabled? 0 : core_mask 1
[    9.845330] sof-audio-pci 0000:00:1f.3: FW Poll Status: reg=0xf0f successful
[    9.845335] sof-audio-pci 0000:00:1f.3: FW Poll Status: reg=0xf0f successful
[    9.845338] sof-audio-pci 0000:00:1f.3: DSP core(s) enabled? 0 : core_mask 1
[    9.845346] sof-audio-pci 0000:00:1f.3: FW Poll Status: reg=0xf0f successful
[    9.845351] sof-audio-pci 0000:00:1f.3: FW Poll Status: reg=0xf0f successful
[    9.845354] sof-audio-pci 0000:00:1f.3: DSP core(s) enabled? 0 : core_mask 1
[    9.845360] sof-audio-pci 0000:00:1f.3: error: tplg component load failed -110
[    9.845438] sof-audio-pci 0000:00:1f.3: error: failed to load DSP topology -22
[    9.845506] sof-audio-pci 0000:00:1f.3: ASoC: failed to probe component -22
[    9.845655] skl_hda_dsp_generic skl_hda_dsp_generic: ASoC: failed to instantiate card -22
[    9.845790] skl_hda_dsp_generic: probe of skl_hda_dsp_generic failed with error -22
[   11.984003] systemd-udevd (1711) used greatest stack depth: 11240 bytes left
[   37.964964] iwlwifi 0000:00:14.3: BIOS contains WGDS but no WRDS
[   39.624948] ax88179_178a 2-2:1.0 enx000ec6a1e622: ax88179 - Link status is: 1
[   39.632078] IPv6: ADDRCONF(NETDEV_CHANGE): enx000ec6a1e622: link becomes ready
[   52.948792] rfkill: input handler disabled

dmesg_topology_load_failed.log

Activity

  1. stevyan
    added
    bugSomething isn't working as expected
    on Apr 11, 2019

  2. tlauda commented on Apr 11, 2019

    @tlauda
    tlauda
    on Apr 11, 2019
    Contributor

    @stevyan It's IPC timeout, so FW logs are needed.

  3. stevyan commented on Apr 12, 2019

    @stevyan
    stevyan
    on Apr 12, 2019
    Author

    sof-logger log

     CORE  LEVEL      COMP_ID                TIMESTAMP            DELTA                FILE_NAME	CONTENT
    0      2          DMA             98479.739583     98479.742188 intel/cavs/hda-dma.c:480 	hda-dmac: 4 channel 0 -> get
    0      2          DMA             98645.729167       165.989578 intel/cavs/hda-dma.c:703 	hda-dmac: 4 channel 0 -> config
    0      2          DMA             98691.354167        45.625000 intel/cavs/hda-dma.c:549 	hda-dmac: 4 channel 0 -> start
    0      2          DMA             98694.843750         3.489583 intel/cavs/hda-dma.c:396 	hda-dmac: 4 channel 0 -> enable
    0      2          IPC             99383.229167       688.385437    src/ipc/handler.c:926 	ipc: hdr 0x30010000 tx (76) > rx (28)
    0      2          IPC             99386.614583         3.385417    src/ipc/handler.c:929 	ipc: pipe 1 comp 0 -> new (type 1)
    0      2         HOST             99391.770833         5.156250     src/audio/host.c:348 	host_new()
    0      2          DMA             99407.083333        15.312500 intel/cavs/hda-dma.c:840 	hda-dmac :5 -> probe
    0      2          DMA             99423.958333        16.875000        src/lib/dma.c:142 	dma_get() ID 5 sref = 1 busy channels 0
    0      2          IPC             99543.489583       119.531250    src/ipc/handler.c:926 	ipc: hdr 0x30010000 tx (84) > rx (28)
    0      2          IPC             99546.718750         3.229167    src/ipc/handler.c:929 	ipc: pipe 1 comp 1 -> new (type 5)
    0      2       VOLUME             99551.197917         4.479167   src/audio/volume.c:178 	volume_new()
    0      2          IPC             99661.666667       110.468750    src/ipc/handler.c:959 	ipc: pipe 1 buffer 2 -> new (0x300 bytes)
    0      2       BUFFER             99665.937500         4.270833   src/audio/buffer.c:54  	buffer_new()
    0      2          IPC             99802.968750       137.031250    src/ipc/handler.c:959 	ipc: pipe 1 buffer 3 -> new (0x300 bytes)
    0      2       BUFFER             99807.239583         4.270833   src/audio/buffer.c:54  	buffer_new()
    0      2          IPC             99959.218750       151.979172    src/ipc/handler.c:926 	ipc: hdr 0x30010000 tx (80) > rx (28)
    0      2          IPC             99962.604167         3.385417    src/ipc/handler.c:929 	ipc: pipe 1 comp 4 -> new (type 2)
    0      2          DAI             99967.916667         5.312500      src/audio/dai.c:203 	dai_new()
    0      2          DAI             99981.666667        13.750000        src/lib/dai.c:87  	dai_get(), d = 0xbe05d0a0, sref = 1
    0      2          DMA             99985.729167         4.062500 intel/cavs/hda-dma.c:840 	hda-dmac :7 -> probe
    0      2          DMA            100002.187500        16.458334        src/lib/dma.c:142 	dma_get() ID 7 sref = 1 busy channels 0
    0      2          IPC            100107.500000       105.312500    src/ipc/handler.c:987 	ipc: pipe 1 -> new
    0      2         PIPE            100114.479167         6.979167 src/audio/pipeline.c:72  	pipeline_new()
    0      2          IPC            100560.625000       446.145844    src/ipc/handler.c:660 	ipc: pm core mask 0x1 -> enable
    0      2          IPC            100946.302083       385.677094    src/ipc/handler.c:926 	ipc: hdr 0x30010000 tx (76) > rx (28)
    0      2          IPC            100949.531250         3.229167    src/ipc/handler.c:929 	ipc: pipe 2 comp 7 -> new (type 1)
    0      2         HOST            100955.520833         5.989583     src/audio/host.c:348 	host_new()
    0      2          DMA            100970.729167        15.208333        src/lib/dma.c:142 	dma_get() ID 4 sref = 2 busy channels 1
    0      2          IPC            101717.291667       746.562500    src/ipc/handler.c:926 	ipc: hdr 0x30010000 tx (84) > rx (28)
    0      2          IPC            101720.625000         3.333333    src/ipc/handler.c:929 	ipc: pipe 2 comp 8 -> new (type 5)
    0      2       VOLUME            101726.718750         6.093750   src/audio/volume.c:178 	volume_new()
    0      2          IPC            102074.010417       347.291656    src/ipc/handler.c:959 	ipc: pipe 2 buffer 9 -> new (0x300 bytes)
    0      2       BUFFER            171994.739583     69920.726562   src/audio/buffer.c:54  	buffer_new()
  4. stevyan
    changed the title [-][BUG][CML] topology load failed sometimes when pulseaudio active. [2/10][/-] [+][BUG][CML] topology load failed sometimes when pulseaudio active. [7/10][/+] on Apr 12, 2019
  5. stevyan
    added
    HDAApplies to HD-Audio bus for codec connection
    CMLApplies to Comet Lake platform
    on Apr 12, 2019

  6. tlauda commented on Apr 12, 2019

    @tlauda
    tlauda
    on Apr 12, 2019
    Contributor

    @stevyan Does this issue reproduce with topology from master without any extra patches?

  7. mengdonglin
    changed the title [-][BUG][CML] topology load failed sometimes when pulseaudio active. [7/10][/-] [+][CML] Random topology load failure[/+] on Apr 12, 2019
  8. mengdonglin
    assigned
    keyonjie
    on Apr 12, 2019
  9. mengdonglin
    added
    P1Blocker bugs or important features
    on Apr 12, 2019
  10. mengdonglin
    changed the title [-][CML] Random topology load failure[/-] [+][CML] IPC time out causes random topology load failure[/+] on Apr 15, 2019
  11. dabekjakub
    self-assigned this
    on Apr 15, 2019

  12. emilchudzik commented on Apr 15, 2019

    @emilchudzik
    emilchudzik
    on Apr 15, 2019
    Contributor

    In my env I have properly loaded topology each time, but issue with pulse audio exists:

    Environment:
    Platform: WHL RVP - HDA mode
    Kernel:
    2de29fa [thesofproject/linux: topic/sof-dev]
    +d04ccf494 [RanderWang/linux: cml-validation-20190415]
    +bfb0729dd [RanderWang/linux: cml-validation-20190415]
    +8a2b13a81 [RanderWang/linux: cml-validation-20190415]
    +63ceb8f68 [RanderWang/linux: cml-validation-20190415]
    +db89510d0 [RanderWang/linux: cml-validation-20190415]

    Firmware: 00bbb11 [thesofproject/sof: master]
    Topology: 00bbb11 [thesofproject/sof: master] -> sof-hda-generic.tplg

    When I disabled pulseaudio, I have only 1/10 issue while second playback start:
    3AEA0DBC

    currently after reboot i have no issue, I can play each time.

    Whan I have enabled pulsuaudio I have many erros with timeout.
    Logs here: #1263 (comment)

  13. keyonjie commented on Apr 15, 2019

    @keyonjie
    keyonjie
    on Apr 15, 2019
    Contributor

    Today I setup this and can duplicate the issue also, I also managed to create simultaneous 2 playback streams to duplicate the ipc timeout issue, will do advanced debugging tomorrow.

  14. emilchudzik commented on Apr 16, 2019

    @emilchudzik
    emilchudzik
    on Apr 16, 2019
    Contributor

    I have no issue with #1269 applied on the current sof master branch without reverting any others commits. Without this PR I had an erros even during boot. Currently simple aplay and arecord works, also in loop.

    Environment:
    Platform: WHL RVP - HDA mode
    Kernel:
    2de29fa [thesofproject/linux: topic/sof-dev]
    +d04ccf494 [RanderWang/linux: cml-validation-20190415]
    +bfb0729dd [RanderWang/linux: cml-validation-20190415]
    +8a2b13a81 [RanderWang/linux: cml-validation-20190415]
    +63ceb8f68 [RanderWang/linux: cml-validation-20190415]
    +db89510d0 [RanderWang/linux: cml-validation-20190415]

    Firmware: 1b15fad [thesofproject/sof: master] + 624c189
    Topology: 1b15fad [thesofproject/sof: master] -> sof-hda-generic.tplg

  15. 20 remaining items

  16. ranj063 commented on Apr 28, 2019

    @ranj063
    ranj063
    on Apr 28, 2019
    Collaborator

    @keyonjie if the timeout is always with the CTX_SAVE ipc, we can simply ignore the timeout in the driver andjust power down the DSP in any case. We used to have this earlier but removed it recently when we fixed the power down sequence in GLK.

    @mmaka1 could you please double check the power down sequence for CNL to make sure we didnt miss anything?

  17. ClarexZhou commented on Apr 29, 2019

    @ClarexZhou
    ClarexZhou
    on Apr 29, 2019

    Add 2 more ipc timed out logs on CML laptop:

    1. ipc timetout during multi pipeline test
      no error sof logger.
      ipctimeout_multiPipeline_dmesg.log
    [    3.463462] HDMI HDA Codec ehdaudio0D2: hdac_hdmi_present_sense: disconnect for pin:port 5:0
[    3.478008] HDMI HDA Codec ehdaudio0D2: hdac_hdmi_present_sense: disconnect for pin:port 6:0
[    4.490375] systemd-udevd (1664) used greatest stack depth: 11504 bytes left
[    5.022408] HDMI HDA Codec ehdaudio0D2: hdac_hdmi_present_sense: disconnect for pin:port 5:0
[    5.031547] HDMI HDA Codec ehdaudio0D2: hdac_hdmi_present_sense: disconnect for pin:port 6:0
[    6.729078] ax88179_178a 1-3:1.0 enx000ec6a1e569: ax88179 - Link status is: 1
[    6.738230] IPv6: ADDRCONF(NETDEV_CHANGE): enx000ec6a1e569: link becomes ready
[    6.770838] sof-audio-pci 0000:00:1f.3: error: volume get failed to idle -16
[    6.771022] sof-audio-pci 0000:00:1f.3: error: volume get failed to idle -16
[    6.771238] sof-audio-pci 0000:00:1f.3: error: volume get failed to idle -16
[    6.771452] sof-audio-pci 0000:00:1f.3: error: volume get failed to idle -16
[    6.771634] sof-audio-pci 0000:00:1f.3: error: volume get failed to idle -16
[    6.771822] sof-audio-pci 0000:00:1f.3: error: volume get failed to idle -16
[    6.771997] sof-audio-pci 0000:00:1f.3: error: volume get failed to idle -16
[    6.772209] sof-audio-pci 0000:00:1f.3: error: volume get failed to idle -16
[    6.772436] sof-audio-pci 0000:00:1f.3: error: volume get failed to idle -16
[    9.275017] rfkill: input handler disabled
[   28.084128] sof-audio-pci 0000:00:1f.3: error: no reply expected, received 0x0
[   28.167629] sof-audio-pci 0000:00:1f.3: firmware boot complete
[   40.161181] sof-audio-pci 0000:00:1f.3: error: ipc timed out for 0x60050000 size 12
[   40.161200] sof-audio-pci 0000:00:1f.3: status: fw entered - code 00000005
[   40.161386] sof-audio-pci 0000:00:1f.3: error: unexpected fault 0x00000000 trace 0x00004000
[   40.161391] sof-audio-pci 0000:00:1f.3: error: waking up any trace sleepers
[   40.161403]  HDMI1: ASoC: trigger FE failed -110
[   40.465442] sof-audio-pci 0000:00:1f.3: error: ipc timed out for 0x60030000 size 12
[   40.465469] sof-audio-pci 0000:00:1f.3: status: fw entered - code 00000005
[   40.465765] sof-audio-pci 0000:00:1f.3: error: unexpected fault 0x00000000 trace 0x00004000
[   40.465769] sof-audio-pci 0000:00:1f.3: error: waking up any trace sleepers
[   40.769435] sof-audio-pci 0000:00:1f.3: error: ipc timed out for 0x60050000 size 12
[   40.769456] sof-audio-pci 0000:00:1f.3: status: fw entered - code 00000005
[   40.769686] sof-audio-pci 0000:00:1f.3: error: unexpected fault 0x00000000 trace 0x00004000
[   40.769691] sof-audio-pci 0000:00:1f.3: error: waking up any trace sleepers
[   40.769708]  HDA Analog: ASoC: trigger FE failed -110
[   41.073325] sof-audio-pci 0000:00:1f.3: error: ipc timed out for 0x60030000 size 12
[   41.073344] sof-audio-pci 0000:00:1f.3: status: fw entered - code 00000005
[   41.073440] sof-audio-pci 0000:00:1f.3: error: unexpected fault 0x00000000 trace 0x00004000
[   41.073444] sof-audio-pci 0000:00:1f.3: error: waking up any trace sleepers
    1. ipc timeoud when start speaker-test: speaker-test -Dhw:0,0 -r48000 -f1000 -c2 -t wav -l 10
      no error sof logger info
      speaker-test-logger.log
      speaker-test-dmesg.log
    [    5.520215] sof-audio-pci 0000:00:1f.3: firmware boot complete
[    6.943460] ax88179_178a 1-3:1.0 enx000ec6a1e569: ax88179 - Link status is: 1
[    6.951870] IPv6: ADDRCONF(NETDEV_CHANGE): enx000ec6a1e569: link becomes ready
[    7.105157] sof-audio-pci 0000:00:1f.3: error: volume get failed to idle -16
[    7.105439] sof-audio-pci 0000:00:1f.3: error: volume get failed to idle -16
[    7.105705] sof-audio-pci 0000:00:1f.3: error: volume get failed to idle -16
[    7.105951] sof-audio-pci 0000:00:1f.3: error: volume get failed to idle -16
[    7.106161] sof-audio-pci 0000:00:1f.3: error: volume get failed to idle -16
[    7.106372] sof-audio-pci 0000:00:1f.3: error: volume get failed to idle -16
[    7.106651] sof-audio-pci 0000:00:1f.3: error: volume get failed to idle -16
[    7.106914] sof-audio-pci 0000:00:1f.3: error: volume get failed to idle -16
[    7.107132] sof-audio-pci 0000:00:1f.3: error: volume get failed to idle -16
[   10.657116] rfkill: input handler disabled
[   28.427115] sof-audio-pci 0000:00:1f.3: error: no reply expected, received 0x0
[   28.510675] sof-audio-pci 0000:00:1f.3: firmware boot complete
[   56.479136] sof-audio-pci 0000:00:1f.3: error: no reply expected, received 0x0
[   56.569053] sof-audio-pci 0000:00:1f.3: firmware boot complete
[   74.732600] sof-audio-pci 0000:00:1f.3: error: no reply expected, received 0x0
[   74.816129] sof-audio-pci 0000:00:1f.3: firmware boot complete
[  101.152722] sof-audio-pci 0000:00:1f.3: error: no reply expected, received 0x0
[  101.241449] sof-audio-pci 0000:00:1f.3: firmware boot complete
[  116.811661] sof-audio-pci 0000:00:1f.3: error: no reply expected, received 0x0
[  116.900530] sof-audio-pci 0000:00:1f.3: firmware boot complete
[  130.855909] sof-audio-pci 0000:00:1f.3: error: ipc timed out for 0x60050000 size 12
[  130.855935] sof-audio-pci 0000:00:1f.3: status: fw entered - code 00000005
[  130.856067] sof-audio-pci 0000:00:1f.3: error: unexpected fault 0x00000000 trace 0x00004000
[  130.856073] sof-audio-pci 0000:00:1f.3: error: waking up any trace sleepers
[  130.856083]  HDMI1: ASoC: trigger FE failed -110
[  130.856423] sof-audio-pci 0000:00:1f.3: error: no reply expected, received 0x0
[  300.348250] sof-audio-pci 0000:00:1f.3: error: no reply expected, received 0x0
[  300.437079] sof-audio-pci 0000:00:1f.3: firmware boot complete
[  320.283306] sof-audio-pci 0000:00:1f.3: error: no reply expected, received 0x0
[  320.372488] sof-audio-pci 0000:00:1f.3: firmware boot complete
[  348.519904] sof-audio-pci 0000:00:1f.3: error: ipc timed out for 0x40010000 size 76
[  348.520200] sof-audio-pci 0000:00:1f.3: error: unexpected fault 0xffffffff trace 0xffffffff
[  348.520208] sof-audio-pci 0000:00:1f.3: error: ctx_save ipc error during suspend -110
[  348.520226] sof-audio-pci 0000:00:1f.3: can't suspend (snd_sof_runtime_suspend [snd_sof] returned -110)
[  412.555923] sof-audio-pci 0000:00:1f.3: error: pcm open failed to resume -22
[  412.555935] sof-audio-pci 0000:00:1f.3: ASoC: can't open component 0000:00:1f.3: -22
[  412.555942]  HDA Analog: ASoC: failed to start FE -22
[  480.881942] sof-audio-pci 0000:00:1f.3: error: pcm open failed to resume -22
[  480.881953] sof-audio-pci 0000:00:1f.3: ASoC: can't open component 0000:00:1f.3: -22
[  480.881961]  HDA Analog: ASoC: failed to start FE -22
[  549.219708] sof-audio-pci 0000:00:1f.3: error: pcm open failed to resume -22
[  549.219720] sof-audio-pci 0000:00:1f.3: ASoC: can't open component 0000:00:1f.3: -22
[  549.219728]  HDA Analog: ASoC: failed to start FE -22
    Kernel repo https://github.com/bardliao/linux/tree/sof-dev-rebase-reduce-v4
       
    Firmware repo https://github.com/thesofproject/sof/commits/master
      be1331a [thesofproject/sof: master]
       
    Topology: https://github.com/thesofproject/sof/commits/master
      file: tools/topology/sof-hda-generic.m4, sof-hda-generic-2ch.tplg

  18. ClarexZhou commented on Apr 29, 2019

    @ClarexZhou
    ClarexZhou
    on Apr 29, 2019

    Try reboot 100 times on CML laptop. Only twice ipc timeout.
    dmesg_failed_56.log
    logger_failed_56.log
    logger-t_failed_56.log

    [    2.467997] iwlwifi 0000:00:14.3: BIOS contains WGDS but no WRDS
[    3.264407] HDMI HDA Codec ehdaudio0D2: hdac_hdmi_present_sense: disconnect for pin:port 5:0
[    3.280020] HDMI HDA Codec ehdaudio0D2: hdac_hdmi_present_sense: disconnect for pin:port 6:0
[    4.887228] HDMI HDA Codec ehdaudio0D2: hdac_hdmi_present_sense: disconnect for pin:port 5:0
[    4.902907] HDMI HDA Codec ehdaudio0D2: hdac_hdmi_present_sense: disconnect for pin:port 6:0
[    5.099145] sof-audio-pci 0000:00:1f.3: error: no reply expected, received 0x0
[    5.188759] sof-audio-pci 0000:00:1f.3: firmware boot complete
[    5.761912] sof-audio-pci 0000:00:1f.3: error: volume get failed to idle -16
[    5.762197] sof-audio-pci 0000:00:1f.3: error: volume get failed to idle -16
[    5.762422] sof-audio-pci 0000:00:1f.3: error: volume get failed to idle -16
[    5.762711] sof-audio-pci 0000:00:1f.3: error: volume get failed to idle -16
[    5.763008] sof-audio-pci 0000:00:1f.3: error: volume get failed to idle -16
[    5.763254] sof-audio-pci 0000:00:1f.3: error: volume get failed to idle -16
[    5.763490] sof-audio-pci 0000:00:1f.3: error: volume get failed to idle -16
[    5.763810] sof-audio-pci 0000:00:1f.3: error: volume get failed to idle -16
[    5.764111] sof-audio-pci 0000:00:1f.3: error: volume get failed to idle -16
[    7.855730] sof-audio-pci 0000:00:1f.3: error: ipc timed out for 0x60030000 size 12
[    7.855749] sof-audio-pci 0000:00:1f.3: status: fw entered - code 00000005
[    7.855978] sof-audio-pci 0000:00:1f.3: error: unexpected fault 0x00000000 trace 0x00004000
[    7.855982] sof-audio-pci 0000:00:1f.3: error: waking up any trace sleepers
[    8.078423] usb 1-6: new high-speed USB device number 5 using xhci_hcd
[    8.227325] usb 1-6: New USB device found, idVendor=0bda, idProduct=5538, bcdDevice=88.07
[    8.227326] usb 1-6: New USB device strings: Mfr=3, Product=1, SerialNumber=2
[    8.227327] usb 1-6: Product: Integrated_Webcam_HD
[    8.227328] usb 1-6: Manufacturer: CKFHH66O4634000251A0
[    8.227328] usb 1-6: SerialNumber: 200901010001
[    8.343423] usb 1-10: new full-speed USB device number 6 using xhci_hcd
[    8.471350] usb 1-10: New USB device found, idVendor=8087, idProduct=0aaa, bcdDevice= 0.02
[    8.471351] usb 1-10: New USB device strings: Mfr=0, Product=0, SerialNumber=0
[    8.592633] rfkill: input handler disabled
[    8.813054] ax88179_178a 1-3:1.0 eth0: register 'ax88179_178a' at usb-0000:00:14.0-3, ASIX AX88179 USB 3.0 Gigabit Ethernet, 00:0e:c6:a1:e5:69
[    8.813099] usbcore: registered new interface driver ax88179_178a
[    8.816923] ax88179_178a 1-3:1.0 enx000ec6a1e569: renamed from eth0
[    9.160236] systemd-udevd (1676) used greatest stack depth: 11632 bytes left
[   12.247791] ax88179_178a 1-3:1.0 enx000ec6a1e569: ax88179 - Link status is: 1
[   12.255779] IPv6: ADDRCONF(NETDEV_CHANGE): enx000ec6a1e569: link becomes ready
[   13.175424] sof-audio-pci 0000:00:1f.3: error: ipc timed out for 0x60030000 size 12
[   13.175432] sof-audio-pci 0000:00:1f.3: status: fw entered - code 00000005
[   13.175649] sof-audio-pci 0000:00:1f.3: error: unexpected fault 0x00000000 trace 0x00004000
[   13.175651] sof-audio-pci 0000:00:1f.3: error: waking up any trace sleepers
[   13.479445] sof-audio-pci 0000:00:1f.3: error: ipc timed out for 0x60050000 size 12
[   13.479457] sof-audio-pci 0000:00:1f.3: status: fw entered - code 00000005
[   13.479681] sof-audio-pci 0000:00:1f.3: error: unexpected fault 0x00000000 trace 0x00004000
[   13.479682] sof-audio-pci 0000:00:1f.3: error: waking up any trace sleepers
[   13.479685]  HDA Analog: ASoC: trigger FE failed -110
[   13.783486] sof-audio-pci 0000:00:1f.3: error: ipc timed out for 0x60030000 size 12
[   13.783499] sof-audio-pci 0000:00:1f.3: status: fw entered - code 00000005
[   13.783746] sof-audio-pci 0000:00:1f.3: error: unexpected fault 0x00000000 trace 0x00004000
[   13.783748] sof-audio-pci 0000:00:1f.3: error: waking up any trace sleepers
[   16.183867] sof-audio-pci 0000:00:1f.3: error: ipc timed out for 0x40010000 size 76
[   16.183884] sof-audio-pci 0000:00:1f.3: status: fw entered - code 00000005
[   16.184153] sof-audio-pci 0000:00:1f.3: error: unexpected fault 0x00000000 trace 0x00004000
[   16.184154] sof-audio-pci 0000:00:1f.3: error: ctx_save ipc error during suspend -110
[   16.184159] sof-audio-pci 0000:00:1f.3: can't suspend (snd_sof_runtime_suspend [snd_sof] returned -110)

    failed sof-logger:

        0      1         PIPE 1.5      10102700.260417         6.770833 src/audio/pipeline.c:844 	pipeline_xrun_recover()
    0      1          DMA          10104145.000000      1444.739624 intel/cavs/hda-dma.c:279 	hda-dmac: 5 wait for buffer full timeout
    0      1         HOST          10104151.406250         6.406250     src/audio/host.c:792 	host_copy() error: dma_copy() failed, ret = 4294967234
    0      1         PIPE          10104157.656250         6.250000 src/audio/pipeline.c:736 	pipeline_copy() error: ret = -62, start->comp.id = 4, dir = 1
    0      1         PIPE 1.5      10104164.114583         6.458333 src/audio/pipeline.c:844 	pipeline_xrun_recover()
    0      1         COMP          10104177.291667        13.177083 rc/audio/component.c:204 	comp_set_state() error: wrong state = 5, COMP_TRIGGER_PREPARE
    0      1         PIPE          10104183.125000         5.833333 src/audio/pipeline.c:365 	pipeline_prepare() error: ret = -22,dev->comp.id = 0
    0      1         PIPE 1.5      10104189.375000         6.250000 src/audio/pipeline.c:851 	pipeline_xrun_recover() error: pipeline_prepare() failed, ret = -22
    0      1         PIPE 1.5      10104195.104167         5.729167 src/audio/pipeline.c:920 	pipeline_task(): xrun recover failed! pipeline will be stopped!

    dmesg_failed_53.log
    logger-t_failed_53.log

    [    3.380501] ax88179_178a 1-3:1.0 enx000ec6a1e569: renamed from eth0
[    4.438312] systemd-udevd (1676) used greatest stack depth: 11912 bytes left
[    4.910529] HDMI HDA Codec ehdaudio0D2: hdac_hdmi_present_sense: disconnect for pin:port 5:0
[    4.919387] HDMI HDA Codec ehdaudio0D2: hdac_hdmi_present_sense: disconnect for pin:port 6:0
[    5.127570] sof-audio-pci 0000:00:1f.3: error: no reply expected, received 0x0
[    5.216885] sof-audio-pci 0000:00:1f.3: firmware boot complete
[    6.801072] sof-audio-pci 0000:00:1f.3: error: volume get failed to idle -16
[    6.801378] sof-audio-pci 0000:00:1f.3: error: volume get failed to idle -16
[    6.801738] sof-audio-pci 0000:00:1f.3: error: volume get failed to idle -16
[    6.802044] sof-audio-pci 0000:00:1f.3: error: volume get failed to idle -16
[    6.802339] sof-audio-pci 0000:00:1f.3: error: volume get failed to idle -16
[    6.802559] sof-audio-pci 0000:00:1f.3: error: volume get failed to idle -16
[    6.802915] sof-audio-pci 0000:00:1f.3: error: volume get failed to idle -16
[    6.803155] sof-audio-pci 0000:00:1f.3: error: volume get failed to idle -16
[    6.803378] sof-audio-pci 0000:00:1f.3: error: volume get failed to idle -16
[    6.839565] ax88179_178a 1-3:1.0 enx000ec6a1e569: ax88179 - Link status is: 1
[    6.848459] IPv6: ADDRCONF(NETDEV_CHANGE): enx000ec6a1e569: link becomes ready
[    9.358939] rfkill: input handler disabled
[   33.431959] sof-audio-pci 0000:00:1f.3: error: ipc timed out for 0x40010000 size 76
[   33.432263] sof-audio-pci 0000:00:1f.3: error: unexpected fault 0xffffffff trace 0xffffffff
[   33.432269] sof-audio-pci 0000:00:1f.3: error: ctx_save ipc error during suspend -110
[   33.432283] sof-audio-pci 0000:00:1f.3: can't suspend (snd_sof_runtime_suspend [snd_sof] returned -110)
    Kernel repo https://github.com/bardliao/linux/tree/sof-dev-rebase-reduce-v3
       
    Firmware repo https://github.com/thesofproject/sof/commits/master
      be1331a [thesofproject/sof: master]
       
    Topology: https://github.com/thesofproject/sof/commits/master
      file: tools/topology/sof-hda-generic.m4, sof-hda-generic-2ch.tplg

  19. keyonjie commented on Apr 29, 2019

    @keyonjie
    keyonjie
    on Apr 29, 2019
    Contributor

    it's tricky that we still seeing this error "hda-dmac: 5 wait for buffer full timeout" in sof-logger.
    @tlauda can anybody from FW team help on this?

  20. emilchudzik commented on Apr 29, 2019

    @emilchudzik
    emilchudzik
    on Apr 29, 2019
    Contributor

    My suggestion is to create uniqe issue for each IPC timeout, with detailed test flow/step to reproduce/detailed description of environment.
    If it will be generic issue it will be hard to debug and reproduce and it will become a sack for every IPC timeout.

    @mengdonglin please verify if issue still exists and close if doesn't.

  21. lgirdwood
    added this to the 1.3 milestone on Apr 29, 2019

  22. keyonjie commented on Apr 30, 2019

    @keyonjie
    keyonjie
    on Apr 30, 2019
    Contributor

    we might need to figure out thesofproject/linux#724 for debugging this kind of issue with linux driver.
    @wenqingfu Michael, can anyone helps on that during PRC team having 4 days' holiday here.

  23. mengdonglin
    changed the title [-][CML] IPC time out issues[/-] [+][CML] Random IPC time out issues[/+] on Apr 30, 2019

  24. ClarexZhou commented on May 8, 2019

    @ClarexZhou
    ClarexZhou
    on May 8, 2019

    0x40010000: GLB_PM_MSG: CTX_SAVE IPC timeout occurred once after stop aplay when Pulseaudio is off. UI freeze then timetout.

    [ 1338.699643] sof-audio-pci 0000:00:1f.3: ipc tx: 0x60050000: GLB_STREAM_MSG: TRIG_STOP
[ 1338.699828] sof-audio-pci 0000:00:1f.3: ipc tx succeeded: 0x60050000: GLB_STREAM_MSG: TRIG_STOP
[ 1338.699840] sof-audio-pci 0000:00:1f.3: In hda_link_pcm_trigger cmd=0
[ 1338.699980] sof-audio-pci 0000:00:1f.3: pcm: free stream 0 dir 0
[ 1338.699991] sof-audio-pci 0000:00:1f.3: ipc tx: 0x60030000: GLB_STREAM_MSG: PCM_FREE
[ 1338.700105] sof-audio-pci 0000:00:1f.3: ipc tx succeeded: 0x60030000: GLB_STREAM_MSG: PCM_FREE
[ 1338.700216] sof-audio-pci 0000:00:1f.3: pcm: close stream 0 dir 0
[ 1339.368582] sof-audio-pci 0000:00:1f.3: ipc rx: 0x90020000: GLB_TRACE_MSG
[ 1339.368615] sof-audio-pci 0000:00:1f.3: ipc rx done: 0x90020000: GLB_TRACE_MSG
[ 1342.055963] sof-audio-pci 0000:00:1f.3: ipc tx: 0x40010000: GLB_PM_MSG: CTX_SAVE
[ 1342.360546] sof-audio-pci 0000:00:1f.3: error: ipc timed out for 0x40010000 size 76
[ 1342.360576] sof-audio-pci 0000:00:1f.3: unknown ROM status value ffffffff
[ 1342.360855] sof-audio-pci 0000:00:1f.3: error: unexpected fault 0xffffffff trace 0xffffffff
[ 1342.360863] sof-audio-pci 0000:00:1f.3: error: ctx_save ipc error during suspend -110
[ 1342.360881] sof-audio-pci 0000:00:1f.3: can't suspend (snd_sof_runtime_suspend [snd_sof] returned -110)
[ 1382.242672] sof-audio-pci 0000:00:1f.3: pcm: open stream 0 dir 0
[ 1382.242678] sof-audio-pci 0000:00:1f.3: error: pcm open failed to resume -22
[ 1382.242687] sof-audio-pci 0000:00:1f.3: ASoC: can't open component 0000:00:1f.3: -22
[ 1382.242693]  HDA Analog: ASoC: failed to start FE -22
[ 1450.570690] sof-audio-pci 0000:00:1f.3: pcm: open stream 0 dir 0
[ 1450.570697] sof-audio-pci 0000:00:1f.3: error: pcm open failed to resume -22
[ 1450.570707] sof-audio-pci 0000:00:1f.3: ASoC: can't open component 0000:00:1f.3: -22
[ 1450.570715]  HDA Analog: ASoC: failed to start FE -22

    Environment
    Rander UCM https://github.com/RanderWang/intel-UCM  
    Kernel repo：c99938c https://github.com/thesofproject/linux/tree/release/sof-v5.0
    Firmware repo: 47fcac2 https://github.com/thesofproject/sof/commits/master |  
    Topology: https://github.com/thesofproject/sof/commits/master . Same as above SOF repo
    file: tools/topology/sof-hda-generic.m4, sof-hda-generic-2ch.tplg

    ipctimeout_Poff_dmesg.log
    ipctimeout_Poff_logger.log

  25. ClarexZhou commented on May 8, 2019

    @ClarexZhou
    ClarexZhou
    on May 8, 2019

    0x30030000: GLB_TPLG_MSG: COMP_CONNECT ipc timed out occurred one time after plug headset.
    No error sof logger
    Dmesg:

    [ 1583.936726] sof-audio-pci 0000:00:1f.3: ipc tx: 0x30100000: GLB_TPLG_MSG: PIPE_NEW
[ 1583.936861] sof-audio-pci 0000:00:1f.3: ipc tx succeeded: 0x30100000: GLB_TPLG_MSG: PIPE_NEW
[ 1583.936866] sof-audio-pci 0000:00:1f.3: DSP core(s) enabled? 1 : core_mask 1
[ 1583.936870] sof-audio-pci 0000:00:1f.3: ipc tx: 0x40070000: GLB_PM_MSG: CORE_ENABLE
[ 1583.936946] sof-audio-pci 0000:00:1f.3: ipc tx succeeded: 0x40070000: GLB_PM_MSG: CORE_ENABLE
[ 1583.936951] sof-audio-pci 0000:00:1f.3: ipc tx: 0x30030000: GLB_TPLG_MSG: COMP_CONNECT
[ 1583.937070] sof-audio-pci 0000:00:1f.3: ipc tx succeeded: 0x30030000: GLB_TPLG_MSG: COMP_CONNECT
[ 1583.937074] sof-audio-pci 0000:00:1f.3: ipc tx: 0x30030000: GLB_TPLG_MSG: COMP_CONNECT
[ 1583.937165] sof-audio-pci 0000:00:1f.3: ipc tx succeeded: 0x30030000: GLB_TPLG_MSG: COMP_CONNECT
[ 1583.937170] sof-audio-pci 0000:00:1f.3: ipc tx: 0x30030000: GLB_TPLG_MSG: COMP_CONNECT
[ 1583.937274] sof-audio-pci 0000:00:1f.3: ipc tx succeeded: 0x30030000: GLB_TPLG_MSG: COMP_CONNECT
[ 1583.937278] sof-audio-pci 0000:00:1f.3: ipc tx: 0x30030000: GLB_TPLG_MSG: COMP_CONNECT
[ 1584.241624] sof-audio-pci 0000:00:1f.3: error: ipc timed out for 0x30030000 size 16
[ 1584.241638] sof-audio-pci 0000:00:1f.3: status: fw entered - code 00000005
[ 1584.241867] sof-audio-pci 0000:00:1f.3: error: unexpected fault 0x00000000 trace 0x00004000
[ 1584.241872] sof-audio-pci 0000:00:1f.3: error: waking up any trace sleepers
[ 1584.241878] sof-audio-pci 0000:00:1f.3: error: failed to load route sink  control none source 
[ 1584.241881] sof-audio-pci 0000:00:1f.3: error: failed to restore pipeline after resume -110
[ 1584.241900] HDMI HDA Codec ehdaudio0D2: No connections found for pin:port 5:0
[ 1584.241909] sof-audio-pci 0000:00:1f.3: pcm: open stream 3 dir 0
[ 1584.241911] sof-audio-pci 0000:00:1f.3: error: pcm open failed to resume -22
[ 1584.241915] sof-audio-pci 0000:00:1f.3: ASoC: can't open component 0000:00:1f.3: -22
[ 1584.241919]  HDMI1: ASoC: failed to start FE -22
[ 1584.438605] sof-audio-pci 0000:00:1f.3: ipc rx: 0x90020000: GLB_TRACE_MSG
[ 1584.438637] sof-audio-pci 0000:00:1f.3: ipc rx done: 0x90020000: GLB_TRACE_MSG
[ 1588.739566] HDMI HDA Codec ehdaudio0D2: No connections found for pin:port 5:0
[ 1588.739570] sof-audio-pci 0000:00:1f.3: pcm: open stream 3 dir 0
[ 1588.739571] sof-audio-pci 0000:00:1f.3: error: pcm open failed to resume -22
[ 1588.739574] sof-audio-pci 0000:00:1f.3: ASoC: can't open component 0000:00:1f.3: -22
[ 1588.739575]  HDMI1: ASoC: failed to start FE -22

    Environment
    Rander UCM https://github.com/RanderWang/intel-UCM  
    Kernel repo：c99938c https://github.com/thesofproject/linux/tree/release/sof-v5.0
    Firmware repo: 05d4e19 https://github.com/thesofproject/sof/commits/master |  
    Topology: https://github.com/thesofproject/sof/commits/master . Same as above SOF repo
    file: tools/topology/sof-hda-generic.m4, sof-hda-generic-2ch.tplg

    ipcTimeOutAfterPlug.log
    ipcTimeOutAfterPlugLogger.log

  26. wenqingfu commented on May 8, 2019

    @wenqingfu
    wenqingfu
    on May 8, 2019

    @ClarexZhou I will close this issue. Please report the last two findings as stand alone issue to track. Thanks!

  27. wenqingfu
    closed this as completedon May 8, 2019

  28. ClarexZhou commented on May 9, 2019

    @ClarexZhou
    ClarexZhou
    on May 9, 2019

    @wenqingfu Report new bugs as below:

    1. [BUG][CML] ipc timed out for '0x30030000: GLB_TPLG_MSG: COMP_CONNECT' [BUG][CML] ipc timed out for '0x30030000: GLB_TPLG_MSG: COMP_CONNECT'  #1395

    2. [BUG][CML]IPC timed out for '0x60040000: GLB_STREAM_MSG: TRIG_START' [BUG][CML] IPC timed out for '0x60040000: GLB_STREAM_MSG: TRIG_START due to pipeline copy errors' #1396

    3. [Bug][CML] ipc timed out for '0x40010000: GLB_PM_MSG: CTX_SAVE' 4. [Bug][CML] ipc timed out for '0x40010000: GLB_PM_MSG: CTX_SAVE' linux#919

    4. [BUG][CML] ipc timed out for 0x30010000 size 84 [BUG][CML] ipc timed out for 0x30010000 size 84 linux#924
      (reported by Canonical)

  29. mengdonglin commented on May 9, 2019

    @mengdonglin
    mengdonglin
    on May 9, 2019
    Collaborator

    IPC time out observed on other platforms:
    #1342
    thesofproject/linux#808
    thesofproject/linux#876
    thesofproject/linux#873

  30. mengdonglin
    added
    IPC timeoutIPC timeout observed
    on May 9, 2019
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 platformHDAApplies to HD-Audio bus for codec connectionIPC timeoutIPC timeout observedP1Blocker bugs or important featuresbugSomething isn't working as expected

Type

No type

Projects

No projects

    Milestone

    Relationships

    None yet

    Development

    No branches or pull requests

    Issue actions