早上跟小荷 @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
