Camera: implement external camera dumpState/close

Also switch to v4l2 timestamp is it's MONOTONIC

Test: Cts CameraDeviceTest
Bug: 72261676
Change-Id: Iec82c254dcf16a56952ff8910d13c92782d48090
diff --git a/camera/device/3.4/default/ExternalCameraDevice.cpp b/camera/device/3.4/default/ExternalCameraDevice.cpp
index b6470f5..14f82bc 100644
--- a/camera/device/3.4/default/ExternalCameraDevice.cpp
+++ b/camera/device/3.4/default/ExternalCameraDevice.cpp
@@ -131,7 +131,7 @@
 
     session = new ExternalCameraDeviceSession(
             callback, mCfg, mSupportedFormats, mCroppingType,
-            mCameraCharacteristics, std::move(fd));
+            mCameraCharacteristics, mCameraId, std::move(fd));
     if (session == nullptr) {
         ALOGE("%s: camera device session allocation failed", __FUNCTION__);
         mLock.unlock();
diff --git a/camera/device/3.4/default/ExternalCameraDeviceSession.cpp b/camera/device/3.4/default/ExternalCameraDeviceSession.cpp
index b6b4626..cffc40e 100644
--- a/camera/device/3.4/default/ExternalCameraDeviceSession.cpp
+++ b/camera/device/3.4/default/ExternalCameraDeviceSession.cpp
@@ -46,6 +46,21 @@
                                        // bad frames. TODO: develop a better bad frame detection
                                        // method
 
+bool tryLock(Mutex& mutex)
+{
+    static const int kDumpLockRetries = 50;
+    static const int kDumpLockSleep = 60000;
+    bool locked = false;
+    for (int i = 0; i < kDumpLockRetries; ++i) {
+        if (mutex.tryLock() == NO_ERROR) {
+            locked = true;
+            break;
+        }
+        usleep(kDumpLockSleep);
+    }
+    return locked;
+}
+
 } // Anonymous namespace
 
 // Static instances
@@ -59,12 +74,14 @@
         const std::vector<SupportedV4L2Format>& sortedFormats,
         const CroppingType& croppingType,
         const common::V1_0::helper::CameraMetadata& chars,
+        const std::string& cameraId,
         unique_fd v4l2Fd) :
         mCallback(callback),
         mCfg(cfg),
         mCameraCharacteristics(chars),
         mSupportedFormats(sortedFormats),
         mCroppingType(croppingType),
+        mCameraId(cameraId),
         mV4l2Fd(std::move(v4l2Fd)),
         mOutputThread(new OutputThread(this, mCroppingType)),
         mMaxThumbResolution(getMaxThumbResolution()),
@@ -119,8 +136,79 @@
     }
 }
 
