开发人员在进行新系统上线前的数据校验测试时,发现一条手工执行的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.2版本的RAC数据库的服务器上,连接了多个public网络,那么就会有如下的需求:

  1. 给其他的,或者说是新的public网络增加新的VIP地址。
  2. 在新的public网络上增加SCAN VIP.
  3. 在新的VIP地址上配置监听
  4. 在新的SCAN VIP地址上配置监听

实际上从11.2版本开始,grid infrastructure(以下可能会简写为GI)就是一个完整的clusterware,不仅仅是用于数据库,也可以用作应用软件的高可用性。上述的4个需求中,第1个是毫无疑问需要的;第2个需求对运行在grid infrastructure上的应用是必要的;第3个需求在运行在grid infrastructure上的数据库来说是必要的;第4个需求,是针对数据库的,这个需求有点难度,因为在一套grid infrastructure中只能允许有一个SCAN LISTENER的存在,由于可以不通过SCAN IP而是直接通过VIP地址连接数据库,所以这个新的SCAN监听可以不需要,但是为了完整,我们可以用变通的方法来实现。

下面我们用一个实例来演示如何实现上述的所有需求。

先简单介绍一下用于演示的环境:11.2.0.1 grid infrastructure for linux 32bit,共2个节点,节点名是xty3和xty4,没有使用DNS(实际上在有DNS的环境下,也不太可能会有第2个public network),所以下面的演示是以没有DNS来配置的。Grid Infrastructure用的是oracle用户安装的(实际生产建议用单独的grid用户),而RDBMS软件也是用oracle安装的。目前的private network是192.168.153.0,对应的网卡设备名是en1,public network是192.168.0.0,对应的网卡设备名是en0,打算新增加的public network是192.168.76.0,对应的网卡设备名是en2。

先看看/etc/hosts文件的内容:

127.0.0.1    localhost.localdomain localhost
::1             localhost6.localdomain6 localhost6
192.168.0.134   xty3
192.168.0.144   xty4
192.168.153.134 xty3-priv
192.168.153.144 xty4-priv
192.168.0.135   xty3-vip
192.168.0.145   xty4-vip
192.168.0.155   xty-cluster-svip1

第1步,配置好新的public network的IP地址和网络路由。注意新的public network IP地址配好后,注意配置好网络路由。

第2步,在所有的节点上编辑/etc/hosts文件,增加如下内容:

192.168.76.134   xty3-pub2
192.168.76.144   xty4-pub2
192.168.76.135   xty3-vip2
192.168.76.145   xty4-vip2
192.168.76.155   xty-cluster-svip2

192.168.76.134和192.168.76.144是两个节点上新的public network的public ip,192.168.76.135和192.168.76.145是相对应的VIP地址,而192.168.76.155则是准备要在新的public network上增加的SCAN IP。而xty-cluster-svip2则是新增的SCAN名字。

第3步,增加新的public network上的vip地址,这一步比较简单,用root用户执行下面的命令:

srvctl add vip -n xty3 -k 2 -A xty3-vip2/255.255.255.0/eth2
srvctl add vip -n xty4 -k 2 -A xty4-vip2/255.255.255.0/eth2

在上述命令中,-n参数后面跟的是节点名(hostname); -k后面的参数表示第几个网络,这里是2,表示第2个public network。-A后面就是VIP地址的属性了,格式为"VIP地址名/子网/网卡设备名"。

然后用crsctl来检查,vip资源已经存在:

[root@xty3 ~]# crsctl stat res -t | egrep "vip|network"
ora.net1.network
ora.net2.network
ora.scan1.vip
ora.xty3-vip2.vip
ora.xty3.vip
ora.xty4-vip2.vip
ora.xty4.vip

[root@xty3 ~]# srvctl config vip -n xty3
VIP exists.:xty3
VIP exists.: /xty3-vip2/192.168.76.135/255.255.255.0/eth2
VIP exists.:xty3
VIP exists.: /xty3-vip/192.168.0.135/255.255.255.0/eth0

[root@xty3 ~]# srvctl config vip -n xty4
VIP exists.:xty4
VIP exists.: /xty4-vip2/192.168.76.145/255.255.255.0/eth2
VIP exists.:xty4
VIP exists.: /xty4-vip/192.168.0.145/255.255.255.0/eth0

ora.net2.network,ora.xty3-vip2.vip,ora.xty4-vip2.vip都是新增的资源。然后使用下面的命令启动新增的VIP:

Read the rest of this entry

,

