burst mode capture and snapshot time elapse 分析

A :

I tested busrt mode capture in  "burst lenth = 5", "burst FPS =5" and "picture size = VGA".  We can analysis time comsuming from the key log as below:

 

V/camera (2181): mAutoFocusTime = 976ms       // auto focus takes 976ms at first.

I/CameraHardware( 2175): int android::CameraHardware::previewThreadWrapper(): preview is waiting
D/CameraHardware( 2175): BC, line:2228, BCEn:1, BCReq:5, BCCur:1
D/CameraHardware( 2175): BC, int android::CameraHardware::burstCaptureHandle() :start
D/IntelCamera( 2175): Does not using the configuration file
V/camera  ( 2181): mShutterLag = 602ms                    // mShutterLag = ShutterCallbacktime - mCaptureStart time. here it means shutter first frame spend 602 ms. 
E/cip_VorbisDec( 2175): UMCAudioDecoder::read mSource->read error -1004, considering end of stream.
D/CameraHardware( 2175):  getParameters
D/CameraHardware( 2175):  getParameters
V/camera  ( 2181): mShutterToPostViewCallbackTime = 71ms     //mShutterToPostViewCallbackTime = mPostViewPictureCallbackTime - mShutterCallbackTime,  here it means process the thumbnail of first frame spend 71ms.
D/ALSAModule( 2175): open called for devices 00000002 in mode 0...
D/libmfldadvci( 2175): IOCTL Get aperture failed: -1
D/JpegEncoder( 2175): Exif start
D/JpegEncoder( 2175): Exif End
I/ALSAModule( 2175): Initialized ALSA PLAYBACK device AndroidPlayback_Speaker_normal
V/camera  ( 2181): mShutterLag = 1010ms             // here it means shutter the first 2 frames spend 1010ms.
D/CameraHardware( 2175):  getParameters
E/cip_VorbisDec( 2175): UMCAudioDecoder::read mSource->read error -1004, considering end of stream.
D/CameraHardware( 2175):  getParameters
V/camera  ( 2181): mShutterToPostViewCallbackTime = 87ms
D/libmfldadvci( 2175): IOCTL Get aperture failed: -1
D/JpegEncoder( 2175): Exif start
D/JpegEncoder( 2175): Exif End
V/camera  ( 2181): mShutterLag = 1407ms
E/cip_VorbisDec( 2175): UMCAudioDecoder::read mSource->read error -1004, considering end of stream.
D/CameraHardware( 2175):  getParameters
D/CameraHardware( 2175):  getParameters
V/camera  ( 2181): mShutterToPostViewCallbackTime = 53ms
D/libmfldadvci( 2175): IOCTL Get aperture failed: -1
D/JpegEncoder( 2175): Exif start
D/JpegEncoder( 2175): Exif End
V/camera  ( 2181): mShutterLag = 1813ms
E/cip_VorbisDec( 2175): UMCAudioDecoder::read mSource->read error -1004, considering end of stream.
D/CameraHardware( 2175):  getParameters
D/CameraHardware( 2175):  getParameters
V/camera  ( 2181): mShutterToPostViewCallbackTime = 57ms
D/libmfldadvci( 2175): IOCTL Get aperture failed: -1
D/JpegEncoder( 2175): Exif start
D/JpegEncoder( 2175): Exif End
V/camera  ( 2181): mShutterLag = 2215ms          //here it means shutter all 5 frames spend 2215ms. 
E/cip_VorbisDec( 2175): UMCAudioDecoder::read mSource->read error -1004, considering end of stream.
D/CameraHardware( 2175):  getParameters
D/CameraHardware( 2175):  getParameters

D/CameraHardware( 2175): BC, line:2179, send the 2, compressed jpeg image
V/camera  ( 2181): mShutterToPostViewCallbackTime = 55ms

V/camera  ( 2181): mPictureDisplayedToJpegCallbackTime = 1ms      // mPictureDisplayedToJpegCallbackTime = mJpegPictureCallbackTime - mPostviewPictureCallbackTime
D/CameraHardware( 2175): BC, line:2228, BCEn:1, BCReq:5, BCCur:2
D/CameraHardware( 2175): BC, int android::CameraHardware::burstCaptureHandle() :start
D/CameraHardware( 2175): BC, line:2179, send the 0, compressed jpeg image
D/libmfldadvci( 2175): IOCTL Get aperture failed: -1
D/JpegEncoder( 2175): Exif start
D/JpegEncoder( 2175): Exif End
D/CameraHardware( 2175): BC, line:1829, leave compressThread
V/camera  ( 2181): mPictureDisplayedToJpegCallbackTime = 141ms    // here it means displaying first thumbnail picture spend 141ms
D/CameraHardware( 2175): BC, line:2228, BCEn:1, BCReq:5, BCCur:3
D/CameraHardware( 2175): BC, int android::CameraHardware::burstCaptureHandle() :start
D/CameraHardware( 2175): BC, line:2179, send the 4, compressed jpeg image
D/dalvikvm( 1599): GC_CONCURRENT freed 395K, 12% free 5770K/6535K, paused 2ms+1ms
D/dalvikvm( 2181): GC_CONCURRENT freed 1826K, 21% free 8022K/10119K, paused 2ms+1ms
V/camera  ( 2181): mPictureDisplayedToJpegCallbackTime = 315ms
D/CameraHardware( 2175): BC, line:2228, BCEn:1, BCReq:5, BCCur:4
D/CameraHardware( 2175): BC, int android::CameraHardware::burstCaptureHandle() :start
D/CameraHardware( 2175): BC, line:2179, send the 1, compressed jpeg image
V/camera  ( 2181): mPictureDisplayedToJpegCallbackTime = 454ms
D/CameraHardware( 2175): BC, line:2228, BCEn:1, BCReq:5, BCCur:5
D/CameraHardware( 2175): BC, int android::CameraHardware::burstCaptureHandle() :start
D/CameraHardware( 2175): BC, line:2179, send the 3, compressed jpeg image
D/dalvikvm( 2181): GC_CONCURRENT freed 728K, 21% free 8066K/10119K, paused 3ms+1ms
V/camera  ( 2181): mPictureDisplayedToJpegCallbackTime = 611ms
D/dalvikvm( 1599): GC_CONCURRENT freed 483K, 12% free 5793K/6535K, paused 3ms+2ms
D/CameraHardware( 2175):  getParameters

