when tapping the keyboard, you can hear the delayed lag of the tap sound after tapping. This needs to be sync'd up better. See screencast for example: http://youtu.be/9LW-xCoqCLo logcat: 01-23 11:21:52.114: D/wpa_supplicant(18662): RX ctrl_iface - hexdump(len=11): 53 49 47 4e 41 4c 5f 50 4f 4c 4c 01-23 11:21:52.114: D/wpa_supplicant(18662): wlan0: Control interface command 'SIGNAL_POLL' 01-23 11:21:52.134: D/wpa_supplicant(18662): nl80211: survey data missing! 01-23 11:21:52.344: D/TrackUtils(300): setFastFlag - flags b4 = 4 , streamType = 1 01-23 11:21:52.344: D/TrackUtils(300): ULL for ringtones/Alarm/Notification/system sound/enforced audible 01-23 11:21:52.344: D/TrackUtils(300): setFastFlags after = 4 01-23 11:21:52.344: D/TrackUtils(300): livesLocally = 0 01-23 11:21:52.344: W/TrackUtils(300): AudioTrack created for streamType =1, flags =4 01-23 11:21:52.344: W/TrackUtils(300): We donot need to inform HAL 01-23 11:21:52.564: D/TrackUtils(300): setFastFlag - flags b4 = 4 , streamType = 1 01-23 11:21:52.564: D/TrackUtils(300): ULL for ringtones/Alarm/Notification/system sound/enforced audible 01-23 11:21:52.564: D/TrackUtils(300): setFastFlags after = 4 01-23 11:21:52.564: D/TrackUtils(300): livesLocally = 0 01-23 11:21:52.564: W/TrackUtils(300): AudioTrack created for streamType =1, flags =4 01-23 11:21:52.564: W/TrackUtils(300): We donot need to inform HAL 01-23 11:21:52.984: E/AudioTrack(300): did not receive expected priority boost on time 01-23 11:21:53.074: D/TrackUtils(300): livesLocally = 0 01-23 11:21:53.074: W/TrackUtils(300): AudioTrack created for streamType =1, flags =4 01-23 11:21:53.074: W/TrackUtils(300): We donot need to inform HAL 01-23 11:21:53.144: D/SST_QC_B2G(300): Signal Strength changed; sending info to content process 01-23 11:21:53.144: D/SIGNAL_STRENGTH_QC_B2G(300): GetDbm = -81 01-23 11:21:53.144: D/SIGNAL_STRENGTH_QC_B2G(300): GetRelSignalStrength = 51 01-23 11:21:53.144: I/Gecko(300): -*- [SUB0] QCContentHelper_QC_B2G: sendMessage to content process: RIL:VoiceInfoChanged{ connected : true, emergencyCallsOnly : false, roaming : false, type : 'edge', signalStrength : -81, relSignalStrength : 51, network : { mcc : '466', mnc : '92', longName : 'Chunghwa Telecom', shortName : 'Chunghwa', }, cell : { gsmLocationAreaCode : 2121, gsmCellId : 52731, cdmaBaseStationId : -1, cdmaBaseStationLatitude : -2147483648, cdmaBaseStationLongitude : -2147483648, cdmaSystemId : -1, cdmaNetworkId : -1, }, state : 'registered', } 01-23 11:21:53.154: D/SIGNAL_STRENGTH_QC_B2G(300): GetDbm = -81 01-23 11:21:53.164: D/SIGNAL_STRENGTH_QC_B2G(300): GetRelSignalStrength = 51 01-23 11:21:53.164: I/Gecko(300): -*- QCMessageManager_QC_B2G: Received sendTargetMessage with topic='mobileconnection', message='RIL:VoiceInfoChanged' 01-23 11:21:53.174: I/Gecko(300): -*- [SUB0] QCContentHelper_QC_B2G: sendMessage to content process: RIL:DataInfoChanged{ connected : false, emergencyCallsOnly : false, roaming : false, type : 'edge', signalStrength : -81, relSignalStrength : 51, network : { mcc : '466', mnc : '92', longName : 'Chunghwa Telecom', shortName : 'Chunghwa', }, cell : { gsmLocationAreaCode : 2121, gsmCellId : 52731, cdmaBaseStationId : -1, cdmaBaseStationLatitude : -2147483648, cdmaBaseStationLongitude : -2147483648, cdmaSystemId : -1, cdmaNetworkId : -1, }, state : 'registered', } 01-23 11:21:53.184: I/Gecko(300): -*- QCMessageManager_QC_B2G: Received sendTargetMessage with topic='mobileconnection', message='RIL:DataInfoChanged' 01-23 11:21:53.194: E/AudioTrack(300): did not receive expected priority boost on time 01-23 11:21:53.284: D/TrackUtils(300): livesLocally = 0 01-23 11:21:53.284: W/TrackUtils(300): AudioTrack created for streamType =1, flags =4 01-23 11:21:53.284: W/TrackUtils(300): We donot need to inform HAL 01-23 11:21:53.404: D/TrackUtils(300): setFastFlag - flags b4 = 4 , streamType = 1 01-23 11:21:53.404: D/TrackUtils(300): ULL for ringtones/Alarm/Notification/system sound/enforced audible 01-23 11:21:53.404: D/TrackUtils(300): setFastFlags after = 4 01-23 11:21:53.404: D/TrackUtils(300): livesLocally = 0 01-23 11:21:53.404: W/TrackUtils(300): AudioTrack created for streamType =1, flags =4 01-23 11:21:53.404: W/TrackUtils(300): We donot need to inform HAL 01-23 11:21:54.044: E/AudioTrack(300): did not receive expected priority boost on time 01-23 11:21:54.134: D/TrackUtils(300): livesLocally = 0 01-23 11:21:54.134: W/TrackUtils(300): AudioTrack created for streamType =1, flags =4 01-23 11:21:54.134: W/TrackUtils(300): We donot need to inform HAL 01-23 11:21:54.704: E/Profiler(300): BPUnw: [1 total] thread_unregister_for_profiling(me=0x4c5908) (NOT REGISTERED) 01-23 11:21:54.734: E/Profiler(300): BPUnw: [1 total] thread_unregister_for_profiling(me=0x4b0fe8) (NOT REGISTERED) Repro 1) install 1.3 nightly on Open C Gaia 22bc6be5b76cdc6d4e9667ff070979041a20ce2f Gecko cd8bc54e911470fa6519d461e5e6b3ddc8f57f5f BuildID 20140122053021 Version 28.0a2 ro.build.version.incremental=eng..20140109.070621 2) launch any app that triggers the onscreen keyboard (eg. Messages) 3) Start tapping words into the textbox 4) Verify the lag in sound of the keyboard taps. this needs to be in sync. Expected: - tapping sound is sync'd Actual: - tapping sound is lagging

