Tales of an oracle dba

During the weekend I've setup two virtual box standard edition 12c machines to test
Dbvisit Standby. During the setup I had some issues with archive log gap's, while collecting information for Dbvisit's excellent support I noticed that v$asm_diskgroup was empty ...

However asmcmd returned information I couldn't understand why and started digging ....

together with my twitter friends @drune and @OsamaOracle who made good suggestions ...

SQL> select upper(name) NAME from v$asm_diskgroup;

no rows selected

SQL> select * from v$asm_diskgroup;

no rows selected

[oracle@SE1] asmcmd

ASMCMD> lsdg

State Type Rebal Sector Block AU Total_MB Free_MB Req_mir_free_MB Usable_file_MB Offline_disks Voting_files Name

MOUNTED EXTERN N 512 4096 1048576 4094 3694 0 3694 0 N ARCHDG1/

MOUNTED EXTERN N 512 4096 1048576 10228 7522 0 7522 0 N DATADG1/

At the same time that @martinberx was suggesting it, I started to use the 10046 trace to see what happens
when I execute

select * from v$asm_diskgroup;

=====================

PARSING IN CURSOR #139820964230440 len=29 dep=0 uid=0 oct=3 lid=0 tim=582985779 hv=3194982195 ad='9f2f6808' sqlid='38z4yk2z6z3tm'

select * from v$asm_diskgroup

END OF STMT

PARSE #139820964230440:c=2000,e=6212,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,plh=3236948515,tim=582985778

EXEC #139820964230440:c=0,e=63,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=3236948515,tim=582985923

WAIT #139820964230440: nam='SQL*Net message to client' ela= 2 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=582985965

Initialized kgfd context:0x7f2a9ae77f00

Terminating kgfd context 0x7f2a9ae77f00

FETCH #139820964230440:c=3000,e=12273,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=3236948515,tim=582998295

STAT #139820964230440 id=1 cnt=0 pid=0 pos=1 obj=0 op='FIXED TABLE FULL X$KFGRP (cr=0 pr=0 pw=0 time=12271 us)'

*** 2014-02-10 22:05:10.377

WAIT #139820964230440: nam='SQL*Net message from client' ela= 18538852 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=601539107

CLOSE #139820964230440:c=0,e=10,dep=0,type=0,tim=601539195

and also the lsdg action in asmcmd

 1* select sid,serial#,module from v$session

SID         SERIAL#  MODULE

29     7        perl@SE1 (TNS V1-V3)

select saddr,paddr from v$session where sid=29 and serial#=7;

SADDR PADDR

---------------- ----------------

00000000A3B64C78 00000000A397A378

SQL> select spid from v$process where addr='00000000A397A378’;

SPID

------------------------

2818

SQL> oradebug setospid 2818;

Oracle pid: 23, Unix process pid: 2818, image: oracle@SE1 (TNS V1-V3)

SQL> ORADEBUG EVENT 10046 TRACE NAME CONTEXT FOREVER, LEVEL 8;

Statement processed.

SQL> oradebug tracefile_name;

/u01/app/oracle/diag/asm/+asm/+ASM/trace/+ASM_ora_2818.trc

which generates this :

Trace file /u01/app/oracle/diag/asm/+asm/+ASM/trace/+ASM_ora_2818.trc

Oracle Database 12c Enterprise Edition Release 12.1.0.1.0 - 64bit Production

With the Automatic Storage Management option

ORACLE_HOME = /u01/app/oracle/product/12.1.0/grid

System name: Linux

Node name: SE1

Release: 3.8.13-16.3.1.el6uek.x86_64

Version: #2 SMP Tue Dec 17 11:24:44 PST 2013

Machine: x86_64

Instance name: +ASM

Redo thread mounted by this instance: 0 

Oracle process number: 23

Unix process pid: 2818, image: oracle@SE1 (TNS V1-V3)

*** 2014-02-10 22:13:26.120

*** SESSION ID:(29.7) 2014-02-10 22:13:26.120

*** CLIENT ID:() 2014-02-10 22:13:26.120

*** SERVICE NAME:() 2014-02-10 22:13:26.120

*** MODULE NAME:(perl@SE1 (TNS V1-V3)) 2014-02-10 22:13:26.120

*** ACTION NAME:() 2014-02-10 22:13:26.120

