Catch firmware errors

[marc-hb]

Final PR at last.

EDIT: "final" except for stable-v2.2; followup in:

• hijack.sh: fail on stable-v2.2 FW errors too #1188

See commit messages.

For a (lot of) context see

• Check for a valid trace for ALL tests #297

... and all the links from there.

cc:

• [Bug][CML] 'error: debugfs entry etrace cannot be read in DSP D3' is in dmesg after system bootup linux#1046
• [BUG] need to rate-limit 'nothing to copy' traces when mixer source is paused. sof#4672
• Catch firmware errors reported in logs #1173

[marc-hb]

There are a LOT of ERRORs in stable-v2.2 https://sof-ci.01.org/softestpr/PR1075/build537/devicetest/index.html , about half the tests have some.

They all seem to be this timeout:

 60561676.864329] ( 1924.374878) c0 wait src/lib/wait.c:53 ERROR poll timeout reg 488520 mask 63 val 0 us 937

Should it really be at the ERROR level?

In one sample context:

[ 58851889.953103] ( 114.739578) c0 ll-schedule ./schedule/ll_schedule.c:186 INFO task 0xbe0a2280 pipe-task avg 1763, max 1796
[ 59389729.931731] ( 537840.000000) c0 ll-schedule ./schedule/ll_schedule.c:186 INFO task 0x9e08c858 agent-work avg 114, max 119
[ 60558956.656103] ( 1169226.750000) c0 ipc src/ipc/ipc3/handler.c:1605 INFO ipc: new cmd 0x60050000
[ 60558979.833186] ( 23.177082) c0 pipe 9.50 ....../pipeline-stream.c:270 INFO pipe trigger cmd 0
[ 60559752.489405] ( 772.656189) c0 ssp-dai 1.2 /drivers/intel/ssp/ssp.c:1122 INFO ssp_trigger() cmd 0
[ 60561676.864329] ( 1924.374878) c0 wait src/lib/wait.c:53 ERROR poll timeout reg 488520 mask 63 val 0 us 937
[ 60561693.478911] ( 16.614582) c0 ssp-dai 1.2 /drivers/intel/ssp/ssp.c:61 WARN ssp_empty_tx_fifo() warning: timeout
[ 60561711.655994] ( 18.177082) c0 ssp-dai 1.2 /drivers/intel/ssp/ssp.c:1084 INFO ssp_stop(), TX stop
[ 60561733.374743] ( 21.718750) c0 dw-dma src/drivers/dw/dma.c:413 INFO dw_dma_stop(): dma 0 channel 0 stop
[ 60561767.437242] ( 34.062500) c0 ll-schedule ./schedule/ll_schedule.c:159 INFO task complete 0xbe0a2200 pipe-task 

[marc-hb]

cavs25 https://sof-ci.01.org/softestpr/PR1075/build536/devicetest/index.html and MTL https://sof-ci.ostc.intel.com/#/result/planresultdetail/28422 show both the same,
interesting ERROR pattern: the nocodec configurations have firmware <err> in practically every test. The configuration with codec have no ERROR message at all (except in very few, other, unrelated and known failures)

Most error messages seem be this timeout

[ 0.037243] <inf> dai_intel_ssp: dai_ssp_pm_runtime_en_ssp_power: dai_ssp_pm_runtime_en_ssp_power en_ssp_power index 0
[ 0.037381] <err> dai_intel_ssp: dai_ssp_poll_for_register_delay: dai_ssp_poll_for_register_delay poll timeout reg 465924 mask 256 val 0 us 125
[ 0.037413] <wrn> dai_intel_ssp: dai_ssp_pm_runtime_en_ssp_power: dai_ssp_pm_runtime_en_ssp_power warning: timeout
[ 0.037421] <inf> dai_intel_ssp: dai_ssp_pm_runtime_en_ssp_power: dai_ssp_pm_runtime_en_ssp_power I2SLCTL

[marc-hb]

New run, same results.

• nocodec configurations have the same DAI timeouts in MTL https://sof-ci.01.org/softestpr/PR1075/build550/devicetest/index.html and cavs25 https://sof-ci.01.org/softestpr/PR1075/build548/devicetest/index.html

• stable-v2.2 also seems to have the same poll timeouts as before in https://sof-ci.01.org/softestpr/PR1075/build549/devicetest/index.html, no change either.

[marc-hb]

test run on 2023-07-18

No change in stable-v2.2 https://sof-ci.01.org/softestpr/PR1075/build629/devicetest/index.html

cavs2.5 https://sof-ci.01.org/softestpr/PR1075/build630/devicetest/index.html

