commit 686f644f981badd481d8781bf80b221544df7b1f
author Shuzhen Wang <shuzhenwang@google.com> Tue Jun 20 16:16:04 2017 -0700
committer Shuzhen Wang <shuzhenwang@google.com> Fri Jun 23 12:05:16 2017 -0700
tree 59d934e011bfa583d9747ca7c994c5e0fe755cc7
parent 4226c955b64e672905b99b71f1b05798ecd30105

Camera: Add debug messages for camera latency

Log latency histogram of:
- processCaptureRequest call,
- dequeueBuffer call, and
- waiting time for handout count fall below max_buffers

Test: Camera CTS
Bug: 62651109
Change-Id: I5ee1cdb4139fa359f0887d6f6871884e28739340

services/camera/libcameraservice/device3/Camera3OutputStream.cpp

diff --git a/services/camera/libcameraservice/device3/Camera3OutputStream.cpp b/services/camera/libcameraservice/device3/Camera3OutputStream.cpp
index ec0f508..e15aa43 100644
--- a/services/camera/libcameraservice/device3/Camera3OutputStream.cpp
+++ b/services/camera/libcameraservice/device3/Camera3OutputStream.cpp
@@ -43,7 +43,8 @@
         mTraceFirstBuffer(true),
         mUseBufferManager(false),
         mTimestampOffset(timestampOffset),
-        mConsumerUsage(0) {
+        mConsumerUsage(0),
+        mDequeueBufferLatency(kDequeueLatencyBinSize) {
 
     if (mConsumer == NULL) {
         ALOGE("%s: Consumer is NULL!", __FUNCTION__);
@@ -68,7 +69,8 @@
         mUseMonoTimestamp(false),
         mUseBufferManager(false),
         mTimestampOffset(timestampOffset),
-        mConsumerUsage(0) {
+        mConsumerUsage(0),
+        mDequeueBufferLatency(kDequeueLatencyBinSize) {
 
     if (format != HAL_PIXEL_FORMAT_BLOB && format != HAL_PIXEL_FORMAT_RAW_OPAQUE) {
         ALOGE("%s: Bad format for size-only stream: %d", __FUNCTION__,
@@ -97,7 +99,8 @@
         mTraceFirstBuffer(true),
         mUseBufferManager(false),
         mTimestampOffset(timestampOffset),
-        mConsumerUsage(consumerUsage) {
+        mConsumerUsage(consumerUsage),
+        mDequeueBufferLatency(kDequeueLatencyBinSize) {
     // Deferred consumer only support preview surface format now.
     if (format != HAL_PIXEL_FORMAT_IMPLEMENTATION_DEFINED) {
         ALOGE("%s: Deferred consumer only supports IMPLEMENTATION_DEFINED format now!",
@@ -134,7 +137,8 @@
         mUseMonoTimestamp(false),
         mUseBufferManager(false),
         mTimestampOffset(timestampOffset),
-        mConsumerUsage(consumerUsage) {
+        mConsumerUsage(consumerUsage),
+        mDequeueBufferLatency(kDequeueLatencyBinSize) {
 
     if (setId > CAMERA3_STREAM_SET_ID_INVALID) {
         mBufferReleasedListener = new BufferReleasedListener(this);
@@ -290,6 +294,9 @@
     write(fd, lines.string(), lines.size());
 
     Camera3IOStreamBase::dump(fd, args);
+
+    mDequeueBufferLatency.dump(fd,
+        "      DequeueBuffer latency histogram:");
 }
 
 status_t Camera3OutputStream::setTransform(int transform) {
@@ -529,7 +536,11 @@
         sp<ANativeWindow> currentConsumer = mConsumer;
         mLock.unlock();
 
+        nsecs_t dequeueStart = systemTime(SYSTEM_TIME_MONOTONIC);
         res = currentConsumer->dequeueBuffer(currentConsumer.get(), anb, fenceFd);
+        nsecs_t dequeueEnd = systemTime(SYSTEM_TIME_MONOTONIC);
+        mDequeueBufferLatency.add(dequeueStart, dequeueEnd);
+
         mLock.lock();
         if (res != OK) {
             ALOGE("%s: Stream %d: Can't dequeue next output buffer: %s (%d)",
@@ -611,6 +622,9 @@
 
     mState = (mState == STATE_IN_RECONFIG) ? STATE_IN_CONFIG
                                            : STATE_CONSTRUCTED;
+
+    mDequeueBufferLatency.log("Stream %d dequeueBuffer latency histogram", mId);
+    mDequeueBufferLatency.reset();
     return OK;
 }