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