Skip to content

[BUG] IPC timeout in sof-logger-check #6042

New issue
New issue
Closed
Closed
[BUG] IPC timeout in sof-logger-check#6042
Assignees
marc-hb
Labels
P3Low-impact bugs or featuresZephyrIssues only observed with Zephyr integratedarea:SOF loggingbugSomething isn't working as expectedwon't fixThis will not be worked on atm (e.g. a bug closed for lack of user request, hardware etc)

Description

@keqiaozhang
keqiaozhang
opened on Jul 21, 2022

Describe the bug
CI detected some different failures when checking sof-logger:

  1. on ADLP_GMB_I2S_ZEPHYR:http://sof-ci.sh.intel.com/#/result/planresultdetail/14129?model=ADLP_GMB_I2S_ZEPHYR&testcase=check-sof-logger
    logger.error
error: in logger_read(), fread(..., /sys/kernel/debug/sof/trace) failed: Operation not permitted(-1)
  1. On APL_UP2_NOCODEC_ZEPHYR:http://sof-ci.sh.intel.com/#/result/planresultdetail/14124?model=APL_UP2_NOCODEC_ZEPHYR&testcase=check-sof-logger
    ** console output**
2022-07-20 16:19:15 UTC [REMOTE_INFO] Trying to get the DMA .ldc trace log with background sof-logger ...
2022-07-20 16:19:15 UTC [REMOTE_COMMAND] sudo /usr/local/bin/sof-logger  -t -f 3 -l  /etc/sof/sof-apl.ldc   >  /home/ubuntu/sof-test/logs/check-sof-logger/2022-07-20-16:19:11-29866/logger.data.txt  2>  /home/ubuntu/sof-test/logs/check-sof-logger/2022-07-20-16:19:11-29866/logger.error.txt  &
2022-07-20 16:19:17 UTC [REMOTE_ERROR] timeout /usr/local/bin/cavstool.py returned unexpected: 0
2022-07-20 16:19:17 UTC [REMOTE_ERROR] Starting func_exit_handler(), exit status=1, FUNCNAME stack:
2022-07-20 16:19:17 UTC [REMOTE_ERROR]  die()  @  /home/ubuntu/sof-test/case-lib/lib.sh
2022-07-20 16:19:17 UTC [REMOTE_ERROR]  run_loggers()  @  /home/ubuntu/sof-test/test-case/check-sof-logger.sh:114
2022-07-20 16:19:17 UTC [REMOTE_ERROR]  main()  @  /home/ubuntu/sof-test/test-case/check-sof-logger.sh:196
2022-07-20 16:19:17 UTC [REMOTE_ERROR]  main()  @  /home/ubuntu/sof-test/test-case/check-sof-logger.sh:263
  1. sof-logger check caused IPC timed out for 0x30020000 (msg/reply size: 12/12):
    https://sof-ci.sh.intel.com/#/result/planresultdetail/14104?model=ADLP_GMB_I2S_ZEPHYR&testcase=check-sof-logger
    ** dmesg**
[   94.492313] kernel: snd_sof:ipc3_log_header: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx: 0x30020000: GLB_TPLG_MSG: COMP_FREE
[   95.001159] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx timed out for 0x30020000 (msg/reply size: 12/12)
[   95.001164] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: preventing DSP entering D3 state to preserve context
[   95.001166] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ------------[ IPC dump start ]------------
[   95.001180] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: hda irq intsts 0x00000000 intlctl 0xc0000001 rirb 00
[   95.001181] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: dsp irq ppsts 0x00000000 adspis 0x00000000
[   95.001187] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: error: host status 0x00000000 dsp status 0x00000000 mask 0x00000003
[   95.001188] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ------------[ IPC dump end ]------------
[   95.001189] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ------------[ DSP dump start ]------------
[   95.001190] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: IPC timeout
[   95.001191] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: fw_state: SOF_FW_BOOT_COMPLETE (6)
[   95.001207] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: 0x00000005: module: ROM, state: FW_ENTERED, running
[   95.001460] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: unexpected fault 0x00000000 trace 0x00004000
[   95.001461] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ------------[ DSP dump end ]------------
[   95.001464] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: failed to free widget SSP2.IN

Activity

  1. keqiaozhang
    added
    area:SOF logging
    bugSomething isn't working as expected
    on Jul 21, 2022

  2. marc-hb commented on Jul 21, 2022

    @marc-hb
    marc-hb
    on Jul 21, 2022
    Collaborator

    Earlier there was this, I don't remember seeing it before but maybe I missed it. Hopefully unrelated.

    [   90.723153] kernel: snd_hda_codec_hdmi ehdaudio0D2: ASoC: sink widget AIF1TX overwritten
