I'm guessing that it's the multi-threaded option that is causing trouble. Something somewhere is not synchronized and it's using a stale value for the lock timeout.
Also turning off the log and then also turning on multithreaded is pretty much asking for a corrupt db at some point. If you are going to turn off the log you should either be ready for corruption or only use it to bulk load the db from a single thread, and then turn it back on again. On Wednesday, 18 June 2014, Steve Ash <stevem...@gmail.com> wrote: > The complete connection URL I am using is: > > jdbc:h2:%s;PAGE_SIZE=32768;CACHE_SIZE=262144;FILE_LOCK=NO;DB_CLOSE_DELAY=-1;COMPRESS_LOB=LZF;LOG=0;DEFAULT_LOCK_TIMEOUT=999999999;MAX_LENGTH_INPLACE_LOB=4096;MAX_MEMORY_ROWS=500000;LARGE_RESULT_BUFFER_SIZE=65536;MULTI_THREADED=1;DB_CLOSE_ON_EXIT=FALSE;JMX=TRUE > > I figured out why I was thinking it wasn't being set. I just set a > breakpoint in the Session constructor and when I hit that was inspecting > what was being pulled out of Database#findSetting(..). The first time this > breakpoint was being hit was trying to construct a session apparently > before any of my extra settings were being SET on the database. I guess H2 > uses this "primordial" session to do the SET updates? If I waited to > activate the breakpoint until right before my query that timed out then set > the breakpoint - I got the actual Session used for that statement, and it > did pull the correct default lock timeout out of the > Database#findSettings(). Sorry for the confusion. Unfortunately it still > doesn't explain how this lock timeout occurred, but I have a guess (below). > > Here is the full exception: > > 2014-06-17 10:01:00,821 ERROR ve-pair-profiling-linkloader-1 > link.LinkGraphLoader - Problem loading the link; isactive trx? true > org.hibernate.PessimisticLockException: could not extract ResultSet > at org.hibernate.dialect.H2Dialect$2.convert(H2Dialect.java:342) > at > org.hibernate.exception.internal.StandardSQLExceptionConverter.convert(StandardSQLExceptionConverter.java:49) > at > org.hibernate.engine.jdbc.spi.SqlExceptionHelper.convert(SqlExceptionHelper.java:126) > at > org.hibernate.engine.jdbc.spi.SqlExceptionHelper.convert(SqlExceptionHelper.java:112) > at > org.hibernate.engine.jdbc.internal.ResultSetReturnImpl.extract(ResultSetReturnImpl.java:89) > at org.hibernate.loader.Loader.getResultSet(Loader.java:2065) > at org.hibernate.loader.Loader.executeQueryStatement(Loader.java:1862) > at org.hibernate.loader.Loader.executeQueryStatement(Loader.java:1838) > at org.hibernate.loader.Loader.doQuery(Loader.java:909) > at > org.hibernate.loader.Loader.doQueryAndInitializeNonLazyCollections(Loader.java:354) > at org.hibernate.loader.Loader.doList(Loader.java:2553) > at org.hibernate.loader.Loader.doList(Loader.java:2539) > at org.hibernate.loader.Loader.listIgnoreQueryCache(Loader.java:2369) > at org.hibernate.loader.Loader.list(Loader.java:2364) > at org.hibernate.loader.hql.QueryLoader.list(QueryLoader.java:496) > at > org.hibernate.hql.internal.ast.QueryTranslatorImpl.list(QueryTranslatorImpl.java:387) > at > org.hibernate.engine.query.spi.HQLQueryPlan.performList(HQLQueryPlan.java:231) > at org.hibernate.internal.SessionImpl.list(SessionImpl.java:1264) > at org.hibernate.internal.QueryImpl.list(QueryImpl.java:103) > at > org.hibernate.internal.AbstractQueryImpl.uniqueResult(AbstractQueryImpl.java:966) > at > com.argodata.match.matching.analysis.link.LinkGraphDao.fetchGroupForEntity(LinkGraphDao.java:114) > at > com.argodata.match.matching.analysis.link.LinkGraphLoader.addLinkInTransaction(LinkGraphLoader.java:252) > at > com.argodata.match.matching.analysis.link.LinkGraphLoader.addLinkHoldingLocks(LinkGraphLoader.java:216) > at > com.argodata.match.matching.analysis.link.LinkGraphLoader.addLink(LinkGraphLoader.java:151) > at > com.argodata.match.profiling.profiling.AsyncPairProfilingLinkerCallback.loadLink(AsyncPairProfilingLinkerCallback.java:91) > at > com.argodata.match.profiling.profiling.AsyncPairProfilingLinkerCallback.access$3(AsyncPairProfilingLinkerCallback.java:90) > at > com.argodata.match.profiling.profiling.AsyncPairProfilingLinkerCallback$1.consume(AsyncPairProfilingLinkerCallback.java:68) > at > com.argodata.match.profiling.profiling.AsyncPairProfilingLinkerCallback$1.consume(AsyncPairProfilingLinkerCallback.java:1) > at > com.argodata.jcf.commons.concurrent.AdaptiveConsumerExecutor$PoolWorker.consumeWork(AdaptiveConsumerExecutor.java:228) > at > com.argodata.jcf.commons.concurrent.AdaptiveConsumerExecutor$PoolWorker.run(AdaptiveConsumerExecutor.java:201) > at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471) > at java.util.concurrent.FutureTask.run(FutureTask.java:262) > at > java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145) > at > java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615) > at java.lang.Thread.run(Thread.java:744) > Caused by: org.h2.jdbc.JdbcSQLException: Timeout trying to lock table > "LINKENTITY"; SQL statement: > select linkgroup0_.groupId as groupId1_1_, linkgroup0_.mergedTo as > mergedTo2_1_, linkgroup0_.status as status3_1_ from LinkGroup linkgroup0_ > cross join LinkEntity linkentity1_ where > linkentity1_.groupId=linkgroup0_.groupId and linkentity1_.id=? [50200-170] > at org.h2.message.DbException.getJdbcSQLException(DbException.java:329) > at org.h2.message.DbException.get(DbException.java:169) > at org.h2.message.DbException.get(DbException.java:146) > *at org.h2.table.RegularTable.doLock(RegularTable.java:501)* > * at org.h2.table.RegularTable.lock(RegularTable.java:435)* > at org.h2.table.TableFilter.lock(TableFilter.java:143) > at org.h2.command.dml.Select.queryWithoutCache(Select.java:604) > at org.h2.command.dml.Query.query(Query.java:307) > at org.h2.command.dml.Query.query(Query.java:277) > at org.h2.command.dml.Query.query(Query.java:36) > at org.h2.command.CommandContainer.query(CommandContainer.java:86) > at org.h2.command.Command.executeQuery(Command.java:191) > at > org.h2.jdbc.JdbcPreparedStatement.executeQuery(JdbcPreparedStatement.java:109) > at > com.mchange.v2.c3p0.impl.NewProxyPreparedStatement.executeQuery(NewProxyPreparedStatement.java:482) > at > org.hibernate.engine.jdbc.internal.ResultSetReturnImpl.extract(ResultSetReturnImpl.java:80) > ... 30 more > > I've looked at the doLock code and its so straightforward that there is > just no way to explain this stacktrace - unless - somehow the lock timeout > wasn't being set in the session correctly or something else was updating > it. Like I said, when I break in the debugger while its executing this > statement the lock timeout is getting passed in correctly. > > It's worth mentioning that this happened on a 32 core server, which had > been doing contentious work for over 45 minutes before, which should've hit > lock timeouts > 2 seconds before (2-3 threads fighting to insert records in > to a few tables that all have secondary indexes). > > I haven't dug through all of the code related to parsing the connection > URL, but Im guessing that all of the extra settings passed in to the URL > are going through the Set update dml code to get them set in the > Database#settings map. My app is going to be requesting a lot of > connections concurrently when it starts doing work. Is is plausible that > somehow the first created connections (with associated Sessions) are racing > with each other to call SET for all of the extra settings in the db url? > And somehow some connections are getting out (with constructed Sessions) > that are seeing the default lock timeout before the SETs have all happened? > This would explain the non-determinism and why its hard for me to > replicate, and why I can't see any Sessions with incorrect lock timeouts on > my machine. It would also explain why it was able to work for so long: if > there were 30ish connections in the connection pool and only 1 had this > wrong timeout, then probability of getting that one is 1/32 + prob of > exceeding 2 second lock wait... maybe thats low enough that it didn't > happen in the first 45 mins. > > Going off of this wild guess: I added LOCK_TIMEOUT=999999999 to the > connection URL (without any valid reason to do so) as well as added a c3p0 > connection customizer to actually call SET LOCK_TIMEOUT on the actual > connection on checkout before it ever goes to hibernate. With both of > these we've been able to run the workload a few times now without any lock > timeouts. Not willing to call it solved yet, but interesting. Does that > theory have any chance of being correct? I'm on 1.3.170 perhaps I need to > upgrade (and just turn off MVStore) > > Thanks, > Steve > > On Tuesday, June 17, 2014 1:50:44 PM UTC-5, Steve Ash wrote: >> >> I am using H2 1.3.170 and am getting lock timeout errors while waiting >> for shared locks. It is coming out of RegularTable.tryLock(). I have set >> DEFAULT_LOCK_TIMEOUT and LOCK_TIMEOUT (not sure what is the difference in >> the two) on the connection url and (at least for default lock timeout can >> see it in INFORMATION_SCHEMA.settings as updated). In the constructor for >> Session I see the lines: >> >> Setting setting = database.findSetting(SetTypes. >> getTypeName(SetTypes.DEFAULT_LOCK_TIMEOUT)); >> this.lockTimeout = setting == null ? Constants.INITIAL_LOCK_TIMEOUT : >> setting.getIntValue(); >> >> This database.findSetting is never getting my lock settings back and thus >> it is always defaulting to INITIAL_LOCK_TIMEOUT of 2000 ms. When I look in >> database.findSettings -- I dont see anywhere that actually populates this >> settings map. >> >> What am I missing here? >> > -- > You received this message because you are subscribed to the Google Groups > "H2 Database" group. > To unsubscribe from this group and stop receiving emails from it, send an > email to h2-database+unsubscr...@googlegroups.com > <javascript:_e(%7B%7D,'cvml','h2-database%2bunsubscr...@googlegroups.com');> > . > To post to this group, send email to h2-database@googlegroups.com > <javascript:_e(%7B%7D,'cvml','h2-database@googlegroups.com');>. > Visit this group at http://groups.google.com/group/h2-database. > For more options, visit https://groups.google.com/d/optout. > -- You received this message because you are subscribed to the Google Groups "H2 Database" group. To unsubscribe from this group and stop receiving emails from it, send an email to h2-database+unsubscr...@googlegroups.com. To post to this group, send email to h2-database@googlegroups.com. Visit this group at http://groups.google.com/group/h2-database. For more options, visit https://groups.google.com/d/optout.
