srvctl起停Oracle实例内幕

Posted on November 30, 2011 by ricky.zhu

早上跟小荷 @oracleblog 探讨说利用srvctl 和sqlplus启动Oracle实例上有什么不同，大概的工作过程是怎样的。 并且他在Solaris上遇到了一个因为project设置问题导致srvctl启动失败的bug，详细过程可以参考这个帖子。

今天就简单介绍下在Oracle 11gR2中利用srvctl启动和停止Oracle instance的过程以及对应的日志查看方法。

简单来说，过程就是：srvctl->srvm (UIserver)->CRSD PE(proxy engine)->CRSD AGFW(agent framework)->agent->GIMH

1）环境是11.2.0.3，Linux64bit，两个节点的RAC


$ ./crsctl query crs activeversion
Oracle Clusterware active version on the cluster is [11.2.0.3.0]
[Wed Nov 30 09:11:43][crsusr@node05:/scratch/u01/11203/grid/bin]
$

2）首先检查下，当前的数据库状态和资源状态


$ date; ./srvctl status database -d mynewracdb
Wednesday, November 30, 2011  9:07:47 AM UTC
Instance mynewrac1 is running on node node05
Instance mynewrac2 is running on node node06
[Wed Nov 30 09:07:50][crsusr@node05:/scratch/u01/11203/grid/bin]

$ ./crsctl stat res -t

...

ora.mynewracdb.db
      1        ONLINE  ONLINE       node05                 Open
      2        ONLINE  ONLINE       node06                 Open
ora.oc4j
      1        ONLINE  ONLINE       node05
ora.scan1.vip
      1        ONLINE  ONLINE       node06
ora.scan2.vip
      1        ONLINE  ONLINE       node05
ora.scan3.vip
      1        ONLINE  ONLINE       node05

...

3）停止数据库在节点1上的实例，查看crsd日志和agent日志



$ date; ./srvctl stop instance -d mynewracdb -i mynewrac1
Wednesday, November 30, 2011  9:08:59 AM UTC
[Wed Nov 30 09:09:21][crsusr@node05:/scratch/u01/11203/grid/bin]
$ ./crsctl stat res -t
--------------------------------------------------------------------------------
NAME           TARGET  STATE        SERVER                   STATE_DETAILS
--------------------------------------------------------------------------------
Local Resources
--------------------------------------------------------------------------------
ora.DB_DG.dg
               ONLINE  ONLINE       node05
               ONLINE  ONLINE       node06
ora.LISTENER.lsnr
               ONLINE  ONLINE       node05
               ONLINE  ONLINE       node06
ora.OCR_VD.dg
               ONLINE  ONLINE       node05
               ONLINE  ONLINE       node06
ora.asm
               ONLINE  ONLINE       node05                 Started
               ONLINE  ONLINE       node06                 Started
ora.gsd
               OFFLINE OFFLINE      node05
               OFFLINE OFFLINE      node06
ora.net1.network
               ONLINE  ONLINE       node05
               ONLINE  ONLINE       node06
ora.ons
               ONLINE  ONLINE       node05
               ONLINE  ONLINE       node06
ora.registry.acfs
               ONLINE  ONLINE       node05
               ONLINE  ONLINE       node06
--------------------------------------------------------------------------------
Cluster Resources
--------------------------------------------------------------------------------
ora.LISTENER_SCAN1.lsnr
      1        ONLINE  ONLINE       node06
ora.LISTENER_SCAN2.lsnr
      1        ONLINE  ONLINE       node05
ora.LISTENER_SCAN3.lsnr
      1        ONLINE  ONLINE       node05
ora.cvu
      1        ONLINE  ONLINE       node05
ora.node05.vip
      1        ONLINE  ONLINE       node05
ora.node06.vip
      1        ONLINE  ONLINE       node06
ora.mynewracdb.db
      1        OFFLINE OFFLINE                               Instance Shutdown
      2        ONLINE  ONLINE       node06                 Open
ora.oc4j
      1        ONLINE  ONLINE       node05
ora.scan1.vip
      1        ONLINE  ONLINE       node06
ora.scan2.vip
      1        ONLINE  ONLINE       node05
ora.scan3.vip
      1        ONLINE  ONLINE       node05
[Wed Nov 30 09:09:45][crsusr@node05:/scratch/u01/11203/grid/bin]
$



crsd.log 日志

/scratch/u01/11203/grid/log/node05/crsd

crsd.log

 30559  2011-11-30 09:09:02.508: [UiServer][49] CS(103727c10)set Properties ( crsusr,10330b690)
