[dna-issues] [JBoss JIRA] Updated: (DNA-616) JPA connector pooling doesn't appear to shutdown
Randall Hauch (JIRA)
jira-events at lists.jboss.org
Thu Jan 7 01:32:38 EST 2010
[ https://jira.jboss.org/jira/browse/DNA-616?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
Randall Hauch updated DNA-616:
------------------------------
Attachment: DNA-616_fix.patch
The problem has to do with the fact that this example uses a FederatedRepositorySource as a source for a JpaRepository (which creates a FederatedRepositorySource on top of the supplied source). Thus, there is a FederatedRepositorySource that uses another FederatedRepositorySource, and this is the condition that causes the deadlock.
When the JcrRepository is created, it uses a SearchIndexer to crawl the content and create the requisite indexes for query/search. The SearchIndexer is create a CompositeRequestChannel (which it uses to submit to the designated repository source a CompositeRequest that remains open, allowing the SearchIndexer to supply requests and then use those requests to build other requests that are submitted within the same execution/transaction), and is submitting a ReadBranchRequest to the source that happens to be the lower FederatedRepositorySource. The FederatedRepositorySource returns a connection that has an execute(...) method that implements the work by using the fork-join algorithm to process the request, which in this case is the CompositeRequest (owned by the CompositeRequestChannel created by the SearchIndexer).
Now, the ForkRequestProcessor works on all the incoming request, which again is the CompositeRequest. The FRP's process(CompositeRequest) is actually inherited from RequestProcessor, and simply uses an iterator to get all of the requests within the CompositeRequest. The iterator promptly returns the first ReadBranchRequest, so the ForkRequestProcessor handles this via it's process(ReadBranchRequest), and like all of the ForkRequestProcessor.process(...) methods, forks the request into appropriate requests to submit to the underlying (federated) sources, and then it enqueues the forked requests into a queue.
Note that the ForkRequestProcessor does NOT mark the requests it processes as being completed. After all, this is the job of the JoinRequestProcessor.
Meanwhile, the ForkRequestProcessor.process(ReadBranchRequest) completes and returns, and the iterator in the ForkRequestProcessor.process(CompositeRequest) then attempts to get the next request.
But the SearchIndexer has only added one ReadBranchRequest and is waiting/blocking until that request is completed before it continues. But the FederatedRepositoryConnection is waiting/blocking until the next request is added to the CompositeRequest. Thus the deadlock.
The only way to break this deadlock is for the ReadRequestBranch to be completed. But, because of the way that FederatedRepositoryConnection.execute(...) is implemented, the ForkRequestProcessor.process(request) must complete before the JoinRequestProcessor is started. So we need to create and start the JoinRequestProcessor without waiting for the ForkRequestProcessor.process(request) to complete.
The solution is actually coded in the FederatedRepositoryConnection.execute(...) - there is a 'shouldProcessSynchronously(Request)' method that returns whether the ForkRequestProcessor should be processed synchronously or asynchronously, and is implemented to always return 'true' (synchronous). The solution to this problem requires that the method return 'false' for CompositeRequests that contain more than one (or an unknown number) of requests. (In other cases, there is just one request, so the forking can be done synchronously, saving the work of pushing the fork processing into the executor service.)
Thus, the 'shouldProcessSynchronously(Request)' was implemented to do this, and the test completed ... with an error. This error is caused by a bug in the JoinRequestProcessor.process(ReadBranchRequest) that failed to properly calculate the projected actual Locations for the ProxyNodes from the source requests. (Apparently the SearchIndexer reads a branch that is deeper than was previously tested.)
Fixing the JoinRequestProcessor.process(ReadBranchRequest) allows the repository example test cases to complete successfully.
See the attached patch, which was committed and verified with a full integration build (all unit and integration tests pass). The patch also changes the log level of the repository example back to 'ERROR' (what it was previously), and also re-enables the 'docs/examples/gettingstarted/repository' project in the 'docs/examples/gettingstarted/pom.xml'.
> JPA connector pooling doesn't appear to shutdown
> ------------------------------------------------
>
> Key: DNA-616
> URL: https://jira.jboss.org/jira/browse/DNA-616
> Project: DNA
> Issue Type: Bug
> Components: Connectors
> Affects Versions: 0.7
> Reporter: Randall Hauch
> Assignee: Randall Hauch
> Priority: Blocker
> Fix For: 0.7
>
> Attachments: DNA-616_fix.patch
>
>
> Our integration tests now appear to be running forever in what appears to be an infinite loop. The unit tests in 'docs/examples/gettingstarted/repositories' module appear to run forever, with the log ending with the snippet below (which goes on forever). Note that the example is running with DEBUG (which also needs to be changed).
> 02:16:42,310 DEBUG org.jboss.dna.connector.store.jpa.model.simple.NodeEntity{referentialIntegrityEnforced=false, childName=Learjet 45, childNamespace=org.jboss.dna.connector.store.jpa.model.common.NamespaceEntity#1, compressed=null, id=5, allowsSameNameChildren=false, largeValues=<uninitialized>, propertyCount=11, data=2c6d8085f7848080808af480a7fbe8f4f4f0baafaff7f7f7aeeae3f0aeeff2e7afeae3f2afb1aeb0fdf0f2e9ede1f2f9d4f9f0e5f7868080808180cef480b8fbe8f4f4f0baafaff7f7f7aeeae2eff3f3aeeff2e7afe4eee1afe5f8e1edf0ece5f3afe1e9f2e3f2e1e6f4afb1aeb0fdc1e9f2e3f2e1e6f4f4808ae9eef4f2efe4f5e3e5e4f7868080808180d3f48084b1b9b9b5f48084e3f2e5f7f7868080808180d3f48081b2f48085ede1ebe5f2f7868080808180d3f48087cce5e1f2eae5f4f48085edefe4e5ecf7868080808180d3f48084cccab4b5f4808be3f2f5e9f3e5d3f0e5e5e4f7868080808180d3f48085b4b5b7ebf4f48083f5f2ecf7868080808180d3f480a7e8f4f4f0baafafe5eeaef7e9ebe9f0e5e4e9e1aeeff2e7aff7e9ebe9afcce5e1f2eae5f4dfb4b5f48085f2e1eee7e5f7868080808180d3f48086b2b1b2b0eeedf4808beef5ede2e5f2c2f5e9ecf4f7868080808180d3f48084b2b6b4abf4808be5edf0f4f9d7e5e9e7e8f4f7868080808180d3f48087b1b3b6b9b5ece2, sameNameSiblingIndex=1, indexInParent=1, nodeUuidString=6ae6cf0c-88b8-4cb9-af63-195a6a351378, children=<uninitialized>, parent=org.jboss.dna.connector.store.jpa.model.simple.NodeEntity#3, workspaceId=1}
> 02:16:42,310 DEBUG more......
> 02:16:42,310 DEBUG about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
> 02:16:42,310 DEBUG
> delete
> from
> DNA_SUBGRAPH_NODES
> where
> QUERY_ID=?
> 02:16:42,311 DEBUG cxnStmtMgr.statementSet( org.hsqldb.jdbc.jdbcConnection at 588a137c ).size(): 15
> 02:16:42,311 DEBUG checkoutStatement: com.mchange.v2.c3p0.stmt.GlobalMaxOnlyStatementCache stats -- total size: 15; checked out: 1; num connections: 1; num keys: 15
> 02:16:42,311 DEBUG about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
> 02:16:42,312 DEBUG checkinStatement(): com.mchange.v2.c3p0.stmt.GlobalMaxOnlyStatementCache stats -- total size: 15; checked out: 0; num connections: 1; num keys: 15
> 02:19:41,831 DEBUG Checking for expired resources - Fri Jan 01 02:19:41 EST 2010 [com.mchange.v2.resourcepool.BasicResourcePool at 427a39ea]
> 02:19:41,831 DEBUG BEGIN check for expired resources. [com.mchange.v2.resourcepool.BasicResourcePool at 427a39ea]
> 02:19:41,831 DEBUG FINISHED check for expired resources. [com.mchange.v2.resourcepool.BasicResourcePool at 427a39ea]
> 02:19:41,831 DEBUG Refurbishing idle resources - Fri Jan 01 02:19:41 EST 2010 [com.mchange.v2.resourcepool.BasicResourcePool at 427a39ea]
> 02:19:41,831 DEBUG trace com.mchange.v2.resourcepool.BasicResourcePool at 427a39ea [managed: 1, unused: 0, excluded: 0] (e.g. com.mchange.v2.c3p0.impl.NewPooledConnection at 2ac6fb1)
> 02:20:26,832 DEBUG Checking for expired resources - Fri Jan 01 02:20:26 EST 2010 [com.mchange.v2.resourcepool.BasicResourcePool at 427a39ea]
> 02:20:26,832 DEBUG BEGIN check for expired resources. [com.mchange.v2.resourcepool.BasicResourcePool at 427a39ea]
> 02:20:26,832 DEBUG FINISHED check for expired resources. [com.mchange.v2.resourcepool.BasicResourcePool at 427a39ea]
> 02:21:11,835 DEBUG Checking for expired resources - Fri Jan 01 02:21:11 EST 2010 [com.mchange.v2.resourcepool.BasicResourcePool at 427a39ea]
> 02:21:11,835 DEBUG BEGIN check for expired resources. [com.mchange.v2.resourcepool.BasicResourcePool at 427a39ea]
> 02:21:11,835 DEBUG FINISHED check for expired resources. [com.mchange.v2.resourcepool.BasicResourcePool at 427a39ea]
> 02:21:56,837 DEBUG Checking for expired resources - Fri Jan 01 02:21:56 EST 2010 [com.mchange.v2.resourcepool.BasicResourcePool at 427a39ea]
> 02:21:56,837 DEBUG BEGIN check for expired resources. [com.mchange.v2.resourcepool.BasicResourcePool at 427a39ea]
> 02:21:56,837 DEBUG FINISHED check for expired resources. [com.mchange.v2.resourcepool.BasicResourcePool at 427a39ea]
> 02:22:41,834 DEBUG Refurbishing idle resources - Fri Jan 01 02:22:41 EST 2010 [com.mchange.v2.resourcepool.BasicResourcePool at 427a39ea]
> 02:22:41,834 DEBUG trace com.mchange.v2.resourcepool.BasicResourcePool at 427a39ea [managed: 1, unused: 0, excluded: 0] (e.g. com.mchange.v2.c3p0.impl.NewPooledConnection at 2ac6fb1)
> 02:22:41,838 DEBUG Checking for expired resources - Fri Jan 01 02:22:41 EST 2010 [com.mchange.v2.resourcepool.BasicResourcePool at 427a39ea]
> 02:22:41,838 DEBUG BEGIN check for expired resources. [com.mchange.v2.resourcepool.BasicResourcePool at 427a39ea]
> 02:22:41,838 DEBUG FINISHED check for expired resources. [com.mchange.v2.resourcepool.BasicResourcePool at 427a39ea]
> 02:23:26,840 DEBUG Checking for expired resources - Fri Jan 01 02:23:26 EST 2010 [com.mchange.v2.resourcepool.BasicResourcePool at 427a39ea]
> 02:23:26,840 DEBUG BEGIN check for expired resources. [com.mchange.v2.resourcepool.BasicResourcePool at 427a39ea]
> 02:23:26,840 DEBUG FINISHED check for expired resources. [com.mchange.v2.resourcepool.BasicResourcePool at 427a39ea]
> 02:24:11,843 DEBUG Checking for expired resources - Fri Jan 01 02:24:11 EST 2010 [com.mchange.v2.resourcepool.BasicResourcePool at 427a39ea]
> 02:24:11,843 DEBUG BEGIN check for expired resources. [com.mchange.v2.resourcepool.BasicResourcePool at 427a39ea]
> 02:24:11,843 DEBUG FINISHED check for expired resources. [com.mchange.v2.resourcepool.BasicResourcePool at 427a39ea]
> 02:24:56,845 DEBUG Checking for expired resources - Fri Jan 01 02:24:56 EST 2010 [com.mchange.v2.resourcepool.BasicResourcePool at 427a39ea]
> 02:24:56,845 DEBUG BEGIN check for expired resources. [com.mchange.v2.resourcepool.BasicResourcePool at 427a39ea]
> 02:24:56,845 DEBUG FINISHED check for expired resources. [com.mchange.v2.resourcepool.BasicResourcePool at 427a39ea]
> 02:25:41,837 DEBUG Refurbishing idle resources - Fri Jan 01 02:25:41 EST 2010 [com.mchange.v2.resourcepool.BasicResourcePool at 427a39ea]
> 02:25:41,837 DEBUG trace com.mchange.v2.resourcepool.BasicResourcePool at 427a39ea [managed: 1, unused: 0, excluded: 0] (e.g. com.mchange.v2.c3p0.impl.NewPooledConnection at 2ac6fb1)
> and so on.
--
This message is automatically generated by JIRA.
-
If you think it was sent incorrectly contact one of the administrators: https://jira.jboss.org/jira/secure/Administrators.jspa
-
For more information on JIRA, see: http://www.atlassian.com/software/jira
More information about the dna-issues
mailing list