[BUG]Unexpected sof error trace print when trigger aplay/arecord

[Liviali155]

Describe the bug Unexpected sof error trace print when trigger aplay/arecord, but aplay/arecord can work normally, just an error message output

To Reproduce 1.sudo reboot 2.aplay -Dhw:0,1 -r48000 -c2 -fs16_le wav/48California_Dreaming.wav -vv -i -d 1 3.sudo sof-logger -l /etc/sof/sof-*.ldc

Reproduction Rate 10/10

Expected behavior There is no sof error trace print when aplay/arecord

Actual result There is sof error trace output when aplay/arecord,but function can work normally

CORE  LEVEL      COMP_ID                TIMESTAMP            DELTA                FILE_NAME CONTENT
    0      1           SA          76527513.697917  76527512.000000      src/lib/agent.c:55     validate(), ll drift detected, delta = 40493

Environment Kernel:https://github.com/thesofproject/linux/commits/topic/sof-dev commit:c5e4a391 Firmware:https://github.com/thesofproject/sof/commits/master commit: 85e462ad Can reproduce on all below platforms: TGL RT711 in HDA mode, ICL rt711 in HDA mode, APL-UP2 nocodec, APL-up2 PCM512x in I2S mode, BYT nocode, BYT 5682 in I2S mode.

dmesg20191217.log sof_errortrace1217.log sof_trace1217.log

[paulstelian97]

IMX8 with CS42888 codec also has this issue:

0 1 SA 1500815271.153153 110893208.000000 src/lib/agent.c:55 validate(), ll drift detected, delta = 1330786

Also the drifts are usually large enough that they often lead to panics (this one run in particular was lucky in the sense that it only gave me the log)

I think this also happens in nocodec on this platform but didn't check recently enough to be sure.

[singalsu]

The file sof_trace1217.log looks empty except the header. There should definitely be something seen from the playback.

[paulstelian97]

@singalsu I think this is an older problem. Should I come back with a full log dump on IMX? This one definitely isn't empty but, given the line you have noticed in my comment, takes quite a bit longer to reproduce than on the other platforms.

[singalsu]

I was wondering if this is related to audio processing and created load in pipelines. I'm seeing this quite often when I'm testing processing components. I wondered if there's SRC in hw:0,1. Seeing trace and component prepare() calls helps to figure out what's included.

[paulstelian97]

@singalsu In my case there is only two HOST, two VOLUME and two DAI (the DAI components being tied to the same hardware), as seen in the sof-imx8qxp-cs42888.m4 topology, one of each per stream (playback + capture simultaneously). No SRC.

For the tested topologies I think there is at least one that doesn't have SRC (sof-tgl-rt711-rt1308.m4 doesn't seem to have any), although I believe it's not related.

[tlauda]

@Liviali155 @singalsu @paulstelian97 Please try with #2221.

Edit: #2221 is the right one.

[paulstelian97]

@tlauda If Livia reports it to be fixed (issue seems to happen much more quickly on the Intel platforms) you should be good to merge. I will chime in if the agent doesn't trigger any issue in 2 hours.

[paulstelian97]

@tlauda Actually... something more interesting is happening. Your commit has the perverse effect on my system, now getting stuff like:

    0      1           SA         114654699.264264     14618.360352      src/lib/agent.c:55     validate(), ll drift detected, delta = 707470
    0      1           SA         114728687.998498     73988.734375      src/lib/agent.c:55     validate(), ll drift detected, delta = 699980

(note: even more than visible here)

EDIT: Removed most of the logs to stop disrupting the conversation flow.

[paulstelian97]

(all errors are happening while DSP is idle)

[tlauda]

@paulstelian97 #2220 was wrong. Please try with #2221.

[paulstelian97]

Trying with #2221 now, will report.

[paulstelian97]

Trying. Now I've got a storm of these logs after an Xrun (as in, 2+ seconds worth of such logs, based on the timestamps it might be more?) with no panic. For me getting these with the small delta is better than getting a delta large enough to trigger a panic but both cases are still bad.

Timestamp of first error: 182888957.115616 Timestamp of last error in burst: 198076948.747748 Actual error message is the same.

Later edit: Also got a panic. Not sure if it's the agent or #2214 acting up though.

[paulstelian97]

@Liviali155 IMX remains as broken as it was before. Can you report if #2221 fixes the issue on the Intel platforms? If so, I'll allow that to be merged and I'll keep on working with the agent disabled for now on IMX.

[Liviali155]

@Liviali155 IMX remains as broken as it was before. Can you report if #2221 fixes the issue on the Intel platforms? If so, I'll allow that to be merged and I'll keep on working with the agent disabled for now on IMX.

Tried with #2221 ,error not seen on below platforms: APL-UP2 nocodec APL-up2 PCM512x in I2S mode TGL RT711 in HDA mode BYT nocode,

But can reproduce on: BYT 5682 in I2S mode.