[20240410]奇怪的逻辑读.txt
--//生产系统优化遇到奇怪的执行情况,搞不懂为什么?探究看看.
1.环境:
SYS@127.0.0.1:9014/ywdb> @ver1
PORT_STRING VERSION BANNER
------------------------------ -------------- --------------------------------------------------------------------------------
x86_64/Linux 2.4.xx 11.2.0.4.0 Oracle Database 11g Enterprise Edition Release 11.2.0.4.0 - 64bit Production
2.问题分析:
SYS@127.0.0.1:9014/ywdb> @ fms 5 10 &day
FORCE_MATCHING_SIGNATURE SQL_ID_COUNT TOTAL_SECONDS
------------------------ ------------ -------------
8680396602758190538 1400 1722
13026426528625086727 774 1169
6490285911540139840 277 320
12120531484079936454 275 289
8968795636694904691 148 252
16302384038956377077 200 225
15582081887848190096 134 184
13723358513528852507 92 160
7809763007758332172 143 159
10224702229797097847 45 67
10 rows selected.
--//fms脚本用来查询gv$active_session_history记录FORCE_MATCHING_SIGNATURE相同sql_id不同的sql语句.
SYS@127.0.0.1:9014/ywdb> @ ffms 8680396602758190538 10
C200
--------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
select a.ksdm,a.jgid,a.ksmc,b.act from ms_ghks a,(select count(1) as act,ksdm,jgid from (SELECT MS_YYHY.HYID, to_char(MS_YYHY.GZRQ,'yyyymmdd') GZRQ ,MS_YYHY.YYSD, MS_GHKS.KSMC, MS_YYHY.KSDM, GY_YGDM
.YGXM, MS_YYHY.YSDM, MS_YYHY.YYBZ,MS_MZGHF.GHF,MS_MZGHF.ZLF,MS_GHKS.JGID FROM MS_YYHY,MS_GHKS,GY_YGDM,MS_YSKS,MS_MZGHF
WHERE MS_YYHY.KSDM = MS_GHKS.KSDM AND MS_YYHY.YSDM = GY_YGDM.YGDM AND MS_YSKS.Mzks = MS_YYHY.KSDM AND MS_YSKS.YSDM = GY_YGDM.YGDM AND MS_YSKS.FYXH = MS_MZGHF.FYXH AND MS_YYHY.T
GBZ = 0 AND MS_YYHY.YYBZ = 0 AND MS_YYHY.NWBZ = 1 AND MS_YYHY.GZRQ = to_date('20240413','yyyymmdd') And MS_YYHY.YSDM='5729'AND MS_GHKS.KSDM =273) group by ksdm,jgid) b where a.ksdm=b.ksdm and a.jgid=b
.jgid and a.ksdm =273 order by a.jgid
time unit : microsecond
SQL_ID CHILD_NUMBER INST_ID FIRST_LOAD_TIME BUFFER_GETS EXECUTIONS ROWS_PROCESSED ELAPSED_TIME AVG_ELA_TIME PLAN_HASH_VALUE LIOS_PER_EXEC
------------- ------------ ---------- ------------------- ----------- ---------- -------------- ------------ ------------ --------------- -------------
a2d7vmm3wtgvc 0 2 2024-04-10/10:05:14 231 1 0 61472 61472 1874477375 231
7f7kuqqd1z2zp 0 2 2024-04-10/10:05:14 231 1 0 60417 60417 1874477375 231
839152ckx6c48 0 2 2024-04-10/10:05:14 231 1 0 63390 63390 1874477375 231
5ka1w8x55q2yd 0 2 2024-04-10/10:05:13 231 1 0 66518 66518 1874477375 231
9v26k2ftumjqn 0 1 2024-04-10/10:05:13 231 1 0 64188 64188 1874477375 231
87r0x9fna7frj 0 2 2024-04-10/10:05:13 231 1 0 60880 60880 1874477375 231
gwtzpbubyaua2 0 2 2024-04-10/10:05:13 231 1 0 89278 89278 1874477375 231
765qr5schjdwh 0 2 2024-04-10/10:04:51 231 1 0 78078 78078 1874477375 231
86b5n8jdb72n0 0 1 2024-04-10/10:04:44 231 1 0 71647 71647 1874477375 231
6tc2gf72wz9jx 0 1 2024-04-10/10:04:44 231 1 0 49302 49302 1874477375 231
10 rows selected.
--//ffms.sql脚本用来查询gv$sql看看FORCE_MATCHING_SIGNATURE=8680396602758190538有那些,参数2显示数量.前面查询的sql语句仅仅
--//显示1条作为参考.
--//你可以发现1个现象,ROWS_PROCESSED=0.逻辑读231.并且执行次数基本都是1,扩大查询范围也是一样,而我手工执行逻辑读都是1(即使
--//我修改sql语句,做硬解析):
Plan hash value: 1874477375
----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
| Id | Operation | Name | Starts | E-Rows |E-Bytes| Cost (%CPU)| E-Time | A-Rows | A-Time | Buffers | OMem | 1Mem | Used-Mem |
----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | 1 | | | 7 (100)| | 0 |00:00:00.01 | 1 | | | |
| 1 | NESTED LOOPS | | 1 | 1 | 68 | 7 (15)| 00:00:01 | 0 |00:00:00.01 | 1 | | | |
| 2 | VIEW | | 1 | 1 | 28 | 6 (17)| 00:00:01 | 0 |00:00:00.01 | 1 | | | |
| 3 | HASH GROUP BY | | 1 | 1 | 44 | 6 (17)| 00:00:01 | 0 |00:00:00.01 | 1 | 983K| 983K| |
| 4 | NESTED LOOPS | | 1 | 1 | 44 | 6 (17)| 00:00:01 | 0 |00:00:00.01 | 1 | | | |
| 5 | NESTED LOOPS | | 1 | 1 | 41 | 6 (17)| 00:00:01 | 0 |00:00:00.01 | 1 | | | |
| 6 | NESTED LOOPS | | 1 | 1 | 29 | 5 (20)| 00:00:01 | 0 |00:00:00.01 | 1 | | | |
| 7 | VIEW | VW_GBF_32 | 1 | 1 | 24 | 5 (20)| 00:00:01 | 0 |00:00:00.01 | 1 | | | |
| 8 | HASH GROUP BY | | 1 | 1 | 46 | 5 (20)| 00:00:01 | 0 |00:00:00.01 | 1 | 964K| 964K| |
| 9 | NESTED LOOPS | | 1 | 1 | 46 | 4 (0)| 00:00:01 | 0 |00:00:00.01 | 1 | | | |
| 10 | NESTED LOOPS | | 1 | 2 | 46 | 4 (0)| 00:00:01 | 0 |00:00:00.01 | 1 | | | |
| 11 | TABLE ACCESS BY INDEX ROWID| MS_GHKS | 1 | 1 | 20 | 1 (0)| 00:00:01 | 0 |00:00:00.01 | 1 | | | |
|* 12 | INDEX RANGE SCAN | I_MS_GHKS_KSDM | 1 | 1 | | 1 (0)| 00:00:01 | 0 |00:00:00.01 | 1 | | | |
|* 13 | INDEX RANGE SCAN | I_MS_YYHY_GZRQ_YSDM | 0 | 2 | | 2 (0)| 00:00:01 | 0 |00:00:00.01 | 0 | | | |
|* 14 | TABLE ACCESS BY INDEX ROWID | MS_YYHY | 0 | 1 | 26 | 3 (0)| 00:00:01 | 0 |00:00:00.01 | 0 | | | |
|* 15 | INDEX UNIQUE SCAN | PK_GY_YGDM | 0 | 1 | 5 | 0 (0)| | 0 |00:00:00.01 | 0 | | | |
| 16 | TABLE ACCESS BY INDEX ROWID | MS_YSKS | 0 | 1 | 12 | 1 (0)| 00:00:01 | 0 |00:00:00.01 | 0 | | | |
|* 17 | INDEX UNIQUE SCAN | I_MS_YSKS_MZKS_YSDM | 0 | 1 | | 0 (0)| | 0 |00:00:00.01 | 0 | | | |
|* 18 | INDEX UNIQUE SCAN | PK_MS_MZGHF | 0 | 1 | 3 | 0 (0)| | 0 |00:00:00.01 | 0 | | | |
|* 19 | TABLE ACCESS BY INDEX ROWID | MS_GHKS | 0 | 1 | 40 | 1 (0)| 00:00:01 | 0 |00:00:00.01 | 0 | | | |
|* 20 | INDEX RANGE SCAN | I_MS_GHKS_KSDM | 0 | 1 | | 0 (0)| | 0 |00:00:00.01 | 0 | | | |
----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
--//逻辑读是1.难道第1次执行许多递归的逻辑读都要计入该语句中吗?
--//我使用set autotrace traceonly跟踪.适当修改sql语句,修改一个字符从大写变成小写,这样重新做1次硬分析.
SYS@127.0.0.1:9014/ywdb> @ gzbpf991tzmtr.sql9_0
PL/SQL procedure successfully completed.
Session altered.
Session altered.
no rows selected
Execution Plan
----------------------------------------------------------
Plan hash value: 1874477375
-------------------------------------------------------------------------------------------------------------
| Id | Operation | Name | Rows | Bytes | Cost (%CPU)| Time |
-------------------------------------------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | 1 | 68 | 7 (15)| 00:00:01 |
| 1 | NESTED LOOPS | | 1 | 68 | 7 (15)| 00:00:01 |
| 2 | VIEW | | 1 | 28 | 6 (17)| 00:00:01 |
| 3 | HASH GROUP BY | | 1 | 44 | 6 (17)| 00:00:01 |
| 4 | NESTED LOOPS | | 1 | 44 | 6 (17)| 00:00:01 |
| 5 | NESTED LOOPS | | 1 | 41 | 6 (17)| 00:00:01 |
| 6 | NESTED LOOPS | | 1 | 29 | 5 (20)| 00:00:01 |
| 7 | VIEW | VW_GBF_32 | 1 | 24 | 5 (20)| 00:00:01 |
| 8 | HASH GROUP BY | | 1 | 46 | 5 (20)| 00:00:01 |
| 9 | NESTED LOOPS | | 1 | 46 | 4 (0)| 00:00:01 |
| 10 | NESTED LOOPS | | 2 | 46 | 4 (0)| 00:00:01 |
| 11 | TABLE ACCESS BY INDEX ROWID| MS_GHKS | 1 | 20 | 1 (0)| 00:00:01 |
|* 12 | INDEX RANGE SCAN | I_MS_GHKS_KSDM | 1 | | 1 (0)| 00:00:01 |
|* 13 | INDEX RANGE SCAN | I_MS_YYHY_GZRQ_YSDM | 2 | | 2 (0)| 00:00:01 |
|* 14 | TABLE ACCESS BY INDEX ROWID | MS_YYHY | 1 | 26 | 3 (0)| 00:00:01 |
|* 15 | INDEX UNIQUE SCAN | PK_GY_YGDM | 1 | 5 | 0 (0)| 00:00:01 |
| 16 | TABLE ACCESS BY INDEX ROWID | MS_YSKS | 1 | 12 | 1 (0)| 00:00:01 |
|* 17 | INDEX UNIQUE SCAN | I_MS_YSKS_MZKS_YSDM | 1 | | 0 (0)| 00:00:01 |
|* 18 | INDEX UNIQUE SCAN | PK_MS_MZGHF | 1 | 3 | 0 (0)| 00:00:01 |
|* 19 | TABLE ACCESS BY INDEX ROWID | MS_GHKS | 1 | 40 | 1 (0)| 00:00:01 |
|* 20 | INDEX RANGE SCAN | I_MS_GHKS_KSDM | 1 | | 0 (0)| 00:00:01 |
-------------------------------------------------------------------------------------------------------------
Predicate Information (identified by operation id):
---------------------------------------------------
12 - access(TO_NUMBER("KSDM")=75)
13 - access("MS_YYHY"."GZRQ"=TO_DATE(' 2024-04-11 00:00:00', 'syyyy-mm-dd hh24:mi:ss') AND
"MS_YYHY"."YSDM"='650')
14 - filter(TO_NUMBER("MS_YYHY"."KSDM")=75 AND "MS_YYHY"."KSDM"="MS_GHKS"."KSDM")
15 - access("ITEM_2"="GY_YGDM"."YGDM")
17 - access("MS_YSKS"."MZKS"="ITEM_1" AND "MS_YSKS"."YSDM"="GY_YGDM"."YGDM")
18 - access("MS_YSKS"."FYXH"="MS_MZGHF"."FYXH")
19 - filter("A"."JGID" IS NOT NULL AND "A"."JGID"="B"."JGID")
20 - access(TO_NUMBER("KSDM")=75)
Statistics
----------------------------------------------------------
806 recursive calls
0 db block gets
231 consistent gets
0 physical reads
0 redo size
529 bytes sent via SQL*Net to client
509 bytes received via SQL*Net from client
1 SQL*Net roundtrips to/from client
0 sorts (memory)
0 sorts (disk)
0 rows processed
--//确实是consistent gets=231,看看硬分析导致806次递规调用.开发应该重视合理地使用绑定变量.
--//第2次执行,逻辑读就是1.
Statistics
----------------------------------------------------------
0 recursive calls
0 db block gets
1 consistent gets
0 physical reads
0 redo size
529 bytes sent via SQL*Net to client
509 bytes received via SQL*Net from client
1 SQL*Net roundtrips to/from client
0 sorts (memory)
0 sorts (disk)
0 rows processed
--//再次看出没有使用绑定变量带来问题.
--//另外一点注意的地方是在会话设置statistics_level=all,看执行计划的逻辑读并没有把一些递归执行的逻辑读记入.
--//实际上如果看出有执行多次就很容易发现这个细节问题:
SYS@127.0.0.1:9014/ywdb> @ ffms 8680396602758190538 200
SQL_ID CHILD_NUMBER INST_ID FIRST_LOAD_TIME PLAN_HASH_VALUE ELAPSED_TIME EXECUTIONS BUFFER_GETS ROWS_PROCESSED LIOS_PER_EXEC ROWS_PER_EXEC AVG_ELA_TIME
------------- ------------ ---------- -------------------- --------------- ------------ ---------- ----------- -------------- ------------- ------------- ------------
...
1yht54qu3rpuy 0 2 2024-04-10/10:30:28 1874477375 66895 1 231 0 231 0 66895
88xpu4vgq7h3s 0 2 2024-04-10/10:30:28 1874477375 113700 2 232 0 116 0 56850
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
373a3r0sbhfbc 0 2 2024-04-10/10:30:25 1874477375 74739 1 235 0 235 0 74739
g0rj4kuhv7x65 0 2 2024-04-10/10:30:25 1874477375 60312 1 235 0 235 0 60312
f002tj5fjbv0a 0 1 2024-04-10/10:30:25 1874477375 79006 1 235 0 235 0 79006
5x4mqfw7vuphh 0 1 2024-04-10/10:30:25 1874477375 118722 2 240 0 120 0 59361
200 rows selected.
3.附上相关脚本:
$ cat fms.sql
-- Copyright 2023 lfree. All rights reserved.
-- Licensed under the Apache License, Version 2.0. See LICENSE.txt for terms and conditions.
--------------------------------------------------------------------------------
--
-- File name: fms.sql v1.0
-- Purpose: Query gv$active_session_history Force_Matching_Signature the same, sql_id different of information
-- Author: lfree
--
-- Usage:
-- @ fms <count(*)_number> <display_record_number> <fromtime> <totime>
-- <count(*)_number>=2>
--
-- Example:
-- @ fms 5 30 &day
--
-- Other:
-- This script uses only the in-memory GV$ACTIVE_SESSION_HISTORY, use
-- @dfms.sql for accessiong the DBA_HIST_ACTIVE_SESS_HISTORY archive
--
--------------------------------------------------------------------------------
WITH a1 AS (SELECT sql_id,force_matching_signature, count(*) cnt1
FROM gv$active_session_history
WHERE force_matching_signature <> 0 AND sample_time BETWEEN &3 AND &4 and sql_opname<>'INSERT'
GROUP BY sql_id, force_matching_signature ) ,
a2 AS (SELECT force_matching_signature, count(*) sql_id_count,sum(cnt1) total_seconds
FROM a1
GROUP BY force_matching_signature
HAVING count(*) >= &&1
ORDER BY 3 desc)
SELECT force_matching_signature, sql_id_count,total_seconds
FROM a2
WHERE rownum <= &2;
--//显示字段顺序做了一些调整.
$ cat ffms.sql
-- Copyright 2023 lfree. All rights reserved.
-- Licensed under the Apache License, Version 2.0. See LICENSE.txt for terms and conditions.
--------------------------------------------------------------------------------
--
-- File name: ffms.sql
-- Purpose: find force_matching_signature from gv$sql
--
-- Author: lfree
--
-- Usage:
-- @ ffms FORCE_MATCHING_SIGNATURE <display_record_number>
--
--------------------------------------------------------------------------------
SELECT REPLACE (sql_fulltext, CHR (13), '') c200
FROM gv$sqlarea
WHERE FORCE_MATCHING_SIGNATURE = &&1 AND ROWNUM = 1;
prompt
prompt time unit : microsecond
prompt
column FIRST_LOAD_TIME format a20
SELECT *
FROM ( SELECT sql_id
,child_number
,inst_id
,first_load_time
,plan_hash_value
,elapsed_time
,executions
,buffer_gets
,rows_processed
,ROUND (buffer_gets / nullif(executions,0),2) lios_per_exec
,ROUND (rows_processed / nullif(executions,0),2) rows_per_exec
,ROUND (elapsed_time / nullif(executions,0),2) avg_ela_time
FROM gv$sql
WHERE FORCE_MATCHING_SIGNATURE = &&1
ORDER BY 4 DESC)
WHERE ROWNUM <= &&2;
来自 “ ITPUB博客 ” ，链接：https://blog.itpub.net/267265/viewspace-3013373/ ，如需转载，请注明出处，否则将追究法律责任。
最新文章
- [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
