[20201007]exadata儲存索引.txt

[20201007]exadata儲存索引.txt

--//很久沒有看生產系統的awr報表，昨天看了一下，發現一條語句有問題。
--//我現在看exadata伺服器的awr報表一般先看Top 10 Foreground Events by Total Wait Time,然後直奔IO Stats與Segment Statistics 部分，看
--//IOStat by Function summary部分以及Segments by Direct Physical Reads部分。

IOStat by Filetype summary

'Data' columns suffixed with M,G,T,P are in multiples of 1024 other columns suffixed with K,M,G,T,P are in multiples of 1000
Small Read and Large Read are average service times, in milliseconds
Ordered by (Data Read + Write) desc

Filetype Name   Reads: Data   Reqs per sec  Data per sec  Writes: Data  Reqs per sec  Data per sec  Small Read    Large Read
Data File       1.4T          1000.91       406.292       1.8G          42.70         .509M         0.48          24.56
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
Temp File       4.9G          9.66          1.384M        6.5G          9.03          1.834M        10.70         10.54
Log File        0M            0.00          0M            1.1G          107.90        .311M         3.50           
Control File    336M          5.94          .093M         80M           1.41          .022M         0.08           
Other           1M            0.27          0M            0M            0.00          0M            0.62           
TOTAL:          1.4T          1016.77       407.77M       9.5G          161.04        2.677M        0.59          24.45

--//注意看下劃線Data per sec對應的是406.292，不知道什麼原因沒有單位(估計溢位了)，估計應該是M,total部分也指示單位應該是M。
--//1.4*1024*1024/3600 = 407.779,基本相近。也就是每秒讀取量已經達到400M/s。而且這個是平均值，如果是一般伺服器，系統早就over了。
--//平均每次請求 406.292/1000.91 = .406M
--//另外我發現1點copy and paste的awr 的html檔案這部分內容，設定set tabstop=16,基本不用對齊處理，可以參考連結：
--//http://blog.itpub.net/267265/viewspace-2216951/ => [20181019]vim小技巧刪除製表符.txt

--//直接檢視Segments by Direct Physical Reads:

Total Direct Physical Reads: 184,881,823
Captured Segments account for 97.9% of Total

Owner      Tablespace Name Object Name    Subobject Name Obj. Type Direct Reads %Total
XXXXXX_YYY XXXXXX_YYY      EMR_YZBCZRZ                   TABLE     166,492,107  90.05
....
--//這裡設定：set tabstop=24，就可以實現對齊。注：行太長，我做了一些小處理。
--//很明顯問題集中在表EMR_YZBCZRZ。但是當我在awr報表檢索EMR_YZBCZRZ並沒有發現對應sql語句。
--//檢查也沒有發現該表建立對應的檢視，我在toad下sga trace檢索EMR_YZBCZRZ，也沒有看到對應的語句。
--//開始以為對應sql語句已經從共享池清除或者沒有使用繫結變數僅僅執行1次。

> select object_id,data_object_id,last_ddl_time from dba_objects where object_name='EMR_YZBCZRZ';

 OBJECT_ID DATA_OBJECT_ID LAST_DDL_TIME
---------- -------------- -------------------
     93712          93712 2019-09-23 16:32:13
--//2019-09-23 16:32:13 改動過表結構。

> SELECT sql_id,count(*)
  FROM DBA_HIST_ACTIVE_SESS_HISTORY
 WHERE     sample_time BETWEEN TRUNC (SYSDATE - 1) + 10 / 24
                           AND TRUNC (SYSDATE - 1) + 11 / 24
       AND current_obj# = 93712
       group by sql_id order by 2 desc;

SQL_ID          COUNT(*)
------------- ----------
5yqm7qry03mcg          5
f8733rs2f3bng          1
39pbhs984wfnu          1

> @ sql_id f8733rs2f3bng
SQL_ID        SQLTEXT
------------- ------------------------
f8733rs2f3bng SELECT sysdate FROM Dual

--//奇怪有點不理解??另外1個語句39pbhs984wfnu也與表EMR_YZBCZRZ無關。有問題是sql_id='5yqm7qry03mcg'語句。
--//DBA_HIST_ACTIVE_SESS_HISTORY儲存是10秒1個取樣的情況，往大的估計也就是5*10=50秒。
--//查詢當前9-10點的情況：
> SELECT count(*)
  FROM V$ACTIVE_SESSION_HISTORY
 WHERE     sample_time BETWEEN TRUNC (SYSDATE ) + 9 / 24
                           AND TRUNC (SYSDATE ) + 10 / 24
       AND current_obj# = 93712
       and sql_id='5yqm7qry03mcg';

  COUNT(*)
