[20231124]奇怪的高逻辑读4.txt
--//很长一段在生产系统看到一条逻辑读很高的sql语句,检查发现谓词使用了DBMS_LOB.SUBSTR函数.
--//开发真奇葩,我无论如何也想不出开发为什么这些写代码,当时脑子短路了,使用trunc还好理解一点.
--//我开始以为主要原因是lob类型导致fetch记录是1行1行提取,逻辑读提高,但是实测的效果要高出许多倍.当时没有继续探究,今天继续
--//探究看看,顺便尝试是否建立函数索引.
--//以前的测试链接:http://blog.itpub.net/267265/viewspace-2936071/=>[20230216]奇怪的高逻辑读3.txt.
1.环境:
SCOTT@book> @ 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.建立测试例子:
SCOTT@book> create table t as select * from all_objects where rownum <=100;
Table created.
--//分析略.
--//@ gts t '' ''
SCOTT@book> @ desc_proc sys dbms_lob substr
INPUT OWNER PACKAGE_NAME OBJECT_NAME
sample : @desc_proc sys dbms_stats gather_%_stats
OWNER PACKAGE_NAME OBJECT_NAME SEQUENCE ARGUMENT_NAME DATA_TYPE IN_OUT DEFAULTED
----- ------------ ----------- -------- ------------- --------- --------- ----------
SYS DBMS_LOB SUBSTR 1 RAW OUT N
2 LOB_LOC BLOB IN N
3 AMOUNT NUMBER IN Y
4 OFFSET NUMBER IN Y
1 VARCHAR2 OUT N
2 LOB_LOC CLOB IN N
3 AMOUNT NUMBER IN Y
4 OFFSET NUMBER IN Y
1 RAW OUT N
2 FILE_LOC BFILE IN N
3 AMOUNT NUMBER IN Y
4 OFFSET NUMBER IN Y
12 rows selected.
--//dbms_lob.substr函数参数与substr不一样,第2个参数AMOUNT表示取字符串的数量,第3个参数OFFSET表示字符串的偏移量.
--//注意最后一列DEFAULTED表明可以不输入第2,3参数(Y),不知道缺省怎么值.可以根据下面的执行推断offset缺省值=1.
--//注意返回数据类型支持raw,varchar2.
3.测试:
SCOTT@book> @ sl all
alter session set statistics_level = all;
Session altered.
SCOTT@book> select * from t where dbms_lob.substr(object_name)='DEPT';
no rows selected
SCOTT@book> @ dpc '' '' ''
PLAN_TABLE_OUTPUT
-------------------------------------
SQL_ID 7fybpwpmd0svt, child number 0
-------------------------------------
select * from t where dbms_lob.substr(object_name)='DEPT'
Plan hash value: 1601196873
--------------------------------------------------------------------------------------------------------------------
| Id | Operation | Name | Starts | E-Rows |E-Bytes| Cost (%CPU)| E-Time | A-Rows | A-Time | Buffers |
--------------------------------------------------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | 1 | | | 3 (100)| | 0 |00:00:00.02 | 1298 |
|* 1 | TABLE ACCESS FULL| T | 1 | 1 | 75 | 3 (0)| 00:00:01 | 0 |00:00:00.02 | 1298 |
--------------------------------------------------------------------------------------------------------------------
Query Block Name / Object Alias (identified by operation id):
-------------------------------------------------------------
1 - SEL$1 / T@SEL$1
Predicate Information (identified by operation id):
---------------------------------------------------
1 - filter("DBMS_LOB"."SUBSTR"(INTERNAL_FUNCTION("OBJECT_NAME"))='DEPT')
--//测试多次,最后稳定在1298逻辑读.
SCOTT@book> select * from t where dbms_lob.substr(object_name,30.0,1.0)='ICOL$';
SCOTT@book> @ pr
==============================
OWNER : SYS
OBJECT_NAME : ICOL$
SUBOBJECT_NAME :
OBJECT_ID : 20
DATA_OBJECT_ID : 2
OBJECT_TYPE : TABLE
CREATED : 2013-08-24 11:37:35
LAST_DDL_TIME : 2013-08-24 11:47:37
TIMESTAMP : 2013-08-24:11:37:35
STATUS : VALID
TEMPORARY : N
GENERATED : N
SECONDARY : N
NAMESPACE : 1
EDITION_NAME :
PL/SQL procedure successfully completed.
SCOTT@book> @ dpc '' '' ''
PLAN_TABLE_OUTPUT
-------------------------------------
SQL_ID baj2g6ratkpgq, child number 0
-------------------------------------
select * from t where dbms_lob.substr(object_name,30.0,1.0)='ICOL$'
Plan hash value: 1601196873
--------------------------------------------------------------------------------------------------------------------
| Id | Operation | Name | Starts | E-Rows |E-Bytes| Cost (%CPU)| E-Time | A-Rows | A-Time | Buffers |
--------------------------------------------------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | 1 | | | 3 (100)| | 1 |00:00:00.02 | 1299 |
|* 1 | TABLE ACCESS FULL| T | 1 | 1 | 75 | 3 (0)| 00:00:01 | 1 |00:00:00.02 | 1299 |
--------------------------------------------------------------------------------------------------------------------
Query Block Name / Object Alias (identified by operation id):
-------------------------------------------------------------
1 - SEL$1 / T@SEL$1
Predicate Information (identified by operation id):
---------------------------------------------------
1 - filter("DBMS_LOB"."SUBSTR"(INTERNAL_FUNCTION("OBJECT_NAME"),30,1)='ICOL$')
--//如果查询有返回值,逻辑读增加1个.
SCOTT@book> with a as (select /*+ materialize */ dbms_lob.substr(object_name) xx,t.* from t ) select * from a where a.xx='DEPT';
no rows selected
SCOTT@book> @ dpc '' '' ''
PLAN_TABLE_OUTPUT
-------------------------------------
SQL_ID 5x7x0rn7294bk, child number 0
-------------------------------------
with a as (select /*+ materialize */ dbms_lob.substr(object_name)
xx,t.* from t ) select * from a where a.xx='DEPT'
Plan hash value: 2328698527
-------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
| Id | Operation | Name | Starts | E-Rows |E-Bytes| Cost (%CPU)| E-Time | A-Rows | A-Time | Buffers | Reads | Writes | OMem | 1Mem | Used-Mem |
-------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | 1 | | | 5 (100)| | 0 |00:00:00.06 | 1315 | 2 | 2 | | | |
| 1 | TEMP TABLE TRANSFORMATION | | 1 | | | | | 0 |00:00:00.06 | 1315 | 2 | 2 | | | |
| 2 | LOAD AS SELECT | | 1 | | | | | 0 |00:00:00.06 | 1303 | 0 | 2 | 270K| 270K| 270K (0)|
| 3 | TABLE ACCESS FULL | T | 1 | 100 | 7500 | 3 (0)| 00:00:01 | 100 |00:00:00.01 | 3 | 0 | 0 | | | |
|* 4 | VIEW | | 1 | 100 | 210K| 2 (0)| 00:00:01 | 0 |00:00:00.01 | 6 | 2 | 0 | | | |
| 5 | TABLE ACCESS FULL | SYS_TEMP_0FD9D6603_17823151 | 1 | 100 | 7500 | 2 (0)| 00:00:01 | 100 |00:00:00.01 | 6 | 2 | 0 | | | |
-------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
Query Block Name / Object Alias (identified by operation id):
-------------------------------------------------------------
1 - SEL$2
2 - SEL$1
3 - SEL$1 / T@SEL$1
4 - SEL$D67CB2D2 / A@SEL$2
5 - SEL$D67CB2D2 / T1@SEL$D67CB2D2
Predicate Information (identified by operation id):
---------------------------------------------------
4 - filter("A"."XX"='DEPT')
4.继续:
--//但是如果执行如下:
select t.*,dbms_lob.substr(object_name) from t;
select t.* from t;
--//两者的逻辑读都是4.
SCOTT@book> @ dpc '' '' ''
PLAN_TABLE_OUTPUT
-------------------------------------
SQL_ID 9s1tjxvnfwkxj, child number 0
-------------------------------------
select t.* from t
Plan hash value: 1601196873
--------------------------------------------------------------------------------------------------------------------
| Id | Operation | Name | Starts | E-Rows |E-Bytes| Cost (%CPU)| E-Time | A-Rows | A-Time | Buffers |
--------------------------------------------------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | 1 | | | 3 (100)| | 100 |00:00:00.01 | 4 |
| 1 | TABLE ACCESS FULL| T | 1 | 100 | 7500 | 3 (0)| 00:00:01 | 100 |00:00:00.01 | 4 |
--------------------------------------------------------------------------------------------------------------------
Query Block Name / Object Alias (identified by operation id):
-------------------------------------------------------------
1 - SEL$1 / T@SEL$1
SCOTT@book> @ dpc '' '' ''
PLAN_TABLE_OUTPUT
-------------------------------------
SQL_ID gxspjy1yabrmp, child number 0
-------------------------------------
select t.*,dbms_lob.substr(object_name) from t
Plan hash value: 1601196873
--------------------------------------------------------------------------------------------------------------------
| Id | Operation | Name | Starts | E-Rows |E-Bytes| Cost (%CPU)| E-Time | A-Rows | A-Time | Buffers |
--------------------------------------------------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | 1 | | | 3 (100)| | 100 |00:00:00.01 | 4 |
| 1 | TABLE ACCESS FULL| T | 1 | 100 | 7500 | 3 (0)| 00:00:01 | 100 |00:00:00.01 | 4 |
--------------------------------------------------------------------------------------------------------------------
Query Block Name / Object Alias (identified by operation id):
-------------------------------------------------------------
1 - SEL$1 / T@SEL$1
--//这是我前面测试不能理解的地方,至少应该有一点点区别.难道这样的函数访问,在oracle的执行计划里面逻辑读不计数吗?
--//如果你看前面使用materialize也可以看出逻辑读不应该是这个数量.
5.尝试是否可以建立索引.
--//注意前面的过滤存在一个INTERNAL_FUNCTION.
1 - filter("DBMS_LOB"."SUBSTR"(INTERNAL_FUNCTION("OBJECT_NAME"))='DEPT')
SCOTT@book> create index if_t_object_name on t(DBMS_LOB.SUBSTR(OBJECT_NAME)) ;
Index created.
--//ok,索引可以建立!!
SCOTT@book> select * from t where dbms_lob.substr(object_name)='ICOL$';
SCOTT@book> @ dpc '' '' ''
PLAN_TABLE_OUTPUT
-------------------------------------
SQL_ID fxs2sk8mvtp5s, child number 0
-------------------------------------
select * from t where dbms_lob.substr(object_name)='ICOL$'
Plan hash value: 1757252843
------------------------------------------------------------------------------------------------------------------------------------------
| Id | Operation | Name | Starts | E-Rows |E-Bytes| Cost (%CPU)| E-Time | A-Rows | A-Time | Buffers |
------------------------------------------------------------------------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | 1 | | | 2 (100)| | 1 |00:00:00.01 | 3 |
| 1 | TABLE ACCESS BY INDEX ROWID| T | 1 | 1 | 75 | 2 (0)| 00:00:01 | 1 |00:00:00.01 | 3 |
|* 2 | INDEX RANGE SCAN | IF_T_OBJECT_NAME | 1 | 1 | | 1 (0)| 00:00:01 | 1 |00:00:00.01 | 2 |
------------------------------------------------------------------------------------------------------------------------------------------
Query Block Name / Object Alias (identified by operation id):
-------------------------------------------------------------
1 - SEL$1 / T@SEL$1
2 - SEL$1 / T@SEL$1
Predicate Information (identified by operation id):
---------------------------------------------------
2 - access("T"."SYS_NC00016$"='ICOL$')
--//很好,可以很好地使用我建立的函数索引.
6.继续分析看看为什么前面的逻辑读是4.
SCOTT@book> drop index IF_T_OBJECT_NAME;
Index dropped.
--//开启跟踪:
SCOTT@book> alter system set "_trace_pin_time"=1 scope=spfile;
System altered.
--//重启数据库略.
SCOTT@book> @ t
TRACEFILE
-------------------------------------------------------------
/u01/app/oracle/diag/rdbms/book/book/trace/book_ora_10291.trc
--//执行如下多次.
select t.*,dbms_lob.substr(object_name) from t;
select t.*,dbms_lob.substr(object_name) from t;
select t.*,dbms_lob.substr(object_name) from t;
$ >| /u01/app/oracle/diag/rdbms/book/book/trace/book_ora_10291.trc
select t.*,dbms_lob.substr(object_name) from t;
$ cp /u01/app/oracle/diag/rdbms/book/book/trace/book_ora_10291.trc 20231128.txt
$ head 20231128.txt
pin ktewh26: kteinpscan dba 0x100041a:4 time 1562795234
pin kdswh11: kdst_fetch dba 0x100041b:1 time 1562795764
pin ktswh102: ktsbvini dba 0x40ce80:4 time 1562795899
pin release 26 ktswh102: ktsbvini dba 0x40ce80:4
pin ktswh100: ktsbgsp dba 0x40ce81:12 time 1562795946
pin release 15 ktswh100: ktsbgsp dba 0x40ce81:12
pin ktswh133: ktsbvopn dba 0x40ce80:4 time 1562795976
pin release 14 ktswh133: ktsbvopn dba 0x40ce80:4
pin ktswh108: ktsbbsrch dba 0x40ce82:11 time 1562796006
pin release 28 ktswh108: ktsbbsrch dba 0x40ce82:11
$ awk '{print $2}' 20231128.txt | sort | uniq -c | sort -rn
1200 release
300 ktswh133:
200 ktswh102:
100 ktswh134:
100 ktswh123:
100 ktswh111:
100 ktswh110:
100 ktswh108:
100 ktswh100:
100 kdlwh01:
100 kdlwh00:
3 kdswh11:
1 ktewh26:
--//可以发现并不是不访问数据块,仅仅执行计划对于这类情况不计数罢了.
SCOTT@book> select min(rowid),max(rowid) from t;
MIN(ROWID) MAX(ROWID)
------------------ ------------------
AAAWe0AAEAAAAQbAAA AAAWe0AAEAAAAQcAAL
SCOTT@book> @ rowid AAAWe0AAEAAAAQbAAA
OBJECT FILE BLOCK ROW ROWID_DBA DBA TEXT
---------- ---------- ---------- ---------- -------------------- -------------------- ----------------------------------------
92084 4 1051 0 0x100041B 4,1051 alter system dump datafile 4 block 1051
SCOTT@book> @ rowid AAAWe0AAEAAAAQcAAL
OBJECT FILE BLOCK ROW ROWID_DBA DBA TEXT
---------- ---------- ---------- ---------- -------------------- -------------------- ----------------------------------------
92084 4 1052 11 0x100041C 4,1052 alter system dump datafile 4 block 1052
$ egrep "0x100041" 20231128.txt
pin ktewh26: kteinpscan dba 0x100041a:4 time 1562795234
pin kdswh11: kdst_fetch dba 0x100041b:1 time 1562795764
pin kdswh11: kdst_fetch dba 0x100041b:1 time 1562797381
pin kdswh11: kdst_fetch dba 0x100041c:1 time 1562844412
--//扫描表对应块0x100041a,0x100041b,0x100041c, 仅仅4次逻辑读.
$ grep "pin release" 20231128.txt | awk '{print $7}' | sort | uniq -c
600 0x40ce80:4
200 0x40ce81:12
300 0x40ce82:11
50 0x40ce83:1
50 0x40ce84:1
--//0x40ce80 = set dba 1,52864 = alter system dump datafile 1 block 52864 = 4247168
--//0x40ce84 = set dba 1,52868 = alter system dump datafile 1 block 52868 = 4247172
SYS@book> @ find_objz 1 52864 '' 1
SYS@book> @ pr
==============================
FILE_ID : 1
BLOCK_ID : 52480
BLOCKS : 1024
SEGMENT_TYPE : TABLE
OWNER : SYS
SEGMENT_NAME : IDL_UB1$
PARTITION_NAME :
EXTENT_ID : 89
BYTES : 8388608
TABLESPACE_NAME : SYSTEM
RELATIVE_FNO : 1
SEGTSN : 0
SEGRFN : 1
SEGBID : 1512
PL/SQL procedure successfully completed.
--//这次测试与前面的不同,访问的是SYS.IDL_UB1$.前面的测试如下,访问的是sys.ARGUMENT$.
--//以前的测试链接:http://blog.itpub.net/267265/viewspace-2936071/=>[20230216]奇怪的高逻辑读3.txt.
--//我再次重复前面的测试,不知道当时错误在那里,确实访问的是SYS.IDL_UB1$.
--//我甚至从冷备份恢复测试确实访问的是SYS.IDL_UB1$.
SYS@book> @ o2 sys.IDL_UB1$
SYS@book> @ pr
==============================
O_OWNER : SYS
O_OBJECT_NAME : IDL_UB1$
O_OBJECT_TYPE : TABLE
SEG_PART_NAME :
O_STATUS : VALID
OID : 225
D_OID : 225
CREATED : 2013-08-24 11:37:39
LAST_DDL_TIME : 2013-08-24 11:37:39
PL/SQL procedure successfully completed.
SCOTT@book> @ cr_rowid 225 1 52864 0
argument list : data_object_id file# block# row#
CREATE_ROWID
------------------
AAAADhAABAAAM6AAAA
SCOTT@book> @ cr_rowid 225 1 52868 800
argument list : data_object_id file# block# row#
CREATE_ROWID
------------------
AAAADhAABAAAM6EAMg
SCOTT@book> SELECT * FROM sys.idl_ub1$ WHERE ROWID BETWEEN 'AAAADhAABAAAM6AAAA' AND 'AAAADhAABAAAM6EAMg';
OBJ# PART VERSION PIECE# LENGTH P
---------- ---------- ---------- ---------- ---------- -
57638 1 0 0 38743 F
SCOTT@book> SELECT * FROM sys.idl_ub1$ WHERE DBMS_ROWID.ROWID_BLOCK_NUMBER(rowid) between 52864 and 52868;
OBJ# PART VERSION PIECE# LENGTH P
---------- ---------- ---------- ---------- ---------- -
57638 1 0 0 38743 F
SYS@book> @ desc sys.idl_ub1$
Name Null? Type
------------------------------- -------- ----------------------------
1 OBJ# NOT NULL NUMBER
2 PART NOT NULL NUMBER
3 VERSION NUMBER
4 PIECE# NOT NULL NUMBER
5 LENGTH NOT NULL NUMBER
6 PIECE NOT NULL LONG RAW
--//确实仅仅有1个对象，PIECE类型为long raw占用许多空间,38743/8000 = 4.8,占5块。
SYS@book> @ oid 57638
SYS@book> @ pr
==============================
O_OWNER : SYS
O_OBJECT_NAME : /a76131c0_XSLTErrorResources_e
O_OBJECT_TYPE : JAVA CLASS
SUBOBJECT_NAME :
CREATED : 2013-08-24 11:45:29
LAST_DDL_TIME : 2013-08-24 11:45:29
O_STATUS : VALID
DATA_OBJECT_ID :
OBJECT_ID : 57638
PL/SQL procedure successfully completed.
--//也就是调用DBMS_LOB.SUBSTR要访问oid=57638对象多次。
SCOTT@book> create index if_t_object_name on t(DBMS_LOB.SUBSTR(OBJECT_NAME)) ;
Index created.
select * from t where dbms_lob.substr(object_name)='ICOL$';
select * from t where dbms_lob.substr(object_name)='ICOL$';
select * from t where dbms_lob.substr(object_name)='ICOL$';
--//执行多次。
$ >| /u01/app/oracle/diag/rdbms/book/book/trace/book_ora_10698.trc
$ cp /u01/app/oracle/diag/rdbms/book/book/trace/book_ora_10698.trc 20231128a.txt
SCOTT@book> select * from t where dbms_lob.substr(object_name)='ICOL$';
...
$ egrep "dba 0x1000" 20231128a.txt
pin qeilwhrp: qeilbk dba 0x1000423:1 time 4238232606
pin kdswh05: kdsgrp dba 0x100041b:1 time 4238232706
pin kdiwh16: kdifxs dba 0x1000423:1 time 4238233321
--//0x1000423 应该访问的索引数据块.
$ egrep "dba " 20231128a.txt
pin qeilwhrp: qeilbk dba 0x1000423:1 time 4238232606
pin kdswh05: kdsgrp dba 0x100041b:1 time 4238232706
pin kdiwh16: kdifxs dba 0x1000423:1 time 4238233321
--//完全看不到dba 0x40ce8X的访问。
7.收尾：
SCOTT@book> alter system reset "_trace_pin_time";
System altered.
--//重启略。
> @ ashtable d DBMS_LOB.SUBSTR 1=1 &day
@ tpt/dashtop sql_id,module "1=1 and sql_id in (select sql_id from v$sqlarea where lower(sql_fulltext) like lower('%DBMS_LOB.SUBSTR%'))" sysdate-1 sysdate
Total
Seconds AAS %This SQL_ID MODULE FIRST_SEEN LAST_SEEN
--------- ------- ------- ------------- ------------------------------ ------------------- -------------------
2200 .0 55% 18vdbxnv6kt3f uwsgi@YDHL_100212 (TNS V1-V3) 2023-11-27 15:08:21 2023-11-28 10:47:19
1810 .0 45% df54kmrg2yz8t uwsgi@YDHL_100212 (TNS V1-V3) 2023-11-27 11:50:06 2023-11-28 10:57:40
> @ sql_id 18vdbxnv6kt3f
--SQL_ID = 18vdbxnv6kt3f
SELECT "V_YDHL_EMPLOYEES"."ORGAN_CODE"
, "V_YDHL_EMPLOYEES"."ID"
, "V_YDHL_EMPLOYEES"."USER_NAME"
, "V_YDHL_EMPLOYEES"."PASSWORD"
, "V_YDHL_EMPLOYEES"."USER_CODE"
, "V_YDHL_EMPLOYEES"."STAFF_NAME"
, "V_YDHL_EMPLOYEES"."PHONE"
, "V_YDHL_EMPLOYEES"."USER_TYPE"
, "V_YDHL_EMPLOYEES"."IS_VALID"
, "V_YDHL_EMPLOYEES"."IS_ADMIN"
, "V_YDHL_EMPLOYEES"."SIGNATURE"
, "V_YDHL_EMPLOYEES"."AUTH"
FROM "V_YDHL_EMPLOYEES"
WHERE DBMS_LOB.SUBSTR("V_YDHL_EMPLOYEES"."USER_NAME") = :arg0;
> @ bind_cap 18vdbxnv6kt3f ''
SQL_ID CHILD_NUMBER WAS NAME POSITION MAX_LENGTH LAST_CAPTURED DATATYPE_STRING VALUE_STRING
------------- ------------ --- ------ -------- ---------- ------------------- --------------- --------------
18vdbxnv6kt3f 0 YES :ARG0 1 128 2023-11-28 00:27:16 VARCHAR2(128) 5621
1 YES :ARG0 1 32 2023-11-28 04:59:51 VARCHAR2(32) 4560
2 YES :ARG0 1 128 2023-11-28 11:44:36 VARCHAR2(128) 1876
--//感觉开发写的有问题,USER_NAME应该类似名字,而查询输入的确实员工代码.
--//我仅仅想说写成这样的代码人不知道那个学校毕业的,实在想不出为什么这样写sql语句。