Setup

  1. Version of Fedora

    1. 7477d568e3748381939d03e65d183fdd364590 (2016-06-06, 4.5.2-SNAPSHOT)

    2. Modeshape5
  2. Fedora configuration details

    1. /etc/default/tomcat7

      JAVA_OPTS="-Djava.awt.headless=true"
JAVA_OPTS="${JAVA_OPTS} -XX:+DisableExplicitGC"
JAVA_OPTS="${JAVA_OPTS} -Xms512m"
JAVA_OPTS="${JAVA_OPTS} -Xmx6g"
JAVA_OPTS="${JAVA_OPTS} -XX:NewSize=256m"
JAVA_OPTS="${JAVA_OPTS} -XX:MaxNewSize=2g"
JAVA_OPTS="${JAVA_OPTS} -XX:MetaspaceSize=64m"
JAVA_OPTS="${JAVA_OPTS} -XX:MaxMetaspaceSize=2g"
JAVA_OPTS="${JAVA_OPTS} -Dfile.encoding=UTF-8"
JAVA_OPTS="${JAVA_OPTS} -Xloggc:/var/log/tomcat7/java-gc.log"
JAVA_OPTS="${JAVA_OPTS} -XX:+PrintGCDetails"
JAVA_OPTS="${JAVA_OPTS} -XX:+PrintGCDateStamps"
JAVA_OPTS="${JAVA_OPTS} -Dfcrepo.home=/data/test"
JAVA_OPTS="${JAVA_OPTS} -Dfcrepo.mysql.username=root"
JAVA_OPTS="${JAVA_OPTS} -Dfcrepo.mysql.password=password"
JAVA_OPTS="${JAVA_OPTS} -Dfcrepo.mysql.host=localhost"
JAVA_OPTS="${JAVA_OPTS} -Dfcrepo.mysql.port=3306"
JAVA_OPTS="${JAVA_OPTS} -Dfcrepo.modeshape.configuration=classpath:/config/jdbc-mysql/repository.json"
JAVA_OPTS="${JAVA_OPTS} -agentpath:/home/nruest/yjp-2016.02/bin/linux-x86-64/libyjpagent.so=delay=10000"
JAVA_OPTS="${JAVA_OPTS} -Dfcrepo.modeshape.configuration=classpath:/config/jdbc-mysql/repository.json"
  3. System details (OS, memory, processors, hardware specs or virtualization, JVM, etc)
    1. Virtual server; 8GiB memory, 2 virutal cpus, fcrepo data is a NFS mount

    2. Ubuntu 14.04.4 LTS

    3. MySQL (Ver 14.14 Distrib 5.5.49, for debian-linux-gnu (x86_64) using readline 6.3)
      1. MySQL data directory was on NFS mount
  4. Initial state of the repository
    1. empty
  5. Number of client processes/threads (ideally clients are on a separate machine)
    1. 1
    2. JMeter client on separate machine

Test

Remote:

./jmeter -Dfedora_4_server=zeta.library.yorku.ca -Dfedora_4_context=fcrepo/rest -Dfilesize_min=10240 -Dfilesize_max=102400 -Dbinary_threads=1 -n -t /home/nruest/git/fcrepo4-jmeter/fedora.jmx >>| /home/nruest/tmp/yorku-test-3-mysql-summary.log

 

Results

summary = 1338426 in 294189s =    4.5/s Avg:   213 Min:     4 Max: 18031 Err:     1 (0.00%)

jmeter.log

yorku-test-3-mysql-summary.log

WARN 21:44:07.378 (ProxyConnection) HikariPool-0 - Connection com.mysql.jdbc.JDBC4Connection@40e9318d marked as broken because of SQLSTATE(08S01), ErrorCode(0)
com.mysql.jdbc.exceptions.jdbc4.CommunicationsException: Communications link failure

The last packet successfully received from the server was 9,630 milliseconds ago.  The last packet sent successfully to the server was 9,630 milliseconds ago.
    at sun.reflect.GeneratedConstructorAccessor69.newInstance(Unknown Source) ~[na:na]
    at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45) ~[na:1.8.0_91]
    at java.lang.reflect.Constructor.newInstance(Constructor.java:423) ~[na:1.8.0_91]
    at com.mysql.jdbc.Util.handleNewInstance(Util.java:404) ~[mysql-connector-java-5.1.38.jar:5.1.38]
    at com.mysql.jdbc.SQLError.createCommunicationsException(SQLError.java:981) ~[mysql-connector-java-5.1.38.jar:5.1.38]
    at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:3465) ~[mysql-connector-java-5.1.38.jar:5.1.38]
    at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:3365) ~[mysql-connector-java-5.1.38.jar:5.1.38]
    at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:3805) ~[mysql-connector-java-5.1.38.jar:5.1.38]
    at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:2478) ~[mysql-connector-java-5.1.38.jar:5.1.38]
    at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:2625) ~[mysql-connector-java-5.1.38.jar:5.1.38]
    at com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2551) ~[mysql-connector-java-5.1.38.jar:5.1.38]
    at com.mysql.jdbc.PreparedStatement.executeInternal(PreparedStatement.java:1861) ~[mysql-connector-java-5.1.38.jar:5.1.38]
    at com.mysql.jdbc.PreparedStatement.executeQuery(PreparedStatement.java:1962) ~[mysql-connector-java-5.1.38.jar:5.1.38]
    at com.zaxxer.hikari.pool.ProxyPreparedStatement.executeQuery(ProxyPreparedStatement.java:52) ~[HikariCP-2.4.3.jar:na]
    at com.zaxxer.hikari.pool.HikariProxyPreparedStatement.executeQuery(HikariProxyPreparedStatement.java) [HikariCP-2.4.3.jar:na]
    at org.modeshape.persistence.relational.DefaultStatements.loadIDs(DefaultStatements.java:140) [modeshape-persistence-relational-5.0.0.Final.jar:5.0.0.Final]
    at org.modeshape.persistence.relational.DefaultStatements.lambda$load$0(DefaultStatements.java:123) [modeshape-persistence-relational-5.0.0.Final.jar:5.0.0.Final]
    at org.modeshape.persistence.relational.DefaultStatements.runBatchOperation(DefaultStatements.java:216) [modeshape-persistence-relational-5.0.0.Final.jar:5.0.0.Final]
    at org.modeshape.persistence.relational.DefaultStatements.load(DefaultStatements.java:122) [modeshape-persistence-relational-5.0.0.Final.jar:5.0.0.Final]
    at org.modeshape.persistence.relational.RelationalDb.lambda$load$13(RelationalDb.java:187) ~[modeshape-persistence-relational-5.0.0.Final.jar:5.0.0.Final]
    at org.modeshape.persistence.relational.RelationalDb.runWithConnection(RelationalDb.java:353) ~[modeshape-persistence-relational-5.0.0.Final.jar:5.0.0.Final]
    at org.modeshape.persistence.relational.RelationalDb.load(RelationalDb.java:187) ~[modeshape-persistence-relational-5.0.0.Final.jar:5.0.0.Final]
    at org.modeshape.jcr.cache.document.LocalDocumentStore.load(LocalDocumentStore.java:82) ~[modeshape-jcr-5.0.0.Final.jar:5.0.0.Final]
    at org.modeshape.jcr.cache.document.WorkspaceCache.loadFromDocumentStore(WorkspaceCache.java:336) ~[modeshape-jcr-5.0.0.Final.jar:5.0.0.Final]
    at org.modeshape.jcr.cache.document.WritableSessionCache.lockNodes(WritableSessionCache.java:1565) ~[modeshape-jcr-5.0.0.Final.jar:5.0.0.Final]
    at org.modeshape.jcr.cache.document.WritableSessionCache.save(WritableSessionCache.java:707) ~[modeshape-jcr-5.0.0.Final.jar:5.0.0.Final]
    at org.modeshape.jcr.JcrSession.save(JcrSession.java:1162) ~[modeshape-jcr-5.0.0.Final.jar:5.0.0.Final]
    at org.fcrepo.http.api.FedoraLdp.createObject(FedoraLdp.java:573) ~[fcrepo-http-api-4.5.2-SNAPSHOT.jar:4.5.2-SNAPSHOT]
    at sun.reflect.GeneratedMethodAccessor36.invoke(Unknown Source) ~[na:na]
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[na:1.8.0_91]
    at java.lang.reflect.Method.invoke(Method.java:498) ~[na:1.8.0_91]
    at org.glassfish.jersey.server.model.internal.ResourceMethodInvocationHandlerFactory$1.invoke(ResourceMethodInvocationHandlerFactory.java:81) ~[jersey-server-2.22.2.jar:na]
    at org.glassfish.jersey.server.model.internal.AbstractJavaResourceMethodDispatcher$1.run(AbstractJavaResourceMethodDispatcher.java:144) ~[jersey-server-2.22.2.jar:na]
    at org.glassfish.jersey.server.model.internal.AbstractJavaResourceMethodDispatcher.invoke(AbstractJavaResourceMethodDispatcher.java:161) ~[jersey-server-2.22.2.jar:na]
    at org.glassfish.jersey.server.model.internal.JavaResourceMethodDispatcherProvider$ResponseOutInvoker.doDispatch(JavaResourceMethodDispatcherProvider.java:160) ~[jersey-server-2.22.2.jar:na]
    at org.glassfish.jersey.server.model.internal.AbstractJavaResourceMethodDispatcher.dispatch(AbstractJavaResourceMethodDispatcher.java:99) ~[jersey-server-2.22.2.jar:na]
    at org.glassfish.jersey.server.model.ResourceMethodInvoker.invoke(ResourceMethodInvoker.java:389) ~[jersey-server-2.22.2.jar:na]
    at org.glassfish.jersey.server.model.ResourceMethodInvoker.apply(ResourceMethodInvoker.java:347) ~[jersey-server-2.22.2.jar:na]
    at org.glassfish.jersey.server.model.ResourceMethodInvoker.apply(ResourceMethodInvoker.java:102) ~[jersey-server-2.22.2.jar:na]
    at org.glassfish.jersey.server.ServerRuntime$2.run(ServerRuntime.java:326) ~[jersey-server-2.22.2.jar:na]
    at org.glassfish.jersey.internal.Errors$1.call(Errors.java:271) ~[jersey-common-2.22.2.jar:na]
    at org.glassfish.jersey.internal.Errors$1.call(Errors.java:267) ~[jersey-common-2.22.2.jar:na]
    at org.glassfish.jersey.internal.Errors.process(Errors.java:315) ~[jersey-common-2.22.2.jar:na]
    at org.glassfish.jersey.internal.Errors.process(Errors.java:297) ~[jersey-common-2.22.2.jar:na]
    at org.glassfish.jersey.internal.Errors.process(Errors.java:267) ~[jersey-common-2.22.2.jar:na]
    at org.glassfish.jersey.process.internal.RequestScope.runInScope(RequestScope.java:317) ~[jersey-common-2.22.2.jar:na]
    at org.glassfish.jersey.server.ServerRuntime.process(ServerRuntime.java:305) ~[jersey-server-2.22.2.jar:na]
    at org.glassfish.jersey.server.ApplicationHandler.handle(ApplicationHandler.java:1154) ~[jersey-server-2.22.2.jar:na]
    at org.glassfish.jersey.servlet.WebComponent.serviceImpl(WebComponent.java:473) ~[jersey-container-servlet-core-2.22.2.jar:na]
    at org.glassfish.jersey.servlet.WebComponent.service(WebComponent.java:427) ~[jersey-container-servlet-core-2.22.2.jar:na]
    at org.glassfish.jersey.servlet.ServletContainer.service(ServletContainer.java:388) ~[jersey-container-servlet-core-2.22.2.jar:na]
    at org.glassfish.jersey.servlet.ServletContainer.service(ServletContainer.java:341) ~[jersey-container-servlet-core-2.22.2.jar:na]
    at org.glassfish.jersey.servlet.ServletContainer.service(ServletContainer.java:228) ~[jersey-container-servlet-core-2.22.2.jar:na]
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:303) ~[tomcat-catalina-7.0.52.jar:7.0.52]
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:208) ~[tomcat-catalina-7.0.52.jar:7.0.52]
    at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:220) ~[tomcat-catalina-7.0.52.jar:7.0.52]
    at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:122) ~[tomcat-catalina-7.0.52.jar:7.0.52]
    at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:501) ~[tomcat-catalina-7.0.52.jar:7.0.52]
    at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:170) ~[tomcat-catalina-7.0.52.jar:7.0.52]
    at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:98) ~[tomcat-catalina-7.0.52.jar:7.0.52]
    at org.apache.catalina.valves.AccessLogValve.invoke(AccessLogValve.java:950) ~[tomcat-catalina-7.0.52.jar:7.0.52]
    at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:116) ~[tomcat-catalina-7.0.52.jar:7.0.52]
    at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:408) ~[tomcat-catalina-7.0.52.jar:7.0.52]
    at org.apache.coyote.http11.AbstractHttp11Processor.process(AbstractHttp11Processor.java:1041) ~[tomcat-coyote-7.0.52.jar:7.0.52]
    at org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:607) ~[tomcat-coyote-7.0.52.jar:7.0.52]
    at org.apache.tomcat.util.net.JIoEndpoint$SocketProcessor.run(JIoEndpoint.java:315) ~[tomcat-coyote-7.0.52.jar:7.0.52]
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) ~[na:1.8.0_91]
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) ~[na:1.8.0_91]
    at java.lang.Thread.run(Thread.java:745) ~[na:1.8.0_91]
