星期二 三月 25, 2014

如何利用RMAN Debug和10046 Trace来诊断RMAN问题?

     在做Support的这些年,我很大的收获是掌握了许多troubleshooting问题的方法和工具,对于每一类问题,都可以大体归类出一些诊断方法。无论问题多么复杂,像扒洋葱一样,一层层去掉无关的,留下关键的,同时借助于一些诊断工具,层层深入,最后找到问题的核心。

     在这篇文章中,我想介绍一下如何对RMAN的问题做debug。 我们借助于下面这个场景,说明如何Debug RMAN 问题


在11.2.0.4上,物理备库上执行归档备份时,出现了下面的错误:

[oracle@test1 ~]$ rman target /

Recovery Manager: Release 11.2.0.4.0 - Production on Tue Mar 25 13:58:59 2014

Copyright (c) 1982, 2011, Oracle and/or its affiliates.  All rights reserved.

connected to target database: R11204 (DBID=2001766638, not open)

RMAN> backup archivelog all;

Starting backup at 25-MAR-14
using target database control file instead of recovery catalog
RMAN-06820: WARNING: failed to archive current log at primary database<==============报错无法连接到主库
Connect identifier for DB_UNIQUE_NAME R11204 not configured

allocated channel: ORA_DISK_1
channel ORA_DISK_1: SID=1 device type=DISK
channel ORA_DISK_1: starting archived log backup set
channel ORA_DISK_1: specifying archived log(s) in backup set
input archived log thread=1 sequence=58 RECID=1 STAMP=842172838  <==============后面的归档备份还是成功的
input archived log thread=1 sequence=59 RECID=2 STAMP=842172838
input archived log thread=1 sequence=60 RECID=3 STAMP=842172928
input archived log thread=1 sequence=61 RECID=4 STAMP=842173275
input archived log thread=1 sequence=62 RECID=5 STAMP=842175748
input archived log thread=1 sequence=63 RECID=6 STAMP=842182033
input archived log thread=1 sequence=64 RECID=7 STAMP=842185463
input archived log thread=1 sequence=65 RECID=9 STAMP=842432288
input archived log thread=1 sequence=66 RECID=8 STAMP=842432286
input archived log thread=1 sequence=67 RECID=10 STAMP=842432291
input archived log thread=1 sequence=68 RECID=11 STAMP=842432322
channel ORA_DISK_1: starting piece 1 at 25-MAR-14
channel ORA_DISK_1: finished piece 1 at 25-MAR-14
piece handle=/u01/app/oracle/fast_recovery_area/SDY/backupset/2014_03_25/o1_mf_annnn_TAG20140325T135903_9m2hlj0p_.bkp tag=TAG20140325T135903 comment=NONE
channel ORA_DISK_1: backup set complete, elapsed time: 00:00:03
Finished backup at 25-MAR-14


注:11.2.0.4有一个新的特性,就是备库上备份归档时,它会连接到主库上,让主库进行一次log switch,所以上面的错误是备库无法连接到主库进行log switch,上面最主要的错误是“Connect identifier for DB_UNIQUE_NAME R11204 not configured ”,看起来是备库要连接主库时需要用到的连接串没有配置正确。这时我们的疑问是这个连接串是在哪里设置的?


首先我们用一下Rman Debug:

[oracle@test1 ~]$ rman target / debug trace=/tmp/rman_debug
RMAN>  backup archivelog all;

RMAN-03090: Starting backup at 25-MAR-14
RMAN-06009: using target database control file instead of recovery catalog
RMAN-06820: WARNING: failed to archive current log at primary database
RMAN-06613: Connect identifier for DB_UNIQUE_NAME R11204 not configured
...


针对生成的/tmp/rman_debug,我们发现连接串用了为空“lprimary_db_cs = NULL”

DBGSQL:       TARGET> begin   :lprimary_db_cs :=     sys.dbms_backup_restore.get_connect_identifier       (dbuname=> :primary_dbunam
e); end;
DBGSQL:          sqlcode = 0
DBGSQL:           B :lprimary_db_cs = NULL《==========这是主库的连接串
DBGSQL:           B :primary_dbuname = R11204
  DBGRCVMAN: getConfig: configurations exists for this site
RMAN-06820: WARNING: failed to archive current log at primary database
DBGMISC:      ENTERED krmkursr [14:08:50.007]

也就是RMAN调用了一个内部的包 sys.dbms_backup_restore.get_connect_identifier来获得在备库连接主库时需要用到的串。这时我们需要知道这个串是在哪里设置的,为何为空。

接下来,针对RMAN进行10046 trace:

[oracle@test1 ~]$ rman target / debug trace=/tmp/rman_debug

Recovery Manager: Release 11.2.0.4.0 - Production on Mon Mar 17 09:00:00 2014

Copyright (c) 1982, 2011, Oracle and/or its affiliates.  All rights reserved.

RMAN-06568: connected to target database: R11204 (DBID=2001766638, not open)

RMAN> sql "alter session set tracefile_identifier=''rman_10046''";

RMAN-06009: using target database control file instead of recovery catalog
RMAN-06162: sql statement: alter session set tracefile_identifier=''rman_10046''

RMAN> sql "alter session set events ''10046 trace name context forever,level 12''";

RMAN-06162: sql statement: alter session set events ''10046 trace name context forever,level 12''

RMAN> backup archivelog all;
RMAN-03090: Starting backup at 25-MAR-14
RMAN-06820: WARNING: failed to archive current log at primary database
RMAN-06613: Connect identifier for DB_UNIQUE_NAME R11204 not configured
...


查看生成的trace file,这个文件在udump下:
$cd /u01/app/diag/rdbms/sdy/SDY/trace
$ls -ltr
-rw-r----- 1 oracle oinstall 1037463 Mar 25 14:11 SDY_ora_3792_rman_10046.trc

PARSING IN CURSOR #140366085001120 len=119 dep=0 uid=0 oct=47 lid=0 tim=1395736859520777 hv=3388798669 ad='7ec65738' sqlid='7pwt2c34
ztxqd'
begin   :lprimary_db_cs :=     sys.dbms_backup_restore.get_connect_identifier       (dbuname=> :primary_dbuname); end;
END OF STMT
PARSE #140366085001120:c=0,e=285,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,plh=0,tim=1395736859520776
BINDS #140366085001120:
 Bind#0
  oacdty=01 mxl=2000(1536) mxlc=00 mal=00 scl=00 pre=00
  oacflg=01 fl2=1000000 frm=01 csi=873 siz=2128 off=0
  kxsbbbfp=7fa986a27f08  bln=2000  avl=00  flg=05
 Bind#1
  oacdty=01 mxl=128(90) mxlc=00 mal=00 scl=00 pre=00
  oacflg=01 fl2=1000000 frm=01 csi=873 siz=0 off=2000
  kxsbbbfp=7fa986a286d8  bln=128  avl=06  flg=01
  value="R11204"
*** ACTION NAME:(0000018 STARTED189) 2014-03-25 14:10:59.521

WAIT #140366085001120: nam='control file sequential read' ela= 10 file#=0 block#=1 blocks=1 obj#=-1 tim=1395736859521532
WAIT #140366085001120: nam='control file sequential read' ela= 4 file#=0 block#=16 blocks=1 obj#=-1 tim=1395736859521566
WAIT #140366085001120: nam='control file sequential read' ela= 4 file#=0 block#=18 blocks=1 obj#=-1 tim=1395736859521580
WAIT #140366085001120: nam='control file sequential read' ela= 4 file#=0 block#=281 blocks=1 obj#=-1 tim=1395736859521594
WAIT #140366085001120: nam='control file sequential read' ela= 4 file#=0 block#=1 blocks=1 obj#=-1 tim=1395736859521614
WAIT #140366085001120: nam='control file sequential read' ela= 3 file#=0 block#=16 blocks=1 obj#=-1 tim=1395736859521627
WAIT #140366085001120: nam='control file sequential read' ela= 2 file#=0 block#=18 blocks=1 obj#=-1 tim=1395736859521638
WAIT #140366085001120: nam='control file sequential read' ela= 3 file#=0 block#=281 blocks=1 obj#=-1 tim=1395736859521650
krsd_get_primary_connect_string: found pcs '' by FAL_SERVER lookup <====================用FAL_SERVER找到了连接串''


所以这个10046 trace,很清楚地告诉我们它是从参数FAL_SERVER上获得了连接串''。

这时,连接到备库,查看参数FAL_SERVER,它的值的确为空:
SQL> show parameter fal

NAME                                 TYPE        VALUE
------------------------------------ ----------- ------------------------------
fal_client                           string
fal_server                           string 

到此,我们通过RMAN debug和10046 trace,获得了我们想要的信息。

总结一下:

如果在执行RMAN命令后,遇到了性能问题或者需要深入跟踪一个错误,那么可以考虑使用rman debug:

$ rman target <connection> catalog <connection> debug trace=/tmp/rmanDebug.trc log=/tmp/rmanLog.txt
run {
...Run your backup commands here
}


如果还需要跟进一步的跟踪可以再使用10046 trace:

$ rman target <connection> catalog <connection> debug trace=/tmp/rmanDebug.trc log=/tmp/rmanLog.txt
RMAN> sql "alter session set tracefile_identifier=''rman_10046''";
RMAN> sql "alter session set events ''10046 trace name context forever,level 12''";
RMAN> run-your-commands;
RMAN> exit;


需要注意的是,上面的这些方法可能会生成大量文件,需要考虑对磁盘空间的压力以及对RMAN的性能的影响。


可以参考MOS文档:RMAN: Quick Debugging Guide (Doc ID 1198753.1)

星期五 三月 21, 2014

如何诊断rac环境下sysdate 返回错误时间问题

最近处理了一些rac环境下访问sysdate返回错误时间的问题,而这种问题往往出现在数据库链接是通过Listener创建的情况下,而且,大部分情况下都是和时区设置相关的。在这篇文章中我们会针对如何诊断这种问题进行解释。这篇文章适用于版本11.2.0.2 及以上版本。

首先,对问题当中涉及到的知识进行介绍。
1. 从版本11.2.0.2 开始oracle 集群(GI)开始拥有了自己的时区和一些其他配置,这些配置保存在配置文件<gi_home>/crs/install/s_crsconfig_<节点名>_env.txt中。
例如:
TZ=Asia/Shanghai
NLS_LANG=AMERICAN_AMERICA.AL32UTF8
TNS_ADMIN=
ORACLE_BASE=
我们能看到变量TZ 用于定义集群的时区。当然,这个集群的时区是在安装GI时从操作系统获得的。既然集群有了时区,那么我们就需要保证GI的时区和操作系统的设置是一致的,并且当操作系统的时区发生改变时,GI的时区也需要改变。而修改集群时区的基本步骤是(修改<gi_home>/crs/install/s_crsconfig_<节点名>_env.txt文件,重启节点)。
2. 当数据库或者listner 使用srvctl 命令或者随着GI启动被启动时,环境变量会继承GI的时区。您也可以通过下面的命令来手动设置数据库和listener资源的环境变量。
srvctl setenv database -d <dbname> -t 'TZ=<时区>'
srvctl setenv listener -l <listenername> -t 'TZ=<时区>'
3. sysdate返回的值并不依赖于数据库的时区设置,oracle 只是简单的从操作系统获取系统时间返回(例如:调用os 函数gettimeofday)。所以,修改数据库的时区对于这种问题并没有帮助。而对应的服务器进程所使用的环境变量TZ才会影响返回的系统时间。


接下来,我们简单介绍一下客户端通过listener 连接到数据库时会经过那些过程。我们会通过一个具体的例子来解释。在这个例子中,我们使用sqlplus 创建数据库链接,并对listener进程搜集truss 信息

1.客户端连接数据库
sqlplus scott/tiger@test
2.listner 进程收到了对应的链接,并产生了对应的server process.
524732: psargs: /u01/app/11.2.0/grid/bin/tnslsnr LISTENER -inherit
......
524732: kfork() = 496094
496094: kfork() (returning as child ...) = 0
......
496094: kfork() = 483742
483742: kfork() (returning as child ...) = 0
3. 为server process指定环境变量。
483742: execve(0x0FFFFFFFFFFF2660, 0x0000000110773730, 0x000000011077B670) argc: 2
483742: argv: oracle<sid name> (LOCAL=NO) <<<<<<<< 服务器进程环境变量被指定
483742: envp: _=/u01/app/11.2.0/grid/bin/oraagent.bin LANG=en_US LOGIN=root
483742: __CLSAGENT_INCARNATION=2 _ORA_AGENT_ACTION=TRUE PATH=
483742: NLS_LANG=AMERICAN_AMERICA.WE8ISO8859P1 __CLSAGENT_USER_NAME=oracle
......
483742: ENV_FILE=/u01/app/11.2.0/grid/crs/install/s_crsconfig_<node name>_env.txt
......
483742: __CLSAGENT_LOGDIR_NAME=crsd PWD=/ TZ=Asia/Shanghai <<<< 时区被指定。

我们能看到环境变量TZ的值在创建服务器进程时会被绑定到server process 中。当然,如果您没有对lisetner 搜集truss 输出。您也可以通过操作系统命令获得对应进程的环境变量,例如:ps eauwww <pid from above>,您可以通过MOS note 373303.1 中的内容获得不同平台的命令。另外,以上的数据库是通过GI agent 启动的,如果数据库是手动启动的(例如:startup 命令),那么,输出会不同。当然, pmon在注册数据库服务到listener时也会将自己的环境变量注册到对应的service上。

所以,在诊断RAC 环境下sysdate 返回错误时间的问题时,我们需要检查以下信息。
1. 操作系统级别的时区设置,并确保操作系统命令date 能返回正确的时间。对于如何查看不同平台的时区设置,请参考note 1209444.1
2. 确认GI 配置文件<gi_home>/crs/install/s_crsconfig_<节点名>_env.txt文件中的变量TZ和操作系统的TZ 设置一致。
3. 确认是否在database或listener资源层面设置了TZ变量。如果设置了,是否和OS,GI的设置是一致的。
4. 另外,server process的环境变量LIBPATH 或 LD_LIBRARY_PATH 也会对oracle访问操作系统函数产生影响。而且GI 的agent进程(适用于版本11.2.0.3 及以上的版本)在启动资源时(例如:database资源)会自动的将进程的以下环境变量清空
LD_LIBRARY_PATH, SHLIB_PATH (HP-UX), LD_LIBPATH_PATH_64 (Solaris), LIBPATH(AIX)
所以,如果您的database是使用srvctl 命令启动的,就需要确认上面的环境变量被设置正确。
例如:srvctl setenv database -d <db_name> -t 'LIBPATH=<gi_home/lib>'
注意:不同的Unix平台,以上命令可能会不同。
所以,我们也去要确认database 资源的LIBPATH 或 LD_LIBRARY_PATH 变量是否被设定。
例如:srvctl getenv database -d <db_name>
另外,在诊断这种问题时,需要搜集以下信息。
1. <gi_home>/crs/install/s_crsconfig_<节点名>_env.txt文件
2. 操作系统时区设置(cat /etc/sysconfig/clock) 和环境变量TZ的设置。以及pmon进程的环境变量。
3. database和 listener资源的环境变量
例如:srvctl getenv database -d <db_name>
srvctl getenv listener -l <listener name>
4. 如果以上的信息没有问题,那么就需要搜集listener 进程的truss(或strace) 输出找到有问题的环境变量设置。
5. 如果1—4 中的信息仍然无法找到问题的原因,请搜集客户端和服务器端的sqlnet trace,以便确认是否有任何的’alter session set ...’命令修改了会话的时区或者相关的变量。
客户端sqlnet trace:设置以下参数到客户端的sqlnet.ora 文件中。
trace_level_client=16
trace_directory_client=c:\tmp ==> 确保该路径存在
trace_file_client=client
trace_unique_client=on
trace_timestamp_client=on
服务器端sqlnet trace:设置以下参数到服务器端的sqlnet.ora文件中
trace_level_server=16
trace_file_server=server
trace_directory_server=/tmp ==> 确保该路径存在
trace_timestamp_server=ON


希望以上的解释对大家诊断类似问题会有所帮助。

星期一 一月 20, 2014

RAC等待事件:gc buffer busy acquire









概述
---------------------
gc buffer busyRAC数据库中常见的等待事件,11g开始gc buffer  busy分为gc buffer busy acquiregc buffer  busy release

gc buffer busy acquire是当session#1尝试请求访问远程实例(remote  instance) buffer,但是在session#1之前已经有相同实例上另外一个session#2请求访问了相同的buffer,并且没有完成,那么session#1等待gc buffer busy acquire

gc buffer busy release是在session#1之前已经有远程实例的session#2请求访问了相同的buffer,并且没有完成,那么session#1等待gc buffer busy release

原因/解决方法
---------------------
- 热点块(hot block)
AWRSegments by Global Cache Buffer Busy 记录了访问频繁的gc buffer.
解决方法可以根据热点块的类型采取不同的解决方法,比如采取分区表,分区索引,反向index等等。这点与单机数据库中的buffer busy waits类似。

- 低效SQL语句
低效SQL语句会导致不必要的buffer被请求访问,增加了buffer busy的机会。在AWR中可以找到TOP SQL。解决方法可以优化SQL语句减少buffer访问。这点与单机数据库中的buffer busy waits类似。

- 数据交叉访问。
RAC数据库,同一数据在不同数据库实例上被请求访问。
如果应用程序可以实现,那么我们建议不同的应用功能/模块数据分布在不同的数据库实例上被访问,避免同一数据被多个实例交叉访问,可以减少buffer的争用,避免gc等待。

- Oracle bug
建议安装Oracle推荐的最新Patch SetPSU
Patch setPSU信息请参考:Oracle Recommended Patches -- Oracle Database (Doc ID 756671.1)

案例分享
---------------------
一个gc buffer busy acquire的案例,和大家分享一下。

- 应用端反映业务处理异常,数据库hang,在第一时间现场DBA收集了hanganalyze (hanganalyze对于分析数据库hang非常重要)

RAC数据库收集hanganalyze的命令:
SQL> conn / as sysdba
SQL> oradebug setmypid
SQL> oradebug unlimit
SQL> oradebug -g all hanganalyze 3

通过hanganalyze我们可以比较容易看到有1000个以上的Chain都有类似的等待关系,比如:

Chain 1 Signature: 'gc current request'<='gc buffer busy acquire'<='enq: TX -  contention'
Chain 2 Signature: 'gc current request'<='gc buffer busy  acquire'<='buffer busy waits'

Chain 1243 Signature: 'gc current request'<='gc buffer busy  acquire'<='enq: TA - contention'
Chain 1244 Signature: 'gc current request'<='gc buffer busy  acquire'<='enq: TA - contention'



Hanganalyze说明数据库中大部分session直接或者间接等待'gc  current request'<='gc buffer busy acquire'。



- 有些情况下dia0 trace文件也会记录hang信息

  inst# SessId  Ser#     OSPID PrcNm Event

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

      1   1152     3  21364904    FG gc buffer busy acquire

      1   2481     3  26607642    FG gc current request

Chain 1 Signature: 'gc current request'<='gc buffer busy acquire'

Chain 1 Signature Hash: 0x8823aa2a 



- 有些情况下dba_hist_active_sess_history也会记录hang信息。


1. 在数据库hang的时间段内,有691个session在等待'enq: TA - contention','enq: TA - contention'的持有者是session#931,serial#39657




2. session#931serial#39657  也是处于等待状态,等待事件是'gc buffer busy acquire',而'gc buffer busy
acquire'
的持有者是session#1324serial#22503



3. session#1324serial#22503  也是处于等待状态,等待事件是'gc current request'




通过分析dba_hist_active_sess_history,也可以得到session等待关系:
'gc current request'<='gc buffer busy  acquire'<='enq: TA - contention'
这个等待关系与hanganalyze是一致的。

- 根据以上分析得到session等待关系,可以确定数据库hang的原因是oracle已知问题Bug
13787307 - Hang in RAC with 'gc current request'<='gc buffer busy acquire'  signature.



- 解决方法:
安装Patch 13787307 或者 设置_gc_bypass_readers=false临时规避这个问题。
另外,在11.2低版本中也有些类似的已知问题,建议安装最新patch set (11.2.0.3/4) + 最新PSU
Patch setPSU信息请参考:Oracle Recommended Patches -- Oracle Database (Doc ID 756671.1)


参与此主题的后续讨论,请回复blog,或者访问我们的中文社区,跟帖"共享:RAC等待事件:gc buffer busy acquire"。 













星期四 十二月 26, 2013

如何分析发生在过去的数据库性能问题

在数据库运行的过程中,我们有时会碰到数据库hung住的问题,在这个时候很多人会选择尽快让它恢复正常而不是找出问题的root cause. 只有在问题被解决后,才意识到需要找到root cause来避免再次碰到相同的问题; 下面就讲讲如何分析发生在过去的数据库性能问题 (这是一篇讲方法论的blog,并没有涉及到具体的案例, 稍后会有更多具体案例的Blog)




1.       首先要申明的是, 对于这样的问题,我们需要有一个正确的期望: 不一定能够找到root cause, 这取决于发生问题时是否收集到了足够的信息.




2.       梳理我们可以收集到的信息, 一般的可以先检查下面的日志


a)       操作系统日志, 参照文档 note 1349613.1 - How To Gather The OS Logs For Each Specific OS Platform


b)       数据库alert log


c)       操作系统resource(CPU, memory, IO, swapping)使用的状况, 推荐使用OSWbb (也可以是nmon等第三方工具)




有的时候可以通过上面的日志找到一些蛛丝马迹, 比如有时alert log中会提示当时有过多的swap活动, 或提示生成了 enqueue/ row cache enqueue 等等的trace, 或提示diag后台进程生成了systemstate dump trace, 那么进一步就是要分析这些trace了;又比如OSWbb的ps输出显示当时有很多和数据库无关的进程在消耗过多的CPU等等, 那么这就证明问题和数据库无关了.




3.       接下来要收集发生问题时间段的AWR report和ASH report


但是往往发生问题后数据库被重起了,那么很不幸AWR report很可能没有发生问题时间段的信息, 那么这样的AWR对我们分析这个问题就没有意义了.


ASH在大部分的情况下都是可以收集到发生问题时间段的信息, 从中可以查到数据库top的等待事件/session; 然后根据具体的问题,进行进一步的分析




4.       如果之前收集到的信息不足以找出问题的原因, 我们还有一个地方可以查,那就是 dba_hist_active_sess_history.


这个视图是用来生成ASH report的, 但是ASH report并没有充分的利用这个视图的强大之处,我们通过分析这个视图的详细数据,往往可以找到问题发生的原因.


可以从宏观和微观两个维度来分析这个视图(用11gR2的dba_hist_active_sess_history做例子):




比如


宏观:


a)       可以按照一段时间内(发生问题的时间段)这些session等待的非空闲等待事件的类型做分类和求和,就可以知道哪种等待事件最严重


b)       可以按照一段时间内(发生问题的时间段)等待最严重事件的这些session所执行的SQL_ID来汇总求和,可以知道哪个SQL跟这个问题相关





微观:


a). 对于某一条dba_hist_active_sess_history的记录,我们可以知道这个session的SESSION_STATE是ON CPU还是WAITING, 如果是ON CPU,那么这个session的event就无意义了; 如果是WAITING, 可以进一步看它的等待事件和BLOCKING_SESSION_STATUS, 如果它是被另一个session阻塞, 那么BLOCKING_SESSION_STATUS这一列就会显示为VALID或 GLOBAL. 然后再检查BLOCKING_INST_ID和BLOCKING_SESSION找到阻塞这个session的是哪里实例上的哪个session


