[20210813]關(guān)于測試sql語(yǔ)句子光標的性能的一些補充

[20210813]關(guān)于測試sql語(yǔ)句子光標的性能的一些補充說(shuō)明.txt

--//昨天測試了[20210812]測試sql語(yǔ)句子光標的性能.txt，我本意是想看看大量執行相同sql語(yǔ)句，執行計劃不變的情況下。
--//children number 0 與children number=127執行時(shí)是否存在差異.當時(shí)的測試有點(diǎn)亂的，而且我開(kāi)始固有的觀(guān)點(diǎn)是
--//children number 0 的執行時(shí)間要比children number=127的要快，而實(shí)際的情況恰恰相反。

--//我開(kāi)始的測試是在session_cached_cursors=50的情況下進(jìn)行的，我馬上發(fā)現差異不大。
SCOTT@book> Select method,count(*),round(avg(TIME_ELA),0),sum(TIME_ELA) from scott.job_times group by method order by 3 ;
METHOD                 COUNT(*) ROUND(AVG(TIME_ELA),0) SUM(TIME_ELA)
-------------------- ---------- ---------------------- -------------
c128=1                        1                    564           564
c1=1                          1                    585           585
c1=150                      150                   4914        737033
c128=150                    150                   4951        742632

--//因為這樣都是軟軟解析，無(wú)法比較兩者差異，我馬上設置session_cached_cursors=0,重復測試。
--//實(shí)際上在設置session_cached_cursors=0的情況下，要慢許多。

$ zzdate;seq 1 | xargs -I{} -P 1 sqlplus -s -l scott/book @m12.txt 2e5 c1=1 {} 1 >/dev/null;zzdate
trunc(sysdate)+09/24+59/1440+04/86400 == 2021/08/12 09:59:04
trunc(sysdate)+09/24+59/1440+19/86400 == 2021/08/12 09:59:19

--//單個(gè)回話(huà)全部完成需要15秒。每秒僅僅執行 200000/15 = 13333.相當慢的執行效率。
--//而我150個(gè)回話(huà)并行。

select child_number,executions from v$sql where sql_id='5zfc9hksnyp90' and child_number in (0,127);
host sleep 10
select child_number,executions from v$sql where sql_id='5zfc9hksnyp90' and child_number in (0,127);

--//10秒的間隔執行僅僅10000次上下，這樣要等150個(gè)回話(huà)全部完成。大約需要200000*150/10000 = 3000秒，差不多50分鐘。
--//于是我換成1e4,還是感覺(jué)有點(diǎn)慢，最后換成2e3。

--//實(shí)際上我換成2e3做測試有一點(diǎn)點(diǎn)問(wèn)題的，我執行腳本m12.txt存在如下代碼
host sleep $(echo &&3/50 | bc -l )

--//每個(gè)回話(huà)啟動(dòng)前等待一小段時(shí)間，最大150/50=3秒，對于2e3這樣的循環(huán)次數，就有可能變成了150個(gè)回話(huà)順序執行。

$ zzdate;seq 150 | xargs -I{} -P 150 sqlplus -s -l scott/book @m12.txt 2e3 c1=150 {} 128 >/dev/null;zzdate
trunc(sysdate)+10/24+05/1440+31/86400 == 2021/08/12 10:05:31
trunc(sysdate)+10/24+05/1440+35/86400 == 2021/08/12 10:05:35
--//完成執行時(shí)間僅僅4秒.說(shuō)明2e3循環(huán)次數太小，當時(shí)做測試時(shí)沒(méi)有仔細考慮這些細節。

SCOTT@book> @ ashtop username,sql_id,event 1=1 trunc(sysdate)+10/24+05/1440+31/86400 trunc(sysdate)+10/24+05/1440+35/86400
    Total
  Seconds     AAS %This   USERNAME             SQL_ID        EVENT                  FIRST_SEEN          LAST_SEEN
