Monday, February 10, 2014

weird stuff with asm happening ....

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 ....




No comments: