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

来源:这里教程网 时间:2026-03-03 20:54:48 作者:

[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留下相关记录。

相关推荐