OpenSL ES buffer queue callback being called a bit late

[Dom Bhuphaibool]

I have an application which plays audio via OpenSL ES. The application sends OpenSL PCM data to be played. Every once in a while the buffer queue callback seems to get called just a bit late which results in an audio glitch. This seems to happen more frequently when the CPU load is high. I'm currently following all guidelines outlined by the High Performance Audio google video by Glenn Kasten, Raph, Levien, and Ian Ni-Lewis.

Particularly, I'm using a lock free ring buffer, setting up my buffers to be that of the native device buffer size (or multiple of it), and the audio sampling rate is the same as the native device sampling rate. But I'm seeing a peculiar behavior in that the buffer queue callback is being called only when audio data is about to run out. 

Testing on a Nexus 7, with a native buffer size of 512 bytes, native sampling rate of 44100 Hz... 

My PCM audio has a sampling rate of 44100 Hz, and is 16-bit stereo PCM

It seems that the Nexus 7 (or the underlying audio implementation) has an audio buffer of 2048 bytes, which for a 16-bit stereo, 44.1 KHz PCM results to about 11.6099 ms of audio. I came to the 2048 bytes internal buffer size conclusion from the following data I gathered... 

---------------------------------------------------------

OpenSL buffer configuration:

16 buffers of size 512 bytes

03-10 15:02:37.371: I/libNativeAudio(8991): elapsed time between callbacks 0.0200 msec, 512 bytes enqueue in 0.0150 msec

03-10 15:02:37.371: I/libNativeAudio(8991): elapsed time between callbacks 0.0170 msec, 512 bytes enqueue in 0.0130 msec

03-10 15:02:37.371: I/libNativeAudio(8991): elapsed time between callbacks 0.0150 msec, 512 bytes enqueue in 0.0120 msec

03-10 15:02:37.381: I/libNativeAudio(8991): elapsed time between callbacks 11.1770 msec, 512 bytes enqueue in 0.0340 msec

03-10 15:02:37.381: I/libNativeAudio(8991): elapsed time between callbacks 0.0210 msec, 512 bytes enqueue in 0.0150 msec

03-10 15:02:37.381: I/libNativeAudio(8991): elapsed time between callbacks 0.0180 msec, 512 bytes enqueue in 0.0120 msec

03-10 15:02:37.381: I/libNativeAudio(8991): elapsed time between callbacks 0.0150 msec, 512 bytes enqueue in 0.0120 msec

03-10 15:02:37.391: I/libNativeAudio(8991): elapsed time between callbacks 11.3130 msec, 512 bytes enqueue in 0.0310 msec

03-10 15:02:37.391: I/libNativeAudio(8991): elapsed time between callbacks 0.0190 msec, 512 bytes enqueue in 0.0150 msec

03-10 15:02:37.391: I/libNativeAudio(8991): elapsed time between callbacks 0.0170 msec, 512 bytes enqueue in 0.0140 msec

03-10 15:02:37.391: I/libNativeAudio(8991): elapsed time between callbacks 0.0140 msec, 512 bytes enqueue in 0.0120 msec

03-10 15:02:37.401: I/libNativeAudio(8991): elapsed time between callbacks 11.1510 msec, 512 bytes enqueue in 0.0300 msec

03-10 15:02:37.401: I/libNativeAudio(8991): elapsed time between callbacks 0.0200 msec, 512 bytes enqueue in 0.0150 msec

03-10 15:02:37.401: I/libNativeAudio(8991): elapsed time between callbacks 0.0170 msec, 512 bytes enqueue in 0.0140 msec

03-10 15:02:37.401: I/libNativeAudio(8991): elapsed time between callbacks 0.0160 msec, 512 bytes enqueue in 0.0120 msec

03-10 15:02:37.411: I/libNativeAudio(8991): elapsed time between callbacks 11.5610 msec, 512 bytes enqueue in 0.0680 msec

03-10 15:02:37.411: I/libNativeAudio(8991): elapsed time between callbacks 0.0290 msec, 512 bytes enqueue in 0.0270 msec

03-10 15:02:37.411: I/libNativeAudio(8991): elapsed time between callbacks 0.0270 msec, 512 bytes enqueue in 0.0210 msec

03-10 15:02:37.411: I/libNativeAudio(8991): elapsed time between callbacks 0.0220 msec, 512 bytes enqueue in 0.0200 msec

03-10 15:02:37.431: I/libNativeAudio(8991): elapsed time between callbacks 11.0760 msec, 512 bytes enqueue in 0.0530 msec

As you can see, the first 2048 bytes gets enqueued by the buffer queue callback really fast, but then it waits until the audio has almost finished playing before calling the buffer queue callback again. This usually works fine until there is some load on the CPU and it seems that the audio thread gets its time slice just a bit late and results in an audio glitch.

Increasing the buffer size doesn't seem to solve the problem...

---------------------------------------------------------

OpenSL buffer configuration:

16 buffers of size 2048 bytes

03-10 15:18:27.421: I/libNativeAudio(10553): elapsed time between callbacks 11.5860 msec, 2048 bytes enqueue in 0.0330 msec

03-10 15:18:27.441: I/libNativeAudio(10553): elapsed time between callbacks 11.6710 msec, 2048 bytes enqueue in 0.0390 msec

03-10 15:18:27.451: I/libNativeAudio(10553): elapsed time between callbacks 11.3190 msec, 2048 bytes enqueue in 0.0280 msec

03-10 15:18:27.461: I/libNativeAudio(10553): elapsed time between callbacks 11.5350 msec, 2048 bytes enqueue in 0.0250 msec

03-10 15:18:27.471: I/libNativeAudio(10553): elapsed time between callbacks 11.4570 msec, 2048 bytes enqueue in 0.0190 msec

03-10 15:18:27.481: I/libNativeAudio(10553): elapsed time between callbacks 11.5220 msec, 2048 bytes enqueue in 0.0280 msec

03-10 15:18:27.491: I/libNativeAudio(10553): elapsed time between callbacks 11.5970 msec, 2048 bytes enqueue in 0.0300 msec

03-10 15:18:27.511: I/libNativeAudio(10553): elapsed time between callbacks 11.8610 msec, 2048 bytes enqueue in 0.0430 msec

03-10 15:18:27.521: I/libNativeAudio(10553): elapsed time between callbacks 11.4110 msec, 2048 bytes enqueue in 0.0520 msec

03-10 15:18:27.531: I/libNativeAudio(10553): elapsed time between callbacks 11.3500 msec, 2048 bytes enqueue in 0.0370 msec

03-10 15:18:27.541: I/libNativeAudio(10553): elapsed time between callbacks 11.3770 msec, 2048 bytes enqueue in 0.0340 msec

03-10 15:18:27.551: I/libNativeAudio(10553): elapsed time between callbacks 11.5160 msec, 2048 bytes enqueue in 0.0350 msec

---------------------------------------------------------

OpenSL buffer configuration:

16 buffers of size 6144 bytes

03-10 15:24:58.231: I/libNativeAudio(11834): elapsed time between callbacks 34.5260 msec, 6144 bytes enqueue in 0.0370 msec

