C3P0 APPARENT DEADLOCK在Apache Tomcat应用程序中

huangapple go评论54阅读模式
英文:

C3P0 APPARENT DEADLOCK in Apache Tomcat application

问题

我在Apache Tomcat应用程序中发现了C3P0日志死锁问题。不久后,Tomcat开始因资源限制而出现故障。这导致httpd子进程的数量增加,直到达到maxRequestWorkers限制,然后服务器发生死锁。根据我的初步研究,C3P0问题可能是Hibernate与PostgreSQL通信失败的原因。

是否可以确认这是否是根本问题,并提供关于可能发生的情况的任何见解将不胜感激。

这是C3P0问题的初始日志:

[警告] [Wed Feb 08 05:52:41.589 2023] [C3P0PooledConnectionPoolManager[identityToken->2t53wqaub1kdwl1wutziz|421f447f]-AdminTaskTimer|ThreadPoolAsynchronousRunner] com.mchange.v2.async.ThreadPoolAsynchronousRunner$DeadlockDetector@578de344 -- 明显死锁!正在为未分配的待处理任务创建紧急线程!
[警告] [Wed Feb 08 05:52:42.270 2023] [C3P0PooledConnectionPoolManager[identityToken->2t53wqaub1kdwl1wutziz|421f447f]-AdminTaskTimer|ThreadPoolAsynchronousRunner] com.mchange.v2.async.ThreadPoolAsynchronousRunner$DeadlockDetector@578de344 -- 明显死锁!完整状态:
托管线程:10
活动线程:10
活动任务:
com.mchange.v2.resourcepool.BasicResourcePool$ScatteredAcquireTask@148953c6
在线程上:C3P0PooledConnectionPoolManager[identityToken->2t53wqaub1kdwl1wutziz|421f447f]-HelperThread-#2
com.mchange.v2.resourcepool.BasicResourcePool$ScatteredAcquireTask@33ec4718
在线程上:C3P0PooledConnectionPoolManager[identityToken->2t53wqaub1kdwl1wutziz|421f447f]-HelperThread-#5
com.mchange.v2.resourcepool.BasicResourcePool$ScatteredAcquireTask@7a772c6f
在线程上:C3P0PooledConnectionPoolManager[identityToken->2t53wqaub1kdwl1wutziz|421f447f]-HelperThread-#7
com.mchange.v2.resourcepool.BasicResourcePool$ScatteredAcquireTask@5e288adc
在线程上:C3P0PooledConnectionPoolManager[identityToken->2t53wqaub1kdwl1wutziz|421f447f]-HelperThread-#0
com.mchange.v2.resourcepool.BasicResourcePool$ScatteredAcquireTask@e1f5bc
在线程上:C3P0PooledConnectionPoolManager[identityToken->2t53wqaub1kdwl1wutziz|421f447f]-HelperThread-#4
com.mchange.v2.resourcepool.BasicResourcePool$ScatteredAcquireTask@51e4b63f
在线程上:C3P0PooledConnectionPoolManager[identityToken->2t53wqaub1kdwl1wutziz|421f447f]-HelperThread-#8
com.mchange.v2.resourcepool.BasicResourcePool$ScatteredAcquireTask@1233fc38
在线程上:C3P0PooledConnectionPoolManager[identityToken->2t53wqaub1kdwl1wutziz|421f447f]-HelperThread-#3
com.mchange.v2.resourcepool.BasicResourcePool$ScatteredAcquireTask@857fac8
在线程上:C3P0PooledConnectionPoolManager[identityToken->2t53wqaub1kdwl1wutziz|421f447f]-HelperThread-#6
com.mchange.v2.resourcepool.BasicResourcePool$ScatteredAcquireTask@794b26b
在线程上:C3P0PooledConnectionPoolManager[identityToken->2t53wqaub1kdwl1wutziz|421f447f]-HelperThread-#1
com.mchange.v2.resourcepool.BasicResourcePool$ScatteredAcquireTask@73b5a9e8
在线程上:C3P0PooledConnectionPoolManager[identityToken->2t53wqaub1kdwl1wutziz|421f447f]-HelperThread-#9
待处理任务:
com.mchange.v2.resourcepool.BasicResourcePool$1RefurbishCheckinResourceTask@7e6a499a
com.mchange.v2.resourcepool.BasicResourcePool$1RefurbishCheckinResourceTask@49dc7d25
com.mchange.v2.resourcepool.BasicResourcePool$1RefurbishCheckinResourceTask@6b79999f
com.mchange.v2.resourcepool.BasicResourcePool$1RefurbishCheckinResourceTask@355d97f1
com.mchange.v2.resourcepool.BasicResourcePool$1RefurbishCheckinResourceTask@19572e59
com.mchange.v2.resourcepool.BasicResourcePool$1RefurbishCheckinResourceTask@33c84d03
com.mchange.v2.resourcepool.BasicResourcePool$1RefurbishCheckinResourceTask@145a8f84
com.mchange.v2.resourcepool.BasicResourcePool$1RefurbishCheckinResourceTask@4d6160e1
com.mchange.v2.resourcepool.BasicResourcePool$ScatteredAcquireTask@6de4aaf2
com.mchange.v2.resourcepool.BasicResourcePool$1RefurbishCheckinResourceTask@1cb54218
池线程堆栈跟踪:
...

