[BUG] WARN validate(), ll drift detected

[oleggtitoff]

Describe the bug
See the bunch of warnings after building SOF from master upstream:
[180448660.052083] ( 87622544.000000) c0 sa src/lib/agent.c:79 WARN validate(), ll drift detected, delta = 41010 [182488660.000000] ( 2040000.000000) c0 sa src/lib/agent.c:79 WARN validate(), ll drift detected, delta = 41007 [190708671.250000] ( 8220011.000000) c0 sa src/lib/agent.c:79 WARN validate(), ll drift detected, delta = 41013 [196196674.010417] ( 5488003.000000) c0 sa src/lib/agent.c:79 WARN validate(), ll drift detected, delta = 41013

To Reproduce

1. git clone https://github.com/thesofproject/sof.git
2. Setup Xtensa environment.
3. cd sof/
   rm -rf tmp
   mkdir tmp
   cd tmp
   cmake -DTOOLCHAIN=xt -DROOT_DIR=$CORE_PATH -DMEU_OPENSSL= '' -DRIMAGE_PRIVATE_KEY=/home/otitov/xcc/meu/otc_private_key_3k.pem ..
   make tgplp_defconfig
   cp ../src/arch/xtensa/configs/override/tigerlake_chrome.config override.config
   make overrideconfig
   make bin -j
   cd ..
   ./scripts/build-tools.sh -T
4. Copy sof-tgl.ri, sof-tgl.ldc and topology to the device. Reboot the device.
5. Connect to the device through ssh and run sof-logger. Play some music on the device. See drift warnings.

Reproduction Rate
Every time.

Expected behavior
Expected not to see these warnings.

Impact
Can impact on third party integration.

Environment

1. Branch name and commit hash of the 2 repositories: sof (firmware/topology) and linux (kernel driver).
   • Kernel (v5.4): {e1b05a5f0f81e0b8e35129f45c335f7882f263d0}
   • SOF: {b0faccc}
2. Name of the topology file
   • Topology: {sof-tgl-max98357a-rt5682.tplg}
3. Name of the platform(s) on which the bug is observed.
   • Platform: {tigerlake_chrome}

Screenshots or console output

