[BUG] max98390 failed to read: 0x24FF on ADLP_GMB_I2S_ZEPHYR

keqiaozhang commented 2 years ago

Describe the bug A clear and concise description of what the bug is. What have you tried to diagnose or workaround this issue? Please also read https://thesofproject.github.io/latest/contribute/process/bug-tracking.html for further information on submitting bugs.

To Reproduce TPLG=/lib/firmware/intel/sof-tplg/sof-adl-max98390-rt5682.tplg MODEL=ADLP_GMB_I2S_ZEPHYR ~/sof-test/test-case/check-suspend-resume.sh -l 20 -u

Reproduction Rate 1/20

Impact codec driver failed to load

Environment 1) Branch name and commit hash of the 2 repositories: sof (firmware/topology) and linux (kernel driver). Kernel Branch: topic/sof-dev/ 076a5996b923 SOF Branch: main/95d6499ad6b4 *Zephyr Commit: 05ec01615712 2) Name of the topology file

Topology: sof-adl-max98390-rt5682.tplg 3) Name of the platform(s) on which the bug is observed.
Platform: ADLP Chrome I2S device

Screenshots or console output

2022-06-22 23:32:08 UTC [ERROR] Caught kernel log error
===========================>>
[  359.860161] kernel: max98390 i2c-MX98390:00: ret=-108, Failed to read: 0x24FF
[  359.864846] kernel: max98390 i2c-MX98390:01: ret=-108, Failed to read: 0x24FF
<<===========================

dmesg

