开发人员在进行新系统上线前的数据校验测试时,发现一条手工执行的SQL执行了超过1小时还没有返回结果。SQL很简单:


SELECT *
  FROM MOBILE_call_1204_OLD
 WHERE BILLING_NBR = '189xxxxxxxx'
   AND START_DATE = TO_DATE('2012-4-9 21:55:42', 'yyyy-mm-dd hh24:mi:ss')

下面是这条SQL的真实的执行计划:

-------------------------------------------------------------
| Id   | Operation          | Name                 | E-Rows |
-------------------------------------------------------------
|    0 | SELECT STATEMENT   |                      |        |
| *  1 |  TABLE ACCESS FULL | MOBILE_CALL_1204_OLD |      1 |
-------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------
1 - filter(("START_DATE"=TO_DATE(' 2012-04-09 21:55:42', 'syyyy-mm-dd hh24:mi:ss') AND "BILLING_NBR"='189xxxxxxxx'))

很显然,在这个表上建billing_nbr和start_date的复合索引,这条SQL就能很快执行完(实际上最后也建了索引)。但是这里我们要探讨的是,为什么这么一条简单的SQL语句,执行了超过1小时还没有结果。MOBILE_CALL_1204_OLD这张表的大小约为12GB,以系统的IO能力,正常情况下不会执行这么长的时间。简单地看了一下,系统的CPU以及IO压力都不高。假设单进程全表扫描表,每秒扫描50MB大小(这实际上是一个很保守的扫描速度了),那么只需要245秒就可以完成扫描。

下面来诊断一下SQL为什么会这么不正常地慢。看看会话的等待(以下会用到Oracle大牛Tanel Poder的脚本):

SQL> @waitprof print 4038 e 1000000
                                                                  Distinct   Avg time
    SID STATE   EVENT                         Time      Time ms     Events   ms/Event 
------- ------- -------------------------  ------- ------------ ---------- ----------
   4038 WAITING db file sequential read      99.61     4482.450        272     16.480
   4038 WORKING On CPU / runqueue              .39       17.550        271       .065

明明是全表扫描的SQL,为什么99%以上的等待时间是db file sequential read,即单块读?!多执行几次waitprof脚本,得到的结果是一致的(注意这里的数据,特别是平均等待时间并不一定是准确的值,这里重点关注的是等待时间的分布)。

那么SQL执行计划为全表扫描(或索引快速全扫描)的时候,在运行时会有哪些情况实际上是单块读?我目前能想到的有:

  • db_file_multiblock_read_count参数设置为1
  • 表或索引的大部分块在buffer cache中,少量不连续的块在磁盘上。
  • 一些特殊的块,比如段头
  • 行链接的块
  • LOB列的索引块和cache的LOB块(虽然10046事件看不到lob索引和cache的lob的读等待,但客观上是存在的。)

那么在这条SQL语句产生的大量单块读,又是属于什么情况呢?我们来看看单块读更细节的情况:

SQL> @waitprof print 4038 e1 200000

                                                    % Total  Total Event   Distinct   Avg time
    SID STATE   EVENT                    P1            Time      Time ms     Events   ms/Event
------- ------- ------------------------ ------------------ ------------ ---------- ----------
   4038 WAITING db file sequential read  file#= 353   30.63      581.923        35     16.626
   4038 WAITING db file sequential read  file#= 355   28.14      534.641        40     13.366
   4038 WAITING db file sequential read  file#= 354   20.52      389.909        24     16.246
   4038 WAITING db file sequential read  file#= 3     19.63      372.942        35     10.655
   4038 WORKING On CPU / runqueue                       .66       12.616       133       .095
   4038 WAITING db file sequential read  file#= 293     .42        7.971         1      7.971

多次执行同样的SQL,发现绝大部分的单块读发生在3、353-355这四个文件上,我们来看看这4个文件是什么:

SQL> select file_id,tablespace_name from dba_data_files where file_id in (355,3,353,354);

   FILE_ID TABLESPACE_NAME
---------- ------------------------------
         3 UNDOTBS1
       353 UNDOTBS1
       354 UNDOTBS1
       355 UNDOTBS1

原来是UNDO表空间。那么另一个疑问就会来了,为什么在UNDO上产生了如此之多的单块读?首先要肯定的是,这条简单的查询语句,是进行的一致性读。那么在进行一致性读的过程中,会有两个动作会涉及到读UNDO块,延迟块清除和构建CR块。下面我们用另一个脚本来查看会话当时的状况:


SQL> @snapper all,out 5 3 4038  
Sampling SID 4038 with interval 5 seconds, taking 3 snapshots...
setting stats to all due option = all

-- Session Snapper v3.52 by Tanel Poder @ E2SN ( http://tech.e2sn.com )

-------------------------------------------------------------------------------------------------------------------------------------
    SID, USERNAME  , TYPE, STATISTIC                                                 ,     HDELTA, HDELTA/SEC,    %TIME, GRAPH
-------------------------------------------------------------------------------------------------------------------------------------
   4038, BILL_MY   , STAT, session logical reads                                     ,        488,       97.6,
   4038, BILL_MY   , STAT, user I/O wait time                                        ,        429,       85.8,
   4038, BILL_MY   , STAT, non - idle wait time                                      ,        429,       85.8,
   4038, BILL_MY   , STAT, non - idle wait count                                     ,        377,       75.4,
   4038, BILL_MY   , STAT, physical read total IO requests                           ,        377,       75.4,
   4038, BILL_MY   , STAT, physical read total bytes                                 ,      3.13M,    625.87k,
   4038, BILL_MY   , STAT, cell physical IO interconnect bytes                       ,      3.13M,    625.87k,
   4038, BILL_MY   , STAT, consistent gets                                           ,        488,       97.6,
   4038, BILL_MY   , STAT, consistent gets from cache                                ,        488,       97.6,
   4038, BILL_MY   , STAT, consistent gets from cache (fastpath)                     ,          8,        1.6,
   4038, BILL_MY   , STAT, consistent gets - examination                             ,        478,       95.6,
   4038, BILL_MY   , STAT, logical read bytes from cache                             ,         4M,    799.54k,
   4038, BILL_MY   , STAT, physical reads                                            ,        382,       76.4
   4038, BILL_MY   , STAT, physical reads cache                                      ,        382,       76.4,
   4038, BILL_MY   , STAT, physical read IO requests                                 ,        377,       75.4,
   4038, BILL_MY   , STAT, physical read bytes                                       ,      3.13M,    625.87k,
   4038, BILL_MY   , STAT, db block changes                                          ,          9,        1.8,
   4038, BILL_MY   , STAT, consistent changes                                        ,        469,       93.8,
   4038, BILL_MY   , STAT, free buffer requested                                     ,        392,       78.4,
   4038, BILL_MY   , STAT, CR blocks created                                         ,         10,          2,
   4038, BILL_MY   , STAT, physical reads cache prefetch                             ,          5,          1,
   4038, BILL_MY   , STAT, shared hash latch upgrades - no wait                      ,        375,         75,
   4038, BILL_MY   , STAT, calls to kcmgas                                           ,        376,       75.2,
   4038, BILL_MY   , STAT, redo entries                                              ,          9,        1.8,
   4038, BILL_MY   , STAT, redo size                                                 ,        648,      129.6,
   4038, BILL_MY   , STAT, redo subscn max counts                                    ,          9,        1.8,
   4038, BILL_MY   , STAT, file io wait time                                         ,       4.3M,    860.97k,
   4038, BILL_MY   , STAT, data blocks consistent reads - undo records applied       ,        476,       95.2,
   4038, BILL_MY   , STAT, rollbacks only - consistent read gets                     ,          1,         .2,
   4038, BILL_MY   , STAT, cleanouts and rollbacks - consistent read gets            ,          9,        1.8,
   4038, BILL_MY   , STAT, immediate (CR) block cleanout applications                ,          9,        1.8,
   4038, BILL_MY   , STAT, commit txn count during cleanout                          ,          9,        1.8,
   4038, BILL_MY   , STAT, cleanout - number of ktugct calls                         ,          9,        1.8,
   4038, BILL_MY   , STAT, table scan rows gotten                                    ,        492,       98.4,
   4038, BILL_MY   , STAT, table scan blocks gotten                                  ,         10,          2,
   4038, BILL_MY   , STAT, heap block compress                                       ,         72,       14.4,
   4038, BILL_MY   , TIME, DB CPU                                                    ,    60.99ms,     12.2ms,     1.2%, |@         |
   4038, BILL_MY   , TIME, sql execute elapsed time                                  ,      4.35s,   869.12ms,    86.9%, |@@@@@@@@@ |
   4038, BILL_MY   , TIME, DB time                                                   ,      4.35s,   869.12ms,    86.9%, |@@@@@@@@@ |
   4038, BILL_MY   , WAIT, db file sequential read                                   ,      4.17s,   834.69ms,    83.5%, |@@@@@@@@@ |
   4038, BILL_MY   , WAIT, db file scattered read                                    ,    49.17ms,     9.83ms,     1.0%, |@         |
--  End of Stats snap 1, end=2012-05-21 22:22:16, seconds=5
...省略另两次的采样输出。

上面的结果是5秒左右的会话采样数据。再一次提醒,涉及到时间,特别要精确到毫秒的,不一定很精确,我们主要是看数据之间的对比。从上面的数据来看,会话请求了382次IO请求,单块读和多块读一共耗时4219.17ms(4.17s+49.17ms),平均每次IO耗时11ms。这个单次IO速度对这套系统的要求来说相对较慢,但也不是慢得很离谱。data blocks consistent reads - undo records applied这个统计值表示进行一致性读时,回滚的UNDO记录条数。
比这个统计值可以很明显地看出,这条SQL在执行时,为了得到一致性读,产生了大量的UNDO记录回滚。那么很显然,在这条SQL语句开始执行的时候,表上有很大的事务还没有提交。当然还有另一种可能是SQL在执行之后有新的很大的事务(不过这种可能性较小一些,因为那样的话这条SQL可能比较快就执行完了)。询问发测试的人员,称没有什么大事务运行过,耳听为虚,眼见为实:

SQL> select object_id from dba_objects where object_name='MOBILE_CALL_1204_OLD';

 OBJECT_ID
----------
     75858

SQL> select * from v$lock where id1=75858;

no rows selected

SQL> select * from dba_tab_modifications where table_name=upper('MOBILE_call_1204_OLD');

   INSERTS    UPDATES    DELETES TIMESTAMP           TRU DROP_SEGMENTS
---------- ---------- ---------- ------------------- --- -------------
         0  162696447          0 2012-05-21 22:00:02 NO              0

这张表目前没有事务,但是曾经update了超过1.6亿条记录。最后一次DML的时间正是这条执行很慢的SQL开始运行之后的时间(这里不能说明最后一次事务量很大,也不能说明最后一次修改对SQL造成了很大影响,但是这里证明了这张表最近的确是修改过,并不是像测试人员说的那样没有修改过)。

实际上对于这张表要做的操作,我之前是类似的表上是有看过的。这张表的总行数有上亿条,而这张表由于进行数据的人工处理,需要update掉绝大部分的行,update时使用并行处理。那么这个问题到,从时间顺序上来讲,应该如下:

  1. 在表上有很大的事务,但是还没有提交。
  2. 问题SQL开始执行查询。
  3. 事务提交。
  4. 在检查SQL性能问题时,表上已经没有事务。

由于update量很大,那么UNDO占用的空间也很大,但是可能由于其他活动的影响,很多UNDO块已经刷出内存,这样在问题SQL执行时,大量的块需要将块回滚到之前的状态(虽然事务开始于查询SQL,但是是在查询SQL开始之后才提交的,一致性读的SCN比较是根据SQL开始的SCN与事务提交SCN比较的,而不是跟事务的开始SCN比较),这样需要访问到大量的UNDO块,但是UNDO块很多已经不在内存中,就不得不从磁盘读入。

对于大事务,特别是更新或DELETE数千万记录的大事务,在生产系统上尽量避免单条SQL一次性做。这造成的影响特别大,比如:

  • 事务可能意外中断,回滚时间很长,事务恢复时过高的并行度可能引起负载增加。
  • 表中大量的行长时间被锁住。
  • 如果事务意外中断,长时间的回滚(恢复)过程中,可能严重影响SQL性能(因为查询时需要回滚块)。
  • 事务还未提交时,影响SQL性能,比如本文中提到的情况。
  • 消耗过多UNDO空间。
  • 对于DELETE大事务,有些版本的oracle在空闲空间查找上会有问题,导致在INSERT数据时,查找空间导致过长的时间。
  • 对于RAC数据库,由于一致性读的代价更大,所以大事务的危害更大。

那么,现在我们可以知道,全表扫描过程还会产生单块读的情况有,读UNDO块。
对于这条SQL,要解决其速度慢的问题,有两种方案:

  1. 在表上建个索引,如果类似的SQL还要多次执行,这是最佳方案。
  2. 取消SQL,重新执行。因为已经没有事务在运行,重新执行只是会产生事务清除,但不会回滚UNDO记录来构建一致性读块。

继续回到问题,从统计数据来看,每秒只构建了少量的一致性读块(CR block created,table scan blocks gotten这两个值均为2),每秒的table scan rows gotten值为98.4,通过dump数据块可以发现块上的行数基本上在49行左右,所以一致性读块数和行数是匹配的。session logical reads每秒为97.6,由于每回滚一条undo记录都要记录一次逻辑读,这个值跟每秒获取的行数也是匹配的(误差值很小),与data blocks consistent reads - undo records applied的值也是很接近的。问题到这儿,产生了一个疑问,就是单块读较多(超过70),因此可以推测,平均每个undo块只回滚了不到2条的undo记录,同时同一数据块上各行对应的undo记录很分散,分散到了多个undo块中,通常应该是聚集在同一个块或相邻块中,这一点非常奇怪,不过现在已经没有这个环境(undo块已经被其他事务重用),不能继续深入地分析这个问题,就留着一个疑问,欢迎探讨(一个可能的解释是块是由多个并发事务修改的,对于这个案例,不会是这种情况,因为在数据块的dump中没有过多ITL,另外更不太可能是一个块更新了多次,因为表实在很大,在短时间内不可能在表上发生很多次这样的大事务)。

在最后,我特别要提到,在生产系统上,特别是OLTP类型的系统上,尽量避免大事务。

客户的一套重要生产系统,出现了性能问题。这个问题涉及的信息如下:

  • 数据库主机的CPU利用率长期在100%左右。
  • 应用系统在晚上进行调整后,开始出现了问题。
  • 数据库中出现大量的latch: shared pool、latch: library cache、cursor: pin S、latch: cache buffers chains和latch: cache buffers lru chain等各种等待。
  • 由于系统较大,整个系统实际上被分成了2个部分,每个部分服务不同的用户。二者的应用基本相同,分别对应2套数据库,二者也同样在出问题之前进行了调整,而数据库的主机配置及参数也是相同的,同时均为10.2.0.5双节点RAC数据库。但是只有其中1套库有性能问题。
  • 2套库的配置虽然没有差别,但是负载方式却有很大的区别,正常的那套库,2个节点的负载基本上是均衡的,而现在有性能问题的这套库,所有的负载基本上全部在第1个节点上(虽然已经多次要求开发商整改,不幸的是...这里不用说了)。

下面是AWR报告中的数据:

性能正常时间段的数据(采集时间2小时):

              Snap Id      Snap Time      Sessions Curs/Sess
            --------- ------------------- -------- ---------
Begin Snap:      3408 19-Sep-11 09:00:21     4,690      39.5
  End Snap:      3412 19-Sep-11 11:00:07     4,950      38.7
   Elapsed:              119.76 (mins)
   DB Time:            2,900.95 (mins)

Cache Sizes
~~~~~~~~~~~                       Begin        End
                             ---------- ----------
               Buffer Cache:    35,840M    35,840M  Std Block Size:         8K
           Shared Pool Size:     6,144M     6,144M      Log Buffer:    30,632K

Load Profile
~~~~~~~~~~~~                            Per Second       Per Transaction
                                   ---------------       ---------------
                  Redo size:          1,968,314.84              6,360.04
              Logical reads:          1,038,182.89              3,354.59
              Block changes:            148,577.35                480.09
             Physical reads:              3,541.98                 11.44
            Physical writes:                546.31                  1.77
                 User calls:              7,811.87                 25.24
                     Parses:              3,187.30                 10.30
                Hard parses:                 10.07                  0.03
                      Sorts:              6,258.90                 20.22
                     Logons:                  9.65                  0.03
                   Executes:             24,100.52                 77.87
               Transactions:                309.48
Instance Efficiency Percentages (Target 100%)
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
            Buffer Nowait %:  100.00       Redo NoWait %:  100.00
            Buffer  Hit   %:   99.69    In-memory Sort %:  100.00
            Library Hit   %:   99.36        Soft Parse %:   99.68
         Execute to Parse %:   86.77         Latch Hit %:   99.64
Parse CPU to Parse Elapsd %:   45.61     % Non-Parse CPU:   99.46

 Shared Pool Statistics        Begin    End
                              ------  ------
             Memory Usage %:   95.44   94.46
    % SQL with executions>1:   89.10   77.18
  % Memory for SQL w/exec>1:   87.82   76.62

Top 5 Timed Events                                         Avg %Total
~~~~~~~~~~~~~~~~~~                                        wait   Call
Event                                 Waits    Time (s)   (ms)   Time Wait Class
------------------------------ ------------ ----------- ------ ------ ----------
CPU time                                        114,107          65.6
db file sequential read           8,232,067      40,956      5   23.5   User I/O
db file scattered read              929,509       2,392      3    1.4   User I/O
log file sync                     2,119,459       2,372      1    1.4     Commit
SQL*Net message from dblink       1,375,619       1,576      1    0.9    Network
          -------------------------------------------------------------
^LWait Events                         DB/Inst: CRM2DB/crm2db1  Snaps: 3408-3412
-> s  - second
-> cs - centisecond -     100th of a second
-> ms - millisecond -    1000th of a second
-> us - microsecond - 1000000th of a second
-> ordered by wait time desc, waits desc (idle events last)
-> %Timeouts: value of 0 indicates value was <  .5%.  Value of null is truly 0

                                                                  Avg
                                            %Time  Total Wait    wait     Waits
Event                                 Waits -outs    Time (s)    (ms)      /txn
---------------------------- -------------- ----- ----------- ------- ---------
db file sequential read           8,232,067   N/A      40,956       5       3.7
db file scattered read              929,509   N/A       2,392       3       0.4
log file sync                     2,119,459     0       2,372       1       1.0
SQL*Net message from dblink       1,375,619   N/A       1,576       1       0.6
SQL*Net more data from clien      1,871,442   N/A       1,428       1       0.8
control file sequential read      3,010,438   N/A       1,179       0       1.4
Backup: sbtbackup                        12   N/A       1,167   97243       0.0
gc cr grant 2-way                 3,688,572   N/A         993       0       1.7
log file parallel write           2,205,552   N/A         974       0       1.0
gc cr multi block request         2,378,748   N/A         721       0       1.1
gc current block 2-way            1,941,104   N/A         693       0       0.9
SQL*Net more data to client       5,142,664   N/A         498       0       2.3
gc buffer busy                      166,717     0         428       3       0.1
direct path read                    424,645   N/A         344       1       0.2
db file parallel read                61,816   N/A         298       5       0.0
enq: HW - contention                 17,487     0         216      12       0.0
db file parallel write              221,865   N/A         210       1       0.1
Backup: sbtwrite2                    36,271   N/A         145       4       0.0
gc current grant 2-way              445,456   N/A         115       0       0.2
enq: TM - contention                    255    74         102     400       0.0
                         

在应用调整第2天上午的awr数据(采集时长1小时):

Load Profile
~~~~~~~~~~~~                            Per Second       Per Transaction
                                   ---------------       ---------------
                  Redo size:          2,420,236.58              6,734.48
              Logical reads:          1,277,888.60              3,555.82
              Block changes:            164,638.57                458.12
             Physical reads:              1,208.59                  3.36
            Physical writes:                456.79                  1.27
                 User calls:              8,785.42                 24.45
                     Parses:              4,103.35                 11.42
                Hard parses:                 12.87                  0.04
                      Sorts:              8,052.30                 22.41
                     Logons:                  9.05                  0.03
                   Executes:             32,573.41                 90.64
               Transactions:                359.38

  % Blocks changed per Read:   12.88    Recursive Call %:    85.01
 Rollback per transaction %:    0.19       Rows per Sort:     8.74

Instance Efficiency Percentages (Target 100%)
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
            Buffer Nowait %:   99.97       Redo NoWait %:  100.00
            Buffer  Hit   %:   99.92    In-memory Sort %:  100.00
            Library Hit   %:   99.92        Soft Parse %:   99.69
         Execute to Parse %:   87.40         Latch Hit %:   99.33
Parse CPU to Parse Elapsd %:   29.94     % Non-Parse CPU:   99.17

 Shared Pool Statistics        Begin    End
                              ------  ------
             Memory Usage %:   95.42   95.02
    % SQL with executions>1:   61.41   72.38
  % Memory for SQL w/exec>1:   60.04   73.07

Top 5 Timed Events                                         Avg %Total
~~~~~~~~~~~~~~~~~~                                        wait   Call
Event                                 Waits    Time (s)   (ms)   Time Wait Class
------------------------------ ------------ ----------- ------ ------ ----------
CPU time                                         69,736          56.2
Backup: sbtwrite2                 2,319,231      22,510     10   18.1 Administra
db file sequential read           3,476,830      20,923      6   16.9   User I/O
latch: shared pool                  159,416       9,280     58    7.5 Concurrenc
Backup: sbtbackup                        28       2,746  98056    2.2 Administra
          -------------------------------------------------------------
^LWait Events                         DB/Inst: CRM2DB/crm2db1  Snaps: 3602-3604
-> s  - second
-> cs - centisecond -     100th of a second
-> ms - millisecond -    1000th of a second
-> us - microsecond - 1000000th of a second
-> ordered by wait time desc, waits desc (idle events last)
-> %Timeouts: value of 0 indicates value was <  .5%.  Value of null is truly 0

                                                                  Avg
                                            %Time  Total Wait    wait     Waits
Event                                 Waits -outs    Time (s)    (ms)      /txn
---------------------------- -------------- ----- ----------- ------- ---------
Backup: sbtwrite2                 2,319,231   N/A      22,510      10       1.8
db file sequential read           3,476,830   N/A      20,923       6       2.7
latch: shared pool                  159,416   N/A       9,280      58       0.1
Backup: sbtbackup                        28   N/A       2,746   98056       0.0
log file sync                     1,283,319     0       2,538       2       1.0
gc buffer busy                    1,088,432     0       2,324       2       0.8
latch: library cache                 31,278   N/A       1,328      42       0.0
control file sequential read      1,512,218   N/A       1,082       1       1.2
log file parallel write           1,157,491   N/A       1,045       1       0.9
SQL*Net message from dblink         952,956   N/A         987       1       0.7
SQL*Net more data from clien        962,454   N/A         837       1       0.7
kst: async disk IO                   17,574   N/A         483      27       0.0
gc cr grant 2-way                 1,539,289   N/A         439       0       1.2
gc current block 2-way              946,330   N/A         353       0       0.7
direct path read                    291,853   N/A         313       1       0.2
db file parallel write              261,735   N/A         298       1       0.2
read by other session                92,451     0         270       3       0.1
cursor: pin S                   304,676,088   N/A         233       0     235.1
db file scattered read               28,062   N/A         132       5       0.0
enq: TX - row lock contentio            466    52         123     263       0.0
direct path write                   227,989   N/A         113       0       0.2
          

从Load profile数据对比来看,应用调整后系统负载有一定的提高,同时每事务逻辑读也有一定的增加(不足10%)。这会是个问题吗?
从第2份数据来看,latch: shared pool 和 latch: library cache有明显的增加。

下面的是性能问题更加严重的时候的AWR数据(采集时长为2小时):

              Snap Id      Snap Time      Sessions Curs/Sess
            --------- ------------------- -------- ---------
Begin Snap:      3744 26-Sep-11 09:00:01     4,504      38.2
  End Snap:      3748 26-Sep-11 11:00:26     4,916      52.7
   Elapsed:              120.41 (mins)
   DB Time:           21,868.27 (mins)

Cache Sizes
~~~~~~~~~~~                       Begin        End
                             ---------- ----------
               Buffer Cache:    35,840M    35,840M  Std Block Size:         8K
           Shared Pool Size:     6,144M     6,144M      Log Buffer:    30,632K

Load Profile
~~~~~~~~~~~~                            Per Second       Per Transaction
                                   ---------------       ---------------
                  Redo size:          1,790,430.57              5,945.33
              Logical reads:          1,162,875.15              3,861.46
              Block changes:            154,064.15                511.59
             Physical reads:              3,007.80                  9.99
            Physical writes:                337.21                  1.12
                 User calls:              8,227.28                 27.32
                     Parses:              3,603.24                 11.96
                Hard parses:                 11.25                  0.04
                      Sorts:              7,304.40                 24.26
                     Logons:                 11.27                  0.04
                   Executes:             25,994.53                 86.32
               Transactions:                301.15

  % Blocks changed per Read:   13.25    Recursive Call %:    82.87
 Rollback per transaction %:    0.21       Rows per Sort:     8.14

Instance Efficiency Percentages (Target 100%)
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
            Buffer Nowait %:   99.99       Redo NoWait %:  100.00
            Buffer  Hit   %:   99.75    In-memory Sort %:  100.00
            Library Hit   %:   99.94        Soft Parse %:   99.69
         Execute to Parse %:   86.14         Latch Hit %:   98.90
Parse CPU to Parse Elapsd %:   14.69     % Non-Parse CPU:   84.51

 Shared Pool Statistics        Begin    End
                              ------  ------
             Memory Usage %:   95.48   94.33
    % SQL with executions>1:   87.63   74.92
  % Memory for SQL w/exec>1:   86.52   74.66

Top 5 Timed Events                                         Avg %Total
~~~~~~~~~~~~~~~~~~                                        wait   Call
Event                                 Waits    Time (s)   (ms)   Time Wait Class
------------------------------ ------------ ----------- ------ ------ ----------
latch: shared pool                  991,918     274,715    277   20.9 Concurrenc
latch: library cache                941,443     232,344    247   17.7 Concurrenc
CPU time                                        212,150          16.2
cursor: pin S                  ############     115,049      0    8.8      Other
latch: cache buffers lru chain    1,106,570      96,442     87    7.4      Other
          -------------------------------------------------------------
^LWait Events                         DB/Inst: CRM2DB/crm2db1  Snaps: 3744-3748
-> s  - second
-> cs - centisecond -     100th of a second
-> ms - millisecond -    1000th of a second
-> us - microsecond - 1000000th of a second
-> ordered by wait time desc, waits desc (idle events last)
-> %Timeouts: value of 0 indicates value was < .5%.  Value of null is truly 0

                                                                  Avg
                                            %Time  Total Wait    wait     Waits
Event                                 Waits -outs    Time (s)    (ms)      /txn
---------------------------- -------------- ----- ----------- ------- ---------
latch: shared pool                  991,918   N/A     274,715     277       0.5
latch: library cache                941,443   N/A     232,344     247       0.4
cursor: pin S                 9,095,470,035   N/A     115,049       0   4,180.5
latch: cache buffers lru cha      1,106,570   N/A      96,442      87       0.5
db file sequential read           7,819,285   N/A      49,564       6       3.6
latch: cache buffers chains         511,936   N/A      35,753      70       0.2
latch free                           95,257     0      14,609     153       0.0
latch: object queue header o        221,907   N/A      14,378      65       0.1
log file sync                     2,156,343     1      11,496       5       1.0
cursor: pin S wait on X             422,320   100       4,603      11       0.2
gc cr grant 2-way                 3,526,856     0       3,430       1       1.6
db file scattered read              624,480   N/A       3,083       5       0.3
enq: TX - row lock contentio          5,946    88       2,600     437       0.0
latch: row cache objects             16,983   N/A       2,281     134       0.0
SQL*Net message from dblink       1,284,487   N/A       2,179       2       0.6
gc buffer busy                      353,228     0       2,054       6       0.2
gc cr multi block request         2,499,709     0       1,974       1       1.1
gc current block 2-way            1,969,516     0       1,920       1       0.9
SQL*Net more data from clien      1,667,513   N/A       1,914       1       0.8
control file sequential read      2,974,349   N/A       1,735       1       1.4
db file parallel read               230,795   N/A       1,645       7       0.1
log file parallel write           1,581,432   N/A       1,303       1       0.7
Backup: sbtbackup                        14   N/A         730   52120       0.0
buffer busy waits                   143,869     0         488       3       0.1
latch: library cache lock             5,058   N/A         378      75       0.0
enq: HW - contention                 22,039     0         370      17       0.0
gc current grant 2-way              424,243   N/A         357       1       0.2
enq: SQ - contention                  5,010     1         354      71       0.0
read by other session                50,153     0         339       7       0.0
direct path read                    324,226   N/A         305       1       0.1
db file parallel write              207,793   N/A         274       1       0.1
row cache lock                      175,301     0         263       1       0.1
          

从第3份数据来看,性能更为恶化,情形更为复杂。

那么针对这个性能现象,可以提出如下的问题:

  • 最直观的,最容易想到的就是,性能问题的出现是否与应用调整有关,如果是,为什么另一套库没有出现问题?会不会是另一套库的负载在2个节点都有相对均衡的负担,而出问题的库,负载全部集中在1个节点上引起?
  • 客户是在应用调整几天后才报告性能问题,这个问题会不会是一个逐渐出现的问题?如果一开始就有严重的性能问题,那么应该会很快报告。不过中间跨了一个周末,所以对于”逐渐出现问题“的判断又加了一些难度。
  • 这么多的性能问题相关的现象中,哪个更贴近问题的原因?实际上在主机的CPU长期保持在100%左右时,会放大平时的一些轻微的问题,或者引起另一些问题。从等待来看,latch: cache buffers chains和cursor: pin S都会引起CPU的急剧增加,而其他的latch竞争同样也会引起CPU的上升,虽然上升没有前者大。到底是SQL执行效率不高引起CPU急剧增加然后引起了shared pool latch等与解析相关的资源争用还是因为解析相关的问题导致CPU急剧增加引起了cache buffers chains等与SQL执行相关的latch争用?或者是2者的共同作用?

下面首先来分析,会不会是应用调整引起的问题,也就是说,是不是由SQL引起的问题。如果是SQL引起的问题,会有几种可能,1是部分频繁执行的SQL执行效率变差;2是增加了很多的硬解析;3是并发增加或者说是SQL的执行次数有上升。仔细检查对比现在和以前的AWR数据,可以排除第1和2这种可能。至于第3种,可能略有增加,但是不一定跟应用调整有关,毕竟正常情况下业务量的变化也是有可能的。所以应用调整引起问题的可能性较小。

会不会是因为负载过大引起的问题,这个很容易验证。取业务低谷期,比如下班时间的数据,进行分析可以发现,既然在CPU在稍低(75%以下)的时候,仍然有大量的library cache latch的争用。下面是取自周日19:00-20:00的AWR数据(注:本文涉及故障的分析时间是在星期一):

Top 5 Timed Events                                         Avg %Total
~~~~~~~~~~~~~~~~~~                                        wait   Call
Event                                 Waits    Time (s)   (ms)   Time Wait Class
------------------------------ ------------ ----------- ------ ------ ----------
CPU time                                         49,224          48.3
latch: shared pool                  185,951      41,178    221   40.4 Concurrenc
latch: library cache                 45,636       8,861    194    8.7 Concurrenc
db file sequential read             815,066       4,763      6    4.7   User I/O
cursor: pin S                  ############       1,732      0    1.7      Other
          -------------------------------------------------------------

                                                                  Avg
                                            %Time  Total Wait    wait     Waits
Event                                 Waits -outs    Time (s)    (ms)      /txn
---------------------------- -------------- ----- ----------- ------- ---------
latch: shared pool                  185,951   N/A      41,178     221       0.6
latch: library cache                 45,636   N/A       8,861     194       0.2
db file sequential read             815,066   N/A       4,763       6       2.8
cursor: pin S                 1,890,998,700   N/A       1,732       0   6,459.2
latch free                            8,549     0       1,278     150       0.0
control file sequential read      1,507,789   N/A         466       0       5.2
Backup: sbtbackup                         7   N/A         428   61096       0.0
log file sync                       285,442     0         309       1       1.0
SQL*Net more data from clien        145,137   N/A         221       2       0.5
db file scattered read               67,716   N/A         173       3       0.2
gc buffer busy                       56,842     0         135       2       0.2
gc cr grant 2-way                   359,146   N/A          99       0       1.2
SQL*Net message from dblink         123,206   N/A          98       1       0.4
log file parallel write             289,048   N/A          91       0       1.0
SQL*Net more data to client       1,242,471   N/A          79       0       4.2
gc current block 2-way              179,654   N/A          66       0       0.6
direct path read                     62,336   N/A          65       1       0.2
gc cr multi block request           228,693   N/A          52       0       0.8
          

至于性能问题是不是逐渐引起的,这个问题目前并不关键,暂时不考虑。只是做为后面分析问题的一个参考。

Read the rest of this entry

,

客户新上线的一套重要生产系统,某个存储过程每小时调用约11万次,每次调用的逻辑读超过了10000,消耗的CPU占数据库CPU Time的25-30%。很显然,这样一个存储过程是值得优化的。

不幸的是,这个存储过程的业务逻辑很复杂,光是参数就有9个。而存储过程所在的包其代码超过了1万行。通过复查代码的方式,耗时耗力,还不一定能够找出问题。

诊断性能问题,首要的是了解这个存储过程所大概要完成的业务功能,然后通过trace或instrument收集足够详细的性能数据。从客户和开发商那里了解到,存在性能问题的存储过程,主要用于系统之间的数据查询接口,根据不同的参数输入查询不同的数据,那么,对于这种小数据量的存储过程,可以考虑使用10046事件来分析是哪些SQL产生了这么多的逻辑读。

但是通过10046事件,发现存储过程中实际执行的SQL并不多,同时并没有逻辑读高的SQL语句。也许问题并没有出现在SQL语句中,而是出现在存储过程中其他非SQL部分。虽然用10046没有找到SQL语句,但还是有重大发现,在过程执行时,大量的逻辑读来自于current方式的读,这显示不是通常的SELECT语句所产生的。接下来我们用dbms_profiler来分析存储过程:

select dbms_profiler.start_profiler from dual;
exec intf.CRM_SERVICE_INTF.QueryService(.....);
exec dbms_profiler.stop_profiler;

然后使用来自MOS文档“Implementing and Using the PL/SQL Profiler [ID 243755.1]”中的profiler.sql脚本,生成一个profiler的结果文件,格式为html。下面是部分的内容:
profiler1

点击其显示的代码行(line),跳转到相应的源代码,发现大量的字符串拼接代码,很明显是用于拼接成XML格式。这很容易理解,因为现在系统之间的文本数据交互,xml几乎成了标准。从上面的截图中也可以看到很多类型于xml:=xml || ‘xxxx’ 这样的代码。是这样的代码引起的问题吗?

检查代码发现,这里用于拼接字符串的变量xml,被定义为clob类型,这引起了我极大的关注。在oracle的标准数据类型中,lob类型由于其能够存储大数据的本质,导致其内部格式和操作是最复杂的。有理由怀疑是clob的大量拼接引起的问题。

在有怀疑对象后,我们可以构造下面的测试来进行验证:

首先创建下面3个不同的存储过程,但是实现的功能是一致的:

create or replace procedure p1 ( v_out out clob)
is
  v_lob clob;
begin
  v_lob:='';
  for rec in (select object_name from dba_objects where rownum< =1000) loop
      v_lob:=v_lob || rec.object_name;
  end loop;
  v_out:=v_lob;
end;
/

      
create or replace procedure p2 ( v_out out clob)
is
  v_lob varchar2(32767);
begin
  v_lob:='';
  for rec in (select object_name from dba_objects where rownum<=1000) loop
      v_lob:=v_lob || rec.object_name;
  end loop;
  v_out:=v_lob;
end;
/

create or replace procedure p3 ( v_out out clob)
is
  v_lob clob;
  v_str varchar2(32767);
  v_cnt number;
begin
  v_lob:='';
  v_cnt:=0;
  v_str:='';
  for rec in (select object_name from dba_objects where rownum<=1000) loop
        v_str:=v_str || rec.object_name;
        v_cnt:=v_cnt+1;
        if v_cnt = 50 then
           v_cnt:=0;
           v_lob:=v_lob || v_str;
           v_str:='';
        end if;   
  end loop;
  if v_cnt <>0 then
     v_lob:=v_lob || v_str;
  end if;   
  v_out:=v_lob;
end;
/

Read the rest of this entry

我给《DBA 手记III》投的一篇稿子,名为《一次由隐含参数引起性能问题的处理》,这篇文章描述了一套关键的系统,由于"_kghdsidx_count"这个参数设置为1,导致了严重的性能问题。从故障现象上看是大量的library cache latch的等待,以及shared pool latch的等待,但是前者的等待时间比后者长得多。在文章中,我提到,在当时我推断,由于"_kghdsidx_count"这个隐含参数设置为1,导致shared pool只有1个subpool,引起了shared pool latch的严重竞争,进而引起了library cache cache的更为严重的竞争,这个竞争的过程如下:

  1. 由于"_kghdsidx_count"=1,使得shared pool latch只有1个child latch。而library cache latch的child latch数量跟CPU数量有关,最大值为67,编号为child #1-#67。
  2. 会话1持有shared pool latch。
  3. 会话2解析SQL语句,首先持有了library cache latch的child latch,假设这里为child #1,然后去请求shared pool latch。很显然,这时候被会话1持有,那么会话2就会等待shared pool latch。
  4. 会话3解析SQL语句,首先需要请求library cache latch,如果请求的library cache child latch刚好是#1,那么由于会话2持有了这个child latch,就会等待library cache latch。
  5. 因此,实际上会话1和会话2的shared pool latch的竞争引起了会话3的library cache latch的等待。如果并发数不是太高,那么shared pool latch的竞争看上去就会比library cache latch的竞争多一些。但是如果有几百个活动会话,这个时候,就会有大量的会话首先等待library cache latch,因为在解析SQL时是首先需要获取library cache latch再获取shared pool latch。由于大量的软解析,甚至不需要获取shared pool latch,同时一个大型的OLTP系统中,某几条相同的SQL并发执行的概率很高,这样会使很多会话同时请求同一library cache child latch;另外,在解析过程中,可能会多次请求library cache latch和shared pool latch,而前者请求和释放的次数会比后者多得多;这样大量的会话在获取library cache latch时处于等待状态,从现象上看就比shared pool latch的等待多得多。


而本文主要表达的是,怎么来验证在解析时,Oracle进程在持有了library cache latch的情况下去请求shared pool latch,而不是在请求shared pool时不需要持有library cache latch。

由于这个验证过程过于internal,所以没有在《DBA手记III》中描述出来。这里写出来,供有兴趣的朋友参考。

验证上面的这一点,有2个方法。下面以测试过程来详细描述。
测试环境 :Oracle 10.2.0.5.1 for Linux X86.

方法一:使用oradebug。

1. 将数据库的"_kghdsidx_count"参数值设为1,并重启数据库,以保证只有一个shared pool child latch。
2. 使用sqlplus连接到数据库,假设这个会话是session-1,查询当前的SID:

SQL> select sid from v$mystat where rownum=1;

       SID
----------
       159

同时获得当前连接的spid为2415。
3. 新建一个连接到数据库,假设会话是session-2,查询shared pool latch的地址,并使用oradebug将这个地址对应的值置为1,以表示该latch已经被持有:


SQL> select addr,latch#,level#,child#,name,gets  from v$latch_children where name='shared pool';

ADDR         LATCH#     LEVEL#     CHILD# NAME                                                     GETS
-------- ---------- ---------- ---------- -------------------------------------------------- ----------
200999BC        216          7          1 shared pool                                             34949
20099A20        216          7          2 shared pool                                                 6
20099A84        216          7          3 shared pool                                                 6
20099AE8        216          7          4 shared pool                                                 6
20099B4C        216          7          5 shared pool                                                 6
20099BB0        216          7          6 shared pool                                                 6
20099C14        216          7          7 shared pool                                                 6

SQL> oradebug poke 0x200999BC 4 1
BEFORE: [200999BC, 200999C0) = 00000000
AFTER:  [200999BC, 200999C0) = 00000001

4. 在session-1会话中执行下面的SQL:

SQL> select owner from t where object_id=3003;

正如预料之中的反映,这个会话hang住。

5. 在session-2中,对session-1的进程作process dump。(注意这个时候不能查询v$session_wait、v$latchholder等视图)

SQL> oradebug setospid 2415
Oracle pid: 15, Unix process pid: 2415, image: oracle@xty (TNS V1-V3)
SQL> oradebug dump processstate 10
Statement processed.
SQL> oradebug tracefile_name
/oracle/app/oracle/admin/xty/udump/xty_ora_2415.trc

然后从/oracle/app/oracle/admin/xty/udump/xty_ora_2415.trc这个TRACE文件中可以找到下面的信息:

Read the rest of this entry

,

在上一篇《SQL Profiles-Part I》,我向大家介绍了什么是SQL Profiles及其作用,如何使用SQL Tuning Advisor来生成SQL Profile,以及生成的SQL Profile产生的Hint。同时也介绍了SQL的signature。那么在今天,将向大家介绍如何手工创建SQL Profiles(即不通过SQL Tuning Advisor)来达成2个目的:

  • 锁定或者说稳定SQL执行计划。
  • 在不能修改应用的SQL的情况下,来改变或者说是强制使SQL使用我们指定的执行计划,即使原始的SQL包含了Hints。

那么,这里最关键的一点是,如何来手工创建SQL Profiles?
答案是,正如上一篇中有朋友的留言,使用DBMS_SQLTUNE.IMPORT_SQL_PROFILE过程。

SQL> desc dbms_sqltune
...
PROCEDURE IMPORT_SQL_PROFILE
参数名称                       类型                    输入/输出默认值?
------------------------------ ----------------------- ------ --------
 SQL_TEXT                       CLOB                    IN
 PROFILE                        SQLPROF_ATTR            IN
 NAME                           VARCHAR2                IN     DEFAULT
 DESCRIPTION                    VARCHAR2                IN     DEFAULT
 CATEGORY                       VARCHAR2                IN     DEFAULT
 VALIDATE                       BOOLEAN                 IN     DEFAULT
 REPLACE                        BOOLEAN                 IN     DEFAULT
 FORCE_MATCH                    BOOLEAN                 IN     DEFAULT
...

这个过程其名字与实际功能有所差异,其实可以理解为CREATE OR REPLACE SQL_PROFILE。过程中的PROFILE参数为SYS.SQLPROF_ATTR,这种类型其实就是VARCHAR2的集合类型(COLLECTION):

SQL> select text from dba_source where name='SQLPROF_ATTR' and owner='SYS';

TYPE     sqlprof_attr
 AS VARRAY(2000) of VARCHAR2(500)

下面我们就用这个过程来创建SQL PROFILE:
为避免干扰,将上一篇测试中生成的SQL Profile删除掉,同时恢复T1表的统计信息中的表行数:

SQL> exec dbms_sqltune.drop_sql_profile('SYS_SQLPROF_014b39f084c88000');

PL/SQL 过程已成功完成。

SQL> exec dbms_stats.set_table_stats('TEST1','T1',numrows=>49953);

PL/SQL 过程已成功完成。

现在我们手工创建一个SQL Profile:

SQL> declare
  2    v_hints sys.sqlprof_attr;
  3  begin
  4    v_hints:=sys.sqlprof_attr('USE_NL(T1 T2)','INDEX(T2)');
  5    dbms_sqltune.import_sql_profile('select t1.*,t2.owner from t1,t2 where t1.object_name like ''%T1%'' and t1.object_id=t2.object_id',
  6                v_hints,'SQLPROFILE_NAME1',force_match=>true);
  7  end;
  8  /

PL/SQL 过程已成功完成。

SQL> select attr_val from dba_sql_profiles a, sys.sqlprof$attr b
  2  where a.signature = b.signature
  3  and a.name='SQLPROFILE_NAME1';

ATTR_VAL
----------------------------------------
USE_NL(T1 T2)
INDEX(T2)

下面执行SQL Profiles对应的SQL:

SQL> select  t1.*,t2.owner
  2       from t1,t2
  3       where t1.object_name like '%T1%'
  4       and t1.object_id=t2.object_id;

已选择29行。

执行计划
----------------------------------------------------------
Plan hash value: 1838229974

---------------------------------------------------------------------------
| Id  | Operation          | Name | Rows  | Bytes | Cost (%CPU)| Time     |
---------------------------------------------------------------------------
|   0 | SELECT STATEMENT   |      |  2498 | 99920 |   219   (4)| 00:00:03 |
|*  1 |  HASH JOIN         |      |  2498 | 99920 |   219   (4)| 00:00:03 |
|*  2 |   TABLE ACCESS FULL| T1   |  2498 | 72442 |    59   (6)| 00:00:01 |
|   3 |   TABLE ACCESS FULL| T2   | 49954 |   536K|   159   (2)| 00:00:02 |
---------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------

   1 - access("T1"."OBJECT_ID"="T2"."OBJECT_ID")
   2 - filter("T1"."OBJECT_NAME" LIKE '%T1%')

Note
-----
   - SQL profile "SQLPROFILE_NAME1" used for this statement

统计信息
----------------------------------------------------------
          0  recursive calls
          0  db block gets
        933  consistent gets
        

可以看到,SQL使用了SQL Profile,不过没有达到我们预期的效果。

看起来是SQL Profile使用的Hints有问题。我们重新设置SQL Profile的Hints,在Hints中加上“Query Block Name"。这一次在执行IMPORT_SQL_PROFILE过程时,将REPLACE参数设置为TRUE,以替换现有的SQL Profile:

SQL> declare
  2    v_hints sys.sqlprof_attr;
  3  begin
  4    v_hints:=sys.sqlprof_attr('USE_NL(T1@SEL$1 T2@SEL$1)','INDEX(T2@SEL$1)');
  5    dbms_sqltune.import_sql_profile('select t1.*,t2.owner from t1,t2 where t1.object_name like ''%T1%'' and t1.object_id=t2.object_id',
  6                v_hints,'SQLPROFILE_NAME1',force_match=>true,replace=>true);
  7  end;
  8  /

PL/SQL 过程已成功完成。

SQL> select attr_val from dba_sql_profiles a, sys.sqlprof$attr b
  2  where a.signature = b.signature
  3  and a.name='SQLPROFILE_NAME1';

ATTR_VAL
----------------------------------------
USE_NL(T1@SEL$1 T2@SEL$1)
INDEX(T2@SEL$1)  

再次执行下面的SQL:

SQL> select  t1.*,t2.owner
  2       from t1,t2
  3       where t1.object_name like '%T1%'
  4       and t1.object_id=t2.object_id;

已选择29行。

执行计划
----------------------------------------------------------
Plan hash value: 3787413387

--------------------------------------------------------------------------------------
| Id  | Operation                   | Name   | Rows  | Bytes | Cost (%CPU)| Time     |
--------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT            |        |  2498 | 99920 |  5061   (1)| 00:01:01 |
|   1 |  TABLE ACCESS BY INDEX ROWID| T2     |     1 |    11 |     2   (0)| 00:00:01 |
|   2 |   NESTED LOOPS              |        |  2498 | 99920 |  5061   (1)| 00:01:01 |
|*  3 |    TABLE ACCESS FULL        | T1     |  2498 | 72442 |    59   (6)| 00:00:01 |
|*  4 |    INDEX RANGE SCAN         | T2_IDX |     1 |       |     1   (0)| 00:00:01 |
--------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------

   3 - filter("T1"."OBJECT_NAME" LIKE '%T1%')
   4 - access("T1"."OBJECT_ID"="T2"."OBJECT_ID")

Note
-----
   - SQL profile "SQLPROFILE_NAME1" used for this statement

统计信息
----------------------------------------------------------
          0  recursive calls
          0  db block gets
        294  consistent gets

这一次达到了预期的效果。看起来在SQL Profiles中对Hints还有一定的要求。
那么我们再一次手工修改T1表的统计信息,看看结果如何:

Read the rest of this entry

,

Oracle 11g从发布到现在,也有几个年头了。而在国内来说,Oracle 10g仍然是主流,甚至一些电信运营商的核心系统仍然在使用9i。作为Oracle 10g的一项新特性,SQL Profiles被使用得并不太多。不管是在论坛、个人的BLOG还是其他一些地方,SQL Profiles的介绍也相对较少。对我个人来说,已经在多个优化场合中使用SQL Profiles,在这里向大家介绍SQL Profiles,就是希望能够了解Oracle数据库的这一功能。

SQL Profiles可以说是Outlines的进化。Outlines能够实现的功能SQL Profiles也完全能够实现,而SQL Profiles具有Outlines不具备的优化,个人认为最重要的有2点:

  • SQL Profiles更容易生成、更改和控制。
  • SQL Profiles在对SQL语句的支持上做得更好,也就是适用范围更广。

关于这2方面的优点,我后面会详细地阐述。

现在我在使用Outlines的场合,均使用SQL Profiles来替代。有一次准备对1条SQL语句使用Outline进行执行计划的稳定,结果使用Outline之后,系统出现大量的library cache latch的争用,不得不关闭Outline的使用,但是改用SQL Profiles不再有这个问题。这或许是个BUG,不过既然能用SQL Profiles代替,也就没再深入去研究这个问题。

使用SQL Profiles无非是两个目的:

  • 锁定或者说是稳定执行计划。
  • 在不能修改应用中的SQL的情况下使SQL语句按指定的执行计划运行。

那么SQL Profile到底是什么?在我看来,SQL Profile就是为某一SQL语句提供除了系统统计信息、对象(表和索引等)统计信息之外的其他信息,比如运行环境、额外的更准确的统计信息,以帮助优化器为SQL语句选择更适合的执行计划。这些说法显得比较枯燥,还是来看看下面的测试。

首先建2个测试表:

SQL> create table t1 as select object_id,object_name from dba_objects where rownum<=50000;

表已创建。

SQL> create table t2 as select * from dba_objects;

表已创建。

SQL> create index t2_idx on t2(object_id);

索引已创建。

SQL> exec dbms_stats.gather_table_stats(user,'t1',cascade=>true,method_opt=>'for all columns size 1');

PL/SQL 过程已成功完成。

SQL> exec dbms_stats.gather_table_stats(user,'t2',cascade=>true,method_opt=>'for all columns size 1');

PL/SQL 过程已成功完成。

然后看看下面这一条SQL:

SQL> select t1.*,t2.owner from t1,t2 where t1.object_name like '%T1%' and t1.object_id=t2.object_id;

已选择29行。


执行计划
----------------------------------------------------------
Plan hash value: 1838229974

---------------------------------------------------------------------------
| Id  | Operation          | Name | Rows  | Bytes | Cost (%CPU)| Time     |
---------------------------------------------------------------------------
|   0 | SELECT STATEMENT   |      |  2498 | 99920 |   219   (4)| 00:00:03 |
|*  1 |  HASH JOIN         |      |  2498 | 99920 |   219   (4)| 00:00:03 |
|*  2 |   TABLE ACCESS FULL| T1   |  2498 | 72442 |    59   (6)| 00:00:01 |
|   3 |   TABLE ACCESS FULL| T2   | 49954 |   536K|   159   (2)| 00:00:02 |
---------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------

   1 - access("T1"."OBJECT_ID"="T2"."OBJECT_ID")
   2 - filter("T1"."OBJECT_NAME" LIKE '%T1%')


统计信息
----------------------------------------------------------
          0  recursive calls
          0  db block gets
        932  consistent gets
          0  physical reads
          0  redo size
       1352  bytes sent via SQL*Net to client
        385  bytes received via SQL*Net from client
          2  SQL*Net roundtrips to/from client
          0  sorts (memory)
          0  sorts (disk)
         29  rows processed

这里省略了SELECT出来的具体数据,但是我们关心的是返回的结果行数、执行计划以及逻辑读这些信息。
首先从执行计划可以看到,这条SQL语句在2个表上都是全表扫描。在第1个表T1上,有 like '%T1%'这样的条件,导致只能全表扫描,这没有问题。但是第2个表,也是全表扫描,这里有没有问题呢?或者说是有没有优化的余地,答案显然是肯定的。
这里的问题在于执行计划ID=1的那一行,Oracle优化器评估T1 like '%T1%'返回的结果行数为2498行,即T1表总行数的5%,如果2个表采用index range scan+nested loop连接,oracle评估的成本会高于full table scan+hash join。下面可以看到Oracle优化器评估的index range_scan+nested loop的成本:

SQL> explain plan for select /*+ use_nl(t1 t2) index(t2) */ t1.*,t2.owner 
     from t1,t2 
     where t1.object_name like '%T1%' 
     and t1.object_id=t2.object_id;

已解释。

SQL> @showplan

PLAN_TABLE_OUTPUT
--------------------------------------------------------------------------------------
Plan hash value: 3787413387
--------------------------------------------------------------------------------------
| Id  | Operation                   | Name   | Rows  | Bytes | Cost (%CPU)| Time     |
--------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT            |        |  2498 | 99920 |  5061   (1)| 00:01:01 |
|   1 |  TABLE ACCESS BY INDEX ROWID| T2     |     1 |    11 |     2   (0)| 00:00:01 |
|   2 |   NESTED LOOPS              |        |  2498 | 99920 |  5061   (1)| 00:01:01 |
|*  3 |    TABLE ACCESS FULL        | T1     |  2498 | 72442 |    59   (6)| 00:00:01 |
|*  4 |    INDEX RANGE SCAN         | T2_IDX |     1 |       |     1   (0)| 00:00:01 |
--------------------------------------------------------------------------------------
Predicate Information (identified by operation id):
---------------------------------------------------
   3 - filter("T1"."OBJECT_NAME" LIKE '%T1%')
   4 - access("T1"."OBJECT_ID"="T2"."OBJECT_ID")

从执行计划可以看到Oracle优化器评估的成本为5061,远远高于原来的219。
但是实际的逻辑读是多少呢?

统计信息
----------------------------------------------------------
          0  recursive calls
          0  db block gets
        290  consistent gets
          0  physical reads
          0  redo size
       1352  bytes sent via SQL*Net to client
        385  bytes received via SQL*Net from client
          2  SQL*Net roundtrips to/from client
          0  sorts (memory)
          0  sorts (disk)
         29  rows processed

加了HINT之后实际的逻辑读只有290,低于原始SQL的932。所以这里可以看出来,由于Oracle优化器过高地估计了T1表经过like操作过滤返回的行数,也就过高地估计了nest loop的成本,最终也就选择了不是最优的执行计划。

下面我们用Oracle的SQL Tuning Advisor来尝试这条SQL:

SQL> var tuning_task varchar2(100);
SQL> DECLARE
  2    l_sql_id v$session.prev_sql_id%TYPE;
  3    l_tuning_task VARCHAR2(30);
  4  BEGIN
  5    l_sql_id:='4zbqykx89yc8v';
  6    l_tuning_task := dbms_sqltune.create_tuning_task(sql_id => l_sql_id);
  7    :tuning_task:=l_tuning_task;
  8    dbms_sqltune.execute_tuning_task(l_tuning_task);
  9    dbms_output.put_line(l_tuning_task);
 10  END;
 11  /
任务_74

PL/SQL 过程已成功完成。

SQL> print tuning_task;

TUNING_TASK
---------------------------------------------------------------------------------------------------------
任务_74

SQL> SELECT dbms_sqltune.report_tuning_task(:tuning_task) FROM dual;

DBMS_SQLTUNE.REPORT_TUNING_TASK(:TUNING_TASK)
--------------------------------------------------------------------------------
GENERAL INFORMATION SECTION
-------------------------------------------------------------------------------
Tuning Task Name                  : 任务_74
Tuning Task Owner                 : TEST1
Scope                             : COMPREHENSIVE
Time Limit(seconds)               : 1800
Completion Status                 : COMPLETED
Started at                        : 12/15/2010 09:56:02
Completed at                      : 12/15/2010 09:56:03
Number of SQL Profile Findings    : 1

-------------------------------------------------------------------------------
Schema Name: TEST1
SQL ID     : 4zbqykx89yc8v
SQL Text   : select t1.*,t2.owner from t1,t2 where t1.object_name like '%T1%'
             and t1.object_id=t2.object_id

-------------------------------------------------------------------------------
FINDINGS SECTION (1 finding)
-------------------------------------------------------------------------------

1- SQL Profile Finding (see explain plans section below)
--------------------------------------------------------
 为此语句找到了性能

  Recommendation (estimated benefit: 46.62%)
  ------------------------------------------
  -考虑接受推荐的 SQL
    executedbms_sqltune.accept_sql_profile(task_name => '任务_74', replace =
            TRUE);

-------------------------------------------------------------------------------
EXPLAIN PLANS SECTION
-------------------------------------------------------------------------------

1- Original With Adjusted Cost
------------------------------
Plan hash value: 1838229974

---------------------------------------------------------------------------
| Id  | Operation          | Name | Rows  | Bytes | Cost (%CPU)| Time     |
---------------------------------------------------------------------------
|   0 | SELECT STATEMENT   |      |    29 |  1160 |   219   (4)| 00:00:03 |
|*  1 |  HASH JOIN         |      |    29 |  1160 |   219   (4)| 00:00:03 |
|*  2 |   TABLE ACCESS FULL| T1   |    29 |   841 |    59   (6)| 00:00:01 |
|   3 |   TABLE ACCESS FULL| T2   | 49954 |   536K|   159   (2)| 00:00:02 |
---------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------

   1 - access("T1"."OBJECT_ID"="T2"."OBJECT_ID")
   2 - filter("T1"."OBJECT_NAME" LIKE '%T1%')

2- Using SQL Profile
--------------------
Plan hash value: 3787413387

--------------------------------------------------------------------------------------
| Id  | Operation                   | Name   | Rows  | Bytes | Cost (%CPU)| Time     |
--------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT            |        |    29 |  1160 |   117   (3)| 00:00:02 |
|   1 |  TABLE ACCESS BY INDEX ROWID| T2     |     1 |    11 |     2   (0)| 00:00:01 |
|   2 |   NESTED LOOPS              |        |    29 |  1160 |   117   (3)| 00:00:02
 |
|*  3 |    TABLE ACCESS FULL        | T1     |    29 |   841 |    59   (6)| 00:00:01 |
|*  4 |    INDEX RANGE SCAN         | T2_IDX |     1 |       |     1   (0)| 00:00:01 |
--------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------

   3 - filter("T1"."OBJECT_NAME" LIKE '%T1%')
   4 - access("T1"."OBJECT_ID"="T2"."OBJECT_ID")

-------------------------------------------------------------------------------

Read the rest of this entry

,

关于全局索引和本地索引的优缺点,分别应该在什么情况下使用,这方面的资料很多,本文不作讨论。本文讨论一种特殊情况,即建立在分区键之上的本地索引。9i也算是很老的Oracle版本了,只是很多系统包括很多大型的核心的系统都在用,因此本文介绍建立在分区键列上的本地索引存在的问题。下面是一些测试:

SQL> create table t1 ( a int, b varchar2(300)) partition by range(a)
  2  (
  3   partition p01 values less than (1000),
  4   partition p02 values less than (2000),
  5   partition p03 values less than (3000),
  6   partition p04 values less than (4000),
  7   partition p05 values less than (5000),
  8   partition p06 values less than (6000),
  9   partition p07 values less than (7000),
 10   partition p08 values less than (8000),
 11   partition p09 values less than (9000),
 12   partition p10 values less than (10000),
 13   partition p11 values less than (11000),
 14   partition p12 values less than (12000),
 15   partition p13 values less than (13000),
 16   partition p14 values less than (14000),
 17   partition p15 values less than (15000),
 18   partition p16 values less than (16000),
 19   partition p17 values less than (17000),
 20   partition p18 values less than (18000),
 21   partition p19 values less than (19000),
 22   partition p20 values less than (20000)
 23  )
 24  /

表已创建。

SQL> insert into t1 select rownum,lpad('x',200,'x') from dual connect by rownum<20000;

已创建19999行。

SQL> commit;

提交完成。

SQL> insert /*+ append */ into t1 select * from t1;

已创建19999行。

SQL> commit;

提交完成。

SQL> insert /*+ append */ into t1 select * from t1;

已创建39998行。

SQL> commit;

提交完成。

SQL> insert /*+ append */ into t1 select * from t1;

已创建79996行。

SQL> commit;

提交完成。

SQL> insert /*+ append */ into t1 select * from t1;

已创建159992行。

SQL> commit;

提交完成。

SQL> insert /*+ append */ into t1 select * from t1;

已创建319984行。

SQL> commit;

提交完成。

首先建立一个测试范围分区表,分区键列是"a",共20个分区,在这个测试表中生成约64万行数据。下面在列a上建本地索引并收集统计信息:

SQL> create index t1_idx on t1(a) local;

索引已创建。

SQL> exec dbms_stats.gather_table_stats(user,'T1',
    method_opt=>'for all columns size 1',cascade=>true);

PL/SQL 过程已成功完成。
SQL> @sosi

Please enter Name of Table Owner (Null = TEST):
Please enter Table Name to show Statistics for: t1

***********
Table Level
***********


Table                   Number                 Empty
Name                   of Rows   Blocks       Blocks
--------------- -------------- -------- ------------
T1                     639,968   18,880            0

Column                    Column                       Distinct            Number       Number
Name                      Details                        Values   Density Buckets        Nulls
------------------------- ------------------------ ------------ --------- ------- ------------
A                         NUMBER(22)                     19,999   .000050       1            0
B                         VARCHAR2(300)                       1  1.000000       1            0

                              B
Index                      Tree     Leaf       Distinct         Number      Cluster
Name            Unique    Level     Blks           Keys        of Rows       Factor
--------------- --------- ----- -------- -------------- -------------- ------------
T1_IDX          NONUNIQUE     1    1,390         19,999        639,968      639,968

Index           Column                     Col Column
Name            Name                       Pos Details
--------------- ------------------------- ---- ------------------------
T1_IDX          A                            1 NUMBER(22)

***************
Partition Level
***************

  Part Partition               Number                 Empty
   Pos Name                   of Rows   Blocks       Blocks
------ --------------- -------------- -------- ------------
     1 P01                     31,968      944            0
     2 P02                     32,000      944            0
     3 P03                     32,000      944            0
     4 P04                     32,000      944            0
     5 P05                     32,000      944            0
     6 P06                     32,000      944            0
     7 P07                     32,000      944            0
     8 P08                     32,000      944            0
     9 P09                     32,000      944            0
    10 P10                     32,000      944            0
    11 P11                     32,000      944            0
    12 P12                     32,000      944            0
    13 P13                     32,000      944            0
    14 P14                     32,000      944            0
    15 P15                     32,000      944            0
    16 P16                     32,000      944            0
    17 P17                     32,000      944            0
    18 P18                     32,000      944            0
    19 P19                     32,000      944            0
    20 P20                     32,000      944            0
                                    B
Index           Partition        Tree     Leaf       Distinct         Number
Name            Name            Level     Blks           Keys        of Rows
--------------- --------------- ----- -------- -------------- --------------
T1_IDX          P01                 1       67            999         31,968
T1_IDX          P02                 1       67          1,000         32,000
T1_IDX          P03                 1       67          1,000         32,000
T1_IDX          P04                 1       67          1,000         32,000
T1_IDX          P05                 1       67          1,000         32,000
T1_IDX          P06                 1       67          1,000         32,000
T1_IDX          P07                 1       67          1,000         32,000
T1_IDX          P08                 1       67          1,000         32,000
T1_IDX          P09                 1       67          1,000         32,000
T1_IDX          P10                 1       67          1,000         32,000
T1_IDX          P11                 1       72          1,000         32,000
T1_IDX          P12                 1       72          1,000         32,000
T1_IDX          P13                 1       72          1,000         32,000
T1_IDX          P14                 1       72          1,000         32,000
T1_IDX          P15                 1       72          1,000         32,000
T1_IDX          P16                 1       72          1,000         32,000
T1_IDX          P17                 1       72          1,000         32,000
T1_IDX          P18                 1       72          1,000         32,000
T1_IDX          P19                 1       72          1,000         32,000
T1_IDX          P20                 1       72          1,000         32,000

下面执行查询:

Read the rest of this entry

,

有客户遇到SQL性能不稳定,突然变差导致系统性能出现严重问题的情况。对于大型的系统来说,SQL性能不稳定,有时突然变差,这是常常遇到的问题。这也是一些DBA的挑战。

对于使用Oracle数据库的应用系统,有时会出现运行得好好的SQL,性能突然变差。特别是对于OLTP类型系统执行频繁的核心SQL,如果出现性能问题,通常会影响整个数据库的性能,进而影响整个系统的正常运行。对于个别的SQL,比如较少使用的查询报表之类的SQL,如果出现问题,通常只影响少部分功能模块,而不会影响整个系统。

那么应该怎么样保持SQL性能的稳定性?

SQL的性能变差,通常是在SQL语句重新进行了解析,解析时使用了错误的执行计划出现的。下列情况是SQL会重新解析的原因:

  • 1. SQL语句没有使用绑定变量,这样SQL每次执行都要解析。
  • 2. SQL长时间没有执行,被刷出SHARED POOL,再次执行时需要重新解析。
  • 3. 在SQL引用的对象(表、视图等)上执行了DDL操作,甚至是结构发生了变化,比如建了一个索引。
  • 4. 对SQL引用的对象进行了权限更改。
  • 5. 重新分析(收集统计信息)了SQL引用的表和索引,或者表和索引统计信息被删除。
  • 6. 修改了与性能相关的部分参数。
  • 7. 刷新了共享池。
  • 8. 当然重启数据库也会使所有SQL全部重新解析。

SQL重新解析后,跟以前相比,性能突然变差,通常是下列原因:

  • 1. 表和索引的优化统计信息被删除,或者重新收集后统计信息不准确。重新收集统计信息通常是由于收集策略(方法)不正确引起。比如对分区表使用analyze命令而不是用dbms_stats包、收集统计信息时采样比例过小等等。Oracle优化器严重依赖于统计信息,如果统计信息有问题,则很容易导致SQL不能使用正确的执行计划。
  • 2. SQL绑定变量窥探(bind peeking),同时绑定变量对应的列上有直方图;或者绑定变量的值变化范围过大、分区数据分布极不均匀:
    • 1) 绑定变量的列上有直方图:
      假如表orders存储所有的订单,state列有3种不同的值:0表示未处理,1表示处理成功完成,2表示处理失败。State列上有一个索引,表中绝大部分数据的state列为1,0和2占少数。有下面的SQL:

      select * from orders where state=:b1
      

      这里:b1是变量,在大多数情况下这个值为0,则应该使用索引,但是如果SQL被重新解析,而第一次执行时应用传给变量b1值为1,则不会使用索引,采用全表扫描的方式来访问表。对于绑定变量的SQL,只在第一次执行时才会进行绑定变量窥探,并以此确定执行计划,该SQL后续执行时全部按这个执行计划。这样在后续执行时,b1变量传入的值为0的时候,仍然是第一次执行时产生的执行计划,即使用的是全表扫描,这样会导致性能很差。

    • 2) 绑定变量的值变化范围过大:
      同样假如orders表有一列created_date表示一笔订单的下单时间,orders表里面存储了最近1年的数据,有如下的SQL:

      Select * from orders where created_date >=:b1;
      

      假如大多数情况下,应用传入的b1变量值为最近几天内的日期值,那么SQL使用的是created_date列上的索引,而如果b1变量值为5个月之前的一个值,那么就会使用全表扫描。与上面描述的直方图引起的问题一样,如果SQL第1次执行时传入的变量值引起的是全表扫描,那么将该SQL后续执行时都使用了全表扫描,从而影响了性能。

    • 3) 分区数据量不均匀:
      对于范围和列表分区,可能存在各个分区之间数据量极不均匀的情况下。比如分区表orders按地区area进行了分区,P1分区只有几千行,而P2分区有200万行数据。同时假如有一列product_id,其上有一个本地分区索引,有如下的SQL:

      select * from orders where area=:b1 and product_id =:b2
      

      这条SQL由于有area条件,因此会使用分区排除。如果第1 次执行时应用传给b1变量的值正好落在P1分区上,很可能导致SQL采用全表扫描访问,如前面所描述的,导致SQL后续执行时全部使用了全表扫描。

  • 3. 其他原因,比如表做了类似于MOVE操作之后,索引不可用,对索引进行了更改。当然这种情况是属于维护不当引起的问题,不在本文讨论的范围。

