[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)