Camera: reduce logspam from abandonded streams

1. Change Camera3Device logs to ALOGV
2. In Camera3OutputStream, only log before we mark stream state
   to STATE_ABANDONED
3. Also changed BUFFER_ERROR log to ALOGV

Test: manually check log of GCA mode switch
Bug: 125415787
Change-Id: Ibd83b7010932a8be25d85573d9c9dce9c394f6bb

services/camera/libcameraservice/device3/Camera3Device.cpp

@@ -1062,14 +1062,18 @@ hardware::Return<void> Camera3Device::requestStreamBuffers(
             nsecs_t waitDuration = kBaseGetBufferWait + getExpectedInFlightDuration();
             status_t res = outputStream->getBuffer(&sb, waitDuration);
             if (res != OK) {
-                ALOGE("%s: Can't get output buffer for stream %d: %s (%d)",
-                        __FUNCTION__, streamId, strerror(-res), res);
                 if (res == NO_INIT || res == DEAD_OBJECT) {
+                    ALOGV("%s: Can't get output buffer for stream %d: %s (%d)",
+                            __FUNCTION__, streamId, strerror(-res), res);
                     bufRet.val.error(StreamBufferRequestError::STREAM_DISCONNECTED);
-                } else if (res == TIMED_OUT || res == NO_MEMORY) {
-                    bufRet.val.error(StreamBufferRequestError::NO_BUFFER_AVAILABLE);
                 } else {
-                    bufRet.val.error(StreamBufferRequestError::UNKNOWN_ERROR);
+                    ALOGE("%s: Can't get output buffer for stream %d: %s (%d)",
+                            __FUNCTION__, streamId, strerror(-res), res);
+                    if (res == TIMED_OUT || res == NO_MEMORY) {
+                        bufRet.val.error(StreamBufferRequestError::NO_BUFFER_AVAILABLE);
+                    } else {
+                        bufRet.val.error(StreamBufferRequestError::UNKNOWN_ERROR);
+                    }
                 }
                 currentReqSucceeds = false;
                 break;
@@ -3154,9 +3158,10 @@ void Camera3Device::returnOutputBuffers(
 
         // Note: stream may be deallocated at this point, if this buffer was
         // the last reference to it.
-        if (res != OK) {
+        if (res == NO_INIT || res == DEAD_OBJECT) {
-            ALOGE("Can't return buffer to its stream: %s (%d)",
+            ALOGV("Can't return buffer to its stream: %s (%d)", strerror(-res), res);
-                strerror(-res), res);
+        } else if (res != OK) {
+            ALOGE("Can't return buffer to its stream: %s (%d)", strerror(-res), res);
         }
 
         // Long processing consumers can cause returnBuffer timeout for shared stream
@@ -5580,7 +5585,7 @@ status_t Camera3Device::RequestThread::prepareHalRequests() {
 
             if (mUseHalBufManager) {
                 if (outputStream->isAbandoned()) {
-                    ALOGE("%s: stream %d is abandoned.", __FUNCTION__, streamId);
+                    ALOGV("%s: stream %d is abandoned, skipping request", __FUNCTION__, streamId);
                     return TIMED_OUT;
                 }
                 // HAL will request buffer through requestStreamBuffer API
@@ -5598,7 +5603,7 @@ status_t Camera3Device::RequestThread::prepareHalRequests() {
                     // Can't get output buffer from gralloc queue - this could be due to
                     // abandoned queue or other consumer misbehavior, so not a fatal
                     // error
-                    ALOGE("RequestThread: Can't get output buffer, skipping request:"
+                    ALOGV("RequestThread: Can't get output buffer, skipping request:"
                             " %s (%d)", strerror(-res), res);
 
                     return TIMED_OUT;

services/camera/libcameraservice/device3/Camera3OutputStream.cpp

@@ -233,6 +233,7 @@ status_t Camera3OutputStream::returnBufferCheckedLocked(
      * queueBuffer
      */
     sp<ANativeWindow> currentConsumer = mConsumer;
+    StreamState state = mState;
     mLock.unlock();
 
     ANativeWindowBuffer *anwBuffer = container_of(buffer.buffer, ANativeWindowBuffer, handle);
@@ -244,7 +245,7 @@ status_t Camera3OutputStream::returnBufferCheckedLocked(
         if (mDropBuffers) {
             ALOGV("%s: Dropping a frame for stream %d.", __FUNCTION__, mId);
         } else if (buffer.status == CAMERA3_BUFFER_STATUS_ERROR) {
-            ALOGW("%s: A frame is dropped for stream %d due to buffer error.", __FUNCTION__, mId);
+            ALOGV("%s: A frame is dropped for stream %d due to buffer error.", __FUNCTION__, mId);
         } else {
             ALOGE("%s: Stream %d: timestamp shouldn't be 0", __FUNCTION__, mId);
         }
@@ -252,7 +253,7 @@ status_t Camera3OutputStream::returnBufferCheckedLocked(
         res = currentConsumer->cancelBuffer(currentConsumer.get(),
                 anwBuffer,
                 anwReleaseFence);
-        if (res != OK) {
+        if (shouldLogError(res, state)) {
             ALOGE("%s: Stream %d: Error cancelling buffer to native window:"
                   " %s (%d)", __FUNCTION__, mId, strerror(-res), res);
         }
@@ -284,9 +285,9 @@ status_t Camera3OutputStream::returnBufferCheckedLocked(
         }
 
         res = queueBufferToConsumer(currentConsumer, anwBuffer, anwReleaseFence, surface_ids);
-        if (res != OK) {
+        if (shouldLogError(res, state)) {
-            ALOGE("%s: Stream %d: Error queueing buffer to native window: "
+            ALOGE("%s: Stream %d: Error queueing buffer to native window:"
-                  "%s (%d)", __FUNCTION__, mId, strerror(-res), res);
+                  " %s (%d)", __FUNCTION__, mId, strerror(-res), res);
         }
     }
     mLock.lock();
@@ -534,10 +535,11 @@ status_t Camera3OutputStream::getBufferLockedCommon(ANativeWindowBuffer** anb, i
             // successful return.
             *anb = gb.get();
             res = mConsumer->attachBuffer(*anb);
-            if (res != OK) {
+            if (shouldLogError(res, mState)) {
                 ALOGE("%s: Stream %d: Can't attach the output buffer to this surface: %s (%d)",
                         __FUNCTION__, mId, strerror(-res), res);
-
+            }
+            if (res != OK) {
                 checkRetAndSetAbandonedLocked(res);
                 return res;
             }
@@ -592,9 +594,10 @@ status_t Camera3OutputStream::getBufferLockedCommon(ANativeWindowBuffer** anb, i
                 ALOGV("Stream %d: Attached new buffer", getId());
 
                 if (res != OK) {
-                    ALOGE("%s: Stream %d: Can't attach the output buffer to this surface: %s (%d)",
+                    if (shouldLogError(res, mState)) {
-                            __FUNCTION__, mId, strerror(-res), res);
+                        ALOGE("%s: Stream %d: Can't attach the output buffer to this surface:"
-
+                                " %s (%d)", __FUNCTION__, mId, strerror(-res), res);
+                    }
                     checkRetAndSetAbandonedLocked(res);
                     return res;
                 }
@@ -604,9 +607,10 @@ status_t Camera3OutputStream::getBufferLockedCommon(ANativeWindowBuffer** anb, i
                 return res;
             }
         } else if (res != OK) {
-            ALOGE("%s: Stream %d: Can't dequeue next output buffer: %s (%d)",
+            if (shouldLogError(res, mState)) {
-                    __FUNCTION__, mId, strerror(-res), res);
+                ALOGE("%s: Stream %d: Can't dequeue next output buffer: %s (%d)",
-
+                        __FUNCTION__, mId, strerror(-res), res);
+            }
             checkRetAndSetAbandonedLocked(res);
             return res;
         }
@@ -639,6 +643,16 @@ void Camera3OutputStream::checkRetAndSetAbandonedLocked(status_t res) {
     }
 }
 
+bool Camera3OutputStream::shouldLogError(status_t res, StreamState state) {
+    if (res == OK) {
+        return false;
+    }
+    if ((res == DEAD_OBJECT || res == NO_INIT) && state == STATE_ABANDONED) {
+        return false;
+    }
+    return true;
+}
+
 status_t Camera3OutputStream::disconnectLocked() {
     status_t res;
 
@@ -838,7 +852,9 @@ status_t Camera3OutputStream::detachBufferLocked(sp<GraphicBuffer>* buffer, int*
         ALOGW("%s: the released buffer has already been freed by the buffer queue!", __FUNCTION__);
     } else if (res != OK) {
         // Treat other errors as abandonment
-        ALOGE("%s: detach next buffer failed: %s (%d).", __FUNCTION__, strerror(-res), res);
+        if (shouldLogError(res, mState)) {
+            ALOGE("%s: detach next buffer failed: %s (%d).", __FUNCTION__, strerror(-res), res);
+        }
         mState = STATE_ABANDONED;
         return res;
     }

services/camera/libcameraservice/device3/Camera3OutputStream.h

@@ -317,6 +317,10 @@ class Camera3OutputStream :
     // Check return status of IGBP calls and set abandoned state accordingly
     void checkRetAndSetAbandonedLocked(status_t res);
 
+    // If the status indicates abandonded stream, only log when state hasn't been updated to
+    // STATE_ABANDONED
+    static bool shouldLogError(status_t res, StreamState state);
+
     static const int32_t kDequeueLatencyBinSize = 5; // in ms
     CameraLatencyHistogram mDequeueBufferLatency;
 

services/camera/libcameraservice/device3/Camera3Stream.h

@@ -458,7 +458,7 @@ class Camera3Stream :
     // Zero for formats with fixed buffer size for given dimensions.
     const size_t mMaxSize;
 
-    enum {
+    enum StreamState {
         STATE_ERROR,
         STATE_CONSTRUCTED,
         STATE_IN_CONFIG,