ADL: Audio latency of (~2n) is obserbed during the speaker playback for n period

[jairaj-arava]

There is a latency of 2n time period is observed for n period playback i.e. for 1 ms period we observed time ~2ms of latency instead of 1ms(expected) as shown below.

[ 182700.513573] ( 40.208332) c1 pipe 1.7 ....../pipeline-stream.c:270 INFO pipe trigger cmd 7
[ 182738.065655] ( 37.552082) c1 ll-schedule ./schedule/ll_schedule.c:513 INFO task add 0xbe1e0900 pipe-task
[ 182756.555238] ( 18.489582) c1 ll-schedule ./schedule/ll_schedule.c:517 INFO task params pri 0 flags 0 start 0 period 1000
[ 182776.659404] ( 20.104166) c1 ll-schedule /schedule/timer_domain.c:62 INFO timer_domain_register domain->type 1 domain->clk 4 domain->ticks_per_ms 38400
[ 182827.648985] ( 50.989582) c1 ll-schedule ./schedule/ll_schedule.c:418 INFO new added task->start 4180199 at 4166725
[ 182846.503151] ( 18.854166) c1 ll-schedule ./schedule/ll_schedule.c:421 INFO num_tasks 1 total_num_tasks 3
[ 182871.607317] ( 25.104166) c1 ipc src/ipc/ipc3/handler.c:504 ERROR TRIGGER DONE
[ 183608.169787] ( 736.562500) c1 demux 1.2 src/audio/mux/mux.c:811 INFO mux_trigger(), command = 7
[ 183639.576036] ( 31.406248) c1 ssp-dai 1.1 /drivers/intel/ssp/ssp.c:1135 INFO ssp_trigger() cmd 7
[ 183658.638535] ( 19.062500) c1 ssp-dai 1.1 /drivers/intel/ssp/ssp.c:918 INFO ssp_pre_start()
[ 183679.628118] ( 20.989582) c1 mn ./drivers/intel/ssp/mn.c:259 INFO mclk_rate 19200000, mclk_source_clock 1
[ 183698.169784] ( 18.541666) c1 mn ./drivers/intel/ssp/mn.c:220 INFO mclk_id 0 mdivr_val 2
[ 183720.930200] ( 22.760416) c1 mn ./drivers/intel/ssp/mn.c:330 INFO find_mn for freq 38400000 bclk 6144000
[ 183741.086449] ( 20.156250) c1 mn ./drivers/intel/ssp/mn.c:369 INFO find_mn m 24 n 25
[ 183760.357281] ( 19.270832) c1 mn ./drivers/intel/ssp/mn.c:628 INFO bclk_rate 6144000, *out_scr_div 6, m 24, n 25
[ 183780.044781] ( 19.687500) c1 ssp-dai 1.1 /drivers/intel/ssp/ssp.c:227 INFO ssp_bclk_prepare_enable(): sscr0 = 0xc3d0057f
[ 183800.201030] ( 20.156250) c1 ssp-dai 1.1 /drivers/intel/ssp/ssp.c:1018 INFO ssp_early_start(): SSE set for SSP1
[ 183910.513525] ( 110.312492) c1 demux 1.2 src/audio/mux/mux.c:811 INFO mux_trigger(), command = 1
[ 183947.596857] ( 37.083332) c1 ssp-dai 1.1 /drivers/intel/ssp/ssp.c:1135 INFO ssp_trigger() cmd 1
[ 183966.398940] ( 18.802082) c1 ssp-dai 1.1 /drivers/intel/ssp/ssp.c:1033 INFO ssp_start()
[ 185622.023874] ( 1655.624878) c1 host 1.0 src/audio/host.c:1003 ERROR HOST COPY
[ 185788.325951] ( 166.302078) c1 pga 1.1 ../audio/volume/volume.c:1195 ERROR VOLUME DONE
[ 185890.617613] ( 102.291664) c1 dai 1.6 src/audio/dai.c:970 ERROR DAI COPY_DONE
[ 187768.586289] ( 1877.968628) c1 pga 1.1 ../audio/volume/volume.c:1195 ERROR VOLUME DONE
[ 187862.388368] ( 93.802078) c1 dai 1.6 src/audio/dai.c:153 ERROR DMA CB DONE

