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