[  347.484434] kernel: PM: suspend entry (s2idle)
[  347.485558] kernel: Filesystems sync: 0.001 seconds
[  347.485834] kernel: Freezing user space processes ... (elapsed 0.002 seconds) done.
[  347.488698] kernel: OOM killer disabled.
[  347.488699] kernel: Freezing remaining freezable tasks ... (elapsed 0.001 seconds) done.
[  347.489838] kernel: printk: Suspending console(s) (use no_console_suspend to debug)
[  347.611639] kernel: asix 3-8.1:1.0 enx000ec67984c8: Link is Down
[  347.946354] kernel: ACPI: EC: interrupt blocked
[  353.313877] kernel: ACPI: EC: interrupt unblocked
[  353.964616] kernel: asix 3-8.1:1.0 enx000ec67984c8: Link is Down
[  354.061611] kernel: OOM killer enabled.
[  354.061618] kernel: Restarting tasks ... done.
[  354.067686] kernel: random: crng reseeded on system resumption
[  354.106084] kernel: PM: suspend exit
[  356.036640] kernel: asix 3-8.1:1.0 enx000ec67984c8: Link is Up - 100Mbps/Full - flow control off
[  359.859747] kernel: max98390 i2c-MX98390:00: no optional property 'temperature_calib' found, default:
[  359.859750] kernel: max98390 i2c-MX98390:00: no optional property 'r0_calib' found, default:
[  359.859750] kernel: max98390 i2c-MX98390:00: max98390_i2c_probe: r0_calib: 0x0,temperature_calib: 0x0
[  359.859920] kernel: ------------[ cut here ]------------
[  359.859921] kernel: i2c i2c-0: Transfer while suspended
[  359.859932] kernel: WARNING: CPU: 2 PID: 16488 at drivers/i2c/i2c-core.h:54 __i2c_transfer+0x55c/0x5b0
[  359.859939] kernel: Modules linked in: snd_soc_max98390(+) snd_soc_max98373_i2c snd_soc_max98373_sdw snd_soc_max98373 snd_soc_max98357a snd_soc_ts3a227e snd_soc_max98090 snd_soc_rt5682_sdw snd_soc_rt5682_i2c snd_soc_rt5682 snd_soc_rt5677 snd_soc_rt5677_spi snd_soc_rt5670 snd_soc_rt5660 snd_soc_rt5651 snd_soc_rt5645 snd_soc_rt5640 snd_soc_rt1011 snd_soc_sdw_mockup snd_soc_rt715_sdca snd_soc_rt1316_sdw snd_soc_rt711_sdca regmap_sdw_mbq snd_soc_rt715 snd_soc_rt1308_sdw snd_soc_rt1308 snd_soc_rl6231 snd_soc_rt711 snd_soc_rt700 regmap_sdw soundwire_bus snd_soc_rt298 snd_soc_rt286 snd_soc_rl6347a snd_soc_wm8804_i2c snd_soc_wm8804 snd_soc_pcm512x_i2c snd_soc_pcm512x snd_soc_da7219 snd_soc_da7213 snd_soc_core snd_compress snd_pcm fuse ax88796b asix usbnet snd_seq_midi snd_seq_midi_event hid_multitouch x86_pkg_temp_thermal intel_powerclamp snd_rawmidi i915 regmap_i2c snd_seq i2c_algo_bit drm_buddy mei_me mei snd_seq_device drm_display_helper elan_i2c drm_kms_helper snd_timer cfbfillrect syscopyarea
[  359.859981] kernel:  cfbimgblt sysfillrect snd sysimgblt soundcore int3403_thermal fb_sys_fops processor_thermal_device_pci cfbcopyarea processor_thermal_device processor_thermal_rfim ttm processor_thermal_mbox int3400_thermal int340x_thermal_zone acpi_thermal_rel intel_pmc_core squashfs drm drm_panel_orientation_quirks efivarfs spi_pxa2xx_platform intel_lpss_pci xhci_pci intel_lpss idma64 xhci_hcd mfd_core i2c_hid_acpi i2c_hid [last unloaded: snd_pcm]
[  359.860004] kernel: CPU: 2 PID: 16488 Comm: modprobe Tainted: G     U  W         5.19.0-rc2-daily-default-20220622-0-g076a5996b923 #dev
[  359.860006] kernel: Hardware name: Google Gimble4ES/Gimble4ES, BIOS  12/21/2021
[  359.860007] kernel: RIP: 0010:__i2c_transfer+0x55c/0x5b0
[  359.860009] kernel: Code: 4d 85 e4 75 07 4c 8b a7 50 01 00 00 48 8d bd 50 01 00 00 e8 36 a7 e7 ff 4c 89 e2 48 c7 c7 f0 f5 2c a4 48 89 c6 e8 e7 6b 3d 00 <0f> 0b 41 bc 94 ff ff ff e9 22 fc ff ff 48 c7 c2 78 f1 2c a4 4c 89
[  359.860011] kernel: RSP: 0018:ffffb4848105f9f8 EFLAGS: 00010282
[  359.860013] kernel: RAX: 0000000000000000 RBX: ffff9f02855cd800 RCX: 0000000000000000
[  359.860014] kernel: RDX: 0000000000000001 RSI: ffffffffa421a6d9 RDI: 00000000ffffffff
[  359.860015] kernel: RBP: ffff9f0281309128 R08: ffffffffa44839e0 R09: 0000000000000005
[  359.860016] kernel: R10: ffffffffa54ae555 R11: 00000000a54ae533 R12: ffff9f0280ac3280
[  359.860017] kernel: R13: 0000000000000002 R14: 0000000000000001 R15: 0000000000000000
[  359.860018] kernel: FS:  00007fd5abe8c740(0000) GS:ffff9f05ee800000(0000) knlGS:0000000000000000
[  359.860020] kernel: CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[  359.860021] kernel: CR2: 00007ffd358a9ff8 CR3: 0000000106590006 CR4: 0000000000770ee0
[  359.860022] kernel: DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
[  359.860023] kernel: DR3: 0000000000000000 DR6: 00000000ffff07f0 DR7: 0000000000000400
[  359.860024] kernel: PKRU: 55555554
[  359.860025] kernel: Call Trace:
[  359.860027] kernel:  
[  359.860030] kernel:  i2c_transfer+0x7f/0x100
[  359.860033] kernel:  regmap_i2c_read+0x69/0xa0 [regmap_i2c]
[  359.860039] kernel:  _regmap_raw_read+0x120/0x2b0
[  359.860043] kernel:  _regmap_bus_read+0x41/0x70
[  359.860046] kernel:  _regmap_read+0x5c/0x160
[  359.860049] kernel:  regmap_read+0x3e/0x70
[  359.860051] kernel:  max98390_i2c_probe.cold+0x179/0x1d0 [snd_soc_max98390]
[  359.860056] kernel:  i2c_device_probe+0x132/0x350
[  359.860059] kernel:  really_probe+0x17d/0x360
[  359.860064] kernel:  __driver_probe_device+0xfe/0x180
[  359.860067] kernel:  driver_probe_device+0x1e/0xa0
[  359.860070] kernel:  __driver_attach+0x9e/0x180
[  359.860074] kernel:  ? __device_attach_driver+0xe0/0xe0
[  359.860076] kernel:  ? __device_attach_driver+0xe0/0xe0
[  359.860079] kernel:  bus_for_each_dev+0x78/0xc0
[  359.860084] kernel:  bus_add_driver+0x15b/0x200
[  359.860088] kernel:  driver_register+0x6c/0xc0
[  359.860091] kernel:  i2c_register_driver+0x3e/0x90
[  359.860093] kernel:  ? 0xffffffffc05f7000
[  359.860095] kernel:  do_one_initcall+0x6f/0x270
[  359.860100] kernel:  ? kmem_cache_alloc_trace+0x4f/0x210
[  359.860105] kernel:  do_init_module+0x4c/0x1f0
[  359.860110] kernel:  load_module+0x1b7c/0x1df0
[  359.860112] kernel:  ? __kernel_read+0x13d/0x2c0
[  359.860124] kernel:  ? __do_sys_finit_module+0xb4/0x120
[  359.860127] kernel:  __do_sys_finit_module+0xb4/0x120
[  359.860135] kernel:  do_syscall_64+0x38/0x90
[  359.860140] kernel:  entry_SYSCALL_64_after_hwframe+0x46/0xb0
[  359.860143] kernel: RIP: 0033:0x7fd5abfd273d
[  359.860145] kernel: Code: 00 c3 66 2e 0f 1f 84 00 00 00 00 00 90 f3 0f 1e fa 48 89 f8 48 89 f7 48 89 d6 48 89 ca 4d 89 c2 4d 89 c8 4c 8b 4c 24 08 0f 05 <48> 3d 01 f0 ff ff 73 01 c3 48 8b 0d 23 37 0d 00 f7 d8 64 89 01 48
[  359.860146] kernel: RSP: 002b:00007ffd358ad158 EFLAGS: 00000246 ORIG_RAX: 0000000000000139
[  359.860148] kernel: RAX: ffffffffffffffda RBX: 00005597f11380a0 RCX: 00007fd5abfd273d
[  359.860149] kernel: RDX: 0000000000000000 RSI: 00005597ef5a9358 RDI: 0000000000000003
[  359.860150] kernel: RBP: 0000000000040000 R08: 0000000000000000 R09: 0000000000000000
[  359.860151] kernel: R10: 0000000000000003 R11: 0000000000000246 R12: 00005597ef5a9358
[  359.860152] kernel: R13: 0000000000000000 R14: 00005597f11382d0 R15: 00005597f11380a0
[  359.860158] kernel:  
[  359.860158] kernel: ---[ end trace 0000000000000000 ]---
[  359.860161] kernel: max98390 i2c-MX98390:00: ret=-108, Failed to read: 0x24FF
[  359.864720] kernel: max98390: probe of i2c-MX98390:00 failed with error -108
[  359.864794] kernel: max98390 i2c-MX98390:01: no optional property 'temperature_calib' found, default:
[  359.864795] kernel: max98390 i2c-MX98390:01: no optional property 'r0_calib' found, default:
[  359.864796] kernel: max98390 i2c-MX98390:01: max98390_i2c_probe: r0_calib: 0x0,temperature_calib: 0x0
[  359.864846] kernel: max98390 i2c-MX98390:01: ret=-108, Failed to read: 0x24FF
[  359.868768] kernel: max98390: probe of i2c-MX98390:01 failed with error -108
[  360.012912] kernel: snd_sof_pci:sof_pci_probe: sof-audio-pci-intel-tgl 0000:00:1f.3: PCI DSP detected
[  360.013341] kernel: snd_sof_pci:sof_pci_probe: sof-audio-pci-intel-tgl 0000:00:1f.3: Platform uses community key, changed fw path to intel/sof/community
[  360.013441] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: DSP detected with PCI class/subclass/prog-if 0x040100
[  360.013684] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: bound 0000:00:02.0 (ops i915_audio_component_bind_ops [i915])
[  360.019453] kernel: snd_sof_intel_hda_common:hda_dsp_ctrl_get_caps: sof-audio-pci-intel-tgl 0000:00:1f.3: checking for capabilities at offset 0xc00
[  360.019459] kernel: snd_sof_intel_hda_common:hda_dsp_ctrl_get_caps: sof-audio-pci-intel-tgl 0000:00:1f.3: found ML capability at 0xc00
[  360.019460] kernel: snd_sof_intel_hda_common:hda_dsp_ctrl_get_caps: sof-audio-pci-intel-tgl 0000:00:1f.3: checking for capabilities at offset 0x800
[  360.019466] kernel: snd_sof_intel_hda_common:hda_dsp_ctrl_get_caps: sof-audio-pci-intel-tgl 0000:00:1f.3: found DSP capability at 0x800
[  360.019469] kernel: snd_sof_intel_hda_common:hda_dsp_ctrl_get_caps: sof-audio-pci-intel-tgl 0000:00:1f.3: checking for capabilities at offset 0x500
[  360.019472] kernel: snd_sof_intel_hda_common:hda_dsp_ctrl_get_caps: sof-audio-pci-intel-tgl 0000:00:1f.3: found GTS capability at 0x500
[  360.019473] kernel: snd_sof_intel_hda_common:hda_dsp_ctrl_get_caps: sof-audio-pci-intel-tgl 0000:00:1f.3: checking for capabilities at offset 0x1f00
[  360.019477] kernel: snd_sof_intel_hda_common:hda_dsp_ctrl_get_caps: sof-audio-pci-intel-tgl 0000:00:1f.3: found DRSM capability at 0x1f00
[  360.019478] kernel: snd_sof_intel_hda_common:hda_dsp_ctrl_get_caps: sof-audio-pci-intel-tgl 0000:00:1f.3: checking for capabilities at offset 0x700
[  360.019483] kernel: snd_sof_intel_hda_common:hda_dsp_ctrl_get_caps: sof-audio-pci-intel-tgl 0000:00:1f.3: found SPIB capability at 0x700
[  360.019511] kernel: snd_sof_intel_hda_common:hda_dsp_stream_init: sof-audio-pci-intel-tgl 0000:00:1f.3: hda global caps = 0x1009701
[  360.019512] kernel: snd_sof_intel_hda_common:hda_dsp_stream_init: sof-audio-pci-intel-tgl 0000:00:1f.3: detected 9 playback and 7 capture streams
[  360.019791] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: use msi interrupt mode
[  360.019793] kernel: snd_sof_intel_hda_common:hda_dsp_probe: sof-audio-pci-intel-tgl 0000:00:1f.3: using IPC IRQ 141
[  360.020045] kernel: snd_sof:snd_sof_pci_update_bits_unlocked: sof-audio-pci-intel-tgl 0000:00:1f.3: Debug PCIR: 00000000 at  00000044
[  360.020047] kernel: snd_sof_intel_hda_common:hda_init_caps: sof-audio-pci-intel-tgl 0000:00:1f.3: PP capability, will probe DSP later.
[  360.022942] kernel: snd_sof:snd_sof_pci_update_bits_unlocked: sof-audio-pci-intel-tgl 0000:00:1f.3: Debug PCIR: 00000040 at  00000048
[  360.022949] kernel: snd_sof:snd_sof_pci_update_bits_unlocked: sof-audio-pci-intel-tgl 0000:00:1f.3: Debug PCIW: 00000000 at  00000048
[  360.026645] kernel: snd_sof_intel_hda_common:hda_dsp_ctrl_init_chip: sof-audio-pci-intel-tgl 0000:00:1f.3: codec_mask = 0x4
[  360.026748] kernel: snd_sof:snd_sof_pci_update_bits_unlocked: sof-audio-pci-intel-tgl 0000:00:1f.3: Debug PCIR: 00000000 at  00000048
[  360.026751] kernel: snd_sof:snd_sof_pci_update_bits_unlocked: sof-audio-pci-intel-tgl 0000:00:1f.3: Debug PCIW: 00000040 at  00000048
[  360.028302] kernel: snd_sof_intel_hda_common:hda_init_caps: sof-audio-pci-intel-tgl 0000:00:1f.3: skipping SoundWire, not detected with ACPI scan
[  360.028581] kernel: snd_sof_intel_hda:hda_codec_probe: sof-audio-pci-intel-tgl 0000:00:1f.3: HDA codec #2 probed OK: response: 8086281c
[  360.030495] kernel: snd_sof_intel_hda:request_codec_module: hdaudio ehdaudio0D2: loading codec module: hdaudio:v8086281Cr00100000a01
[  360.046061] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: NHLT table not found
[  360.046068] kernel: snd_sof:sof_set_fw_state: sof-audio-pci-intel-tgl 0000:00:1f.3: fw_state change: 0 -> 1
[  360.046327] kernel: snd_sof_intel_hda_common:check_dmic_num: sof-audio-pci-intel-tgl 0000:00:1f.3: overriding DMICs detected in NHLT tables 0 by kernel param 4
[  360.046329] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: hda codecs found, mask 4
[  360.046381] kernel: snd_sof:snd_sof_load_firmware: sof-audio-pci-intel-tgl 0000:00:1f.3: loading firmware
[  360.046566] kernel: snd_sof:snd_sof_load_firmware_raw: sof-audio-pci-intel-tgl 0000:00:1f.3: request_firmware intel/sof/community/sof-adl.ri successful
[  360.046569] kernel: snd_sof:sof_ipc3_fw_parse_ext_man: sof-audio-pci-intel-tgl 0000:00:1f.3: found sof_ext_man header type 1 size 0x1a0
[  360.046572] kernel: snd_sof:sof_ipc3_fw_parse_ext_man: sof-audio-pci-intel-tgl 0000:00:1f.3: found sof_ext_man header type 0 size 0x50
[  360.046573] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: Firmware info: version 2:0:0-95d64
[  360.046574] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: Firmware: ABI 3:22:1 Kernel ABI 3:21:0
[  360.046575] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: FW ABI is more recent than kernel
[  360.046575] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: Firmware debug build 65535 on dtermin.-extman - options:
                        GDB: disabled
                        lock debug: disabled
                        lock vdebug: disabled