From the log, we can see 5 frames are evenly distributed, we also didn't add time adjust to burst mode capture.

B.

So we can conclude from the log:

total burst mode capture time  =  autofocus time(976ms)  +   mShutterLag(2215ms) +  mShutterToPostViewCallbackTime(71 + 87 + 53 + 57 + 55 ms) +  mPictureDisplayedToJpegCallbackTime(611ms)

                                                      = 4125ms

 

The other factor is picture size:  the biger picture size will take more time, here we tested base on VGA picture size.

C.

1. From the log.

Each frame's capture time = the mShutterLag latancy time(400ms) +  mShutterToPostViewCallbackTime(50ms) + mPictureDisplayedToJpegCallbackTime latancy time(150ms)   = 600ms.

totally time elapse = mAutoFocusTime(900ms) + Each frame's capture time(600ms) x 5 = 3900ms

the actually elapse time is also about 4s.

This is for VGA picture size. it will be longer with larger picture size.

2.  I also tested 8M picture size.

Each frame's capture time = the mShutterLag latancy time(400ms) + mShutterToPostViewCallbackTime(50ms) + mPictureDisplayedToJpegCallbackTime latancy time (1800ms) = 2.25s

totally time elapse = mAutoFocusTime(987ms) + Each frame's capture time(2250ms) x 5 = 12237ms =12.237s

the actually elapse time is also about 12s by my count.

It's really long.. 

3. This time makeup also suit for single picture snapshot. I tested by taking 1 picture on VGA picture size:

totally time elapse = mAutoFocusTime(689ms) + mShutterLag(730ms) + mShutterToPostViewCallbackTime(150ms) + mPictureDisplayedToJpegCallbackTime(416ms)  + mJpegCallbackFinishTime(927ms)

                            = 2912 ms.

the actually elapse time is also about 2.5s - 3s.

4. tested by taking 1 picture on 8M picture size:

totally time elapse = mAutoFocusTime(1009ms) + mShutterLag(867ms) + mShutterToPostViewCallbackTime(166ms) + mPictureDisplayedToJpegCallbackTime(1800ms)  + mJpegCallbackFinishTime(1098ms)

                            =  4940ms.

the actually elapse time is also about 5s.

D.

I found the front camera capture performance is much better than rear camera. It's because it's SOC camera, needn't 3A related process.

 

I defined PERFORMANCE_TUNING in libcamera.so and get the time consuming log as below:

 

1. Let's take normal snapshot for e.g:

 

a. VGA picture size:

 

 mAutoFocusTime = 970ms    //Auto Focus always take about 1s for rear camera, and just about 100ms for front camera. I think it's the first bottleneck. it should be less than 300ms according to PRD.
V/camera  ( 3101): startPreview
D/CameraHardware( 3966): stop preview: 12ms
D/CameraHardware( 3966): start picture thead 12ms
D/CameraHardware( 3966): snapshot start 98ms
D/CameraHardware( 3966): take first frame 367ms
D/CameraHardware( 3966): take second frame 169ms
D/CameraHardware( 3966): Postview 12ms
D/CameraHardware( 3966): snapshot stop 25ms
D/CameraHardware( 3966): Jpeg encoded 113ms     // for VGA picture size, it only takes about 100ms.
D/CameraHardware( 3966): start preview 1132ms      // it always take 1000ms from closing picturethread to restart previewthread, I think it's the second  bottleneck.
D/CameraHardware( 3966): Start normal preview

 

b. 8M picture size

 

mAutoFocusTime = 1009ms
V/camera  ( 3101): startPreview
D/CameraHardware( 3966): stop preview: 445ms
D/CameraHardware( 3966): start picture thead 3ms
D/CameraHardware( 3966): snapshot start 148ms
D/CameraHardware( 3966): take first frame 350ms
D/CameraHardware( 3966): take second frame 94ms
D/CameraHardware( 3966): Postview 3ms
D/CameraHardware( 3966): snapshot stop 16ms
D/CameraHardware( 3966): Jpeg encoded 1455ms   // for 8M picture size, it take about 1500ms - 1900ms for encoding. I think it's the third bottleneck. Maybe hw jpeg encoder will decrease this one. 
D/CameraHardware( 3966): start preview 50ms
I/CameraHardware( 3966): int android::CameraHardware::aeAfAwbThread(): previewaeafawb return from wait
D/CameraHardware( 3966): Start normal preview

 

2. For burst mode capture is almost the same.  Jpeg encoding time will x5, so for 8M picture size, it will take about 12s to complete burst mode capture.

 

I think uneven capture frame interval has no significant. Because the interval differences are tiny. From the code, it will be influenced by burstCaptureSkipReqBufs() and mCamera->toRGB565().