一个oracle bug的简单验证(r8笔记第45天)

最近碰到了一个oracle bug，但是我感觉还是有些运气的成分，虽然错误日志和bug描述吻合，版本也完全对应，现在有几个问题在我脑海中翻腾，就是这个问题是不是一个特例，是不是一些额外的原因导致的，于是我翻出了日志重新来看。 这是一个一主两备的环境，一个本地灾备，一个异地灾备，数据库版本是10.2.0.4.0，单实例 数据库日志如下： Redo Shipping Client Connected as PUBLIC -- Connected User is Valid RFS[8]: Assigned to RFS process 17656 RFS[8]: Identified database type as 'physical standby' RFS[8]: Archived Log: '/U01/app/oracle/flash_recovery_area/Stest2/archivelog/2016_03_21/o1_mf_1_8080_cgxw8n7l_.arc' Mon Mar 21 02:51:34 2016 ksvcreate: Process(m000) creation failed Mon Mar 21 02:52:34 2016 ksvcreate: Process(m000) creation failed Mon Mar 21 02:53:34 2016 ksvcreate: Process(m000) creation failed 为什么是在2:50开始会报出这个错误，也是有一定的触发条件，那就是每天的2:50会开启一个查询窗口，然后在几个小时后关闭窗口，想来11g是该有多幸福啊。 上面的错误日志就是在crontab中设定的数据库状态从read-only和online之间不断的切换报出的。 看到这些日志，感觉有几个疑点。 1）为什么2:50开始就会报出这个错误，是否和应用的查询有关，有性能不良的sql语句导致 2）对于应用，是否开启了大批量的查询session，导致系统的进程资源不足 3）是否是系统层面的资源使用紧张导致 4）10gR2的环境其实还有一套，但是那套备库环境印象中却没有类似的错误日志 5）问题能够重现 6）问题的解决方案 对于这几个问题，相信弄明白了，自己说服自己了最重要。 首先第一个问题，是否和应用的查询有关，是否有性能不良的sql语句导致。因为是10g的备库，所以ash的信息这块还是不独立的，如果需要监控只能自己 定制监控了。当然这种活自己也是驾轻就熟，但是先可以放一放，我的设想是如果没有sql语句的问题，先看看后面的几个问题。 然后第二个问题，是否有大批量的查询导致的session溢出 查看最新的一部分日志，发现了下面的情况 [@test.cyou.com bdump]$ ls -lrt|tail -20 -rw-r----- 1 oracle oinstall 911 Mar 21 02:50 test_p012_17123.trc -rw-r----- 1 oracle oinstall 911 Mar 21 02:50 test_p011_17121.trc -rw-r----- 1 oracle oinstall 911 Mar 21 02:50 test_p010_17119.trc -rw-r----- 1 oracle oinstall 911 Mar 21 02:50 test_p009_17117.trc -rw-r----- 1 oracle oinstall 909 Mar 21 02:50 test_p008_17115.trc -rw-r----- 1 oracle oinstall 908 Mar 21 02:50 test_p007_17113.trc -rw-r----- 1 oracle oinstall 911 Mar 21 02:50 test_p006_17111.trc -rw-r----- 1 oracle oinstall 911 Mar 21 02:50 test_p005_17109.trc -rw-r----- 1 oracle oinstall 912 Mar 21 02:50 test_p004_17107.trc -rw-r----- 1 oracle oinstall 912 Mar 21 02:50 test_p003_17105.trc -rw-r----- 1 oracle oinstall 911 Mar 21 02:50 test_p002_17103.trc -rw-r----- 1 oracle oinstall 909 Mar 21 02:50 test_p001_17101.trc -rw-r----- 1 oracle oinstall 911 Mar 21 02:50 test_p000_17099.trc -rw-r----- 1 oracle oinstall 3002 Mar 21 02:50 test_mrp0_17097.trc -rw-r----- 1 oracle oinstall 57547 Mar 21 06:29 test_mmon_338.trc -rw-r----- 1 oracle oinstall 3236 Mar 21 06:30 test_rsm0_391.trc -rw-r----- 1 oracle oinstall 2475 Mar 21 06:30 test_dmon_342.trc -rw-r----- 1 oracle oinstall 2013 Mar 21 19:42 test_mrp0_3136.trc -rw-r----- 1 oracle oinstall 367817 Mar 21 19:42 alert_test.log -rw-r----- 1 oracle oinstall 567898962 Mar 21 21:29 drctest.log 里面的亮点在于出现了大量的p00x的进程，这些都是一些和并行相关的进程。但是为什么要并行呢。自己一个直接的联想是可能启用并行的一些操作，比如并行 查询，如果session数足够多，可能就会抛出资源使用的问题了。当然，因为没有任何监控，目前这是一个猜想，当然也可以间接从zabbix的监控中看 出确实没有进程的急剧提升 抓取其中的一个日志来看看。 /U01/app/oracle/admin/test/bdump/test_p000_12950.trc Oracle Database 10g Enterprise Edition Release 10.2.0.4.0 - 64bit Production With the Partitioning, OLAP, Data Mining and Real Application Testing options ORACLE_HOME = /U01/app/oracle/product/10.2 System name: Linux Node name: test.cyou.com Release: 2.6.18-128.el5 Version: #1 SMP Wed Dec 17 11:41:38 EST 2008 Machine: x86_64 Instance name: test Redo thread mounted by this instance: 1 Oracle process number: 23 Unix process pid: 12950, image: oracle@test.cyou.com (P000) *** 2016-03-20 02:50:01.953 *** SERVICE NAME:() 2016-03-20 02:50:01.952 *** SESSION ID:(2956.3620) 2016-03-20 02:50:01.952 Slave exiting with ORA-10388 exception KCBR: Number of read descriptors = 1024 KCBR: Media recovery blocks read (ASYNC) = 1328 KCBR: Redo cache copies/changes = 16458/16458 KCBR: Influx buffers flushed = 8 times KCBR: Reads = 119 reap (110 no-op, 0 one), 30 all 如果认为还不足以论证或者先不太明白，可以先放一放。 第三个问题，系统层面的资源是否紧张。这个可以从zabbix看出，无论io，cpu，cache，swap都没有出现任何紧张的情况 Tasks: 216 total, 1 running, 214 sleeping, 0 stopped, 1 zombie Cpu(s): 0.4%us, 0.0%sy, 0.0%ni, 99.6%id, 0.0%wa, 0.0%hi, 0.0%si, 0.0%st Mem: 65996408k total, 39600240k used, 26396168k free, 1014300k buffers Swap: 8385920k total, 232k used, 8385688k free, 37149992k cached 从目前的情况来看，资源的情况还是比较富足的。 那么第四个问题10gR2的环境还有一套，为什么没有类似的错误，经过验证，发现那套环境是10.2.0.5.0的环境，而一个相关的bug是5583049， mos中的描述很清晰。问题发生在10.2.0.4的版本中，在其它的平台会有一些差别。

