Repository navigation
[BUG] WARN validate(), ll drift detected #3854
Description
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
- git clone https://github.com/thesofproject/sof.git
- Setup Xtensa environment.
- 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 - Copy sof-tgl.ri, sof-tgl.ldc and topology to the device. Reboot the device.
- 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
- Branch name and commit hash of the 2 repositories: sof (firmware/topology) and linux (kernel driver).
- Kernel (v5.4): {e1b05a5f0f81e0b8e35129f45c335f7882f263d0}
- SOF: {b0faccc}
- Name of the topology file
- Topology: {sof-tgl-max98357a-rt5682.tplg}
- 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
Activity
[-][BUG][/-][+][BUG] WARN validate(), ll drift detected[/+]slawblauciak commentedon Feb 23, 2021
@oleggtitoff hi, can you please check the releases/tgl/v11.0-hotfix2 tag and test it? Thanks.
oleggtitoff commentedon Feb 24, 2021
Hi @slawblauciak, thanks for your advice.
Unfortunately, we are not able to build FW from this tag.
Got this error:
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 commentedon Feb 25, 2021
looks the rimage version with the release branch is different, can you try 'git submodule update' in the sof/ folder before building.
oleggtitoff commentedon Feb 25, 2021
Hi @keyonjie, @slawblauciak, thanks for your comments.
Added submodule update command after checkout:
But got the same error. Could you please suggest, what else can we try?
lgirdwood commentedon Feb 26, 2021
@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 commentedon Mar 1, 2021
@oleggtitoff yes, do something like 'rm rimage -rf' before the 'git submodule update'.
oleggtitoff commentedon Mar 1, 2021
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 commentedon Mar 2, 2021
hi @oleggtitoff I think the master is already aligned with tgl/v11 after the #3768 was merged, can you try the latest master?
oleggtitoff commentedon Mar 3, 2021
Hi @keyonjie,
I tried the latest master and still can see the bunch of warnings.
keyonjie commentedon Mar 4, 2021
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 commentedon Mar 5, 2021
@keyonjie could this issue explain the very recent
25_02_TestGenericProcessorCompMultiCorePlb48000Hz32b32b4chPR_CODEC_REGRESSIONfailure in https://sof-ci.01.org/sof-pr-viewer/#/build/PR3896/build6134676? (WHL/CNL)Its
dma_trace.logshows hundreds ofWARN validate(), ll drift detected, delta = 25605The more visible error is:
SNR value is smaller than acceptable value (80.00) on channel 0: 16.12 , 16.43, 14.99, 13.15on channels 1,2,3 and 4marc-hb commentedon Mar 5, 2021
Same failure in https://sof-ci.01.org/sof-pr-viewer/#/build/PR3891/build6130418 but on TGL this time:
The
dma_trace.loghas "only" tens ofmarc-hb commentedon Mar 5, 2021
PR #2686 downgraded this error to a warning, because of "non-critical" drifts (~ "soft" real-time?). However I don't see anything about "critical" drifts in #2686
Should it be upgraded to an error again when the drift is too large or when there are too many in a row or both?
https://github.com/thesofproject/sof/issues?q=%22ll+detected+drift%2C+delta%22+
returns 28 issues which seems a lot, however github search syntax for whitespace unfortunately does not work; this other, disordered search returns the same issues: https://github.com/thesofproject/sof/issues?q=%22delta+detected+drift+ll%22
https://docs.github.com/en/github/searching-for-information-on-github/understanding-the-search-syntax#use-quotation-marks-for-queries-with-whitespace
keyonjie commentedon Mar 8, 2021
Hi all, looks the drift comes from re-requesting HPRO during exiting from WFI, @oleggtitoff can you try if #3762 can fix the issue at your end?
@marc-hb I am not sure if the drift can lead to bad SNR or other errors, but at least it raise flag of abnormal issues happened, so at least a warning here is legit to me. BTW, PR #3762 should fix the drift issue so it worth to try with it for other quality issues IMO.
mwasko commentedon Mar 8, 2021
To avoid any regression the #3762 should be taken alongside with the #3865 (merged to master).
lgirdwood commentedon Mar 8, 2021
@keyonjie both merged now, can we close ?
oleggtitoff commentedon Mar 9, 2021
Hi everybody, the issue is fixed. Thank you very much!
check-sof-logger: rewrite most of it so it can actually find bugs
check-sof-logger: rewrite most of it so it can actually find bugs
check-sof-logger: rewrite most of it so it can actually find bugs
check-sof-logger: rewrite most of it so it can actually find bugs
check-sof-logger: rewrite most of it so it can actually find bugs
check-sof-logger: rewrite most of it so it can actually find bugs