ITPUB论坛－专业的IT技术社区

登录 注册
ITPUB论坛－专业的IT技术社区»论坛 › ≡ 大数据与数据库 ≡ › Oracle数据库管理 › RAC中一次混乱的性能诊断过程
12下一页
返回列表 发新帖
查看: 6420|回复: 14
收藏 | 打印 上一主题 下一主题

RAC中一次混乱的性能诊断过程

[复制链接]
gaopengtttt
论坛徽章:
9
ITPUB社区OCM联盟徽章 日期:2013-03-27 11:17:11奥运纪念徽章 日期:2013-06-18 09:13:52ITPUB社区千里马徽章 日期:2013-08-22 09:58:03大众 日期:2013-08-30 14:51:33路虎 日期:2013-12-01 18:25:42
跳转到指定楼层
1#
发表于 2011-7-13 16:32 | 只看该作者 回帖奖励 |倒序浏览 |阅读模式

RAC中一次混乱的性能诊断过程
   众所周知在RAC中，问题很可能来自于CACHE FUSION（内存融合）的机制，简单的说就是CACHE BUFFER中的块在内存融合的机制下通过LMD进程进行传递，比如我节点1需要访问数据块A，通过SEND MESSAGE到MASTER节点询问块A所在的节点，MASTER告诉节点1 A块在节点2的BUFFER CACHE中，这个时候又可能是当前读和一致性读，如果块正在被修改就会构架PI来进行一致性读，传递块给节点1，这个时候PCM锁是X模式，如果当前块A没有被修改，只是被节点2SELECT，这个时候就是当前读，传递当前块给节点1，这个时候PCM锁是S模式，这个大概就是内存融合的机制。
  最近遇到一个问题我们数据库服务器在高负载的情况下，CPU降低到40%左右，我试图找到问题，因为数据库服务器是RAC，并且AWRRPT的TOP5 EVENT如下：
Top 5 Timed Events
Event
Waits
Time(s)
Avg Wait(ms)
% Total Call Time
Wait Class
CPU time
4,677
79.7
gc cr multi block request
6,108,620
793
0
13.5
Cluster
gc buffer busy
117,685
138
1
2.3
Cluster
db file sequential read
65,355
105
2
1.8
User I/O
gc current block 2-way
205,250
79
0
1.3
Cluster


首先可以肯定的是这个问题绝对是处在块传递上，解决这样的问题有2个方法
1、
用SERVICE 来分离业务，通过分离业务让特定的数据块只在指定的节点里进行访问，避免传递。
2、
尽可能的减少逻辑读，逻辑读少了自然传递的可能性就小了，也就是这一点让我前期的诊断陷入了错误的方向。
分离业务是不能的，因为牵涉太大，所以我自然而然的想到了减少逻辑读，带着这个理念我进入了查看SQL的阶段，首先当然是查看最耗时的SQL
SQL ordered by Elapsed Time
  • Resources reported for PL/SQL code includes the resources used by all SQL statements called by the code.
  • % Total DB Time is the Elapsed Time of the SQL statement divided into the Total Database Time multiplied by 100
  • Total DB Time (s): 5,870
  • Captured SQL account for 16.7% of Total
Elapsed Time (s)
CPU Time (s)
Executions
Elap per Exec (s)
% Total DB Time
SQL Id
SQL Module
SQL Text
66
61
10
6.61
1.13
  
