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) {