aaudio: fix timestamps and underruns

Start the client after we get valid timing data from the server.
That can take a while because of the long cold start times.
The client is synced with the current position of the service.
Now the client can start clean with no underruns.

Bug: 63918065
Test: test_timestamps.cpp
Change-Id: I5d01eb844e4b14cd5477d56ea1dd9e309abc1c52
diff --git a/services/oboeservice/AAudioServiceStreamBase.cpp b/services/oboeservice/AAudioServiceStreamBase.cpp
index 2dc62a0..ca7b528 100644
--- a/services/oboeservice/AAudioServiceStreamBase.cpp
+++ b/services/oboeservice/AAudioServiceStreamBase.cpp
@@ -42,7 +42,7 @@
 
 AAudioServiceStreamBase::AAudioServiceStreamBase(AAudioService &audioService)
         : mUpMessageQueue(nullptr)
-        , mAAudioThread()
+        , mTimestampThread()
         , mAtomicTimestamp()
         , mAudioService(audioService) {
     mMmapClient.clientUid = -1;
@@ -54,10 +54,10 @@
     ALOGD("AAudioServiceStreamBase::~AAudioServiceStreamBase() destroying %p", this);
     // If the stream is deleted when OPEN or in use then audio resources will leak.
     // This would indicate an internal error. So we want to find this ASAP.
-    LOG_ALWAYS_FATAL_IF(!(mState == AAUDIO_STREAM_STATE_CLOSED
-                        || mState == AAUDIO_STREAM_STATE_UNINITIALIZED
-                        || mState == AAUDIO_STREAM_STATE_DISCONNECTED),
-                        "service stream still open, state = %d", mState);
+    LOG_ALWAYS_FATAL_IF(!(getState() == AAUDIO_STREAM_STATE_CLOSED
+                        || getState() == AAUDIO_STREAM_STATE_UNINITIALIZED
+                        || getState() == AAUDIO_STREAM_STATE_DISCONNECTED),
+                        "service stream still open, state = %d", getState());
 }
 
 std::string AAudioServiceStreamBase::dumpHeader() {
@@ -71,7 +71,7 @@
            << std::dec << std::setfill(' ') ;
     result << std::setw(6) << mMmapClient.clientUid;
     result << std::setw(4) << (isRunning() ? "yes" : " no");
-    result << std::setw(6) << mState;
+    result << std::setw(6) << getState();
     result << std::setw(7) << getFormat();
     result << std::setw(6) << mFramesPerBurst;
     result << std::setw(5) << getSamplesPerFrame();
@@ -124,7 +124,7 @@
 
 aaudio_result_t AAudioServiceStreamBase::close() {
     aaudio_result_t result = AAUDIO_OK;
-    if (mState == AAUDIO_STREAM_STATE_CLOSED) {
+    if (getState() == AAUDIO_STREAM_STATE_CLOSED) {
         return AAUDIO_OK;
     }
 
@@ -146,37 +146,50 @@
         mUpMessageQueue = nullptr;
     }
 
-    mState = AAUDIO_STREAM_STATE_CLOSED;
+    setState(AAUDIO_STREAM_STATE_CLOSED);
     return result;
 }
 
+aaudio_result_t AAudioServiceStreamBase::startDevice() {
+    mClientHandle = AUDIO_PORT_HANDLE_NONE;
+    return mServiceEndpoint->startStream(this, &mClientHandle);
+}
+
 /**
  * Start the flow of audio data.
  *
  * An AAUDIO_SERVICE_EVENT_STARTED will be sent to the client when complete.
  */
 aaudio_result_t AAudioServiceStreamBase::start() {
+    aaudio_result_t result = AAUDIO_OK;
     if (isRunning()) {
         return AAUDIO_OK;
     }
 
     if (mServiceEndpoint == nullptr) {
         ALOGE("AAudioServiceStreamBase::start() missing endpoint");
-        return AAUDIO_ERROR_INVALID_STATE;
+        result = AAUDIO_ERROR_INVALID_STATE;
+        goto error;
     }
+
+    // Start with fresh presentation timestamps.
+    mAtomicTimestamp.clear();
+
     mClientHandle = AUDIO_PORT_HANDLE_NONE;
-    aaudio_result_t result = mServiceEndpoint->startStream(this, &mClientHandle);
-    if (result != AAUDIO_OK) {
-        ALOGE("AAudioServiceStreamBase::start() mServiceEndpoint returned %d", result);
-        disconnect();
-    } else {
-        if (result == AAUDIO_OK) {
-            sendServiceEvent(AAUDIO_SERVICE_EVENT_STARTED);
-            mState = AAUDIO_STREAM_STATE_STARTED;
-            mThreadEnabled.store(true);
-            result = mAAudioThread.start(this);
-        }
-    }
+    result = startDevice();
+    if (result != AAUDIO_OK) goto error;
+
+    // This should happen at the end of the start.
+    sendServiceEvent(AAUDIO_SERVICE_EVENT_STARTED);
+    setState(AAUDIO_STREAM_STATE_STARTED);
+    mThreadEnabled.store(true);
+    result = mTimestampThread.start(this);
+    if (result != AAUDIO_OK) goto error;
+
+    return result;
+
+error:
+    disconnect();
     return result;
 }
 
@@ -197,13 +210,13 @@
 
     sendCurrentTimestamp();
     mThreadEnabled.store(false);
-    result = mAAudioThread.stop();
+    result = mTimestampThread.stop();
     if (result != AAUDIO_OK) {
         disconnect();
         return result;
     }
     sendServiceEvent(AAUDIO_SERVICE_EVENT_PAUSED);
-    mState = AAUDIO_STREAM_STATE_PAUSED;
+    setState(AAUDIO_STREAM_STATE_PAUSED);
     return result;
 }
 
