[20260626]等待事件external table read.txt

--//很久以前就知道21c启动，要执行$ORACLE_HOME/QOpatch/qopiprep.bat的脚本，特别是第1次启动数据库，执行非常缓慢，需要13秒
--//完成,主要出现的external table read等待事件，以前做过探究，启动实例后由后台进程mmon完成。

--//尝试启动服务器centos 9，使用strace跟踪深入探究。

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.

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。

2.测试：
--//启动服务器，第1次启动实例。
SYS@book> startup mount
ORACLE instance started.
Total System Global Area 1157625848 bytes
Fixed Size                  9684984 bytes
Variable Size             704643072 bytes
Database Buffers          436207616 bytes
Redo Buffers                7090176 bytes
Database mounted.

SYS@book> @ bg mmon
ADDR                 PID SPID                           PROGRAM
---------------- ------- ------------------------------ --------------------------
000000007E57C5B0      29 207596                         oracle@centos9 (MMON)
--//记下进程号207596

$ strace -Ttt -y -f -p 207596 -e open,read 2>&1 | tee mmon.txt

SYS@book> alter database open ;
Database altered.
--//按ctrl+c中断strace的跟踪、

SYS@book> column p1 format 999999999999999
SYS@book> @ ashtop event,sid,p1,p1raw,p2raw,p3raw "EVENT='external table read'" sysdate-5/1440 sysdate
    Total                                                                                                                                                          Distinct Distinct    Distinct
  Seconds     AAS %This   EVENT               SID               P1 P1RAW             P2RAW             P3RAW             FIRST_SEEN          LAST_SEEN           Execs Seen  Tstamps Execs Seen1
--------- ------- ------- ------------------- --- ---------------- ----------------- ----------------- ----------------- ------------------- ------------------- ---------- -------- -----------
       17      .0  100% | external table read 105  139722146389968 00007F1398E71FD0  0000000000000000  0000000002FB0000  2026-06-26 09:06:23 2026-06-26 09:06:39          1       17           1
--//0x2FB0000  = 50003968 = 47.6875 MiB ,读取47.68M。整个执行时间17秒，打开了strace跟踪，导致时间比不开启strace要长一点。

SYS@book> @ usid 105
SYS@book> @ pr
==============================
U_USERNAME                    :
U_SID                         :  '105,30574'
U_AUDSID                      : 0
U_OSUSER                      : oracle
U_MACHINE                     : centos9
U_PROGRAM                     : (MMON)
U_SPID                        : 207596
U_PID                         : 29
CPID                          : 207596
SQL_ID                        :
USID_SQL_HASH_VALUE           : 0
LASTCALL                      : 570
STATUS                        : ACTIVE
SADDR                         : 000000007E7FF0B0
PADDR                         : 000000007E57C5B0
TADDR                         :
LOGON_TIME                    : 2026-06-26 09:02:49
TRACEFILE                     : /u01/app/oracle/diag/rdbms/book/book/trace/book_mmon_207596.trc
PL/SQL procedure successfully completed.
--//对应后台进程mmon。

3.分析跟踪文件：

$ grep qopiprep.bat mmon.txt
[pid 254199] 09:06:23.754320 read(3</u01/app/oracle/product/21.0.0/dbhome_1/QOpatch/qopiprep.bat>, "#!/bin/sh\n#\n# $Header: rdbms/src"..., 80) = 80 <0.000012>
[pid 254199] 09:06:23.754536 read(255</u01/app/oracle/product/21.0.0/dbhome_1/QOpatch/qopiprep.bat>, "#!/bin/sh\n#\n# $Header: rdbms/src"..., 3029) = 3029 <0.000011>
[pid 254199] 09:06:23.783538 read(255</u01/app/oracle/product/21.0.0/dbhome_1/QOpatch/qopiprep.bat>, "if [ $? -eq 0 ] ; then\n  LANG=\"$"..., 3029) = 1481 <0.000021>
[pid 254199] 09:06:23.896863 read(255</u01/app/oracle/product/21.0.0/dbhome_1/QOpatch/qopiprep.bat>, "\nrm -rf $ORABASE/rdbms/log/xml_f"..., 3029) = 695 <0.000023>
[pid 254199] 09:06:23.907546 read(255</u01/app/oracle/product/21.0.0/dbhome_1/QOpatch/qopiprep.bat>, "$ORACLE_HOME/OPatch/opatch lsinv"..., 3029) = 640 <0.000020>
[pid 254199] 09:06:40.332472 read(255</u01/app/oracle/product/21.0.0/dbhome_1/QOpatch/qopiprep.bat>, "RETVAL=$?;\nif [ $RETVAL -ne 0 ] "..., 3029) = 423 <0.000011>
[pid 254199] 09:06:40.375561 read(255</u01/app/oracle/product/21.0.0/dbhome_1/QOpatch/qopiprep.bat>, "\necho \"UIJSVTBOEIZBEFFQBL\";\n\nrm "..., 3029) = 132 <0.000011>
[pid 254199] 09:06:40.385739 read(255</u01/app/oracle/product/21.0.0/dbhome_1/QOpatch/qopiprep.bat>, "rm -f $ORABASE/rdbms/log/stout_$"..., 3029) = 50 <0.000010>
[pid 254199] 09:06:40.395851 read(255</u01/app/oracle/product/21.0.0/dbhome_1/QOpatch/qopiprep.bat>, "", 3029) = 0 <0.000008>
--//文件句柄发现变化。