在以前我写的一篇文章《Oracle与防火墙》中提到,网络防火墙会切断长时间空闲的TCP连接,这个空闲时间具体多长可以在防火墙内部进行设置。防火墙切断连接之后,会有下面的可能:

  • 切断连接之前,连接对应的Oracle会话正在执行一个耗时特别长的SQL,比如存储过程而在此过程中没有任何数据输出到客户端,这样当SQL执行完成之后,向客户端返回结果时,如果TCP连接已经被防火墙中断,这时候显然会出现错误,连接中断,那么会话也就会中断。但是客户端还不知道,会一直处于等待服务器返回结果的状态。
  • 切断连接之前,Oracle会话一直处于空闲状态,在防火墙中断之后,客户端向Oracle服务器提交SQL时,由于TCP连接已经中断,这时客户端侦测到连接中断,那么客户端就会报ORA-3113/ORA-3114这类错误,然后会话中断。但是在Oracle服务器端,会话一直在处于等待客户端消息的状态。
  • 当然,如果服务器和客户端都一直闲着,没有任何消息往来,那么客户端和客户端的会话就一直存在,直到客户端发送消息即提交SQL到Oracle服务器。

从上面的前面2种情况来看,防火墙切断数据库TCP连接,引起的后果就会有:

  • 客户端报ORA-3113/3114错误,对这于长连接的后台应用不是个好事,特别是对那种C/C++开发的后台应用没有重连机制,就会出现问题或者程序退出。如果应用在一个较长的时间内没有任何活动,而这个时间超过了防火墙的设置,那应用的连接被中断。
  • 对于有连接池或重连机制的应用,如果连接池过大,导致空闲连接过多,或者是防火墙的连接断开时间过短同时应用太闲,那么连接频繁地被中断,而在数据库服务器端,则连接越来越多,即会话数越来越多,甚至最终超过了数据为最大连接数。
  • 其他一些影响,比如你在跑一个脚本而长时间没有输出,结果防火墙切断了连接,你之前的工作就白做,当然这些影响范围都较小。

那么如何防止出现以上的问题? 对于没有重连机制的长连接应用,临时的解决办法是调大防火墙的连接切断时长;或者应用端在闲时定期执行一条类似于select 1 from dual这样的SQL;或者在Oracle服务端开启DCD功能,而DCD(死连接检测,即Dead Connection Detection)的时间长度短于防火墙的连接切断时长;或者使用操作系统的tcp keep-alive功能。对于有重连机制或有连接池的应用,为了避免数据库端连接数满,可以使用DCD或tcp keep-alive功能,如果DCD或TCP keep-alive的时间短于防火墙连接切断时长,那么连接将不会中断,因为防火墙视连接为活动状态(不过按MOS文档的说法,DCD的包有可能被防火墙忽略,即用DCD使连接保持活动状态可能没有作用)。而如果DCD或TCP keep-alive的时间长于防火墙连接切断时长,那么连接被中断的会话和进程将得到清理。

这里简单介绍一下TCP keep-alive,顾名思议,就是让TCP连接保持存活状态,这是由TCP协议层实现的功能,也是在TCP连接空闲时间超过设置的时间,就会发送探测包,因此,这个功能跟Oracle的DCD是极为类似的,所不同的是,这是由协议层实现的功能,是不能通过trace应用进程来跟踪包的发送。

理论是完美的,而现实差距越很远。

下面是一个有关的案例。一套运行在AIX 5.3上的RAC数据库,数据库版本为10.2.0.4,这套数据库在sqlnet.ora文件中有设置sqlnet.expire_time=5,后果却是,数据库的连接数过几天就要满一次,防火墙设置的时间是8小时,也就是说只会切断空闲时间超过8小时的连接,这个时间已经足够长,晚上系统太闲,总会有部分连接空闲时间过长,但是由于设置了DCD,连接应该不会被防火墙切断,而即使防火墙切断了连接,那么在DCD的作用下,数据库服务器端的会话和进程也应该被清理才是,即使DCD不起作用,那TCP keep-alive也应该起作用才是,那为什么会话和进程数越来越多,甚至达到了最大进程数或会话数呢?

检查应用服务器(weblogic)的连接池,并核对应用服务器到数据库的TCP连接,发现连接池监控中的连接数量并不多,而对比应用服务器上看到的到数据库数据库的TCP连接数量和数据库数据器上看到的应用服务器建立过来的TCP连接数量,二者之间差距非常大,前者远远小于后者,就是说,大量的连接已经被切断,应用服务器的连接已经退出,但是数据库端的连接还没有释放。从weblogic的日志来看,经常出现类似于连接失效并建立新的数据库连接这样的信息。

DCD为什么没有起作用,是不是DCD的BUG?DCD的确是有很多BUG,但是完全不工作的BUG应该是很少的。将sqlnet.expire_time设为1,5以及其他值,都不起作用,甚至重启过主机都没有起作用(当然并不是专门为了DCD而重启主机)。

使用truss命令来跟踪Oracle进程:


SQL> host
$ truss -p 828090
kread(0, 0x0000000000000000, 0) (sleeping...)
...很长时间没有任何反应...
^CPstatus: process is not stopped
$ 
$ exit

