[20240328]为什么找不到执行计划.txt
--//最近一直在优化生产系统监控sql语句,遇到一个无法解析的情况,记录下来.
1.环境:
SYS@192.168.100.235:1521/orcl> @ 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.235:1521/orcl> @ sqlhh 89u3urxj9zs1x .15
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
------------------- ---------- ------------- --------------- ---------- --------------- --------------- ------------- ------------- -------------- --------------- ----------- --------------- --------------- ---------------
2024-03-25 07:00:34 1 89u3urxj9zs1x 2280867756 7 31 31 10.0 0 0 0 0.0 0 0 0
2024-03-25 07:00:34 1 89u3urxj9zs1x 4173261031 6 4069 4058 10.0 150592 0 0 0.0 0 0 0
2024-03-25 08:00:38 1 89u3urxj9zs1x 2280867756 7 34 34 10.0 0 0 0 0.0 0 0 0
2024-03-25 08:00:38 1 89u3urxj9zs1x 4173261031 8 4755 4743 10.0 212289 0 0 0.0 0 0 0
2024-03-25 09:00:40 1 89u3urxj9zs1x 2280867756 8 33 32 10.0 0 0 0 0.0 0 0 0
2024-03-25 09:00:40 1 89u3urxj9zs1x 4173261031 10 5036 5032 10.0 236710 0 0 0.0 0 0 0
6 rows selected.
--//出现2个执行计划,从输出看可以发现其中1个执行很快,但是我看sql语句时出现疑惑,该语句不会执行很快,理论讲
--//PLAN_HASH_VALUE=2280867756不应该出现在dba_hist_sqlstat视图里面(LIOS_PER_EXEC=0)
SYS@192.168.100.235:1521/orcl> @ sql_id 89u3urxj9zs1x
--SQL_ID = 89u3urxj9zs1x
SELECT 'DISK_READ' ROWINFO
, disk_read.*
FROM (
SELECT DISK_READS
, EXECUTIONS
, ROUND(disk_reads / decode(executions, 0, 1, executions), 2) READS_PER_EXEC
, round(CPU_TIME/1000000, 2) CPU_TIME
, PARSING_SCHEMA_NAME
, LAST_ACTIVE_TIME
, SQL_ID
, SQL_FULLTEXT
FROM v$sqlarea
WHERE executions > 0
order by disk_reads desc) disk_read
WHERE rownum < 11;
--//这条语句不可能执行很快的.
3.分析:
--//看看0点的执行情况.
SYS@192.168.100.235:1521/orcl> @ ashtop to_char(sample_time,'hh24mi'),client_id,SQL_PLAN_HASH_VALUE sql_id='89u3urxj9zs1x' trunc(sysdate) trunc(sysdate)+1/24
Total Distinct Distinct Distinct
Seconds AAS %This TO_C CLIENT_ID SQL_PLAN_HASH_VALUE FIRST_SEEN LAST_SEEN Execs Seen Tstamps Execs Seen1
--------- ------- ------- ---- --------------- ------------------- ------------------- ------------------- ---------- -------- -----------
5 .0 17% | 0007 192.168.101.227 4173261031 2024-03-29 00:07:26 2024-03-29 00:07:30 1 5 1
5 .0 17% | 0057 192.168.101.217 4173261031 2024-03-29 00:57:39 2024-03-29 00:57:43 1 5 1
4 .0 13% | 0017 192.168.101.227 4173261031 2024-03-29 00:17:29 2024-03-29 00:17:32 1 4 1
4 .0 13% | 0027 192.168.101.227 4173261031 2024-03-29 00:27:30 2024-03-29 00:27:33 1 4 1
4 .0 13% | 0037 192.168.101.227 4173261031 2024-03-29 00:37:31 2024-03-29 00:37:34 1 4 1
4 .0 13% | 0047 192.168.101.227 4173261031 2024-03-29 00:47:34 2024-03-29 00:47:37 1 4 1
4 .0 13% | 0058 192.168.101.217 4173261031 2024-03-29 00:58:22 2024-03-29 00:58:25 1 4 1
7 rows selected.
--//噢,有两台机器同时做这类监控,再次重申我的观点,这类监控就是没用的东西.而且执行计划PLAN_HASH_VALUE=4173261031.
--//这就有点奇怪了.ashtop脚本查询来源是v$active_session_history视图.而前面的sqlhh查询来源 dba_hist_sqlstat视图.
--//理论dba_hist_sqlstat记录信息来源v$active_session_history,怎么会在dba_hist_sqlstat视图里出现其它PLAN_HASH_VALUE值呢.
SYS@192.168.100.235:1521/orcl> @ ashtop to_char(sample_time,'hh24mi'),client_id,SQL_PLAN_HASH_VALUE "sql_id='89u3urxj9zs1x' and client_id='192.168.101.217'" trunc(sysdate) trunc(sysdate)+1/24
Total Distinct Distinct Distinct
Seconds AAS %This TO_C CLIENT_ID SQL_PLAN_HASH_VALUE FIRST_SEEN LAST_SEEN Execs Seen Tstamps Execs Seen1
--------- ------- ------- ---- --------------- ------------------- ------------------- ------------------- ---------- -------- -----------
5 .0 56% | 0057 192.168.101.217 4173261031 2024-03-29 00:57:39 2024-03-29 00:57:43 1 5 1
4 .0 44% | 0058 192.168.101.217 4173261031 2024-03-29 00:58:22 2024-03-29 00:58:25 1 4 1
SYS@192.168.100.235:1521/orcl> @ ashtop to_char(sample_time,'hh24mi'),client_id,SQL_PLAN_HASH_VALUE "sql_id='89u3urxj9zs1x' and client_id='192.168.101.227'" trunc(sysdate) trunc(sysdate)+1/24
Total Distinct Distinct Distinct
Seconds AAS %This TO_C CLIENT_ID SQL_PLAN_HASH_VALUE FIRST_SEEN LAST_SEEN Execs Seen Tstamps Execs Seen1
--------- ------- ------- ---- --------------- ------------------- ------------------- ------------------- ---------- -------- -----------
5 .0 24% | 0007 192.168.101.227 4173261031 2024-03-29 00:07:26 2024-03-29 00:07:30 1 5 1
4 .0 19% | 0017 192.168.101.227 4173261031 2024-03-29 00:17:29 2024-03-29 00:17:32 1 4 1
4 .0 19% | 0027 192.168.101.227 4173261031 2024-03-29 00:27:30 2024-03-29 00:27:33 1 4 1
4 .0 19% | 0037 192.168.101.227 4173261031 2024-03-29 00:37:31 2024-03-29 00:37:34 1 4 1
4 .0 19% | 0047 192.168.101.227 4173261031 2024-03-29 00:47:34 2024-03-29 00:47:37 1 4 1
--//注:我看了一下两台IP的机器名都是localhost.localdomain,管理混乱,连机器起一个名字都没有做好.
--//我怀疑这两个IP是同一台主机.从时间间隔看"感觉"应该是10分钟做一次这样的查询.
SYS@192.168.100.235:1521/orcl> @ ashtop to_char(sample_time,'hh24:mi'),client_id,SQL_PLAN_HASH_VALUE "sql_id='89u3urxj9zs1x' " trunc(sysdate)+1/24 trunc(sysdate)+2/24
Total Distinct Distinct Distinct
Seconds AAS %This TO_CH CLIENT_ID SQL_PLAN_HASH_VALUE FIRST_SEEN LAST_SEEN Execs Seen Tstamps Execs Seen1
--------- ------- ------- ----- --------------- ------------------- ------------------- ------------------- ---------- -------- -----------
4 .0 11% | 01:08 192.168.101.227 4173261031 2024-03-29 01:08:16 2024-03-29 01:08:19 1 4 1
5 .0 14% | 01:18 192.168.101.227 4173261031 2024-03-29 01:18:16 2024-03-29 01:18:20 1 5 1
4 .0 11% | 01:28 192.168.101.217 4173261031 2024-03-29 01:28:24 2024-03-29 01:28:27 1 4 1
4 .0 11% | 01:29 192.168.101.217 4173261031 2024-03-29 01:29:07 2024-03-29 01:29:10 1 4 1
3 .0 8% | 01:38 192.168.101.217 4173261031 2024-03-29 01:38:27 2024-03-29 01:38:29 1 3 1
5 .0 14% | 01:39 192.168.101.217 4173261031 2024-03-29 01:39:08 2024-03-29 01:39:12 1 5 1
4 .0 11% | 01:48 192.168.101.217 4173261031 2024-03-29 01:48:29 2024-03-29 01:48:32 1 4 1
4 .0 11% | 01:49 192.168.101.217 4173261031 2024-03-29 01:49:10 2024-03-29 01:49:13 1 4 1
4 .0 11% | 01:58 192.168.101.227 4173261031 2024-03-29 01:58:32 2024-03-29 01:58:35 1 4 1
9 rows selected.
--//注:重新按照时间排列,不知道为什么中间的时间出现执行2次的情况,但是执行计划的PLAN_HASH_VALUE=4173261031.
--//不理解为什么执行次数会出现这样的情况.
SYS@192.168.100.235:1521/orcl> @ sqlhh 89u3urxj9zs1x 1
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
------------------- ---------- ------------- --------------- ---------- --------------- --------------- ------------- ------------- -------------- --------------- ----------- --------------- --------------- ---------------
...
2024-03-29 00:00:43 1 89u3urxj9zs1x 2280867756 8 38 37 10.0 0 0 0 0.0 0 0 0
2024-03-29 00:00:43 1 89u3urxj9zs1x 4173261031 7 4374 4367 10.0 195833 0 0 0.0 0 0 0
2024-03-29 01:00:46 1 89u3urxj9zs1x 2280867756 7 38 37 10.0 0 0 0 0.0 0 0 0
2024-03-29 01:00:46 1 89u3urxj9zs1x 4173261031 9 4174 4156 10.0 185793 0 0 0.0 0 0 0
2024-03-29 02:00:48 1 89u3urxj9zs1x 2280867756 7 39 37 10.0 0 0 0 0.0 0 0 0
2024-03-29 02:00:48 1 89u3urxj9zs1x 4173261031 9 4463 4455 10.0 195599 0 0 0.0 0 0 0
....
2024-03-29 07:00:01 1 89u3urxj9zs1x 4173261031 8 4051 4026 8.8 179319 0 0 0.0 0 0 0
46 rows selected.
--//0-1点记录8+7=15次,1-2点记录7+9=16次.是否可以理解执行快的v$active_session_history没有记录.
SYS@192.168.100.235:1521/orcl> @ dpcawr 89u3urxj9zs1x '' 2280867756
no rows selected
--//在awr里面根本没有相关记录,PLAN_HASH_VALUE=2280867756.
SYS@192.168.100.235:1521/orcl> @ dpcawr 89u3urxj9zs1x adaptive 4173261031
PLAN_TABLE_OUTPUT
--------------------
SQL_ID 89u3urxj9zs1x
--------------------
select 'DISK_READ' ROWINFO, disk_read.* from (select
DISK_READS,EXECUTIONS, ROUND(disk_reads / decode(executions, 0, 1,
executions),2) READS_PER_EXEC,round(CPU_TIME/1000000,2)
CPU_TIME,PARSING_SCHEMA_NAME,LAST_ACTIVE_TIME,SQL_ID,SQL_FULLTEXT from
v$sqlarea where executions > 0 order by disk_reads desc) disk_read
where rownum < 11
Plan hash value: 4173261031
----------------------------------------------------------------------------------------------------
| Id | Operation | Name | E-Rows |E-Bytes| Cost (%CPU)| E-Time |
----------------------------------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | | | 1 (100)| |
| 1 | COUNT STOPKEY | | | | | |
| 2 | VIEW | | 1 | 16519 | 1 (100)| 00:00:01 |
| 3 | SORT ORDER BY STOPKEY| | 1 | 16532 | 1 (100)| 00:00:01 |
| 4 | FIXED TABLE FULL | X$KGLCURSOR_CHILD_SQLID | 1 | 16532 | 0 (0)| |
----------------------------------------------------------------------------------------------------
Query Block Name / Object Alias (identified by operation id):
-------------------------------------------------------------
1 - SEL$1
2 - SEL$71D7A081 / DISK_READ@SEL$1
3 - SEL$71D7A081
4 - SEL$71D7A081 / X$KGLCURSOR_CHILD_SQLID@SEL$5
Note
-----
- Warning: basic plan statistics not available. These are only collected when:
* hint 'gather_plan_statistics' is used for the statement or
* parameter 'statistics_level' is set to 'ALL', at session or system level
--//仅仅存在PLAN_HASH_VALUE=4173261031的执行计划.
--//为什么出现这样的情况我无法解析.
--//顺便说一下这个版本的PLAN_HASH_VALUE计算与其它机器不同.
--//参考链接: https://blog.itpub.net/267265/viewspace-2922082/ =>[20221104]执行计划一样Plan hash value不同.txt
SYS@127.0.0.1:9015/ywdb> @ sqlhh 89u3urxj9zs1x .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
------------------- ---------- ------------- --------------- ---------- --------------- --------------- ------------- ------------- -------------- --------------- ----------- --------------- --------------- ---------------
2024-03-29 05:00:05 2 89u3urxj9zs1x 2280867756 6 1500 1440 10.0 0 0 0 0.0 0 0 0
2024-03-29 06:00:16 2 89u3urxj9zs1x 2280867756 6 1345 1308 10.0 0 0 0 0.0 0 0 0
2024-03-29 07:00:33 2 89u3urxj9zs1x 2280867756 6 1314 1235 10.0 0 0 0 0.0 0 0 0
2024-03-29 08:00:47 2 89u3urxj9zs1x 2280867756 6 1285 1269 10.0 0 0 0 0.0 0 0 0
--//其它机器看到PLAN_HASH_VALUE=2280867756.顺便说一个这样的监控基本没用,看看6次执行在实例2.看到实例2的执行情况,
--//根本没有考虑rac环境,这样的监控有什么用,拿来分析问题不是漏掉了实例1的情况吗?
--//扫描是v$sqlarea,这样的产品拿来买不是欺骗用户吗?
SYS@127.0.0.1:9014/ywdb> @ ashtop to_char(sample_time,'hh24:mi'),client_id sql_id='89u3urxj9zs1x' trunc(sysdate) trunc(sysdate)+1/24
Total Distinct Distinct Distinct
Seconds AAS %This TO_CH CLIENT_ID FIRST_SEEN LAST_SEEN Execs Seen Tstamps Execs Seen1
--------- ------- ------- ----- -------------- ------------------- ------------------- ---------- -------- -----------
2 .0 22% | 00:09 192.168.90.217 2024-03-29 00:09:14 2024-03-29 00:09:15 1 2 1
2 .0 22% | 00:19 192.168.90.217 2024-03-29 00:19:20 2024-03-29 00:19:21 1 2 1
2 .0 22% | 00:39 192.168.90.217 2024-03-29 00:39:15 2024-03-29 00:39:16 1 2 1
1 .0 11% | 00:29 192.168.90.217 2024-03-29 00:29:15 2024-03-29 00:29:15 1 1 1
1 .0 11% | 00:49 192.168.90.217 2024-03-29 00:49:16 2024-03-29 00:49:16 1 1 1
1 .0 11% | 00:59 192.168.90.217 2024-03-29 00:59:18 2024-03-29 00:59:18 1 1 1
6 rows selected.
--//其它机器执行都是6次,也许上面的主机是一台虚拟机器192.168.100.235,还是许多现象无法解析.
来自 “ ITPUB博客 ” ，链接：https://blog.itpub.net/267265/viewspace-3011593/ ，如需转载，请注明出处，否则将追究法律责任。
最新文章
- [20261008]验证Shared Memory Segments key以及Semaphore Arrays Key(11g).txt
- [20261008]gdb引入结构体是否可行.txt
- [20261008]bpftrace定义结构体例子.txt
- [20261007]关于oracle sskgph2函数.txt
- [20261007]oracle Semaphore Arrays Key值的冲突.txt
- [20261004]oracle sskgph2函数等价c以及python脚本.txt
- [20261004]bpftrace查看oracle函数调用堆栈问题.txt
- [20261002]验证sskgphpjw函数参与运算的字符串是否存在规律.txt
- [20261002]oracle Semaphore Arrays Key值的计算2.txt
- [20261001]oracle Semaphore Arrays Key值的计算.txt