--//取出读取次数最多的文件。"
$ grep " read(" mmon.txt | grep -o "</.*>,"  | sort | uniq -c | sort -nr | head -10
   5619 </u01/app/oracle/product/21.0.0/dbhome_1/jdk/jre/lib/rt.jar>,
    923 </u01/app/oracle/product/21.0.0/dbhome_1/jdk/jre/lib/amd64/libzip.so>,
    691 </u01/app/oracle/product/21.0.0/dbhome_1/OPatch/modules/com.sun.xml.bind.jaxb-impl.jar>,
    589 </u01/app/oracle/product/21.0.0/dbhome_1/OPatch/jlib/opatch.jar>,
    548 </u01/app/oracle/product/21.0.0/dbhome_1/oui/jlib/OraInstaller.jar>,
    246 </u01/app/oracle/product/21.0.0/dbhome_1/oui/jlib/xmlparserv2.jar>,
    237 </u01/app/oracle/product/21.0.0/dbhome_1/rdbms/mesg/kupus.msb>,
    181 </u01/app/oracle/product/21.0.0/dbhome_1/jdk/jre/lib/amd64/server/libjvm.so>,
    137 </u01/app/oracle/product/21.0.0/dbhome_1/OPatch/modules/com.sun.xml.bind.jaxb-core.jar>,
    100 </u01/app/oracle/product/21.0.0/dbhome_1/jdk/jre/lib/amd64/libjava.so>,

--//读取次数最多的主要集中在/u01/app/oracle/product/21.0.0/dbhome_1/jdk/jre/lib/rt.jar。

--//看看读取次数多靠前的文件大小。
 $ grep " read(" mmon.txt | grep -o "</.*>,"  | sort | uniq -c | sort -nr | head -10 | awk '{print $2}' | sed "s/<//;s/>,$//"| xargs  ls -lh --time-style=+"%Y-%m-%d %H:%M:%S"
-rwxr-xr-x. 1 oracle oinstall 227K 2021-07-28 04:58:45 /u01/app/oracle/product/21.0.0/dbhome_1/jdk/jre/lib/amd64/libjava.so
-rwxr-xr-x. 1 oracle oinstall 125K 2021-07-28 04:58:45 /u01/app/oracle/product/21.0.0/dbhome_1/jdk/jre/lib/amd64/libzip.so
-rwxr-xr-x. 1 oracle oinstall  17M 2021-07-28 04:58:45 /u01/app/oracle/product/21.0.0/dbhome_1/jdk/jre/lib/amd64/server/libjvm.so
-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
-rw-r-----. 1 oracle oinstall 3.0M 2021-06-04 21:15:06 /u01/app/oracle/product/21.0.0/dbhome_1/OPatch/jlib/opatch.jar
-rw-r-----. 1 oracle oinstall 250K 2019-09-19 18:53:56 /u01/app/oracle/product/21.0.0/dbhome_1/OPatch/modules/com.sun.xml.bind.jaxb-core.jar
-rw-r-----. 1 oracle oinstall 1.1M 2018-03-15 10:26:30 /u01/app/oracle/product/21.0.0/dbhome_1/OPatch/modules/com.sun.xml.bind.jaxb-impl.jar
-rw-r-----. 1 oracle oinstall 4.9M 2021-07-28 02:57:36 /u01/app/oracle/product/21.0.0/dbhome_1/oui/jlib/OraInstaller.jar
-rw-r-----. 1 oracle oinstall 1.9M 2021-07-06 13:48:00 /u01/app/oracle/product/21.0.0/dbhome_1/oui/jlib/xmlparserv2.jar
-rw-r--r--. 1 oracle oinstall  42K 2021-07-27 20:12:18 /u01/app/oracle/product/21.0.0/dbhome_1/rdbms/mesg/kupus.msb

