Skip to content

Oracle 排障配置与调整 - 14. page

使用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有这个情况。

遭遇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一晚上,我还做好了各种回退工作,技术不累人,就是熬夜真心伤身.也幸好客户对我们的信任依然如旧.

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

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

浅谈ORA-12545 / TNS-12545故障诊断思路

前一个刚经历rac安装完后遭遇的ORA-12545错误,这里就顺便把这个错误的诊断思路理出来,毕竟这个错误在10g后还是比较常见,本文只是对这个故障的处理诊断思路做一些经验上的讨论,纯为有趣。

12545的报错提示为如下:

ORA-12545 / TNS-12545 Connect failed because target host or object does not exist

先往下聊吧,这类错误通常是和hostname相关配置不正确有关,举个例子

[ora10g@ludatou ~]$ tnsping lu10g
TNS Ping Utility for Linux: Version 10.2.0.4.0 - Production on 15-APR-2014 12:08:27
Copyright (c) 1997,  2007, Oracle.  All rights reserved.
Used parameter files:

Used TNSNAMES adapter to resolve the alias
Attempting to contact (DESCRIPTION = (ADDRESS = (PROTOCOL = TCP)(HOST = ludatou)(PORT = 1523)) (CONNECT_DATA = (SERVER = DEDICATED) (SERVICE_NAME = lu10g)))
OK (10 msec)

[ora10g@ludatou ~]$ sqlplus luda/luda@lu10g
SQL*Plus: Release 10.2.0.4.0 - Production on Tue Apr 15 12:12:15 2014
Copyright (c) 1982, 2007, Oracle.  All Rights Reserved.

Connected to:
Oracle Database 10g Enterprise Edition Release 10.2.0.4.0 - Production
With the Partitioning, OLAP, Data Mining and Real Application Testing options

=====这里我的tnsnames配置的解析主机名是ludatou,而且采用网络验证方式登录成功
[ora10g@ludatou ~]$ cat /etc/hosts
# Do not remove the following line, or various programs
# that require network functionality will fail.
127.0.0.1               localhost.localdomain localhost
192.168.102.128         ludatou   luda
=====在这边我把/etc/hosts文件的主机名ludatou变更为ludatouxx,变更结果如下
[ora10g@ludatou ~]$ cat /etc/hosts
# Do not remove the following line, or various programs
# that require network functionality will fail.
127.0.0.1               localhost.localdomain localhost
192.168.102.128         ludatouxx   luda
 

再次在客户端(另外一个主机)远程登录,在响应了很久之后报错

[root@ludatou ~]# su - oracle
[oracle@ludatou ~]$ sqlplus luda/luda@lu10g
SQL*Plus: Release 11.1.0.7.0 - Production on Tue Apr 15 12:13:40 2014
Copyright (c) 1982, 2008, Oracle.  All rights reserved.

ERROR:
ORA-12545 Connect failed because target host or object does not exist
 

下来以分类场景的方式来描述这类故障的诊断:
场景1:
当连接数据库不通过listener的时候,而是使用BEQ协议来连接数据库,这个时候如果$ORACLE_HOME/bin目录下oracle文件丢失或者损坏,用户执行权限不足,以及Oracle_home(多个安装版本)的路径设置错误的情况下,使用beq协议连接oracle的用户就会遭遇ORA/TNS-12545的错误。
关于BEQ协议可以参考如下解释:

This is the bequeth oracle process. The bequeth process starts first. Later all the processes related to particular database are controlled by its bequeth process. 

场景2:
这个场景就是上面我所做的测试场景,由客户端通过listner连接服务端oracle数据库,这个时候如果客户端的tnsnames解析文件中对应service name部分的hostname和服务端的hostname不匹配,就会报错ora-12545.
在这个场景中可以使用nslookup命令来搜索对应的主机,按照上面的例子,这里使用nslookup命令搜索ludatou主机时候则会出现以下情况:

$ nslookup ludatou
Server: 192.168.102.128
Address: 192.168.1.102#53
** server can't find ludatou: ==>Indicates ludatou is not resolvable on the machine

这个场景的解决办法就是把客户端的tnsnames中的hostname部分写为ip,避免服务端主机名变更导致配置不符的情况出现。

场景3:
参考 RAC实施完遭遇ORA-12545

Cause: One of the hostname (which corresponds to public IP or VIP) is not reachable from this client machine.
When the server side load balancing is enabled in the RAC setup, the listener will redirect the connection to the least loaded node.While doing so, the server sends the packet NSPTRD containing the hostname of the corresponding machine.

The Remote Service Handler value registered with the remote Listener process via the REMOTE_LISTENER parameter is built by the LOCAL_LISTENER value on the local server.So, its necessary to check whether the local_listener / remote listener information are reflected properly in the listener services output as well.

Diagnosis:
Enable the oracle sqlnet client tracing at support level, and reproduce the issue.In the generated client trace, you would see the below information:
After NSPTCN Connect to the listener , listener sends

场景4:
listerner.ora的hostname配置错误,导致监听无法找寻到正确的监听地址,也会产生ora/tns-12545的错误。具体监听日志报错如下:

Error listening on: (DESCRIPTION=(ADDRESS=(PROTOCOL=TCP)(HOST=abc)(PORT=1522)))
TNS-12545: Connect failed because target host or object does not exist
TNS-12560: TNS:protocol adapter error
TNS-00515: Connect failed because target host or object does not exist

如果打开了sqlnet的trace跟踪,可以发现类似如下的报错:

