首页 >数据库 >mysql教程 >一次EVENT 10200寻找Buffer Get之旅,最终以狗血案例而告终

一次EVENT 10200寻找Buffer Get之旅,最终以狗血案例而告终

WBOY
WBOY原创
2016-06-07 16:36:52924浏览

很多案件的最终结局其实都是很狗血的,这不我也深深的经历了一遭。整个过程感觉就像小时候大家伙玩传奇一样,从迷宫一层一层的下,下到最底层之后发现,妹的,居然不是大Boss,居然是个小怪。浪费了我大量的精力。首先介绍一下背景,11g一条语句比10g一条语句

很多案件的最终结局其实都是很狗血的,这不我也深深的经历了一遭。整个过程感觉就像小时候大家伙玩>一样,从迷宫一层一层的下,下到最底层之后发现,妹的,居然不是大Boss,居然是个小怪。浪费了我大量的精力。首先介绍一下背景,11g一条语句比10g一条语句的cost下降了很多,但是buffer get确增加了很多。相关表的数据量其实没多少差异。所以当时我就在思考,这多出来的buffer get是那些块,涉及的对象是那些。

================================》10g执行计划
Execution Plan 
---------------------------------------------------------- 
Plan hash value: 2721392943 
------------------------------------------------------------------------------------------------------------------------------------- 
| Id  | Operation                                | Name                     | Rows  | Bytes | Cost (%CPU)| Time     | Pstart| Pstop | 
------------------------------------------------------------------------------------------------------------------------------------- 
|   0 | SELECT STATEMENT                         |                          |     1 |       |   225   (1)| 00:00:03 |       |       | 
|   1 |  SORT AGGREGATE                          |                          |     1 |       |            |          |       |       | 
|   2 |   VIEW                                   |                          |    21 |       |   225   (1)| 00:00:03 |       |       | 
|   3 |    HASH GROUP BY                         |                          |    21 |  1701 |   225   (1)| 00:00:03 |       |       | 
|   4 |     VIEW                                 |                          |    21 |  1701 |   224   (1)| 00:00:03 |       |       | 
|   5 |      UNION-ALL                           |                          |       |       |            |          |       |       | 
|   6 |       NESTED LOOPS OUTER                 |                          |    20 |   860 |   191   (1)| 00:00:03 |       |       | 
|   7 |        TABLE ACCESS BY GLOBAL INDEX ROWID| UR_USER_INFO             |     6 |   186 |     8   (0)| 00:00:01 | ROWID | ROWID | 
|*  8 |         INDEX RANGE SCAN                 | IDX_USERINFO_IX          |     6 |       |     3   (0)| 00:00:01 |       |       | 
|   9 |        PARTITION RANGE ALL               |                          |     3 |    36 |    30   (0)| 00:00:01 |     1 |    18 | 
|  10 |         TABLE ACCESS BY LOCAL INDEX ROWID| OR_ORDERLINE_INFO        |     3 |    36 |    30   (0)| 00:00:01 |     1 |    18 | 
|* 11 |          INDEX RANGE SCAN                | IDX_OR_ORDERLINE_INFO_IN |     3 |       |    29   (0)| 00:00:01 |     1 |    18 | 
|  12 |       NESTED LOOPS OUTER                 |                          |     1 |    43 |    33   (0)| 00:00:01 |       |       | 
|  13 |        PARTITION RANGE ALL               |                          |     1 |    34 |    32   (0)| 00:00:01 |     1 |    18 | 
|* 14 |         TABLE ACCESS BY LOCAL INDEX ROWID| OR_ORDERLINE_INFO        |     1 |    34 |    32   (0)| 00:00:01 |     1 |    18 | 
|* 15 |          INDEX RANGE SCAN                | IDX_OR_ORDERLINE_INFO_CI |     6 |       |    30   (0)| 00:00:01 |     1 |    18 | 
|  16 |        PARTITION RANGE ITERATOR          |                          |     1 |     9 |     1   (0)| 00:00:01 |   KEY |   KEY | 
|* 17 |         INDEX UNIQUE SCAN                | PK_UR_USER_INFO          |     1 |     9 |     1   (0)| 00:00:01 |   KEY |   KEY | 
------------------------------------------------------------------------------------------------------------------------------------- 
Predicate Information (identified by operation id): 
--------------------------------------------------- 
   8 - access("USR"."CUST_ID"=TO_NUMBER(:CUST_ID)) 
  11 - access("USR"."ID_NO"="OL"."ID_NO"(+)) 
  14 - filter("OL"."DATA_STATUS"='00') 
  15 - access("OL"."CUST_ID"=TO_NUMBER(:CUST_ID)) 
  17 - access("USR"."ID_NO"(+)="OL"."ID_NO") 
