Add event-log logging for TTS requests.

Change-Id: I5023194c469a602b85259088a2e59373c96a941e
diff --git a/Android.mk b/Android.mk
index 9fbdde7..335fb73 100644
--- a/Android.mk
+++ b/Android.mk
@@ -36,6 +36,7 @@
 # EventLogTags files.
 LOCAL_SRC_FILES += \
        core/java/android/content/EventLogTags.logtags \
+       core/java/android/speech/tts/EventLogTags.logtags \
        core/java/android/webkit/EventLogTags.logtags \
        telephony/java/com/android/internal/telephony/EventLogTags.logtags \
 
diff --git a/core/java/android/speech/tts/AudioPlaybackHandler.java b/core/java/android/speech/tts/AudioPlaybackHandler.java
index c7603ee..8ef4295 100644
--- a/core/java/android/speech/tts/AudioPlaybackHandler.java
+++ b/core/java/android/speech/tts/AudioPlaybackHandler.java
@@ -384,11 +384,16 @@
             }
             count += written;
         }
+
+        param.mLogger.onPlaybackStart();
     }
 
     private void handleSynthesisDone(MessageParams msg) {
         final SynthesisMessageParams params = (SynthesisMessageParams) msg;
         handleSynthesisDone(params);
+        // This call is delayed more than it should be, but we are
+        // certain at this point that we have all the data we want.
+        params.mLogger.onWriteData();
     }
 
     // Flush all remaining data to the audio track, stop it and release
@@ -416,6 +421,8 @@
         final SynthesisMessageParams params = (SynthesisMessageParams) msg;
         if (DBG) Log.d(TAG, "completeAudioAvailable(" + params + ")");
 
+        params.mLogger.onPlaybackStart();
+
         // Channel config and bytes per frame are checked before
         // this message is sent.
         int channelConfig = AudioPlaybackHandler.getChannelConfig(params.mChannelCount);
