[20210208]lob欄位與查詢的問題.txt

lfree發表於2021-02-08

[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少,其中細節我不是很清楚.


來自 “ ITPUB部落格 ” ,連結:http://blog.itpub.net/267265/viewspace-2756736/,如需轉載,請註明出處,否則將追究法律責任。

相關文章