Merge "Camera: Add debug messages for camera latency" into oc-dev
diff --git a/services/camera/libcameraservice/Android.mk b/services/camera/libcameraservice/Android.mk
index ef2f3b3..502ac5d 100644
--- a/services/camera/libcameraservice/Android.mk
+++ b/services/camera/libcameraservice/Android.mk
@@ -54,7 +54,8 @@
     gui/RingBufferConsumer.cpp \
     utils/CameraTraces.cpp \
     utils/AutoConditionLock.cpp \
-    utils/TagMonitor.cpp
+    utils/TagMonitor.cpp \
+    utils/LatencyHistogram.cpp
 
 LOCAL_SHARED_LIBRARIES:= \
     libui \
diff --git a/services/camera/libcameraservice/device3/Camera3Device.cpp b/services/camera/libcameraservice/device3/Camera3Device.cpp
index 4571db8..e8b9b20 100644
--- a/services/camera/libcameraservice/device3/Camera3Device.cpp
+++ b/services/camera/libcameraservice/device3/Camera3Device.cpp
@@ -613,6 +613,11 @@
     }
     write(fd, lines.string(), lines.size());
 
+    if (mRequestThread != NULL) {
+        mRequestThread->dumpCaptureRequestLatency(fd,
+                "    ProcessCaptureRequest latency histogram:");
+    }
+
     {
         lines = String8("    Last request sent:\n");
         write(fd, lines.string(), lines.size());
@@ -3407,7 +3412,8 @@
         mCurrentPreCaptureTriggerId(0),
         mRepeatingLastFrameNumber(
             hardware::camera2::ICameraDeviceUser::NO_IN_FLIGHT_REPEATING_FRAMES),
-        mPrepareVideoStream(false) {
+        mPrepareVideoStream(false),
+        mRequestLatency(kRequestLatencyBinSize) {
     mStatusId = statusTracker->addComponent();
 }
 
@@ -3632,6 +3638,9 @@
     // The exit from any possible waits
     mDoPauseSignal.signal();
     mRequestSignal.signal();
+
+    mRequestLatency.log("ProcessCaptureRequest latency histogram");
+    mRequestLatency.reset();
 }
 
 void Camera3Device::RequestThread::checkAndStopRepeatingRequest() {
@@ -3848,11 +3857,14 @@
             mNextRequests.size());
 
     bool submitRequestSuccess = false;
+    nsecs_t tRequestStart = systemTime(SYSTEM_TIME_MONOTONIC);
     if (mInterface->supportBatchRequest()) {
         submitRequestSuccess = sendRequestsBatch();
     } else {
         submitRequestSuccess = sendRequestsOneByOne();
     }
+    nsecs_t tRequestEnd = systemTime(SYSTEM_TIME_MONOTONIC);
+    mRequestLatency.add(tRequestStart, tRequestEnd);
 
     if (useFlushLock) {
         mFlushLock.unlock();
diff --git a/services/camera/libcameraservice/device3/Camera3Device.h b/services/camera/libcameraservice/device3/Camera3Device.h
index 1ca6811..bfb58c6 100644
--- a/services/camera/libcameraservice/device3/Camera3Device.h
+++ b/services/camera/libcameraservice/device3/Camera3Device.h
@@ -40,6 +40,7 @@
 #include "device3/StatusTracker.h"
 #include "device3/Camera3BufferManager.h"
 #include "utils/TagMonitor.h"
+#include "utils/LatencyHistogram.h"
 #include <camera_metadata_hidden.h>
 
 /**
@@ -699,6 +700,11 @@
          */
         bool isStreamPending(sp<camera3::Camera3StreamInterface>& stream);
 
+        // dump processCaptureRequest latency
+        void dumpCaptureRequestLatency(int fd, const char* name) {
+            mRequestLatency.dump(fd, name);
+        }
+
       protected:
 
         virtual bool threadLoop();
@@ -820,6 +826,9 @@
 
         // Flag indicating if we should prepare video stream for video requests.
         bool               mPrepareVideoStream;
+
+        static const int32_t kRequestLatencyBinSize = 40; // in ms
+        CameraLatencyHistogram mRequestLatency;
     };
     sp<RequestThread> mRequestThread;
 
diff --git a/services/camera/libcameraservice/device3/Camera3IOStreamBase.cpp b/services/camera/libcameraservice/device3/Camera3IOStreamBase.cpp
index cb39244..7ad2300 100644
--- a/services/camera/libcameraservice/device3/Camera3IOStreamBase.cpp
+++ b/services/camera/libcameraservice/device3/Camera3IOStreamBase.cpp
@@ -85,6 +85,8 @@
     lines.appendFormat("      Total buffers: %zu, currently dequeued: %zu\n",
             mTotalBufferCount, mHandoutTotalBufferCount);
     write(fd, lines.string(), lines.size());
+
+    Camera3Stream::dump(fd, args);
 }
 
 status_t Camera3IOStreamBase::configureQueueLocked() {
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;
 }
 
diff --git a/services/camera/libcameraservice/device3/Camera3OutputStream.h b/services/camera/libcameraservice/device3/Camera3OutputStream.h
index 98ffb73..97aa7d4 100644
--- a/services/camera/libcameraservice/device3/Camera3OutputStream.h
+++ b/services/camera/libcameraservice/device3/Camera3OutputStream.h
@@ -21,6 +21,7 @@
 #include <gui/IProducerListener.h>
 #include <gui/Surface.h>
 
+#include "utils/LatencyHistogram.h"
 #include "Camera3Stream.h"
 #include "Camera3IOStreamBase.h"
 #include "Camera3OutputStreamInterface.h"
@@ -269,6 +270,9 @@
     void onBuffersRemovedLocked(const std::vector<sp<GraphicBuffer>>&);
     status_t detachBufferLocked(sp<GraphicBuffer>* buffer, int* fenceFd);
 
+    static const int32_t kDequeueLatencyBinSize = 5; // in ms
+    CameraLatencyHistogram mDequeueBufferLatency;
+
 }; // class Camera3OutputStream
 
 } // namespace camera3
diff --git a/services/camera/libcameraservice/device3/Camera3Stream.cpp b/services/camera/libcameraservice/device3/Camera3Stream.cpp
index b45ef77..ba352c4 100644
--- a/services/camera/libcameraservice/device3/Camera3Stream.cpp
+++ b/services/camera/libcameraservice/device3/Camera3Stream.cpp
@@ -60,7 +60,8 @@
     mOldMaxBuffers(0),
     mPrepared(false),
     mPreparedBufferIdx(0),
-    mLastMaxCount(Camera3StreamInterface::ALLOCATE_PIPELINE_MAX) {
+    mLastMaxCount(Camera3StreamInterface::ALLOCATE_PIPELINE_MAX),
+    mBufferLimitLatency(kBufferLimitLatencyBinSize) {
 
     camera3_stream::stream_type = type;
     camera3_stream::width = width;
@@ -459,8 +460,11 @@
     // Wait for new buffer returned back if we are running into the limit.
     if (getHandoutOutputBufferCountLocked() == camera3_stream::max_buffers) {
         ALOGV("%s: Already dequeued max output buffers (%d), wait for next returned one.",
-                __FUNCTION__, camera3_stream::max_buffers);
+                        __FUNCTION__, camera3_stream::max_buffers);
+        nsecs_t waitStart = systemTime(SYSTEM_TIME_MONOTONIC);
         res = mOutputBufferReturnedSignal.waitRelative(mLock, kWaitForBufferDuration);
+        nsecs_t waitEnd = systemTime(SYSTEM_TIME_MONOTONIC);
+        mBufferLimitLatency.add(waitStart, waitEnd);
         if (res != OK) {
             if (res == TIMED_OUT) {
                 ALOGE("%s: wait for output buffer return timed out after %lldms (max_buffers %d)",
@@ -655,6 +659,9 @@
     ALOGV("%s: Stream %d: Disconnecting...", __FUNCTION__, mId);
     status_t res = disconnectLocked();
 
+    mBufferLimitLatency.log("Stream %d latency histogram for wait on max_buffers", mId);
+    mBufferLimitLatency.reset();
+
     if (res == -ENOTCONN) {
         // "Already disconnected" -- not an error
         return OK;
@@ -663,6 +670,13 @@
     }
 }
 
+void Camera3Stream::dump(int fd, const Vector<String16> &args) const
+{
+    (void)args;
+    mBufferLimitLatency.dump(fd,
+            "      Latency histogram for wait on max_buffers");
+}
+
 status_t Camera3Stream::getBufferLocked(camera3_stream_buffer *,
         const std::vector<size_t>&) {
     ALOGE("%s: This type of stream does not support output", __FUNCTION__);
diff --git a/services/camera/libcameraservice/device3/Camera3Stream.h b/services/camera/libcameraservice/device3/Camera3Stream.h
index 9cdc1b3..b5a9c5d 100644
--- a/services/camera/libcameraservice/device3/Camera3Stream.h
+++ b/services/camera/libcameraservice/device3/Camera3Stream.h
@@ -25,6 +25,7 @@
 
 #include "hardware/camera3.h"
 
+#include "utils/LatencyHistogram.h"
 #include "Camera3StreamBufferListener.h"
 #include "Camera3StreamInterface.h"
 
@@ -349,7 +350,7 @@
     /**
      * Debug dump of the stream's state.
      */
-    virtual void     dump(int fd, const Vector<String16> &args) const = 0;
+    virtual void     dump(int fd, const Vector<String16> &args) const;
 
     /**
      * Add a camera3 buffer listener. Adding the same listener twice has
@@ -502,6 +503,10 @@
     // Outstanding buffers dequeued from the stream's buffer queue.
     List<buffer_handle_t> mOutstandingBuffers;
 
+    // Latency histogram of the wait time for handout buffer count to drop below
+    // max_buffers.
+    static const int32_t kBufferLimitLatencyBinSize = 33; //in ms
+    CameraLatencyHistogram mBufferLimitLatency;
 }; // class Camera3Stream
 
 }; // namespace camera3
diff --git a/services/camera/libcameraservice/utils/LatencyHistogram.cpp b/services/camera/libcameraservice/utils/LatencyHistogram.cpp
new file mode 100644
index 0000000..538bb6e
--- /dev/null
+++ b/services/camera/libcameraservice/utils/LatencyHistogram.cpp
@@ -0,0 +1,106 @@
+/*
+ * Copyright (C) 2017 The Android Open Source Project
+ *
+ * Licensed under the Apache License, Version 2.0 (the "License");
+ * you may not use this file except in compliance with the License.
+ * You may obtain a copy of the License at
+ *
+ *      http://www.apache.org/licenses/LICENSE-2.0
+ *
+ * Unless required by applicable law or agreed to in writing, software
+ * distributed under the License is distributed on an "AS IS" BASIS,
+ * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+ * See the License for the specific language governing permissions and
+ * limitations under the License.
+ */
+
+#define LOG_TAG "CameraLatencyHistogram"
+#include <inttypes.h>
+#include <utils/Log.h>
+#include <utils/String8.h>
+
+#include "LatencyHistogram.h"
+
+namespace android {
+
+CameraLatencyHistogram::CameraLatencyHistogram(int32_t binSizeMs, int32_t binCount) :
+        mBinSizeMs(binSizeMs),
+        mBinCount(binCount),
+        mBins(binCount),
+        mTotalCount(0) {
+}
+
+void CameraLatencyHistogram::add(nsecs_t start, nsecs_t end) {
+    nsecs_t duration = end - start;
+    int32_t durationMs = static_cast<int32_t>(duration / 1000000LL);
+    int32_t binIndex = durationMs / mBinSizeMs;
+
+    if (binIndex < 0) {
+        binIndex = 0;
+    } else if (binIndex >= mBinCount) {
+        binIndex = mBinCount-1;
+    }
+
+    mBins[binIndex]++;
+    mTotalCount++;
+}
+
+void CameraLatencyHistogram::reset() {
+    mBins.clear();
+    mTotalCount = 0;
+}
+
+void CameraLatencyHistogram::dump(int fd, const char* name) const {
+    if (mTotalCount == 0) {
+        return;
+    }
+
+    String8 lines;
+    lines.appendFormat("%s (%" PRId64 ") samples\n", name, mTotalCount);
+
+    String8 lineBins, lineBinCounts;
+    formatHistogramText(lineBins, lineBinCounts);
+
+    lineBins.append("\n");
+    lineBinCounts.append("\n");
+    lines.append(lineBins);
+    lines.append(lineBinCounts);
+
+    write(fd, lines.string(), lines.size());
+}
+
+void CameraLatencyHistogram::log(const char* fmt, ...) {
+    if (mTotalCount == 0) {
+        return;
+    }
+
+    va_list args;
+    va_start(args, fmt);
+    String8 histogramName = String8::formatV(fmt, args);
+    ALOGI("%s (%" PRId64 ") samples:", histogramName.string(), mTotalCount);
+    va_end(args);
+
+    String8 lineBins, lineBinCounts;
+    formatHistogramText(lineBins, lineBinCounts);
+
+    ALOGI("%s", lineBins.c_str());
+    ALOGI("%s", lineBinCounts.c_str());
+}
+
+void CameraLatencyHistogram::formatHistogramText(
+        String8& lineBins, String8& lineBinCounts) const {
+    lineBins = "  ";
+    lineBinCounts = "  ";
+
+    for (int32_t i = 0; i < mBinCount; i++) {
+        if (i == mBinCount - 1) {
+            lineBins.append("    inf (max ms)");
+        } else {
+            lineBins.appendFormat("%7d", mBinSizeMs*(i+1));
+        }
+        lineBinCounts.appendFormat("   %02.2f", 100.0*mBins[i]/mTotalCount);
+    }
+    lineBinCounts.append(" (%)");
+}
+
+}; //namespace android
diff --git a/services/camera/libcameraservice/utils/LatencyHistogram.h b/services/camera/libcameraservice/utils/LatencyHistogram.h
new file mode 100644
index 0000000..bfd9b1b
--- /dev/null
+++ b/services/camera/libcameraservice/utils/LatencyHistogram.h
@@ -0,0 +1,48 @@
+/*
+ * Copyright (C) 2017 The Android Open Source Project
+ *
+ * Licensed under the Apache License, Version 2.0 (the "License");
+ * you may not use this file except in compliance with the License.
+ * You may obtain a copy of the License at
+ *
+ *      http://www.apache.org/licenses/LICENSE-2.0
+ *
+ * Unless required by applicable law or agreed to in writing, software
+ * distributed under the License is distributed on an "AS IS" BASIS,
+ * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+ * See the License for the specific language governing permissions and
+ * limitations under the License.
+ */
+
+#ifndef ANDROID_SERVERS_CAMERA_LATENCY_HISTOGRAM_H_
+#define ANDROID_SERVERS_CAMERA_LATENCY_HISTOGRAM_H_
+
+#include <vector>
+
+#include <utils/Timers.h>
+#include <utils/Mutex.h>
+
+namespace android {
+
+// Histogram for camera latency characteristic
+class CameraLatencyHistogram {
+public:
+    CameraLatencyHistogram() = delete;
+    CameraLatencyHistogram(int32_t binSizeMs, int32_t binCount=10);
+    void add(nsecs_t start, nsecs_t end);
+    void reset();
+
+    void dump(int fd, const char* name) const;
+    void log(const char* format, ...);
+private:
+    int32_t mBinSizeMs;
+    int32_t mBinCount;
+    std::vector<int64_t> mBins;
+    uint64_t mTotalCount;
+
+    void formatHistogramText(String8& lineBins, String8& lineBinCounts) const;
+}; // class CameraLatencyHistogram
+
+}; // namespace android
+
+#endif // ANDROID_SERVERS_CAMERA_LATENCY_HISTOGRAM_H_