一、问题发现:
发现一个数据库语句执行很慢,奇怪的是,仅仅是一个insert 语句。难道一个insert语句要执行3秒钟,这个提起了我的兴趣。把当时的出问题的时段的awr报告打印出来一看发现一条奇怪的sql语句,我至今从来没有遇到过如此长的sql语句。看看它长什么样子:
没有错,你没有看错,就是一条insert语句。这个我还没有截屏完整,好几个屏幕。绑定变量有28000个。次见这么长的sql语句,见绑定变量如此多的语句。
和开发了解下需求:根据2个表数据,按一定业务逻辑插入到一个临时表,于是,就有上面这个拼接sql。(其实这要在以前,拿我来设计的话,我会直接写成plsql处理,但是现在是互联网微服务,于是,很多都变成微服务了。)
二、问题分析:
insert语句很慢,索引很多是一个原因。分析了下awr,是cursor: pin S wait on X等待事件。这个事件什么意思呢?
A session waits for this event when it is requesting a shared mutex pin and another session is holding an exclusive mutex pin on the same cursor object.
Wait Time: Microseconds
Parameter Description
P1 Hash value of cursor
P2 Mutex value (top 2 bytes contains SID holding mutex in exclusive mode, and bottom two bytes usually hold the value 0)
P3 Mutex where (an internal code locator) OR'd with Mutex Sleeps
搜索了下网上文章,导致这个等待事件有如下原因:
过多的子游标 High Version Counts, Mutex持有者得不到CPU, 已经被KILLED的SESSION仍持有Mutex
实际该 cursor: pin S wait on X等待事件往往是由于其他因素诱发的。Mutex争用仅仅是问题的症状,但根本原因需要Database Consultant 进一步挖掘。 那我这个是什么原因呢?
我检查了下等待事件:
SYS@VIPAY>selects.p1,to_char(s.p2) ,BLOCKING_SESSION,s.session_id,s.sql_Id,to_char(s.SAMPLE_TIME,'mm-dd hh24:mi:ss') fromv$active_session_history s whereSAMPLE_TIME betweento_date('2019-08-27 00:15','YYYY-MM-DD HH24:mi')
2 andto_date('2019-08-27 00:45','YYYY-MM-DD HH24:mi')
3 ands.event='cursor: pin S wait on X';
P1 TO_CHAR(S.P2) BLOCKING_SESSION SESSION_ID SQL_ID TO_CHAR(S.SAMP
---------- ---------------------------------------- ---------------- ---------- ------------- --------------
2721535173 12262131630080 2855 4225 5y45fw2j3fp65 08-27 00:30:23
2721535173 12262131630080 2855 4225 5y45fw2j3fp65 08-27 00:30:22
2721535173 12262131630080 2855 4225 5y45fw2j3fp65 08-27 00:30:21
2721535173 12262131630080 2855 4225 5y45fw2j3fp65 08-27 00:30:20
2721535173 6876242640896 1601 2855 5y45fw2j3fp65 08-27 00:30:19
2721535173 6876242640896 1601 4225 5y45fw2j3fp65 08-27 00:30:19
2721535173 6876242640896 1601 2855 5y45fw2j3fp65 08-27 00:30:18
2721535173 6876242640896 1601 4225 5y45fw2j3fp65 08-27 00:30:18
2721535173 6876242640896 1601 2855 5y45fw2j3fp65 08-27 00:30:17
2721535173 6876242640896 1601 4225 5y45fw2j3fp65 08-27 00:30:17
2721535173 6876242640896 1601 2855 5y45fw2j3fp65 08-27 00:30:16
2721535173 1979979923456 461 2855 5y45fw2j3fp65 08-27 00:30:10
2721535173 1979979923456 461 2855 5y45fw2j3fp65 08-27 00:30:09
2721535173 1979979923456 461 2855 5y45fw2j3fp65 08-27 00:30:08
2721535173 1979979923456 461 2855 5y45fw2j3fp65 08-27 00:30:07
2721535173 1979979923456 461 2855 5y45fw2j3fp65 08-27 00:30:06
2721535173 2946347565056 686 461 5y45fw2j3fp65 08-27 00:30:05
2721535173 2946347565056 686 2399 5y45fw2j3fp65 08-27 00:30:05
2721535173 2946347565056 686 2855 5y45fw2j3fp65 08-27 00:30:05
2721535173 2946347565056 686 3543 5y45fw2j3fp65 08-27 00:30:05
2721535173 2946347565056 686 4335 5y45fw2j3fp65 08-27 00:30:05
2721535173 2946347565056 686 461 5y45fw2j3fp65 08-27 00:30:04
2721535173 2946347565056 686 2399 5y45fw2j3fp65 08-27 00:30:04
2721535173 2946347565056 686 2855 5y45fw2j3fp65 08-27 00:30:04
2721535173 2946347565056 686 3543 5y45fw2j3fp65 08-27 00:30:04
2721535173 2946347565056 686 4335 5y45fw2j3fp65 08-27 00:30:04
2721535173 2946347565056 686 461 5y45fw2j3fp65 08-27 00:30:03
2721535173 2946347565056 686 2399 5y45fw2j3fp65 08-27 00:30:03
2721535173 2946347565056 686 2855 5y45fw2j3fp65 08-27 00:30:03
2721535173 2946347565056 686 3543 5y45fw2j3fp65 08-27 00:30:03
2721535173 2946347565056 686 4335 5y45fw2j3fp65 08-27 00:30:03
2721535173 2946347565056 686 461 5y45fw2j3fp65 08-27 00:30:02
2721535173 2946347565056 686 2399 5y45fw2j3fp65 08-27 00:30:02
2721535173 2946347565056 686 2855 5y45fw2j3fp65 08-27 00:30:02
2721535173 2946347565056 686 3543 5y45fw2j3fp65 08-27 00:30:02
2721535173 2946347565056 686 4335 5y45fw2j3fp65 08-27 00:30:02
原来是会话ID4225等待2855,2855等待461,461等待686.原来,所有的会话都在等待686会话完成。看来,只有 找到686这个会话在干什么,就知道所有的会话等待问题迎刃而解了。等我找到686会话之后,发现686会话等待是 on cpu。而且686真正执行的sql也是
15y45fw2j3fp65
到这里有点懵了。意思就是,所有的会话都在等待686,所以产生cursor: pin S wait on X等待事件。,而686自己正在执行。
三、问题解决:
到这里就有办法了,就是,减少insert执行时间,就不会产生等待。绑定变量的是28000个,上下文切换频繁,所以减少绑定变量。原来一个insert 拼接800记录,现在拼接300记录,果然发现,执行时间变成1秒,再减少,变成200记录,时间变成0.5秒,再减少100,执行时间变成0.05秒。再往下减少,执行时间不变。