[20200408]优化的困惑6.txt

[20200408]优化的困惑6.txt 1.环境： > @ 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 --//生产系统awr报表(1个小时取样9:00-10:00),一般上午的业务高峰在9－11点。 SQL ordered by Elapsed Time Elapsed Time (s)Executions  Elapsed Time per Exec (s)  %Total   %CPU    %IO    SQL Id          SQL Module  SQL Text 1,660.15        6,522,522   0.00                        10.16   99.45   0.00   190q1sz3ywrd7   xxxxxx.eee  begin :con := "TASSETACL"."QUE..." .... 256.02          20,773      0.01                         1.57   98.58   0.18   ck3nrshb15tb4   httpd.exe   begin tlogon.logon; end; > @ashtop username sql_id='190q1sz3ywrd7'  trunc(sysdate) sysdate     Total   Seconds     AAS %This   USERNAME             FIRST_SEEN          LAST_SEEN --------- ------- ------- -------------------- ------------------- -------------------        57      .0  100% | ppppp_hhh           2020-04-08 00:09:01 2020-04-08 10:49:37 --//你可以发现记录的差异很大,ashtop抓取一天的(截至11点)仅仅57次。而实际上awr一个小时的取样上记录的消耗就是1,660.15秒。 SELECT s.SNAP_ID         ,x.BEGIN_INTERVAL_TIME         ,x.END_INTERVAL_TIME         ,ELAPSED_TIME_DELTA         ,CPU_TIME_DELTA         ,EXECUTIONS_DELTA         ,EXECUTIONS_TOTAL         ,ROWS_PROCESSED_DELTA     FROM DBA_HIST_SQLSTAT s, DBA_HIST_SNAPSHOT x    WHERE     s.sql_id = '190q1sz3ywrd7'          AND s.snap_id = x.snap_id          AND s.instance_number = x.instance_number          AND s.snap_id > 47717 ORDER BY 1;    SNAP_ID BEGIN_INTERVAL_TIME      END_INTERVAL_TIME        ELAPSED_TIME_DELTA CPU_TIME_DELTA EXECUTIONS_DELTA EXECUTIONS_TOTAL ROWS_PROCESSED_DELTA ---------- ------------------------ ------------------------ ------------------ -------------- ---------------- ---------------- --------------------      47717 2020-04-07 20:00:27.425  2020-04-07 21:00:40.767           425178360      429067659          2028755        376359816              2028656      47718 2020-04-07 21:00:40.767  2020-04-07 22:00:11.917           393515919      397370610          1871627        378231458              1871552      47719 2020-04-07 22:00:11.917  2020-04-07 23:00:35.213           423088126      427605907          2053886        380285348              2053797      47720 2020-04-07 23:00:35.213  2020-04-08 00:00:58.924           429128635      431995342          1995530        382280880              1995440      47721 2020-04-08 00:00:58.924  2020-04-08 01:00:05.598           337517500      341298355          1609105        383889985              1609050      47722 2020-04-08 01:00:05.598  2020-04-08 02:00:13.056           282346751      285727015          1336993        385226998              1336967      47723 2020-04-08 02:00:13.056  2020-04-08 03:00:09.325           308328198      311747635          1532358        386759424              1532308      47724 2020-04-08 03:00:09.325  2020-04-08 04:00:25.469           305779343      309529920          1543277        388302709              1543234      47725 2020-04-08 04:00:25.469  2020-04-08 05:00:31.997           259257887      263003051          1278748        389581461              1278727      47726 2020-04-08 05:00:31.997  2020-04-08 06:00:17.175           225393781      228169213          1107595        390689123              1107583      47727 2020-04-08 06:00:17.175  2020-04-08 07:00:40.763           239479033      242475052          1228663        391917786              1228653      47728 2020-04-08 07:00:40.763  2020-04-08 08:00:03.617           405715775      409634835          1901449        393819235              1901364      47729 2020-04-08 08:00:03.617  2020-04-08 09:00:27.330          1402061211     1390975250          5463459        399282696              5462542      47730 2020-04-08 09:00:27.330  2020-04-08 10:00:03.866          1660151958     1650944455          6522522        405805428              6521177 ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~=>awr报表看到的情况。      47731 2020-04-08 10:00:03.866  2020-04-08 11:00:10.612          1684893892     1668526722          6614401        412419904              6613025 65 rows selected. --//与awr报表结果能够对上。 > set verify off > @ tpt/sqlid 190q1sz3ywrd7 '' Show SQL text, child cursors and execution stats for SQLID 190q1sz3ywrd7 child nvl('','%') HASH_VALUE PLAN_HASH_VALUE  CH# SQL_TEXT ---------- --------------- ---- ---------------------------------------------------- 3354287527               0    0 begin :con := "TASSETACL"."QUERYACL"(:sn, :on); end;  CH# PARENT_HANDLE    OBJECT_HANDLE     PLAN_HASH     PARSES   H_PARSES EXECUTIONS    FETCHES ROWS_PROCESSED ROWS_PER_FETCH    CPU_SEC CPU_SEC_EXEC    ELA_SEC ELA_SEC_EXEC       LIOS  LIOS_EXEC       PIOS      SORTS USERS_EXECUTING ---- ---------------- ---------------- ---------- ---------- ---------- ---------- ---------- -------------- -------------- ---------- ------------ ---------- ------------ ---------- ---------- ---------- ---------- ---------------    0 0000000257135C60 00000012F7FB7550          0  401749624         21  412651534          0      408108832                7000034.21   .016963548 7039372.73   .017058879      48083 .000116522        787          0               1    2 0000000257135C60 00000012F9A978B0          0        232         16        232          0            232                   .086992   .000374966    .087203   .000375875         25 .107758621          2          0               0 > 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 --//1分钟执行98368，相当于98368/60 = 1639次/秒。总执行时间24630463/1000000 = 24.63秒。如果1个小时需要时间 24.63*60 = 1477.8秒。 --//实际上就是语句执行很快很频繁，ash抓取的很少，使用ashtop查询感觉就很少，而实际上该语句执行频繁，导致累计的执行时间很长。 --//awr通过共享池记录信息得到的执行时间就很长，我仅仅想说的是如果一味依赖ashtop优化很有可能漏掉一些语句，必须结合awr报表分析。 --//再看看其它sqlid的情况: 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,586,496       1,586,318       1.00            54.90           100.3   0     f8733rs2f3bng   xxxxxx.eee      SELECT sysdate FROM Dual --//看看sql_id=f8733rs2f3bng的情况.每秒1586496 /3600 = 440次,真心不知道2层应用这么频繁的取时间干吗？ > @ashtop username sql_id='f8733rs2f3bng'  trunc(sysdate) trunc(sysdate)+1     Total   Seconds     AAS %This   USERNAME             FIRST_SEEN          LAST_SEEN --------- ------- ------- -------------------- ------------------- -------------------       202      .0  100% | ppppp_hhh           2020-04-09 00:07:21 2020-04-09 09:02:13 > @ sqlh f8733rs2f3bng 47725    SNAP_ID BEGIN_INTERVAL_TIME      END_INTERVAL_TIME        ELAPSED_TIME_DELTA CPU_TIME_DELTA EXECUTIONS_DELTA EXECUTIONS_TOTAL ROWS_PROCESSED_DELTA ---------- ------------------------ ------------------------ ------------------ -------------- ---------------- ---------------- --------------------      47725 2020-04-08 04:00:25.469  2020-04-08 05:00:31.997             7141572        7203923           215786       3354343829               215775      47726 2020-04-08 05:00:31.997  2020-04-08 06:00:17.175             4574151        4673262           136395       3354480224               136393      47727 2020-04-08 06:00:17.175  2020-04-08 07:00:40.763             3798263        3817422           112460       3354592684               112458      47728 2020-04-08 07:00:40.763  2020-04-08 08:00:03.617            13867983       13889906           411939       3355004626               411922      47729 2020-04-08 08:00:03.617  2020-04-08 09:00:27.330            43644031       43617459          1244318       3356248945              1244221      47730 2020-04-08 09:00:27.330  2020-04-08 10:00:03.866            54897269       55068562          1586496       3357835458              1586318 ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~=>awr报表看到的情况。      47731 2020-04-08 10:00:03.866  2020-04-08 11:00:10.612            60389158       60230921          1749372       3359584835              1749174      47732 2020-04-08 11:00:10.612  2020-04-08 12:00:18.524            59827861       59805942          1758971       3361343815              1758782      47733 2020-04-08 12:00:18.524  2020-04-08 13:00:02.355            23749911       24026347           695032       3362038859               694984      47734 2020-04-08 13:00:02.355  2020-04-08 14:00:26.007            15035649       15211668           432078       3362470943               432061      47735 2020-04-08 14:00:26.007  2020-04-08 15:00:40.175            22348860       22415693           633409       3363104353               633383      47736 2020-04-08 15:00:40.175  2020-04-08 16:00:14.460            49562753       49574393          1444387       3364548740              1444230      47737 2020-04-08 16:00:14.460  2020-04-08 17:00:38.031            54970827       55141616          1606165       3366154922              1606023      47738 2020-04-08 17:00:38.031  2020-04-08 18:00:01.399            49183175       48795619          1466208       3367621148              1466066      47739 2020-04-08 18:00:01.399  2020-04-08 19:00:07.235            27137146       27088885           821674       3368442823               821623      47740 2020-04-08 19:00:07.235  2020-04-08 20:00:14.101            14831048       14991744           447466       3368890291               447452      47741 2020-04-08 20:00:14.101  2020-04-08 21:00:11.637            12160351       12101217           370494       3369260790               370481      47742 2020-04-08 21:00:11.637  2020-04-08 22:00:27.950            12319875       12638031           379221       3369640012               379206      47743 2020-04-08 22:00:27.950  2020-04-08 23:00:34.225            11564187       11710203           334095       3369974111               334082      47744 2020-04-08 23:00:34.225  2020-04-09 00:00:22.968            12027081       12308169           358049       3370332161               358038      47745 2020-04-09 00:00:22.968  2020-04-09 01:00:45.856             7381876        7455839           209685       3370541849               209683 ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~                       47746 2020-04-09 01:00:45.856  2020-04-09 02:00:08.315             5077171        5127228           143303       3370685152               143300      47747 2020-04-09 02:00:08.315  2020-04-09 03:00:31.720             6364851        6399034           198665       3370883819               198658      47748 2020-04-09 03:00:31.720  2020-04-09 04:00:06.878             5217293        5217218           160556       3371044375               160553      47749 2020-04-09 04:00:06.878  2020-04-09 05:00:14.312             4524945        4684314           137784       3371182161               137785      47750 2020-04-09 05:00:14.312  2020-04-09 06:00:20.776             3627379        3765428           109897       3371292058               109897      47751 2020-04-09 06:00:20.776  2020-04-09 07:00:02.527             3555284        3517481           108242       3371400300               108241      47752 2020-04-09 07:00:02.527  2020-04-09 08:00:26.637            13776302       13749953           406720       3371807020               406694      47753 2020-04-09 08:00:26.637  2020-04-09 09:00:40.259            44080344       44001288          1243052       3373050074              1242961 29 rows selected. --//7381876+5077171+6364851+5217293+4524945+3627379+3555284+13776302+44080344 = 93605445 --//93605445/1000000 = 93.605445 --//通过ashtop看到大约202秒。而实际上仅仅94秒。正好与前面看到的情况相反。因为ashtop的取样是业务最不忙的情况。 --//看看上面8－12点的ELAPSED_TIME_DELTA的情况就明白 --//总之做优化时ashtop与awr报表两者相结合，才能更好的解决优化问题。