综上所述,SQL语句性能突然变差,主要是因为绑定变量和统计信息的原因。注意这里只讨论了突然变差的情况,而对于由于数据量和业务量的增加性能逐步变差的情况不讨论。
为保持SQL性能或者说是执行计划的稳定性,需要从以下几个方面着手:

  • 1. 规划好优化统计信息的收集策略。对于Oracle 10g来说,默认的策略能够满足大部分需求,但是默认的收集策略会过多地收集列上的直方图。由于绑定变量与直方图固有的矛盾,为保持性能稳定,对使用绑定变量的列,不收集列上的直方图;对的确需要收集直方图的列,在SQL中该列上的条件就不要用绑定变量。统计信息收集策略,可以考虑对大部分表,使用系统默认的收集策略,而对于有问题的,可以用DBMS_STATS.LOCK_STATS锁定表的统计信息,避免系统自动收集该表的统计信息,然后编写脚本来定制地收集表的统计信息。脚本中类似如下:

    exec dbms_stats.unlock_table_stats…
    exec dbms_stats.gather_table_stats…
    exec dbms_stats.lock_table_stats…
    
  • 2. 修改SQL语句,使用HINT,使SQL语句按HINT指定的执行计划进行执行。这需要修改应用,同时需要逐条SQL语句进行,加上测试和发布,时间较长,成本较高,风险也较大。
  • 3. 修改隐含参数” _optim_peek_user_binds”为FALSE,修改这个参数可能会引起性能问题(这里讨论的是稳定性问题)。
  • 4. 使用OUTLINE。对于曾经出现过执行计划突然变差的SQL语句,可以使用OUTLINE来加固其执行计划。在10g中DBMS_OUTLN.CREATE_OUTLINE可以根据已有的执行正常的SQL游标来创建OUTLINE。如果事先对所有频繁执行的核心SQL使用OUTLINE加固执行计划,将最大可能地避免SQL语句性能突然变差。
    注:DBMS_OUTLN可以通过$ORACLE_HOME/rdbms/admin/dbmsol.sql脚本来安装。
  • 5. 使用SQL Profile。SQL Profile是Oracle 10g之后的新功能,此处不再介绍,请参考相应的文档。

