google-ar / sceneform-android-sdk

Sceneform SDK for Android
https://developers.google.com/sceneform/develop/
Apache License 2.0
1.23k stars 603 forks source link

Camera pause and reinit randomly #407

Open stewe93 opened 5 years ago

stewe93 commented 5 years ago

I'm trying to implement a basic app which will add some cubes (81pcs) to the view on tap. The cubes are generated with the ShapeFactory, the materials are just colors. After the tap, the cubes are added but after a while (random time) the session looks like closed and reinited. Below find the relevant log, this happened after 3sec then the cubes were added.

I/zygote64: Do full code cache collection, code=250KB, data=164KB
I/zygote64: After code cache collection, code=205KB, data=126KB
E/native: hit_test.cc:376 generic::internal: No point hit.
E/native: hit_test.cc:376 generic::internal: No point hit.
E/native: hit_test.cc:376 generic::internal: No point hit.
E/native: hit_test.cc:376 generic::internal: No point hit.
E/native: hit_test.cc:376 generic::internal: No point hit.
E/native: hit_test.cc:376 generic::internal: No point hit.
E/native: hit_test.cc:376 generic::internal: No point hit.
I/chatty: uid=10137(hu.android.stewe93) identical 1 line
E/native: hit_test.cc:376 generic::internal: No point hit.
I/native: session.cc:603 Entering Session::Pause.
I/native: cameras.cc:736 Camera changed state from 3 to 4: Capture session stopping...
I/native: android_camera.cc:1147 Capture sequence completed.
E/ACameraDevice: onDeviceIdle sending state cb
I/native: android_camera.cc:1095 Capture session closed for camera 0
I/native: cameras.cc:736 Camera changed state from 4 to 1: Capture session finished streaming.
I/native: android_camera.cc:696 Reset cleanly got to CLOSED state for camera 0
I/native: cameras.cc:736 Camera changed state from 1 to 0: Camera device closed successfully.
V/third_party/redwood/base/jni_common/jni_helper.cc: JniHelper: about to attach thread. (Called from line 55.)
V/third_party/redwood/base/jni_common/jni_helper.cc: JniHelper: thread already attached. (Called from line 55.)
V/third_party/redwood/base/jni_common/jni_helper.cc: ~JniHelper: did not need to detach thread. (Called from line 55.)
I/native: session.cc:661 Session::Pause returning OK.
I/native: session.cc:545 Entering Session::Resume.
V/third_party/redwood/base/jni_common/jni_helper.cc: JniHelper: about to attach thread. (Called from line 46.)
V/third_party/redwood/base/jni_common/jni_helper.cc: JniHelper: thread already attached. (Called from line 46.)
V/third_party/redwood/base/jni_common/jni_helper.cc: ~JniHelper: did not need to detach thread. (Called from line 46.)
I/native: feature_combo_node.cc:196 Cleared scoped_image buffers in feature_combo.
I/native: image_cache.h:388 Starting ImageCache drain.
I/native: image_cache.h:417 Finished ImageCache drain.
I/native: android_sensors.cc:133 Starting thread.
E/NdkImageReader: AImageReader_getWindow
I/native: android_sensors.cc:28 Gyro min delay 2.5ms requesting 5ms
I/native: android_sensors.cc:28 Accel min delay 2.5ms requesting 5ms
I/native: cameras.cc:736 Camera changed state from 0 to 1: Camera device opened successfully.
I/native: cameras.cc:736 Camera changed state from 1 to 2: Capture session starting...
I/native: cameras.cc:736 Camera changed state from 2 to 3: Capture session started streaming.
I/native: session.cc:598 Session::Resume returning OK.
E/native: session.cc:1117 FrameHitTest while not tracking. Returning empty list.
E/BufferItemConsumer: [ImageReader-640x480f23u3m16-13211-0] Failed to release buffer: Unknown error -1 (1)
I/chatty: uid=10137(hu.android.stewe93) ImageReader-640 identical 5 lines
E/BufferItemConsumer: [ImageReader-640x480f23u3m16-13211-0] Failed to release buffer: Unknown error -1 (1)
I/native: timebase_helpers.cc:168 Timebase offset intialized to 0
E/native: hit_test.cc:376 generic::internal: No point hit.
I/native: performance_monitor.cc:115 Event: FeatureExtraction is taking too long, it took 151.867ms
W/native: data_manager.cc:184 Re-initializing filter!