The same behavior is observed for 10ms period too. I see ~20ms for the 10ms period.

[ 161311.868590] ( 18.489582) c1 ll-schedule ./schedule/ll_schedule.c:517 INFO task params pri 0 flags 0 start 0 period 10000

[ 162225.358137] ( 38.697914) c1 ssp-dai 1.1 /drivers/intel/ssp/ssp.c:1135 INFO ssp_trigger() cmd 1
[ 162245.410220] ( 20.052082) c1 ssp-dai 1.1 /drivers/intel/ssp/ssp.c:1033 INFO ssp_start()
[ 181894.992772] ( 19649.582031) c1 host 1.0 src/audio/host.c:1003 ERROR HOST COPY
[ 183115.721890] ( 1220.729126) c1 pga 1.1 ../audio/volume/volume.c:1195 ERROR VOLUME DONE
[ 183464.992710] ( 349.270813) c1 dai 1.6 src/audio/dai.c:970 ERROR DAI COPY_DONE
[ 203025.981516] ( 19560.988281) c1 pga 1.1 ../audio/volume/volume.c:1195 ERROR VOLUME DONE
[ 203365.825252] ( 339.843750) c1 dai 1.6 src/audio/dai.c:153 ERROR DMA CB DONE
[ 221972.387013] ( 18606.562500) c1 pga 1.1 ../audio/volume/volume.c:1195 ERROR VOLUME DONE

[jairaj-arava]

@abonislawski @bardliao @ranj063 @plbossart @sathya-nujella

[kv2019i]

@jairaj-arava Is this based purely on observing the logs or does this show up as a problem in the use case (in terms of runtime errors and/or measured audio latency)? The FW does use a buffer of multiple periods (we've had some recent discussion with @plbossart ) so FW can copy multiple periods as part of normal processing to save power.

[lgirdwood]

@jairaj-arava can you check topology in the following places

1. Host DMA - I think we have 2 or 3 periods in our buffers here to avoid R/W races between FW and HW.
2. DAI DMA - same as 1) but IIRC DW-DMA needed more periods for headroom for LLI.
3. pipeline definintion - there may be 2 period buffers in between some modules. Can you check your test pipeline and make sure these are set to 1 period.

We can possibly get away with minimum 2 periods for 1 & 2 above, but should be able to use 1 period in the pipeline where we are not doing IO with DMA.

[jairaj-arava]

@cujomalainey

[cujomalainey]

@jairaj-arava Is this based purely on observing the logs or does this show up as a problem in the use case (in terms of runtime errors and/or measured audio latency)?

The issue we are seeing is that latency caused by the DSP is approaching unacceptable levels even at 10ms for use cases like VC.

[cujomalainey]

@jairaj-arava can you check topology in the following places

1. Host DMA - I think we have 2 or 3 periods in our buffers here to avoid R/W races between FW and HW.
2. DAI DMA - same as 1) but IIRC DW-DMA needed more periods for headroom for LLI.
3. pipeline definintion - there may be 2 period buffers in between some modules. Can you check your test pipeline and make sure these are set to 1 period.

We can possibly get away with minimum 2 periods for 1 & 2 above, but should be able to use 1 period in the pipeline where we are not doing IO with DMA.

I think @lgirdwood proposed 3 and we tried it see change below. It did not yield any substantial results.

