Showing posts with label cluster. Show all posts
Showing posts with label cluster. Show all posts

Friday, 16 September 2016

Oracle RAC - home rolling an ORA.CVU patch

I have managed to stop the cluster from wasting away memory chunks owing to BUG [Note 1523366.1]. Oracle's solution is to opatch. However, the client cannot do that at this point owing to the country wide dependency on the system. In addition to this, to opatch the system is risky considering the fragile nature of RAC in Windows. I am not 100% confident that an opatch will be successful and I would sooner create a new cluster  than to apply a patch to and Oracle RAC system on Windows.

For the original discovery of the bug - see here
For the fragility of the cluster - see here


A recap: the command that is left open every 6 hours during the CVU health check is:

C:\Windows\system32\cmd.exe /K E:\OracleGrid\11.2.0.3\bin\cluvfy comp health -_format

A screenshot can be found here when the orphaned session grows in numbers:

For the memory leak fix, I did the following.

I backup a copy of the bat file: E:\OracleGrid\11.2.0.3\bin\cluvfy.bat 

I then open the original cluvfy,bat in notepad and carefully make the following changes

CHANGE 1
FROM:
if not (%CRSHOME%)==() (
  @set "CV_HOME=%CRSHOME%"
)

set CMDPATH=%~dp0

TO:
if not (%CRSHOME%)==() (
  @set "CV_HOME=%CRSHOME%"
)

set EXIT_OPTION=

if "%CVU_RESOURCE_OPTIONS%"=="" set EXIT_OPTION=/B


set CMDPATH=%~dp0

CHANGE 2
FROM:
exit /B %errorlevel%
goto done

:ERROR
exit /B 1

TO:
exit %EXIT_OPTION% %errorlevel%
goto done

:ERROR
exit %EXIT_OPTION% 1

Once the change is made, save and copy the file across to node 2. I can also move the CVU to avoid creating any unwanted issues using while carrying out the above changes

srvctl relocate cvu -n <node name>

However, considering the batch file is executed every 6 hours, the chances are slim.

The idea to carry this out came after looking at the source code of the 11.2.0.4 home - I noted a bug fix by a certain Oracle developer @ Oracle. I diff'd the old and new CVU, evaluated the developers intention, and took only what I needed from his fix to manually patch the CVU myself. I first recreated the problem in the 11.2.0.4 test environment, monitored it for a day, patched it with my fix, and monitored for a few days. Once done satisfied, I took the 'patch' live. This fix will allow the in house DBA and his manager to have a cluster that no longer crashes once a month - forever. The nightmare is over and this solution will suffice until we create a new cluster for 12c. Done fixed it.

Monday, 4 July 2016

ORA.CVU Memory Leak - Windows Bug


The production cluster at the company I contract too had been running smoothly for ~30 days. Last week, during my morning check, I discovered the the listener and second and third scan resources on our cluster were in a state I had not seen:

INTERMEDIATE - CHECK TIMED OUT


crsctl stat res -t returned the following:

CLUSTER HEALTH REPORT  
---------------------  
.                      
crsctl stat res

-t     
------------------------------------------------
NAME           TARGET  STATE        SERVER                   STATE_DETAILS       
------------------------------------------------
Local Resources
------------------------------------------------
................
ora.LISTENER.lsnr
               ONLINE  INTERMEDIATE <node1>    CHECK TIMED OUT     
               ONLINE  ONLINE       <node2>                              
................
------------------------------------------------
Cluster Resources
------------------------------------------------
ora.LISTENER_SCAN1.lsnr
      1        ONLINE  ONLINE       <node2>                              
ora.LISTENER_SCAN2.lsnr
      1        ONLINE  INTERMEDIATE <node1>   CHECK TIMED OUT     
ora.LISTENER_SCAN3.lsnr
      1        ONLINE  INTERMEDIATE <node1>   CHECK TIMED OUT     
ora.cvu
      1        ONLINE  ONLINE       <node1>                              
......................

According to the log, the issue began at 01:47 that morning and had been consistently in this state.

