一个电信运营商客户的核心交易系统,临时表空间大量被占用,临时表空间被撑到了600GB。这样的问题复杂吗?取决于很多因素,不过今天所要讲的案例,并不复杂,如果我们对临时表空间在何种情况下使用有足够了解。

首先,我们要去检查是什么会话占用了临时表空间,具体占用了多少,临时段的具体类型是什么。正如我们要想知道这个月的花费过大,去分析原因时就要去看是哪些开销过大、开销了多少金额、开销的用途等。

这个步骤比较简单,查询v$sort_usage就可以了:

select * from 
(select username,session_addr,sql_id,contents,segtype,blocks*8/1024/1024 gb 
from v$sort_usage order by blocks desc) 
where rownum<=200;

USERNAME    SESSION_ADDR     SQL_ID        CONTENTS  SEGTYPE            GB
----------  ---------------- ------------- --------- --------- -----------
XXXX        0700002949BCD8A0 291nk7db4bwdh TEMPORARY SORT      .9677734375
XXXX        070000294BD99628 291nk7db4bwdh TEMPORARY SORT      .9677734375
XXXX        070000294CD10480 291nk7db4bwdh TEMPORARY SORT      .9677734375
XXXX        070000294DD1AC88 291nk7db4bwdh TEMPORARY SORT      .9677734375
XXXX        070000294CD68D70 291nk7db4bwdh TEMPORARY SORT      .9677734375
XXXX        070000294DBDF760 291nk7db4bwdh TEMPORARY SORT      .9677734375
XXXX        070000294EDB5D10 291nk7db4bwdh TEMPORARY SORT      .9677734375
XXXX        070000294FD7D818 291nk7db4bwdh TEMPORARY SORT      .9677734375
...结果较多,忽略部分输出...

SQL_ID都是一样的,那这个SQL是否有其特殊性呢?SEGTYPE为SORT表明这个临时段是“排序段”,用于SQL排序,大小居然也是一样,会话占用的临时段大小将近1GB,几百个会话加在一起,想不让临时表空间不撑大都难。

看看这个相同的SQL ID代表的SQL是什么:

SQL> @sqlbyid 291nk7db4bwdh

SQL_FULLTEXT
--------------------------------------------------------------------------------------------------------------
 SELECT  A.LLEVEL,  A.LMODE  FROM TABLE_XXX A  WHERE A.SERVICE_NAME = :SERVICE_NAME AND STATE='Y'

很明显,这是一条非常简单的SQL,没有ORDER BY ,也没有GROUP BY、UNION、DISTINCT等需要排序的,TABLE_XXX是一张普通的表,而不是视图。出现了什么问题?会不会是v$sort_usage的SQL_ID列有错误?我们查看其中一个会话正在执行的SQL:

select sid,prev_sql_id, sql_id from v$session where saddr='070000294AC0D050';

        SID PREV_SQL_ID   SQL_ID
----------- ------------- -------------
       3163 291nk7db4bwdh

v$sort_usage中看到某个会话当前没有执行任何SQL,v$sort_usage中的SQL_ID是该会话前一条执行的SQL。为什么这里显示的是会话前一条执行的SQL,关于这个问题后面再详述,但至少有一点是可以判断的:如果大量的临时段都是由会话当前正在执行的SQL所产生的,那说明同时有几百个会话在执行需要大量临时空间的SQL,那系统早就崩溃了。所以这些临时表空间的占用不应该是由当前在执行的SQL所产生的,至少大部分不是。

大部分人的一个错误观点是,临时表空间中当前占用的空间是由会话当前正在执行的SQL所产生的。上面的一个简单的分析判断,情况不应该是这样。我们可以基于查询类SQL的执行过程来分析:

  1. 解析SQL语句(Parse),生成一个游标(Open Cursor)。
  2. 执行SQL语句(Execute),严格说就是执行新产生的游标。
  3. 在游标中取数据(Fetch)。
  4. 关闭游标(Close Cursor)。

关键在第3步。大家都知道取数据有一个array size的概念,表示一次从游标中取多少条数据,这是一个循环的过程。如果SQL查询得到的数据有1000条,每次取100条,则需要取10次。对于Fetch Cursor,有两点:

  1. 一个游标,或者说一条SQL语句,并不要求客户端把所有数据取完,只取了一部分数据就关闭游标也是可以的。
  2. 只要还没有关闭游标,数据库就要维护该游标的状态,如果是排序的SQL,也需要维持该SQL已经排好序的数据。

很显然,从上述第2点可以知道,如果一条SQL使用了临时段来排序,在SQL对应的游标没关闭的情况下,Oracle数据库不会去释放临时段,因为对于Oracle数据库来说,它不会知道客户端是否还要继续取游标的数据。

基于这样的分析,我们只需要随便选择一个占用了接近1GB的会话,查询v$open_cursor,查看其打开的游标中是否有大数据量排序的SQL:

SQL> select sql_id,sorts,rows_processed/executions from v$sql
  2  where parsing_schema_name='ACCT' and executions>0 and sorts>0
  3  and sql_id in (select sql_id from v$open_cursor where sid=4505)
  4  order by 3;
  
  SQL_ID              SORTS ROWS_PROCESSED/EXECUTIONS
------------- ----------- -------------------------
...省略部分输出结果...
86vp997jbz7s6       63283                       593
cfpdpb526ad43         592               35859.79899
cfpdpb526ad43         188               55893.61702
cfpdpb526ad43         443                     71000

Read the rest of this entry

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$有足够的数据,这样问题就解决了。

在11g里面,随着ASM、RAC、Data Guard(包括Active Data Guard)的成熟,使用RAC+ASM+Data Guard越来越成为一种可靠的、维护简单、稳定的高可用性和容灾保护方案。这篇文章谈谈如何管理Oracle 11g Data Guard环境中的归档日志。

归档日志是重要的,不然就不必提到这篇文章,备份恢复需要它,而Data Guard也需要它。在早期版本的Data Guard环境中,常常面临着归档日志管理问题。在Data Guard环境里面,对归档日志管理需要达到以下几个方面的要求或者说是需求:

  • 不能够随意删除掉归档日志,归档日志丢失会导致Data Guard需要重新搭建。
  • 不能随意使用RMAN删除归档日志,否则同样会导致Data Guard需要重新搭建。
  • 在使用RMAN备份后,如果归档没有被传送或应用到备库上,那么RMAN不应该删除归档日志,否则Data Guard需要的归档就必须从备份里面还原出来,增加了维护工作量。
  • 对RMAN的备份脚本没有特别的要求,否则脚本意外改动,可能会导致Data Guard需要的归档日志被删除。
  • 归档应尽量保存在磁盘上,以避免Data Guard长时间维护时归档被删除。
  • 备库的归档日志不需要花精力去维护,自动删除已经应用过的归档日志。

