Hi all, I've added a few logs to [1] turning it into [2]. The objective was to understand where we are leaking arbitrarily large amount of time in update operations. I can confirm that querying the DB and interacting with HTTP is nearly constant. Al the time is wasted between the "Starting updates" and "Completed updates" logs.
In some cases it takes a fair amount of time. (This behaviour would be perfect for us ~ .5 sec)
QUERY [MARCO]: Starting updates 5860 QUERY [MARCO]: Completed updates 6397
In some other it's acceptable ... (This can be tolerated if it doesn't apply too often ~ 3.2 secs)
QUERY [MARCO]: Starting updates 4650 QUERY [MARCO]: Completed updates 7832
But then there are cases when it definetely explodes (This is unacceptable ~15.5 sec)
QUERY [MARCO]: Starting updates 4650 QUERY [MARCO]: Completed updates 20362
The three examples occur more or less at the same time (in 2-3 minutes or so). I remind you that the pattern is very insertion intensive. There are two clients which read and write through RESTXQ to/from 2 different logical DBs on the same server. Is it possible that behaving concurrently we cause some sort of race condition that serializes operations for a long time period? Please help us out because it's getting to deeply nested into BaseX's internals for us to understand.
Thanks a lot and BR, Marco.
[1] https://github.com/BaseXdb/basex/blob/master/basex-core/src/main/java/org/ba... [2] public Iter iter() throws QueryException { compile();
long time = System.currentTimeMillis(); Util.errln("QUERY [MARCO]: Start query iter " + time);
try { [...] final Updates updates = resources.updates; if(updates != null) { // if parent context exists, updates will be performed by main context Util.errln("QUERY [MARCO]: Starting updates " + (System.currentTimeMillis() - time)); if(qcParent == null) { [...] Util.errln("QUERY [MARCO]: Completed updates " + (System.currentTimeMillis() - time)); } } Util.errln("QUERY [MARCO]: Completed query" + (System.currentTimeMillis() - time)); return cache;
} catch(final StackOverflowError ex) { [...] } }
On 22/02/2015 22:08, Marco Lettere wrote:
I'm planning to add some logging here [1] and here [2]. Do you think it will unleash some details? M.
[1] https://github.com/BaseXdb/basex/blob/master/basex-api/src/main/java/org/bas... [2] https://github.com/BaseXdb/basex/blob/master/basex-core/src/main/java/org/ba...
On 22/02/2015 20:05, Christian Grün wrote:
I'd like just to understand to what relates the huge difference (d) between "querying the db and scheduling an update to the PUL" which is what the internal function does and the time logged by the basexhttp server as the completion time of the whole RestXQ call which is T + d.
Hm, difficult to tell. In all cases, the PUL will be executed before the result of a query will be sent to the client.