[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看到一些異常大的資料,一要考慮溢位的情況,另外情況我自己無法解析.

[20230426]奇怪的AVG_IOW_MS.txt

相關文章