The central log did not reveal the underlying cause of the issue
E:\OracleGrid\11.2.0.3\log\<node1>\alert<node1>.log

[E:\OracleGrid\11.2.0.3\bin\oraagent.exe(4348)]CRS-5818:Aborted command 'check' for resource 'ora.LISTENER.lsnr'. Details at (:CRSAGF00113:) {1:60709:2} in E:\OracleGrid\11.2.0.3\log\<node1>\agent\crsd\oraagent\oraagent.log.

[E:\OracleGrid\11.2.0.3\bin\oraagent.exe(5148)]CRS-5014:Agent "E:\OracleGrid\11.2.0.3\bin\oraagent.exe" timed out starting process "E:\OracleGrid\11.2.0.3\bin\lsnrctl.exe" for action "check": details at "(:CLSN00009:)" in "E:\OracleGrid\11.2.0.3\log\<node1>\agent\crsd\oraagent\oraagent.log"

[E:\OracleGrid\11.2.0.3\bin\oraagent.exe(5128)]CRS-5818:Aborted command 'check' for resource 'ora.LISTENER_SCAN3.lsnr'. Details at (:CRSAGF00113:) {1:60709:48526} in E:\OracleGrid\11.2.0.3\log\<node1>\agent\crsd\oraagent\oraagent.log.

Looking at the E:\OracleGrid\11.2.0.3\log\<node1>\agent\crsd\oraagent\oraagent.log log file, I find the following:
2016-07-01 11:08:36.517: [   AGENT][5124] {1:60709:2} UserErrorException: Locale is ..
2016-07-01 11:08:36.517: [ora.LISTENER.lsnr][5124] {1:60709:2} [check] clsnUtils::error Exception type=2 string=
CRS-5017: The resource action "ora.LISTENER.lsnr check" encountered the following error:
(:CLSN00009:)Utils:execCmd aborted. For details refer to "(:CLSN00109:)" in "E:\OracleGrid\11.2.0.3\log\<node1>\agent\crsd\oraagent\oraagent.log".
..
2016-07-01 11:08:38.421: [ora.LISTENER_SCAN2.lsnr][4348] {1:60709:2} [check] got lock..
2016-07-01 11:08:38.421: [ora.LISTENER_SCAN2.lsnr][4348] {1:60709:2} [check] tryActionLock }.
2016-07-01 11:08:38.421: [ora.LISTENER_SCAN2.lsnr][4348] {1:60709:2} [check] abort  }.
2016-07-01 11:08:38.421: [ora.LISTENER_SCAN2.lsnr][4348] {1:60709:2} [check] (:CLSN00110:) clsn_agent::abort }..
2016-07-01 11:08:38.421: [    AGFW][4348] {1:60709:2} Command: check for resource: ora.LISTENER_SCAN2.lsnr 1 1 completed with status: TIMEDOUT..
...

This is message appears many times and is the the same response for SCAN2 and SCAN3 checks.

However, the users were not complaining, the sessions were distributed evenly across all cluster nodes and operations could be considered "smooth". According to v$sessions and the listener logs, new connections were being made across both listeners and scans. I began checking MOS for notes on this issue. I discovered that there were a few different issues related to this problem so I began cross referencing the log files and the items found on MOS. I found a note making reference to a memory leak - so I grepped through all listener logs and I discovered a match.

Early that morning, the memory limit had been reached on the heap and the first sign of trouble was revealed in the listener alert file:
E:\OracleGrid\11.2.0.3\log\diag\tnslsnr\<node1>\listener\alert.xml
<msg time='2016-07-01T01:47:16.033+02:00' org_id='oracle' comp_id='tnslsnr'
 type='UNKNOWN' level='16' host_id='<node1>'
 host_addr='::1'>
 <txt>TNS-12531: TNS:cannot allocate memory
 </txt>
</msg>

Just as the note had depicted, there was another sign to look for - memory exceptions in the cvutrace.log file
E:\OracleGrid\11.2.0.3\log\<node1>\cvu\cvutrc\cvutrace.log file.0

