故障溯源是运维工作中十分重要的工作，如果不能正确的完成溯源，可能会导致无法正常消缺，甚至引导运维人员进行错误的操作，导致问题进一步恶化。今天老白要和大家分享的这个案例就是这样的。大概是7、8年前了，老白的一个客户进行应用大版本升级以后，Oracle数据库出现了较为严重的性能问题，主要表现为几个问题。
首先是数据库RED日志的生成频率增加，平均每隔3分钟就会切换一个日志。而之前切换时间都在十多分钟到二十分钟一次。
其次是数据库中出现了大量“enq: TX - row lock contention”,” gc current block busy”,” gc buffer busy”等等待事件。从AWR报告中可以看到行锁等待事件排在第二位：
第三是共享池的争用较为严重，并且经常出现ORA-4031。
基于上述现象，某第三方服务厂商的专家进行了诊断，并提出了以下优化建议：
| 参数名称 | 11月之前的值 | 建议调整值 | 目前值 |
| shared_pool_size | 8G | 15G | 10G |
| db_cache_size | 16G | 20G | 20G |
| large_pool_size | 0 | 256M | 256M |
| java_pool_size | 0 | 128M | 256m |
| sga_target | 50G | 0 | 0 |
在调整前，本系统是使用自动内存管理的，本次调整关闭了内存自动管理，并且加大了共享池。调整后，系统性能未见好转，反而有性能进一步恶化的趋势，两个节点上的ORA-4031错误都更多了，连生成AWR报告也由于ORA-4031而无法完成。
由于服务厂商的调整进一步恶化了系统，因此客户向优化团队求助。老白的团队到达现场后，首先和客户进行了情况调研，通过访谈发现本次故障发生在应用系统升级之后，而业务人员明显感觉两次性能下降，第一次是应用软件升级后的第一个业务高峰期，第二次是第三方服务厂家进行调整后。
从这一点上可以看出，本次性能问题应该和应用软件的升级有很大的关系。从第二次性能恶化的情况来看，性能问题可能与共享池有关。从AWR报告上看：
| % Blocks changed per Read: | 17.05 | Recursive Call %: | 78.12 |
| Rollback per transaction %: | 3.53 | Rows per Sort: | 90.69 |
| Buffer Nowait %: | 99.95 | Redo NoWait %: | 100.00 |
| Buffer Hit %: | 100.02 | In-memory Sort %: | 100.00 |
| Library Hit %: | 94.41 | Soft Parse %: | 92.78 |
| Execute to Parse %: | 10.11 | Latch Hit %: | 99.88 |
| Parse CPU to Parse Elapsd %: | 51.71 | % Non-Parse CPU: | 92.53 |
| Begin | End | |
| Memory Usage %: | 90.22 | 92.49 |
| % SQL with executions>1: | 39.88 | 34.33 |
| % Memory for SQL w/exec>1: | 46.12 | 40.82 |
从上述LOAD PROFILE的数据看，系统的并发访问量并不大，每秒执行数不到1600，从TOP 5 EVENT上看，CPU TIME占58.7，row cache lock等待为12.1%，平均每次等待时间为7毫秒，等待的延时并不算十分严重。从SQL执行的情况看，大于一次执行的SQL的比例为39.88%，尚不足一半。这说明本系统的SQL重用比例很低，大多数SQL只执行一次。
经过与开发商的交流后，优化项目组确定这个应用的特点是大量使用临时表，临时表主要用于两个方面：
- 中间计算临时用表，从业务表中批量抽取数据，存储到中间计算临时表中，然后进行其他计算
- 计算结果临时存储表（这些计算结果放在一张表中，供前台客户查阅，系统约定3小时后这些数据就不使用了，由一个JOB定期清除）
正是由于临时表的使用，才导致了SQL无法多次重复使用，同时由于应用软件中并没有使用Oracle的临时表，而使用了普通表充当临时表。这一点导致了系统产生了大量的REDO。
从应用的这个特点来看，之前的取消SGA自动管理的操作实际上是一个风险十分大的操作。而将SHARED_POOL_SIZE参数从8G加大到15G后，对系统性能几乎没有任何改善。从这一点来看，这个问题不是简单的调整共享池相关的参数就可以解决问题的。要解决这个故障，需要进一步分析应用的特点，然后针对应用特点分析AWR报告中的数据，找到问题的真正根源。
到目前为止，我们已经发现了第一个问题，就是使用普通表充当临时表，这样的操作可能导致下面的问题：
- 产生大量不必要的REDO
- 创建表和删除表会产生大量的共享池争用，恶化共享池的性能
从TOP5 EVENT看：
| Event | Waits | Time (s) | Avg Wait (ms) | % Total Call Time | Wait Class |
| CPU time | 16,635 | 58.7 | |||
| row cache lock | 522,700 | 3,436 | 7 | 12.1 | Concurrency |
| enq:TX - row lock contention | 6,105 | 2,019 | 331 | 7.1 | Application |
| gc current block busy | 36,562 | 801 | 22 | 2.8 | Cluster |
| latch free | 35,000 | 724 | 21 | 2.6 | Other |
所有的等待事件的平均响应时间和所占比例来看，虽然存在一定的问题，但是还不是十分恶化，到底是什么原因导致了故障呢？难道是CPU出现了资源瓶颈吗？从AWR报告上
| Statistic | Total |
| NUM_LCPUS | 0 |
| NUM_VCPUS | 0 |
| AVG_BUSY_TIME | 68,476 |
| AVG_IDLE_TIME | 286,704 |
| AVG_IOWAIT_TIME | 1,023 |
| AVG_SYS_TIME | 5,678 |
| AVG_USER_TIME | 62,684 |
| BUSY_TIME | 2,194,948 |
| IDLE_TIME | 9,178,134 |
| IOWAIT_TIME | 36,599 |
| SYS_TIME | 185,512 |
| USER_TIME | 2,009,436 |
| LOAD | 0 |
| OS_CPU_WAIT_TIME | 2,123,500 |
| RSRC_MGR_CPU_WAIT_TIME | 0 |
| PHYSICAL_MEMORY_BYTES | ############### |
| NUM_CPUS | 32 |
| NUM_CPU_CORES | 16 |
可以看出，本系统有16个双核CPU，平均的IDLE时间接近BUSY的4倍，说明CPU资源十分充足，并无瓶颈。分析过程好像走入了死胡同，于是只能再次从应用入手进行分析，通过分析采样时间内的awr报告，发现下面一条语句消耗了大量的资源：
select o.owner#,
o.obj#,
decode(o.linkname,
null,
decode(u.name, null, 'SYS',u.name),
o.remoteowner),
o.name,
o.linkname,
o.namespace,
o.subname
from user$ u,obj$ o
whereu.user#(+) = o.owner#
and o.type#= :1
andnotexists
(select p_obj# fromdependency$ where p_obj# = o.obj#)
orderby o.obj#
forupdate
上述语句在采样时间内，共执行了26次，每次的执行时间为96.59s，其中CPU花费时间为91.18s,每次的逻辑读为742,554.50。从上述指标来看，该语句的逻辑读较高，由于该表的查询涉及到了SYS用户下的三个数据库表对象，分别是obj$,user$,dependency$，从TOP Segment也可以看到，数据库资源主要集中在了obj$及I_DEPENDENCY2索引之上。下面进行依次说明：
该图表明数据库对象sys.I_DEPENDENCY2 的逻辑读占整个数据库的逻辑读27.92%,同时sys.obj$表的逻辑读占整个数据库的逻辑读6.56%，在Segmentsby Logical Reads中出现两个系统对象，不太正常。
在Segmentsby Row Lock Waits中，sys.obj$对象上的一个索引I_OBJ#的采样时间内共发生行锁等待1810次，占行锁等待的46.84%。
这条语句对字典表进行查询，并且通过forupdate加锁，而这条语句的平均执行时间长达2000多秒，这种操作对共享池会有较大的影响，会引起大量不必要的ROWCACHE方面的争用。
这条语句是哪个应用执行的呢？执行这条语句的目的是什么呢？为了进一步分析这个问题，需要分析ASH的相关数据。通过下面的语句对ASH的数据进行检查：
Select ash.session_id,ash.session_serial#,ash.user_id,ash.program,ash.event
From
v$active_session_history ash,v$event_name en
Where en.event# = ash.event# and ash.sql_id='gfjvxb25b773h'
andash.sample_time >=:begin_date and ash.sample_time< :end_date;
通过上述查询，发现执行这条语句的会话是后台进程smon。而且这条语句也阻塞了大量的前台进程，导致大量前台进程出现“enq: TX - row lock contention”，而被阻塞的前台进程正在执行的语句是：
update obj$ set obj#=:6, type#=:7, ctime=:8, mtime=:9,stime=:10, status=:11, dataobj#=:13, flags=:14, oid$=:15, spare1=:16,spare2=:17 where owner#=:1 and name=:2 and namespace=:3 and(remoteowner=:4 orremoteowner is null and :4 is null)and (linkname=:5or linkname is null and :5 is null) and (subname=:12 or subname is null and :12is null)
这个情况正好和TOP EVENT里的enq: TX - row lock contention等待事件相符了。从上述情况看，这条语句可能和导致系统变慢的主要原因有关。下面就需要找到smon为什么会执行这条语句，这条语句为什么会执行这么长时间的原因了。
为了分析这条SQL的用途，对其他数据库的ASH数据进行了分析，在其他数据库中，只有少量的数据库中发现了SMON执行了这条语句，而且执行的速度都很快，执行时间一般小于20毫秒。从这个现象上看，smon的这种行为可能和应用的特点有关。为什么这条语句在其他系统上执行的很快，而在本系统上执行的那么慢呢？于是再次和开发人员进行了深入的沟通，进一步了解应用的细节。
在和开发人员的沟通中，发现了一个十分重要的一点，就是应用系统在创建了一张临时使用的表后，又在上面创建了一个别名，供后续的操作使用，当临时表的数据超时时，定时JOB会删除别名和临时表。是不是这个操作导致了smon出现这个问题呢？
在分析别名删除的内部原理的时候，发现了一个特殊的操作，当删除别名时，别名表中的数据是由前台进程完成删除的，但是obj$中的别名对象是由smon进程延时删除的，正是这个操作执行了那条select... For update语句。基于这个原理，可以做一个假设。如果obj$中积压了大量待删除的别名对象，那么这条selectfor update语句的执行速度就会变慢，这种积压达到了一定的程度，就可能出现类似的问题。
为了确定这个问题和别名存在直接的关系，通过ASH数据，我们再次分析那些被阻塞的前台会话，发现被锁的会话主要在执行PA_FMIS_BASE.NEWENTITYBYQUERY过程，其中包含了创建临时表和公共同义词。从这一点上，基本上可以定位这个问题和别名的创建和删除有关。
SMON后台进程执行那条selectfor update的目的是为了找到并清理obj$表中的已被drop掉的同义词及其引用的对象（type#=10）。通过下面的语句：
Select count(*)
from user$ u,obj$ o
whereu.user#(+) = o.owner#
and o.type#= 10
andnotexists
(select p_obj# from dependency$ where p_obj# = o.obj#);
查询数据库中不存在（type#=10）的对象时，发现一个现象，上午10点左右查询时，数据库中不存在的对象有1,290,716左右（积压严重），而到了下午下班时段，又进行了一次查询，发现数据库中不存在的对象又增长了10,000。从AWR报告中这条语句的执行次数上我们也可以看到，在1小时的采样周期中，这条语句执行了近30次，而正常情况下，smon每天只做2次这种清理工作（每隔12小时进行一次）。这表明smon进程在清理obj$表中type=10的对象时，发生了性能问题，包括清理速度慢、甚至出现了清理失败后进行重试等情况。
正常情况下，smon进程应该是在数据库启动时或者每隔12小时进行一次obj$对象的清理，因此如果应用每天不停地创建、删除大量的同义词，很可能发生这种由于SMON无法及时清理obj$中type=10的对象产生的性能问题。而且更可怕的是，如果obj$等关键数据字典表不断膨胀，会引起rowcache的严重争用，导致系统整体的性能下降。
根据前期发现的问题，以及分析的结果。临时表的使用和临时表上public别名的滥用是导致本次系统出现行故障的主要原因。而这种应用模式是本系统一直以来所惯用的，和9月份系统升级并无直接关联。9月份系统升级后系统总体性能下降，共享池争用严重化只是一个巧合，是obj$中无效对象积压到一定程度后量变触发质变的结果。
基于上述分析，针对应用的特点，以及导致这个问题的两个主要原因，提出以下几个方面的解决方案：
- 使用ORACLE全局临时表替代目前的普通表充当临时表的做法
- 取消public别名的使用
- 手工清理obj$中的无效对象，解决smon清理临时对象引起的共享池性能问题
可以使用Oracle提供的全局临时表技术（GTT）实现目前普通表操作的功能，其作用域仅限于当前会话。并且GTT的操作本身都是在临时表空间中完成，不会产生redo数据，性能更好。在具体使用GTT时，需要注意以下几点：
- GTT有2种，一种是事务级的（oncommit delete rows），事务完成后，数据就不存在了；另一种是会话级的（on commitpreserve rows），事务完成后，数据还存在，因此在实现时，需要根据需要选择
- 如果使用了会话级的临时表，在该表不再需要时，应用要主动清空该表（truncate table），这样，它才能被临时表清理进程删除
因为应用中使用临时表的地方很多，如果要一次性完成调整，不太容易，建议不妨采用分部走的方式，首先改造一些产生临时表多，调用频繁的存储过程，这样见效会比较快，而且工作量也比较适中。
使用临时表和取消public别名的使用这两个工作都必须修改应用，因此无法立即实施，在应用未完成优化前，需要对obj$进行清理，从而解决目前的性能问题。
首先可以通过停掉所有应用，数据库重启的方式，让SMON进行自动清理，但是如果自动清理速度很慢，达不到明显效果的话，就得尝试用手工清理了，但这种方式存在一定的风险，因此在执行前，数据库必须做全备。具体步骤如下：
一、 在参数文件中设置10052event,来禁用smon清理obj$表的功能，具体的值如下
EVENT="10052 trace namecontext forever, level 65535"
二、 重启数据库到restricted模式。
三、 通过下面的语句进行obj$表的清理
delete from obj$ where(name,owner#) in ( select o.name,u.user# from user$ u, obj$ o where u.user#(+)=o.owner# and o.type#=10 and not exists (select p_obj# from dependency$where p_obj# = o.obj#) );
commit;
四、 关闭数据库（必须shutdown abort）
五、 从参数文件中移除10052event的相关设置
六、 启动数据库，并实时监控数据库alert日志是否出现异常
除了上述操作外，优化小组修改了部分被错误修改的参数，将SGA管理模式恢复为自动管理，SHARED_POOL的最小值加大为12G。完成上述两项修改后，系统恢复正常。
调整了数据库参数，并清理了obj$后，业务部门反映系统总体性能有明显的提升。而从AWR报告上，也看到等待事件恢复了正常：
| Event | Waits | Time(s) | Avg Wait (ms) | % Total Call Time | Wait Class |
| CPU time | 28,482 | 79.8 | |||
| log file parallel write | 750,551 | 742 | 1 | 2.1 | System I/O |
| row cache lock | 1,585,499 | 713 | 0 | 2.0 | Concurrency |
| db file sequential read | 143,706 | 489 | 3 | 1.4 | User I/O |
| gc current block busy | 28,883 | 332 | 11 | .9 | Cluster |
从Load profile上，也可以看出，整个系统的总体处理能力有了十分明显的提升：
Load Profile
| Per Second | Per Transaction | |
| Redo size: | 3,983,191.77 | 83,024.27 |
| Logical reads: | 154,959.25 | 3,229.92 |
| Block changes: | 7,823.44 | 163.07 |
| Physical reads: | 475.71 | 9.92 |
| Physical writes: | 456.42 | 9.51 |
| User calls: | 1,850.22 | 38.57 |
| Parses: | 2,328.50 | 48.53 |
| Hard parses: | 172.94 | 3.60 |
| Sorts: | 694.62 | 14.48 |
| Logons: | 0.13 | 0.00 |
| Executes: | 3,126.54 | 65.17 |
| Transactions: | 47.98 |
从上述数据看，系统的总体吞吐能力提高了一倍多，而各项等待事件都处于良好的状态。Row cache lock方面的等待下降为2%左右，并且平均每次等待时间从7毫秒下降为小于1毫秒，本次优化取得了良好的效果。
下过围棋的朋友都知道序盘最重要的是取势争先，为中盘的缠斗争取最佳的势态。而刚刚进入中高级水平的棋手最难把握的是对形势的判断，何时要保守，何时要拼命，何时急何时缓，都是基于对形势的正确判断。其实优化也是一样，没有对形势的准确判断，我们就无法采取最为正确的优化方案。而判断目前系统的问题主要在哪个方面以及某个优化措施能够发挥多大的作用，是在优化工作中最为困难的一个环节。
本次优化工作经历了两个阶段，第一阶段的优化仅仅调整了部分SGA参数，并没有取得预期的效果。这阶段的主要措施是关闭了共享内存自动管理，加大了DBCACHE和SHARED POOL。一般情况下，这种调整不会低系统产生什么负面的影响，甚至可能对系统有益。不过在这个案例中，这种调整可能会导致系统的问题。因为针对这个系统独特的应用特点，这种调整是存在很大风险的。这个操作仅仅基于本系统由于ORA-4031宕过一次机，并且从AWR报告上看，ROW CACHE和LIBRARY CACHE的争用相当严重，于是就决定采取上述措施。而实际上，基于对该系统应用特点的分析，在这种情况下关闭SGA自动管理是一个十分危险的动作，系统性能问题的根本原因不可能是在SGA自动管理上，因为这个系统的SGA RESIZE虽然存在，但是并不频繁。而关闭SGA自动管理，这种在其他系统中百试百灵，没有副作用的操作，在这个应用系统的环境下，是肯定要出问题的。果不其然，调整后第二天，这个系统的总体性能就出现了下降，虽然从AWR指标上看不出太多的问题，调整参数后半个多月，问题愈发严重，甚至连生成AWR报告都会报ORA-4031了，这个系统随时都有再次宕机的可能。
而第二次优化不仅仅依赖于AWR提供的数据，更多的和开发团队进行了沟通，充分理解了应用软件的特点，结合AWR和应用特点，终于发现临时表和PUBLIC别名这个问题的根源，从而找到了解决问题的正确方向，很好的完成了本次优化工作。
这个例子中的核心点并不是手工处理OBJ$这种充满了风险的操作，而是对系统问题的判断。哪个操作才是导致问题的根源，做哪个操作才能真正解决问题。绝大多数缺乏优化经验的DBA，哪怕是工作了10年的ORACLE高手，也不一定会很准确的完成形势判断，从而一招制敌。准确的判断是基于对系统整体清晰的认识的基础的，没有深入的调研，没有对系统进行深入的剖析，是无法完成真正的优化的。
一个成功的优化工作，是基于对系统总体形势的正确判断的，只有抓住了问题的根源，解决了最为根本的问题，那么这次优化才可能有较为长期的优化效果。而正确额形势判断，仅仅依靠读几份AWR报告，看几条SQL是完全不够的。没有充分的对系统的理解，是很难完成形势判断的。优化其实是一个工程，而不仅仅是某些技术的简单堆砌，只有充分理解应用，才能做出最切合实际的优化方案。
本次分析过程中，参考了两篇ORACLE MOS的文章，有兴趣的朋友可以去MOS上查看：
SMON Consumes High CPU With Excessive Redo Log Generation [ID 1073704.1]
Smon Cleanup Preventing Job Processes From Executing [ID 340128.1]
作者：白鳝
3063
被折叠的 条评论
为什么被折叠?
到【灌水乐园】发言
