2014年5月8日,是一个重要的日子。一个省级电信运营商,将核心的CRM系统Oracle数据库进行了升级迁移,成功地从原来运行在IBM 595平台上的双节点10.2.0.5 RAC数据库,迁移并升级到基于x86+vmware平台的双节点11.2.0.3 RAC数据库上。新平台的服务器成本只有原小型机成本的十分之一。我个人认为是这是一个里程碑式的事件,这标志着,不远的将来,以IBM p系列为代表的小型机将退出电信运营商的舞台,而以x86平台为核心的私有云平台将占主导地位。

在这篇文章中,我分享一个小小的主题,那就是关于数据库迁移升级后的统计信息收集策略问题。

在Oracle数据库的世界里,统计信息显得是那么重要,所以在升级系统时,我们考虑的一个重要问题是,在新的系统上采用何种统计信息收集策略,或者至少要保证上线的时候不能因为统计信息问题而导致系统性能异常。

这套CRM系统在2010年之前运行在Oracle 9i之上,那时采用手工手集统计信息的方式,每个月在固定的日期收集2-3次统计信息。在我接触到这套系统之前,系统隔段时间总会遇到收集统计信息后某些SQL性能变差影响业务的问题。后来我与这套系统的DBA商量,对手工要收集统计信息的表进行了梳理,去掉可能会引起问题的直方图,对某些表上的某些列必须收集直方图,最后将dbms_stats.gather_table_stats中的method_opt参数改为for all column size repeat,之后基本上再没出现过统计信息变更导致性能的问题。

2010新数据库随应用的升级同时升级到了10.2.0.5版本。开始仍然是用一张表一张表的方式收集统计信息,再后来,随时时间和应用的演变,统计信息的收集也发生了变化。但仍然是手工收集的方式,而没有开启统计信息自动收集。

此次升级到11.2.0.3,我们将面临两个问题:

  1. 在新系统上线之时如何保证统计信息正确,以确保系统上线成功?
  2. 新系统上线之后,统计信息的收集策略应该是怎么样的?

其实这两个问题可以合成一个问题,因为第一个问题的答案决定了后一个问题。对于第一个问题,有两种可能的处理办法:

  1. 迁移时将原数据库的统计信息迁移过来
  2. 在新数据库上自动收集统计信息

或许有的人会毫不犹豫地选择第一种方法,但是我们认为这种方法有很明显的缺点:

  1. 11gR2版本在优化器方面与10gR2版本相比,多少有些变化,这不一定能保证此种统计信息的收集方法使得新系统的SQL的执行计划就是合理的。
  2. 如果用这种方法,那么在上线后启用自动统计信息的收集将会面临风险,因为没有测试验证过。那么此后只能采用手动统计信息的方式。

基于大量11gR2数据库采用自动统计信息的现状、11gR2在CBO以及自动收集统计信息上的不断完善,我们决定在此次新系统上线时以及上线后,采用“自动收集统计信息”的策略。为了保证这个策略是可行的,SPA(SQL Performance Analyzer)就派上了用场。我们使用原生产库的月初、月中、月末三个不同时间段的shared pool的所有SQL,以及一个月内的AWR中的所有SQL,进行SPA测试。而对于新数据库的统计信息,我们使用了最简单的命令来收集统计信息:dbms_stats.gather_database_stats(options=>'gather auto'); 这条命令与数据库自带的自动收集统计信息的任务是基本一致的,也是”增量“收集统计信息的方式,只收集统计信息缺失或陈旧的表和索引的统计信息,唯一的区别是自动任务是有时间窗口的,而手工执行时没有时间窗口而已。

在用这样的方式收集统计信息后,我们使用SPA测试了数万条SQL语句,再用几十个SQL PROFILE固化了可能存在风险的SQL,这样系统就顺利上线了。

不过这种统计信息收集的方式还有一个关键点,那就是直方图。由于跨平台迁移,对于停机时间要求很严格的系统来说,毫无疑问是使用增量同步数据的方式来迁移数据。如果在上线之前用上述的命令来收集统计信息,那直方图一定是有问题的,或许你会发现,表上几乎没有直方图。这个问题是什么产生的?其实这个问题在文档中已经有提及,那就是自动收集统计信息实际上是参考col_usage$来决定是否要在列上收集直方图。Oracle在硬解析SQL语句时,会记录where后面列的使用,是相等比较,或是范围比较,或者是否有相等连接等等。对于全新的数据库,col_usage$是没有数据或是严重不完整的,所以,用刚才提到的命令或自动收集的统计信息就没有直方图了。解决这个问题的办法就是,在上线之前,使用SPA测试足够多的SQL语句,让col_usage$有足够的数据,这样问题就解决了。

