MODE-1822 - VersionManager.checkin throws exception in the transaction when using JTA transaction manager

[ozhou]

Hi Randall,

I re-tested this issue with latest 3.1.3, the bug is fixed. Thanks.

But I found another issue may relate to this fix.

RIght after calling the function described in the issue, I call the following code to query the content that persist just now

public void testCreateNewNode() {
    .....
    createNewNode(sessionHolder);
    Query query = sessionHolder.getSession().getWorkspace().getQueryManager().createQuery("SELECT * FROM [pd:product]", Query.JCR_SQL2);
    System.out.println(query.execute().toString());
}

        @Transactional
        public void createNewNode(JCRSessionHolder sessionHolder) throws ItemExistsException, PathNotFoundException, NoSuchNodeTypeException, LockException, VersionException, ConstraintViolationException, RepositoryException {
            VersionManager vm = sessionHolder.getSession().getWorkspace().getVersionManager();

            Node node = sessionHolder.getSession().getRootNode().addNode("Test3", "pd:product");
            node.addMixin("mix:versionable");
            node.setProperty("name", "lalalal");
            node.setProperty("code", "lalalal");
            sessionHolder.getSession().save();
            vm.checkin(node.getPath());
        }

The chances are high to get the duplicated result. But not every time.

+---+-----------------+-----------------+----------------------------------+---------------------------------------------+---------------------+---------------------+----------------------+---------------------------+-----------------------+---------------------------------------------------------------+--------------------+
| # | pd:product.name | pd:product.code | pd:product.jcr:primaryType       | pd:product.jcr:mixinTypes                   | pd:product.jcr:path | pd:product.jcr:name | pd:product.jcr:score | pd:product.mode:localName | pd:product.mode:depth | Location(pd:product)                                          | Score(pd:product)  |
+---+-----------------+-----------------+----------------------------------+---------------------------------------------+---------------------+---------------------+----------------------+---------------------------+-----------------------+---------------------------------------------------------------+--------------------+
| 1 | lalalal         | lalalal         | {http://www.ozhou.com/pd}product | {http://www.jcp.org/jcr/mix/1.0}versionable | /{}Test3            | {}Test3             |                      | Test3                     | 1                     | /{}Test3 @ 8c3fc847505d64ce92d520-8927-4d8b-9389-53099a315930 | 3.4474973678588867 |
| 2 | lalalal         | lalalal         | {http://www.ozhou.com/pd}product | {http://www.jcp.org/jcr/mix/1.0}versionable | /{}Test3            | {}Test3             |                      | Test3                     | 1                     | /{}Test3 @ 8c3fc847505d64ce92d520-8927-4d8b-9389-53099a315930 | 3.4474973678588867 |
+---+-----------------+-----------------+----------------------------------+---------------------------------------------+---------------------+---------------------+----------------------+---------------------------+-----------------------+---------------------------------------------------------------+--------------------+

[rhauch]

I have a feeling that this is caused by Lucene leaking multiple records for the nodes while the indexes are being updated. Using "SELECT DISTINCT..." should eliminate this.

However, please log an issue just in case we're adding the same node to the index more than once.

[ozhou]

Hi Randall,

The workaround can work but I agree it may be a bug related to the indexes.

I have created MODE-1837 to track this

[ozhou]

Hi Randall,

Sorry to go back again.

Another critical issue found: in the above code, if I call VersionManager.checkout(node.getPath()) right after VersionManager.checkin(node.getPath), the node is still in check-in state, not check-out state.

And if replace this two lines with VersionManager.checkpoint(node.getPath()), the node is checked in but not in the check-out state

I have reopened issue since I have no way to workaround this.

[rhauch]

Oliver, thanks for reopening that issue. I've committed to the 'master' branch a fix that I think will work a lot better and that tests more variations/combinations. These fixes will be in 3.2.

[ozhou]

Hi Randall,

Thanks for your fix. I've already built 3.2-SNAPSHOT on my machine and I can confirm that MODE-1822 has been fixed. And at the same time, I tested MODE-1837 again, and it seems fixed as well, I don't get duplicated result after running my test a lot of times. Congratulations.

But one thing causes my attention is about write performance with or without explicit JTA transaction in 3.2-SNAPSHOT.

The code if running without explicit JTA transaction, it costs 5.21s to execute.

However, if running with explicit JTA transaction, it costs 11.3s to execute which almost double the execution time.

I can image within a explicit JTA transaction, it must have extra overhead, I just do not realize the overhead is such high.

Maybe some opmizations can be done later, but anyway, right now the bugs has gone.

[rhauch]

Thanks for your fix. I've already built 3.2-SNAPSHOT on my machine and I can confirm that MODE-1822 has been fixed. And at the same time, I tested MODE-1837 again, and it seems fixed as well, I don't get duplicated result after running my test a lot of times. Congratulations.

Thanks for testing and verifying.

But one thing causes my attention is about write performance with or without explicit JTA transaction in 3.2-SNAPSHOT.

The code if running without explicit JTA transaction, it costs 5.21s to execute.

However, if running with explicit JTA transaction, it costs 11.3s to execute which almost double the execution time.

I can image within a explicit JTA transaction, it must have extra overhead, I just do not realize the overhead is such high.

Maybe some opmizations can be done later, but anyway, right now the bugs has gone.

There is additional overhead associated with user/container-managed transactions. That was something we had to add so that all the various independent readers/writers** participating in the transaction are sure to get (and correctly cache) the same persisted-but-not-committed view of the world. The caching changes were the key. We surely do need to optimize the approach, since we're probably clearing the local caches more often than we really need to, plus we're relying upon extra transaction-related behaviors (e.g., synchronizations) that are not used when no explicit transactions enabled.

The only recommendation I have now is to avoid explicit transactions when you can. There will be times that you cannot avoid it, but there may be times when you can.

Also, if you can put together a test case that uses non-trivial and more realistic operations, we can use that to better profile and improve performance. If you do that, please log an issue (which we'll probably target to 3.3).

** Even with one session there may be multiple "readers and writers" participating in the transaction. For example, several components (e.g., VersionManager, NamespaceRegistry, WorkspaceManager, LockManager, etc.) do what JCR calls "workspace write" operations that don't use the session's view of the world and until now were completely independent of the transaction. However, that behavior was not correct when an explicit transaction was used, since those separate components do need to see the persisted-but-not-committed states. The fix for MODE-1822 uses a single, shared workspace cache within the scope of the transaction (whereas without explicit transactions, there is a single workspace cache shared by all sessions), and these transactionally-scoped workspace caches have to be managed and maintained.

[ozhou]

Okay, thanks for the detailed explanation.

I see you have another pull request sent for this issue to optimize the performance, I'll test it once it is merged into master.

Then I'll try to prepare one more realistic example, that may cost some time.

[ozhou]

I updated to the latest code, it seems not help for my case.

I just tried to run the code under VisualVM to collect some performance information. I found the biggest difference between transaction and non-transaction is the thread named [Hibernate Search: Index updates queue processor for index nodeinfo-1]

I have attached the VisualVM snapshot file and screenshot, as you can see, when using transaction, this thread used 13,020ms CPU, when not using transaction, this thread used only 3,273ms CPU. Therefore what I suspect is hibernate index update may be the root cause for the performance.

Hope it helps.

[ozhou]

In order to further investigate the issue, today I used JProfiler to run my test again and had a very interesting finding.

See attached thread history report for details.

My anaylsis is the following:

In the non-transaction case, there are 8 [Lucene Merge Thread] threads created.

However, in the transaction case, there are 89 [Lucene Merge Thread] threads created which almost ten times than previous case.

It's not quite normal for me why such difference exists.

[ozhou]

Today  I disabled the query functionality to verify whether it is really a Hibernate Search/Lucene related issue.

I'm very surprised to see the transaction case even run a little bit faster than non-transacation case.

That make me believe it should be a Hibernate Search/Lucene related issue.

Should I open another JIRA issue for this one?

[hchiorean]

Hi Oliver,

Please open another issue around Hibernate/Lucene performance and add the same data (JProfiler)

Thanks

[ozhou]

MODE-1854 is created.

Thanks in advance.