不久之后,Tomcat开始记录资源问题:

08-Feb-2023 05:52:49.672 严重 [ajp-nio-127.0.0.1-8009-exec-123] org.apache.coyote.AbstractProtocol$ConnectionHandler.process 未能完成请求的处理
java.lang.OutOfMemoryError: 无法创建本机线程:可能内存不足或达到了进程/资源限制
在java.base/java.lang.Thread.start0(Native Method)

ps显示,不久后Tomcat开始出错,大量httpd进程开始生成。这将持续数小时,直到达到500的限制。

英文:

I am seeing a C3P0 log dead lock issue in an Apache Tomcat application.

Not long after this I begin to see failures in Tomcat due to resource limits.

This then causes the number of httpd daughter processes to increase until the maxRequestWorkers limit is hit and the server then deadlocks.

From my initial research it looks like the C3P0 issue could be a failure of hibernate to communicate with postgres.

A confirmation of whether that is the root issue would be appreciated as well as any insight into what might be going on here.

This is this initial log that C3P0 issues:

[WARN] [Wed Feb 08 05:52:41.589 2023] [C3P0PooledConnectionPoolManager[identityToken->2t53wqaub1kdwl1wutziz|421f447f]-AdminTaskTimer|ThreadPoolAsynchronousRunner] com.mchange.v2.async.ThreadPoolAsynchronousRunner$DeadlockDetector@578de344 -- APPARENT DEADLOCK!!! Creating emergency threads for unassigned pending tasks!
[WARN] [Wed Feb 08 05:52:42.270 2023] [C3P0PooledConnectionPoolManager[identityToken->2t53wqaub1kdwl1wutziz|421f447f]-AdminTaskTimer|ThreadPoolAsynchronousRunner] com.mchange.v2.async.ThreadPoolAsynchronousRunner$DeadlockDetector@578de344 -- APPARENT DEADLOCK!!! Complete Status: 
	Managed Threads: 10
	Active Threads: 10
	Active Tasks: 
		com.mchange.v2.resourcepool.BasicResourcePool$ScatteredAcquireTask@148953c6
			on thread: C3P0PooledConnectionPoolManager[identityToken->2t53wqaub1kdwl1wutziz|421f447f]-HelperThread-#2
		com.mchange.v2.resourcepool.BasicResourcePool$ScatteredAcquireTask@33ec4718
			on thread: C3P0PooledConnectionPoolManager[identityToken->2t53wqaub1kdwl1wutziz|421f447f]-HelperThread-#5
		com.mchange.v2.resourcepool.BasicResourcePool$ScatteredAcquireTask@7a772c6f
			on thread: C3P0PooledConnectionPoolManager[identityToken->2t53wqaub1kdwl1wutziz|421f447f]-HelperThread-#7
		com.mchange.v2.resourcepool.BasicResourcePool$ScatteredAcquireTask@5e288adc
			on thread: C3P0PooledConnectionPoolManager[identityToken->2t53wqaub1kdwl1wutziz|421f447f]-HelperThread-#0
		com.mchange.v2.resourcepool.BasicResourcePool$ScatteredAcquireTask@e1f5bc
			on thread: C3P0PooledConnectionPoolManager[identityToken->2t53wqaub1kdwl1wutziz|421f447f]-HelperThread-#4
		com.mchange.v2.resourcepool.BasicResourcePool$ScatteredAcquireTask@51e4b63f
			on thread: C3P0PooledConnectionPoolManager[identityToken->2t53wqaub1kdwl1wutziz|421f447f]-HelperThread-#8
		com.mchange.v2.resourcepool.BasicResourcePool$ScatteredAcquireTask@1233fc38
			on thread: C3P0PooledConnectionPoolManager[identityToken->2t53wqaub1kdwl1wutziz|421f447f]-HelperThread-#3
		com.mchange.v2.resourcepool.BasicResourcePool$ScatteredAcquireTask@857fac8
			on thread: C3P0PooledConnectionPoolManager[identityToken->2t53wqaub1kdwl1wutziz|421f447f]-HelperThread-#6
		com.mchange.v2.resourcepool.BasicResourcePool$ScatteredAcquireTask@794b26b
			on thread: C3P0PooledConnectionPoolManager[identityToken->2t53wqaub1kdwl1wutziz|421f447f]-HelperThread-#1
		com.mchange.v2.resourcepool.BasicResourcePool$ScatteredAcquireTask@73b5a9e8
			on thread: C3P0PooledConnectionPoolManager[identityToken->2t53wqaub1kdwl1wutziz|421f447f]-HelperThread-#9
	Pending Tasks: 
		com.mchange.v2.resourcepool.BasicResourcePool$1RefurbishCheckinResourceTask@7e6a499a
		com.mchange.v2.resourcepool.BasicResourcePool$1RefurbishCheckinResourceTask@49dc7d25
		com.mchange.v2.resourcepool.BasicResourcePool$1RefurbishCheckinResourceTask@6b79999f
		com.mchange.v2.resourcepool.BasicResourcePool$1RefurbishCheckinResourceTask@355d97f1
		com.mchange.v2.resourcepool.BasicResourcePool$1RefurbishCheckinResourceTask@19572e59
		com.mchange.v2.resourcepool.BasicResourcePool$1RefurbishCheckinResourceTask@33c84d03
		com.mchange.v2.resourcepool.BasicResourcePool$1RefurbishCheckinResourceTask@145a8f84
		com.mchange.v2.resourcepool.BasicResourcePool$1RefurbishCheckinResourceTask@4d6160e1
		com.mchange.v2.resourcepool.BasicResourcePool$ScatteredAcquireTask@6de4aaf2
		com.mchange.v2.resourcepool.BasicResourcePool$1RefurbishCheckinResourceTask@1cb54218
