Sceneform-android-sdk: Very laggy AR experience on version 1.14 (on multiple devices)

[soshial]

This bug did not happen on v1.12.

2019-12-17 17:29:17.924 11602-12187/? E/ACameraMetadata: getConstEntry: cannot find metadata tag 65578
2019-12-17 17:29:17.958 11602-12187/? E/ACameraMetadata: getConstEntry: cannot find metadata tag 65578
2019-12-17 17:29:18.077 11602-12187/? E/ACameraMetadata: getConstEntry: cannot find metadata tag 65578
2019-12-17 17:29:18.131 583-12203/? E/mm-camera-isp2: isp_stats_buf_mgr_get_buf:338 failed: to get buf for stats type 3
2019-12-17 17:29:18.131 583-12203/? E/mm-camera-isp2: isp_parser_thread_process_raw_stats:257 failed: get buf failed
2019-12-17 17:29:18.132 583-12203/? E/mm-camera-isp2: isp_parser_thread_func:592 failed: isp_parser_process
2019-12-17 17:29:18.137 11602-12187/? E/ACameraMetadata: getConstEntry: cannot find metadata tag 65578
2019-12-17 17:29:18.160 11602-12187/? E/ACameraMetadata: getConstEntry: cannot find metadata tag 65578
2019-12-17 17:29:18.164 583-12203/? E/mm-camera-isp2: isp_stats_buf_mgr_get_buf:338 failed: to get buf for stats type 3

Devices, that experience the problem:

1. Nexus 5X
2. Pixel 4
3. Sony Xperia 1

[Kristina-Simakova]

Have the same on Pixel 4/1.14

[soshial]

Thank you, @Kristina-Simakova, I will update the list. To be honest, I expected any device but not the latest Pixel :)

[japser36]

I'm getting the same error logging in logcat, Samsung Galaxy S7. I'm in a bit of a different environment though, react-native v0.60.3 running react-viro v2.17.0 which supports ARCore v1.10.0 (I thought maybe this could help locate the bug if it was already present back in that version, so I posted)

01-09 13:50:47.598 27130 29930 I native  : timebase_helpers.cc:168 Timebase offset intialized to 0
01-09 13:50:47.601 27130 29933 E native  : loge.h:15 CameraMetrics: FirstCaptureComplete: 453.703961ms
01-09 13:50:47.602 27130 29930 E native  : loge.h:15 DataSourceMetrics: kFirstImageCallback: 703.578115ms
01-09 13:50:47.602 27130 29782 E ACameraMetadata: getConstEntry: cannot find metadata tag 65578
01-09 13:50:47.602 27130 29930 E ACameraMetadata: getConstEntry: cannot find metadata tag 65578
01-09 13:50:47.633 27130 29782 E ACameraMetadata: getConstEntry: cannot find metadata tag 65578
01-09 13:50:47.633 27130 29930 E ACameraMetadata: getConstEntry: cannot find metadata tag 65578

The 'cannot find metadata tag 65578' errors continue to show up between other logs until it shows this:

01-09 13:50:58.435 27130 29930 E native  : camera_image_stream.cc:270 generic::failed_precondition: Failed to extract the native metadata, status=generic::deadline_exceeded: Timed out waiting for metadata.

which leads to this kind of error being logged multiple times:

01-09 13:50:58.493 27130 29930 E native  : camera_image_stream.cc:231 Camera Image Stream failed to dequeue Image from ImageReader. status=ImageReaderStatusErrorSpaceClass::AMEDIA_IMGREADER_NO_BUFFER_AVAILABLE: AImageReader_acquireLatestImage acquired_image_count=9

which leads to this:

01-09 13:50:58.599 27130 27130 F libc    : Fatal signal 11 (SIGSEGV), code 1, fault addr 0x0 in tid 27130 (ation.*********) // I removed the app name

Which leads to a crash...
I understand some of this may be react-native or viro specific, and thus not necessarily helpful, in which case please feel free to remove this comment :)

[cemalaytekin]

Same on samsung note8.

[visyan]

Same on samsung S8. Logcat is flooded with E/ACameraMetadata: getConstEntry: cannot find metadata tag 65578 until our app is force closed

