Skip to content

Database - 48. page

Script to Collect DRM Information

参考文档：drmdiag.sql
适用 11.2.0.1 to 12.1.0.1 [Release 11.2 to 12.1]

-- NAME: DRMDIAG.SQL
-- ------------------------------------------------------------------------
-- AUTHOR: Michael Polaski - Oracle Support Services
-- ------------------------------------------------------------------------
-- PURPOSE:
-- This script is intended to provide a user friendly guide to troubleshoot
-- drm (dynamic resource remastering) waits. The script will create a file
-- called drmdiag_.out in your local directory.

set echo off
set feedback off
column timecol new_value timestamp
column spool_extension new_value suffix
select to_char(sysdate,'Mondd_hh24mi') timecol,
'.out' spool_extension from sys.dual;
column output new_value dbname
select value || '_' output
from v$parameter where name = 'db_name';
spool drmdiag_&&dbname&&timestamp&&suffix
set trim on
set trims on
set lines 140
set pages 100
set verify off
alter session set optimizer_features_enable = '10.2.0.4';
set feedback on

PROMPT DRMDIAG DATA FOR &&dbname&&timestamp
PROMPT Important paramenters:
PROMPT
PROMPT _gc_policy_minimum (default is 1500). Increasing this would cause DRMs to happen less frequently.
PROMPT Use the "OBJECT_POLICY_STATISTICS" section later in this report to see how active various objects are.
PROMPT
PROMPT _gc_policy_time (default to 10 (minutes)). Amount of time to evaluate policy stats. Use the
PROMPT "OBJECT_POLICY_STATISTICS" section later in this report to see how active various objects are for the
PROMPT _gc_policy_time. Usually not necessary to change this parameter.
PROMPT
PROMPT _gc_read_mostly_locking (default is TRUE). Setting this to FALSE would disable read mostly related DRMs.
PROMPT
PROMPT gcs_server_processes (default is derived from CPU count/4). May need to increase this above the
PROMPT default to add LMS processes to complte the work during a DRM but the default is usually adequate.
PROMPT
PROMPT _gc_element_percent (default is 110). May need to apply the fix for bug 14791477 and increase this to
PROMPT 140 if running out of lock elements. Usually not necessary to change this parameter.
PROMPT
PROMPT GC Related parameters set in this instance:
show parameter gc
PROMPT
PROMPT CPU count on this instance:
show parameter cpu_count

PROMPT
PROMPT SGA INFO FOR &&dbname&&timestamp
PROMPT
PROMPT Larger buffer caches (above 100 gig) may increase the cost of DRMs significantly.
set lines 120
set pages 100
column component format a40 tru
column current_size format 99999999999999999
column min_size format 99999999999999999
column max_size format 99999999999999999
column user_specified_size format 99999999999999999
select component, current_size, min_size, max_size, user_specified_size
from v$sga_dynamic_components
where current_size > 0;

PROMPT
PROMPT ASH THRESHOLD...
PROMPT
PROMPT This will be the threshold in milliseconds for total drm freeze
PROMPT times. This will be used for the next queries to look for the worst
PROMPT 'drm freeze' minutes. Any minutes that have an average log file
PROMPT sync time greater than the threshold will be analyzed further.
column threshold_in_ms new_value threshold format 999999999.999
select decode(min(threshold_in_ms),null,0,min(threshold_in_ms)) threshold_in_ms
from (select inst_id, to_char(sample_time,'Mondd_hh24mi') minute,
sum(time_waited)/1000 threshold_in_ms
from gv$active_session_history
where event like '%drm freeze%'
group by inst_id,to_char(sample_time,'Mondd_hh24mi')
order by 3 desc)
where rownum <= 10; PROMPT PROMPT ASH WORST MINUTES FOR DRM FREEZE WAITS: PROMPT PROMPT APPROACH: These are the minutes where the avg drm freeze time PROMPT was the highest (in milliseconds). column event format a30 tru column program format a35 tru column total_wait_time format 999999999999.999 column avg_time_waited format 999999999999.999 select to_char(sample_time,'Mondd_hh24mi') minute, inst_id, event, sum(time_waited)/1000 TOTAL_WAIT_TIME , count(*) WAITS, avg(time_waited)/1000 AVG_TIME_WAITED from gv$active_session_history where event like '%drm freeze%' group by to_char(sample_time,'Mondd_hh24mi'), inst_id, event having sum(time_waited)/1000 > &&threshold
order by 1,2;