Pool thread stack traces:
...

Not long after this is the resource issues that tomcat starts to log:

08-Feb-2023 05:52:49.672 SEVERE [ajp-nio-127.0.0.1-8009-exec-123] org.apache.coyote.AbstractProtocol$ConnectionHandler.process Failed to complete processing of a request
	java.lang.OutOfMemoryError: unable to create native thread: possibly out of memory or process/resource limits reached
		at java.base/java.lang.Thread.start0(Native Method)

ps shows that soon after Tomcat begins to error a large number of httpd processes begins to spawn. This continues for several hours until the limit of 500 is hit.

[vcr@qa-9440 ~]$ ps auxwww |grep httpd
root     4154    0.0  0.0    23504    10668  -  Ss   Mon17       0:33.03 /usr/local/sbin/httpd -DNOHTTPACCEPT
www     45854    0.0  0.0    23504    11452  -  I    05:53       0:01.41 /usr/local/sbin/httpd -DNOHTTPACCEPT
www     46742    0.0  0.0    23504    11448  -  I    05:54       0:00.84 /usr/local/sbin/httpd -DNOHTTPACCEPT
www     46986    0.0  0.0    23504    11412  -  I    05:55       0:00.67 /usr/local/sbin/httpd -DNOHTTPACCEPT
www     47031    0.0  0.0    23504    11436  -  I    05:55       0:00.54 /usr/local/sbin/httpd -DNOHTTPACCEPT
www     47034    0.0  0.0    23504    11444  -  I    05:55       0:00.60 /usr/local/sbin/httpd -DNOHTTPACCEPT
www     47223    0.0  0.0    26064    11600  -  I    05:55       0:00.43 /usr/local/sbin/httpd -DNOHTTPACCEPT
www     47390    0.0  0.0    23504    11412  -  I    05:56       0:00.40 /usr/local/sbin/httpd -DNOHTTPACCEPT
www     47411    0.0  0.0    23504    11428  -  I    05:56       0:00.32 /usr/local/sbin/httpd -DNOHTTPACCEPT
www     47520    0.0  0.0    23504    11384  -  I    05:56       0:00.30 /usr/local/sbin/httpd -DNOHTTPACCEPT
www     47617    0.0  0.0    23504    11408  -  I    05:56       0:00.28 /usr/local/sbin/httpd -DNOHTTPACCEPT
www     47619    0.0  0.0    23504    11336  -  I    05:56       0:00.22 /usr/local/sbin/httpd -DNOHTTPACCEPT
www     47653    0.0  0.0    23504    11356  -  I    05:56       0:00.23 /usr/local/sbin/httpd -DNOHTTPACCEPT
www     47716    0.0  0.0    23504    11340  -  I    05:56       0:00.20 /usr/local/sbin/httpd -DNOHTTPACCEPT
www     47735    0.0  0.0    23504    11364  -  I    05:56       0:00.18 /usr/local/sbin/httpd -DNOHTTPACCEPT
...