--//看看这些操作那个花费时间多少。
$ grep "</u01/app/oracle/product/21.0.0/dbhome_1/jdk/jre/lib/rt.jar>" mmon.txt  | grep -o "<[0-9.]\+>$" | sed "s/<//;s/>//" | paste -sd+ | bc -l
6.372135
--//花费6.37秒。

$ grep " read(" mmon.txt | egrep -o "<[0-9.]+>$"  |  sed "s/<//;s/>//" | paste -sd+ | bc -l
9.362830
--//总的读取操作需要9.36秒

$ egrep -o "<[0-9.]+>$" mmon.txt |  sed "s/<//;s/>//" | paste -sd+ | bc -l
29.634375
--//总共需要29秒执行时间。前面的按ctrl+c，我有点慢，估计差5-6秒的时间。

--//查看/u01/app/oracle/diag/rdbms/book/book/trace/book_mmon_207596.trc:
*** 2026-06-26T09:06:19.295358+08:00 (CDB$ROOT(1))
*** SESSION ID:(105.30574) 2026-06-26T09:06:19.295700+08:00
*** CLIENT ID:() 2026-06-26T09:06:19.295982+08:00
*** SERVICE NAME:(SYS$BACKGROUND) 2026-06-26T09:06:19.296266+08:00
*** MODULE NAME:() 2026-06-26T09:06:19.296523+08:00
*** ACTION NAME:() 2026-06-26T09:06:19.296836+08:00
*** CLIENT DRIVER:(SERVER) 2026-06-26T09:06:19.297101+08:00
*** CONTAINER ID:(1) 2026-06-26T09:06:19.297364+08:00
*** CONTAINER ID:(1) 2026-06-26T09:06:19.297364+08:00

 : QPI: Obtaining lock SUCCESSFUL, qp_result=0 at : 26-JUN-26 09.06.19.171455000 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/
--//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

*** 2026-06-26T09:06:19.715287+08:00 (CDB$ROOT(1))
 :
QPI: opatch file present, opatch
 :
QPI: qopiprep.bat file present
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
 : QPI: In opatch_inv_refresh_job
 : QPI: In REFRESH_OPATCH_DATA

*** 2026-06-26T09:06:42.908886+08:00 (CDB$ROOT(1))
 : QPI: Latest xml inventory is loaded into table

*** 2026-06-26T09:06:43.799803+08:00 (CDB$ROOT(1))
 : QPI: Release lock get_opatch_lsinventory
 : QPI: Releasing lock SUCCESSFUL, qp_result=0 at : 26-JUN-26 09.06.43.800514000 AM +08:00

--//仔细阅读/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
--//不就是显示打了那些补丁吗?

--//直接执行看看输出什么内容：
$ $ORACLE_HOME/OPatch/opatch lsinventory
Oracle Interim Patch Installer version 12.2.0.1.26
Copyright (c) 2026, 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/opatch2026-06-26_09-56-01AM_1.log
Lsinventory Output file location : /u01/app/oracle/product/21.0.0/dbhome_1/cfgtoollogs/opatch/lsinv/lsinventory2026-06-26_09-56-01AM.txt
--------------------------------------------------------------------------------
Local Machine Information::
Hostname: centos9.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数据库启动执行这脚本做什么，执行1次不行吗？有可能给别人利用，干一些事情!!

--//说明就是启动数据库时mmon进程执行/u01/app/oracle/product/21.0.0/dbhome_1/QOpatch/qopiprep.bat脚本导致的情况。
--//加上开机os没有加载这些文件，导致启动感觉有点慢。
--//测试环境，感觉没必要每次启动都执行它，修改应该问题不大，可以改名，然后建立一个空文件。

--//注：执行完成后会在目录留下/u01/app/oracle/homes/OraDB21Home1/rdbms/log/opatch留下相关记录。
$ ll | tail -4
-rw-r-----. 1 oracle oinstall 3654 2026-06-25 09:13:04 opatch2026-06-25_09-13-03AM_1.log
-rw-r-----. 1 oracle oinstall 3653 2026-06-25 16:10:35 opatch2026-06-25_16-10-26PM_1.log
-rw-r-----. 1 oracle oinstall 3654 2026-06-26 09:06:40 opatch2026-06-26_09-06-32AM_1.log
-rw-r-----. 1 oracle oinstall 9729 2026-06-26 09:06:35 opatch_history.txt

