极限优化:从75到2000,由技能到性能提升岂止20倍

崔华,网名 dbsnake

Oracle ACE Director,ACOUG 核心专家

编辑手记:感谢崔华授权我们独家转载其精品文章,也欢迎大家向“Oracle”社区投稿。

崔华手记:这篇文章的标题颇有些标题党的味道,但这不是我的初衷。其实我想表达的是,基于RDBMS的应用系统的性能问题绝大多数都是和SQL直接相关,而基于Oracle数据库的SQL优化能否奏效、效果的好与坏归根结底比拼的还是对CBO和执行计划的理解程度,这也正是我在《基于Oracle的SQL优化》一书中提出来的SQL优化方法论的第一点——Oracle里SQL优化的本质是基于对CBO和执行计划的深刻理解

整个事情是这样的……

快下班的时候去打卡,兄弟部门的同事拦住了我,说他们有一个测试系统,性能一直上不去,现在每分钟仅能跑75个Job,想让我帮忙看一下。

简单的用TOP和VMSTAT看了一下,发现在他们并发跑Job的时候,CPU占用率接近100%,IDLE值接近零,看上去瓶颈像是在CPU上。

我让他们将事发时间段的AWR报告发给我,然后我就回家了。

第二天早上来到公司,我打开了这份AWR报告。

如下是这份AWR报告的部分内容:

DB Name

DB Id

Instance

Inst num

Startup Time

Release

RAC

GALT

3872212397

galt

1

17-Apr-13 20:04

11.2.0.1.0

NO

Host Name

Platform

CPUs

Cores

Sockets

Memory (GB)

riserver2

Linux x86 64-bit

4

4

1

15.50

Snap Id

Snap Time

Sessions

Cursors/Session

Begin Snap:

277

22-Apr-13 18:00:45

40

1.8

End Snap:

278

22-Apr-13 19:00:58

91

1.9

Elapsed:

60.22 (mins)

DB Time:

1,413.75 (mins)

Top 5 Timed Foreground Events

Event

Waits

Time(s)

Avg wait (ms)

% DB time

Wait Class

latch: cache buffers chains

894,797

22,111

25

26.07

Concurrency

DB CPU

11,130

13.12

direct path write temp

53,039

1,877

35

2.21

User I/O

db file sequential read

14,467

145

10

0.17

User I/O

latch free

6,208

141

23

0.17

Other

从上述显示内容中我们可以看出,上述数据库在上述采样时间段是非常繁忙的,Cache Buffers Chains有894797次等待,平均等待时间25毫秒,占了26.07%的DB time。

Cache Buffers Chains等待通常说明存在热点块,这可能是由于Oracle自身的Bug(例如“Bug 10396041 – ‘cache buffers chains’ latch contention [ID 10396041.8]”),当然更多的情形是由于应用的某些SQL不恰当的多读了一些本不应该它们读的数据块。所以通常情况下缓解Cache Buffers Chains的方法就是调整SQL,缩减目标SQL所需要读的数据块的数量,这样Cache Buffers Chains等待的数量自然就下去了。

从上述AWR报告中SQL ordered by Gets部分我们可以很轻易的定位出待调整的目标SQL为SQL ID为“73qyztauub2a1”和“74hnt3vjjm85a”的这两条SQL:

SQL ID为“73qyztauub2a1”的SQL文本为如下所示:

SELECT s.LOCATOR_ID, s.segment_ID, n.en_name

FROM ANA_SEG_CLASS S, ana_segment a, ana_name n

where A.SEGMENT_ID = S.SEGMENT_ID

and s.locator_id = n.locator_id

and n.en_name = :1

and ((a.orgn_city = :2 and a.start_time > :3 and a.start_time < :4) or

(a.dstn_city = :5 and a.end_time > :6 and a.end_time < :7))

and n.person_id_count > 0

从同样采样时间段的AWR SQL Report中我们可以看出SQL ID为“73qyztauub2a1”的目标SQL的资源消耗和执行计划为如下所示:

Stat Name

Statement Total

Per Execution

% Snap Total

Elapsed Time (ms)

80,758,772

1,009,484.65

95.21

CPU Time (ms)

10,583,843

132,298.04

95.09

Executions

80

Buffer Gets

2,032,606,807

25,407,585.09

93.88

Disk Reads

419,668

5,245.85

