Apparent Deadlock

[Sergey Temchenko]

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 disable FastDev, clear my Confluence and enable 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!

[Daniel Eads]

Hey Sergey,

Sorry you're having trouble after switching to QuickReload!

We have a dedicated Developer Community that might be good to check out for plugin development related questions. Since the topics are more focused, it's easier for other developers to watch the questions coming in and provide guidance.

Unfortunately we don't have a lot of developers over here on the standard Community and we don't have any quick ideas for you in regular user-facing support. But I suspect another developer will have seen this in the past or have an idea for you.

Cheers,
Daniel

[Sergey Temchenko]

Ok, i will resubmit this question there.