[20200416]可怕的防水牆產品.txt

[20200416]可怕的防水牆產品.txt

--//上午想跟蹤特定sql語句執行，當我檢查轉儲檔案時發現，裡面大量如下：
=====================
PARSING IN CURSOR #139709865332328 len=52 dep=1 uid=131 oct=47 lid=131 tim=1586923154761667 hv=3354287527 ad='257135c60' sqlid='190q1sz3ywrd7'
begin :con := "TASSETACL"."QUERYACL"(:sn, :on); end;
END OF STMT
PARSE #139709865332328:c=0,e=15,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=1,plh=0,tim=1586923154761663
BINDS #139709865332328:
 Bind#0
  oacdty=01 mxl=4000(4000) mxlc=00 mal=00 scl=00 pre=00
  oacflg=03 fl2=0001 frm=01 csi=852 siz=4000 off=0
  kxsbbbfp=7f10bcbbffa8  bln=4000  avl=00  flg=05
 Bind#1
  oacdty=01 mxl=32(10) mxlc=00 mal=00 scl=00 pre=00
  oacflg=10 fl2=0001 frm=01 csi=852 siz=32 off=0
  kxsbbbfp=7fff3a251b5e  bln=32  avl=10  flg=09
  value="xxxxxx_yyy"
 Bind#2
  oacdty=01 mxl=32(07) mxlc=00 mal=00 scl=00 pre=00
  oacflg=10 fl2=0001 frm=01 csi=852 siz=32 off=0
  kxsbbbfp=7fff3a251b92  bln=32  avl=07  flg=09
  value="ZZZZZZ"
  EXEC #139709865332328:c=0,e=356,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=1,plh=0,tim=1586923154762116
CLOSE #139709865332328:c=0,e=9,dep=1,type=3,tim=1586923154762194
PARSE #139709865332328:c=0,e=16,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=1,plh=0,tim=1586923154762258
BINDS #139709865332328:
 Bind#0
  oacdty=01 mxl=4000(4000) mxlc=00 mal=00 scl=00 pre=00
  oacflg=03 fl2=0001 frm=01 csi=852 siz=4000 off=0
  kxsbbbfp=7f10bcbbffa8  bln=4000  avl=00  flg=05
 Bind#1
  oacdty=01 mxl=32(10) mxlc=00 mal=00 scl=00 pre=00
  oacflg=10 fl2=0001 frm=01 csi=852 siz=32 off=0
  kxsbbbfp=7fff3a251b5e  bln=32  avl=10  flg=09
  value="xxxxxx_yyy"
 Bind#2
  oacdty=01 mxl=32(07) mxlc=00 mal=00 scl=00 pre=00
  oacflg=10 fl2=0001 frm=01 csi=852 siz=32 off=0
  kxsbbbfp=7fff3a251b92  bln=32  avl=07  flg=09
  value="YYYYYY"

--//一般如果跟蹤特定的sql語句，可能看到一些遞迴的sql語句，我跟蹤到的大量執行。
begin :con := "TASSETACL"."QUERYACL"(:sn, :on); end;

--//在執行的語句前裡面涉及到的每個表都要呼叫1次"TASSETACL"."QUERYACL"(:sn, :on);。引數1是shcema，引數2是表名。
--//你可以想像每次執行語句前都要進行這樣的檢查，是一個非常恐怖的操作。

--//看看awr報表的情況：
SQL ordered by Executions

    %CPU - CPU Time as a percentage of Elapsed Time
    %IO - User I/O Time as a percentage of Elapsed Time
    Total Executions: 23,199,582
    Captured SQL account for 34.2% of Total

Executions      Rows Processed  Rows per Exec   Elapsed Time (s)%CPU    %IO   SQL Id          SQL Module      SQL Text
6,522,522       6,521,177       1.00            1,660.15        99.4    0     190q1sz3ywrd7   xxxxxx.eee      begin :con := "TASSETACL".QUE...
2,228,287       2,228,115       1.00            107.98          99.5    0     g7ytdh9mxt1s0   xxxxxx.eee      select count ( :"SYS_B_0" ) fr...

--//一個小時消耗1,660.15秒。6522522/3600 = 1811,每秒相當於1811次。
> set numw 13
> @ d_buffer 190q1sz3ywrd7 60
  EXECUTIONS1  BUFFER_GETS1 ELAPSED_TIME1 ROWS_PROCESSED1
------------- ------------- ------------- ---------------
    412766619         48108 7039402462143       408223884

... sleep 60 , waiting ....

  EXECUTIONS2  BUFFER_GETS2 ELAPSED_TIME2 ROWS_PROCESSED2
------------- ------------- ------------- ---------------
    412864987         48108 7039427092606       408322243

總buffer_gets 每次buffer_gets      執行次數    總執行時間  每次執行時間  總處理記錄數 平均處理記錄數
------------- --------------- ------------- ------------- ------------- ------------- --------------
            0               0         98368      24630463 250.391011304         98359  .999908506831


--//現在還是疫情期間，根本沒有達到業務高峰，大約現在60%的業務量。
--//想像一下如果伺服器CPU能力不強肯定無法處理這樣大量的語句，而且由於執行的語句相同導致cursor muetux的爭用。

select * from V$MUTEX_SLEEP_HISTORY   where mutex_identifier=3354287527 order by sleep_timestamp desc;
--//結果我不貼出來了。

> @ tpt/ash/ash_wait_chains event2 sql_id='190q1sz3ywrd7' trunc(sysdate) sysdate
%This     SECONDS        AAS WAIT_CHAIN
------ ---------- ---------- --------------------------
  99%          67          0 -> ON CPU
   1%           1          0 -> library cache: mutex X

--//注：這樣看會存在一些誤導，參考連結：http://blog.itpub.net/267265/viewspace-2685107/=>[20200408]最佳化的困惑6.txt
--//實際上執行時間遠不止67秒。
--//我僅僅提醒一些要使用這類產品的使用者，如果你業務已經很忙，上線前仔細測試。

Report Summary
Load Profile

                Per Second      Per Transaction                 Per Exec        Per Call
...
Executes (SQL): 6,486.6         90.9             

--//每秒的執行次數已經達到了64XX次。而上線前最多也就是30xx次上下。db time至少增加40%。
--//我看了疫情前業務高峰可以達到95XX次，如果在加上國內的應用系統大部分是豆腐渣中的豆腐渣工程，這樣的問題會更加嚴重。

                Snap Id         Snap Time             Sessions  Cursors/Session Instances
Begin Snap:     45498           06-Jan-20 10:00:32    4379      2.2             2
End Snap:       45499           06-Jan-20 11:00:49    4625      2.3             2
Elapsed:                        60.28 (mins)                                     
DB Time:                        434.29 (mins)