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

RESOLVED WONTFIX

Status

Firefox OS
Gaia::Camera
RESOLVED WONTFIX
3 years ago
2 months ago

People

(Reporter: behsieh, Assigned: behsieh, NeedInfo)

Tracking

Firefox Tracking Flags

(Not tracked)

Details

Attachments

(6 attachments)

(Assignee)

Description

3 years ago
Created attachment 8546337 [details]
log(camera_video_switch_slow).txt
(Assignee)

Updated

3 years ago
Assignee: nobody → behsieh
(Assignee)

Comment 1

3 years ago
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
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
Flags: needinfo?(duan.xiaodong)
(Assignee)

Comment 3

3 years ago
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
(Assignee)

Comment 4

3 years ago
Created attachment 8546389 [details]
top-information
(Assignee)

Comment 5

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

Comment 6

3 years ago
Created attachment 8546426 [details]
adb_shell_top.txt

adb shell top inforamtion when issue reprodues.
Flags: needinfo?(duan.xiaodong)

Comment 7

3 years ago
Dear becker,

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

Thanks,
Xiaodong
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
Flags: needinfo?(duan.xiaodong)
Created attachment 8546454 [details]
b2g-info

b2g-info when issue happened
Created attachment 8546457 [details]
top.txt

top information when issue happened

Comment 11

3 years ago
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");
}
Flags: needinfo?(duan.xiaodong)
(Assignee)

Comment 12

3 years ago
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
(Assignee)

Updated

3 years ago
Flags: needinfo?(duan.xiaodong)

Comment 13

3 years ago
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
Flags: needinfo?(duan.xiaodong)

Comment 14

3 years ago
Created attachment 8547385 [details]
log_switch2videomode.txt
(Assignee)

Comment 15

3 years ago
Hi Xiaodong:
great information , looks you blocking in waiting mDisplayLock.lock.
can you keep trace which thread holding mDisplayLock.lock?
thanks
Flags: needinfo?(duan.xiaodong)
(Assignee)

Comment 16

3 years ago
Hi Xiaodong:
any update?
thanks

Comment 17

2 months ago
Firefox OS is not being worked on
Status: NEW → RESOLVED
Last Resolved: 2 months ago
Resolution: --- → WONTFIX
You need to log in before you can comment on or make changes to this bug.