[   90.723158] kernel: snd_hda_codec_hdmi ehdaudio0D2: ASoC: source widget AIF1RX overwritten
[   90.749485] kernel: max98390 i2c-MX98390:00: Direct firmware load for dsm_param_R_Google_Gimble4ES.bin failed with error -2
[   90.749516] kernel: max98390 i2c-MX98390:00: Direct firmware load for dsm_param.bin failed with error -2
[   90.749543] kernel: max98390 i2c-MX98390:00: Direct firmware load for dsmparam.bin failed with error -2
[   90.776064] kernel: max98390 i2c-MX98390:01: Direct firmware load for dsm_param_L_Google_Gimble4ES.bin failed with error -2
[   90.776094] kernel: max98390 i2c-MX98390:01: Direct firmware load for dsm_param.bin failed with error -2
[   90.776120] kernel: max98390 i2c-MX98390:01: Direct firmware load for dsmparam.bin failed with error -2
[   90.780714] kernel: snd_sof:sof_pcm_new: sof-audio-pci-intel-tgl 0000:00:1f.3: creating new PCM DMIC16kHz

  3. marc-hb commented on Jul 21, 2022

    @marc-hb
    marc-hb
    on Jul 21, 2022
    Collaborator

    I'm afraid cavstool logging recently added by thesofproject/sof-test#929 is triggering these issues , seems to affect thesofproject/sof-test#897 too.

  4. marc-hb commented on Jul 21, 2022

    @marc-hb
    marc-hb
    on Jul 21, 2022
    Collaborator

    IPC timeout again in daily run 14165?model=ADLP_GMB_I2S_ZEPHYR&testcase=check-sof-logger

    This time APL (and everything else) was fine

  5. marc-hb
    changed the title [-][BUG] sof-logger check failure[/-] [+][BUG] IPC timeout in sof-logger-check[/+] on Jul 21, 2022
  6. keqiaozhang
    transferred this issue fromthesofproject/sof-teston Jul 25, 2022
  7. mengdonglin
    added
    ZephyrIssues only observed with Zephyr integrated
    on Jul 25, 2022
  8. marc-hb
    self-assigned this
    on Jul 25, 2022

  9. marc-hb commented on Jul 26, 2022

    @marc-hb
    marc-hb
    on Jul 26, 2022
    Collaborator

    No check-sof-logger failure in recent daily runs and the zephyr logs are there... maybe someone fixed this while fixing something else?

    • No check-sof-logger failure in daily 14218
      Start Time: 2022-07-25 21:29:47 UTC

    • No check-sof-logger failure in daily 14198
      Start Time: 2022-07-24 21:29:42 UTC
      Kernel Branch: topic/sof-dev
      Kernel Commit: 70f9e7b34a9d
      SOF Branch: main
      SOF Commit: 2845fc8cdec2
      Zephyr Commit: e81c0b07e248

    • Last failure so far was in daily 14165?model=ADLP_GMB_I2S_ZEPHYR&testcase=check-sof-logger and only on one device
      Start Time: 2022-07-21 21:29:41 UTC
      Kernel Branch: topic/sof-dev
      Kernel Commit: 0d1355b1845e
      SOF Branch: main
      SOF Commit: 104c63547f05
      Zephyr Commit: 31b9a6acc60a

  10. marc-hb commented on Jul 27, 2022

    @marc-hb
    marc-hb
    on Jul 27, 2022
    Collaborator

    Failure is back today in daily 14276?model=ADLP_GMB_I2S_ZEPHYR&testcase=check-sof-logger on just one system :-(

    Start Time: 2022-07-27 21:29:44 UTC
    Kernel Branch: topic/sof-dev
    Kernel Commit: bf69e513b171
    SOF Branch: main
    SOF Commit: e4c2872b60f6
    Zephyr Commit: d5222f318d29

  11. marc-hb commented on Jul 29, 2022

    @marc-hb
    marc-hb
    on Jul 29, 2022
    Collaborator

    I got distracted by the migration to west but I have some good leads, stay tuned.

  12. keqiaozhang commented on Aug 2, 2022

    @keqiaozhang
    keqiaozhang
    on Aug 2, 2022
    CollaboratorAuthor

    Earlier there was this, I don't remember seeing it before but maybe I missed it. Hopefully unrelated.

    [   90.723153] kernel: snd_hda_codec_hdmi ehdaudio0D2: ASoC: sink widget AIF1TX overwritten
[   90.723158] kernel: snd_hda_codec_hdmi ehdaudio0D2: ASoC: source widget AIF1RX overwritten
[   90.749485] kernel: max98390 i2c-MX98390:00: Direct firmware load for dsm_param_R_Google_Gimble4ES.bin failed with error -2
[   90.749516] kernel: max98390 i2c-MX98390:00: Direct firmware load for dsm_param.bin failed with error -2
[   90.749543] kernel: max98390 i2c-MX98390:00: Direct firmware load for dsmparam.bin failed with error -2
[   90.776064] kernel: max98390 i2c-MX98390:01: Direct firmware load for dsm_param_L_Google_Gimble4ES.bin failed with error -2
[   90.776094] kernel: max98390 i2c-MX98390:01: Direct firmware load for dsm_param.bin failed with error -2
[   90.776120] kernel: max98390 i2c-MX98390:01: Direct firmware load for dsmparam.bin failed with error -2
[   90.780714] kernel: snd_sof:sof_pcm_new: sof-audio-pci-intel-tgl 0000:00:1f.3: creating new PCM DMIC16kHz

    Above errors are unrelated to this bug. it's just looking for the firmware dsm_param.bin of the codec in /opt/google/dsm/dsmparam.bin. We just lack DSM algorithm, which will not affect the audio function.

  13. mengdonglin
    added
    P3Low-impact bugs or features
    won't fixThis will not be worked on atm (e.g. a bug closed for lack of user request, hardware etc)
    on Aug 30, 2022

  14. mengdonglin commented on Sep 6, 2022

    @mengdonglin
    mengdonglin
    on Sep 6, 2022
    Collaborator

    Won't fix cAVS tool issue. Will switch to new logging tool.

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

Metadata

Metadata

Assignees

Labels

P3Low-impact bugs or featuresZephyrIssues only observed with Zephyr integratedarea:SOF loggingbugSomething isn't working as expectedwon't fixThis will not be worked on atm (e.g. a bug closed for lack of user request, hardware etc)

Type

No type

Projects

No projects

    Milestone

    No milestone

    Relationships

    None yet

    Development

    No branches or pull requests

    Issue actions