After force close I got this:
2020-01-17 14:04:43.335 3505-11173/? E/CameraDeviceClient: Disconnect from CameraDeviceClient 2020-01-17 14:04:43.335 3505-11173/? E/Camera2-FrameProcessorBase: removeListener: 2020-01-17 14:04:43.351 11118-11118/? E/Telephony: PhoneInterfaceManager: [PhoneIntfMgr] getCarrierPackageNamesForIntent: No UICC 2020-01-17 14:04:43.383 3314-3349/? E/BufferQueueProducer: [com.android.settings/com.android.settings.SubSettings[2248]#1] disconnect: not connected (req=1) 2020-01-17 14:04:43.518 2248-2248/? E/ViewRootImpl: sendUserActionEvent() returned. 2020-01-17 14:04:43.565 3875-3894/? E/libprocessgroup: Failed to kill process cgroup uid 10292 pid 15752 in 243ms, 1 processes remain 2020-01-17 14:04:43.565 3875-3894/? E/libprocessgroup: Error encountered killing process cgroup uid 99228 pid 16251: No such file or directory 2020-01-17 14:04:43.585 3875-4064/? E/InputDispatcher: channel 'f127f4b Sys2038:io.supportsquare.passerelle.remotesupport/io.s2.passerelle.remotesupport.app.android.activity.StreamActivity (server)' ~ Channel is unrecoverably broken and will be disposed! 2020-01-17 14:04:43.612 3505-19350/? E/Surface: queueBuffer: error queuing buffer to SurfaceTexture, -32 2020-01-17 14:04:43.612 3505-19350/? E/Camera3-OutputStream: returnBufferCheckedLocked: Stream 0: Error queueing buffer to native window: Broken pipe (-32) 2020-01-17 14:04:43.612 3505-19350/? E/Camera3-Device: Can't return buffer to its stream: Broken pipe (-32) 2020-01-17 14:04:43.612 3505-19351/? E/Surface: queueBuffer: error queuing buffer to SurfaceTexture, -32

[blackarrow13]

I am seeing the same logs on Sony Xperia ZX3.
E/ACameraMetadata: getConstEntry: cannot find metadata tag 65576 E/ACameraMetadata: getConstEntry: cannot find metadata tag 65578
Installed the latest system update (Android 10), my app is using ArCore 1.14

[denisk20]

This happens on a regular emulator as well, API Level 27: x86: Android 8.1 (Google APIs) system image. ArCore 1.14.1

[amarkovits]

Same issue on Samsung Galaxy S10+

[amarkovits]

actualy if I'm using ArCore 1.14.0 and on the device the version is 1.14.191118106 it works fine

[renaudbedard]

I'm getting the same issue on Note 10 and Galaxy S9, using ARCore 1.14.1. It doesn't appear to be related to the version of the SDK that the app is built with; we're still using the 1.10 SDK, and updating the device to the APK for 1.14.1 appears to have triggered the issue.

[fredsa]

Issue #982 (E/ACameraMetadata: getConstEntry: cannot find metadata tag 65578) should be fixed in Google Play Services for AR 1.15.0 and later. As of today, the update is available to 100% of users on ARCore supported devices. For testing purposes, the APK is available for download and side loading from https://github.com/google-ar/arcore-android-sdk/releases.

Please let us know if the laggy experience is not fixed by this update. Closing for now, as we believe this issue is indeed fixed.

[denisk20]

I confirm that this doesn't happen to me anymore in 1.15.0.

[visyan]

Still having a leggy experience, when I activate the AR core camera it seems to take a while for it to 'settle' to become usable.

I see a lot of this in the logging:
camera_image_stream.cc:269 FAILED_PRECONDITION: Failed to extract the native metadata, status=DEADLINE_EXCEEDED: Timed out waiting for metadata.

EDIT: this is on a Samsung S8

Logging excerpt:

E/native: camera_image_stream.cc:269 FAILED_PRECONDITION: Failed to extract the native metadata, status=DEADLINE_EXCEEDED: Timed out waiting for metadata. D/ViewRootImpl@189a5d7[Toast]: dispatchAttachedToWindow E/native: camera_image_stream.cc:269 FAILED_PRECONDITION: Failed to extract the native metadata, status=DEADLINE_EXCEEDED: Timed out waiting for metadata. E/native: camera_image_stream.cc:269 FAILED_PRECONDITION: Failed to extract the native metadata, status=DEADLINE_EXCEEDED: Timed out waiting for metadata. D/ViewRootImpl@189a5d7[Toast]: Relayout returned: old=[0,72][2076,1080] new=[729,756][1347,888] result=0x7 surface={valid=true 526219255808} changed=true D/mali_winsys: EGLint new_window_surface(egl_winsys_display *, void *, EGLSurface, EGLConfig, egl_winsys_surface **, EGLBoolean) returns 0x3000 D/OpenGLRenderer: eglCreateWindowSurface = 0x7a87dfcd80, 0x7a851ca010 E/native: camera_image_stream.cc:269 FAILED_PRECONDITION: Failed to extract the native metadata, status=DEADLINE_EXCEEDED: Timed out waiting for metadata. E/native: camera_image_stream.cc:269 FAILED_PRECONDITION: Failed to extract the native metadata, status=DEADLINE_EXCEEDED: Timed out waiting for metadata. D/ViewRootImpl@189a5d7[Toast]: MSG_RESIZED: frame=Rect(729, 756 - 1347, 888) ci=Rect(0, 0 - 0, 0) vi=Rect(0, 0 - 0, 0) or=2 W/ACameraCaptureSession: Device is closed but session 0 is not notified I/native: logger.h:28 CameraMetrics: CloseCaptureSession: 768.345153ms logger.h:28 CameraMetrics: CloseCamera: 768.4035ms I/native: logger.h:28 CameraMetrics: OpenCamera: 935.973038ms D/ACameraDevice: Device error received, code 0, frame number 0, request ID -1, subseq ID 0 E/ACameraDevice: Camera device 0 failed to create stream: Status(-8): '4: createStream:659: Camera device no longer alive' Fail to create new session. cannot configure streams I/native: logger.h:28 CameraMetrics: CreateCaptureSession: 76.252577ms I/native: cameras.cc:1258 Camera 0 changed state CLOSED->OPEN; Camera device opened successfully. i=0 cameras.cc:1258 Camera 0 changed state OPEN->RECOVERING; Attempting recovery during capture session creation from: Code=-10000; Message=UNKNOWN: ACameraDevice_createCaptureSession ACAMERA_ERROR_UNKNOWN [type.googleapis.com/util.ErrorSpacePayload='CameraStatusErrorSpaceClass::ACAMERA_ERROR_UNKNOWN'] i=1 I/native: logger.h:28 CameraMetrics: CloseCamera: 343.153us I/native: logger.h:28 CameraMetrics: OpenCamera: 351.924269ms D/ACameraDevice: Device error received, code 0, frame number 0, request ID -1, subseq ID 0 E/ACameraDevice: Camera device 0 failed to create stream: Status(-8): '4: createStream:659: Camera device no longer alive' Fail to create new session. cannot configure streams I/native: logger.h:28 CameraMetrics: CreateCaptureSession: 84.981653ms I/native: cameras.cc:1258 Camera 0 changed state RECOVERING->CLOSED; Camera device closed successfully. i=3 cameras.cc:1258 Camera 0 changed state CLOSED->OPEN; Camera device opened successfully. i=4 cameras.cc:1258 Camera 0 changed state OPEN->RECOVERING; Attempting recovery during capture session creation from: Code=-10000; Message=UNKNOWN: ACameraDevice_createCaptureSession ACAMERA_ERROR_UNKNOWN [type.googleapis.com/util.ErrorSpacePayload='CameraStatusErrorSpaceClass::ACAMERA_ERROR_UNKNOWN'] i=5 I/native: logger.h:28 CameraMetrics: OpenCamera: 320.776ms I/native: logger.h:28 CameraMetrics: CreateCaptureSession: 34.903039ms I/native: capture_request_utils.cc:193 Flash: ConfigureRequestFlashMode - OFF I/native: cameras.cc:1258 Camera 0 changed state RECOVERING->CLOSED; Camera device closed successfully. i=2 cameras.cc:1258 Camera 0 changed state CLOSED->OPEN; Camera device opened successfully. i=3 cameras.cc:1258 Camera 0 changed state OPEN->CAPTURING; Started capture session. i=4 I/native: logger.h:28 CameraMetrics: CloseCamera: 457.538us D/ACameraDevice: Device error received, code 0, frame number 0, request ID -1, subseq ID 0 I/native: cameras.cc:1258 Camera 0 changed state CAPTURING->RECOVERING; Got device disconnected callback. i=5 I/native: timebase_helpers.cc:168 Timebase offset intialized to 0 I/native: logger.h:28 DataSourceMetrics: kFirstGlCallback: 1.784870768s E/native: camera_image_stream.cc:269 FAILED_PRECONDITION: Failed to extract the native metadata, status=DEADLINE_EXCEEDED: Timed out waiting for metadata. E/native: camera_image_stream.cc:269 FAILED_PRECONDITION: Failed to extract the native metadata, status=DEADLINE_EXCEEDED: Timed out waiting for metadata. E/native: camera_image_stream.cc:269 FAILED_PRECONDITION: Failed to extract the native metadata, status=DEADLINE_EXCEEDED: Timed out waiting for metadata. D/mali_winsys: EGLint new_window_surface(egl_winsys_display *, void *, EGLSurface, EGLConfig, egl_winsys_surface **, EGLBoolean) returns 0x3000 E/native: camera_image_stream.cc:269 FAILED_PRECONDITION: Failed to extract the native metadata, status=DEADLINE_EXCEEDED: Timed out waiting for metadata. E/native: camera_image_stream.cc:269 FAILED_PRECONDITION: Failed to extract the native metadata, status=DEADLINE_EXCEEDED: Timed out waiting for metadata. I/chatty: uid=10292(io.supportsquare.passerelle.remotesupport) ImageReader-640 identical 1 line E/native: camera_image_stream.cc:269 FAILED_PRECONDITION: Failed to extract the native metadata, status=DEADLINE_EXCEEDED: Timed out waiting for metadata. E/native: camera_image_stream.cc:269 FAILED_PRECONDITION: Failed to extract the native metadata, status=DEADLINE_EXCEEDED: Timed out waiting for metadata.

[soshial]

This is still extremely laggy on v1.15 on Nexus 5X.

[omaremad166]

Still lagging on pixel 2!

[peiyumo]

I am using v1.16 on Huawei Mate 20 pro, still having this problem.

[Akarne]

Same, v1.16 on Samsung S8 and this problem appeared.

[chnouman]

I'm also facing this issue. What the heck is going on.

[jparismorgan]

I am also seeing a similar issue. I have many log lines that say cannot find metadata tag 65578. I also have four log lines that say camera_image_stream.cc:231 Camera Image Stream failed to dequeue Image from ImageReader. status=ImageReaderStatusErrorSpaceClass::AMEDIA_IMGREADER_NO_BUFFER_AVAILABLE: AImageReader_acquireLatestImage acquired_image_count=0. These four log lines are spread out over the course of the session.

I'm seeing tracking issues, and am able to repro nearly 100% of the time. Device specs:

• Galaxy note 10+ 5G, Android Version 10, ARCore runtime 1.16.200302046
• The app is built with ARCore & SceneForm 1.11

I have a full dump that I can share privately, but here are several excerpts with relevant sections:

```04-07 22:53:02.045 10402 19361 19361 E ACameraMetadata: getConstEntry: cannot find metadata tag 65578
04-07 22:53:02.047 10402 19361 19361 E native : hit_test.cc:381 generic::internal: No point hit.
04-07 22:53:02.048 1000 702 702 D keymaster_swd: keymaster_swd [WRN] (swd_run_cb:245) swd_begin() returns 0
04-07 22:53:02.051 10402 19361 14544 E ACameraMetadata: getConstEntry: cannot find metadata tag 65578
04-07 22:53:02.059 1000 702 702 D keymaster_swd: keymaster_swd [WRN] (swd_run_cb:245) swd_update() returns 0
04-07 22:53:02.059 10402 19361 14524 W native : motion_tracking_context.cc:951 generic::resource_exhausted: Behind by: 494.176146ms, skip current frame.
04-07 22:53:02.060 10402 19361 14545 E native : camera_image_stream.cc:231 Camera Image Stream failed to dequeue Image from ImageReader. status=ImageReaderStatusErrorSpaceClass::AMEDIA_IMGREADER_NO_BUFFER_AVAILABLE: AImageReader_acquireLatestImage acquired_image_count=0
04-07 22:53:02.062 1000 702 702 D keymaster_swd: keymaster_swd [WRN] (swd_run_cb:245) swd_finish() returns 0

```04-07 22:53:02.997 10402 19361 19361 E ACameraMetadata: getConstEntry: cannot find metadata tag 65578
04-07 22:53:02.998 10402 19361 19361 E native  : hit_test.cc:381 generic::internal: No point hit.
04-07 22:53:03.012 10402 19361 14524 W native  : motion_tracking_context.cc:951 generic::resource_exhausted: Behind by: 653.9125ms, skip current frame.
04-07 22:53:03.014 10402 19361 14545 E native  : camera_image_stream.cc:231 Camera Image Stream failed to dequeue Image from ImageReader. status=ImageReaderStatusErrorSpaceClass::AMEDIA_IMGREADER_NO_BUFFER_AVAILABLE: AImageReader_acquireLatestImage acquired_image_count=0
04-07 22:53:03.019 10402 19361 14544 E ACameraMetadata: getConstEntry: cannot find metadata tag 65578