[20200320]SQL語句優化的困惑.txt

lfree發表於2020-03-20

[20200320]SQL語句優化的困惑.txt

--//三月初的一次優化.

SYS@ZZZZ/dbcn> @ashtop username,sql_id "username='OOII'" trunc(sysdate) trunc(sysdate)+1
    Total
  Seconds     AAS %This   USERNAME SQL_ID        FIRST_SEEN          LAST_SEEN
--------- ------- ------- -------- ------------- ------------------- -------------------
      277      .0   30% | OOII     abnnf6rh06s6c 2020-03-02 00:02:04 2020-03-02 11:33:53
      248      .0   27% | OOII     9srkzbahfjmrc 2020-03-02 00:01:07 2020-03-02 11:40:14
       71      .0    8% | OOII                   2020-03-02 00:13:43 2020-03-02 11:37:48
       52      .0    6% | OOII     39w37j74gyu0m 2020-03-02 00:58:34 2020-03-02 11:37:17
...
30 rows selected.

--//靠前的2條語句很容易確定優化方案,謂詞建立索引就ok了.可以優化後我發現一個奇怪的情況:

SYS@ZZZZ/dbcn> @ashtop username,sql_id "username='OOII'" trunc(sysdate) trunc(sysdate)+1
    Total
  Seconds     AAS %This   USERNAME             SQL_ID        FIRST_SEEN          LAST_SEEN
--------- ------- ------- -------------------- ------------- ------------------- -------------------
      144      .0   24% | OOII                               2020-03-09 00:15:00 2020-03-09 10:50:03
       25      .0    4% | OOII                 g3a9ff2a5h2pq 2020-03-09 07:56:01 2020-03-09 10:40:33
       19      .0    3% | OOII                 4896nn1g5m3zr 2020-03-09 08:27:42 2020-03-09 10:32:16
...
30 rows selected.

--//sql_id=NULL的對應的時間上升了.到底什麼回事呢,還是我看到的情況是當天比較特殊.前段時間精力都放在網路上面.
--//今天仔細分析看看.
SYS@ZZZZ/dbcn> @ tpt/sqlid abnnf6rh06s6c ''
Show SQL text, child cursors and execution stats for SQLID abnnf6rh06s6c child nvl('','%')
  HASH_VALUE PLAN_HASH_VALUE  CH# SQL_TEXT
------------ --------------- ---- ------------------------------------------------------------------------------------------------------------------------------------------------------
  3758317772      1695611142    0 select * from ( select this_.id as id6_0_, this_.biaoshi as biaoshi6_0_, this_.biaoti as biaoti6_0_, this_.huanzhe_id as huanzhe4_6_0_, this_.jcdh as
                                  jcdh6_0_, this_.jcjs_time as jcjs6_6_0_, this_.jcks_id as jcks7_6_0_, this_.jcks_time as jcks8_6_0_, this_.jcsb_id as jcsb9_6_0_, this_.jcxm_ids as
                                  jcxm10_6_0_, this_.jcyq as jcyq6_0_, this_.jcys as jcys6_0_, this_.jfbs as jfbs6_0_, this_.jiuzhen_id as jiuzhen14_6_0_, this_.kd_time as kd15_6_0_,
                                  this_.kdks_id as kdks16_6_0_, this_.kdys as kdys6_0_, this_.left_pic as left18_6_0_, this_.right_pic as right19_6_0_, this_.state as state6_0_,
                                  this_.yanbie as yanbie6_0_ from jcd this_ where this_.biaoshi=:1 order by this_.jcjs_time desc ) where rownum <= :2

--//建立索引BIAOSHI, STATE, JCJS_TIME欄位索引。主要還考慮了sql_id 9srkzbahfjmrc 的情況。實際如果單獨考慮這條語句建立
--//BIAOSHI, JCJS_TIME更好.優化後的情況,實際上這個查詢值返回的結果經常是0。
--//注:實際開始2個索引都建立,後來我刪除BIAOSHI, JCJS_TIME的索引。
 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 0000000239F96498 0000001309714680   1695611142     26629878           20     26629878     26648392        1002409   .03761611582 312815.66951 .01174679319 315071.30841  .0118314965   2139274284 80.333611893         1250     26538060               0

--//優化後執行計劃:
Plan hash value: 1695611142
--------------------------------------------------------------------------------------------------------------------------------------------
| Id  | Operation                      | Name                          | E-Rows |E-Bytes| Cost (%CPU)| E-Time   |  OMem |  1Mem | Used-Mem |
--------------------------------------------------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT               |                               |        |       |    20 (100)|          |       |       |          |
|*  1 |  COUNT STOPKEY                 |                               |        |       |            |          |       |       |          |
|   2 |   VIEW                         |                               |     40 | 89000 |    20   (5)| 00:00:01 |       |       |          |
|*  3 |    SORT ORDER BY STOPKEY       |                               |     40 |  5480 |    20   (5)| 00:00:01 |  1024 |  1024 |          |
|   4 |     TABLE ACCESS BY INDEX ROWID| JCD                           |     40 |  5480 |    19   (0)| 00:00:01 |       |       |          |
|*  5 |      INDEX RANGE SCAN          | I_JCD_BIAOSHI_STATE_JCJS_TIME |     40 |       |     3   (0)| 00:00:01 |  1025K|  1025K|          |
--------------------------------------------------------------------------------------------------------------------------------------------

$ seq 20 | xargs -IQ echo "@tpt/ash/dashtop username,sql_id username='OOII' trunc(sysdate-20+Q) trunc(sysdate-20+Q)+1"
$ seq 20 | xargs -IQ echo "@tpt/ash/dashtop username,sql_id username='OOII' trunc(sysdate-20+Q) trunc(sysdate-20+Q)+1" | sqlplus -s -l sys/PASSWORD@XXXXXX:1521/dbcn as sysdba | grep "OOII                         "
   2%  OOII                                         40 2020-03-01 03:05:05 2020-03-01 16:17:29
   7%  OOII                                        160 2020-03-02 08:48:43 2020-03-02 21:53:52
   3%  OOII                                         60 2020-03-03 03:30:39 2020-03-03 19:23:30
   4%  OOII                                         90 2020-03-04 00:27:10 2020-03-04 23:45:22
   4%  OOII                                         90 2020-03-05 08:09:07 2020-03-05 23:16:04
   4%  OOII                                         70 2020-03-06 01:50:54 2020-03-06 22:41:01
  21%  OOII                                         80 2020-03-07 04:59:58 2020-03-07 20:33:11
   6%  OOII                                         20 2020-03-08 01:43:20 2020-03-08 21:20:11
  33%  OOII                                        580 2020-03-09 06:42:23 2020-03-09 20:56:15
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~  
  21%  OOII                                        270 2020-03-10 02:26:01 2020-03-10 22:01:23
   9%  OOII                                        130 2020-03-11 01:30:07 2020-03-11 22:11:05
  11%  OOII                                        130 2020-03-12 08:54:09 2020-03-12 19:50:59
  14%  OOII                                        200 2020-03-13 02:12:50 2020-03-13 21:29:40
  27%  OOII                                         80 2020-03-14 02:34:19 2020-03-14 16:52:30
  19%  OOII                                         70 2020-03-15 01:58:51 2020-03-15 18:40:31
  10%  OOII                                        290 2020-03-16 02:41:54 2020-03-16 23:14:23
  18%  OOII                                        430 2020-03-17 06:34:06 2020-03-17 17:13:20
  13%  OOII                                        330 2020-03-18 03:22:44 2020-03-18 21:19:41
  10%  OOII                                        220 2020-03-19 01:01:38 2020-03-19 21:18:35
  43%  OOII                                         30 2020-03-20 03:09:06 2020-03-20 04:16:23

--//3月9號反而cpu time上升很快。 3.14,3.15(星期6,7),3.20(當天)偏低。其它時間段比原來上升不少。

$ seq 20 | xargs -IQ echo "@tpt/ash/dashtop username,sql_id username='OOII' trunc(sysdate-20+Q) trunc(sysdate-20+Q)+1" | sqlplus -s -l sys/PASSWORD@XXXXXX:1521/dbcn as sysdba | egrep "abnnf6rh06s6c|9srkzbahfjmrc|OOII                         "
  33%  OOII                 abnnf6rh06s6c          620 2020-03-01 00:00:38 2020-03-01 23:54:10
  31%  OOII                 9srkzbahfjmrc          580 2020-03-01 00:31:06 2020-03-01 23:53:19
   2%  OOII                                         40 2020-03-01 03:05:05 2020-03-01 16:17:29
  26%  OOII                 abnnf6rh06s6c          580 2020-03-02 00:33:40 2020-03-02 23:30:17
  25%  OOII                 9srkzbahfjmrc          560 2020-03-02 00:17:26 2020-03-02 23:44:51
   7%  OOII                                        160 2020-03-02 08:48:43 2020-03-02 21:53:52
  25%  OOII                 abnnf6rh06s6c          600 2020-03-03 00:25:11 2020-03-03 23:46:49
  25%  OOII                 9srkzbahfjmrc          590 2020-03-03 00:24:21 2020-03-03 23:37:47
   3%  OOII                                         60 2020-03-03 03:30:39 2020-03-03 19:23:30
  26%  OOII                 abnnf6rh06s6c          670 2020-03-04 00:08:25 2020-03-04 23:25:57
  23%  OOII                 9srkzbahfjmrc          580 2020-03-04 00:23:59 2020-03-04 23:41:00
   4%  OOII                                         90 2020-03-04 00:27:10 2020-03-04 23:45:22
  27%  OOII                 9srkzbahfjmrc          610 2020-03-05 00:26:12 2020-03-05 22:51:08
  24%  OOII                 abnnf6rh06s6c          550 2020-03-05 00:12:39 2020-03-05 23:33:28
   4%  OOII                                         90 2020-03-05 08:09:07 2020-03-05 23:16:04
  24%  OOII                 9srkzbahfjmrc          400 2020-03-06 00:32:44 2020-03-06 16:21:09
  17%  OOII                 abnnf6rh06s6c          280 2020-03-06 00:33:34 2020-03-06 11:33:17
   4%  OOII                                         70 2020-03-06 01:50:54 2020-03-06 22:41:01
--//注 我3月6號上班建立的索引。
  21%  OOII                                         80 2020-03-07 04:59:58 2020-03-07 20:33:11
   3%  OOII                 abnnf6rh06s6c           10 2020-03-07 04:54:06 2020-03-07 04:54:06
   6%  OOII                                         20 2020-03-08 01:43:20 2020-03-08 21:20:11
  33%  OOII                                        580 2020-03-09 06:42:23 2020-03-09 20:56:15
  21%  OOII                                        270 2020-03-10 02:26:01 2020-03-10 22:01:23
   9%  OOII                                        130 2020-03-11 01:30:07 2020-03-11 22:11:05
  11%  OOII                                        130 2020-03-12 08:54:09 2020-03-12 19:50:59
  14%  OOII                                        200 2020-03-13 02:12:50 2020-03-13 21:29:40
   2%  OOII                 abnnf6rh06s6c           30 2020-03-13 06:44:29 2020-03-13 15:02:30
  27%  OOII                                         80 2020-03-14 02:34:19 2020-03-14 16:52:30
   3%  OOII                 9srkzbahfjmrc           10 2020-03-14 07:35:23 2020-03-14 07:35:23
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
  19%  OOII                                         70 2020-03-15 01:58:51 2020-03-15 18:40:31
   3%  OOII                 9srkzbahfjmrc           10 2020-03-15 09:44:19 2020-03-15 09:44:19
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~   
  10%  OOII                                        290 2020-03-16 02:41:54 2020-03-16 23:14:23
  18%  OOII                                        430 2020-03-17 06:34:06 2020-03-17 17:13:20
  13%  OOII                                        330 2020-03-18 03:22:44 2020-03-18 21:19:41
  10%  OOII                                        220 2020-03-19 01:01:38 2020-03-19 21:18:35
  24%  OOII                                         50 2020-03-20 03:09:06 2020-03-20 08:45:32

--//反到是3.14,3.15看到sql_id=9srkzbahfjmrc.不過也就是出現1次。
--//awr每秒取樣1次,取樣10秒放入awr報表,這樣實際上10秒就是1次。
--//問題是優化為什麼cpu_time反而上升呢?
--//單獨看sql_id = 'abnnf6rh06s6c'的情況:

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 = 'abnnf6rh06s6c'
         AND s.snap_id = x.snap_id
         AND s.instance_number = x.instance_number
         AND s.snap_id > 46833
ORDER BY 1;

     SNAP_ID BEGIN_INTERVAL_TIME      END_INTERVAL_TIME        ELAPSED_TIME_DELTA CPU_TIME_DELTA EXECUTIONS_DELTA EXECUTIONS_TOTAL ROWS_PROCESSED_DELTA ROWS_PROCESSED_TOTAL
------------ ------------------------ ------------------------ ------------------ -------------- ---------------- ---------------- -------------------- --------------------
       46833 2020-03-02 00:00:02.822  2020-03-02 01:00:24.818            26195750       26067035             1208         26100448                    0               998769
       46834 2020-03-02 01:00:24.818  2020-03-02 02:00:34.263            25932063       25766090             1202         26101650                    0               998769
       46835 2020-03-02 02:00:34.263  2020-03-02 03:00:07.341            25505938       25342125             1192         26102842                    0               998769
       46836 2020-03-02 03:00:07.341  2020-03-02 04:00:28.718            25656006       25461121             1206         26104048                    0               998769
       46837 2020-03-02 04:00:28.718  2020-03-02 05:00:49.503            25164150       25010197             1208         26105256                    0               998769
       46838 2020-03-02 05:00:49.503  2020-03-02 06:00:08.663            24354532       24180336             1186         26106442                    0               998769
       46839 2020-03-02 06:00:08.663  2020-03-02 07:00:04.905            24547284       24395289             1198         26107640                    0               998769
       46840 2020-03-02 07:00:04.905  2020-03-02 08:00:11.333            25468829       25321159             1202         26108842                    0               998769
       46846 2020-03-02 13:00:36.574  2020-03-02 14:00:48.955            25249223       25106180             1206         26116056                    1               998772
       46847 2020-03-02 14:00:48.955  2020-03-02 15:00:19.667            24953683       24828239             1190         26117246                    0               998772
       46853 2020-03-02 20:00:07.886  2020-03-02 21:00:28.987            24850789       24758246             1206         26124448                    0               998772
       46854 2020-03-02 21:00:28.987  2020-03-02 22:00:38.943            24294364       24193323             1204         26125652                    0               998772
       46855 2020-03-02 22:00:38.943  2020-03-02 23:00:12.030            24443804       24338324             1190         26126842                    0               998772
       46856 2020-03-02 23:00:12.030  2020-03-03 00:00:33.484            24904103       24798227             1208         26128050                    0               998772
       46857 2020-03-03 00:00:33.484  2020-03-03 01:00:55.706            24690257       24615275             1208         26129258                    0               998772
       46858 2020-03-03 01:00:55.706  2020-03-03 02:00:06.009            24236144       24146328             1182         26130440                    0               998772
       46859 2020-03-03 02:00:06.009  2020-03-03 03:00:13.199            25100733       24995170             1202         26131642                    0               998772
       46860 2020-03-03 03:00:13.199  2020-03-03 04:00:19.833            25271305       25200152             1204         26132846                    0               998772
       46861 2020-03-03 04:00:19.833  2020-03-03 05:00:18.947            25077010       24970208             1198         26134044                    0               998772
       46862 2020-03-03 05:00:18.947  2020-03-03 06:00:32.586            24920416       24799221             1206         26135250                    0               998772
       46863 2020-03-03 06:00:32.586  2020-03-03 07:00:39.731            24706316       24577248             1202         26136452                    0               998772
       46864 2020-03-03 07:00:39.731  2020-03-03 08:00:22.933            25476935       25326159             1194         26137646                    0               998772
       46870 2020-03-03 13:00:12.300  2020-03-03 14:00:24.763            24487515       24382277             1204         26144846                    0               998779
       46875 2020-03-03 18:00:53.428  2020-03-03 19:00:21.705            24283814       24220310             1190         26150846                    0               998781
       46877 2020-03-03 20:00:06.704  2020-03-03 21:00:03.966            24585860       24495267             1200         26153240                    0               998781
       46878 2020-03-03 21:00:03.966  2020-03-03 22:00:19.050            25600065       25457126             1204         26154444                    0               998781
       46879 2020-03-03 22:00:19.050  2020-03-03 23:00:24.964            25553487       25479128             1202         26155646                    0               998781
       46883 2020-03-04 02:00:46.172  2020-03-04 03:00:11.461            25310335       25122174             1188         26160442                    0               998781
       46884 2020-03-04 03:00:11.461  2020-03-04 04:00:32.651            25646728       25447124             1208         26161650                    0               998781
       46885 2020-03-04 04:00:32.651  2020-03-04 05:00:07.159            25064696       24960187             1190         26162840                    0               998781
       46886 2020-03-04 05:00:07.159  2020-03-04 06:00:13.058            25079377       24991194             1202         26164042                    0               998781
       46887 2020-03-04 06:00:13.058  2020-03-04 07:00:20.348            25226813       25086182             1202         26165244                    0               998781
       46888 2020-03-04 07:00:20.348  2020-03-04 08:00:25.622            26015101       25853054             1202         26166446                    0               998781
       46894 2020-03-04 13:00:47.152  2020-03-04 14:00:02.982            24115730       23971313             1184         26173638                    0               998782
       46895 2020-03-04 14:00:02.982  2020-03-04 15:00:09.214            25020057       24867229             1202         26174840                    0               998782
       46901 2020-03-04 20:00:16.619  2020-03-04 21:00:37.542            24579114       24393293             1206         26182050                    0               998782
       46902 2020-03-04 21:00:37.542  2020-03-04 22:00:54.656            24685885       24579257             1206         26183256                    1               998783
       46903 2020-03-04 22:00:54.656  2020-03-04 23:00:00.693            24381874       24268315             1182         26184438                    0               998783
       46904 2020-03-04 23:00:00.693  2020-03-05 00:00:08.098            24882706       24748236             1202         26185640                    0               998783
       46905 2020-03-05 00:00:08.098  2020-03-05 01:00:03.310            24391892       24217327             1198         26186838                    0               998783
       46906 2020-03-05 01:00:03.310  2020-03-05 02:00:21.555            24624015       24468259             1206         26188044                    0               998783
       46907 2020-03-05 02:00:21.555  2020-03-05 03:00:28.294            24926209       24844209             1202         26189246                    0               998783
       46908 2020-03-05 03:00:28.294  2020-03-05 04:00:07.830            24809374       24720266             1194         26190440                    0               998783
       46909 2020-03-05 04:00:07.830  2020-03-05 05:00:29.404            25223881       25111191             1206         26191646                    0               998783
       46910 2020-03-05 05:00:29.404  2020-03-05 06:00:50.817            24918400       24847238             1208         26192854                    0               998783
       46911 2020-03-05 06:00:50.817  2020-03-05 07:00:11.754            24495585       24401302             1188         26194042                    0               998783
       46912 2020-03-05 07:00:11.754  2020-03-05 08:00:02.899            25585767       25473128             1196         26195238                    0               998783
       46918 2020-03-05 13:00:24.895  2020-03-05 14:00:42.177            24765453       24623245             1206         26202452                    0               998784
