1119629 - [OPEN FFOS1.1->FFOS1.3] switch camera to video mode take around 30 seconds when in calling.

Status: RESOLVED WONTFIX

(Firefox OS Graveyard :: Gaia::Camera, defect)

Description

[becker hsieh{:behsieh}]

Attachment: log(camera_video_switch_slow).txt

Comment 1

[becker hsieh{:behsieh}]

from the log
in coming call start at
04-26 08:46:32.009: E/AudioPolicyManager(118): setPhoneState() state 2
lunch camera at 
04-26 08:46:43.599: V/QualcommCameraHardware(118): startCamera E
04-26 08:46:43.599: V/QualcommCameraHardware(118): loading liboemcamera at 0xb000f4b0
04-26 08:46:43.599: V/QualcommCameraHardware(118):  openCamera : E
04-26 08:46:43.819: V/QualcommCameraHardware(118):  openCamera : X
04-26 08:46:43.819: V/QualcommCameraHardware(118): openCamera : X
04-26 08:46:43.819: V/QualcommCameraHardware(118): startCamera X
receive 1st frame at 
04-26 08:46:44.449: I/QualcommCameraHardware(118): receivePreviewFrame E
04-26 08:46:44.449: I/QualcommCameraHardware(118): receivePreviewFrame X
and stop camera in here (takes around 40s)
04-26 08:46:47.509: V/QualcommCameraHardware(118): stopPreview: E
04-26 08:47:26.609: V/QualcommCameraHardware(118): stopPreview: X
start preview again
04-26 08:47:26.699: V/QualcommCameraHardware(118): startPreview E
04-26 08:47:26.859: V/QualcommCameraHardware(118): startPreview X
receive frame
04-26 08:47:26.909: I/QualcommCameraHardware(118): receivePreviewFrame E
04-26 08:47:26.909: I/QualcommCameraHardware(118): receivePreviewFrame X

Comment 2

[Danny Liang [:dliang]]

Hi Xiaodong,
We cannot reproduce this issue on Open v1.3 by your STR, could you provide more information as following?
1. What's your gecko/gaia version?
2. Could you reproduce this issue on user build?
3. Is there any other background process when issue happen? Could you provide STR in detail?
4. Could you provide b2g-info and top information when issue happen?
   - adb shell b2g-info
   - adb shell top -m 15 -d 1 -t

Comment 3

[becker hsieh{:behsieh}]

here is what we observe
in b2g info as below
           NAME  PID NICE  USS  PSS  RSS VSIZE OOM_ADJ USER    
            b2g  115    0 49.1 51.2 61.2 186.1       0 root    
     Homescreen  407   18 13.3 14.8 24.1  69.0       8 app_407 
 Communications  580   18 15.2 16.9 26.7  81.0      11 app_580 
       Messages 1264   18 12.5 14.2 23.7  74.0      11 app_1264
        Browser 1378   18  9.8 11.3 20.1  63.9      12 app_1378
         Camera 1765    1 12.7 14.8 24.9  85.4       2 app_1765