除此之外,可以调整一些参数避免潜在的问题,比如将"_btree_bitmap_plans"参数设置为FALSE(这个参数请参考互联网上的文章或Oracle文档)。

而在实际工作中,通过使用定制的统计信息收集策略,以及在部分系统上使用OUTLINE,系统基本上不会出现已有的SQL性能突然变差的情况。当然也有维护人员操作不当引起的SQL性能突然变差,比如建了某个索引而没有收集统计信息,导致SQL使用了新建的索引,而该索引并不适合于那条SQL;维护人员意外删除了表个索引的统计信息。

,

一条看上去很简单的SQL:

SELECT * FROM V_CALL_EVENT_10906 
WHERE to_char(start_date, 'yyyymmdd') in ('20090620', '20090621', '20090622') 

执行时长比较长,以至于出现ORA-01555错误,由于返回的结果数据行数非常大,取1月之内3天的数据,不太适合于使用索引,同时应用结构上决定了,也不能按天分区。

这里如果我们能够把表访问从6次,改为1次,那么性能就能大幅提升,这里修改视图的定义如下:

V_CALL_EVENT_10906视图定义如下:

CREATE VIEW V_CALL_EVENT_10906 
AS
SELECT ACCT_ID1 ACCT_ID,
               SERV_ID,
               EVENT_TYPE_ID,
               ACCT_ITEM_TYPE_ID1 ACCT_ITEM_TYPE_ID,
               CALLING_AREA_CODE,
               CALLING_NBR,
               CALLED_AREA_CODE,
               CALLED_NBR,
               START_DATE,
               START_DATE + DURATION / 3600 / 24 END_DATE,
               DURATION,
               CHARGE1 CHARGE,
               BILLING_CYCLE_ID,
               TO_DATE(CREATED_DATE) CREATED_DATE,
               TO_DATE(START_DATE) DATA_DATE,
               RESERVED_FIELD1,
               1 SPLIT_ID
 FROM CALL_EVENT_10906
