CRAS: input device reports full hw buffer after calling flush_buffer() |
|||||||
Issue descriptionNoticed this problem on two KBL platforms. It can be reproduced by: (1) run /usr/bin/cras with valgrind (2) using input stream with system AEC enabled. Observed this problem during another AEC related work. My customized log below reveals the issue: 2018-08-22T00:01:56.448938+08:00 ERR cras_server[15509]: [APM] set rmodule ext to dev Silent playback device. 2018-08-22T00:01:56.459935+08:00 ERR cras_server[15509]: Echo ref dev 0x5fdfbf0 2018-08-22T00:01:56.461488+08:00 ERR cras_server[15509]: [APM] set rmodule ext to dev kblmax98373: :0,2 // cras_iodev_open to internal mic 2018-08-22T00:02:07.080312+08:00 ERR cras_server[15509]: add_ext_dsp_module_to_pipeline dev kblmax98373: :0,4, ext 0x6d0bbd0 2018-08-22T00:02:07.081219+08:00 ERR cras_server[15509]: COnfigured padding 240 2018-08-22T00:02:07.102071+08:00 ERR cras_server[15509]: Dev level: 944 2018-08-22T00:02:07.105327+08:00 ERR cras_server[15509]: Dev get buf, request 944 2018-08-22T00:02:07.110282+08:00 ERR cras_server[15509]: input_data_run 944 frames 2018-08-22T00:02:07.111556+08:00 ERR cras_server[15509]: After run, fbuffer level 1184 2018-08-22T00:02:07.114131+08:00 ERR cras_server[15509]: Dev put 944 2018-08-22T00:02:07.114659+08:00 ERR cras_server[15509]: fbuffer read 944, left 240 // In main thread, // create APM instance, takes 0.19 seconds which exceeds 8192/48000 2018-08-22T00:02:07.118334+08:00 ERR cras_server[15509]: Opening dev kblmax98373: :0,4, echo_reference_dev (null) 2018-08-22T00:02:07.300347+08:00 ERR cras_server[15509]: audio processing config: 2018-08-22T00:02:07.306297+08:00 ERR cras_server[15509]: pre amp gain 3.600000 // In audio thread // appending the 1st input stream, iodev should flush old buffer 2018-08-22T00:02:07.355340+08:00 ERR cras_server[15509]: Flush input buffer for dev kblmax98373: :0,4 2018-08-22T00:02:07.357632+08:00 ERR cras_server[15509]: pcm_avail returned frames larger than buf_size: kblmax98373: :0,4: 11568 > 8192 for 1 times // frame queued returns full buffer of 8192 frames, which is not correct. 2018-08-22T00:02:07.357878+08:00 ERR cras_server[15509]: Dev level: 8192 My guess is that, if main thread, for some reason, takes too long between open iodev and attaching the 1st stream, causing input dev to have full buffer. Then the immediate call to flush_buffer() will not successfully do what we expect. Will investigate more and post update on this issue.
,
Aug 29
The following revision refers to this bug: https://chromium.googlesource.com/chromiumos/third_party/adhd/+/80ffce30f0c57d685406f532ba637d92a69ec7ef commit 80ffce30f0c57d685406f532ba637d92a69ec7ef Author: Hsin-Yu Chao <hychao@chromium.org> Date: Wed Aug 29 18:15:07 2018 CRAS: iodev - Fix input_dsp_offset calculation There's case when number of frames read from input device is smaller than the last tracked input_dsp_offset. Updating the input_dsp_offset for next thread wake up should base on the max number of frames that has input dsp applied. BUG= chromium:876333 TEST=Test normal recording, and recording with AEC effect. Change-Id: I749c6f06ee6920b3d3bd7011fe04f5c0cf6be1a4 Reviewed-on: https://chromium-review.googlesource.com/1188053 Commit-Ready: Hsinyu Chao <hychao@chromium.org> Tested-by: Hsinyu Chao <hychao@chromium.org> Reviewed-by: Dylan Reid <dgreid@chromium.org> [modify] https://crrev.com/80ffce30f0c57d685406f532ba637d92a69ec7ef/cras/src/tests/iodev_unittest.cc [modify] https://crrev.com/80ffce30f0c57d685406f532ba637d92a69ec7ef/cras/src/server/cras_iodev.c
,
Aug 29
The following revision refers to this bug: https://chromium.googlesource.com/chromiumos/third_party/adhd/+/6240415074048b5593c9613a542fd2034cbdbf95 commit 6240415074048b5593c9613a542fd2034cbdbf95 Author: Hsin-Yu Chao <hychao@chromium.org> Date: Wed Aug 29 18:15:08 2018 CRAS: alsa_io - Sync avail frames before forward snd_pcm_forwardable calculation is only based on buffer pointer in user space. That means the returned forwardable number can be much less than the real hw buffer level. This causes unexpected large delay for input. Fix this by adding a call to snd_pcm_avail before that to sync with hw pointer, so that the following forward call can actually flush most of the buffer. BUG= chromium:876333 TEST=Create input stream right after CRAS starts, add log or check cras_test_client --dump_a that input dev level can stay reasonable low level. Change-Id: Icc1b0776546f7f9da44f3eb9790fe541238bd3cc Reviewed-on: https://chromium-review.googlesource.com/1188054 Commit-Ready: Hsinyu Chao <hychao@chromium.org> Tested-by: Hsinyu Chao <hychao@chromium.org> Reviewed-by: Cheng-Yi Chiang <cychiang@chromium.org> Reviewed-by: Dylan Reid <dgreid@chromium.org> [modify] https://crrev.com/6240415074048b5593c9613a542fd2034cbdbf95/cras/src/server/cras_alsa_io.c
,
Sep 3
Need this be merge to M69 to stabilize audio capture
,
Sep 3
This bug requires manual review: We are only 0 days from stable. Please contact the milestone owner if you have questions. Owners: amineer@(Android), kariahda@(iOS), cindyb@(ChromeOS), govind@(Desktop) For more details visit https://www.chromium.org/issue-tracking/autotriage - Your friendly Sheriffbot
,
Sep 3
update subject as the root cause is for all boards.
,
Sep 4
Merge approved, M69.
,
Sep 5
The following revision refers to this bug: https://chromium.googlesource.com/chromiumos/third_party/adhd/+/9affeb50eaae8bdae2441c55db8307384bd8114f commit 9affeb50eaae8bdae2441c55db8307384bd8114f Author: Hsin-Yu Chao <hychao@chromium.org> Date: Wed Sep 05 03:32:48 2018 CRAS: iodev - Fix input_dsp_offset calculation There's case when number of frames read from input device is smaller than the last tracked input_dsp_offset. Updating the input_dsp_offset for next thread wake up should base on the max number of frames that has input dsp applied. BUG= chromium:876333 TEST=Test normal recording, and recording with AEC effect. Change-Id: I749c6f06ee6920b3d3bd7011fe04f5c0cf6be1a4 Reviewed-on: https://chromium-review.googlesource.com/1188053 Commit-Ready: Hsinyu Chao <hychao@chromium.org> Tested-by: Hsinyu Chao <hychao@chromium.org> Reviewed-by: Dylan Reid <dgreid@chromium.org> (cherry picked from commit 80ffce30f0c57d685406f532ba637d92a69ec7ef) Reviewed-on: https://chromium-review.googlesource.com/1206090 Reviewed-by: Hsinyu Chao <hychao@chromium.org> Commit-Queue: Hsinyu Chao <hychao@chromium.org> [modify] https://crrev.com/9affeb50eaae8bdae2441c55db8307384bd8114f/cras/src/tests/iodev_unittest.cc [modify] https://crrev.com/9affeb50eaae8bdae2441c55db8307384bd8114f/cras/src/server/cras_iodev.c
,
Sep 5
The following revision refers to this bug: https://chromium.googlesource.com/chromiumos/third_party/adhd/+/2f54e38065c21b7747c93da7ab31cf0cc77d4736 commit 2f54e38065c21b7747c93da7ab31cf0cc77d4736 Author: Hsin-Yu Chao <hychao@chromium.org> Date: Wed Sep 05 03:41:22 2018 CRAS: alsa_io - Sync avail frames before forward snd_pcm_forwardable calculation is only based on buffer pointer in user space. That means the returned forwardable number can be much less than the real hw buffer level. This causes unexpected large delay for input. Fix this by adding a call to snd_pcm_avail before that to sync with hw pointer, so that the following forward call can actually flush most of the buffer. BUG= chromium:876333 TEST=Create input stream right after CRAS starts, add log or check cras_test_client --dump_a that input dev level can stay reasonable low level. Change-Id: Icc1b0776546f7f9da44f3eb9790fe541238bd3cc Reviewed-on: https://chromium-review.googlesource.com/1188054 Commit-Ready: Hsinyu Chao <hychao@chromium.org> Tested-by: Hsinyu Chao <hychao@chromium.org> Reviewed-by: Cheng-Yi Chiang <cychiang@chromium.org> Reviewed-by: Dylan Reid <dgreid@chromium.org> (cherry picked from commit 6240415074048b5593c9613a542fd2034cbdbf95) Reviewed-on: https://chromium-review.googlesource.com/1206091 Reviewed-by: Hsinyu Chao <hychao@chromium.org> Commit-Queue: Hsinyu Chao <hychao@chromium.org> [modify] https://crrev.com/2f54e38065c21b7747c93da7ab31cf0cc77d4736/cras/src/server/cras_alsa_io.c
,
Sep 6
Done merge to R69. |
|||||||
►
Sign in to add a comment |
|||||||
Comment 1 by hychao@chromium.org
, Aug 24