Statistics 
---------------------------------------------------------- 
          0  recursive calls 
          0  db block gets 
        582  consistent gets 
          0  physical reads 
          0  redo size 
        657  bytes sent via SQL*Net to client 
        492  bytes received via SQL*Net from client 
          2  SQL*Net roundtrips to/from client 
          0  sorts (memory) 
          0  sorts (disk) 
          1  rows processed
================================》11g执行计划
Execution Plan 
---------------------------------------------------------- 
Plan hash value: 2721392943 
------------------------------------------------------------------------------------------------------------------------------------- 
| Id  | Operation                                | Name                     | Rows  | Bytes | Cost (%CPU)| Time     | Pstart| Pstop | 
------------------------------------------------------------------------------------------------------------------------------------- 
|   0 | SELECT STATEMENT                         |                          |     1 |       |    55   (2)| 00:00:01 |       |       | 
|   1 |  SORT AGGREGATE                          |                          |     1 |       |            |          |       |       | 
|   2 |   VIEW                                   |                          |     3 |       |    55   (2)| 00:00:01 |       |       | 
|   3 |    HASH GROUP BY                         |                          |     3 |   231 |    55   (2)| 00:00:01 |       |       | 
|   4 |     VIEW                                 |                          |     3 |   231 |    54   (0)| 00:00:01 |       |       | 
|   5 |      UNION-ALL                           |                          |       |       |            |          |       |       | 
|   6 |       NESTED LOOPS OUTER                 |                          |     2 |    86 |    36   (0)| 00:00:01 |       |       | 
|   7 |        TABLE ACCESS BY GLOBAL INDEX ROWID| UR_USER_INFO             |     2 |    62 |     4   (0)| 00:00:01 | ROWID | ROWID | 
|*  8 |         INDEX RANGE SCAN                 | IDX_USERINFO_IX          |     2 |       |     2   (0)| 00:00:01 |       |       | 
|   9 |        PARTITION RANGE ALL               |                          |     1 |    12 |    16   (0)| 00:00:01 |     1 |    18 | 
|  10 |         TABLE ACCESS BY LOCAL INDEX ROWID| OR_ORDERLINE_INFO        |     1 |    12 |    16   (0)| 00:00:01 |     1 |    18 | 
|* 11 |          INDEX RANGE SCAN                | IDX_OR_ORDERLINE_INFO_IN |     2 |       |    14   (0)| 00:00:01 |     1 |    18 | 
|  12 |       NESTED LOOPS OUTER                 |                          |     1 |    43 |    18   (0)| 00:00:01 |       |       | 
|  13 |        PARTITION RANGE ALL               |                          |     1 |    34 |    17   (0)| 00:00:01 |     1 |    18 | 
|* 14 |         TABLE ACCESS BY LOCAL INDEX ROWID| OR_ORDERLINE_INFO        |     1 |    34 |    17   (0)| 00:00:01 |     1 |    18 | 
|* 15 |          INDEX RANGE SCAN                | IDX_OR_ORDERLINE_INFO_CI |     3 |       |    15   (0)| 00:00:01 |     1 |    18 | 
|  16 |        PARTITION RANGE ITERATOR          |                          |     1 |     9 |     1   (0)| 00:00:01 |   KEY |   KEY | 
|* 17 |         INDEX UNIQUE SCAN                | PK_UR_USER_INFO          |     1 |     9 |     1   (0)| 00:00:01 |   KEY |   KEY | 
------------------------------------------------------------------------------------------------------------------------------------- 
Predicate Information (identified by operation id): 
--------------------------------------------------- 
   8 - access("USR"."CUST_ID"=TO_NUMBER(:CUST_ID)) 
  11 - access("USR"."ID_NO"="OL"."ID_NO"(+)) 
  14 - filter("OL"."DATA_STATUS"='00') 
  15 - access("OL"."CUST_ID"=TO_NUMBER(:CUST_ID)) 
  17 - access("USR"."ID_NO"(+)="OL"."ID_NO") 