and in MTL https://sof-ci.01.org/softestpr/PR1075/build631/devicetest/index.html

Same errors all around.

---

September 19th, no change in:
ACE https://sof-ci.01.org/softestpr/PR1075/build754/devicetest/index.html
CAVS https://sof-ci.01.org/softestpr/PR1075/build753/devicetest/index.html
stable-v2.2 https://sof-ci.01.org/softestpr/PR1075/build752/devicetest/index.html

[marc-hb]

SOFCI TEST

[marc-hb]

cavs https://sof-ci.01.org/softestpr/PR1075/build129/devicetest/index.html has some new type of error:

[ 0.598035] <inf> dai_intel_dmic_nhlt: dai_dmic_configure_coeff: fir_length_a = 101, fir_length_b = 247, packed = 0
[ 0.598055] <inf> dai_intel_dmic_nhlt: dai_nhlt_dmic_dai_params_get: set 4ch pdm0 and pdm1
[ 0.598065] <err> dai_intel_dmic_nhlt: dai_nhlt_get_clock_div: pdm = 0, FIR_CONFIG = 0x00010064
[ 0.598078] <err> dai_intel_dmic_nhlt: dai_nhlt_get_clock_div: dai_index = 0, rate_div = 800, p_clkdiv = 16, p_mcic = 25, p_mfir = 2
[ 0.598090] <inf> dai_intel_dmic_nhlt: dai_nhlt_update_rate: rate = 48000, channels = 4, format = 2
[ 0.598100] <inf> dai_intel_dmic_nhlt: dai_nhlt_update_rate: io_clk 38400000, rate_div 800
[ 0.598111] <inf> dai_intel_dmic_nhlt: dai_dmic_set_config_nhlt: dmic_set_config_nhlt(): enable0 3, enable1 3

cavs25 https://sof-ci.01.org/softestpr/PR1075/build753/devicetest/index.html is from the old build service and very old (sept 2023)

MTL https://sof-ci.01.org/softestpr/PR1075/build128/devicetest/index.html has plenty of FW errors but unfortunately no logs, dunno why.

stable-v2.2 has underruns https://sof-ci.01.org/softestpr/PR1075/build130/devicetest/index.html and suspend/resume failures, otherwise mostly OK.

[marc-hb]

SOFCI TEST

EDIT, now blocked by (among others):

• dai_ssp_set_reg_config: SSPx configuration: Ignoring SSCR1:TSRE SSCR1:RSRE from blob sof#9026

[marc-hb]

cavs https://sof-ci.01.org/softestpr/PR1075/build269/devicetest/index.html has the "ignoring blob" errors in NOCODEC and not much else I could find.

Same thing with ACE https://sof-ci.01.org/softestpr/PR1075/build270/devicetest/index.html

stable-v2.2 https://sof-ci.01.org/softestpr/PR1075/build271/devicetest/index.html seems to have many underruns and that's it

[ujfalusi]

@marc-hb, the underruns looks like to be coming from pause/resume tests only, right?

All logs contains that I can see via CI (2023-09-04 is the oldest)

[marc-hb]

I think you might be right. The rest in https://sof-ci.01.org/softestpr/PR1075/build269/devicetest/index.html seems to be ERROR dtrace_add_event() which could probably be lowered to a WARN and that's it?

In any case stable-v2.2 is obviously not the priority. I'd really like to enable this for Zephyr.

[marc-hb]

SOFCI TEST

EDIT: MTL https://sof-ci.01.org/softestpr/PR1075/build327/devicetest/index.html is 100% green!

CAVS https://sof-ci.01.org/softestpr/PR1075/build328/devicetest/index.html has only one device available but it's all green.

LNL https://sof-ci.01.org/softestpr/PR1075/build326/devicetest/index.html has one unrelated device PM runtime misconfiguration.

stable-v2.2 still has a lot of dtrace dropped logs errors https://sof-ci.01.org/softestpr/PR1075/build325/devicetest/index.html
thesofproject/sof#9036

[fredoh9]

Looks good, let's merge this now

[marc-hb]

MTL https://sof-ci.01.org/softestpr/PR1075/build331/devicetest/index.html 100% green.

stable-v2.2 100% (cause not catching errors yet) https://sof-ci.01.org/softestpr/PR1075/build332/devicetest/index.html

LNL has a couple of known issues already listed above
https://sof-ci.01.org/softestpr/PR1075/build329/devicetest/index.html

CAVS https://sof-ci.01.org/softestpr/PR1075/build330/devicetest/index.html had only one MODEL available but it's all green.