03-10 15:24:58.271: I/libNativeAudio(11834): elapsed time between callbacks 34.8040 msec, 6144 bytes enqueue in 0.0390 msec

03-10 15:24:58.301: I/libNativeAudio(11834): elapsed time between callbacks 34.6740 msec, 6144 bytes enqueue in 0.0340 msec

03-10 15:24:58.341: I/libNativeAudio(11834): elapsed time between callbacks 34.6820 msec, 6144 bytes enqueue in 0.0440 msec

03-10 15:24:58.371: I/libNativeAudio(11834): elapsed time between callbacks 34.6150 msec, 6144 bytes enqueue in 0.0230 msec

03-10 15:24:58.411: I/libNativeAudio(11834): elapsed time between callbacks 34.8830 msec, 6144 bytes enqueue in 0.0640 msec

03-10 15:24:58.441: I/libNativeAudio(11834): elapsed time between callbacks 34.5610 msec, 6144 bytes enqueue in 0.0290 msec

Also, the audio glitch seems to happen more frequently on devices that have a different sampling rate than the audio's sampling rate. On Nexus 4 where the sampling rate is 48 KHz but the audio is 44.1 KHz. But this may also be due to perception or CPU load circumstances. Or it could be related to resampling detour that needs to be done to play the audio. 

But the glitches definitely occurs on 44.1 KHz devices (playing 44.1 KHz PCM audio). I'm just curious to why the audio thread waits until the audio data almost runs out before calling the buffer queue callback. Has anyone else experience this or have found a solution?

Any suggestions and/or insights would be greatly appreciated. Thanks in advance!

[Glenn Kasten]

Since you're using native sample rate of 44.1 kHz, I assume this is Nexus 7 (2012), right?

[ let me know if you actually are using 2013 version ]

You mentioned you're using 512 byte buffers (128 frames at 16-bits per sample, stereo 2 samples per frame).

What value is being reported by

http://developer.android.com/reference/android/media/AudioManager.html#PROPERTY_OUTPUT_FRAMES_PER_BUFFER

[Dom Bhuphaibool]

Hi Glenn,

Yes, it's the older version of Nexus 7 (2012). 

The value returned by PROPERTY_OUTPUT_FRAMES_PER_BUFFER is 512.

Yes, my PCM is 44.1 kHz, 16-bits per sample, stereo (2 channels). For a buffer size of 512, it's 128 frames as you've mentioned. 

[Glenn Kasten]

I'd recommend using that property frame count per buffer instead.  For details see section "Performance", of 

<NDKroot>/ndk/docs/opensles/index.html   

Please post an update here after using the property frame count; I'm hoping it will improve things.

[Philippe Simons]

Dom your, I think you are mis-interpreting the value of PROPERTY_OUTPUT_FRAMES_PER_BUFFER.

It's not BYTES per buffer, but FRAMES

1 frame of stereo 16bits is 32bits, so a buffer should be 4 bytes * PROPERTY_OUTPUT_FRAMES_PER_BUFFER, which is 2048 bytes.

Philippe

--
You received this message because you are subscribed to the Google Groups "android-ndk" group.
To unsubscribe from this group and stop receiving emails from it, send an email to android-ndk...@googlegroups.com.
To post to this group, send email to andro...@googlegroups.com.
Visit this group at http://groups.google.com/group/android-ndk.
For more options, visit https://groups.google.com/d/optout.

[Dom Bhuphaibool]

Ah, okay but if you look at my original post, I had posted the results of using buffer size of 2048 bytes (which would be 512 frames of 16-bit stereo PCM). The buffer queue callback does get called at a more regular interval but it is sometimes slightly late. 512 frames of 44.1 kHz is about 11.6099 ms of audio. Every now and then the callback gets called slightly after this time has elapsed which results in an audio glitch. It doesn't happen often but is noticeable when it does, and happens more when there are lots of things requesting/competing for CPU usage. 

Here is the output from the original post for buffer size of 2048 bytes (512 frames):

---------------------------------------------------------

OpenSL buffer configuration:

16 buffers of size 2048 bytes

03-10 15:18:27.421: I/libNativeAudio(10553): elapsed time between callbacks 11.5860 msec, 2048 bytes enqueue in 0.0330 msec

03-10 15:18:27.441: I/libNativeAudio(10553): elapsed time between callbacks 11.6710 msec, 2048 bytes enqueue in 0.0390 msec

03-10 15:18:27.451: I/libNativeAudio(10553): elapsed time between callbacks 11.3190 msec, 2048 bytes enqueue in 0.0280 msec

03-10 15:18:27.461: I/libNativeAudio(10553): elapsed time between callbacks 11.5350 msec, 2048 bytes enqueue in 0.0250 msec

03-10 15:18:27.471: I/libNativeAudio(10553): elapsed time between callbacks 11.4570 msec, 2048 bytes enqueue in 0.0190 msec

03-10 15:18:27.481: I/libNativeAudio(10553): elapsed time between callbacks 11.5220 msec, 2048 bytes enqueue in 0.0280 msec

03-10 15:18:27.491: I/libNativeAudio(10553): elapsed time between callbacks 11.5970 msec, 2048 bytes enqueue in 0.0300 msec

03-10 15:18:27.511: I/libNativeAudio(10553): elapsed time between callbacks 11.8610 msec, 2048 bytes enqueue in 0.0430 msec

03-10 15:18:27.521: I/libNativeAudio(10553): elapsed time between callbacks 11.4110 msec, 2048 bytes enqueue in 0.0520 msec

03-10 15:18:27.531: I/libNativeAudio(10553): elapsed time between callbacks 11.3500 msec, 2048 bytes enqueue in 0.0370 msec

03-10 15:18:27.541: I/libNativeAudio(10553): elapsed time between callbacks 11.3770 msec, 2048 bytes enqueue in 0.0340 msec

03-10 15:18:27.551: I/libNativeAudio(10553): elapsed time between callbacks 11.5160 msec, 2048 bytes enqueue in 0.0350 msec

If the callback would get called around ~10 ms, it would be much better to allow room for delay but as is, it is very close to the 11.6 ms limit. Sometimes 11.8, etc. which results in an audio glitch.

Does it matter how many buffers I use? I've tried different configurations between 2, 4, 8, and 16, but all still results in an audio glitch every now and then.

Also, is the audio thread which services the callback supposed to have a nice value of -19 or -16? When I query it, it returns -16 via getpriority(PRIO_PROCESS, 0). (But this call returns the highest nice value of all threads in the current process - is there an api to get the value for the calling thread?). I'm wondering if there is latency with the scheduler or if the scheduler is not servicing it properly by preempting it because it doesn't have a priority of -19. Here's my original post regarding thread priority: https://groups.google.com/forum/#!topic/android-ndk/CzYqy9uiFaU

On a Nexus 5 where the native sampling rate is 48 kHz, the callback doesn't get called at regular interval even if I'm using 240 frames buffer (960 bytes). I'm assuming it's because it has to take a detour to the resampler because I'm sending it 44.1 kHz PCM. More audio glitches seem to be happening on Nexus 5. Is there anything else I can do short of performing the resampling myself? Currently the audio is being decoded in the java layer from MP3 to PCM, and I'm sending the PCM data to OpenSL. 

Thanks!