Statistics 
---------------------------------------------------------- 
          0  recursive calls 
          0  db block gets 
        837  consistent gets 
          0  physical reads 
          0  redo size 
        676  bytes sent via SQL*Net to client 
        520  bytes received via SQL*Net from client 
          2  SQL*Net roundtrips to/from client 
          0  sorts (memory) 
          0  sorts (disk) 
          1  rows processed

事先得说明一下,11g的执行计划里面涉及的表和索引我都重新收集了统计信息。从这个执行计划中可以看出,我们的consistent gets从582增加到了837,而执行计划的cost其实是下降了,从225下降到55。所以我们从多出的这200多个consistent gets着手。如果我们要追踪这些块,这里需要使用10200 event。

1.做10200 event,从trace里面找信息

*** 2014-05-19 15:55:43.558
*** ACTION NAME:() 2014-05-19 15:55:43.556
*** MODULE NAME:(sqlplus@w25k03da (TNS V1-V3)) 2014-05-19 15:55:43.556
*** SERVICE NAME:(SYS$USERS) 2014-05-19 15:55:43.556
*** SESSION ID:(5146.581) 2014-05-19 15:55:43.556
Consistent read started for block 34 : 11c999f4
  env: (scn: 0x0af1.fa66895f  xid: 0x0000.000.00000000  uba: 0x00000000.0000.00  statement num=0  parent xid: xid: 0x0000.000.00000000  scn: 0x0000.00000000 8sch: scn: 0x0000.00000000)
CR exa ret 2 on:  3800103c0  scn: 0xffff.ffffffff  xid: 0x0000.000.00000000  uba: 0x00000000.0000.00  scn: 0xffff.ffffffff  sfl: 0
Consistent read finished for block 34 : 11c999f4
Consistent read started for block 34 : 7ece819f
  env: (scn: 0x0af1.fa66895f  xid: 0x0000.000.00000000  uba: 0x00000000.0000.00  statement num=0  parent xid: xid: 0x0000.000.00000000  scn: 0x0000.00000000 8sch: scn: 0x0000.00000000)
CR exa ret 2 on:  3800103c0  scn: 0xffff.ffffffff  xid: 0x0000.000.00000000  uba: 0x00000000.0000.00  scn: 0xffff.ffffffff  sfl: 0
Consistent read finished for block 34 : 7ece819f
*** 2014-05-19 15:35:19.883
ktrgtc2(): started for block  objd: 0x00020c7c
  env [0x9fffffffbf36cf94]: (scn: 0x0aef.60c6b2af  xid: 0x0000.000.00000000  uba: 0x00000000.0000.00  statement num=0  parent xid: 0x0000.000.00000000  st-scn: 0x0000.00000000  hi-scn: 0x0000.00000000  ma-scn: 0x0000.00000000  flg: 0x00000660)
ktrexc(): returning 2 on:  6000000000177a70  cr-scn: 0xffff.ffffffff  xid: 0x0000.000.00000000  uba: 0x00000000.0000.00  cl-scn: 0xffff.ffffffff  sfl: 0
ktrgtc2(): completed for block  objd: 0x00020c7c
ktrgtc2(): started for block  objd: 0x00020c7c
  env [0x9fffffffbf36cf94]: (scn: 0x0aef.60c6b2af  xid: 0x0000.000.00000000  uba: 0x00000000.0000.00  statement num=0  parent xid: 0x0000.000.00000000  st-scn: 0x0000.00000000  hi-scn: 0x0000.00000000  ma-scn: 0x0000.00000000  flg: 0x00000660)
