之前遇到一个很有意思的问题,让自己学到了不少东西。分享给大家, 读下面的故事前,请先了解下面的几个概念
死锁:是指两个或两个以上的进程在执行过程中,由于竞争资源或者由于彼此通信而造成的一种阻塞的现象,若无外力作用,它们都将无法推进下去。此时称系统处于死锁状态或系统产生了死锁,这些永远在互相等待的进程称为死锁进程
数据库死锁:如果需要“修改”一条数据,首先数据库上会在上面加锁,以保证在同一时间只有一个事务能进行修改操作。锁定(Locking)发生在当一个事务获得对某一资源的“锁”时,这时,其他的事务就不能更改这个资源了,这种机制的存在是为了保证数据一致性
ITL: (Interested Transaction List)是Oracle数据块内部的一个组成部分位于数据库头(block header),是由一系列的ITS(Interested Transaction Slot,事物槽)列表组成,ITL用来记录该块所有发生的事务,一个its可以看作是事务记录。 如果这个事务已经提交,那么这个itL的位置就可以被反复使用, 因为ITL类似记录,所以,有的时候也叫itL槽位。如果一个事务一直没有提交, 那么,这个事务将一直占用一个ITL槽位,ITL里面记录了事务信息,回滚段的入口, 事务类型等等。如果这个事务已经提交, 那么,ITL槽位中还保存的有这个事务提交时候的SCN号。
问题现象
故事是这么发生的,很久很久以前......
系统新版本在地市上线不久,现场人员反馈执行批量业务操的的时候会出现业务办理卡死的情况,阻塞正常业务。现场同事还反馈说,问题出现概率非必现,批量操作有时候正常,有时候会开始, 某种情况下才会出现,未发现问题产生的规律
又是偶现问题.....又是头疼问题......
问题处理
排查过程
从现场获取了日志使用UEditor工具对日志分割后获取批量操作的信息,从日志上看2018-11-19 14:22:27 线程5开始假死, 处于等待状态 1800秒(30分钟)后假死结束,
2018-11-19 14:22:26,391 INFO [com.star.sms.business.payment.BatchPaymentServiceImpl$1] pool-882-thread-5start|size=3
2018-11-19 14:22:27,008 INFO [com.star.sms.business.accept2.billing.AcceptSheetBillContext] Current Thread:pool-882-thread-5 ######caclulate halfMonth fee total time : 73 #####
2018-11-19 14:22:27,569 INFO [com.star.sms.business.accept2.billing.AcceptSheetBillContext] Current Thread:pool-882-thread-5 ######caclulate halfMonth fee total time : 72 #####
2018-11-19 14:52:26,916 INFO [com.star.sms.business.accept2.billing.AcceptSheetBillContext] Current Thread:pool-882-thread-5 ######caclulate halfMonth fee total time : 58 #####
2018-11-19 14:52:27,112 INFO [com.star.sms.business.payment.BatchPaymentServiceImpl$1] pool-882-thread-5end|time=1800.721 s
2018-11-19 14:52:26,672 INFO [com.star.sms.business.payment.BatchPaymentServiceImpl$1] pool-882-thread-3end|time=1800.281 s
2018-11-19 14:52:26,683 INFO [com.star.sms.business.payment.BatchPaymentServiceImpl$1] pool-882-thread-1end|time=1800.292 s
2018-11-19 14:52:26,916 INFO [com.star.sms.business.accept2.billing.AcceptSheetBillContext] Current Thread:pool-882-thread-5 ######caclulate halfMonth fee total time : 58 #####
2018-11-19 14:52:27,032 INFO [com.star.sms.business.armgmt.ChargeCauseWriteOffListener] Received write offevent,accountid = 8322425
2018-11-19 14:52:27,033 INFO [com.star.sms.business.armgmt.ArInnerServiceImpl]account id :8322425,there is not owe bill to write off
2018-11-19 14:52:27,036 INFO [com.star.sms.business.armgmt.ArInnerServiceImpl]query subscriber by accountId is empty(id:8322425 operWay:2)
2018-11-19 14:52:27,038 INFO [com.star.sms.business.armgmt.ArInnerServiceImpl]query subscriber by accountId is empty(id:8322425 operWay:2)
2018-11-19 14:52:27,038 INFO [com.star.sms.business.armgmt.ArInnerServiceImpl]account id :8322425,there is not owe bill to write off
2018-11-19 14:52:27,112 INFO [com.star.sms.business.payment.BatchPaymentServiceImpl$1] pool-882-thread-5 end|time=1800.721 s
使用 jstack 查看线程的堆栈信息,分析线程堆栈信息:发现其中批量线程池中几个子线程都停在(第13行) $Proxy953.modifyDiscountInstance 数据库修改优惠事例的时候,这个方法在程序中的作用只是一个UPDATE操作
org.springframework.aop.support.DelegatingIntroductionInterceptor.doProceed(DelegatingIntroductionInterceptor.java:132)
org.springframework.aop.support.DelegatingIntroductionInterceptor.invoke(DelegatingIntroductionInterceptor.java:120)
org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
org.eclipse.gemini.blueprint.service.util.internal.aop.ServiceTCCLInterceptor.invokeUnprivileged(ServiceTCCLInterceptor.java:70)
org.eclipse.gemini.blueprint.service.util.internal.aop.ServiceTCCLInterceptor.invoke(ServiceTCCLInterceptor.java:53)
org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
org.eclipse.gemini.blueprint.service.importer.support.LocalBundleContextAdvice.invoke(LocalBundleContextAdvice.java:57)
org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
org.springframework.aop.support.DelegatingIntroductionInterceptor.doProceed(DelegatingIntroductionInterceptor.java:132)
org.springframework.aop.support.DelegatingIntroductionInterceptor.invoke(DelegatingIntroductionInterceptor.java:120)
org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:204)
$Proxy953.modifyDiscountInstance(Unknown Source)
com.star.sms.business.accept2.instance.PromotionInstanceContext.cancel(PromotionInstanceContext.java:262)
com.star.sms.business.accept2.instance.PricePlanInstanceContext.delete(PricePlanInstanceContext.java:443)
com.star.sms.business.accept2.utils.RenewalFeeHelper.changePricePlan(RenewalFeeHelper.java:92)
com.star.sms.business.accept2.instance.ProductInstanceContextAfterNew.changePricePlanByStrategy(ProductInstanceContextAfterNew.java:965)
com.star.sms.business.accept2.order.ProductRenewalFeeOrderContext.doComplete(ProductRenewalFeeOrderContext.java:132)
怀疑数据库中存在死锁, 因此执行了下面的SQL查看SQL执行中是否有相互阻塞互锁的情况, 发现猜测结果和预想不一样,并没有发现有因为锁造成等待的SQL
with vw_lock AS (SELECT * FROM v$lock)
select
a.sid,
'is blocking' blocking,
(select 'sid:'||s.sid||' object:'||do.object_name||' rowid:'||
dbms_rowid.rowid_create ( 1, ROW_WAIT_OBJ#, ROW_WAIT_FILE#,
ROW_WAIT_BLOCK#, ROW_WAIT_ROW# )
||' sql_id:'||s.sql_id
from v$session s, dba_objects do
where s.sid=b.sid
and s.ROW_WAIT_OBJ# = do.OBJECT_ID
) blockee,
b.sid sid2,b.id1,b.id2
from vw_lock a, vw_lock b
where a.block = 1
and b.request > 0
and a.id1 = b.id1
and a.id2 = b.id2;
再查看数据库正在执行的SQL信息,发现修改产品实例的SQL存在 enq: TX - allocate ITL entry阻塞, 那么什么是enq: TX - allocate ITL entry?
举个栗子来说明: 假设数据块只有2个itl槽位,而现在发生了3个事务,而且,因为该块被数据添满或者达到了配置的最大的值的时候,根本没有剩余的空间来分配新的itl,所以发生了等待,这就是enq: TX - allocate ITL entry
select username,
sid,
serial#,
sql_id,
event,
machine,
program,
blocking_session,
status,
module
from gv$session
where wait_class# <> 6
order by blocking_session;
所以产生问题现象的直接原因是,事务一直没有提交,数据库一直处于ITL卡槽分配等待状态,最终事务超时,这也是前面日志中的1800秒日志的由来
问题原因
业务系统产生卡死的直接原因找到了, 但是问题又来了, 系统为什么会出现 enq: TX - allocate ITL entry 问题呢?
经过分析发现批量业务处理的时候按照数据量使用多线程处理,程序按照业务的任务数量分配线程, 当所有线程处理结束后统一提交事务,仔细想想几个操作员在做批量处理,系统分配线程处理,子线程UPDATE表数据,等待事务,等待事务, 我勒个去!!
- 业务程序处理大量数据,主线程等待所有线程处理完成后,才会被唤醒执行提交事务
- 子线程中执行程序中的UPDATE的时候很多个事务让, ORACLE分配ITL事务卡槽,discountInstance 数据块的卡槽已经全部分配,又等地其他使用卡槽的事务释放,其他事务却等通知呢, 因为等待主线程通知commit;
最终造成系统程序的主线程与Oracle事务中ITL卡槽分配互锁
try {
result = processByCall(datas);
if (CollectionUtils.isEmpty(result.getFailList())) {
result.setSucess(true);
transactionGuarded.hold(Thread.currentThread().getName());
} else {
result.setSucess(false);
transactionGuarded.setFailed();
}
} catch (Throwable ex) {
pringlog(ex);
result.setSucess(false);
transactionGuarded.setFailed();
throw new RuntimeException(ex);
} finally {
if (transactionGuarded.isSuccess()) {
transactionManager.commit(status);
} else {
transactionManager.rollback(status);
}
}
解决方法
ITL 的空间是由INITRANS 决定的, 当表被初始化的时候的几个参数 决定了ITL相关信息
- INITRANS 指的是一个 BLOCK 上初始预分配给并行交易控制的空间 (ITLs)
- MAXTRANS 指的是如果 INITRANS 空间不够用了,就会自动扩展 ITL ,直到最大值也就是 MAXTRANS 值为止,预设是 255 。但是,如果 BLOCK 空间已经不足,也有可能无法持续扩充到 255 个 ITS 空间
SQL> select table_name,tablespace_name,ini_trans,max_trans from user_tables where table_name='DISCOUNTINSTANCEEN';
TABLE_NAME TABLESPACE_NAME INI_TRANS MAX_TRANS
------------------------------ ------------------------------ ---------- ----------
DISCOUNTINSTANCEEN TBLSMSUSER 10 255
ITL发生等待的情况有2中情况
- ITL已经达到了MAXTRANS 的最大值
这种情况可能是由于高并发引起,可以考虑减少业务操作的并发数以及扩大MAXTRANS 的值来解决
- ITL没有达到最大值,但是已经没有空间供其扩展
这发生这种情况的表通常会被经常UPDATE,从而造成预留空间(PCTFREE)被填满。可以通过增加表的INITRANS或者 PCTFREE来解决(视该表上的并发事务量而定,通常,如果并发量高,建议优先增加
INITRANS,反之,则优先考虑增加PCTFREE)