----------
        67

--//粗略估計67秒。估計這個時間總的消耗不大，在awr報表沒有看到該語句。為什麼在toad下sga trace檢索EMR_YZBCZRZ沒有發現呢?

> @ sql_id 5yqm7qry03mcg
old   1: select sql_id,sql_fulltext sqltext from gv$sqlarea where sql_id='&1'
new   1: select sql_id,sql_fulltext sqltext from gv$sqlarea where sql_id='5yqm7qry03mcg'
SQL_ID        SQLTEXT
------------- -----------------------------------------------------------------------------------------------
5yqm7qry03mcg WITH x AS (
                          ... --/trunc
                         )
                    SELECT x.*,y.xtsj
                     FROM x,emr_yzbczrz y WHERE x.yzbxh = y.yzbxh AND (y.czjs = 2 OR (y.czjs = 1 AND y.czlx = 5))  
                     and y.xtsj  >=to_date(:1,'yyyy-mm-dd hh24:mi:ss') and y.xtsj <=to_date(:2,'yyyy-mm-dd hh24:mi:ss')

> @desc v$sqlarea
      Name          Null?    Type
      ------------- -------- ----------------
    1 SQL_TEXT               VARCHAR2(1000)
    2 SQL_FULLTEXT           CLOB
    3 SQL_ID                 VARCHAR2(13)
...
--//才發現emr_yzbczrz在1000個字元之外，toad按照字串查詢sql語句的缺點暴露出來，漏掉該sql語句。

> @ desc xxxxxx_yyy.emr_yzbczrz
           Name    Null?    Type
           ------- -------- --------------
.......
   10      XTSJ             DATE

--//很明顯這個欄位是"最近"新增上來的。

> set timing on
> select min(XTSJ) from emr_yzbczrz;
MIN(XTSJ)
-------------------
2019-09-23 16:32:14
Elapsed: 00:00:06.47

--//與查詢dba_objects檢視的LAST_DDL_TIME=2019-09-23 16:32:13,基本對上，也就是2019-09-23 16:32:13新增這個欄位xtsj。
--//查詢需要7秒,很明顯這樣取最小值的查詢方式沒有充分利用exadata的儲存索引.更改如下:

> select min(XTSJ) from emr_yzbczrz where xtsj<='2019-09-23 16:32:15';
MIN(XTSJ)
-------------------
2019-09-23 16:32:14
Elapsed: 00:00:00.18
--//這樣飛快。

--//獲取繫結變數值看看:
> @ bind_cap 5yqm7qry03mcg ''
SQL_ID        CHILD_NUMBER WAS NAME POSITION MAX_LENGTH LAST_CAPTURED       DATATYPE_STRING VALUE_STRING        C30
------------- ------------ --- ---- -------- ---------- ------------------- --------------- ------------------- ----------------------
5yqm7qry03mcg            2 YES :1          1        128 2019-12-31 22:51:08 VARCHAR2(128)   2019-12-31 22:50:30
                           YES :2          2        128 2019-12-31 22:51:08 VARCHAR2(128)   2019-12-31 22:51:05
--//查詢時間範圍很小,2019-12-31 22:50:30 - 2019-12-31 22:51:05,僅僅範圍在35秒.
--//我大概可以猜測開發的目的,也就顯示在一個螢幕上不斷重新整理,估計是給某個領導檢視,哈哈一點意思都沒有.

> @ bind_cap_awr 5yqm7qry03mcg ''
   SNAP_ID SQL_ID        WAS LAST_CAPTURED       NAME POSITION MAX_LENGTH DATATYPE_STRING VALUE_STRING         C30
---------- ------------- --- ------------------- ---- -------- ---------- --------------- -------------------- -----------------------
........
     45520 5yqm7qry03mcg YES 2019-12-31 22:51:08 :1          1        128 VARCHAR2(128)   2019-12-31 22:50:30
                                                 :2          2        128 VARCHAR2(128)   2019-12-31 22:51:05
1442 rows selected.
--//這是我看到最大LAST_CAPTURED時間，也就是以後這條語句再也沒有出現在awr報表。
--//很明顯exadata的儲存索引揮發極大的作用，掩蓋問題的本質，如果你直接執行sql_id語句，僅僅不到1秒就完成了。

--//如果查詢:
SELECT count(*)
  FROM V$ACTIVE_SESSION_HISTORY
 WHERE     sample_time BETWEEN TRUNC (SYSDATE ) + 9 / 24
                           AND TRUNC (SYSDATE ) + 10 / 24
       and sql_id='5yqm7qry03mcg';
count(*)
-------
67