ktrexc(): returning 2 on:  6000000000177a70  cr-scn: 0xffff.ffffffff  xid: 0x0000.000.00000000  uba: 0x00000000.0000.00  cl-scn: 0xffff.ffffffff  sfl: 0
ktrgtc2(): completed for block  objd: 0x00020c7c
ktrget2(): started for block   objd: 0x00020c7c
env [0x9fffffffbf36cf94]: (scn: 0x0aef.60c6b2af  xid: 0x0000.000.00000000  uba: 0x00000000.0000.00  statement num=0  parent xid: 0x0000.000.00000000  st-scn: 0x0000.00000000  hi-scn: 0x0000.00000000  ma-scn: 0x0000.00000000  flg: 0x00000660)
showing 0xc000000a65ec1b18 694591c4 (2) dscn ffffffff:ffff bcrp ffff:ffffffff, bestcrp (nil)
ktrexf(): returning 9 on:  6000000000177a70  cr-scn: 0xffff.ffffffff  xid: 0x0000.000.00000000  uba: 0x00000000.0000.00  cl-scn: 0xffff.ffffffff  sfl: 0
new dscn ffff:ffffffff ret=9
ktrgcm(): completed for block   objd: 0x00020c7c
ktrget3(): completed for  block  objd: 0x00020c7c

上面可以看到,在10g中,我们10200的一致读的信息是:Consistent read started for block 34 : 11c999f4,而我们11g的一致读的信息是ktrgtc2(): started for block objd: 0x00020c7c.可以看到11g比10g的trace更加的智能,它直接告诉了你object_id号,这可以帮助我们快速定位到相关的对象。而10g呢?它给出的只是一个DBA的地址,我们要通过相关函数先去转换成文件号和块号,然后通过文件号和块号去dba_extents去查具体对象名。

2.根据trace的地址找到真实的object

================================》10g Trace
Consistent read started for block 34 : 11c999f4
Consistent read started for block 34 : 7ece819f
Consistent read started for block 34 : 4ac285db
Consistent read started for block 34 : 8347e921
Consistent read started for block 12 : 0c06184e
Consistent read started for block 36 : 25c92364
Consistent read started for block 36 : 2bc7db6d
Consistent read started for block 36 : 2a01835b
Consistent read started for block 36 : 25c9237c
Consistent read started for block 36 : 25c9237f
Consistent read started for block 36 : 25c92384
Consistent read started for block 36 : 25c9898c
Consistent read started for block 36 : 25c9899c
Consistent read started for block 36 : 25c9899e
SELECT DBMS_UTILITY.DATA_BLOCK_ADDRESS_FILE (TO_NUMBER ('11C999F4', 'XXXXXXXX'))AS FILE_NO,DBMS_UTILITY.DATA_BLOCK_ADDRESS_BLOCK (TO_NUMBER ('11C999F4', 'XXXXXXXX')) AS BLOCK_NO FROM DUAL;
SELECT SEGMENT_NAME FROM DBA_EXTENTS A WHERE FILE_ID=71   AND  629236   BETWEEN BLOCK_ID AND BLOCK_ID+BLOCKS-1; 
================================》11g Trace
ktrgtc2(): started for block   objd: 0x00020c7c 
ktrgtc2(): started for block   objd: 0x00020c7c 
ktrget2(): started for block   objd: 0x00020c7c
ktrget2(): started for block   objd: 0x0001b36a
ktrgtc2(): started for block   objd: 0x0002149d 
ktrget2(): started for block   objd: 0x0002149d
ktrget2(): started for block   objd: 0x0002149e
ktrget2(): started for block   objd: 0x0002149e
ktrget2(): started for block   objd: 0x0002149f
ktrget2(): started for block   objd: 0x000214a0
ktrget2(): started for block   objd: 0x000214a1
ktrget2(): started for block   objd: 0x000214a1
select to_number('20c7c','XXXXX') from dual;
select object_name from dba_objects where object_id='134268';

通过上述查询及统计,我们定位出,10g里面查询索引IDX_OR_ORDERLINE_INFO_IN,读取块514次,而在11g里面查询索引IDX_OR_ORDERLINE_INFO_IN读取783次,所以这个索引应该有问题,我们来看看索引的情况。