PROMPT
PROMPT ASH DRM BACKGROUND PROCESS WAITS DURING WORST MINUTES:
PROMPT
PROMPT APPROACH: What is LMS doing when 'drm freeze' waits
PROMPT are happening? LMD and LMON info may also be relevant
column inst format 999
column minute format a12 tru
column event format a50 tru
column program format a55 wra
select to_char(sample_time,'Mondd_hh24mi') minute, inst_id inst,
sum(time_waited)/1000 TOTAL_WAIT_TIME , count(*) WAITS,
avg(time_waited)/1000 AVG_TIME_WAITED,
program, event
from gv$active_session_history
where to_char(sample_time,'Mondd_hh24mi') in (select to_char(sample_time,'Mondd_hh24mi')
from gv$active_session_history
where event like '%drm freeze%'
group by to_char(sample_time,'Mondd_hh24mi'), inst_id
having sum(time_waited)/1000 > &&threshold and sum(time_waited)/1000 > 0.5)
and (program like '%LMS%' or program like '%LMD%' or
program like '%LMON%' or event like '%drm freeze%')
group by to_char(sample_time,'Mondd_hh24mi'), inst_id, program, event
order by 1,2,3,5 desc, 4;

PROMPT
PROMPT POLICY HISTORY INFO:
PROMPT See if you can correlate policy history events with minutes of high
PROMPT wait time.
select * from gv$policy_history
order by event_date;
PROMPT
PROMPT DYNAMIC_REMASTER_STATS
PROMPT This shows where time is spent during DRM operations.
set heading off
set lines 60
select 'Instance: '||inst_id inst, 'Remaster Ops: '||remaster_ops rops,
'Remaster Time: '||remaster_time rtime, 'Remastered Objects: '||remastered_objects robjs,
'Quiesce Time: '||quiesce_time qtime, 'Freeze Time: '||freeze_time ftime,
'Cleanup Time: '||cleanup_time ctime, 'Replay Time: '||replay_time rptime,
'Fixwrite Time: '||fixwrite_time fwtime, 'Sync Time: '||sync_time stime,
'Resources Cleaned: '||resources_cleaned rclean,
'Replayed Locks Sent: '||replayed_locks_sent rlockss,
'Replayed Locks Received: '||replayed_locks_received rlocksr,
'Current Objects: '||current_objects
from gv$dynamic_remaster_stats
order by 1;
set lines 120
set heading on

PROMPT
PROMPT OBJECT_POLICY_STATISTICS:
PROMPT The sum of the last 3 columns (sopens,xopens,xfers) decides whether the object
PROMPT will be considered for DRM (_gc_policy_minimum). The duration of the stats
PROMPT are controlled by _gc_policy_time (default is 10 minutes).
select object,node,sopens,xopens,xfers from x$object_policy_statistics;

PROMPT
PROMPT ACTIVE OBJECTS (OBJECT_POLICY_STATISTICS)
PROMPT These are the objects that are above the default _gc_policy_minimum (1500).
select object, node, sopens+xopens+xfers activity
from x$object_policy_statistics
where sopens+xopens+xfers > 1500
order by 3 desc;

PROMPT LWM FOR LE FREELIST
PROMPT This number should never get near zero, if it does consider the fix for bug 14791477
PROMPT and/or increasing _gc_element_percent.
select sum(lwm) from x$kclfx;

PROMPT
PROMPT GCSPFMASTER INFO WITH OBJECT NAMES
column objname format a120 tru
select o.name || ' - '|| o.subname objname, o.type#, h.*
from v$gcspfmaster_info h, obj$ o where h.data_object_id=o.dataobj#
order by data_object_id;

