EmulatedCamera2: Improve thread sequencing

- When the readout thread is the slow point, frames could be dropped
  in various ways. Add signals to slow down the configure thread and
  the sensor when the readout thread is behind.

- Clean up verbose logs to be clearer

Bug: 6243944

Change-Id: I2efb909f03183273a71dc7edede3aa107117f558
diff --git a/tools/emulator/system/camera/EmulatedFakeCamera2.cpp b/tools/emulator/system/camera/EmulatedFakeCamera2.cpp
index d630db4..56dac9e 100644
--- a/tools/emulator/system/camera/EmulatedFakeCamera2.cpp
+++ b/tools/emulator/system/camera/EmulatedFakeCamera2.cpp
@@ -31,11 +31,11 @@
 
 namespace android {
 
-const uint32_t EmulatedFakeCamera2::kAvailableFormats[5] = {
+const uint32_t EmulatedFakeCamera2::kAvailableFormats[4] = {
         HAL_PIXEL_FORMAT_RAW_SENSOR,
         HAL_PIXEL_FORMAT_BLOB,
         HAL_PIXEL_FORMAT_RGBA_8888,
-        HAL_PIXEL_FORMAT_YV12,
+        //        HAL_PIXEL_FORMAT_YV12,
         HAL_PIXEL_FORMAT_YCrCb_420_SP
 };
 
@@ -355,7 +355,7 @@
     *stream_id = mNextStreamId;
     if (format_actual) *format_actual = format;
     *usage = GRALLOC_USAGE_HW_CAMERA_WRITE;
-    *max_buffers = 4;
+    *max_buffers = kMaxBufferCount;
 
     ALOGV("Stream allocated: %d, %d x %d, 0x%x. U: %x, B: %d",
             *stream_id, width, height, format, *usage, *max_buffers);
@@ -630,7 +630,7 @@
     if (mRequest == NULL) {
         Mutex::Autolock il(mInternalsMutex);
 
-        ALOGV("Getting next request");
+        ALOGV("Configure: Getting next request");
         res = mParent->mRequestQueueSrc->dequeue_request(
             mParent->mRequestQueueSrc,
             &mRequest);
@@ -640,7 +640,7 @@
             return false;
         }
         if (mRequest == NULL) {
-            ALOGV("Request queue empty, going inactive");
+            ALOGV("Configure: Request queue empty, going inactive");
             // No requests available, go into inactive mode
             Mutex::Autolock lock(mInputMutex);
             mActive = false;
@@ -665,7 +665,7 @@
 
         mNextBuffers = new Buffers;
         mNextNeedsJpeg = false;
-        ALOGV("Setting up buffers for capture");
+        ALOGV("Configure: Setting up buffers for capture");
         for (size_t i = 0; i < streams.count; i++) {
             int streamId = streams.data.u8[i];
             const Stream &s = mParent->getStreamInfo(streamId);
@@ -682,7 +682,8 @@
             b.format = s.format;
             b.stride = s.stride;
             mNextBuffers->push_back(b);
-            ALOGV("  Buffer %d: Stream %d, %d x %d, format 0x%x, stride %d",
+            ALOGV("Configure:    Buffer %d: Stream %d, %d x %d, format 0x%x, "
+                    "stride %d",
                     i, b.streamId, b.width, b.height, b.format, b.stride);
             if (b.format == HAL_PIXEL_FORMAT_BLOB) {
                 mNextNeedsJpeg = true;
@@ -744,12 +745,22 @@
             mParent->mSensor->getScene().setHour(*e.data.i32);
         }
 
-        // Start waiting on sensor or JPEG block
+        // Start waiting on readout thread
+        mWaitingForReadout = true;
+        ALOGV("Configure: Waiting for readout thread");
+    }
+
+    if (mWaitingForReadout) {
+        bool readoutDone;
+        readoutDone = mParent->mReadoutThread->waitForReady(kWaitPerLoop);
+        if (!readoutDone) return true;
+
         if (mNextNeedsJpeg) {
-            ALOGV("Waiting for JPEG compressor");
+            ALOGV("Configure: Waiting for JPEG compressor");
         } else {
-            ALOGV("Waiting for sensor");
+            ALOGV("Configure: Waiting for sensor");
         }
+        mWaitingForReadout = false;
     }
 
     if (mNextNeedsJpeg) {
@@ -757,7 +768,7 @@
         jpegDone = mParent->mJpegCompressor->waitForDone(kWaitPerLoop);
         if (!jpegDone) return true;
 
-        ALOGV("Waiting for sensor");
+        ALOGV("Configure: Waiting for sensor");
         mNextNeedsJpeg = false;
     }
     bool vsync = mParent->mSensor->waitForVSync(kWaitPerLoop);
@@ -765,7 +776,7 @@
     if (!vsync) return true;
 
     Mutex::Autolock il(mInternalsMutex);
-    ALOGV("Configuring sensor for frame %d", mNextFrameNumber);
+    ALOGV("Configure: Configuring sensor for frame %d", mNextFrameNumber);
     mParent->mSensor->setExposureTime(mNextExposureTime);
     mParent->mSensor->setFrameDuration(mNextFrameDuration);
     mParent->mSensor->setSensitivity(mNextSensitivity);
@@ -775,7 +786,7 @@
         StreamBuffer &b = mNextBuffers->editItemAt(i);
 
         Stream s = mParent->getStreamInfo(b.streamId);
-
+        ALOGV("Configure: Dequeing buffer from stream %d", b.streamId);
         res = s.ops->dequeue_buffer(s.ops, &(b.buffer) );
         if (res != NO_ERROR || b.buffer == NULL) {
             ALOGE("%s: Unable to dequeue buffer from stream %d: %s (%d)",
@@ -801,7 +812,7 @@
             return false;
         }
     }
-
+    ALOGV("Configure: Done configure for frame %d", mNextFrameNumber);
     mParent->mReadoutThread->setNextCapture(mRequest, mNextBuffers);
     mParent->mSensor->setDestinationBuffers(mNextBuffers);
 
@@ -848,11 +859,30 @@
     return OK;
 }
 
+bool EmulatedFakeCamera2::ReadoutThread::waitForReady(nsecs_t timeout) {
+    status_t res;
+    Mutex::Autolock lock(mInputMutex);
+    while (!readyForNextCapture()) {
+        res = mReadySignal.waitRelative(mInputMutex, timeout);
+        if (res == TIMED_OUT) return false;
+        if (res != OK) {
+            ALOGE("%s: Error waiting for ready: %s (%d)", __FUNCTION__,
+                    strerror(-res), res);
+            return false;
+        }
+    }
+    return true;
+}
+
+bool EmulatedFakeCamera2::ReadoutThread::readyForNextCapture() {
+    return (mInFlightTail + 1) % kInFlightQueueSize != mInFlightHead;
+}
+
 void EmulatedFakeCamera2::ReadoutThread::setNextCapture(
         camera_metadata_t *request,
         Buffers *buffers) {
     Mutex::Autolock lock(mInputMutex);
-    if ( (mInFlightTail + 1) % kInFlightQueueSize == mInFlightHead) {
+    if ( !readyForNextCapture() ) {
         ALOGE("In flight queue full, dropping captures");
         mParent->signalError();
         return;
@@ -900,6 +930,7 @@
 bool EmulatedFakeCamera2::ReadoutThread::threadLoop() {
     static const nsecs_t kWaitPerLoop = 10000000L; // 10 ms
     status_t res;
+    int32_t frameNumber;
 
     // Check if we're currently processing or just waiting
     {
@@ -924,6 +955,7 @@
                 return true;
             } else {
                 Mutex::Autolock iLock(mInternalsMutex);
+                mReadySignal.signal();
                 mRequest = mInFlightQueue[mInFlightHead].request;
                 mBuffers  = mInFlightQueue[mInFlightHead].buffers;
                 mInFlightQueue[mInFlightHead].request = NULL;
@@ -945,17 +977,36 @@
 
     if (!gotFrame) return true;
 
-    // Got sensor data, construct frame and send it out
-    ALOGV("Readout: Constructing metadata and frames");
     Mutex::Autolock iLock(mInternalsMutex);
 
-    camera_metadata_entry_t metadataMode;
+    camera_metadata_entry_t entry;
+    res = find_camera_metadata_entry(mRequest,
+            ANDROID_REQUEST_FRAME_COUNT,
+            &entry);
+    if (res != NO_ERROR) {
+        ALOGE("%s: error reading frame count tag: %s (%d)",
+                __FUNCTION__, strerror(-res), res);
+        mParent->signalError();
+        return false;
+    }
+    frameNumber = *entry.data.i32;
+
     res = find_camera_metadata_entry(mRequest,
             ANDROID_REQUEST_METADATA_MODE,
-            &metadataMode);
+            &entry);
+    if (res != NO_ERROR) {
+        ALOGE("%s: error reading metadata mode tag: %s (%d)",
+                __FUNCTION__, strerror(-res), res);
+        mParent->signalError();
+        return false;
+    }
 
-    if (*metadataMode.data.u8 == ANDROID_REQUEST_METADATA_FULL) {
-        ALOGV("Metadata requested, constructing");
+    // Got sensor data and request, construct frame and send it out
+    ALOGV("Readout: Constructing metadata and frames for request %d",
+            frameNumber);
+
+    if (*entry.data.u8 == ANDROID_REQUEST_METADATA_FULL) {
+        ALOGV("Readout: Metadata requested, constructing");
 
         camera_metadata_t *frame = NULL;
 
@@ -991,7 +1042,6 @@
                 EMULATOR_SCENE_HOUROFDAY,
                 &requestedHour);
         if (res == NAME_NOT_FOUND) {
-            ALOGV("Adding vendor tag");
             res = add_camera_metadata_entry(frame,
                     EMULATOR_SCENE_HOUROFDAY,
                     &hourOfDay, 1);
@@ -999,19 +1049,18 @@
                 ALOGE("Unable to add vendor tag");
             }
         } else if (res == OK) {
-            ALOGV("Replacing value in vendor tag");
             *requestedHour.data.i32 = hourOfDay;
         } else {
-            ALOGE("Error looking up vendor tag");
+            ALOGE("%s: Error looking up vendor tag", __FUNCTION__);
         }
 
         collectStatisticsMetadata(frame);
         // TODO: Collect all final values used from sensor in addition to timestamp
-
+        ALOGV("Readout: Enqueue frame %d", frameNumber);
         mParent->mFrameQueueDst->enqueue_frame(mParent->mFrameQueueDst,
                 frame);
     }
-
+    ALOGV("Readout: Free request");
     res = mParent->mRequestQueueSrc->free_request(mParent->mRequestQueueSrc, mRequest);
     if (res != NO_ERROR) {
         ALOGE("%s: Unable to return request buffer to queue: %d",
@@ -1022,17 +1071,17 @@
     mRequest = NULL;
 
     int compressedBufferIndex = -1;
-    ALOGV("Processing %d buffers", mBuffers->size());
+    ALOGV("Readout: Processing %d buffers", mBuffers->size());
     for (size_t i = 0; i < mBuffers->size(); i++) {
         const StreamBuffer &b = (*mBuffers)[i];
-        ALOGV("  Buffer %d: Stream %d, %d x %d, format 0x%x, stride %d",
+        ALOGV("Readout:    Buffer %d: Stream %d, %d x %d, format 0x%x, stride %d",
                 i, b.streamId, b.width, b.height, b.format, b.stride);
         if (b.streamId >= 0) {
             if (b.format == HAL_PIXEL_FORMAT_BLOB) {
                 // Assumes only one BLOB buffer type per capture
                 compressedBufferIndex = i;
             } else {
-                ALOGV("Sending image buffer %d to output stream %d",
+                ALOGV("Readout:    Sending image buffer %d to output stream %d",
                         i, b.streamId);
                 GraphicBufferMapper::get().unlock(*(b.buffer));
                 const Stream &s = mParent->getStreamInfo(b.streamId);
@@ -1050,7 +1099,7 @@
         delete mBuffers;
         mBuffers = NULL;
     } else {
-        ALOGV("Starting JPEG compression for buffer %d, stream %d",
+        ALOGV("Readout:  Starting JPEG compression for buffer %d, stream %d",
                 compressedBufferIndex,
                 (*mBuffers)[compressedBufferIndex].streamId);
         mParent->mJpegCompressor->start(mBuffers, captureTime);
@@ -1059,14 +1108,14 @@
 
     Mutex::Autolock l(mInputMutex);
     mRequestCount--;
-
+    ALOGV("Readout: Done with request %d", frameNumber);
     return true;
 }
 
 status_t EmulatedFakeCamera2::ReadoutThread::collectStatisticsMetadata(
         camera_metadata_t *frame) {
     // Completely fake face rectangles, don't correspond to real faces in scene
-    ALOGV("Collecting statistics metadata");
+    ALOGV("Readout:    Collecting statistics metadata");
 
     status_t res;
     camera_metadata_entry_t entry;
diff --git a/tools/emulator/system/camera/EmulatedFakeCamera2.h b/tools/emulator/system/camera/EmulatedFakeCamera2.h
index e9e0dfc..11016e8 100644
--- a/tools/emulator/system/camera/EmulatedFakeCamera2.h
+++ b/tools/emulator/system/camera/EmulatedFakeCamera2.h
@@ -193,6 +193,7 @@
         camera_metadata_t *mRequest;
 
         Mutex mInternalsMutex; // Lock before accessing below members.
+        bool    mWaitingForReadout;
         bool    mNextNeedsJpeg;
         int32_t mNextFrameNumber;
         int64_t mNextExposureTime;
@@ -210,6 +211,7 @@
 
         // Input
         status_t waitUntilRunning();
+        bool waitForReady(nsecs_t timeout);
         void setNextCapture(camera_metadata_t *request,
                 Buffers *buffers);
 
@@ -221,11 +223,14 @@
         bool mRunning;
         bool threadLoop();
 
+        bool readyForNextCapture();
         status_t collectStatisticsMetadata(camera_metadata_t *frame);
 
         // Inputs
         Mutex mInputMutex; // Protects mActive, mInFlightQueue, mRequestCount
         Condition mInputSignal;
+        Condition mReadySignal;
+
         bool mActive;
 
         static const int kInFlightQueueSize = 4;
@@ -327,6 +332,7 @@
     static const uint32_t kMaxRawStreamCount = 1;
     static const uint32_t kMaxProcessedStreamCount = 3;
     static const uint32_t kMaxJpegStreamCount = 1;
+    static const uint32_t kMaxBufferCount = 4;
     static const uint32_t kAvailableFormats[];
     static const uint32_t kAvailableRawSizes[];
     static const uint64_t kAvailableRawMinDurations[];
diff --git a/tools/emulator/system/camera/fake-pipeline2/Sensor.cpp b/tools/emulator/system/camera/fake-pipeline2/Sensor.cpp
index 5eff98d..d00b6ee 100644
--- a/tools/emulator/system/camera/fake-pipeline2/Sensor.cpp
+++ b/tools/emulator/system/camera/fake-pipeline2/Sensor.cpp
@@ -188,14 +188,17 @@
     uint8_t *ret;
     if (mCapturedBuffers == NULL) {
         int res;
-        res = mReadoutComplete.waitRelative(mReadoutMutex, reltime);
+        res = mReadoutAvailable.waitRelative(mReadoutMutex, reltime);
         if (res == TIMED_OUT) {
             return false;
         } else if (res != OK || mCapturedBuffers == NULL) {
             ALOGE("Error waiting for sensor readout signal: %d", res);
             return false;
         }
+    } else {
+        mReadoutComplete.signal();
     }
+
     *captureTime = mCaptureTime;
     mCapturedBuffers = NULL;
     return true;
@@ -267,9 +270,14 @@
     if (capturedBuffers != NULL) {
         ALOGVV("Sensor readout complete");
         Mutex::Autolock lock(mReadoutMutex);
+        if (mCapturedBuffers != NULL) {
+            ALOGV("Waiting for readout thread to catch up!");
+            mReadoutComplete.wait(mReadoutMutex);
+        }
+
         mCapturedBuffers = capturedBuffers;
         mCaptureTime = captureTime;
-        mReadoutComplete.signal();
+        mReadoutAvailable.signal();
         capturedBuffers = NULL;
     }
 
diff --git a/tools/emulator/system/camera/fake-pipeline2/Sensor.h b/tools/emulator/system/camera/fake-pipeline2/Sensor.h
index 2919be4..ce7b4ad 100644
--- a/tools/emulator/system/camera/fake-pipeline2/Sensor.h
+++ b/tools/emulator/system/camera/fake-pipeline2/Sensor.h
@@ -187,6 +187,7 @@
 
     Mutex mReadoutMutex; // Lock before accessing readout variables
     // Start of readout variables
+    Condition mReadoutAvailable;
     Condition mReadoutComplete;
     Buffers  *mCapturedBuffers;
     nsecs_t   mCaptureTime;