diff --git a/core/java/android/speech/tts/EventLogTags.logtags b/core/java/android/speech/tts/EventLogTags.logtags
new file mode 100644
index 0000000..1a9f5fe
--- /dev/null
+++ b/core/java/android/speech/tts/EventLogTags.logtags
@@ -0,0 +1,6 @@
+# See system/core/logcat/event.logtags for a description of the format of this file.
+
+option java_package android.speech.tts;
+
+76001 tts_speak_success (engine|3),(caller|3),(length|1),(locale|3),(rate|1),(pitch|1),(engine_latency|2|3),(engine_total|2|3),(audio_latency|2|3)
+76002 tts_speak_failure (engine|3),(caller|3),(length|1),(locale|3),(rate|1),(pitch|1)
diff --git a/core/java/android/speech/tts/EventLogger.java b/core/java/android/speech/tts/EventLogger.java
new file mode 100644
index 0000000..63b954b
--- /dev/null
+++ b/core/java/android/speech/tts/EventLogger.java
@@ -0,0 +1,175 @@
+/*
+ * Copyright (C) 2011 The Android Open Source Project
+ *
+ * Licensed under the Apache License, Version 2.0 (the "License"); you may not
+ * use this file except in compliance with the License. You may obtain a copy of
+ * the License at
+ *
+ * http://www.apache.org/licenses/LICENSE-2.0
+ *
+ * Unless required by applicable law or agreed to in writing, software
+ * distributed under the License is distributed on an "AS IS" BASIS, WITHOUT
+ * WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. See the
+ * License for the specific language governing permissions and limitations under
+ * the License.
+ */
+package android.speech.tts;
+
+import android.os.SystemClock;
+import android.text.TextUtils;
+
+/**
+ * Writes data about a given speech synthesis request to the event logs.
+ * The data that is logged includes the calling app, length of the utterance,
+ * speech rate / pitch and the latency and overall time taken.
+ *
+ * Note that {@link EventLogger#onStopped()} and {@link EventLogger#onError()}
+ * might be called from any thread, but on {@link EventLogger#onPlaybackStart()} and
+ * {@link EventLogger#onComplete()} must be called from a single thread
+ * (usually the audio playback thread}
+ */
+class EventLogger {
+    private final SynthesisRequest mRequest;
+    private final String mCallingApp;
+    private final String mServiceApp;
+    private final long mReceivedTime;
+    private long mPlaybackStartTime = -1;
+    private volatile long mRequestProcessingStartTime = -1;
+    private volatile long mEngineStartTime = -1;
+    private volatile long mEngineCompleteTime = -1;
+
+    private volatile boolean mError = false;
+    private volatile boolean mStopped = false;
+    private boolean mLogWritten = false;
+
+    EventLogger(SynthesisRequest request, String callingApp,
+            String serviceApp) {
+        mRequest = request;
+        mCallingApp = callingApp;
+        mServiceApp = serviceApp;
+        mReceivedTime = SystemClock.elapsedRealtime();
+    }
+
+    /**
+     * Notifies the logger that this request has been selected from
+     * the processing queue for processing. Engine latency / total time
+     * is measured from this baseline.
+     */
+    public void onRequestProcessingStart() {
+        mRequestProcessingStartTime = SystemClock.elapsedRealtime();
+    }
+
+    /**
+     * Notifies the logger that a chunk of data has been received from
+     * the engine. Might be called multiple times.
+     */
+    public void onEngineDataReceived() {
+        if (mEngineStartTime == -1) {
+            mEngineStartTime = SystemClock.elapsedRealtime();
+        }
+    }
+
+    /**
+     * Notifies the logger that the engine has finished processing data.
+     * Will be called exactly once.
+     */
+    public void onEngineComplete() {
+        mEngineCompleteTime = SystemClock.elapsedRealtime();
+    }
+
+    /**
+     * Notifies the logger that audio playback has started for some section
+     * of the synthesis. This is normally some amount of time after the engine
+     * has synthesized data and varides depending on utterances and
+     * other audio currently in the queue.
+     */
+    public void onPlaybackStart() {
+        // For now, keep track of only the first chunk of audio
+        // that was played.
+        if (mPlaybackStartTime == -1) {
+            mPlaybackStartTime = SystemClock.elapsedRealtime();
+        }
+    }
+
+    /**
+     * Notifies the logger that the current synthesis was stopped.
+     * Latency numbers are not reported for stopped syntheses.
+     */
+    public void onStopped() {
+        mStopped = false;
+    }
+
+    /**
+     * Notifies the logger that the current synthesis resulted in
+     * an error. This is logged using {@link EventLogTags#writeTtsSpeakFailure}.
+     */
+    public void onError() {
+        mError = true;
+    }
+
+    /**
+     * Notifies the logger that the current synthesis has completed.
+     * All available data is not logged.
+     */
+    public void onWriteData() {
+        if (mLogWritten) {
+            return;
+        } else {
+            mLogWritten = true;
+        }
+
+        long completionTime = SystemClock.elapsedRealtime();
+        // onPlaybackStart() should normally always be called if an
+        // error does not occur.
+        if (mError || mPlaybackStartTime == -1 || mEngineCompleteTime == -1) {
+            EventLogTags.writeTtsSpeakFailure(mServiceApp, mCallingApp,
+                    getUtteranceLength(), getLocaleString(),
+                    mRequest.getSpeechRate(), mRequest.getPitch());
+            return;
+        }
+
+        // We don't report stopped syntheses because their overall
+        // total time spent will be innacurate (will not correlate with
+        // the length of the utterance).
+        if (mStopped) {
+            return;
+        }
+
+        final long audioLatency = mPlaybackStartTime - mReceivedTime;
+        final long engineLatency = mEngineStartTime - mRequestProcessingStartTime;
+        final long engineTotal = mEngineCompleteTime - mRequestProcessingStartTime;
+        EventLogTags.writeTtsSpeakSuccess(mServiceApp, mCallingApp,
+                getUtteranceLength(), getLocaleString(),
+                mRequest.getSpeechRate(), mRequest.getPitch(),
+                engineLatency, engineTotal, audioLatency);
+    }
+
+    /**
+     * @return the length of the utterance for the given synthesis, 0
+     *          if the utterance was {@code null}.
+     */
+    private int getUtteranceLength() {
+        final String utterance = mRequest.getText();
+        return utterance == null ? 0 : utterance.length();
+    }
+
+    /**
+     * Returns a formatted locale string from the synthesis params of the
+     * form lang-country-variant.
+     */
+    private String getLocaleString() {
+        StringBuilder sb = new StringBuilder(mRequest.getLanguage());
+        if (!TextUtils.isEmpty(mRequest.getCountry())) {
+            sb.append('-');
+            sb.append(mRequest.getCountry());
+
+            if (!TextUtils.isEmpty(mRequest.getVariant())) {
+                sb.append('-');
+                sb.append(mRequest.getVariant());
+            }
+        }
+
+        return sb.toString();
+    }
+
+}
diff --git a/core/java/android/speech/tts/PlaybackSynthesisCallback.java b/core/java/android/speech/tts/PlaybackSynthesisCallback.java
index bdaa1b8..38030a6 100644
--- a/core/java/android/speech/tts/PlaybackSynthesisCallback.java
+++ b/core/java/android/speech/tts/PlaybackSynthesisCallback.java
@@ -65,29 +65,42 @@
 
     private final UtteranceCompletedDispatcher mDispatcher;
     private final String mCallingApp;
