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/AAudioService.cpp b/services/oboeservice/AAudioService.cpp
index 855ae69..5b34895 100644
--- a/services/oboeservice/AAudioService.cpp
+++ b/services/oboeservice/AAudioService.cpp
@@ -215,8 +215,7 @@
         return AAUDIO_ERROR_INVALID_HANDLE;
     }
 
-    aaudio_result_t result = serviceStream->start();
-    return result;
+    return serviceStream->start();
 }
 
 aaudio_result_t AAudioService::pauseStream(aaudio_handle_t streamHandle) {
diff --git a/services/oboeservice/AAudioServiceEndpointMMAP.cpp b/services/oboeservice/AAudioServiceEndpointMMAP.cpp
index 58213f8..4be25c8 100644
--- a/services/oboeservice/AAudioServiceEndpointMMAP.cpp
+++ b/services/oboeservice/AAudioServiceEndpointMMAP.cpp
@@ -250,6 +250,8 @@
 
 aaudio_result_t AAudioServiceEndpointMMAP::startStream(sp<AAudioServiceStreamBase> stream,
                                                    audio_port_handle_t *clientHandle) {
+    // Start the client on behalf of the AAudio service.
+    // Use the port handle that was provided by openMmapStream().
     return startClient(mMmapClient, &mPortHandle);
 }
 
@@ -262,11 +264,12 @@
 aaudio_result_t AAudioServiceEndpointMMAP::startClient(const android::AudioClient& client,
                                                        audio_port_handle_t *clientHandle) {
     if (mMmapStream == nullptr) return AAUDIO_ERROR_NULL;
+    ALOGD("AAudioServiceEndpointMMAP::startClient(%p(uid=%d, pid=%d))",
+          &client, client.clientUid, client.clientPid);
     audio_port_handle_t originalHandle =  *clientHandle;
-    aaudio_result_t result = AAudioConvert_androidToAAudioResult(mMmapStream->start(client,
-                                                                                    clientHandle));
-    ALOGD("AAudioServiceEndpointMMAP::startClient(%p(uid=%d, pid=%d), %d => %d) returns %d",
-          &client, client.clientUid, client.clientPid,
+    status_t status = mMmapStream->start(client, clientHandle);
+    aaudio_result_t result = AAudioConvert_androidToAAudioResult(status);
+    ALOGD("AAudioServiceEndpointMMAP::startClient() , %d => %d returns %d",
           originalHandle, *clientHandle, result);
     return result;
 }
diff --git a/services/oboeservice/AAudioServiceEndpointShared.cpp b/services/oboeservice/AAudioServiceEndpointShared.cpp
index 43d73b7..18dc12f 100644
--- a/services/oboeservice/AAudioServiceEndpointShared.cpp
+++ b/services/oboeservice/AAudioServiceEndpointShared.cpp
@@ -122,7 +122,6 @@
         startSharingThread_l();
     }
     if (result == AAUDIO_OK) {
-        ALOGD("AAudioServiceEndpointShared::startStream() use shared stream client.");
         result = getStreamInternal()->startClient(sharedStream->getAudioClient(), clientHandle);
     }
     return result;
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;
diff --git a/services/oboeservice/AAudioServiceStreamBase.h b/services/oboeservice/AAudioServiceStreamBase.h
index 301795d..6f61401 100644
--- a/services/oboeservice/AAudioServiceStreamBase.h
+++ b/services/oboeservice/AAudioServiceStreamBase.h
@@ -191,6 +191,12 @@
         mState = state;
     }
 
+    /**
+     * Device specific startup.
+     * @return AAUDIO_OK or negative error.
+     */
+    virtual aaudio_result_t startDevice();
+
     aaudio_result_t writeUpMessageQueue(AAudioServiceMessage *command);
 
     aaudio_result_t sendCurrentTimestamp();
@@ -213,7 +219,7 @@
     SharedRingBuffer*       mUpMessageQueue;
     std::mutex              mUpMessageQueueLock;
 
-    AAudioThread            mAAudioThread;
+    AAudioThread            mTimestampThread;
     // This is used by one thread to tell another thread to exit. So it must be atomic.
     std::atomic<bool>       mThreadEnabled{false};
 