PROMPT
PROMPT ASH DETAILS FOR WORST MINUTES:
PROMPT
PROMPT APPROACH: If you cannot determine the problem from the data
PROMPT above, you may need to look at the details of what each session
PROMPT is doing during each 'bad' snap. Most likely you will want to
PROMPT note the times of the high drm freezewaits, look at what
PROMPT LMS, LMD0, LMON is doing at those times, and go from there...
set lines 140
column program format a45 wra
column sample_time format a25 tru
column event format a30 tru
column time_waited format 999999.999
column p1 format a40 tru
column p2 format a40 tru
column p3 format a40 tru
select sample_time, inst_id inst, session_id, program, event, time_waited/1000 TIME_WAITED,
p1text||': '||p1 p1,p2text||': '||p2 p2,p3text||': '||p3 p3
from gv$active_session_history
where to_char(sample_time,'Mondd_hh24mi') in (select
to_char(sample_time,'Mondd_hh24mi')
from gv$active_session_history
where event like '%drm freeze%'
group by to_char(sample_time,'Mondd_hh24mi'), inst_id
having sum(time_waited)/1000 > &&threshold)
and time_waited > 0.5
order by 1,2,3,4,5;

spool off

PROMPT
PROMPT OUTPUT FILE IS: drmdiag_&&dbname&&timestamp&&suffix
PROMPT
Grid and Cluster Oracle Oracle 排障配置与调整 | Guang Cai Li | |   DRM

libXp.so.6: cannot open shared object file,during installing oracle database 11g on rhel as 6.1 x64

报错信息：

/tmp/OraInstall2011-09-24_10-16-11PM/jre/1.4.2/lib
/i386/libawt.so: libXp .so.6: cannot open  shared object file: No such file or directory occurred..

这个错误是我在以前安装时候碰到的，最近问的人挺多，则顺便趁早上这个点发布出来.首先我们从错误上看能很明显看到是libxp.so.6这个文件出问题了，但是你使用rpm -qa | grap libXp你会发现，这个包已经安装了，
仔细检查你会发现，系统提示的是/tmp/OraInstall2011-09-24_10-16-11PM/jre/1.4.2/lib/i386/libawt.so，i386而不是686，而现在安装的平台都常都是linux 6.1 x64上,默认安装的libXp版本也是64bit版本的，所以这里的解决办法基本就可以明了了，使用rpm -e | grep libXp，然后安装正确的386版本的libXp即可。如果有依赖包先卸载依赖包。

Database Linux Oracle Oracle 排障配置与调整 | Guang Cai Li | |   libXp.so.6 oracle 11g

使用Strace让oracle hgng住的测试

数据库hang住的原因很多,以往碰到得案例不少,大部分都和内存的抖动引起的进程僵死，或者bug造成，或者其他类似如归档满了，dg最高级模式下网络阻塞等原因.今天这里我介绍的这个案例偏门，几乎很难碰到.这里测试的版本为11.2.0.2版本，基于linux内核2.6.18 ×64. 且10g和11r1版本此类测试无效.这应该算是11.0.2.2的一个bug.

在linux中有一个命令strace，它常被用来跟踪进程执行时的系统调用和所接收的信号。
具体的参数含义如下：