[Glenn Kasten]

Sorry, I missed that point from your original post.

In any case, I recommend that we focus on the 512 frame / buffer case, 

as that is the way this particular device is intended to work.

512 frames per buffer at 44.1 kHz gives a nominal cycle time of ~11.61

milliseconds.  The internal data path includes an additional buffer (not visible to your app),

so that it can tolerate a small amount of timing jitter without underrunning/glitching.

I recommend using 2 app-level (OpenSL ES) buffers.

There is more recent support for 1 app-level buffer, 

but the platform version on your device may not support it yet.

Additional app-level buffers beyond 2 typically do not add value.

Both your app callback thread and the internal AudioFlinger threads

are supposed to run at elevated SCHED_FIFO priority, which is beyond either -16 or -19.

To confirm this, can you please do this (you may need root):

adb shell ps | grep media

get the process ID of mediaserver from the output, while audio is active

adb shell ps -t -P -p mediaserver_pid#

(save this output)

now get the process ID of your app, while audio is active

adb shell ps -t -P -p your_app_pid#

(save this output too)

adb shell dumpsys media.audio_flinger

(and this output)

Then please share the results here.  This should help to diagnose

where the problem might be, such as problem with priorities,

cause of underruns, etc.  Thanks.

[Dom Bhuphaibool]

Hi Glenn, 

Here's the result... Please let me know what you can decipher and if you need anything else. Thanks!

