现象:最近现场反馈一个问题,系统在审批的时候,经常卡死,整个系统完全用不了,浏览器访问处于loading的状态。
排查:
1.一般系统挂了首先想到内存问题,但是现象是loading,也就是说没有挂,线程正在执行,怀疑是线程被阻塞了,配置上jvisualvm监控了一下,出问题后内存没满确定不是内存问题,查看线程dump发现大部分都在执行sql查询,
初步发现是执行sql慢导致的。
2.我们用的是sybase数据库,执行了几个简单sql发现几分钟都没执行完,使用sp_sysmon "00:00:30"监控近30秒的情况发现cpu、内存、线程都没问题,几乎1%使用率都不到,怀疑是某个连接阻塞了表,导致其他连接全部阻塞导致的。
3.我们使用自己写的存储过程查看阻塞的连接,结果如下:
PS:使用sp_lock命令就可以查看哪个连接阻塞了数据库,但是显示的都是tableid等,还需要再次查询转换成具体表名等,自己写的存储过程只是此处转换了一下,后面会附上。
发现其中1万多个锁,7000多个排它锁,Ex_row-blk是阻塞了其他连接的锁,发现有21个阻塞了其他连接的锁,对应的表是T_ZXLD_SYYH,执行select * from master..sysprocesses找到对应的连接,如上图的User有316/287/283等,结果如下:
此时基本确定了原因,我们用的是c3p0连接池,应该是某个连接阻塞了表,其他所有连接查询时候都被阻塞了,导致连接池被占满,所有请求凡是涉及数据库查询的都被阻塞了,页面始终处于loading状态。
4.那么接下来就是找到阻塞的地方,上图发现tran_name都是$chained_transaction,结合程序判断,也就是说都在执行某个责任链里面的事务时阻塞了,系统就2处使用了责任链,直接就可以判断到时审批的责任链导致的,那么接下来就是排查此处代码是否有问题了,审批流程如下:
(1)开启事务
(2)根据参数查询出要审批的主表数据,2个sql
(3)逐条调用审批组件(类似工作流的一个组件)审批,每条数据大约5个更新sql,2个查询sql
(4)更新主表状态,每条数据1个更新sql
(5)插入审计日志,每条数据1个插入sql
(6)生成提醒消息,查询全部主表数据,20个查询sql,5个更新删除sql(非常慢)
(7)更新增量记录表,记录该条数据修改时间和状态等,每条数据1个更新sql
(8)提交事务
怀疑并发时相互阻塞导致的,生成提醒消息的地方,会查询全部业务表,如果此时有其他连接在事务中审批,就会阻塞,其他连接在生成消息,相互阻塞,造成死锁。理论上数据库会自动处理死锁的,但是不知道什么原因,日志报的死锁数量不是特别多。
而且此处业务处理也太合理,正常用户每次批量审批大约100条数据,所以大约有900多个增删改sql,200多个查询sql,像生成消息等sql执行非常慢(因为涉及更新旧消息),这么多操作放到一个事务中非常慢,审批表大约3000w数据,业务主表500w数据,执行起来也不是很快。
解决办法:重构了此处代码,讲上面执行慢的(5)(6)(7)步骤新起一个线程,不放到事务中执行,即使失败也影响不大。这样sql减少了30%,速度快了不少,更新到现场,观察了一个星期,发现未出现不响应等情况,算是问题解决。
虽然问题解决,但是根本原因没有找到,为什么会相互阻塞,为什么死锁没自动检测,这个是后续需要跟踪的。
最后,问题虽然解决了,但是中间沟通花了不少时间,和运维人员要现场数据耽误了很多事,简单整理一下,后续出问题的时候搜集这几个数据:
1、sp__lock的结果;(使用文章最后提供的存储过程)
2、select * from master..sysprocesses;
3、如果数据库慢,加上sp_sysmon "00:00:30"的结果;
4、中间件线程dump文件;
附上sybase查看锁的存储过程
IF OBJECT_ID ('dbo.sp__lock') IS NOT NULL DROP PROCEDURE dbo.sp__lockGOcreate procedure sp__lock( @dbname char(30)=null,@spid int=null, @dont_format char(1) = null)asbegin declare @dbid smallint if @dbname is not null select @dbid=db_id(@dbname) if (charindex("sa_role", show_role()) > 0) begin if @dont_format is null select "Type"=substring(v.name,1,11), "User"=substring(suser_name(p.suid)+" ("+rtrim(convert(char(6),l.spid))+")",1,20), "Table"=substring(db_name(l.dbid)+".."+convert(char(20),object_name(l.id,l.dbid)),1,26), "Page"=convert(char(8),l.page), "Cmd"=substring(p.cmd,1,11) from master..syslocks l, master..sysprocesses p, master..spt_values v where p.spid=l.spid and l.type = v.number and v.type = "L" and p.dbid=isnull(@dbid,p.dbid) and p.spid=isnull(@spid,p.spid) and l.dbid=isnull(@dbid,l.dbid) and l.spid=isnull(@spid,l.spid) order by l.dbid, l.id, v.name else select "Type"=v.name, "User"=suser_name(p.suid)+" ("+rtrim(convert(char(6),l.spid))+")", "Table"=db_name(l.dbid)+".."+object_name(l.id,l.dbid), "Page"=l.page, "Cmd"=p.cmd from master..syslocks l, master..sysprocesses p, master..spt_values v where p.spid=l.spid and l.type = v.number and v.type = "L" and p.dbid=isnull(@dbid,p.dbid) and p.spid=isnull(@spid,p.spid) and l.dbid=isnull(@dbid,l.dbid) and l.spid=isnull(@spid,l.spid) order by l.dbid, l.id, v.name return end select "Type"=v.name, "Usernm"=convert(varchar(60),suser_name(p.suid)+" ("+rtrim(convert(char(6),l.spid))+")"), "TableNm"=convert(varchar(60),db_name(l.dbid)+".."), "Page"=l.page, "Cmd"=p.cmd, l.id, l.dbid into #locks from master..syslocks l, master..sysprocesses p, master..spt_values v where p.spid=l.spid and l.type = v.number and v.type = "L" and l.dbid=isnull(@dbid,l.dbid) and l.spid=isnull(@spid,l.spid) and p.dbid=isnull(@dbid,p.dbid) and p.spid=isnull(@spid,p.spid) update #locks set TableNm=TableNm+object_name(id,dbid) where dbid=db_id() or dbid=1 or dbid=2 update #locks set TableNm=TableNm+convert(varchar,id) where dbid<>db_id() and dbid>2 delete #locks where TableNm like "tempdb..#locks%" if @dont_format is null select substring(Type, 1,11), "User"=substring(Usernm, 1,14), "Table"=convert(char(26),TableNm), "Page"=convert(char(8),Page), "Cmd"=substring(Cmd,1,11) from #locks order by dbid, id, Type else select Type, "User"=Usernm, "Table"=TableNm, Page, Cmd from #locks order by dbid, id, TypeendGO