codec2 sfplugin: add traces for frame processing latency

Bug: 217969867
Test: Record trace & analyze in ui.perfetto.dev
Change-Id: Ideccc5e78ed5fcd2744b33c6036b5afa231b2b9a
diff --git a/media/codec2/sfplugin/CCodecBufferChannel.cpp b/media/codec2/sfplugin/CCodecBufferChannel.cpp
index 99aa593..a66e81e 100644
--- a/media/codec2/sfplugin/CCodecBufferChannel.cpp
+++ b/media/codec2/sfplugin/CCodecBufferChannel.cpp
@@ -16,7 +16,9 @@
 
 //#define LOG_NDEBUG 0
 #define LOG_TAG "CCodecBufferChannel"
+#define ATRACE_TAG  ATRACE_TAG_VIDEO
 #include <utils/Log.h>
+#include <utils/Trace.h>
 
 #include <algorithm>
 #include <atomic>
@@ -327,6 +329,8 @@
     }
     c2_status_t err = C2_OK;
     if (!items.empty()) {
+        ScopedTrace trace(ATRACE_TAG, android::base::StringPrintf(
+                "CCodecBufferChannel::queue(%s@ts=%lld)", mName, (long long)timeUs).c_str());
         {
             Mutexed<PipelineWatcher>::Locked watcher(mPipelineWatcher);
             PipelineWatcher::Clock::time_point now = PipelineWatcher::Clock::now();
@@ -1909,6 +1913,8 @@
         // When using input surface we need to restore the original input timestamp.
         timestamp = work->input.ordinal.customOrdinal;
     }
+    ScopedTrace trace(ATRACE_TAG, android::base::StringPrintf(
+            "CCodecBufferChannel::onWorkDone(%s@ts=%lld)", mName, timestamp.peekll()).c_str());
     ALOGV("[%s] onWorkDone: input %lld, codec %lld => output %lld => %lld",
           mName,
           work->input.ordinal.customOrdinal.peekll(),
diff --git a/media/codec2/sfplugin/Codec2Buffer.cpp b/media/codec2/sfplugin/Codec2Buffer.cpp
index 2d3c70a..ad9e30c 100644
--- a/media/codec2/sfplugin/Codec2Buffer.cpp
+++ b/media/codec2/sfplugin/Codec2Buffer.cpp
@@ -16,7 +16,9 @@
 
 //#define LOG_NDEBUG 0
 #define LOG_TAG "Codec2Buffer"
+#define ATRACE_TAG  ATRACE_TAG_VIDEO
 #include <utils/Log.h>
+#include <utils/Trace.h>
 
 #include <aidl/android/hardware/graphics/common/Cta861_3.h>
 #include <aidl/android/hardware/graphics/common/Smpte2086.h>
@@ -229,6 +231,7 @@
           mAllocatedDepth(0),
           mBackBufferSize(0),
           mMediaImage(new ABuffer(sizeof(MediaImage2))) {
+        ATRACE_CALL();
         if (!format->findInt32(KEY_COLOR_FORMAT, &mClientColorFormat)) {
             mClientColorFormat = COLOR_FormatYUV420Flexible;
         }
@@ -581,6 +584,7 @@
      * Copy C2GraphicView to MediaImage2.
      */
     status_t copyToMediaImage() {
+        ATRACE_CALL();
         if (mInitCheck != OK) {
             return mInitCheck;
         }
@@ -619,7 +623,9 @@
         const sp<AMessage> &format,
         const std::shared_ptr<C2GraphicBlock> &block,
         std::function<sp<ABuffer>(size_t)> alloc) {
+    ATRACE_BEGIN("GraphicBlockBuffer::Allocate block->map()");
     C2GraphicView view(block->map().get());
+    ATRACE_END();
     if (view.error() != C2_OK) {
         ALOGD("C2GraphicBlock::map failed: %d", view.error());
         return nullptr;
@@ -664,6 +670,7 @@
 }
 
 std::shared_ptr<C2Buffer> GraphicBlockBuffer::asC2Buffer() {
+    ATRACE_CALL();
     uint32_t width = mView.width();
     uint32_t height = mView.height();
     if (!mWrapped) {
@@ -752,8 +759,10 @@
         ALOGD("C2Buffer precond fail");
         return nullptr;
     }
+    ATRACE_BEGIN("ConstGraphicBlockBuffer::Allocate block->map()");
     std::unique_ptr<const C2GraphicView> view(std::make_unique<const C2GraphicView>(
             buffer->data().graphicBlocks()[0].map().get()));
+    ATRACE_END();
     std::unique_ptr<const C2GraphicView> holder;
 
     GraphicView2MediaImageConverter converter(*view, format, false /* copy */);
@@ -854,11 +863,13 @@
         return false;
     }
 
+    ATRACE_BEGIN("ConstGraphicBlockBuffer::canCopy block->map()");
     GraphicView2MediaImageConverter converter(
             buffer->data().graphicBlocks()[0].map().get(),
             // FIXME: format() is not const, but we cannot change it, so do a const cast here
             const_cast<ConstGraphicBlockBuffer *>(this)->format(),
             true /* copy */);
+    ATRACE_END();
     if (converter.initCheck() != OK) {
         ALOGD("ConstGraphicBlockBuffer::canCopy: converter init failed: %d", converter.initCheck());
         return false;
diff --git a/media/codec2/sfplugin/utils/Codec2BufferUtils.cpp b/media/codec2/sfplugin/utils/Codec2BufferUtils.cpp
index bff9db5..7fc4c27 100644
--- a/media/codec2/sfplugin/utils/Codec2BufferUtils.cpp
+++ b/media/codec2/sfplugin/utils/Codec2BufferUtils.cpp
@@ -16,7 +16,9 @@
 
 //#define LOG_NDEBUG 0
 #define LOG_TAG "Codec2BufferUtils"
+#define ATRACE_TAG  ATRACE_TAG_VIDEO
 #include <utils/Log.h>
+#include <utils/Trace.h>
 
 #include <libyuv.h>
 
@@ -36,8 +38,8 @@
 namespace {
 
 /**
- * A flippable, optimizable memcpy. Constructs such as (from ? src : dst) do not work as the results are
- * always const.
+ * A flippable, optimizable memcpy. Constructs such as (from ? src : dst)
+ * do not work as the results are always const.
  */
 template<bool ToA, size_t S>
 struct MemCopier {
@@ -139,15 +141,18 @@
 
     if (IsNV12(view)) {
         if (IsNV12(img)) {
+            ScopedTrace trace(ATRACE_TAG, "ImageCopy: NV12->NV12");
             libyuv::CopyPlane(src_y, src_stride_y, dst_y, dst_stride_y, width, height);
             libyuv::CopyPlane(src_u, src_stride_u, dst_u, dst_stride_u, width, height / 2);
             return OK;
         } else if (IsNV21(img)) {
+            ScopedTrace trace(ATRACE_TAG, "ImageCopy: NV12->NV21");
             if (!libyuv::NV21ToNV12(src_y, src_stride_y, src_u, src_stride_u,
                                     dst_y, dst_stride_y, dst_v, dst_stride_v, width, height)) {
                 return OK;
             }
         } else if (IsI420(img)) {
+            ScopedTrace trace(ATRACE_TAG, "ImageCopy: NV12->I420");
             if (!libyuv::NV12ToI420(src_y, src_stride_y, src_u, src_stride_u, dst_y, dst_stride_y,
                                     dst_u, dst_stride_u, dst_v, dst_stride_v, width, height)) {
                 return OK;
@@ -155,15 +160,18 @@
         }
     } else if (IsNV21(view)) {
         if (IsNV12(img)) {
+            ScopedTrace trace(ATRACE_TAG, "ImageCopy: NV21->NV12");
             if (!libyuv::NV21ToNV12(src_y, src_stride_y, src_v, src_stride_v,
                                     dst_y, dst_stride_y, dst_u, dst_stride_u, width, height)) {
                 return OK;
             }
         } else if (IsNV21(img)) {
+            ScopedTrace trace(ATRACE_TAG, "ImageCopy: NV21->NV21");
             libyuv::CopyPlane(src_y, src_stride_y, dst_y, dst_stride_y, width, height);
             libyuv::CopyPlane(src_v, src_stride_v, dst_v, dst_stride_v, width, height / 2);
             return OK;
         } else if (IsI420(img)) {
+            ScopedTrace trace(ATRACE_TAG, "ImageCopy: NV21->I420");
             if (!libyuv::NV21ToI420(src_y, src_stride_y, src_v, src_stride_v, dst_y, dst_stride_y,
                                     dst_u, dst_stride_u, dst_v, dst_stride_v, width, height)) {
                 return OK;
@@ -171,22 +179,26 @@
         }
     } else if (IsI420(view)) {
         if (IsNV12(img)) {
+            ScopedTrace trace(ATRACE_TAG, "ImageCopy: I420->NV12");
             if (!libyuv::I420ToNV12(src_y, src_stride_y, src_u, src_stride_u, src_v, src_stride_v,
                                     dst_y, dst_stride_y, dst_u, dst_stride_u, width, height)) {
                 return OK;
             }
         } else if (IsNV21(img)) {
+            ScopedTrace trace(ATRACE_TAG, "ImageCopy: I420->NV21");
             if (!libyuv::I420ToNV21(src_y, src_stride_y, src_u, src_stride_u, src_v, src_stride_v,
                                     dst_y, dst_stride_y, dst_v, dst_stride_v, width, height)) {
                 return OK;
             }
         } else if (IsI420(img)) {
+            ScopedTrace trace(ATRACE_TAG, "ImageCopy: I420->I420");
             libyuv::CopyPlane(src_y, src_stride_y, dst_y, dst_stride_y, width, height);
             libyuv::CopyPlane(src_u, src_stride_u, dst_u, dst_stride_u, width / 2, height / 2);
             libyuv::CopyPlane(src_v, src_stride_v, dst_v, dst_stride_v, width / 2, height / 2);
             return OK;
         }
     }
+    ScopedTrace trace(ATRACE_TAG, "ImageCopy: generic");
     return _ImageCopy<true>(view, img, imgBase);
 }
 
@@ -210,15 +222,18 @@
     int height = view.crop().height;
     if (IsNV12(img)) {
         if (IsNV12(view)) {
+            ScopedTrace trace(ATRACE_TAG, "ImageCopy: NV12->NV12");
             libyuv::CopyPlane(src_y, src_stride_y, dst_y, dst_stride_y, width, height);
             libyuv::CopyPlane(src_u, src_stride_u, dst_u, dst_stride_u, width, height / 2);
             return OK;
         } else if (IsNV21(view)) {
+            ScopedTrace trace(ATRACE_TAG, "ImageCopy: NV12->NV21");
             if (!libyuv::NV21ToNV12(src_y, src_stride_y, src_u, src_stride_u,
                                     dst_y, dst_stride_y, dst_v, dst_stride_v, width, height)) {
                 return OK;
             }
         } else if (IsI420(view)) {
+            ScopedTrace trace(ATRACE_TAG, "ImageCopy: NV12->I420");
             if (!libyuv::NV12ToI420(src_y, src_stride_y, src_u, src_stride_u, dst_y, dst_stride_y,
                                     dst_u, dst_stride_u, dst_v, dst_stride_v, width, height)) {
                 return OK;
@@ -226,15 +241,18 @@
         }
     } else if (IsNV21(img)) {
         if (IsNV12(view)) {
+            ScopedTrace trace(ATRACE_TAG, "ImageCopy: NV21->NV12");
             if (!libyuv::NV21ToNV12(src_y, src_stride_y, src_v, src_stride_v,
                                     dst_y, dst_stride_y, dst_u, dst_stride_u, width, height)) {
                 return OK;
             }
         } else if (IsNV21(view)) {
+            ScopedTrace trace(ATRACE_TAG, "ImageCopy: NV21->NV21");
             libyuv::CopyPlane(src_y, src_stride_y, dst_y, dst_stride_y, width, height);
             libyuv::CopyPlane(src_v, src_stride_v, dst_v, dst_stride_v, width, height / 2);
             return OK;
         } else if (IsI420(view)) {
+            ScopedTrace trace(ATRACE_TAG, "ImageCopy: NV21->I420");
             if (!libyuv::NV21ToI420(src_y, src_stride_y, src_v, src_stride_v, dst_y, dst_stride_y,
                                     dst_u, dst_stride_u, dst_v, dst_stride_v, width, height)) {
                 return OK;
@@ -242,22 +260,26 @@
         }
     } else if (IsI420(img)) {
         if (IsNV12(view)) {
+            ScopedTrace trace(ATRACE_TAG, "ImageCopy: I420->NV12");
             if (!libyuv::I420ToNV12(src_y, src_stride_y, src_u, src_stride_u, src_v, src_stride_v,
                                     dst_y, dst_stride_y, dst_u, dst_stride_u, width, height)) {
                 return OK;
             }
         } else if (IsNV21(view)) {
+            ScopedTrace trace(ATRACE_TAG, "ImageCopy: I420->NV21");
             if (!libyuv::I420ToNV21(src_y, src_stride_y, src_u, src_stride_u, src_v, src_stride_v,
                                     dst_y, dst_stride_y, dst_v, dst_stride_v, width, height)) {
                 return OK;
             }
         } else if (IsI420(view)) {
+            ScopedTrace trace(ATRACE_TAG, "ImageCopy: I420->I420");
             libyuv::CopyPlane(src_y, src_stride_y, dst_y, dst_stride_y, width, height);
             libyuv::CopyPlane(src_u, src_stride_u, dst_u, dst_stride_u, width / 2, height / 2);
             libyuv::CopyPlane(src_v, src_stride_v, dst_v, dst_stride_v, width / 2, height / 2);
             return OK;
         }
     }
+    ScopedTrace trace(ATRACE_TAG, "ImageCopy: generic");
     return _ImageCopy<false>(view, img, imgBase);
 }