61.45

Parse Calls

80

1.00

1.01

Rows

8

0.10

User I/O Wait Time (ms)

1,729,574

Cluster Wait Time (ms)

0

Application Wait Time (ms)

0

Concurrency Wait Time (ms)

0

Invalidations

0

Version Count

15

Sharable Mem(KB)

482

从上述显示内容中我们可以看出,SQL ID为“73qyztauub2a1”的目标SQL在采样时间段每次执行平均只返回0.1行记录,但平均每次执行需要耗时1009秒,平均每次执行所消耗的逻辑读为25407585。

从该SQL的执行计划我们可以看出,CBO评估出来执行该SQL所对应的成本值为2,这是一个明显异常的值,假如成本值真的像CBO评估的那样为2的话,那么该SQL就不可能平均每次执行需要消耗超过2500万的逻辑读。

很明显,这里很可能是上述SQL所涉及到的对象的统计信息出现了问题,我们现在来检查一下:

表ANA_NAME的统计信息为如下所示:

从上述显示内容中我们可以看出,表ANA_NAME的相关统计信息值全部为0,但实际上表ANA_NAME是一个有300多万数据量的大表:

SQL> select count(*) from ana_name;

COUNT(*)

———-

3180474

所以很明显这里是由于表ANA_NAME的统计信息严重不准而导致CBO选错了执行计划。分析清楚了问题的原因,解决起来就很简单了,我们只需要重新对上述SQL所涉及到的表用如下命令重新收集一下统计信息就好了:

SQL> exec dbms_stats.gather_table_stats(ownname => ‘GALT’,tabname => ‘ANA_NAME’,cascade => true,no_invalidate => false);

PL/SQL procedure successfully completed

SQL> exec dbms_stats.gather_table_stats(ownname => ‘GALT’,tabname => ‘ANA_SEGMENT’,cascade => true,no_invalidate => false);

PL/SQL procedure successfully completed

SQL> exec dbms_stats.gather_table_stats(ownname => ‘GALT’,tabname => ‘ANA_SEG_CLASS’,cascade => true,no_invalidate => false);

PL/SQL procedure successfully completed

重新收集完统计信息后表ANA_NAME的相关统计信息已经有了值:

同时,上述SQL ID为“73qyztauub2a1”的目标SQL的执行计划也已经恢复了正常:

SQL> explain plan for SELECT s.LOCATOR_ID, s.segment_ID, n.en_name FROM ANA_SEG_CLASS S, ana_segment a , ana_name n where A.SEGMENT_ID = S.SEGMENT_ID and s.locator_id = n.locator_id and n.en_name = :1 and ( ( a.orgn_city = :2 and a.start_time > :3 and a.start_time < :4 ) or ( a.dstn_city=:5 and a.end_time> :6 and a.end_time < :7 ) ) and n.person_id_count > 0;

Explained

SQL> col plan_table_output for a200

SQL> select * from table(dbms_xplan.display);

是不是这就完事了?——事情没有这么简单。

表ANA_NAME的那300多万的数据早就存在了,并不是今天早上才导入的,为什么经过了昨晚的自动收集统计信息作业,其各项统计信息的值还是为0?

是不是因为这个库的自动统计信息收集作业被禁掉了?

我们来检查一下:

SQL> select client_name,status from dba_autotask_task;

CLIENT_NAME STATUS

—————————————————————- ——–

sql tuning advisor ENABLED

auto optimizer stats collection ENABLED

auto space advisor ENABLED

SQL> select window_name,autotask_status from dba_autotask_window_clients;

WINDOW_NAME AUTOTASK_STATUS

—————————— —————

MONDAY_WINDOW ENABLED

TUESDAY_WINDOW ENABLED

WEDNESDAY_WINDOW ENABLED

THURSDAY_WINDOW ENABLED

FRIDAY_WINDOW ENABLED

SATURDAY_WINDOW ENABLED

SUNDAY_WINDOW ENABLED

7 rows selected

SQL> select window_name,repeat_interval from dba_scheduler_windows where enabled=’TRUE’;

WINDOW_NAME REPEAT_INTERVAL

—————- ——————————————————

MONDAY_WINDOW freq=daily;byday=MON;byhour=22;byminute=0; bysecond=0

TUESDAY_WINDOW freq=daily;byday=TUE;byhour=22;byminute=0; bysecond=0