--------- ------- ------- -------------------- ------------- ---------------------- ------------------- -------------------
       12     3.0   34% | SCOTT                5zfc9hksnyp90                        2021-08-12 10:05:32 2021-08-12 10:05:34
        7     1.8   20% | SCOTT                3hvsjqq60ng1u                        2021-08-12 10:05:32 2021-08-12 10:05:34
        5     1.3   14% | SCOTT                              library cache: mutex X 2021-08-12 10:05:32 2021-08-12 10:05:32
        3      .8    9% | SCOTT                                                     2021-08-12 10:05:32 2021-08-12 10:05:34
        2      .5    6% | SYS                                library cache: mutex X 2021-08-12 10:05:32 2021-08-12 10:05:32
        1      .3    3% | SCOTT                0k8522rmdzg4k                        2021-08-12 10:05:32 2021-08-12 10:05:32
        1      .3    3% | SCOTT                459f3z9u4fb3u                        2021-08-12 10:05:32 2021-08-12 10:05:32
        1      .3    3% | SCOTT                cm5vu20fhtnq1                        2021-08-12 10:05:32 2021-08-12 10:05:32
        1      .3    3% | SCOTT                fj2820gfajfgf                        2021-08-12 10:05:32 2021-08-12 10:05:32
        1      .3    3% | SYS                                null event             2021-08-12 10:05:32 2021-08-12 10:05:32
        1      .3    3% | SYS                                                       2021-08-12 10:05:32 2021-08-12 10:05:32
11 rows selected.
--//這樣沒(méi)有看到cursor: mutex S的等待事件。
--//實(shí)際上使用1e4作為循環(huán)次數還是比較合理的，估計3000/(200000/10000) = 150秒，有機會(huì )重復測試看看。

--//晚上我檢索cursor: mutex S相關(guān)鏈接，發(fā)現有一些人講是一些版本上的bug。我發(fā)現eygle的鏈接介紹比較詳細，轉載其中一部分。
https://www.eygle.com/archives/2017/07/oracle_mutex_cursor_mutex_s.html

Cursor: Mutex S 等待事件是指，一個(gè)會(huì )話(huà)以共享模式請求一個(gè)Mutex，而其他會(huì )話(huà)以排他模式正在持有Cursor 上的 Mutex。

從文檔說(shuō)明可以看到，此處的Mutex是位于 Cursor 對象上的固有 Mutex，也就是針對 Parent Cursor 的。這個(gè)等待的第一個(gè)參數會(huì )披露
出 SQL 的 Hash Value。

A session waits on this event when it is requesting a mutex in shared mode, when another session is currently holding a
this mutex in exclusive mode on the same cursor object.

Parameter    Description
P1          Hash value of cursor
P2          Mutex value (top 2 bytes contain SID holding mutex in exclusive mode, and bottom two bytes usually hold the value 0)
P3          Mutex where (an internal code locator) OR'd with Mutex Sleeps

這其中的幾個(gè)函數作用如下：

kksfbc - 內核編譯共享對象(游標)查找綁定游標 (kernel compile shared objects (cursor) find bound cursor)
kkscsSearchChildList - 用于掃描子游標列表(Search Cursor Children List).
kkshGetNextChild - 獲取下一個(gè)子游標，掃描過(guò)程的跳轉；
kgxRelease(.,AOL) - 用于釋放 Mutex (release the mutex).

...

在SQL解析時(shí)，對于父游標的檢測同樣會(huì )使用 Cursor mutex S:

Parent examination

When finding a cursor to execute, the parent must be examined. The examination of the parent is performed using the
mutex, cursor: mutex S.

When the parent cursor has many child cursors involved, this waits will come as the server process has to traverse the
entire list of child cursors under the parent to find a match.

Mutex is in the parent cursor.

在 SQL 解析時(shí) kgxSharedExamine 就是在檢測共享游標。

--//我個(gè)人的理解oracle在檢索子光標列表時(shí)應該從children number大的那端開(kāi)始，如果合適執行計劃，oracle這樣做有它的道理。因
--//為children number越大應該是最近生成的執行計劃，許多情況下滿(mǎn)足業(yè)務(wù)需求。這樣如果最后選擇的執行計劃選擇children number
--//=0的情況下相對慢一些,檢索探察子光標列表的時(shí)間增加，出現cursor: mutex S的情況也會(huì )增加。

--//做一個(gè)想象，假如一些短連接執行sql語(yǔ)句有大量子光標并且執行頻率很高，第一次執行一定是軟解析，并且一些執行1次就退出的情
--//況下，并且許多執行計劃選擇children number很小的執行計劃，這樣就可能出現我前面測試遇到的情況，檢索探察子光標列表的時(shí)
--//間增加出現大量的cursor: mutex S等待事件.

--//有機會(huì )再重復測試看看.............