[6880@<node1>] [main] [ 2016-07-01 05:27:02.783 CAT ] [VerificationUtil.getNodelist:685]  ==== Nodelist after: nodelist[0]:<node1>
Exception in thread "main" java.lang.NullPointerException
at sun.misc.FloatingDecimal.readJavaFormatString(FloatingDecimal.java:989)
at java.lang.Double.valueOf(Double.java:447)
at java.lang.Double.<init>(Double.java:539)
at oracle.ops.verification.framework.engine.component.FreeSpaceComponent.initializeReqdValues(FreeSpaceComponent.java:240)
at oracle.ops.verification.framework.engine.component.FreeSpaceComponent.init(FreeSpaceComponent.java:98)
at oracle.ops.verification.framework.engine.component.FreeSpaceComponent.<init>(FreeSpaceComponent.java:85)
at oracle.ops.verification.framework.engine.component.ComponentFactory.createComponent(ComponentFactory.java:164)
at oracle.ops.verification.framework.engine.component.HealthComponent.verifyComponents(HealthComponent.java:211)
at oracle.ops.verification.framework.engine.component.HealthComponent.verify(HealthComponent.java:145)
at oracle.ops.verification.framework.engine.ClusterVerifier.verifyComponent(ClusterVerifier.java:117)
at oracle.ops.verification.client.CluvfyDriver.main(CluvfyDriver.java:276)

The note I am referring to is note: Windows: Ora.LISTENER.lsnr Status goes to INTERMEDIATE CHECK TIMED OUT (Doc ID 1523366.1)

The bug in a nutshell: ora.cvu runs cluvfy comp health -_format but fails to close its session thereby consuming heap memory until the listener and scan resources on the node, where CVU is hosted ,begins failing.

I opened process explorer and found 125 instances of the open cluvfy commands:

C:\Windows\system32\cmd.exe  /K E:\OracleGrid\11.2.0.3\bin\cluvfy  comp health -_format 



I killed all off all but one process in hopes that it would free memory and allow the cluster to correct itself. This did not work. I then tried to restart ora.cvu using

srvctl stop cvu
srvctl start cvu

The statues did not change. I tried to stop one of the scans and start it up again

srvctl stop SCAN_LISTENER -i 3
srvctl start SCAN_LISTENER -i 3

The process became stuck during the shutdown process as it timed out.
I cancelled the shutdown and tried to start it up - this too timed out.

I coordinated with my managers, explained the scenario and it was decided that the first node would be restarted. Not great, but at least the shutdown was controlled by us and not left to the whims of the clusterware. The node was restarted and the issue went away - at least for now until the bug consumes it all again over time.

The CVU is a health check conducted by the cluster. By default, the process runs every 6 hours meaning it can spawn and leave 4 sessions every 24 hours. It runs on only one cluster node and the bug impacts only the hosting node.

The issue is said to be fixed in 11.2.0.4. The only hint of a workaround I have found by Oracle is to disable CVU - this is something that I am considering as CVU was only introduced recently in 11.2.0.2. This admission can be found in the MOS note: Clusterware resource ora.cvu FAQ (Doc ID 1524235.1) - Known issues with ora.cvu

I am testing this in our test cluster and will research further to find out what the implications are. Until then, I will continue killing left over sessions to see if this curtails the failure. I will certainly know whether this helps or not in 30 days whether or not killing the left over cmd sessions prevents the issue.

One last possibility to buy time is to extend the CVU check from its 6 hour check to 12 to 24 hours - this would stave of a crash from anywhere between 2 to 4 months. This can be done using the following command:
E:\>srvctl config cvu
CVU is configured to run once every 360 minutes

E:\>srvctl modify cvu -t 720


UPDATE:
I've been periodically killing left over clufvy sessions and the cluster is holding thus far, it has been over 30 days since the issue occurred. The CVU service also jumped nodes, so I monitored the wrong node for a few days until the penny dropped.

FINAL UPDATE: I have been able to write my own fix for the problem. It can be found here. 

Wednesday, 1 June 2016

Cannot get GPnP profile. Error CLSGPNP_NO_DAEMON (GPNPD daemon is not running)