[131978267.239583] ( 747.656250) c0 kd-test 12.61 ..../audio/detect_test.c:556 test_keyword_cmd()
[131978285.104167] ( 17.864584) c0 kd-test 12.61 ..../audio/detect_test.c:470 test_keyword_cmd_set_data(), SOF_CTRL_CMD_BINARY
[131978302.916667] ( 17.812500) c0 kd-test 12.61 ..../audio/detect_test.c:410 test_keyword_set_config(), blob size = 32
[131979656.614583] ( 1353.697876) c0 sa src/lib/agent.c:79 WARN validate(), ll drift detected, delta = 42177
[131979716.250000] ( 59.635418) c0 pga 11.54 ../audio/volume/volume.c:561 volume_ctrl_set_cmd(), channel = 0, value = 65536
[131979735.208333] ( 18.958334) c0 pga 11.54 ../audio/volume/volume.c:561 volume_ctrl_set_cmd(), channel = 1, value = 65536
[131980457.239583] ( 722.031250) c0 pga 8.40 ../audio/volume/volume.c:561 volume_ctrl_set_cmd(), channel = 0, value = 65536
[131980473.854167] ( 16.614584) c0 pga 8.40 ../audio/volume/volume.c:561 volume_ctrl_set_cmd(), channel = 1, value = 65536
[131981126.250000] ( 652.395813) c0 pga 7.34 ../audio/volume/volume.c:561 volume_ctrl_set_cmd(), channel = 0, value = 65536
[131981143.125000] ( 16.875000) c0 pga 7.34 ../audio/volume/volume.c:561 volume_ctrl_set_cmd(), channel = 1, value = 65536
[131981641.406250] ( 498.281250) c0 pga 6.28 ../audio/volume/volume.c:561 volume_ctrl_set_cmd(), channel = 0, value = 65536
[131981658.593750] ( 17.187500) c0 pga 6.28 ../audio/volume/volume.c:561 volume_ctrl_set_cmd(), channel = 1, value = 65536
[131982283.072917] ( 624.479187) c0 pga 5.22 ../audio/volume/volume.c:561 volume_ctrl_set_cmd(), channel = 0, value = 65536
[131982299.322917] ( 16.250000) c0 pga 5.22 ../audio/volume/volume.c:561 volume_ctrl_set_cmd(), channel = 1, value = 65536
[131982952.291667] ( 652.968750) c0 pga 3.16 ../audio/volume/volume.c:561 volume_ctrl_set_cmd(), channel = 0, value = 65536
[131982968.854167] ( 16.562500) c0 pga 3.16 ../audio/volume/volume.c:561 volume_ctrl_set_cmd(), channel = 1, value = 65536
[131983650.416667] ( 681.562500) c0 pga 2.10 ../audio/volume/volume.c:561 volume_ctrl_set_cmd(), channel = 0, value = 65536
[131983667.031250] ( 16.614584) c0 pga 2.10 ../audio/volume/volume.c:561 volume_ctrl_set_cmd(), channel = 1, value = 65536
[131984290.781250] ( 623.750000) c0 demux 1.2 src/audio/mux/mux.c:343 mux_cmd() cmd = 0x00000066
[131984308.385417] ( 17.604166) c0 demux 1.2 src/audio/mux/mux.c:284 mux_ctrl_set_cmd(), cdata->cmd = 0x00000003
[131984325.989583] ( 17.604166) c0 demux 1.2 src/audio/mux/mux.c:100 mux_set_values()
[131985087.187500] ( 761.197937) c0 pga 1.1 ../audio/volume/volume.c:561 volume_ctrl_set_cmd(), channel = 0, value = 65536
[131985103.802083] ( 16.614584) c0 pga 1.1 ../audio/volume/volume.c:561 volume_ctrl_set_cmd(), channel = 1, value = 65536
[131985597.187500] ( 493.385406) c0 ipc src/ipc/handler.c:606 ipc: pm -> restore
[131986372.083333] ( 774.895813) c0 pipe 1.7 src/audio/pipeline.c:541 pipe params dir 0 frame_fmt 0 buffer_fmt 0 rate 48000
[131986390.208333] ( 18.125000) c0 pipe 1.7 src/audio/pipeline.c:545 pipe params stream_tag 1 channels 2 sample_valid_bytes 2 sample_container_bytes 2
[131986497.916667] ( 107.708336) c0 demux 1.2 src/audio/mux/mux.c:265 mux_params()
[131986564.687500] ( 66.770836) c0 dai 1.6 src/audio/dai.c:351 dai_playback_params() dest_dev = 4 stream_id = 0 src_width = 2 dest_width = 2
[131986583.593750] ( 18.906250) c0 dai 1.6 src/audio/dai.c:357 dai_playback_params() fifo 0x77210
[131986611.458333] ( 27.864584) c0 pipe 1.7 src/audio/pipeline.c:668 pipe prepare
[131986672.864583] ( 61.406250) c0 demux 1.2 src/audio/mux/mux.c:642 mux_prepare()
[131989236.354167] ( 2563.489502) c0 pipe 1.7 src/audio/pipeline.c:863 pipe trigger cmd 1
[131989330.520833] ( 94.166664) c0 demux 1.2 src/audio/mux/mux.c:698 mux_trigger(), command = 1
[131989351.093750] ( 20.572916) c0 ssp-dai 1.1 /drivers/intel/ssp/ssp.c:843 ssp_trigger() cmd 1
[131989369.375000] ( 18.281250) c0 ssp-dai 1.1 /drivers/intel/ssp/ssp.c:631 ssp_pre_start()
[131989426.979167] ( 57.604168) c0 mn ./drivers/intel/ssp/mn.c:264 mclk_rate 19200000, mclk_source_clock 1
[131989445.468750] ( 18.489584) c0 mn ./drivers/intel/ssp/mn.c:226 mclk_id 0 mdivr_val 2
[131989467.760417] ( 22.291666) c0 mn ./drivers/intel/ssp/mn.c:328 find_mn for freq 38400000 bclk 1536000
[131989485.729167] ( 17.968750) c0 mn ./drivers/intel/ssp/mn.c:633 bclk_rate 1536000, *out_scr_div 25, m 1, n 1
[131989503.385417] ( 17.656250) c0 ssp-dai 1.1 /drivers/intel/ssp/ssp.c:687 ssp_set_config(), sscr0 = 0xc1c0187f
[131989522.812500] ( 19.427084) c0 ssp-dai 1.1 /drivers/intel/ssp/ssp.c:760 ssp_start()
[131989645.520833] ( 122.708336) c0 ll-schedule ./schedule/ll_schedule.c:348 task add 0xbe090100 pipe-task <f11818eb-e92e-4082-82a3-dc54c604ebb3>
[131989662.604167] ( 17.083334) c0 ll-schedule ./schedule/ll_schedule.c:352 task params pri 0 flags 0 start 0 period 1000
[131989683.177083] ( 20.572916) c0 ll-schedule ./schedule/ll_schedule.c:252 num_tasks 3 total_num_tasks 3
[131991619.218750] ( 1936.041626) c0 sa src/lib/agent.c:79 WARN validate(), ll drift detected, delta = 42519
[170507717.031250] ( 38516096.000000) c0 sa src/lib/agent.c:79 WARN validate(), ll drift detected, delta = 41003
[219535741.770833] ( 49028024.000000) c0 sa src/lib/agent.c:79 WARN validate(), ll drift detected, delta = 41007
[230141701.718750] ( 10605960.000000) c0 sa src/lib/agent.c:79 WARN validate(), ll drift detected, delta = 41023
[241587734.375000] ( 11446033.000000) c0 sa src/lib/agent.c:79 WARN validate(), ll drift detected, delta = 41012
[252069733.854167] ( 10481999.000000) c0 sa src/lib/agent.c:79 WARN validate(), ll drift detected, delta = 41025
[253667728.854167] ( 1597995.000000) c0 sa src/lib/agent.c:79 WARN validate(), ll drift detected, delta = 41013
[268751700.364583] ( 15083972.000000) c0 sa src/lib/agent.c:79 WARN validate(), ll drift detected, delta = 41014
[283257740.364583] ( 14506040.000000) c0 sa src/lib/agent.c:79 WARN validate(), ll drift detected, delta = 41024
[284153721.041667] ( 895980.687500) c0 sa src/lib/agent.c:79 WARN validate(), ll drift detected, delta = 41020
[292335710.416667] ( 8181989.500000) c0 sa src/lib/agent.c:79 WARN validate(), ll drift detected, delta = 41013
[293047734.322917] ( 712023.875000) c0 sa src/lib/agent.c:79 WARN validate(), ll drift detected, delta = 41005

