camera自动升级失败问题

2024-01-09 22:14:22

 

camera自动升级过程中失败:

只有自动升级时才会失败，手动点击升级时是正常的。

 

 

自动升级和手动升级调用的接口是完全一样的，并且都是通过EventBus 接收升级的event调用同一段函数进行处理，所以函数调用上没有任何区别，显然不是代码逻辑的错误。

通过查看失败的log发现connect camera时超时了：

camera自动升级失败问题

 

 折叠源码

...

 

UsbInterface[mId=1,mAlternateSetting=9,mName=null,mClass=14,mSubclass=2,mProtocol=0,mEndpoints=[

09-21 23:58:38.434  4991  5066 I GeneralHidUpgrade: UsbEndpoint[mAddress=129,mAttributes=5,mMaxPacketSize=3040,mInterval=1]]

09-21 23:58:38.434  4991  5066 I GeneralHidUpgrade: UsbInterface[mId=1,mAlternateSetting=10,mName=null,mClass=14,mSubclass=2,mProtocol=0,mEndpoints=[

09-21 23:58:38.434  4991  5066 I GeneralHidUpgrade: UsbEndpoint[mAddress=129,mAttributes=5,mMaxPacketSize=5056,mInterval=1]]

09-21 23:58:38.434  4991  5066 I GeneralHidUpgrade: UsbInterface[mId=1,mAlternateSetting=11,mName=null,mClass=14,mSubclass=2,mProtocol=0,mEndpoints=[

09-21 23:58:38.434  4991  5066 I GeneralHidUpgrade: UsbEndpoint[mAddress=129,mAttributes=5,mMaxPacketSize=5116,mInterval=1]]]]

09-21 23:58:38.435  1926  1926 I Gralloc1Allocator: allocate createDescriptor desc: 0x734ae56000

09-21 23:58:38.436  1926  1926 I gralloc : mali_gralloc_select_format: req_format=0x00000001 req_fmt_mapped=0x1 internal_format=0x300000001 usage=0xb00

09-21 23:58:38.438  4991  5067 V CameraDeviceApi: Connect Device

09-21 23:58:38.449  1927  2111 I vndksupport: sphal namespace is not configured for this process. Loading /vendor/lib64/hw/gralloc.bigfish.so from the current namespace instead.

09-21 23:58:38.458  4991  5067 I CameraApi: BcdDevice : 9910

09-21 23:58:38.458  4991  5067 D UsbDeviceConnectionJNI: close

09-21 23:58:38.466  2234  2332 I WindowManager: attrs is fullscreen. Set mForceStatusBar as false.

09-21 23:58:38.466  1927  2111 I vndksupport: sphal namespace is not configured for this process. Loading /vendor/lib64/hw/gralloc.bigfish.so from the current namespace instead.

09-21 23:58:38.476  4991  4991 I CameraApi: on Connect: TC01-CAM

09-21 23:58:38.482  1927  2111 I vndksupport: sphal namespace is not configured for this process. Loading /vendor/lib64/hw/gralloc.bigfish.so from the current namespace instead.

09-21 23:58:38.500  4991  5063 I libUVCCamera: [5063*sp_usb_UVCCamera.cpp:146:nativeConnect]:** vid=0x1bcf, pid=0x2680, busnum = 1, devAddr=5, usbfs_str=/dev/bus/usb, fd = 87

09-21 23:58:38.500  4991  5063 I libUVCCamera: [5063*sp_usb_UVCCamera.cpp:149:nativeConnect]:..

09-21 23:58:38.500  4991  5063 I libUVCCamera: [5063*sp_UVCCamera.cpp:129:connect]:connecting 1bcf:2680...

09-21 23:58:38.500  4991  5063 I libUVCCamera: [5063*sp_UVCCamera.cpp:137:connect]:sp_uvc_init2

09-21 23:58:38.500  4991  5063 I libUVCCamera: [5063*sp_UVCCamera.cpp:141:connect]:sp_uvc_init2 finished

09-21 23:58:38.500  4991  5063 I libUVCCamera: [5063*sp_UVCCamera.cpp:151:connect]:connecting 1bcf:2680...

09-21 23:58:38.500  4991  5063 I libUVCCamera: [5063*sp_UVCCamera.cpp:156:connect]:>>> sp_uvc_find_device2

09-21 23:58:38.501  4991  5063 I libUVCCamera: [5063*sp_UVCCamera.cpp:161:connect]:<<< sp_uvc_find_device2

09-21 23:58:38.507  2234  2359 I EventHub: Removing device TC01-CAM due to epoll hang-up event.

09-21 23:58:38.507  2234  2359 I EventHub: Removed device: path=/dev/input/event6 name=TC01-CAM id=7 fd=123 classes=0x80000001

09-21 23:58:38.510  2234  2359 I InputReader: Device removed: id=7, name='TC01-CAM', sources=0x00000101

09-21 23:58:38.511  2234  2359 I EventHub: Removing device '/dev/input/event6' due to inotify event

09-21 23:58:38.512  2234  2358 I WindowManager: attrs is fullscreen. Set mForceStatusBar as false.

09-21 23:58:38.513  3017  3218 E mcuapimanagerjni: check_mcutouch_input_count[1916] open /sys/devices/virtual/swmcutouch/swmcutouch/inputCnt failed!

09-21 23:58:38.526  2062  2062 I <-host-11: type=1400 audit(0.0:975): avc: denied { read } for path="socket:[41786]" dev="sockfs" ino=41786 scontext=u:r:su:s0 tcontext=u:r:su:s0 tclass=tcp_socket permissive=1

09-21 23:58:38.526  2062  2062 I ->host-11: type=1400 audit(0.0:976): avc: denied { write } for path="socket:[41786]" dev="sockfs" ino=41786 scontext=u:r:su:s0 tcontext=u:r:su:s0 tclass=tcp_socket permissive=1

09-21 23:58:38.926  3728  3851 D LayerManager: LayerSweeper [run] working……

09-21 23:58:39.161  2437  2729 D <tvapi> : [TVApiSystemSignalImpl.java::run:127:2437]: Jacon_Li isNoSignalSleepSupport false

09-21 23:58:39.162  2437  2729 D <tvapi> : [TVApiSystemSignalImpl.java::ResetTimer:94:2437]: ResetTimer all source ======= mNoSignalNotifyTime = 300

09-21 23:58:39.403  4991  4991 I CameraApi: on Attach: null

09-21 23:58:39.412  2558  3405 D HiRMService_Performance: topActivity pkg : com.seewo.studystation.launcher, class : com.seewo.studystation.login.ui.activity.LoginMainActivity

09-21 23:58:39.428  3728  3851 D LayerManager: LayerSweeper [run] working……

09-21 23:58:39.513  3017  3218 E mcuapimanagerjni: check_mcutouch_input_count[1916] open /sys/devices/virtual/swmcutouch/swmcutouch/inputCnt failed!

09-21 23:58:39.929  3728  3851 D LayerManager: LayerSweeper [run] working……

09-21 23:58:40.161  2437  2729 D <tvapi> : [TVApiSystemSignalImpl.java::run:127:2437]: Jacon_Li isNoSignalSleepSupport false

09-21 23:58:40.161  2437  2729 D <tvapi> : [TVApiSystemSignalImpl.java::ResetTimer:94:2437]: ResetTimer all source ======= mNoSignalNotifyTime = 300

09-21 23:58:40.413  2558  3405 D HiRMService_Performance: topActivity pkg : com.seewo.studystation.launcher, class : com.seewo.studystation.login.ui.activity.LoginMainActivity

09-21 23:58:40.431  3728  3851 D LayerManager: LayerSweeper [run] working……

09-21 23:58:40.462  4991  4996 I zygote64: Do partial code cache collection, code=55KB, data=49KB

09-21 23:58:40.463  4991  4996 I zygote64: After code cache collection, code=55KB, data=49KB

09-21 23:58:40.463  4991  4996 I zygote64: Increasing code cache capacity to 256KB

09-21 23:58:40.514  3017  3218 E mcuapimanagerjni: check_mcutouch_input_count[1916] open /sys/devices/virtual/swmcutouch/swmcutouch/inputCnt failed!

09-21 23:58:40.933  3728  3851 D LayerManager: LayerSweeper [run] working……

09-21 23:58:41.161  2437  2729 D <tvapi> : [TVApiSystemSignalImpl.java::run:127:2437]: Jacon_Li isNoSignalSleepSupport false

09-21 23:58:41.162  2437  2729 D <tvapi> : [TVApiSystemSignalImpl.java::ResetTimer:94:2437]: ResetTimer all source ======= mNoSignalNotifyTime = 300

09-21 23:58:41.304  1920  2258 D audio_hal: out(0xe79030e0) do_out_standby

09-21 23:58:41.304  1920  2258 D audio_hal: pcm_close card:device(hw:0:0)

09-21 23:58:41.307  2234  2245 D PowerManagerService: releaseWakeLockInternal: lock=201055943 [AudioMix], flags=0x0

09-21 23:58:41.307  2234  2245 D PowerManagerNotifier: onWakeLockReleased: flags=1, tag="AudioMix", packageName=audioserver, ownerUid=1041, ownerPid=0, workSource=null

09-21 23:58:41.307  2234  2245 D PowerManagerService: updateWakeLockSummaryLocked: mWakefulness=Awake, mWakeLockSummary=0x0

09-21 23:58:41.307  2234  2245 D PowerManagerService: updateUserActivitySummaryLocked: mWakefulness=Awake, mUserActivitySummary=0x1, nextTimeout=864424194 (in 863989617 ms)

09-21 23:58:41.307  2234  2245 D PowerManagerService: updateDisplayPowerStateLocked: mDisplayReady=true, policy=3, mWakefulness=1, mWakeLockSummary=0x0, mUserActivitySummary=0x1, mBootCompleted=true, mScreenBrightnessBoostInProgress=false, mIsVrModeEnabled= false, sQuiescent=false

09-21 23:58:41.414  2558  3405 D HiRMService_Performance: topActivity pkg : com.seewo.studystation.launcher, class : com.seewo.studystation.login.ui.activity.LoginMainActivity

09-21 23:58:41.435  3728  3851 D LayerManager: LayerSweeper [run] working……

09-21 23:58:41.515  3017  3218 E mcuapimanagerjni: check_mcutouch_input_count[1916] open /sys/devices/virtual/swmcutouch/swmcutouch/inputCnt failed!

09-21 23:58:41.937  3728  3851 D LayerManager: LayerSweeper [run] working……

09-21 23:58:42.162  2437  2729 D <tvapi> : [TVApiSystemSignalImpl.java::run:127:2437]: Jacon_Li isNoSignalSleepSupport false

09-21 23:58:42.163  2437  2729 D <tvapi> : [TVApiSystemSignalImpl.java::ResetTimer:94:2437]: ResetTimer all source ======= mNoSignalNotifyTime = 300

09-21 23:58:42.415  2558  3405 D HiRMService_Performance: topActivity pkg : com.seewo.studystation.launcher, class : com.seewo.studystation.login.ui.activity.LoginMainActivity

09-21 23:58:42.439  3728  3851 D LayerManager: LayerSweeper [run] working……

09-21 23:58:42.480  4147  4233 D awcn.DefaultHeartbeatImpl: |[seq:25836056.AWCN10_1] heartbeat session:Session@[25836056.AWCN10_1|spdy_0rtt_open]

09-21 23:58:42.480  4147  4233 D awcn.TnetSpdySession: |[seq:25836056.AWCN10_1] ping host:https://acs4public.m.taobao.com thread:AWCN Scheduler1

09-21 23:58:42.480  4147  4233 D awcn.TnetSpdySession: |[seq:25836056.AWCN10_1] https://acs4public.m.taobao.com submit ping ms:45091 force:true

09-21 23:58:42.480  4147  4233 D awcn.DefaultHeartbeatImpl: |[seq:25836056.AWCN10_1] reSchedule session:Session@[25836056.AWCN10_1|spdy_0rtt_open] delay:45091

09-21 23:58:42.516  3017  3218 E mcuapimanagerjni: check_mcutouch_input_count[1916] open /sys/devices/virtual/swmcutouch/swmcutouch/inputCnt failed!

09-21 23:58:42.528  4147  4244 I awcn.TnetSpdySession: |[seq:25836056.AWCN10_1] ping receive Host:https://acs4public.m.taobao.com id:3

09-21 23:58:42.941  3728  3851 D LayerManager: LayerSweeper [run] working……

09-21 23:58:43.162  2437  2729 D <tvapi> : [TVApiSystemSignalImpl.java::run:127:2437]: Jacon_Li isNoSignalSleepSupport false

09-21 23:58:43.163  2437  2729 D <tvapi> : [TVApiSystemSignalImpl.java::ResetTimer:94:2437]: ResetTimer all source ======= mNoSignalNotifyTime = 300

09-21 23:58:43.416  2558  3405 D HiRMService_Performance: topActivity pkg : com.seewo.studystation.launcher, class : com.seewo.studystation.login.ui.activity.LoginMainActivity

09-21 23:58:43.442  3728  3851 D LayerManager: LayerSweeper [run] working……

09-21 23:58:43.517  3017  3218 E mcuapimanagerjni: check_mcutouch_input_count[1916] open /sys/devices/virtual/swmcutouch/swmcutouch/inputCnt failed!

09-21 23:58:43.943  3728  3851 D LayerManager: LayerSweeper [run] working……

09-21 23:58:44.135  4991  4996 I zygote64: Compiler allocated 6MB to compile void android.view.ViewRootImpl.performTraversals()

09-21 23:58:44.162  2437  2729 D <tvapi> : [TVApiSystemSignalImpl.java::run:127:2437]: Jacon_Li isNoSignalSleepSupport false

09-21 23:58:44.163  2437  2729 D <tvapi> : [TVApiSystemSignalImpl.java::ResetTimer:94:2437]: ResetTimer all source ======= mNoSignalNotifyTime = 300

09-21 23:58:44.417  2558  3405 D HiRMService_Performance: topActivity pkg : com.seewo.studystation.launcher, class : com.seewo.studystation.login.ui.activity.LoginMainActivity

09-21 23:58:44.445  3728  3851 D LayerManager: LayerSweeper [run] working……

09-21 23:58:44.519  3017  3218 E mcuapimanagerjni: check_mcutouch_input_count[1916] open /sys/devices/virtual/swmcutouch/swmcutouch/inputCnt failed!

09-21 23:58:44.947  3728  3851 D LayerManager: LayerSweeper [run] working……

09-21 23:58:45.162  2437  2729 D <tvapi> : [TVApiSystemSignalImpl.java::run:127:2437]: Jacon_Li isNoSignalSleepSupport false

09-21 23:58:45.163  2437  2729 D <tvapi> : [TVApiSystemSignalImpl.java::ResetTimer:94:2437]: ResetTimer all source ======= mNoSignalNotifyTime = 300

09-21 23:58:45.418  2558  3405 D HiRMService_Performance: topActivity pkg : com.seewo.studystation.launcher, class : com.seewo.studystation.login.ui.activity.LoginMainActivity

09-21 23:58:45.448  3728  3851 D LayerManager: LayerSweeper [run] working……

09-21 23:58:45.520  3017  3218 E mcuapimanagerjni: check_mcutouch_input_count[1916] open /sys/devices/virtual/swmcutouch/swmcutouch/inputCnt failed!

09-21 23:58:45.638  1935  2843 W HiMW@hi_mw_logic_media_player.cpp: [35m[printSignalStatus:167] [no signal] there is no video playing, count = 8500.[0m

09-21 23:58:45.950  3728  3851 D LayerManager: LayerSweeper [run] working……

09-21 23:58:46.163  2437  2729 D <tvapi> : [TVApiSystemSignalImpl.java::run:127:2437]: Jacon_Li isNoSignalSleepSupport false

09-21 23:58:46.164  2437  2729 D <tvapi> : [TVApiSystemSignalImpl.java::ResetTimer:94:2437]: ResetTimer all source ======= mNoSignalNotifyTime = 300

09-21 23:58:46.418  2558  3405 D HiRMService_Performance: topActivity pkg : com.seewo.studystation.launcher, class : com.seewo.studystation.login.ui.activity.LoginMainActivity

09-21 23:58:46.451  3728  3851 D LayerManager: LayerSweeper [run] working……

09-21 23:58:46.521  3017  3218 E mcuapimanagerjni: check_mcutouch_input_count[1916] open /sys/devices/virtual/swmcutouch/swmcutouch/inputCnt failed!

09-21 23:58:46.953  3728  3851 D LayerManager: LayerSweeper [run] working……

09-21 23:58:47.163  2437  2729 D <tvapi> : [TVApiSystemSignalImpl.java::run:127:2437]: Jacon_Li isNoSignalSleepSupport false

09-21 23:58:47.163  2437  2729 D <tvapi> : [TVApiSystemSignalImpl.java::ResetTimer:94:2437]: ResetTimer all source ======= mNoSignalNotifyTime = 300

09-21 23:58:47.419  2558  3405 D HiRMService_Performance: topActivity pkg : com.seewo.studystation.launcher, class : com.seewo.studystation.login.ui.activity.LoginMainActivity

09-21 23:58:47.454  3728  3851 D LayerManager: LayerSweeper [run] working……

09-21 23:58:47.522  3017  3218 E mcuapimanagerjni: check_mcutouch_input_count[1916] open /sys/devices/virtual/swmcutouch/swmcutouch/inputCnt failed!

09-21 23:58:47.956  3728  3851 D LayerManager: LayerSweeper [run] working……

09-21 23:58:48.163  2437  2729 D <tvapi> : [TVApiSystemSignalImpl.java::run:127:2437]: Jacon_Li isNoSignalSleepSupport false

09-21 23:58:48.164  2437  2729 D <tvapi> : [TVApiSystemSignalImpl.java::ResetTimer:94:2437]: ResetTimer all source ======= mNoSignalNotifyTime = 300

09-21 23:58:48.420  2558  3405 D HiRMService_Performance: topActivity pkg : com.seewo.studystation.launcher, class : com.seewo.studystation.login.ui.activity.LoginMainActivity

09-21 23:58:48.457  3728  3851 D LayerManager: LayerSweeper [run] working……

09-21 23:58:48.482  4991  5067 E GeneralHidUpgrade: Connect Device Timeout!

09-21 23:58:48.482  4991  5067 D UpgradeDeviceHelper: onFailed :deviceupgradeapi.exception.DeviceNoConnectException: Device Not Connected!

09-21 23:58:48.484  4991  5067 I MAXHUB-debug_upgrade: │ [RxCachedThreadScheduler-5] onUpgradeStatus

 

...

 

而这个超时错误是代码中写定的:

@Override

public void connectDevice(UsbDevice device) throws IOException {

    Log.v(TAG, "Connect Device");

    Boolean result = Single

            .<Boolean>create(emitter -> CameraApi.i(mcotext).connectDevice(device,

                    () -> emitter.onSuccess(true),

                    () -> emitter.onError(new IOException("Connect Device Fail!"))))

            .timeout(10, TimeUnit.SECONDS, Single.just(false))

            .blockingGet();

    if (!result) {

        throw new IOException("Connect Device Timeout!");

    }

}

超时10s自动报错退出。

从   09-21 23:58:38.438  4991  5067 V CameraDeviceApi: Connect Device

到   09-21 23:58:48.482  4991  5067 E GeneralHidUpgrade: Connect Device Timeout!

确实是到了10s的超时时间。所以会不会是超时时间太短了呢？？

紧接着就把超时时间改成了1min···········    然后测试果然可以，虽然挺长时间升级进度条没有反应，但是时间长一些会升级成功的。

 

 

但是······

仍有概率性的超时失败，1min的超时时间都有问题，那只能继续往下找了。

 

那么是什么原原因造成连接超时的呢？这就成了解决本次异常的关键了。没有任何思路，接着看代码。

上面的connectDevice会调用到下面的方法：

@Override

public void onConnect(final UsbDevice device, final CUSBListener.UsbControlBlock ctrlBlock, final boolean createNew) {

    Log.i(TAG, "on Connect: " + (device == null? "null": device.getProductName()));

    if (mSpcaJNI != null) {

        mSpcaJNI.destroy();

    }

    mSpcaJNI = new SpcaJNI();

    mCompositeDisposable.add(Single.just(true)

            .observeOn(Schedulers.io())

            .subscribe(x -> {

                int ret = mSpcaJNI.open(ctrlBlock);   //  调用到这里

                if (ret != 0) {

                    // no camera opened.

                    Log.e(TAG, "Open Device fail!");

                    mSpcaJNI.destroy();

                    mOnConnectFail.run();

                } else {

                    mOnConnected.run();

                }

            }));

}

之后调用到

SpcaJNI的方法:

public int open(UsbControlBlock ctrlBlock) {

    this.mCtrlBlock = ctrlBlock;

    int result = this.nativeConnect(this.mNativePtr, this.mCtrlBlock.getVenderId(), this.mCtrlBlock.getProductId(), this.mCtrlBlock.getFileDescriptor(), this.mCtrlBlock.getBusNum(), this.mCtrlBlock.getDevNum(), this.getUSBFSName(this.mCtrlBlock));

    if (this.mNativePtr != 0L && TextUtils.isEmpty(this.mSupportedSize)) {

        this.mSupportedSize = nativeGetSupportedSize(this.mNativePtr);

    }

 

    nativeSetPreviewSize(this.mNativePtr, 640, 480, 1, 30, 1, 2.0F);

    return result;

}

这里的this.nativeConnect方法是个调用C++的native方法：

private final native int nativeConnect(long var1, int var3, int var4, int var5, int var6, int var7, String var8);

而native被供应商封装成so库了，所以给调试带来了很大的麻烦

所以继续看log：

09-21 23:58:38.476  4991  4991 I CameraApi: on Connect: TC01-CAM

09-21 23:58:38.482  1927  2111 I vndksupport: sphal namespace is not configured for this process. Loading /vendor/lib64/hw/gralloc.bigfish.so from the current namespace instead.

09-21 23:58:38.500  4991  5063 I libUVCCamera: [5063*sp_usb_UVCCamera.cpp:146:nativeConnect]:** vid=0x1bcf, pid=0x2680, busnum = 1, devAddr=5, usbfs_str=/dev/bus/usb, fd = 87

09-21 23:58:38.500  4991  5063 I libUVCCamera: [5063*sp_usb_UVCCamera.cpp:149:nativeConnect]:..

09-21 23:58:38.500  4991  5063 I libUVCCamera: [5063*sp_UVCCamera.cpp:129:connect]:connecting 1bcf:2680...

09-21 23:58:38.500  4991  5063 I libUVCCamera: [5063*sp_UVCCamera.cpp:137:connect]:sp_uvc_init2

09-21 23:58:38.500  4991  5063 I libUVCCamera: [5063*sp_UVCCamera.cpp:141:connect]:sp_uvc_init2 finished

09-21 23:58:38.500  4991  5063 I libUVCCamera: [5063*sp_UVCCamera.cpp:151:connect]:connecting 1bcf:2680...

09-21 23:58:38.500  4991  5063 I libUVCCamera: [5063*sp_UVCCamera.cpp:156:connect]:>>> sp_uvc_find_device2

09-21 23:58:38.501  4991  5063 I libUVCCamera: [5063*sp_UVCCamera.cpp:161:connect]:<<< sp_uvc_find_device2

09-21 23:58:38.507  2234  2359 I EventHub: Removing device TC01-CAM due to epoll hang-up event.

09-21 23:58:38.507  2234  2359 I EventHub: Removed device: path=/dev/input/event6 name=TC01-CAM id=7 fd=123 classes=0x80000001

09-21 23:58:38.510  2234  2359 I InputReader: Device removed: id=7, name='TC01-CAM', sources=0x00000101

09-21 23:58:38.511  2234  2359 I EventHub: Removing device '/dev/input/event6' due to inotify event

 

发现升级失败超时的时候就是这个地方没有继续下去了，从打印来看貌似是个第三方库，所以就去全球最大同性交友网站github寻找了一番，让我找到了一个极其类似的代码： https://github.com/LukeSong07/urtc_libuvccamera.git

上面的log应该是这段代码打印的:

UVCCamera.cpp

//======================================================================

/**

 * カメラへ接続する

 */

int UVCCamera::connect(int vid, int pid, int fd, int busnum, int devaddr, const char *usbfs) {

    ENTER();

    uvc_error_t result = UVC_ERROR_BUSY;

    if (!mDeviceHandle && fd) {

        if (mUsbFs)

            free(mUsbFs);

        mUsbFs = strdup(usbfs);

        if (UNLIKELY(!mContext)) {

            result = uvc_init2(&mContext, NULL, mUsbFs);

//          libusb_set_debug(mContext->usb_ctx, LIBUSB_LOG_LEVEL_DEBUG);

            if (UNLIKELY(result < 0)) {

                LOGD("failed to init libuvc");

                RETURN(result, int);

            }

        }

        // カメラ機能フラグをクリア

        clearCameraParams();

        fd = dup(fd);

        // 指定したvid,idを持つデバイスを検索, 見つかれば0を返してmDeviceに見つかったデバイスをセットする(既に1回uvc_ref_deviceを呼んである)

//      result = uvc_find_device2(mContext, &mDevice, vid, pid, NULL, fd);

        result = uvc_get_device_with_fd(mContext, &mDevice, vid, pid, NULL, fd, busnum, devaddr);

        if (LIKELY(!result)) {

            // カメラのopen処理

            result = uvc_open(mDevice, &mDeviceHandle);                        // 怀疑 发生阻塞的地方

            if (LIKELY(!result)) {

                // open出来た時

#if LOCAL_DEBUG

                uvc_print_diag(mDeviceHandle, stderr);

#endif

                mFd = fd;

                mStatusCallback = new UVCStatusCallback(mDeviceHandle);

                mButtonCallback = new UVCButtonCallback(mDeviceHandle);

                mPreview = new UVCPreview(mDeviceHandle);

            } else {

                // open出来なかった時

                LOGE("could not open camera:err=%d", result);

                uvc_unref_device(mDevice);

//              SAFE_DELETE(mDevice);   // 参照カウンタが0ならuvc_unref_deviceでmDeviceがfreeされるから不要 XXX クラッシュ, 既に破棄されているのを再度破棄しようとしたからみたい

                mDevice = NULL;

                mDeviceHandle = NULL;

                close(fd);

            }

        } else {

            LOGE("could not find camera:err=%d", result);

            close(fd);

        }

    } else {

        // カメラが既にopenしている時

        LOGW("camera is already opened. you should release first");

    }

    RETURN(result, int);

}

在sp_uvc_find_device2之后log就没有更新了，所以就猜测在调用uvc_open时发生了阻塞，造成一直等待在这里

device.c

/** @brief Open a UVC device

 * @ingroup device

 *

 * @param dev Device to open

 * @param[out] devh Handle on opened device

 * @return Error opening device or SUCCESS

 */

uvc_error_t uvc_open(uvc_device_t *dev, uvc_device_handle_t **devh) {

    uvc_error_t ret;

    struct libusb_device_handle *usb_devh;

    uvc_device_handle_t *internal_devh;

    struct libusb_device_descriptor desc;

 

    UVC_ENTER();

 

    ret = libusb_open(dev->usb_dev, &usb_devh);

    UVC_DEBUG("libusb_open() = %d", ret);

 

    if (UNLIKELY(ret != UVC_SUCCESS)) {

        UVC_EXIT(ret);

        return ret;

    }

 

    uvc_ref_device(dev);

 

    internal_devh = calloc(1, sizeof(*internal_devh));

    internal_devh->dev = dev;

    internal_devh->usb_devh = usb_devh;

    internal_devh->reset_on_release_if = 0;  // XXX

    ret = uvc_get_device_info(dev, &(internal_devh->info));

    pthread_mutex_init(&internal_devh->status_mutex, NULL);  // XXX saki

 

    if (UNLIKELY(ret != UVC_SUCCESS))

        goto fail2; // uvc_claim_if was not called yet and we don't need to call uvc_release_if

#if !UVC_DETACH_ATTACH

    /* enable automatic attach/detach kernel driver on supported platforms in libusb */

    libusb_set_auto_detach_kernel_driver(usb_devh, 1);

#endif

    UVC_DEBUG("claiming control interface %d",

            internal_devh->info->ctrl_if.bInterfaceNumber);

    ret = uvc_claim_if(internal_devh,

            internal_devh->info->ctrl_if.bInterfaceNumber);

    if (UNLIKELY(ret != UVC_SUCCESS))

        goto fail;

 

    libusb_get_device_descriptor(dev->usb_dev, &desc);

    internal_devh->is_isight = (desc.idVendor == 0x05ac && desc.idProduct == 0x8501);

 

    if (internal_devh->info->ctrl_if.bEndpointAddress) {

        UVC_DEBUG("status check transfer:bEndpointAddress=0x%02x", internal_devh->info->ctrl_if.bEndpointAddress);

        internal_devh->status_xfer = libusb_alloc_transfer(0);

        if (UNLIKELY(!internal_devh->status_xfer)) {

            ret = UVC_ERROR_NO_MEM;

            goto fail;

        }

 

        libusb_fill_interrupt_transfer(internal_devh->status_xfer, usb_devh,

                internal_devh->info->ctrl_if.bEndpointAddress,

                internal_devh->status_buf, sizeof(internal_devh->status_buf),

                _uvc_status_callback, internal_devh, 0);

        ret = libusb_submit_transfer(internal_devh->status_xfer);

        UVC_DEBUG("libusb_submit_transfer() = %d", ret);

 

        if (UNLIKELY(ret)) {

            LOGE("device has a status interrupt endpoint, but unable to read from it");

            goto fail;

        }

    } else {

        LOGE("internal_devh->info->ctrl_if.bEndpointAddress is null");

    }

 

    if (dev->ctx->own_usb_ctx && dev->ctx->open_devices == NULL) {

        /* Since this is our first device, we need to spawn the event handler thread */

        uvc_start_handler_thread(dev->ctx);

    }

 

    DL_APPEND(dev->ctx->open_devices, internal_devh);

    *devh = internal_devh;

 

    UVC_EXIT(ret);

 

    return ret;

 

fail:

    uvc_release_if(internal_devh, internal_devh->info->ctrl_if.bInterfaceNumber); // XXX crash, assume when uvc_get_device_info failed.

fail2:

#if !UVC_DETACH_ATTACH

    /* disable automatic attach/detach kernel driver on supported platforms in libusb */

    libusb_set_auto_detach_kernel_driver(usb_devh, 0);

#endif

    libusb_close(usb_devh);

    uvc_unref_device(dev);

    uvc_free_devh(internal_devh);

 

    UVC_EXIT(ret);

 

    return ret;

}

接下来就犯难了，由于供应商对代码进行了修改所以造成行号和log都有变化，上面的开源代码中的log在供应商的so库中并没有打印，所以无法确定哪里发生了阻塞。 只能猜测libusb_open这个方法没有返回了，接着往下看：

core_original.c

/** \ingroup dev

 * Open a device and obtain a device handle. A handle allows you to perform

 * I/O on the device in question.

 *

 * Internally, this function adds a reference to the device and makes it

 * available to you through libusb_get_device(). This reference is removed

 * during libusb_close().

 *

 * This is a non-blocking function; no requests are sent over the bus.

 *

 * \param dev the device to open

 * \param handle output location for the returned device handle pointer. Only

 * populated when the return code is 0.

 * \returns 0 on success

 * \returns LIBUSB_ERROR_NO_MEM on memory allocation failure

 * \returns LIBUSB_ERROR_ACCESS if the user has insufficient permissions

 * \returns LIBUSB_ERROR_NO_DEVICE if the device has been disconnected

 * \returns another LIBUSB_ERROR code on other failure

 */

int API_EXPORTED libusb_open(libusb_device *dev,

    libusb_device_handle **handle)

{

    struct libusb_context *ctx = DEVICE_CTX(dev);

    struct libusb_device_handle *_handle;

    size_t priv_size = usbi_backend->device_handle_priv_size;

    int r;

    usbi_dbg("open %d.%d", dev->bus_number, dev->device_address);

 

    if (!dev->attached) {

        return LIBUSB_ERROR_NO_DEVICE;

    }

 

    _handle = malloc(sizeof(*_handle) + priv_size);

    if (!_handle)

        return LIBUSB_ERROR_NO_MEM;

 

    r = usbi_mutex_init(&_handle->lock, NULL);

    if (r) {

        free(_handle);

        return LIBUSB_ERROR_OTHER;

    }

 

    _handle->dev = libusb_ref_device(dev);

    _handle->auto_detach_kernel_driver = 0;

    _handle->claimed_interfaces = 0;

    memset(&_handle->os_priv, 0, priv_size);

 

    r = usbi_backend->open(_handle);

    if (r < 0) {

        usbi_dbg("open %d.%d returns %d", dev->bus_number, dev->device_address, r);

        libusb_unref_device(dev);

        usbi_mutex_destroy(&_handle->lock);

        free(_handle);

        return r;

    }

 

    usbi_mutex_lock(&ctx->open_devs_lock);

    list_add(&_handle->list, &ctx->open_devs);

    usbi_mutex_unlock(&ctx->open_devs_lock);

    *handle = _handle;

 

    /* At this point, we want to interrupt any existing event handlers so

     * that they realise the addition of the new device's poll fd. One

     * example when this is desirable is if the user is running a separate

     * dedicated libusb events handling thread, which is running with a long

     * or infinite timeout. We want to interrupt that iteration of the loop,

     * so that it picks up the new fd, and then continues. */

    usbi_fd_notification(ctx);

 

    return 0;

}

上面的代码注释透露着一个非常重要的信息"This is a non-blocking function; no requests are sent over the bus."  这是一个非阻塞功能； 没有请求通过总线发送。     但是就是没有及时返回········   这里就开始陷入深深的怀疑人生的时候了。

 

冷静分析:

既然手动升级能够成功，那么代码逻辑上应该是没有问题的，况且自动升级和手动升级的时候都保证了在主线程调用camera升级接口，所以目前已知的点来讲手动和自动升级没有明显区别。又观察手动升级的时候进度条也是等了大概两秒才开始出现的，那么最开始那段操作可能就是耗时操作了。既然是主线程耗时操作很容易导致ANR，所以就去看log，在超时附近寻找ANR的log，但是相当遗憾地没有找到·········   所以ANR估计是不可能的推测了。

 

所以就开始怀疑哪里加锁了？或者任务调度了？或者I/O多路复用造成的阻塞？？

 

加锁这个怀疑对象有一些疑虑，camera也没有其他地方占用为啥要加锁，况且在无法调试so的情况下去看运行时的锁有些困难········   同时缺少各种调试工具 先搁置。

 

再去怀疑由于任务调度进程切换造成的进程阻塞，因为上面讲超时时间改为1min后是有几率能够成功的，并且手动升级的时候也是能够100%成功的，从点下驱动升级到升级有进度条的那一刻的等待时间貌似有差异······   这种现象就很像的任务调度问题了。

然后赶紧回顾了一下linux任务调度策略,猜测目前遇到的connect camera为I/O消耗型的进程,但是android预装的io相关调试工具太少了，没办法查看。

 

那么就只能去看看ps 命令和top命令显示任务的优先级了:

手动升级

Hi3751V810:/ # ps -el | grep -i systemupgrade                                                                                                         

F S   UID   PID  PPID C PRI  NI BIT    SZ WCHAN  TTY          TIME CMD

5 S  1000  3641  1954 1  29 -10  64 774068 SyS_epoll_wait ? 00:00:16 b.systemupgrade

自动升级

5 S  1000  5622  1954 5  19   0  64 733635 SyS_epoll_wait ? 00:00:01 b.systemupgrade

 

通过对比可一发现，手动升级和自动升级的优先级(PRI)和nice(NI) 确实不一样·········

 

验证怀疑： 那么我们怎么去测试???

android系统为我们预留了一个系统级的方法:特权应用    特权应用优先级肯定高，而且绝对不会被杀。

因此就在systemupgradeupgrade的AndroidManifests中设置为android:persistent="true" 

之后进行了自动升级测试，果然次次都能成功，所以怀疑得到验证了·········  就是任务优先级太低造成的任务被调度切换造成的阻塞等待

 

解决问题：

 

问题又来了，ota应用很占用内存，并且不需要让他实时占用cpu资源，完全没有必要让它成为persist应用。并且要从android端应用层入手去提高它的优先级。

这个时候又要引入一个android端进程优先级ADJ算法了，在android中ADJ主要是用来作为lowmemorykiller的凭据的，当内存紧张时android会选去一些adj较低的进程进行查杀，从而提高系统运行速度。并且adj还可以用来作为分配CPU资源参考依据:

 

camera自动升级失败问题

 

那么问题又来了，我们如何在应用层获取自身的adj值呢，很遗憾android并没有为应用层提供获取adj值得接口，只提供了

Thread.currentThread().priority 进程优先级方法，但是这个优先级的值颗粒度太差，无法分辨咱们遇到的问题。所以要想办法获取adj值还得靠自己，好在linux为咱们提供了可以获取sdj值得方法：

cat /proc/PID/oom_score_adj

 

所以我们又去测试了手动升级和自动升级的adj值差异:

 

 

自动升级：

Hi3751V810:/ # cat /proc/6987/oom_score_adj

700

手动升级：

Hi3751V810:/ # cat /proc/7138/oom_score_adj

0

 

 

经过上面对比，发现同样是生活在一起的两口子，做人的差距咋就这么大呢？

 

如此一来我们就能分辨adj值了，那么怎么去合法提升优先级呢？？？

我们来看看adj 0和700代表了什么

camera自动升级失败问题

 

原来手动升级属于前台进程，就是有用户界面直接调用的进程。这种有UI直接影响用户体验的任务优先级肯定会很高以确保UI流畅和体验度。

那我们的自动升级属于后台服务，静悄悄的做一些事情，存在感卑微。

 

那我们就只有让我们的自动升级在真正升级操作的时候提升一点存在感，自动检测和下载的时候就在后台悄悄地搞事情就好了。因此我们就要在真正升级的时候将后台服务置于前台。

 

android又为我提供了一个把服务置于前台的工具: startForeground

所以解决方案就有了,开始升级时就置于前台，获得较高优先级，升级完了就stopForeground 又回到后台偷偷搞事情。

 

码代码验证，最后发现真正升级时adj值被提升到了200属于SCHED_GROUP_DEFAULT前台进程组，并且测试多次没有失败过，可谓效果显著。

 

这起匪夷所思的问题，就在一脸懵逼地遇到和一脸懵逼地解决中完成了。

 

 

经验教训就是:

 

没事多看看各种解决疑难杂症的帖子和博客   定位问题的经验方法很重要！

 

 

camera自动升级失败问题

 

 

参考:

一、任务调度

Linux的任务调度机制

jstack命令解析

二、I/O

Linux上查看造成IO高负载的进程

定位iowait问题

linux命令---lsof

linux命令---iotop

三、ADJ

解读Android进程优先级ADJ算法

进程优先级

 

上一篇：基于Camera Link和PCIe DMA的多通道视频采集和显示系统


下一篇：基于Camera Link和PCIe DMA的多通道视频采集和显示系统