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