b). 按照SAMPLE_TIME排序,我们可以找到问题发生的具体的时间点 (还是比较精确的)


c). 对某个session, dba_hist_active_sess_history还能揭示更多有用的信息, 比如这个session当前执行的SQL语句的类型(SQL_OPCODE, SQL_OPNAME), 这个session是否在PARSE(IN_PARSE, IN_HARD_PARSE等), 它是什么客户端(PROGRAM, MODULE, ACTION, CLIENT_ID, MACHINE), 它使用的PGA(PGA_ALLOCATED), 它使用的temp空间大小(TEMP_SPACE_ALLOCATED)等等




善于使用 dba_hist_active_sess_history能极大地帮助我们分析问题.但是也要注意dba_hist_active_sess_history不是万能的: 如果最终阻塞别人的session当时并不是active的或者它并没有被ASH记录到dba_hist_active_sess_history中, 我们还是不能知道它当时处于一种什么状况.




结语: 总之, 分析类似的问题就是充分挖掘已有的trace/日志的过程, 但是因为缺少足够的诊断日志/信息,很多时候还是无法找到问题发生的原因. 如果我们确实有需要找到root cause, 那么在发生问题时就需要收集到足够多的信息. 比如hanganalyze, systemstate dump等






参与此主题的后续讨论,可以访问我们的中文社区,跟帖 "如何分析发生在过去的数据库性能问题"。 

星期四 十月 24, 2013

高并发高负载情况下常见的3种性能问题

前言

这篇blog是基于处理oracle数据库性能问题的经验写就,它是对常见的性能问题做的总结,它的适用范围: 高并发高负载的系统. 需要先申明的是: 对于所有的调优的方法,都是有适用范围的; 所以下面提到的所有的内容,请” 批判性”阅读.



1. OS swapping/paging 引发的数据库concurrency方面的性能问题



Oracle数据库在工作的时候, 对于latch/mutex这样的轻量级的”锁”,我们期望它是可以非常快的获取/释放的(这些操作都是对内存的操作,而内存的操作正常时候也确实都是很快的). 但是如果OS发生了大量的swapping/paging的情况下,那么对内存的操作会变慢,那么latch/mutex的操作就会变慢,在并发大的情况下就会发生hung/slow的情况.



引发swapping/paging的常见情况有:

a). 内存短缺

b). 内存并不短缺; 但短时间内, 有大量的新进程分配了很多内存

c). 拷贝大文件/备份数据库 使得操作系统的高速文件缓存突然激增



对应的调优方式:

Lock SGA, 这样SGA(相应的latch/mutex)就会被pin在内存里而不受swapping的影响.

如果在SGA很大的情况下,同时使用large page(hugepage)技术,减少latch/mutex获取/释放的时间.





2. SGA resizing引发的数据库性能问题



在AMM/ASMM内存自动管理的机制下, shared pool和buffer cache及其它几个component可以根据需要自动调整大小,避免ora-4031的错误.但是在高并发的情况下,短时间内频繁的resize的过程会使得一些内存操作(如latch/mutex的获取释放)的时间变长, 有很大几率触发各种latch/mutex争用. 而且如果shared pool被resize时减少的太多,那么latch/mutex的争用也会加剧.



引发这种问题的原因: 

有些是因为bug; 但是从深层次的角度考虑,这种resize的操作不可避免的会对性能有影响,只是影响的程度不同罢了. 而且bug的fix也只是减缓这种操作的impact, 而不能完全避免这种影响.



推荐的调优方式:

1). 设置buffer cache和shared pool的值(在内存自动管理的情况下,这个值会作为最小值)

2). 设置resize的频率不能少于16分钟

alter system set "_memory_broker_stat_interval"=999;



Disable AMM/ASMM也可以作为一个方法,但是缺点是: 碰到ora-4031的几率会比自动内存管理大.



3. DDL引发的数据库性能问题



这种情况只发生在高并发高负载的情况下.

对于一个使用频繁的表做DDL (比如grant, 修改表定义, 收集统计信息等等),那么用到这个表的所有的SQL语句都会被invalidate掉;如果使用这个表的SQL语句很多并且执行频率很快,那么在短时间内需要hard parse 的 SQL语句就会很多. 这就变成了一种 “hardparse storm”, latch/mutex的争用就不可避免, 还有library cache lock/row cache lock也会变多; 严重的时候数据库就会slow/hung.



推荐的调优方式:

不要在负载高的时间段做DDL

参与此主题的后续讨论,可以访问我们的中文社区,跟帖 “高并发高负载情况下常见的3种性能问题"





星期二 九月 17, 2013

RAC 性能诊断实例 --- TX - index contention


最近,很多读者反应,希望能够写一些实际案例分析的文章。这种文章会和大家的实际工作更接近一些。
而且,最近解决了一些RAC 的性能问题。在这里,找到了一个比较有代表性的例子,和大家分享一下,也欢迎大家一起讨论。



问题的症状很明确,在一个双节点的RAC 数据库中,数据库大概hang住了10分钟,之后自动恢复正常了。而且,问题只发生在实例1上,实例2是正常的。



首先,我们搜集了问题期间的实例1 AWR报告(实例2AWR也被搜集了,但是并没有什么异常,所以没有贴出来),发现了以下的信息。



Top 5 Timed Foreground Events



Event Waits Time(s) Avg wait (ms) % DB time Wait
Class


enq: TX - index contention 448 90,738 202540 51.18 Concurrency


enq: US - contention 134,660 64,312 478 36.27 Other


resmgr:cpu quantum 98,992 12,204 123 6.88 Scheduler


gc current grant busy 21,377 7,352 344 4.15 Cluster


latch: enqueue hash chains 2,126 6,422 3021 3.62 Other



我们能看到,等待事件“enq: TX - index contention” 是等待时间最长的事件,而且平均等待时间很长。



Instance Activity Stats


=================


branch node splits 6 0.00 0.00


leaf node 90-10 splits 124 0.09 0.00


leaf node splits 674 0.47 0.00



Segments by Row Lock Waits


=================



Owner Tablespace Name Object Name Subobject
Name Obj. Type Row Lock Waits % of Capture


XXXX XXXX A
INDEX 836 71.03


XXXX XXXX B
INDEX 185 15.72


XXXX XXXX C
INDEX 68 5.78


XXXX XXXX D
TABLE 59 5.01


XXXX XXXX E
TABLE 20 1.70



我们能看到,产生最高的row lock等待时间的对象是一个索引。



另外,客户确认以下的sql 语句是执行最频繁的。


insert into XXXX (......) values (:1, :2, :3, :4, :5, :6,
:7......);



从以上的信息,似乎我们很容易认为这个问题是由于过多的索引块分裂,或者由于过多相近的值被insert 到表里,导致了索引的争用。




但是,在和客户进一步确认后,发现上面的想法应该是错误的,因为我们得到了以下的反馈。


1. 经过和正常性能时的AWR报告相比,等待事件 “enq: TX - index contention” 的确在数据性能正常时没有出现。


2. 和正常性能时的AWR比较后,并没有看到索引分裂有明显增加。


3. 和性能正常时比较,insert语句执行的次数并没有增加。而且,数据库的负载并没有增长。


4. 另外,根据TX等待事件的平均等待时间(202540ms,
也就是超过200), 看起来更象是类似于某些进程hang住导致的。



接下来 ,我们查看了DBA_HIST_ACTIVE_SESS_HISTORY的信息,但是很遗憾,有大概10分钟的信息是空白的。比较幸运的是,问题开始的几分钟还是有信息出现的。所以,我们取到了最初几分钟的ASH报告,并发现,下面的进程阻塞了上面我们提到的insert 语句。


Blocking Sid (Inst) %
Activity Event Caused % Event User Program # Samples Active XIDs


1234, 5678( 1) 46.92
enq: TX - index contention 46.92 XXXX JDBC Thin Client 25/150 [ 17%] 1



另外,根据DBA_HIST_ACTIVE_SESS_HISTORY 中的信息,我们发现上面的blocker进程(1234,
5678( 1)
)一直在等待“latch: object queue header operation”。问题到这一步,有些朋友可能会得出结论,问题是由于DRM导致的,因为等待事件“latch: object queue header
operation
”是在DRM时产生的。但是,我们并没有相关的信息来支持我们的判断,而且,这时候我们只能确认问题和DRM 相关,但是不能确定就是DRM导致的,而是有两种可能性:


1. 问题的确是由于DRM导致的。


2. DRM在问题期间的确发生了,但是由于数据库性能的问题,DRM也是受害者之一。



我们知道,对于DRMlms,lmd lmon进程都会参与。所以,接下来要做的事情是查看这些进程的trace file OSW报告,来确认这些进程的状态。幸运的是,我们很快有了新的发现。


lmon 跟踪文件


......


*** 2013-xx-xx 00:00:00.000


==============================


kjfmHBcheck: LMS0
(ospid: xxxxxx) not moving for 21 sec (1367110915.1367110894)


: Not in wait; last wait ended 0 secs ago.


: last wait_id 655230104 at 'latch: gc
element'.



*** 2013-xx-xx 00:00:00.000


==============================


kjfmHBcheck: LMS1
(ospid: xxxxxx) not moving for 20 sec (1367110916.1367110896)


: Not in wait; last wait ended 0 secs ago.


: last wait_id 671495420 at 'latch: gc
element'.



看起来lms 进程的确有性能问题。


lms 跟踪文件


......


*** 2013-xx-xx 00:00:00.000


DRM(516) win(1) lms 0
finished replaying gcs resources


kjfmHBupdateTime: took
33 seconds for 255 heartbeats


lms 0 finished fixing
gcs write protocol



*** 2013-xx-xx 00:00:00.000


DRM(517) win(1) lms 0
finished replaying gcs resources



*** 2013-xx-xx 00:00:00.000


lms 0 finished fixing
gcs write protocol



*** 2013-xx-xx 00:00:00.000


SKGXP_TRACE_FLUSH:
output truncated 11 traces lost


SKGXP_TRACE_FLUSH:
start


SKGXP: (16520 <-
7836)SKGXPDOCON:can't accept new connections under timed wait context


SKGXP: (16520 <-
7390)SKGXPDOCON:can't accept new connections under timed wait context


SKGXP: (16520 <-
7404)SKGXPDOCON:can't accept new connections under timed wait context


SKGXP: (16520 <-
9004)SKGXPDOCON:can't accept new connections under timed wait context


SKGXP: (16520 <-
9089)SKGXPDOCON:can't accept new connections under timed wait context


SKGXP: (16520 <-
7344)SKGXPDOCON:can't accept new connections under timed wait context


SKGXP: (16520 <-
7470)SKGXPDOCON:can't accept new connections under timed wait context


SKGXP: (16520 <-
9495)SKGXPDOCON:can't accept new connections under timed wait context


SKGXP: (16520 <-
7676)SKGXPDOCON:can't accept new connections under timed wait context


SKGXP: (16520 <-
9192)SKGXPDOCON:can't accept new connections under timed wait context


SKGXP: (16520 <-
8758)SKGXPDOCON:can't accept new connections under timed wait context


SKGXP_TRACE_FLUSH: end


看起来,lms的确能够完成DRM的工作,但是正在忙于接受新的数据库链接。对于RAC数据库,当新的数据库连接被建立时lms进程需要在实例之间对新的会话进行一些数据的传递,这是正常的。而且,虽然客户没有安装OSW,但是从客户安装的第三方操作系统监控软件,我们发现在问题期间lms进程占用了100% cpu时间。


所以,我们可以看到,DRM并不是导致问题的原因,而是受害者之一。而问题的真正的原因可能有以下的两种可能。


1. 过多的数据库连接导致lms 忙于处理新的数据库连接,而无法处理其他的请求。


2. Oracle 存在bug,导致了lms 进程在处理新的连接时spin 在了某个地方。这种判断的主要依据是lms进程占用了100% cpu,这说明lms进程很忙。


最后,我们搜集到了问题期间的listener 日志。但是无法拿到lms进程的堆栈信息(diag lmon进程并没dump
lms
进程的堆栈信息,而且客户也没有在问题期间搜集lms进程的pstack信息输出)。接下来,问题的原因水落石出----“连接风暴”。因为我们在问题出现之前的大概5分钟到问题结束,每分钟会有大概300个链接尝试连接数据库,而在正常期间,每分钟大概只有10个链接左右。当连接风暴结束之后,数据库也恢复正常运行了。


总结:实际工作中我们会遇到很多常见的问题,可以利用经验进行判断,并直接给出所谓的原因和解决方案,而且有时候的确是正确的。但是,从oracle support的角度来讲,在诊断问题过程中,我们需要的是了解在问题期间系统到底发生了什么,同时运用我们的知识来进行分析,并且找到相应的证据支持自己的分析,最后找到问题真正的原因,并给出相应的解决方案。而且,即使我们不能得到足够的信息进行完整的分析,我们也需要利用我们的知识和已有的信息,来给出问题可能的原因和比较“靠谱”的解决方案,而不能仅仅依靠我们的经验。


注意:以上问题中AWR和跟踪文件中的涉及客户系统的信息已经被修改或者没有贴出来。



如果您对本文感兴趣,请在这里进行讨论。

星期日 九月 15, 2013

Oracle技术支持是如何分析数据库性能问题的

    我的同事有幸参加了今年在上海的Oracle Open World,交流中有用户说我们中文的博客中跟性能相关的文章太少了。我们一贯非常重视用户的反馈,所以从现在开始我们会尽可能多的写一些大家感兴趣的话题。

    调优是一个永恒的话题,贯穿于一个数据库系统的完整生命周期。在这里我们主要关注的是作为技术支持我们是如何看待调优问题的,面向的对象主要是负责维护数据库系统的DBA。这个话题国内外有很多的大牛们写了很多很牛的书了,真的很好,我们中国的Oracle爱好者在这方面也有很多很好的经验。但是,我们还是会遇到有人问如何分析数据库的性能问题?万变不离其中。下边就简单阐述一下作为Oracle技术支持是如何分析一个性能问题的。首先声明,这个不是我创造的,而是Oracle全球技术支持通用的一个方法论(听起来是不是挺吓人?)

    有几个概念先要说清楚。对于用户而言,性能就是响应时间,也就是我发起一个操作,到这个操作完成的时间间隔。比如在12306买火车票,用户只关心从我开始发起买票这个操作,到什么时候我买到了。但是从整个系统的角度看就不一样了。一个三层架构的系统至少包含了客户端,应用服务器,数据库服务器。对于最终用户而言,我只知道我点了确认键后等了10分钟才跳转到成功页面,但是如果想要做优化,系统的维护者必须知道这10分钟究竟是分别花在哪一个阶段。一个典型的流程图:
      客户端发起请求→应用服务器收到请求→应用用服务器发送请求→数据库服务器收到请求→数据库服务器处理请求→数据库服务器返回请求→应用用服务器收到返回→客户端收到返回

      所以,这中间任何一个环节的缓慢都会造成这个请求响应的缓慢。实际上,我们还可以进一步深入分析,究竟是在某一个环节中间慢,还是两个环节在交互的时候有延迟?举个例子,如果大量的时间消耗在数据库服务器收到请求到数据库服务器返回请求,那么这个就是数据库这个环节的问题;但如果时间是消耗在数据库服务器返回请求到应用用服务器收到返回,那么就是两个环节之间的问题了。好在现在每一层都有自己的日志,通过客户端的日志我们能知道总共的响应时间,应用程序和数据库服务器的日志能知道这两层消耗的时间,加加减减就知道问题出在哪了。

      好了,如果不幸问题确认是发生在数据库层(为什么总是我?!),我们该怎么办呢?从数据库的角度,响应时间是这样计算的:
    响应时间=服务时间+等待时间

    服务时间其实就是我们通常说的CPU时间,等待时间就比如等待I/O,等待锁等等。绝大部分时候我们都是期望响应时间要尽可能接近服务时间,因为那样CPU才是真正在干活的;等待时间是我们通常需要去减小的,因为这意味着请求在等待某些资源,而没有干活。降低响应时间实际就是降低服务和等待时间,或者说降低CPU时间,I/O或锁等待。我们今天讲的是一个大的方法论,以后有机会会继续讲一些特定场景的优化。

    还有一个我想强调的是,对于操作系统而言,Oracle也是一个应用程序。我们依然需要从操作系统上获得CPU,内存这样的资源。如果操作系统有性能问题了的话,所有运行在上边的应用程序都将出问题,Oracle也不例外。当然,你可能会说我这个服务器就是数据库服务器,上边只运行了Oracle,但你能保证没有人用这个服务器下载复制电影导致带宽和I/O耗尽吗?这个真的是可能的。

    嘚啵嘚说了一堆,下边真的要说说我们是怎么分析数据库性能问题的了。

    + 问题描述。我一直以为性能问题比有错误或告警报出的问题更难解决,其中一个原因就是有错误的问题描述很简单,比如我运行了一条SQL,返回了942错误。性能问题的一个难点就是到底什么是问题,好多人都只会说”我的数据库慢“或者”我的应用没有响应“,从我上边画的流程图你就能知道这样的描述真的是没有意义的,那么什么样的描述是好的呢?

      - 用户看到的现象是什么样的?所有的应用都慢,还是某一条特定的SQL慢?
      - 问题发生的起止时间点?现象是自己消失的还是DBA手工干预了?DBA做了什么操作?
      - 问题发生的频率?很多性能问题都是有规律可循的。
      - 发生问题的时候有什么特殊的操作?对一张表添加了一个列?
      - 应用程序的负载是否有变化?比如正好是早晨刚开门时的业务高峰期?
      - 是否最近做过什么变更?比如上了一套新的应用?数据库刚打了一个补丁?操作系统加CPU了?

    回答了这些问题,说不定你自己也找到问题的原因了。如果你不说,技术支持,尤其是远程技术支持,是不会知道这个系统的背景的。多说一句,不光是使用Oracle技术支持要这样,大家在论坛或社区问问题的时候也要遵循这个原则,含糊的问题只能得到含糊的回答。

    + 问题描述清楚了,下边该我们技术支持来验证问题到底是不是这样的了。你可能又会说你就是不相信我们呗,亲,真的不是这样的。要知道如果一个问题的描述都是错误的话,之后的分析再怎么正确也是徒劳的。我们要避免这种情况,就算它只有万分之一的可能,因为它会极大的浪费我们的精力。那么怎么验证呢?
      - 对于整个系统的性能问题,大家都知道AWR/ASH report,但其实你还要提供一份基线作对比。嗯,你可能会说如果我是新上的系统呢?好吧,我只能说我们尽力而为,因为调优无极限,你要是就是想拿能并发100个用户的系统并发10000个用户我也没办法。
      - 对于某条SQL语句的问题,大家都知道SQL_TRACE,同样,我们要基线。一条从来都没有快过的SQL可能真的需要应用程序开发者看看是不是真的要这么写了。

    + 分析问题。基于自上而下的原则:
      - 操作系统的性能有没有问题?给我看看OSWatcher的输出呗(MOS文档1526578.1,中文的哦)
      - 整个数据库的性能有没有问题?AWR/ASH。对于整个数据库的性能问题,我的原则是看有问题时消耗最多DB Time的是什么类型,当然,这个是基于基线的,有的系统可能物理I/O永远是占用DB Time最多的部分,但不见得有问题。
      - 数据库hang住了?hanganalyze和systemstate dump。我们有个工具叫HANGFG(MOS文档362094.1),你就不用手工输入那些复杂的命令了。
      - 只是某条语句有问题?看看SQL_TRACE吧

    + 解决问题。一旦问题的原因定位到,找一个最合适的解决方法实施就好了。对于性能问题,调优有时是渐进的,你可能需要调调这,改改那,最后彻底解决问题。我理解大家做一次变更走流程很麻烦,我们也会尽可能尽量一次性将需要做的变更都找到,但真的不能百分百保证。

    综上,分析一个数据库性能问题,我们需要
      - 一个清晰准确的问题描述。
      - 足够的诊断信息,推荐MOS文档1549179.1 - 最佳实践:针对性能问题的主动型数据收集,也是中文的。

    当然,最好所有问题都消灭在萌芽中(技术支持不会失业吧。。),推荐MOS文档1549184.1 - 最佳实践:主动避免数据库和查询相关的性能问题。

    好了,今天就和大家说这么多。10月16号我们有个在线讲座关于数据库性能的(上一篇博客),欢迎各位捧场:)


    后续的讨论可以到这里继续



星期三 八月 21, 2013

如何诊断RAC系统中的'gc cr multi block request'?

     'gc cr multi block request' 是RAC数据库上比较常见的一种等待事件,在RAC 上进行全表扫描(Full Table Scan)或者全索引扫描(Index Fast Full Scan)时,容易产生这样的多块读等待。

     这种等待产生的主要原因:
1. 数据库参数db_file_multiblock_read或者db_block_size设置太大,导致多块读时GC传输量太大;
2. OS上UDP相关的参数设置不够大导致接收发送UDP的缓存区溢出;
3. 私网性能;
4. LMS设置问题(个数不足或者不是实时运行(real time))导致LMS的处理能力不够,不能及时传输global cache data/message。

    这方面的Bug比较少,在11.2之前有一个BUG 8464597,当db_block_size = 32k时,引发大量"gc cr multi block request" 而且性能下降,这个Bug在11.2已经修复。
    很多情况下,降低DB_FILE_MULTIBLOCK_READ_COUNT 并且 加大OS UDP相关参数会将极大缓解'gc cr multi block request' 等待。

     最近处理了一个问题,从10.2升级到11.2.0.3后产生大量'gc cr multi block request' 等待,发现DB_FILE_MULTIBLOCK_READ_COUNT, UDP 参数等都没有改变,只是升级后LMS的个数在不同实例间不同而且下降了很多,后来把LMS个数增加并且各个实例值保持一致后,问题得到解决。

                                                                Avg
                                                          wait   % DB
Event                                 Waits     Time(s)   (ms)   time Wait Class
------------------------------ ------------ ----------- ------ ------ ----------
gc cr multi block request           632,923      32,441     51   35.5 Cluster
DB CPU                                           13,518          14.8
gc cr grant 2-way                   327,717      10,900     33   11.9 Cluster
gc current grant 2-way              190,856       6,855     36    7.5 Cluster
gc current block 2-way              101,154       3,792     37    4.1 Cluster


如果发现AWR TOP5 等待中存在'gc cr multi block request' 而且它的Avg wait(ms)较高,那么请参考下面的诊断步骤:


第一步,查看db_file_multiblock_read_count和db_block_size参数设置。

SQL>show parameter db_block_size
SQL>show parameter db_file_multiblock_read_count

db_block_size一般为8192, db_file_multiblock_read_count一般为16.

第二步,参看OS udp相关参数设置,udp 的参数在不同的OS上是不同的,这些参数会设置UDP的接收缓存区和发送缓存区的大小,一般来说接收缓存区要>=发送缓存区。 如果在生产库修改这些参数,最好咨询OS厂商了解注意事项。

AIX上:
#no –a
                udp_recvspace
                udp_sendspace

o 设置udp_sendspace >=[(DB_BLOCK_SIZE * DB_FILE_MULTIBLOCK_READ_COUNT) + 4096],但是不低于 65536.
  比如,DB_BLOCK_SIZE=8192, DB_FILE_MULTIBLOCK_READ_COUNT=16,那么udp_sendspace>= (8192 * 16) + 4096=135168.注意这个值只是最低值,并不是Oracle要求必须设置这么大。
o 设置udp_recvspace 为 4到10倍 udp_sendpace
o 由于sb_max 必须 >= udp_recvspaceIf ,可能需要增加sb_max的值(默认为1048576)
o 如果udp的参数设置不合理,可能会产生“socket buffer overflows”,如果这个值非0, 需要增加udp_recvspace:
 netstat -s | grep "socket buffer overflows"
o 参考资料:http://www-03.ibm.com/support/techdocs/atsmastr.nsf/WebIndex/WP100883
  Minimum Software Versions and Patches Required to Support Oracle Products on IBM Power Systems (Doc ID 282036.1)

Linux上:
#More /etc/sysctl.conf

net.core.rmem_default
net.core.rmem_max
net.core.wmem_default
net.core.wmem_max

官方文档上要求的最低值:
http://docs.oracle.com/cd/E11882_01/install.112/e24321/pre_install.htm#BABDAEDB
Oracle Database Installation Guide
11g Release 2 (11.2) for Linux
E24321-07
rmem_default     262144     
rmem_max     4194304
wmem_default     262144     
wmem_max     1048576

可以将这几个值都设为4k:
net.core.rmem_default = 4194304
net.core.rmem_max = 4194304
net.core.wmem_default = 4194304
net.core.wmem_max = 4194304

HP上:

请检查UDP设置是否足够大:
$ /bin/ndd -get /dev/sockets socket_udp_rcvbuf_default
$ /bin/ndd -get /dev/sockets socket_udp_sndbuf_default

确保socket_udp_rcvbuf_default至少是socket_udp_sndbuf_default的两倍。

Sun:
可以用下面的命令查看UDP设置:
ndd /dev/udp udp_xmit_hiwat
ndd /dev/udp udp_recv_hiwat
ndd /dev/udp udp_max_buf

可以用下面的命令设置这两个值为OS最大允许的:
ndd -set /dev/udp udp_xmit_hiwat
ndd -set /dev/udp udp_recv_hiwat
ndd -set /dev/udp udp_max_buf <1M or higher>

更多信息,可以参考MOS文档:
Tuning Inter-Instance Performance in RAC and OPS (Doc ID 181489.1)

第三步,查看网络情况。
比如用netstat -s 命令查看是否有bad data length, bad checksums, incomplete headers, socket buffer overflows等,注意这些值是累计的,需要查看它们在发生问题的时候是否有增加。
另外可以查看AWR中是否有 "Global Cache Blocks Lost" ,理想情况下这个值是0,如果有较大的block lost,说明网络有问题(按照MOS 文档563566.1进行网络检查)。
还可以请网管查看私网的性能情况。

第四步,检查LMS。
1. 查看LMS的trace file,查看是否有异常。
2. 查看LMS进程的优先级是否是实时的(real time)的?

比如AIX:
# ps -elf|grep lms

ps -elf|grep lms
F      S      UID      PID     PPID   C PRI NI ADDR    SZ    WCHAN    STIME    TTY  TIME CMD
240103 A   oracle  4719002        1   5  39 -- 8ae40b590 248856            Jul 28      - 570:45 ora_lms0_rac1

priority 越小说明优先级越高,PRI小于40说明是Real Time的:
http://aix4admins.blogspot.co.uk/2011/08/commands-and-processes-process-you-use.html

3. 查看LMS的个数:
SQL>show parameter GCS_SERVER_PROCESSES
这个值决定了LMS的个数

这个值依赖于CPU的个数(cpu_count),根据11.2官方文档:
http://docs.oracle.com/cd/E11882_01/server.112/e25513/initparams094.htm#REFRN10259
Default value
If 1 - 3 CPUS, then 1
If 4 - 15 CPUs, then 2
If 16 or more CPUs, then 2 + (CPUs / 32). If the result includes a fraction, then the fraction is disregarded. For example, if you had 20 CPUs, then 2 + (20 / 32) would equal 2 GCS processes.
If CLUSTER_DATABASE is set to false, then 0
If ASM, then 1

在AIX上,有的时候CPU可能是动态增加的,那么一定要注意检查LMS进程的个数是否随之调整了。


有关这个问题的讨论,可以在中文社区帖子中进行 如何诊断RAC系统中的'gc cr multi block request'?

星期六 四月 06, 2013

RAC 中锁(排队)的管理

本文会对RAC中锁的管理进行介绍,其中包括以下三部分内容。
1.    RAC 中锁的介绍
2.    RAC如何发现死锁
3.    搜集RAC 中锁的诊断信息

适用范围:9.2 及以上版本。

首先,我们对RAC中锁的基本概念进行一些介绍。对于RAC数据库,我们可以把锁分为两类,第一类我们可以称之为buffer lock, 这种锁针对数据库的buffer,另一种锁就是我们经常提到的排队(enqueue)。本文主要介绍后一种( buffer lock 会在今后的文章中介绍)。
既然是锁,那么就会包含等待者(convert)和 持有者(grant) 队列,类型(用来表示所保护的资源),以及访问的模式。另外,对于RAC系统,由于需要在多个实例间维护访问的一致性,每个锁也会有一个master 节点,在master 节点中会包含这个锁的完整的grant 和convert 队列,而每一个访问过这个锁的节点,也会保存本地的grant 和convert 队列。我们在共享池中看到的’ges resources’ 部分,就包含了锁的master信息,当然,也可以认为master信息是GRD 的一部分。
对于锁,另一个重要的概念就是模式(或级别),针对不同的操作,需要获得不同模式的锁,毕竟锁是一种串行的机制,串行在很多时候意味着等待,而我们并不希望看到等待,所以我们需要锁具有不同的模式,来尽量避免等待。同时,也为了保证数据的一致性,锁的有些模式之间是可以兼容的,而有些是不能兼容的。对于RAC系统,我们可以参照以下的表格,了解锁的模式和兼容性。



当用户进程需要申请锁的时候,会发生以下的过程。
1.    申请进程发送消息给master节点,找到关于锁的全部grant 和 covert 队列信息。
2.    Master 节点通知持有者释放(Down convert)相应模式的锁。
3.    如果持有者不能释放,即申请锁的兼容模式无效(进程不能以申请的模式获得锁,因为其他进程正在以不兼容的方式持有这个锁),申请进程进入等待者队列。
4.    当持有者释放锁之后,master节点通知申请进程能够以所申请的模式获得锁并进入持有者队列,申请请求成功结束。




对于RAC环境中的死锁(对于死锁的概念,本文不做介绍),是由LMD进程处理的。基本的过程是。
1.    LMD进程定期搜索各个实例的锁信息,发现可能的死锁。
2.    在可能的死锁进程被发现之后,LMD会验证死锁。
3.    在得到验证之后,LMD会选择回滚导致死锁的进程的当前SQL语句,来打破死锁。

接下来,我们通过下面的例子,对诊断RAC 中锁相关的问题进行简单的介绍。我们用下面的步骤制造一个DML 死锁。
1.    Session1: update emp set ename='new name' where empno=7934;
2.    Session2 : update emp set ename='new name1'where empno=7902;
3.    Session1 : update emp set ename='new name1'where empno=7902;
4.    Session2: update emp set ename='new name' where empno=7934;

之后我们在数据库实例1的alert log 中会找到死锁的信息。
Sun Apr  7 04:45:39 2013
Global Enqueue Services Deadlock detected. More info in file
 /u01/app/oracle/admin/ONEPIECE/bdump/onepiece1_lmd0_6257.trc

从实例1的lmd 跟踪文件中,我们能够找到类似的信息。
DUMP LOCAL BLOCKER/HOLDER: block level 5 res [0x70022][0x1de6],[TX]
----------resource 0x0x3f969794----------------------
resname       : [0x70022][0x1de6],[TX]
……
GRANTED_Q :
lp 0x3f9714e0 gl KJUSEREX rp 0x3f969794 [0x70022][0x1de6],[TX]
  master 0 gl owner 0x456339e8 possible pid 14942 xid 1D000-0001-000000A6 bast 0 rseq 39 mseq 0 history 0x95
  open opt KJUSERDEADLOCK 
CONVERT_Q:
lp 0x3f9715b4 gl KJUSERNL rl KJUSEREX rp 0x3f969794 [0x70022][0x1de6],[TX]
  master 0 owner 1  bast 0 rseq 8 mseq 0x1 history 0x97ad
  convert opt KJUSERGETVALUE 

以上的信息说明对于enqueue  [0x70022][0x1de6],[TX],它的master 节点为节点1,grant 队列中有一个进程14942,convert队列中包含一个进程,但是这个进程在节点2,不会在节点1的跟踪文件中显示出进程的详细信息,需要到节点2的lmd 跟踪文件中查找。所以,我们能够看到master节点会包含enqueue 的全局信息。

----------resource 0x0x423753fc----------------------
resname       : [0xb0004][0xf8f],[TX]
……
GRANTED_Q :
CONVERT_Q:
lp 0x4488c5b0 gl KJUSERNL rl KJUSEREX rp 0x423753fc [0xb0004][0xf8f],[TX]
  master 1 gl owner 0x456339e8 possible pid 14942 xid 1D000-0001-000000A6 bast 0 rseq 113 mseq 0 history 0x1495149a
  convert opt KJUSERGETVALUE 

以上的信息说明对于enqueue  [0xb0004][0xf8f],[TX],它的master节点为节点2,grant 队列为空,而convert队列中有1个进程14942, 但是,由于节点1并不是这个enqueue的master节点,所以只能显示本地节点的信息。如果要获取这个enqueue的全部信息,需要查看节点2的lmd跟踪文件。

对于RAC中死锁的问题,LMD跟踪文件会描绘死锁的图像。也就是经常提到的WFG。
Global Wait-For-Graph(WFG) at ddTS[0.1] :
BLOCKED 0x4488c5b0 5 wq 2 cvtops x1 [0xb0004][0xf8f],[TX] [1D000-0001-000000A6] 0
BLOCKER 0x5d8512dc 5 wq 1 cvtops x8 [0xb0004][0xf8f],[TX] [16000-0002-00000043] 1
BLOCKED 0x5d88d58c 5 wq 2 cvtops x1 [0x70022][0x1de6],[TX] [16000-0002-00000043] 1
BLOCKER 0x3f9714e0 5 wq 1 cvtops x8 [0x70022][0x1de6],[TX] [1D000-0001-000000A6] 0

以上信息的含义,可以参考Note 242263.1 : Analyzing ORA-60 Deadlocks in a RAC Environment。

最后,对于诊断RAC中锁的问题,我们还可以通过以下的信息进行诊断
查询视图gv$lock, gv$ges_enqueue
搜集 systemstate dump, hanganalyze dump 文件
搜集 lmd 跟踪文件 和产生的用户进程跟踪文件。





星期一 二月 04, 2013

RAC 数据库中的 'log file sync' 等待事件



简介


本文主要讨论 RAC 数据库中的'log file sync' 等待事件。RAC 数据库中的'log file sync' 等待事件要比单机数据库中的'log file sync' 等待事件复杂,主要原因是由于RAC 数据库需要将SCN同步到所有实例。


首先,回顾一下单机数据库中的'log file sync' 等待事件,当user session 提交(commit)时,user session会通知LGWR进程将redo buffer中的信息写入到redo log file,当LGWR进程完成写操作后,LGWR再post(通知)user session 写操作已经完成,user session 接收到LGWR的通知后提交操作才完成。因此user session 在没有收到LGWR post(通知)之前一致处于等待状态,具体的等待事件为'log file sync'。


在RAC数据库中为了一致性读,需要将Commit SCN同步/传播到所有的节点上。SCN同步/传播的主要方法有两种:Lamport SCN 和 immediate commit propagation (BOC)。



10gR1 及以下版本默认使用Lamport SCN,Lamport SCN方式即一个节点上的commit SCN 不保证立刻同步/传播到所有节点,也就是说可能延时同步/传播,对于一些实时性要求高的RAC数据库Lamport SCN方式是不可取的。如果希望commit SCN 立刻同步/传播到所有节点,手动修改参数MAX_COMMIT_PROPAGATION_DELAY=1



从10gR2开始默认使用immediate commit propagation (BOC),BOC即一个节点上的commit SCN 立刻同步/传播到所有节点。





介绍 immediate commit propagation (BOC)的工作原理 



1. user session 执行提交(commit),user session会通知LGWR进程将redo buffer中的信息写入到redo log file。

2. LGWR进程收到user session通知后,将redo buffer中的信息写入redo log file,同时LGWR 将COMMIT SCN 同步/传播给远程的数据库实例的LMS 进程。

3. 远程数据库实例的LMS将commit SCN同步到本地SCN,然后通知commit实例的LMS,表示SCN 同步已经完成。

4. 当commit 实例的LMS接收到所有远程数据库实例的LMS的通知后,commit 实例的LMS再通知本地的LGWR 所有节点SCN同步已经完成。


5. LGWR 在完成了IO 操作和LMS进程通知后,LGWR通知user session commit 成功。user session在没有收到LGWR通知前,一直处于等待log file sync。 





通过以上原理的说明,我们不难看出来导致'log file sync' 等待事件的主要原因有:

1. 磁盘IO 慢导致LGWR进程将redo buffer中的信息写入到redo log file速度慢。

2. user session commit过于频繁。

3. 本地或者远程服务器CPU资源不足,导致LMS和/或者LGWR不能及时得到CPU调度,不能正常工作。

4. RAC私有网络性能差,导致LMS同步commit SCN慢。

5. ORACLE BUG.



分析处理'log file sync' 等待事件时的重要log/信息


1. AWR 


例如:AWR中log file sync 的等待时间与log file parallel write的时间基本相同,因此是由于IO问题导致的log file sync.




2. LGWR and LMS process trace file


例如:LGWR trace文件中报出下面的信息,很有可能是IO慢导致的。


Warning: log write time 1000ms, size 2KB 


3. OSWatcher <--- 可以帮助我们确认服务器CPU资源使用情况




例如:下面的是OSW中vmstat 的输出,其中runQ中的进程达到48个,表明当时CPU资源是非常紧张的,会导致LMS/LGWR不能获得CPU 调度,导致Log file sync等待。


        procs           memory                   page                              faults       cpu


   r     b     w      avm    free   re   at    pi   po    fr   de    sr     in     sy    cs  us sy id


48    22     0  23877753  30244459    0    0     0    0     0    0     0  153454 2184632 114234  38 60  2


48    22     0  23877753  30244094    0    0     0    0     0    0     0  153694 2181493 114887  36 61  3


注:关于OSW的安装配置请参考BLOG中的文章:


https://blogs.oracle.com/Database4CN/entry/%E5%88%A9%E5%99%A8osw_oswatcher_black_box_%E4%B9%8B%E7%AE%80%E4%BB%8B%E7%AF%87


4. Alert log 



5. Script to Collect Log File Sync Diagnostic Information (lfsdiag.sql) [Document 1064487.1] 




解决'log file sync' 等待事件主要方法

1. 提高磁盘IO速度

2. 采用批量提交,减少应用commit次数

3. 安装OSWatcher 定位CPU使用率高的进程

4. 采用专用网络,正确设置网络UDP buffer参数

5. 安装最新版本数据库避免bug,具体bug修复的版本参考文档: 


WAITEVENT: "log file sync" Reference Note (Doc ID 34592.1) 




星期一 十二月 10, 2012

11gR2 集群管理软件(GI) 启动顺序和诊断方法简介


在这篇文章里我们会对11gR2
GI
的启动顺序进行介绍,并且对常见的GI启动时遇到的问题和对应的解决办法进行介绍。


基本上我们可以把GI的启动过程分成3个阶段,ohasd阶段,构建集群阶段,启动资源阶段。


首先,ohasd阶段。


1. /etc/inittab文件中的脚本


h1:35:respawn:/etc/init.d/init.ohasd run
>/dev/null 2>&1 </dev/null


被调用,产生下面的进程


root 4865 1 0 Dec02 ? 00:01:01 /bin/sh /etc/init.d/init.ohasd
run


所以如果说你没有发现这个进程,那么说明


+init.ohasd 脚本可能没有被调用


+ os运行在不正确的级别


+ 一些S* ohasd脚本挂起, 例如S96ohasd


+ GI没有配置自动启动(crsctl enable crs


之后,ohasd.bin 进程会被启动,这个时候OLR会被访问,所以,如果ohasd.bin不能正常工作,就需要查看OLR是否存在而且能够被正常访问。OLR存放在$GRID_HOME/cdata/${HOSTNAME}.olr




2. ohasd.bin进程会启动对应的agents(orarootagent,
oraagent, cssdagnet
cssdmonitor) 来启动集群的初始化资源。如果说,您发现这些agent进程不能启动,很多时候都是由于路径$GRID_HOME/bin 下的可执行文件存在问题,例如,文件权限设置有问题,文件corruption.


接下来,构建集群阶段。


1. Mdnsd 进程透过多播(Multicast)发现集群中的节点和所有的网卡信息。所以,一定要确定集群中的网卡支持多播。而且节点间的通信正常。


2. Gpnpd 进程启动,发布构建集群所需要的bootstrap 信息,并且在集群的所有节点之间同步gpnp profile。当然,同步是透过mdnsd实现的。所以,如果是这个进程存在问题,您需要确认节点间的通信正常,而且gpnp
profile
<gi_home>/gpnp/profiles/peer/profile.xml)存在而且可以被访问。


3. Gipcd 进程启动,这个进程负责管理集群中所有的私网(cluster
interconnect
)网卡。当然,私网信息是通过gpnpd获得的,所以,如果这个进程存在问题,您需要确认gpnpd 进程正常运行。


4. Ocssd.bin 进程启动。这个进程首先通过gpnp profile中的信息发现表决盘(Voting Disk),之后通过gpnpd 进程获得集群私网信息,和其他的节点建立连接。所以,如果ocssd.bin
不能正常运行,您需要确认一下的信息


+ gpnp profile 存在而且可以被访问。


+ gpnpd 进程正常运行。


+ 表决盘所在的asm disk 或设备能够正常被访问。


+ 节点私网间的通信正常。


5. 启动其他的初始化进程:ora.ctssd, ora.asm, ora.cluster_interconnect.haip, ora.crf, ora.crsd
等。


注意:以上的过程是同时进行的。也就是说ocssd.bin, gpnpd.bin gipcd.bin 同时启动,直到gpnpd.bin正常运行,ocssd.bin gipcd.bin 才能获得相应的信息,在gpnpd.bin没有正常运行之前,ocssd.bin gipcd.bin 中出现的无法访问gpnp profile错误是可以忽略掉的。


最后,资源启动阶段。在这个阶段,主要是通过crsd进程启动各个资源。


1. Crsd进程启动。这个进程需要访问OCR,如果您的OCR是存放在ASM上,需要确保


ASM实例正常运行,并且OCR所在的ASM磁盘组已经装载。如果OCR存放在裸设备上,那么需要确保对应的设备正常运行。


2. Crsd 启动对应的agents(orarootagent,
oraagent_<rdbms_owner>, oraagent_<gi_owner> )
如果agent不能启动,很多时候都是由于路径$GRID_HOME/bin 下的可执行文件存在问题,例如,文件权限设置有问题,文件corruption.


3. 所有的资源启动。


 ora.net1.network : 网络资源,这个资源负责管理集群的公网,scanvip, vip,
listener
资源都依赖于这个资源。所以,如果这个资源存在问题,vip, scanvip listener 都会offline,您需要检查公网是否存在问题。


ora.<scan_name>.vipscan对应的vip资源,最多可以有3个。


ora.<node_name>.vip : 节点对应的vip 资源


ora.<listener_name>.lsnr: 监听程序资源。在这里我们要注意,从11gR2开始,listener.ora文件会自动生成,不再需要手动修改。


ora.LISTENER_SCAN<n>.lsnr: scan 监听程序。


ora.<磁盘组名>.dg: ASM 磁盘组资源。这个资源会在磁盘组被mount时创建,dismount时删除。


ora.<数据库名>.db: 数据库资源。在11gR2中实例资源已经不再存在了,新的数据库资源会管理rac 数据库的所有实例,而数据库包含哪些实例,是通过资源参数“USR_ORA_INST_NAME@SERVERNAME(<node name> )”来决定的。另外,如果您的数据库存储在ASM磁盘上,那么数据库资源会依赖于对应的磁盘组资源,这个dependency是自动添加的。但是,如果数据库被转移到了其他的磁盘组之后,原有的dependancy不会被自动删除,需要手动删除(crsctl modify res ……)


ora.<服务名>.svc:数据库服务资源。从11gR2 开始,这个资源只有一个了,不会像10gR2一样,每个数据库服务资源包含,srv cs 两个资源。


ora.cvu :这个资源从11.2.0.2被引入,定期对集群执行cluvfy操作,验证集群是否存在一些配置上的问题


ora.ons : ONS资源,和之前版本的功能,基本相同。


另外,我们对诊断GI启动问题所需要查看的文件进行简单的介绍


$GRID_HOME/log/<node_name>/ocssd <==
ocssd.bin
日志


$GRID_HOME/log/<node_name>/gpnpd <== gpnpd.bin 日志


$GRID_HOME/log/<node_name>/gipcd <== gipcd.bin 日志


$GRID_HOME/log/<node_name>/agent/crsd <== crsd.bin 日志


$GRID_HOME/log/<node_name>/agent/ohasd <== ohasd.bin
日志


$GRID_HOME/log/<node_name>/mdnsd <== mdnsd.bin 日志


$GRID_HOME/log/<node_name>/client <== 用户使用GI 工具(ocrdump, crsctl, ocrcheck, gpnptool等等)对集群进行操作的日志。


$GRID_HOME/log/<node_name>/ctssd <== ctssd.bin
日志


$GRID_HOME/log/<node_name>/crsd <== crsd.bin 日志


$GRID_HOME/log/<node_name>/cvu <== cluvfy 日志输出。


$GRID_HOME/bin/diagcollection.sh <== 通过这个脚本获得更全面的诊断日志。


最后,集群的套接字文件(/var/tmp/.oracle
/tmp/.oracle),由于集群中很多进程之间的通信都是通过ipc实现的,所以,这些套接字文件一定要存在而且权限正确。


以上,我们对GI启动的顺序和基本的诊断方法进行了简单的介绍,希望能够为大家在诊断GI启动问题时能够提供一些帮助。



如果您希望对这篇文章进行进一步的讨论,请在以下的链接回复。


https://communities.oracle.com/portal/server.pt/community/view_discussion_topic/216?threadid=536875&doPagination=false&Portlet=View%20Discussion&PrevPage=Communities-EditDiscussion

星期二 九月 11, 2012

如何诊断RAC数据库上的“IPC Send timeout”问题?

   RAC 数据库上比较常见的一种问题就是“IPC Send timeout”。数据库Alert log中出现了“IPC Send timeout”之后,经常会伴随着ora-29740 或者 "Waiting for clusterware split-brain resolution"等,数据库实例会因此异常终止或者被驱逐出集群。

比如:

实例1的ALERT LOG:

Thu Jul 02 05:24:50 2012
IPC Send timeout detected.Sender: ospid 6143755<==发送者
Receiver: inst 2 binc 1323620776 ospid 49715160
<==接收者
Thu Jul 02 05:24:51 2012
IPC Send timeout to 1.7 inc 120 for msg type 65516 from opid 13
Thu Jul 02 05:24:51 2012
Communications reconfiguration: instance_number 2
Waiting for clusterware split-brain resolution <==出现脑裂
Thu Jul 02 05:24:51 2012
Trace dumping is performing id=[cdmp_20120702052451]
Thu Jul 02 05:34:51 2012
Evicting instance 2 from cluster <==过了10分钟,实例2被驱逐出集群

实例2的ALERT LOG:

Thu Jul 02 05:24:50 2012
IPC Send timeout detected. Receiver ospid 49715160 <==接收者
Thu Jul 02 05:24:50 2012
Errors in file /u01/oracle/product/admin/sales/bdump/sales2_lms6_49715160.trc:
Thu Jul 02 05:24:51 2012
Waiting for clusterware split-brain resolution
Thu Jul 02 05:24:51 2012
Trace dumping is performing id=[cdmp_20120702052451]
Thu Jul 02 05:35:02 2012
Errors in file /u01/oracle/product/admin/sales/bdump/sales2_lmon_6257780.trc:
ORA-29740: evicted by member 0, group incarnation 122  <==实例2出现ORA-29740错误,并被驱逐出集群
Thu Jul 02 05:35:02 2012
LMON: terminating instance due to error 29740
Thu Jul 02 05:35:02 2012
Errors in file /u01/oracle/product/admin/sales/bdump/sales2_lms7_49453031.trc:
ORA-29740: evicted by member , group incarnation

    在RAC实例间主要的通讯进程有LMON, LMD, LMS等进程。正常来说,当一个消息被发送给其它实例之后,发送者期望接收者会回复一个确认消息,但是如果这个确认消息没有在指定的时间内收到(默认300秒),发送者就会认为消息没有达到接收者,于是会出现“IPC Send timeout”问题。

    这种问题通常有以下几种可能性:
1. 网络问题造成丢包或者通讯异常。
2. 由于主机资源(CPU、内存、I/O等)问题造成这些进程无法被调度或者这些进程无响应。
3. Oracle Bug.

   在这方面的Oracle Bug不是太多,大多数时候都是网络或者资源问题造成这种情况。

   为了分析这种问题,网络和资源监控工具是非常必要的。推荐安装OSWBB,对于如何
安装使用OSWBB,请参考文章利器OSW (OSWatcher Black Box) 之简介篇

   下面是一个由于主机资源紧张造成的“IPC Send timeout”例子:

   实例1的Alert log中显示接收者是2号机的进程1596935,

Fri Aug 01 02:04:29 2008
 IPC Send timeout detected.Sender: ospid 1506825 <==发送者
 Receiver: inst 2 binc -298848812 ospid 1596935  <==接收者

   查看当时2号机的OSWatcher的vmstat输出:

 zzz ***Fri Aug 01 02:01:51 CST 2008
 System Configuration: lcpu=32 mem=128000MB
 kthr     memory             page              faults        cpu    
 ----- ----------- ------------------------ ------------ -----------
  r  b   avm   fre  re  pi  po  fr   sr  cy  in   sy  cs us sy id wa
 25  1 7532667 19073986   0   0   0   0    5   0 9328 88121 20430 32 10 47 11
58  0 7541201 19065392   0   0   0   0    0   0 11307 177425 10440 87 13  0  0 <==idle的CPU为0,说明CPU100%被使用
61  1 7552592 19053910   0   0   0   0    0   0 11122 206738 10970 85 15  0  0

 zzz ***Fri Aug 01 02:03:52 CST 2008
   System Configuration: lcpu=32 mem=128000MB
   kthr     memory             page              faults        cpu    
 ----- ----------- ------------------------ ------------ -----------
  r  b   avm   fre  re  pi  po  fr   sr  cy  in   sy  cs us sy id wa
 25  1 7733673 18878037   0   0   0   0    5   0 9328 88123 20429 32 10 47 11
81  0 7737034 18874601   0   0   0   0    0   0 9081 209529 14509 87 13  0  0 <==CPU的run queue非常高
80  0 7736142 18875418   0   0   0   0    0   0 9765 156708 14997 91  9  0  0 <==idle的CPU为0,说明CPU100%被使用

  上面这个例子说明当主机CPU负载非常高的时候,接收进程无法响应发送者,从而引发了“IPC Send timeout”。

  下面是一个由于网络问题造成的“IPC Send timeout”例子:

   实例1的Alert log中显示接收者是2号机的进程49715160,

Thu Jul 02 05:24:50 2012
IPC Send timeout detected.Sender: ospid 6143755 <==发送者
Receiver: inst 2 binc 1323620776 ospid 49715160 <==接收者

   查看当时2号机的OSWatcher的vmstat输出,没有发现CPU和内存紧张的问题,查看OSWatcher的netstat输出,在发生问题前几分钟,私网的网卡上有大量的网络包传输。

Node2:
zzz Thu Jul 02 05:12:38 CDT 2012
Name  Mtu   Network     Address            Ipkts Ierrs    Opkts Oerrs  Coll
en1   1500  10.182.3    10.182.3.2       4073847798     0 512851119     0     0 <==4073847798 - 4073692530 = 155268 个包/30秒

zzz Thu Jul 02 05:13:08 CDT 2012
Name  Mtu   Network     Address            Ipkts Ierrs    Opkts Oerrs  Coll
en1   1500  10.182.3    10.182.3.2       4074082951     0 513107924     0     0 <==4074082951 - 4073847798 = 235153 个包/30秒

Node1:
zzz Thu Jul 02 05:12:54 CDT 2012
Name  Mtu   Network     Address            Ipkts Ierrs    Opkts Oerrs  Coll
en1   1500  10.182.3    10.182.3.1       502159550     0 4079190700     0     0 <==502159550 - 501938658 = 220892 个包/30秒

zzz Thu Jul 02 05:13:25 CDT 2012
Name  Mtu   Network     Address            Ipkts Ierrs    Opkts Oerrs  Coll
en1   1500  10.182.3    10.182.3.1       502321317     0 4079342048     0     0 <==502321317 - 502159550 = 161767 个包/30秒

查看这个系统正常的时候,大概每30秒传输几千个包:

zzz Thu Jul 02 04:14:09 CDT 2012
Name  Mtu   Network     Address            Ipkts Ierrs    Opkts Oerrs  Coll
en1   1500  10.182.3    10.182.3.2       4074126796     0 513149195     0     0 <==4074126796 - 4074122374 = 4422个包/30秒

   这种突然的大量的网络传输可能会引发网络传输异常。对于这种情况,需要联系网管对网络进行检查。在某些案例中,重启私网交换机或者调换了交换机后问题不再发生。(请注意,网络的正常的传输量会根据硬件和业务的不同而不同。)


下面是一个由于I/O问题造成的“IPC Send timeout”例子:

   实例的Alert log中显示接收者是1号机的LMON进程:

Sun Feb 22 07:57:30 2014
IPC Send timeout detected. Receiver ospid 44105801 [oracle@db1 (LMON)] <========================接收者

查看这个进程生成的trace文件db1_lmon_44105801.trc,发现当时LMON的函数都是和IO有关的:

kjxgmpoll: stalled for 94 seconds (threshold 42 sec)

----- Call Stack Trace -----
skdstdst <- ksedst1 <- ksedst <- dbkedDefDump <- ksedmp
       <- ksdxfdmp <- ksdxcb <- sspuser <- 48bc <- sigthreadmask
        <- sslsstehdlr <- sslsshandler <- 48bc <- skgfsio <- skgfqio
         <- ksfd_skgfqio <- ksfd_io <- ksfdread <- kfk_ufs_sync_io <- kfk_submit_ufs_io
          <- kfk_submit_io <- kfk_io1 <- kfkRequest <- kfk_transitIO <- kfioSubmitIO

           <- kfioRequestPriv <- kfioRequest <- ksfd_kfioRequest <- 576 <- ksfd_osmio
            <- ksfd_io <- ksfdread <- kccrbp <- kccgrd <- kjxgrf_rr_read
             <- kjxgrDD_rr_read <- kjxgrimember <- kjxggpoll <- kjfmact <- kjfdact
              <- kjfcln <- ksbrdp <- opirip <- opidrv <- sou2o
               <- opimai_real <- ssthrdmain <- main <- start

   总结一下,对于
“IPC Send timeout”
1) 通过Oracle自带的CHM (Cluster Health Monitor)的输出来检查当时的资源、网络使用情况。CHM只在某些平台和版本上存在,关于CHM,请参考文章11gR2 新特性:Oracle Cluster Health Monitor(CHM)简介
2) 如果没有CHM,请安装OSWBB来监控网络和主机资源。
3) 检查网络上是否有UDP或者IP包丢失的情况、网络上是否有错误。
4) 检查所有节点的网络设置是否正确。比如,所有节点MTU的设置必须是一致的,如果Jumbo Frame被使用的话,需要保证交换机可以支持MTU为9000.
5) 检查服务器是否有CPU使用率高或者内存不足的情况。
6) 检查实例被驱逐之前是否有数据库hang或者严重的性能问题。


  在下面的MOS文档中有针对“IPC Send timeout”的介绍:
  Top 5 issues for Instance Eviction (Doc ID 1374110.1)

星期一 九月 03, 2012

11gR2 如何诊断节点重启问题

本文对如何诊断11gR2 GI环境下的节点重启问题进行了一些介绍。

首先,像10g版本一样,我们首先介绍在GI中能够导致节点重启的进程。
1.Ocssd.bin:这个进程的功能和10g版本的功能基本差不多,主要是节点监控(Node Monitoring)和组管理(Group Management)。详细的信息请参考之前文章“如何诊断节点重启问题”了解详细的内容。
2.Cssdagent.bin/Cssdmonitor.bin:这2个进程是11gR2新增加的。他们的工作主要是同ocssd.bin进行本地心跳(Local HeartBeat),默认情况下每1秒钟一次。本地心跳的作用是监控本地的ocssd.bin进程是否正常运行。同时,他们也监控自己到ocssd.bin之间的连接。所以,我们可以认为,这两个进程的出现代替了10g中的oclsomon/oclsvmon(如果第三方集群管理软件存在)和oprocd。

接下来,介绍一个11gR2的重要的新特性—rebootless restart,这个新特性是在版本11.2.0.2被介绍的。从这个版本开始,当集群中的某个节点被驱逐(例如丢失网络心跳)或者该节点的ocssd.bin出现问题时,集群将不会直接重新启动该节点,而是首先尝试重新启动GI stack来解决问题,如果GI stack不能够在指定的时间内(short disk I/O timeout)完成graceful shutdown,才会重新启动节点,之后,存活的节点对集群进行重新配置。

下面我们列出在诊断11gR2 节点重启问题时经常搜集的信息
1.Ocssd.log
2.Cssdagent 和 cssdmonitor logs
<GI_home>/log/<node_name>/agent/ohasd/oracssdagent_root/oracssdagent_root.log
<GI_home>/log/<node_name>/agent/ohasd/oracssdmonitor_root_root/oracssdmonitor_root.log
3.Cluster alert log
<GI_home>/log/<node_name>/alert<node_name>.log
4.OS log
5.OSW 或者 CHM 报告

最后,我们对常见的节点重启的问题进行介绍。
1.由于丢失网络心跳导致的节点重启问题。对于这种原因导致的节点重启,诊断的方式和10g基本没有什么区别。但是有一个误区需要指出来。下面是一段GI alert log 信息,他们来自于node2。
2012-08-15 16:30:06.554 [cssd(11011) ]CRS-1612:Network communication with node node1 (1) missing for 50% of timeout interval.  Removal of this node from cluster in 14.510 seconds
2012-08-15 16:30:13.586 [cssd(11011) ]CRS-1611:Network communication with node node1 (1) missing for 75% of timeout interval.  Removal of this node from cluster in 7.470 seconds
2012-08-15 16:30:18.606 [cssd(11011) ]CRS-1610:Network communication with node node1 (1) missing for 90% of timeout interval.  Removal of this node from cluster in 2.450 seconds
2012-08-15 16:30:21.073 [cssd(11011) ]CRS-1632:Node node1 is being removed from the cluster in cluster incarnation 236379832
2012-08-15 16:30:21.086 [cssd(11011) ]CRS-1601:CSSD Reconfiguration complete. Active nodes are node2 .