--//僅僅顯示67,對應67秒顯然有點多,實際上每次執行不到0.5s上下 ,總共 0.5*67 = 34秒上下。

> set numw 12
> @ d_buffer 5yqm7qry03mcg 60
 EXECUTIONS1 BUFFER_GETS1 ELAPSED_TIME1 ROWS_PROCESSED1
------------ ------------ ------------- ---------------
       89718   4293590676   44928290360         1435349

1 row selected.

... sleep 60 , waiting ....

 EXECUTIONS2 BUFFER_GETS2 ELAPSED_TIME2 ROWS_PROCESSED2
------------ ------------ ------------- ---------------
       89720      1811045   44929438434         1435373

1 row selected.

總buffer_gets 每次buffer_gets 執行次數   總執行時間 每次執行時間 總處理記錄數 平均處理記錄數
------------- --------------- -------- ------------ ------------ ------------ --------------
  -4291779631     -2145889816        2      1148074       574037           24             12

1 row selected.
--//^_^，運氣真不好，第一次看到統計資訊溢位的情況,相減變成了負數.再做一次對比：

> @ d_buffer 5yqm7qry03mcg 60
 EXECUTIONS1 BUFFER_GETS1 ELAPSED_TIME1 ROWS_PROCESSED1
------------ ------------ ------------- ---------------
       89722      4999857   44930492814         1435496

1 row selected.

... sleep 60 , waiting ....

 EXECUTIONS2 BUFFER_GETS2 ELAPSED_TIME2 ROWS_PROCESSED2
------------ ------------ ------------- ---------------
       89724      8188024   44931515542         1435596

1 row selected.

總buffer_gets 每次buffer_gets 執行次數   總執行時間 每次執行時間 總處理記錄數 平均處理記錄數
------------- --------------- -------- ------------ ------------ ------------ --------------
      3188167       1594083.5        2      1022728       511364          100             50
1 row selected.
--//可以發現平均每次執行消耗511364微秒(單位是10^-6秒)，相當於0.5秒。
--//1594084*8192/1024/1024/1024 = 12.16G,表EMR_YZBCZRZ大小就是11.9G，基本對上。


--//建立索引再測試：
CREATE INDEX XXXXXX_YYY.i_EMR_YZBCZRZ_XTSJ ON XXXXXX_YYY.EMR_YZBCZRZ
(XTSJ)
LOGGING
STORAGE    (
            BUFFER_POOL      DEFAULT
            FLASH_CACHE      DEFAULT
            CELL_FLASH_CACHE DEFAULT
           )
NOPARALLEL
ONLINE;

*
ERROR at line 1:
ORA-00604: error occurred at recursive SQL level 2
ORA-01031: insufficient privileges
ORA-06512: at line 13
ORA-00604: error occurred at recursive SQL level 2
ORA-01031: insufficient privileges
ORA-06512: at line 13
--//alert.log
Tue Jan 07 10:57:25 2020
online index (re)build cleanup: objn=151619 maxretry=2000 forever=0
--//奇怪，怎麼會有出現這樣的情況，居然出現2次報錯.而且索引已經建立完成,至少可用.另外寫一篇blog分析。我發現onlin建立索引時
--//SYS_JOURNAL_151619 IOT表沒有刪除,似乎在嘗試2000次後報錯.
--//注：我必須要online建立，不然影響業務，建立需要不到4分鐘(不知道這2000次嘗試佔了多少時間)。

> @ d_buffer 5yqm7qry03mcg 60
 EXECUTIONS1 BUFFER_GETS1 ELAPSED_TIME1 ROWS_PROCESSED1
------------ ------------ ------------- ---------------
       89745     22989971   44942090061         1436189

1 row selected.
... sleep 60 , waiting ....
 EXECUTIONS2 BUFFER_GETS2 ELAPSED_TIME2 ROWS_PROCESSED2
------------ ------------ ------------- ---------------
       89747     23066613   44942854509         1436302
1 row selected.

總buffer_gets 每次buffer_gets     執行次數   總執行時間 每次執行時間 總處理記錄數 平均處理記錄數
------------- --------------- ------------ ------------ ------------ ------------ --------------
        76642           38321            2       764448       382224          113           56.5
1 row selected.
--//使用.38秒,僅僅節約一點點時間，像這種情況是建立索引還是不需要建立索引非常糾結。
--//做這樣最佳化非常沒有成就感,我大概節省了 (0.511-0.382)*67 = 8.643 秒，感覺跟沒做沒有什麼區別。

總結：
1.很久不看awr報表，有點生疏,排除問題走了一個大大的彎路。
2.正好透過toad檢索沒有發現問題sql語句，又走了一個彎路。
3.exadate 我個人觀點就是就是一些垃圾系統的保護傘，試想如果這樣的系統在遷回非exadata系統時，如果沒有發現問題語句。
  這樣的系統能用才怪。實際上還有更多的語句被exadata的優異IO效能掩蓋無法暴露出來。
