AIX: Long "Disk file operations I/O" time with ASM

Maclean Liu(刘相兵

ASM disk open can incur 2 separate open() system calls
when it need only use a single open.

When opening ASM disks, we try to determine if the file that is open is a VSD/
HSD raw device. This is done to give a warning to the customer that usage of
such a device will result in data loss. This check incurs an extra open() and
stat() system call. If the open() system call itself is taking a long time
due to some OS bug/limitation, the extra open() system call can make it even worse.

This fix removes the additional open() call which can help reduce
the time spent waiting for "Disk file operations I/O" for cases
where some OS issue is making open() calls have poor performance.

Rediscovery Notes:
In 10046 trace output one might see long times
waiting for 'Disk file operations I/O' .. FileOperation=2

Workaround:
None

SQL> alter session set events '10046 trace name context forever,level 8';

Session altered.

SQL> select count(*) from large ;

  COUNT(*)
----------
   9631616



PARSE #47294153349528:c=5999,e=5721,p=17,cr=25,cu=0,mis=1,r=0,dep=0,og=1,plh=2114139301,tim=1331402759830853
EXEC #47294153349528:c=0,e=38,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=2114139301,tim=1331402759830994
WAIT #47294153349528: nam='SQL*Net message to client' ela= 6 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1331402759831069
WAIT #47294153349528: nam='Disk file operations I/O' ela= 307 FileOperation=2 fileno=4 filetype=2 obj#=76963 tim=1331402759831485
WAIT #47294153349528: nam='db file sequential read' ela= 24 file#=4 block#=522 blocks=1 obj#=76963 tim=1331402759831541




SQL> select * from v$event_name where name='Disk file operations I/O';

    EVENT#   EVENT_ID NAME                                                             PARAMETER1
---------- ---------- ---------------------------------------------------------------- ----------------------------------------------------------------
PARAMETER2                                                       PARAMETER3                                                       WAIT_CLASS_ID WAIT_CLASS#
---------------------------------------------------------------- ---------------------------------------------------------------- ------------- -----------
WAIT_CLASS
----------------------------------------------------------------
        11  166678035 Disk file operations I/O                                         FileOperation
fileno                                                           filetype                                                            1740759767           8
User I/O



[oracle@nas ~]$ cd /proc/9228/fd
[oracle@nas fd]$ ls -l
total 0
lr-x------ 1 oracle oinstall 64 Mar 10 13:09 0 -> /dev/null
l-wx------ 1 oracle oinstall 64 Mar 10 13:09 1 -> /dev/null
l-wx------ 1 oracle oinstall 64 Mar 10 13:09 10 -> /s01/orabase/diag/rdbms/g11r23/G11R23/trace/G11R23_ora_9228.trm
l-wx------ 1 oracle oinstall 64 Mar 10 13:09 12 -> pipe:[2624953]
l-wx------ 1 oracle oinstall 64 Mar 10 13:09 2 -> /dev/null
lrwx------ 1 oracle oinstall 64 Mar 10 13:09 256 -> /s01/orabase/oradata/G11R23/system01.dbf
lrwx------ 1 oracle oinstall 64 Mar 10 13:09 257 -> /s01/orabase/oradata/G11R23/users01.dbf
lrwx------ 1 oracle oinstall 64 Mar 10 13:09 258 -> /s01/orabase/oradata/G11R23/undotbs01.dbf
lr-x------ 1 oracle oinstall 64 Mar 10 13:09 3 -> /dev/null
lr-x------ 1 oracle oinstall 64 Mar 10 13:09 4 -> /dev/null
lr-x------ 1 oracle oinstall 64 Mar 10 13:09 5 -> /s01/orabase/product/11.2.0/dbhome_1/rdbms/mesg/oraus.msb
lr-x------ 1 oracle oinstall 64 Mar 10 13:09 6 -> /proc/9228/fd
lr-x------ 1 oracle oinstall 64 Mar 10 13:09 7 -> /dev/zero
l-wx------ 1 oracle oinstall 64 Mar 10 13:09 8 -> /s01/orabase/diag/rdbms/g11r23/G11R23/trace/G11R23_ora_9228.trc
lr-x------ 1 oracle oinstall 64 Mar 10 13:09 9 -> pipe:[2624952]

fileno=4 ==>users01.dbf

[oracle@nas fd]$ sqlplus  / as sysdba



SQL> select name from v$datafile where file#=4;

NAME
--------------------------------------------------------------------------------
/s01/orabase/oradata/G11R23/users01.dbf





SQL> oradebug setospid 9228
Oracle pid: 19, Unix process pid: 9228, image: oracle@nas.oracle.com (TNS V1-V3)


SQL> oradebug call close 257;
Function returned 0



SPID 9228:

SQL> select count(*) from large ;
select count(*) from large
                     *
ERROR at line 1:
ORA-01115: IO error reading block from file  (block # )
ORA-01110: data file 4: '/s01/orabase/oradata/G11R23/users01.dbf'
ORA-27072: File I/O error
Linux-x86_64 Error: 9: Bad file descriptor
Additional information: 4
Additional information: 523
Additional information: -1



10046 trace

PARSING IN CURSOR #47294153035576 len=27 dep=0 uid=90 oct=3 lid=90 tim=1331403171960894 hv=3542646734 ad='91f0e220' sqlid='7raqd139khzyf'
select count(*) from large
END OF STMT
PARSE #47294153035576:c=1000,e=89,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=2114139301,tim=1331403171960893
EXEC #47294153035576:c=0,e=44,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=2114139301,tim=1331403171961028
WAIT #47294153035576: nam='SQL*Net message to client' ela= 7 driver id=1650815232 #bytes=1 p3=0 obj#=76963 tim=1331403171961099
WAIT #47294153035576: nam='db file scattered read' ela= 26 file#=4 block#=523 blocks=5 obj#=76963 tim=1331403171961255
DDE: Problem Key 'ORA 1110' was flood controlled (0x1) (no incident)
ORA-01110: data file 4: '/s01/orabase/oradata/G11R23/users01.dbf'
ORA-27072: File I/O error
Linux-x86_64 Error: 9: Bad file descriptor
Additional information: 4
Additional information: 523
Additional information: -1
FETCH #47294153035576:c=0,e=395,p=0,cr=2,cu=0,mis=0,r=0,dep=0,og=1,plh=2114139301,tim=1331403171961532
STAT #47294153035576 id=1 cnt=0 pid=0 pos=1 obj=0 op='SORT AGGREGATE (cr=0 pr=0 pw=0 time=12 us)'
STAT #47294153035576 id=2 cnt=0 pid=1 pos=1 obj=76963 op='TABLE ACCESS FULL LARGE (cr=0 pr=0 pw=0 time=3 us cost=2 size=0 card=1)'
WAIT #47294153035576: nam='SQL*Net break/reset to client' ela= 6 driver id=1650815232 break?=1 p3=0 obj#=76963 tim=1331403171961662
WAIT #47294153035576: nam='SQL*Net break/reset to client' ela= 79 driver id=1650815232 break?=0 p3=0 obj#=76963 tim=1331403171961765