[20210813]關於測試sql語句子游標的效能的一些補充說明.txt

[20210813]關於測試sql語句子游標的效能的一些補充說明.txt

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

--//我開始的測試是在session_cached_cursors=50的情況下進行的，我馬上發現差異不大。
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

--//因為這樣都是軟軟解析，無法比較兩者差異，我馬上設定session_cached_cursors=0,重複測試。
--//實際上在設定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

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

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個回話全部完成。大約需要200000*150/10000 = 3000秒，差不多50分鐘。
--//於是我換成1e4,還是感覺有點慢，最後換成2e3。

--//實際上我換成2e3做測試有一點點問題的，我執行指令碼m12.txt存在如下程式碼
host sleep $(echo &&3/50 | bc -l )

--//每個回話啟動前等待一小段時間，最大150/50=3秒，對於2e3這樣的迴圈次數，就有可能變成了150個回話順序執行。

$ 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
--//完成執行時間僅僅4秒.說明2e3迴圈次數太小，當時做測試時沒有仔細考慮這些細節。

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.
--//這樣沒有看到cursor: mutex S的等待事件。
--//實際上使用1e4作為迴圈次數還是比較合理的，估計3000/(200000/10000) = 150秒，有機會重複測試看看。

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

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

從文件說明可以看到，此處的Mutex是位於 Cursor 物件上的固有 Mutex，也就是針對 Parent Cursor 的。這個等待的第一個引數會披露
出 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

這其中的幾個函式作用如下：

kksfbc - 核心編譯共享物件(遊標)查詢繫結遊標 (kernel compile shared objects (cursor) find bound cursor)
kkscsSearchChildList - 用於掃描子游標列表(Search Cursor Children List).
kkshGetNextChild - 獲取下一個子游標，掃描過程的跳轉；
kgxRelease(.,AOL) - 用於釋放 Mutex (release the mutex).

...

在SQL解析時，對於父遊標的檢測同樣會使用 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 解析時 kgxSharedExamine 就是在檢測共享遊標。

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

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

--//有機會再重複測試看看.............