> adb shell ps -t -P -p {mediaserver_pid#} pid=125

USER     PID   PPID  VSIZE  RSS   PRIO  NICE  RTPRI SCHED  PCY  WCHAN    PC         NAME

media     125   1     40076  5032  20    0     0     0     fg  ffffffff 00000000 S /system/bin/mediaserver

media     256   125   40076  5032  4     -16   0     0     fg  ffffffff 00000000 S ApmTone

media     257   125   40076  5032  4     -16   0     0     fg  ffffffff 00000000 S ApmAudio

media     258   125   40076  5032  4     -16   0     0     fg  ffffffff 00000000 S ApmOutput

media     274   125   40076  5032  -4    -19   3     1     fg  ffffffff 00000000 S FastMixer

media     544   125   40076  5032  1     -19   0     0     fg  ffffffff 00000000 S AudioOut_2

media     545   125   40076  5032  20    0     0     0     fg  ffffffff 00000000 S Binder_1

media     607   125   40076  5032  20    0     0     0     fg  ffffffff 00000000 S Binder_2

media     1906  125   40076  5032  20    0     0     0     fg  ffffffff 00000000 S Binder_2

media     10294 125   40076  5032  20    0     0     0     fg  ffffffff 00000000 S Binder_3

media     24460 125   40076  5032  20    0     0     0     fg  ffffffff 00000000 S Binder_4

media     29528 125   40076  5032  18    -2    0     0     fg  ffffffff 00000000 S TimedEventQueue

media     29529 125   40076  5032  18    -2    0     0     fg  ffffffff 00000000 S .vorbis.decoder

media     29530 125   40076  5032  18    -2    0     0     fg  ffffffff 00000000 S OMXCallbackDisp

media     29531 125   40076  5032  4     -16   0     0     fg  ffffffff 00000000 S AudioTrack

> adb shell ps -t -P -p {your_app_pid#} pid=26633

USER     PID   PPID  VSIZE  RSS   PRIO  NICE  RTPRI SCHED  PCY  WCHAN    PC         NAME

u0_a453   26633 123   821524 79344 20    0     0     0     fg  ffffffff 00000000 S com.rdio.android.mono:remote

u0_a453   26636 26633 821524 79344 20    0     0     0     fg  ffffffff 00000000 S GC

u0_a453   26638 26633 821524 79344 20    0     0     0     fg  ffffffff 00000000 S Signal Catcher

u0_a453   26639 26633 821524 79344 20    0     0     0     fg  ffffffff 00000000 S JDWP

u0_a453   26640 26633 821524 79344 20    0     0     0     fg  ffffffff 00000000 S Compiler

u0_a453   26641 26633 821524 79344 20    0     0     0     fg  ffffffff 00000000 S ReferenceQueueD

u0_a453   26642 26633 821524 79344 20    0     0     0     fg  ffffffff 00000000 S FinalizerDaemon

u0_a453   26643 26633 821524 79344 20    0     0     0     fg  ffffffff 00000000 S FinalizerWatchd

u0_a453   26644 26633 821524 79344 20    0     0     0     fg  ffffffff 00000000 S Binder_1

u0_a453   26645 26633 821524 79344 20    0     0     0     fg  ffffffff 00000000 S Binder_2

u0_a453   26651 26633 821524 79344 20    0     0     0     fg  ffffffff 00000000 S oid.mono:remote

u0_a453   26668 26633 821524 79344 20    0     0     0     fg  ffffffff 00000000 S oid.mono:remote

u0_a453   26677 26633 821524 79344 20    0     0     0     fg  ffffffff 00000000 S oid.mono:remote

u0_a453   26678 26633 821524 79344 20    0     0     0     fg  ffffffff 00000000 S oid.mono:remote

u0_a453   26684 26633 821524 79344 -3    -16   2     1     fg  ffffffff 00000000 S AudioTrack

u0_a453   26692 26633 821524 79344 20    0     0     0     fg  ffffffff 00000000 S WifiManager

u0_a453   26696 26633 821524 79344 18    -2    0     0     fg  ffffffff 00000000 S MediaCodec_loop

u0_a453   26697 26633 821524 79344 18    -2    0     0     fg  ffffffff 00000000 S gle.mp3.decoder

u0_a453   26698 26633 821524 79344 18    -2    0     0     fg  ffffffff 00000000 S OMXCallbackDisp

u0_a453   26699 26633 821524 79344 18    -2    0     0     fg  ffffffff 00000000 S MediaCodec_loop

u0_a453   26700 26633 821524 79344 18    -2    0     0     fg  ffffffff 00000000 S gle.mp3.decoder

u0_a453   26701 26633 821524 79344 18    -2    0     0     fg  ffffffff 00000000 S OMXCallbackDisp

u0_a453   26713 26633 821524 79344 20    0     0     0     fg  ffffffff 00000000 S oid.mono:remote

u0_a453   26726 26633 821524 79344 20    0     0     0     fg  ffffffff 00000000 S oid.mono:remote

u0_a453   26910 26633 821524 79344 20    0     0     0     fg  ffffffff 00000000 S oid.mono:remote

u0_a453   26911 26633 821524 79344 20    0     0     0     fg  ffffffff 00000000 S oid.mono:remote

u0_a453   26919 26633 821524 79344 20    0     0     0     fg  ffffffff 00000000 S Binder_3

u0_a453   26920 26633 821524 79344 20    0     0     0     fg  ffffffff 00000000 S Binder_4

u0_a453   28439 26633 821524 79344 20    0     0     0     fg  ffffffff 00000000 S oid.mono:remote

u0_a453   30115 26633 821524 79344 20    0     0     0     fg  ffffffff 00000000 S oid.mono:remote

u0_a453   30758 26633 821524 79344 4     -16   0     0     fg  ffffffff 00000000 S oid.mono:remote

u0_a453   31095 26633 821524 79344 20    0     0     0     fg  ffffffff 00000000 S Binder_5

> adb shell dumpsys media.audio_flinger

Clients:

  pid: 521

  pid: 613

  pid: 762

  pid: 13508

  pid: 26633

Notification Clients:

  pid: 125

  pid: 521

  pid: 613

  pid: 762

  pid: 13508

  pid: 18474

  pid: 26633

Global session refs:

 session pid count

       6 762   1

     323 521   1

     366 13508   1

     524 521   1

     564 18474   1

     565 18474   1

     681 521   1

     692 26633   1

     703 613   2

     704 613   1

     706 521   1

Hardware status: 0

Standby Time mSec: 3000

Output thread 0x40d4e008 internals

Normal frame count: 1024

last write occurred (msecs): 22

total writes: 234920

delayed writes: 1

blocked in write: 1

suspend count: 0

mix buffer : 0x400b80d8

Fast track availMask=0x40

io handle: 2

TID: 544

standby: 0

Sample rate: 44100

HAL frame count: 512

Channel Count: 2

Channel Mask: 0x00000003

Format: 1

Frame size: 4

Pending setParameters commands: 

 Index Command

Pending config events: 

AudioMixer tracks: 000003bf

FastMixer command=MIX_WRITE writeSequence=941029 framesWritten=240879104

          numTracks=2 writeErrors=47 underruns=16 overruns=125

          sampleRate=44100 frameCount=512 measuredWarmup=83.5 ms, warmupCycles=4

          mixPeriod=11.61 ms

Simple moving statistics over last 380.4 seconds:

  wall clock time in ms per mix cycle:

    mean=11.61 min=0.04 max=14.85 stddev=0.19

  raw CPU load in us per mix cycle:

    mean=326 min=38 max=2715 stddev=108

Distribution of mix cycle times in ms for the tails (> ~3 stddev outliers):

  left tail: mean=8.29 min=0.04 max=9.88 stddev=2.69

  right tail: mean=13.95 min=13.03 max=14.85 stddev=0.52

Fast tracks: kMaxFastTracks=8 activeMask=0x5

Index Active Full Partial Empty  Recent Ready

    0    yes  847       0    60    full  2048

    1     no    0       0     0    full     0

    2    yes  549      97   615    full   512

    3     no  240      28    77   empty     0

    4     no  907     142   371   empty     0

    5     no  111      58   164   empty     0

    6     no  937      79   210   empty     0

    7     no  787      77   173   empty     0

Output thread 0x40d4e008 stream volumes in dB:

    0:-8.2, 1:-27, 2:-21, 3:-14, 4:-14, 5:-21, 6:0, 7:-27, 8:-22, 9:-14

Output thread 0x40d4e008 tracks

   Name Client Type      Fmt Chn mask Session fCount S F SRate  L dB  R dB    Server Main buf  Aux Buf Flags UndFrmCnt

   F  5    613    1 00000001 00000003     704   8329 S 1 44100  -Inf  -Inf  00002089 400B80D8 00000000 0x600         0 

   F  3    521    1 00000001 00000003     681   4146 S 1 44100  -Inf  -Inf  00001032 400B80D8 00000000 0x600         0 

   F  1    762    0 00000001 00000001       6    512 I 0 44100   -10   -10  00000000 400B80D8 00000000 0x000         0 

      9    613    5 00000001 00000003     703   4096 S 1 44100     0     0  0000F800 400B80D8 00000000 0x400      1024 

   F  7    521    1 00000001 00000003     524   4786 S 1 44100  -Inf  -Inf  000012B2 400B80D8 00000000 0x600         0 

   F  2  26633    3 00000001 00000003     692    512 A 1 44100     0     0  01F8B400 400B80D8 00000000 0x400     23040 

   F  4    521    1 00000001 00000003     706   4146 S 1 44100  -Inf  -Inf  00001032 400B80D8 00000000 0x600         0 

      7    521    1 00000001 00000003     323   4786 S 1 44100  -Inf  -Inf  000012B2 400B80D8 00000000 0x600         0 

      4  13508    3 00000001 00000003     366  44100 S 1 44100     0     0  00567E6F 400B80D8 00000000 0x601      2449 

Output thread 0x40d4e008 active tracks

   Name Client Type      Fmt Chn mask Session fCount S F SRate  L dB  R dB    Server Main buf  Aux Buf Flags UndFrmCnt

   F  2  26633    3 00000001 00000003     692    512 A 1 44100     0     0  01F8B400 400B80D8 00000000 0x400     23040 

Normal mixer raw underrun counters: partial=0 empty=60

- 0 Effect Chains:

--
You received this message because you are subscribed to a topic in the Google Groups "android-ndk" group.
To unsubscribe from this topic, visit https://groups.google.com/d/topic/android-ndk/HP1n8fphSs0/unsubscribe.
To unsubscribe from this group and all its topics, send an email to android-ndk...@googlegroups.com.

[Dom Bhuphaibool]

BTW, the other thread in my process (pid=26633) which has a nice value of -16 I believe is the mp3 decoder thread which I set the priority in Java via SetThreadPriority(THREAD_PRIORITY_AUDIO). I still experience audio glitch not doing this (i.e., leaving its priority as the default value). But maybe it's not a good idea to increase the decoder thread priority since it will compete with the OpenSL callback thread? (although they do have different scheduling policies...) what's your advice on this?

[Glenn Kasten]

Thanks for the additional ps and dumpsys outputs; I'll summarize what I see in them:

In mediaserver process, FastMixer thread has:
PRIO -4, NICE -19, RTPRI 3, SCHED 1
This is the so-called "Fast mixer" which drives the audio output
and receives and mixes input from all the fast tracks.

mediaserver process also has an AudioTrack thread with
PRIO 4, NICE -16, RTPRI 0, SCHED 0 
This thread is not relevant to the discussion here,
but it's a good example of a thread with elevated priority,
but not realtime priority.  This is what all normal user threads can do
to themselves. It's probably there for some internal sound, maybe a ringtone
or notification.

Then in your app process there is an AudioTrack thread with
PRIO -3, NICE -16, RTPRI 2, SCHED 1 
This thread handles OpenSL ES callbacks, such as buffer queue completion.

How to interpret PRIO, NICE, RTPRI, and SCHED:

- SCHED=0 means default scheduling policy CFS.
NICE ranges from -19 (or -20, not sure) up to 19 (or 20, not sure),
where more negative nice values mean a greater share of CPU,
and more positive nice values means a smaller share of CPU.
This is a simplification of CFS, but it gives the gist.
RTPRI is irrelevant.  PRIO is 20 + NICE.

- SCHED=1 means first-in first-out scheduling policy aka SCHED_FIFO.

NICE is irrelevant. RTPRI ranges from 0 (or 1, not sure)

up to 99 (or 100, not sure), where higher values will preempt lower values.

All SCHED_FIFO threads will preempt CFS threads.

So FastMixer and your app callback thread are both SCHED_FIFO,

and the FastMixer is slightly higher RTPRI but that doesn't really matter

since they cooperate rather than compete with each other.

So far so good.  Now on to the timing statistics.

The key section of dumpsys media.audio_flinger is:

Simple moving statistics over last 380.4 seconds:

  wall clock time in ms per mix cycle:

    mean=11.61 min=0.04 max=14.85 stddev=0.19

  raw CPU load in us per mix cycle:

    mean=326 min=38 max=2715 stddev=108

Distribution of mix cycle times in ms for the tails (> ~3 stddev outliers):

  left tail: mean=8.29 min=0.04 max=9.88 stddev=2.69

  right tail: mean=13.95 min=13.03 max=14.85 stddev=0.52

Just as you are reading the value of CLOCK_MONOTONIC in your app callback,

FastMixer reads the value of CLOCK_MONOTONIC upon return from

each write call to the audio driver.  Ideally the period should be ~11.61 ms.

Indeed that is the mean (average) value.  But the simple min and max are off.

The simple max of 14.85 ms is not ideal, but with double-buffering it can be tolerated.

However the simple min of 0.04 indicates something may be wrong.

Going deeper into the statistics, the next section for the "tails" or "outliers"

throws away most of the cycle times and looks only at the very worst offenders ...

the extremely large and extremely small values.  Again we see a number

of large values around ~14 ms, but that can be dealt with due to double-buffering.

It's the small value - esp. the .04 - that is troublesome.

To see if this was a one-time or common event, can you please re-run

the dumpsys media.audio_flinger a number of times.  I'm curious to see

if the "min" value is always near 0 ms.   Since this is simple moving statistics,

and the sample window is ~380 second (6 minutes), please wait at least

6 minutes or more between dumpsys so that we're sure we're getting

new minimums each time. And make sure audio is playing continuously

during this period, so that we're not seeing startup-related timing.

I don't know for a fact that these small min values are the cause of the clicks
you hear, but they could certainly be a contributor and it could make sense to start there.

[Dom Bhuphaibool]

Hi Glenn,

Thank you for your detailed description! One thing I'm not completely clear on is the interpretation of the value in "simple moving statistics" from the dump sys of audio flinger. Is this the time that it took for each write call to the audio driver to return? If so, does a min value of around 0.04 ms indicate that something was not written? (Or the data was written really fast?) Also, does this means that we then make another call to the audio driver to write the next 11.6 ms of audio (potentially overwriting what's currently being played?)

When you are referring to double buffering, do you mean in the driver level (so that when we write to the audio driver we are writing to a buffer and not to to the device) or do you mean that double buffering is being done at a higher level (in audio flinger)?

I've ran the dumpsys command for media.audio_flinger as requested for about 5 times with at least 6 mins in between each. I've noticed that the min does tend to fluctuate and when there's an audio glitch, the left tail min will be around 0.05 ms. Otherwise it usually starts around 8 ms. I did a complete shutdown and restart before starting the logs. Initially I just had our app running and everything seems to be much more smooth. So, afterwards, I decided to simulate a real world condition by starting other apps. This tends to increase the frequency of the audio glitches. I've annotated the pid with the name of the processes in the first couple logs.

> adb shell dumbsys media.audio_flinger

Clients:

  pid: 502 {systerm_server}

  pid: 618 {com.android.systemui}

  pid: 792 {com.android.phone}

  pid: 3476 {com.android.mono:remote}

Notification Clients:

  pid: 125 {/system/bin/mediaserver}

  pid: 502 {system_server}

  pid: 618 {com.android.systemui}

  pid: 792 {com.android.phone}

  pid: 3476 {com.rdio.android.mono:remote}

  pid: 3626 {com.rdio.android.ui:remote}

Global session refs:

 session pid count

       6 792   1

      11 3476   1

      22 3626   1

      23 3626   1

      26 618   2

      27 618   1

      28 502   1

Hardware status: 0

Standby Time mSec: 3000

Output thread 0x40ca5008 internals

Normal frame count: 1024

last write occurred (msecs): 22

total writes: 46167

delayed writes: 0

blocked in write: 1

suspend count: 0

mix buffer : 0x413a52e0

Fast track availMask=0xd0

io handle: 2

TID: 527

standby: 0

Sample rate: 44100

HAL frame count: 512

Channel Count: 2

Channel Mask: 0x00000003

Format: 1

Frame size: 4

Pending setParameters commands: 

 Index Command

Pending config events: 

AudioMixer tracks: 00000037

FastMixer command=MIX_WRITE writeSequence=184729 framesWritten=47289856

          numTracks=2 writeErrors=1 underruns=0 overruns=2

          sampleRate=44100 frameCount=512 measuredWarmup=78.6 ms, warmupCycles=4

          mixPeriod=11.61 ms

Simple moving statistics over last 380.4 seconds:

  wall clock time in ms per mix cycle:

    mean=11.61 min=8.25 max=14.79 stddev=0.14

  raw CPU load in us per mix cycle:

    mean=327 min=51 max=1756 stddev=101

Distribution of mix cycle times in ms for the tails (> ~3 stddev outliers):

  left tail: mean=9.60 min=8.25 max=10.38 stddev=0.64

  right tail: mean=13.52 min=12.81 max=14.79 stddev=0.63

Fast tracks: kMaxFastTracks=8 activeMask=0x9

Index Active Full Partial Empty  Recent Ready

    0    yes  173       0     0    full  2048

    1     no    0       0     0    full     0

    2     no   32       2     5   empty     0

    3    yes   13       0    18    full   512

    4     no   16       2     6   empty     0

    5     no   35       3    15   empty     0

    6     no    0       0     0    full     0

    7     no    0       0     0    full     0

Output thread 0x40ca5008 stream volumes in dB:

    0:-8.2, 1:-27, 2:-21, 3:-14, 4:-14, 5:-21, 6:0, 7:-27, 8:-22, 9:-14

Output thread 0x40ca5008 tracks

   Name Client Type      Fmt Chn mask Session fCount S F SRate  L dB  R dB    Server Main buf  Aux Buf Flags UndFrmCnt

   F  1    792    0 00000001 00000001       6    512 I 0 44100   -10   -10  00000000 413A52E0 00000000 0x000         0 

   F  2    618    1 00000001 00000003      27   8329 S 1 44100  -Inf  -Inf  00002089 413A52E0 00000000 0x600         0 

      1    618    5 00000001 00000003      26   4096 S 1 44100     0     0  0000F800 413A52E0 00000000 0x400      1024 

   F  5    502    1 00000001 00000003      28   4146 S 1 44100  -Inf  -Inf  00001032 413A52E0 00000000 0x600         0 

   F  3   3476    3 00000001 00000003      11    512 A 1 44100     0     0  02B81400 413A52E0 00000000 0x400      8192 

Output thread 0x40ca5008 active tracks

   Name Client Type      Fmt Chn mask Session fCount S F SRate  L dB  R dB    Server Main buf  Aux Buf Flags UndFrmCnt

   F  3   3476    3 00000001 00000003      11    512 A 1 44100     0     0  02B81400 413A52E0 00000000 0x400      8192 

Normal mixer raw underrun counters: partial=0 empty=0

- 0 Effect Chains:

==============================================>

> adb shell dumbsys media.audio_flinger

Clients:

  pid: 502

  pid: 618

  pid: 792

  pid: 3476

Notification Clients:

  pid: 125

  pid: 502

  pid: 618

  pid: 792

  pid: 1234 {com.facebook.katana}

  pid: 3476 {com.rdio.android.mono:remote}

  pid: 16019 {com.android.chrome}

Global session refs:

 session pid count

       6 792   1

      11 3476   1

      26 618   2

      27 618   1

      57 502   1

      61 502   1

Hardware status: 0

Standby Time mSec: 3000

Output thread 0x40ca5008 internals

Normal frame count: 1024

last write occurred (msecs): 3416

total writes: 55612

delayed writes: 0

blocked in write: 0

suspend count: 0

mix buffer : 0x413a52e0

Fast track availMask=0x90

io handle: 2

TID: 527

standby: 1

Sample rate: 44100

HAL frame count: 512

Channel Count: 2

Channel Mask: 0x00000003

Format: 1

Frame size: 4

Pending setParameters commands: 

 Index Command

Pending config events: 

AudioMixer tracks: 00000077

FastMixer command=COLD_IDLE writeSequence=222508 framesWritten=56957440

          numTracks=1 writeErrors=9 underruns=1 overruns=25

          sampleRate=44100 frameCount=512 measuredWarmup=78.6 ms, warmupCycles=4

          mixPeriod=11.61 ms

Simple moving statistics over last 380.4 seconds:

  wall clock time in ms per mix cycle:

    mean=11.61 min=0.05 max=147.97 stddev=0.84

  raw CPU load in us per mix cycle:

    mean=297 min=0 max=6516 stddev=124

Distribution of mix cycle times in ms for the tails (> ~3 stddev outliers):

  left tail: mean=3.06 min=0.05 max=8.02 stddev=3.06

  right tail: mean=19.73 min=14.26 max=147.97 stddev=23.45

Fast tracks: kMaxFastTracks=8 activeMask=0x1

Index Active Full Partial Empty  Recent Ready

    0    yes  630       0     0    full  1536

    1     no    0       0     0    full     0

    2     no   32       2     5   empty     0

    3     no  130       0    55   empty     0

    4     no  137      17    54   empty     0

    5     no  140      16    55   empty     0

    6     no   14       2     6   empty     0

    7     no    0       0     0    full     0

Output thread 0x40ca5008 stream volumes in dB:

    0:-8.2, 1:-27, 2:-21, 3:-14, 4:-14, 5:-21, 6:0, 7:-27, 8:-22, 9:-14

Output thread 0x40ca5008 tracks

   Name Client Type      Fmt Chn mask Session fCount S F SRate  L dB  R dB    Server Main buf  Aux Buf Flags UndFrmCnt

   F  1    792    0 00000001 00000001       6    512 I 0 44100   -10   -10  00000000 413A52E0 00000000 0x000         0 

   F  2    618    1 00000001 00000003      27   8329 S 1 44100  -Inf  -Inf  00002089 413A52E0 00000000 0x600         0 

   F  6    502    1 00000001 00000003      61   4146 S 1 44100  -Inf  -Inf  00001032 413A52E0 00000000 0x600         0 

   F  5    502    1 00000001 00000003      57   4786 S 1 44100  -Inf  -Inf  000012B2 413A52E0 00000000 0x600         0 

      1    618    5 00000001 00000003      26   4096 S 1 44100     0     0  0000F800 413A52E0 00000000 0x400      1024 

   F  3   3476    3 00000001 00000003      11    512 I 1 44100     0     0  0348F600 413A52E0 00000000 0x601     26624 

Output thread 0x40ca5008 active tracks

   Name Client Type      Fmt Chn mask Session fCount S F SRate  L dB  R dB    Server Main buf  Aux Buf Flags UndFrmCnt

Normal mixer raw underrun counters: partial=0 empty=0

- 0 Effect Chains:

==============================================>

> adb shell dumbsys media.audio_flinger

Clients:

  pid: 502

  pid: 618

  pid: 792

  pid: 3476

Notification Clients:

  pid: 125

  pid: 502

  pid: 618

  pid: 792

  pid: 1234

  pid: 3476

  pid: 16019

Global session refs:

 session pid count

       6 792   1

      11 3476   1

      26 618   2

      27 618   1

      89 502   1

      90 502   1

      91 502   1

      92 502   1

Hardware status: 0

Standby Time mSec: 3000

Output thread 0x40ca5008 internals

Normal frame count: 1024

last write occurred (msecs): 12

total writes: 61853

delayed writes: 0

blocked in write: 1

suspend count: 0

mix buffer : 0x413a52e0

Fast track availMask=0x80

io handle: 2

TID: 527

standby: 0

Sample rate: 44100

HAL frame count: 512

Channel Count: 2

Channel Mask: 0x00000003

Format: 1

Frame size: 4

Pending setParameters commands: 

 Index Command

Pending config events: 

AudioMixer tracks: 0000017f

FastMixer command=MIX_WRITE writeSequence=247489 framesWritten=63351808

          numTracks=2 writeErrors=10 underruns=1 overruns=29

          sampleRate=44100 frameCount=512 measuredWarmup=16.8 ms, warmupCycles=4

          mixPeriod=11.61 ms

Simple moving statistics over last 141.8 seconds:

  wall clock time in ms per mix cycle:

    mean=11.61 min=0.07 max=17.45 stddev=0.34

  raw CPU load in us per mix cycle:

    mean=306 min=0 max=3498 stddev=149

Distribution of mix cycle times in ms for the tails (> ~3 stddev outliers):

  left tail: mean=5.39 min=0.07 max=8.21 stddev=3.21

  right tail: mean=15.83 min=14.89 max=17.45 stddev=0.95

Fast tracks: kMaxFastTracks=8 activeMask=0x9

Index Active Full Partial Empty  Recent Ready

    0    yes  825       0     0    full  2048

    1     no    0       0     0    full     0

    2     no   32       2     5   empty     0

    3    yes  649       0    62    full   512

    4     no  230      28    81   empty     0

    5     no  181      21    69   empty     0

    6     no   89      11    30   empty     0

    7     no   36       4     8   empty     0

Output thread 0x40ca5008 stream volumes in dB:

    0:-8.2, 1:-27, 2:-21, 3:-14, 4:-14, 5:-21, 6:0, 7:-27, 8:-22, 9:-14

Output thread 0x40ca5008 tracks

   Name Client Type      Fmt Chn mask Session fCount S F SRate  L dB  R dB    Server Main buf  Aux Buf Flags UndFrmCnt

   F  6    502    1 00000001 00000003      90   4786 S 1 44100  -Inf  -Inf  000012B2 413A52E0 00000000 0x600         0 

   F  1    792    0 00000001 00000001       6    512 I 0 44100   -10   -10  00000000 413A52E0 00000000 0x000         0 

      8    502    1 00000001 00000003      89   4786 S 1 44100  -Inf  -Inf  000012B2 413A52E0 00000000 0x600         0 

   F  2    618    1 00000001 00000003      27   8329 S 1 44100  -Inf  -Inf  00002089 413A52E0 00000000 0x600         0 

   F  4    502    1 00000001 00000003      91   4786 S 1 44100  -Inf  -Inf  000012B2 413A52E0 00000000 0x600         0 

      1    618    5 00000001 00000003      26   4096 S 1 44100     0     0  0000F800 413A52E0 00000000 0x400      1024 

   F  5    502    1 00000001 00000003      92   3101 S 1 44100  -Inf  -Inf  00000C1D 413A52E0 00000000 0x600         0 

   F  3   3476    3 00000001 00000003      11    512 A 1 44100     0     0  03A50400 413A52E0 00000000 0x400     29696 

Output thread 0x40ca5008 active tracks

   Name Client Type      Fmt Chn mask Session fCount S F SRate  L dB  R dB    Server Main buf  Aux Buf Flags UndFrmCnt

   F  3   3476    3 00000001 00000003      11    512 A 1 44100     0     0  03A50400 413A52E0 00000000 0x400     29696 

Normal mixer raw underrun counters: partial=0 empty=0

- 0 Effect Chains:

==============================================>

> adb shell dumbsys media.audio_flinger

Clients:

  pid: 502

  pid: 618

  pid: 792

  pid: 3476

Notification Clients:

  pid: 125

  pid: 502

  pid: 618

  pid: 792

  pid: 1234

  pid: 3476

  pid: 16019

  pid: 20027

Global session refs:

 session pid count

       6 792   1

      11 3476   1

      27 618   1

      89 502   1

      90 502   1

      91 502   1

     105 20027   1

     106 20027   1

     107 502   1

Hardware status: 0

Standby Time mSec: 3000

Output thread 0x40ca5008 internals

Normal frame count: 1024

last write occurred (msecs): 11

total writes: 100575

delayed writes: 0

blocked in write: 1

suspend count: 0

mix buffer : 0x413a52e0

Fast track availMask=0x20

io handle: 2

TID: 527

standby: 0

Sample rate: 44100

HAL frame count: 512

Channel Count: 2

Channel Mask: 0x00000003

Format: 1

Frame size: 4

Pending setParameters commands: 

 Index Command

Pending config events: 

AudioMixer tracks: 0000016f

FastMixer command=MIX_WRITE writeSequence=402391 framesWritten=103004672

          numTracks=2 writeErrors=14 underruns=6 overruns=38

          sampleRate=44100 frameCount=512 measuredWarmup=13.5 ms, warmupCycles=4

          mixPeriod=11.61 ms

Simple moving statistics over last 305.7 seconds:

  wall clock time in ms per mix cycle:

    mean=11.61 min=0.04 max=23.41 stddev=0.25

  raw CPU load in us per mix cycle:

    mean=326 min=0 max=8394 stddev=126

Distribution of mix cycle times in ms for the tails (> ~3 stddev outliers):

  left tail: mean=7.13 min=0.04 max=9.29 stddev=3.40

  right tail: mean=14.77 min=13.77 max=23.41 stddev=1.88

Fast tracks: kMaxFastTracks=8 activeMask=0x9

Index Active Full Partial Empty  Recent Ready

    0    yes  445       0     3    full  2048

    1     no    0       0     0    full     0

    2     no   32       2     5   empty     0

    3    yes  602       0    85    full   512

    4     no  230      28    81   empty     0

    5     no  229      27    89   empty     0

    6     no   89      11    30   empty     0

    7     no   92      11    31   empty     0

Output thread 0x40ca5008 stream volumes in dB:

    0:-8.2, 1:-27, 2:-21, 3:-14, 4:-14, 5:-21, 6:0, 7:-27, 8:-22, 9:-14

Output thread 0x40ca5008 tracks

   Name Client Type      Fmt Chn mask Session fCount S F SRate  L dB  R dB    Server Main buf  Aux Buf Flags UndFrmCnt

   F  6    502    1 00000001 00000003      90   4786 S 1 44100  -Inf  -Inf  000012B2 413A52E0 00000000 0x600         0 

   F  1    792    0 00000001 00000001       6    512 I 0 44100   -10   -10  00000000 413A52E0 00000000 0x000         0 

      8    502    1 00000001 00000003      89   4786 S 1 44100  -Inf  -Inf  000012B2 413A52E0 00000000 0x600         0 

   F  2    618    1 00000001 00000003      27   8329 S 1 44100  -Inf  -Inf  00002089 413A52E0 00000000 0x600         0 

   F  7    502    1 00000001 00000003     107   4146 S 1 44100  -Inf  -Inf  00001032 413A52E0 00000000 0x600         0 

   F  4    502    1 00000001 00000003      91   4786 S 1 44100  -Inf  -Inf  000012B2 413A52E0 00000000 0x600         0 

   F  3   3476    3 00000001 00000003      11    512 A 1 44100     0     0  05FC9E00 413A52E0 00000000 0x400     39424 

Output thread 0x40ca5008 active tracks

   Name Client Type      Fmt Chn mask Session fCount S F SRate  L dB  R dB    Server Main buf  Aux Buf Flags UndFrmCnt

   F  3   3476    3 00000001 00000003      11    512 A 1 44100     0     0  05FC9E00 413A52E0 00000000 0x400     39424 

Normal mixer raw underrun counters: partial=0 empty=3

- 0 Effect Chains:

==============================================>

> adb shell dumbsys media.audio_flinger

Clients:

  pid: 502

  pid: 618

  pid: 792

  pid: 3476

Notification Clients:

  pid: 125

  pid: 502

  pid: 618

  pid: 792

  pid: 1234

  pid: 3476

  pid: 16019

  pid: 20027

Global session refs:

 session pid count

       6 792   1

      11 3476   1

      27 618   1

      89 502   1

      90 502   1

      91 502   1

     105 20027   1

     106 20027   1

     117 502   1

     118 618   2

Hardware status: 0

Standby Time mSec: 3000

Output thread 0x40ca5008 internals

Normal frame count: 1024

last write occurred (msecs): 11

total writes: 127838

delayed writes: 0

blocked in write: 1

suspend count: 0

mix buffer : 0x413a52e0

Fast track availMask=0x20

io handle: 2

TID: 527

standby: 0

Sample rate: 44100

HAL frame count: 512

Channel Count: 2

Channel Mask: 0x00000003

Format: 1

Frame size: 4

Pending setParameters commands: 

 Index Command

Pending config events: 

AudioMixer tracks: 0000017f

FastMixer command=MIX_WRITE writeSequence=511459 framesWritten=130924032

          numTracks=2 writeErrors=18 underruns=8 overruns=47

          sampleRate=44100 frameCount=512 measuredWarmup=80.7 ms, warmupCycles=4

          mixPeriod=11.61 ms

Simple moving statistics over last 380.4 seconds:

  wall clock time in ms per mix cycle:

    mean=11.61 min=0.08 max=19.42 stddev=0.17

  raw CPU load in us per mix cycle:

    mean=332 min=64 max=1356 stddev=110

Distribution of mix cycle times in ms for the tails (> ~3 stddev outliers):

  left tail: mean=8.97 min=0.08 max=10.46 stddev=2.50

  right tail: mean=13.60 min=12.72 max=19.42 stddev=1.26

Fast tracks: kMaxFastTracks=8 activeMask=0x9

Index Active Full Partial Empty  Recent Ready

    0    yes  699       0     3    full  2048

    1     no    0       0     0    full     0

    2     no   32       2     5   empty     0

    3    yes  889       0   109    full   512

    4     no  230      28    81   empty     0

    5     no  269      32   104   empty     0

    6     no   89      11    30   empty     0

    7     no  132      16    44   empty     0

Output thread 0x40ca5008 stream volumes in dB:

    0:-8.2, 1:-27, 2:-21, 3:-14, 4:-14, 5:-21, 6:0, 7:-27, 8:-22, 9:-14

Output thread 0x40ca5008 tracks

   Name Client Type      Fmt Chn mask Session fCount S F SRate  L dB  R dB    Server Main buf  Aux Buf Flags UndFrmCnt

   F  6    502    1 00000001 00000003      90   4786 S 1 44100  -Inf  -Inf  000012B2 413A52E0 00000000 0x600         0 

   F  1    792    0 00000001 00000001       6    512 I 0 44100   -10   -10  00000000 413A52E0 00000000 0x000         0 

      8    502    1 00000001 00000003      89   4786 S 1 44100  -Inf  -Inf  000012B2 413A52E0 00000000 0x600         0 

   F  2    618    1 00000001 00000003      27   8329 S 1 44100  -Inf  -Inf  00002089 413A52E0 00000000 0x600         0 

   F  7    502    1 00000001 00000003     117   4146 S 1 44100  -Inf  -Inf  00001032 413A52E0 00000000 0x600         0 

   F  4    502    1 00000001 00000003      91   4786 S 1 44100  -Inf  -Inf  000012B2 413A52E0 00000000 0x600         0 

      4    618    5 00000001 00000003     118   4096 S 1 44100     0     0  0000F800 413A52E0 00000000 0x400         0 

   F  3   3476    3 00000001 00000003      11    512 A 1 44100     0     0  079ED800 413A52E0 00000000 0x400     50688 

Output thread 0x40ca5008 active tracks

   Name Client Type      Fmt Chn mask Session fCount S F SRate  L dB  R dB    Server Main buf  Aux Buf Flags UndFrmCnt

   F  3   3476    3 00000001 00000003      11    512 A 1 44100     0     0  079ED800 413A52E0 00000000 0x400     50688 

Normal mixer raw underrun counters: partial=0 empty=3

- 0 Effect Chains:

[Glenn Kasten]

The times are the delta times between return from write. E.g.

  write()

  get time X

  write()

  get time Y

  write()

  get time Z

The delta times are Y-X, Z-Y, etc.

A small delta time that is that so close to 0 indicates something may be wrong, but I don't know what yet.

Usually a small delta happens right after a large delta, but since the max deltas

are not as bad as the min deltas, I'm concerned there is something else going on.

Double-buffering is along the full path from Audioflinger/FastMixer to HAL

(hardware abstraction layer) to kernel driver, typically configured in the audio HAL.

<p style="margin-bottom: 0px; font-size: 12px; line-height: normal; font-family: 'C

...

[Dom Bhuphaibool]

Thanks Glenn for the clarification! 

I'm wondering if there's a way to instrument my build so that when I run systrace, it can display when my buffer queue callback is called (by the high priority audio thread). Is there some API I can use in the NDK layer that would be equivalent to the Java API android.os.Trace.beginSection()?

The reason I'm asking is that I noticed a peculiar behavior last night as I was inspecting LogCat and playing audio in our app. Our app is built with Xamarin (Mono runtime on Android). It seems that every time Mono performs its garbage collection, if the time it took to do the garbage collection is greater than twice the time it takes to play the native frame size (in my case 2 x 11.6 ms), the audio glitch occurs. The factor of 2 seems to indicate double buffering of the audio. But it's difficult to know for sure what's going on by just inspecting LogCat and listening. I would love to run systrace and see when the buffer queue callback gets called, if it ever gets preempted and/or why it's being called late occasionally, etc. 

Also, could you point me to the source code where the high priority audio thread gets created. I'm wondering if it has any signal handling routines that somehow Mono is sending it signals? It wouldn't make any sense because Mono shouldn't know anything about that thread, but I would love to take a look at that code regardless. 

Thanks again and please let me know if I can provide any other info (to help us get to the bottom of this). 

[Glenn Kasten]

systrace does not have a _public_ (stable) native API, but there is of course one internally.

I'll share it with you but please be aware that it is unstable and subject to change without notice:

  system/core/include/*utils*/*race.h

Sorry I won't be able to follow-up beyond that.

Your client callback thread is created in frameworks/av/media/libmedia/AudioTrack.cpp

One thing to check on ... do you attach the client callback thread to Dalvik VM ?
It is intended to _not_ be attached to the VM.  That could cause some disturbance.

[Dom Bhuphaibool]

Thanks Glenn for the pointer regarding a way to hook into systrace from native!!! systrace is much more useful now that I can see the buffer queue callback. 

Regarding the client callback thread (high priority client audio thread), I didn't realized it was also used for the audio player event callback as well. Although I wasn't attaching that thread to the Dalvik VM from the callback, I was however calling into the Mono VM. From talking to the guys who wrote the Mono VM, it sounds like implicitly attaching to their VM could cause this thread to be suspended during their GC. I've since fixed this so that client callback thread no longer leaves native land. Listening to the audio, it seemed to have been improved (less glitches) but I still have a question. I've been doing a periodic sysdump of media.audio_flinger and it still reports a left tail minimum of <= 0.05 ms. Not really sure what could be causing that. 

I will try to continue with profiling with systrace and report back when I have more data. If you can think of anything else, please let me know. 

One last question... On Nexus 5 running Android 4.4.2, when I inspect the threads in my process, the high priority audio thread is listed as SCHED_CFS instead of SCHED_FIFO. The nice value is -16 but I was wondering why on different devices, the thread scheduling priorities were different. 

Thanks! 

[Glenn Kasten]

> left tail minimum of ~0

Yes, that is disturbing to me.  

I suspect it's not glitching because double-buffering is hiding over this.

I'd like to get to the root cause of this.

> SCHED_CFS on Nexus 5

Are you using native sample rate, as reported by this API

http://developer.android.com/reference/android/media/AudioManager.html#PROPERTY_OUTPUT_SAMPLE_RATE

Nexus 5 and Nexus 7 2010 have different native sample rates, and different native recommended frame counts per buffer

for fast track.   If correct native sample rate is not used, the fast path is disabled.

[Dom Bhuphaibool]

> Regarding Nexus 5 and Nexus 7 2010

Ah yes, what you said makes complete sense since Nexus 5 native sampling rate is 48 kHz and I'm sending it 44.1 kHz. (So, SCHED_FIFO is only used for fast track then)

> Regarding left tail min of ~0

Your comment regarding double-buffering hiding this also makes a lot of sense. I've been listening on the Nexus 7 now for the past hour and it's definitely much better. When I don't interact with the device and only use it for audio playback, I seldom hear glitches. When I tax the system by switching between different apps, sometimes audio glitches occur, but I'm assuming that this is expected (? due to the load on the CPU). Running systrace for an extended time is a bit unstable (in the output), but this is expected as you had warned me. My next task is to test more with the Nexus 5, where we're not using the fast path route. 

Thanks for your help thus far Glenn! You've been tremendous!!!