openhab1-addons
openhab1-addons copied to clipboard
Published
20 hours ago •
openhab
openhab
[Persistence] Deadlock with MySQL Persistence
Setup: OpenHAB 2.2.0 MQTT Broker (receiving power consumption updates about every 1-4 seconds) MySQL Persistence HABPanel with interactive=true mysql charts of power consumption value
After a while OpenHAB doesn't fully react on HTTP requests. "kill -3" gives (only relevant part):
Found one Java-level deadlock:
=============================
"qtp20620470-16320":
waiting to lock monitor 0x631b4fd0 (object 0x6d7aeab0, a com.mysql.jdbc.JDBC4Connection),
which is held by "items-92"
"items-92":
waiting to lock monitor 0x014bcdf8 (object 0x6d7cb990, a java.util.GregorianCalendar),
which is held by "qtp20620470-15134"
"qtp20620470-15134":
waiting to lock monitor 0x631b4fd0 (object 0x6d7aeab0, a com.mysql.jdbc.JDBC4Connection),
which is held by "items-92"
Java stack information for the threads listed above:
===================================================
"qtp20620470-16320":
at com.mysql.jdbc.JDBC4Connection.isValid(JDBC4Connection.java:94)
- waiting to lock <0x6d7aeab0> (a com.mysql.jdbc.JDBC4Connection)
at org.openhab.persistence.mysql.internal.MysqlPersistenceService.isConnected(MysqlPersistenceService.java:492)
at org.openhab.persistence.mysql.internal.MysqlPersistenceService.query(MysqlPersistenceService.java:598)
at org.openhab.core.persistence.internal.QueryablePersistenceServiceDelegate.query(QueryablePersistenceServiceDelegate.java:47)
at org.eclipse.smarthome.io.rest.core.internal.persistence.PersistenceResource.getItemHistoryDTO(PersistenceResource.java:274)
at org.eclipse.smarthome.io.rest.core.internal.persistence.PersistenceResource.httpGetPersistenceItemData(PersistenceResource.java:162)
at sun.reflect.GeneratedMethodAccessor61.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:498)
at org.glassfish.jersey.server.model.internal.ResourceMethodInvocationHandlerFactory$1.invoke(ResourceMethodInvocationHandlerFactory.java:81)
at org.glassfish.jersey.server.model.internal.AbstractJavaResourceMethodDispatcher$1.run(AbstractJavaResourceMethodDispatcher.java:144)
at org.glassfish.jersey.server.model.internal.AbstractJavaResourceMethodDispatcher.invoke(AbstractJavaResourceMethodDispatcher.java:161)
at org.glassfish.jersey.server.model.internal.JavaResourceMethodDispatcherProvider$ResponseOutInvoker.doDispatch(JavaResourceMethodDispatcherProvider.java:160)
at org.glassfish.jersey.server.model.internal.AbstractJavaResourceMethodDispatcher.dispatch(AbstractJavaResourceMethodDispatcher.java:99)
at org.glassfish.jersey.server.model.ResourceMethodInvoker.invoke(ResourceMethodInvoker.java:389)
at org.glassfish.jersey.server.model.ResourceMethodInvoker.apply(ResourceMethodInvoker.java:347)
at org.glassfish.jersey.server.model.ResourceMethodInvoker.apply(ResourceMethodInvoker.java:102)
at org.glassfish.jersey.server.ServerRuntime$2.run(ServerRuntime.java:326)
at org.glassfish.jersey.internal.Errors$1.call(Errors.java:271)
at org.glassfish.jersey.internal.Errors$1.call(Errors.java:267)
at org.glassfish.jersey.internal.Errors.process(Errors.java:315)
at org.glassfish.jersey.internal.Errors.process(Errors.java:297)
at org.glassfish.jersey.internal.Errors.process(Errors.java:267)
at org.glassfish.jersey.process.internal.RequestScope.runInScope(RequestScope.java:317)
at org.glassfish.jersey.server.ServerRuntime.process(ServerRuntime.java:305)
at org.glassfish.jersey.server.ApplicationHandler.handle(ApplicationHandler.java:1154)
at org.glassfish.jersey.servlet.WebComponent.serviceImpl(WebComponent.java:473)
at org.glassfish.jersey.servlet.WebComponent.service(WebComponent.java:427)
at org.glassfish.jersey.servlet.ServletContainer.service(ServletContainer.java:388)
at org.glassfish.jersey.servlet.ServletContainer.service(ServletContainer.java:341)
at org.glassfish.jersey.servlet.ServletContainer.service(ServletContainer.java:228)
at com.eclipsesource.jaxrs.publisher.internal.ServletContainerBridge.service(ServletContainerBridge.java:76)
at org.eclipse.jetty.servlet.ServletHolder.handle(ServletHolder.java:848)
at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:584)
at org.ops4j.pax.web.service.jetty.internal.HttpServiceServletHandler.doHandle(HttpServiceServletHandler.java:71)
at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:143)
at org.eclipse.jetty.security.SecurityHandler.handle(SecurityHandler.java:548)
at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:226)
at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1180)
at org.ops4j.pax.web.service.jetty.internal.HttpServiceContext.doHandle(HttpServiceContext.java:284)
at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:512)
at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:185)
at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1112)
at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:141)
at org.ops4j.pax.web.service.jetty.internal.JettyServerHandlerCollection.handle(JettyServerHandlerCollection.java:80)
at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:134)
at org.eclipse.jetty.server.Server.handle(Server.java:534)
at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:333)
at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:251)
at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:283)
at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:108)
at org.eclipse.jetty.io.SelectChannelEndPoint$2.run(SelectChannelEndPoint.java:93)
at org.eclipse.jetty.util.thread.strategy.ExecuteProduceConsume.executeProduceConsume(ExecuteProduceConsume.java:303)
at org.eclipse.jetty.util.thread.strategy.ExecuteProduceConsume.produceConsume(ExecuteProduceConsume.java:148)
at org.eclipse.jetty.util.thread.strategy.ExecuteProduceConsume.run(ExecuteProduceConsume.java:136)
at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:671)
at org.eclipse.jetty.util.thread.QueuedThreadPool$2.run(QueuedThreadPool.java:589)
at java.lang.Thread.run(Thread.java:748)
"items-92":
at com.mysql.jdbc.PreparedStatement.setTimestampInternal(PreparedStatement.java:4821)
- waiting to lock <0x6d7cb990> (a java.util.GregorianCalendar)
- locked <0x6d7aeab0> (a com.mysql.jdbc.JDBC4Connection)
at com.mysql.jdbc.PreparedStatement.setTimestamp(PreparedStatement.java:4787)
at org.openhab.persistence.mysql.internal.MysqlPersistenceService.store(MysqlPersistenceService.java:442)
at org.openhab.core.persistence.internal.PersistenceServiceDelegate.store(PersistenceServiceDelegate.java:55)
at org.eclipse.smarthome.core.persistence.internal.PersistenceManagerImpl.handleStateEvent(PersistenceManagerImpl.java:131)
- locked <0x6bcbfee0> (a java.util.HashMap)
at org.eclipse.smarthome.core.persistence.internal.PersistenceManagerImpl.stateChanged(PersistenceManagerImpl.java:432)
at org.eclipse.smarthome.core.items.GenericItem$1.run(GenericItem.java:234)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
at java.lang.Thread.run(Thread.java:748)
"qtp20620470-15134":
at com.mysql.jdbc.ResultSetImpl.fastTimestampCreate(ResultSetImpl.java:1067)
- waiting to lock <0x6d7aeab0> (a com.mysql.jdbc.JDBC4Connection)
at com.mysql.jdbc.ResultSetRow.getTimestampFast(ResultSetRow.java:1393)
- locked <0x6d7cb990> (a java.util.GregorianCalendar)
at com.mysql.jdbc.ByteArrayRow.getTimestampFast(ByteArrayRow.java:127)
at com.mysql.jdbc.ResultSetImpl.getTimestampInternal(ResultSetImpl.java:6592)
at com.mysql.jdbc.ResultSetImpl.getTimestamp(ResultSetImpl.java:6192)
at org.openhab.persistence.mysql.internal.MysqlPersistenceService.query(MysqlPersistenceService.java:710)
at org.openhab.core.persistence.internal.QueryablePersistenceServiceDelegate.query(QueryablePersistenceServiceDelegate.java:47)
at org.eclipse.smarthome.io.rest.core.internal.persistence.PersistenceResource.getItemHistoryDTO(PersistenceResource.java:274)
at org.eclipse.smarthome.io.rest.core.internal.persistence.PersistenceResource.httpGetPersistenceItemData(PersistenceResource.java:162)
at sun.reflect.GeneratedMethodAccessor61.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:498)
at org.glassfish.jersey.server.model.internal.ResourceMethodInvocationHandlerFactory$1.invoke(ResourceMethodInvocationHandlerFactory.java:81)
at org.glassfish.jersey.server.model.internal.AbstractJavaResourceMethodDispatcher$1.run(AbstractJavaResourceMethodDispatcher.java:144)
at org.glassfish.jersey.server.model.internal.AbstractJavaResourceMethodDispatcher.invoke(AbstractJavaResourceMethodDispatcher.java:161)
at org.glassfish.jersey.server.model.internal.JavaResourceMethodDispatcherProvider$ResponseOutInvoker.doDispatch(JavaResourceMethodDispatcherProvider.java:160)
at org.glassfish.jersey.server.model.internal.AbstractJavaResourceMethodDispatcher.dispatch(AbstractJavaResourceMethodDispatcher.java:99)
at org.glassfish.jersey.server.model.ResourceMethodInvoker.invoke(ResourceMethodInvoker.java:389)
at org.glassfish.jersey.server.model.ResourceMethodInvoker.apply(ResourceMethodInvoker.java:347)
at org.glassfish.jersey.server.model.ResourceMethodInvoker.apply(ResourceMethodInvoker.java:102)
at org.glassfish.jersey.server.ServerRuntime$2.run(ServerRuntime.java:326)
at org.glassfish.jersey.internal.Errors$1.call(Errors.java:271)
at org.glassfish.jersey.internal.Errors$1.call(Errors.java:267)
at org.glassfish.jersey.internal.Errors.process(Errors.java:315)
at org.glassfish.jersey.internal.Errors.process(Errors.java:297)
at org.glassfish.jersey.internal.Errors.process(Errors.java:267)
at org.glassfish.jersey.process.internal.RequestScope.runInScope(RequestScope.java:317)
at org.glassfish.jersey.server.ServerRuntime.process(ServerRuntime.java:305)
at org.glassfish.jersey.server.ApplicationHandler.handle(ApplicationHandler.java:1154)
at org.glassfish.jersey.servlet.WebComponent.serviceImpl(WebComponent.java:473)
at org.glassfish.jersey.servlet.WebComponent.service(WebComponent.java:427)
at org.glassfish.jersey.servlet.ServletContainer.service(ServletContainer.java:388)
at org.glassfish.jersey.servlet.ServletContainer.service(ServletContainer.java:341)
at org.glassfish.jersey.servlet.ServletContainer.service(ServletContainer.java:228)
at com.eclipsesource.jaxrs.publisher.internal.ServletContainerBridge.service(ServletContainerBridge.java:76)
at org.eclipse.jetty.servlet.ServletHolder.handle(ServletHolder.java:848)
at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:584)
at org.ops4j.pax.web.service.jetty.internal.HttpServiceServletHandler.doHandle(HttpServiceServletHandler.java:71)
at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:143)
at org.eclipse.jetty.security.SecurityHandler.handle(SecurityHandler.java:548)
at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:226)
at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1180)
at org.ops4j.pax.web.service.jetty.internal.HttpServiceContext.doHandle(HttpServiceContext.java:284)
at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:512)
at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:185)
at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1112)
at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:141)
at org.ops4j.pax.web.service.jetty.internal.JettyServerHandlerCollection.handle(JettyServerHandlerCollection.java:80)
at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:134)
at org.eclipse.jetty.server.Server.handle(Server.java:534)
at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:333)
at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:251)
at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:283)
at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:108)
at org.eclipse.jetty.io.SelectChannelEndPoint$2.run(SelectChannelEndPoint.java:93)
at org.eclipse.jetty.util.thread.strategy.ExecuteProduceConsume.executeProduceConsume(ExecuteProduceConsume.java:303)
at org.eclipse.jetty.util.thread.strategy.ExecuteProduceConsume.produceConsume(ExecuteProduceConsume.java:148)
at org.eclipse.jetty.util.thread.strategy.ExecuteProduceConsume.run(ExecuteProduceConsume.java:136)
at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:671)
at org.eclipse.jetty.util.thread.QueuedThreadPool$2.run(QueuedThreadPool.java:589)
at java.lang.Thread.run(Thread.java:748)
Found 1 deadlock.
Guessing from the stacktrace I'm currently trying to run services/mysql.cfg with "localtime=false". Running for ~8 hours now without any further hickup. Maybe you'd like to track down the deadlock, anyway. If you'd need further details, please let me know.
Best, ghmartin77
Hey, same issue here, and I think I found the issue, it's a mysql connector bug, specifically I am running the binary stable distribution for raspbian (2.3.0-1), from https://dl.bintray.com/openhab/apt-repo2 and this is what I see openhab using:
$ find /var/lib/openhab2/ -name mysql-connector-java*
/var/lib/openhab2/cache/org.eclipse.osgi/234/0/.cp/lib/mysql-connector-java-5.1.26-bin.jar
/var/lib/openhab2/tmp/kar/openhab-addons-2.3.0/mysql/mysql-connector-java
/var/lib/openhab2/tmp/kar/openhab-addons-2.3.0/mysql/mysql-connector-java/5.1.38/mysql-connector-java-5.1.38.jar
However, according to this bug, https://bugs.mysql.com/bug.php?id=67760 mysql-connector-java violates the JDBC spec prior to 5.1.35, and by running openhab with -verbose:classname it's clear that 5.1.26 is the one used by openhab, and it does NOT use the system one (in my case 5.1.42 is installed as a system library).
I'm trying to find out where the build scripts for these deb files are, I believe the issue is that the connector just needs to be upgraded (so just the build script needs a version adjusted), I don't really know where it is though (I assume buried inside some jar provided by the binary openhab distro)
JDBC Binding is the replacement of the old MySql only JDBC Binding! https://github.com/openhab/openhab1-addons/tree/master/bundles/persistence/org.openhab.persistence.mysql mysql-connector-java-5.1.26-bin.jar: https://github.com/openhab/openhab1-addons/tree/master/bundles/persistence/org.openhab.persistence.mysql/lib
Why not using JDBC Binding with Mysql. It is It is fully compatible, more modern and faster. Currently loads mysql-connector-java-5.1.39.jar https://github.com/openhab/openhab1-addons/tree/master/bundles/persistence/org.openhab.persistence.jdbc
To use an existing database of the old MySql binding with JDBC binding, see: https://www.openhab.org/addons/persistence/jdbc/#configuration
Just wanted to say, I applied the merged from this bug and I've been running for over a month without a crash.
https://github.com/openhab/openhab1-addons/pull/5699
@ghmartin77 can you try running with the latest version and let us know if it fixes your issue?
I meanwhile followed lewie's recommendation and switched to JDBC Binding using MySQL >= 5.1.39 plus moved on to OpenHAB 2.3.0. Cannot switch back easily (different table structure) without breaking my current installation. If I have some sparetime I'll give it a try, though.
Don't worry if you can't get to it. We'll leave this open a little while longer in case you can.