Tested on a Galaxy S7 and a Pixel 2 XL, both produce this sometimes and I don't shake the phones or anything like that, just watching my cubes. If you need any further information about this, please let me know, I will provide it asap.

stewe93 commented 5 years ago

Maybe a better log caught:


E/native: hit_test.cc:376 generic::internal: No point hit.
E/native: hit_test.cc:376 generic::internal: No point hit.
E/native: hit_test.cc:376 generic::internal: No point hit.
D/OpenGLRenderer: eglDestroySurface = 0x74304a31a0
I/native: session.cc:603 Entering Session::Pause.
I/native: cameras.cc:736 Camera changed state from 3 to 4: Capture session stopping...
E/ACameraDevice: onDeviceIdle sending state cb
I/native: android_camera.cc:1147 Capture sequence completed.
I/native: android_camera.cc:1095 Capture session closed for camera 0
I/native: cameras.cc:736 Camera changed state from 4 to 1: Capture session finished streaming.
I/native: android_camera.cc:696 Reset cleanly got to CLOSED state for camera 0
I/native: cameras.cc:736 Camera changed state from 1 to 0: Camera device closed successfully.
V/third_party/redwood/base/jni_common/jni_helper.cc: JniHelper: about to attach thread. (Called from line 55.)
V/third_party/redwood/base/jni_common/jni_helper.cc: JniHelper: thread already attached. (Called from line 55.)
V/third_party/redwood/base/jni_common/jni_helper.cc: ~JniHelper: did not need to detach thread. (Called from line 55.)
I/native: session.cc:661 Session::Pause returning OK.
D/ViewRootImpl@cf34ac7[ViewRenderableWindow]: dispatchDetachedFromWindow
D/InputEventReceiver: channel 'c6c3078 ViewRenderableWindow (client)' ~ Disposing input event receiver.
D/InputEventReceiver: channel 'c6c3078 ViewRenderableWindow (client)' ~NativeInputEventReceiver.
I/Choreographer: Skipped 57 frames!  The application may be doing too much work on its main thread.
D/ViewRootImpl@9f6f86f[MainActivity]: MSG_WINDOW_FOCUS_CHANGED 0
D/ViewRootImpl@9f6f86f[MainActivity]: MSG_WINDOW_FOCUS_CHANGED 1
I/native: session.cc:545 Entering Session::Resume.
V/third_party/redwood/base/jni_common/jni_helper.cc: JniHelper: about to attach thread. (Called from line 46.)
V/third_party/redwood/base/jni_common/jni_helper.cc: JniHelper: thread already attached. (Called from line 46.)
V/third_party/redwood/base/jni_common/jni_helper.cc: ~JniHelper: did not need to detach thread. (Called from line 46.)
I/native: feature_combo_node.cc:196 Cleared scoped_image buffers in feature_combo.
I/native: image_cache.h:388 Starting ImageCache drain.
I/native: image_cache.h:417 Finished ImageCache drain.
I/native: android_sensors.cc:133 Starting thread.
E/NdkImageReader: AImageReader_getWindow
V/Surface: sf_framedrop debug : 0x4f4c, game : false, logging : 0
I/ACameraManager: getCameraCharacteristics: CameraId 0
I/native: android_sensors.cc:28 Gyro min delay 2ms requesting 5ms
I/native: android_sensors.cc:28 Gyro min delay 2ms requesting 5ms
I/native: android_sensors.cc:28 Accel min delay 2ms requesting 5ms
I/native: session.cc:598 Session::Resume returning OK.
I/native: cameras.cc:736 Camera changed state from 0 to 1: Camera device opened successfully.
I/native: cameras.cc:736 Camera changed state from 1 to 2: Capture session starting...
I/native: cameras.cc:736 Camera changed state from 2 to 3: Capture session started streaming.
E/native: session.cc:1117 FrameHitTest while not tracking. Returning empty list.
D/ViewRootImpl@9f6f86f[MainActivity]: Relayout returned: old=[0,0][1080,1920] new=[0,0][1080,1920] result=0x1 surface={valid=true 499840466944} changed=false
D/SurfaceView: BG show() Surface(name=Background for - SurfaceView - hu.android.stewe93/hu.android.stewe93.MainActivity@55dcb30@0) com.google.ar.sceneform.ArSceneView{55dcb30 V.E...... ......ID 0,0-1080,1920 #7f090090 app:id/sceneform_ar_scene_view}
D/SurfaceView: surfaceChanged (1080,1920) 1 com.google.ar.sceneform.ArSceneView{55dcb30 V.E...... ......ID 0,0-1080,1920 #7f090090 app:id/sceneform_ar_scene_view}
D/ViewRootImpl@f6f3251[ViewRenderableWindow]: setView = android.widget.FrameLayout{149a8f4 V.E...... ......I. 0,0-0,0} TM=true MM=false
D/ViewRootImpl@9f6f86f[MainActivity]: Relayout returned: old=[0,0][1080,1920] new=[0,0][1080,1920] result=0x1 surface={valid=true 499840466944} changed=false
D/ViewRootImpl@f6f3251[ViewRenderableWindow]: dispatchAttachedToWindow
V/Surface: sf_framedrop debug : 0x4f4c, game : false, logging : 0
D/ViewRootImpl@f6f3251[ViewRenderableWindow]: Relayout returned: old=[0,0][0,0] new=[540,960][540,960] result=0x7 surface={valid=true 498985857024} changed=true
D/mali_winsys: EGLint new_window_surface(egl_winsys_display *, void *, EGLSurface, EGLConfig, egl_winsys_surface **, egl_color_buffer_format *, EGLBoolean) returns 0x3000,  [1x1]-format:1
D/OpenGLRenderer: eglCreateWindowSurface = 0x74304a31a0
D/ViewRootImpl@f6f3251[ViewRenderableWindow]: MSG_RESIZED_REPORT: frame=Rect(540, 960 - 540, 960) ci=Rect(0, 0 - 0, 0) vi=Rect(0, 0 - 0, 0) or=1
E/BufferItemConsumer: [ImageReader-640x480f23u3m16-26659-0] Failed to release buffer: Unknown error -1 (1)
I/chatty: uid=10597(u0_a597) ImageReader-640 identical 5 lines
E/BufferItemConsumer: [ImageReader-640x480f23u3m16-26659-0] Failed to release buffer: Unknown error -1 (1)
I/native: timebase_helpers.cc:168 Timebase offset intialized to 0
E/native: session.cc:1117 FrameHitTest while not tracking. Returning empty list.
I/native: distribute.cc:92 No keypoints to prune.
I/native: performance_monitor.cc:115 Event: FeatureExtraction is taking too long, it took 243.728ms
W/native: data_manager.cc:184 Re-initializing filter!
W/native: vio_initializer.cc:394 Dropped initialization window due to skip in data.
I/native: data_manager.cc:107 Mapping backend detected fault.
I/native: data_manager.cc:109 Saving current map to map buffer.
I/native: data_manager.cc:131 Generated map # 0, ID f064db28-0b98-2823-9a2f-513493f18f2a, non-marginalized keyframes 18, landmarks 0
E/native: session.cc:1117 FrameHitTest while not tracking. Returning empty list.
E/native: session.cc:1117 FrameHitTest while not tracking. Returning empty list.
E/native: session.cc:1117 FrameHitTest while not tracking. Returning empty list.
E/native: session.cc:1117 FrameHitTest while not tracking. Returning empty list.
E/native: session.cc:1117 FrameHitTest while not tracking. Returning empty list.
E/native: session.cc:1117 FrameHitTest while not tracking. Returning empty list.
E/native: session.cc:1117 FrameHitTest while not tracking. Returning empty list.
E/native: session.cc:1117 FrameHitTest while not tracking. Returning empty list.
E/native: session.cc:1117 FrameHitTest while not tracking. Returning empty list.
E/native: session.cc:1117 FrameHitTest while not tracking. Returning empty list.
E/native: session.cc:1117 FrameHitTest while not tracking. Returning empty list.
E/native: session.cc:1117 FrameHitTest while not tracking. Returning empty list.
I/chatty: uid=10597(u0_a597) hu.android.stewe93 identical 2 lines
E/native: session.cc:1117 FrameHitTest while not tracking. Returning empty list.
E/native: session.cc:1117 FrameHitTest while not tracking. Returning empty list.
E/native: session.cc:1117 FrameHitTest while not tracking. Returning empty list.
I/native: ba_initialization_helpers.cc:543 Number of landmarks before eliminating short tracks 1502, and after elimination 378
I/native: ba_initialization_helpers.cc:710 num_frames_for_dsolver: 4
I/native: ba_initialization_helpers.cc:711 number_of_landmarks_for_dsolver: 50
I/native: ba_initialization_helpers.cc:718 maximum_cam_meas_displacement_squared: 0.00466837
W/native: tightly_coupled_dsolver.cc:395 Invalid local gravity solution. Failed to solve constrained deterministic optimization.
W/native: tightly_coupled_dsolver.cc:397 Solved local gravity 0.757339 -8.39773 -5.19976
W/native: tightly_coupled_dsolver.cc:398 Expected gravity norm 9.80665|  Solved gravity norm 9.9062
I/native: tightly_coupled_dsolver.cc:571 Successful result with unconstrained optimization.
I/native: ba_initialization_helpers.cc:780 Deterministic solution
I/native: ba_initialization_helpers.cc:781 Local gravity 0.754483 -8.38643  -5.0228
I/native: ba_initialization_helpers.cc:782 Estimated I_q_G   0.493319   0.022146 -0.0389971   0.868691
I/native: ba_initialization_helpers.cc:783 Gyro bias   0.0618057 -0.00688634   0.0545793
I/native: ba_initialization_helpers.cc:784 Global velocity -0.0176584 0.00205498 -0.0367183
I/native: ba_initialization_helpers.cc:786 Accel bias 0.00490249  -0.016158 -0.0411615
I/native: ba_initialization.cc:682 Deterministic initialization
I/native: ba_initialization_helpers.cc:883 Num. landmarks before pruning 369
I/native: ba_initialization_helpers.cc:884 Num. landmarks uninitialized: 9
I/native: ba_initialization_helpers.cc:896 Num. landmarks initialized after pruning 60
I/native: ba_initialization_helpers.cc:898 Num. landmarks uninitialized: 318
I/native: ba_initialization.cc:196 Intrinsic vector size of the camera 0 is 7
E/native: session.cc:1117 FrameHitTest while not tracking. Returning empty list.
E/native: session.cc:1117 FrameHitTest while not tracking. Returning empty list.
I/native: ba_initialization.cc:400 Initializer did not converge: Maximum number of iterations reached. Number of iterations: 18.
I/native: ba_initialization_helpers.h:190 Number of measurements used in BA initialization for temporal landmarks: 240
I/native: ba_initialization_helpers.h:192 Number of good measurements (i.e., reprojection errors <= 3 pixels) in BA initialization for temporal landmarks: 240
E/native: session.cc:1117 FrameHitTest while not tracking. Returning empty list.
I/native: visual_inertial_filter.cc:991 VIO sliding window is initialized, with sliding window size 4
I/native: vio_fault_detector.cc:485 VIO did not use vision constraints.
E/native: hit_test.cc:376 generic::internal: No point hit.
I/chatty: uid=10597(u0_a597) hu.android.stewe93 identical 2 lines
E/native: hit_test.cc:376 generic::internal: No point hit.
W/native: map_manager.cc:171 VIWLS Map Manager: Overwriting rolling shutter time from 0.0318896 to 0.0318896
I/native: visual_inertial_wls.cc:339 The number of keyframes in the current map is less than 2 keyframes. This is not a valid map right now.
E/native: hit_test.cc:376 generic::internal: No point hit.
I/chatty: uid=10597(u0_a597) hu.android.stewe93 identical 2 lines
E/native: hit_test.cc:376 generic::internal: No point hit.
E/native: hit_test.cc:376 generic::internal: No point hit.

@claywilkinson would You mind to take a look please? It's really weird that in completely random times the camera image turns off then on and I think it's not related to my implementation.