Received ORADEBUG command (#1) 'EVENT 10046 TRACE NAME CONTEXT FOREVER, LEVEL 8' from process '2723'

*** 2014-02-10 22:13:26.121

Finished processing ORADEBUG command (#1) 'EVENT 10046 TRACE NAME CONTEXT FOREVER, LEVEL 8'

*** 2014-02-10 22:13:40.668

Received ORADEBUG command (#2) 'tracefile_name' from process '2723'

*** 2014-02-10 22:13:40.669

Finished processing ORADEBUG command (#2) 'tracefile_name'

*** 2014-02-10 22:15:24.837

WAIT #140181062274144: nam='SQL*Net message from client' ela= 558311444 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1215999416

CLOSE #140181062274144:c=0,e=10,dep=0,type=0,tim=1215999600

=====================

PARSING IN CURSOR #140181062274144 len=47 dep=0 uid=0 oct=3 lid=0 tim=1216001667 hv=2237657138 ad='9f36be20' sqlid='acnhubu2pzw1k'

/* ASMCMD */ select * from v$asm_diskgroup_stat

END OF STMT

PARSE #140181062274144:c=1000,e=1997,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,plh=486334127,tim=1216001665

WAIT #140181062274144: nam='SQL*Net message to client' ela= 2 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1216001773

WAIT #140181062274144: nam='SQL*Net message from client' ela= 1356 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1216003177

EXEC #140181062274144:c=0,e=48,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=486334127,tim=1216003273

WAIT #140181062274144: nam='Disk file operations I/O' ela= 2237 FileOperation=2 fileno=0 filetype=15 obj#=-1 tim=1216006405

WAIT #140181062274144: nam='ASM sync cache disk read' ela= 2558 group=2 obj=1 block=8 obj#=-1 tim=1216009066

WAIT #140181062274144: nam='Disk file operations I/O' ela= 20 FileOperation=2 fileno=0 filetype=15 obj#=-1 tim=1216009216

WAIT #140181062274144: nam='ASM sync cache disk read' ela= 811 group=2 obj=8 block=0 obj#=-1 tim=1216010056

WAIT #140181062274144: nam='ASM sync cache disk read' ela= 602 group=2 obj=8 block=60 obj#=-1 tim=1216010750

WAIT #140181062274144: nam='ASM sync cache disk read' ela= 1059 group=2 obj=8 block=120 obj#=-1 tim=1216011895

WAIT #140181062274144: nam='ASM sync cache disk read' ela= 658 group=2 obj=8 block=180 obj#=-1 tim=1216012648

WAIT #140181062274144: nam='ASM sync cache disk read' ela= 674 group=2 obj=8 block=240 obj#=-1 tim=1216013413

WAIT #140181062274144: nam='SQL*Net message to client' ela= 2 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1216013620

WAIT #140181062274144: nam='Disk file operations I/O' ela= 20 FileOperation=2 fileno=0 filetype=15 obj#=-1 tim=1216013781

WAIT #140181062274144: nam='ASM sync cache disk read' ela= 599 group=1 obj=8 block=60 obj#=-1 tim=1216014409

WAIT #140181062274144: nam='ASM sync cache disk read' ela= 639 group=1 obj=8 block=120 obj#=-1 tim=1216015116

WAIT #140181062274144: nam='ASM sync cache disk read' ela= 426 group=1 obj=8 block=180 obj#=-1 tim=1216015650

WAIT #140181062274144: nam='ASM sync cache disk read' ela= 882 group=1 obj=8 block=240 obj#=-1 tim=1216016620

FETCH #140181062274144:c=4000,e=13420,p=0,cr=0,cu=0,mis=0,r=2,dep=0,og=1,plh=486334127,tim=1216016721

STAT #140181062274144 id=1 cnt=2 pid=0 pos=1 obj=0 op='FIXED TABLE FULL X$KFGRP_STAT (cr=0 pr=0 pw=0 time=13352 us)'

WAIT #140181062274144: nam='SQL*Net message from client' ela= 1327 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1216018167

CLOSE #140181062274144:c=0,e=7,dep=0,type=0,tim=1216018228

=====================

PARSING IN CURSOR #140181062273064 len=1397 dep=2 uid=0 oct=3 lid=0 tim=1216021926 hv=2564988146 ad='9f2c77d8' sqlid='1gskc7qcf577k'

select   inst_id, number_kfgbrb, 'REBAL',   decode(op_kfgbrb, 1, 'RESYNC', 2, 'RESILVER', 3, 'REBALANCE', 'COMPACT'),   decode(error_kfgbrb, 0,          decode(sign(state_kfgbrb - op_kfgbrb), 0,                 decode((select state_kfgmg from x$kfgmg where                          number_kfgmg=number_kfgbrb and op_kfgmg=1 and                          pass_kfgmg=op_kfgbrb), 3, 'REAP',                        decode((select rebalst_kfgmg from x$kfgmg where                                 number_kfgmg=number_kfgbrb and op_kfgmg = 1                                 and pass_kfgmg=op_kfgbrb), 1, 'EST', 3, 'EST',                                5, 'EST', 0, 'WAIT', '', 'WAIT', 'RUN')),                  1, 'DONE', 'WAIT'), 'ERRS'),   power_kfgbrb,   (select actual_kfgmg from x$kfgmg where number_kfgmg=number_kfgbrb    and op_kfgmg = 1 and pass_kfgmg=op_kfgbrb),   (select sofar_kfgmg from x$kfgmg where number_kfgmg=number_kfgbrb    and op_kfgmg = 1 and pass_kfgmg=op_kfgbrb),   (select work_kfgmg from x$kfgmg where number_kfgmg=number_kfgbrb    and op_kfgmg = 1 and pass_kfgmg=op_kfgbrb),   (select rate_kfgmg from x$kfgmg where number_kfgmg=number_kfgbrb    and op_kfgmg = 1 and pass_kfgmg=op_kfgbrb),   (select time_kfgmg from x$kfgmg where number_kfgmg=number_kfgbrb    and op_kfgmg = 1 and pass_kfgmg=op_kfgbrb),   decode(error_kfgbrb, 0, '', 'ORA-' || error_kfgbrb), con_id  from x$kfgbrb

END OF STMT

PARSE #140181062273064:c=2000,e=2870,p=0,cr=0,cu=0,mis=1,r=0,dep=2,og=4,plh=2802141400,tim=1216021925

CLOSE #140181062273064:c=0,e=7,dep=2,type=0,tim=1216022547

=====================

PARSING IN CURSOR #140181062274144 len=181 dep=1 uid=0 oct=3 lid=0 tim=1216024992 hv=2797184208 ad='9f2ccb18' sqlid='fgj46y2mbm96h'

select   group_number, operation, pass, state, power, actual,   sofar, est_work, est_rate, est_minutes, error_code, con_id  from gv$asm_operation where inst_id = USERENV('Instance')

END OF STMT

PARSE #140181062274144:c=6000,e=6327,p=0,cr=0,cu=0,mis=1,r=0,dep=1,og=4,plh=2802141400,tim=1216024982

CLOSE #140181062274144:c=0,e=7,dep=1,type=0,tim=1216025086

=====================

PARSING IN CURSOR #140181062275568 len=71 dep=0 uid=0 oct=3 lid=0 tim=1216025673 hv=2266270607 ad='9f2d1998' sqlid='3k7n9vf3j92wg'

/* ASMCMD */ select operation from v$asm_operation where group_number=1

END OF STMT

PARSE #140181062275568:c=6000,e=7400,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,plh=4014866482,tim=1216025672

WAIT #140181062275568: nam='SQL*Net message to client' ela= 1 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1216025742

WAIT #140181062275568: nam='SQL*Net message from client' ela= 268 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1216026079

EXEC #140181062275568:c=0,e=30,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=4014866482,tim=1216026145

FETCH #140181062275568:c=0,e=77,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=4014866482,tim=1216026246

STAT #140181062275568 id=1 cnt=0 pid=0 pos=1 obj=0 op='FIXED TABLE FIXED INDEX X$KFGBRB (ind:1) (cr=0 pr=0 pw=0 time=80 us)'

WAIT #140181062275568: nam='SQL*Net message to client' ela= 0 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1216026276

WAIT #140181062275568: nam='SQL*Net message from client' ela= 316 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1216026592

CLOSE #140181062275568:c=0,e=122,dep=0,type=0,tim=1216026747

=====================

PARSING IN CURSOR #140181062275568 len=71 dep=0 uid=0 oct=3 lid=0 tim=1216028147 hv=768609183 ad='9f2c0e50' sqlid='4w32mxwqx02wz'

/* ASMCMD */ select operation from v$asm_operation where group_number=2

END OF STMT

PARSE #140181062275568:c=1000,e=1352,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,plh=4014866482,tim=1216028146

WAIT #140181062275568: nam='SQL*Net message to client' ela= 1 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1216028221

WAIT #140181062275568: nam='SQL*Net message from client' ela= 222 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1216028475

EXEC #140181062275568:c=0,e=21,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=4014866482,tim=1216028530

FETCH #140181062275568:c=0,e=56,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=4014866482,tim=1216028608

STAT #140181062275568 id=1 cnt=0 pid=0 pos=1 obj=0 op='FIXED TABLE FIXED INDEX X$KFGBRB (ind:1) (cr=0 pr=0 pw=0 time=55 us)'

WAIT #140181062275568: nam='SQL*Net message to client' ela= 1 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1216028685

*** 2014-02-10 22:15:48.367

Received ORADEBUG command (#3) 'EVENT 10046 TRACE NAME CONTEXT OFF' from process '2723'

*** 2014-02-10 22:15:48.370

Finished processing ORADEBUG command (#3) 'EVENT 10046 TRACE NAME CONTEXT OFF'

Hmm strange it uses v$asm_diskgroup_stat and other views.

after checking disk permissions with kfod which looked fine

[oracle@SE1 redhat]$ kfod disks=all

--------------------------------------------------------------------------------

 Disk          Size Path                                     User     Group   

================================================================================

   1:       5114 Mb /dev/asm-disk1                           oracle   dba     

   2:       4094 Mb /dev/asm-disk2                           oracle   dba     

   3:       5114 Mb /dev/asm-disk3                           oracle   dba     

   4:      12288 Mb /dev/sda                                 root     dba     

   5:       2987 Mb /dev/sda3                                root     dba     

   6:      35840 Mb /dev/sdb                                 root     dba     

   7:       5120 Mb /dev/sdc                                 root     dba     

   8:       4096 Mb /dev/sdd                                 root     dba     

   9:       5120 Mb /dev/sde                                 root     dba     

--------------------------------------------------------------------------------

ORACLE_SID ORACLE_HOME                                                          

================================================================================

      +ASM /u01/app/oracle/product/12.1.0/grid  

Martin Carsten Bach aka as @MartinDBA came with this suggestion :

MartinDBA
@pfierens @martinberx you could check permission on the block devices, kfod disks=all (might need to set ask_diskstring too)
10/02/14 22:46

And that seemed to do it, for some reason the asm_diskstring was not set ... after setting the asm_diskstring select from v$asm_diskgroup worked again.

SQL> select name from v$asm_diskgroup;

NAME

------------------------------

DATADG1

ARCHDG1

Big Thanks to all who helped me here, twitter is great and having friend out there is even better, thank you guys !!!

BTW after fixing the v$asm_diskgroup dbvisit standby started resolving the archive log gap, it looks like a great product I will be investigating deeper ....

Last week I had an issue on a freshly installed dev system with 12c and Oracle Restart.

In about 3 months time there were 7,5 million audit files generated in the GI home.

This caused the zfs filesystem to fill up completely ( zfs doesn't like this ;-) we didn't finish monitoring yet on this system so we noticed it when damage was done ....

cleaning up the zfs filesystem was one thing, first we had to make some space otherwise we got ...

rm: cannot remove : No space left on device

First since is was a dev system and holidays anyways I stop ASM and the databases ...After cleaning up some space we could to following ...

cd $GRID_HOME/rdbms/audit
find . > /tmp/rm_audit

remove the first line of that file ...

cat rm_audit | xargs -l 100 rm

and then slowly the space was given back...

now time to change the check interval to something more reasonable since it was checking each second .... and thus generating an audit file each second or 86400 each day

to view all the parameters

crsctl stat res -p 

for example on the ASM instance following parameters are set.

NAME=ora.asm

TYPE=ora.asm.type

ACL=owner:grid:rwx,pgrp:asmdba:r-x,other::r--

ACTIONS=

ACTION_FAILURE_TEMPLATE=

ACTION_SCRIPT=

ACTION_TIMEOUT=60

AGENT_FILENAME=%CRS_HOME%/bin/oraagent%CRS_EXE_SUFFIX%

ALERT_TEMPLATE=

ALIAS_NAME=

ASM_DISKSTRING=/dev/oracle/*

AUTO_START=restore

CHECK_INTERVAL=1

CHECK_TIMEOUT=30

CLEAN_TIMEOUT=60

DEFAULT_TEMPLATE=PROPERTY(RESOURCE_CLASS=asm) ELEMENT(INSTANCE_NAME= %GEN_USR_ORA_INST_NAME%)

DEGREE=1

DELETE_TIMEOUT=60

DESCRIPTION=Oracle ASM resource

ENABLED=1

GEN_USR_ORA_INST_NAME=+ASM

INSTANCE_FAILOVER=1

but databases are impacted as well.

so we changed it to every minute a check

-bash-4.1$ crsctl modify resource ora.dba12c.db -attr "CHECK_INTERVAL=60"

-bash-4.1$ crsctl modify resource ora.asm -attr "CHECK_INTERVAL=60"

ofcourse a cron job to delete the audit files on a regular basis installed ...

Tales of an oracle dba

Thursday, February 20, 2014

T4 Quarterly Patch 2014 jan ..

Tuesday, February 11, 2014

speaking in 2014

Monday, February 10, 2014

weird stuff with asm happening ....

Saturday, February 8, 2014

standby logfile groups on SE

Saturday, December 28, 2013

Friday, December 27, 2013

replicate controlfile or restore controlfile

lots of audit files generated in ASM home dir on 12cR1