SQL> oradebug setospid 828090
Oracle pid: 247, Unix process pid: 828090, image: oracle@db2
SQL> oradebug short_stack 
ksdxfstk+002c<-ksdxcb+04e4<-sspuser+0074<-000044C0<-nttrd+0120<-nsprecv+07a0<-nsrdr+0114<-nsdo+1710<-nsbrecv+0040<-nioqrc+04a8<-opikndf2+0688<-opitsk+08a8<-opiino+0990<-opiodr+0ae0<-opidrv+0484<-sou2o+0090<-opimai_real+01bc<-main+0098<-__start+0098
SQL>  oradebug short_stack
ksdxfstk+002c<-ksdxcb+04e4<-sspuser+0074<-000044C0<-nttrd+0120<-nsprecv+07a0<-nsrdr+0114<-nsdo+1710<-nsbrecv+0040<-nioqrc+04a8<-opikndf2+0688<-opitsk+08a8<-opiino+0990<-opiodr+0ae0<-opidrv+0484<-sou2o+0090<-opimai_real+01bc<-main+0098<-__start+0098

没有看到DCD起任何作用的迹象,使用truss跟踪其他多个空闲Oracle也是如此。

那么TCP keep-alive呢,怎么样来判断有没有起作用?在AIX上其答案是使用kdb(这个需要root用户权限)。

在笔记本电脑上使用sqlplus连接到数据库,在数据库主机上使用netstat -Aan | grep 1521 | grep “你的IP地址”,以获得sqlplus连接的TCP连接信息,显示的第1列是一串16数据,然后使用kdb:

#kdb 
The specified kernel file is a 64-bit kernel
Preserving 1418178 bytes of symbol table
First symbol __mulh
           START              END <name >
0000000000001000 0000000003E5C050 start+000FD8
F00000002FF47600 F00000002FFDC940 __ublock+000000
000000002FF22FF4 000000002FF22FF8 environ+000000
000000002FF22FF8 000000002FF22FFC errno+000000
F100070F00000000 F100070F10000000 pvproc+000000
F100070F10000000 F100070F18000000 pvthread+000000
PFT:
PVT:
id....................0002
raddr.....0000000002000000 eaddr.....F200800090000000
size..............00080000 align.............00001000
valid..1 ros....0 fixlmb.1 seg....0 wimg...2
Command enhancement entry point is called.

 Welcome to VXDRV subcommands 
Command enhancement entry for vxodmdb called.called.

 Welcome to vxdrv subcommands 
(0)> sockinfo f100060009b04398 tcpcb | egrep "KEEP|opts"
    t_timer....... 00000000 (TCPT_KEEP)
    timewait.prv@0000000000000000  inp_v6opts  @0000000000000000  
    opts........ 0004 (REUSEADDR)   

可以看到,这个TCP连接没有KEEPALIVE选项(属性),keep-alive对应的timer(TCPT_KEEP)数值为0,表示没有设置timer时间。
会不会是DCD功能屏蔽了TCP keep-alive?
将sqlnet.ora中expire_time设置去掉,然后重复上述步骤,这次有了变化:

#kdb  
The specified kernel file is a 64-bit kernel
Preserving 1418178 bytes of symbol table
First symbol __mulh
           START              END <name >
0000000000001000 0000000003E5C050 start+000FD8
F00000002FF47600 F00000002FFDC940 __ublock+000000
000000002FF22FF4 000000002FF22FF8 environ+000000
000000002FF22FF8 000000002FF22FFC errno+000000
F100070F00000000 F100070F10000000 pvproc+000000
F100070F10000000 F100070F18000000 pvthread+000000
PFT:
PVT:
id....................0002
raddr.....0000000002000000 eaddr.....F200800090000000
size..............00080000 align.............00001000
valid..1 ros....0 fixlmb.1 seg....0 wimg...2
Command enhancement entry point is called.

 Welcome to VXDRV subcommands 
Command enhancement entry for vxodmdb called.called.

 Welcome to vxdrv subcommands 
(0)> sockinfo f100060009c1b398 tcpcb | egrep "KEEP|opts"
    t_timer....... 00000464 (TCPT_KEEP)
    timewait.prv@0000000000000000  inp_v6opts  @0000000000000000  
    opts........ 000C (REUSEADDR|KEEPALIVE)

可以看到,这个TCP连接已经有了KEEPALIVE选项(属性),同时keep-alive timer为16进制数464,即十进制1124,表示还有562秒(timer这里的时间以半秒为单位)就会发送keep-alive探测包。

反复通过加上DCD设置和去掉DCD设置进行测试,发现只要一加上DCD功能,那么Oracle进程就不会为TCP连接设置keep-alive选项(属性),反之则会设置keep-alive。从这里很明显地看出来,DCD功能开启后,不但没有起作用,还关闭了TCP keep-alive功能。

