[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博客 ” ，链接：https://blog.itpub.net/267265/viewspace-2681575/ ，如需转载，请注明出处，否则将追究法律责任。
最新文章
- [20261008]验证Shared Memory Segments key以及Semaphore Arrays Key(11g).txt
- [20261008]gdb引入结构体是否可行.txt
- [20261008]bpftrace定义结构体例子.txt
- [20261007]关于oracle sskgph2函数.txt
- [20261007]oracle Semaphore Arrays Key值的冲突.txt
- [20261004]oracle sskgph2函数等价c以及python脚本.txt
- [20261004]bpftrace查看oracle函数调用堆栈问题.txt
- [20261002]验证sskgphpjw函数参与运算的字符串是否存在规律.txt
- [20261002]oracle Semaphore Arrays Key值的计算2.txt
- [20261001]oracle Semaphore Arrays Key值的计算.txt
