Add audio debugging, section media.log
Change-Id: I6d920c45caa6f74448d484cb0888b264752bbd62
diff --git a/src/devices/audio_debugging.jd b/src/devices/audio_debugging.jd
index 3142045..31d61d5 100644
--- a/src/devices/audio_debugging.jd
+++ b/src/devices/audio_debugging.jd
@@ -151,3 +151,271 @@
<li><code>reboot</code></li>
</ol>
+<h2 id="mediaLog">media.log</h2>
+
+<h3>ALOGx macros</h3>
+
+<p>
+The standard Java language logging API in Android SDK is
+<a class="external-link" href="http://developer.android.com/reference/android/util/Log.html" target="_android">android.util.Log</a>.
+</p>
+
+<p>
+The corresponding C language API in Android NDK is
+<code>__android_log_print</code>
+declared in <code><android/log.h></code>.
+</p>
+
+<p>
+Within the native portion of Android framework, we
+prefer macros named <code>ALOGE</code>, <code>ALOGW</code>,
+<code>ALOGI</code>, <code>ALOGV</code>, etc. They are declared in
+<code><utils/Log.h></code>, and for the purposes of this article
+we'll collectively refer to them as <code>ALOGx</code>.
+</p>
+
+<p>
+All of these APIs are easy-to-use and well-understood, so they are pervasive
+throughout the Android platform. In particular the <code>mediaserver</code>
+process, which includes the AudioFlinger sound server, uses
+<code>ALOGx</code> extensively.
+</p>
+
+<p>
+Nevertheless, there are some limitations to <code>ALOGx</code> and friends:
+</p>
+
+<ul>
+<li>
+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 <code>ALOGV</code> variant is disabled at
+compile-time by default. But of course even it can result in log spam
+if it is enabled.
+</li>
+<li>
+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 <code>FastMixer</code>.
+</li>
+<li>
+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,
+<i>after</i> it becomes clear that the log would have been interesting.
+</li>
+</ul>
+
+<h3>NBLOG, media.log, and MediaLogService</h3>
+
+<p>
+The <code>NBLOG</code> APIs and associated <code>media.log</code>
+process and <code>MediaLogService</code>
+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 <code>NBLOG</code> is the
+C++ logging API, <code>media.log</code> is a Linux process name, and <code>MediaLogService</code>
+is an Android binder service for examining the logs.
+</p>
+
+<p>
+A <code>media.log</code> "timeline" is a series
+of log entries whose relative ordering is preserved.
+By convention, each thread should use it's own timeline.
+</p>
+
+<h3>Benefits</h3>
+
+<p>
+The benefits of the <code>media.log</code> system include:
+</p>
+<ul>
+<li>doesn't spam the main log unless and until it is needed</li>
+<li>can be examined even when <code>mediaserver</code> crashes or hangs</li>
+<li>is non-blocking per timeline</li>
+<li>
+less disturbance to performance
+(of course no form of logging is completely non-intrusive)
+</li>
+</ul>
+
+<h3>Architecture</h3>
+
+<p>
+The diagram below shows the relationship of the <code>mediaserver</code> process
+and the <code>init</code> process, before <code>media.log</code> is introduced:
+</p>
+<img src="audio/images/medialog_before.png" alt="Architecture before media.log" />
+<p>
+Notable points:
+</p>
+<ul>
+<li><code>init</code> forks and execs <code>mediaserver</code></li>
+<li><code>init</code> detects the death of <code>mediaserver</code>, and re-forks as necessary</li>
+<li><code>ALOGx</code> logging is not shown
+</ul>
+
+<p>
+The diagram below shows the new relationship of the components,
+after <code>media.log</code> is added to the architecture:
+</p>
+<img src="audio/images/medialog_after.png" alt="Architecture after media.log" />
+<p>
+Important changes:
+</p>
+
+<ul>
+
+<li>
+Clients use <code>NBLOG</code> API to construct log entries and append them to
+a circular buffer in shared memory.
+</li>
+
+<li>
+<code>MediaLogService</code> can dump the contents of the circular buffer at any time.
+</li>
+
+<li>
+The circular buffer is designed in such a way that any corruption of the
+shared memory will not crash <code>MediaLogService</code>, and it will still be able
+to dump as much of the buffer that is not affected by the corruption.
+</li>
+
+<li>
+The circular buffer is non-blocking and lock-free for both writing
+new entries and reading existing entries.
+</li>
+
+<li>
+No kernel system calls are required to write to or read from the circular buffer
+(other than optional timestamps).
+</li>
+
+</ul>
+
+<h4>Where to use</h4>
+
+<p>
+As of Android 4.4, there are only a few log points in AudioFlinger
+that use the <code>media.log</code> system. Though the new APIs are not as
+easy to use as <code>ALOGx</code>, 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
+<code>FastMixer</code> thread.
+</p>
+
+<h3>How to use</h3>
+
+<h4>Add logs</h4>
+
+<p>
+First, you need to add logs to your code.
+</p>
+
+<p>
+In <code>FastMixer</code> thread, use code such as this:
+</p>
+<pre>
+logWriter->log("string");
+logWriter->logf("format", parameters);
+logWriter->logTimestamp();
+</pre>
+<p>
+As this <code>NBLog</code> timeline is used only by the <code>FastMixer</code> thread,
+there is no need for mutual exclusion.
+</p>
+
+<p>
+In other AudioFlinger threads, use <code>mNBLogWriter</code>:
+</p>
+<pre>
+mNBLogWriter->log("string");
+mNBLogWriter->logf("format", parameters);
+mNBLogWriter->logTimestamp();
+</pre>
+<p>
+For threads other than <code>FastMixer</code>,
+the thread's <code>NBLog</code> timeline can be used by both the thread itself, and
+by binder operations. <code>NBLog::Writer</code> does not provide any
+implicit mutual exclusion per timeline, so be sure that all logs occur
+within a context where the thread's mutex <code>mLock</code> is held.
+</p>
+
+<p>
+After you have added the logs, re-build AudioFlinger.
+</p>
+
+<b>Caution:</b>
+<p>
+A separate <code>NBLog::Writer</code> 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 <code>mLock</code>). Or you can
+use the <code>NBLog::LockedWriter</code> wrapper instead of <code>NBLog::Writer</code>.
+However, this negates a prime benefit of this API: its non-blocking
+behavior.
+</p>
+
+<p>
+The full <code>NBLog</code> API is at <code>frameworks/av/include/media/nbaio/NBLog.h</code>.
+</p>
+
+<h4>Enable media.log</h4>
+
+<p>
+<code>media.log</code> is disabled by default. It is active only when property
+<code>ro.test_harness</code> is <code>1</code>. You can enable it by:
+</p>
+
+<pre>
+adb root
+adb shell
+echo ro.test_harness=1 > /data/local.prop
+chmod 644 /data/local.prop
+reboot
+</pre>
+
+<p>
+The connection is lost during reboot, so:
+</p>
+<pre>
+adb shell
+</pre>
+
+The command <code>ps media</code> will now show two processes:
+<ul>
+<li>media.log</li>
+<li>mediaserver</li>
+</ul>
+<p>
+Note the process ID of <code>mediaserver</code> for later.
+</p>
+
+<h4>Displaying the timelines</h4>
+
+<p>
+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:
+</p>
+<pre>
+dumpsys media.log
+</pre>
+
+<p>
+Note that by design timelines are independent,
+and there is no facility for merging timelines.
+</p>
+
+<h4>Recovering logs after mediaserver death</h4>
+
+<p>
+Now try killing <code>mediaserver</code> process: <code>kill -9 #</code>, where # is
+the process ID you noted earlier. You should see a dump from <code>media.log</code>
+in the main <code>logcat</code>, showing all the logs leading up to the crash.
+</p>
+<pre>
+dumpsys media.log
+</pre>