================================》10g
SQL> select INDEX_NAME,PARTITION_NAME,BLEVEL,LEAF_BLOCKS,NUM_ROWS from DBA_IND_PARTITIONS where INDEX_NAME='IDX_OR_ORDERLINE_INFO_IN';
INDEX_NAME                     PARTITION_NAME                     BLEVEL LEAF_BLOCKS   NUM_ROWS
------------------------------ ------------------------------ ---------- ----------- ----------
IDX_OR_ORDERLINE_INFO_IN       PART_01                                 2        1106      52833
IDX_OR_ORDERLINE_INFO_IN       PART_02                                 1           3        381
IDX_OR_ORDERLINE_INFO_IN       PART_03                                 0           1          4
IDX_OR_ORDERLINE_INFO_IN       PART_04                                 0           1         10
IDX_OR_ORDERLINE_INFO_IN       PART_05                                 1           3        206
IDX_OR_ORDERLINE_INFO_IN       PART_06                                 1         165       3766
IDX_OR_ORDERLINE_INFO_IN       PART_07                                 0           1          4
IDX_OR_ORDERLINE_INFO_IN       PART_08                                 0           1          9
IDX_OR_ORDERLINE_INFO_IN       PART_09                                 0           1         14
IDX_OR_ORDERLINE_INFO_IN       PART_10                                 1         496      10939
IDX_OR_ORDERLINE_INFO_IN       PART_11                                 1         448      10377
IDX_OR_ORDERLINE_INFO_IN       PART_12                                 0           1         54
IDX_OR_ORDERLINE_INFO_IN       PART_13                                 0           1         13
IDX_OR_ORDERLINE_INFO_IN       PART_14                                 0           1          4
IDX_OR_ORDERLINE_INFO_IN       PART_15                                 1          16       4431
IDX_OR_ORDERLINE_INFO_IN       PART_16                                 1          88       3380
IDX_OR_ORDERLINE_INFO_IN       PART_17                                 1         292       5994
IDX_OR_ORDERLINE_INFO_IN       PART_18                                 0           0          0
================================》11g
SQL> select INDEX_NAME,PARTITION_NAME,BLEVEL,LEAF_BLOCKS,NUM_ROWS from DBA_IND_PARTITIONS where INDEX_NAME='IDX_OR_ORDERLINE_INFO_IN';
INDEX_NAME                     PARTITION_NAME                     BLEVEL LEAF_BLOCKS   NUM_ROWS GLO
------------------------------ ------------------------------ ---------- ----------- ---------- ---
IDX_OR_ORDERLINE_INFO_IN       PART_01                                 1         152      54315 YES
IDX_OR_ORDERLINE_INFO_IN       PART_02                                 1           2        426 YES
IDX_OR_ORDERLINE_INFO_IN       PART_03                                 0           1         23 YES
IDX_OR_ORDERLINE_INFO_IN       PART_04                                 0           1         78 YES
IDX_OR_ORDERLINE_INFO_IN       PART_05                                 1           2        621 YES
IDX_OR_ORDERLINE_INFO_IN       PART_06                                 1          15       5248 YES
IDX_OR_ORDERLINE_INFO_IN       PART_07                                 0           1         66 YES
IDX_OR_ORDERLINE_INFO_IN       PART_08                                 0           1        244 YES
IDX_OR_ORDERLINE_INFO_IN       PART_09                                 0           1         18 YES
IDX_OR_ORDERLINE_INFO_IN       PART_10                                 1          38      13537 YES
IDX_OR_ORDERLINE_INFO_IN       PART_11                                 1          42      15065 YES
IDX_OR_ORDERLINE_INFO_IN       PART_12                                 0           1        107 YES
IDX_OR_ORDERLINE_INFO_IN       PART_13                                 0           1         17 YES
IDX_OR_ORDERLINE_INFO_IN       PART_14                                 0           1         33 YES
IDX_OR_ORDERLINE_INFO_IN       PART_15                                 1          13       4431 YES
IDX_OR_ORDERLINE_INFO_IN       PART_16                                 1          12       4081 YES
IDX_OR_ORDERLINE_INFO_IN       PART_17                                 1          28       9846 YES
IDX_OR_ORDERLINE_INFO_IN       PART_18                                 0           0          0 YES