-c 统计每一系统调用的所执行的时间,次数和出错的次数等.
-d 输出strace关于标准错误的调试信息.
-f 跟踪由fork调用所产生的子进程.
-ff 如果提供-o filename,则所有进程的跟踪结果输出到相应的filename.pid中,pid是各进程的进程号.
-F 尝试跟踪vfork调用.在-f时,vfork不被跟踪.
-h 输出简要的帮助信息.
-i 输出系统调用的入口指针.
-q 禁止输出关于脱离的消息.
-r 打印出相对时间关于,,每一个系统调用.
-t 在输出中的每一行前加上时间信息.
-tt 在输出中的每一行前加上时间信息,微秒级.
-ttt 微秒级输出,以秒了表示时间.
-T 显示每一调用所耗的时间.
-v 输出所有的系统调用.一些调用关于环境变量,状态,输入输出等调用由于使用频繁,默认不输出.
-V 输出strace的版本信息.
-x 以十六进制形式输出非标准字符串
-xx 所有字符串以十六进制形式输出.
-a column
设置返回值的输出位置.默认 为40.
-e expr
指定一个表达式,用来控制如何跟踪.格式如下:
[qualifier=][!]value1[,value2]...
qualifier只能是 trace,abbrev,verbose,raw,signal,read,write其中之一.value是用来限定的符号或数字.默认的 qualifier是 trace.感叹号是否定符号.例如:
-eopen等价于 -e trace=open,表示只跟踪open调用.而-etrace!=open表示跟踪除了open以外的其他调用.有两个特殊的符号 all 和 none.
注意有些shell使用!来执行历史记录里的命令,所以要使用\\.
-e trace=set
只跟踪指定的系统 调用.例如:-e trace=open,close,rean,write表示只跟踪这四个系统调用.默认的为set=all.
-e trace=file
只跟踪有关文件操作的系统调用.
-e trace=process
只跟踪有关进程控制的系统调用.
-e trace=network
跟踪与网络有关的所有系统调用.
-e strace=signal
跟踪所有与系统信号有关的 系统调用
-e trace=ipc
跟踪所有与进程通讯有关的系统调用
-e abbrev=set
设定 strace输出的系统调用的结果集.-v 等与 abbrev=none.默认为abbrev=all.
-e raw=set
将指 定的系统调用的参数以十六进制显示.
-e signal=set
指定跟踪的系统信号.默认为all.如 signal=!SIGIO(或者signal=!io),表示不跟踪SIGIO信号.
-e read=set
输出从指定文件中读出 的数据.例如:
-e read=3,5
-e write=set
输出写入到指定文件中的数据.
-o filename
将strace的输出写入文件filename
-p pid
跟踪指定的进程pid.
-s strsize
指定输出的字符串的最大长度.默认为32.文件名一直全部输出.
-u username
以username 的UID和GID执行被跟踪的命令

如果做过在linux的开发，那么对这个命令一定不会陌生，哈哈。闲话不多说，我们接着猪蹄，今天我们主要是采用-p -o这2个参数，用它对oracle的进程进行跟踪调用。
首先我对lgwr进程进行跟踪调用，执行如下：

[root@ludatou ~]# ps -ef | grep lgwr
root     10136  9578  0 06:30 pts/1    00:00:00 grep lgwr
ora10g   32496     1  0 Apr15 ?        00:00:04 ora_lgwr_lu11r2
[root@ludatou ~]# export ORACLE_SID=lu11r2
[root@ludatou ~]# strace -p $(pgrep -fx ora_lgwr_$ORACLE_SID) -o /tmp/l.out -T &
[1] 10257
[root@ludatou ~]# Process 32496 attached - interrupt to quit

这个时候日志l.out的输出大致如下（我db是空闲的）：

gettimeofday({1397602111, 401986}, NULL) = 0 <0.000032>
gettimeofday({1397602111, 402111}, NULL) = 0 <0.000032>
gettimeofday({1397602111, 402233}, NULL) = 0 <0.000032>
gettimeofday({1397602111, 402356}, NULL) = 0 <0.000031>
gettimeofday({1397602111, 402510}, NULL) = 0 <0.000032>
gettimeofday({1397602111, 402537}, NULL) = 0 <0.000011>
gettimeofday({1397602111, 402551}, NULL) = 0 <0.000007>
gettimeofday({1397602111, 402560}, NULL) = 0 <0.000005>
times(NULL)                             = 436324232 <0.000002>
gettimeofday({1397602111, 402570}, NULL) = 0 <0.000003>
gettimeofday({1397602111, 402573}, NULL) = 0 <0.000002>
semtimedop(131073, 0xbfa12088, 1, {3, 0}

这个时候数据库运行正常，正常读写提交，具体如下：

SQL> conn luda/luda
Connected.
SQL> create table t1 as select * from dba_objects;

Table created.

SQL> alter table t1 add ludatou varchar2(200);

Table altered.

SQL> update t1 set ludatou=250;

50068 rows updated.

SQL> commit;

Commit complete.

下一步我将strace跟踪lgwr的进程杀掉后，再看看数据库是否运行正常，具体如下：

1.杀掉跟踪进程

[root@ludatou ~]# kill %1
[root@ludatou ~]# Process 32496 detached
--这个时候提示守护进程和32496进程（lgwr）分离

2.在数据库层面执行
SQL> update t1 set ludatou=250;

50068 rows updated.

SQL> commit;

到这一步会发现….一直没反应，查看全库等待事件为log file sync.这个时候检测lgwr的进程状态可以发现为如下：

[ora11g@ludatou ~]$ ps $(pgrep -fx ora_lgwr_$ORACLE_SID)
  PID TTY      STAT   TIME COMMAND
32496 ?        Ts     0:00 ora_lgwr_lu11r2

进程32496为Ts的状态，意味着该进程为停止状态或者该进程被其他进程控制.但是实际上我已经把strace停止。我们将其唤醒：

kill -SIGCONT 32496
[ora11g@ludatou ~]$ ps $(pgrep -fx ora_lgwr_$ORACLE_SID)
  PID TTY      STAT   TIME COMMAND
32496 ?        Ss     0:00 ora_lgwr_lu11r2

这个时候进程变为ss状态，而且数据库也随之恢复正常。这不知道应算是数据库的bug还是linux的bug，个人更倾向linux，毕竟我执行退出strace了，实际上strace进程还附加在lgwr进程上不断callout进程。这个测试我只在11.2.0.2，11.1.0.7，10.2.0.4版本上测试过，目前只有11.2.0.2有这个情况。

Database Grid and Cluster Linux Oracle Oracle 排障配置与调整 等待事件 | Guang Cai Li |

遭遇ORA-00600 [ksnwait:nsevwait]

遭遇ORA-00600 [ksnwait:nsevwait]

这件事情在遭遇时候恰巧我们公司一个上海工程师到客户现场修复数据库安全漏洞打了CPU，但是当天晚上数据库就宕机了，客户把事故的根源矛头直指我们，临危受命之下连夜赶往客户现场。
在现场后才感受到此次故障对客户的影响之深，科技部的领导都到位了，匆匆忙忙落位开始诊断，发现数据库alert.log报错如下：

Errors in file /app/oracle/diag/rdbms/prod/prod/trace/prod_pmon_401638.trc:
ORA-00600: internal error code, arguments: [ksnwait:nsevwait], [], [], [], [], [], [], [], [], [], [], []
PMON (ospid: 401638): terminating the instance due to error 472
Instance terminated by PMON

当前环境为：
aix 6.1
oracle 11.2.0.1

从上面的报错可以很明确的看到是因为pmon进程宕掉,最终引起数据库崩溃.

关键报错信息00600，ksnwait:nsevwait,这类报错第一眼的感觉就是bug，在OTN上验证了我的诊断，此错误为bug8554900引起,修复补丁为Patch:8554900.
在不应用修复补丁的情况下可以通过尝试使用用参数SQLNET.OUTBOUND_CONNECT_TIMEOUT设置大一点的值去规避,这个bug在11.2.0.2版本之后修复完了，而且考虑到这个版本为11.2.0.1的初始版本，漏洞会比较多，我建议直接将数据库升级到版本11.2.0.3.8版本，客户同意了我的解决方案，并于当晚升上去，最终和开发部分standby一晚上，我还做好了各种回退工作，技术不累人，就是熬夜真心伤身.也幸好客户对我们的信任依然如旧.

总结：
由上面所见，选择一个稳定的数据库版本，可以为后续的数据库运维工作，为数据库的运行带来长远的效益。且行且小心。

Database Oracle Oracle 排障配置与调整 | Guang Cai Li | |   11.2.0.1 bug8554900 ksnwait:nsevwait

Oracle异常错误在数据库层面的跟踪—ERRORSPACK

最近在一个项目中碰到一个事情，缘由大概如下：
业务由中间价tomcat连接到oracle db，每连接一次呢要插入对应表中一条数据，结果出现了偶尔报错ora-01461的错误，估计是因为插入的数据表中对应字段使用varchar2类型数据，但是经过字符集转换后由于长短不一直造成自负超过4000字节，此时数据库会将数据类型转换成long字段类型数据插入，导致字段类型不一致，所以报错01046的错误。
像这类错误只会在业务前端展示，在数据库这层无法看到明确的报错，解决这类问题有2个思路：

一是更新jdbc的驱动；

二是找到对应的表更改字段的varchar2为long等长字段。

我遇到情况是上面的第一种，当时我采用oracle 10g最新的jdbc驱动更新中间件的tomcat（数据库版本为9206），但是很遗憾隔了没多久又出现同样的报错情况。最终我决定要找到对应的表，可是这时候应用开发也不知道是哪张表，无赖之下只能在oracle层面采取errorstack的方式跟踪，大概的原理如下：

errorstack事件：dump 错误栈信息，通常Oracle发生错误时前台进程将得到一条错误信息，但某些情况下得不到错误信息，可以采用这种方式得到Oracle错误。

使用语法：

alter session set events ’12899 trace name errorstack forever’; 不需要重启数据库，在session级别生效。
alter system set events ’12899 trace name errorstack forever’;-需要重启数据库，在全局系统生效

我这里以错误ORA-12899的方式为例，具体如下：

执行语句：

alter system set events ’12899 trace name errorstack forever’;

SQL> alter system set events '12899 trace name errorstack forever';

System altered.

SQL> desc t1
Name Null? Type
----------------------------------------- -------- ----------------------------
ID NUMBER
NAME VARCHAR2(4)

SQL> insert into t1 values(250,'ludatou');
insert into t1 values(250,'ludatou')
*
ERROR at line 1:
ORA-12899: value too large for column "SYS"."T1"."NAME" (actual: 7, maximum: 4)

可以在user_dump下找到最新的dump，ls -lFrt，就为此次错误的跟踪trace,Trace的内容如下：

*** 2014-01-15 17:24:13.461
----- Error Stack Dump -----
ORA-12899: value too large for column "SYS"."T1"."NAME" (actual: 7, maximum: 4)
----- Current SQL Statement for this session (sql_id=8f4g5vujpymhg) -----
insert into t1 values(250,'ludatou')
↑↑↑↑↑
这个trace把语句也抓起来了。

----- Call Stack Trace -----
calling call entry argument values in hex
location type point (? means dubious value)
-------------------- -------- -------------------- ----------------------------

*** 2014-01-15 17:24:13.992
skdstdst()+38 call kgdsdst() BFD338FC ? 2 ?
ksedst1()+88 call skdstdst() BFD338FC ? 0 ? 1 ? AC9E128 ?
8551B9E ? AC9E128 ?
ksedst()+33 call ksedst1()+8 0 ? F9F580 ? 2050033 ? 0 ?
FF ? 2004 ?
dbkedDefDump()+1062 call ksedst() 0 ? 0 ? 0 ? 0 ? 0 ? 0 ?
ksedmp()+47 call dbkedDefDump() 1 ? 0 ?
dbkdaKsdActDriver() call 00000000 1 ? 1F060C ? 1D19EC ? 0 ?
+1481 FAA03A0 ? F9E3720 ?
dbgdaExecuteAction( call 00000000 F9F580 ? BFD35630 ?
)+595
dbgdaRunAction()+89 call dbgdaExecuteAction( F9F580 ? F21B294 ? 20C0002 ?
4 ) BFD35630 ? 1 ?
dbgdRunActions()+64 call dbgdaRunAction() F9F580 ? 71D0810 ?
dbgdProcessEventAct call dbgdRunActions() DC16520 ? DC16529 ?
ions()+604
dbgdChkEventKgErr() call dbgdProcessEventAct F9F580 ? FAA03A0 ? 71D093C ?
+1542 ions() 0 ? 1 ? EA055FB ?
dbkdChkEventRdbmsEr call dbgdChkEventKgErr() F9F580 ? 223BAD0 ? 3263 ?
r()+23
__PGOSF12_ksfpec()+ call dbkdChkEventRdbmsEr 3263 ? 8 ? EABE0A0 ?
139 r() EABE0A0 ? EAB6A38 ?
BFD35F24 ?
dbgePostErrorKGE()+ call 00000000 FAA03A0 ? 3263 ?
825
Database Middleware Oracle Oracle 排障配置与调整 | Guang Cai Li | |   ERRORSPACK middleware ORACLE tomcat