===>UI server 收到停止的命令，发给Proxy Engine

 30560  2011-11-30 09:09:02.527: [UiServer][48] {1:52451:782} Sending message to PE. ctx= 1047fa450, Client PID: 16523
 30561  2011-11-30 09:09:02.529: [   CRSPE][47] {1:52451:782} Processing PE command id=838. Description: [Stat Resource : 104622f50]
 30562  2011-11-30 09:09:02.532: [   CRSPE][47] {1:52451:782} Expression Filter : ((TYPE == ora.database.type) AND (NAME == ora.mynewracdb.db))
 30563  2011-11-30 09:09:02.557: [UiServer][48] {1:52451:782} Done for ctx=1047fa450
 30564  2011-11-30 09:09:02.678: [UiServer][49] CS(103727c10)set Properties ( crsusr,10384c290)
 30565  2011-11-30 09:09:02.696: [UiServer][48] {1:52451:783} Container [ Name: UI_STOP
 30566          API_HDR_VER:
 30567          TextMessage[2]
 30568          CLIENT:
 30569          TextMessage[]
 30570          CLIENT_NAME:
 30571          TextMessage[/scratch/u01/11203/grid/jdk/jre/bin/sparcv9/java]
 30572          CLIENT_PID:
 30573          TextMessage[16523]
 30574          CLIENT_PRIMARY_GROUP:
 30575          TextMessage[oinstall]
 30576          FILTER:
 30577          TextMessage[(^A(^A(^A(^A(^A(^ANAME^Ast^Aora.mynewracdb.^A)^A&&^A(^ANAME^Aen^A.svc^A)^A)^A&&^A(^ATYPE^A==^Aora.service.type^A)^A)^A&&^A(^A(^ASTATE^A!=^AOFFLINE^A)^A||^A(^ATARGET^A!=^
AOFFLINE^A)^A)^A)^A||^A(^A(^A(^ANAME^A==^Aora.mynewracdb.db^A)^A&&^A(^ATYPE^A==^Aora.database.type^A)^A)^A&&^A(^ASTATE^A!=^AOFFLINE^A)^A)^A)^A&&^A(^ALAST_SERVER^A==^Anode05^A)^A)]
 30578          FILTER_TAG:
 30579          TextMessage[1]
 30580          KEEP_D_TARGETS_TAG:
 30581          TextMessage[1]
 30582          LOCALE:
 30583          TextMessage[AMERICAN_AMERICA.US7ASCII]
 30584          QUEUE_TAG:
 30585          TextMessage[1]
 30586  ]
 30587  2011-11-30 09:09:02.697: [UiServer][48] {1:52451:783} Sending message to PE. ctx= 1047fb9d0, Client PID: 16523
 30588  2011-11-30 09:09:02.698: [   CRSPE][47] {1:52451:783} Cmd : 104622f50 : flags: KEEP_D_TARGETS_TAG | QUEUE_TAG
 30589  2011-11-30 09:09:02.699: [   CRSPE][47] {1:52451:783} Processing PE command id=839. Description: [Stop Resource : 104622f50]
 30590  2011-11-30 09:09:02.703: [   CRSPE][47] {1:52451:783} Expression Filter : ((((((NAME st ora.mynewracdb.) AND (NAME en .svc)) AND (TYPE == ora.service.type)) AND ((STATE != OFFLINE) OR (TARG
ET != OFFLINE))) OR (((NAME == ora.mynewracdb.db) AND (TYPE == ora.database.type)) AND (STATE != OFFLINE))) AND (LAST_SERVER == node05))
 30591  2011-11-30 09:09:02.713: [   CRSPE][47] {1:52451:783} Expression Filter : ((((((NAME st ora.mynewracdb.) AND (NAME en .svc)) AND (TYPE == ora.service.type)) AND ((STATE != OFFLINE) OR (TARG
ET != OFFLINE))) OR (((NAME == ora.mynewracdb.db) AND (TYPE == ora.database.type)) AND (STATE != OFFLINE))) AND (LAST_SERVER == node05))
 30592  2011-11-30 09:09:02.737: [   CRSPE][47] {1:52451:783} RI [ora.mynewracdb.db 1 1] new target state: [OFFLINE] old value: [ONLINE]
 30593  2011-11-30 09:09:02.740: [  CRSOCR][45] {1:52451:783} Multi Write Batch processing...
 30594  2011-11-30 09:09:02.742: [   CRSPE][47] {1:52451:783} RI [ora.mynewracdb.db 1 1] new internal state: [STOPPING] old value: [STABLE]

===> PE发送诶agent framework

 30595  2011-11-30 09:09:02.744: [   CRSPE][47] {1:52451:783} Sending message to agfw: id = 22058
 30596  2011-11-30 09:09:02.744: [    AGFW][42] {1:52451:783} Agfw Proxy Server received the message: RESOURCE_STOP[ora.mynewracdb.db 1 1] ID 4099:22058
 30597  2011-11-30 09:09:02.744: [   CRSPE][47] {1:52451:783} CRS-2673: Attempting to stop 'ora.mynewracdb.db' on 'node05'
 30598
 30599  2011-11-30 09:09:02.745: [    AGFW][42] {1:52451:783} Agfw Proxy Server forwarding the message: RESOURCE_STOP[ora.mynewracdb.db 1 1] ID 4099:22058 to the agent /scratch/u01/11203/grid/bin/o