幸运的是,在11g环境里面,上述的几点很容易就满足,那就是只需要做到以下几点。

  • 使用快速恢复区(fast recovery area),在10g版本的文档中称为闪回恢复区(flash recovery area),老实说,一直不太明白为什么取名叫闪回恢复区,难道是因为10g有了数据库闪回功能?在RAC中,毫无疑问快速恢复区最好是置放在ASM上。
  • 为快速恢复区指定合适的空间。首先我们需要预估一个合理的归档保留时间长。比如由于备份系统问题或Data Guard备库问题、维护等,需要归档保留的时间长度。假设是24小时,再评估一下在归档量最大的24小时之内,会有多少量的归档?一般来说是在批量数据处理的时候归档量最大,假设这24小时之内归档最大为200G。注意对于RAC来说是所有节点在这24小时的归档量之和。最后为快速恢复区指定需要的空间量,比通过参数db_recovery_file_dest_size指定快速恢复区的大小。这里同样假设快速恢复区们存放归档日志。
  • 在备库上指定快速恢复区以及为快速恢复区指定合适的大小,在备库上指定快速恢复区的大小主要考虑的是:切换成为主库后归档日志容量;如果主库归档容量压力大,备库能否存储更多的归档日志以便可以通过备库来备份归档日志。
  • 对主库和备份使用RMAN配置归档删除策略:CONFIGURE ARCHIVELOG DELETION POLICY TO APPLIED ON ALL STANDBY;

完成了上述几个步骤,那么归档管理的要求基本上就达到了。通过这样的设置,实现的效果如下:

  • 归档日志如果没有应用到备库,那么在RMAN中使用backup .... delete inputs alldelete archivelog all不会将归档日志删除。但但是请注意如果是使用delete force命令则会删除掉归档,不管归档有没有被应用到备库。
  • 如果归档日志已经应用到了备库,那么在RMAN中使用backup .... delete inputs alldelete archivelog all可以删除归档日志,在正常情况下,由于归档日志可能很快应用到Data Guard,所以在RMAN备份之后可以正常删除归档日志。RMAN也不需要使用特别的备份脚本,也不必担心人为不小心使用。delete archivelog all命令删除了归档。
  • 备库的归档日志存储到快速恢复区中,备库的快速恢复区空间紧张时,会自动删除已经应用过的较早的归档日志以释放空间,这样便可以实现备库的归档日志完全自动管理。
  • 如果由于备份异常或Data Guard异常,在快速恢复区空间紧张时,Oracle在切换日志时,会自动删除掉已经应用过的归档日志,以释放空间。但是如果归档日志没有应用到Data Guard,那么归档日志不会被删除。这种情况下,快速恢复区的归档可能会增加到空间耗尽,最后就会出现数据库不能归档,数据库挂起的问题。

注意上面最后一点,当快速恢复区空间紧张时,Oracle开始删除归档日志,删除的条件还包括归档日志已经应用到备库,这种情况下如果归档日志还没有备份,也会被删除掉。这里的问题是,文档中描述的快速恢复区空间紧张,具体是指什么时间?也就是快速恢复区的空间消耗多少百分比的时候才算是空间紧张?在MOS文章《Files being deleted in the flash recovery area, messages in the alert log Deleted Oracle managed file <filename> (Doc ID 1369341.1)》里面有提到,空间使用率达到80%以后就开始删除文件(归档日志)。

Oracle在往快速恢复区存储文件时,其步骤大概是这样的:Oracle估计需要的空间大小(切换日志时就是归档日志大小),然后将这个大小与当前的占用空间大小相加,看是否超过了80%,如果超过了,那么就回收空间(回收的空间应大于等于新建文件需要的空间大小,也就是回收的空间以够用为原则)。如果不能回收空间(比如归档日志没有被应用到备库),那就只能继续占用新的空间,直到空间耗尽。

这里的问题是,假设快速恢复区设定了200G空间,那么在使用到80%,也就是160G的时候就开始回收空间。那么我们在估算空间时,就应该上浮20%。比如我们要求保留24小时归档,这24小时之内归档量最大是200G,那么我们应该为快速恢复区设置240G左右的容量。

那么,这个80%的比率能够更改吗以便延迟Oracle删除归档日志的时间吗?答案是肯定的。没有相应的数据库参数来设定,但是可以通过事件来设置,事件号是19823:

oerr ora 19823
19823, 00000, "soft limit recovery area space pressure percentage"
// *Document: NO
// *Cause: Set on all instances to alter recovery area space pressure
//         trigger percentage.
// *Action: level 1 to 100 indicates the percentage when the space
//          pressure has to be triggered.

下在是一个测试:
测试环境:主库是Oracle 11.2.0.3 for Linux两节点RAC,备库是Oracle 11.2.0.3 for linux单实例库。测试是在主库的节点1上进行的,其在线日志大小为512MB,快速恢复区指定的大小为16GB。
当前主库的FRA(快速恢复区)的使用率已经接近于80%:

select * from V$RECOVERY_AREA_USAGE;

FILE_TYPE            PERCENT_SPACE_USED PERCENT_SPACE_RECLAIMABLE NUMBER_OF_FILES
-------------------- ------------------ ------------------------- ---------------
CONTROL FILE                          0                         0               0
REDO LOG                          15.33                         0              13
ARCHIVED LOG                      64.04                     63.81              45
BACKUP PIECE                        .24                         0               1
IMAGE COPY                            0                         0               0
FLASHBACK LOG                         0                         0               0
FOREIGN ARCHIVED LOG                  0                         0               0

在主库上创建一个表,并插入一行数据:

create table t1 ( id number, name char(1000)) tablespace TBS_USERS;
insert into t1 values (1,'a');

然后执行下在的测试代码:

begin
  for i in 1..300000 loop
    update t1 set name=to_char(i);
  end loop;
  commit;
end;
/

这段代码产生的日志量大约在690MB左右:

SQL> select * from v$sesstat where sid=155 and statistic#=178;

       SID STATISTIC#      VALUE
---------- ---------- ----------
       155        178  696908584

多次执行上述代码,发现FRA(快速恢复区)的空间使用率基本上在80%左右。alert日志也有相应的删除较早的归档日志的信息:

Thu Jan 02 12:28:50 2014
Thread 1 advanced to log sequence 981 (LGWR switch)
  Current log# 12 seq# 981 mem# 0: +DATA1/ractest/onlinelog/group_12.299.835542549
  Current log# 12 seq# 981 mem# 1: +DG_FLA/ractest/onlinelog/group_12.298.835542551
