CRAS: recorded chunk of samples repeating |
|||||||||||
Issue description
Ben first found this reproduced using Hotwording on Kevin. And I continued from his test patch to found it's relatively easy to reproduce, around 1 out of 20 tries.
Basically I inspect all recorded raw data using Audacity, look for corrupted sound matching identical wave form of size 20ms. Then use the starting time of repeating samples to track back to the audio dump log.
The problem is revealed by below log, with some comments explaining the detail. In short, when client thread process shm ready callback slower than server receives data from hardware, overrun happens in shared memory. The overrun could happen like 6-8 times, and then client thread wake up, it handles the same buffer multiple times.
1198.159954623 READ_AUDIO dev:a hw_level:26879 read:160
1198.160210998 AUDIO_THREAD_WWW Write buffer offset (0, 0)
/* Read buffer has write offset 1920 */
1198.160213040 AUDIO_THREAD_RRR Read buffer offset (1920, 0)
/* Write buffer at shm #0 */
1198.160215082 CONV_COPY wr_buf:0 shm_writable:480 offset:0
1198.160254457 CAPTURE_WRITE stream:3a0000 write:480 shm_fr:0
1198.160274873 READ_AUDIO_DONE read_remainder:0
1198.160317165 CAPTURE_POST stream:3a0000 thresh:480 rd_buf:1
/* Read buffer at shm #1 */
1198.160415457 FILL_AUDIO_TSTAMP dev:5 tstamp:000001198.160413707
1198.160418373 FILL_AUDIO dev:5 hw_level:1698
1198.160425082 WRITE_STREAMS_STREAM id:360000 shm_frames:1024 cb_pending:1
1198.160430915 WRITE_STREAMS_MIX write_limit:1024 max_offset:0
1198.160542040 DEV_STREAM_MIX written:1024 read:1024
1198.160543790 WRITE_STREAMS_MIXED write_limit:1024
1198.162294957 FILL_AUDIO_DONE hw_level:1698 total_written:1024 min_cb_level:1024
1198.162376623 SET_DEV_WAKE dev:5 hw_level:2628 sleep:2628
1198.162378082 DEV_SLEEP_TIME dev:5 wake:000001198.217123998
1198.162380123 DEV_SLEEP_TIME dev:a wake:000001198.160938082
1198.162383623 SLEEP sleep:000000000.000000000 longest_wake:002766167
1198.162395582 WAKE num_fds:1
1198.162627165 READ_AUDIO_TSTAMP dev:a tstamp:000001198.162625415
1198.162659540 BZ_SET_CAP_TS0 dev:a tstamp:000001196.492747009
1198.162660707 BZ_SET_CAP_TS1 rate=48000, stream_frames=80157, delay_frames=26719
1198.162673540 BZ_SET_CAP_TS0 dev:a tstamp:000001196.492761301
1198.162674998 BZ_SET_CAP_TS1 rate=48000, stream_frames=80157, delay_frames=26719
1198.162677623 READ_AUDIO dev:a hw_level:26719 read:160
1198.162911248 AUDIO_THREAD_WWW Write buffer offset (0, 0)
/* Read buffer's write offset got set to zero */
1198.162912707 AUDIO_THREAD_RRR Read buffer offset (0, 0) // <----------
/* Write buffer has moved to shm #1 */
1198.162914165 CONV_COPY wr_buf:1 shm_writable:480 offset:0
1198.162953540 CAPTURE_WRITE stream:3a0000 write:480 shm_fr:0
1198.162971040 READ_AUDIO_DONE read_remainder:0
/* Read buffer still at shm #1, client thread hasn't processed yet */
1198.163042207 CAPTURE_POST stream:3a0000 thresh:480 rd_buf:1
To address this issue, we need to add reasonable check before calling cras_shm_check_write_overrun() to reset the write pointer off read buffer.
,
Nov 7 2016
We should first fix that. Then we should figure out how to get the client thread scheduled more reliably.
,
Nov 21 2016
The following revision refers to this bug: https://chromium.googlesource.com/chromiumos/third_party/adhd/+/29f2d63ef874e146553f4c871c1ce23517efda6e commit 29f2d63ef874e146553f4c871c1ce23517efda6e Author: Hsin-Yu Chao <hychao@chromium.org> Date: Tue Nov 08 07:22:02 2016 CRAS: audio_thread - Avoid using MIN macro MIN() macro would make function called twice and sometimes that wastes a lot of computation. BUG= chromium:662886 TEST=None Change-Id: I800633caf152f1e13e03c29ff9e278ba5180a815 Reviewed-on: https://chromium-review.googlesource.com/409236 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/29f2d63ef874e146553f4c871c1ce23517efda6e/cras/src/server/audio_thread.c
,
Nov 23 2016
The following revision refers to this bug: https://chromium.googlesource.com/chromiumos/third_party/adhd/+/443a8d0eb551cc101e6354c668765b2e3d2371d9 commit 443a8d0eb551cc101e6354c668765b2e3d2371d9 Author: Hsin-Yu Chao <hychao@chromium.org> Date: Thu Nov 17 10:17:40 2016 CRAS: client - Don't read repeated data CRAS client could handles multiple messages from server about capture data ready. We should check if the read offset of stream shm reaches write offset, to avoid reading repeated data. BUG= chromium:662886 TEST=Execute 'cras_test_client --capture_file /tmp/1' and then hit 'p', 'enter', 'p', 'enter'... repeat 10 times while making some sound to internal mic. Inspect the recorded /tmp/1 file using Audacity to verify there are no repeated samples, but with several short discontinuity instead. Change-Id: I40bf34cbae31f76bd013ec855a4d5ef4055399f2 Reviewed-on: https://chromium-review.googlesource.com/411668 Commit-Ready: Nicolas Boichat <drinkcat@chromium.org> Tested-by: Hsinyu Chao <hychao@chromium.org> Reviewed-by: Dylan Reid <dgreid@chromium.org> [modify] https://crrev.com/443a8d0eb551cc101e6354c668765b2e3d2371d9/cras/src/tests/cras_test_client.c [modify] https://crrev.com/443a8d0eb551cc101e6354c668765b2e3d2371d9/cras/src/libcras/cras_client.c [modify] https://crrev.com/443a8d0eb551cc101e6354c668765b2e3d2371d9/cras/src/common/cras_shm.h
,
Nov 23 2016
The following revision refers to this bug: https://chromium.googlesource.com/chromiumos/third_party/adhd/+/fe3b32adb850b6637934195ec2a0055fb9199ce5 commit fe3b32adb850b6637934195ec2a0055fb9199ce5 Author: Hsin-Yu Chao <hychao@chromium.org> Date: Fri Nov 18 09:29:22 2016 CRAS: audio_thread - Log when input stream overruns Fix cras_shm_check_write_overrun() function in detecting when unread data is overwritten, and return the result so audio thread can ATLOG this problem. BUG= chromium:662886 TEST=Use 'cras_test_client --capture_file /tmp/1' and hit 'p','enter' a few times to emulate a bad client. Check audio dump to veriy there's AUDIO_OVERRUN logged. Change-Id: Ib5b90ce05d957487b29639dffbbe3067ab5f6915 Reviewed-on: https://chromium-review.googlesource.com/412428 Commit-Ready: Nicolas Boichat <drinkcat@chromium.org> Tested-by: Hsinyu Chao <hychao@chromium.org> Reviewed-by: Dylan Reid <dgreid@chromium.org> [modify] https://crrev.com/fe3b32adb850b6637934195ec2a0055fb9199ce5/cras/src/tests/shm_unittest.cc [modify] https://crrev.com/fe3b32adb850b6637934195ec2a0055fb9199ce5/cras/src/tests/cras_test_client.c [modify] https://crrev.com/fe3b32adb850b6637934195ec2a0055fb9199ce5/cras/src/server/audio_thread.c [modify] https://crrev.com/fe3b32adb850b6637934195ec2a0055fb9199ce5/cras/src/common/cras_shm.h [modify] https://crrev.com/fe3b32adb850b6637934195ec2a0055fb9199ce5/cras/src/common/cras_types.h
,
Nov 25 2016
,
Nov 25 2016
Your change meets the bar and is auto-approved for M56 (branch: 2924)
,
Nov 25 2016
The following revision refers to this bug: https://chromium.googlesource.com/chromiumos/third_party/adhd/+/156560d7e296b1035e98537a8f280526675fe0ca commit 156560d7e296b1035e98537a8f280526675fe0ca Author: Hsin-Yu Chao <hychao@chromium.org> Date: Thu Nov 17 10:17:40 2016 CRAS: client - Don't read repeated data CRAS client could handles multiple messages from server about capture data ready. We should check if the read offset of stream shm reaches write offset, to avoid reading repeated data. BUG= chromium:662886 TEST=Execute 'cras_test_client --capture_file /tmp/1' and then hit 'p', 'enter', 'p', 'enter'... repeat 10 times while making some sound to internal mic. Inspect the recorded /tmp/1 file using Audacity to verify there are no repeated samples, but with several short discontinuity instead. Change-Id: I40bf34cbae31f76bd013ec855a4d5ef4055399f2 Reviewed-on: https://chromium-review.googlesource.com/411668 Commit-Ready: Nicolas Boichat <drinkcat@chromium.org> Tested-by: Hsinyu Chao <hychao@chromium.org> Reviewed-by: Dylan Reid <dgreid@chromium.org> (cherry picked from commit 443a8d0eb551cc101e6354c668765b2e3d2371d9) Reviewed-on: https://chromium-review.googlesource.com/414845 Reviewed-by: Hsinyu Chao <hychao@chromium.org> Commit-Queue: Hsinyu Chao <hychao@chromium.org> [modify] https://crrev.com/156560d7e296b1035e98537a8f280526675fe0ca/cras/src/tests/cras_test_client.c [modify] https://crrev.com/156560d7e296b1035e98537a8f280526675fe0ca/cras/src/libcras/cras_client.c [modify] https://crrev.com/156560d7e296b1035e98537a8f280526675fe0ca/cras/src/common/cras_shm.h
,
Nov 25 2016
The following revision refers to this bug: https://chromium.googlesource.com/chromiumos/third_party/adhd/+/9471b6ec01faf8afd30be16b19acecc39f3b13ab commit 9471b6ec01faf8afd30be16b19acecc39f3b13ab Author: Hsin-Yu Chao <hychao@chromium.org> Date: Fri Nov 18 09:29:22 2016 CRAS: audio_thread - Log when input stream overruns Fix cras_shm_check_write_overrun() function in detecting when unread data is overwritten, and return the result so audio thread can ATLOG this problem. BUG= chromium:662886 TEST=Use 'cras_test_client --capture_file /tmp/1' and hit 'p','enter' a few times to emulate a bad client. Check audio dump to veriy there's AUDIO_OVERRUN logged. Change-Id: Ib5b90ce05d957487b29639dffbbe3067ab5f6915 Reviewed-on: https://chromium-review.googlesource.com/412428 Commit-Ready: Nicolas Boichat <drinkcat@chromium.org> Tested-by: Hsinyu Chao <hychao@chromium.org> Reviewed-by: Dylan Reid <dgreid@chromium.org> (cherry picked from commit fe3b32adb850b6637934195ec2a0055fb9199ce5) Reviewed-on: https://chromium-review.googlesource.com/414846 Reviewed-by: Hsinyu Chao <hychao@chromium.org> Commit-Queue: Hsinyu Chao <hychao@chromium.org> [modify] https://crrev.com/9471b6ec01faf8afd30be16b19acecc39f3b13ab/cras/src/tests/shm_unittest.cc [modify] https://crrev.com/9471b6ec01faf8afd30be16b19acecc39f3b13ab/cras/src/tests/cras_test_client.c [modify] https://crrev.com/9471b6ec01faf8afd30be16b19acecc39f3b13ab/cras/src/server/audio_thread.c [modify] https://crrev.com/9471b6ec01faf8afd30be16b19acecc39f3b13ab/cras/src/common/cras_shm.h [modify] https://crrev.com/9471b6ec01faf8afd30be16b19acecc39f3b13ab/cras/src/common/cras_types.h
,
Nov 28 2016
Request merge to M55
,
Nov 28 2016
[Automated comment] Less than 2 weeks to go before stable on M55, manual review required.
,
Nov 28 2016
Do we really need this in 55? At this point I would be tempted to skip it unless this is a blocking regression (kevin hotwording in the initial report would not block here IMO), stable RC is targeting this week. If we really need this please let me know.
,
Nov 29 2016
I think it's fine to skip M55. Thanks!
,
May 30 2017
,
Aug 1 2017
,
Aug 4 2017
Verified in Chrome OS 9807.0.0, 62.0.3176.0. |
|||||||||||
►
Sign in to add a comment |
|||||||||||
Comment 1 by grunell@chromium.org
, Nov 7 2016