(Preallocated a 4633   18 10.8 12.3 21.1  62.9      10 root    

System memory info:

            Total 171.6 MB
     Used - cache 146.6 MB
  B2G procs (PSS) 135.6 MB
    Non-B2G procs  11.0 MB
     Free + cache  25.0 MB
             Free   3.5 MB
            Cache  21.6 MB

Low-memory killer parameters:

  notify_trigger 14336 KB

  oom_adj min_free
        0  4096 KB
        1  5120 KB
        2  6144 KB
        6  7168 KB
        8  8192 KB
       10 20480 KB


without dialing call 
camera switch mode might causes around 34s delay.

01-06 09:28:04.429   119   119 E QualcommCamera: Qvoid android::stop_preview(camera_device*): E
01-06 09:28:38.459   119   119 E QualcommCamera: Qint android::start_preview(camera_device*): E
01-06 09:28:38.539   119   119 E mm-camera: Waiting for frame thread to start ! 
01-06 09:28:38.539   119   119 E mm-camera: Wait over, frame thread ready !!!! 
01-06 09:28:38.629   119   119 E QualcommCamera: Qint android::start_preview(camera_device*): X

also attached top information

Comment 4

[becker hsieh{:behsieh}]

Attachment: top-information

Comment 5

[becker hsieh{:behsieh}]

Hi Xiaodong
can you take a look inside stop preview.
why it take a lots of time.

Comment 6

[Duan Xiaodong]

Attachment: adb_shell_top.txt

adb shell top inforamtion when issue reprodues.

Comment 7

[Duan Xiaodong]

Dear becker,

Thanks for your important information.
I will check it right now and give you feedback later.

Thanks,
Xiaodong

Comment 8

[Danny Liang [:dliang]]

Update what I found as following:
1. The issue didn't depend on background application number, I can reproduce this issue with only home screen at background.
2. I tried to test on v1.3t, I can still reproduce this issue on ZTE Open. But we cannot reproduce issue on Tarako with same gecko/gaia
3. Compare with top of Open and Tarako, we found the CPU usage of Compositor is over 50% on Open when issue happened, but it's less than 10% on Tarako in normal case.

Hi Xiaodong,
Could you help to check if anything wrong or any limitation on Compositor? As I know, we didn't have source code of hwCompositor.
Thanks,
Danny

Comment 9

[Danny Liang [:dliang]]

Attachment: b2g-info

b2g-info when issue happened

Comment 10

[Danny Liang [:dliang]]

Attachment: top.txt

top information when issue happened

Comment 11

[Duan Xiaodong]

Dear All,

From log(camera_video_switch_slow).txt, the costing time is between Line 1271 and Line 3007.

Line 1269: 04-26 08:46:47.509: V/QualcommCameraHardware(118): stopPreview: E
Line 1270: 04-26 08:46:47.509: E/QualcommCameraHardware(118): stopPreview:  Cancelling postview buffer 57 
-----------------------------------------
// @@ Time 08:46:47.509
Line 1271: 04-26 08:46:47.509: E/QualcommCameraHardware(118): stoppreview : display lock
// @@ Time 08:47:26.559 - 08:46:47.509 = 39 seconds
Line 3007: 04-26 08:47:26.559: E/QualcommCameraHardware(118): stopPreview : after cancelling thumbnail buffer
-----------------------------------------
Line 3008: 04-26 08:47:26.559: E/QualcommCameraHardware(118): stoppreview : display unlock
Line 3009: 04-26 08:47:26.559: I/QualcommCameraHardware(118): stopPreviewInternal E: 1
Line 3012: 04-26 08:47:26.609: E/QualcommCameraHardware(118): stopPreviewInternal, J_mCameraRunning = 0
Line 3013: 04-26 08:47:26.609: E/QualcommCameraHardware(118): stopPreviewInternal, before calling deinitpre mPreviewInitialized = 1
Line 3017: 04-26 08:47:26.609: I/QualcommCameraHardware(118): stopPreviewInternal X: 0
Line 3018: 04-26 08:47:26.609: V/QualcommCameraHardware(118): stopPreview: X

void QualcommCameraHardware::stopPreview()
{
    LOGV("stopPreview: E");
    Mutex::Autolock l(&mLock);
    {
        if (mDataCallbackTimestamp && (mMsgEnabled & CAMERA_MSG_VIDEO_FRAME))
            return;
    }
    if( mSnapshotThreadRunning ) {
        LOGV("In stopPreview during snapshot");
        return;
    }
    if( mPreviewWindow != NULL ) {
        private_handle_t *handle;
        for (int cnt = 0; cnt < (mZslEnable? (MAX_SNAPSHOT_BUFFERS-2) : numCapture); cnt++) {
            if(mPreviewWindow != NULL && mThumbnailBuffer[cnt] != NULL) {
                handle = (private_handle_t *)(*mThumbnailBuffer[cnt]);
                LOGE("%s:  Cancelling postview buffer %d ", __FUNCTION__, handle->fd);
                LOGE("stoppreview : display lock"); // @@ Time is 08:46:47.509
                mDisplayLock.lock();
                if (BUFFER_LOCKED == mThumbnailLockState[cnt]) {
                    if (GENLOCK_FAILURE == genlock_unlock_buffer(handle)) {
                       LOGE("%s: genlock_unlock_buffer failed", __FUNCTION__);
                       mDisplayLock.unlock();
                       continue;
                    } else {
                       mThumbnailLockState[cnt] = BUFFER_UNLOCKED;
                    }
                }
                status_t retVal = mPreviewWindow->cancel_buffer(mPreviewWindow,
                         mThumbnailBuffer[cnt]); // @@ cancel_buffer function costs 39 seconds.
                LOGE("stopPreview : after cancelling thumbnail buffer"); // @@ Time is 08:47:26.559
                if(retVal != NO_ERROR)
                    LOGE("%s: cancelBuffer failed for postview buffer %d",
                                                     __FUNCTION__, handle->fd);
                // unregister , unmap and release as well
                int mBufferSize = previewWidth * previewHeight * 3/2;
                int mCbCrOffset = PAD_TO_WORD(previewWidth * previewHeight);
                if(mThumbnailMapped[cnt]  && (mSnapshotFormat == PICTURE_FORMAT_JPEG)
                          || mZslEnable) {
                    LOGE("%s:  Unregistering Thumbnail Buffer %d ", __FUNCTION__, handle->fd);
                    register_buf(mBufferSize,
                        mBufferSize, mCbCrOffset, 0,
                        handle->fd,
                        0,
                        (uint8_t *)mThumbnailMapped[cnt],
                        MSM_PMEM_THUMBNAIL,
                        false, false);
                    if (munmap((void *)(mThumbnailMapped[cnt]),handle->size ) == -1) {
                      LOGE("StopPreview : Error un-mmapping the thumbnail buffer %d", index);
                    }
                    mThumbnailMapped[cnt] = NULL;
                 }
                mThumbnailBuffer[cnt] = NULL;
                LOGE("stoppreview : display unlock");
                mDisplayLock.unlock();
          }
       }
    }
    stopPreviewInternal();
    LOGV("stopPreview: X");
}

Comment 12

[becker hsieh{:behsieh}]

Hi Xiaodong
from your comment.
are you sure cancel buffer take too much time? can you put more log in between those code to make sure it is not stuck in mDisplayLock.lock()


and for cancel_buffer. it was calling into display.
we also found when issue happen, Compositor cost more than 50% cpu usage.
you might need to dig into display and check it
thanks

Comment 13

[Duan Xiaodong]

Dear Becker,

We find that mDisplayLock.lock() cost much more time via log. Camera process is stuck in mDisplay.lock() as dialer process may occupy the display lock.

Line 5760: 01-12 07:46:30.439 V/QualcommCameraHardware(117): stopPreview: E
Line 5762: 01-12 07:46:30.439 E/QualcommCameraHardware(117): stopPreview:  Cancelling postview buffer 58 

// Time : 07:46:30.439 
Line 5764: 01-12 07:46:30.439 E/QualcommCameraHardware(117): stoppreview : display lock
// Time : 07:47:01.639 
Line 8664: 01-12 07:47:01.639 E/QualcommCameraHardware(117): stoppreview : mDisplayLock.lock()

Line 8666: 01-12 07:47:01.639 E/QualcommCameraHardware(117): stopPreview : after cancelling thumbnail buffer
Line 8668: 01-12 07:47:01.639 E/QualcommCameraHardware(117): stoppreview : display unlock
Line 8670: 01-12 07:47:01.639 I/QualcommCameraHardware(117): stopPreviewInternal E: 1
Line 8684: 01-12 07:47:01.699 E/QualcommCameraHardware(117): stopPreviewInternal, J_mCameraRunning = 0
Line 8686: 01-12 07:47:01.699 E/QualcommCameraHardware(117): stopPreviewInternal, before calling deinitpre mPreviewInitialized = 1
Line 8694: 01-12 07:47:01.699 I/QualcommCameraHardware(117): stopPreviewInternal X: 0
Line 8696: 01-12 07:47:01.699 V/QualcommCameraHardware(117): stopPreview: X

void QualcommCameraHardware::stopPreview()
{
    LOGV("stopPreview: E");
    Mutex::Autolock l(&mLock);
    {
        if (mDataCallbackTimestamp && (mMsgEnabled & CAMERA_MSG_VIDEO_FRAME))
            return;
    }
    if( mSnapshotThreadRunning ) {
        LOGV("In stopPreview during snapshot");
        return;
    }
    if( mPreviewWindow != NULL ) {
        private_handle_t *handle;
        for (int cnt = 0; cnt < (mZslEnable? (MAX_SNAPSHOT_BUFFERS-2) : numCapture); cnt++) {
            if(mPreviewWindow != NULL && mThumbnailBuffer[cnt] != NULL) {
                handle = (private_handle_t *)(*mThumbnailBuffer[cnt]);
                LOGE("%s:  Cancelling postview buffer %d ", __FUNCTION__, handle->fd);
                LOGE("stoppreview : display lock"); // @@ Time: 07:46:30.439 
                mDisplayLock.lock(); // @@ mDisplayLock.lock() cost about 31 seconds.
                LOGE("stoppreview : mDisplayLock.lock()");// @@ Time :07:47:01.639 
                if (BUFFER_LOCKED == mThumbnailLockState[cnt]) {
                    if (GENLOCK_FAILURE == genlock_unlock_buffer(handle)) {
                       LOGE("%s: genlock_unlock_buffer failed", __FUNCTION__);
                       mDisplayLock.unlock();
                       continue;
                    } else {
                       mThumbnailLockState[cnt] = BUFFER_UNLOCKED;
                       LOGE("stoppreview : mThumbnailLockState[cnt] = BUFFER_UNLOCKED");
                    }
                }
                status_t retVal = mPreviewWindow->cancel_buffer(mPreviewWindow,
                                                              mThumbnailBuffer[cnt]);
                LOGE("stopPreview : after cancelling thumbnail buffer");
                if(retVal != NO_ERROR)
                    LOGE("%s: cancelBuffer failed for postview buffer %d",
                                                     __FUNCTION__, handle->fd);
                // unregister , unmap and release as well
                int mBufferSize = previewWidth * previewHeight * 3/2;
                int mCbCrOffset = PAD_TO_WORD(previewWidth * previewHeight);
                if(mThumbnailMapped[cnt]  && (mSnapshotFormat == PICTURE_FORMAT_JPEG)
                          || mZslEnable) {
                    LOGE("%s:  Unregistering Thumbnail Buffer %d ", __FUNCTION__, handle->fd);
                    register_buf(mBufferSize,
                        mBufferSize, mCbCrOffset, 0,
                        handle->fd,
                        0,
                        (uint8_t *)mThumbnailMapped[cnt],
                        MSM_PMEM_THUMBNAIL,
                        false, false);
                    if (munmap((void *)(mThumbnailMapped[cnt]),handle->size ) == -1) {
                      LOGE("StopPreview : Error un-mmapping the thumbnail buffer %d", index);
                    }
                    mThumbnailMapped[cnt] = NULL;
                 }
                mThumbnailBuffer[cnt] = NULL;
                LOGE("stoppreview : display unlock");
                mDisplayLock.unlock();
          }
       }
    }
    stopPreviewInternal();
    LOGV("stopPreview: X");
}

I also have attached the log (log_switch2videomode).We need to find a solution for the race condition of display lock.

Thanks,
Xiaoodng

Comment 14

[Duan Xiaodong]

Attachment: log_switch2videomode.txt

Comment 15

[becker hsieh{:behsieh}]

Hi Xiaodong:
great information , looks you blocking in waiting mDisplayLock.lock.
can you keep trace which thread holding mDisplayLock.lock?
thanks

Comment 16

[becker hsieh{:behsieh}]

Hi Xiaodong:
any update?
thanks

Comment 17

[BMO Automation]

Firefox OS is not being worked on