raagent_crsusr
 30600  2011-11-30 09:09:02.749: [UiServer][48] {1:52451:783} Container [ Name: ORDER
 30601          MESSAGE:
 30602          TextMessage[CRS-2673: Attempting to stop 'ora.mynewracdb.db' on 'node05']

 30603          MSGTYPE:
 30604          TextMessage[3]
 30605          OBJID:
 30606          TextMessage[ora.mynewracdb.db 1 1]
 30607          WAIT:
 30608          TextMessage[0]
 30609  ]
 30610  2011-11-30 09:09:02.809: [  CRSOCR][45] {1:52451:783} Multi Write Batch done.
 30611  2011-11-30 09:09:13.319: [UiServer][49] CS(10333fad0)set Properties ( crsusr,1043d8e50)
 30612  2011-11-30 09:09:13.336: [UiServer][48] {1:52451:784} Container [ Name: UI_STOP
 30613          API_HDR_VER:
 30614          TextMessage[2]
 30615          CLIENT:
 30616          TextMessage[]
 30617          CLIENT_NAME:
 30618          TextMessage[Unknown process]
 30619          CLIENT_PID:
 30620          TextMessage[9788]
 30621          CLIENT_PRIMARY_GROUP:
 30622          TextMessage[oinstall]
 30623          EVENT_TAG:
 30624          TextMessage[1]
 30625          FILTER:
 30626          TextMessage[(^A(^A(^ANAME^A==^Aora.mynewracdb.db^A)^A&&^A(^ALAST_SERVER^A==^Anode05^A)^A)^A&&^A(^ASTATE^A!=^AOFFLINE^A)^A)^AUSR_ORA_OPI=true^AUSR_ORA_INST_NAME=mynewrac1]
 30627          FILTER_TAG:
 30628          TextMessage[1]
 30629          FORCE_TAG:
 30630          TextMessage[1]
 30631          LOCALE:
 30632          TextMessage[AMERICAN_AMERICA.WE8ISO8859P1]
 30633          NO_WAIT_TAG:
 30634          TextMessage[1]
 30635  ]
 30636  2011-11-30 09:09:13.337: [UiServer][48] {1:52451:784} Sending message to PE. ctx= 1047fa890, Client PID: 9788
 30637  2011-11-30 09:09:13.339: [   CRSPE][47] {1:52451:784} Cmd : 104622950 : flags: EVENT_TAG | FORCE_TAG
 30638  2011-11-30 09:09:13.339: [   CRSPE][47] {1:52451:784} Processing PE command id=840. Description: [Stop Resource : 104622950]
 30639  2011-11-30 09:09:13.341: [   CRSPE][47] {1:52451:784} Expression Filter : (((NAME == ora.mynewracdb.db) AND (LAST_SERVER == node05)) AND (STATE != OFFLINE))
 30640  2011-11-30 09:09:13.345: [   CRSPE][47] {1:52451:784} Expression Filter : (((NAME == ora.mynewracdb.db) AND (LAST_SERVER == node05)) AND (STATE != OFFLINE))
 30641  2011-11-30 09:09:13.354: [   CRSPE][47] {1:52451:784} Attribute overrides for the command: USR_ORA_INST_NAME = mynewrac1;USR_ORA_OPI = true;

====》 PE处理完毕，发给我UIserver，并由UIserver返回给sender，也就是最终的用户UI，在这里是svrctl

 30642  2011-11-30 09:09:13.367: [   CRSPE][47] {1:52451:784} PE Command [ Stop Resource : 104622950 ] has completed
 30643  2011-11-30 09:09:13.368: [   CRSPE][47] {1:52451:784} UI Command [Stop Resource : 104622950] is replying to sender.


agent 日志

/scratch/u01/11203/grid/log/node05/agent/crsd/oraagent_crsusr

oraagent_crsusr.log
 

====> agent 收到PE 发来的命令，开始准备停止的命令
 