对于这套系统,最后去掉了DCD设置,并将所有的空闲连接清理掉,经过多天的观察,系统的连接数一直保持稳定,与应用服务器的实际连接数保持一致。

那是不是启用了DCD之后,TCP keep-alive就会被关闭,这里不能贸然下定论,不同的版本、不同的平台或许有差异,至少我一个同事在Linux上测试时,tcp keep-alive是共存的。

在诊断处理这个案例的过程之中,不得不提到另外一点,写在此处,与大家分享。在诊断问题的初期阶段,询问系统维护人员(通常连应用和数据库一起维护),应用服务器和数据库之间是否有防火墙,如果有,是怎么样设置的TCP连接断开时间。而维护人员最开始的回答是没有防火墙。从表面上看,也应该是没有防火墙。数据库服务器其中一个IP地址是192.168.8.42,而两台应用服务器服务器的IP地址是192.168.8.201和192.168.8.202,咋一看是在同一网段,中间应该不会有防火墙。然而仔细检查相关数据:

$ifconfig -a
....省略部分输出....
en4: flags=5e080867,c0<up ,BROADCAST,DEBUG,NOTRAILERS,RUNNING,SIMPLEX,MULTICAST,GROUPRT,64BIT,CHECKSUM_OFFLOAD(ACTIVE),PSEG,LARGESEND,CHAIN>
        inet 192.168.8.42 netmask 0xffffff80 broadcast 192.168.8.127
        inet 192.168.8.43 netmask 0xffffff80 broadcast 192.168.8.127
         tcp_sendspace 131072 tcp_recvspace 65536 rfc1323 0

可以看到,实际上数据库跟应用服务器是在不同的子网之中。这里子网掩码为0xffffff80,也就是我们通常写的子网掩码255.255.255.128,这样0-127为一个子网,128-255为一个子网(当然子网的第1个和最后一个地址都是不能使用的)。那么最后一个数字为201和202的两个IP地址显然就在第2个子网中,子网之间仍然需要有路由功能的网络设备,那么在之间有防火墙也是有可能的。用上面的方法去检查应用服务器的网络配置,发现其被划在了更小的子网之中。系统维护人员最终确认应用服务器和数据库之间的确是有防火墙存在。因此我们可以总结出两点:1,全面的知识对诊断数据库问题很有帮助。2, 如果经过详尽分析问题发现与别人说的不一致,需要坚持,并需要为自己的坚持寻找更多的数据来证实。

--The End--

,

如同我在《我们应该怎样安装Oracle数据库?》这一篇文章提及,只要安装Oracle软件的时候严格按文档操作,通常不会遇到太大的问题。但是,现实环境总是那么复杂,在一些新的软件组合或者是新的版本上进行安装,容易遇到一些比较复杂的或者说是解决起来不是那么容易的问题。本文将要描述的就是在这样一个环境下的安装:HP-UX 11.31 IA64、Symantec SFRAC、Oracle 10g RAC。当安装CRS运行root.sh时,一直挂起,也就是说,root.sh一直过不去。下面列出这个问题的解决过程,供朋友们参考。

先来看看运行root.sh得到输出:

cwxndb01:[/oracle/app/oracle/product/crs]#./root.sh
WARNING: directory '/oracle/app/oracle/product' is not owned by root
WARNING: directory '/oracle/app/oracle' is not owned by root
WARNING: directory '/oracle/app' is not owned by root
WARNING: directory '/oracle' is not owned by root
Checking to see if Oracle CRS stack is already configured
Checking to see if any 9i GSD is up

Setting the permissions on OCR backup directory
Setting up NS directories
Oracle Cluster Registry configuration upgraded successfully
WARNING: directory '/oracle/app/oracle/product' is not owned by root
WARNING: directory '/oracle/app/oracle' is not owned by root
WARNING: directory '/oracle/app' is not owned by root
WARNING: directory '/oracle' is not owned by root
Successfully accumulated necessary OCR keys.
Using ports: CSS=49895 CRS=49896 EVMC=49898 and EVMR=49897.
node <nodenumber>: <nodename> <private interconnect name> <hostname>
node 0: cwxndb01 cwxndb01-priv cwxndb01
Creating OCR keys for user 'root', privgrp 'sys'..
Operation successful.
Now formatting voting device: /dev/vx/rdsk/vgdata01/lv_vote_128m_01
Now formatting voting device: /dev/vx/rdsk/vgdata02/lv_vote_128m_02
Now formatting voting device: /dev/vx/rdsk/vgdata03/lv_vote_128m_03
Format of 3 voting devices complete.
Startup will be queued to init within 30 seconds.

然后就在显示完"Startup will be queued to init within 30 seconds"之后就一直挂起。在安装CRS运行root.sh时,一般失败的情形是报错然后退出,很少有一直挂起的。

为了解决一个未知的问题,我们通常分为3步,了解当前正在做什么,当前所做的为什么会引起问题,解决问题。那么现在,我们需要知道的是root.sh这个脚本正在做什么,执行到了哪里。

  • 使用"ps -ef | grep root.sh"命令,找到root.sh的pid,然后再寻找这个pid的子进程,一直定位到最末端,发现当前正在运行的命令是"sleep 60",而"sleep 60"的上级命令是"init.cssd startcheck CSS"。
  • root.sh的核心其实在于$ORA_CRS_HOME/install/rootconfig这个脚本,在这个文件中,我们根据上述线索,找到下面的代码:
    # Prepare to start the daemons.
    $ID/init.crs start
    
    # Check to see if they are going to start.
    $ID/init.cssd startcheck CSS
    if [ "$?" != "0" ]; then
      $ECHO CRS daemons not set to start. See $MSGFILE for details.
      exit 1
    fi
    

    实际上运行root.sh的输出中的"Startup will be queued to init within 30 seconds.",正是init.crs start的显示。从root.sh当前运行的子进程来看,目前正在运行"$ID/init.cssd startcheck CSS"这一命令。所以接下来我们需要知道在这一个命令里面会一直挂起。

在HP-UX操作系统中,init.cssd在/sbin/init.d目录下,我们可以发现init.cssd也是一个比较复杂的脚本。为了搞清楚一个shell脚本执行到了哪里出了问题,我们可以使用sh -x以调试方式运行shell脚本。(实际上在分析root.sh当前正在进行的操作时,我们同样可以用sh -x ./root.sh这样的命令来运行。)

我们手工执行如下的命令:

 
   cd /sbin/init.d
   sh -x init.cssd startcheck CSS

然后发现在下面的代码中32-37行代码处挂起:


# check on vendor clusterware and filesystem dependencies.
# Startcheck is supposed to block for a long time waiting on dependencies.
'startcheck') # Returns 0 if we should start
              # Returns 1 on a non-cluster boot
              # Returns 2 if disabled by admin
              # Returns 3 on error

    # Check our startup run status, initialized by the automatic startup
    # or manual startup routes.
    $ID/init.cssd runcheck
    STATUS=$?
    if [ "$STATUS" != "0" ]; then
      exit $STATUS;
    fi

    # If we have vendor clusterware, and CLINFO indicates a non-clustered boot
    # then prevent CRS startup.
    if [ $USING_VC -eq 1 ]
    then
      # Run CLINFO to get cluster status. It returns 0 if the machine is
      # booting in clustered mode.
      $EVAL $CLINFO
      if [ "$?" != "0" ]; then
        $LOGMSG "Oracle Cluster Ready Services disabled by non-clustered boot."
        $ID/init.cssd norun
        exit 1;
      fi

      # Wait for the Vendor Clusterware to start
      $EVAL $VC_UP
      RC=$?
      while [ $RC -ne 0 ]; do
        $LOGMSG "Oracle Cluster Ready Services waiting for $VC_NAME to start."
        $SLEEP $DEP_CHECK_WAIT
        $EVAL $VC_UP
        RC=$?
      done
    fi

32-37行代码是一个循环,从代码注释上看,是在等待Vendor Clusterware启动。如果一直没有启动,就一直循环,也就是一直挂起。代码”$EVAL $VC_UP“用于判断Vendon Clusterware是否已启动。这里$VC_UP是什么值呢,在文件中搜索代码,可以找到如下的代码:

