[20241030]等待事件external table read.txt
--//下午开机，马上测试，我发现启动数据库时有点慢，探究发现出现external table read等待事件，做一些简单探究。
1.环境：
SCOTT@book01p> @ver2
==============================
PORT_STRING : x86_64/Linux 2.4.xx
VERSION : 21.0.0.0.0
BANNER : Oracle Database 21c Enterprise Edition Release 21.0.0.0.0 - Production
BANNER_FULL : Oracle Database 21c Enterprise Edition Release 21.0.0.0.0 - Production
Version 21.3.0.0.0
BANNER_LEGACY : Oracle Database 21c Enterprise Edition Release 21.0.0.0.0 - Production
CON_ID : 0
PL/SQL procedure successfully completed.
2.问题提出：
SYS@book> @ ashtop event,p1,p1raw,p2raw,p3raw 1=1 &5min
Total Distinct Distinct Distinct
Seconds AAS %This EVENT P1 P1RAW P2RAW P3RAW FIRST_SEEN LAST_SEEN Execs Seen Tstamps Execs Seen1
--------- ------- ------- --------------------- ---------------- ----------------- ----------------- ----------------- ------------------- ------------------- ---------- -------- -----------
19 .1 7% | 3 2024-10-30 15:32:53 2024-10-30 15:34:49 2 19 19
11 .0 4% | LGWR any worker group 0 0000000000000000 0000000000000000 0000000000000000 2024-10-30 15:33:04 2024-10-30 15:33:25 1 11 11
11 .0 4% | external table read 140026990743960 00007F5A930AD198 0000000000000000 0000000002FB0000 2024-10-30 15:32:50 2024-10-30 15:33:00 1 11 1
11 .0 4% | 100 2024-10-30 15:33:28 2024-10-30 15:36:32 1 10 10
10 .0 3% | 1 2024-10-30 15:32:38 2024-10-30 15:35:08 4 10 8
....
30 rows selected.
--//Distinct Execs Seen=1,执行1次需要11秒。
SYS@book> @ ev_namepr "external table read"
==============================
EVENT# : 426
EVENT_ID : 1850448852
NAME : external table read
PARAMETER1 : filectx
PARAMETER2 : file#
PARAMETER3 : size
WAIT_CLASS_ID : 1740759767
WAIT_CLASS# : 8
WAIT_CLASS : User I/O
DISPLAY_NAME : external table read
CON_ID : 0
PL/SQL procedure successfully completed.
--//参数1PARAMETER1=filectx，不清楚表示怎么？p2=file#，对应诊断没有。
--//P3=size,0x0000000002FB0000 = 50003968,50003968/1024/1024 = 78.6M,读取的信息量有点大。
3.分析：
SYS@book> @ ashtop event,sid "event='external table read'" "'2024-10-30 15:32:50'" sysdate
Total Distinct Distinct Distinct
Seconds AAS %This EVENT SID FIRST_SEEN LAST_SEEN Execs Seen Tstamps Execs Seen1
--------- ------- ------- ------------------------------------------ ---------- ------------------- ------------------- ---------- -------- -----------
11 .0 100% | external table read 133 2024-10-30 15:32:50 2024-10-30 15:33:00 1 11 1
--//启动数据库涉及该等待事件，仅仅sid= 133.
SYS@book> @ usid 133
SYS@book> @ pr 133
==============================
U_USERNAME :
U_SID : '133,10013'
U_AUDSID : 0
U_OSUSER : oracle
U_MACHINE : centtest
U_PROGRAM : (MMON)
U_SPID : 2888
U_PID : 29
CPID : 2888
SQL_ID :
USID_SQL_HASH_VALUE : 0
LASTCALL : 534
STATUS : ACTIVE
SADDR : 000000007BD88520
PADDR : 000000007C7C08B0
TADDR :
LOGON_TIME : 2024-10-30 15:32:33
TRACEFILE : /u01/app/oracle/diag/rdbms/book/book/trace/book_mmon_2888.trc
PL/SQL procedure successfully completed.
$ ll /proc/2888/fd
total 0
lr-x------. 1 oracle oinstall 64 2024-10-30 15:41:58 0 -> /dev/null
l-wx------. 1 oracle oinstall 64 2024-10-30 15:41:58 1 -> /dev/null
l-wx------. 1 oracle oinstall 64 2024-10-30 15:41:58 10 -> /u01/app/oracle/diag/rdbms/book/book/trace/book_mmon_2888.trm
lr-x------. 1 oracle oinstall 64 2024-10-30 15:41:58 11 -> /u01/app/oracle/product/21.0.0/dbhome_1/rdbms/mesg/kupus.msb
l-wx------. 1 oracle oinstall 64 2024-10-30 15:41:58 2 -> /dev/null
lrwx------. 1 oracle oinstall 64 2024-10-30 15:41:58 256 -> /u01/oradata/BOOK/system01.dbf
lrwx------. 1 oracle oinstall 64 2024-10-30 15:41:58 257 -> /u01/oradata/BOOK/undotbs01.dbf
lrwx------. 1 oracle oinstall 64 2024-10-30 15:41:58 258 -> /u01/oradata/BOOK/control01.ctl
lrwx------. 1 oracle oinstall 64 2024-10-30 15:41:58 259 -> /u01/oradata/BOOK/control02.ctl
lrwx------. 1 oracle oinstall 64 2024-10-30 15:41:58 260 -> /u01/oradata/BOOK/sysaux01.dbf
lrwx------. 1 oracle oinstall 64 2024-10-30 15:41:58 261 -> /u01/oradata/BOOK/temp01.dbf
lrwx------. 1 oracle oinstall 64 2024-10-30 15:41:58 262 -> /u01/oradata/BOOK/book01p/sysaux01.dbf
lrwx------. 1 oracle oinstall 64 2024-10-30 15:41:58 263 -> /u01/oradata/BOOK/book01p/system01.dbf
lr-x------. 1 oracle oinstall 64 2024-10-30 15:41:58 3 -> /dev/null
lr-x------. 1 oracle oinstall 64 2024-10-30 15:41:58 4 -> /u01/app/oracle/product/21.0.0/dbhome_1/rdbms/mesg/oraus.msb
lr-x------. 1 oracle oinstall 64 2024-10-30 15:41:58 5 -> /proc/2888/fd
lrwx------. 1 oracle oinstall 64 2024-10-30 15:41:58 6 -> /u01/app/oracle/dbs/hc_book.dat
lrwx------. 1 oracle oinstall 64 2024-10-30 15:41:58 7 -> /u01/app/oracle/dbs/lkBOOK
lr-x------. 1 oracle oinstall 64 2024-10-30 15:41:58 8 -> /u01/app/oracle/product/21.0.0/dbhome_1/rdbms/mesg/oraus.msb
l-wx------. 1 oracle oinstall 64 2024-10-30 15:41:58 9 -> /u01/app/oracle/diag/rdbms/book/book/trace/book_mmon_2888.trc
--//查看/u01/app/oracle/diag/rdbms/book/book/trace/book_mmon_2888.trc：
*** 2024-10-30T15:32:47.638707+08:00 (CDB$ROOT(1))
*** SESSION ID:(133.10013) 2024-10-30T15:32:47.638742+08:00
*** CLIENT ID:() 2024-10-30T15:32:47.638751+08:00
*** SERVICE NAME:(SYS$BACKGROUND) 2024-10-30T15:32:47.638761+08:00
*** MODULE NAME:() 2024-10-30T15:32:47.638769+08:00
*** ACTION NAME:() 2024-10-30T15:32:47.638775+08:00
*** CLIENT DRIVER:(SERVER) 2024-10-30T15:32:47.638782+08:00
*** CONTAINER ID:(1) 2024-10-30T15:32:47.638791+08:00
*** CONTAINER ID:(1) 2024-10-30T15:32:47.638791+08:00
: QPI: Obtaining lock SUCCESSFUL, qp_result=0 at : 30-OCT-24 03.32.47.559442000 PM +08:00
: QPI: Got lock get_opatch_lsinventory
: QPI: In opatch_run_job
: QPI: In sanity check..
*** 2024-10-30T15:32:47.722401+08:00 (CDB$ROOT(1))
: QPI: t_root is /u01/app/oracle/product/21.0.0/dbhome_1/
: QPI: t_orabase is /u01/app/oracle/homes/OraDB21Home1/
: QPI: t_op_inst_path is /u01/app/oracle/product/21.0.0/dbhome_1/OPatch/
: QPI: t_op_scpt_path is /u01/app/oracle/product/21.0.0/dbhome_1/QOpatch/
: QPI: t_op_log_path is /u01/app/oracle/homes/OraDB21Home1/rdbms/log/
: QPI: op_scpt_path :/u01/app/oracle/product/21.0.0/dbhome_1/QOpatchpos1
:
QPI: opatch file present, opatch
:
QPI: qopiprep.bat file present
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
: QPI: In opatch_inv_refresh_job
: QPI: In REFRESH_OPATCH_DATA
*** 2024-10-30T15:33:01.096721+08:00 (CDB$ROOT(1))
: QPI: Latest xml inventory is loaded into table
: QPI: Release lock get_opatch_lsinventory
: QPI: Releasing lock SUCCESSFUL, qp_result=0 at : 30-OCT-24 03.33.01.405626000 PM +08:00
--//感觉执行qopiprep.bat脚本，看下划线。
--//开始 2024-10-30T15:32:47.722401+08:00 到结束2024-10-30T15:33:01.096721+08:00需要14秒。
$ locate qopiprep.bat
/u01/app/oracle/product/21.0.0/dbhome_1/QOpatch/qopiprep.bat
--//参看/u01/app/oracle/product/21.0.0/dbhome_1/QOpatch/qopiprep.bat，存在如下内容。
# DESCRIPTION
# bat file for external table preprocessor.
#
--//里面除了rm语句外，感觉执行的如下语句。
$ORACLE_HOME/OPatch/opatch lsinventory -customLogDir $ORABASE/rdbms/log -xml $ORABASE/rdbms/log/xml_file_${DBSID}_${PD}.xml -retry 0 -invPtrLoc $ORACLE_HOME/oraInst.loc >> $ORABASE/rdbms/log/stout_${DBSID}_${PD}.txt
4.换一个方式分析看看：
SYS@book> shutdown immediate ;
Database closed.
Database dismounted.
ORACLE instance shut down.
SYS@book> startup mount
ORACLE instance started.
Total System Global Area 805306280 bytes
Fixed Size 9691048 bytes
Variable Size 473956352 bytes
Database Buffers 314572800 bytes
Redo Buffers 7086080 bytes
Database mounted.
SYS@book> @ bg mmon
ADDR PID SPID PROGRAM
---------------- ------- ------------------------------ --------------------------
000000007C7C1EB8 30 3613 oracle@centtest (MMON)
$ strace -Ttt -y -f -p 3613 -e open,read 2>&1 | tee mmon.txt
SYS@book> alter database open ;
Database altered.
SYS@book> @ ashtop event,p1,p1raw,p2raw,p3raw "EVENT='external table read'" &5min
Total Distinct Distinct Distinct
Seconds AAS %This EVENT P1 P1RAW P2RAW P3RAW FIRST_SEEN LAST_SEEN Execs Seen Tstamps Execs Seen1
--------- ------- ------- ------------------------------------------ --------------------- ----------------- ----------------- ----------------- ------------------- ------------------- ---------- -------- -----------
3 .0 100% | external table read 140462199525848 00007FBFE781D1D8 0000000000000000 0000000002FB0000 2024-10-31 09:30:23 2024-10-31 09:30:25 1 3 1
--//需要3秒，我估计一些文件第2次执行OS已经缓存了，注意P3raw=0000000002FB0000与前面测试不变。
$ grep qopiprep.bat mmon.txt
09:30:22.664315 open("/u01/app/oracle/product/21.0.0/dbhome_1/QOpatch/qopiprep.bat", O_RDONLY) = 11 <0.000028>
[pid 4271] 09:30:23.043730 open("/u01/app/oracle/product/21.0.0/dbhome_1/QOpatch/qopiprep.bat", O_RDONLY) = 3 <0.000012>
[pid 4271] 09:30:23.043823 read(3</u01/app/oracle/product/21.0.0/dbhome_1/QOpatch/qopiprep.bat>, "#!/bin/sh\n#\n# $Header: rdbms/src"..., 80) = 80 <0.000008>
[pid 4271] 09:30:23.043979 read(255</u01/app/oracle/product/21.0.0/dbhome_1/QOpatch/qopiprep.bat>, "#!/bin/sh\n#\n# $Header: rdbms/src"..., 3029) = 3029 <0.000008>
[pid 4271] 09:30:23.065370 read(255</u01/app/oracle/product/21.0.0/dbhome_1/QOpatch/qopiprep.bat>, "if [ $? -eq 0 ] ; then\n LANG=\"$"..., 3029) = 1481 <0.000009>
[pid 4271] 09:30:23.086514 read(255</u01/app/oracle/product/21.0.0/dbhome_1/QOpatch/qopiprep.bat>, "\nrm -rf $ORABASE/rdbms/log/xml_f"..., 3029) = 695 <0.000008>
[pid 4271] 09:30:23.089437 read(255</u01/app/oracle/product/21.0.0/dbhome_1/QOpatch/qopiprep.bat>, "$ORACLE_HOME/OPatch/opatch lsinv"..., 3029) = 640 <0.000007>
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
[pid 4271] 09:30:25.817371 read(255</u01/app/oracle/product/21.0.0/dbhome_1/QOpatch/qopiprep.bat>, "RETVAL=$?;\nif [ $RETVAL -ne 0 ] "..., 3029) = 423 <0.000009>
[pid 4271] 09:30:25.840230 read(255</u01/app/oracle/product/21.0.0/dbhome_1/QOpatch/qopiprep.bat>, "\necho \"UIJSVTBOEIZBEFFQBL\";\n\nrm "..., 3029) = 132 <0.000007>
[pid 4271] 09:30:25.843852 read(255</u01/app/oracle/product/21.0.0/dbhome_1/QOpatch/qopiprep.bat>, "rm -f $ORABASE/rdbms/log/stout_$"..., 3029) = 50 <0.000008>
[pid 4271] 09:30:25.846193 read(255</u01/app/oracle/product/21.0.0/dbhome_1/QOpatch/qopiprep.bat>, "", 3029) = 0 <0.000008>
--//下划线那行执行并不慢，也许os已经缓存这些文件。
$ ps -fp 4271
UID PID PPID C STIME TTY TIME CMD
--//进程已经不存在了。
--//仔细检查主要集中read /u01/app/oracle/product/21.0.0/dbhome_1/jdk/jre/lib/rt.jar文件。
$ ls -lh /u01/app/oracle/product/21.0.0/dbhome_1/jdk/jre/lib/rt.jar
-rwxr-xr-x. 1 oracle oinstall 64M 2021-07-28 04:58:45 /u01/app/oracle/product/21.0.0/dbhome_1/jdk/jre/lib/rt.jar
SYS@book> shutdown immediate ;
Database closed.
Database dismounted.
ORACLE instance shut down.
--//改名qopiprep.bat。
$ cdf /u01/app/oracle/product/21.0.0/dbhome_1/QOpatch/qopiprep.bat
cd /u01/app/oracle/product/21.0.0/dbhome_1/QOpatch
$ mv qopiprep.bat qopiprep.bat.xxx
‘qopiprep.bat’ -> ‘qopiprep.bat.xxx’
--//再次重启数据库观察看看。
SYS@book> startup
ORACLE instance started.
Total System Global Area 805306280 bytes
Fixed Size 9691048 bytes
Variable Size 473956352 bytes
Database Buffers 314572800 bytes
Redo Buffers 7086080 bytes
Database mounted.
Database opened.
SYS@book> @ ashtop sid,event,p1,p1raw,p2raw,p3raw "EVENT='external table read'" &5min
no rows selected
--//可以发现问题消失。不过/u01/app/oracle/diag/rdbms/book/book/trace/book_mmon_5299.trc记录如下：
*** 2024-10-31T09:46:31.180918+08:00 (CDB$ROOT(1))
*** SESSION ID:(133.56630) 2024-10-31T09:46:31.180949+08:00
*** CLIENT ID:() 2024-10-31T09:46:31.180958+08:00
*** SERVICE NAME:(SYS$BACKGROUND) 2024-10-31T09:46:31.180965+08:00
*** MODULE NAME:() 2024-10-31T09:46:31.180975+08:00
*** ACTION NAME:() 2024-10-31T09:46:31.180982+08:00
*** CLIENT DRIVER:(SERVER) 2024-10-31T09:46:31.180989+08:00
*** CONTAINER ID:(1) 2024-10-31T09:46:31.180996+08:00
*** CONTAINER ID:(1) 2024-10-31T09:46:31.180996+08:00
: QPI: Obtaining lock SUCCESSFUL, qp_result=0 at : 31-OCT-24 09.46.31.178664000 AM +08:00
: QPI: Got lock get_opatch_lsinventory
: QPI: In opatch_run_job
: QPI: In sanity check..
: QPI: t_root is /u01/app/oracle/product/21.0.0/dbhome_1/
: QPI: t_orabase is /u01/app/oracle/homes/OraDB21Home1/
: QPI: t_op_inst_path is /u01/app/oracle/product/21.0.0/dbhome_1/OPatch/
: QPI: t_op_scpt_path is /u01/app/oracle/product/21.0.0/dbhome_1/QOpatch/
: QPI: t_op_log_path is /u01/app/oracle/homes/OraDB21Home1/rdbms/log/
: QPI: op_scpt_path :/u01/app/oracle/product/21.0.0/dbhome_1/QOpatchpos1
:
QPI: opatch file present, opatch
:
QPI: OPATCH_SCPT_DIR not present:/u01/app/oracle/product/21.0.0/dbhome_1/QOpatch
: QPI: Releasing lock SUCCESSFUL, qp_result=0 at : 31-OCT-24 09.46.31.235191000 AM +08:00
: QPI: in get_opatch_lsinventory, ERROR code -20013 : ORA-20013: DBMS_QOPATCH ran mostly in non install area
: QPI: Releasing lock FAILED, qp_result=4 at : 31-OCT-24 09.46.31.235326000 AM +08:00
Error in dbkgcroa_run_once_action-8: 20013, ORA-20013: DBMS_QOPATCH ran mostly in non install area
ORA-06512: at "SYS.DBMS_QOPATCH", line 2327
ORA-06512: at "SYS.DBMS_QOPATCH", line 854
ORA-06512: at "SYS.DBMS_QOPATCH", line 634
ORA-06512: at "SYS.DBMS_QOPATCH", line 2309
$ mv qopiprep.bat.xxx qopiprep.bat
‘qopiprep.bat.xxx’ -> ‘qopiprep.bat’
--//再次重启数据库观察看看。
SYS@book> @ ashtop sid,event,p1,p1raw,p2raw,p3raw "EVENT='external table read'" &5min
Total Distinct Distinct Distinct
Seconds AAS %This SID EVENT P1 P1RAW P2RAW P3RAW FIRST_SEEN LAST_SEEN Execs Seen Tstamps Execs Seen1
--------- ------- ------- ---------- ------------------- --------------------- ----------------- ----------------- ----------------- ------------------- ------------------- ---------- -------- -----------
1 .0 100% | 133 external table read 140261813977496 00007F913F990198 0000000000000000 0000000002FB0000 2024-10-31 09:45:00 2024-10-31 09:45:00 1 1 1
--//问题再现!!说明就是启动数据库时mmon进程执行/u01/app/oracle/product/21.0.0/dbhome_1/QOpatch/qopiprep.bat脚本导致的情况。
--//加上开机os没有加载这些文件，导致启动感觉有点慢。
--//我测试环境，感觉没必要每次启动都执行它，修改应该问题不大。
--//不知道oracle数据库启动执行这脚本做什么，执行1次不行吗？有可能给别人利用，干一些事情!!
--//如果建立一个空文件，mmon跟踪看到如下内容：
: QPI: Obtaining lock SUCCESSFUL, qp_result=0 at : 31-OCT-24 10.10.12.401347000 AM +08:00
: QPI: Got lock get_opatch_lsinventory
: QPI: In opatch_run_job
: QPI: In sanity check..
: QPI: t_root is /u01/app/oracle/product/21.0.0/dbhome_1/
: QPI: t_orabase is /u01/app/oracle/homes/OraDB21Home1/
: QPI: t_op_inst_path is /u01/app/oracle/product/21.0.0/dbhome_1/OPatch/
: QPI: t_op_scpt_path is /u01/app/oracle/product/21.0.0/dbhome_1/QOpatch/
: QPI: t_op_log_path is /u01/app/oracle/homes/OraDB21Home1/rdbms/log/
: QPI: op_scpt_path :/u01/app/oracle/product/21.0.0/dbhome_1/QOpatchpos1
:
QPI: opatch file present, opatch
:
QPI: qopiprep.bat file present
: QPI: In opatch_inv_refresh_job
: QPI: In REFRESH_OPATCH_DATA
*** 2024-10-31T10:10:12.742299+08:00 (CDB$ROOT(1))
: QPI: Latest xml inventory is loaded into table
: QPI: in get_opatch_lsinventory, ERROR code 100 : ORA-01403: no data found
: QPI: Releasing lock SUCCESSFUL, qp_result=0 at : 31-OCT-24 10.10.12.756129000 AM +08:00
--//建立如下文件：
$ cat aa.bat
DBSID=$ORACLE_SID
PD=$$
ORABASE=`$ORACLE_HOME/bin/orabasehome`
#rm -rf $ORABASE/rdbms/log/xml_file_${DBSID}_${PD}.xml
$ORACLE_HOME/OPatch/opatch lsinventory -customLogDir $ORABASE/rdbms/log -xml $ORABASE/rdbms/log/xml_file_${DBSID}_${PD}.xml -retry 0 -invPtrLoc $ORACLE_HOME/oraInst.loc >> $ORABASE/rdbms/log/stout_${DBSID}_${PD}.txt
$ source aa.bat
--//看看生成文件的内容。
$ $ORACLE_HOME/OPatch/opatch lsinventory -invPtrLoc $ORACLE_HOME/oraInst.loc
Oracle Interim Patch Installer version 12.2.0.1.26
Copyright (c) 2024, Oracle Corporation. All rights reserved.
Oracle Home : /u01/app/oracle/product/21.0.0/dbhome_1
Central Inventory : /u01/app/oraInventory
from : /u01/app/oracle/product/21.0.0/dbhome_1/oraInst.loc
OPatch version : 12.2.0.1.26
OUI version : 12.2.0.9.0
Log file location : /u01/app/oracle/product/21.0.0/dbhome_1/cfgtoollogs/opatch/opatch2024-10-31_10-20-25AM_1.log
Lsinventory Output file location : /u01/app/oracle/product/21.0.0/dbhome_1/cfgtoollogs/opatch/lsinv/lsinventory2024-10-31_10-20-25AM.txt
--------------------------------------------------------------------------------
Local Machine Information::
Hostname: centtest.com
ARU platform id: 226
ARU platform description:: Linux x86-64
Installed Top-level Products (1):
Oracle Database 21c 21.0.0.0.0
There are 1 products installed in this Oracle Home.
There are no Interim patches installed in this Oracle Home.
--------------------------------------------------------------------------------
OPatch succeeded.
$ $ORACLE_HOME/bin/orabasehome
/u01/app/oracle/homes/OraDB21Home1
--//-customLogDir $ORABASE/rdbms/log 会在目录留下/u01/app/oracle/homes/OraDB21Home1/rdbms/log/opatch留下相关记录。
来自 “ ITPUB博客 ” ，链接：https://blog.itpub.net/267265/viewspace-3044821/ ，如需转载，请注明出处，否则将追究法律责任。
最新文章
- [20261008]验证Shared Memory Segments key以及Semaphore Arrays Key(11g).txt
- [20261008]gdb引入结构体是否可行.txt
- [20261008]bpftrace定义结构体例子.txt
- [20261007]关于oracle sskgph2函数.txt
- [20261007]oracle Semaphore Arrays Key值的冲突.txt
- [20261004]oracle sskgph2函数等价c以及python脚本.txt
- [20261004]bpftrace查看oracle函数调用堆栈问题.txt
- [20261002]验证sskgphpjw函数参与运算的字符串是否存在规律.txt
- [20261002]oracle Semaphore Arrays Key值的计算2.txt
- [20261001]oracle Semaphore Arrays Key值的计算.txt
