Audio Debugging
This article describes some tips and tricks for debugging Android audio.
Tee Sink
The "tee sink" is an AudioFlinger debugging feature, available in custom builds only, for retaining a short fragment of recent audio for later analysis. This permits comparison between what was actually played or recorded vs. what was expected.
For privacy the tee sink is disabled by default, at both compile-time and run-time. To use the tee sink, you will need to enable it by re-compiling, and also by setting a property. Be sure to disable this feature after you are done debugging; the tee sink should not be left enabled in production builds.
The instructions in the remainder of this section are for Android 4.4, and may require changes for other versions.
Compile-time setup
cd frameworks/av/services/audioflinger
- edit
Configuration.h
- uncomment
#define TEE_SINK
- re-build
libaudioflinger.so
adb root
adb remount
- push or sync the new
libaudioflinger.so
to the device's/system/lib
Run-time setup
adb shell getprop | grep ro.debuggable
Confirm that the output is:[ro.debuggable]: [1]
adb shell
ls -ld /data/misc/media
Confirm that the output is:
drwx------ media media ... media
If the directory does not exist, create it as follows:
mkdir /data/misc/media chown media:media /data/misc/media
echo af.tee=# > /data/local.prop
where theaf.tee
value is a number described belowchmod 644 /data/local.prop
reboot
Values for af.tee
property
The value of af.tee
is a number between 0 and 7, expressing the sum of several bits, one per feature. See the code at AudioFlinger::AudioFlinger()
in AudioFlinger.cpp
for an explanation of each bit, but briefly:
- 1 = input
- 2 = FastMixer output
- 4 = per-track AudioRecord and AudioTrack
There is no bit for deep buffer or normal mixer yet, but you can get similar results using "4."
Test and acquire data
- Run your audio test
adb shell dumpsys media.audio_flinger
- Look for a line in dumpsys output such as this:
tee copied to /data/misc/media/20131010101147_2.wav
This is a PCM .wav file
adb pull
any/data/misc/media/*.wav
files of interest; note that track-specific dump filenames do not appear in the dumpsys output, but are still saved to/data/misc/media
upon track closure- Review the dump files for privacy concerns before sharing with others
Suggestions
Try these ideas for more useful results:
- Disable touch sounds and key clicks
- Maximize all volumes
- Disable apps that make sound or record from microphone, if they are not of interest to your test
- Track-specific dumps are only saved when the track is closed; you may need to force close an app in order to dump its track-specific data
- Do the
dumpsys
immediately after test; there is a limited amount of recording space available - To make sure you don't lose your dump files, upload them to your host periodically. Only a limited number of dump files are preserved; older dumps are removed after that limit is reached.
Restore
As noted above, the tee sink feature should not be left enabled. Restore your build and device as follows:
- Revert the source code changes to
Configuration.h
- Re-build
libaudioflinger.so
- Push or sync the restored
libaudioflinger.so
to the device's/system/lib
adb shell
rm /data/local.prop
rm /data/misc/media/*.wav
reboot
media.log
ALOGx macros
The standard Java language logging API in Android SDK is android.util.Log.
The corresponding C language API in Android NDK is __android_log_print
declared in <android/log.h>
.
Within the native portion of Android framework, we prefer macros named ALOGE
, ALOGW
, ALOGI
, ALOGV
, etc. They are declared in <utils/Log.h>
, and for the purposes of this article we'll collectively refer to them as ALOGx
.
All of these APIs are easy-to-use and well-understood, so they are pervasive throughout the Android platform. In particular the mediaserver
process, which includes the AudioFlinger sound server, uses ALOGx
extensively.
Nevertheless, there are some limitations to ALOGx
and friends:
- They are suspectible to "log spam": the log buffer is a shared resource so it can easily overflow due to unrelated log entries, resulting in missed information. The
ALOGV
variant is disabled at compile-time by default. But of course even it can result in log spam if it is enabled. - The underlying kernel system calls could block, possibly resulting in priority inversion and consequently measurement disturbances and inaccuracies. This is of special concern to time-critical threads such as
FastMixer
. - If a particular log is disabled to reduce log spam, then any information that would have been captured by that log is lost. It is not possible to enable a specific log retroactively, after it becomes clear that the log would have been interesting.
NBLOG, media.log, and MediaLogService
The NBLOG
APIs and associated media.log
process and MediaLogService
service together form a newer logging system for media, and are specifically designed to address the issues above. We will loosely use the term "media.log" to refer to all three, but strictly speaking NBLOG
is the C++ logging API, media.log
is a Linux process name, and MediaLogService
is an Android binder service for examining the logs.
A media.log
"timeline" is a series of log entries whose relative ordering is preserved. By convention, each thread should use it's own timeline.
Benefits
The benefits of the media.log
system include:
- doesn't spam the main log unless and until it is needed
- can be examined even when
mediaserver
crashes or hangs - is non-blocking per timeline
- less disturbance to performance (of course no form of logging is completely non-intrusive)
Architecture
The diagram below shows the relationship of the mediaserver
process and the init
process, before media.log
is introduced:
Notable points:
init
forks and execsmediaserver
init
detects the death ofmediaserver
, and re-forks as necessaryALOGx
logging is not shown
The diagram below shows the new relationship of the components, after media.log
is added to the architecture:
Important changes:
- Clients use
NBLOG
API to construct log entries and append them to a circular buffer in shared memory. MediaLogService
can dump the contents of the circular buffer at any time.- The circular buffer is designed in such a way that any corruption of the shared memory will not crash
MediaLogService
, and it will still be able to dump as much of the buffer that is not affected by the corruption. - The circular buffer is non-blocking and lock-free for both writing new entries and reading existing entries.
- No kernel system calls are required to write to or read from the circular buffer (other than optional timestamps).
Where to use
As of Android 4.4, there are only a few log points in AudioFlinger that use the media.log
system. Though the new APIs are not as easy to use as ALOGx
, they are not extremely difficult either. We encourage you to learn the new logging system for those occasions when it is indispensable. In particular, it is recommended for AudioFlinger threads that must run frequently, periodically, and without blocking such as the FastMixer
thread.
How to use
Add logs
First, you need to add logs to your code.
In FastMixer
thread, use code such as this:
logWriter->log("string"); logWriter->logf("format", parameters); logWriter->logTimestamp();
As this NBLog
timeline is used only by the FastMixer
thread, there is no need for mutual exclusion.
In other AudioFlinger threads, use mNBLogWriter
:
mNBLogWriter->log("string"); mNBLogWriter->logf("format", parameters); mNBLogWriter->logTimestamp();
For threads other than FastMixer
, the thread's NBLog
timeline can be used by both the thread itself, and by binder operations. NBLog::Writer
does not provide any implicit mutual exclusion per timeline, so be sure that all logs occur within a context where the thread's mutex mLock
is held.
After you have added the logs, re-build AudioFlinger.
Caution:A separate NBLog::Writer
timeline is required per thread, to ensure thread safety, since timelines omit mutexes by design. If you want more than one thread to use the same timeline, you can protect with an existing mutex (as described above for mLock
). Or you can use the NBLog::LockedWriter
wrapper instead of NBLog::Writer
. However, this negates a prime benefit of this API: its non-blocking behavior.
The full NBLog
API is at frameworks/av/include/media/nbaio/NBLog.h
.
Enable media.log
media.log
is disabled by default. It is active only when property ro.test_harness
is 1
. You can enable it by:
adb root adb shell echo ro.test_harness=1 > /data/local.prop chmod 644 /data/local.prop reboot
The connection is lost during reboot, so:
adb shell
The command
ps media
will now show two processes:
- media.log
- mediaserver
Note the process ID of mediaserver
for later.
Displaying the timelines
You can manually request a log dump at any time. This command shows logs from all the active and recent timelines, and then clears them:
dumpsys media.log
Note that by design timelines are independent, and there is no facility for merging timelines.
Recovering logs after mediaserver death
Now try killing mediaserver
process: kill -9 #
, where # is the process ID you noted earlier. You should see a dump from media.log
in the main logcat
, showing all the logs leading up to the crash.
dumpsys media.log