-
Notifications
You must be signed in to change notification settings - Fork 314
New issue
Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.
By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.
Already on GitHub? Sign in to your account
ADL: Audio latency of (~2n) is obserbed during the speaker playback for n period #8011
Comments
@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. |
@jairaj-arava can you check topology in the following places
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. |
The issue we are seeing is that latency caused by the DSP is approaching unacceptable levels even at 10ms for use cases like VC. |
I think @lgirdwood proposed 3 and we tried it see change below. It did not yield any substantial results.
|
@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 |
Hi @cujomalainey, [ 118139.943222] ( 20.104166) c1 ssp-dai 1.1 /drivers/intel/ssp/ssp.c:1018 INFO ssp_early_start(): SSE set for SSP1 |
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. |
@cujomalainey are we certain that the latency is caused by audio in the test? |
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. |
@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? |
Hi @ranj063 ,
|
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
The text was updated successfully, but these errors were encountered: