[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报表两者相结合，才能更好的解决优化问题。