sof_logger_log.txt
dmesg_log.txt

[slawblauciak]

@oleggtitoff hi, can you please check the releases/tgl/v11.0-hotfix2 tag and test it? Thanks.

[oleggtitoff]

Hi @slawblauciak, thanks for your advice.

Unfortunately, we are not able to build FW from this tag.
Got this error:

/sof/rimage/src/rimage.c:185: main: Assertion `image.adsp->write_firmware' failed.
Aborted (core dumped)
src/arch/xtensa/CMakeFiles/run_rimage.dir/build.make:74: recipe for target 'src/arch/xtensa/CMakeFiles/run_rimage' failed
make[3]: *** [src/arch/xtensa/CMakeFiles/run_rimage] Error 134
CMakeFiles/Makefile2:2484: recipe for target 'src/arch/xtensa/CMakeFiles/run_rimage.dir/all' failed
make[2]: *** [src/arch/xtensa/CMakeFiles/run_rimage.dir/all] Error 2
CMakeFiles/Makefile2:2101: recipe for target 'src/arch/xtensa/CMakeFiles/bin.dir/rule' failed
make[1]: *** [src/arch/xtensa/CMakeFiles/bin.dir/rule] Error 2
Makefile:662: recipe for target 'bin' failed
make: *** [bin] Error 2

We build it the same way as in the reproduction steps above, the only difference is to git checkout tags/releases/tgl/v11.0-hotfix2.
Do you have any ideas?

[keyonjie]

looks the rimage version with the release branch is different, can you try 'git submodule update' in the sof/ folder before building.

[oleggtitoff]

Hi @keyonjie, @slawblauciak, thanks for your comments.

Added submodule update command after checkout:

git checkout tags/releases/tgl/v11.0-hotfix2
git submodule update

But got the same error. Could you please suggest, what else can we try?

[lgirdwood]

@oleggtitoff are you able to clone rimage repo and build ? Something may be out of sync, sub repo may need to be pulled as well.

[keyonjie]

@oleggtitoff yes, do something like 'rm rimage -rf' before the 'git submodule update'.

[oleggtitoff]

Hi guys, thank you very much.
We managed to build firmware from releases/tgl/v11.0-hotfix2 tag. There are no warnings with this version.
But please tell us if you are planning to fix these warnings in the master too?

[keyonjie]

hi @oleggtitoff I think the master is already aligned with tgl/v11 after the #3768 was merged, can you try the latest master?

[oleggtitoff]

Hi @keyonjie,
I tried the latest master and still can see the bunch of warnings.

[keyonjie]

Hi @oleggtitoff thanks for information, looks we need to define different warn_timeout for TGL platforms, the reason why you didn't see it with tgl-011 is that SA is disabled there.

[marc-hb]

@keyonjie could this issue explain the very recent 25_02_TestGenericProcessorCompMultiCorePlb48000Hz32b32b4ch PR_CODEC_REGRESSION failure in https://sof-ci.01.org/sof-pr-viewer/#/build/PR3896/build6134676? (WHL/CNL)

Its dma_trace.log shows hundreds of WARN validate(), ll drift detected, delta = 25605

The more visible error is: SNR value is smaller than acceptable value (80.00) on channel 0: 16.12 , 16.43, 14.99, 13.15 on channels 1,2,3 and 4

[marc-hb]

Same failure in https://sof-ci.01.org/sof-pr-viewer/#/build/PR3891/build6130418 but on TGL this time:

01:40:59.079 SNR value is smaller than acceptable value (80.00) on channel 0: 6.51
01:40:59.079 Wave verification failed on channel 1

01:40:59.126 SNR value is smaller than acceptable value (80.00) on channel 0: 6.33
01:40:59.126 Wave verification failed on channel 2

01:40:59.158 SNR value is smaller than acceptable value (80.00) on channel 0: 8.56
01:40:59.158 Wave verification failed on channel 3

01:40:59.220 SNR value is smaller than acceptable value (80.00) on channel 0: 6.98
01:40:59.220 Wave verification failed on channel 4

The dma_trace.log has "only" tens of

[ 3612396.718750] ( 11993.437500) c0 sa src/lib/agent.c:79 WARN validate(), ll drift detected, delta = 41007
[ 3656401.041667] ( 44004.324219) c0 sa src/lib/agent.c:79 WARN validate(), ll drift detected, delta = 40990