[  360.046577] kernel: snd_sof:sof_ipc3_fw_parse_ext_man: sof-audio-pci-intel-tgl 0000:00:1f.3: found sof_ext_man header type 2 size 0x70
[  360.046578] kernel: snd_sof:sof_ipc3_get_cc_info: sof-audio-pci-intel-tgl 0000:00:1f.3: Firmware info: used compiler XCC 12:0:8 xcc used optimization flags -O2
[  360.046587] kernel: snd_sof:sof_ipc3_fw_parse_ext_man: sof-audio-pci-intel-tgl 0000:00:1f.3: found sof_ext_man header type 3 size 0x30
[  360.046588] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: unknown sof_ext_man header type 3 size 0x30
[  360.046588] kernel: snd_sof:sof_ipc3_fw_parse_ext_man: sof-audio-pci-intel-tgl 0000:00:1f.3: found sof_ext_man header type 4 size 0x20
[  360.046589] kernel: snd_sof:ipc3_fw_ext_man_get_dbg_abi_info: sof-audio-pci-intel-tgl 0000:00:1f.3: Firmware: DBG_ABI 5:3:0
[  360.046590] kernel: snd_sof:sof_ipc3_fw_parse_ext_man: sof-audio-pci-intel-tgl 0000:00:1f.3: found sof_ext_man header type 5 size 0x20
[  360.046590] kernel: snd_sof:ipc3_fw_ext_man_get_config_data: sof-audio-pci-intel-tgl 0000:00:1f.3: manifest can hold up to 3 config elements
[  360.046591] kernel: snd_sof:ipc3_fw_ext_man_get_config_data: sof-audio-pci-intel-tgl 0000:00:1f.3: get index 0 token 1 val 384
[  360.046592] kernel: snd_sof:ipc3_fw_ext_man_get_config_data: sof-audio-pci-intel-tgl 0000:00:1f.3: get index 1 token 2 val 0
[  360.046592] kernel: snd_sof:ipc3_fw_ext_man_get_config_data: sof-audio-pci-intel-tgl 0000:00:1f.3: get index 2 token 0 val 0
[  360.046593] kernel: snd_sof:sof_set_fw_state: sof-audio-pci-intel-tgl 0000:00:1f.3: fw_state change: 1 -> 2
[  360.046607] kernel: snd_sof:snd_sof_pci_update_bits_unlocked: sof-audio-pci-intel-tgl 0000:00:1f.3: Debug PCIR: 00000002 at  00000048
[  360.046611] kernel: snd_sof:snd_sof_pci_update_bits_unlocked: sof-audio-pci-intel-tgl 0000:00:1f.3: Debug PCIW: 00000000 at  00000048
[  360.046618] kernel: snd_sof:snd_sof_pci_update_bits_unlocked: sof-audio-pci-intel-tgl 0000:00:1f.3: Debug PCIR: 00000000 at  00000044
[  360.046620] kernel: snd_sof:snd_sof_pci_update_bits_unlocked: sof-audio-pci-intel-tgl 0000:00:1f.3: Debug PCIW: 00000004 at  00000044
[  360.046621] kernel: snd_sof:snd_sof_run_firmware: sof-audio-pci-intel-tgl 0000:00:1f.3: booting DSP firmware
[  360.046640] kernel: usbcore: registered new interface driver snd-usb-audio
[  360.046692] kernel: snd_sof_intel_hda_common:hda_dsp_stream_setup_bdl: sof-audio-pci-intel-tgl 0000:00:1f.3: period_bytes:0x0
[  360.046694] kernel: snd_sof_intel_hda_common:hda_dsp_stream_setup_bdl: sof-audio-pci-intel-tgl 0000:00:1f.3: periods:1
[  360.046752] kernel: snd_sof_intel_hda_common:hda_dsp_stream_hw_params: sof-audio-pci-intel-tgl 0000:00:1f.3: FW Poll Status: reg[0x160]=0x40000 successful
[  360.046765] kernel: snd_sof_intel_hda_common:hda_dsp_stream_hw_params: sof-audio-pci-intel-tgl 0000:00:1f.3: FW Poll Status: reg[0x160]=0x40000 successful
[  360.046767] kernel: snd_sof_intel_hda_common:hda_dsp_stream_setup_bdl: sof-audio-pci-intel-tgl 0000:00:1f.3: period_bytes:0x0
[  360.046768] kernel: snd_sof_intel_hda_common:hda_dsp_stream_setup_bdl: sof-audio-pci-intel-tgl 0000:00:1f.3: periods:1
[  360.046797] kernel: snd_sof_intel_hda_common:hda_dsp_cl_boot_firmware: sof-audio-pci-intel-tgl 0000:00:1f.3: Attempting iteration 0 of Core En/ROM load...
[  360.046803] kernel: snd_sof_intel_hda_common:hda_dsp_core_power_up: sof-audio-pci-intel-tgl 0000:00:1f.3: FW Poll Status: reg[0x4]=0xf010f0f successful
[  360.046814] kernel: snd_sof_intel_hda_common:hda_dsp_core_reset_leave: sof-audio-pci-intel-tgl 0000:00:1f.3: FW Poll Status: reg[0x4]=0xf010f0e successful
[  360.046815] kernel: snd_sof_intel_hda_common:hda_dsp_core_run: sof-audio-pci-intel-tgl 0000:00:1f.3: unstall/run core: core_mask = 1
[  360.046818] kernel: snd_sof_intel_hda_common:hda_dsp_core_is_enabled: sof-audio-pci-intel-tgl 0000:00:1f.3: DSP core(s) enabled? 1 : core_mask 1
[  360.047327] kernel: snd_sof_intel_hda_common:cl_dsp_init: sof-audio-pci-intel-tgl 0000:00:1f.3: FW Poll Status: reg[0xd4]=0x80000000 successful
[  360.123562] kernel: snd_sof_intel_hda_common:cl_dsp_init: sof-audio-pci-intel-tgl 0000:00:1f.3: FW Poll Status: reg[0x80000]=0x5000001 successful
[  360.144188] kernel: snd_sof_intel_hda_common:hda_cl_copy_fw: sof-audio-pci-intel-tgl 0000:00:1f.3: FW Poll Status: reg[0x80000]=0x5 successful
[  360.144216] kernel: snd_sof_intel_hda_common:hda_dsp_stream_trigger: sof-audio-pci-intel-tgl 0000:00:1f.3: FW Poll Status: reg[0x160]=0x140000 successful
[  360.144242] kernel: snd_sof_intel_hda_common:hda_dsp_cl_boot_firmware: sof-audio-pci-intel-tgl 0000:00:1f.3: Firmware download successful, booting...
[  360.158776] kernel: snd_sof:ipc3_log_header: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc rx: 0x70000000: FW_READY
[  360.158789] kernel: snd_sof:ipc3_fw_ready: sof-audio-pci-intel-tgl 0000:00:1f.3: DSP is ready 0x70000000 offset 0x81000
[  360.158908] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: Firmware info: version 2:0:0-95d64
[  360.158913] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: Firmware: ABI 3:22:1 Kernel ABI 3:21:0
[  360.158919] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: FW ABI is more recent than kernel
[  360.158922] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: Firmware debug build 65535 on dtermin.-fwready. - options:
                        GDB: disabled
                        lock debug: disabled
                        lock vdebug: disabled
[  360.159165] kernel: snd_sof:ipc3_get_windows: sof-audio-pci-intel-tgl 0000:00:1f.3:  mailbox upstream 0x81000 - size 0x1000
[  360.159170] kernel: snd_sof:ipc3_get_windows: sof-audio-pci-intel-tgl 0000:00:1f.3:  mailbox downstream 0xa0000 - size 0x2000
[  360.159175] kernel: snd_sof:ipc3_get_windows: sof-audio-pci-intel-tgl 0000:00:1f.3:  stream region 0xc1000 - size 0x1000
[  360.159179] kernel: snd_sof:ipc3_get_windows: sof-audio-pci-intel-tgl 0000:00:1f.3:  debug region 0xc0000 - size 0x800
[  360.159187] kernel: snd_sof:sof_set_fw_state: sof-audio-pci-intel-tgl 0000:00:1f.3: fw_state change: 2 -> 5
[  360.159318] kernel: snd_sof:snd_sof_pci_update_bits_unlocked: sof-audio-pci-intel-tgl 0000:00:1f.3: Debug PCIR: 00000000 at  00000048
[  360.159345] kernel: snd_sof:snd_sof_pci_update_bits_unlocked: sof-audio-pci-intel-tgl 0000:00:1f.3: Debug PCIW: 00000002 at  00000048
[  360.159372] kernel: snd_sof:snd_sof_pci_update_bits_unlocked: sof-audio-pci-intel-tgl 0000:00:1f.3: Debug PCIR: 00000004 at  00000044
[  360.159392] kernel: snd_sof:snd_sof_pci_update_bits_unlocked: sof-audio-pci-intel-tgl 0000:00:1f.3: Debug PCIW: 00000000 at  00000044
[  360.159396] kernel: snd_sof:snd_sof_run_firmware: sof-audio-pci-intel-tgl 0000:00:1f.3: firmware boot complete
[  360.159400] kernel: snd_sof:sof_set_fw_state: sof-audio-pci-intel-tgl 0000:00:1f.3: fw_state change: 5 -> 6
[  360.159518] kernel: snd_sof:ipc3_log_header: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc rx done: 0x70000000: FW_READY
[  360.159549] kernel: snd_sof:ipc3_dtrace_init: sof-audio-pci-intel-tgl 0000:00:1f.3: dma_trace_pages: 16
[  360.159641] kernel: snd_sof_intel_hda_common:hda_dsp_stream_hw_params: sof-audio-pci-intel-tgl 0000:00:1f.3: FW Poll Status: reg[0x80]=0x40000 successful
[  360.159703] kernel: snd_sof_intel_hda_common:hda_dsp_stream_hw_params: sof-audio-pci-intel-tgl 0000:00:1f.3: FW Poll Status: reg[0x80]=0x40000 successful
[  360.159724] kernel: snd_sof_intel_hda_common:hda_dsp_stream_setup_bdl: sof-audio-pci-intel-tgl 0000:00:1f.3: period_bytes:0x0
[  360.159729] kernel: snd_sof_intel_hda_common:hda_dsp_stream_setup_bdl: sof-audio-pci-intel-tgl 0000:00:1f.3: periods:1
[  360.159761] kernel: snd_sof:ipc3_dtrace_enable: sof-audio-pci-intel-tgl 0000:00:1f.3: stream_tag: 1
[  360.160146] kernel: snd_sof:ipc3_log_header: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx: 0x90030000: GLB_TRACE_MSG: DMA_PARAMS_EXT
[  360.661546] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx timed out for 0x90030000 (msg/reply size: 80/12)
[  360.661554] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: preventing DSP entering D3 state to preserve context
[  360.661557] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ------------[ IPC dump start ]------------
[  360.661575] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: hda irq intsts 0x00000000 intlctl 0xc0000000 rirb 00
[  360.661577] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: dsp irq ppsts 0x00000000 adspis 0x00000000
[  360.661586] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: error: host status 0x00000000 dsp status 0x00000000 mask 0x00000003
[  360.661588] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ------------[ IPC dump end ]------------
[  360.661590] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ------------[ DSP dump start ]------------
[  360.661591] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: IPC timeout
[  360.661592] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: fw_state: SOF_FW_BOOT_COMPLETE (6)
[  360.661606] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: status: fw entered - code 00000005
[  360.661816] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: unexpected fault 0x00000000 trace 0x00004000
[  360.661817] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ------------[ DSP dump end ]------------
[  360.661820] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: can't set params for DMA for trace -110
[  360.661842] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: failed to initialize firmware tracing -110
[  360.662047] kernel: snd_sof:sof_machine_register: sof-audio-pci-intel-tgl 0000:00:1f.3: created machine adl_max98390_rt5682
[  360.662248] kernel: snd_sof_pci:sof_pci_probe_complete: sof-audio-pci-intel-tgl 0000:00:1f.3: Completing SOF PCI probe
[  360.668235] kernel: rt5682s i2c-RTL5682:00: Using default DAI clk names: rt5682-dai-wclk, rt5682-dai-bclk
[  360.724679] kernel: rt5682s i2c-RTL5682:00: Device with ID register 8c7dd820 is not rt5682s
[  360.732030] kernel: snd_soc_sof_rt5682:sof_audio_probe: sof_rt5682 adl_max98390_rt5682: sof_rt5682_quirk = 1d01068

