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 && adb disable-verity && 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=# > /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><android/log.h></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><utils/Log.h></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->log("string"); 351 logWriter->logf("format", parameters); 352 logWriter->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->log("string"); 365 mNBLogWriter->logf("format", parameters); 366 mNBLogWriter->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