CameraService: Add more systracing, fix module init order

Improve debugging of performance of concurrent calls to the service.

- Add ATRACE calls to camera service entry points
- Add ATRACE calls for camera HAL module calls
- Ensure that camera module init method is called before all others

Bug: 23718257
Bug: 23933447
Change-Id: I2a025866ab39eda3962877120cab13a063c7727e

2 files changed, 84 insertions, 14 deletions

diff --git a/services/camera/libcameraservice/CameraService.cpp b/services/camera/libcameraservice/CameraService.cpp
index 9230994..7e33e0c 100644
--- a/services/camera/libcameraservice/CameraService.cpp
+++ b/services/camera/libcameraservice/CameraService.cpp
@@ -15,6 +15,7 @@
  */
 
 #define LOG_TAG "CameraService"
+#define ATRACE_TAG ATRACE_TAG_CAMERA
 //#define LOG_NDEBUG 0
 
 #include <algorithm>
@@ -156,7 +157,6 @@ void CameraService::onFirstRef()
     }
 
     mModule = new CameraModule(rawModule);
-    ALOGI("Loaded \"%s\" camera module", mModule->getModuleName());
     err = mModule->init();
     if (err != OK) {
         ALOGE("Could not initialize camera HAL module: %d (%s)", err,
@@ -168,6 +168,7 @@ void CameraService::onFirstRef()
         mModule = nullptr;
         return;
     }
+    ALOGI("Loaded \"%s\" camera module", mModule->getModuleName());
 
     mNumberOfCameras = mModule->getNumberOfCameras();
     mNumberOfNormalCameras = mNumberOfCameras;
@@ -403,10 +404,12 @@ void CameraService::onTorchStatusChangedLocked(const String8& cameraId,
 }
 
 int32_t CameraService::getNumberOfCameras() {
+    ATRACE_CALL();
     return getNumberOfCameras(CAMERA_TYPE_BACKWARD_COMPATIBLE);
 }
 
 int32_t CameraService::getNumberOfCameras(int type) {
+    ATRACE_CALL();
     switch (type) {
         case CAMERA_TYPE_BACKWARD_COMPATIBLE:
             return mNumberOfNormalCameras;
@@ -421,6 +424,7 @@ int32_t CameraService::getNumberOfCameras(int type) {
 
 status_t CameraService::getCameraInfo(int cameraId,
                                       struct CameraInfo* cameraInfo) {
+    ATRACE_CALL();
     if (!mModule) {
         return -ENODEV;
     }
@@ -448,6 +452,7 @@ int CameraService::cameraIdToInt(const String8& cameraId) {
 }
 
 status_t CameraService::generateShimMetadata(int cameraId, /*out*/CameraMetadata* cameraInfo) {
+    ATRACE_CALL();
     status_t ret = OK;
     struct CameraInfo info;
     if ((ret = getCameraInfo(cameraId, &info)) != OK) {
@@ -534,6 +539,7 @@ status_t CameraService::generateShimMetadata(int cameraId, /*out*/CameraMetadata
 
 status_t CameraService::getCameraCharacteristics(int cameraId,
                                                 CameraMetadata* cameraInfo) {
+    ATRACE_CALL();
     if (!cameraInfo) {
         ALOGE("%s: cameraInfo is NULL", __FUNCTION__);
         return BAD_VALUE;
@@ -611,6 +617,7 @@ int CameraService::getCameraPriorityFromProcState(int procState) {
 }
 
 status_t CameraService::getCameraVendorTagDescriptor(/*out*/sp<VendorTagDescriptor>& desc) {
+    ATRACE_CALL();
     if (!mModule) {
         ALOGE("%s: camera hardware module doesn't exist", __FUNCTION__);
         return -ENODEV;
@@ -621,6 +628,7 @@ status_t CameraService::getCameraVendorTagDescriptor(/*out*/sp<VendorTagDescript
 }
 
 int CameraService::getDeviceVersion(int cameraId, int* facing) {
+    ATRACE_CALL();
     struct camera_info info;
     if (mModule->getCameraInfo(cameraId, &info) != OK) {
         return -1;
@@ -652,6 +660,7 @@ status_t CameraService::filterGetInfoErrorCode(status_t err) {
 }
 
 bool CameraService::setUpVendorTags() {
+    ATRACE_CALL();
     vendor_tag_ops_t vOps = vendor_tag_ops_t();
 
     // Check if vendor operations have been implemented
@@ -660,9 +669,7 @@ bool CameraService::setUpVendorTags() {
         return false;
     }
 
-    ATRACE_BEGIN("camera3->get_metadata_vendor_tag_ops");
     mModule->getVendorTagOps(&vOps);
-    ATRACE_END();
 
     // Ensure all vendor operations are present
     if (vOps.get_tag_count == NULL || vOps.get_all_tags == NULL ||
@@ -962,7 +969,7 @@ status_t CameraService::handleEvictionsLocked(const String8& cameraId, int clien
         /*out*/
         sp<BasicClient>* client,
         std::shared_ptr<resource_policy::ClientDescriptor<String8, sp<BasicClient>>>* partial) {
-
+    ATRACE_CALL();
     status_t ret = NO_ERROR;
     std::vector<DescriptorPtr> evictedClients;
     DescriptorPtr clientDescriptor;
@@ -1151,6 +1158,7 @@ status_t CameraService::connect(
         /*out*/
         sp<ICamera>& device) {
 
+    ATRACE_CALL();
     status_t ret = NO_ERROR;
     String8 id = String8::format("%d", cameraId);
     sp<Client> client = nullptr;
@@ -1175,6 +1183,7 @@ status_t CameraService::connectLegacy(
         /*out*/
         sp<ICamera>& device) {
 
+    ATRACE_CALL();
     String8 id = String8::format("%d", cameraId);
     int apiVersion = mModule->getModuleApiVersion();
     if (halVersion != CAMERA_HAL_API_VERSION_UNSPECIFIED &&
@@ -1215,6 +1224,7 @@ status_t CameraService::connectDevice(
         /*out*/
         sp<ICameraDeviceUser>& device) {
 
+    ATRACE_CALL();
     status_t ret = NO_ERROR;
     String8 id = String8::format("%d", cameraId);
     sp<CameraDeviceClient> client = nullptr;
@@ -1234,6 +1244,8 @@ status_t CameraService::connectDevice(
 
 status_t CameraService::setTorchMode(const String16& cameraId, bool enabled,
         const sp<IBinder>& clientBinder) {
+
+    ATRACE_CALL();
     if (enabled && clientBinder == nullptr) {
         ALOGE("%s: torch client binder is NULL", __FUNCTION__);
         return -EINVAL;
@@ -1322,6 +1334,8 @@ status_t CameraService::setTorchMode(const String16& cameraId, bool enabled,
 }
 
 void CameraService::notifySystemEvent(int32_t eventId, const int32_t* args, size_t length) {
+    ATRACE_CALL();
+
     switch(eventId) {
         case ICameraService::USER_SWITCHED: {
             doUserSwitch(/*newUserIds*/args, /*length*/length);
@@ -1337,6 +1351,8 @@ void CameraService::notifySystemEvent(int32_t eventId, const int32_t* args, size
 }
 
 status_t CameraService::addListener(const sp<ICameraServiceListener>& listener) {
+    ATRACE_CALL();
+
     ALOGV("%s: Add listener %p", __FUNCTION__, listener.get());
 
     if (listener == nullptr) {
@@ -1385,6 +1401,8 @@ status_t CameraService::addListener(const sp<ICameraServiceListener>& listener)
 }
 
 status_t CameraService::removeListener(const sp<ICameraServiceListener>& listener) {
+    ATRACE_CALL();
+
     ALOGV("%s: Remove listener %p", __FUNCTION__, listener.get());
 
     if (listener == 0) {
@@ -1411,6 +1429,8 @@ status_t CameraService::removeListener(const sp<ICameraServiceListener>& listene
 }
 
 status_t CameraService::getLegacyParameters(int cameraId, /*out*/String16* parameters) {
+
+    ATRACE_CALL();
     ALOGV("%s: for camera ID = %d", __FUNCTION__, cameraId);
 
     if (parameters == NULL) {
@@ -1435,6 +1455,8 @@ status_t CameraService::getLegacyParameters(int cameraId, /*out*/String16* param
 }
 
 status_t CameraService::supportsCameraApi(int cameraId, int apiVersion) {
+    ATRACE_CALL();
+
     ALOGV("%s: for camera ID = %d", __FUNCTION__, cameraId);
 
     switch (apiVersion) {
@@ -1802,6 +1824,8 @@ MediaPlayer* CameraService::newMediaPlayer(const char *file) {
 }
 
 void CameraService::loadSound() {
+    ATRACE_CALL();
+
     Mutex::Autolock lock(mSoundLock);
     LOG1("CameraService::loadSound ref=%d", mSoundRef);
     if (mSoundRef++) return;
@@ -1824,6 +1848,8 @@ void CameraService::releaseSound() {
 }
 
 void CameraService::playSound(sound_kind kind) {
+    ATRACE_CALL();
+
     LOG1("playSound(%d)", kind);
     Mutex::Autolock lock(mSoundLock);
     sp<MediaPlayer> player = mSoundPlayer[kind];
@@ -1933,6 +1959,8 @@ bool CameraService::BasicClient::canCastToApiClient(apiLevel level) const {
 }
 
 status_t CameraService::BasicClient::startCameraOps() {
+    ATRACE_CALL();
+
     int32_t res;
     // Notify app ops that the camera is not available
     mOpsCallback = new OpsCallback(this);
@@ -1974,6 +2002,8 @@ status_t CameraService::BasicClient::startCameraOps() {
 }
 
 status_t CameraService::BasicClient::finishCameraOps() {
+    ATRACE_CALL();
+
     // Check if startCameraOps succeeded, and if so, finish the camera op
     if (mOpsActive) {
         // Notify app ops that the camera is available again
@@ -2006,6 +2036,8 @@ status_t CameraService::BasicClient::finishCameraOps() {
 }
 
 void CameraService::BasicClient::opChanged(int32_t op, const String16& packageName) {
+    ATRACE_CALL();
+
     String8 name(packageName);
     String8 myName(mClientPackageName);
 
@@ -2229,6 +2261,8 @@ static bool tryLock(Mutex& mutex)
 }
 
 status_t CameraService::dump(int fd, const Vector<String16>& args) {
+    ATRACE_CALL();
+
     String8 result("Dump of the Camera Service:\n");
     if (checkCallingPermission(String16("android.permission.DUMP")) == false) {
         result.appendFormat("Permission Denial: "
diff --git a/services/camera/libcameraservice/common/CameraModule.cpp b/services/camera/libcameraservice/common/CameraModule.cpp
index 6a4dfe0..16b8aba 100644
--- a/services/camera/libcameraservice/common/CameraModule.cpp
+++ b/services/camera/libcameraservice/common/CameraModule.cpp
@@ -15,14 +15,18 @@
  */
 
 #define LOG_TAG "CameraModule"
+#define ATRACE_TAG ATRACE_TAG_CAMERA
 //#define LOG_NDEBUG 0
 
+#include <utils/Trace.h>
+
 #include "CameraModule.h"
 
 namespace android {
 
 void CameraModule::deriveCameraCharacteristicsKeys(
         uint32_t deviceVersion, CameraMetadata &chars) {
+    ATRACE_CALL();
     // HAL1 devices should not reach here
     if (deviceVersion < CAMERA_DEVICE_API_VERSION_2_0) {
         ALOGV("%s: Cannot derive keys for HAL version < 2.0");
@@ -150,9 +154,7 @@ CameraModule::CameraModule(camera_module_t *module) {
         ALOGE("%s: camera hardware module must not be null", __FUNCTION__);
         assert(0);
     }
-
     mModule = module;
-    mCameraInfoMap.setCapacity(getNumberOfCameras());
 }
 
 CameraModule::~CameraModule()
@@ -168,14 +170,20 @@ CameraModule::~CameraModule()
 }
 
 int CameraModule::init() {
+    ATRACE_CALL();
+    int res = OK;
     if (getModuleApiVersion() >= CAMERA_MODULE_API_VERSION_2_4 &&
             mModule->init != NULL) {
-        return mModule->init();
+        ATRACE_BEGIN("camera_module->init");
+        res = mModule->init();
+        ATRACE_END();
     }
-    return OK;
+    mCameraInfoMap.setCapacity(getNumberOfCameras());
+    return res;
 }
 
 int CameraModule::getCameraInfo(int cameraId, struct camera_info *info) {
+    ATRACE_CALL();
     Mutex::Autolock lock(mCameraInfoLock);
     if (cameraId < 0) {
         ALOGE("%s: Invalid camera ID %d", __FUNCTION__, cameraId);
@@ -185,14 +193,20 @@ int CameraModule::getCameraInfo(int cameraId, struct camera_info *info) {
     // Only override static_camera_characteristics for API2 devices
     int apiVersion = mModule->common.module_api_version;
     if (apiVersion < CAMERA_MODULE_API_VERSION_2_0) {
-        return mModule->get_camera_info(cameraId, info);
+        int ret;
+        ATRACE_BEGIN("camera_module->get_camera_info");
+        ret = mModule->get_camera_info(cameraId, info);
+        ATRACE_END();
+        return ret;
     }
 
     ssize_t index = mCameraInfoMap.indexOfKey(cameraId);
     if (index == NAME_NOT_FOUND) {
         // Get camera info from raw module and cache it
         camera_info rawInfo, cameraInfo;
+        ATRACE_BEGIN("camera_module->get_camera_info");
         int ret = mModule->get_camera_info(cameraId, &rawInfo);
+        ATRACE_END();
         if (ret != 0) {
             return ret;
         }
@@ -217,20 +231,36 @@ int CameraModule::getCameraInfo(int cameraId, struct camera_info *info) {
 }
 
 int CameraModule::open(const char* id, struct hw_device_t** device) {
-    return filterOpenErrorCode(mModule->common.methods->open(&mModule->common, id, device));
+    int res;
+    ATRACE_BEGIN("camera_module->open");
+    res = filterOpenErrorCode(mModule->common.methods->open(&mModule->common, id, device));
+    ATRACE_END();
+    return res;
 }
 
 int CameraModule::openLegacy(
         const char* id, uint32_t halVersion, struct hw_device_t** device) {
-    return mModule->open_legacy(&mModule->common, id, halVersion, device);
+    int res;
+    ATRACE_BEGIN("camera_module->open_legacy");
+    res = mModule->open_legacy(&mModule->common, id, halVersion, device);
+    ATRACE_END();
+    return res;
 }
 
 int CameraModule::getNumberOfCameras() {
-    return mModule->get_number_of_cameras();
+    int numCameras;
+    ATRACE_BEGIN("camera_module->get_number_of_cameras");
+    numCameras = mModule->get_number_of_cameras();
+    ATRACE_END();
+    return numCameras;
 }
 
 int CameraModule::setCallbacks(const camera_module_callbacks_t *callbacks) {
-    return mModule->set_callbacks(callbacks);
+    int res;
+    ATRACE_BEGIN("camera_module->set_callbacks");
+    res = mModule->set_callbacks(callbacks);
+    ATRACE_END();
+    return res;
 }
 
 bool CameraModule::isVendorTagDefined() {
@@ -239,12 +269,18 @@ bool CameraModule::isVendorTagDefined() {
 
 void CameraModule::getVendorTagOps(vendor_tag_ops_t* ops) {
     if (mModule->get_vendor_tag_ops) {
+        ATRACE_BEGIN("camera_module->get_vendor_tag_ops");
         mModule->get_vendor_tag_ops(ops);
+        ATRACE_END();
     }
 }
 
 int CameraModule::setTorchMode(const char* camera_id, bool enable) {
-    return mModule->set_torch_mode(camera_id, enable);
+    int res;
+    ATRACE_BEGIN("camera_module->set_torch_mode");
+    res = mModule->set_torch_mode(camera_id, enable);
+    ATRACE_END();
+    return res;
 }
 
 status_t CameraModule::filterOpenErrorCode(status_t err) {