[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看到一些异常大的数据,一要考虑溢出的情况,另外情况我自己无法解析.