今天下午收到客户的邮件,说有一个job在运行的时候报错了,希望我们能帮忙看看是什么原因。
ERROR: Caught en exception: ORA-12801: error signaled in parallel query server P130
ORA-27090: Unable to reserve kernel resources for asynchronous disk I/O
Linux-x86_64 Error: 2: No such file or directory
Additional information: 3
Additional information: 128
Additional information: 1
ORA-27090: Unable to reserve kernel resources for asynchronous disk I/O
Linux-x86_64 Error: 2: No such file or directory
Additional information: 3
Additional information: 128
Additional information: 1
ORA-27090: Unable to reserve kernel resources for asynchronous disk I/O
Linux-x86_64 Error: 2: No such file or directory
Additional information: 3
Additional information: 128
Additional information: 1
ORA-27090: Unable to reserve kernel resources for asynchronous disk I/O
Additional information: 3
Additional information: 128
Additional information: 2113522240
ORA-27090: Unable to reserve kernel resources for asynchronous disk I/O
Additional information: 3
Additional information: 128
Additional information: 2113522240
从错误信息来看是由于并行进程引起的,查看了客户提供的日志,这个job是一个每天都会执行的job,每次回启用几个独立的process来并行跑,每个process里面的sql语句都走了并行,并行度是8,所以占用的session数不会太多,在100个以内是肯定的。
这个时候查看awr只能在报告头看到session的数据,得到不一些具体的session占用情况,查看ash也得不到,因为得到的都是active session的信息。
这些信息可以自己使用脚本来自动采集,也会有所侧重,得到的数据也更有意义和说服力。
我抓取了下午的报告,报告的时间在错误发生前几分钟。
可以看到session数已经用了不少了,而且绝大多数的session都在JDBC的程序上。
STATUS CNT
-------- ----------
ACTIVE 165
INACTIVE 9879
----------
sum 10044
.
PROGRAM CNT STATUS
----------------------------------- ---------- --------
JDBC Thin Client 9113 INACTIVE
extract@ccbdbpr (TNS V1-V3) 90 INACTIVE
Session_count osuser hash_value sql_id
1 truwl71 1443142349 bhm5y9tb096qd
4844 pcmwrk01 3361273624 5vxmncv45jxss
42 truwl15 941869720 f6hcnghw27kns
4 pcowrk01 3359590350 fa311gg43yjyf
15 pcmwrk01 2311663385 27uaksf4wkbst
65 parwrk01 1950821498 459f3z9u4fb3u
2 truwl74 1443142349 bhm5y9tb096qd
15 truwl35 941869720 f6hcnghw27kns
1 truwl35 3428812084 bwjxuug65z19n
30 truwl22 941869720 f6hcnghw27kns
1 truwl41 4042609743 bg0xgs3sgap2g
9 pcmwrk01 1204453754 frvwp893wp0bu
2 truwl74 4042609743 bg0xgs3sgap2g
1 truwl71 1488663547 b26tu71cbqczv
192 pcmwrk01 20635029 byd95500mprcp
1 truwl71 2397213050 26b628u7f54bu
64 pcmwrk01 2555678015 6vf0fzkc5939z
425 pcmwrk01 1950821498 459f3z9u4fb3u
36 truwl32 941869720 f6hcnghw27kns
5 parwrk01 1209197086 07h65fd415shy
1 truwl25 1605399126 g1p5bjdgv0wkq
32 truwl71 941869720 f6hcnghw27kns
32 truwl14 941869720 f6hcnghw27kns
449 pcmwrk01 3203606695 dm03006zg6a57
40 truwl65 941869720 f6hcnghw27kns
33 truwl43 941869720 f6hcnghw27kns
2 truwl53 647050378 f9mmq7sm92d4a
可以很明显看到sql_id(5vxmncv45jxss)占用了相当多的session,可以断定这些session都是inactive的。这个可以通过如下的信息来验证。
STATUS CNT
-------- ----------
ACTIVE 165
INACTIVE 9879
----------
sum 10044
查看问题语句对应的系统用户竟然是另外一个模块的。根据sql_id抓取了对应的sql语句,是一个很简单的select 语句。
/* CM9_ServiceAgreement_selectServiceAgreement_1 */ SELECT xxxxx FROM SERVICE_AGREEMENT WHERE SERVICE_AGREEMENT.AGREEMENT_NO = :1 AND SERVICE_AGREEMENT.EXPI
RATION_DATE IS NULL
和开发做了确认,发现这是一个客户化的job导致的问题,已经做了修复,打了补丁到生产环境,时间是今天凌晨,所以客户就希望我们能够看看哪些占用很多的session是以前的历史session还是今天的,这个问题看似挺容易,但是却是无处可查,
v$session中的信息早就被刷掉了,要得到哪些session的登录时间来判断是很难的,除非自己做了更多细致的监控。
这个时候我是通过另外一个思路来推的。
我抓取了几个报告。
问题发生一个小时前的报告,在2点左右,session数在9000左右,pcmwrk占用的session是2000多。
然后抓取了上午11点的报告,pcmwrk占用的session在4000多。
通过这些信息还不能推论是否有大量的历史session.
我又抓取了一个问题发生1个小时后的报告,大概在5点左右,pcmwrk占用的session在15个左右。
通过这个就可以很自信的告诉客户,这些session都是今天的,至于为什么占用这么多的session,和补丁的修复也有关系,开发还在继续排查和分析。
这个问题告诉我们,一个看似简单的问题可能是由另外一个问题导致的。问题的背后都有一定的原因,需要我们留心,可能在排查的时候就会轻松很多。