Session.update() gets slower over time.

dkmoon commented 2 years ago

SPECIFIC ISSUE ENCOUNTERED

I pulled a clean copy of the example _augmented_facesjava and applied the attached patch to generate measure miliseconds spent in session.update(). It seems the function call gets significantly slower over time. The function takes up to 60msec and hence it generates 1-2 fps at most. This is critical because the app quickly becomes unusable less than 3 minutes. I also changed the update mode to _LATEST_CAMERAIMAGE, but it also gets slower.

I'm also attaching a graph using my measurement data.

VERSIONS USED

Android Studio: Android Studio Arctic Fox | 2020.3.1 Patch 4
ARCore SDK for Android: com.google.ar:core:1.29.0
Device manufacturer, model, and O/S: Xiaomi Redmi note 10 5G
Google Play Services for AR (ARCore): versionName=1.29.213210223 On Windows, use: adb shell pm dump com.google.ar.core | findstr /i "packages: versionName" On macOS, use: adb shell pm dump com.google.ar.core | egrep -i versionName\|packages:
Output of adb shell getprop ro.build.fingerprint: Redmi/camellian_eea/camellian:11/RP1A.200720.011/V12.5.1.0.RKSEUXM:user/release-keys

STEPS TO REPRODUCE THE ISSUE

git clone the arcore-android-sdk project
apply the patch attached
open augmented_faces_java in Android Studio
run it and leave it for 3 minutes.

WORKAROUNDS (IF ANY)

NA

ADDITIONAL COMMENTS

The patch and a generated graph are here:

patch.txt session.update.pdf

dkmoon commented 2 years ago

I'm also attaching a log file for your information.