union all
SELECT ACCT_ID1 ACCT_ID,
               SERV_ID,
               EVENT_TYPE_ID,
               ACCT_ITEM_TYPE_ID2 ACCT_ITEM_TYPE_ID,
               CALLING_AREA_CODE,
               CALLING_NBR,
               CALLED_AREA_CODE,
               CALLED_NBR,
               START_DATE,
               START_DATE + DURATION / 3600 / 24 END_DATE,
               DURATION,
               CHARGE2 CHARGE,
               BILLING_CYCLE_ID,
               TO_DATE(CREATED_DATE) CREATED_DATE,
               TO_DATE(START_DATE) DATA_DATE,
               RESERVED_FIELD1,
               2 SPLIT_ID
 FROM CALL_EVENT_10906
WHERE ACCT_ITEM_TYPE_ID2 != 0
  AND ACCT_ITEM_TYPE_ID2 IS NOT NULL

为节省篇幅,这个视图的定义实际上没有完全列出,视图中实际有5个“UNION ALL”,也就是CALL_EVENT_10906实际访问了6次。

CREATE VIEW V_CALL_EVENT_10906 
AS 
select /*+ no_merge(v) no_push_pred(v) */
v.* FROM 
(SELECT /*+   parallel(a,4) */
          ACCT_ID1 ACCT_ID,
                   SERV_ID,
                   EVENT_TYPE_ID,
                   DECODE(B.SPLIT_ID, 1, ACCT_ITEM_TYPE_ID1, 2, ACCT_ITEM_TYPE_ID2, 3, ACCT_ITEM_TYPE_ID3,   4, ACCT_ITEM_TYPE_ID4, 5, ACCT_ITEM_TYPE_ID5, 6,ACCT_ITEM_TYPE_ID6,0) ACCT_ITEM_TYPE_ID,
                   CALLING_AREA_CODE,
                   CALLING_NBR,
                   CALLED_AREA_CODE,
                   CALLED_NBR,
                   START_DATE,
                   START_DATE + DURATION / 3600 / 24 END_DATE,
                   DURATION,
                   DECODE(B.SPLIT_ID, 1, CHARGE1, 2, CHARGE2, 3, CHARGE3, 4, CHARGE4, 5, CHARGE5, 6,CHARGE6,0) CHARGE,
                   BILLING_CYCLE_ID,
                   TO_DATE(CREATED_DATE) CREATED_DATE,
                   TO_DATE(START_DATE) DATA_DATE,
                   RESERVED_FIELD1,
                   B.SPLIT_ID SPLIT_ID
           FROM CALL_EVENT_10906812 A,
                                   (
                  SELECT 1 SPLIT_ID
                    FROM DUAL
                  UNION ALL
                  SELECT 2
                    FROM DUAL  
                  UNION ALL  
                  SELECT 3
                    FROM DUAL
                  UNION ALL  
                  SELECT 4
                    FROM DUAL
                  UNION ALL  
                  SELECT 5
                    FROM DUAL
                  UNION ALL  
                  SELECT 6 FROM DUAL) B
) v,(select /*+ no_merge */ 0 id from dual) K
where nvl(v.acct_item_type_id,0) !=k.id;