plbossart commented 2 years ago

@keqiaozhang @XiaoyunWu6666 are you sure the script is working? This is supposed to be a test WITHOUT any audio driver, but here we can see clearly references to sof-audio-pci-intel-tgl?

marc-hb commented 2 years ago

This was in daily test run 13499

I noticed that all kmod-load-unload tests failed in the same run[*], so we should probably start there first!

[*] because of

https://github.com/thesofproject/sof/issues/5733 ?

plbossart commented 2 years ago

Indeed this seems to be a case of compounded issues. I wonder why an IPC with the DMA trace configuration is not fatal, we seem to continue to probe - not sure how this works. Adding @ujfalusi for comments.

ujfalusi commented 2 years ago

From the log for: https://sof-ci.sh.intel.com/#/result/planresultdetail/13499?model=ADLP_GMB_I2S_ZEPHYR&testcase=check-kmod-load-unload-after-playback-5

After module load the DSP is booted, firmware is downloaded, we receive the FW_READY message and the first IPC (GLB_TRACE_MSG:DMA_PARAMS_EXT) times out. Since a timeout is a 'feature' not a failure we continue (dtrace is not going to work since it is not initialized). The next IPC (GLB_TPLG_MSG:PIPE_NEW) also times out and that is going to fail the card creation.

