[20210208]lob字段与查询的问题.txt

--//链接:http://www.itpub.net/thread-2140819-1-1.html,查询很慢.里面包含lob字段.
--//不知道对方在什么环境或者工具下测试得到的,不过toad,PLSQLDev存在一定欺骗性.它并没有取出lob字段的全部,
--//至少在toad下如此.通过测试说明问题.

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

CREATE TABLE t1 (id INT, a VARCHAR2(100), b CLOB, c CLOB);
INSERT INTO t1 SELECT rownum, dummy, lpad('a',4000,'a') ,lpad('b',4000,'b') FROM dual CONNECT BY LEVEL <= 1000;
commit ;
--//分析略,每个字段保存4000个字符,实际上这些blob并不保存在段内.

SELECT segment_name, segment_type, bytes
  FROM user_segments
 WHERE segment_name IN ('T1'
                       ,'SYS_IL0000096089C00004$$'
                       ,'SYS_IL0000096089C00003$$'
                       ,'SYS_LOB0000096089C00003$$'
                       ,'SYS_LOB0000096089C00004$$');

SEGMENT_NAME                   SEGMENT_TYPE            BYTES
------------------------------ ------------------ ----------
SYS_IL0000096089C00003$$       LOBINDEX                65536
SYS_IL0000096089C00004$$       LOBINDEX                65536
SYS_LOB0000096089C00003$$      LOBSEGMENT            9437184
SYS_LOB0000096089C00004$$      LOBSEGMENT            9437184
T1                             TABLE                  131072

--//表占128K.

2.分析:
--//sqlplus:
SCOTT@book>  set timing on
SCOTT@book>  set autot traceonly
SCOTT@book> select * from t1;
1000 rows selected.
Elapsed: 00:00:25.43
Execution Plan
---------------------------
Plan hash value: 3617692013
--------------------------------------------------------------------------
| Id  | Operation         | Name | Rows  | Bytes | Cost (%CPU)| Time     |
--------------------------------------------------------------------------
|   0 | SELECT STATEMENT  |      |  1000 |   214K|     5   (0)| 00:00:01 |
|   1 |  TABLE ACCESS FULL| T1   |  1000 |   214K|     5   (0)| 00:00:01 |
--------------------------------------------------------------------------
Statistics
----------------------------------------------------------
          0  recursive calls
          0  db block gets
       5002  consistent gets
       4000  physical reads
          0  redo size
   17488548  bytes sent via SQL*Net to client
    1119519  bytes received via SQL*Net from client
       5002  SQL*Net roundtrips to/from client
          0  sorts (memory)
          0  sorts (disk)
       1000  rows processed

--//25秒.如果你使用10046跟踪,你可以发现每个lob2个fetch,因为在段外1次lob索引1次lob字段.这样自然很慢.你可以从上面的SQL*Net
--//roundtrips to/from client=5002可以看出来问题.
--//physical reads = 4000, 因为lob缺省采用直接路径读取.不占用缓存数据.

SCOTT@book> select id,a from t1;
1000 rows selected.
Elapsed: 00:00:00.01
Execution Plan
----------------------------------------------------------
Plan hash value: 3617692013
--------------------------------------------------------------------------
| Id  | Operation         | Name | Rows  | Bytes | Cost (%CPU)| Time     |
--------------------------------------------------------------------------
|   0 | SELECT STATEMENT  |      |  1000 |  6000 |     5   (0)| 00:00:01 |
|   1 |  TABLE ACCESS FULL| T1   |  1000 |  6000 |     5   (0)| 00:00:01 |
--------------------------------------------------------------------------
Statistics
----------------------------------------------------------
          1  recursive calls
          0  db block gets
         20  consistent gets
          0  physical reads
          0  redo size
      10248  bytes sent via SQL*Net to client
        563  bytes received via SQL*Net from client
          6  SQL*Net roundtrips to/from client
          0  sorts (memory)
          0  sorts (disk)
       1000  rows processed

3.测试toad下:
SCOTT@book> @ sid 44
SPID       PID        SID    SERIAL# PNAME  TRACEFILE                                                         PROGRAM   TERMINAL     SQL_ID  STATUS
------ ------- ---------- ---------- ------ ----------------------------------------------------------------- --------- ------------ ------- --------
22343       27         44      17971        /u01/app/oracle/diag/rdbms/book/book/trace/book_ora_22343.trc     Toad.exe  XX9984BCP             INACTIVE

