- 最后登录
- 2023-8-16
- 在线时间
- 1686 小时
- 威望
- 2135
- 金钱
- 50532
- 注册时间
- 2011-10-12
- 阅读权限
- 200
- 帖子
- 5207
- 精华
- 39
- 积分
- 2135
- UID
- 2
|
1#
发表于 2012-3-10 21:12:38
|
查看: 8102 |
回复: 0
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 |
|