2011-11-30 09:09:02.759: [    AGFW][10] {1:52451:783} Agent received the message: RESOURCE_STOP[ora.mynewracdb.db 1 1] ID 4099:22059
2011-11-30 09:09:02.759: [    AGFW][10] {1:52451:783} Preparing STOP command for: ora.mynewracdb.db 1 1
2011-11-30 09:09:02.759: [    AGFW][10] {1:52451:783} ora.mynewracdb.db 1 1 state changed from: ONLINE to: STOPPING
2011-11-30 09:09:02.767: [ora.mynewracdb.db][18] {1:52451:783} [stop] (:CLSN00108:) clsn_agent::stop {
2011-11-30 09:09:02.768: [ora.mynewracdb.db][18] {1:52451:783} [stop] InstAgent::stop_option stop mode immediate option 1
2011-11-30 09:09:02.768: [ora.mynewracdb.db][18] {1:52451:783} [stop] InstAgent::stop {
2011-11-30 09:09:02.771: [ora.mynewracdb.db][18] {1:52451:783} [stop] InstAgent::stop  shutdown mode: 3
2011-11-30 09:09:02.772: [ora.mynewracdb.db][18] {1:52451:783} [stop] DbAgent::preStopCbk {
2011-11-30 09:09:02.772: [ora.mynewracdb.db][18] {1:52451:783} [stop] DbAgentEventModule::stop stopping event bridge
2011-11-30 09:09:02.805: [ USRTHRD][18] {1:52451:783} CssSemaphore::release, released semaphore CLSN.AQPROC.mynewracdb.MASTER
2011-11-30 09:09:02.805: [ USRTHRD][18] {1:52451:783} AQPROC.mynewracdb CssSemMM::relinquishMastership I am no longer the master
2011-11-30 09:09:02.810: [ USRTHRD][18] {1:52451:783} WorkerThread::removeWorker total workers: 3
2011-11-30 09:09:02.819: [ USRTHRD][18] {1:52451:783} InstConnection:~InstConnection: this 014e6fd0
2011-11-30 09:09:02.820: [ora.mynewracdb.db][18] {1:52451:783} [stop] DbAgentEventModule::stop stopping rlb event bridge
2011-11-30 09:09:02.855: [ USRTHRD][18] {1:52451:783} CssSemaphore::release, released semaphore CLSN.RLB.mynewracdb.MASTER
2011-11-30 09:09:02.855: [ USRTHRD][18] {1:52451:783} RLB.mynewracdb CssSemMM::relinquishMastership I am no longer the master
2011-11-30 09:09:02.860: [ USRTHRD][18] {1:52451:783} WorkerThread::removeWorker total workers: 2
2011-11-30 09:09:02.863: [ USRTHRD][18] {1:52451:783} InstConnection:~InstConnection: this 014e6f70
2011-11-30 09:09:02.866: [ CRSCEVT][18] {1:52451:783} ClusterPublisher::disconnect Disconnected
2011-11-30 09:09:02.867: [ USRTHRD][18] {1:52451:783} Thread:DedicatedThreadstop {
2011-11-30 09:09:02.867: [ USRTHRD][18] {1:52451:783} Thread:DedicatedThreadstop }
2011-11-30 09:09:02.867: [ora.mynewracdb.db][18] {1:52451:783} [stop] DbAgent::preStopCbk }
2011-11-30 09:09:02.869: [ora.mynewracdb.db][18] {1:52451:783} [stop] ConnectionPool::getConnection 260 pConnxn 014e76f0
2011-11-30 09:09:02.869: [ora.mynewracdb.db][18] {1:52451:783} [stop] InstAgent::stop pool pConnxn 014e76f0
2011-11-30 09:09:02.870: [ora.mynewracdb.db][18] {1:52451:783} [stop] InstConnection::shutdown mode 3
2011-11-30 09:09:07.147: [ora.mynewracdb.db][18] {1:52451:783} [stop] DbAgent::stopCbk: {
2011-11-30 09:09:07.147: [ora.mynewracdb.db][18] {1:52451:783} [stop] DbAgent::stopCbk {
2011-11-30 09:09:07.148: [ora.mynewracdb.db][18] {1:52451:783} [stop] DbAgent::stopCbk close - ALTER DATABASE CLOSE NORMAL /* db agent *//* {1:52451:783} */
2011-11-30 09:09:13.156: [ora.mynewracdb.db][18] {1:52451:783} [stop] DbAgent::stopCbk dismount - ALTER DATABASE DISMOUNT /* db agent *//* {1:52451:783} */
2011-11-30 09:09:13.266: [ USRTHRD][18] {1:52451:783} Thread:DedicatedThreadstop {
2011-11-30 09:09:13.266: [ USRTHRD][18] {1:52451:783} Thread:DedicatedThreadstop }
2011-11-30 09:09:13.266: [ora.mynewracdb.db][18] {1:52451:783} [stop] DbAgent::stopCbk }
2011-11-30 09:09:13.266: [ora.mynewracdb.db][18] {1:52451:783} [stop] InstConnection::shutdown mode 5
2011-11-30 09:09:18.103: [ora.asm][13] {1:52451:2} [check] CrsCmd::ClscrsCmdData::stat entity 1 statflag 1 useFilter 0
2011-11-30 09:09:18.186: [ora.asm][13] {1:52451:2} [check] AsmProxyAgent::check clsagfw_res_status 0
2011-11-30 09:09:21.785: [ora.mynewracdb.db][18] {1:52451:783} [stop] ConnectionPool::releaseConnection InstConnection 014e76f0
2011-11-30 09:09:21.786: [ora.mynewracdb.db][18] {1:52451:783} [stop] ConnectionPool::stopConnection
2011-11-30 09:09:21.786: [ora.mynewracdb.db][18] {1:52451:783} [stop] ConnectionPool::removeConnection connection count 1
2011-11-30 09:09:21.786: [ora.mynewracdb.db][18] {1:52451:783} [stop] ConnectionPool::removeConnection sid  mynewrac1, InstConnection 014e76f0
2011-11-30 09:09:21.787: [ USRTHRD][18] {1:52451:783} InstConnection::breakCall pConnxn:014e76f0  DetachLock:00ac96f8 m_pSvcH:01e150b0
2011-11-30 09:09:21.787: [ USRTHRD][18] {1:52451:783} InstConnection:~InstConnection: this 014e76f0
2011-11-30 09:09:21.789: [ora.mynewracdb.db][18] {1:52451:783} [stop] ConnectionPool::removeConnection delete InstConnection 014e76f0
2011-11-30 09:09:21.789: [ora.mynewracdb.db][18] {1:52451:783} [stop] ConnectionPool::removeConnection freed 1

2011-11-30 09:09:21.789: [ora.mynewracdb.db][18] {1:52451:783} [stop] ConnectionPool::stopConnection sid mynewrac1 status  1
2011-11-30 09:09:21.790: [ora.mynewracdb.db][18] {1:52451:783} [stop] InstAgent::stop db/asm
2011-11-30 09:09:21.790: [ora.mynewracdb.db][18] {1:52451:783} [stop] ConnectionPool::stopConnection
2011-11-30 09:09:21.790: [ora.mynewracdb.db][18] {1:52451:783} [stop] ConnectionPool::removeConnection connection count 0
2011-11-30 09:09:21.791: [ora.mynewracdb.db][18] {1:52451:783} [stop] ConnectionPool::removeConnection freed 0
2011-11-30 09:09:21.791: [ora.mynewracdb.db][18] {1:52451:783} [stop] ConnectionPool::stopConnection sid mynewrac1 status  1
2011-11-30 09:09:21.791: [ora.mynewracdb.db][18] {1:52451:783} [stop] InstAgent::stop: }
2011-11-30 09:09:21.792: [ora.mynewracdb.db][18] {1:52451:783} [stop] (:CLSN00108:) clsn_agent::stop }
2011-11-30 09:09:21.792: [    AGFW][18] {1:52451:783} Command: stop for resource: ora.mynewracdb.db 1 1 completed with status: SUCCESS
2011-11-30 09:09:21.795: [    AGFW][10] {1:52451:783} Agent sending reply for: RESOURCE_STOP[ora.mynewracdb.db 1 1] ID 4099:22059
2011-11-30 09:09:21.797: [ora.mynewracdb.db][9] {1:52451:783} [check] ConnectionPool::resetConnection  s_statusOfConnectionMap 00ab1f68
2011-11-30 09:09:21.797: [ora.mynewracdb.db][9] {1:52451:783} [check] ConnectionPool::resetConnection sid mynewrac1 status  2
2011-11-30 09:09:21.798: [ora.mynewracdb.db][9] {1:52451:783} [check] Gimh::check condition changes to (GIMH_NEXT_NUM) 1 exists

====》注意这里的GIMH，这是instance提供的一个接口，可以直接访问到实例，这里的agent就是通过这个接口判断instance是否healthy的，决定database资源是否online或者offline等状态。


2011-11-30 09:09:21.798: [ora.mynewracdb.db][9] {1:52451:783} [check] clsnDbAgent:checkCbk clsagfw_res_status 22
2011-11-30 09:09:21.798: [ USRTHRD][9] {1:52451:783} Thread:DedicatedThreadstop {
2011-11-30 09:09:21.798: [ USRTHRD][9] {1:52451:783} Thread:DedicatedThreadstop }
2011-11-30 09:09:21.799: [ USRTHRD][9] {1:52451:783} Gimh::destructor gimh_dest_query_ctx rc=0
2011-11-30 09:09:21.800: [ USRTHRD][9] {1:52451:783} Gimh::destructor gimh_dest_inst_ctx rc=0
2011-11-30 09:09:21.800: [ora.mynewracdb.db][9] {1:52451:783} [check] ConnectionPool::stopConnection
2011-11-30 09:09:21.800: [ora.mynewracdb.db][9] {1:52451:783} [check] ConnectionPool::removeConnection connection count 0
2011-11-30 09:09:21.801: [ora.mynewracdb.db][9] {1:52451:783} [check] ConnectionPool::removeConnection freed 0
2011-11-30 09:09:21.801: [ora.mynewracdb.db][9] {1:52451:783} [check] ConnectionPool::stopConnection sid mynewrac1 status  1
2011-11-30 09:09:21.801: [ora.mynewracdb.db][9] {1:52451:783} [check] InstAgent::check checkCounter 34 prev clsagfw_res_status 2 current clsagfw_res_status 2
2011-11-30 09:09:21.803: [    AGFW][10] {1:52451:783} ora.mynewracdb.db 1 1 state changed from: STOPPING to: PLANNED_OFFLINE
2011-11-30 09:09:21.803: [    AGFW][10] {1:52451:783} ora.mynewracdb.db 1 1 state details has changed from: Open to: Instance Shutdown
2011-11-30 09:09:21.804: [    AGFW][10] {1:52451:783} Agent sending last reply for: RESOURCE_STOP[ora.mynewracdb.db 1 1] ID 4099:22059
2011-11-30 09:09:21.829: [ USRTHRD][23] ClusterSubscriber::SubscriberWorker::InternalClusterSubscriber::handleEventCBexecuting for reason 1

4）启动实例，并再次验证crsd日志和agnet日志



$ date; ./srvctl start instance -d mynewracdb -i mynewrac1
Wednesday, November 30, 2011  9:10:48 AM UTC
[Wed Nov 30 09:11:25][crsusr@node05:/scratch/u01/11203/grid/bin]
$


crsd 日志类似，不再贴出来，下面看看crsd agent日志：

 41386  2011-11-30 09:10:33.788: [    AGFW][10] {1:52451:2} Agent received the message: AGENT_HB[Engine] ID 12293:22088
 41387  2011-11-30 09:10:50.810: [    AGFW][10] {1:52451:809} Agent received the message: RESOURCE_START[ora.mynewracdb.db 1 1] ID 4098:22138
 41388  2011-11-30 09:10:50.810: [    AGFW][10] {1:52451:809} Preparing START command for: ora.mynewracdb.db 1 1
 41389  2011-11-30 09:10:50.810: [    AGFW][10] {1:52451:809} ora.mynewracdb.db 1 1 state changed from: PLANNED_OFFLINE to: STARTING
 41390  2011-11-30 09:10:50.818: [ora.mynewracdb.db][13] {1:52451:809} [start] (:CLSN00107:) clsn_agent::start {
 41391  2011-11-30 09:10:50.819: [ora.mynewracdb.db][13] {1:52451:809} [start] InstAgent::start {
 41392  2011-11-30 09:10:50.819: [ora.mynewracdb.db][13] {1:52451:809} [start] ConnectionPool::stopConnection
 41393  2011-11-30 09:10:50.820: [ora.mynewracdb.db][13] {1:52451:809} [start] ConnectionPool::removeConnection connection count 0
 41394  2011-11-30 09:10:50.820: [ora.mynewracdb.db][13] {1:52451:809} [start] ConnectionPool::removeConnection freed 0
 41395  2011-11-30 09:10:50.820: [ora.mynewracdb.db][13] {1:52451:809} [start] ConnectionPool::stopConnection sid mynewrac1 status  1
 41396  2011-11-30 09:10:50.820: [ USRTHRD][13] {1:52451:809} ConnectionPool::~ConnectionPool m_oracleHome:/scratch/u02/product/dbhome_1, m_oracleSid:mynewrac1, m_usrOraEnv:
 41397  2011-11-30 09:10:50.821: [ USRTHRD][13] {1:52451:809} Thread:DedicatedThreadstop {
 41398  2011-11-30 09:10:50.821: [ USRTHRD][13] {1:52451:809} Thread:DedicatedThreadstop }
 41399  2011-11-30 09:10:50.822: [ora.mynewracdb.db][13] {1:52451:809} [start] DbAgent:getOracleSid 13 oracle_sid = mynewrac1
 41400  2011-11-30 09:10:50.822: [ora.mynewracdb.db][13] {1:52451:809} [start] DbAgent:getOracleSid  oracle_sid = mynewrac1
 41401  2011-11-30 09:10:50.823: [ora.mynewracdb.db][13] {1:52451:809} [start] getOracleHomeAttrib: oracle_home = /scratch/u02/product/dbhome_1
 41402  2011-11-30 09:10:50.823: [ora.mynewracdb.db][13] {1:52451:809} [start] ConnectionPool::ConnectionPool 2 m_oracleHome:/scratch/u02/product/dbhome_1, m_oracleSid:mynewrac1, m_usrOraEnv:
 41403  2011-11-30 09:10:50.824: [ora.mynewracdb.db][13] {1:52451:809} [start] DbAgent::setOracleSidAttrib updating GEN_USR_ORA_INST_NAME@SERVERNAME(node05) to mynewrac1
 41404  2011-11-30 09:10:50.824: [ora.mynewracdb.db][13] {1:52451:809} [start] clsnUtils::setResAttrib nonPerX current value GEN_USR_ORA_INST_NAME value mynewrac1
 41405  2011-11-30 09:10:50.826: [ora.mynewracdb.db][13] {1:52451:809} [start] CrsCmd::ClscrsCmdData::stat entity 1 statflag 32 useFilter 0
 41406  2011-11-30 09:10:50.899: [ora.mynewracdb.db][13] {1:52451:809} [start] setResAttrib: attr GEN_USR_ORA_INST_NAME@SERVERNAME(node05) clsagfw attribVal mynewrac1 clscrs tmpAttrValue mynewrac
1
 41407  2011-11-30 09:10:50.899: [ora.mynewracdb.db][13] {1:52451:809} [start] setResAttrib clsagfw_modify_attribute attr GEN_USR_ORA_INST_NAME@SERVERNAME(node05) value mynewrac1 retCode 0
 41408  2011-11-30 09:10:50.900: [ora.mynewracdb.db][13] {1:52451:809} [start] sModifyConfig for mynewracdb
 41409  2011-11-30 09:10:50.900: [ora.mynewracdb.db][13] {1:52451:809} [start] getOracleHomeAttrib: oracle_home = /scratch/u02/product/dbhome_1
 41410  2011-11-30 09:10:50.901: [ora.mynewracdb.db][13] {1:52451:809} [start] Utils::getCrsHome crsHome /scratch/u01/11203/grid
 41411  2011-11-30 09:10:50.919: [ora.mynewracdb.db][13] {1:52451:809} [start] sclsnInstAgent::sUpdateOratab oratab is /var/opt/oracle/oratab
 41412  2011-11-30 09:10:50.921: [ora.mynewracdb.db][13] {1:52451:809} [start] sclsnInstAgent::sUpdateOratab CssLock
 41413  2011-11-30 09:10:50.938: [ora.mynewracdb.db][13] {1:52451:809} [start] ConfigFile::getValue name mynewracdb value
 41414  2011-11-30 09:10:50.962: [ora.mynewracdb.db][13] {1:52451:809} [start] ConfigFile::updateInPlace file /var/opt/oracle/oratab is updated
 41415  2011-11-30 09:10:50.962: [ora.mynewracdb.db][13] {1:52451:809} [start] sclsnInstAgent::sUpdateOratab file updated with dbName mynewracdb value /scratch/u02/product/dbhome_1:N
 41416  2011-11-30 09:10:50.962: [ora.mynewracdb.db][13] {1:52451:809} [start] sclsnInstAgent::sUpdateOratab CSS unlock
 41417  2011-11-30 09:10:50.977: [ora.mynewracdb.db][13] {1:52451:809} [start] ConfigFile:update file is /scratch/u02/product/dbhome_1/dbs/initmynewrac1.ora not modified
 41418  2011-11-30 09:10:50.985: [ora.mynewracdb.db][13] {1:52451:809} [start] Utils::getCrsHome crsHome /scratch/u01/11203/grid
 41419  2011-11-30 09:10:50.985: [ora.mynewracdb.db][13] {1:52451:809} [start] crsHome = /scratch/u01/11203/grid
 41420  2011-11-30 09:10:50.985: [ora.mynewracdb.db][13] {1:52451:809} [start] oracleHome = /scratch/u02/product/dbhome_1
 41421  2011-11-30 09:10:50.985: [ora.mynewracdb.db][13] {1:52451:809} [start] command = '/scratch/u01/11203/grid/bin/setasmgidwrap oracle_binary_path=/scratch/u02/product/dbhome_1/bin/oracle'
 41422  2011-11-30 09:10:50.986: [ora.mynewracdb.db][13] {1:52451:809} [start] start dependency = hard(ora.DB_DG.dg) weak(type:ora.listener.type,global:type:ora.scan_listener.type,uniform:ora.ons,g
lobal:ora.gns) pullup(ora.DB_DG.dg)
 41423  2011-11-30 09:10:50.986: [ora.mynewracdb.db][13] {1:52451:809} [start] ASM disk group dependency found
 41424  2011-11-30 09:10:50.986: [ora.mynewracdb.db][13] {1:52451:809} [start] Utils:execCmd action = 1 flags = 6 ohome = /scratch/u01/11203/grid cmdname = setasmgidwrap.

 
  41425  2011-11-30 09:10:51.245: [ora.mynewracdb.db][13] {1:52451:809} [start] execCmd ret = 0
 41426  2011-11-30 09:10:51.247: [ora.mynewracdb.db][13] {1:52451:809} [start] Utils::getCrsHome crsHome /scratch/u01/11203/grid
 41427  2011-11-30 09:10:51.247: [ora.mynewracdb.db][13] {1:52451:809} [start] clsnInstConnection::makeConnectStr UsrOraEnv  m_oracleHome /scratch/u02/product/dbhome_1 Crshome /scratch/u01/11203/gr
id
 41428  2011-11-30 09:10:51.247: [ora.mynewracdb.db][13] {1:52451:809} [start] Utils::getCrsHome crsHome /scratch/u01/11203/grid
 41429  2011-11-30 09:10:51.247: [ora.mynewracdb.db][13] {1:52451:809} [start] clsnInstConnection::makeConnectStr LIBRARY_PATH1 ,LD_LIBRARY_PATH=
 41430  2011-11-30 09:10:51.248: [ora.mynewracdb.db][13] {1:52451:809} [start] Utils::getCrsHome crsHome /scratch/u01/11203/grid
 41431  2011-11-30 09:10:51.248: [ora.mynewracdb.db][13] {1:52451:809} [start] clsnInstConnection::makeConnectStr LIBRARY_PATH2 ,LD_LIBRARY_PATH=,LD_LIBRARY_PATH_64=
 41432  2011-11-30 09:10:51.248: [ora.mynewracdb.db][13] {1:52451:809} [start] makeConnectStr = (DESCRIPTION=(ADDRESS=(PROTOCOL=beq)(PROGRAM=/scratch/u02/product/dbhome_1/bin/oracle)(ARGV0=oraclemy
newrac1)(ENVS='ORACLE_HOME=/scratch/u02/product/dbhome_1,ORACLE_SID=mynewrac1,LD_LIBRARY_PATH=,LD_LIBRARY_PATH_64=')(ARGS='(DESCRIPTION=(LOCAL=YES)(ADDRESS=(PROTOCOL=beq)))'))(CONNECT_DATA=(SID=myn
ewrac1)))
 41433  2011-11-30 09:10:51.251: [ora.mynewracdb.db][13] {1:52451:809} [start] Container:start oracle home /scratch/u02/product/dbhome_1
 41434  2011-11-30 09:10:51.251: [ora.mynewracdb.db][13] {1:52451:809} [start] InstConnection::connectInt: server not attached
 41435  2011-11-30 09:10:51.470: [ora.mynewracdb.db][13] {1:52451:809} [start] InstAgent::startup

 ...
  41561  2011-11-30 09:11:25.513: [ USRTHRD][13] {1:52451:809} DbAgentEventModule::notifyDbOpen database is now open
 41562  2011-11-30 09:11:25.513: [ USRTHRD][13] {1:52451:809} DbAgentEventModule::notifyDbOpen starting AQ
 41563  2011-11-30 09:11:25.513: [ USRTHRD][13] {1:52451:809} DbAgentEventModule::notifyDbOpen starting RLB
 41564  2011-11-30 09:11:25.514: [ CRSCEVT][13] {1:52451:809} ClusterPublisher::connect connecting
 41565  2011-11-30 09:11:25.532: [ CRSCEVT][13] {1:52451:809} ClusterPublisher::connect Connected
 41566  2011-11-30 09:11:25.533: [ora.mynewracdb.db][13] {1:52451:809} [start] DbAgent::startCbk: }
 41567  2011-11-30 09:11:25.535: [ora.mynewracdb.db][13] {1:52451:809} [start] InstAgent::start: startConnection pool
 41568  2011-11-30 09:11:25.535: [ora.mynewracdb.db][13] {1:52451:809} [start] ConnectionPool::stopConnection
 41569  2011-11-30 09:11:25.535: [ora.mynewracdb.db][13] {1:52451:809} [start] ConnectionPool::removeConnection connection count 0
 41570  2011-11-30 09:11:25.536: [ora.mynewracdb.db][13] {1:52451:809} [start] ConnectionPool::removeConnection freed 0
 41571  2011-11-30 09:11:25.536: [ora.mynewracdb.db][13] {1:52451:809} [start] ConnectionPool::stopConnection sid mynewrac1 status  1
 41572  2011-11-30 09:11:25.536: [ USRTHRD][13] {1:52451:809} ConnectionPool::~ConnectionPool m_oracleHome:/scratch/u02/product/dbhome_1, m_oracleSid:mynewrac1, m_usrOraEnv:
 41573  2011-11-30 09:11:25.536: [ora.mynewracdb.db][13] {1:52451:809} [start] ConnectionPool::ConnectionPool 2 m_oracleHome:/scratch/u02/product/dbhome_1, m_oracleSid:mynewrac1, m_usrOraEnv:
 41574  2011-11-30 09:11:25.537: [ora.mynewracdb.db][13] {1:52451:809} [start] ConnectionPool::startConnection  s_statusOfConnectionMap 00ab1f68
 41575  2011-11-30 09:11:25.537: [ora.mynewracdb.db][13] {1:52451:809} [start] ConnectionPool::startConnection sid mynewrac1 status  2
 41576  2011-11-30 09:11:25.537: [ora.mynewracdb.db][13] {1:52451:809} [start] InstAgent::start release pConnxn 01b3d528 pConnxn
 41577  2011-11-30 09:11:25.538: [ora.mynewracdb.db][13] {1:52451:809} [start] ConnectionPool::releaseConnection InstConnection 019bf570
 41578  2011-11-30 09:11:25.539: [ora.mynewracdb.db][13] {1:52451:809} [start] InstAgent::start: }
 41579  2011-11-30 09:11:25.539: [ora.mynewracdb.db][13] {1:52451:809} [start] (:CLSN00107:) clsn_agent::start }
 41580  2011-11-30 09:11:25.540: [    AGFW][13] {1:52451:809} Command: start for resource: ora.mynewracdb.db 1 1 completed with status: SUCCESS
 41581  2011-11-30 09:11:25.544: [ora.mynewracdb.db][9] {1:52451:809} [check] Gimh::check OH /scratch/u02/product/dbhome_1 SID mynewrac1
 41582  2011-11-30 09:11:25.544: [    AGFW][10] {1:52451:809} Agent sending reply for: RESOURCE_START[ora.mynewracdb.db 1 1] ID 4098:22138
 41583  2011-11-30 09:11:25.545: [ora.mynewracdb.db][9] {1:52451:809} [check] Gimh::check condition changes to (GIMH_NEXT_NUM) 9 exists
 41584  2011-11-30 09:11:25.546: [ora.mynewracdb.db][9] {1:52451:809} [check] updating GEN_START_OPTIONS from  to open
 41585  2011-11-30 09:11:25.546: [ USRTHRD][9] {1:52451:809} Thread:DedicatedThreadstart {
 41586  2011-11-30 09:11:25.547: [ USRTHRD][9] {1:52451:809} Thread:DedicatedThreadstart }
 41587  2011-11-30 09:11:25.547: [ USRTHRD][2425] {1:52451:809} DbAgent::Dedicated Thread {
 41588  2011-11-30 09:11:25.548: [ USRTHRD][2425] {1:52451:809} CrsCmd::ClscrsCmdData::stat entity 1 statflag 32 useFilter 0
 41589  2011-11-30 09:11:25.549: [    AGFW][10] {1:52451:809} ora.mynewracdb.db 1 1 state changed from: STARTING to: ONLINE
 41590  2011-11-30 09:11:25.550: [    AGFW][10] {1:52451:809} Started implicit monitor for [ora.mynewracdb.db 1 1] interval=1000 delay=1000
 41591  2011-11-30 09:11:25.550: [    AGFW][10] {1:52451:809} ora.mynewracdb.db 1 1 state details has changed from: Instance Shutdown to: Open
 41592  2011-11-30 09:11:25.551: [    AGFW][10] {1:52451:809} Agent sending last reply for: RESOURCE_START[ora.mynewracdb.db 1 1] ID 4098:22138

This entry was posted in 数据库 and tagged , . Bookmark the permalink.

2 Responses to srvctl起停Oracle实例内幕

  1. 小荷 says:
    November 30, 2011 at 10:20 pm

    文章来的好及时！
    11.2.0.3确实和现在在用的10gR2的管理方式上有了很大的不同，在我看来复杂了不少。不知oracle是基于什么考虑整出这样的一个架构来，是为了和其他的cluster资源整合么？

    Reply
  2. ricky.zhu says:
    December 1, 2011 at 9:50 am

    这个说来话长，回头我有空博一篇，介绍一下。 ^_^

    Reply

Leave a Reply

Your email address will not be published. Required fields are marked *