b/tools/topology/topology1/sof/pipe-volume-demux-playback.m4
index b3c096ed4..3241dadcb 100644
--- a/tools/topology/topology1/sof/pipe-volume-demux-playback.m4
+++ b/tools/topology/topology1/sof/pipe-volume-demux-playback.m4
@@ -72,7 +72,7 @@ W_MUXDEMUX(0, 1, PIPELINE_FORMAT, 2, 2,
SCHEDULE_CORE,
 W_BUFFER(0, COMP_BUFFER_SIZE(2,
        COMP_SAMPLE_SIZE(PIPELINE_FORMAT), PIPELINE_CHANNELS,
COMP_PERIOD_FRAMES(PCM_MAX_RATE, SCHEDULE_PERIOD)),
        PLATFORM_HOST_MEM_CAP)
-W_BUFFER(1, COMP_BUFFER_SIZE(2,
+W_BUFFER(1, COMP_BUFFER_SIZE(1,
        COMP_SAMPLE_SIZE(PIPELINE_FORMAT), PIPELINE_CHANNELS,
COMP_PERIOD_FRAMES(PCM_MAX_RATE, SCHEDULE_PERIOD)),
        PLATFORM_COMP_MEM_CAP)
 W_BUFFER(2, COMP_BUFFER_SIZE(DAI_PERIODS,

[ranj063]

@cujomalainey @lgirdwood I debugged this with @jairaj-arava and here's my conclusion. There is no 2x latency in the pipeline at all. What you see is because of flawed logic for printing the logs. Basically in dai_copy() when dma_copy() gets called, dai_dma_cb() get invoked right away but at that time, dd->test_dma is not set to true, so the "DMA CB DONE" never gets printed until after the dai_copy() runs again but this happens only after the second period dai_dma_cb() gets invoked.

@jairaj-arava please post the changes we used for debug for reference

[jairaj-arava]

Hi @cujomalainey,
As @ranj063 said, we used the new_changes_in_dai.patch that has corrected logic for the logs and couldn't see any latency in the pipeline as shown below

[ 118139.943222] ( 20.104166) c1 ssp-dai 1.1 /drivers/intel/ssp/ssp.c:1018 INFO ssp_early_start(): SSE set for SSP1
[ 118248.328635] ( 108.385414) c1 demux 1.2 src/audio/mux/mux.c:811 INFO mux_trigger(), command = 1
[ 118285.568216] ( 37.239582) c1 ssp-dai 1.1 /drivers/intel/ssp/ssp.c:1135 INFO ssp_trigger() cmd 1
[ 118304.318216] ( 18.750000) c1 ssp-dai 1.1 /drivers/intel/ssp/ssp.c:1033 INFO ssp_start()
[ 119955.568150] ( 1651.249878) c1 host 1.0 src/audio/host.c:1003 ERROR HOST COPY
[ 120122.651477] ( 167.083328) c1 pga 1.1 ../audio/volume/volume.c:1195 ERROR VOLUME DONE
[ 120219.005640] ( 96.354164) c1 dai 1.6 src/audio/dai.c:153 ERROR DMA CB DONE
[ 120246.505638] ( 27.499998) c1 dai 1.6 src/audio/dai.c:972 ERROR DAI COPY_DONE
[ 122115.672231] ( 1869.166626) c1 pga 1.1 ../audio/volume/volume.c:1195 ERROR VOLUME DONE

[cujomalainey]

Interesting, so DMA was so fast that we didn't even exit the copy callback before we got the DMA callback. Thanks for spotting the flaw in my code.

That being said, we are still measuring approximately 60ms of latency at 10ms periods via external testing.

[ranj063]

@cujomalainey are we certain that the latency is caused by audio in the test?

[cujomalainey]

We are not, I did not have a hand in building the test. I am working to have the system shared with Intel. Essentially timing is gained from an external board that communicated with a program on the dut via USB.

That being said, 1ms period measurements are only slightly higher than we expected, so assuming a constant adder from the test, it should not be causing the effect in theory.

[ranj063]

@cujomalainey in that case can we close this issue for now and open a new one when we have more details about the latency issue?

[jairaj-arava]

Hi @ranj063 ,
Seems, as @cujomalainey mentioned below, the issue is seen with the other test setup. I am talking to the team to have the setup and to replicate the same. Will keep posted here once I have the setup.

Interesting, so DMA was so fast that we didn't even exit the copy callback before we got the DMA callback. Thanks for spotting the flaw in my code.

That being said, we are still measuring approximately 60ms of latency at 10ms periods via external testing.