Caused by: java.io.EOFException: Can not read response from server. Expected to read 4 bytes, read 0 bytes before connection was unexpectedly lost.
    at com.mysql.jdbc.MysqlIO.readFully(MysqlIO.java:2957) ~[mysql-connector-java-5.1.38.jar:5.1.38]
    at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:3375) ~[mysql-connector-java-5.1.38.jar:5.1.38]
    ... 63 common frames omitted
ERROR 21:44:08.228 (RepositoryExceptionMapper) Caught a repository exception: org.modeshape.persistence.relational.RelationalProviderException: java.sql.SQLException: Connection is closed

4 Comments

  1. Andrew Woods

    Michael Durbin, do you have any thoughts on what Nick Ruest could do in configuring MySQL for the above error?

  2. Jim Coble

    Nick Ruest, Andrew Woods We are seeing a similar error in our current Fedora 4.7.1 testing; namely, first request of the day results in an error like this ...

    ERROR o.f.h.c.e.WildcardExceptionMapper - Exception intercepted by WildcardExceptionMapper: com.mysql.jdbc.exceptions.jdbc4.CommunicationsException: The last packet successfully received from the server was 61,539,074 milliseconds ago.  The last packet sent successfully to the server was 61,539,074 milliseconds ago. is longer than the server configured value of 'wait_timeout'. You should consider either expiring and/or testing connection validity before use in your application, increasing the server configured values for client timeouts, or using the Connector/J connection property 'autoReconnect=true' to avoid this problem.

    Subsequent requests succeed.  We are trying the "autoReconnect=true" tactic suggested by the error message (no definitive results on that yet) but I'm curious if any other (better) solution has been found.

    Thanks.

    1. Andrew Woods

      Michael Durbin ^^

      1. Jim Coble

        Andrew Woods, Michael Durbin I may have found a solution to this issue.  Our initial 4.7.1 setup was using a JNDI datasource for the MySQL database.  I have switched that back to putting the database information directly in the repository.json file and, while it's early, it looks like that may have fixed the problem.  I'm guessing the problem is not in using a JNDI datasource per se but rather in the way I had configured that datasource.  If I am able to figure out something more specific about why the current approach works and the JNDI datasource didn't, I'll let you (and the community) know.

All content on the LYRASIS Wiki is licensed under the CC BY (Attribution) license, unless otherwise noted.