Apparent Deadlock

tgrey · October 29, 2018, 7:44am

Environment: Confluence 6.11 Evaluate, H2 database

Hello, common question about APPARENT DEADLOCK which appears from nowhere(c3p0?). Some time ago i started noticing that after each plugin reload i get APPARENT DEADLOCK that increases total amount of time to release new version to test confluence. That time i used FastDev to reload plugin. Now i disabled FastDev, cleared my Confluence and enabled QuickReload. I thought this error would gone. But no. Unlike JIRA instance it still causes APPARENT DEADLOCK and somewhy calls QR 2 times. Anyway i can’t figure out how to fix it. I’ve read a lot of information, but nothing helped.

I’ve tried to increase Xmx and others.

This is my log:

custom-confluence-plugins-1.37.jar' to become stable (31727045 bytes)...
[INFO] [talledLocalContainer] 2018-10-26 18:36:55,276 INFO [QuickReload - Plugin Installer] [plugins.quickreload.install.PluginInstallerMechanic] downArrowMsg 
[INFO] [talledLocalContainer] |
[INFO] [talledLocalContainer] |
[INFO] [talledLocalContainer] |
[INFO] [talledLocalContainer] |
[INFO] [talledLocalContainer] |
[INFO] [talledLocalContainer] v
[INFO] [talledLocalContainer] 
[INFO] [talledLocalContainer] Starting Quick Reload - '/var/www/custom-plugins/tn/confluence/custom-confluence-plugins/target/custom-confluence-plugins-1.37.jar'....
[INFO] [talledLocalContainer] 
[INFO] [talledLocalContainer] 
[INFO] [talledLocalContainer] 2018-10-26 18:36:56,080 INFO [QuickReload - Stable File Watcher] [plugins.quickreload.install.PluginInstaller] info 'custom-confluence-plugins-1.37.jar' now appears to be stable (31727045 bytes)
[INFO] [talledLocalContainer] 2018-10-26 18:36:56,083 INFO [QuickReload - Stable File Watcher] [plugins.quickreload.install.PluginInstaller] info 'custom-confluence-plugins-1.37.jar' is indeed an Atlassian plugin and will be installed shortly...
[INFO] [talledLocalContainer] 2018-10-26 18:37:08,125 WARN [alert-dispatch:thread-1] [confluence.alert-log] log 1540568228124 ; WARNING ; JVM ; JVM-1002 ; Garbage collection exceeded time limit ; not-detected ; ; ; {"durationInMillis":5284,"windowInMillis":20000,"limitPercent":10,"threadMemoryAllocations":"","threadDump":[]}
[INFO] [talledLocalContainer] 2018-10-26 18:37:08,126 WARN [alert-dispatch:thread-1] [atlassian-monitor] log 2018-10-26T15:37:08.124Z Component 'Java' alerted 'Garbage collection exceeded time limit' (details: {"durationInMillis":5284,"windowInMillis":20000,"limitPercent":10,"threadMemoryAllocations":"","threadDump":[]}, trigger: {"pluginKey": "not-detected"})
[INFO] [talledLocalContainer] 2018-10-26 18:37:29,352 WARN [C3P0PooledConnectionPoolManager[identityToken->z8kfsx9y1d44fjr1ybiw4e|1d9d814d]-AdminTaskTimer] [mchange.v2.async.ThreadPoolAsynchronousRunner] log com.mchange.v2.async.ThreadPoolAsynchronousRunner$DeadlockDetector@63894b7 -- APPARENT DEADLOCK!!! Creating emergency threads for unassigned pending tasks!
[INFO] [talledLocalContainer] 2018-10-26 18:37:29,486 WARN [C3P0PooledConnectionPoolManager[identityToken->z8kfsx9y1d44fjr1ybiw4e|1d9d814d]-AdminTaskTimer] [mchange.v2.async.ThreadPoolAsynchronousRunner] log com.mchange.v2.async.ThreadPoolAsynchronousRunner$DeadlockDetector@63894b7 -- APPARENT DEADLOCK!!! Complete Status: 
[INFO] [talledLocalContainer] Managed Threads: 3
[INFO] [talledLocalContainer] Active Threads: 3
[INFO] [talledLocalContainer] Active Tasks: 
[INFO] [talledLocalContainer] com.mchange.v2.resourcepool.BasicResourcePool$1DestroyResourceTask@29ed8f74
[INFO] [talledLocalContainer] on thread: C3P0PooledConnectionPoolManager[identityToken->z8kfsx9y1d44fjr1ybiw4e|1d9d814d]-HelperThread-#0
[INFO] [talledLocalContainer] com.mchange.v2.resourcepool.BasicResourcePool$1DestroyResourceTask@4c51cbd9
[INFO] [talledLocalContainer] on thread: C3P0PooledConnectionPoolManager[identityToken->z8kfsx9y1d44fjr1ybiw4e|1d9d814d]-HelperThread-#2
[INFO] [talledLocalContainer] com.mchange.v2.resourcepool.BasicResourcePool$1DestroyResourceTask@73f47a99
[INFO] [talledLocalContainer] on thread: C3P0PooledConnectionPoolManager[identityToken->z8kfsx9y1d44fjr1ybiw4e|1d9d814d]-HelperThread-#1
[INFO] [talledLocalContainer] Pending Tasks: 
[INFO] [talledLocalContainer] com.mchange.v2.resourcepool.BasicResourcePool$1DestroyResourceTask@38807346
[INFO] [talledLocalContainer] com.mchange.v2.resourcepool.BasicResourcePool$ScatteredAcquireTask@695fc779
[INFO] [talledLocalContainer] Pool thread stack traces:
[INFO] [talledLocalContainer] Thread[C3P0PooledConnectionPoolManager[identityToken->z8kfsx9y1d44fjr1ybiw4e|1d9d814d]-HelperThread-#0,5,main]
[INFO] [talledLocalContainer] java.net.SocketInputStream.socketRead0(Native Method)
[INFO] [talledLocalContainer] java.net.SocketInputStream.socketRead(SocketInputStream.java:116)
[INFO] [talledLocalContainer] java.net.SocketInputStream.read(SocketInputStream.java:171)
[INFO] [talledLocalContainer] java.net.SocketInputStream.read(SocketInputStream.java:141)
[INFO] [talledLocalContainer] java.io.BufferedInputStream.fill(BufferedInputStream.java:246)
[INFO] [talledLocalContainer] java.io.BufferedInputStream.read(BufferedInputStream.java:265)
[INFO] [talledLocalContainer] java.io.DataInputStream.readInt(DataInputStream.java:387)
[INFO] [talledLocalContainer] org.h2.value.Transfer.readInt(Transfer.java:157)
[INFO] [talledLocalContainer] org.h2.engine.SessionRemote.done(SessionRemote.java:599)
[INFO] [talledLocalContainer] org.h2.engine.SessionRemote.close(SessionRemote.java:552)
[INFO] [talledLocalContainer] org.h2.jdbc.JdbcConnection.close(JdbcConnection.java:383)
[INFO] [talledLocalContainer] com.mchange.v2.c3p0.impl.NewPooledConnection.close(NewPooledConnection.java:642)
[INFO] [talledLocalContainer] com.mchange.v2.c3p0.impl.NewPooledConnection.closeMaybeCheckedOut(NewPooledConnection.java:255)
[INFO] [talledLocalContainer] com.mchange.v2.c3p0.impl.C3P0PooledConnectionPool$1PooledConnectionResourcePoolManager.destroyResource(C3P0PooledConnectionPool.java:622)
[INFO] [talledLocalContainer] com.mchange.v2.resourcepool.BasicResourcePool$1DestroyResourceTask.run(BasicResourcePool.java:1076)
[INFO] [talledLocalContainer] com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread.run(ThreadPoolAsynchronousRunner.java:696)
[INFO] [talledLocalContainer] Thread[C3P0PooledConnectionPoolManager[identityToken->z8kfsx9y1d44fjr1ybiw4e|1d9d814d]-HelperThread-#1,5,main]
[INFO] [talledLocalContainer] java.net.SocketInputStream.socketRead0(Native Method)
[INFO] [talledLocalContainer] java.net.SocketInputStream.socketRead(SocketInputStream.java:116)
[INFO] [talledLocalContainer] java.net.SocketInputStream.read(SocketInputStream.java:171)
[INFO] [talledLocalContainer] java.net.SocketInputStream.read(SocketInputStream.java:141)
[INFO] [talledLocalContainer] java.io.BufferedInputStream.fill(BufferedInputStream.java:246)
[INFO] [talledLocalContainer] java.io.BufferedInputStream.read(BufferedInputStream.java:265)
[INFO] [talledLocalContainer] java.io.DataInputStream.readInt(DataInputStream.java:387)
[INFO] [talledLocalContainer] org.h2.value.Transfer.readInt(Transfer.java:157)
[INFO] [talledLocalContainer] org.h2.engine.SessionRemote.done(SessionRemote.java:599)
[INFO] [talledLocalContainer] org.h2.engine.SessionRemote.close(SessionRemote.java:552)
[INFO] [talledLocalContainer] org.h2.jdbc.JdbcConnection.close(JdbcConnection.java:383)
[INFO] [talledLocalContainer] com.mchange.v2.c3p0.impl.NewPooledConnection.close(NewPooledConnection.java:642)
[INFO] [talledLocalContainer] com.mchange.v2.c3p0.impl.NewPooledConnection.closeMaybeCheckedOut(NewPooledConnection.java:255)
[INFO] [talledLocalContainer] com.mchange.v2.c3p0.impl.C3P0PooledConnectionPool$1PooledConnectionResourcePoolManager.destroyResource(C3P0PooledConnectionPool.java:622)
[INFO] [talledLocalContainer] com.mchange.v2.resourcepool.BasicResourcePool$1DestroyResourceTask.run(BasicResourcePool.java:1076)
[INFO] [talledLocalContainer] com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread.run(ThreadPoolAsynchronousRunner.java:696)
[INFO] [talledLocalContainer] Thread[C3P0PooledConnectionPoolManager[identityToken->z8kfsx9y1d44fjr1ybiw4e|1d9d814d]-HelperThread-#2,5,main]
[INFO] [talledLocalContainer] com.mchange.v2.c3p0.impl.NewPooledConnection.close(NewPooledConnection.java:642)
[INFO] [talledLocalContainer] com.mchange.v2.c3p0.impl.NewPooledConnection.closeMaybeCheckedOut(NewPooledConnection.java:255)
[INFO] [talledLocalContainer] com.mchange.v2.c3p0.impl.C3P0PooledConnectionPool$1PooledConnectionResourcePoolManager.destroyResource(C3P0PooledConnectionPool.java:622)
[INFO] [talledLocalContainer] com.mchange.v2.resourcepool.BasicResourcePool$1DestroyResourceTask.run(BasicResourcePool.java:1076)
[INFO] [talledLocalContainer] com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread.run(ThreadPoolAsynchronousRunner.java:696)
[INFO] [talledLocalContainer] 
[INFO] [talledLocalContainer] 2018-10-26 18:38:29,498 WARN [C3P0PooledConnectionPoolManager[identityToken->z8kfsx9y1d44fjr1ybiw4e|1d9d814d]-AdminTaskTimer] [mchange.v2.async.ThreadPoolAsynchronousRunner] log Task com.mchange.v2.resourcepool.BasicResourcePool$1DestroyResourceTask@29ed8f74 (in deadlocked PoolThread) failed to complete in maximum time 60000ms. Trying interrupt().
[INFO] [talledLocalContainer] 2018-10-26 18:38:29,498 WARN [C3P0PooledConnectionPoolManager[identityToken->z8kfsx9y1d44fjr1ybiw4e|1d9d814d]-AdminTaskTimer] [mchange.v2.async.ThreadPoolAsynchronousRunner] log Task com.mchange.v2.resourcepool.BasicResourcePool$1DestroyResourceTask@73f47a99 (in deadlocked PoolThread) failed to complete in maximum time 60000ms. Trying interrupt().
[INFO] [talledLocalContainer] 2018-10-26 18:38:29,498 WARN [C3P0PooledConnectionPoolManager[identityToken->z8kfsx9y1d44fjr1ybiw4e|1d9d814d]-AdminTaskTimer] [mchange.v2.async.ThreadPoolAsynchronousRunner] log Task com.mchange.v2.resourcepool.BasicResourcePool$1DestroyResourceTask@4c51cbd9 (in deadlocked PoolThread) failed to complete in maximum time 60000ms. Trying interrupt().
[INFO] [talledLocalContainer] 2018-10-26 18:39:25,433 DEBUG [368:StdOutHandler [/usr/lib/jvm/java-8-openjdk-amd64/jre/bin/java]] [plugins.synchrony.bootstrap.LoggingOutputHandler] processLine {"synchrony":{"request":{"remote-addr":"127.0.0.1","uri":"/synchrony/heartbeat","request-method":"get","query-string":null},"response":{"status":200},"ns":"synchrony.middleware.logging","level":"info","message":"synchrony.middleware.logging [info] null"}}
[INFO] [talledLocalContainer] 2018-10-26 18:39:40,623 INFO [QuickReload - Plugin Installer] [atlassian.plugin.manager.DefaultPluginManager] updatePlugin Updating plugin 'custom-confluence-plugins' from version '1.37' to version '1.37'
[INFO] [talledLocalContainer] 2018-10-26 18:39:40,625 INFO [QuickReload - Plugin Installer] [atlassian.plugin.manager.DefaultPluginManager] broadcastPluginDisabling Disabling custom-confluence-plugins
[INFO] [talledLocalContainer] 2018-10-26 18:39:42,045 WARN [QuickReload - Plugin Installer] [spring.scanner.extension.DevModeBeanInitialisationLoggerBeanPostProcessor] postProcessBeforeInstantiation BeforeInstantiation [beanName=com.atlassian.prettyurls.module.UrlRouteModuleDescriptor, objectType=com.atlassian.prettyurls.module.UrlRouteModuleDescriptor, level=-5]
[INFO] [talledLocalContainer] 2018-10-26 18:39:42,046 WARN [QuickReload - Plugin Installer] [spring.scanner.extension.DevModeBeanInitialisationLoggerBeanPostProcessor] postProcessAfterInitialization AfterInitialisation [beanName=com.atlassian.prettyurls.module.UrlRouteModuleDescriptor, objectType=com.atlassian.prettyurls.module.UrlRouteModuleDescriptor, level=-5]
[INFO] [talledLocalContainer] 2018-10-26 18:39:46,569 INFO [QuickReload - Plugin Installer] [plugins.quickreload.install.PluginInstallerMechanic] installPluginImmediately 
[INFO] [talledLocalContainer] ^
[INFO] [talledLocalContainer] |
[INFO] [talledLocalContainer] |
[INFO] [talledLocalContainer] |
[INFO] [talledLocalContainer] |
[INFO] [talledLocalContainer] |
[INFO] [talledLocalContainer] 
[INFO] [talledLocalContainer] Just press up arrow!
[INFO] [talledLocalContainer] 
[INFO] [talledLocalContainer] Quick Reload Finished (171290 ms) - 'custom-confluence-plugins-1.37.jar'
[INFO] [talledLocalContainer] 2018-10-26 18:39:46,570 INFO [QuickReload - Plugin Installer] [plugins.quickreload.install.PluginInstallerMechanic] downArrowMsg 
[INFO] [talledLocalContainer] |
[INFO] [talledLocalContainer] |
[INFO] [talledLocalContainer] |
[INFO] [talledLocalContainer] |
[INFO] [talledLocalContainer] |
[INFO] [talledLocalContainer] v
[INFO] [talledLocalContainer] 
[INFO] [talledLocalContainer] Starting Quick Reload - '/var/www/custom-plugins/tn/confluence/custom-confluence-plugins/target/custom-confluence-plugins-1.37.jar'....
[INFO] [talledLocalContainer] 
[INFO] [talledLocalContainer] 
[INFO] [talledLocalContainer] 2018-10-26 18:42:01,323 WARN [diagnostics-jvm-thread] [confluence.util.profiling.DurationThresholdWarningTimingHelperFactory] logMessage Execution time for publishing event com.atlassian.confluence.internal.diagnostics.GarbageCollectorTimeAnalyticsEvent@4f42d403 took 51538 ms (warning threshold is 5000 ms)
[INFO] [talledLocalContainer] 2018-10-26 18:42:17,096 WARN [synchrony-interop-executor:thread-1] [plugins.synchrony.bootstrap.DefaultSynchronyProxyMonitor] pollHealthcheck Could not ping the synchrony-proxy [http://127.0.0.1:1990/synchrony-proxy/healthcheck]: {}
[INFO] [talledLocalContainer] java.net.SocketTimeoutException: Read timed out
[INFO] [talledLocalContainer] at java.net.SocketInputStream.socketRead0(Native Method)
[INFO] [talledLocalContainer] at java.net.SocketInputStream.socketRead(SocketInputStream.java:116)
....
[INFO] [talledLocalContainer] 2018-10-26 18:43:02,782 WARN [C3P0PooledConnectionPoolManager[identityToken->z8kfsx9y1d44fjr1ybiw4e|1d9d814d]-AdminTaskTimer] [mchange.v2.async.ThreadPoolAsynchronousRunner] log com.mchange.v2.async.ThreadPoolAsynchronousRunner$DeadlockDetector@63894b7 -- APPARENT DEADLOCK!!! Creating emergency threads for unassigned pending tasks!

And this is my POM:

<?xml version="1.0" encoding="UTF-8"?>

<project xmlns="http://maven.apache.org/POM/4.0.0"
   xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
   xsi:schemaLocation="http://maven.apache.org/POM/4.0.0 http://maven.apache.org/maven-v4_0_0.xsd">

   <modelVersion>4.0.0</modelVersion>
   <groupId>com.custom.plugins</groupId>
   <artifactId>custom-plugin</artifactId>
   <version>1.37</version>

   <name>Custom Plugin</name>
   <description>Custom reports plugin.</description>
   <packaging>atlassian-plugin</packaging>

   <dependencies>
     [....]
   </dependencies>

   <build>
      <plugins>
         <plugin>
            <groupId>com.atlassian.maven.plugins</groupId>
            <artifactId>maven-confluence-plugin</artifactId>
            <version>${amps.version}</version>
            <extensions>true</extensions>
            <configuration>
               <productVersion>${confluence.version}</productVersion>
               <productDataVersion>${confluence.version}</productDataVersion>
               <jvmArgs>-Datlassian.velocity.deprecation.strictmode=false</jvmArgs>
               <jvmArgs>-Xmx1024m</jvmArgs>
               <jvmArgs>-Xms524m</jvmArgs>
               <jvmArgs>-XX:MaxPermSize=524m</jvmArgs>
               <jvmArgs>-XX:PermSize=128m</jvmArgs>

               <!-- make AMPS faster & enable QuickReload-->
               <!-- see https://bitbucket.org/atlassianlabs/quickreload/overview -->
               <enableQuickReload>true</enableQuickReload>
               <enableFastdev>false</enableFastdev>
               <enableDevToolbox>false</enableDevToolbox>
               <enablePde>false</enablePde>
               <skipRestDocGeneration>true</skipRestDocGeneration>
               <allowGoogleTracking>false</allowGoogleTracking>
               <skipManifestValidation>true</skipManifestValidation>
               <extractDependencies>false</extractDependencies>
               <skipManifestValidation>true</skipManifestValidation>
            </configuration>
         </plugin>
         <plugin>
            <artifactId>maven-compiler-plugin</artifactId>
            <version>3.1</version>
            <configuration>
               <source>1.7</source>
               <target>1.7</target>
            </configuration>
         </plugin>
         <plugin>
            <groupId>org.apache.maven.plugins</groupId>
            <artifactId>maven-compiler-plugin</artifactId>
            <configuration>
               <source>1.8</source>
               <target>1.8</target>
            </configuration>
         </plugin>
      </plugins>
   </build>

   <properties>
      <confluence.version>6.11.0</confluence.version>
      <hipchat.notifications.version>6.23.8</hipchat.notifications.version>
      <amps.version>6.2.4</amps.version>
   </properties>

   <organization>
      <name>....</name>
   </organization>
</project>

Any help?

Thanks!

tgrey · October 29, 2018, 11:25am

I don’t sure how to fix that problem with H2, but i’ve tried to change DB to MySQL and it seems to work.
Now i don’t get any errors with c3p0, deadlock or something else. Also QR finishes fast.