Patch 5583049: 'KSVCREATE: PROCESS(M000) CREATION FAILED' AFTER STANDBY OPEN RO MULTIPLE TIMES
Last Updated     18-Jul-2009 06:33 (6+ years ago)   Size     23.5 KB              
Product     Oracle Database - Enterprise Edition     
Release     Oracle 10.2.0.4                        Classification     General    
Platform     Linux x86-64                           Patch Tag       

所以这个问题在10.2.0.5，经过验证是不存在的。 然后第5个问题，那就来复现一些，复现的过程如果顺利会解释清楚第一个和第二个问题的可能性 验证很简单，就是把备库置为read-only状态 DGMGRL> edit database speak4 set state='read-only'; Succeeded. 然后查看日志，发现问题竟然能够马上复现，而且很有规律，是一分钟会出现一次，从目前的青年卡来看，和应用的sql导致的影响不大了。 对于数据库层面的资源使用，可以参考下面的查询结果。 SQL> select * from v$resource_limit; RESOURCE_NAME CURRENT_UTILIZATION MAX_UTILIZATION INITIAL_ALLOCATION LIMIT_VALUE ----------------------- ------------------- --------------- -------------------- -------------------- processes 36 41 1000 1000 sessions 27 46 3000 3000 enqueue_locks 29 93 32860 32860 enqueue_resources 29 29 13420 UNLIMITED 发现session数还远远未达到，所以这个可能性极低。 所以这个问题基本能够看出确实复现了问题，那么怎么进一步验证呢，我们可以打开另外一个备库来，验证一下，切换两次之后，也看到了同样的错误。 通过上面的各种测试已经能够充分能够验证问题所在了。 好了最后一个问题，那就是如何解决，官方提供了两种方案。 一种是重启，另外一种是设置关闭sga自动管理，并设置statistics=basic 这种方案还是根据具体的情况来选用。为什么设置statistics=basic需要关闭sga的自动管理呢。 SQL> alter system set statistics_level=basic; alter system set statistics_level=basic * ERROR at line 1: ORA-02097: parameter cannot be modified because specified value is invalid ORA-00830: cannot set statistics_level to BASIC with auto-tune SGA enabled 这个错误已经很明显说明了这种依赖。 当然自己还是认真测了论证了一番，发现确实如此，重新切换read-only,online就再没有这个问题了。 通过这个小的案例可以看出，其实一个很细小的问题还是需要投入一些认真的测试，不能简单认为是一个bug就草率了事,自己说服了自己，处理问题才会更加从容不迫。