search

openhab / openhab1-addons

Add-ons for openHAB 1.x
Eclipse Public License 2.0
3.43k stars 1.71k forks source link

[Persistence] Deadlock with MySQL Persistence #5592

Open ghmartin77 opened 6 years ago

ghmartin77 commented 6 years ago

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

edman007 commented 5 years ago

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)

lewie commented 5 years ago

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

edman007 commented 5 years ago

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

9037568 commented 5 years ago

@ghmartin77 can you try running with the latest version and let us know if it fixes your issue?

ghmartin77 commented 5 years ago

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.

9037568 commented 5 years ago

Don't worry if you can't get to it. We'll leave this open a little while longer in case you can.