nsc2addr: (DESCRIPTION=(ADDRESS=(PROTOCOL=TCP)(HOST=abc)(PORT=1522)))
nttbnd2addr: entry
snlinGetAddrInfo: entry
snlinGetAddrInfo: Invalid IP address string abc
snlinFreeAddrInfo: entry
snlinFreeAddrInfo: exit
snlinGetAddrInfo: exit
nttbnd2addr: looking up IP addr for host: abc
snlinGetAddrInfo: entry
snlinGetAddrInfo: Name resolution failed for abc
snlinFreeAddrInfo: entry
snlinFreeAddrInfo: exit
snlinGetAddrInfo: exit
nttbnd2addr: *** hostname lookup failure! ***
nttbnd2addr: exit
nserror: entry
nserror: nsres: id=0, op=78, ns=12545, ns2=12560; nt[0]=515, nt[1]=0, nt[2]=0; ora[0]=0, ora[1]=0, ora[2]=0

这类问题解决办法就是检测监听的配置是否和主机的ip,hostname配置吻合,不吻合的情况下会造成12545的错误。

场景5:
操作系统或者硬件问题也会导致产生ora/tns-12545的产生。
5.1windows 2000 with Service Pack 3 会导致这个ora/tns-12545 的产生
http://support.microsoft.com/default.aspx?scid=kb;en-us;329405
5.2Solaris系统在配置不正确情况下也会导致ora/tns-12545的产生

以上的场景描述是对1254错误的故障做一些分类分析,大概的诊断思路也是这样。

当然以上只是针对12545,oracle网络的错误有很多,对于诊断oracle网络错误,我个人的习惯诊断流程是如下
1.check listener.log确认是否有报错信息
2.check syslog是否有设备或者系统的报错信息
3.check $ORACLE_HOME/bin/oracle文件是否存在以及权限正确与否
4.check tnsnames,sqlnet,listener的配置是否与主机对应
5.在rac环境下,我会优先检查节点和client的通信情况,网络配置文件是否配置正确,最后才是taf和ld的影响
6.必要时候开启trace进一步跟踪详细信息

ORA-01628: max # extents (32765) for rollback seg

这个故障的情形是这样的,不停报错01628,业务挂起,回滚表空间从10g扩到32g后,也会产生同样的报错,而且回滚使用率100%。
Oracle版本: 10201
系统平台: HP-UN
这个错误我曾经在9i的版本上遭遇,但是不是bug,当时是更改回滚的storage参数设置extent限制为unlimited解决,而这里10201版本下设置为unlimited则无用,与官方文档反复效验后确认和bug 6499872吻合。
最终通过升级数据库的办法规避此bug,同时也再次说明,选择一个稳定的数据库版本是多么的重要。

官方描述如下:

Applies to:
Oracle Database - Enterprise Edition - Version 9.2.0.1 to 11.1.0.7 [Release 9.2 to 11.1]
Information in this document applies to any platform.
Details
Bug 6499872  ORA-01628: max # extents (32765) for rollback seg

 This note gives a brief overview of bug 6499872.
 The content was last updated on: 12-DEC-2008
 Click here for details of each of the sections below.
Affects:

    Product (Component) 	Oracle Server (Rdbms)
    Range of versions believed to be affected 	Versions >= 9.2 but BELOW 11.2
    Versions confirmed as being affected

        10.2.0.3
        10.2.0.2
        10.1.0.5
        9.2.0.8

    Platforms affected 	Generic (all / most platforms affected)

Fixed:

    This issue is fixed in

        11.1.0.7 (Server Patch Set)
        10.2.0.4 (Server Patch Set)

Symptoms:

Related To:

    ORA-1628



    System Managed Undo (SMU)

Description

    Once an undo segment was filled up with maxextents and the transaction got an
    ORA-1628, other transactions that bound to the same undo segment also will get same
    error code.

    REDISCOVERY INFORMATION:
    Repeated ORA-1628 errors with AUM and

    * many offline undo segments.  More than the average number of transactions
    * The undo segment referenced on error ORA-1628 will have high number of unexpired extents

    The following queries can be used to identify the bug:

    alter session set nls_date_format='mm/dd/yy hh24:mi:ss';
    set pagesize 200
    set linesize 200
    set echo on

    select sysdate from dual;

    COL undots NOPRINT NEW_VALUE p_undots FORMAT A20;
    SELECT value FROM gv$parameter WHERE name='undo_tablespace' and inst_id=sys_context('userenv','instance');

    select (nvl(sum(bytes),0)) from dba_free_space  where  tablespace_name = '&&p_undots';

    select sum(bytes)  from dba_data_files where tablespace_name = (select value from gv$parameter
    where name='undo_tablespace' and inst_id=sys_context('userenv','instance') );

    select segment_name,  nvl(sum(act),0) "ACT BYTES",    nvl(sum(unexp),0) "UNEXP BYTES", nvl(sum(exp),0) "EXP BYTES"
    from ( select segment_name,          nvl(sum(bytes),0) act,00 unexp, 00 exp
           from    DBA_UNDO_EXTENTS
           where status='ACTIVE'  and tablespace_name =   '&&p_undots'
           group by segment_name
           union
           select segment_name,00 act, nvl(sum(bytes),0) unexp, 00 exp from    DBA_UNDO_EXTENTS
           where status='UNEXPIRED'  and tablespace_name =  '&&p_undots'
           group by segment_name
           union
           select segment_name,            00 act, 00 unexp, nvl(sum(bytes),0) exp
           from    DBA_UNDO_EXTENTS
           where status='EXPIRED'  and tablespace_name =   '&&p_undots'
           group by segment_name
          ) group by segment_name;

    select status,count(*)  from dba_rollback_segs  group by status;



Please note: The above is a summary description only. Actual symptoms can vary. Matching to any symptoms here does not confirm that you are encountering this problem. For questions about this bug please consult Oracle Support.
References

    Bug:6499872 (This link will only work for PUBLISHED bugs)
    Note:245840.1 Information on the sections in this article