WEDNESDAY_WINDOW freq=daily;byday=WED;byhour=22;byminute=0; bysecond=0

THURSDAY_WINDOW freq=daily;byday=THU;byhour=22;byminute=0; bysecond=0

FRIDAY_WINDOW freq=daily;byday=FRI;byhour=22;byminute=0; bysecond=0

SATURDAY_WINDOW freq=daily;byday=SAT;byhour=6;byminute=0; bysecond=0

SUNDAY_WINDOW freq=daily;byday=SUN;byhour=6;byminute=0; bysecond=0

7 rows selected

SQL> select window_name, job_name, job_start_time from (select * from dba_autotask_job_history where client_name=’auto optimizer stats collection’ order by window_start_time desc) where rownum<4;

WINDOW_NAME JOB_NAME JOB_START_TIME

————— ——————— ————————————

TUESDAY_WINDOW ORA$AT_OS_OPT_SY_1 09-4月 -13 10.00.00.825901 下午 PRC

SQL> select window_name,window_next_time from dba_autotask_window_clients;

WINDOW_NAME WINDOW_NEXT_TIME

—————————— ————————————-

MONDAY_WINDOW 15-4月 -13 10.00.00.000000 下午 PRC

TUESDAY_WINDOW 16-4月 -13 10.00.00.000000 下午 PRC

WEDNESDAY_WINDOW 10-4月 -13 10.00.00.000000 下午 PRC

THURSDAY_WINDOW 11-4月 -13 10.00.00.000000 下午 PRC

FRIDAY_WINDOW 12-4月 -13 10.00.00.000000 下午 PRC

SATURDAY_WINDOW 13-4月 -13 06.00.00.000000 上午 PRC

SUNDAY_WINDOW 14-4月 -13 06.00.00.000000 上午 PRC

7 rows selected

从上述显示内容中我们可以看出,上述库的自动统计信息收集作业并没有被禁掉,只是出于某种原因,自4月9日晚上10点最后一次运行完后就再没有被执行过。

Oracle 11g里的自动统计信息收集作业每次运行时会先生成名为ORA$AT_OS_OPT_XXX的Job,然后再执行这个Job。所以有一种可能就是虽然自动统计信息收集作业没有被禁掉,但Oracle在生成Job的时候碰到了问题,比如参数job_queue_processes的值被设成了0。

从如下查询结果中我们可以看到,上述库的job_queue_processes的值果然是0:

SQL> show parameter job;

NAME TYPE VALUE

———————————— ———– ——————————

job_queue_processes integer 0

从上述库的alert log里我们看到了如下内容:

Wed Apr 10 14:09:50 2013

ALTER SYSTEM SET job_queue_processes=0 SCOPE=BOTH;

Wed Apr 10 14:10:26 2013

ALTER SYSTEM SET aq_tm_processes=0 SCOPE=BOTH;

ALTER DATABASE OPEN

Wed Apr 10 14:10:35 2013

这说明上述库的参数job_queue_processes和aq_tm_processes在4月10日下午2点多的时候被修改成了0,难怪上述库的自动统计信息收集作业自4月9日晚上10点最后一次运行完后就再没有被成功执行过。

我们将上述两个参数的值给改回来:

SQL> alter system set job_queue_processes = 1000 scope=both;

System altered

SQL> alter system set aq_tm_processes = 1 scope=both;

System altered

SQL> show parameter job_queue_processes;

NAME TYPE VALUE

———————————— ———– ——————————

job_queue_processes integer 1000

SQL> show paramete aq_tm_processes;

NAME TYPE VALUE

———————————— ———– ——————————

aq_tm_processes integer 1

从如下查询结果中我们可以看到,参数job_queue_processes恢复成大于0的值后,上述库的自动统计信息收集作业的各个窗口所对应的WINDOW_NEXT_TIME的值也随之恢复了正常:

SQL> select window_name,window_next_time from dba_autotask_window_clients;

WINDOW_NAME WINDOW_NEXT_TIME

—————————— ————————————

MONDAY_WINDOW 29-4月 -13 10.00.00.000000 下午 PRC

TUESDAY_WINDOW 23-4月 -13 10.00.00.000000 下午 PRC

WEDNESDAY_WINDOW 24-4月 -13 10.00.00.000000 下午 PRC