SELECT * FROM ( Select RowNum ...
66
59
10
6.56
1.12
  
SELECT COUNT(*) FROM TEST1...
58
54
1
57.80
0.98
  
SELECT * FROM ( Select RowNum ...
46
43
7
6.56
0.78
  
SELECT COUNT(*) FROM TEST1 ...
45
44
7
6.45
0.77
  
SELECT * FROM ( Select RowNum ...
37
25
3
12.24
0.63
  
select ti.serialno itemNo, ti....
33
33
5
6.56
0.56
  
SELECT * FROM ( Select RowNum ...
33
31
5
6.52
0.56
  
SELECT COUNT(*) FROM TEST1 ...
32
29
58
0.55
0.54
  
SELECT DISTINCT Wflog.* FROM W...
32
29
5
6.31
0.54
  
SELECT COUNT(*) FROM TEST1 ...

结果可以看到基本没有特别耗时的SQL，所以想通过优化单个SQL来大幅度提高性能的想法是不能实现的，然后进入查看最多逻辑读取的SQL
SQL ordered by Gets
  • Resources reported for PL/SQL code includes the resources used by all SQL statements called by the code.
  • Total Buffer Gets: 584,021,980
  • Captured SQL account for 32.1% of Total
Buffer Gets
Executions
Gets per Exec
%Total
CPU Time (s)
Elapsed Time (s)
SQL Id
SQL Module
SQL Text
17,941,301
10
1,794,130.10
3.07
60.59
66.10
  
SELECT * FROM ( Select RowNum ...
17,941,301
10
1,794,130.10
3.07
58.65
65.59
  
SELECT COUNT(*) FROM TEST1...
12,532,568
7
1,790,366.86
2.15
43.76
45.18
  
SELECT * FROM ( Select RowNum ...
12,532,548
7
1,790,364.00
2.15
43.05
45.91
  
SELECT COUNT(*) FROM TEST1...
8,932,380
5
1,786,476.00
1.53
29.04
31.14
  
SELECT COUNT(*) FROM TEST1...
8,932,379
5
1,786,475.80
1.53
29.90
30.93
  
SELECT * FROM ( Select RowNum ...
8,915,316
5
1,783,063.20
1.53
30.75
32.61
  
SELECT COUNT(*) FROM TEST1...
8,915,315
5
1,783,063.00
1.53
33.06
32.80
  
SELECT * FROM ( Select RowNum ...
8,900,709
5
1,780,141.80
1.52
29.95
31.08
  
SELECT * FROM ( Select RowNum ...
8,900,701
5
1,780,140.20
1.52
29.24
31.55
  
SELECT COUNT(*) FROM
TEST1...
6,705,179
1
6,705,179.00
1.15
53.53
57.80
  
SELECT * FROM ( Select RowNum ...


通过分析这里可能出现问题，因为SQL都是差不多或者说引用的对象都差不多，我最开始想如果能够找到方法减少这里的逻辑读，那问题一定能够改善，接着直接查看逻辑读最多的SEGMENT
Segments by Logical Reads
  • Total Logical Reads: 584,021,980
  • Captured Segments account for 99.1% of Total
Owner
Tablespace Name
Object Name
Subobject Name
Obj. Type
Logical Reads
%Total
PROD
PROD_TBS
PK_TEST
INDEX
161,827,056
27.71
PROD
PROD_TBS
PK_TEST1
INDEX
128,519,568
22.01
PROD
PROD_TBS
TEST1
TABLE
59,829,760
10.24
PROD
PROD_TBS
TEST2
TABLE
54,734,688
9.37
PROD
PROD_TBS
TEST3
TABLE
37,143,040
6.36

分析后这些SEGMENT都是以上语句涉及到的，因为语句基本同形，我就开始了SQL调优。
性能, font

使用道具 举报

回复
gaopengtttt
论坛徽章:
9
ITPUB社区OCM联盟徽章 日期:2013-03-27 11:17:11奥运纪念徽章 日期:2013-06-18 09:13:52ITPUB社区千里马徽章 日期:2013-08-22 09:58:03大众 日期:2013-08-30 14:51:33路虎 日期:2013-12-01 18:25:42
2#
 楼主| 发表于 2011-7-13 16:42 | 只看该作者
一切好像都已经找到根源，如果我能减少这些语句逻辑读那问题就解决了。
但是后来我发现问题并非如此，CACHE FUSION传递的是逻辑块，但是引起逻辑读最高的语句不一定就是引起CACHE FUSION的语句。后来我查看了SQL按照CLUSTER WAIT排序
SQL ordered by Cluster Wait Time
Cluster Wait Time (s)        CWT % of Elapsd Time        Elapsed Time(s)        CPU Time(s)        Executions        SQL Id        SQL Module        SQL Text
18.02        49.06        36.73        24.68        3        9xwa8z12j7t70
          select ti.serialno itemNo, ti....
14.58        48.02        30.35        18.81        2        d786an1rx2zhg
          select ti.serialno itemNo, ti....
14.18        47.90        29.60        18.39        2        00h3bza336z9t
          select ti.serialno itemNo, ti....
11.81        48.58        24.32        15.23        2        14sgv87uwx9au
          select ti.serialno itemNo, ti....
10.08        52.87        19.06        9.99        1        g6htdj8u01bu6
          select ti.serialno itemNo, ti....
9.22        51.46        17.92        10.29        1        9mfptg5r6rr9y
          select ti.serialno itemNo, ti....
9.01        43.47        20.73        11.44        2        fyy7w418qk66k
          select ti.serialno itemNo, ti....
可以看到这里的语句和了逻辑读和耗时的语句完全不同，并且较多，也是同形的。开始我觉得没有过分耗时的语句就不算有性能问题，所以没有关注，后来我又通过语句查看了CLUSTER等待的SQL语句如下：
select wait_class_id, wait_class, count(*) cnt
   from dba_hist_active_sess_history
   where snap_id between 7744 and 7745
   group by wait_class_id, wait_class
   order by 3
select event_id, event, count(*) cnt from dba_hist_active_sess_history
  where snap_id between 7744 and 7745 and wait_class_id=3871361733
  group by event_id, event
  order by 3;
   select sql_text from dba_hist_sqltext where sql_id in
   (select sql_id from dba_hist_active_sess_history
   where snap_id between 7744 and 7745
   and event_id in (661121159)
   group by sql_id);
   最后得出的语句是：

select ti.serialno itemNo,       ti.insuredcode
select ti.serialno itemNo,       ti.insuredcode
select ti.serialno itemNo,       ti.insuredcode
select ti.serialno itemNo,       ti.insuredcode
select ti.serialno itemNo,       ti.insuredcode
select ti.serialno itemNo,       ti.insuredcode
select ti.serialno itemNo,       ti.insuredcode
select ti.serialno itemNo,       ti.insuredcode
select ti.serialno itemNo,       ti.insuredcode
select ti.serialno itemNo,       ti.insuredcode
这个也验证了AWRRPT的结果，然后我转向查看SEGMENT信息，我这里只给出了语句一部分，我查看了语句完全相同。

使用道具 举报

回复
gaopengtttt
论坛徽章:
9
ITPUB社区OCM联盟徽章 日期:2013-03-27 11:17:11奥运纪念徽章 日期:2013-06-18 09:13:52ITPUB社区千里马徽章 日期:2013-08-22 09:58:03大众 日期:2013-08-30 14:51:33路虎 日期:2013-12-01 18:25:42
3#
 楼主| 发表于 2011-7-13 16:51 | 只看该作者
Segments by Global Cache Buffer Busy
  • % of Capture shows % of GC Buffer Busy for each top segment compared
  • with GC Buffer Busy for all segments captured by the Snapshot
Owner
Tablespace Name
Object Name
Subobject Name
Obj. Type
GC Buffer Busy
% of Capture
PROD
PROD_TBS
Test100
TABLE
117,030
99.99
Segments by Current Blocks Received
  • Total Current Blocks Received: 8,649,348
  • Captured Segments account for 99.6% of Total
Owner
Tablespace Name
Object Name
Subobject Name
Obj. Type
Current Blocks Received
%Total
PROD
PROD_TBS
Test100
TABLE
8,320,599
96.20
我这里给出了第一行，我觉得可以说明问题了，然后我查看了语句，发现语句确实包含了TEST100这个表，这完全说明前期的分析是不对的。真正引起集群等待的原因是对TEST100块进行传递的结果，一切都是它的问题。最后我查看了这些语句，这些语句都对表TEST100进行FULL TABLE SCAN，所以我觉得只要改善了TEST100 的FULL TABLE SCAN应该可以解决一些问题了。不知道大家觉得如何？

总结：
在RAC的性能诊断中，特别是涉及到集群等待事件比如GC BUFFER BUSY这样的事件，不要片面的认为这个问题一定是由逻辑读最高的语句引起的，很可能最耗时最高逻辑读的语句不是引起问题的根源。最好结合集群等待对象和语句进行分析。同时通过语句提取信息进行验证。
我的分析只限于个人，可能是我经验不够的原因，可能一些大虾觉得是很简单的问题，我只是分享一下。
呵呵

使用道具 举报

回复
gaopengtttt
论坛徽章:
9
ITPUB社区OCM联盟徽章 日期:2013-03-27 11:17:11奥运纪念徽章 日期:2013-06-18 09:13:52ITPUB社区千里马徽章 日期:2013-08-22 09:58:03大众 日期:2013-08-30 14:51:33路虎 日期:2013-12-01 18:25:42
4#
 楼主| 发表于 2011-7-13 17:09 | 只看该作者
执行计划
PLAN_TABLE_OUTPUT
----------------------------------------------------------------------------------------------------

Plan hash value: 644919638

----------------------------------------------------------------------------------------------------
| Id  | Operation                           | Name                 | Starts | E-Rows | A-Rows |   A-Time   | Buffers | Reads  |
----------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT                    |                      |      1 |        |      1 |00:00:10.56 |     142K|  18446 |
|   1 |  HASH GROUP BY                      |                      |      1 |      1 |      1 |00:00:10.56 |     142K|  18446 |
|*  2 |   HASH JOIN OUTER                   |                      |      1 |      1 |      1 |00:00:10.56 |     142K|  18446 |
|   3 |    VIEW                             |                      |      1 |      1 |      1 |00:00:00.68 |   34315 |      0 |
|   4 |     HASH GROUP BY                   |                      |      1 |      1 |      1 |00:00:00.68 |   34315 |      0 |

PLAN_TABLE_OUTPUT
----------------------------------------------------------------------------------------------------
|   5 |      NESTED LOOPS OUTER             |                      |      1 |      1 |      2 |00:00:00.67 |   34315 |      0 |
|*  6 |       HASH JOIN OUTER               |                      |      1 |      1 |      2 |00:00:00.67 |   34307 |      0 |
|   7 |        NESTED LOOPS                 |                      |      1 |      1 |      2 |00:00:00.01 |      16 |      0 |
|   8 |         NESTED LOOPS                |                      |      1 |      1 |      2 |00:00:00.01 |       8 |      0 |
|*  9 |          TABLE ACCESS BY INDEX ROWID| testttttttttttttt    |      1 |      1 |      1 |00:00:00.01 |       3
|* 10 |           INDEX RANGE SCAN          | PK_testttttttttttttt |      1 |      1 |      1 |00:00:00.01 |       2 |   
|* 11 |          TABLE ACCESS BY INDEX ROWID| testtttttt           |      1 |      1 |      2 |00:00:00.01 |       5 |   
|* 12 |           INDEX RANGE SCAN          | PK_testttttt         |      1 |      6 |      2 |00:00:00.01 |       3 |      0 |
|* 13 |         TABLE ACCESS BY INDEX ROWID | test123123           |      2 |      1 |      2 |00:00:00.01 |       8 |     
|* 14 |          INDEX UNIQUE SCAN          | PK_test123123        |      2 |      1 |      2 |00:00:00.01 |       6 |      0 |
|* 15 |        TABLE ACCESS FULL            | test7777             |      1 |    765K|    807K|00:00:00.01 |   34291 |  

PLAN_TABLE_OUTPUT
----------------------------------------------------------------------------------------------------
|* 16 |       TABLE ACCESS BY INDEX ROWID   | test999              |      2 |      1 |      2 |00:00:00.01 |       8
|* 17 |        INDEX UNIQUE SCAN            | PK_test999           |      2 |      1 |      2 |00:00:00.01 |       6 |      0
|  18 |    VIEW                             |                      |      1 |   3344K|    812K|00:00:10.14 |     107K|  18446 |
|  19 |     HASH GROUP BY                   |                      |      1 |   3344K|    812K|00:00:09.32 |     107K|  18446 |
|  20 |      TABLE ACCESS FULL              | test100              |      1 |   3344K|   3448K|00:00:06.90 |     107K|  184
----------------------------------------------------------------------------------------------------

问题就是TEST100 大家看看 TEST100 FULL SCAN的逻辑读是107K。。
晕

使用道具 举报

回复
xpzxsq
论坛徽章:
11
2010新春纪念徽章 日期:2010-01-04 08:33:082014年世界杯参赛球队: 加纳 日期:2014-07-14 15:09:36马上有房 日期:2014-02-18 16:42:022014年新春福章 日期:2014-02-18 16:42:02路虎 日期:2014-02-09 20:38:39ITPUB社区OCM联盟徽章 日期:2013-11-21 14:19:262013年新春福章 日期:2013-02-25 14:51:24ITPUB 11周年纪念徽章 日期:2012-10-09 18:08:15ITPUB十周年纪念徽章 日期:2011-11-01 16:24:042010新春纪念徽章 日期:2010-03-01 11:19:49
5#
发表于 2011-7-13 17:11 | 只看该作者
很好的分享案例，期待你的优化结果和最终结论。

使用道具 举报

回复
sfx123
论坛徽章:
2
生肖徽章2007版:牛 日期:2008-11-17 15:05:152010新春纪念徽章 日期:2010-03-01 11:20:52
6#
发表于 2011-7-13 18:48 | 只看该作者
问题是逻辑读高也是因为语句引起的吧。结果还是要改语句或者建索引或者收缩，这个情况多半要改语句了。

使用道具 举报

回复
magic007
论坛徽章:
25
授权会员 日期:2007-08-20 23:44:422011新春纪念徽章 日期:2011-01-25 15:42:562011新春纪念徽章 日期:2011-02-18 11:42:49管理团队成员 日期:2011-05-07 01:45:082012新春纪念徽章 日期:2012-01-04 11:49:54咸鸭蛋 日期:2012-02-06 17:15:202012新春纪念徽章 日期:2012-02-13 15:11:362012新春纪念徽章 日期:2012-02-13 15:11:362012新春纪念徽章 日期:2012-02-13 15:11:362012新春纪念徽章 日期:2012-02-13 15:11:36
7#
发表于 2011-7-13 21:48 | 只看该作者
在解决性能问题的时候，需要准确描述性能现象：你这里提到，在高负载的时候，CPU降低到40%左右，注意这里是降低，这说明了存在什么性能问题？业务上有没有反映出来？
其次，你这个AWR报告采集的是多长时间的数据。10分钟还是30分钟还是1小时？

如果你觉得CPU降低到40%是一个异常，需要与基准的性能数据（BASELINE）先做一个对比。

使用道具 举报

回复
gaopengtttt
论坛徽章:
9
ITPUB社区OCM联盟徽章 日期:2013-03-27 11:17:11奥运纪念徽章 日期:2013-06-18 09:13:52ITPUB社区千里马徽章 日期:2013-08-22 09:58:03大众 日期:2013-08-30 14:51:33路虎 日期:2013-12-01 18:25:42
8#
 楼主| 发表于 2011-7-14 09:35 | 只看该作者
当然又一个BASELINE，我设置的BASELINE就是DB_TIME在 60左右。
采样是默认的一个的小时，如果达到80 以上就说明遇到了问题。
有时候业务也会有反映，用户会反映慢，但不是每次。
Snap Id Snap Time Sessions Cursors/Session
Begin Snap: 7744 13-Jul-11 14:00:36 290 6.4
End Snap: 7745 13-Jul-11 15:00:10 288 6.5
Elapsed:   59.57 (mins)     
DB Time:   97.84 (mins)

使用道具 举报

回复
gaopengtttt
论坛徽章:
9
ITPUB社区OCM联盟徽章 日期:2013-03-27 11:17:11奥运纪念徽章 日期:2013-06-18 09:13:52ITPUB社区千里马徽章 日期:2013-08-22 09:58:03大众 日期:2013-08-30 14:51:33路虎 日期:2013-12-01 18:25:42
9#
 楼主| 发表于 2011-7-14 09:37 | 只看该作者
问题时间一段采样
-------- ----------- ------------------------ ------------ ----------- --------
r  b  p   avm   fre  fi  fo  pi  po  fr   sr  in   sy  cs us sy id wa hr mi se
2  0  0 3591454 467354   0   3   0   0   0    0 3023 59356 8566 47  5 47  1 14:00:32
3  0  0 3576594 482202   0   3   0   0   0    0 3239 71456 9802 62  6 31  1 14:01:02
2  0  0 3576622 482165   0   3   0   0   0    0 1654 45752 6021 40  4 55  1 14:01:32
2  0  0 3611028 447744   0   3   0   0   0    0 858 48118 4240 51  2 46  0 14:02:02
2  0  0 3576742 482015   0   4   0   0   0    0 917 50989 4418 48  3 48  0 14:02:32
3  0  0 3595701 463031   0   2   0   0   0    0 1985 53165 6614 63  4 32  1 14:03:02
2  0  0 3599407 459316   0   3   0   0   0    0 2589 56910 7534 50  5 45  1 14:03:32
2  0  0 3606270 452444   0   2   0   0   0    0 1559 58546 5647 58  4 38  0 14:04:02
4  0  0 3635034 423673   0   3   0   0   0    0 1519 65990 5552 72  5 23  0 14:04:32
2  0  0 3613377 445317   0   2   0   0   0    0 2151 56721 6909 43  4 52  1 14:05:02
2  1  0 3604552 454115   0   4   0   0   0    0 1908 62178 6776 53  4 43  1 14:05:32
3  1  0 3602270 456381   0   2   0   0   0    0 1582 53084 5576 65  3 32  0 14:06:02
3  0  0 3607179 451465   0   3   0   0   0    0 1198 46641 4877 63  3 34  0 14:06:32
2  0  0 3598300 460330   0   2   0   0   0    0 3574 68783 10507 47  6 46  0 14:07:02
3  0  0 3611540 447081   0   2   0   0   0    0 921 47671 4705 63  3 34  0 14:07:32
2  1  0 3594206 464397   0   2   0   0   0    0 1065 44161 4670 34  4 61  1 14:08:02
3  0  0 3574878 483718   0   3   0   0   0    0 762 41840 4050 50  2 47  0 14:08:32
3  0  0 3597669 460912   0   2   0   0   0    0 1563 46152 5783 46  3 50  0 14:09:02
3  0  0 3605713 452862   0   3   0   0   0    0 1978 49089 6664 49  4 46  1 14:09:32
2  1  0 3614788 443767   0   3   0   0   0    0 3041 65582 9197 37  5 56  1 14:10:02
  kthr     memory              page              faults        cpu       time

使用道具 举报

回复
magic007
论坛徽章:
25
授权会员 日期:2007-08-20 23:44:422011新春纪念徽章 日期:2011-01-25 15:42:562011新春纪念徽章 日期:2011-02-18 11:42:49管理团队成员 日期:2011-05-07 01:45:082012新春纪念徽章 日期:2012-01-04 11:49:54咸鸭蛋 日期:2012-02-06 17:15:202012新春纪念徽章 日期:2012-02-13 15:11:362012新春纪念徽章 日期:2012-02-13 15:11:362012新春纪念徽章 日期:2012-02-13 15:11:362012新春纪念徽章 日期:2012-02-13 15:11:36
10#
发表于 2011-7-14 09:41 | 只看该作者
如果你仅仅是找出CPU利用率为啥降低到40%，需要现在的AWR报告 与BASELINE进行对比，看看有什么差异。

使用道具 举报

回复

12下一页
返回列表 发新帖
高级模式
B Color Image Link Quote Code Smilies
您需要登录后才可以回帖 登录 | 注册

本版积分规则 发表回复

TOP技术积分榜 社区积分榜 徽章 团队 统计 知识索引树 积分竞拍 文本模式 帮助
  ITPUB首页 | ITPUB论坛 | 数据库技术 | 企业信息化 | 开发技术 | 微软技术 | 软件工程与项目管理 | IBM技术园地 | 行业纵向讨论 | IT招聘 | IT文档
  ChinaUnix | ChinaUnix博客 | ChinaUnix论坛
CopyRight 1999-2011 itpub.net All Right Reserved. 北京盛拓优讯信息技术有限公司版权所有　联系我们 未成年人举报专区　
京ICP备16024965号-8 　北京市公安局海淀分局网监中心备案编号：11010802021510　广播电视节目制作经营许可证：编号（京）字第1149号   
快速回复 返回顶部 返回列表