HP-UX) MACH_HARDWARE=`/bin/uname -m`
       CLUSTERDIR=/opt/nmapi/nmapi2
       if [ "$MACH_HARDWARE" = "ia64" ]; then
          SO_EXT=so
          NMAPIDIR_64=$CLUSTERDIR/lib/hpux64
       else
          SO_EXT=sl
          NMAPIDIR_64=$CLUSTERDIR/lib/pa20_64
       fi
       LD_LIBRARY_PATH=$ORA_CRS_HOME/lib:$NMAPIDIR_64:/usr/lib:$LD_LIBRARY_PATH
       export LD_LIBRARY_PATH
       # Presence of this file indicates that vendor clusterware is installed
       SKGXNLIB=${NMAPIDIR_64}/libnmapi2.${SO_EXT}
       if [ -f $SKGXNLIB ]; then
         USING_VC=1
       fi

       VC_UP="$PSEF | $GREP '/usr/lbin/cm[g]msd' 1>$NULL 2>$NULL"
       # NOTE: Not supporting Hardware partitioning machines.
       REBOOT_TOC="/var/opt/oracle/bin/reboot_toc"
       if [ -x $REBOOT_TOC ]; then
       FAST_REBOOT="$REBOOT_TOC || /usr/sbin/reboot -r -n -q"
       SLOW_REBOOT="/bin/kill -HUP `$CAT /var/run/syslog.pid` ; /bin/sync & $SLEEP 2 ; $REBOOT_TOC || /usr/sbin/reboot -r -n -q"
       else
         FAST_REBOOT="/usr/sbin/reboot -r -n -q"
         SLOW_REBOOT="/bin/kill -HUP `$CAT /var/run/syslog.pid` ; /bin/sync & $SLEEP 2 ; /usr/sbin/reboot -r -n -q"
       fi
       DFL_CLSINFO=$CLUSTERDIR/bin/clsinfo
       if [ $USING_VC -eq 0 ]; then
          # We are not using vendor clusterware.
          VC_NAME=""
          VC_UP=/bin/true
          CLINFO=/bin/true
          # We do not have a slow reboot without vendor clusterware
          SLOW_REBOOT=$FAST_REBOOT
       elif [ -f $DFL_CLSINFO ]; then
          # We are using Generic HP Vendor Clusterware
          VC_NAME="Generic HP-UX Vendor Clusterware"
          VC_UP=/bin/true
          CLINFO=$DFL_CLSINFO
       else
          # We are using HPUX ServiceGuard Clusterware
          VC_NAME="HP-UX Service Guard"
          CLINFO=/bin/true
       fi

       ID=/sbin/init.d

以上一段代码的主要意思是:如果存在/opt/nmapi/nmapi2/libnmapi2.so文件,那么表示系统使用了Vendor Clusterware,也就是使用了第三方集群软件。如果存在/opt/nmapi/nmapi2/bin/clsinfo文件,则表示系统使用了其他的第三方集群软件,并且该文件可以执行用于判断是否已经启动Vendor Clusterware,即VC_UP=/opt/nmapi/nmapi2/bin/clsinfo。如果不存在该文件,表示系统使用的是HP ServiceGuard,那么VC_UP="$PSEF | $GREP '/usr/lbin/cm[g]msd' 1>$NULL 2>$NULL" ,即判断cm开头的一些进程是否在运行,用来判断Service Guard是否在运行。从sh -x执行结果来看,脚本认为系统用的是Service Guard,很显然,这个是错误的,一直在等待Service Guard启动,那这样很明显就会一直等待而挂起。

那么到目前为止,可以知道是由于错误地判断了Vendor Clusterware引起了问题,那么用于判断Vendor Clusterware的文件/opt/nmapi/nmapi2/bin/clsinfo应该不存在于系统中。/opt/nmapi/nmapi2/bin目录下的确没有clsinfo这个文件。而/opt/nmapi/nmapi2/lib目录下存在相应的库文件:

cwxndb01:[/opt/nmapi/nmapi2/lib/hpux64]#ll
total 0
lr-xr-xr-x   1 bin        bin             27 Jul 18 13:33 libnmapi2.so -> /usr/lib/hpux64/libvcsmm.so

可以看到库文件用的是symantec sfrac的库文件。
而bin目录下没有任意文件,看起来应该是symantec sfrac安装的BUG。

那怎么样来解决这个问题呢,知道了原因,解决就很简单了:

cwxndb01:[/opt/nmapi/nmapi2]#cd /opt/nmapi/nmapi2/bin
cwxndb01:[/opt/nmapi/nmapi2/bin]#ln -s /opt/VRTSvcs/ops/bin/clsinfo

只需要在这个目录下建一个链接即可。做完上述操作后,再清理掉环境,重新运行root.sh,一切顺利。

这个问题引起的根本原因,看起来是Symantec SFRAC安装的一个bug。不过总的来说,新版本的SFRAC环境下安装RAC数据库已经方便很多,跟普通方式安装CRS没有任何区别,而早期版本的SFRAC环境下安装RAC,需要使用SFRAC提供的专用界面进行安装。

--The End---

,

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

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

下面是AWR报告中的数据:

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

Read the rest of this entry

,

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

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

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

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

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

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

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

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

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

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

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

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

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

Read the rest of this entry

提起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.

客户一套运行在Oracle 10.2.0.5 RAC上的系统,间歇性地出现性能问题。其性能现象为前台反映性能缓慢,从系统上看CPU利用率大幅增加,load增加。这种性能问题通常在出现几分钟后自动恢复正常。

从AWR中的TOP 5等待来看:

Top 5 Timed Events                                         Avg %Total
~~~~~~~~~~~~~~~~~~                                        wait   Call
Event                                 Waits    Time (s)   (ms)   Time Wait Class
------------------------------ ------------ ----------- ------ ------ ----------
latch: cache buffers lru chain      774,812     140,185    181   29.7      Other
gc buffer busy                    1,356,786      61,708     45   13.1    Cluster
latch: object queue header ope      903,456      55,089     61   11.7      Other
latch: cache buffers chains         360,522      49,016    136   10.4 Concurrenc
gc current grant busy               112,970      19,893    176    4.2    Cluster
          -------------------------------------------------------------

