[20210813]关于测试sql语句子光标的性能的一些补充

[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等待事件.

--//有机会再重复测试看看.............