ITPub博客

首页 > 数据库 > Oracle > [20210923]sql语句占用Sharable Memory分析.txt

[20210923]sql语句占用Sharable Memory分析.txt

原创 Oracle 作者:lfree 时间:2021-09-23 10:50:59 0 删除 编辑

[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                         = <ChildNode><ChildNumber>323</ChildNumber><ID>7</ID><reason>Top Level RPI Cursor(0)</reason><size>2x4</size><ctxxyfl>16778240</ctxxyfl><ispri>0</ispri></ChildNode><ChildNode><ChildNumber>323</ChildNumber><ID>9</ID><reason>PQ Slave
mismatch(2)</reason><size>2x60</size><ctxPlanSig>ccdf70700000000fc9fba9800000000f00000000000000000000000000000000
038400c0000000000000007700000000ce437f380000000f00000000
</ctxPlanSig><kxfxupsig>00000000c7a39f02c5acbdf8000000000000000100000000000000003635c081
00000000000000000000000000000000f837968c00a3857300000000 </kxfxupsig></ChildNode><ChildNode><ChildNumber>323</ChildNumber><ID>9</ID><reason>PQ Slave
mismatch(2)</reason><size>2x60</size><ctxPlanSig>c2cf5b280000000f4cee71f80000000100000000000000000000000000000000
038400c0000000000000007a000000004ea43b100000000100000000
</ctxPlanSig><kxfxupsig>000000008a46675c45b5dfaf000000000000000100000000000000003635c081
00000000000000000000000000000000b4a46a2eea96e88400000000 </kxfxupsig></ChildNode><ChildNode><ChildNumber>323</ChildNumber><ID>7</ID><reason>Top Level RPI
Cursor(0)</reason><size>2x4</size><ctxxyfl>16778240</ctxxyfl><ispri>0</ispri></ChildNode>
--------------------------------------------------

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;

来自 “ ITPUB博客 ” ,链接:http://blog.itpub.net/267265/viewspace-2793215/,如需转载,请注明出处,否则将追究法律责任。

请登录后发表评论 登录
全部评论
熟悉oracle相关技术,擅长sql优化,rman备份与恢复,熟悉linux shell编程。

注册时间:2008-01-03

  • 博文量
    3031
  • 访问量
    6775229