diff --git a/services/oboeservice/AAudioServiceStreamMMAP.cpp b/services/oboeservice/AAudioServiceStreamMMAP.cpp
index 47041c5..a629ed6 100644
--- a/services/oboeservice/AAudioServiceStreamMMAP.cpp
+++ b/services/oboeservice/AAudioServiceStreamMMAP.cpp
@@ -50,7 +50,7 @@
 }
 
 aaudio_result_t AAudioServiceStreamMMAP::close() {
-    if (mState == AAUDIO_STREAM_STATE_CLOSED) {
+    if (getState() == AAUDIO_STREAM_STATE_CLOSED) {
         return AAUDIO_OK;
     }
 
@@ -67,7 +67,6 @@
     aaudio_result_t result = AAudioServiceStreamBase::open(request,
                                                            AAUDIO_SHARING_MODE_EXCLUSIVE);
     if (result != AAUDIO_OK) {
-        ALOGE("AAudioServiceStreamBase open returned %d", result);
         return result;
     }
 
@@ -85,13 +84,10 @@
 /**
  * Start the flow of data.
  */
-aaudio_result_t AAudioServiceStreamMMAP::start() {
-    if (isRunning()) {
-        return AAUDIO_OK;
-    }
-
-    aaudio_result_t result = AAudioServiceStreamBase::start();
+aaudio_result_t AAudioServiceStreamMMAP::startDevice() {
+    aaudio_result_t result = AAudioServiceStreamBase::startDevice();
     if (!mInService && result == AAUDIO_OK) {
+        // Note that this can sometimes take 200 to 300 msec for a cold start!
         result = startClient(mMmapClient, &mClientHandle);
     }
     return result;
@@ -126,6 +122,7 @@
 
 aaudio_result_t AAudioServiceStreamMMAP::startClient(const android::AudioClient& client,
                                                        audio_port_handle_t *clientHandle) {
+    // Start the client on behalf of the application. Generate a new porthandle.
     aaudio_result_t result = mServiceEndpoint->startClient(client, clientHandle);
     return result;
 }
diff --git a/services/oboeservice/AAudioServiceStreamMMAP.h b/services/oboeservice/AAudioServiceStreamMMAP.h
index bf0aab3..83cd2ef 100644
--- a/services/oboeservice/AAudioServiceStreamMMAP.h
+++ b/services/oboeservice/AAudioServiceStreamMMAP.h
@@ -53,14 +53,6 @@
     aaudio_result_t open(const aaudio::AAudioStreamRequest &request) override;
 
     /**
-     * Start the flow of audio data.
-     *
-     * This is not guaranteed to be synchronous but it currently is.
-     * An AAUDIO_SERVICE_EVENT_STARTED will be sent to the client when complete.
-     */
-    aaudio_result_t start() override;
-
-    /**
      * Stop the flow of data so that start() can resume without loss of data.
      *
      * This is not guaranteed to be synchronous but it currently is.
@@ -89,6 +81,12 @@
 
     aaudio_result_t getHardwareTimestamp(int64_t *positionFrames, int64_t *timeNanos) override;
 
+    /**
+     * Device specific startup.
+     * @return AAUDIO_OK or negative error.
+     */
+    aaudio_result_t startDevice() override;
+
 private:
 
     bool                     mInService = false;
diff --git a/services/oboeservice/AAudioServiceStreamShared.cpp b/services/oboeservice/AAudioServiceStreamShared.cpp
index 834f39f..348d407 100644
--- a/services/oboeservice/AAudioServiceStreamShared.cpp
+++ b/services/oboeservice/AAudioServiceStreamShared.cpp
@@ -237,9 +237,15 @@
 aaudio_result_t AAudioServiceStreamShared::getHardwareTimestamp(int64_t *positionFrames,
                                                                 int64_t *timeNanos) {
 
-    aaudio_result_t result = mServiceEndpoint->getTimestamp(positionFrames, timeNanos);
+    int64_t position = 0;
+    aaudio_result_t result = mServiceEndpoint->getTimestamp(&position, timeNanos);
     if (result == AAUDIO_OK) {
-        *positionFrames -= mTimestampPositionOffset.load(); // Offset from shared MMAP stream
+        int64_t offset = mTimestampPositionOffset.load();
+        // TODO, do not go below starting value
+        position -= offset; // Offset from shared MMAP stream
+        ALOGV("getHardwareTimestamp() %8lld = %8lld - %8lld",
+              (long long) position, (long long) (position + offset), (long long) offset);
     }
+    *positionFrames = position;
     return result;
 }