通过UNION DUAL表,得到6行结果,同时与CALL_EVENT_10906表之间没有任何关联条件,这样就会形成笛卡尔连接(cartesian join),CALL_EVENT_10906这个表的每一行数据,将实际产生6行输出。这样就避免了对这个表扫描6次。

为什么这里还要嵌套一层,再加上这样的条件:

where nvl(v.acct_item_type_id,0) !=k.id

这个条件实际上是:

where nvl(v.acct_item_type_id,0) !=0

如果不嵌套一层,那么就会形成CALL_EVENT_10906与DUAL表UNION之后的结果之后的连接关系,就不会使用cartesian join了。

,

我们经常使用Sql Trace和10046 event来诊断Oracle数据库性能问题。而level超过1的10046事件通常称为extended sql trace,通常用于诊断确定的单个SQL、存储过程或会话的性能问题,具有如下的几个优点:

  • 可以得到SQL执行时实际的执行计划。
  • 可以得到SQL执行时所花时间的具体分布,CPU消耗了多长时间,多块读消耗了多长时间等等。
  • 可以得到SQL执行时的各种与性能相关的统计数据,逻辑读、物理读、fetch次数、parse次数等等。
  • 不仅能够用于性能测试,同时能够用于诊断正在执行的SQL或存储过程的性能。
  • 有很多的工具用于格式化生成的trace文件,除了Oracle自带的TKPROF、Metalink Note 224270.1 Trace Analyzer,以及第三方的免费工具如orasrp,《Troubleshooting Oracle Performance》作者开发的TVD$XTAT,甚至还有商业化的软件Hotsos Profiler等。