A few days ago, the motherboard on our ESX server blew. This server was home to 2 different operational environment for the organisation. The domain I am tasked to maintain was gone in a flash. The server engineers remounted the SAN on a backup ESX machine with the same physical properties as the recently failed system. Before beginning recovery I began copying logs and backups from our DR to a safe location: over the last 5 months there seem to have been more hardware failures than the 3 years I was last a DBA in 2010. I know that if I had a backup of the system safely somewhere OUTSIDE of a VM environment, I would be able to restore the system regardless of how many servers failed.

Being the exact same physical server and starting up the exact same VMs, which were running no less than 30 minutes ago, I thought the cluster would come up in the exact same way.
This was not the case: the servers started, but the CRS failed to start up. The errors began popping up one after another in the cluster log.

E:\OracleGrid\11.2.0.3\log\<node1>\alert<node1>.log
[ohasd(1548)]CRS-2302:Cannot get GPnP profile. Error CLSGPNP_NO_DAEMON (GPNPD daemon is not running). 
..........
[cssd(5064)]CRS-1656:The CSS daemon is terminating due to a fatal error; Details at (:CSSSC00011:) in E:\OracleGrid\11.2.0.3\log\<node1>\cssd\ocssd.log
2016-05-30 10:44:05.766: 
[ohasd(2424)]CRS-2765:Resource 'ora.cssdmonitor' has failed on server '<node1>'.

Oracle Cluster Synchronization Services has failed because it seems to me that the GPNPD daemon is not running. The reasons for which are below.

E:\OracleGrid\11.2.0.3\log\<node1>\cssd\ocssd.log
2016-05-30 10:44:05.329: [    CSSD][5064]clssnmOpenGIPCEndp: opening cluster listener on gipc://<node1>:nm_<CLUSTER_NAME>-cluster
2016-05-30 10:44:05.329: [GIPCGMOD][5064] gipcmodGipcPassInitializeNetwork: Initializing passthrough GIPC
2016-05-30 10:44:05.385: [    GPNP][5064] clsgpnp_Init: [at clsgpnp0.c:585] 'E:\OracleGrid\11.2.0.3' in effect as GPnP home base.
2016-05-30 10:44:05.385: [    GPNP][5064] clsgpnp_Init: [at clsgpnp0.c:619] GPnP pid=5060, GPNP comp tracelevel=1, depcomp tracelevel=0, tlsrc:ORA_DAEMON_LOGGING_LEVELS, apitl:0, complog:1, tstenv:0, devenv:0, envopt:0, flags=2003
2016-05-30 10:44:05.396: [    GPNP][5064] clsgpnpkwf_initwfloc: [at clsgpnpkwf.c:399] Using FS Wallet Location : E:\OracleGrid\11.2.0.3\gpnp\<node1>\wallets\peer\
[   CLWAL][5064]clsw_Initialize: OLR initlevel [70000]
2016-05-30 10:44:05.422: [    GPNP][5064] clsgpnp_profileCallUrlInt: [at clsgpnp.c:2104] get-profile call to url "ipc://GPNPD_<node1>" disco "" [f=3 claimed- host: cname: seq: auth:] 
2016-05-30 10:44:05.431: [    GPNP][5064] clsgpnp_profileCallUrlInt: [at clsgpnp.c:2234] Result: (0) CLSGPNP_OK. Successful get-profile CALL to remote "ipc://GPNPD_<node1>" disco ""
2016-05-30 10:44:05.432: [ CLSINET][5064] Returning NETDATA: 0 interfaces
2016-05-30 10:44:05.432: [GIPCXCPT][5064] gipcmodGipcPassInitializeNetwork: failed to find any interfaces in clsinet, ret gipcretFail (1)
2016-05-30 10:44:05.432: [GIPCGMOD][5064] gipcmodGipcPassInitializeNetwork: EXCEPTION[ ret gipcretFail (1) ]  failed to determine host from clsinet
2016-05-30 10:44:05.640: [GIPCXCPT][5064] gipcSetAttributeStringF [gipcInternalAddress : gipcInternal.c : 354]: EXCEPTION[ ret gipcretFail (1) ]  failure for obj 00000000063EAED0 [000000000000025a] { gipcAddress : name '', objFlags 0x0, addrFlags 0x0 }, name 'name', val 000000000012D130, len 39, flags 0x4000
2016-05-30 10:44:05.640: [GIPCXCPT][5064] gipcEndpointF [clsssclsnrsetup : clsssc.c : 2763]: EXCEPTION[ ret gipcretFail (1) ]  failed endp create ctx 0000000005060F20 [000000000000006b] { gipcContext : traceLevel 2, fieldLevel 0x0, numDead 0, numPending 0, numZombie 0, numObj 5, numWait 0, hgid 000000000000006c, flags 0x2, objFlags 0x0 }, name 'gipc://<node1>:nm_<CLUSTER_NAME>-cluster', flags 0x0
2016-05-30 10:44:05.640: [    CSSD][5064]clsssclsnrsetup: gipcEndpoint failed, rc 1
2016-05-30 10:44:05.640: [    CSSD][5064]clssnmOpenGIPCEndp: failed to listen on gipc addr gipc://<node1>:nm_<CLUSTER_NAME>-cluster- ret 1
2016-05-30 10:44:05.640: [    CSSD][5064]clssnmCompleteInitVFDiscovery: failed to open gipc endp
2016-05-30 10:44:05.640: [    CSSD][5064](:CSSSC00011:)clssscExit: A fatal error occurred during initialization