SYS@book> exec dbms_system.set_sql_trace_in_session( sid => 44, serial# => 17971, sql_trace=>true);
PL/SQL procedure successfully completed.

--//在toad下执行,注意打开auto trace,因为这样才能全部取出.
select * from t1;

SYS@book> exec dbms_system.set_sql_trace_in_session( sid => 44, serial# => 17971, sql_trace=>false);
PL/SQL procedure successfully completed.

--//可以query viewer发现仅仅25msecs完成.
--//查看跟踪文件:
=====================
PARSING IN CURSOR #139777477988224 len=16 dep=0 uid=83 oct=3 lid=83 tim=1612747781609757 hv=2245880055 ad='7d8447e8' sqlid='27uhu2q2xuu7r'
select * from t1
END OF STMT
PARSE #139777477988224:c=0,e=573,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,plh=3617692013,tim=1612747781609756
EXEC #139777477988224:c=0,e=22,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=3617692013,tim=1612747781611476
FETCH #139777477988224:c=0,e=86,p=0,cr=3,cu=0,mis=0,r=25,dep=0,og=1,plh=3617692013,tim=1612747781611605
FETCH #139777477988224:c=0,e=33,p=0,cr=1,cu=0,mis=0,r=25,dep=0,og=1,plh=3617692013,tim=1612747781633977
FETCH #139777477988224:c=0,e=35,p=0,cr=1,cu=0,mis=0,r=25,dep=0,og=1,plh=3617692013,tim=1612747781636460
LOBGETLEN: c=1000,e=243,p=0,cr=0,cu=0,tim=1612747781641507
LOBGETLEN: c=0,e=9,p=0,cr=0,cu=0,tim=1612747781642322
LOBREAD: c=0,e=205,p=1,cr=1,cu=0,tim=1612747781643403
LOBGETLEN: c=0,e=9,p=0,cr=0,cu=0,tim=1612747781645535
LOBGETLEN: c=0,e=9,p=0,cr=0,cu=0,tim=1612747781646236
LOBREAD: c=0,e=48,p=1,cr=1,cu=0,tim=1612747781647081
LOBGETLEN: c=0,e=9,p=0,cr=0,cu=0,tim=1612747781648681
LOBGETLEN: c=0,e=8,p=0,cr=0,cu=0,tim=1612747781649322
...

--//注意看跟踪的fetch r=25,也就是连续3次fetch,75条,使用tkprof生成报表.

********************************************************************************
SQL ID: 27uhu2q2xuu7r Plan Hash: 3617692013
select *
from
 t1


call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute      1      0.00       0.00          0          0          0           0
Fetch       41      0.00       0.00          0         54          0        1000
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total       43      0.00       0.00          0         54          0        1000

Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: 83
Number of plan statistics captured: 1

Rows (1st) Rows (avg) Rows (max)  Row Source Operation
---------- ---------- ----------  ---------------------------------------------------
      1000       1000       1000  TABLE ACCESS FULL T1 (cr=54 pr=0 pw=0 time=1055 us cost=5 size=220000 card=1000)

--//fetch 41 ,每次25条.实际上如果没有lob字段,fetch每次1000条.可以参考
--//http://blog.itpub.net/267265/viewspace-2152038/=>[20180320]toad环境中一次fetch等于多少
--//fetch 1001,1000...

$ grep "FETCH" /u01/app/oracle/diag/rdbms/book/book/trace/book_ora_22343.trc | grep "#139777477988224"|head -4
FETCH #139777477988224:c=0,e=86,p=0,cr=3,cu=0,mis=0,r=25,dep=0,og=1,plh=3617692013,tim=1612747781611605
FETCH #139777477988224:c=0,e=33,p=0,cr=1,cu=0,mis=0,r=25,dep=0,og=1,plh=3617692013,tim=1612747781633977
FETCH #139777477988224:c=0,e=35,p=0,cr=1,cu=0,mis=0,r=25,dep=0,og=1,plh=3617692013,tim=1612747781636460
FETCH #139777477988224:c=0,e=86,p=0,cr=2,cu=0,mis=0,r=25,dep=0,og=1,plh=3617692013,tim=1612747782265124

$ grep "FETCH" /u01/app/oracle/diag/rdbms/book/book/trace/book_ora_22343.trc | grep "#139777477988224"|wc
     41      82    4279

--//toad缺省是preview clob and long date是勾上的,通过toad菜单的view->options查询lob确定.

4.PLSQLDev:
--//首先说明一点我很少使用它.
SYS@book> @ sid 86
sid = 86
SPID       PID        SID    SERIAL# PNAME  TRACEFILE                                                         PROGRAM      TERMINAL     SQL_ID        STATUS
------ ------- ---------- ---------- ------ ----------------------------------------------------------------- ------------ ------------ ------------- --------
22480       30         86       7215        /u01/app/oracle/diag/rdbms/book/book/trace/book_ora_22480.trc     PLSQLDev.exe IKD84BCP                   INACTIVE

SYS@book> exec dbms_system.set_sql_trace_in_session( sid => 86, serial# => 7215, sql_trace=>true);
PL/SQL procedure successfully completed.

select * from t1;

--//选择全部,是7秒完成.

SYS@book> exec dbms_system.set_sql_trace_in_session( sid => 86, serial# => 7215, sql_trace=>false);
PL/SQL procedure successfully completed.

$ grep FETCH /u01/app/oracle/diag/rdbms/book/book/trace/book_ora_22480.trc | grep "#14061305745925"
FETCH #140613057459256:c=999,e=325,p=0,cr=4,cu=0,mis=0,r=100,dep=0,og=1,plh=3617692013,tim=1612749198858424
FETCH #140613057459256:c=0,e=260,p=0,cr=2,cu=0,mis=0,r=100,dep=0,og=1,plh=3617692013,tim=1612749200579073
FETCH #140613057459256:c=0,e=235,p=0,cr=2,cu=0,mis=0,r=100,dep=0,og=1,plh=3617692013,tim=1612749201249537
FETCH #140613057459256:c=0,e=251,p=0,cr=3,cu=0,mis=0,r=100,dep=0,og=1,plh=3617692013,tim=1612749201973919
FETCH #140613057459256:c=0,e=256,p=0,cr=2,cu=0,mis=0,r=100,dep=0,og=1,plh=3617692013,tim=1612749202695432
FETCH #140613057459256:c=1000,e=262,p=0,cr=2,cu=0,mis=0,r=100,dep=0,og=1,plh=3617692013,tim=1612749203418385
FETCH #140613057459256:c=0,e=253,p=0,cr=3,cu=0,mis=0,r=100,dep=0,og=1,plh=3617692013,tim=1612749204246545
FETCH #140613057459256:c=0,e=261,p=0,cr=2,cu=0,mis=0,r=100,dep=0,og=1,plh=3617692013,tim=1612749204998188
FETCH #140613057459256:c=0,e=273,p=0,cr=2,cu=0,mis=0,r=100,dep=0,og=1,plh=3617692013,tim=1612749205714597
FETCH #140613057459256:c=1000,e=277,p=0,cr=2,cu=0,mis=0,r=100,dep=0,og=1,plh=3617692013,tim=1612749206438245
FETCH #140613057459256:c=0,e=13,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=3617692013,tim=1612749207161531

--//fetch 每次100.

********************************************************************************
SQL ID: 2z5kqzmsngdpd Plan Hash: 3617692013

select *
from
 t1


call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute      1      0.00       0.00          0          0          0           0
Fetch       11      0.00       0.00          0         24          0        1000
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total       13      0.00       0.00          0         24          0        1000

Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: 83
Number of plan statistics captured: 1

Rows (1st) Rows (avg) Rows (max)  Row Source Operation
---------- ---------- ----------  ---------------------------------------------------
      1000       1000       1000  TABLE ACCESS FULL T1 (cr=24 pr=0 pw=0 time=1327 us cost=5 size=220000 card=1000)

********************************************************************************
--//大量的读取浪费在lob字段上.

5.总结:
sqlplus下,fetch 基本是每行1次,通过lob索引次数还会增加.并且每个lob一次,这样大量的时间浪费在lob以及网络往返上.
toad每次fetch 25,但是我估计它并没有完全取出lob,时间相当较短.
PLSQLDev每次fetch 100.
但是我有点不明白toad,PLSQLDev的LOBREAD不一样,也许是这个导致toad比PLSQLDev快.

--//toad:
$ grep LOBREAD /u01/app/oracle/diag/rdbms/book/book/trace/book_ora_22343.trc | wc
    147     294    7863

$ grep LOBGETLEN /u01/app/oracle/diag/rdbms/book/book/trace/book_ora_22343.trc | wc
    294     588   16156
    
--//294/2 = 147
--//PLSQLDev
$ grep LOBREAD /u01/app/oracle/diag/rdbms/book/book/trace/book_ora_22480.trc|wc
   2000    4000  106538

$ grep LOBGETLEN /u01/app/oracle/diag/rdbms/book/book/trace/book_ora_22480.trc|wc
   2000    4000  110119

--//toad下LOBGETLEN=294次,是LOBREAD的2倍.但是LOBGETLEN,LOBREAD次数比PLSQLDev少,其中细节我不是很清楚.