不过前段时间在用10046事件诊断一个性能问题的时候,却让生成的结果误导了。后来仔细检查发现,在会话开启sql trace的情况下,SQL语句会重新解析,导致开启sql trace之后与开启之前相比,执行计划可能发生了变化,导致sql trace的结果不能真实地反映会话执行SQL的情况,在分析时容易发生偏差。

下面是一个测试:

测试的环境是Oracle 10.2.0.1 for Windows,不过前面提到的案例,是发生在Oracle 9i下的,所以9i和10g都有这个问题,而11g目前还没有测试过,有兴趣的朋友可以在11g上进行测试。

首先创建一个sql文件,内容为:

select /*+ testsql */ sum(value) from t1 where flag=:v_flag;

创建一个列上数据有倾斜的表:
SQL> create table t1 (value number ,flag number,pad varchar2(2000));

表已创建。

SQL> insert into t1 select rownum,mod(rownum,2000),lpad('x',1000,'x') from dba_objects;

已创建49796行。

SQL> commit;

提交完成。

SQL> insert into t1 select rownum,3000,lpad('x',1000,'x') from dba_objects where rownum<=10000;

已创建10000行。

SQL> commit;

提交完成。

SQL> create index t1_idx on t1(flag);

索引已创建。

SQL> exec dbms_stats.gather_table_stats(ownname=>user,tabname=>'T1',cascade=>true,method_opt=>'for all indexed columns');

PL/SQL 过程已成功完成。
SQL> select column_name,num_distinct,num_buckets from user_tab_columns where table_name='T1';

COLUMN_NAME                    NUM_DISTINCT NUM_BUCKETS
------------------------------ ------------ -----------
VALUE                                                  
FLAG                                   2030          75
PAD         

在创建的测试表中,FLAG列有2001个不同的值,其中,0-1999之间每个值约为25个,而有一个特殊的值3000,有10000个。收集统计信息时,在FLAG列上收集了直方图。

下面运行test.sql:

SQL> var v_flag number;                             
SQL> exec :v_flag:=3000; 
SQL> set autot on stat
SQL> @test
                                                       
SUM(VALUE)
----------
  50005000
统计信息
-------------------------------------------------------
          0  recursive calls
          0  db block gets
       8575  consistent gets
          0  physical reads
          0  redo size
        412  bytes sent via SQL*Net to client
        384  bytes received via SQL*Net from client
          2  SQL*Net roundtrips to/from client
          0  sorts (memory)
          0  sorts (disk)
          1  rows processed

我们来看看SQL的执行计划:

Read the rest of this entry

,