+    private final EventLogger mLogger;
 
     PlaybackSynthesisCallback(int streamType, float volume, float pan,
             AudioPlaybackHandler audioTrackHandler, UtteranceCompletedDispatcher dispatcher,
-            String callingApp) {
+            String callingApp, EventLogger logger) {
         mStreamType = streamType;
         mVolume = volume;
         mPan = pan;
         mAudioTrackHandler = audioTrackHandler;
         mDispatcher = dispatcher;
         mCallingApp = callingApp;
+        mLogger = logger;
     }
 
     @Override
     void stop() {
         if (DBG) Log.d(TAG, "stop()");
 
+        // Note that mLogger.mError might be true too at this point.
+        mLogger.onStopped();
+
         synchronized (mStateLock) {
-            if (mToken == null || mStopped) {
-                Log.w(TAG, "stop() called twice, before start(), or after done()");
+            if (mStopped) {
+                Log.w(TAG, "stop() called twice");
                 return;
             }
-            mAudioTrackHandler.stop(mToken);
-            mToken = null;
+            // mToken will be null if the engine encounters
+            // an error before it called start().
+            if (mToken != null) {
+                mAudioTrackHandler.stop(mToken);
+                mToken = null;
+            } else {
+                // In all other cases, mAudioTrackHandler.stop() will
+                // result in onComplete being called.
+                mLogger.onWriteData();
+            }
             mStopped = true;
         }
     }
@@ -124,7 +137,7 @@
             }
             SynthesisMessageParams params = new SynthesisMessageParams(
                     mStreamType, sampleRateInHz, audioFormat, channelCount, mVolume, mPan,
-                    mDispatcher, mCallingApp);
+                    mDispatcher, mCallingApp, mLogger);
             mAudioTrackHandler.enqueueSynthesisStart(params);
 
             mToken = params;
@@ -157,6 +170,8 @@
             mAudioTrackHandler.enqueueSynthesisDataAvailable(mToken);
         }
 
+        mLogger.onEngineDataReceived();
+
         return TextToSpeech.SUCCESS;
     }
 
@@ -177,6 +192,7 @@
             }
 
             mAudioTrackHandler.enqueueSynthesisDone(mToken);
+            mLogger.onEngineComplete();
         }
         return TextToSpeech.SUCCESS;
     }
@@ -184,6 +200,9 @@
     @Override
     public void error() {
         if (DBG) Log.d(TAG, "error() [will call stop]");
+        // Currently, this call will not be logged if error( ) is called
+        // before start.
+        mLogger.onError();
         stop();
     }
 
