[20210923]sql語句佔用Sharable Memory分析.txt

lfree發表於2021-09-23

[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_DEL他的單位是什麼.

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/,如需轉載,請註明出處,否則將追究法律責任。

相關文章