diff --git a/Android.mk b/Android.mk index 9fbdde72bffae..335fb732b214d 100644 --- a/Android.mk +++ b/Android.mk @@ -36,6 +36,7 @@ LOCAL_SRC_FILES := $(call find-other-java-files,$(FRAMEWORKS_BASE_SUBDIRS)) # 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 c7603ee2b5f56..8ef4295de33a4 100644 --- a/core/java/android/speech/tts/AudioPlaybackHandler.java +++ b/core/java/android/speech/tts/AudioPlaybackHandler.java @@ -384,11 +384,16 @@ class AudioPlaybackHandler { } 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 @@ class AudioPlaybackHandler { 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 0000000000000..1a9f5fe874e33 --- /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 0000000000000..63b954b0b7117 --- /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 bdaa1b825350d..38030a6d98619 100644 --- a/core/java/android/speech/tts/PlaybackSynthesisCallback.java +++ b/core/java/android/speech/tts/PlaybackSynthesisCallback.java @@ -65,29 +65,42 @@ class PlaybackSynthesisCallback extends AbstractSynthesisCallback { 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 @@ class PlaybackSynthesisCallback extends AbstractSynthesisCallback { } SynthesisMessageParams params = new SynthesisMessageParams( mStreamType, sampleRateInHz, audioFormat, channelCount, mVolume, mPan, - mDispatcher, mCallingApp); + mDispatcher, mCallingApp, mLogger); mAudioTrackHandler.enqueueSynthesisStart(params); mToken = params; @@ -157,6 +170,8 @@ class PlaybackSynthesisCallback extends AbstractSynthesisCallback { mAudioTrackHandler.enqueueSynthesisDataAvailable(mToken); } + mLogger.onEngineDataReceived(); + return TextToSpeech.SUCCESS; } @@ -177,6 +192,7 @@ class PlaybackSynthesisCallback extends AbstractSynthesisCallback { } mAudioTrackHandler.enqueueSynthesisDone(mToken); + mLogger.onEngineComplete(); } return TextToSpeech.SUCCESS; } @@ -184,6 +200,9 @@ class PlaybackSynthesisCallback extends AbstractSynthesisCallback { @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 @@ class PlaybackSynthesisCallback extends AbstractSynthesisCallback { } 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 51f3d2e83a5ba..caf02ef3eb56a 100644 --- a/core/java/android/speech/tts/SynthesisMessageParams.java +++ b/core/java/android/speech/tts/SynthesisMessageParams.java @@ -30,6 +30,7 @@ final class SynthesisMessageParams extends MessageParams { final int mChannelCount; final float mVolume; final float mPan; + final EventLogger mLogger; public volatile AudioTrack mAudioTrack; @@ -38,7 +39,7 @@ final class SynthesisMessageParams extends MessageParams { 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 @@ final class SynthesisMessageParams extends MessageParams { 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 7ea93738ea2b9..010c155f56dc0 100644 --- a/core/java/android/speech/tts/TextToSpeechService.java +++ b/core/java/android/speech/tts/TextToSpeechService.java @@ -82,8 +82,7 @@ public abstract class TextToSpeechService extends Service { private AudioPlaybackHandler mAudioPlaybackHandler; private CallbackMap mCallbacks; - - private int mDefaultAvailability = TextToSpeech.LANG_NOT_SUPPORTED; + private String mPackageName; @Override public void onCreate() { @@ -99,9 +98,10 @@ public abstract class TextToSpeechService extends Service { mCallbacks = new CallbackMap(); + mPackageName = getApplicationInfo().packageName; + // Load default language - mDefaultAvailability = onLoadLanguage(getDefaultLanguage(), - getDefaultCountry(), getDefaultVariant()); + onLoadLanguage(getDefaultLanguage(), getDefaultCountry(), getDefaultVariant()); } @Override @@ -457,12 +457,14 @@ public abstract class TextToSpeechService extends Service { // 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 @@ public abstract class TextToSpeechService extends Service { @Override protected int playImpl() { AbstractSynthesisCallback synthesisCallback; + mEventLogger.onRequestProcessingStart(); synchronized (this) { mSynthesisCallback = createSynthesisCallback(); synthesisCallback = mSynthesisCallback; @@ -495,7 +498,7 @@ public abstract class TextToSpeechService extends Service { protected AbstractSynthesisCallback createSynthesisCallback() { return new PlaybackSynthesisCallback(getStreamType(), getVolume(), getPan(), - mAudioPlaybackHandler, this, getCallingApp()); + mAudioPlaybackHandler, this, getCallingApp(), mEventLogger); } private void setRequestParams(SynthesisRequest request) {