可以看到,TOP 5中,有3个是latch相关的等待,而另外2个则是跟RAC相关的等待。
如果再查看更细的等待数据,可以发现其他问题:


                                                                  Avg
                                            %Time  Total Wait    wait     Waits
Event                                 Waits -outs    Time (s)    (ms)      /txn
---------------------------- -------------- ----- ----------- ------- ---------
latch: cache buffers lru cha        774,812   N/A     140,185     181       1.9
gc buffer busy                    1,356,786     6      61,708      45       3.3
latch: object queue header o        903,456   N/A      55,089      61       2.2
latch: cache buffers chains         360,522   N/A      49,016     136       0.9
gc current grant busy               112,970    25      19,893     176       0.3
gcs drm freeze in enter serv         38,442    97      18,537     482       0.1
gc cr block 2-way                 1,626,280     0      15,742      10       3.9
gc remaster                           6,741    89      12,397    1839       0.0
row cache lock                       52,143     6       9,834     189       0.1

从上面的数据还可以看到,除了TOP 5等待,还有"gcs drm freeze in enter server mode“以及"gc remaster"这2种比较少见的等待事件,从其名称来看,明显与DRM有关。那么这2种等待事件与TOP 5的事件有没有什么关联?。MOS文档"Bug 6960699 - "latch: cache buffers chains" contention/ORA-481/kjfcdrmrfg: SYNC TIMEOUT/ OERI[kjbldrmrpst:!master] [ID 6960699.8]”提及,DRM的确可能会引起大量的"latch: cache buffers chains"、"latch: object queue header operation"等待,虽然文档没有提及,但不排除会引起”latch: cache buffers lru chain“这样的等待。

为了进一步证实性能问题与DRM相关,使用tail -f命令监控LMD后台进程的trace文件。在trace文件中显示开始进行DRM时,查询v$session视图,发现大量的 "latch: cache buffers chains" 、"latch: object queue header operation"等待事件,同时有"gcs drm freeze in enter server mode“和"gc remaster"等待事件,同时系统负载升高,前台反映性能下降。而在DRM完成之后,这些等待消失,系统性能恢复到正常。

看起来,只需要关闭DRM就能避免这个问题。怎么样来关闭/禁止DRM呢?很多MOS文档提到的方法是设置2个隐含参数:

_gc_affinity_time=0
_gc_undo_affinity=FALSE

不幸的是,这2个参数是静态参数,也就是说必须要重启实例才能生效。
实际上可以设置另外2个动态的隐含参数,来达到这个目的。按下面的值设置这2个参数之后,不能完全算是禁止/关闭了DRM,而是从”事实上“关闭了DRM。

_gc_affinity_limit=250
_gc_affinity_minimum=10485760

甚至可以将以上2个参数值设置得更大。这2个参数是立即生效的,在所有的节点上设置这2个参数之后,系统不再进行DRM,经常一段时间的观察,本文描述的性能问题也不再出现。

下面是关闭DRM之后的等待事件数据:

Top 5 Timed Events                                         Avg %Total
~~~~~~~~~~~~~~~~~~                                        wait   Call
Event                                 Waits    Time (s)   (ms)   Time Wait Class
------------------------------ ------------ ----------- ------ ------ ----------
CPU time                                         15,684          67.5
db file sequential read           1,138,905       5,212      5   22.4   User I/O
gc cr block 2-way                   780,224         285      0    1.2    Cluster
log file sync                       246,580         246      1    1.1     Commit
SQL*Net more data from client       296,657         236      1    1.0    Network
          -------------------------------------------------------------
          
                                                                  Avg
                                            %Time  Total Wait    wait     Waits
Event                                 Waits -outs    Time (s)    (ms)      /txn
---------------------------- -------------- ----- ----------- ------- ---------
db file sequential read           1,138,905   N/A       5,212       5       3.8
gc cr block 2-way                   780,224   N/A         285       0       2.6
log file sync                       246,580     0         246       1       0.8
SQL*Net more data from clien        296,657   N/A         236       1       1.0
SQL*Net message from dblink          98,833   N/A         218       2       0.3
gc current block 2-way              593,133   N/A         218       0       2.0
gc cr grant 2-way                   530,507   N/A         154       0       1.8
db file scattered read               54,446   N/A         151       3       0.2
kst: async disk IO                    6,502   N/A         107      16       0.0
gc cr multi block request           601,927   N/A         105       0       2.0
SQL*Net more data to client       1,336,225   N/A          91       0       4.5
log file parallel write             306,331   N/A          83       0       1.0
gc current block busy                 6,298   N/A          72      11       0.0
Backup: sbtwrite2                     4,076   N/A          63      16       0.0
gc buffer busy                       17,677     1          54       3       0.1
gc current grant busy                75,075   N/A          54       1       0.3
direct path read                     49,246   N/A          38       1       0.2

