ERXExistsQualifier blocks *all coordinators* even before a SELECT?!?
ERXExistsQualifier blocks *all coordinators* even before a SELECT?!?
- Subject: ERXExistsQualifier blocks *all coordinators* even before a SELECT?!?
- From: "email@hidden" <email@hidden>
- Date: Thu, 13 Oct 2016 18:26:41 +0200
Hello there,
just the very now, I have bumped into a weird problem.
I run some DB-intensive background tasks. So as they do not block the whole application, I set up er.extensions.ERXObjectStoreCoordinatorPool.maxCoordinators > 1, and my code
(a) gives one of the coordinators to all sessions (through sess.defaultEditingContext=ERXEC.newEditingContext(osc))
Since sessions rarely or never do long selects/inserts/whatever, there's no harm they share the coordinator.
(b) the background threads each get one of the remaining coordinators
Thus, the background threads (which _do_ _very_ long selects; actually, they do ERXEOControlUtilities.objectCountWithQualifier, involving joins) might block one another, but never block the sessions.
So far, it worked well. Today, in session, I used the ERXExistsQualifier -- and it looks like its usage blocks somehow until the background threads (which use different coordinators -- I did check) are done?!?
To me, it does not make any sense, but it works like this -- the following code (where qualifiedEOsSVM is just a thin shell over objectsWithFetchSpecification)
=== 1 ===
def me=new EOKeyValueQualifier('user',EOQualifier.QualifierOperatorEqual,session.currentUser)
def hasme=new ERXExistsQualifier(me,'userLinks')
Log "FETCH STARTS ..."
all=DBGenGeneratedItem.qualifiedEOsSVM(DBGenGeneratedItem, hasme, session.defaultEditingContext())
Log "...FETCH ENDS"
===
logs out something like this -- always the delay betw. the 1st and 2nd log (here about 4 seconds) is big, and always it is full of the thread logs:
=== 1 log ===
18:09:42.129 WARN FETCH STARTS... //log:NSLog [WorkerThread11]
... lots of “background-thread-did-end” logs here ...
18:09:46.936 DEBUG === Begin Internal Transaction //log:NSLog [WorkerThread11]
18:09:46.936 DEBUG evaluateExpression: ... proper one with EXISTS ... //log:NSLog [WorkerThread11]
18:09:46.938 DEBUG 5 row(s) processed //log:NSLog [WorkerThread11]
18:09:46.938 DEBUG === Commit Internal Transaction //log:NSLog [WorkerThread11]
18:09:46.944 WARN ... FETCH DID END //log:NSLog [WorkerThread11]
===
If I do not launch the threads at all, the log is always as expected, i.e., something like this (compare the delay)
=== 1 log, no background threads exist ===
18:14:35.079 WARN FETCH STARTS... //log:NSLog [WorkerThread4]
18:14:35.080 DEBUG === Begin Internal Transaction //log:NSLog [WorkerThread4]
===
If, instead of using the ERXExistsQualifier, I simply fetch all the rows and filter them programmatically, something like
=== 2 ===
def fs=new EOFetchSpecification('DBGenGeneratedItem',null,null)
NSLog.err.appendln "FETCH STARTS..."
all=session.defaultEditingContext().objectsWithFetchSpecification(fs)
NSLog.err.appendln "... FETCH DID END, FILTERING ..."
all=all.findAll {
it.userLinks.find { sess.currentUser==it.user }
}
NSLog.err.appendln "... FETCH AND FILTER DID END"
===
and run all the background threads as usually, _there is no delay again_, the log looks like this:
=== 2 log ===
18:18:49.722 WARN FETCH STARTS... //log:NSLog [WorkerThread8]
18:18:49.722 DEBUG === Begin Internal Transaction //log:NSLog [WorkerThread8]
18:18:49.722 DEBUG evaluateExpression: ... SIMPLE ONE ... //log:NSLog [WorkerThread8]
18:18:49.723 DEBUG 6 row(s) processed //log:NSLog [WorkerThread8]
18:18:49.723 DEBUG === Commit Internal Transaction //log:NSLog [WorkerThread8]
18:18:49.731 WARN ... FETCH DID END, FILTERING ... //log:NSLog [WorkerThread8]
18:18:49.737 DEBUG === Begin Internal Transaction //log:NSLog [WorkerThread8]
18:18:49.737 DEBUG evaluateExpression: ... SELECTing userLinks for 1st item ... //log:NSLog [WorkerThread8]
18:18:49.738 DEBUG 0 row(s) processed //log:NSLog [WorkerThread8]
18:18:49.738 DEBUG === Commit Internal Transaction //log:NSLog [WorkerThread8]
... etc, other SQL transactions to select userLinks for the other items when filtering ...
18:18:49.750 WARN ... FETCH AND FILTER DID END //log:NSLog [WorkerThread8]
... lots of “background-thread-did-end” logs here ...
===
I must frankly admit I have no idea what the darn happens there -- it looks like there is some weird ERXExistsQualifier pre-processing, which waits for all the background threads which fetch inside different store coordinators?!?
Does it make any sense?
Thanks for any advice,
OC
_______________________________________________
Do not post admin requests to the list. They will be ignored.
Webobjects-dev mailing list (email@hidden)
Help/Unsubscribe/Update your Subscription:
This email sent to email@hidden