@@ -234,7 +247,7 @@
     }
 
     sendServiceEvent(AAUDIO_SERVICE_EVENT_STOPPED);
-    mState = AAUDIO_STREAM_STATE_STOPPED;
+    setState(AAUDIO_STREAM_STATE_STOPPED);
     return result;
 }
 
@@ -242,20 +255,20 @@
     aaudio_result_t result = AAUDIO_OK;
     // clear flag that tells thread to loop
     if (mThreadEnabled.exchange(false)) {
-        result = mAAudioThread.stop();
+        result = mTimestampThread.stop();
     }
     return result;
 }
 
 aaudio_result_t AAudioServiceStreamBase::flush() {
-    if (mState != AAUDIO_STREAM_STATE_PAUSED) {
+    if (getState() != AAUDIO_STREAM_STATE_PAUSED) {
         ALOGE("AAudioServiceStreamBase::flush() stream not paused, state = %s",
               AAudio_convertStreamStateToText(mState));
         return AAUDIO_ERROR_INVALID_STATE;
     }
     // Data will get flushed when the client receives the FLUSHED event.
     sendServiceEvent(AAUDIO_SERVICE_EVENT_FLUSHED);
-    mState = AAUDIO_STREAM_STATE_FLUSHED;
+    setState(AAUDIO_STREAM_STATE_FLUSHED);
     return AAUDIO_OK;
 }
 
@@ -283,9 +296,9 @@
 }
 
 void AAudioServiceStreamBase::disconnect() {
-    if (mState != AAUDIO_STREAM_STATE_DISCONNECTED) {
+    if (getState() != AAUDIO_STREAM_STATE_DISCONNECTED) {
         sendServiceEvent(AAUDIO_SERVICE_EVENT_DISCONNECTED);
-        mState = AAUDIO_STREAM_STATE_DISCONNECTED;
+        setState(AAUDIO_STREAM_STATE_DISCONNECTED);
     }
 }
 
@@ -321,6 +334,9 @@
     aaudio_result_t result = getFreeRunningPosition(&command.timestamp.position,
                                                     &command.timestamp.timestamp);
     if (result == AAUDIO_OK) {
+        ALOGV("sendCurrentTimestamp() SERVICE  %8lld at %lld",
+              (long long) command.timestamp.position,
+              (long long) command.timestamp.timestamp);
         command.what = AAudioServiceMessage::code::TIMESTAMP_SERVICE;
         result = writeUpMessageQueue(&command);
 
@@ -329,13 +345,16 @@
             result = getHardwareTimestamp(&command.timestamp.position,
                                           &command.timestamp.timestamp);
             if (result == AAUDIO_OK) {
+                ALOGV("sendCurrentTimestamp() HARDWARE %8lld at %lld",
+                      (long long) command.timestamp.position,
+                      (long long) command.timestamp.timestamp);
                 command.what = AAudioServiceMessage::code::TIMESTAMP_HARDWARE;
                 result = writeUpMessageQueue(&command);
             }
         }
     }
 
-    if (result == AAUDIO_ERROR_UNAVAILABLE) {
+    if (result == AAUDIO_ERROR_UNAVAILABLE) { // TODO review best error code
         result = AAUDIO_OK; // just not available yet, try again later
     }
     return result;