To simplify fixing the issue, I shut down the second VM node and focused exclusively on the first node. I restarted the system and let the cluster try to self start. This failed.

This is when I began digging deeper into the logs in conjunction with MOS. I ran to MOS to begin searching for a solution as the above errors did not resonate with me. I was fortunate that the first
item that popped up in MOS was titled "GI Fails to Start as no Private Network Interface is Available (Doc ID 1481176.1)" - without opening the note, I immediately checked
the private network interface. I was happy to see that the private network interfaces for the node interconnect were left out of the migration - meaning that the cluster nodes
were unable to interface. I requested the administrators to correct the interface. Once they were restored, I managed to get the first node up, followed by the second node.

SUMMARY:

Check the private interface, make sure the interface is viewable in network properties on both nodes in the cluster - if not, have the administrator check that they have been made available to the VMs in the cluster.

Thursday, 10 March 2016

Daily Cluster Health Report

This post will show you how to setup a RAC component report: an email that sends the state of the cluster components. This helps a DBA keep an eye on the cluster and act preemptively if any component appears offline.

REQUIREMENTS:

1. Access to Task Scheduler (or cron for Linux)
2. A from address from a recognized mail server within your domain.
3. A home folder to deploy the scripts

INSTALL

1. Open up command prompt (cmd) and execute the following – adjust root location if need be

e:
mkdir E:\dba\script\clusterhealthreport
cd E:\dba\script\clusterhealthreport

2. Create a file called mail.vbs inside E:\oracle\scripts\LogReport. Copy the following and paste into the file
'Grab the parameters
from_address = WScript.Arguments(0)
to_address = WScript.Arguments(1)
subject = WScript.Arguments(2)
file = WScript.Arguments(3)

'Set the file reading variables
Const ForReading = 1
Dim fso
Set fso = CreateObject("Scripting.FileSystemObject")

'Set the mail properties
SMTPServer = "smtprelay.inter.domain.net"
Recipient = to_address
From = from_address
Subject = subject


'Create the mail object
GenericSendmail SMTPserver, From, Recipient, Subject, Message
Sub GenericSendmail (SMTPserver, From, Recipient, Subject, Message)
Message = fso.OpenTextFile(file,ForReading).ReadAll

'Assisgn the values to our mail object and send the mail off
set msg = WScript.CreateObject("CDO.Message")
msg.From = From
msg.To = Recipient
msg.Subject = Subject
msg.TextBody = Message
msg.Configuration.Fields ("http://schemas.microsoft.com/cdo/configuration/smtpserver") = SMTPServer
msg.Configuration.Fields("http://schemas.microsoft.com/cdo/configuration/sendusing") = 2
msg.Configuration.Fields.Update
msg.Send
End Sub

