.removeAll() freezes indefinitely

[Kashish-Sharma]

#764 Issue Basics

• ObjectBox version : 2.5.1, 3.0.0-alpha2
• Reproducibility: always

Reproducing the bug

Description

When calling removeAll() on an Entity, DB operation freezes

Code

box.removeAll()

Entities

@Entity
data class MyEntity(
    @Id
    var id: Long? = null,
    @Uid(5199960888095114421L)
    var idA: Int? = null,
    @Uid(8980596607626398101L)
    var idB: String? = null,
    @Uid(8428670953150503097L)
    var idC: Int? = null
)

Misc

box.remove(box.all)

works

• I'm calling all this in a worker
• Earlier when enitites had a default values like " " for string etc, it worked, but now have made all such fields nullable with default null.
• It works for the first time when app is installed ( In the worker, first removeAll and then put a list of entities), but when we sync again i.e. removeAll and put, it just freezes on removeAll
• I'm also observing the DB.

[greenrobot-team]

Also #644.

Thanks, will have a look at this. Is there a minimal code snippet that reproduces this? E.g. if I understand correctly:

removeAll()
put()
// kill and start app
removeAll()
put()

[Kashish-Sharma]

I'm using 2.5.1 in my production app, and it works fine there.
But for the next update, I had to update some entities and then it started happening.
It only freezes when I try to use .removeAll() on entities I've updated.

PS: I've followed the procedure mentioned in docs to change/rename a field and entity.

[greenrobot]

First, can you verify that there are a "reasonable" amount of object to be removed? E.g. it may take a while if you have millions of objects.

Then, it would help a lot if we knew a bit more on what is going on in your app. Seems like you can reproduce this? Great, can you send us stack traces (e.g. use the debugger) once it froze? If this is a deadlock, please look for threads inside the objectbox code and send their stacks as well. Thanks!

[Kashish-Sharma]

There are about 10K to 20K objects, and also box.remove(box.all) removes all within few seconds. I dont think its a deadlock because then box.remove(box.all) shouldn't be working, right?.
I'll post stack traces in a while.

[greenrobot]

Yeah, 10K to 20K objects should not be any trouble. Really hope stack traces give us more clues.

[Kashish-Sharma]

Ok so I'm using debugger for the first time.
I added a break point at box.removeAll(), then step over and then it says waiting for the previous debug statement to complete

[Kashish-Sharma]

Logcat after freeze

Logcat Warn