D/AugmentedFacesActivity: Avg session.update() per frame (msec): 27.565
I/native: I0112 13:03:05.352780   19590 session.cc:3330] Update Frame Delay to 2 frames.
I/.augmentedface: ProcessProfilingInfo new_methods=157 is saved saved_to_disk=1 resolve_classes_delay=8000
D/AugmentedFacesActivity: Avg session.update() per frame (msec): 22.661
I/native: I0112 13:03:06.880518   19590 session.cc:3330] Update Frame Delay to 1 frames.
D/AugmentedFacesActivity: Avg session.update() per frame (msec): 25.018
D/AugmentedFacesActivity: Avg session.update() per frame (msec): 28.675
D/AugmentedFacesActivity: Avg session.update() per frame (msec): 29.143
D/AugmentedFacesActivity: Avg session.update() per frame (msec): 29.651
D/AugmentedFacesActivity: Avg session.update() per frame (msec): 29.759
D/AugmentedFacesActivity: Avg session.update() per frame (msec): 28.966
D/AugmentedFacesActivity: Avg session.update() per frame (msec): 29.08
D/AugmentedFacesActivity: Avg session.update() per frame (msec): 28.676
D/AugmentedFacesActivity: Avg session.update() per frame (msec): 28.697
D/AugmentedFacesActivity: Avg session.update() per frame (msec): 28.326
D/AugmentedFacesActivity: Avg session.update() per frame (msec): 27.069
D/AugmentedFacesActivity: Avg session.update() per frame (msec): 27.61
D/AugmentedFacesActivity: Avg session.update() per frame (msec): 27.878
D/AugmentedFacesActivity: Avg session.update() per frame (msec): 28.101
D/AugmentedFacesActivity: Avg session.update() per frame (msec): 28.591
I/native: I0112 13:03:37.165127   19643 stationary_detector.cc:199] SensorFusion: Enter stationary state. Stability time: 10
D/AugmentedFacesActivity: Avg session.update() per frame (msec): 28.592
D/AugmentedFacesActivity: Avg session.update() per frame (msec): 29.212
D/AugmentedFacesActivity: Avg session.update() per frame (msec): 29.695
D/AugmentedFacesActivity: Avg session.update() per frame (msec): 29.04
I/native: I0112 13:03:45.640833   19643 stationary_detector.cc:185] SensorFusion: Exit stationary state: Gyro HP:false Acc HP: false Gyro Norm: true
D/AugmentedFacesActivity: Avg session.update() per frame (msec): 29.414
D/AugmentedFacesActivity: Avg session.update() per frame (msec): 29.566
D/AugmentedFacesActivity: Avg session.update() per frame (msec): 30.073
D/AugmentedFacesActivity: Avg session.update() per frame (msec): 28.99
D/AugmentedFacesActivity: Avg session.update() per frame (msec): 29.785
D/AugmentedFacesActivity: Avg session.update() per frame (msec): 30.279
I/native: I0112 13:03:57.804549   19643 stationary_detector.cc:199] SensorFusion: Enter stationary state. Stability time: 10
D/AugmentedFacesActivity: Avg session.update() per frame (msec): 28.583
D/AugmentedFacesActivity: Avg session.update() per frame (msec): 28.338
D/AugmentedFacesActivity: Avg session.update() per frame (msec): 28.471
D/AugmentedFacesActivity: Avg session.update() per frame (msec): 28.39
D/AugmentedFacesActivity: Avg session.update() per frame (msec): 28.194
D/AugmentedFacesActivity: Avg session.update() per frame (msec): 28.233
D/AugmentedFacesActivity: Avg session.update() per frame (msec): 28.581
D/AugmentedFacesActivity: Avg session.update() per frame (msec): 28.221
I/native: I0112 13:04:13.904153   19643 stationary_detector.cc:185] SensorFusion: Exit stationary state: Gyro HP:false Acc HP: false Gyro Norm: true
D/AugmentedFacesActivity: Avg session.update() per frame (msec): 28.17
D/AugmentedFacesActivity: Avg session.update() per frame (msec): 28.31
D/AugmentedFacesActivity: Avg session.update() per frame (msec): 29.066
I/.augmentedface: Background concurrent copying GC freed 145789(4207KB) AllocSpace objects, 0(0B) LOS objects, 49% free, 4491KB/8983KB, paused 101us total 101.409ms
D/AugmentedFacesActivity: Avg session.update() per frame (msec): 28.777
D/AugmentedFacesActivity: Avg session.update() per frame (msec): 30.739
D/AugmentedFacesActivity: Avg session.update() per frame (msec): 31.021
D/AugmentedFacesActivity: Avg session.update() per frame (msec): 31.363
D/AugmentedFacesActivity: Avg session.update() per frame (msec): 32.892
D/AugmentedFacesActivity: Avg session.update() per frame (msec): 32.869
I/native: I0112 13:04:34.849953   19643 stationary_detector.cc:199] SensorFusion: Enter stationary state. Stability time: 10
D/AugmentedFacesActivity: Avg session.update() per frame (msec): 35.123
D/AugmentedFacesActivity: Avg session.update() per frame (msec): 36.436
D/AugmentedFacesActivity: Avg session.update() per frame (msec): 37.145
I/native: I0112 13:04:41.572080   19643 stationary_detector.cc:185] SensorFusion: Exit stationary state: Gyro HP:false Acc HP: false Gyro Norm: true
D/AugmentedFacesActivity: Avg session.update() per frame (msec): 36.857
D/AugmentedFacesActivity: Avg session.update() per frame (msec): 38.405
D/AugmentedFacesActivity: Avg session.update() per frame (msec): 39.805
D/AugmentedFacesActivity: Avg session.update() per frame (msec): 40.719
D/AugmentedFacesActivity: Avg session.update() per frame (msec): 41.95
D/AugmentedFacesActivity: Avg session.update() per frame (msec): 42.416
D/AugmentedFacesActivity: Avg session.update() per frame (msec): 44.149
I/.augmentedface: Background concurrent copying GC freed 155747(4475KB) AllocSpace objects, 0(0B) LOS objects, 49% free, 4468KB/8936KB, paused 114us total 101.908ms
D/AugmentedFacesActivity: Avg session.update() per frame (msec): 45.189
D/AugmentedFacesActivity: Avg session.update() per frame (msec): 45.407
I/native: I0112 13:05:08.544194   19643 stationary_detector.cc:199] SensorFusion: Enter stationary state. Stability time: 10
D/AugmentedFacesActivity: Avg session.update() per frame (msec): 48.64
D/AugmentedFacesActivity: Avg session.update() per frame (msec): 48.875
I/native: I0112 13:05:12.683374   19643 stationary_detector.cc:185] SensorFusion: Exit stationary state: Gyro HP:false Acc HP: false Gyro Norm: true
D/AugmentedFacesActivity: Avg session.update() per frame (msec): 48.784
D/AugmentedFacesActivity: Avg session.update() per frame (msec): 51.481
D/AugmentedFacesActivity: Avg session.update() per frame (msec): 51.626
I/native: I0112 13:05:22.944707   19643 stationary_detector.cc:199] SensorFusion: Enter stationary state. Stability time: 10
D/AugmentedFacesActivity: Avg session.update() per frame (msec): 53.304
D/AugmentedFacesActivity: Avg session.update() per frame (msec): 54.677
I/native: I0112 13:05:33.150954   19643 stationary_detector.cc:185] SensorFusion: Exit stationary state: Gyro HP:false Acc HP: false Gyro Norm: true
D/AugmentedFacesActivity: Avg session.update() per frame (msec): 55.286
D/AugmentedFacesActivity: Avg session.update() per frame (msec): 57.053
D/AugmentedFacesActivity: Avg session.update() per frame (msec): 56.639
D/AugmentedFacesActivity: Avg session.update() per frame (msec): 58.986
D/AugmentedFacesActivity: Avg session.update() per frame (msec): 59.627
D/AugmentedFacesActivity: Avg session.update() per frame (msec): 62.465
D/AugmentedFacesActivity: Avg session.update() per frame (msec): 61.861
I/native: I0112 13:05:58.340554   19643 stationary_detector.cc:199] SensorFusion: Enter stationary state. Stability time: 10
D/AugmentedFacesActivity: Avg session.update() per frame (msec): 60.685
I/.augmentedface: Background concurrent copying GC freed 154012(4452KB) AllocSpace objects, 0(0B) LOS objects, 49% free, 4472KB/8945KB, paused 95us total 100.174ms
D/AugmentedFacesActivity: Avg session.update() per frame (msec): 64.335
I/native: I0112 13:06:09.323505   19643 stationary_detector.cc:185] SensorFusion: Exit stationary state: Gyro HP:false Acc HP: false Gyro Norm: true
D/AugmentedFacesActivity: Avg session.update() per frame (msec): 64.582
D/AugmentedFacesActivity: Avg session.update() per frame (msec): 64.896
D/AugmentedFacesActivity: Avg session.update() per frame (msec): 61.891
D/AugmentedFacesActivity: Avg session.update() per frame (msec): 64.38
D/AugmentedFacesActivity: Avg session.update() per frame (msec): 62.061
D/AugmentedFacesActivity: Avg session.update() per frame (msec): 59.037
D/AugmentedFacesActivity: Avg session.update() per frame (msec): 63.576
D/AugmentedFacesActivity: Avg session.update() per frame (msec): 61.903
I/native: I0112 13:06:39.920844   19643 stationary_detector.cc:199] SensorFusion: Enter stationary state. Stability time: 10
D/AugmentedFacesActivity: Avg session.update() per frame (msec): 58.792
I/native: I0112 13:06:44.448913   19643 stationary_detector.cc:185] SensorFusion: Exit stationary state: Gyro HP:false Acc HP: false Gyro Norm: true
D/AugmentedFacesActivity: Avg session.update() per frame (msec): 61.22
D/AugmentedFacesActivity: Avg session.update() per frame (msec): 61.203
D/AugmentedFacesActivity: Avg session.update() per frame (msec): 53.29
D/AugmentedFacesActivity: Avg session.update() per frame (msec): 51.182
D/AugmentedFacesActivity: Avg session.update() per frame (msec): 55.432
D/AugmentedFacesActivity: Avg session.update() per frame (msec): 49.25
D/AugmentedFacesActivity: Avg session.update() per frame (msec): 49.798
D/AugmentedFacesActivity: Avg session.update() per frame (msec): 48.355
I/native: I0112 13:07:13.233547   19643 stationary_detector.cc:199] SensorFusion: Enter stationary state. Stability time: 10
D/AugmentedFacesActivity: Avg session.update() per frame (msec): 47.386
I/native: I0112 13:07:15.521463   19643 stationary_detector.cc:185] SensorFusion: Exit stationary state: Gyro HP:false Acc HP: false Gyro Norm: true
D/AugmentedFacesActivity: Avg session.update() per frame (msec): 47.16
I/.augmentedface: Background concurrent copying GC freed 153011(4484KB) AllocSpace objects, 0(0B) LOS objects, 49% free, 4429KB/8859KB, paused 104us total 104.203ms
D/AugmentedFacesActivity: Avg session.update() per frame (msec): 46.417
D/AugmentedFacesActivity: Avg session.update() per frame (msec): 44.572
D/AugmentedFacesActivity: Avg session.update() per frame (msec): 41.807
D/AugmentedFacesActivity: Avg session.update() per frame (msec): 42.235
I/native: I0112 13:07:28.732443   19643 stationary_detector.cc:199] SensorFusion: Enter stationary state. Stability time: 10
I/native: I0112 13:07:31.316676   19643 stationary_detector.cc:185] SensorFusion: Exit stationary state: Gyro HP:false Acc HP: false Gyro Norm: true
D/AugmentedFacesActivity: Avg session.update() per frame (msec): 43.786
D/AugmentedFacesActivity: Avg session.update() per frame (msec): 43.343
D/AugmentedFacesActivity: Avg session.update() per frame (msec): 43.892
D/AugmentedFacesActivity: Avg session.update() per frame (msec): 45.76
D/AugmentedFacesActivity: Avg session.update() per frame (msec): 42.187
D/AugmentedFacesActivity: Avg session.update() per frame (msec): 42.327
D/AugmentedFacesActivity: Avg session.update() per frame (msec): 44.026
D/AugmentedFacesActivity: Avg session.update() per frame (msec): 43.351
D/AugmentedFacesActivity: Avg session.update() per frame (msec): 43.277
D/AugmentedFacesActivity: Avg session.update() per frame (msec): 43.89
I/native: I0112 13:07:59.904348   19643 stationary_detector.cc:199] SensorFusion: Enter stationary state. Stability time: 10
D/AugmentedFacesActivity: Avg session.update() per frame (msec): 44.996
I/native: I0112 13:08:03.432779   19643 stationary_detector.cc:185] SensorFusion: Exit stationary state: Gyro HP:false Acc HP: false Gyro Norm: true
D/AugmentedFacesActivity: Avg session.update() per frame (msec): 44.046
D/AugmentedFacesActivity: Avg session.update() per frame (msec): 45.412
D/AugmentedFacesActivity: Avg session.update() per frame (msec): 45.938
D/AugmentedFacesActivity: Avg session.update() per frame (msec): 47.316
D/AugmentedFacesActivity: Avg session.update() per frame (msec): 47.054
D/AugmentedFacesActivity: Avg session.update() per frame (msec): 47.77
D/AugmentedFacesActivity: Avg session.update() per frame (msec): 47.609
D/AugmentedFacesActivity: Avg session.update() per frame (msec): 48.206
D/AugmentedFacesActivity: Avg session.update() per frame (msec): 47.876
D/AugmentedFacesActivity: Avg session.update() per frame (msec): 49.201
D/AugmentedFacesActivity: Avg session.update() per frame (msec): 48.152
D/AugmentedFacesActivity: Avg session.update() per frame (msec): 49.917
I/.augmentedface: Background concurrent copying GC freed 141428(4185KB) AllocSpace objects, 0(0B) LOS objects, 49% free, 4383KB/8765KB, paused 104us total 100.395ms
D/AugmentedFacesActivity: Avg session.update() per frame (msec): 48.141
D/AugmentedFacesActivity: Avg session.update() per frame (msec): 49.007
D/AugmentedFacesActivity: Avg session.update() per frame (msec): 49.242
D/AugmentedFacesActivity: Avg session.update() per frame (msec): 49.599
D/AugmentedFacesActivity: Avg session.update() per frame (msec): 49.102
D/AugmentedFacesActivity: Avg session.update() per frame (msec): 50.254
D/AugmentedFacesActivity: Avg session.update() per frame (msec): 50.94
D/AugmentedFacesActivity: Avg session.update() per frame (msec): 50.841
D/AugmentedFacesActivity: Avg session.update() per frame (msec): 51.853
D/AugmentedFacesActivity: Avg session.update() per frame (msec): 52.083
D/AugmentedFacesActivity: Avg session.update() per frame (msec): 51.601
D/AugmentedFacesActivity: Avg session.update() per frame (msec): 52.287
D/AugmentedFacesActivity: Avg session.update() per frame (msec): 51.795
D/AugmentedFacesActivity: Avg session.update() per frame (msec): 52.869
I/.augmentedface: Background concurrent copying GC freed 148657(4356KB) AllocSpace objects, 0(0B) LOS objects, 49% free, 4415KB/8830KB, paused 120us total 120.165ms
D/AugmentedFacesActivity: Avg session.update() per frame (msec): 52.871
D/AugmentedFacesActivity: Avg session.update() per frame (msec): 53.351
D/AugmentedFacesActivity: Avg session.update() per frame (msec): 53.287
D/AugmentedFacesActivity: Avg session.update() per frame (msec): 53.614
D/AugmentedFacesActivity: Avg session.update() per frame (msec): 52.686
D/AugmentedFacesActivity: Avg session.update() per frame (msec): 54.014
D/AugmentedFacesActivity: Avg session.update() per frame (msec): 54.202
D/AugmentedFacesActivity: Avg session.update() per frame (msec): 54.729
D/AugmentedFacesActivity: Avg session.update() per frame (msec): 54.819
D/AugmentedFacesActivity: Avg session.update() per frame (msec): 55.168
D/AugmentedFacesActivity: Avg session.update() per frame (msec): 55.486
D/AugmentedFacesActivity: Avg session.update() per frame (msec): 55.807
D/AugmentedFacesActivity: Avg session.update() per frame (msec): 55.999
D/AugmentedFacesActivity: Avg session.update() per frame (msec): 56.511
D/AugmentedFacesActivity: Avg session.update() per frame (msec): 57.378
D/AugmentedFacesActivity: Avg session.update() per frame (msec): 57.017
D/AugmentedFacesActivity: Avg session.update() per frame (msec): 57.284
D/AugmentedFacesActivity: Avg session.update() per frame (msec): 58.413
D/AugmentedFacesActivity: Avg session.update() per frame (msec): 58.072
D/AugmentedFacesActivity: Avg session.update() per frame (msec): 57.803
D/AugmentedFacesActivity: Avg session.update() per frame (msec): 57.962
D/AugmentedFacesActivity: Avg session.update() per frame (msec): 52.144
D/AugmentedFacesActivity: Avg session.update() per frame (msec): 54.958
D/AugmentedFacesActivity: Avg session.update() per frame (msec): 59.762
D/AugmentedFacesActivity: Avg session.update() per frame (msec): 54.713
D/AugmentedFacesActivity: Avg session.update() per frame (msec): 58.359
D/AugmentedFacesActivity: Avg session.update() per frame (msec): 60.568
D/AugmentedFacesActivity: Avg session.update() per frame (msec): 61.611
D/AugmentedFacesActivity: Avg session.update() per frame (msec): 56.053
I/.augmentedface: Background concurrent copying GC freed 143615(4195KB) AllocSpace objects, 0(0B) LOS objects, 49% free, 4401KB/8803KB, paused 96us total 103.848ms
D/AugmentedFacesActivity: Avg session.update() per frame (msec): 58.684
D/AugmentedFacesActivity: Avg session.update() per frame (msec): 61.74
D/AugmentedFacesActivity: Avg session.update() per frame (msec): 55.726

devbridie commented 2 years ago

Pixel 4 XL:

Let me try a different device as well.

devbridie commented 2 years ago

OnePlus 8T:

Doesn't seem to repro on these devices; I'll try to find somebody with yours.

RGregat commented 2 years ago

I have nothing to add to this issue, but I find the dot diagram from the OnePlus compared to the Pixel very interesting. :O to consistent in my opinion :P

google-ar / arcore-android-sdk