Thu Jan 02 12:28:50 2014
LNS: Standby redo logfile selected for thread 1 sequence 981 for destination LOG_ARCHIVE_DEST_2
Thu Jan 02 12:28:50 2014
Deleted Oracle managed file +DG_FLA/ractest/archivelog/2014_01_02/thread_2_seq_309.424.835783855
Deleted Oracle managed file +DG_FLA/ractest/archivelog/2014_01_02/thread_1_seq_947.426.835783855
Deleted Oracle managed file +DG_FLA/ractest/archivelog/2014_01_02/thread_1_seq_948.437.835784237
Archived Log entry 2645 added for thread 1 sequence 980 ID 0xc8804744 dest 1:

上面的日志也可以看到其过程是:切换日志;删除不需要的最老的归档日志;生成新的归档日志。

现在我们利用事件19823将这个比率调到95%看看会是什么样子:

SQL> alter system set event='19823 trace name context forever,level 95' scope=spfile sid='*';

然后重启主库。再运行上面的测试代码,发现Oracle不再删除归档日志,而是到接近95%的空间使用率时再开始删除归档日志:

FILE_TYPE            PERCENT_SPACE_USED PERCENT_SPACE_RECLAIMABLE NUMBER_OF_FILES
-------------------- ------------------ ------------------------- ---------------
CONTROL FILE                          0                         0               0
REDO LOG                          15.33                         0              13
ARCHIVED LOG                      68.99                     65.72              49
BACKUP PIECE                        .24                         0               1
IMAGE COPY                            0                         0               0
FLASHBACK LOG                         0                         0               0
FOREIGN ARCHIVED LOG                  0                         0               0

.............

FILE_TYPE            PERCENT_SPACE_USED PERCENT_SPACE_RECLAIMABLE NUMBER_OF_FILES
-------------------- ------------------ ------------------------- ---------------
CONTROL FILE                          0                         0               0
REDO LOG                          15.33                         0              13
ARCHIVED LOG                      78.62                      59.9              55
BACKUP PIECE                        .24                         0               1
IMAGE COPY                            0                         0               0
FLASHBACK LOG                         0                         0               0
FOREIGN ARCHIVED LOG                  0                         0               0

从上面的最后一次对v$recovery_area_usage的查询数据可以看到,此时空间利用率达到了94.19%,离95%已经很接近(在线日志的大小是512MB,占快速恢复区的3.1%,如果在快速恢复区里面多一个文件就会超过95%)。

接下来我们将这个比率调整到50%,看看是什么结果:

SQL> alter system set event='19823 trace name context forever,level 50' scope=spfile sid='*';

然后重启主库。再运行上面的测试代码,发现Oracle在删除归档日志,但是每次均删除的日志只需要容纳要新增的文件即可,不会一下子删除到使利用率到50%以下:

FILE_TYPE            PERCENT_SPACE_USED PERCENT_SPACE_RECLAIMABLE NUMBER_OF_FILES
-------------------- ------------------ ------------------------- ---------------
CONTROL FILE                          0                         0               0
REDO LOG                          15.33                         0              13
ARCHIVED LOG                      72.47                     48.57              54
BACKUP PIECE                        .24                         0               1
IMAGE COPY                            0                         0               0
FLASHBACK LOG                         0                         0               0
FOREIGN ARCHIVED LOG                  0                         0               0

然后一直使用alter system switch logfile命令,每执行一次,Oracle会删除一个归档日志,到最后快速恢复区的空间利用率到接近于50%。

Thu Jan 02 12:56:29 2014
Thread 1 advanced to log sequence 1004 (LGWR switch)
  Current log# 12 seq# 1004 mem# 0: +DATA1/ractest/onlinelog/group_12.299.835542549
  Current log# 12 seq# 1004 mem# 1: +DG_FLA/ractest/onlinelog/group_12.298.835542551
Thu Jan 02 12:56:30 2014
Deleted Oracle managed file +DG_FLA/ractest/archivelog/2014_01_02/thread_1_seq_963.317.835788195
Thu Jan 02 12:56:30 2014
LNS: Standby redo logfile selected for thread 1 sequence 1004 for destination LOG_ARCHIVE_DEST_2
Archived Log entry 2703 added for thread 1 sequence 1003 ID 0xc8804744 dest 1:


FILE_TYPE            PERCENT_SPACE_USED PERCENT_SPACE_RECLAIMABLE NUMBER_OF_FILES
-------------------- ------------------ ------------------------- ---------------
CONTROL FILE                          0                         0               0
REDO LOG                          15.33                         0              13
ARCHIVED LOG                      33.29                     28.86              65
BACKUP PIECE                        .24                         0               1
IMAGE COPY                            0                         0               0
FLASHBACK LOG                         0                         0               0
FOREIGN ARCHIVED LOG                  0                         0               0   

因此,我们可以了解event 19823的用途。对于空间容量比较小的主机,但是希望归档能够尽量保留在快速恢复区,以便留有足够的备份时间窗口,那么可以考虑把这个百分比调整到更大,比如90%,95%等。

在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

在JAVA使用JDBC连接数据库进行操作时,有可能为了避免语句运行超时,而设置超时时长。

这里有一个问题是,假设一个事务有两条DML SQL语句,会话在执行第一条SQL成功后,执行第二条SQL超时而中止时,事务处于什么样的状态?通常来说,一个SQL报错,只会进行语句级回滚,整个事务不会进行回滚。我们来进行一下测试。

测试环境:Oracle 11.2.0.2 for Windows。
首先在TEST用户下生成测试表和数据。

TEST@xj11g> create table t1 ( id number primary key,name varchar2(20));

表已创建。

TEST@xj11g> create table t2 ( id number primary key,name varchar2(20));

表已创建。

TEST@xj11g> insert into t2 values (1,'a');

已创建 1 行。

TEST@xj11g> commit;

提交完成。

编译如下的JAVA代码(TestTimeout.java):

import java.sql.*;

public class TestTimeout {
    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[]) {
        test1();
    }
    public static void test1() {
        Connection conn = null;
        Statement pstmt = null;
        try {
            conn = getConnection();
            conn.setAutoCommit(false);
            pstmt = conn.createStatement();
            pstmt.setQueryTimeout(60);
            pstmt.execute("insert into t1 values (1,'xx')");
            pstmt.execute("update t2 set name='x' where id=1");
            conn.commit();
        } catch (Exception e) {
            e.printStackTrace();
            try {
                Thread.sleep(300000);
            } catch (Exception f) {
            }
        } finally {
            try {
                pstmt.close();
                conn.close();
            } catch (SQLException e) {
                e.printStackTrace();
            }
        }
    }
}

编译JAVA代码:

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

在一个会话里面将T2表中ID=1的行进行UPDATE操作,但是不提交。

TEST@xj11g> update t2 set name='y' where id=1;

已更新 1 行。

然后运行测试用JAVA程序:

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

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

可以预见的是,在执行update表T2时会被锁住:

SYS@xj11g> select sid,event,sql_id from v$session where sid=206;

        SID EVENT                         SQL_ID
----------- ----------------------------- -------------
        206 enq: TX - row lock contention 3b3b7s22dv13t

一会儿后JAVA程序报如下的错误:

java.sql.SQLException: ORA-01013: 用户请求取消当前的操作

        at oracle.jdbc.driver.DatabaseError.throwSqlException(DatabaseError.java:112)
        at oracle.jdbc.driver.T4CTTIoer.processError(T4CTTIoer.java:331)
        at oracle.jdbc.driver.T4CTTIoer.processError(T4CTTIoer.java:288)
        at oracle.jdbc.driver.T4C8Oall.receive(T4C8Oall.java:743)
        at oracle.jdbc.driver.T4CStatement.doOall8(T4CStatement.java:207)
        at oracle.jdbc.driver.T4CStatement.executeForRows(T4CStatement.java:946)
        at oracle.jdbc.driver.OracleStatement.doExecuteWithTimeout(OracleStatement.java:1160)
        at oracle.jdbc.driver.OracleStatement.executeInternal(OracleStatement.java:1679)
        at oracle.jdbc.driver.OracleStatement.execute(OracleStatement.java:1645)
        at TestTimeout.test1(TestTimeout.java:23)
        at TestTimeout.main(TestTimeout.java:12)

可以看到,JAVA程序自己CANCEL掉了SQL的执行。
在JAVA代码中长时间的SLEEP是为了便于观察SQL报错后,事务的状态。

SYS@xj11g> select xidusn,xidslot,xidsqn,status from v$transaction where ses_addr=(select saddr from v$session where sid=206);

     XIDUSN     XIDSLOT      XIDSQN STATUS
----------- ----------- ----------- ----------------
          4          28        4117 ACTIVE

SYS@xj11g> select * from v$lock where sid=206;

  SID TY         ID1         ID2       LMODE     REQUEST       CTIME       BLOCK
----- -- ----------- ----------- ----------- ----------- ----------- -----------
  206 AE         100           0           4           0         203           0
  206 TM       63075           0           3           0         203           0
  206 TX      262172        4117           6           0         203           0
SYS@xj11g> select owner,object_name,object_type from dba_objects where object_id=63075;

OWNER    OBJECT_NAME  OBJECT_TYPE
-------- ------------ ------------
TEST     T1           TABLE

可以看到JAVA程序的会话(此时还没断开连接),仍然是在事务中,并且在表T1上加了锁。
此时如果向T1表插入ID值为1的数据,会被锁阻塞。

SYS@xj11g> insert into test.t1 values (1,'xx');

不过奇怪的是,过几分钟后(JAVA中的SLEEP 300000表示休眠300秒,即5分钟),上述的INSERT语句报错了。查询发现JAVA代码中的INSERT的数据提交了:

insert into test.t1 values (1,'xx')
*
第 1 行出现错误:
ORA-00001: 违反唯一约束条件 (TEST.SYS_C0011027)

SYS@xj11g> select * from test.t1;

         ID NAME
----------- --------------------
          1 xx

其实想想就能明白,这个并不奇怪,因为JAVA代码的最后正常断开了数据库连接,在默认情况下,正常断开的数据库连接会自动提交没有提交的事务。这也是一种很难排查的产生数据不一致的原因之一。

小结:这个测试JAVA程序,可以表明,JDBC中的语句超时,只会使当前的SQL中止运行,但如果是在一个事务中,之前运行的DML语句并没有提交。这造成的后果有两种:
1. 如果是连接池,那么超时之前更新的数据可能会被其他请求重用时得以提交,或者是在连接释放时得以提交,这造成数据的不一致,因为不是一个逻辑上有效的事务。
2. 由于数据被更新而没有及时回滚,可能会导致应用重新发起相同的事务时被锁住。如果被锁住的会话仍然有超时中止的机制,那么这种情况就会越来越严重。

为了避免以上的两种问题,在超时后,应该主动发起一次ROLLBACK操作。

最后是JAVA程序测试时数据库会话的SQL TRACE记录:

PARSING IN CURSOR #356760536 len=33 dep=0 uid=52 oct=6 lid=52 tim=36160405140 hv=2229109881 ad='7ff55ce8608' sqlid='3b3b7s22dv13t'
update t2 set name='x' where id=1
END OF STMT
PARSE #356760536:c=0,e=675,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,plh=2789547903,tim=36160405139

*** 2013-09-09 00:51:01.836
WAIT #356760536: nam='enq: TX - row lock contention' ela= 63181195 name|mode=1415053318 usn<<16 | slot=589851 sequence=4123 obj#=63077 tim=36223613008
EXEC #356760536:c=0,e=63208180,p=0,cr=2,cu=1,mis=0,r=0,dep=0,og=1,plh=2789547903,tim=36223613365
ERROR #3:err=1013 tim=36223613426
STAT #356760536 id=1 cnt=0 pid=0 pos=1 obj=0 op='UPDATE  T2 (cr=0 pr=0 pw=0 time=4 us)'
STAT #356760536 id=2 cnt=1 pid=1 pos=1 obj=63078 op='INDEX UNIQUE SCAN SYS_C0011028 (cr=1 pr=0 pw=0 time=10 us cost=1 size=25 card=1)'
WAIT #356760536: nam='SQL*Net break/reset to client' ela= 3586 driver id=1952673792 break?=0 p3=0 obj#=63077 tim=36223617262
WAIT #356760536: nam='SQL*Net message to client' ela= 2 driver id=1952673792 #bytes=1 p3=0 obj#=63077 tim=36223617407

*** 2013-09-09 00:56:01.903
WAIT #356760536: nam='SQL*Net message from client' ela= 300048871 driver id=1952673792 #bytes=1 p3=0 obj#=63077 tim=36523666376
CLOSE #356760536:c=0,e=62,dep=0,type=0,tim=36523666818
XCTEND rlbk=0, rd_only=0, tim=36523666956

在上面可以看到,在最后的确有一个事务事交(XCTEND rlbk=0, rd_only=0)。

是不是我们的数据库,加上一套成熟可靠的备份软件(比如NBU、DP、TSM等),以及购置了可靠的大容量的带库就足够了?或者下面一个案例能够给我们一些启示。

案例来自于一个老客户,一套重要系统的Oracle RAC数据库,由于硬件问题,一个包含关键业务数据的文件被离线(在归档模式下,写文件出错会导致文件被置为离线状态,而不是库宕掉)。在尝试recover datafile的时候,提示缺少一个归档日志。归档日志已经被备到带库上,本地磁盘上已经没有了这个归档日志文件。

这套库是用TSM备份的,使用rman还原归档日志,称找不到这个归档日志。看起来出问题了,在rman中用下面的命令:

list backup of archivelog sequence 18884 thread 2;

返回的结果说没有找到这个归档日志的备份。甚至于用命令:

list backup of archivelog all;

发现好些归档日志没有了备份。但是这些文件又不在本地磁盘上。那么,这里有几种可能:

  1. 归档日志被人为地删除,根本没有备份
  2. 归档日志的备份已经被删除,通过delete backup命令

第1种情况,可以从v$archived_log视图判断归档日志到底有没有备份(通过BACKUP_COUNT列)。我们可以从备份保留的日志中判断第2种情况是否存在。

检查备份操作的日志,发现恢复所需要的归档日志文件是成功备份了的。那备份怎么消失了?在备份操作的日志目录中,还发现一个日志文件有crosscheck backup然后delete expired backup的记录,而被删除的备份正好有恢复所需要的归档日志所在的备份。所以,这里可以知道,出现了上述说的第2种情况,备份被删除了。

为什么会出现备份在crosscheck backup之后成为expired状态,这个结果就来源于在rman中进行crosscheck backup时,备份服务器返回的结果表明这个备份不可访问了,或许是权限问题,或者是配置不当,或者是备份文件真的不能访问了。从目前的情况来看,备份都是成功的,看上去带库、备份服务器都是好的。不过这里值得注意的是,这是一套RAC数据库,归档日志是在节点1上完成的,在节点1上也进行了crosscheck backup,并且是先进行crosscheck,而其结果表明备份是available状态的。但是随后节点2的crosscheck的结果是expired,那只能说明由于权限或配置问题,导致节点2不能访问到节点1所做的备份(当然不排除在这个时间窗口内备份在带库上或备份服务端删除的可能,但是可能性较小,所以分析问题得先从可能性更大的入手)。

是不是没救了?答案在于,备份到底还在不在带库上?

节点1先crosscheck正常,随后节点2 crosscheck称备份文件没有或不可访问,然后节点2删除了备份。只不过这里要注意的是:既然crosscheck不能访问不到备份,那么delete操作也应当不会真正删除备份(备份都访问不到怎么能物理删除呢?),只是把备份信息从catalog里面删除掉而已。所以这里的结论是真正的备份还在带库上。可以找备份管理员或通过TSM命令来检查,不过客户说,搞TSM的人找不到了。

接下来,尝试找找看,有没有在备份归档日志之后,但在删除备份之前的备份控制文件存在。可惜没有,如果有,可以用这个控制文件来还原归档日志。
或许可以通过手工在catalog库里面添加记录,然后同步到控制文件来进行恢复。
不过我们还有另一个方法,就是直接使用dbms_backup_restore包:

DECLARE 
v_dev varchar2(50);
v_done boolean:=false;
BEGIN 
v_dev:=sys.dbms_backup_restore.deviceAllocate(type=>'sbt_tape',ident=>'t1',params=>'ENV=(TDPO_OPTFILE=/usr/tivoli/tsm/client/oracle/bin64/tdpo.opt)'); 
dbms_backup_restore.RestoreSetArchivedLog(destination=>'/arch');
dbms_backup_restore.RestoreArchivedLog(thread=>2,sequence=>18884);
dbms_backup_restore.RestoreBackupPiece(done => v_done,handle => 'xxx_archlog_backup<xxxx1_7941 :796937510>.dbf', params => null);
sys.dbms_backup_restore.deviceDeallocate; 
END; 

幸运的是,归档日志成功还原,然后数据文件成功recover。

从这个案例中,我们获得的是:

  • 并不是说,备份没有报错,备份正常运行就足够了。在备份的时候,为了避免备份出错而失败,在备份之前进行crosscheck archivelog,把人为删除掉的归档从catalog中去掉从而不备份,也就在备份时不报错;或者是备份时skip inaccessible;实际上这有点类似于掩耳盗铃,备份可能是残缺的,根本不可用。
  • rman中的crosscheck backup,使得backup成为expired状态,这本身说明可能存在问题,而不仅仅是从catalog中删除备份了事。针对这个案例来说,backup成为expired,本身就是一种异常,就应该要去检查备份服务器的配置等。
  • 所有涉及备份相关的操作,包括备份,删除备份,crosscheck备份,保留详细的rman日志是非常有用的。
  • 应该在每次备份后,对控制文件进行一次备份;打开控制文件的AUTO BACKUP也是有必要的。

--The End.

在编译《Oracle Core——Essential Internals for DBAs and Developers》这本书的第6章时,这章有提到进程在查找空闲缓冲区时,会从REPL_AUX链(即辅助LRU链)开始扫描,在扫描的过程中发现有dirty buffer,则会将该buffer从REPL_AUX链取下再链到WRITE_MAIN链上。这里提到的REPL_AUX链,主要用于链接那些能够马上复用的buffer(缓冲区),比如一致性读块,很少访问的块,大表全表扫描的块。而进程在查找可用的空闲或可复用的缓冲区时,会从REPL_AUX链开始查找,如果REPL_AUX链上如果有可用的缓冲区,那么进程就能很快获取到缓冲区以便用于存储从磁盘读入的块。

那在REPL_AUX链上会不会有脏块呢?如果没有,那么进程在扫描REPL_AUX时会更快更简单。而答案是”在REPL_AUX链上是会存在脏块“的。下面用实验来验证一下,测试环境为Oracle 10.2.0.4 for Windows。
1. 准备测试数据:

create table test.t1 as select * from dba_objects;
insert into test.t1 select * from test.t1;
--多执行几次上面的insert.
commit;
--最终T1表的segment大小为72M左右。
create index test.t1_idx on test.t1(owner);

2. 将数据库buffer_cache设置为60M大小,重启数据库(注意sga_target参数值为0)。

3. 执行下面的查询:

select /*+ index(t1) */ sum(object_id) from test.t1 where owner='SYS' ;

4. 查询X$BH表里面挂在REPL_AUX链上的buffer:


SQL> select * from (
  2  select obj,dbarfil,dbablk,to_char(state,'xxxxxxxx') state,to_char(lru_flag,'xxxxxxxx') lru_flag,to_char(flag,'xxxxxxxx') flag
  3  ,tch,dirty_queue from x$bh where obj=24523 and state<>0 and bitand(lru_flag,4)=4 order by dbablk
  4  ) where rownum<=10;

       OBJ    DBARFIL     DBABLK STATE     LRU_FLAG  FLAG             TCH DIRTY_QUEUE
---------- ---------- ---------- --------- --------- --------- ---------- -----------
     24523          8      16743         1         6     80000          0           0
     24523          8      27850         1         6     80000          0           0
     24523          8      27938         1         6     80000          0           0
     24523          8      28895         1         6     80000          0           0
     24523          8      29620         1         6     80000          0           0
     24523          8      29692         1         6     80000          0           0
     24523          8      29830         1         6     80000          0           0
     24523          8      29842         1         6     80000          0           0
     24523          8      29906         1         6     80000          0           0
     24523          8      29980         1         6     80000          0           0

已选择10行。

LRU_FLAG是一个按位的标志,4表示”on auxiliary list(在辅助链表上)“,而上面的结果中LRU_FLAG为6,即2+4,说明这些buffer都在REPL_AUX链上。

5. 更新表T1中的一行数据:


SQL> select dbms_rowid.rowid_create(1,24523,8,16743,1) from dual;

DBMS_ROWID.ROWID_C
------------------
AAAF/LAAIAAAEFnAAB

更新这一行:

update test.t1 set object_name='b' where rowid='AAAF/LAAIAAAEFnAAB';
commit;

6. 再次检查X$BH中刚刚更新的那个块:

SQL> select obj,dbarfil,dbablk,to_char(state,'xxxxxxxx') state,to_char(lru_flag,'xxxxxxxx') lru_flag,to_char(flag,'xxxxxxxx') flag

  2  ,tch,dirty_queue from x$bh where obj=24523 and dbablk=16743 order by dbablk;

       OBJ    DBARFIL     DBABLK STATE     LRU_FLAG  FLAG             TCH DIRTY_QUEUE
---------- ---------- ---------- --------- --------- --------- ---------- -----------
     24523          8      16743         1         6   2002001          1           0

上面的结果中,FLAG也是按位表示的标示,最右边的1(即最低位的1)表示块是脏块(dirty buffer,从v$gbh的视图定义也能看到)。而LRU_FLAG=6表示buffer仍然还在REPL_AUX链上。

7. 在数据库上不做任何操作,过一段时间(大约5分钟之后),DBW进程会将刚才更改的脏块写到磁盘,再次检查X$BH:

SQL> select obj,dbarfil,dbablk,to_char(state,'xxxxxxxx') state,to_char(lru_flag,'xxxxxxxx') lru_flag,to_char(flag,'xxxxxxxx') flag

  2  ,tch,dirty_queue from x$bh where obj=24523 and dbablk=16743 order by dbablk;

       OBJ    DBARFIL     DBABLK STATE     LRU_FLAG  FLAG             TCH DIRTY_QUEUE
---------- ---------- ---------- --------- --------- --------- ---------- -----------
     24523          8      16743         1         6   2202000          1           0

在上面的结果中可以看到,LRU_FLAG仍然为6,表示仍然在REPL_AUX链上,而FLAG最低位从原来的1变成了0,表示已经不是脏块了。FLAG的从左向边第2个“2”数字(原来是0)表示"Buffer has been written once(缓冲区已经写过)"。

从上面的测试可以表明,在REPL_AUX链上是可能存在脏块的。不过REPL_AUX链上存在脏块的可能性非常小,其原因在于,REPL_AUX链上主要是很少被再次访问的块:一致性读的块不可能被修改;大表的全表扫描的块(“大表”的概念在《Oracle Core》这本书中有提到,主要涉及_small_table_threshold这个隐含参数),很少有对整个大表的所有块进行修改;WRITE_AUX链上的buffer在写完后会放回REPL_AUX链,不过这样的块被重新修改的可能性较小,因为WRITE_MAIN和WRITE_AUX的块来源于REPL链上较早之前修改过并且很少被访问的块,从概率上说被再次修改的可能性很小。所以REPL_AUX链上通常都是可以马上能够被重用的buffer。

通过类似的测试还可以说明两点:

  1. buffer在三个LRU子链(REPL_MAIN/REPL_AUX/WRITE_MAIN/)上移动,主要是由进程在寻找可用的buffer时由该进程移动。而buffer在另三个LRU子链(WRITE_MAIN/WRITE_AUX/REPL_AUX)上的移动由数据库写进程(DBW)来完成。这里要说明的是,DBW进程只有在是由前台进程触发的数据库写操作之后才会将buffer从WRITE_AUX移到REPL_AUX链上,而由检查点触发的写操作,不会使buffer在LRU的链上移动。
  2. 只有进程在读磁盘或通过clone产生一致性读需要buffer时,才会扫描LRU链并使buffer在LRU的四个子链上移动,而update这类DML操作在修改内存中的块时,是不会使buffer在LRU四个子链上移动的,所以如果REPL_AUX链上的buffer修改了,它也不会移动,仍然在REPL_AUX链上,使得REPL_AUX链上出现脏块。

--the end

,

《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

,

Oracle数据库在安装了2012年1月发布的CPU或PSU补丁之后,经常出现下面一些现象:

  • 应用出现ORA-19706: invalid SCN错误。
  • 在alert日志中出现类似于:
    Wed May 30 15:09:57 2012
    Advanced SCN by 68093 minutes worth to 0x0ba9.4111a520, by distributed transaction remote logon, remote DB:xxxx.
    Client info : DB logon user xxxx, machine xxxx, program oracle@xxxx (J001), and OS user oracle
    这样的警告。
  • 在alert日志中出现类似于:
    Wed May 30 12:02:00 2012
    Rejected the attempt to advance SCN over limit by 166 hours worth to 0x0ba9.3caec689, by distributed transaction remote logon, remote DB: xxxx.
    Client info : DB logon user xxxx, machine xxxx, program oracle@xxxx (J000), and OS user oracle
    这样的错误信息。
  • 在alert日志中出现类似于:
    Sat Mar 17 05:57:45 2012
    ALTER DATABASE OPEN
    ************************************************************
    Warning: The SCN headroom for this database is only 38 days!
    ************************************************************
    这样的信息。
  • 在MOS文档《ORA-19706 and Related Alert Log Messages [ID 1393360.1]》中还提到其他会出现在alert中的一些警告信息:
    Warning - High Database SCN: Current SCN value is 0x0b7b.0008e40b, threshold SCN value is 0x0b75.055dc000, If you have not previously reported this warning on this database, please notify Oracle Support so that additional diagnosis can be performed.
    WARNING: This patch can not take full effect until this RAC database has been completely shutdown and restarted again.Oracle recommends that it is done at the earliest convenience.

如果说以上的现象只是警告或应用级报错,影响范围有限,那么不幸的是如果遇到RECO进程在恢复分布式事务时遇到SCN问题,则可能使数据库宕掉,例如:


Wed May 30 14:44:02 2012
Errors in file /oracle/admin/miboss/bdump/xxxx_reco_225864.trc:
ORA-19706: invalid SCN
Wed May 30 14:44:02 2012
Errors in file /oracle/admin/miboss/bdump/xxxx_reco_225864.trc:
ORA-00600: internal error code, arguments: [18348], [0x000000000], [485331304561], [], [], [], [], []
.........
RECO: terminating instance due to error 476
Intance terminated by RECO, pid s= 225864

那么2012年1月发布的CPU或PSU补丁到底使数据库在SCN处理方面产生了什么样的变化?这种变化对数据库有什么危害吗?甚至于说,以上提示的信息是由于这个补丁的BUG引起的吗?

要回答这些问题,得先从SCN讲起。SCN可以说是Oracle中的很基础,但同时也是很重要的东西,它是一个单向增长的“时钟”,广泛应用于数据库的恢复、事务ACID、一致性读还有分布式事务中。那么除了这些,SCN还有以下一些知识点:

  • SCN的内部存储方式:在Oracle内部,SCN分为两部分存储,分别称之为scn wrap和scn base。实际上SCN长度为48位,即它其实就是一个48位的整数。只不过可能是由于在早些年通常只能处理32位甚至是16位的数据,所以人为地分成了低32位(scn base)和高16位(scn wrap)。为什么不设计成64位,这个或许是觉得48位已经足够长了并且为了节省两个字节的空间:)。那么SCN这个48位长的整数,最大就是2^48(2的48次方, 281万亿,281474976710656),很大的一个数字了。
  • Maximum Reasonable SCN:在当前时间点,SCN最大允许达到(或者说最大可能)的SCN值。也称为Reasonable SCN Limit,简称RSL。这个值是一个限制,避免数据库的SCN无限制地增大,甚至达到了SCN的最大值。这个值大约是这样一个公式计算出来的:(当前时间-1988年1月1日)*24*3600*SCN每秒最大可能增长速率。当前时间减1988年1月1日的结果是天数,24表示1天24小时,3600表示1小时3600秒。不过这个公式里面“当前时间-1988年1月”部分并不是两个时间直接相减,而是按每月31天进行计算的(或许是为了计算简单,因此在Oracle内部可能要频繁地计算,这个计算方法可以在安装了13498243这个补丁后得到的scnhealthcheck.sql文件中看到,《Installing, Executing and Interpreting output from the "scnhealthcheck.sql" script [ID 1393363.1]》这篇MOS文档解释了这个脚本的使用及对结果的解释,实际上直接看脚本代码更为清楚)。那么SCN最秒最大可能增长速率是多少呢,这个跟Oracle版本有一定的关系,在11.2.0.2之前是16384(即16K),在11.2.0.2及之后版本是32768(即32K)。在11.2.0.2的版本中有一个隐含参数,_max_reasonable_scn_rate,其默认值就是32768(不建议调整这个值)。如果按16K的最大值,SCN要增长到最大,要超过500年。
  • SCN Headroom:这个是指Maximum Reasonable SCN与当前数据库SCN的差值。在alert中通常是以“天”为单位,这个只是为了容易让人读而已。天数=(Maximum Reasonable SCN-Current SCN)/16384/3600/24。这个值就的意思就是,如果按SCN的每大增长速率,多少天会到达Maximum Reasonable SCN。但实际上即使如此,也不会到达Maximum Reasonable SCN,因为到那时Maximum Reasonable SCN也增大了(越时间增大),要到达Maximum Reasonable SCN,得必须以SCN最大可能速率的2倍才行。
  • SCN的异常增长:通常来说,每秒最大允许的16K/32K增长速率已经足够了,但是不排除由于BUG,或者人为调整导致SCN异常增长过大。特别是后者,比如数据库通过特殊手段强制打开,手工把SCN递增得很大。同时Oracle的SCN会通过db link进行传播。如果A库通过db link连接到B库,如果A库的SCN高于B库的SCN,那么B库就会递增SCN到跟A库一样,反之如果A库的SCN低于B库的SCN,那么A库的SCN会递增到跟B库的SCN一样。也就是说,涉及到db link进行操作的多个库,它们会将SCN同步到这些库中的最大的SCN。
  • 那么,如果是数据库本身操作而不是通过db link同步使得SCN的增长,其增长速率如何判断呢,这个可以通过系统的统计量“calls to kcmgas”和"DEBUG calls to kcmgas"来得到。kcmgas的意思是get and advance SCN,即获取并递增SCN。
  • 在两个库通过db link进行分布式事务时,假设B库的SCN值要高于A库的SCN,因此要将B库的SCN增同步到A库,但是如果B库的SCN过高,这样同步到A库之后,使得A库面临Headroom过小的风险,那么A库会拒绝同步SCN,这个时候就会报ORA-19706: Invalid SCN错误。分布式事务,或者说是通过db link的操作就会失败,即使是通过db link的查询操作。这里显然有一个阈值,如果递增SCN使得Headroom过小到什么值时,就会拒绝递增(同步)SCN?目前来看是这样:如果打了2012年1月CPU或PSU补丁,11.2.0.2及以后的版本,是1天即24小时,其他版本是31天即744小时,打了补丁之后可以由隐含参数_external_scn_rejection_threshold_hours来调整。而没有打补丁的情况下,视同此参数设为0,实际最小为1小时。由于Oracle 9.2.0.8没有了最新的补丁集,显示也不会有这个参数,保持默认为1小时。注意这是一个静态参数。所以打了2012年1月CPU或PSU补丁的一个重要变化是增加了_external_scn_rejection_threshold_hours参数,同时使11.2.0.2以下版本的数据库其Headroom的阈值增得较大。这带来的影响就是ORA-19706的错误出现的概率更高。解决的办法将_external_scn_rejection_threshold_hours这个隐含参数设置为较小的值,推荐的值是24,即1天。从_external_scn_rejection_threshold_hours这个参数名的字面意思结合它的作用,可以说这个参数就是”拒绝外部SCN“的阈值。对于数据库自身产生的SCN递增是没有影响的。
  • 虽然11.2.0.2及之后的版本,其默认的每秒最大可能SCN增长速率为32K,这使得Maximum Reasonable SCN更大,也就是说其SCN可以增长到更大的值。那也就是可能会使11.2.0.2的库与低版本的数据库之间不能进行db link连接。或者是11.2.0.2的库不能与16K速率的(比如调整了_max_reasonable_scn_rate参数值)的11.2.0.2的库进行db link连接。

现在是时候来回答以下几个问题了:

  • 2012年1月后发布的CPU或PSU补丁到底使数据库在SCN处理方面产生了什么样的变化?答案是:增加了_external_scn_rejection_threshold_hours参数,11.2.0.2及以上版本的这个参数默认值是24,其他版本默认值是744。这样使11.2.0.2以下版本的数据库其Headroom的阈值增得较大。
  • 这种变化对数据库有什么危害吗?答案是:在一个具有很多系统的大型企业环境里面,db link使用很多,甚至有一些不容易管控到的数据库也在跟关键系统通过 db link进行连接,在这样的环境中,过高的SCN扩散到关键系统,而系统如果打了这个补丁,其Headroom阈值变大,那么就更容易出现ORA-19706错误,对db link依赖很严重的系统可能会导致业务系统问题,严重情况下甚至会宕库。不过通过设置隐含参数_external_scn_rejection_threshold_hours可解决这样的问题。所以,如果你安装了2012年1月的CPU或PSU补丁,请尽快设置此参数为建议的值24,极端情况下你可以设置为1。
  • alert中的那些提示或警告信息是BUG引起的吗?答案是:这些提示或警告不是BUG引起的。它只是提醒你注意SCN过高增长,或者是你的Headroom较小(在Headroom小于62天时可能会提醒),引起你的重视。实际上根据MOS文档《System Change Number (SCN), Headroom, Security and Patch Information [ID 1376995.1]》的说法,这个补丁修复了SCN相关的一些BUG。如果非要说BUG,可以勉强认为补丁安装后新增的参数_external_scn_rejection_threshold_hours其默认值过大。Bug 13554409 - Fix for bug 13554409 [ID 13554409.8]就是说的这个问题。不过这个问题已经在2012年4月的CPU或PSU补丁中得到修复。

在最后我们来解读一下alert日志中的一些信息:

  • 信息:
    Wed May 30 15:09:53 2012
    Completed crash recovery at
    Thread 1: logseq 3059, block 19516, scn 12754630269552
    2120 data blocks read, 2120 data blocks written, 19513 redo blocks read
    .....
    Wed May 30 15:09:57 2012
    Advanced SCN by 68093 minutes worth to 0x0ba9.4111a520, by distributed transaction remote logon, remote DB:xxxx.
    Client info : DB logon user xxxx, machine xxxx, program oracle@xxxx (J001), and OS user oracle
    这里是说,SCN向前(跳跃)递增了68098分钟,其递增后的SCN是0x0ba9.4111a520。注意这里的分钟的计算就是根据SCN每秒最大可能增长速率为16K来的。我们计算一下:
    0x0ba94111a520转换成10进制12821569053984。
    在alert日志中,这个信息是刚打开数据库的时候,所以 crash recovery完成时的scn可以做为近似的当前SCN,其值为12754630269552:
    (12821569053984-12754630269552)/16384/60=68093.65278320313
    这里16384值的是SCN每秒最大可能增长速率,可以看到计算结果极为接近。

    我们再来计算一下这个SCN的headroom是多少:

    SQL>    select
      2     ((((
      3      ((to_number(to_char(cur_date,'YYYY'))-1988)*12*31*24*60*60) +
      4      ((to_number(to_char(cur_date,'MM'))-1)*31*24*60*60) +
      5      (((to_number(to_char(cur_date,'DD'))-1))*24*60*60) +
      6      (to_number(to_char(cur_date,'HH24'))*60*60) +
      7      (to_number(to_char(cur_date,'MI'))*60) +
      8      (to_number(to_char(cur_date,'SS')))
      9      ) * (16*1024)) - 12821569053984)
     10     / (16*1024*60*60*24)
     11     ) headroom
     12     from (select to_date('2012-05-30 15:09:57','yyyy-mm-dd hh24:mi:ss') cur_date from dual);
    
      HEADROOM
    ----------
    24.1496113
    

    可以看到结果为24天,由于这个时候_external_scn_rejection_threshold_hours参数值为24,即1天,所以虽然有这么大的跳跃,但SCN仍然增长成功。

  • 信息:
    Wed May 30 12:02:00 2012
    Rejected the attempt to advance SCN over limit by 166 hours worth to 0x0ba9.3caec689, by distributed transaction remote logon, remote DB: xxxx.
    Client info : DB logon user xxxx, machine xxxx, program oracle@xxxx (J000), and OS user oracle
    在这个信息中,拒绝了db link引起的SCN增加。计算一下这个SCN的headroom:
    0x0ba93caec689转换成10进制是12821495465609
    当前时间是2012-05-30 12:02:00,

    SQL>    select
      2     ((((
      3      ((to_number(to_char(cur_date,'YYYY'))-1988)*12*31*24*60*60) +
      4      ((to_number(to_char(cur_date,'MM'))-1)*31*24*60*60) +
      5      (((to_number(to_char(cur_date,'DD'))-1))*24*60*60) +
      6      (to_number(to_char(cur_date,'HH24'))*60*60) +
      7      (to_number(to_char(cur_date,'MI'))*60) +
      8      (to_number(to_char(cur_date,'SS')))
      9      ) * (16*1024)) - 12821495465609)
     10     / (16*1024*60*60*24)
     11     ) headroom
     12     from (select to_date('2012-05-30 12:02:00','yyyy-mm-dd hh24:mi:ss') cur_date from dual);
    
      HEADROOM
    ----------
    24.0710752
    

    由于这个时候_external_scn_rejection_threshold_hours参数值为744,即31天,计算出的headroom在这个阈值之内,因此拒绝增加SCN。
    (31-24.0710752)*24=166.2941952,正好是166小时。

--update on 2012/6/2--
实际上2012年1月的CPU或PSU补丁之后还会有下面的变化:

  1. _minimum_giga_scn这个隐含没有了,可惜了这个手工增加SCN的利器。
  2. 11.2.0.2及之后的版本,从原来的32K SCN最大速率调整回了16K速率。可以用下面的SQL来得到结果:
    SQL&gt select decode(bitand(DI2FLAG,65536),65536,'Y','N') using16 
      2   from x$kccdi2;
    
    U
    -
    Y
    

    上面的SQL的结果只有在11.2.0.2及以上版本才有意义,结果为Y,表示使用的是16K的速率,否则是使用32K速率。

本文涉及的一些参数,和SCN的一些算法,可能会随着版本或补丁的变化而产生较大的变化。

important update: 实际上在Jan 2012的PSU/CPU补丁中存在较大的SCN BUG,目前已经不建议打这个补丁集,而是打到更高的PSU补丁集上。

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