本来正在研究Mutex的算法,发现在11.2.0.1到11.2.0.3之间,Oracle对Mutex算法做出很大的调整,听闻12C发布,一时心痒,不知12C中Mutex又有哪些变化,马上Down下Solaris版的12C,准备安装。
声明下,之所以要装Solaris下的12C,并非我独立特行,看过我以前文章的Puber一定知道,是因为Dtrace的原故。这个简单的工具可以帮助我们掀开Oracle重重黑幕,一窥Oracle内部原理。
我的OS是Solaris 10,以下是我的Solaris版本信息:
bash-3.2$ uname -r
5.10
bash-3.2$ cat release
Oracle Solaris 10 8/11 s10x_u10wos_17b X86
Copyright (c) 1983, 2011, Oracle and/or its affiliates. All rights reserved.
Assembled 23 August 2011
我的Solaris是默认安装,没有使用Customs方式,安装非常简单,不需描述。下面说说12C的安装过程。
其实和11GR2也差不太多,非常简单,只在条件检查这里,报如下错误:Swap空间期望是3G,我只有500M。还有/tmp空间,我的是1G。这两个原来装11GR2时也报错,不过后安装也是成功的,这里我毫不犹豫选择“忽略”。后一个,缺少SUNWeu8os包,本来是想解决一下的,但简单百度了一下,没有找到装这个包的相关信息。心急之下,把它也忽略了。
接下来安装也还算顺利,就是在后装的百分之八十几时,报了一个错,Retry一下,还是报错,只能跳过。然后就没有报错了,安装过程还算顺利的完成了。
急不可待的sqlplus / as sysdba,准备手动建个库玩玩。但是,报如下错误:
bash-3.2$ sqlplus / as sysdba
SQL*Plus: Release 12.1.0.1.0 Production on Thu Jun 27 16:33:23 2013
Copyright (c) 1982, 2013, Oracle. All rights reserved.
ERROR:
ORA-12560: TNS:protocol adapter error
Enter user-name:
ORA-12560这种情况在Windows下比较常见,也比较容易解决,但在其他系统中遇到,就比较棘手了。
本来想绕过去,不让我本地连接,我就通过监听连接。于是配置了监听,生成了密码文件,还有tnsnames.ora,然后通过监听连接,依然报错,错误信息如下:
bash-3.2$ sqlplus sys/oracle@prod as sysdba
SQL*Plus: Release 12.1.0.1.0 Production on Thu Jun 27 17:09:54 2013
Copyright (c) 1982, 2013, Oracle. All rights reserved.
ERROR:
ORA-12537: TNS:connection closed
变成了ORA-12537错误,还是连不上。
遇到这种奇怪问题,也没啥思路,我们的方法,只能是各种各样的跟踪。要想解决问题,必先了解问题出在哪个环境。要想知道问题出在哪个环节,也只能跟踪了。但是这点问题还不需要Dtrace和gdb/mdb,先用Truss试试就行,看看连接时有什么系统调用。
先不连接进入Sqlplus:
bash-3.2$ sqlplus /nolog
SQL*Plus: Release 12.1.0.1.0 Production on Thu Jun 27 17:24:00 2013
Copyright (c) 1982, 2013, Oracle. All rights reserved.
SQL>
然后查一下sqlplus的进程号:
bash-3.2$ ps -ef|grep sql
oracle 969 872 0 17:24:01 pts/2 0:00 sqlplus /nolog
接着跟踪969进程,并将结果写到/tmp/sqlplus.log中:
bash-3.2$ truss -o /tmp/sqlplus.log -p 969
然后在sqlplus /nolog中connect连接:
SQL> conn / as sysdba
ERROR:
ORA-12560: TNS:protocol adapter error
查看跟踪结果,没发现太有用的信息,但也有些收获,发现有很多这样的信息:
stat("/export/home/oradb/diag/clients/user_oracle/host_1667750511_80/alert/log.xml", 0xFFFFFD7FFFDE8320) = 0
open("/export/home/oradb/diag/clients/user_oracle/host_1667750511_80/trace/sqlnet.log", O_WRONLY|O_APPEND|O_CREAT|O_LARGEFILE, 0660) = 11
chown("/export/home/oradb/diag/clients/user_oracle/host_1667750511_80/trace/sqlnet.log", 4294967295, 101) = 0
stat("/export/home/oradb/diag/clients/user_oracle/host_1667750511_80/trace/sqlnet.log", 0xFFFFFD7FFFDEAAA0) = 0
chmod("/export/home/oradb/diag/clients/user_oracle/host_1667750511_80/trace/sqlnet.log", 0640) = 0
从这些可以看到,虽然我并没有通过监听连接,但SQLPLUS还是要向监听日志和sqlnet.log日志中写信息。马上打开log.xml和sqlnet.log,看一下是否有更详细的信息。
它们两个中的信息类似,以sqlnet.log为例,找到一些报错:
Fatal NI connect error 12560, connecting to:
(DESCRIPTION=(ADDRESS=(PROTOCOL=beq)(PROGRAM=/export/home/oradb/product/12.1.0/bin/oracle)(ARGV0=oracleh3)(ARGS='(DESCRIPTION=(LOCAL=YES)(ADDRESS=(PROTOCOL=beq)))')(DETACH=NO))(CONNECT_DATA=(CID=(PROGRAM=sqlplus@h3)(HOST=h3)(USER=oracle))))
VERSION INFORMATION:
TNS for Solaris: Version 12.1.0.1.0 - Production
Oracle Bequeath NT Protocol Adapter for Solaris: Version 12.1.0.1.0 - Production
Time: 27-JUN-2013 17:49:37
Tracing not turned on.
Tns error struct:
ns main err code: 12560
TNS-12560: TNS:protocol adapter error
ns secondary err code: 0
nt main err code: 530
TNS-00530: Protocol adapter error
nt secondary err code: 8
nt OS err code: 0
除了TNS-12560,它和ORA-12560对应。还有个TNS-00530,这个不知道是干吗的,也算有点收获。GooGle、百度一下,没发现太有用的信息。这个新发现的TNS-00530,对解决问题没啥太大帮助。
接下来怎么办?既然Sqlplus会向sqlnet.log中写日志,只要提高日志的级别,让它输出更详细的信息,说不定可以找到更详细的信息定位问题。马上动手,还是原来的位置:$ORACLE_HOME/network/admin,创建sqlnet.ora文件,我输入的内容如下:
bash-3.2$ cat sqlnet.ora
DIAG_ADR_ENABLED=on
ADR_BASE=/export/home/oracle/trace
TRACE_LEVEL_CLIENT=16
TRACE_LEVEL_SERVER=16
关于这几个参数,在12C的文档“Net Services Reference”章节中sqlnet.ora配置小节,“ADR Diagnostic Parameters in sqlnet.ora”部分有介绍。开启连接时的跟踪,两个级别值16,已经是高的级别了。文档中有介绍的:
TRACE_LEVEL_CLIENT
Purpose
To turn client tracing on at a specified level or to turn it off. This parameter is also applicable when non-ADR tracing is used.
Default
off or 0
Values
- off or 0 for no trace output
- user or 4 for user trace information
- admin or 10 for administration trace information
- support or 16 for Oracle Support Services trace information
Example
TRACE_LEVEL_CLIENT=user
其他参数我不再粘了,你自己查阅吧。
还有,参数“ADR_BASE=/export/home/oracle/trace”中的目录:trace,一定要创建下。
好,再用sqlplus / as sysdba连接下,错误当然还是依旧了。到/export/home/oracle/trace目录中查看,Oracle建了好多层目录,在/export/home/oracle/trace/oradiag_oracle/diag/clients/user_oracle/host_1667750511_80/trace目录中,用“ls –lFrt”查询日志新的trc文件,就是跟踪结果了。
跟踪结果非常详细,有Sqlplus希望在sqlnet.ora中读取的参数等等,想了解进程连接过程的,可以好好研究下这份跟踪文件。先不管这些,在跟踪结果中找一下错误信息,有这样一段报错:
2013-06-27 22:20:02.380430 : sntpcall:entry
2013-06-27 22:20:02.380477 : sntpcall:not detaching from parent with additional fork
2013-06-27 22:20:02.380506 : sntpcall:waiting for OS to spawn process /export/home/oradb/product/12.1.0/bin/oracle
2013-06-27 22:20:02.386670 : sntpcall:process forked.
2013-06-27 22:20:02.387077 : sntpcall:hdl[IR]=16, hdl[IW]=15
2013-06-27 22:20:02.387144 : sntpcall:spawned process initialized in 0 csec.
2013-06-27 22:20:02.387181 : sntpcall:result string is NTP8 0
2013-06-27 22:20:02.387241 : sntpcall:Can't read from pipe; err[1] = 8
2013-06-27 22:20:02.387293 : sntpcall:exit
2013-06-27 22:20:02.387373 : ntpcon:exit
2013-06-27 22:20:02.387431 : nserror:entry
2013-06-27 22:20:02.387469 : nserror:nsres: id=0, op=65, ns=12560, ns2=0; nt[0]=530, nt[1]=8, nt[2]=0; ora[0]=0, ora[1]=0, ora[2]=0
2013-06-27 22:20:02.387517 : nsopen:unable to open transport
2013-06-27 22:20:02.387552 : nstoClearTimeout:entry
2013-06-27 22:20:02.387582 : nstoClearTimeout:ATO disabled for ctx=0x558520
2013-06-27 22:20:02.387642 : nstoClearTimeout:STO disabled for ctx=0x558520
2013-06-27 22:20:02.387672 : nstoClearTimeout:RTO disabled for ctx=0x558520
2013-06-27 22:20:02.387698 : nstoClearTimeout:PITO disabled for ctx=0x558520
2013-06-27 22:20:02.387726 : nstoUpdateActive:entry
2013-06-27 22:20:02.387754 : nstoUpdateActive:Active timeout is -1 (see nstotyp
“sntpcall:waiting for OS to spawn process /export/home/oradb/product/12.1.0/bin/oracle”这行,说明这是要执行Oracle的可执行文件。它下面没几行,有个报错:“sntpcall:Can't read from pipe; err[1] = 8”,这说明很有可能是Oracle可执行文件执行有问题,导致官道异常。
这些信息说明,十有八九是Oracle可执行文件执行出了问题。我找了一个11GR2的测试环境,试了一下Sqlplus / as sysdba时的Trc文件,也有类似步骤,但没有“sntpcall:Can't read from pipe; err[1] = 8”。
接下来,会是什么导致Oracle可执行文件异常呢?我先到$ORACLE_HOME/bin下,查看下Oracle可执行文件的信息:
bash-3.2$ ls -lFrt /export/home/oradb/product/12.1.0/bin/oracle
-rwxr-x--x 1 oracle oinstall 0 Jun 27 16:33 /export/home/oradb/product/12.1.0/bin/oracle*
查看的结果如上,问题已经一目了然了。
它的权限不对,还有文件的长度竞然是0字节。0字节的可执行文件,当然执行异常了。
具体的原因是什么我也不清楚,极有可能是缺少SUNWeu8os包引发安装过程异常导致的。接下来解决方案,用Relink all尝试一下,如果不行,先将SUNWeu8os包问题搞搞定,再重装一次。
退出sqlplus,到$ORACLE_HOME/bin下,./relink all了一下。Relink时的日志是“$ORACLE_HOME/install/relink.log”,查看Relink日志,Relink期间没有报错,后一步是:
chmod 6751 /export/home/oradb/product/12.1.0/bin/oracle
这一步是将可执行文件的权限改成 6751 。如果权限不对,执行Oracle也是会有问题。Relink后,再次查看文件状态:
bash-3.2$ ls -lFrt oracle
-rwsr-s--x 1 oracle oinstall 341926760 Jun 27 16:30 oracle*
差不多340M,11GR2是240多M,大了100M。再次连接:
bash-3.2$ sqlplus / as sysdba
SQL*Plus: Release 12.1.0.1.0 Production on Thu Jun 27 23:40:57 2013
Copyright (c) 1982, 2013, Oracle. All rights reserved.
Connected to an idle instance.
终于不再报错,成功连接,对应的服务器进程也已经启动:
bash-3.2$ ps -ef|grep LOCAL
oracle 1076 1075 0 23:40:58 ? 0:00 oracleh3 (DESCRIPTION=(LOCAL=YES)(ADDRESS=(PROTOCOL=beq)))
好,开始我的12C探索之旅。预告下先,下周将如期发布,《Mutex原理和调优及在11G、12C中的变迁》。