--// 26202452 - 26195238 = 7214 ,7214/6 = 1202.注意看BEGIN_INTERVAL_TIME的時間,上下間隔6小時,即使8-12時間段沒有出現在
--//awr報表中。平均每小時的執行次數也是1200次。
       46925 2020-03-05 20:00:21.952  2020-03-05 21:00:20.911            24637329       24534279             1200         26210844                    0               998785
       46926 2020-03-05 21:00:20.911  2020-03-05 22:00:32.808            24829303       24694249             1204         26212048                    0               998785
       46927 2020-03-05 22:00:32.808  2020-03-05 23:00:03.908            25038537       24956207             1190         26213238                    0               998785
       46931 2020-03-06 02:00:08.939  2020-03-06 03:00:05.661            25670004       25501141             1198         26218038                    0               998785
       46932 2020-03-06 03:00:05.661  2020-03-06 04:00:12.069            25929401       25826081             1202         26219240                    0               998785
       46933 2020-03-06 04:00:12.069  2020-03-06 05:00:12.595            25194427       25037190             1201         26220441                    0               998785
       46934 2020-03-06 05:00:12.595  2020-03-06 06:00:25.034            25226215       25111177             1205         26221646                    0               998785
       46935 2020-03-06 06:00:25.034  2020-03-06 07:00:30.439            25031020       24905209             1200         26222846                    0               998785
       46936 2020-03-06 07:00:30.439  2020-03-06 08:00:18.328            25752400       25657098             1196         26224042                    0               998785