2020-05-04 22:49:00.151 6413-6921/? W/System.err: java.lang.NullPointerException: Attempt to read from null array
2020-05-04 22:49:00.151 6413-6921/? W/System.err:     at com.sec.android.sdhms.power.q.b(Unknown Source:9)
2020-05-04 22:49:00.151 6413-6921/? W/System.err:     at com.sec.android.sdhms.power.L.a(:1)
2020-05-04 22:49:00.151 6413-6921/? W/System.err:     at com.sec.android.sdhms.common.d.A(:4)
2020-05-04 22:49:00.151 6413-6921/? W/System.err:     at com.sec.android.sdhms.common.d.E(:6)
2020-05-04 22:49:00.151 6413-6921/? W/System.err:     at com.sec.android.sdhms.common.l.run(Unknown Source:2)
2020-05-04 22:49:00.151 6413-6921/? W/System.err:     at android.os.Handler.handleCallback(Handler.java:883)
2020-05-04 22:49:00.151 6413-6921/? W/System.err:     at android.os.Handler.dispatchMessage(Handler.java:100)
2020-05-04 22:49:00.151 6413-6921/? W/System.err:     at android.os.Looper.loop(Looper.java:237)
2020-05-04 22:49:00.151 6413-6921/? W/System.err:     at android.os.HandlerThread.run(HandlerThread.java:67)
2020-05-04 22:49:01.475 4940-5261/? W/DeviceStorageMonitorService: updateBroadcasts(/data) oldLevel:0, newLevel:0, seq:1
2020-05-04 22:49:01.476 4940-5261/? W/DeviceStorageMonitorService: There is no file /sys/fs/f2fs/userdata/sec_fs_stat
2020-05-04 22:49:01.476 4940-5261/? W/DeviceStorageMonitorService: updateBroadcasts_filenode(/data) fn_oldLevel:0, fn_newLevel:0, seq:1
2020-05-04 22:49:01.916 4940-5312/? E/IWCMonitor: poor link count is 1
2020-05-04 22:49:01.916 4940-5312/? E/IWCMonitor: [POOR_LINK_DETECTED] 0 -> 1
2020-05-04 22:49:01.916 4940-5312/? E/IWCMonitor.File: Poor Link, timestamp =: 1588612741916  RSSI:-63  AP:e8:65:d4:34:cf:60
2020-05-04 22:49:01.920 4940-5312/? E/IWCMonitor.File: List of Known APs: Candidate List: [ <e8:65:d4:34:cf:60;119;4173696389>  <40:5b:d8:4f:81:ef;3;4516756411> ], Core List: [ <18:80:90:bb:af:40;1582607390649>  <78:17:35:29:ed:3d;1582558878200>  <78:17:35:29:72:ed;1584120610895>  <78:17:35:29:72:e9;1584235824431>  <00:a3:8e:46:81:2f;1580798696395>  <18:80:90:bb:af:4f;1584096235024> ], Probation List: []
2020-05-04 22:49:01.922 4940-5312/? E/IWCMonitor.File: Q-Table Action Taken: Q-Table: [ 4.862807 0.000000 0.000000; 0.278750 0.000000 0.000000; 0.219905 0.000000 0.000000; ] >> Action Taken: 0, New State: 0
2020-05-04 22:49:02.939 4940-5312/? E/IWCMonitor: poor link count is 0
2020-05-04 22:49:02.940 4940-5312/? E/IWCMonitor.File: Good Link, timestamp =: 1588612741916  RSSI:-63  AP:e8:65:d4:34:cf:60 Direction: -1 Direction (soft): -1
2020-05-04 22:49:02.941 4940-5312/? E/IWCMonitor.File: Good Link, timestamp =: 1588612742941, RSSI:-63, AP:e8:65:d4:34:cf:60
2020-05-04 22:49:05.606 4940-5039/? E/BatteryExternalStatsWorker: no controller energy info supplied for bluetooth
2020-05-04 22:49:05.736 6413-6455/? W/System: A resource failed to call close. 
2020-05-04 22:49:05.736 6413-6455/? W/System: A resource failed to call close. 
2020-05-04 22:49:05.998 4940-5312/? E/IWCMonitor: poor link count is 1
2020-05-04 22:49:05.998 4940-5312/? E/IWCMonitor: [POOR_LINK_DETECTED] 0 -> 1
2020-05-04 22:49:05.998 4940-5312/? E/IWCMonitor.File: Poor Link, timestamp =: 1588612745998  RSSI:-63  AP:e8:65:d4:34:cf:60
2020-05-04 22:49:06.002 4940-5312/? E/IWCMonitor.File: Q-Table Action Taken: Q-Table: [ 4.862807 0.000000 0.000000; 0.278750 0.000000 0.000000; 0.219905 0.000000 0.000000; ] >> Action Taken: 0, New State: 0
2020-05-04 22:49:07.017 4940-5312/? E/IWCMonitor: poor link count is 0
2020-05-04 22:49:07.017 4940-5312/? E/IWCMonitor.File: Good Link, timestamp =: 1588612745998  RSSI:-63  AP:e8:65:d4:34:cf:60 Direction: -1 Direction (soft): -1
2020-05-04 22:49:07.019 4940-5312/? E/IWCMonitor.File: Good Link, timestamp =: 1588612747019, RSSI:-63, AP:e8:65:d4:34:cf:60
2020-05-04 22:49:08.041 4940-5312/? E/IWCMonitor: poor link count is 1
2020-05-04 22:49:08.042 4940-5312/? E/IWCMonitor: [POOR_LINK_DETECTED] 0 -> 1
2020-05-04 22:49:09.080 4940-5312/? E/IWCMonitor: poor link count is 0
2020-05-04 22:49:09.080 4940-5312/? E/IWCMonitor.File: Good Link, timestamp =: 1588612748042  RSSI:-63  AP:e8:65:d4:34:cf:60 Direction: -1 Direction (soft): -1
2020-05-04 22:49:09.080 4940-5312/? E/IWCMonitor.File: Good Link, timestamp =: 1588612749080, RSSI:-63, AP:e8:65:d4:34:cf:60
2020-05-04 22:49:10.087 4940-5312/? E/IWCMonitor: poor link count is 1
2020-05-04 22:49:10.087 4940-5312/? E/IWCMonitor: [POOR_LINK_DETECTED] 0 -> 1
2020-05-04 22:49:10.087 4940-5312/? E/IWCMonitor.File: Poor Link, timestamp =: 1588612750087  RSSI:-63  AP:e8:65:d4:34:cf:60
2020-05-04 22:49:10.090 4940-5312/? E/IWCMonitor.File: List of Known APs: Candidate List: [ <e8:65:d4:34:cf:60;119;4173704559>  <40:5b:d8:4f:81:ef;3;4516764581> ], Core List: [ <18:80:90:bb:af:40;1582607390649>  <78:17:35:29:ed:3d;1582558878200>  <78:17:35:29:72:ed;1584120610895>  <78:17:35:29:72:e9;1584235824431>  <00:a3:8e:46:81:2f;1580798696395>  <18:80:90:bb:af:4f;1584096235024> ], Probation List: []
2020-05-04 22:49:10.092 4940-5312/? E/IWCMonitor.File: Q-Table Action Taken: Q-Table: [ 4.862807 0.000000 0.000000; 0.278750 0.000000 0.000000; 0.219905 0.000000 0.000000; ] >> Action Taken: 0, New State: 0
2020-05-04 22:49:10.203 6413-6921/? W/System.err: java.lang.NullPointerException: Attempt to read from null array
2020-05-04 22:49:10.203 6413-6921/? W/System.err:     at com.sec.android.sdhms.power.q.b(Unknown Source:9)
2020-05-04 22:49:10.203 6413-6921/? W/System.err:     at com.sec.android.sdhms.power.L.a(:1)
2020-05-04 22:49:10.203 6413-6921/? W/System.err:     at com.sec.android.sdhms.common.d.A(:4)
2020-05-04 22:49:10.203 6413-6921/? W/System.err:     at com.sec.android.sdhms.common.d.E(:6)
2020-05-04 22:49:10.203 6413-6921/? W/System.err:     at com.sec.android.sdhms.common.l.run(Unknown Source:2)
2020-05-04 22:49:10.203 6413-6921/? W/System.err:     at android.os.Handler.handleCallback(Handler.java:883)
2020-05-04 22:49:10.203 6413-6921/? W/System.err:     at android.os.Handler.dispatchMessage(Handler.java:100)
2020-05-04 22:49:10.203 6413-6921/? W/System.err:     at android.os.Looper.loop(Looper.java:237)
2020-05-04 22:49:10.204 6413-6921/? W/System.err:     at android.os.HandlerThread.run(HandlerThread.java:67)
2020-05-04 22:49:11.109 4940-5312/? E/IWCMonitor: poor link count is 2
2020-05-04 22:49:11.109 4940-5312/? E/IWCMonitor: [POOR_LINK_DETECTED] 1 -> 2
2020-05-04 22:49:11.110 4940-5312/? E/IWCMonitor.File: Poor Link, timestamp =: 1588612751110  RSSI:-64  AP:e8:65:d4:34:cf:60
2020-05-04 22:49:11.114 4940-5312/? E/IWCMonitor.File: List of Known APs: Candidate List: [ <e8:65:d4:34:cf:60;119;4173705583>  <40:5b:d8:4f:81:ef;3;4516765605> ], Core List: [ <18:80:90:bb:af:40;1582607390649>  <78:17:35:29:ed:3d;1582558878200>  <78:17:35:29:72:ed;1584120610895>  <78:17:35:29:72:e9;1584235824431>  <00:a3:8e:46:81:2f;1580798696395>  <18:80:90:bb:af:4f;1584096235024> ], Probation List: []
2020-05-04 22:49:11.116 4940-5312/? E/IWCMonitor.File: Q-Table Action Taken: Q-Table: [ 4.862807 0.000000 0.000000; 0.278750 0.000000 0.000000; 0.219905 0.000000 0.000000; ] >> Action Taken: 0, New State: 0
2020-05-04 22:49:11.406 4062-5602/? W/ogle.android.g: Long monitor contention with owner services-3-619 (5604) at bayz adic.c()(PG:1) waiters=0 in bayz adic.d() for 107ms
2020-05-04 22:49:12.124 4940-5312/? E/IWCMonitor: poor link count is 3
2020-05-04 22:49:12.125 4940-5312/? E/IWCMonitor: [POOR_LINK_DETECTED] 2 -> 3
2020-05-04 22:49:12.125 4940-5312/? E/IWCMonitor.File: Poor Link, timestamp =: 1588612752125  RSSI:-64  AP:e8:65:d4:34:cf:60
2020-05-04 22:49:12.127 4940-5312/? E/IWCMonitor.File: List of Known APs: Candidate List: [ <e8:65:d4:34:cf:60;119;4173706596>  <40:5b:d8:4f:81:ef;3;4516766619> ], Core List: [ <18:80:90:bb:af:40;1582607390649>  <78:17:35:29:ed:3d;1582558878200>  <78:17:35:29:72:ed;1584120610895>  <78:17:35:29:72:e9;1584235824431>  <00:a3:8e:46:81:2f;1580798696395>  <18:80:90:bb:af:4f;1584096235024> ], Probation List: []
2020-05-04 22:49:12.130 4940-5312/? E/IWCMonitor.File: Q-Table Action Taken: Q-Table: [ 4.862807 0.000000 0.000000; 0.278750 0.000000 0.000000; 0.219905 0.000000 0.000000; ] >> Action Taken: 0, New State: 0
2020-05-04 22:49:13.137 4940-5312/? E/IWCMonitor: poor link count is 0
2020-05-04 22:49:13.138 4940-5312/? E/IWCMonitor.File: Good Link, timestamp =: 1588612752125  RSSI:-64  AP:e8:65:d4:34:cf:60 Direction: -1 Direction (soft): -1
2020-05-04 22:49:13.139 4940-5312/? E/IWCMonitor.File: Good Link, timestamp =: 1588612753139, RSSI:-63, AP:e8:65:d4:34:cf:60
2020-05-04 22:49:14.169 4940-5312/? E/IWCMonitor: poor link count is 1
2020-05-04 22:49:14.169 4940-5312/? E/IWCMonitor: [POOR_LINK_DETECTED] 0 -> 1
2020-05-04 22:49:14.169 4940-5312/? E/IWCMonitor.File: Poor Link, timestamp =: 1588612754169  RSSI:-63  AP:e8:65:d4:34:cf:60
2020-05-04 22:49:14.177 4940-5312/? E/IWCMonitor.File: List of Known APs: Candidate List: [ <e8:65:d4:34:cf:60;119;4173708646>  <40:5b:d8:4f:81:ef;3;4516768668> ], Core List: [ <18:80:90:bb:af:40;1582607390649>  <78:17:35:29:ed:3d;1582558878200>  <78:17:35:29:72:ed;1584120610895>  <78:17:35:29:72:e9;1584235824431>  <00:a3:8e:46:81:2f;1580798696395>  <18:80:90:bb:af:4f;1584096235024> ], Probation List: []
2020-05-04 22:49:14.178 4940-5312/? E/IWCMonitor.File: Q-Table Action Taken: Q-Table: [ 4.862807 0.000000 0.000000; 0.278750 0

Logcat Debug

2020-05-04 22:51:13.030 4940-5312/? E/IWCMonitor: poor link count is 13
2020-05-04 22:51:13.031 4940-5312/? E/IWCMonitor: [POOR_LINK_DETECTED] 12 -> 13
2020-05-04 22:51:13.031 4940-5312/? E/IWCMonitor.File: Poor Link, timestamp =: 1588612873031  RSSI:-65  AP:e8:65:d4:34:cf:60
2020-05-04 22:51:13.032 4940-5312/? E/IWCMonitor.File: List of Known APs: Candidate List: [ <e8:65:d4:34:cf:60;119;4173827501>  <40:5b:d8:4f:81:ef;3;4516887523> ], Core List: [ <18:80:90:bb:af:40;1582607390649>  <78:17:35:29:ed:3d;1582558878200>  <78:17:35:29:72:ed;1584120610895>  <78:17:35:29:72:e9;1584235824431>  <00:a3:8e:46:81:2f;1580798696395>  <18:80:90:bb:af:4f;1584096235024> ], Probation List: []
2020-05-04 22:51:13.034 4940-5312/? E/IWCMonitor.File: Q-Table Action Taken: Q-Table: [ 4.862807 0.000000 0.000000; 0.278750 0.000000 0.000000; 0.219905 0.000000 0.000000; ] >> Action Taken: 0, New State: 0
2020-05-04 22:51:14.212 4940-5245/? D/TelephonyManager: getAllCellInfo : Caller (PID / UID / TID): 4940 / 1000 / 5245
2020-05-04 22:51:14.432 6413-6549/? D/ia: limitCPUFreq:: freq = 1261000
2020-05-04 22:51:14.434 4940-7384/? D/CustomFrequencyManagerService: acquireDVFSLockLocked : type : DVFS_MAX_LIMIT  frequency : 1261000  uid : 1000  pid : 4940  pkgName : SIOP_ARM_MAX@3
2020-05-04 22:51:14.434 4940-7384/? D/CustomFrequencyManagerService: acquireDVFSLockLocked : new is min = 1261000
2020-05-04 22:51:14.801 6159-6717/? D/ContactsProvider_EventLog: contents_sample_state: [CONTACT contacts(121) data(1423) accounts({vnd.sec.contact.sim (4)=9, com.google (3)=113, vnd.sec.contact.phone (2)=1, com.google.android.apps.tachyon (42)=57, com.whatsapp (26)=99, com.samsung.android.coreapps (16)=3}) accounts deleted({}) in_trash(in_trash(0), in_trash_for_sync(0)) calls([logtype:100 cnt:126, logtype:300 cnt:500, logtype:1000 cnt:1008, logtype:1150 cnt:106]) countryIso(IN) userId(0)  ]
    contents_sample_state: [ agr({[3 ,26]=35, [3 ,3 ,26 ,26]=1, [3]=15, [4]=6, [3 ,26 ,26]=1, [2]=1, [3 ,26 ,16]=2, [3 ,26 ,42]=52, [3 ,26 ,16 ,42]=1, [3 ,26 ,26 ,42]=1, [3 ,3 ,26]=1, [3 ,42]=2, [4 ,42]=1, [4 ,26]=2})  ]
    contents_sample_state: [ actCnt({android.process.acore(6159)=1})  ]
    contents_sample_state: [PROFILE contacts(0) data(0) accounts({})  ] [SAPROFILE contacts(1) data(5) accounts({vnd.sec.contact.phone (1)=1})  ]
    contents_sample_state: [STORAGE Contacts(CE) Profile(CE) SAProfile(CE) CallLog(CE)  ]
2020-05-04 22:51:14.950 6269-6269/? D/io_stats: !@   8,0 r 3263313 98322192 w 667861 10249996 d 67348 3486076 f 163790 165800 iot 1069484 884915 th 102400 0 0 pt 0 inp 0 0 39122.363
2020-05-04 22:51:16.109 4940-5312/? E/IWCMonitor: poor link count is 0
2020-05-04 22:51:16.110 4940-5312/? E/IWCMonitor.File: Good Link, timestamp =: 1588612873031  RSSI:-65  AP:e8:65:d4:34:cf:60 Direction: -1 Direction (soft): -1
2020-05-04 22:51:16.114 4940-5312/? E/IWCMonitor.File: Good Link, timestamp =: 1588612876113, RSSI:-64, AP:e8:65:d4:34:cf:60
2020-05-04 22:51:17.135 4940-5312/? E/IWCMonitor: poor link count is 1
2020-05-04 22:51:17.136 4940-5312/? E/IWCMonitor: [POOR_LINK_DETECTED] 0 -> 1
2020-05-04 22:51:17.136 4940-5312/? E/IWCMonitor.File: Poor Link, timestamp =: 1588612877136  RSSI:-64  AP:e8:65:d4:34:cf:60
2020-05-04 22:51:17.140 4940-5312/? E/IWCMonitor.File: List of Known APs: Candidate List: [ <e8:65:d4:34:cf:60;119;4173831609>  <40:5b:d8:4f:81:ef;3;4516891631> ], Core List: [ <18:80:90:bb:af:40;1582607390649>  <78:17:35:29:ed:3d;1582558878200>  <78:17:35:29:72:ed;1584120610895>  <78:17:35:29:72:e9;1584235824431>  <00:a3:8e:46:81:2f;1580798696395>  <18:80:90:bb:af:4f;1584096235024> ], Probation List: []
2020-05-04 22:51:17.145 4940-5312/? E/IWCMonitor.File: Q-Table Action Taken: Q-Table: [ 4.862807 0.000000 0.000000; 0.278750 0.000000 0.000000; 0.219905 0.000000 0.000000; ] >> Action Taken: 0, New State: 0
2020-05-04 22:51:17.258 4940-5245/? D/TelephonyManager: getAllCellInfo : Caller (PID / UID / TID): 4940 / 1000 / 5245

[Kashish-Sharma]

@greenrobot any updates?

Thus issue only happens when I update entities having relations and delete them. Tried updating entities without relations and removeAll() works fine for them.

[greenrobot]

Oh there's a misunderstanding going on here - I was waiting for you and stack traces 😀

We really need to catch this issue "in action" and that's what stack traces are for. Maybe @greenrobot-team has a few moments left today to guide you finding relevant info.

[Kashish-Sharma]

Ok sure!

[greenrobot-team]

@Kashish-Sharma Here is how you can dump the current threads. Do this when the app is frozen.
First, in Android Studio, run the app in debug mode (or press Shift+F9) and bring it to freeze, then:

1. Open the Debug tool window.
2. In the Debug tool window click the camera icon (Get thread dump).
3. Use the export button to create a text file, which you can drop in your comment to upload.

After 2. you can also already analyze inside Android Studio which threads are active, and potentially the one that is hanging.

Edit: it might also be helpful to simply run the Profiler and click on CPU to see which threads are consuming resources.
https://developer.android.com/studio/profile/cpu-profiler

[Kashish-Sharma]

@greenrobot-team Thanks for helping out, here's the dump
threads_report.txt

[greenrobot-team]

Thank you! Looking at the dump there are a few threads that call ObjectBox API, like you said calling Box.removeAll(). One is actually removing, the others are waiting their turn to obtain a transaction. So nothing appears locked up.

As it appears you are using coroutines, check those run on a sensible dispatcher (e.g. IO vs Default). There are also other threads blocking each other, but I can't tell if those are the culprit.

As mentioned running the Android Studio Profiler and clicking on CPU to see which threads are consuming resources might help.
https://developer.android.com/studio/profile/cpu-profiler

[Kashish-Sharma]

@greenrobot-team I'm looking more into the profiler.

But here is a trace recording, to upload the traces I've renamed from .trace to .txt
cpu-atrace-20200512T175931.txt

[greenrobot]

The trace file has like a hundred processes, and I wasn't able to find yours...

To summarize, up to this point we do not see anything we can work with. You have plenty of threads (coroutines, or whatever) going on, so it might also be a problem in your application. Try to "prove" the one or the other. E.g. try to isolate the problem, or find a minimal setup that runs into this problems.