going to try this on a 1.3 Buri device to see if it reproduces on other hardware.

I cannot reproduce this on a 1.3 Buri.

We need to find out if this reproduces on a Sora device, as that will determine if this is a vendor bug or a Jellybean bug. Vance - Can you ask TCL to check this on a Sora device?

Hi Jason - Soul 3.5 also has this keypad tone delay problem, according to TCL, the delay is about 1 second

This is likely a hardware decoder bug in regards to Jellybean support. Rudy - Can you point me at what music file in the Gaia repository is being played here when the keyboard is tapped?

We got 2 sounds for normal key and special key, respectively, https://github.com/mozilla-b2g/gaia/tree/master/apps/keyboard/resources/sounds - key.ogg - special.ogg Thanks.

(In reply to Rudy Lu [:rudyl] from comment #6) > We got 2 sounds for normal key and special key, respectively, > https://github.com/mozilla-b2g/gaia/tree/master/apps/keyboard/resources/ > sounds > - key.ogg > - special.ogg > > Thanks. Weird. I guess this isn't a hardware decoder bug, as this involves ogg files.

1.3+ on this bug. Rudy, Please take a look at this.

(In reply to Preeti Raghunath(:Preeti) from comment #8) > 1.3+ on this bug. > > Rudy, > > Please take a look at this. Rudy wouldn't be able to look into this - this is a gecko regression. Switching needinfo to Anthony to have someone look at this from the media perspective.

Is it possible to get the logcat output from a run where NSPR_LOG_MODULES=MediaDecoder:5 is set in the environment? That should allow us to see the timing of what's happening inside the media playback code.

(In reply to Matthew Gregan [:kinetik] from comment #10) > Is it possible to get the logcat output from a run where > NSPR_LOG_MODULES=MediaDecoder:5 is set in the environment? That should > allow us to see the timing of what's happening inside the media playback > code. Sure, just tell me how to set this up. The original logcat i put in comment 0 is all that is currently enabled.

(In reply to Tony Chung [:tchung] from comment #11) > (In reply to Matthew Gregan [:kinetik] from comment #10) > > Is it possible to get the logcat output from a run where > > NSPR_LOG_MODULES=MediaDecoder:5 is set in the environment? That should > > allow us to see the timing of what's happening inside the media playback > > code. > > Sure, just tell me how to set this up. The original logcat i put in > comment 0 is all that is currently enabled. See https://developer.mozilla.org/en-US/docs/Mozilla/Debugging/HTTP_logging#Firefox_OS_phones. You'll want to run: adb shell export NSPR_LOG_MODULES=MediaDecoder:5 export NSPR_LOG_FILE=/data/local/tmp/myLogFile stop b2g /system/bin/b2g.sh Then, execute the STR in the bug. Then, pull the NSPR log file from your device & attach it to the bug.

Completely guessing at what the problem is likely to be (the requested logs should help confirm), I think this problem will disappear if the apps that want to repeatedly play short sounds with low latency use Web Audio rather than <audio> elements. Can someone with the hardware showing this problem please test the following page and report if "Method 1" shows the same delay as the keyboard and whether "Method 2" is an improvement? Test case is here: http://flim.org/~kinetik/tests/bug962932/test.html

cc scheng to help this one.

I have tested it. There is an improvement in "Method 2".

That's interesting, because, when i measured attachment 8339708 [details] on an Otoro a couple of weeks before Christmas, I saw 100 ms additional latency in Web Audio over that of Audio.play(). That testcase didn't use cloneNode().

Here is an experiment using WebAudio for keyboard sounds. It works, but the sounds are delayed a solid 10s. I'm trying to figure out why, but if anyone can figure it out feel free to take the bug/patch.

I am not certain, but it may be possible that bug 952893 and bug 963220 could be impacting the WebAudio version. If we get those fixed, I would like to try the WebAudio version again.

Kevin, which device is that? I've seen weird things on some devices.

(In reply to Paul Adenot (:padenot) from comment #21) > Kevin, which device is that? I've seen weird things on some devices. I asked Kevin this on irc last night. It was a nexus device. He's currently rebuilding for buri to retest. I wonder if the driver in vanilla gonk has some audio delay baked in that the OEM fixed for their buri proprietary buri gonk.

I tried pulling nspr logs from comment 12 steps, but the file came up 0 bytes. So the only thing i have after reproducing the issue again, was what is in the console. See https://gist.github.com/tonychung/8715099. Let me know how else i can help. Tony

We should get a log so we can confirm where the problem is.

mwu - see comment 12. Do you know why NSPR logs are failing to work with those directions?

FWIW, I noticed this yesterday as well when trying a trunk/1.4 build on a Nexus 4. (In reply to Rudy Lu [:rudyl] from comment #6) > We got 2 sounds for normal key and special key, respectively, > https://github.com/mozilla-b2g/gaia/tree/master/apps/keyboard/resources/ > sounds > - key.ogg > - special.ogg Er, why are these compressed at all? I can't imagine there is much savings for compressing a 250ms sound -- the overhead of spinning up the decoder has got to be worse than just keeping these around as wavs (ideally wavs with appropriate frequency/format for direct playback on devices).

(In reply to Vladimir Vukicevic [:vlad] [:vladv] from comment #26) > Er, why are these compressed at all? I can't imagine there is much savings > for compressing a 250ms sound -- the overhead of spinning up the decoder has > got to be worse than just keeping these around as wavs (ideally wavs with > appropriate frequency/format for direct playback on devices). Good point Vlad. The opus versions are only a few kB smaller than the wav files. Zipped, they are probably about the same. I'll evaluate putting in uncompressed wav files instead in bug 964999. Still, I don't think this is really the issue here. If we are only seeing this on some devices, but not the buri with the same gecko, it seems it must be a gonk issue. Right? What am I missing?

(In reply to Ben Kelly [:bkelly] from comment #27) > Still, I don't think this is really the issue here. If we are only seeing > this on some devices, but not the buri with the same gecko, it seems it must > be a gonk issue. Right? What am I missing? Oh yeah, definitely not the issue here. Just pointed it out when I noticed they were oggs for fixing later.

I'm going to take this, but it will be difficult to make real progress without the problem device. Tony, is there any way we could get a sora device overnighted to me? Or is there someone else with a sora that wants to take this?

(In reply to Ben Kelly [:bkelly] from comment #29) > I'm going to take this, but it will be difficult to make real progress > without the problem device. > > Tony, is there any way we could get a sora device overnighted to me? Or is > there someone else with a sora that wants to take this? Hi Ben, So far, we've seen this on the 1.3 builds of Open C, the TCL Soul 3.5 (aka Sora, i think), and we saw it on the Flame. (thats' running m-c/master). Unfortunately, all these phones are going to MWC, so we can't send any out at this time until the event is over. But if you need any more logs, please let us know how we can help. Sorry im not much more helpful here.

While talking on IRC with Tony we realized that maybe this is just appearing on JB based gonk. The only JB device I have is a tarako. I'll try to reproduce there.

It definitely reproduces on a nexus 4; would be interesting if it happens on tarako too. That would nail it down as a JB issue.

(In reply to Vladimir Vukicevic [:vlad] [:vladv] from comment #32) > It definitely reproduces on a nexus 4; would be interesting if it happens on > tarako too. That would nail it down as a JB issue. I can reproduce a delay on tarako, although I'm hitting a bunch of other perf problems with the keyboard on that device, so I'm not 100% sure it's the same issue.

I will try to hack up a stripped down image on my tarako. If I can avoid the other memory pressure issues maybe I can reproduce this in isolation.

(In reply to Ben Kelly [:bkelly] from comment #34) > I will try to hack up a stripped down image on my tarako. If I can avoid > the other memory pressure issues maybe I can reproduce this in isolation. Any luck ben? i feel bad asking you to help with bug work, but unable to provide you the environement to test against. :(

Unfortunately, I probably won't have an answer until next week at the earliest. I'm kind of swamped at the moment. I haven't even worked through the tarako build process yet.

(In reply to Tony Chung [:tchung] from comment #30) >... > Hi Ben, > So far, we've seen this on the 1.3 builds of Open C, the TCL Soul 3.5 (aka > Sora, i think), and we saw it on the Flame. (thats' running m-c/master). > Unfortunately, all these phones are going to MWC, so we can't send any out > at this time until the event is over. But if you need any more logs, > please let us know how we can help. Sorry im not much more helpful here. Andreas, can we find a way to get an Open C to Ben since this issue affects MWC Demos?

Figured out a different way to get NSPR logs on. I've included a logcat with NSPR logs included in the output with MediaDecoder:5 turned on.

So, this log entry: 02-01 02:32:18.432: E/AudioTrack(306): did not receive expected priority boost on time indicates Gonk/Android has slept for ~310ms in AudioTrack::processAudioBuffer (see https://android.googlesource.com/platform/frameworks/av/+/a0d77cd6bf5f4ee3ee9d67ad26e7f9981991d4e7/media/libmedia/AudioTrack.cpp link 1226) What has changed at the Gonk layer (especially around AudioFlinger) that is causing this to fail?

(In reply to Matthew Gregan [:kinetik] from comment #40) > So, this log entry: > > 02-01 02:32:18.432: E/AudioTrack(306): did not receive expected priority > boost on time > > indicates Gonk/Android has slept for ~310ms in > AudioTrack::processAudioBuffer (see > https://android.googlesource.com/platform/frameworks/av/+/ > a0d77cd6bf5f4ee3ee9d67ad26e7f9981991d4e7/media/libmedia/AudioTrack.cpp link > 1226) > > What has changed at the Gonk layer (especially around AudioFlinger) that is > causing this to fail? Specifically JB gonk here actually. We know this bug only happens on JB-specific devices.

The only JB-specific gonk patches I'm seeing in dom/system/gonk/android_audio are: * bug 870682 * bug 892876 bug 870682 deals with Audio Channels policy, where as bug 892876 deals with audio in/out enumerations. I'm putting needinfo on the patch assignee & mwu to see if one of the two them can look into this.

I'm also unassigning Ben at this point, as I think we've figured out the root cause of the delay, so we don't need additional perf investigation here.

(In reply to Jason Smith [:jsmith] from comment #42) > * bug 892876 As mentioned in bug 892876, that change updates Audio Device IN/OUT enums similar to jb. FM wasn't working and I root caused that enums are changed in JB is the issue. If that change is incorrect, it may cause some audio device to not work, however I don't think it can introduce delay in any way.

A bit more info. JellyBean introduced new functionality to AudioFlinger called FastMixer, which allows for lower latency when the AudioTrack meets certain criteria. We modified our audio code to make use of this on Android a while back, and I guess it's now kicking in on B2G with the JB based Gonk. FastMixer relies on the SchedulingPolicyService to set SCHED_RR/SCHED_FIFO on its threads. It looks like Gonk runs /system/b2g/fakesched which is a stubbed out SPS: https://github.com/mozilla-b2g/gonk-misc/blob/master/fakesched.cpp So I guess the fix is to add the require support to fakesched.

(In reply to Matthew Gregan [:kinetik] from comment #45) > So I guess the fix is to add the require[d] support to fakesched. i.e. something like this http://androidxref.com/4.3_r2.1/xref/frameworks/base/services/java/com/android/server/os/SchedulingPolicyService.java#40

Clearing ni as Matthew has identified the bug.

Nice find guys! Do you have someone to work this?

I'm going to take this back for the time being. I will try to implement the fix outlined in comment 45 and comment 46. Matt, or anyone else, if you plan to work on this please feel free to steal it back. It may be a day or two before I can start working on it.

(In reply to Ben Kelly [:bkelly] from comment #49) > I'm going to take this back for the time being. I will try to implement the > fix outlined in comment 45 and comment 46. > > Matt, or anyone else, if you plan to work on this please feel free to steal > it back. It may be a day or two before I can start working on it. We can't wait that long. This is a MWC demo blocker + 1.3+ blocker. We need someone on this asap to get a fix. Otherwise, we're going to risk every JB-based device demo (i.e. all of them) at MWC.

(In reply to Matthew Gregan [:kinetik] from comment #40) > indicates Gonk/Android has slept for ~310ms in > AudioTrack::processAudioBuffer (see > https://android.googlesource.com/platform/frameworks/av/+/ > a0d77cd6bf5f4ee3ee9d67ad26e7f9981991d4e7/media/libmedia/AudioTrack.cpp link > 1226) While it isn't a proper fix, setting kMaxTries to 1 would ameliorate the problem.

Ok, I can now build and flash gonk on my tarako. I can also reproduce the delayed audio. Unfortunately I am out of time for today. Tomorrow I will implement the solution from comment 45 and comment 46. If that becomes difficult I will try the suggestion in comment 51.

So it turns out tarako is actually an ICS device. Since I don't have a JB device I won't be able to investigate this. Mike has agreed to take it on. Note, I believe the delayed audio on tarako is coming from trying the headphone device first before falling back to the speaker. This is based on log messages from AudioPolicyManager. The output device confusion could possibly be due to the extra wires hanging out the headphone jack on this particular device confusing detection of actual headphones.

I opened bug 967581 to track delayed keyboard audio on tarako.

This is a somewhat straightforward port of the java version of SchedulePolicyService. Had to drop in some code from widget/gonk/GonkPermission.cpp for /proc parsing and implement onTransact manually.

Comment on attachment 8370301 [details] Link to Github pull-request: https://github.com/mozilla-b2g/gonk-misc/pull/147 r=me with questions answered. I get the jist of what this is trying to do, but a couple of details weren't quite clear. I also wasn't sure if this needs to compile for older SDKs.

Dave, I've made changes based on your comments. The check for the tid belonging to a pid was changed to your suggestion of /proc/(pid)/task/(tid)/status. This doesn't need to build on anything older than Jellybean. Lemme know if you have any other comments and I'll address them in a followup.

Can we get ETA to fix this bug? Thank you.

(In reply to Michael Wu [:mwu] from comment #57) > Dave, I've made changes based on your comments. The check for the tid > belonging to a pid was changed to your suggestion of > /proc/(pid)/task/(tid)/status. This doesn't need to build on anything older > than Jellybean. Lemme know if you have any other comments and I'll address > them in a followup. I took a look at the updated version and that seems alot clearer to me :)

Any reason to do a full open/close for the pid/tid check instead of a stat? Seems like it might require less resources.

I guess you could also just do access(filename, F_OK) since we really only need to know if the file exists.

I've switched to access in the PR.

We're fighting against a glitchy sound issue in bug 917193 on buri devices. The touch tones sound scratchy/glitchy whenever there's a spike in CPU usage happening at the same time; is there a chance that it's related to the issue in this bug?

(In reply to Gabriele Svelto [:gsvelto] from comment #63) > We're fighting against a glitchy sound issue in bug 917193 on buri devices. > The touch tones sound scratchy/glitchy whenever there's a spike in CPU usage > happening at the same time; is there a chance that it's related to the issue > in this bug? Zero chance. This is a bug that only affects JB or KK based devices.

(In reply to Michael Wu [:mwu] from comment #64) > Zero chance. This is a bug that only affects JB or KK based devices. OK, thanks for clearing it up.

Master: cb47162b80b49448c33853e5ee89c7b3f9b83f5a

John, can you assist with this uplift please? :)

Actually, I'm feeling motivated tonight. v1.3: 7e006b3f770f7ca77d4b007e568ccd050bd1a89e

Inder, I noticed you stubbed requestPriority in frameworks/av/services/audioflinger/SchedulingPolicyService.cpp. Can you revert that change? I implemented the service in this bug so we can actually use this now.

:ikumar - I've already got this all queued up here, just waiting for gonksched to make it into our tree.

Great! Thanks Michaels!