那么,这里不得不提的是,什么是DRM?DRM对系统来说有什么好处?本文不再详述,因为下面的2篇文档已经描述得比较清楚,有兴趣的朋友可以参考:

关于本文所使用的2个隐含参数,在上述第二篇文档中也有详细描述。
--END---

当一个存储过程所依赖(引用的)对象发生某些更改时,会使得存储过程失效(invalidated),比如存储过程依赖(引用)的表增加减少了列、存储过程依赖(引用)的存储过程被重新编译。本文将介绍一种特殊的会引起存储过程失效的情况。

下面通过测试来演示与DB LINK相关的存储过程失效的情况:

1. 在TEST用户下创建到db1的DB LINK:

SQL> create database link to_db connect to perfstat identified by xxx using 'db1';

数据库链接已创建。

2.在TEST2用户下创建到db2的DB LINK,DB LINK的名称仍然为to_db,但实际上连接的数据库与TEST用户下to_db这个DB LINK连接的数据库并不是同一个数据库:

SQL> create database link to_db connect to perfstat identified by xxx using 'db2';

数据库链接已创建。

3. 在TEST用户下创建存储过程TEST_P1:

SQL> create or replace procedure test_p1
  2  is
  3    v_dbid number;
  4  begin
  5    select dbid into v_dbid from stats$snapshot@to_db where rownum<2;
  6  end;
  7  /

过程已创建。

SQL> select object_id,status from user_objects where object_name='TEST_P1';

 OBJECT_ID STATUS
---------- ----------
     18443 VALID

4. 在TEST2用户下创建存储过程TEST2_P1,这里存储过程TEST2_P1的代码与TEST用户下存储过程TEST_P1的代码明显不同。这两个存储过程的共同点是都引用了STATS$SNAPSHOT@TO_DB这个远程表。由于TEST和TEST2用户下TO_DB连接的是不同的数据库,因此这2个存储过程引用的STATS$SNAPSHOT@TO_DB位于不同的数据库上,也就是说是不同的表

SQL> create or replace procedure test2_p1
  2  is
  3    v_snap_time date;
  4  begin
  5    select snap_time into v_snap_time from stats$snapshot@to_db where rownum<2;
  6  end;
  7  /

过程已创建。

SQL> select object_id,status from user_objects where object_name='TEST2_P1';

 OBJECT_ID STATUS
---------- ----------
     18445 VALID

5. 在TEST用户下查看存储过程TEST_P1的状态,发现其状态为INVALID,而实际上这个时候这个存储过程以及其引用的对象没有任何变更:

SQL> select object_id,status from user_objects where object_name='TEST_P1';

 OBJECT_ID STATUS
---------- ----------
     18443 INVALID

6. 如果重新编译TEST.TEST_P1,那么其状态会成为VALID,但是这个时候TEST2.TEST2_P1则又莫名其妙地变成为INVALID:

SQL> alter procedure test.test_p1 compile;

过程已更改。

SQL> select object_id,owner,object_name,status from dba_objects 
  where object_name in ('TEST_P1','TEST2_P1');

 OBJECT_ID OWNER           OBJECT_NAME                    STATUS
---------- --------------- ------------------------------ ----------
     18443 TEST            TEST_P1                        VALID
     18445 TEST2           TEST2_P1                       INVALID

7. 在TEST2用户下执行存储过程TEST2_P1,然后再次检查存储过程状态:

SQL> exec test2_p1

PL/SQL 过程已成功完成。

SQL> select object_id,owner,object_name,status from dba_objects
  2  where object_name in ('TEST_P1','TEST2_P1');

 OBJECT_ID OWNER           OBJECT_NAME                    STATUS
---------- --------------- ------------------------------ ----------
     18443 TEST            TEST_P1                        INVALID
     18445 TEST2           TEST2_P1                       VALID

可以看到,TEST.TEST_P1失效了,而TEST2.TEST2_P1又正常了。

在这里就可以提出问题了:为什么创建了TEST2.TEST2_P1这个存储过程之后,TEST.TEST_P1就失效了?为什么TEST.TEST_P1重新编译之后TEST2.TEST2_P1又失效了?为什么TEST2.TEST2_P1重新执行(有一个隐式的编译过程)后,TEST.TEST_P1又失效了?

其实上以上三个问题可以归纳为一个问题:为什么TEST.TEST_P1和TEST2.TEST2_P1这2个存储过程,在其中一个状态正常的情况下,另一个为失效状态?

Read the rest of this entry

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

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


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

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

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

方法一:使用oradebug。

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

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

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

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


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

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

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

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

SQL> select owner from t where object_id=3003;

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

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

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

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

Read the rest of this entry

,