[20230426]奇怪的AVG_IOW_MS.txt

[20230426]奇怪的AVG_IOW_MS.txt --//昨天在例行检查时,发现一个奇怪现象,就是使用sqlhh.sql查询一条sql语句,遇到AVG_IOW_MS特别高的情况,看看怎么回事. 1.环境: SYS@192.168.100.237:1521/orcldg> @ pr ============================== PORT_STRING                   : x86_64/Linux 2.4.xx VERSION                       : 19.0.0.0.0 BANNER                        : Oracle Database 19c Enterprise Edition Release 19.0.0.0.0 - Production BANNER_FULL                   : Oracle Database 19c Enterprise Edition Release 19.0.0.0.0 - Production Version 19.3.0.0.0 BANNER_LEGACY                 : Oracle Database 19c Enterprise Edition Release 19.0.0.0.0 - Production CON_ID                        : 0 PL/SQL procedure successfully completed. 2.问题提出: SYS@192.168.100.237:1521/orcldg> @ sqlhh 623b841u978k2 0.2 time unit : millisecond BEGIN_INTERVAL_TIME    INST_ID SQL_ID        PLAN_HASH_VALUE EXECUTIONS ELA_MS_PER_EXEC CPU_MS_PER_EXEC ROWS_PER_EXEC LIOS_PER_EXEC BLKRD_PER_EXEC IOW_MS_PER_EXEC  AVG_IOW_MS CLW_MS_PER_EXEC APW_MS_PER_EXEC CCW_MS_PER_EXEC ------------------- ---------- ------------- --------------- ---------- --------------- --------------- ------------- ------------- -------------- --------------- ----------- --------------- --------------- --------------- 2023-04-26 08:00:54          1 623b841u978k2      1547877051       6152             213               9          46.6           641             30             206         6.9               0               0               0 2023-04-26 09:00:57          1 623b841u978k2      1547877051       8256             206               9          49.1           651             29             198     26400.7               0               0               0 2023-04-26 10:00:59          1 623b841u978k2      1547877051       9765             140               8          50.3           634             19             134        10.2               0               0               0 2023-04-26 11:00:02          1 623b841u978k2      1547877051       9291             104               6          46.9           581             15              98         9.6               0               0               0 --//AVG_IOW_MS=26400.7,这个也太大了. --//感觉这台虚拟机器磁盘IO也太慢了,ELA_MS_PER_EXEC,CPU_MS_PER_EXEC差距也太大了. --//难道是溢出了.检查看看. 3.分析: --//sqlhh.sql 读取的字段: ...   , ROUND(SUM(iowait_delta        ) / DECODE(SUM(physical_read_requests_delta)+SUM(physical_write_requests_delta),0,1                                             ,SUM(physical_read_requests_delta)+SUM(physical_write_requests_delta))/1000,1)  avg_iow_ms SELECT begin_interval_time      , iowait_delta      , physical_read_requests_delta      , physical_write_requests_delta      , iowait_total      , physical_read_requests_total      , physical_write_requests_total   FROM dba_hist_snapshot sn      , dba_hist_sqlstat st  WHERE sn.snap_id          =  st.snap_id    AND sn.dbid             =  st.dbid    AND sn.instance_number  =  st.instance_number    AND sql_id              =  '623b841u978k2'    AND begin_interval_time >= timestamp'2023-04-26 07:00:00'    AND begin_interval_time <= timestamp'2023-04-26 12:00:00'  ORDER BY 1; BEGIN_INTERVAL_TIME     IOWAIT_DELTA PHYSICAL_READ_REQUESTS_DELTA PHYSICAL_WRITE_REQUESTS_DELTA IOWAIT_TOTAL PHYSICAL_READ_REQUESTS_TOTAL PHYSICAL_WRITE_REQUESTS_TOTAL ----------------------- ------------ ---------------------------- ----------------------------- ------------ ---------------------------- ----------------------------- 2023-04-26 08:00:54.772   1264592303                       184021                             0  16944219225                      2502794                             0 2023-04-26 09:00:57.316   1636843131                           62                             0  18581062356                      2737916                             0 ~~~~~~~~~~~~~~~~~~~~~ 2023-04-26 10:00:59.792   1305841944                       128170                             0  19886342981                      2921310                             0 2023-04-26 11:00:02.321    910326952                        94430                             0  20796669933                      3057923                             0 --//很奇怪的现象,注意下划线这行,PHYSICAL_READ_REQUESTS_DELTA=62.注意看PHYSICAL_READ_REQUESTS_TOTAL,而实际应该是 2737916-2502794 = 235122 2921310-2737916 = 183394 3057923-2921310 = 136613 --//这些信息相差对不上PHYSICAL_READ_REQUESTS_DELTA信息.为什么,理论讲不会出现溢出的情况. --//再看看IOwait_ttotal列: 18581062356-16944219225 = 1636843131 19886342981-18581062356 = 1305280625 20796669933-19886342981 = 910326952 --//可以对上IOWAIT_DELTA列信息. --//1636843131/62/1000 = 26400.695,可以对应AVG_IOW_MS列信息.为什么出现这样的情况不理解. $ rlsql -s -l  sys/xxxx@192.168.100.237:1521/orcldg as sysdba <<< "@ sqlhh 623b841u978k2 100" | awk '{if ($13>15){print $0}}' BEGIN_INTERVAL_TIME    INST_ID SQL_ID        PLAN_HASH_VALUE EXECUTIONS ELA_MS_PER_EXEC CPU_MS_PER_EXEC ROWS_PER_EXEC LIOS_PER_EXEC BLKRD_PER_EXEC IOW_MS_PER_EXEC  AVG_IOW_MS CLW_MS_PER_EXEC APW_MS_PER_EXEC CCW_MS_PER_EXEC 2023-04-24 13:00:05          1 623b841u978k2      1547877051       4064              71               5          41.3           476             11              66      4179.5               0               0               0 2023-04-26 09:00:57          1 623b841u978k2      1547877051       8256             206               9          49.1           651             29             198     26400.7               0               0               0 --//仅仅出现2次. 4.总结: --//以后工作注意,执行sqlhh.sql看到一些异常大的数据,一要考虑溢出的情况,另外情况我自己无法解析.