3. Create a file called clusterhealthreport.bat and paste the following into it. Set the variables in yellow to what you want:
SET CLUSTERNAME=CLUSTERNAME
SET WORKING_DIR=E:\dba\script\clusterhealthreport
SET PATH=%PATH%;%WORKING_DIR%
SET ORACLE_BASE=E:\Oracle
SET ORACLE_HOME=E:\OracleGrid\11.2.0.4

cd %WORKING_DIR%
E:

SETLOCAL EnableDelayedExpansion

echo CLUSTER HEALTH REPORT  > clusterhealthreport.log
echo ---------------------  >> clusterhealthreport.log
echo .                      >> clusterhealthreport.log
echo crsctl stat res -t     >> clusterhealthreport.log

crsctl stat res -t >> clusterhealthreport.log

mail.vbs serveraddress@servername.net emailaddress@domain.net "%CLUSTERNAME% Cluster Health Report" %WORKING_DIR%\clusterhealthreport.log

4. Create a task scheduler to run once a day – I usually set it for 5:30am:























Click start, open task scheduler















Right click task scheduler library



Under the general tab, ensure the task executes with the highest privileges and runs while the user in not logged into the system. Enter a description for the server administrator.

Create a schedule – for details on their configuration see the screenshot below.


In the action tab, browse to the bat file location created in step 3

Your email should look like the following:
CLUSTER HEALTH REPORT 
--------------------- 
.                     
crsctl stat res -t    
--------------------------------------------------------------------------------
NAME           TARGET  STATE        SERVER                   STATE_DETAILS      
--------------------------------------------------------------------------------
Local Resources
--------------------------------------------------------------------------------
ora.DATA.dg
               ONLINE  ONLINE       yournodedb01                              
               ONLINE  ONLINE       yournodedb02                               
ora.H_DRIVE.dg
               ONLINE  ONLINE       yournodedb01                              
               ONLINE  ONLINE       yournodedb02                              
ora.LISTENER.lsnr
               ONLINE  ONLINE       yournodedb01                              
               ONLINE  ONLINE       yournodedb02                              
ora.asm
               ONLINE  ONLINE       yournodedb01           Started            
               ONLINE  ONLINE       yournodedb02           Started            
ora.gsd
               OFFLINE OFFLINE      yournodedb01                              
               OFFLINE OFFLINE      yournodedb02                              
ora.net1.network
               ONLINE  ONLINE       yournodedb01                              
               ONLINE  ONLINE       yournodedb02                              
ora.ons
               ONLINE  ONLINE       yournodedb01                              
               ONLINE  ONLINE       yournodedb02                              
ora.registry.acfs
               ONLINE  ONLINE       yournodedb01                              
               ONLINE  ONLINE       yournodedb02                              
--------------------------------------------------------------------------------
Cluster Resources
--------------------------------------------------------------------------------
ora.LISTENER_SCAN1.lsnr
      1        ONLINE  ONLINE       yournodedb02                              
ora.LISTENER_SCAN2.lsnr
      1        ONLINE  ONLINE       yournodedb01                              
ora.LISTENER_SCAN3.lsnr
      1        ONLINE  ONLINE       yournodedb01                              
ora.cvu
      1        ONLINE  ONLINE       yournodedb01                              
ora.oc4j
      1        ONLINE  ONLINE       yournodedb01                              
ora.scan1.vip
      1        ONLINE  ONLINE       yournodedb02                              
ora.scan2.vip
      1        ONLINE  ONLINE       yournodedb01                              
ora.scan3.vip
      1        ONLINE  ONLINE       yournodedb01                              
ora.database.db
      1        ONLINE  ONLINE       yournodedb01           Open               
      2        ONLINE  ONLINE       yournodedb02           Open               
ora.yournodedb01.vip
      1        ONLINE  ONLINE       yournodedb01                               
ora.yournodedb02.vip
      1        ONLINE  ONLINE       yournodedb02