Oracle blob字段"direct path read"案例解析
一、背景
某项目RAC集群IO负载较高，物理读IO居高不下。在经过优化后，数据库负载以及物理IO已大幅下降，但是其中有条SQL时不时的就会运行并且是"direct path read"等待事件，下面就围绕此场景案例等待事件做一个深度追踪。
二、总体概况
优化前的数据库负载以及IO
优化后的数据库负载以及IO消耗已大幅下降
在做小范围监控时，红框sql执行频率较高，并且有一部分IO性能上的消耗，这回成功的吸引了我的注意力！
根据sql_id获取sqltext之后查看执行计划
SQL> set autotrace on;
SQL> select u.USERGUID,
2 w.WINDOWNAME,
3 u.USERNAME,
4 w.WINDOWNO,
5 w.OUGUID,
6 u.workstatus,
7 b.piccontent,
8 b.picContentType
9 from AUDIT_WINDOW_USER u
10 INNER JOIN AUDIT_WINDOW w
11 on w.RowGuid = u.WINDOWGUID
12 inner join Frame_User_ExtendInfo b
13 on u.userguid = b.userguid
14 where u.WindowGuid ='e2dfe459-0cff-4fdf-8748-73f5d5d222a0'
15 and u.IS_ONUSER = 1;
执行计划
Elapsed: 00:00:00.01
Execution Plan
----------------------------------------------------------
Plan hash value: 1536823471
--------------------------------------------------------------------------------------------------------
| Id | Operation | Name | Rows | Bytes | Cost (%CPU)| Time |
--------------------------------------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | 1 | 421 | 5 (0)| 00:00:01 |
| 1 | NESTED LOOPS | | 1 | 421 | 5 (0)| 00:00:01 |
| 2 | NESTED LOOPS | | 1 | 421 | 5 (0)| 00:00:01 |
| 3 | NESTED LOOPS | | 1 | 285 | 4 (0)| 00:00:01 |
| 4 | TABLE ACCESS BY INDEX ROWID| AUDIT_WINDOW | 1 | 132 | 2 (0)| 00:00:01 |
|* 5 | INDEX RANGE SCAN | IX_AUDIT_WINDOW_3 | 1 | | 1 (0)| 00:00:01 |
| 6 | TABLE ACCESS BY INDEX ROWID| AUDIT_WINDOW_USER | 1 | 153 | 2 (0)| 00:00:01 |
|* 7 | INDEX RANGE SCAN | IDX_AUDITWINUSER_A | 1 | | 1 (0)| 00:00:01 |
|* 8 | INDEX UNIQUE SCAN | PK4 | 1 | | 0 (0)| 00:00:01 |
| 9 | TABLE ACCESS BY INDEX ROWID | FRAME_USER_EXTENDINFO | 1 | 136 | 1 (0)| 00:00:01 |
--------------------------------------------------------------------------------------------------------
Predicate Information (identified by operation id):
---------------------------------------------------
5 - access("W"."ROWGUID"=U'e2dfe459-0cff-4fdf-8748-73f5d5d222a0')
7 - access("U"."WINDOWGUID"=U'e2dfe459-0cff-4fdf-8748-73f5d5d222a0' AND "U"."IS_ONUSER"=1)
8 - access("U"."USERGUID"="B"."USERGUID")
Statistics
----------------------------------------------------------
1 recursive calls
0 db block gets
12 consistent gets
1 physical reads
0 redo size
1840 bytes sent via SQL*Net to client
856 bytes received via SQL*Net from client
4 SQL*Net roundtrips to/from client
0 sorts (memory)
0 sorts (disk)
1 rows processed
上述sql执行始终会发生一次物理读
检查表结构之后，发现列piccontent为blob类型字段，具体存储对象为图像类型的二进制数据。
去掉blob类型字段之后重新查看执行计划,逻辑读少1个block，没有了物理读
Execution Plan
----------------------------------------------------------
Plan hash value: 1536823471
--------------------------------------------------------------------------------------------------------
| Id | Operation | Name | Rows | Bytes | Cost (%CPU)| Time |
--------------------------------------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | 1 | 359 | 5 (0)| 00:00:01 |
| 1 | NESTED LOOPS | | 1 | 359 | 5 (0)| 00:00:01 |
| 2 | NESTED LOOPS | | 1 | 359 | 5 (0)| 00:00:01 |
| 3 | NESTED LOOPS | | 1 | 285 | 4 (0)| 00:00:01 |
| 4 | TABLE ACCESS BY INDEX ROWID| AUDIT_WINDOW | 1 | 132 | 2 (0)| 00:00:01 |
|* 5 | INDEX RANGE SCAN | IX_AUDIT_WINDOW_3 | 1 | | 1 (0)| 00:00:01 |
| 6 | TABLE ACCESS BY INDEX ROWID| AUDIT_WINDOW_USER | 1 | 153 | 2 (0)| 00:00:01 |
|* 7 | INDEX RANGE SCAN | IDX_AUDITWINUSER_A | 1 | | 1 (0)| 00:00:01 |
|* 8 | INDEX UNIQUE SCAN | PK4 | 1 | | 0 (0)| 00:00:01 |
| 9 | TABLE ACCESS BY INDEX ROWID | FRAME_USER_EXTENDINFO | 1 | 74 | 1 (0)| 00:00:01 |
--------------------------------------------------------------------------------------------------------
Predicate Information (identified by operation id):
---------------------------------------------------
5 - access("W"."ROWGUID"=U'e2dfe459-0cff-4fdf-8748-73f5d5d222a0')
7 - access("U"."WINDOWGUID"=U'e2dfe459-0cff-4fdf-8748-73f5d5d222a0' AND "U"."IS_ONUSER"=1)
8 - access("U"."USERGUID"="B"."USERGUID")
Statistics
----------------------------------------------------------
0 recursive calls
0 db block gets
11 consistent gets --->少了1个逻辑读
0 physical reads --->没有物理读
0 redo size
1084 bytes sent via SQL*Net to client
524 bytes received via SQL*Net from client
2 SQL*Net roundtrips to/from client
0 sorts (memory)
0 sorts (disk)
1 rows processed
三、10046 TRACE跟踪
继续做10046 trace
SQL> alter session set events '10046 trace name context forever,level 12';
SQL> select u.USERGUID,
2 w.WINDOWNAME,
3 u.USERNAME,
4 w.WINDOWNO,
5 w.OUGUID,
6 u.workstatus,
7 b.piccontent,
8 b.picContentType
9 from AUDIT_WINDOW_USER u
10 INNER JOIN AUDIT_WINDOW w
11 on w.RowGuid = u.WINDOWGUID
12 inner join Frame_User_ExtendInfo b
13 on u.userguid = b.userguid
14 where u.WindowGuid ='e2dfe459-0cff-4fdf-8748-73f5d5d222a0'
15 and u.IS_ONUSER = 1;
SQL> alter session set events '10046 trace name context off';
查看trace文件
WAIT #139931257298064: nam='SQL*Net message to client' ela= 1 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1555029862153465
*** 2019-04-12 08:44:44.557
WAIT #139931257298064: nam='SQL*Net message from client' ela= 22403818 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1555029884557585
CLOSE #139931257298064:c=0,e=5,dep=0,type=1,tim=1555029884557674
=====================
PARSING IN CURSOR #139931257280352 len=438 dep=0 uid=84 oct=3 lid=84 tim=1555029884557954 hv=2920849128 ad='219bf1630' sqlid='akabjjyr1j7r8'
select u.USERGUID,
w.WINDOWNAME,
u.USERNAME,
w.WINDOWNO,
w.OUGUID,
u.workstatus,
b.piccontent,
b.picContentType
from AUDIT_WINDOW_USER u
INNER JOIN AUDIT_WINDOW w
on w.RowGuid = u.WINDOWGUID
inner join Frame_User_ExtendInfo b
on u.userguid = b.userguid
where u.WindowGuid ='e2dfe459-0cff-4fdf-8748-73f5d5d222a0'
and u.IS_ONUSER = 1
END OF STMT
PARSE #139931257280352:c=0,e=249,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=1536823471,tim=1555029884557949
EXEC #139931257280352:c=0,e=41,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=1536823471,tim=1555029884558105
WAIT #139931257280352: nam='SQL*Net message to client' ela= 1 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1555029884558146
WAIT #139931257280352: nam='SQL*Net message from client' ela= 236 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1555029884558412
WAIT #139931257280352: nam='SQL*Net message to client' ela= 0 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1555029884558600
FETCH #139931257280352:c=0,e=180,p=0,cr=9,cu=0,mis=0,r=1,dep=0,og=1,plh=1536823471,tim=1555029884558617
WAIT #139931257280352: nam='SQL*Net message from client' ela= 89 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1555029884558726
WAIT #0: nam='Disk file operations I/O' ela= 225 FileOperation=2 fileno=7 filetype=2 obj#=89337 tim=1555029884559145
WAIT #0: nam='Disk file operations I/O' ela= 787 FileOperation=2 fileno=0 filetype=15 obj#=89337 tim=1555029884560062
WAIT #0: nam='direct path read' ela= 484 file number=7 first dba=2585756 block cnt=1 obj#=89337 tim=1555029884561237
WAIT #0: nam='SQL*Net message to client' ela= 0 driver id=1650815232 #bytes=1 p3=0 obj#=89337 tim=1555029884561265
LOBREAD: c=999,e=2543,p=1,cr=1,cu=0,tim=1555029884561288
WAIT #0: nam='SQL*Net message from client' ela= 563 driver id=1650815232 #bytes=1 p3=0 obj#=89337 tim=1555029884561868
FETCH #139931257280352:c=0,e=18,p=0,cr=2,cu=0,mis=0,r=0,dep=0,og=1,plh=1536823471,tim=1555029884561910
STAT #139931257280352 id=1 cnt=1 pid=0 pos=1 obj=0 op='NESTED LOOPS (cr=11 pr=0 pw=0 time=165 us cost=5 size=421 card=1)'
STAT #139931257280352 id=2 cnt=1 pid=1 pos=1 obj=0 op='NESTED LOOPS (cr=10 pr=0 pw=0 time=156 us cost=5 size=421 card=1)'
STAT #139931257280352 id=3 cnt=1 pid=2 pos=1 obj=0 op='NESTED LOOPS (cr=8 pr=0 pw=0 time=114 us cost=4 size=285 card=1)'
STAT #139931257280352 id=4 cnt=1 pid=3 pos=1 obj=88394 op='TABLE ACCESS BY INDEX ROWID AUDIT_WINDOW (cr=4 pr=0 pw=0 time=61 us cost=2 size=132 card=1)'
STAT #139931257280352 id=5 cnt=1 pid=4 pos=1 obj=90000 op='INDEX RANGE SCAN IX_AUDIT_WINDOW_3 (cr=3 pr=0 pw=0 time=41 us cost=1 size=0 card=1)'
STAT #139931257280352 id=6 cnt=1 pid=3 pos=2 obj=88399 op='TABLE ACCESS BY INDEX ROWID AUDIT_WINDOW_USER (cr=4 pr=0 pw=0 time=49 us cost=2 size=153 card=1)'
STAT #139931257280352 id=7 cnt=1 pid=6 pos=1 obj=141442 op='INDEX RANGE SCAN IDX_AUDITWINUSER_A (cr=3 pr=0 pw=0 time=34 us cost=1 size=0 card=1)'
STAT #139931257280352 id=8 cnt=1 pid=2 pos=2 obj=90076 op='INDEX UNIQUE SCAN PK4 (cr=2 pr=0 pw=0 time=41 us cost=0 size=0 card=1)'
STAT #139931257280352 id=9 cnt=1 pid=1 pos=2 obj=89336 op='TABLE ACCESS BY INDEX ROWID FRAME_USER_EXTENDINFO (cr=1 pr=0 pw=0 time=17 us cost=1 size=136 card=1)'
WAIT #139931257280352: nam='SQL*Net message to client' ela= 1 driver id=1650815232 #bytes=1 p3=0 obj#=89337 tim=1555029884562131
*** 2019-04-12 08:45:00.800
WAIT #139931257280352: nam='SQL*Net message from client' ela= 16238510 driver id=1650815232 #bytes=1 p3=0 obj#=89337 tim=1555029900800656
CLOSE #139931257280352:c=0,e=6,dep=0,type=0,tim=1555029900800769
=====================
PARSING IN CURSOR #139931256401000 len=55 dep=0 uid=84 oct=42 lid=84 tim=1555029900800851 hv=2217940283 ad='0' sqlid='06nvwn223659v'
alter session set events '10046 trace name context off'
END OF STMT
PARSE #139931256401000:c=0,e=27,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,plh=0,tim=1555029900800851
EXEC #139931256401000:c=0,e=348,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,plh=0,tim=1555029900801244
注意看下图第59行，LOBREAD这一段，LOBREAD: c=999,e=2543,p=1,cr=1,cu=0,tim=1555029884561288
c代表cpu耗费时间（微妙）
e代表总消耗时间（微秒）
p代表物理读
cr代表逻辑读
cu代表current 模式读取的数据块
tim代表时间戳
之前执行计划中无论怎么执行都会发生物理读，这其中就是消耗在这LOBREAD
继续往下看等待事件’direct path read’
WAIT #0: nam=‘direct path read’ ela= 484 file number=7 first dba=2585756 block cnt=1 obj#=89337 tim=1555029884561237
obj#=89337为dba_objects的object_id
查看此object_id对应的LOB对象，与实际列piccontent对应的表一致
SQL> col owner for a10
SQL> col object_name for a40
SQL> col table_name for a20
SQL> col column_name for a20
SQL> SELECT O.OWNER,O.OBJECT_ID, O.OBJECT_NAME, O.OBJECT_TYPE,l.cache,
2 L.TABLE_NAME, L.COLUMN_NAME
3 FROM DBA_OBJECTS O
4 INNER JOIN DBA_LOBS L ON L.SEGMENT_NAME=O.OBJECT_NAME AND O.OWNER =L.OWNER where O.OBJECT_NAME='SYS_LOB0000089336C00007$$'
5 ORDER BY 1;
OWNER OBJECT_ID OBJECT_NAME OBJECT_TYPE CACHE TABLE_NAME COLUMN_NAME
---------- ---------- ---------------------------------------- ------------------- ---------- -------------------- --------------------
NHZWFW 89337 SYS_LOB0000089336C00007$$ LOB NO FRAME_USER_EXTENDINF PICCONTENT
继续往下看，获取FRAME_USER_EXTENDINFO表结构信息
select dbms_metadata.get_ddl(‘TABLE’,‘FRAME_USER_EXTENDINFO’,‘NHZWFW’) from dual;
截取一部分如下，其中PICCONTENT列blob类型在定义时默认为”NOCACHE“
LOB ("PICCONTENT") STORE AS BASICFILE (
TABLESPACE "ZWFW_NH" ENABLE STORAGE IN ROW CHUNK 8192 RETENTION
NOCACHE LOGGING --->默认NOCACHE
STORAGE(INITIAL 65536 NEXT 1048576 MINEXTENTS 1 MAXEXTENTS 2147483645
PCTINCREASE 0 FREELISTS 1 FREELIST GROUPS 1
BUFFER_POOL DEFAULT FLASH_CACHE DEFAULT CELL_FLASH_CACHE DEFAULT))
查看Oracle DOC,lob类型的列默认就是NOCACHE,并且不会走buffer cache，这就很好的解释了之前执行计划以及trace跟踪中的物理读。
https://docs.oracle.com/cd/B28359_01/server.111/b28286/statements_7002.htm#i2215507
实际上Oracle可以将lob字段可以放入数据缓存,Oracle提供了方法只需修改lob属性即可
ALTER TABLE table_NAME MODIFY LOB (COLUMN_NAME) ( CACHE READS);
( CACHE READS);注意read后面有1个S. 这样下次读取lob对象都可以从buffer cache中获取，而不用耗费物理IO。
四、总结
虽然Oracle提供了修改lob类型cache属性的方法，但是此项特性开启之后会消耗buffer cache的热块，在某些情况下会将其他block刷出buffer cache，适得其反。所以如果lob类型的列字段较大的话(此案例为blob类型的图片)，就不适合用cache。当然在实际业务层面，应尽量避免lob大字段类型的频繁获取，此项会对数据库服务器IO、网络带宽性能有影响。
733
被折叠的 条评论
为什么被折叠?
到【灌水乐园】发言