因为11g是新创建的索引,我们可以看到其实它的leaf_blocks其实比较少,而相同的10g是很多的。并且PART_01这个分区在10g上索引的层级是2级。那么按照正常思维来看,10g需要扫描更多的索引块才能获取到相关数据才对。但是我们看到的情况正好相反。那么问题究竟出在哪儿?

此时一个同事提醒我,把语句真实的运行了一把,运行出来后,顿时恍然大悟,这就是一个狗血的案例。简直是一个血的教训啊。因为环境的原因,10g上和11g上有些数据差异,但是数据量的差异其实是很小的(这点从统计信息上可以看到)。而11g统计信息也是重新收集了。问题就出在数据的差异导致11g查询出来的结果集是29条,而10g查询出来的是19条,查询的结果集多了,当然buffer get就多了。这就是最大的原因。

SQL> select a.ID_NO as ID_NO,
                  min(a.DATA_STATUS) as DATA_STATUS,
                  min(a.IS_OPEN) as IS_OPEN,
             from (select usr.id_no AS ID_NO,
                          decode(ol.data_status, null, '99', '01') AS DATA_STATUS,
                          nvl(ol.id_no, 0) as IS_OPEN,
                          usr.phone_no as SERVICE_NO
                     from UR_USER_INFO usr, OR_ORDERLINE_INFO ol
                    where usr.cust_id = :CUST_ID
                      and usr.ID_NO = ol.ID_NO(+)
                   union all
                   select ol.id_no AS ID_NO,
                          ol.data_status AS DATA_STATUS,
                          nvl(usr.id_no, 1) as IS_OPEN,
                          ol.service_no as SERVICE_NO
                     from UR_USER_INFO usr, OR_ORDERLINE_INFO ol
                    where ol.cust_id = :CUST_ID
                      and usr.ID_NO(+) = ol.ID_NO
                      and ol.DATA_STATUS = '00' and rownum select a.ID_NO as ID_NO,
                min(a.DATA_STATUS) as DATA_STATUS,
                min(a.IS_OPEN) as IS_OPEN,
           from (select usr.id_no AS ID_NO,
                        decode(ol.data_status, null, '99', '01') AS DATA_STATUS,
                        nvl(ol.id_no, 0) as IS_OPEN,
                        usr.phone_no as SERVICE_NO
                   from UR_USER_INFO usr, OR_ORDERLINE_INFO ol
                  where usr.cust_id = :CUST_ID
                    and usr.ID_NO = ol.ID_NO(+)
                 union all
                 select ol.id_no AS ID_NO,
                        ol.data_status AS DATA_STATUS,
                        nvl(usr.id_no, 1) as IS_OPEN,
                        ol.service_no as SERVICE_NO
                   from UR_USER_INFO usr, OR_ORDERLINE_INFO ol
                  where ol.cust_id = :CUST_ID
                    and usr.ID_NO(+) = ol.ID_NO
                    and ol.DATA_STATUS = '00') a
          group by a.id_no;
     ID_NO DA    IS_OPEN 
---------- -- ---------- 
1.6310E+13 99          0 
1.6310E+13 99          0 
1.6310E+13 99          0 
1.6001E+13 99          0 
1.6310E+13 99          0 
1.6310E+13 99          0 
1.6310E+13 99          0 
1.6310E+13 99          0 
1.6310E+13 99          0 
1.6310E+13 99          0 
1.6310E+13 99          0 
1.6001E+13 99          0 
1.6310E+13 99          0 
1.6001E+13 99          0 
1.6001E+13 99          0 
1.6001E+13 99          0 
1.6310E+13 99          0 
1.6310E+13 99          0 
1.6310E+13 99          0 
19 rows selected.

总结:不要太过依赖于执行计划出现的那些信息,有时候需要把语句真实运行一把。

声明:
本文内容由网友自发贡献,版权归原作者所有,本站不承担相应法律责任。如您发现有涉嫌抄袭侵权的内容,请联系admin@php.cn