4.像這樣的索引是建立還是不建立，我自己心裡也非常糾結。
5.而且像這樣的語句awr報表居然漏掉，有點意外。看來給修改awr收集資訊設定：http://blog.itpub.net/267265/viewspace-2217432/
6.不知道今天是否運氣不好,居然看到BUFFER_GETS溢位的情況.
--// buffer_gets 最大應該是 2^32-1 = 4294967295.
--//(4294967295-4293590676+1811045 )/2 = 1593832
--//1593832*8192/1024/1024/1024 = 12.12G.
7.不到半個小時再看,我發現SYS_JOURNAL_151619 IOT表已經刪除,我建立的索引已經不見,估計回滾了.不過我已經大概知道問題的原因,
  去年上半年購買的一個防水牆產品造成的問題,另寫一篇文章描述該問題.
8.今天不知道什麼原因，許多事情非常不順，是否天氣太熱27度。年關快到，做事情一定不要浮躁，要小心小心再小心。

--//附上測試指令碼:
$ cat d_buffer.sql
col executions1 new_value x1
col buffer_gets1 new_value x2
col ELAPSED_TIME1 new_value x3
col ROWS_PROCESSED1 new_value x4

col executions2 new_value y1
col buffer_gets2 new_value y2
col ELAPSED_TIME2 new_value y3
col ROWS_PROCESSED2 new_value y4

col var3 new_value var3

select executions executions1,buffer_gets buffer_gets1,elapsed_time elapsed_time1,rows_processed rows_processed1  from v$sqlarea where sql_id='&&1';

prompt ... sleep &&2 , waiting ....
host sleep &&2

select executions executions2,buffer_gets buffer_gets2,elapsed_time elapsed_time2 ,rows_processed rows_processed2 from v$sqlarea where sql_id='&&1';

select &y2-&x2 "總buffer_gets", (&y2-&x2)/(&y1-&x1) "每次buffer_gets",&y1- &x1 "執行次數" , &y3-&x3 "總執行時間", (&y3-&x3)/(&y1-&x1) "每次執行時間" , &y4-&x4 "總處理記錄數",(&y4-&x4)/(&y1-&x1) "平均處理記錄數" from dual ;

$ cat bind_cap.sql
set verify off
column value_string format a50
column datatype_string format a15
break on sql_id on child_number  skip 1
select  replace(sql_fulltext,chr(13),'') c200 from v$sql where sql_id='&1' and rownum<=1;

SELECT sql_id,
       child_number,
       was_captured,
       name,
       position,
       max_length,
       last_captured,
       datatype_string,
       DECODE (
          datatype_string,
          'DATE', TO_CHAR (TO_DATE (value_string, 'mm/dd/yy hh24:mi:ss'),
                           'yyyy/mm/dd hh24:mi:ss'),
          value_string)
          value_string,
          decode(datatype_string,'TIMESTAMP',ANYDATA.accesstimestamp (value_anydata)) c30
  FROM v$sql_bind_capture
 WHERE sql_id = '&1' and was_captured='YES' and  DUP_POSITION is null and name=nvl('&&2',name)
 order by child_number,was_captured,position;
break on sql_id on child_number  skip 0

$ cat bind_cap_awr.sql
set verify off
prompt
prompt @bind_cap_awr sql_id [column]
prompt
column value_string format a50
column datatype_string format a15
break on snap_id on sql_id on was_captured on last_captured skip 1

select  replace(sql_fulltext,chr(13),'') c200 from v$sql where sql_id='&1' and rownum<=1;
--select  replace(sql_text,chr(13),'') c200 from DBA_HIST_SQLTEXT where sql_id='&1' and rownum<=1;

SELECT snap_id,
         sql_id,
         was_captured,
         last_captured,
         name,
         position,
         max_length,
         datatype_string,
         DECODE (
            datatype_string,
            'DATE', TO_CHAR (TO_DATE (value_string, 'mm/dd/yy hh24:mi:ss'),
                             'yyyy/mm/dd hh24:mi:ss'),
            value_string)
            value_string,
            decode(datatype_string,'TIMESTAMP',ANYDATA.accesstimestamp (value_anydata)) c30
    FROM DBA_HIST_SQLBIND
   WHERE sql_id = '&1' AND was_captured = 'YES' and  dup_position is null and name=nvl('&&2',name)
ORDER BY snap_id ,last_captured, was_captured, position;
break on snap_id on sql_id on was_captured on last_captured skip 0