Home | History | Annotate | Download | only in audio
      1 page.title=Audio Debugging
      2 @jd:body
      3 
      4 <!--
      5     Copyright 2013 The Android Open Source Project
      6 
      7     Licensed under the Apache License, Version 2.0 (the "License");
      8     you may not use this file except in compliance with the License.
      9     You may obtain a copy of the License at
     10 
     11         http://www.apache.org/licenses/LICENSE-2.0
     12 
     13     Unless required by applicable law or agreed to in writing, software
     14     distributed under the License is distributed on an "AS IS" BASIS,
     15     WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
     16     See the License for the specific language governing permissions and
     17     limitations under the License.
     18 -->
     19 <div id="qv-wrapper">
     20   <div id="qv">
     21     <h2>In this document</h2>
     22     <ol id="auto-toc">
     23     </ol>
     24   </div>
     25 </div>
     26 
     27 <p>
     28 This article describes some tips and tricks for debugging Android audio.
     29 </p>
     30 
     31 <h2 id="teeSink">Tee Sink</h2>
     32 
     33 <p>
     34 The "tee sink" is
     35 an AudioFlinger debugging feature, available in custom builds only,
     36 for retaining a short fragment of recent audio for later analysis.
     37 This permits comparison between what was actually played or recorded
     38 vs. what was expected.
     39 </p>
     40 
     41 <p>
     42 For privacy the tee sink is disabled by default, at both compile-time and
     43 run-time.  To use the tee sink, you will need to enable it by re-compiling,
     44 and also by setting a property.  Be sure to disable this feature after you are
     45 done debugging; the tee sink should not be left enabled in production builds.
     46 </p>
     47 
     48 <p>
     49 The instructions in the remainder of this section are for Android 5.x and 6.x.
     50 For Android 7.x, replace <code>/data/misc/media</code> with
     51 <code>/data/misc/audioserver</code>.
     52 Additionally, you must use a userdebug or eng build.
     53 If you use a userdebug build, then disable verity with:</p>
     54 <pre>
     55 <code>$ adb root &amp;&amp; adb disable-verity &amp;&amp; adb reboot</code>
     56 </pre>
     57 
     58 <h3 id="compile">Compile-time setup</h3>
     59 
     60 <ol>
     61 <li><code>$ cd frameworks/av/services/audioflinger</code></li>
     62 <li>Edit <code>Configuration.h</code>.</li>
     63 <li>Uncomment <code>#define TEE_SINK</code>.</li>
     64 <li>Re-build <code>libaudioflinger.so</code>.</li>
     65 <li><code>$ adb root</code></li>
     66 <li><code>$ adb remount</code></li>
     67 <li>Push or sync the new <code>libaudioflinger.so</code> to the device's <code>/system/lib</code>.</li>
     68 </ol>
     69 
     70 <h3 id="runtime">Run-time setup</h3>
     71 
     72 <ol>
     73 <li><code>$ adb shell getprop | grep ro.debuggable</code>
     74 <br />Confirm that the output is: <code>[ro.debuggable]: [1]</code>
     75 </li>
     76 <li><code>$ adb shell</code></li>
     77 <li><code>$ ls -ld /data/misc/media</code>
     78 <br />
     79 <p>
     80 Confirm that the output is:
     81 </p>
     82 <pre>
     83 drwx------ media media ... media
     84 </pre>
     85 <br />
     86 <p>
     87 If the directory does not exist, create it as follows:
     88 </p>
     89 <pre>
     90 $ mkdir /data/misc/media
     91 $ chown media:media /data/misc/media
     92 </pre>
     93 </li>
     94 <li><code>$ echo af.tee=# &gt; /data/local.prop</code>
     95 <br />Where the <code>af.tee</code> value is a number described below.
     96 </li>
     97 <li><code>$ chmod 644 /data/local.prop</code></li>
     98 <li><code>$ reboot</code></li>
     99 </ol>
    100 
    101 <h4>Values for <code>af.tee</code> property</h4>
    102 
    103 <p>
    104 The value of <code>af.tee</code> is a number between 0 and 7, expressing
    105 the sum of several bits, one per feature.
    106 See the code at <code>AudioFlinger::AudioFlinger()</code> in <code>AudioFlinger.cpp</code>
    107 for an explanation of each bit, but briefly:
    108 </p>
    109 <ul>
    110 <li>1 = input</li>
    111 <li>2 = FastMixer output</li>
    112 <li>4 = per-track AudioRecord and AudioTrack</li>
    113 </ul>
    114 
    115 <p>
    116 There is no bit for deep buffer or normal mixer yet,
    117 but you can get similar results using "4."
    118 </p>
    119 
    120 <h3 id="test">Test and acquire data</h3>
    121 
    122 <ol>
    123 <li>Run your audio test.</li>
    124 <li><code>$ adb shell dumpsys media.audio_flinger</code></li>
    125 <li>Look for a line in dumpsys output such as this:<br />
    126 <code>tee copied to /data/misc/media/20131010101147_2.wav</code>
    127 <br />This is a PCM .wav file.
    128 </li>
    129 <li>Then <code>adb pull</code> any <code>/data/misc/media/*.wav</code> files of interest;
    130 note that track-specific dump filenames do not appear in the dumpsys output,
    131 but are still saved to <code>/data/misc/media</code> upon track closure.
    132 </li>
    133 <li>Review the dump files for privacy concerns before sharing with others.</li>
    134 </ol>
    135 
    136 <h4>Suggestions</h4>
    137 
    138 <p>Try these ideas for more useful results:</p>
    139 
    140 <ul>
    141 <li>Disable touch sounds and key clicks to reduce interruptions in test output.</li>
    142 <li>Maximize all volumes.</li>
    143 <li>Disable apps that make sound or record from microphone,
    144 if they are not of interest to your test.
    145 </li>
    146 <li>Track-specific dumps are only saved when the track is closed;
    147 you may need to force close an app in order to dump its track-specific data
    148 </li>
    149 <li>Do the <code>dumpsys</code> immediately after test;
    150 there is a limited amount of recording space available.</li>
    151 <li>To make sure you don't lose your dump files,
    152 upload them to your host periodically.
    153 Only a limited number of dump files are preserved;
    154 older dumps are removed after that limit is reached.</li>
    155 </ul>
    156 
    157 <h3 id="restore">Restore</h3>
    158 
    159 <p>
    160 As noted above, the tee sink feature should not be left enabled.
    161 Restore your build and device as follows:
    162 </p>
    163 <ol>
    164 <li>Revert the source code changes to <code>Configuration.h</code>.</li>
    165 <li>Re-build <code>libaudioflinger.so</code>.</li>
    166 <li>Push or sync the restored <code>libaudioflinger.so</code>
    167 to the device's <code>/system/lib</code>.
    168 </li>
    169 <li><code>$ adb shell</code></li>
    170 <li><code>$ rm /data/local.prop</code></li>
    171 <li><code>$ rm /data/misc/media/*.wav</code></li>
    172 <li><code>$ reboot</code></li>
    173 </ol>
    174 
    175 <h2 id="mediaLog">media.log</h2>
    176 
    177 <h3 id="alogx">ALOGx macros</h3>
    178 
    179 <p>
    180 The standard Java language logging API in Android SDK is
    181 <a href="http://developer.android.com/reference/android/util/Log.html">android.util.Log</a>.
    182 </p>
    183 
    184 <p>
    185 The corresponding C language API in Android NDK is
    186 <code>__android_log_print</code>
    187 declared in <code>&lt;android/log.h&gt;</code>.
    188 </p>
    189 
    190 <p>
    191 Within the native portion of Android framework, we
    192 prefer macros named <code>ALOGE</code>, <code>ALOGW</code>,
    193 <code>ALOGI</code>, <code>ALOGV</code>, etc.  They are declared in
    194 <code>&lt;utils/Log.h&gt;</code>, and for the purposes of this article
    195 we'll collectively refer to them as <code>ALOGx</code>.
    196 </p>
    197 
    198 <p>
    199 All of these APIs are easy-to-use and well-understood, so they are pervasive
    200 throughout the Android platform.  In particular the <code>mediaserver</code>
    201 process, which includes the AudioFlinger sound server, uses
    202 <code>ALOGx</code> extensively.
    203 </p>
    204 
    205 <p>
    206 Nevertheless, there are some limitations to <code>ALOGx</code> and friends:
    207 </p>
    208 
    209 <ul>
    210 <li>
    211 They are susceptible to "log spam": the log buffer is a shared resource
    212 so it can easily overflow due to unrelated log entries, resulting in
    213 missed information.  The <code>ALOGV</code> variant is disabled at
    214 compile-time by default.  But of course even it can result in log spam
    215 if it is enabled.
    216 </li>
    217 <li>
    218 The underlying kernel system calls could block, possibly resulting in
    219 priority inversion and consequently measurement disturbances and
    220 inaccuracies.  This is of
    221 special concern to time-critical threads such as <code>FastMixer</code> and <code>FastCapture</code>.
    222 </li>
    223 <li>
    224 If a particular log is disabled to reduce log spam,
    225 then any information that would have been captured by that log is lost.
    226 It is not possible to enable a specific log retroactively,
    227 <i>after</i> it becomes clear that the log would have been interesting.
    228 </li>
    229 </ul>
    230 
    231 <h3 id="nblog">NBLOG, media.log, and MediaLogService</h3>
    232 
    233 <p>
    234 The <code>NBLOG</code> APIs and associated <code>media.log</code>
    235 process and <code>MediaLogService</code>
    236 service together form a newer logging system for media, and are specifically
    237 designed to address the issues above.  We will loosely use the term
    238 "media.log" to refer to all three, but strictly speaking <code>NBLOG</code> is the
    239 C++ logging API, <code>media.log</code> is a Linux process name, and <code>MediaLogService</code>
    240 is an Android binder service for examining the logs.
    241 </p>
    242 
    243 <p>
    244 A <code>media.log</code> "timeline" is a series
    245 of log entries whose relative ordering is preserved.
    246 By convention, each thread should use it's own timeline.
    247 </p>
    248 
    249 <h3 id="benefits">Benefits</h3>
    250 
    251 <p>
    252 The benefits of the <code>media.log</code> system are that it:
    253 </p>
    254 <ul>
    255 <li>Doesn't spam the main log unless and until it is needed.</li>
    256 <li>Can be examined even when <code>mediaserver</code> crashes or hangs.</li>
    257 <li>Is non-blocking per timeline.</li>
    258 <li>Offers less disturbance to performance.
    259 (Of course no form of logging is completely non-intrusive.)
    260 </li>
    261 </ul>
    262 
    263 <h3 id="architecture">Architecture</h3>
    264 
    265 <p>
    266 The diagram below shows the relationship of the <code>mediaserver</code> process
    267 and the <code>init</code> process, before <code>media.log</code> is introduced:
    268 </p>
    269 <img src="images/medialog_before.png" alt="Architecture before media.log" id="figure1" />
    270 <p class="img-caption">
    271   <strong>Figure 1.</strong> Architecture before media.log
    272 </p>
    273 
    274 <p>
    275 Notable points:
    276 </p>
    277 <ul>
    278 <li><code>init</code> forks and execs <code>mediaserver</code>.</li>
    279 <li><code>init</code> detects the death of <code>mediaserver</code>, and re-forks as necessary.</li>
    280 <li><code>ALOGx</code> logging is not shown.</li>
    281 </ul>
    282 
    283 <p>
    284 The diagram below shows the new relationship of the components,
    285 after <code>media.log</code> is added to the architecture:
    286 </p>
    287 <img src="images/medialog_after.png" alt="Architecture after media.log" id="figure2" />
    288 <p class="img-caption">
    289   <strong>Figure 2.</strong> Architecture after media.log
    290 </p>
    291 
    292 <p>
    293 Important changes:
    294 </p>
    295 
    296 <ul>
    297 
    298 <li>
    299 Clients use <code>NBLOG</code> API to construct log entries and append them to
    300 a circular buffer in shared memory.
    301 </li>
    302 
    303 <li>
    304 <code>MediaLogService</code> can dump the contents of the circular buffer at any time.
    305 </li>
    306 
    307 <li>
    308 The circular buffer is designed in such a way that any corruption of the
    309 shared memory will not crash <code>MediaLogService</code>, and it will still be able
    310 to dump as much of the buffer that is not affected by the corruption.
    311 </li>
    312 
    313 <li>
    314 The circular buffer is non-blocking and lock-free for both writing
    315 new entries and reading existing entries.
    316 </li>
    317 
    318 <li>
    319 No kernel system calls are required to write to or read from the circular buffer
    320 (other than optional timestamps).
    321 </li>
    322 
    323 </ul>
    324 
    325 <h4>Where to use</h4>
    326 
    327 <p>
    328 As of Android 4.4, there are only a few log points in AudioFlinger
    329 that use the <code>media.log</code> system.  Though the new APIs are not as
    330 easy to use as <code>ALOGx</code>, they are not extremely difficult either.
    331 We encourage you to learn the new logging system for those
    332 occasions when it is indispensable.
    333 In particular, it is recommended for AudioFlinger threads that must
    334 run frequently, periodically, and without blocking such as the
    335 <code>FastMixer</code> and <code>FastCapture</code> threads.
    336 </p>
    337 
    338 <h3 id="how">How to use</h3>
    339 
    340 <h4>Add logs</h4>
    341 
    342 <p>
    343 First, you need to add logs to your code.
    344 </p>
    345 
    346 <p>
    347 In <code>FastMixer</code> and <code>FastCapture</code> threads, use code such as this:
    348 </p>
    349 <pre>
    350 logWriter-&gt;log("string");
    351 logWriter-&gt;logf("format", parameters);
    352 logWriter-&gt;logTimestamp();
    353 </pre>
    354 <p>
    355 As this <code>NBLog</code> timeline is used only by the <code>FastMixer</code> and
    356 <code>FastCapture</code> threads,
    357 there is no need for mutual exclusion.
    358 </p>
    359 
    360 <p>
    361 In other AudioFlinger threads, use <code>mNBLogWriter</code>:
    362 </p>
    363 <pre>
    364 mNBLogWriter-&gt;log("string");
    365 mNBLogWriter-&gt;logf("format", parameters);
    366 mNBLogWriter-&gt;logTimestamp();
    367 </pre>
    368 <p>
    369 For threads other than <code>FastMixer</code> and <code>FastCapture</code>,
    370 the thread's <code>NBLog</code> timeline can be used by both the thread itself, and
    371 by binder operations.  <code>NBLog::Writer</code> does not provide any
    372 implicit mutual exclusion per timeline, so be sure that all logs occur
    373 within a context where the thread's mutex <code>mLock</code> is held.
    374 </p>
    375 
    376 <p>
    377 After you have added the logs, re-build AudioFlinger.
    378 </p>
    379 
    380 <p class="caution"><strong>Caution:</strong>
    381 A separate <code>NBLog::Writer</code> timeline is required per thread,
    382 to ensure thread safety, since timelines omit mutexes by design.  If you
    383 want more than one thread to use the same timeline, you can protect with an
    384 existing mutex (as described above for <code>mLock</code>).  Or you can
    385 use the <code>NBLog::LockedWriter</code> wrapper instead of <code>NBLog::Writer</code>.
    386 However, this negates a prime benefit of this API: its non-blocking
    387 behavior.
    388 </p>
    389 
    390 <p>
    391 The full <code>NBLog</code> API is at <code>frameworks/av/include/media/nbaio/NBLog.h</code>.
    392 </p>
    393 
    394 <h4>Enable media.log</h4>
    395 
    396 <p>
    397 <code>media.log</code> is disabled by default. It is active only when property
    398 <code>ro.test_harness</code> is <code>1</code>.  You can enable it by:
    399 </p>
    400 
    401 <pre>
    402 $ adb root
    403 $ adb shell
    404 $ echo ro.test_harness=1 > /data/local.prop
    405 $ chmod 644 /data/local.prop
    406 $ reboot
    407 </pre>
    408 
    409 <p>
    410 The connection is lost during reboot, so:
    411 </p>
    412 <pre>
    413 $ adb shell
    414 </pre>
    415 
    416 The command <code>ps media</code> will now show two processes:
    417 <ul>
    418 <li>media.log</li>
    419 <li>mediaserver</li>
    420 </ul>
    421 <p>
    422 Note the process ID of <code>mediaserver</code> for later.
    423 </p>
    424 
    425 <h4>Displaying the timelines</h4>
    426 
    427 <p>
    428 You can manually request a log dump at any time.
    429 This command shows logs from all the active and recent timelines, and then clears them:
    430 </p>
    431 <pre>
    432 $ dumpsys media.log
    433 </pre>
    434 
    435 <p>
    436 Note that by design timelines are independent,
    437 and there is no facility for merging timelines.
    438 </p>
    439 
    440 <h4>Recovering logs after mediaserver death</h4>
    441 
    442 <p>
    443 Now try killing <code>mediaserver</code> process: <code>kill -9 #</code>, where # is
    444 the process ID you noted earlier.  You should see a dump from <code>media.log</code>
    445 in the main <code>logcat</code>, showing all the logs leading up to the crash.
    446 </p>
    447 <pre>
    448 $ dumpsys media.log
    449 </pre>
    450