57 rows selected.

--//你可以發現CPU_time實際上每小時消耗24秒(注只要出現在awr報表中),平均每小時接近1200次,基本可以猜測每3秒執行一次,又一
--//個經典刷屏程式.你還可以發現3月6號以後這條sql語句不再出現在awr報表中,實際上正是我建立索引的時間。

--//拿BEGIN_INTERVAL_TIME3月5號的資料觀察。你可以發現時間點0-7,13,20-22 實際上這些時間段正是沒有業務的時間段。也就是當
--//正常業務展開時,這些語句就不再抓取到awr報表,這也是我以前優化漏掉的原因之一。
--//這也正常解析為什麼3.14,3.15號抓取到sql語句的原因,星期6,7基本業務不忙。
--//同時就很好解析為什麼優化後CPU_TIME反而升高的原因。
--//實際上如果大家注意ROWS_PROCESSED_DELTA列大部分的時間都是0,也就是根本沒有輸出。這樣頻繁的刷屏有意義嗎?完全應該把刷
--//屏次數改為60秒應該都沒有問題,開發實際上完全不考慮機器效能濫用伺服器資源。

SYS@ZZZZ/dbcn> @ d_buffer abnnf6rh06s6c 60
 EXECUTIONS1 BUFFER_GETS1 ELAPSED_TIME1 ROWS_PROCESSED1
------------ ------------ ------------- ---------------
    26629322   2139272613  315071268571         1002406

... sleep 60 , waiting ....

 EXECUTIONS2 BUFFER_GETS2 ELAPSED_TIME2 ROWS_PROCESSED2
------------ ------------ ------------- ---------------
    26629342   2139272673  315071269917         1002406

總buffer_gets 每次buffer_gets     執行次數   總執行時間 每次執行時間 總處理記錄數 平均處理記錄數
------------- --------------- ------------ ------------ ------------ ------------ --------------
           60               3           20         1346         67.3            0              0

--//再次驗證3秒執行1次。
--// sql_id=9srkzbahfjmrc的情況類似,只不過改為6秒執行1次罷了。

來自 “ ITPUB部落格 ” ,連結:http://blog.itpub.net/267265/viewspace-2681575/,如需轉載,請註明出處,否則將追究法律責任。

相關文章