Realm-java: Bidirectional links Caused slowness when parsing collection changeset

[jpmcosta]

Goal

I think I've found a bug that makes Realm freeze while trying to execute transactions to update data.

Results

My schema worked fine in Realm 2.3.0, but it doesn't seem to work well in Realm 3.1.3.

Steps & Code to Reproduce

I've created a simple app to reproduce the bug: https://github.com/jpmcosta/RealmTestProject/tree/47b091215e2517ae337b88f6a5aeb597edf6542d:

• run the app;
• click on the FABs and on the items in the list;
  
  
  
  • example: click 5 times on the left FAB, 5 times on right FAB, and then click once or twice on one of the items in the list.
  
  
• the app will eventually freeze and will have to be force closed.

Details of the app:

• left FAB will create a Filter, replicating my app's use case (2 transactions):
  
  
  
  • first, updates the data of a temporary Filter;
  
  
  • then, copies the temporary Filter data to the actual Filter.
  
  
• right FAB will create an Item for every Feed (1 transaction);
• clicking on the items in the list (Filters) will update their isEnabled value (1 transaction).

Version of Realm and tooling

Realm version(s): 3.1.3

Android version: 5.1.1 (22)

[beeender]

I can reproduce this, checking now.

[Zhuinden]

after adding a bunch of logs

        mFilterFab.setOnClickListener(new View.OnClickListener() {

            @Override
            public void onClick(View v) {
                getRealm().executeTransaction(new Realm.Transaction() {

                    @Override
                    public void execute(Realm realm) {
                        // Update temporary Filter, before "committing changes".

                        Filter tempFilter = realm.where(Filter.class).equalTo("id", 0).findFirst();
                        tempFilter.reset();

                        for (int i = 0; i < APP_COUNT; i++) {
                            Log.i("ANRTEST", "PRE RANDOM [" + i + "]");
                            if (mRandom.nextBoolean()) {
                                Log.i("ANRTEST", "PRE GET [" + i + "]");
                                App app = mApps.get(mRandom.nextInt(APP_COUNT));
                                Log.i("ANRTEST", "PRE CONTAINS [" + i + "]");
                                if (!tempFilter.apps.contains(app)) {
                                    Log.i("ANRTEST", "PRE ADD [" + i + "]");
                                    tempFilter.apps.add(app);
                                    Log.i("ANRTEST", "POST ADD [" + i + "]");
                                }
                                Log.i("ANRTEST", "POST CONTAINS [" + i + "]");
                            }
                            Log.i("ANRTEST", "POST RANDOM [" + i + "]");
                        }
                        Log.i("ANRTEST", "END OF LOOP");
                    }
                });
                Log.i("ANRTEST", "POST EXECUTE TRANSACTION");

it appears that the transaction ends properly in the sense that it reaches END OF LOOP, but the app never reaches POST EXECUTE TRANSACTION.

[beeender]

yeah... something is wrong when parsing the nested linked field change transaction log in the object store...

[Zhuinden]

Leaving in either tempFilter.reset(); which calls apps.clear(), or leaving in tempFilter.apps.add(app); will trigger the ANR.

[Zhuinden]

@beeender all I can see is btw is that the schema looks like this:

      FILTER
           \
            \ *
             \/
             APP
             / /\
          * /   | 1
          \/    |
        FEED    |
       /\  \    | 
         \  \*  |
       1  \  \  |
           \ \/ |
            ITEM     

And as we know, modifying filter.apps is what causes the ANR.

---

EDIT: Removing item.app seems to stop the crash. So I guess the problem is with the cycle from FILTER -> APP -> FEED -> ITEM -> APP

[beeender]

@jpmcosta I have some updates for this issue in https://github.com/realm/realm-object-store/issues/438

So your test project is great that it reaches a worst case for our transaction log parsing. To know which object in the collection is changed, we need to go through the transaction log and the linking graph to see which element is changed or not.

Basically all the circular links and the random parent links from the testing project make the transaction log parser have to go through every object created in the Realm. Yeah, clicking on the filter is only changing one field of it, but since everything is linked together, the parser has to go through everything to see what is NOT changed. That really takes time.

We will try to optimize this to make it run faster, but it might take time since this use case is kind of unusual and the circular links making things complex.

But right now, I think there is something you can do in your project, what i tried is to set Item.app which solves the problem. We recently released a feature called backlinks, see https://realm.io/docs/java/3.1.3/api/ . It gives you ability to get the reversed linked object without storing the link into the db. Maybe you can try that to reduce the levels of nested links or your schema?

Thanks again for the great testing project to show this problem!

[jpmcosta]

@beeender thanks for the update!

About the issue

I don't like to make guesses, because I don't want to waste your time with pointless theories.
However, I would like to ask you if you were able to rule out an infinite loop situation in your testing? I mean, were you able to confirm that the parser ever finishes, and doesn't start another parsing task?
Baseless theory: from my usage, it seems that once a circular path is created, an infinite loop "task" is also created. With fewer objects, it is still possible to make transactions in-between infinite "tasks", but with more circular paths being created, the number of infinite tasks completely blocks any other transactions. That's what it feels like, but it could just be the case that the number of paths increases exponentially, and it just blocks.

Backlinks

I had already noticed that, I will try it out.
I had already tried a few other things to remove circular links, but with not much success (my actual schema is a bit different from the test project).
I'll update here if I manage to improve things, because right now the app is not usable once filters are created.

[beeender]

At the same time, there is only one parsing task running.

It should not be an infinite loop, from my testing, with 3 filters, clicking the adding item button 2 times could cause the parsing take 1+ minutes on my emulator.
But running the similar testing with pure c++ on the desktop shows the slowness, but not that slow. So it is very possible I still miss some key point of the c++ testing, you can see the code https://gist.github.com/beeender/3759da9032ae9a199b3d6b9f2560d38e

since you are doing synced transaction, every time you commit something, the parsing will heppen. So when you click the right + button, some items added, then the parsing starts. It will block the operation when you toggle the filter.

BTW, if it is an async transaction, all the parsing will happen in a background thread without blocking the UI unless you commit a synced transaction on UI thread or calling refresh.

[Zhuinden]

refresh() waits for the current open transaction to finish? Hmm...

[jpmcosta]

I've tried to wait in my use case, but after 5 minutes I just give up (my schema is more complex).

On the other hand, even if the async transaction doesn't block the UI, I stop being able to query Realm, which is one of the reasons why the whole app suffers.

[beeender]

@Zhuinden no, it is another lock. refresh() will deliver the notifications, if there is any notification token on current thread, and the background thread has been start to parse the transaction log, it will wait. Otherwise no blocking.

[beeender]

@jpmcosta right, in this case, async transaction doesn't solve the problem either, since the UI still needs to wait parsing finishes to get the latest data.

May I ask in your project, how many object will be there?

[jpmcosta]

@beeender 8 different linked types. The number of objects is similar though. I mean, with 150 Application objects, and 1 or 2 objects of other types, it hangs.

[beeender]

For the specific case here, the Filter actually only has a single direction link to the App. And change Filter.isEnabled should effect other Filter objects in the collection. I think that is something should be optimized in our parsing. But I don't have too much ideas right now.

[jpmcosta]

I was trying to figure out if there was an infinite loop or not.
I've modified the test app to run multiple tests on different graphs, but with the same number of objects. Here: https://github.com/jpmcosta/RealmTestProject/tree/cdd686001d5293a1ee3ab7b43ded542ea2b89b0d

The test is simply:

getRealm().executeTransaction(new Realm.Transaction() {

    @Override
    public void execute(Realm realm) {
        Filter filter = realm.where(Filter.class).equalTo("id", 0).findFirst();
        filter.isEnabled = !filter.isEnabled;
    }
});

I've tried to remove parentFeed from Item, to see the impact it might have, and I found that if Item has a parentFeed object, the testing times jump from a maximum of ~8000ms to a maximum of ~70000ms.

I've run tests 1000+ times, with different OBJECT_COUNT, and indeed it doesn't seem to exist an infinite loop, just really slow transaction times.

With 10 Apps, 10 Feeds, 10 Items, no repeated links, and 3 Filters pointing to App#0, these were some of my results:

[test 0] time: 2235
[test 1] time: 590
[test 2] time: 144
[test 3] time: 406
[test 4] time: 507
[test 5] time: 373
[test 6] time: 1030
[test 7] time: 270
[test 8] time: 1519
[test 9] time: 1911
[test 1] time: 656
[test 2] time: 16650
[test 3] time: 19002
[test 4] time: 27234
[test 5] time: 13973
[test 6] time: 5564
[test 7] time: 12968
[test 8] time: 69333
[test 9] time: 3139
[test 10] time: 8201

[Zhuinden]

Current workaround is to replace bidirectional links with @LinkingObjects using 3.4.0-SNAPSHOT and therefore enabling link queries across inverse relationships.

[beeender]

Some updates: https://github.com/realm/realm-object-store/pull/517 will make this case faster, but i haven't done a benchmark to see how fast it is right now.

The change has been released in 4.0.0+

[sync-by-unito[bot]]

➤ Christan Melchior commented:

Since @LinkingObjects are now supported which can be used to work around this and there has also been performance optimizations on our side, I'll close this assuming this enough.