THURSDAY_WINDOW 25-4月 -13 10.00.00.000000 下午 PRC

FRIDAY_WINDOW 26-4月 -13 10.00.00.000000 下午 PRC

SATURDAY_WINDOW 27-4月 -13 06.00.00.000000 上午 PRC

SUNDAY_WINDOW 28-4月 -13 06.00.00.000000 上午 PRC

7 rows selected

接下来,我们对上述SQL所涉及到的schema重新收集了一下统计信息(以避免再次出现有目标表的统计信息严重不准的情形):

SQL> EXEC DBMS_STATS.GATHER_SCHEMA_STATS(OWNNAME => ‘GALT’,ESTIMATE_PERCENT => DBMS_STATS.AUTO_SAMPLE_SIZE,CASCADE => TRUE,METHOD_OPT => ‘FOR ALL COLUMNS SIZE REPEAT’,no_invalidate => false);

PL/SQL procedure successfully completed

此时第一阶段的调整就结束了,根据同事的反馈,现在每分钟能跑的Job的数量已经从之前的75上升到了现在的2000 。

原文发布于微信公众号 - 数据和云(OraNews)

原文发表时间:2016-05-11

本文参与腾讯云自媒体分享计划,欢迎正在阅读的你也加入,一起分享。

发表于

我来说两句

0 条评论
登录 后参与评论

相关文章

来自专栏数据和云

DBA入门之路:察微知渐细致入微

在DBA的职业生涯中,要面临无数的艰难险阻、排忧解难,所以细致入微,严谨认真的风格必不可少。养成了察微知渐的习惯,才能在分析诊断故障时层剖缕析,直指核心;而我也...

2013
来自专栏数据和云

自相矛盾:一个进程可以自成死锁么?

崔华,网名 dbsnake Oracle ACE Director,ACOUG 核心专家 编辑手记:感谢崔华授权我们独家转载其精品文章,也欢迎大家向“Oracl...

3364
来自专栏杨建荣的学习笔记

通过错误的sql来测试推理sql的解析过程(二) (r8笔记第7天)

之前总结过一篇 通过错误的sql来测试推理sql的解析过程 也算是以毒攻毒,当然也分析出来一些有意思的内容来,让原本看起来枯燥的内容有了更多的实践意义。 ...

2629
来自专栏杨建荣的学习笔记

job处理缓慢的性能问题排查与分析(r4笔记第18天)

昨天开发的同事找到我说,生产有个job处理数据的速度很慢,想让我帮忙看看是怎么回事,最近碰到这种问题相对比较多了,但是问题的原因也是五花八门。我还是大体找他们了...

2746
来自专栏数据和云

Oracle智能之SQL诊断:SQL Tuning Advisor推荐执行计划

编辑手记:在前一段,一篇智能数据库优化的论文引起广泛的关注,其实在 Oracle 数据库中,已经引入了大量自动化和智能化的方法去进行自动调节,包括在 SQL 层...

2725
来自专栏编程

计算机专业基础书籍推荐

编辑:小虾米 夏沫 本文根据网上的参考资料以及自己的学习经验总结整理而成,旨在给大家做一个参考,希望大家在工作、学习中遇到相关的问题之后能从这些参考书中获得帮...

19110
来自专栏杨建荣的学习笔记

数据库负载急剧提高的应急处理(二) (r9笔记第55天)

对于之前碰到的一个数据库负载急剧提升的问题,做了应急处理之后,我们需要再冷静下来,来看看是哪些地方出现了问题,还需要哪些改进。 首先第一个问题就是为什么会突然负...

3184
来自专栏数据和云

Oracle 12c 新特性:SQL Plan Directives与过量的动态采样解析

在 12c 中,优化器进行了较大的改变,推出了 Adaptive query optimization,从整体上说,Adaptive query optimiz...

842
来自专栏杨建荣的学习笔记

一条看似平常的报警邮件所做的分析(r8笔记第9天)

今天留意到一封报警邮件。内容如下: ZABBIX-监控系统: ------------------------------------ 报警内容: CPU u...

2334
来自专栏数据和云

极致之处,精彩无限 - 优化了一半的SQL

编辑手记:RWP(Real World Performance)团队是全球最优秀的性能优化团队,他们的目标在于系统性能千倍的提升。感谢刘永甫专家的授权,他从RW...

3455

扫描关注云+社区