以上的信息并不一定说明节点node1是由于丢失网络心跳而被驱逐出集群的,首先我们要验证, node2在报 node1 丢失网络心跳的时候node1 的状态,如果说node1 已经重启或者存在严重的性能问题(可以通过os log 或者OSW 报告验证),那么node1 重启并不是由于node2发现node1丢失网络心跳造成的,而是由于node1出现问题后产生的结果,这里的reconfiguration,仅仅是集群成员信息的更新,并不会导致节点重启。而且,从11.2.0.2开始,由于rebootless restart的介入,node eviction 首先导致的结果是GI stack重启,而不是直接节点重启。但是,如果在node2报node1丢失节点心跳的时候,node1的ocssd.bin仍然正常运行(可以通过ocssd.log验证)或者node1也报丢失了和其他节点的网络心跳,那么node1的重启是由于GI node eviction导致的。

2.由于丢失磁盘心跳导致的节点重启,这种情况和10g的情况基本相同,在这里不作详细的描述。

3.由于ocssd.bin 丢失了和Cssdagent/Cssdmonitor.bin的本地心跳导致的节点重启,对于这种情况,一般来说,我们会在oracssdagent_root.log 或oracssdmonitor_root.log 看到以下的信息。
2012-07-23 14:09:58.506: [ USRTHRD][1095805248] (:CLSN00111: )clsnproc_needreboot: Impending reboot at 75% of limit 28030; disk timeout 28030, network timeout 26380, last heartbeat from CSSD at epoch seconds 1343023777.410, 21091 milliseconds ago based on invariant clock 269251595; now polling at 100 ms
……
2012-07-23 14:10:02.704: [ USRTHRD][1095805248] (:CLSN00111: )clsnproc_needreboot: Impending reboot at 90% of limit 28030; disk timeout 28030, network timeout 26380, last heartbeat from CSSD at epoch seconds 1343023777.410, 25291 milliseconds ago based on invariant clock 269251595; now polling at 100 ms
……
从上面的信息我们看到本地心跳的timeout时间为28 秒左右(misscount – reboot time)。

4.由于操作系统资源竞争导致的节点重启。 如果说操作系统的资源被耗尽或者存在严重的竞争,也会导致ocssd.bin不能正常工作,造成节点重启。对于这种情况,虽然重启操作系统的命令会由ocssd.bin发出,但是真正的原因是os资源竞争。以下是一小段OSW输出,它显示了 在节点重启之前 cpu 耗尽。
Linux OSWbb v5.0 node1
SNAP_INTERVAL 30
CPU_COUNT 8
OSWBB_ARCHIVE_DEST /osw/archive
procs -----------memory---------- ---swap-- -----io---- -system-- -----cpu------
r  b   swpd   free   buff  cache   si   so    bi    bo   in    cs us sy id wa
……
zzz ***Mon Aug 30 17:55:21 CST 2012
158  6 4200956 923940   7664 19088464    0    0  1296  3574 11153 231579  0 100  0  0  0
zzz ***Mon Aug 30 17:55:53 CST 2012
135  4 4200956 923760   7812 19089344    0    0     4    45  570 14563  0 100  0  0  0
zzz ***Mon Aug 30 17:56:53 CST 2012
126  2 4200956 923784   8396 19083620    0    0   196  1121  651 15941  2 98  0  0  0

对于这种原因导致的重启问题,也适用于10g。

本文只是对11gR2诊断节点重启问题进行了简单的介绍,更详细的内容,请参考以下的内容
Note 1050693.1 : Troubleshooting 11.2 Clusterware Node Evictions (Reboots)

星期三 三月 28, 2012

如何诊断节点重启问题

本文对如何诊断RAC环境中节点重启问题进行了介绍。适用于10gR2和11gR1.

首先我们对能够导致节点重启的CRS进程进行介绍。
1.ocssd : 它的主要功能是节点监控(Node Monitoring)和组管理(Group Management),它是CRS的核心进程之一。节点监控是指监控集群中节点的健康,监控的方法是通过网络心跳(network heartbeat)和磁盘心跳(disk heartbeat)实现的,如果集群中的节点连续丢失磁盘心跳或网络心跳,该节点就会被从集群中驱逐,也就是节点重启。组管理导致的节点重启,我们称之为node kill escalation(只有在11gR1以及以上版本适用),我们会在后面的文章进行详细介绍。重启需要在指定的时间(reboot time,一般为3秒)内完成。

网络心跳:ocssd.bin进程每秒钟向集群中的各个节点通过私网发送网络心跳信息,以确认各个节点是否正常。如果某个节点连续丢失网络心跳达到阀值,misscount(默认为30秒,如果存在其他集群管理软件则为600秒),集群会通过表决盘进行投票,使丢失网络心跳的节点被主节点驱逐出集群,即节点重启。如果集群只包含2个节点,则会出现脑裂,结果是节点号小的节点存活下来,即使是节点号小的节点存在网络问题。

磁盘心跳:ocssd.bin进程每秒钟都会向所有表决盘(Voting File)注册本节点的状态信息,这个过程叫做磁盘心跳。如果某个节点连续丢失磁盘心跳达到阀值,disk timeou(一般为200秒),则该节点会自动重启以保证集群的一致性。另外,CRS只要求[N/2]+1个表决盘可用即可,其中N为表决盘数量,一般为奇数。

2.oclsomon:这个进程负责监控ocssd是否挂起,如果发现ocssd.bin存在性能问题,则重启该节点。
3.oprocd:这个进程只在Linux和Unix系统,并且第三方集群管理软件未安装的情况下才会出现。如果它发现节点挂起,则重启该节点。

注意:以上的所有进程都是由脚本init.cssd产生的。

接下来是诊断节点重启问题是经常搜集的信息。
1.操作系统日志
2.<crs主目录>/log/<节点名称>/cssd/ocssd.log
3.oprocd.log(/etc/oracle/oprocd/*.log.* 或 /var/opt/oracle/oprocd/*.log.*)
4.<crs主目录>/log/<节点名称>/cssd/oclsomon/oclsomon.log
5. Oracle OSWatcher 报告

接下来我们讨论如何诊断节点重启问题。

1.由ocssd导致的节点重启。
如果在ocssd.log中出现以下错误,则表示节点重启是由于丢失网络心跳。接下来需要查看和网络相关的信息,如操作系统日志,OSW报表(traceroute的输出),以确定网络层面(cluster interconnect)是否存在问题,并确定最终的原因。
[ CSSD]2012-03-02 23:56:18.749 [3086] >WARNING: clssnmPollingThread: node <node_name> at 50% heartbeat fatal, eviction in 14.494 seconds
[ CSSD]2012-03-02 23:56:25.749 [3086] >WARNING: clssnmPollingThread: node <node_name> at 75% heartbeat fatal, eviction in 7.494 seconds
[ CSSD]2012-03-02 23:56:32.749 [3086] >WARNING: clssnmPollingThread: node <node_name>at 90% heartbeat fatal, eviction in 0.494 seconds
[CSSD]2012-03-02 23:56:33.243 [3086] >TRACE:   clssnmPollingThread: Eviction started for node <node_name>, flags 0x040d, state 3, wt4c 0
[CSSD]2012-03-02 23:56:33.243 [3086] >TRACE:   clssnmDiscHelper: <node_name>, node(4) connection failed, con (1128a5530), probe(0)
[CSSD]2012-03-02 23:56:33.243 [3086] >TRACE:   clssnmDiscHelper: node 4 clean up, con (1128a5530), init state 5, cur state 5
[CSSD]2012-03-02 23:56:33.243 [3600] >TRACE:   clssnmDoSyncUpdate: Initiating sync 196446491
[CSSD]2012-03-02 23:56:33.243 [3600] >TRACE:   clssnmDoSyncUpdate: diskTimeout set to (27000)ms

注意:如果在主节点的ocssd.log中出现以上信息的时间点要晚于节点的重启时间,则说明节点重启的原因不是丢失网络心跳。

如果ocssd.log中出现以下错误,则表示节点重启是由于丢失磁盘心跳。接下来需要查看操作系统日志,OSWatcher报告(iostat的输出),以确定i/o层面是否存在问题,并确定最终的原因。
2010-08-13 18:34:37.423: [    CSSD][150477728]clssnmvDiskOpen: Opening /dev/sdb8
2010-08-13 18:34:37.423: [    CLSF][150477728]Opened hdl:0xf4336530 for dev:/dev/sdb8:
2010-08-13 18:34:37.429: [   SKGFD][150477728]ERROR: -9(Error 27072, OS Error (Linux Error: 5: Input/output error
Additional information: 4
Additional information: 720913
Additional information: -1)
)
2010-08-13 18:34:37.429: [    CSSD][150477728](:CSSNM00060: )clssnmvReadBlocks: read failed at offset 17 of /dev/sdb8
2010-08-13 18:34:38.205: [    CSSD][4110736288](:CSSNM00058: )clssnmvDiskCheck: No I/O completions for 200880 ms for voting file /dev/sdb8)
2010-08-13 18:34:38.206: [    CSSD][4110736288](:CSSNM00018: )clssnmvDiskCheck: Aborting, 0 of 1 configured voting disks available, need 1
2010-08-13 18:34:38.206: [    CSSD][4110736288]###################################
2010-08-13 18:34:38.206: [    CSSD][4110736288]clssscExit: CSSD aborting from thread clssnmvDiskPingMonitorThread
2010-08-13 18:34:38.206: [    CSSD][4110736288]###################################

2. 由oclsomon导致的节点重启。
如果在oclsomon.log 中出现错误,则表示节点重启是由于ocssd进程挂起,由于ocssd进程拥有实时(RT)优先级,很可能此时操作系统存在资源(如cpu)竞争,接下来需要察看操作系统日志,OSW报表(vmstat,top的输出),以确定最终的原因。

3.由oprocd导致的节点重启。
如果在oprocd日志中出现以下信息,则表明节点重启是由oprocd进程导致。

Dec 21 16:15:30.369857 | LASTGASP | AlarmHandler:  timeout(2312 msec) exceeds interval(1000 msec)+margin(500 msec).   Rebooting NOW.

由于oprocd进程通过查看系统时间以确定操作系统是否挂起,正确的配置ntp(或其他时间同步软件),调整diagwait=13 可以避免节点重启,另外,如果需要大幅度修改系��时间,建议首先停止CRS,在修改完成之后再重新启动。当然,我们也不排除操作系统挂起导致oprocd重启节点,所以,也需要查看OSWatcher报告(vmstat,top的输出),以确定最终的原因。

本文只是对诊断节点重启问题的思路进行了介绍,在具体实际问题当中还需要灵活运用。



关于更多的信息,请阅读以下的MOS 文章。
Note 265769.1 :Troubleshooting 10g and 11.1 Clusterware Reboots
Note 1050693.1 :Troubleshooting 11.2 Clusterware Node Evictions (Reboots)

About

本博客由Oracle全球技术支持中国区的工程师维护。为中文用户提供数据库相关的技术支持信息,包括常用的诊断工具、诊断方法、产品新特性、案例分析等。此外,MOS也陆续推出各类中文内容:技术通讯统一发布在Note 1529795.1 中,中文文档列表更新在Note 1533057.1 中,网上讲座请查看MOS文档 1456176.1,在"Archived"中可以下载历史的录音和文档。

Search

Archives
« 四月 2014
星期日星期一星期二星期三星期四星期五星期六
  
1
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
   
       
今天