4.测试改名操作看看：

$ cd /u01/app/oracle/product/21.0.0/dbhome_1/QOpatch
$ mv qopiprep.bat qopiprep.bat.xxx
$ touch  qopiprep.bat
$ chmod 754 qopiprep.bat
$ ll
total 4
-rwxr-xr--. 1 oracle oinstall    0 2026-06-26 10:47:53 qopiprep.bat
-rwxr-xr--. 1 oracle oinstall 3029 2026-06-26 10:47:37 qopiprep.bat.xxx

--//重新启动数据库看看：
SYS@book> @ ashtop event,sid,p1,p1raw,p2raw,p3raw "EVENT='external table read'" sysdate-15/1440 sysdate
no rows selected

--//看不到external table read等待事件。

--//查看mmon的跟踪文件：
*** 2026-06-26T10:49:41.988205+08:00 (CDB$ROOT(1))
*** SESSION ID:(302.32679) 2026-06-26T10:49:41.988226+08:00
*** CLIENT ID:() 2026-06-26T10:49:41.988235+08:00
*** SERVICE NAME:(SYS$BACKGROUND) 2026-06-26T10:49:41.988242+08:00
*** MODULE NAME:() 2026-06-26T10:49:41.988250+08:00
*** ACTION NAME:() 2026-06-26T10:49:41.988256+08:00
*** CLIENT DRIVER:(SERVER) 2026-06-26T10:49:41.988263+08:00
*** CONTAINER ID:(1) 2026-06-26T10:49:41.988270+08:00
*** CONTAINER ID:(1) 2026-06-26T10:49:41.988270+08:00

 : QPI: Obtaining lock SUCCESSFUL, qp_result=0 at : 26-JUN-26 10.49.41.985934000 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

*** 2026-06-26T10:49:42.677788+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 : 26-JUN-26 10.49.42.692856000 AM +08:00
--//有一个报错。QPI: in get_opatch_lsinventory, ERROR code 100 : ORA-01403: no data found

$ oerrz ora-100
00100, 00000, "no data found"
// *Cause: An application made reference to unknown or inaccessible data.
// *Action: Handle this condition within the application or make appropriate
//          modifications to the application code.
//             NOTE: If the application uses Oracle-mode SQL instead of
//             ANSI-mode SQL, ORA-01403 will be generated instead of ORA-00100.

 $ oerrz 1403
01403, 00000, "no data found"
// *Cause: No data was found from the objects.
// *Action: There was no data from the objects which may be due to end of fetch.

--//正常使用数据库没有任何问题。不过感觉第1次启动数据库还是很慢。

--//记录重启虚拟机后，启动数据库后的等待事件。
SYS@book> @ ashtop event 1=1 sysdate-15/1440 sysdate
    Total                                                                                        Distinct Distinct    Distinct
  Seconds     AAS %This   EVENT                        FIRST_SEEN          LAST_SEEN           Execs Seen  Tstamps Execs Seen1
--------- ------- ------- ---------------------------- ------------------- ------------------- ---------- -------- -----------
       66      .1   66% | db file sequential read      2026-06-26 15:41:29 2026-06-26 15:42:06         13       30          21
       18      .0   18% |                              2026-06-26 15:41:28 2026-06-26 15:42:38          4       15          13
        4      .0    4% | db file scattered read       2026-06-26 15:41:52 2026-06-26 15:41:54          2        3           2
        3      .0    3% | log file parallel write      2026-06-26 15:41:52 2026-06-26 15:42:06          1        2           2
        2      .0    2% | control file parallel write  2026-06-26 15:41:28 2026-06-26 15:41:31          1        2           2
        2      .0    2% | oracle thread bootstrap      2026-06-26 15:41:50 2026-06-26 15:42:06          1        2           2
        1      .0    1% | LGWR any worker group        2026-06-26 15:41:52 2026-06-26 15:41:52          1        1           1
        1      .0    1% | Parameter File I/O           2026-06-26 15:41:28 2026-06-26 15:41:28          1        1           1
        1      .0    1% | cursor: pin S wait on X      2026-06-26 15:41:50 2026-06-26 15:41:50          1        1           1
        1      .0    1% | direct path read             2026-06-26 15:42:35 2026-06-26 15:42:35          1        1           1
        1      .0    1% | read by other session        2026-06-26 15:42:06 2026-06-26 15:42:06          1        1           1
11 rows selected.