I'm not sure what log the slogger contains, but it does not match the dmesg (not ecen with the previous boot, module removal). The signature looks similar to https://github.com/thesofproject/sof/issues/5733, which is closed, so there is a good chance that this issue is also?

ujfalusi commented 2 years ago

@plbossart, @marc-hb, the

[  359.860161] kernel: max98390 i2c-MX98390:00: ret=-108, Failed to read: 0x24FF
[  359.864846] kernel: max98390 i2c-MX98390:01: ret=-108, Failed to read: 0x24FF
...
[  360.046566] kernel: snd_sof:snd_sof_load_firmware_raw: sof-audio-pci-intel-tgl 0000:00:1f.3: request_firmware intel/sof/community/sof-adl.ri successful

It is really in driver loading time:

[  359.860030] kernel:  i2c_transfer+0x7f/0x100
[  359.860033] kernel:  regmap_i2c_read+0x69/0xa0 [regmap_i2c]
[  359.860039] kernel:  _regmap_raw_read+0x120/0x2b0
[  359.860043] kernel:  _regmap_bus_read+0x41/0x70
[  359.860046] kernel:  _regmap_read+0x5c/0x160
[  359.860049] kernel:  regmap_read+0x3e/0x70
[  359.860051] kernel:  max98390_i2c_probe.cold+0x179/0x1d0 [snd_soc_max98390]
[  359.860056] kernel:  i2c_device_probe+0x132/0x350
[  359.860059] kernel:  really_probe+0x17d/0x360

is printed after the suspend/resume iterations w/o audio modules and it is coming when the audio modules are re-loaded at the end of the test case.

keqiaozhang commented 2 years ago

@fredoh9 we haven't seen such issue in CI for months. Please @fredoh9 help to confirm it in recent stable-v2.2 tests.

fredoh9 commented 2 years ago

ADLP_GMB_I2S* is not part of stable-v2.2 nor ADLP_GMB_I2S* are actively being tested. Hard to tell

mengdonglin commented 2 years ago

@sathyap-chrome Can you please ask Maxim engineer to check if there is some regression for max98390 codec in upstream?

sathyap-chrome commented 2 years ago

Sure @mengdonglin

keqiaozhang commented 1 year ago

This is a very old bug and no similar issue reported when testing with latest sof-dev branch. Closing this bug.

thesofproject / linux

[BUG] max98390 failed to read: 0x24FF on ADLP_GMB_I2S_ZEPHYR #3715