C3P0/Hibernate configurations:

<!-- Configure the dataSource.-->
	<bean id="dataSource"
		class="com.mchange.v2.c3p0.ComboPooledDataSource">
		<property name="driverClass">
			<value>${db.driver}</value>
		</property>
		<property name="jdbcUrl">
			<value>${db.url}</value>
		</property>
		<property name="user">
			<value>${db.username}</value>
		</property>
		<property name="password">
			<value>${db.password}</value>
		</property>
		<property name="acquireRetryAttempts" value="0" />
		<property name="acquireRetryDelay" value="2000" />
		<property name="initialPoolSize" value="10" />
		<property name="minPoolSize" value="1" />
		<property name="maxPoolSize" value="20" />
		<property name="maxIdleTime" value="5" />
		<property name="autoCommitOnClose" value="false" />
		<property name="numHelperThreads" value="10" />
	</bean>

	<!--
		Setup Hibernate based on config file 
		classpath:com/niksun/resources/hibernate.cfg.xml.
		
		PostgreSQLDialect
	-->

	<bean id="sessionFactory"
		class="org.springframework.orm.hibernate5.LocalSessionFactoryBean">
		<property name="dataSource" ref="dataSource">
		</property>
		<property name="hibernateProperties">
			<props>
				<prop key="hibernate.dialect">
					org.hibernate.dialect.PostgreSQL10Dialect 
				</prop>
				<prop key="hibernate.show_sql">false</prop>
				<prop key="hibernate.format_sql">false</prop>
				<prop key="hibernate.c3p0.maxPoolSize">100</prop>
				<prop key="hibernate.c3p0.min_size">10</prop>
				<prop key="hibernate.jdbc.batch_size">20</prop>
				<!--prop key="hibernate.hbm2ddl.auto">validate</prop-->
				
			</props>
		</property>
	</bean>

答案1

得分: 1

以下是翻译好的部分:

"ScatteredAcquireTask" 是导致线程池饱和并挂起的任务,它是 c3p0 尝试从后端数据库获取新连接的任务。这些尝试是"挂起"的,意味着它们既不成功,也不失败,也没有抛出异常。它们只是无限期地阻塞着尝试运行它们的线程。这个挂起是你需要调试的问题。这种类型的挂起可能是由于在AWS上配置不正确的身份验证配置引起的,但也可能来自许多其他未知因素。如果在发生这些事件时,你可以尝试一个简单的测试程序,该程序仅尝试使用相同的 dbUrl/user/password 来获取连接,这可能会提供一些见解。

失败是正常的。c3p0 对于连接获取有时失败的情况非常有弹性,网络和数据库都是不完美的。但它不能容忍既不成功也不失败的情况。它期望获取尝试要么成功,要么在一个相当宽松的时间窗口内失败。无限期的挂起将耗尽其线程。

英文:

The task that's hanging and saturating your thread pool is ScatteredAcquireTask, which is c3p0 trying to get new Connections from the backend DB. Those attempts are hanging, meaning they are neither succeeding nor failing with an Exception. They are just indefinitely holding up the Thread that tries to run them. This hang is what you need to debug. This sort of hang can come from, e.g. incorrect authentication configuration on AWS, but also from lots of other mysteries. If you can try a test program that simply tries to acquire a Connection with the same dbUrl/user/password when these events happen, that might give some insight.

Failure is normal. c3p0 is very resilient to the fact that Connection acquisition sometimes fails, networks and databases are imperfect. But it is not resilient to neither failing nor succeeding. It expects acquisition attempts to either succeed, or fail within a pretty generous time window. Indefinite hangs will eat up its threads.

huangapple
  • 本文由 发表于 2023年2月9日 01:10:41
  • 转载请务必保留本文链接:https://go.coder-hub.com/75389324.html
匿名

发表评论

匿名网友

:?: :razz: :sad: :evil: :!: :smile: :oops: :grin: :eek: :shock: :???: :cool: :lol: :mad: :twisted: :roll: :wink: :idea: :arrow: :neutral: :cry: :mrgreen:

确定