Closed Bug 1012936 Opened 11 years ago Closed 10 years ago

WebRTC audio on Flame broken up in calls

Categories

(Core :: WebRTC: Audio/Video, defect)

Product:
Core
Component:
WebRTC: Audio/Video
Platform:
ARM
Gonk (Firefox OS)
Type:
defect
Priority:
Not set
Severity:
critical

Tracking

()

Status:
RESOLVED FIXED

People

(Reporter: jesup, Assigned: shell)

References

Details

(Whiteboard: [p=0])

Attachments

(3 files)

logcat on mediaserver
4.83 MB, patch
Details | Diff | Splinter Review
webrtc profiling data
2.21 MB, application/zip
Details
logcat for audio log
24.00 KB, patch
Details | Diff | Splinter Review
Copied from bug 1003749 comment 11 by :rlin. This appears to be a separate bug from the inability to reopen audio there. This sounds like a vendor issue. --------------- Test with gecko:182867:7f5a8526b55a at central on v10F-3 ROM image. WebRTC using VP8 codec and connect to desktop, The symptom changes to broken sound. You can see this kind of logs keep output on logcat. D/AudioResourceManager( 301): key = USECASE_PCM_RECORDING, value = true, useCase = 1 D/AudioResourceManager( 301): checkUseCaseConflict = 1 D/mm-camera-intf( 301): mm_stream_read_msm_frame: VIDIOC_DQBUF buf_index 2, frame_idx 2404, stream type 7 D/AudioResourceManager( 301): usecase = 7 , refCount =0, maxrefcount =2 D/AudioResourceManager( 301): usecase = 10 , refCount =0, maxrefcount =1 D/AudioResourceManager( 301): updateUsecaseRefCount useCase=1,value=1,desc->refCount=378 D/AudioResourceManager( 301): updateUsecaseRefCount useCase = 1, refCount =379 That means audio HAL layer try to enable/disable audio codec again and again...
needinfo-ing frlee to look into this (with vendor if/as needed). rlin, can you attach a more complete log?
Flags: needinfo?(rlin)
Flags: needinfo?(frlee)
The mediaserver log is for this issue. We can found the audio HAL keep re-enabling and disabling.
Flags: needinfo?(rlin)
Randy, can you recheck with the 10G-2 firmware? Bug 1008017 appears fixed now as well, and I don't see this issue in the logs there
Flags: needinfo?(rlin)
I think I'm hearing the problem myself; with v10G-2 I'm getting audio, with with loud random/periodic pops
Hey Shell, I marked the whiteboard to indicate that we believe this is a vendor issue and we need it for Loop. Can you confirm we're flagging this to the vendor? Thanks.
Flags: needinfo?(sescalante)
Whiteboard: [p=0, POVB, ft:loop]
Hi Randell, As my testing on v10G-2, [ro.build.date]: [Tue May 20 09:29:20 CST 2014] gecko: 6/2 Still found the audio HAL keeps opening and closing. D/AudioHardwareALSA( 292): AudioResourceManager - setParameter D/AudioResourceManager( 292): setParameter USECASE_PCM_RECORDING=true: D/AudioResourceManager( 292): key = USECASE_PCM_RECORDING, value = true, useCase = 1 D/AudioResourceManager( 292): checkUseCaseConflict = 1 D/AudioResourceManager( 292): usecase = 7 , refCount =1, maxrefcount =2 D/AudioResourceManager( 292): usecase = 10 , refCount =0, maxrefcount =1 D/AudioResourceManager( 292): updateUsecaseRefCount useCase=1,value=1,desc->refCount=387 <=== keep increasing
Flags: needinfo?(rlin)
feature-b2g: --- → 2.0
Shell -- I saw your email. Thanks for flagging this to the vendor. I'm making you the assignee until we find the right person to hand this off to.
Assignee: nobody → sescalante
Flags: needinfo?(sescalante)
Blocks: Loopmov_1_1
Hi Randell - Could you let know how to test WebRTC on Flame once we flash master gaia/gecko onto it? Thanks Vance
Flags: needinfo?(rjesup)
I was using talky.io in a two-flame call, v10G-2 base. This was with the mercurial patch queue at http://hg.mozilla.org/users/rjesup_wgate.com/h264_omx (in particular the first 2 patches there). I'll note I didn't hear breakup in http://mozilla.github.com/webrtc-landing/gum_test.html (though note audio there will be 'odd' since the echo canceller is trying to cancel out your audio).
Flags: needinfo?(rjesup)
based on comment 7, issue has been flagged to vendor. remove my NI.
Flags: needinfo?(frlee)
*Test flame with BuildID 20140609040203 I try to make the video call from flame to desktop with vp8 codec. On desktop side, I can hear the pop-sounds repeatly. Check the log in logcat and found the fifo_ object in opensles_input.cc may become full on frame device. In this function: void OpenSlesInput::RecorderSimpleBufferQueueCallbackHandler( SLAndroidSimpleBufferQueueItf queue_itf) { ALOGE("RecorderSimpleBufferQueueCallbackHandler %d %d", fifo_->size(), fifo_->capacity()); if (fifo_->size() >= fifo_->capacity() || number_overruns_ > 0) { ++number_overruns_; event_.SignalEvent(kOverrun, number_overruns_); return; } Insert log and found: E/AudioRecord(13872): EVENT_MORE_DATA size 194 fr 97 E/AudioRecord(13872): RecorderSimpleBufferQueueCallbackHandler 6 8 E/AudioRecord(13872): EVENT_MORE_DATA size 688 fr 1024 E/AudioRecord(13872): RecorderSimpleBufferQueueCallbackHandler 7 8 E/AudioRecord(13872): EVENT_MORE_DATA size 882 fr 680 E/AudioRecord(13872): EVENT_MORE_DATA size 478 fr 239 E/AudioRecord(13872): SendAudioFrame 480 48000 E/AudioRecord(13872): RecorderSimpleBufferQueueCallbackHandler 7 8 E/AudioRecord(13872): EVENT_MORE_DATA size 404 fr 1024 E/AudioRecord(13872): RecorderSimpleBufferQueueCallbackHandler 8 8 When fifo_ object is full, It would go through the bool OpenSlesInput::HandleOverrun function() Then restart the audio record task. That would cause the pop-sound. Also I can notice the voice lagging(delay) problem on desktop side. BTW, I can't found those problems on nexus-4 device.
The flame CPU's usage reach more than 90% on vp8 case. User 58%, System 36%, IOW 0%, IRQ 0% User 213 + Nice 420 + Sys 394 + Idle 45 + IOW 0 + IRQ 0 + SIRQ 7 = 1079 PID TID PR CPU% S VSS RSS PCY UID Thread Proc 1128 1986 0 17% S 147444K 64928K u0_a1128 opensl_rec_thre /system/b2g/plugin-container 290 561 0 16% R 213932K 92548K root Gecko_IOThread /system/b2g/b2g 290 290 0 16% S 213932K 92548K root b2g /system/b2g/b2g 1128 1570 1 7% S 147444K 64928K u0_a1128 MediaStreamGrph /system/b2g/plugin-container 290 898 0 6% S 213932K 92548K root Compositor /system/b2g/b2g 1128 2032 0 4% S 147444K 64928K u0_a1128 ViECaptureThrea /system/b2g/plugin-container 1128 1128 1 3% S 147444K 64928K u0_a1128 Browser /system/b2g/plugin-container 290 647 0 2% S 213932K 92548K root BgHangManager /system/b2g/b2g 1128 2031 1 1% S 147444K 64928K u0_a1128 ProcessThread /system/b2g/plugin-container 1128 1136 0 1% S 147444K 64928K u0_a1128 ImageBridgeChil /system/b2g/plugin-container By issuing "adb shell ps -p -t" and check the thread NICE/RTPRI value. USER PID PPID VSIZE RSS PRIO NICE RTPRI SCHED WCHAN PC NAME u0_a1128 1128 910 147444 64260 21 1 0 0 ffffffff b6ea263c S /system/b2g/plugin-container u0_a1128 1129 1128 147444 64260 21 1 0 0 c029cd98 b6ea263c S Chrome_ChildThr u0_a1128 1130 1128 147444 64260 21 1 0 0 c01d5750 b6ea2808 S Analysis Helper u0_a1128 1131 1128 147444 64260 21 1 0 0 c01d5750 b6ea2808 S Analysis Helper u0_a1128 1132 1128 147444 64260 21 1 0 0 c026fc44 b6ea26c4 S Socket Thread u0_a1128 1133 1128 147444 64260 21 1 0 0 c01d5750 b6ea2808 S BgHangManager u0_a1128 1134 1128 147444 64260 21 1 0 0 c026fc44 b6ea26c4 S (Nuwa) u0_a1128 1135 1128 147444 64260 21 1 0 0 c01d5750 b6ea2808 S Timer u0_a1128 1136 1128 147444 64260 21 1 0 0 c01d5750 b6ea2808 S ImageBridgeChil u0_a1128 1137 1128 147444 64260 21 1 0 0 c01d5750 b6ea2808 S BufferMgrChild u0_a1128 1139 1128 147444 64260 20 0 0 0 00000000 b6ea14f8 R Binder_1 u0_a1128 1140 1128 147444 64260 20 0 0 0 c0659adc b6ea14f8 S Binder_2 u0_a1128 1141 1128 147444 64260 21 1 0 0 c01d5750 b6ea2808 S BufferMgrChild u0_a1128 1483 1128 147444 64260 21 1 0 0 c01d5750 b6ea2808 S Net Predictor u0_a1128 1484 1128 147444 64260 21 1 0 0 c01d5750 b6ea2808 S HTML5 Parser u0_a1128 1502 1128 147444 64260 21 1 0 0 c01d5750 b6ea2808 S MediaManager u0_a1128 1563 1128 147444 64260 21 1 0 0 c01d5750 b6ea2808 S Trace u0_a1128 1566 1128 147444 64260 21 1 0 0 c01d5750 b6ea2808 S ProcessThread u0_a1128 1568 1128 147444 64260 21 1 0 0 c01d5750 b6ea2808 S CameraThread u0_a1128 1569 1128 147444 64260 21 1 0 0 c01d5750 b6ea2808 S Latency Logger u0_a1128 1570 1128 147444 64260 21 1 0 0 c01d5750 b6ea2808 S MediaStreamGrph u0_a1128 1602 1128 147444 64260 6 -14 0 0 c01d5750 b6ea2808 S Browser u0_a1128 1603 1128 147444 64260 6 -14 0 0 c026fc44 b6ea1644 S Browser u0_a1128 1604 1128 147444 64260 6 -14 0 0 c01d5750 b6ea2808 S Browser u0_a1128 1605 1128 147444 64260 6 -14 0 0 c01d5750 b6ea2808 S Browser u0_a1128 1615 1128 147444 64260 20 0 0 0 c0659adc b6ea14f8 S Binder_3 u0_a1128 1618 1128 147444 64260 4 -16 0 0 c01d5750 b6ea2808 S AudioTrack u0_a1128 1634 1128 147444 64260 4 -16 0 0 c01d5750 b6ea2808 S AudioTrack u0_a1128 1652 1128 147444 64260 20 0 0 0 c0659adc b6ea14f8 S Binder_4 u0_a1128 1689 1128 147444 64260 20 0 0 0 c0659adc b6ea14f8 S Binder_5 u0_a1128 1983 1128 147444 64260 21 1 0 0 c01d5750 b6ea2808 S CameraThread u0_a1128 1985 1128 147444 64260 4 -16 0 0 c01d5750 b6ea2808 S AudioRecord u0_a1128 1986 1128 147444 64260 21 1 0 0 c07c926c b6ea1234 S opensl_rec_thre u0_a1128 2026 1128 147444 64260 21 1 0 0 c01d5750 b6ea2808 S Sys Load Info u0_a1128 2028 1128 147444 64260 4 -16 0 0 c01d5750 b6ea2808 S AudioTrack u0_a1128 2030 1128 147444 64260 21 1 0 0 c01d5750 b6ea2808 S ProcessThread u0_a1128 2031 1128 147444 64260 21 1 0 0 c01d5750 b6ea2808 S ProcessThread u0_a1128 2032 1128 147444 64260 21 1 0 0 c01d5750 b6ea2808 S ViECaptureThrea u0_a1128 2033 1128 147444 64260 21 1 0 0 c01d5750 b6ea2808 S DecodingThread u0_a1128 2034 1128 147444 64260 21 1 0 0 c01d5750 b6ea2808 S IncomingVideoSt u0_a1128 2035 1128 147444 64260 21 1 0 0 c01d5750 b6ea2808 S WebRtc_event_ti u0_a1128 2037 1128 147444 64260 4 -16 0 0 c01d5750 b6ea2808 S AudioTrack Looks like "opensl_rec_thread"'s priority isn't high enough. Hi Jesup, is it possible to assign nice value in "opensl_rec_thread" as "AudioRecord"?
Flags: needinfo?(rjesup)
Attached file webrtc profiling data —
I profile webrtc by the latest gecko this morning. Here are the settings. video resolution: 320x240 (both sides) video codec: vp8 audio codec: opus
For the comment 11/12 I tested with the engineer build. Test again on today's pvt user build on flame. Connect from flame to Desktop with vp8 codec (320x240 video frame size) The top result is here. (adb shell top -m 20 -t) User 60%, System 27%, IOW 0%, IRQ 1% User 143 + Nice 281 + Sys 190 + Idle 73 + IOW 0 + IRQ 0 + SIRQ 13 = 700 PID TID PR CPU% S VSS RSS PCY UID Thread Proc 5864 7177 0 10% S 132344K 56436K u0_a5864 opensl_rec_thre /system/b2g/plugin-container 5041 5076 0 8% R 214972K 90400K root Compositor /system/b2g/b2g 5864 6650 0 7% R 132224K 56436K u0_a5864 MediaStreamGrph /system/b2g/plugin-container 5041 5041 1 6% S 214972K 90400K root b2g /system/b2g/b2g 5864 5864 1 4% S 132224K 56436K u0_a5864 Browser /system/b2g/plugin-container 5864 7230 1 4% S 132344K 56436K u0_a5864 DecodingThread /system/b2g/plugin-container 5864 5869 0 4% S 132224K 56436K u0_a5864 Socket Thread /system/b2g/plugin-container 5864 7229 0 3% S 132344K 56436K u0_a5864 ViECaptureThrea /system/b2g/plugin-container 397 7206 0 2% S 35548K 10004K camera mm-qcamera-daem /system/bin/mm-qcamera-daemon 5041 5054 0 2% S 214972K 90400K root Socket Thread /system/b2g/b2g 5864 5865 0 2% S 132224K 56436K u0_a5864 Chrome_ChildThr /system/b2g/plugin-container 5041 5050 0 2% S 214972K 90400K root Gecko_IOThread /system/b2g/b2g On the engineer build, the cpu usage on the opensl_rec_thread is higher than the user build. This result is similar to comment 13.
Flags: needinfo?(rjesup)
Dears, could you pls provide the issue phenomenon and reproduce step in detail tks.
hi Randy, Youlong and yanan are T2M's contact window. please kindly provide logs and image you tested today. (i supposed that you tested the latest V122 or V121-2 + v2.0 gaia/gecko)
Flags: needinfo?(rlin)
This result based on the v122 plus 17th June's gecko. I use the desktop Firefox nightly and connect to flame device with vp8 video codec and set the the frame size to 320*240. On laptop side, I can hear the pop noise. Check the logcat log and I can found the audio driver keeps opening and closing.
Flags: needinfo?(rlin)
I realized that the AEC Mobile patch for gonk from Bug 979716 never was landed, though it was r+'d. I tried it and it reduces the CPU use on opensl_rec_thread noticeably (~20% to ~15-6%), and made the pops go away for me. I also tried it with some additional patches from that bug that aren't r+'d (bitrate 16000, and complexity 1). The combination seems to cut it a few % additional (to ~12-13%); per that bug if we want to reduce the complexity we should benchmark the different options. This was measured using "top -t | grep open" in an adb shell. Randy - can you give this a try? If you still hear pops, can you try those other two patches? (Note that you can try this without even a build; it's just a pref change). Thanks!!!!
Flags: needinfo?(rlin)
This doesn't really belong under the feature-b2g flag, as this is a vendor issue.
feature-b2g: 2.0 → ---
Component: WebRTC: Audio/Video → Vendcom
Product: Core → Firefox OS
Version: Trunk → unspecified
The audio issue symptom changes between user use the front or back camera. When I switch to front camera, I seldom hear the pop sound, too. I also notify the mm-qcamera-daemon process doesn't consume too much CPU on this case. Those cpu usage result is applying the Bug 979716 patch, ** opus complexity = 1 ** bitrate = 16000 Also set the frame size = 176*144 *Back Camera: (Often hear pop-sound) User 67%, System 27%, IOW 0%, IRQ 1% User 286 + Nice 191 + Sys 195 + Idle 27 + IOW 0 + IRQ 0 + SIRQ 10 = 709 PID TID PR CPU% S VSS RSS PCY UID Thread Proc 400 1599 1 14% R 36260K 11644K camera mm-qcamera-daem /system/bin/mm-qcamera-daemon <------- 318 318 0 7% R 194912K 84644K root b2g /system/b2g/b2g 1142 1564 0 6% S 132948K 47320K u0_a1142 opensl_rec_thre /system/b2g/plugin-container 1142 1559 0 6% R 132948K 47320K u0_a1142 MediaStreamGrph /system/b2g/plugin-container 318 847 0 6% S 194912K 84644K root Compositor /system/b2g/b2g 1142 1142 0 5% S 132948K 47320K u0_a1142 Browser /system/b2g/plugin-container 1142 1146 0 4% S 132948K 47320K u0_a1142 Socket Thread /system/b2g/plugin-container 318 606 0 3% S 194912K 84644K root Socket Thread /system/b2g/b2g 400 1607 0 3% S 36260K 11644K camera mm-qcamera-daem /system/bin/mm-qcamera-daemon 400 1580 0 2% S 36260K 11644K camera mm-qcamera-daem /system/bin/mm-qcamera-daemon *Front camera. (Seldom hear the pop.) User 55%, System 25%, IOW 0%, IRQ 0% User 119 + Nice 239 + Sys 164 + Idle 116 + IOW 0 + IRQ 0 + SIRQ 4 = 642 PID TID PR CPU% S VSS RSS PCY UID Thread Proc 1229 1407 0 12% R 131740K 44932K u0_a1229 opensl_rec_thre /system/b2g/plugin-container 298 298 0 8% R 195840K 81952K root b2g /system/b2g/b2g 1229 1404 1 7% S 131740K 44932K u0_a1229 MediaStreamGrph /system/b2g/plugin-container 298 849 1 6% S 195840K 81952K root Compositor /system/b2g/b2g 1229 1229 1 6% S 131740K 44932K u0_a1229 Browser /system/b2g/plugin-container 1229 1234 1 5% S 131740K 44932K u0_a1229 Socket Thread /system/b2g/plugin-container 298 591 0 3% S 195840K 81952K root Socket Thread /system/b2g/b2g 298 575 0 2% S 195840K 81952K root Gecko_IOThread /system/b2g/b2g 1229 1230 1 2% R 131740K 44932K u0_a1229 Chrome_ChildThr /system/b2g/plugin-container 1579 1579 0 2% R 1340K 668K root top top 1229 1464 0 2% S 131700K 44892K u0_a1229 ProcessThread /system/b2g/plugin-container 896 896 0 2% S 0K 0K root RX_Thread 355 1422 0 1% S 29484K 9124K camera mm-qcamera-daem /system/bin/mm-qcamera-daemon <--- It may need to clarify why mm-qcamera-daemon process cause higher cpu usage on back camera source.
Flags: needinfo?(rlin)
POVB or not? Dolphin has the same issue. See bug 1021484.
hi Yanan, Youlong, do you have any finding in the logs (comment 17)?
Flags: needinfo?(yanan.zhao)
hi francis, I remember in provious mails, we have discuss about these issues on 1.4/2.0 gecko/gaia. we'll try to follow these bug in coming 1.4/2.0 project. our resource really is lack of handling things out of project. tks.
Whiteboard: [p=0, POVB, ft:loop] → [p=0, POVB]
I have been battling this issue a bit on dolphin recently and my analysis is like Randy's in comment 12; the nice value of opensl_rec_thread is too low so it get's starved and can't take care of all the recorded samples fast enough. Opensl detects this buffer overrun and restarts the recording device. Again see bug 1021484. We can see that the intended priority of the opensl_rec_thread is realtime here: http://dxr.mozilla.org/mozilla-central/source/media/webrtc/trunk/webrtc/modules/audio_device/android/opensles_input.cc#526 As you can see in comment 12 though, the nice value is 1 (normal prio). The reason seems to be bug 885190. I tried my best at reverting bug 885190 and in other ways increase the priority of opensl_rec_thread but to no avail (yet). Probably a permissions thing. This is my best lead on continuing with this bug. We'd preferably have the nice value for opensl_rec_thread be the same as for the AudioRecord thread (which is handing the samples to opensl_rec_thread), namely -16. rjesup, fyi
Component: Vendcom → WebRTC: Audio/Video
Flags: needinfo?(yanan.zhao) → needinfo?(rjesup)
Product: Firefox OS → Core
Whiteboard: [p=0, POVB] → [p=0]
So opensl_rec_thread couldn't set SCHED_RR or SCHED_FIFO as its scheduling policy even after I reverted bug 885190. I didn't pursue that track so I am not exactly sure of the reason why. Instead I, in the case of failure, fell back to lowering the thread's nice value. I did this for the webrtc::ThreadPosix class so several threads were affected. I believe they all used to have a nice of 1. That is at least true for the ones with kRealtimePriority. Here is how all affected threads were set (thread prio -> nice): Trace (kHighestPriority -> -14) ProcessThread (kNormalPriority -> 0) opensl_rec_thread (kRealtimePriority -> -19) ProcessThread (kNormalPriority -> 0) ProcessThread (kNormalPriority -> 0) ViECaptureThread (kHighPriority -> -10) DecodingThread (kHighestPriority -> -14) IncomingVideoStreamThread (kRealtimePriority -> -19) WebRtc_event_timer_thread (kRealtimePriority -> -19) I did this test on a dolphin that, with it being only single core, saw the same problem as the flame but more often and with more severe symptoms. After changing the priorities I can conclude that the audio quality sent from the device is much better than before. There are no popping sounds at all. There is little to none garbled audio - it used to be impossible to hear what was said. This test also concludes that bug 1021484 is a duplicate.
(In reply to Andreas Pehrson [:pehrsons] (Telenor) from comment #25) > So opensl_rec_thread couldn't set SCHED_RR or SCHED_FIFO as its scheduling > policy even after I reverted bug 885190. I didn't pursue that track so I am > not exactly sure of the reason why. You need root privileges to use RR or FIFO scheduling... and a mistake there can lock the system, requiring some form of deadman or higher priority monitor/killer.
Flags: needinfo?(rjesup)
Is fixing the thread priorities (e.g., per comment 25) something we might want to do, or has this been fixed in other ways? I saw elsewhere that the audio pops is supposedly fixed but haven't gotten around to test.
Flags: needinfo?(rjesup)
No longer blocks: Loopmov_1_1
This was fixed a while ago.
Status: NEW → RESOLVED
Closed: 10 years ago
Flags: needinfo?(rjesup)
Resolution: --- → FIXED
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: