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
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_