[20210923]sql语句占用Sharable Memory分析.txt
--//前几天看awr报表,中秋前没有看,生成awr报表,利用放假时间看了一下,发现一些奇怪的问题,做一个记录.
SQL ordered by Sharable Memory
Only Statements with Sharable Memory greater than 1048576 are displayed
Sharable Mem (b) Executions % Total SQL Id SQL Module SQL Text
205,589,416 1.51 7ksrtc8rzpawc SELECT a.object_name, c.sid, C...
117,101,264 0.86 5r14h528vkacs select to_char(min(start_time)...
--//两条sql语句消耗共享池1.51+0.86 = 2.37%,反推共享池占用
--//205589416/(1.51/100)/1024/1024/1024 = 12.68G
--//117101264/(0.86/100)/1024/1024/1024 = 12.68G
--//对比awr前面部分:
Cache Sizes
Begin End
Buffer Cache: 58,112M 58,112M Std Block Size: 8K
Shared Pool Size: 12,875M 12,993M Log Buffer: 167,468K
--//基本一致
SQL ordered by Version Count
Only Statements with Version Count greater than 20 are displayed
Version Count Executions SQL Id SQL Module SQL Text
407 5r14h528vkacs select to_char(min(start_time)...
397 7ksrtc8rzpawc SELECT a.object_name, c.sid, C...
--//可以发现这两条sql语句占用内存大,版本数量高(children number),有点奇怪的地方时执行次数竟然没有信息,没有执行成功吗?
--//或者是awr报表的这段时间没有执行.
--//具体看sql语句如下,为了查看方便我做了格式化处理.
--//我检索5r14h528vkacs,7ksrtc8rzpawc 在awr报表其他地方没有相关显示.
--//sql_id=5r14h528vkacs
SELECT to_char(min(start_time), 'YYYY-MM-DD HH24:MI:SS') backupStart, to_char(max(completion_time), 'YYYY-MM-DD HH24:MI:SS') backupEnd,
round(sum(output_bytes)/1048576, 2) backupSize, round(sum(ELAPSED_SECONDS)) backupTime
FROM v$backup_set_details
WHERE completion_time > sysdate-1
--//sql_id = 7ksrtc8rzpawc
SELECT a.object_name, c.sid,
CASE TO_CHAR(b.locked_mode)
WHEN '0' THEN 'NONE'
WHEN '1' THEN 'NULL'
WHEN '2' THEN 'ROW-S (RS)'
WHEN '3' THEN 'ROW-X (RX)'
WHEN '4' THEN 'SHARE (S)'
WHEN '5' THEN 'S/ROW-X (SRX)'
WHEN '6' THEN 'Exclusive (X)'
ELSE TO_CHAR(b.locked_mode)
END locked_mode, c.SERIAL#, b.process, c.program, c.SQL_ADDRESS
FROM all_objects a, sys.gv_$locked_object b, sys.GV_$SESSION C
WHERE a.object_id = b.object_id
AND b.process = c.process
ORDER BY a.object_name
--//实际上可以大致猜测出来的某个监测软件执行的.
--//这条语句应该是用来检测lock,阻塞情况的,感觉在1个小时的awr报表时间段内,执行几次.难道1个小时无法完成吗?
--//看看一些细节.
$ rlsql <<< "@ share 7ksrtc8rzpawc" | grep "Y$" | sort |uniq -c
103 PQ_SLAVE_MISMATCH = Y
203 PURGED_CURSOR = Y
1 TOP_LEVEL_RPI_CURSOR = Y
--//PURGED_CURSOR不知道表示什么,大部分主要原因是PQ_SLAVE_MISMATCH,与并行有关.好像PURGED_CURSOR也是一样.
--------------------------------------------------
SQL_TEXT = SELECT a.object_name, c.sid, CASE TO_CHAR(b.locked_mode) WHEN '0' THEN 'NONE' WHEN '1' THEN 'NULL' WHEN '2' THEN 'ROW-S (RS)' WHEN '3' THEN 'ROW-X (RX)' WHEN '4' THEN 'SHARE (S)' WHEN '5' THEN 'S/ROW-X (SRX)' WHEN '6' THEN 'Exclusive (X)' ELSE TO_CHAR(b.locked_mode)
END locked_mode, c.SERIAL#, b.process, c.program, c.SQL_ADDRESS FROM all_objects a, sys.gv_$locked_object b, sys.GV_$SESSION C WHERE a.object_id = b.object_id AND b.process = c.process ORDER BY a.object_name
SQL_ID = 7ksrtc8rzpawc
ADDRESS = 00000000F1F19DE8
CHILD_ADDRESS = 00000013383B3748
CHILD_NUMBER = 323
PURGED_CURSOR = Y
REASON =
mismatch(2)
038400c0000000000000007700000000ce437f380000000f00000000
00000000000000000000000000000000f837968c00a3857300000000
mismatch(2)
038400c0000000000000007a000000004ea43b100000000100000000
00000000000000000000000000000000b4a46a2eea96e88400000000
Cursor(0)
--------------------------------------------------
PL/SQL procedure successfully completed.
$ rlsql <<< "@ share 5r14h528vkacs" | grep "Y$" | sort |uniq -c
6 PQ_SLAVE_MISMATCH = Y
143 PURGED_CURSOR = Y
1 TOP_LEVEL_RPI_CURSOR = Y
> select count(*) from v$sql where sql_id='5r14h528vkacs';
COUNT(*)
----------
207
--//自己尝试手工执行,sql_id='7ksrtc8rzpawc'执行还可以,另外一条sql_id=5r14h528vkacs慢的惊人.加入/*+ rule */提示倒是很快.
--//看看执行历史情况:
$ rlsql -s -l <<< "@ sqlh 7ksrtc8rzpawc 60360" | awk '$8>0{ print $0}'
SNAP_ID BEGIN_INTERVAL_TIME END_INTERVAL_TIME ELAPSED_TIME_DELTA CPU_TIME_DELTA EXECUTIONS_DELTA EXECUTIONS_TOTAL ROWS_PROCESSED_DELTA BUFFER_GETS_DELTA
60360 2021-09-16 15:00:20.273 2021-09-16 16:00:27.666 17267146 16734456 12 9896 0 2846404
60361 2021-09-16 16:00:27.666 2021-09-16 17:00:35.402 17467751 16113550 11 9907 0 2935098
60362 2021-09-16 17:00:35.402 2021-09-16 18:00:42.710 17397997 16587478 12 9919 0 3610294
60363 2021-09-16 18:00:42.710 2021-09-16 19:00:49.267 5706942 5624147 11 9930 0 1156237
60364 2021-09-16 19:00:49.267 2021-09-16 20:00:55.888 3632476 3588456 11 9941 0 480505
60365 2021-09-16 20:00:55.888 2021-09-16 21:00:02.425 3378819 3309498 11 9952 0 480430
60366 2021-09-16 21:00:02.425 2021-09-16 22:00:08.779 4700865 4658291 12 9964 0 907270
60367 2021-09-16 22:00:08.779 2021-09-16 23:00:15.337 5228546 5180214 12 9976 0 1298313
60396 2021-09-18 03:00:31.614 2021-09-18 04:00:38.887 2175458 2143674 13 6500 0 606
60397 2021-09-18 04:00:38.887 2021-09-18 05:00:45.948 684576 672897 6 6506 0 84
60398 2021-09-18 05:00:45.948 2021-09-18 06:00:52.782 1128216 1025847 9 6515 0 219
60399 2021-09-18 06:00:52.782 2021-09-18 07:01:00.111 1495069 1469780 12 6527 0 259
60400 2021-09-18 07:01:00.111 2021-09-18 08:00:06.816 1463967 1358789 11 6538 0 328
60401 2021-09-18 08:00:06.816 2021-09-18 09:00:14.308 1675913 1545762 12 6550 0 914
60402 2021-09-18 09:00:14.308 2021-09-18 10:00:21.551 1619163 1575762 12 6562 0 1055
60403 2021-09-18 10:00:21.551 2021-09-18 11:00:29.278 1790554 1619755 12 6574 0 1209
60404 2021-09-18 11:00:29.278 2021-09-18 12:00:36.802 1527840 1467774 11 6585 0 1334
60508 2021-09-22 19:00:32.012 2021-09-22 20:00:38.544 6581198 6532009 12 11657 0 1653970
60509 2021-09-22 20:00:38.544 2021-09-22 21:00:45.077 7305830 7191910 12 11669 0 2045091
60510 2021-09-22 21:00:45.077 2021-09-22 22:00:52.061 5502320 5408176 11 11680 0 1369411
60511 2021-09-22 22:00:52.061 2021-09-22 23:00:01.476 4890146 4840267 12 11692 0 1067321
60512 2021-09-22 23:00:01.476 2021-09-23 00:00:05.723 6101451 5920093 12 11704 0 1067535
60513 2021-09-23 00:00:05.723 2021-09-23 01:00:12.580 6288106 6251048 13 11717 0 978975
60514 2021-09-23 01:00:12.580 2021-09-23 02:00:19.000 3952515 3920402 11 11728 0 143129
--//可以大致猜测每小时执行12次,也就是5分钟调用1次.其它没有记录的情况因为awr记录其它更严重的问题,没有记录.
$ rlsql -s -l <<< "@ sqlh 5r14h528vkacs 60360" | awk '$8>0{ print $0}'
SNAP_ID BEGIN_INTERVAL_TIME END_INTERVAL_TIME ELAPSED_TIME_DELTA CPU_TIME_DELTA EXECUTIONS_DELTA EXECUTIONS_TOTAL ROWS_PROCESSED_DELTA BUFFER_GETS_DELTA
60360 2021-09-16 15:00:20.273 2021-09-16 16:00:27.666 2672974 2119676 12 8131 12 24
60361 2021-09-16 16:00:27.666 2021-09-16 17:00:35.402 2260125 1750734 11 8142 11 6
60362 2021-09-16 17:00:35.402 2021-09-16 18:00:42.710 2954360 2151668 12 8154 12 24
60363 2021-09-16 18:00:42.710 2021-09-16 19:00:49.267 2099157 1830722 12 8166 12 24
60364 2021-09-16 19:00:49.267 2021-09-16 20:00:55.888 1711786 1478772 11 8177 11 22
60365 2021-09-16 20:00:55.888 2021-09-16 21:00:02.425 1822142 1576764 11 8188 11 22
60366 2021-09-16 21:00:02.425 2021-09-16 22:00:08.779 1936184 1591756 12 8200 12 22
60367 2021-09-16 22:00:08.779 2021-09-16 23:00:15.337 1932777 1681750 12 8212 12 24
60393 2021-09-18 00:00:11.018 2021-09-18 01:00:17.648 1432085 1210816 11 8521 11 0
60394 2021-09-18 01:00:17.648 2021-09-18 02:00:24.583 1611489 1328800 13 8534 13 0
60394 2021-09-18 01:00:17.669 2021-09-18 02:00:24.604 466534 294957 11 135 11 0
60395 2021-09-18 02:00:24.583 2021-09-18 03:00:31.590 1518155 1253810 13 8547 13 0
60395 2021-09-18 02:00:24.604 2021-09-18 03:00:31.614 590830 351946 13 148 13 0
60396 2021-09-18 03:00:31.590 2021-09-18 04:00:38.865 1410434 1158826 12 8559 12 0
60396 2021-09-18 03:00:31.614 2021-09-18 04:00:38.887 483393 314948 12 160 12 0
60397 2021-09-18 04:00:38.865 2021-09-18 05:00:45.925 1408079 1152823 12 8571 12 0
60397 2021-09-18 04:00:38.887 2021-09-18 05:00:45.948 255187 164977 6 166 6 0
60398 2021-09-18 05:00:45.925 2021-09-18 06:00:52.761 1477943 1232812 12 8583 12 0
60398 2021-09-18 05:00:45.948 2021-09-18 06:00:52.782 548988 262961 9 175 9 0
60399 2021-09-18 06:00:52.761 2021-09-18 07:01:00.088 1538426 1268809 12 8595 12 0
60399 2021-09-18 06:00:52.782 2021-09-18 07:01:00.111 569501 340948 12 187 12 0
60400 2021-09-18 07:01:00.088 2021-09-18 08:00:06.790 1564314 1316800 12 8607 12 0
60400 2021-09-18 07:01:00.111 2021-09-18 08:00:06.816 467240 305954 11 198 11 0
60401 2021-09-18 08:00:06.790 2021-09-18 09:00:14.281 2299961 1783731 12 8619 12 0
60401 2021-09-18 08:00:06.816 2021-09-18 09:00:14.308 512641 340950 12 210 12 0
60402 2021-09-18 09:00:14.281 2021-09-18 10:00:21.608 2681696 1861716 12 8631 12 0
60402 2021-09-18 09:00:14.308 2021-09-18 10:00:21.551 539612 359947 12 222 12 0
60403 2021-09-18 10:00:21.551 2021-09-18 11:00:29.278 522892 340948 12 234 12 0
60404 2021-09-18 11:00:29.278 2021-09-18 12:00:36.802 484821 320951 11 245 11 0
60505 2021-09-22 16:00:09.884 2021-09-22 17:00:17.613 1501952 1058840 12 1444 12 14
60505 2021-09-22 16:00:09.860 2021-09-22 17:00:17.570 2255123 1886713 12 9866 12 12
60506 2021-09-22 17:00:17.570 2021-09-22 18:00:25.173 2676363 2081688 12 9878 12 24
60506 2021-09-22 17:00:17.613 2021-09-22 18:00:25.221 1695205 1423788 12 1456 12 22
60507 2021-09-22 18:00:25.221 2021-09-22 19:00:32.051 1825972 1447779 12 1468 12 24
60507 2021-09-22 18:00:25.173 2021-09-22 19:00:32.012 2207632 1827723 12 9890 12 22
60508 2021-09-22 19:00:32.012 2021-09-22 20:00:38.544 1902363 1648749 12 9902 12 22
60508 2021-09-22 19:00:32.051 2021-09-22 20:00:38.565 1644284 1381791 12 1480 12 22
60509 2021-09-22 20:00:38.544 2021-09-22 21:00:45.077 2117621 1739733 12 9914 12 24
60509 2021-09-22 20:00:38.565 2021-09-22 21:00:45.102 1881761 1505766 12 1492 12 22
60510 2021-09-22 21:00:45.102 2021-09-22 22:00:52.085 1661078 1305801 11 1503 11 22
60510 2021-09-22 21:00:45.077 2021-09-22 22:00:52.061 1819517 1582756 11 9925 11 20
60511 2021-09-22 22:00:52.061 2021-09-22 23:00:01.476 2151873 1707740 12 9937 12 24
60511 2021-09-22 22:00:52.085 2021-09-22 23:00:01.424 1729378 1449779 12 1515 12 24
60512 2021-09-22 23:00:01.476 2021-09-23 00:00:05.723 1910579 1642750 12 9949 12 22
60512 2021-09-22 23:00:01.424 2021-09-23 00:00:05.747 1655012 1365795 11 1526 11 22
60513 2021-09-23 00:00:05.723 2021-09-23 01:00:12.580 2202945 1883717 13 9962 13 26
60513 2021-09-23 00:00:05.747 2021-09-23 01:00:12.603 1836682 1474774 12 1538 12 24
60514 2021-09-23 01:00:12.580 2021-09-23 02:00:19.000 1934219 1512765 11 9973 11 22
--//不知道ELAPSED_TIME_DELTA的单位是什么.
ELAPSED_TIME_DELTA NUMBER Delta value of elapsed time (in microseconds) used by this cursor for parsing/executing/fetching
--//单位是微秒.自己搞错了.
--//2119676/12/1000/1000 = 0.017663966666666666666666,每次执行
0.01766秒.
> @ ashtop machine,sql_id,event "sql_id in ('5r14h528vkacs','7ksrtc8rzpawc')" sysdate-10 sysdate
Total
Seconds AAS %This MACHINE SQL_ID EVENT FIRST_SEEN LAST_SEEN
--------- ------- ------- -------------------- ------------- ---------------------------------------- ------------------- -------------------
564 .0 34% | H3C-APM 5r14h528vkacs 2021-09-21 22:33:31 2021-09-23 09:52:38
452 .0 27% | H3C-APM 5r14h528vkacs direct path write temp 2021-09-23 08:49:31 2021-09-23 09:52:34
310 .0 19% | H3C-APM 5r14h528vkacs direct path read temp 2021-09-23 08:49:52 2021-09-23 09:52:46
176 .0 11% | H3C-APM 7ksrtc8rzpawc 2021-09-21 03:17:19 2021-09-23 09:53:05
98 .0 6% | H3C-Ucenter 7ksrtc8rzpawc 2021-09-21 03:27:31 2021-09-23 09:49:09
40 .0 2% | H3C-Ucenter 5r14h528vkacs 2021-09-21 04:17:18 2021-09-23 09:43:57
12 .0 1% | H3C-Ucenter 5r14h528vkacs control file sequential read 2021-09-21 07:34:09 2021-09-23 05:30:43
2 .0 0% | H3C-APM 5r14h528vkacs control file sequential read 2021-09-23 07:40:11 2021-09-23 09:41:06
1 .0 0% | H3C-APM 7ksrtc8rzpawc PX qref latch 2021-09-23 09:27:10 2021-09-23 09:27:10
1 .0 0% | H3C-APM 7ksrtc8rzpawc cursor: pin S wait on X 2021-09-22 08:27:27 2021-09-22 08:27:27
1 .0 0% | H3C-Ucenter 5r14h528vkacs Disk file Mirror Read 2021-09-22 16:42:27 2021-09-22 16:42:27
1 .0 0% | H3C-Ucenter 7ksrtc8rzpawc PX Deq: Signal ACK EXT 2021-09-23 08:40:47 2021-09-23 08:40:47
1 .0 0% | H3C-Ucenter 7ksrtc8rzpawc enq: PS - contention 2021-09-21 14:21:28 2021-09-21 14:21:28
1 .0 0% | H3C-Ucenter 7ksrtc8rzpawc reliable message 2021-09-22 16:57:39 2021-09-22 16:57:39
14 rows selected.
--//华为的东西做的也太不专业,真有点丢脸,^_^.
--//我顺便看了awr SNAP_ID=60360,60361的报表.
SQL ordered by Sharable Memory
Only Statements with Sharable Memory greater than 1048576 are displayed
Sharable Mem (b) Executions % Total SQL Id SQL Module SQL Text
14,636,699 11 0.11 7ksrtc8rzpawc JDBC Thin Client SELECT a.object_name, c.sid, C...
13,805,787 11 0.10 7ksrtc8rzpawc JDBC Thin Client SELECT a.object_name, c.sid, C...
8,485,373 11 0.06 5r14h528vkacs JDBC Thin Client select to_char(min(start_time)...
8,197,045 11 0.06 5r14h528vkacs JDBC Thin Client select to_char(min(start_time)...
SQL ordered by Version Count
Only Statements with Version Count greater than 20 are displayed
Version Count Executions SQL Id SQL Module SQL Text
620 11 7ksrtc8rzpawc JDBC Thin Client SELECT a.object_name, c.sid, C...
620 11 7ksrtc8rzpawc JDBC Thin Client SELECT a.object_name, c.sid, C...
487 11 5r14h528vkacs JDBC Thin Client select to_char(min(start_time)...
487 11 5r14h528vkacs JDBC Thin Client select to_char(min(start_time)...
--//很奇怪这里显示2条.占用内存没有前面这么严重.顺便看了今天的awr 9-10点的报表.
--//5r14h528vkacs 出现在SQL ordered by Elapsed Time部分,我第一次看到.
Elapsed Time (s) Executions Elapsed Time per Exec (s) %Total %CPU %IO SQL Id SQL Module SQL Text
....
1,159.96 1.60 36.36 5r14h528vkacs select to_char(min(start_time)...
--//实际上很明显开发这类监测程序的开发人员没有很好理解oracle的工作原理,估计拿着人家的脚本照抄一遍,算作自己的东西拿来买,并
--//不知道访问sys.gv_$locked_object b, sys.GV_$SESSION C视图要打开并行.包括像v$backup_set_details视图.
--//你可以看执行计划查询v$backup_set_details要访问GV$KSFQP, GV$RMAN_STATUS_CURRENT视图.当负载变化时,并行的数量也会发生变
--//化,这样导致大量的子光标,消耗大量的共享内存,更要命的是执行还很慢!!
--//一个简单的改进方法就是加入提示.例子:
SELECT /*+ parallel(4) */
TO_CHAR (MIN (start_time), 'YYYY-MM-DD HH24:MI:SS') backupStart
,TO_CHAR (MAX (completion_time), 'YYYY-MM-DD HH24:MI:SS') backupEnd
,ROUND (SUM (output_bytes) / 1048576, 2) backupSize
,ROUND (SUM (ELAPSED_SECONDS)) backupTime
FROM v$backup_set_details
WHERE completion_time > SYSDATE - 1
--//我反复测试多次,退出再登录,不会产生大量子光标,并且执行也不慢.
--//注:我尝试加入rule提示,视乎也可以.我自己也给尝试看看是否这样还会产生大量的子光标.
--//附上sqlh.sql脚本.
$ cat sqlh.sql
column BEGIN_INTERVAL_TIME format a24
column END_INTERVAL_TIME format a24
prompt @ sqlh sql_id [snap_id]
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
,BUFFER_GETS_DELTA
FROM DBA_HIST_SQLSTAT s, DBA_HIST_SNAPSHOT x
WHERE s.sql_id = '&&1'
AND s.snap_id = x.snap_id
AND s.instance_number = x.instance_number
AND s.snap_id >= nvl('&&2',0)
ORDER BY 1;