@@ -208,7 +227,7 @@
             }
             SynthesisMessageParams params = new SynthesisMessageParams(
                     mStreamType, sampleRateInHz, audioFormat, channelCount, mVolume, mPan,
-                    mDispatcher, mCallingApp);
+                    mDispatcher, mCallingApp, mLogger);
             params.addBuffer(buffer, offset, length);
 
             mAudioTrackHandler.enqueueSynthesisCompleteDataAvailable(params);
diff --git a/core/java/android/speech/tts/SynthesisMessageParams.java b/core/java/android/speech/tts/SynthesisMessageParams.java
index 51f3d2e..caf02ef 100644
--- a/core/java/android/speech/tts/SynthesisMessageParams.java
+++ b/core/java/android/speech/tts/SynthesisMessageParams.java
@@ -30,6 +30,7 @@
     final int mChannelCount;
     final float mVolume;
     final float mPan;
+    final EventLogger mLogger;
 
     public volatile AudioTrack mAudioTrack;
 
@@ -38,7 +39,7 @@
     SynthesisMessageParams(int streamType, int sampleRate,
             int audioFormat, int channelCount,
             float volume, float pan, UtteranceCompletedDispatcher dispatcher,
-            String callingApp) {
+            String callingApp, EventLogger logger) {
         super(dispatcher, callingApp);
 
         mStreamType = streamType;
@@ -47,6 +48,7 @@
         mChannelCount = channelCount;
         mVolume = volume;
         mPan = pan;
+        mLogger = logger;
 
         // initially null.
         mAudioTrack = null;
diff --git a/core/java/android/speech/tts/TextToSpeechService.java b/core/java/android/speech/tts/TextToSpeechService.java
index 7ea9373..010c155 100644
--- a/core/java/android/speech/tts/TextToSpeechService.java
+++ b/core/java/android/speech/tts/TextToSpeechService.java
@@ -82,8 +82,7 @@
     private AudioPlaybackHandler mAudioPlaybackHandler;
 
     private CallbackMap mCallbacks;
-
-    private int mDefaultAvailability = TextToSpeech.LANG_NOT_SUPPORTED;
+    private String mPackageName;
 
     @Override
     public void onCreate() {
@@ -99,9 +98,10 @@
 
         mCallbacks = new CallbackMap();
 
+        mPackageName = getApplicationInfo().packageName;
+
         // Load default language
-        mDefaultAvailability = onLoadLanguage(getDefaultLanguage(),
-                getDefaultCountry(), getDefaultVariant());
+        onLoadLanguage(getDefaultLanguage(), getDefaultCountry(), getDefaultVariant());
     }
 
     @Override
@@ -457,12 +457,14 @@
         // Non null after synthesis has started, and all accesses
         // guarded by 'this'.
         private AbstractSynthesisCallback mSynthesisCallback;
+        private final EventLogger mEventLogger;
 
         public SynthesisSpeechItem(String callingApp, Bundle params, String text) {
             super(callingApp, params);
             mText = text;
             mSynthesisRequest = new SynthesisRequest(mText, mParams);
             setRequestParams(mSynthesisRequest);
+            mEventLogger = new EventLogger(mSynthesisRequest, getCallingApp(), mPackageName);
         }
 
         public String getText() {
@@ -485,6 +487,7 @@
         @Override
         protected int playImpl() {
             AbstractSynthesisCallback synthesisCallback;
+            mEventLogger.onRequestProcessingStart();
             synchronized (this) {
                 mSynthesisCallback = createSynthesisCallback();
                 synthesisCallback = mSynthesisCallback;
@@ -495,7 +498,7 @@
 
         protected AbstractSynthesisCallback createSynthesisCallback() {
             return new PlaybackSynthesisCallback(getStreamType(), getVolume(), getPan(),
-                    mAudioPlaybackHandler, this, getCallingApp());
+                    mAudioPlaybackHandler, this, getCallingApp(), mEventLogger);
         }
 
         private void setRequestParams(SynthesisRequest request) {