-void ExternalCameraDeviceSession::dumpState(const native_handle_t*) {
-    // TODO: b/72261676 dump more runtime information
+
+void ExternalCameraDeviceSession::dumpState(const native_handle_t* handle) {
+    if (handle->numFds != 1 || handle->numInts != 0) {
+        ALOGE("%s: handle must contain 1 FD and 0 integers! Got %d FDs and %d ints",
+                __FUNCTION__, handle->numFds, handle->numInts);
+        return;
+    }
+    int fd = handle->data[0];
+
+    bool intfLocked = tryLock(mInterfaceLock);
+    if (!intfLocked) {
+        dprintf(fd, "!! ExternalCameraDeviceSession interface may be deadlocked !!\n");
+    }
+
+    if (isClosed()) {
+        dprintf(fd, "External camera %s is closed\n", mCameraId.c_str());
+        return;
+    }
+
+    bool streaming = false;
+    size_t v4L2BufferCount = 0;
+    SupportedV4L2Format streamingFmt;
+    std::unordered_set<uint32_t>  inflightFrames;
+    {
+        Mutex::Autolock _l(mLock);
+        bool sessionLocked = tryLock(mLock);
+        if (!sessionLocked) {
+            dprintf(fd, "!! ExternalCameraDeviceSession mLock may be deadlocked !!\n");
+        }
+        streaming = mV4l2Streaming;
+        streamingFmt = mV4l2StreamingFmt;
+        v4L2BufferCount = mV4L2BufferCount;
+        inflightFrames = mInflightFrames;
+        if (sessionLocked) {
+            mLock.unlock();
+        }
+    }
+
+    dprintf(fd, "External camera %s V4L2 FD %d, cropping type %s, %s\n",
+            mCameraId.c_str(), mV4l2Fd.get(),
+            (mCroppingType == VERTICAL) ? "vertical" : "horizontal",
+            streaming ? "streaming" : "not streaming");
+    if (streaming) {
+        // TODO: dump fps later
+        dprintf(fd, "Current V4L2 format %c%c%c%c %dx%d\n",
+                streamingFmt.fourcc & 0xFF,
+                (streamingFmt.fourcc >> 8) & 0xFF,
+                (streamingFmt.fourcc >> 16) & 0xFF,
+                (streamingFmt.fourcc >> 24) & 0xFF,
+                streamingFmt.width, streamingFmt.height);
+
+        size_t numDequeuedV4l2Buffers = 0;
+        {
+            std::lock_guard<std::mutex> lk(mV4l2BufferLock);
+            numDequeuedV4l2Buffers = mNumDequeuedV4l2Buffers;
+        }
+        dprintf(fd, "V4L2 buffer queue size %zu, dequeued %zu\n",
+                v4L2BufferCount, numDequeuedV4l2Buffers);
+    }
+
+    dprintf(fd, "In-flight frames (not sorted):");
+    for (const auto& frameNumber : inflightFrames) {
+        dprintf(fd, "%d, ", frameNumber);
+    }
+    dprintf(fd, "\n");
+    mOutputThread->dump(fd);
+    dprintf(fd, "\n");
+
+    if (intfLocked) {
+        mInterfaceLock.unlock();
+    }
+
+    return;
 }
 
 Return<void> ExternalCameraDeviceSession::constructDefaultRequestSettings(
@@ -292,21 +380,20 @@
 
 Return<void> ExternalCameraDeviceSession::close() {
     Mutex::Autolock _il(mInterfaceLock);
-    Mutex::Autolock _l(mLock);
-    if (!mClosed) {
-        // TODO: b/72261676 Cleanup inflight buffers/V4L2 buffer queue
+    bool closed = isClosed();
+    if (!closed) {
+        mOutputThread->flush();
+        mOutputThread->requestExit();
+        mOutputThread->join();
+
+        Mutex::Autolock _l(mLock);
+        // free all buffers
+        for(auto pair : mStreamMap) {
+            cleanupBuffersLocked(/*Stream ID*/pair.first);
+        }
+        v4l2StreamOffLocked();
         ALOGV("%s: closing V4L2 camera FD %d", __FUNCTION__, mV4l2Fd.get());
         mV4l2Fd.reset();
-        mOutputThread->requestExit(); // TODO: join?
-
-        // free all imported buffers
-        for(auto& pair : mCirculatingBuffers) {
-            CirculatingBuffers& buffers = pair.second;
-            for (auto& p2 : buffers) {
-                sHandleImporter.freeBuffer(p2.second);
-            }
-        }
-
         mClosed = true;
     }
     return Void();
@@ -442,15 +529,13 @@
     // TODO: program fps range per capture request here
     //       or limit the set of availableFpsRange
 
-    sp<V4L2Frame> frameIn = dequeueV4l2FrameLocked();
+
+    nsecs_t shutterTs = 0;
+    sp<V4L2Frame> frameIn = dequeueV4l2FrameLocked(&shutterTs);
     if ( frameIn == nullptr) {
         ALOGE("%s: V4L2 deque frame failed!", __FUNCTION__);
         return Status::INTERNAL_ERROR;
     }
-    // TODO: This can probably be replaced by use v4lbuffer timestamp
-    //       if the device supports it
-    nsecs_t shutterTs = systemTime(SYSTEM_TIME_MONOTONIC);
-
 
     // TODO: reduce object copy in this path
     HalRequest halReq = {
@@ -1726,7 +1811,7 @@
     std::list<HalRequest> reqs = mRequestList;
     mRequestList.clear();
     if (mProcessingRequest) {
-        std::chrono::seconds timeout = std::chrono::seconds(kReqWaitTimeoutSec);
+        std::chrono::seconds timeout = std::chrono::seconds(kFlushWaitTimeoutSec);
         auto st = mRequestDoneCond.wait_for(lk, timeout);
         if (st == std::cv_status::timeout) {
             ALOGE("%s: wait for inflight request finish timeout!", __FUNCTION__);
@@ -1746,26 +1831,49 @@
     }
 
     std::unique_lock<std::mutex> lk(mRequestListLock);
+    int waitTimes = 0;
     while (mRequestList.empty()) {
-        std::chrono::seconds timeout = std::chrono::seconds(kReqWaitTimeoutSec);
+        if (exitPending()) {
+            return;
+        }
+        std::chrono::milliseconds timeout = std::chrono::milliseconds(kReqWaitTimeoutMs);
         auto st = mRequestCond.wait_for(lk, timeout);
         if (st == std::cv_status::timeout) {
-            // no new request, return
-            return;
+            waitTimes++;
+            if (waitTimes == kReqWaitTimesMax) {
+                // no new request, return
+                return;
+            }
         }
     }
     *out = mRequestList.front();
     mRequestList.pop_front();
     mProcessingRequest = true;
+    mProcessingFrameNumer = out->frameNumber;
 }
 
 void ExternalCameraDeviceSession::OutputThread::signalRequestDone() {
     std::unique_lock<std::mutex> lk(mRequestListLock);
     mProcessingRequest = false;
+    mProcessingFrameNumer = 0;
     lk.unlock();
     mRequestDoneCond.notify_one();
 }
 
+void ExternalCameraDeviceSession::OutputThread::dump(int fd) {
+    std::lock_guard<std::mutex> lk(mRequestListLock);
+    if (mProcessingRequest) {
+        dprintf(fd, "OutputThread processing frame %d\n", mProcessingFrameNumer);
+    } else {
+        dprintf(fd, "OutputThread not processing any frames\n");
+    }
+    dprintf(fd, "OutputThread request list contains frame: ");
+    for (const auto& req : mRequestList) {
+        dprintf(fd, "%d, ", req.frameNumber);
+    }
+    dprintf(fd, "\n");
+}
+
 void ExternalCameraDeviceSession::cleanupBuffersLocked(int id) {
     for (auto& pair : mCirculatingBuffers.at(id)) {
         sHandleImporter.freeBuffer(pair.second);
@@ -2027,15 +2135,25 @@
     return OK;
 }
 
-sp<V4L2Frame> ExternalCameraDeviceSession::dequeueV4l2FrameLocked() {
+sp<V4L2Frame> ExternalCameraDeviceSession::dequeueV4l2FrameLocked(/*out*/nsecs_t* shutterTs) {
     sp<V4L2Frame> ret = nullptr;
 
+    if (shutterTs == nullptr) {
+        ALOGE("%s: shutterTs must not be null!", __FUNCTION__);
+        return ret;
+    }
+
     {
         std::unique_lock<std::mutex> lk(mV4l2BufferLock);
         if (mNumDequeuedV4l2Buffers == mV4L2BufferCount) {
             std::chrono::seconds timeout = std::chrono::seconds(kBufferWaitTimeoutSec);
             mLock.unlock();
             auto st = mV4L2BufferReturned.wait_for(lk, timeout);
+            // Here we introduce a case where mV4l2BufferLock is acquired before mLock, while
+            // the normal lock acquisition order is reversed, but this is fine because in most of
+            // cases we are protected by mInterfaceLock. The only thread that can compete these
+            // locks are the OutputThread, where we do need to make sure we don't acquire mLock then
+            // mV4l2BufferLock
             mLock.lock();
             if (st == std::cv_status::timeout) {
                 ALOGE("%s: wait for V4L2 buffer return timeout!", __FUNCTION__);
@@ -2062,6 +2180,15 @@
         // TODO: try to dequeue again
     }
 
+    if (buffer.flags & V4L2_BUF_FLAG_TIMESTAMP_MONOTONIC) {
+        // Ideally we should also check for V4L2_BUF_FLAG_TSTAMP_SRC_SOE, but
+        // even V4L2_BUF_FLAG_TSTAMP_SRC_EOF is better than capture a timestamp now
+        *shutterTs = static_cast<nsecs_t>(buffer.timestamp.tv_sec)*1000000000LL +
+                buffer.timestamp.tv_usec * 1000LL;
+    } else {
+        *shutterTs = systemTime(SYSTEM_TIME_MONOTONIC);
+    }
+
     {
         std::lock_guard<std::mutex> lk(mV4l2BufferLock);
         mNumDequeuedV4l2Buffers++;
@@ -2072,15 +2199,20 @@
 }
 
 void ExternalCameraDeviceSession::enqueueV4l2Frame(const sp<V4L2Frame>& frame) {
-    Mutex::Autolock _l(mLock);
-    frame->unmap();
-    v4l2_buffer buffer{};
-    buffer.type = V4L2_BUF_TYPE_VIDEO_CAPTURE;
-    buffer.memory = V4L2_MEMORY_MMAP;
-    buffer.index = frame->mBufferIndex;
-    if (TEMP_FAILURE_RETRY(ioctl(mV4l2Fd.get(), VIDIOC_QBUF, &buffer)) < 0) {
-        ALOGE("%s: QBUF index %d fails: %s", __FUNCTION__, frame->mBufferIndex, strerror(errno));
-        return;
+    {
+        // Release mLock before acquiring mV4l2BufferLock to avoid potential
+        // deadlock
+        Mutex::Autolock _l(mLock);
+        frame->unmap();
+        v4l2_buffer buffer{};
+        buffer.type = V4L2_BUF_TYPE_VIDEO_CAPTURE;
+        buffer.memory = V4L2_MEMORY_MMAP;
+        buffer.index = frame->mBufferIndex;
+        if (TEMP_FAILURE_RETRY(ioctl(mV4l2Fd.get(), VIDIOC_QBUF, &buffer)) < 0) {
+            ALOGE("%s: QBUF index %d fails: %s", __FUNCTION__,
+                    frame->mBufferIndex, strerror(errno));
+            return;
+        }
     }
 
     {
diff --git a/camera/device/3.4/default/include/ext_device_v3_4_impl/ExternalCameraDeviceSession.h b/camera/device/3.4/default/include/ext_device_v3_4_impl/ExternalCameraDeviceSession.h
index 62b6c27..30145ac 100644
--- a/camera/device/3.4/default/include/ext_device_v3_4_impl/ExternalCameraDeviceSession.h
+++ b/camera/device/3.4/default/include/ext_device_v3_4_impl/ExternalCameraDeviceSession.h
@@ -91,6 +91,7 @@
             const std::vector<SupportedV4L2Format>& sortedFormats,
             const CroppingType& croppingType,
             const common::V1_0::helper::CameraMetadata& chars,
+            const std::string& cameraId,
             unique_fd v4l2Fd);
     virtual ~ExternalCameraDeviceSession();
     // Call by CameraDevice to dump active device states
@@ -184,7 +185,7 @@
     int v4l2StreamOffLocked();
 
     // TODO: change to unique_ptr for better tracking
-    sp<V4L2Frame> dequeueV4l2FrameLocked(); // Called with mLock hold
+    sp<V4L2Frame> dequeueV4l2FrameLocked(/*out*/nsecs_t* shutterTs); // Called with mLock hold
     void enqueueV4l2Frame(const sp<V4L2Frame>&);
 
     // Check if input Stream is one of supported stream setting on this device
@@ -225,6 +226,7 @@
                 const hidl_vec<Stream>& streams);
         Status submitRequest(const HalRequest&);
         void flush();
+        void dump(int fd);
         virtual bool threadLoop() override;
 
     private:
@@ -236,7 +238,9 @@
         static int getCropRect(
                 CroppingType ct, const Size& inSize, const Size& outSize, IMapper::Rect* out);
 
-        static const int kReqWaitTimeoutSec = 3;
+        static const int kFlushWaitTimeoutSec = 3; // 3 sec
+        static const int kReqWaitTimeoutMs = 33;   // 33ms
+        static const int kReqWaitTimesMax = 90;    // 33ms * 90 ~= 3 sec
 
         void waitForNextRequest(HalRequest* out);
         void signalRequestDone();
@@ -268,6 +272,7 @@
         std::condition_variable mRequestDoneCond; // signaled when a request is done processing
         std::list<HalRequest> mRequestList;
         bool mProcessingRequest = false;
+        uint32_t mProcessingFrameNumer = 0;
 
         // V4L2 frameIn
         // (MJPG decode)-> mYu12Frame
@@ -291,7 +296,9 @@
     const common::V1_0::helper::CameraMetadata mCameraCharacteristics;
     const std::vector<SupportedV4L2Format> mSupportedFormats;
     const CroppingType mCroppingType;
+    const std::string& mCameraId;
     unique_fd mV4l2Fd;
+
     // device is closed either
     //    - closed by user
     //    - init failed