在Oracle数据库中,SQL解析有几种:

  • 硬解析,过多的硬解析在系统中产生shared pool latch和library cache liatch争用,消耗过多的shared pool,使得系统不具有可伸缩性。
  • 软解析,过多的软解析仍然可能会导致系统问题,特别是如果有少量的SQL高并发地进行软解析,会产生library cache latch或者是share方式的mutex争用。
  • 软软解析,其实这也也属于软解析,与普通的软解析不同的是,软软解析的SQL会在会话的cached cursor中命中。
  • 一次解析,多次执行,这是解析次数最少的方式,也是系统最具有可扩展性的方式。

那么在JAVA开发的应用中,怎么样才能实现上述第4种方式?如果是循环处理某种数据,这个比较容易实现。其实对于不是这种情况,Oracle也提供了很好的方式来实现这一点。下面是一个例子(例子代码文件为TestStmtCache.java)。

import java.sql.*;
import oracle.jdbc.driver.OracleConnection;

public class TestStmtCache {
    public static Connection getConnection() throws Exception {
        String driver = "oracle.jdbc.driver.OracleDriver";
        String url = "jdbc:oracle:thin:@localhost:1521:xj11g";
        Class.forName(driver);
        return DriverManager.getConnection(url, "test", "test");
    }

    public static void main(String args[]) {
        Connection conn = null;
        try {
            conn = getConnection();
            conn.setAutoCommit(false);
            ((OracleConnection)conn).setStatementCacheSize(0);
            for (int i=0; i <200; i++) {
                testNoCache(conn);
            }
            ((OracleConnection)conn).setStatementCacheSize(20);
            ((OracleConnection)conn).setImplicitCachingEnabled(true);

            for (int i=0; i <200; i++) {
                testCache(conn);
            }
        } catch (Exception e) {
            e.printStackTrace();
        } finally {
            try {
                conn.close();
            } catch (SQLException e) {
                e.printStackTrace();
            }
        }
    }
    public static void testCache(Connection conn) {
        PreparedStatement pstmt = null;
        try {
            pstmt = conn.prepareStatement("select /*cache_test1 */ * from t1 where rownum<=1");
            pstmt.execute();
        } catch (Exception e) {
            e.printStackTrace();
        } finally {
            try {
                pstmt.close();
            } catch (SQLException e) {
                e.printStackTrace();
            }
        }
    }

    public static void testNoCache(Connection conn) {
        PreparedStatement pstmt = null;
        try {
            pstmt = conn.prepareStatement("select /*nocache_test1 */ * from t1 where rownum<=1");
            pstmt.execute();
        } catch (Exception e) {
            e.printStackTrace();
        } finally {
            try {
                pstmt.close();
            } catch (SQLException e) {
                e.printStackTrace();
            }
        }
    }
}

编译上述代码文件TestStmtCache.java,并运行:

E:\JavaCode>set CLASSPATH=.;ojdbc14.jar

E:\JavaCode>d:\works\Java\jdk1.5.0_21\bin\javac TestStmtCache.java

E:\JavaCode>d:\works\Java\jdk1.5.0_21\jre\bin\java TestStmtCache

在数据库中进行查询:

SYS@xj11g> select sql_id,parse_calls,executions,sql_text from v$sqlarea where sql_text like '%cache_test%' and sql_text not like '%v$%';

SQL_ID        PARSE_CALLS  EXECUTIONS SQL_TEXT
------------- ----------- ----------- ------------------------------------------------------------
3nbu9qp40ptjk         200         200 select /*nocache_test1 */ * from t1 where rownum< =1
47hja0fwmmb6c           1         200 select /*cache_test1 */ * from t1 where rownum<=1

可以看到,这两条SQL语句,都执行了200次,但是标记为"nocache_test1"的SQL没有进行语句缓存,其parse calls为200次,即解析了200次,其中一次是硬解析。而标记为"cache_test1"的SQL语句,使用了语句缓存,但是parse calls只有1次,即只有一次硬解析,执行了200次。这里关键的代码在于:

            ((OracleConnection)conn).setStatementCacheSize(20);
            ((OracleConnection)conn).setImplicitCachingEnabled(true);

上述第一行代码设置语句缓存大小,当然20比较偏小,对于比较大型的系统来说,设到200-300比较合适,不过这会耗用一定数量的JAVA内存。这个数值表示一个连接能够缓存多少语句。第二行代码是设置隐式打开语句缓存,也即自动会对PreparedStatement的SQL语句进行缓存。

那么,上述的方式无疑是比较简单的,但是这种方式有一个问题就是,缓存的利用效率可能不高,因为JAVA会将不常用的SQL语句也进行了缓存。Oracle的JDBC驱动也提供了一种手工控制的方式:
将测试代码中的第22行替换为:

((OracleConnection)conn).setExplicitCachingEnabled(true);

第40行替换为:

pstmt = ((OracleConnection)conn).getStatementWithKey ("cache_test1");
if (pstmt==null)

第46行替换为:

((OraclePreparedStatement)pstmt).closeWithKey ("cache_test1");

这样通过手工编码的方式控制哪些语句需要缓存,哪些不需要。
关于语句缓存(Statement Caching)可以参考Oracle在线文档:Statement and Result Set Caching

《ORA-1555错误解决一例》一文中,当时尝试模拟UNDO段头事务表被覆盖的情况下出现ORA-01555错误,没有成功。实际上没有成功的原因是事务数虽然多,但是事务过小,使UNDO块没有被覆盖完,这样通过回滚事务表仍然能够得到事务表以前的数据。本文进一步讨论一些有关延迟块清除和一致性读方面的内容(但不会涉及到延迟块清除和一致性读的具体概念和过程,只是一些有趣的东西)。

先来看看一个数据块中ITL的转储:

Block header dump:  0x0200410a
 Object id on Block? Y
 seg/obj: 0x5f07  csc: 0xb08.1303a672  itc: 3  flg: -  typ: 1 - DATA
     fsl: 0  fnx: 0x0 ver: 0x01
 
 Itl           Xid                  Uba         Flag  Lck        Scn/Fsc
0x01   0x0001.025.0000472d  0x00000000.0000.00  C---    0  scn 0x0b08.12f461da
0x02   0x0007.015.00004ba0  0x0080d9a0.16f7.39  C-U-    0  scn 0x0b08.12fb5cae
0x03   0x0000.000.00000000  0x00000000.0000.00  ----    0  fsc 0x0000.00000000

我们看看ITL中的第2个条目,其Flag为"C-U-",C表示commit(提交),U表示Upper bound(上限),这里”U“表明ITL中记录的事务的提交SCN并不是精确的,只是表明事务提交的精确SCN是在ITL中记录的SCN之前,对于第2条ITL来说,其事务提交SCN小于或等于”0x0b08.12fb5cae“。那么这里的问题是:Upper bound是在什么情况下出现的?如果一个SQL语句对该块进行一致性读时,发现ITL中的Upper bound的SCN比一致性读需要的SCN大,这时会发生什么?要回答这些问题,先来看下面的一系列测试过程:

1. 在会话1中建测试表t1,将插入500行数据,每个块只有1行数据,一共500个块,然后再创建一个较大的测试表t2,插入1000行数据:

SQL> @mysid

       SID
----------
       160

SQL> create table t1 ( id number, small_vc varchar2(20),padding varchar2(1000)) pctfree 90 pctused 10;

表已创建。

SQL> insert /*+ append */ into t1
  2  select rownum,rownum || lpad('0',10,'0'),lpad('0',1000,'0')
  3  from dba_objects
  4  where rownum< =500;

已创建500行。

SQL>
SQL> commit;

提交完成。

SQL> create table t2 (id number,vc varchar2(20),padding varchar2(1000)) pctfree 90 pctused 10;

表已创建。

SQL> insert /*+ append */ into t2
  2  select rownum,lpad(rownum,20,'0'),lpad(rownum,1000,'0')
  3  from dba_objects
  4  where rownum<=1000;

已创建1000行。

SQL> commit;

提交完成。

SQL> select dbms_rowid.rowid_relative_fno(rowid),dbms_rowid.rowid_block_number(rowid)
  2  from t1
  3  where rownum<=5;

DBMS_ROWID.ROWID_RELATIVE_FNO(ROWID) DBMS_ROWID.ROWID_BLOCK_NUMBER(ROWID)
------------------------------------ ------------------------------------
                                   8                                16650
                                   8                                16651
                                   8                                16652
                                   8                                16653
                                   8                                16654

2. 在会话1中更新测试表T1中的所有行,并获取事务ID,然后再dump1个数据块和事务对应的UNDO段头块

SQL> update t1 set padding=lower(padding);

已更新500行。

SQL> select xidusn,xidslot,xidsqn,to_char(start_scnw,'xxxxxxxx') start_scnw,
  2  to_char(start_scnb,'xxxxxxxx') start_scnb,
  3  start_scnb+start_scnw*power(2,32) start_scn from v$transaction;

    XIDUSN    XIDSLOT     XIDSQN START_SCN START_SCN         START_SCN
---------- ---------- ---------- --------- --------- -----------------
         7         21      19360       b08  12f461db    12129305649627

SQL> select file_id,block_id from dba_rollback_segs where segment_name='_SYSSMU7$';

   FILE_ID   BLOCK_ID
---------- ----------
         2        105

SQL> alter system dump datafile 8 block 16650;

系统已更改。

SQL> alter system dump datafile 2 block 105;

系统已更改。

事务使用的事务表在回滚段_SYSSMU7$上,即第7个回滚段。事务表中的条目为21,即事务表中的第21条记录。

数据块dump出来的结果是(去掉了对本文话题无关紧要的内容,以后也是如此):


*** 2012-05-26 11:14:38.439
Start dump data blocks tsn: 8 file#: 8 minblk 16650 maxblk 16650
buffer tsn: 8 rdba: 0x0200410a (8/16650)
scn: 0x0b08.12f461f5 seq: 0x01 flg: 0x00 tail: 0x61f50601
frmt: 0x02 chkval: 0x0000 type: 0x06=trans data
Hex dump of block: st=0, typ_found=1

Block header dump:  0x0200410a
 Object id on Block? Y
 seg/obj: 0x5f07  csc: 0xb08.12f461ce  itc: 3  flg: -  typ: 1 - DATA
     fsl: 0  fnx: 0x0 ver: 0x01
 
 Itl           Xid                  Uba         Flag  Lck        Scn/Fsc
0x01   0x0001.025.0000472d  0x00000000.0000.00  ----    0  fsc 0x0000.00000000
0x02   0x0007.015.00004ba0  0x0080d9a0.16f7.39  ----    1  fsc 0x0000.00000000
0x03   0x0000.000.00000000  0x00000000.0000.00  ----    0  fsc 0x0000.00000000

可以看到ITL中的第2条正是当前活动事务在这个块上所使用的ITL。Xid为“0x0007.015.00004ba0”,转换成10进制正是“7.21.19360”,这跟之前查询出来的事务ID是一致的。ITL中此时的flag为"----",正是活动事务的标志。由于块中只有1行数据,因此Lck为1,即该事务在这个块中锁住的行数为1行。

下面再来看看此时UNDO段头块的转储结果:

Read the rest of this entry

,

开发人员在进行新系统上线前的数据校验测试时,发现一条手工执行的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类型的系统上,尽量避免大事务。

客户新上线的一套重要生产系统,某个存储过程每小时调用约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

提起Oracle数据库的Hint,几乎每一个DBA都知道这一强大工具。在Oracle中,Hint可以用来改变SQL的执行计划、固定SQL的执行计划。Oracle数据库内部的很多特性也依赖于Hint,比如Outline、Profile等。

但是在日常工作中,很多开发人员或DBA,对Hint的使用仍然存在一些错误的方式。下面将列举主要的2种。(本文不讨论Hint的滥用即过度使用问题)。

1. NOLOGGING的不正确使用。

很多人知道,在进行数据处理时,如果不产生日志或只产生少量的日志,将会有明显的、甚至是巨大的效率提升。下面有几条不同的SQL:

INSERT INTO T1 NOLOGGING;
INSERT INTO T1 SELECT * FROM T2 NOLOGGING;
INSERT /*+ NOLOGGING */ INTO T1 VALUES ('0');
INSERT /*+ NOLOGGING */ INTO T1 SELECT * FROM T2;
DELETE /*+ NOLOGGING */ FROM T1;
UPDATE /*+ NOLOGGING */ T1 SET A='1';

实际上,上述所有的SQL没有一个能够实现“不产生”日志的数据更改操作。第1-2条SQL语句虽然没有将NOLOGGING写为Hint的形式,但是也是很多人的错误写法,一并列在此处。事实上,NOLOGGING并不是Oracle的一个有效的Hint,而是一个SQL关键字,通常用于DDL语句中。这里NOLOGGING相当于给SELECT的表指定了一个别名为“NOLOGGING”。下面是NOLOGGING的一些正确用法:

CREATE TABLE T1 NOLOGGING AS SELECT * FROM T2;
CREATE INDEX T1_IDX ON T1(A) NOLOGGING;
ALTER INDEX T1_IDX REDUILD ONLINE NOLOGGING;
ALTER TABLE T1 NOLOGGING;

上述SQL中,最后一条SQL只是将表的LOGGING属性改为"NO"。而之前的几条SQL能够有效地减少DDL操作时减少的日志量。

在DML操作中,只有下面一种方式能够在大数据量时仍然只会产生极少量的日志:

INSERT /*+ APPEND */ INTO T1 SELECT * FROM T2;

也就是使用append hint。但是这个hint要达到目的,需要以下几个条件:

  • 使用INSERT /*+ APPEND */ INTO .. SELECT .. FROM形式的INSERT SQL。
  • 如果是在归档模式下,需要将表的LOGGING属性置为NO。
  • 表空间或数据库的FORCE LOGGING属性为NO。注意在非归档模式下也是可以设置FORCE LOGGING的。

这里提到的insert语句中的append hint,对于索引,仍然会产生日志,也就是说append hint对索引是没有效果的。
另外,DDL中使用的nologging关键字和inset语句中使用的append hint,并不是说完全不产生日志,只是对表的数据块的数据部分的更改不会有日志产生,但是SQL执行过程中数据字典的更改、空间分配等递归SQL、段头和位图块的更改、将数据块标记为unrecoverable等仍然会产生少量日志。

2. Hint的不正确写法。

这是一个比较不容易发现的问题。下面几条SQL,哪一条SQL的append hint会生效:

1. INSERT /*+ append,parallel(t1) */ INTO T1 SELECT * FROM T2;
2. INSERT /*+ parallel(t1), append */ INTO T1 SELECT * FROM T2;
3. INSERT /*+ this is append */ INTO T1 SELECT * FROM T2;
4. INSERT /*+ this append */ INTO T1 SELECT * FROM T2;

要回答这个问题,请先看下面的测试(测试环境:10.2.0.1 for Windows):

SQL> INSERT /*+ append,parallel(t1) */ INTO T1 SELECT * FROM T2;
已创建55640行。
统计信息
----------------------------------------------------------
      12304  redo size
SQL> COMMIT;

SQL> INSERT /*+ parallel(t1), append */ INTO T1 SELECT * FROM T2;
已创建55640行。
统计信息
----------------------------------------------------------
    5739584  redo size
SQL> COMMIT;

SQL> INSERT /*+ this is append */ INTO T1 SELECT * FROM T2;
已创建55640行。
统计信息
----------------------------------------------------------
    5746604  redo size
SQL> COMMIT;

SQL> INSERT /*+ this append */ INTO T1 SELECT * FROM T2;
已创建55640行。
统计信息
----------------------------------------------------------
      12052  redo size
SQL> COMMIT;

从上面的输出可以看到,通过insert语句执行产生的redo size判断,4条SQL语句中,1和4这2条SQL中的append hint起了作用,而2和3这2条SQL中的append hint没有起作用。我们看看第1和第2条SQL,只不过是parallel和append换了个位置,结果就截然不同;而第3和第4条SQL,只是一个多了"is"这个词,另一个没有,其结果也完全不同。这里有什么玄机吗?

这里就需要了解Oracle在解析SQL时,是怎样解析hint的。
Oracle在解析hint,从左到右进行,如果遇到一个词是oracle关键字或者说是保留字,将忽略这个词以及之后的所有词。如果遇到的一个词即不是关键字也不是hint,就忽略该词。如果遇到的一个词是有效的hint,那么就会保留该hint。

Oracle的保留字或者说是关键词(虽然二者在意义不一样,但这里不将其区分),可以通过视图v$reserved_words来查询。"is"正是一个关键词,甚至连","(逗号)也是一个关键词。这样,上面的第2和第3条SQL,Oracle解析时当遇到","和"is"时,就忽略了后面的所有hint。在第4条SQL中,this并不是一个关键词,所以append hint有效。基于这个原理,下面的一条SQL中的hint也是不起作用的:

INSERT /*+ NOLOGGING APPEND */ INTO T1 SELECT * FROM T2;

在9.2.0.8和11.2.0.2这2个版本下进行同样的测试,结果完全一样。
为了避免这样的情况,在SQL中书写hint时,在/*+ */--+这2种结构内只写hint,而不要写逗号,或者是其他的注释。如果要对SQL写注释,在专门的注释结构中写入。比如/* test comment */。如果与hint混写注释,虽然当时没有关键词在里面,但随着版本升级,很可能会加入新的关键词。

另外,一些很常见的hint形式,比如/*+ parallel(t,8) */,/*+ index(t,t_idx) */,虽然当前没有问题,但标准的写法应该是:
/*+ parallel(t 8) */,/*+ index(t t_idx) */

--end end.

在上一篇《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

,

我们都知道drop table, truncate table时都会先做一次checkpoint,将被删除对象的脏块写入磁盘。

客户有一套系统,Oracle 9.2.0.8,需要做数据迁移,由于种种原因,采用的是逻辑迁移的方式。由于库比较大,超过了1.5T,而停机时间又有限,因此在正式迁移之前需要做大量的测试,测试的目的,一方面是看迁移流程上是否存在问题,另一方面是看迁移的时候,哪个地方会存在性能瓶颈,并进行优化,同时估算实施迁移时间。

第一次测试后,需要把测试产生的大量用户及其对象全部删除,删除用的是drop user username cascade。不幸的是这种方式删除得相当地慢。一个9000多个表的用户,删除了1个半小时才删除了4000多个表。为什么这么慢?有没有办法提高速度?

drop table既然要做checkpoint,那么在db cache非常大的情况下,这需要消耗的时间是比较长的。如果能够减少这个时间无疑将大幅提高速度。首先尝试做一次checkpoint,将buffer cache全部刷新出去:

alter system checkpoint;
alter session set events 'immediate trace name flush_cache level 1';

发现没什么效果。

由于db_cache_size有50GB左右,db_keep_cache_size有6G左右。重新设置参数,将db_keep_cache_size设为0,将db_cache_size设为200M,重启一下数据库,重新执行删除用户的操作,操作很快完成。

在另一次同样的过程中,采用同样的修改参数的方式,效果同样非常明显。

这是个简单的案例,与君共享。

Oracle提供了方便的树形查询功能,也就是connect by 语句。树形结构是很常见的,比如组织机构树,产品目录树等。本文不讲述connect by 如何使用,只是提出在使用树形查询时需要考虑的一个有关于性能方面的问题。

这里提到的问题,主要是Oracle优化器在评估connect by 语句的cardinality时,存在的缺陷,下面将举例说明。

在这个例子中所使用的表,是一个真实的生产系统中的表,BSS_ORG:

SQL> desc bss_org
 名称                         是否为空? 类型
 ---------------------------- -------- --------------

 BSS_ORG_ID                   NOT NULL NUMBER(9)
 NAME                         NOT NULL VARCHAR2(64)
 BSS_PARENT_ORG_ID                     NUMBER(9)
 BSS_ORG_LEVEL_ID             NOT NULL NUMBER(3)
 STATE                        NOT NULL VARCHAR2(3)
 STATE_DATE                            DATE
 BSS_ORG_CODE                          VARCHAR2(15)

在这个BSS_ORG表中,BSS_ORG_ID是主键,BSS_PARENT_ORG_ID与BSS_ORG_ID形成上下层级关系。这个表的统计信息如下:

Table                   Number                 Empty Average    Chain Average Global
Name                   of Rows   Blocks       Blocks   Space    Count Row Len Stats
--------------- -------------- -------- ------------ ------- -------- ------- ------
BSS_ORG                  5,739       52            0       0        0      53 YES

Column                    Column                       Distinct            Number
Name                      Details                        Values   Density Buckets
------------------------- ------------------------ ------------ --------- ------- --
BSS_ORG_ID                NUMBER(9,0) NOT NULL            5,739   .000174       1
NAME                      VARCHAR2(64) NOT NULL           5,034   .000361     200
BSS_PARENT_ORG_ID         NUMBER(9,0)                       905   .002189     200
BSS_ORG_LEVEL_ID          NUMBER(3,0) NOT NULL                6   .000087       6
STATE                     VARCHAR2(3) NOT NULL                2   .000087       2
STATE_DATE                DATE                            1,624   .001434     200
BSS_ORG_CODE              VARCHAR2(15)                    5,639   .000179     200

下面的测试,是在Oracle 11.1.0.6 for Windows版本下进行的测试。在Oracle 9i、Oracle 10g下测试的结果与Oracle 11g下测试的结果是相符的。当然这里谈到的问题是cardinality,因此在三个版本下,SQL的执行计划可能有所不同,但最终的结论是一致的。(BTW:从10g开始,connect by语句有一个新的执行步骤,称为CONNECT BY NO FILTERING,对应的Hint是no_connect_by_filtering)。

SQL> explain plan for
  2  SELECT   bss_org_id
  3        FROM bss_org t
  4  START WITH bss_org_id = 1
  5  CONNECT BY bss_parent_org_id =
  6                                PRIOR bss_org_id;

已解释。

SQL> @showplan

PLAN_TABLE_OUTPUT

---------------------------------------------------------------------------------------------------
| Id  | Operation                               | Name    | Rows  | Bytes | Cost (%CPU)| Time     |
---------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT                        |         |  5739 | 80346 |    16   (0)| 00:00:01 |
|*  1 |  CONNECT BY NO FILTERING WITH START-WITH|         |       |       |            |          |
|   2 |   TABLE ACCESS FULL                     | BSS_ORG |  5739 | 80346 |    16   (0)| 00:00:01 |
---------------------------------------------------------------------------------------------------

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

   1 - access("BSS_PARENT_ORG_ID"=PRIOR "BSS_ORG_ID")
       filter("BSS_ORG_ID"=1)

SQL> explain plan for
  2  SELECT   bss_org_id
  3        FROM bss_org t
  4  START WITH bss_org_id = 832044754
  5  CONNECT BY bss_parent_org_id =
  6                                PRIOR bss_org_id;

已解释。

SQL> @showplan

---------------------------------------------------------------------------------------------------
| Id  | Operation                               | Name    | Rows  | Bytes | Cost (%CPU)| Time     |
---------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT                        |         |  5739 | 80346 |    16   (0)| 00:00:01 |
|*  1 |  CONNECT BY NO FILTERING WITH START-WITH|         |       |       |            |          |
|   2 |   TABLE ACCESS FULL                     | BSS_ORG |  5739 | 80346 |    16   (0)| 00:00:01 |
---------------------------------------------------------------------------------------------------

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

   1 - access("BSS_PARENT_ORG_ID"=PRIOR "BSS_ORG_ID")
       filter("BSS_ORG_ID"=832044754)

上面的2条SQL,第1条实际应该返回的行数为5739,第2条SQL实际应该返回的行数为4,但是从执行计划上看,Oracle优化器评估的行数均为5739。

SQL> create index bss_org_idx1 on bss_org(bss_parent_org_id);

索引已创建。

SQL> explain plan for
  2  SELECT   *
  3        FROM bss_org t
  4  START WITH bss_org_id = 1
  5  CONNECT BY bss_parent_org_id =
  6                                PRIOR bss_org_id;

已解释。

SQL> @showplan

----------------------------------------------------------------------------------------------
| Id  | Operation                     | Name         | Rows  | Bytes | Cost (%CPU)| Time     |
----------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT              |              |     6 |   318 |     4   (0)| 00:00:01 |
|*  1 |  CONNECT BY WITH FILTERING    |              |       |       |            |          |
|   2 |   TABLE ACCESS BY INDEX ROWID | BSS_ORG      |     1 |    53 |     2   (0)| 00:00:01 |
|*  3 |    INDEX UNIQUE SCAN          | PK_BSS_ORG   |     1 |       |     1   (0)| 00:00:01 |
|   4 |   NESTED LOOPS                |              |       |       |            |          |
|   5 |    CONNECT BY PUMP            |              |       |       |            |          |
|   6 |    TABLE ACCESS BY INDEX ROWID| BSS_ORG      |     6 |   318 |     4   (0)| 00:00:01 |
|*  7 |     INDEX RANGE SCAN          | BSS_ORG_IDX1 |     6 |       |     1   (0)| 00:00:01 |
----------------------------------------------------------------------------------------------

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

   1 - access("BSS_PARENT_ORG_ID"=PRIOR "BSS_ORG_ID")
   3 - access("BSS_ORG_ID"=1)
   7 - access("BSS_PARENT_ORG_ID"=PRIOR "BSS_ORG_ID")

SQL> explain plan for
  2  SELECT   *
  3        FROM bss_org t
  4  START WITH bss_org_id = 832044754
  5  CONNECT BY bss_parent_org_id =
  6                                PRIOR bss_org_id;

已解释。

SQL> @showplan

----------------------------------------------------------------------------------------------
| Id  | Operation                     | Name         | Rows  | Bytes | Cost (%CPU)| Time     |
----------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT              |              |     6 |   318 |     4   (0)| 00:00:01 |
|*  1 |  CONNECT BY WITH FILTERING    |              |       |       |            |          |
|   2 |   TABLE ACCESS BY INDEX ROWID | BSS_ORG      |     1 |    53 |     2   (0)| 00:00:01 |
|*  3 |    INDEX UNIQUE SCAN          | PK_BSS_ORG   |     1 |       |     1   (0)| 00:00:01 |
|   4 |   NESTED LOOPS                |              |       |       |            |          |
|   5 |    CONNECT BY PUMP            |              |       |       |            |          |
|   6 |    TABLE ACCESS BY INDEX ROWID| BSS_ORG      |     6 |   318 |     4   (0)| 00:00:01 |
|*  7 |     INDEX RANGE SCAN          | BSS_ORG_IDX1 |     6 |       |     1   (0)| 00:00:01 |
----------------------------------------------------------------------------------------------

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

   1 - access("BSS_PARENT_ORG_ID"=PRIOR "BSS_ORG_ID")
   3 - access("BSS_ORG_ID"=832044754)
   7 - access("BSS_PARENT_ORG_ID"=PRIOR "BSS_ORG_ID")

这里在BSS_PARENT_ORG_ID列上建一个索引,是为了使执行计划与9i、10g下的一致。
这2条SQL返回的结果行数,与前面的2条SQL一样,分别是5739和4,但是从执行计划上看,Oracle优化器评估出来的行数都是6。

从前面的两个测试来看,优化器评估出来的SQL返回的行数要么是5739(表BSS_ORG的总行数),要么是6(总行数/BSS_PARENT_ORG_ID的Disctint Values)。但无论如何,随着不同的start with条件,这个行数(cardinality)与实际返回的结果行数可能会存在非常大的差异。如果仅仅是测试中这样一个简单的SQL,实际上不会有什么问题,很容易出现问题的地方在于,一个复杂的SQL中,有类似于测试SQL这样的子查询,这样使得表连接的评估出现很大的偏差,这样容易引起非常大的性能问题。

在9i下,如果BSS_PARENT_ORG_ID上如果没有索引,那么最后一个测试SQL的执行计划如下:

SQL> explain plan for
  2  SELECT   *
  3        FROM bss_org t
  4  START WITH bss_org_id = 832044754
  5  CONNECT BY bss_parent_org_id =
  6                                PRIOR bss_org_id
  7                                ;

已解释。

SQL> @showplan

----------------------------------------------------------------------------
| Id  | Operation                    |  Name       | Rows  | Bytes | Cost  |
----------------------------------------------------------------------------
|   0 | SELECT STATEMENT             |             |  5739 |   297K|     9 |
|*  1 |  CONNECT BY WITH FILTERING   |             |       |       |       |
|   2 |   TABLE ACCESS BY INDEX ROWID| BSS_ORG     |       |       |       |
|*  3 |    INDEX UNIQUE SCAN         | PK_BSS_ORG  |     1 |     7 |     1 |
|   4 |   HASH JOIN                  |             |       |       |       |
|   5 |    CONNECT BY PUMP           |             |       |       |       |
|   6 |    TABLE ACCESS FULL         | BSS_ORG     |  5739 |   297K|     9 |
|   7 |   TABLE ACCESS FULL          | BSS_ORG     |  5739 |   297K|     9 |
----------------------------------------------------------------------------

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

   1 - filter("T"."BSS_ORG_ID"=832044754)
   3 - access("T"."BSS_ORG_ID"=832044754)

这里9i的优化器评估出来的cardinality为5739,而11g与此同样的执行计划,评估的cardinality是6。

前段时间就遇上由于connect by语句引起的性能问题。数据库为Oracle 9208,开始由于bss_org表的bss_parent_org_id列上没有索引,导致connect by部分得到的cardinality为5739,结果SQL性能非常差,在bss_parent_org_id上建索引后,执行计划改变,connect by 部分得到的cardinality为6,SQL性能大幅提升。

对于Oracle优化器不能准确评估connect by 语句的cardinality,目前没有比较好的解决办法。必要的时候只有考虑使用Hint了。欢迎朋友们针对此问题进行讨论。