[20210916]探究mutex的值 8.txt

[20210916]探究mutex的值 8.txt

--//昨天做了mutex相關sleep的測試,我前面提到隱含引數
SYS@book> @ hide mutex
NAME               DESCRIPTION       DEFAULT_VALUE SESSION_VALUE SYSTEM_VALUE ISSES ISSYS_MOD
------------------ ----------------- ------------- ------------- ------------ ----- ---------
_mutex_spin_count  Mutex spin count  TRUE          255           255          FALSE IMMEDIATE
_mutex_wait_scheme Mutex wait scheme TRUE          2             2            FALSE IMMEDIATE
_mutex_wait_time   Mutex wait time   TRUE          1             1            FALSE IMMEDIATE

--//預設_mutex_wait_time=1,單位釐秒. 當大於1時sleeps的時間會出現指數回退,看看這樣的情況如下.
--//網上找了一段資料:
* _mutex_spin_count (Integer)
- This sets the number of times to spin before yielding/waiting.

* _mutex_wait_scheme (Integer)
- In 11.2 this controls which wait scheme to use. It can be set to one

of the three wait schemes described above thus:
_mutex_wait_scheme = 0                        – Always YIELD
_mutex_wait_scheme = 1 & _mutex_wait_time = t – Always SLEEP for t milli-seconds (default)
_mutex_wait_scheme = 2 & _mutex_wait_time = t – EXP BACKOFF with maximum sleep


1.環境:
SYS@book> @ ver1
PORT_STRING                    VERSION        BANNER
------------------------------ -------------- --------------------------------------------------------------------------------
x86_64/Linux 2.4.xx            11.2.0.4.0     Oracle Database 11g Enterprise Edition Release 11.2.0.4.0 - 64bit Production

SYS@book> alter system set session_cached_cursors=0 scope=spfile;
System altered.

--//重啟略,設定目的主要保證每次都是軟解析,這樣都會訪問library cache mutex.
--//session 1:
SCOTT@book> @ spid
       SID    SERIAL# PROCESS                  SERVER    SPID       PID  P_SERIAL# C50
---------- ---------- ------------------------ --------- ------ ------- ---------- --------------------------------------------------
       295          5 9539                     DEDICATED 9540        21          3 alter system kill session '295,5' immediate;

--//sid=295 = 0x127.

SCOTT@book> select * from dept where deptno=20;
    DEPTNO DNAME          LOC
---------- -------------- -------------
        20 RESEARCH       DALLAS
--//執行5次以上。

SCOTT@book> @ hash
HASH_VALUE SQL_ID        CHILD_NUMBER HASH_HEX
---------- ------------- ------------ ---------
  95129850 80baj2c2ur47u            0   5ab90fa
--//95129850%131072 = 102650,確定library cache mutex 地址如下,透過轉儲library cache,過程略.
oradebug setmypid
oradebug dump library_cache 10;
--//檢查轉儲,搜尋Bucket: #=102650,發現如下:
Bucket: #=102650 Mutex=0x80528f40(0, 6, 0, 6)

SYS@book> alter system set "_mutex_wait_time"=500 scope=memory;
System altered.
--//相當於5秒.

2.建立測試指令碼:

$ cat mutex_sleeps.sh
#! /bin/bash
# test mutix sleep change
#
# argv1=mutex_address
# argv2=poke mutex_address1 value
# argv3=poke mutex_address2 value
# argv4=sleep seconds
#

vdate=$(date '+%Y%m%d%H%M%S')
echo $vdate
offset4=`printf "%x" $(( 0x${1} + 0x4  )) `
#echo $offset4

sqlplus -s -l / as sysdba <<EOF | ts.awk
oradebug setmypid
oradebug poke 0x${1}       4 0x${2}
oradebug poke 0x${offset4}   4 0x${3}
oradebug peek 0x${1} 24
quit
EOF

sqlplus -s -l scott/book <<<"select * from dept where deptno=20;"  &

strace -Ttt -f -p $! -o /tmp/mutex_${vdate}.txt -e select,sched_yield,semtimedop,getrusage &

sqlplus -s -l / as sysdba <<EOF | ts.awk
oradebug setmypid
$(seq ${4} | xargs -IQ echo -e "oradebug peek 0x${1} 24\nhost sleep 1\n")
oradebug poke 0x${1}       8 0x0000000000000000
$(seq 5    | xargs -IQ echo -e "oradebug peek 0x${1} 24\nhost sleep 1\n")
--oradebug peek 0x${1} 24
quit
EOF

--//簡單說明:開始設定值非0,執行sqlplus語句放在後臺,這時會掛起,透過$!獲得前面sqlplus的程式號,透過strace監測,等待一定時間後,
--//修改設定值為0,sqlplus正常執行後退出,strace跟蹤也停止.透過前後sleep的差值就可以知道次數,同時看看strace跟蹤的呼叫次數
--//是否基本一致.

3.測試:
$ . mutex_sleeps.sh 80528f40 00000000 00009999 15 | grep "080528F40,"
[2021-09-16 09:43:36] BEFORE: [080528F40, 080528F44) = 00000000
[2021-09-16 09:43:36] AFTER:  [080528F40, 080528F44) = 00000000
[2021-09-16 09:43:36] [080528F40, 080528F58) = 00000000 00009999 000000C7 000AAC48 000190FA 00000000
Process 23609 attached - interrupt to quit
Process 23640 attached
Process 23609 detached
Process 23640 detached
[2021-09-16 09:43:36] [080528F40, 080528F58) = 00000000 00009999 000000C7 000AAC48 000190FA 00000000
[2021-09-16 09:43:37] [080528F40, 080528F58) = 00000000 00009999 000000C7 000AAC48 000190FA 00000000
[2021-09-16 09:43:38] [080528F40, 080528F58) = 00000000 00009999 000000C7 000AAC48 000190FA 00000000
[2021-09-16 09:43:39] [080528F40, 080528F58) = 00000000 00009999 000000C7 000AAC48 000190FA 00000000
[2021-09-16 09:43:40] [080528F40, 080528F58) = 00000000 00009999 000000C7 000AAC48 000190FA 00000000
[2021-09-16 09:43:41] [080528F40, 080528F58) = 00000000 00009999 000000C7 000AAC48 000190FA 00000000
[2021-09-16 09:43:42] [080528F40, 080528F58) = 00000000 00009999 000000C7 000AAC48 000190FA 00000000
[2021-09-16 09:43:43] [080528F40, 080528F58) = 00000000 00009999 000000C7 000AAC48 000190FA 00000000
[2021-09-16 09:43:44] [080528F40, 080528F58) = 00000000 00009999 000000C7 000AAC48 000190FA 00000000
[2021-09-16 09:43:45] [080528F40, 080528F58) = 00000000 00009999 000000C7 000AAC48 000190FA 00000000
[2021-09-16 09:43:46] [080528F40, 080528F58) = 00000000 00009999 000000C7 000AAC48 000190FA 00000000
[2021-09-16 09:43:47] [080528F40, 080528F58) = 00000000 00009999 000000C7 000AAC48 000190FA 00000000
[2021-09-16 09:43:48] [080528F40, 080528F58) = 00000000 00009999 000000C7 000AAC48 000190FA 00000000
[2021-09-16 09:43:49] [080528F40, 080528F58) = 00000000 00009999 000000C7 000AAC48 000190FA 00000000
[2021-09-16 09:43:50] [080528F40, 080528F58) = 00000000 00009999 000000C7 000AAC48 000190FA 00000000
[2021-09-16 09:43:51] BEFORE: [080528F40, 080528F48) = 00000000 00009999
[2021-09-16 09:43:51] AFTER:  [080528F40, 080528F48) = 00000000 00000000
[2021-09-16 09:43:51] [080528F40, 080528F58) = 00000000 00000000 000000C7 000AAC48 000190FA 00000000
[2021-09-16 09:43:52] [080528F40, 080528F58) = 00000000 00000000 000000C8 000AAC5B 000190FA 00000000
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
[2021-09-16 09:43:53] [080528F40, 080528F58) = 00000000 00000000 000000C8 000AAC5B 000190FA 00000000
[2021-09-16 09:43:54] [080528F40, 080528F58) = 00000000 00000000 000000C8 000AAC5B 000190FA 00000000
[2021-09-16 09:43:55] [080528F40, 080528F58) = 00000000 00000000 000000C8 000AAC5B 000190FA 00000000
--//0x5b-0x48 = 19
--//5b = 91   48 = 72   91-72 = 19

$ grep semtimedop /tmp/mutex_20210916094335.txt
23640 09:43:36.258247 semtimedop(43581440, 0x7fff24813d80, 1, {0, 10000000}) = -1 EAGAIN (Resource temporarily unavailable) <0.010610>
23640 09:43:36.268982 semtimedop(43581440, 0x7fff24813d80, 1, {0, 10000000}) = -1 EAGAIN (Resource temporarily unavailable) <0.010943>
23640 09:43:36.280047 semtimedop(43581440, 0x7fff24813d80, 1, {0, 30000000}) = -1 EAGAIN (Resource temporarily unavailable) <0.030853>
23640 09:43:36.311030 semtimedop(43581440, 0x7fff24813d80, 1, {0, 30000000}) = -1 EAGAIN (Resource temporarily unavailable) <0.030873>
23640 09:43:36.342035 semtimedop(43581440, 0x7fff24813d80, 1, {0, 80000000}) = -1 EAGAIN (Resource temporarily unavailable) <0.080866>
23640 09:43:36.423035 semtimedop(43581440, 0x7fff24813d80, 1, {0, 90000000}) = -1 EAGAIN (Resource temporarily unavailable) <0.090863>
23640 09:43:36.514031 semtimedop(43581440, 0x7fff24813d80, 1, {0, 180000000}) = -1 EAGAIN (Resource temporarily unavailable) <0.180894>
23640 09:43:36.695056 semtimedop(43581440, 0x7fff24813d80, 1, {0, 230000000}) = -1 EAGAIN (Resource temporarily unavailable) <0.230866>
23640 09:43:36.926053 semtimedop(43581440, 0x7fff24813d80, 1, {0, 400000000}) = -1 EAGAIN (Resource temporarily unavailable) <0.400880>
23640 09:43:37.327071 semtimedop(43581440, 0x7fff24813d80, 1, {0, 410000000}) = -1 EAGAIN (Resource temporarily unavailable) <0.410827>
23640 09:43:37.738030 semtimedop(43581440, 0x7fff24813d80, 1, {0, 740000000}) = -1 EAGAIN (Resource temporarily unavailable) <0.740943>
23640 09:43:38.479359 semtimedop(43581440, 0x7fff24813d80, 1, {0, 710000000}) = -1 EAGAIN (Resource temporarily unavailable) <0.710692>
23640 09:43:39.190173 semtimedop(43581440, 0x7fff24813d80, 1, {1, 360000000}) = -1 EAGAIN (Resource temporarily unavailable) <1.360780>
23640 09:43:40.551330 semtimedop(43581440, 0x7fff24813d80, 1, {1, 370000000}) = -1 EAGAIN (Resource temporarily unavailable) <1.370597>
23640 09:43:41.922297 semtimedop(43581440, 0x7fff24813d80, 1, {2, 660000000}) = -1 EAGAIN (Resource temporarily unavailable) <2.660649>
23640 09:43:44.583363 semtimedop(43581440, 0x7fff24813d80, 1, {2, 710000000}) = -1 EAGAIN (Resource temporarily unavailable) <2.710690>
23640 09:43:47.315069 semtimedop(43581440, 0x7fff24813d80, 1, {5, 0}) = -1 EAGAIN (Resource temporarily unavailable) <5.000956>
--//注意看最後一行開始時間09:43:47.315069到9:43:52.XXXXX結束.更新mutex結構裡面的第12-15位元組sleeps資訊.
--//注意看裡面的引數{0, 10000000},引數1表示0秒 ,引數2 10000000/10^9 = .01秒.
--//可以看出semtimedop的引數時間變化逐步增加.1,1,3,3,8,9,18,23,40,41,64,71,136,137,266,271,500,單位cs.

$ grep semtimedop /tmp/mutex_20210916094335.txt |wc
     17     238    2298
--//奇怪總是相差2.

$ egrep "semtimedop|getrusage" /tmp/mutex_20210916094335.txt
23640 09:43:36.257760 getrusage(RUSAGE_SELF, {ru_utime={0, 21996}, ru_stime={0, 29995}, ...}) = 0 <0.000025>
23640 09:43:36.257922 getrusage(RUSAGE_SELF, {ru_utime={0, 21996}, ru_stime={0, 29995}, ...}) = 0 <0.000023>
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
23640 09:43:36.258247 semtimedop(43581440, 0x7fff24813d80, 1, {0, 10000000}) = -1 EAGAIN (Resource temporarily unavailable) <0.010610>
23640 09:43:36.268982 semtimedop(43581440, 0x7fff24813d80, 1, {0, 10000000}) = -1 EAGAIN (Resource temporarily unavailable) <0.010943>
23640 09:43:36.280047 semtimedop(43581440, 0x7fff24813d80, 1, {0, 30000000}) = -1 EAGAIN (Resource temporarily unavailable) <0.030853>
23640 09:43:36.311030 semtimedop(43581440, 0x7fff24813d80, 1, {0, 30000000}) = -1 EAGAIN (Resource temporarily unavailable) <0.030873>
23640 09:43:36.342035 semtimedop(43581440, 0x7fff24813d80, 1, {0, 80000000}) = -1 EAGAIN (Resource temporarily unavailable) <0.080866>
23640 09:43:36.423035 semtimedop(43581440, 0x7fff24813d80, 1, {0, 90000000}) = -1 EAGAIN (Resource temporarily unavailable) <0.090863>
23640 09:43:36.514031 semtimedop(43581440, 0x7fff24813d80, 1, {0, 180000000}) = -1 EAGAIN (Resource temporarily unavailable) <0.180894>
23640 09:43:36.695056 semtimedop(43581440, 0x7fff24813d80, 1, {0, 230000000}) = -1 EAGAIN (Resource temporarily unavailable) <0.230866>
23640 09:43:36.926053 semtimedop(43581440, 0x7fff24813d80, 1, {0, 400000000}) = -1 EAGAIN (Resource temporarily unavailable) <0.400880>
23640 09:43:37.327071 semtimedop(43581440, 0x7fff24813d80, 1, {0, 410000000}) = -1 EAGAIN (Resource temporarily unavailable) <0.410827>
23640 09:43:37.738030 semtimedop(43581440, 0x7fff24813d80, 1, {0, 740000000}) = -1 EAGAIN (Resource temporarily unavailable) <0.740943>
23640 09:43:38.479102 getrusage(RUSAGE_SELF, {ru_utime={0, 21996}, ru_stime={0, 30995}, ...}) = 0 <0.000029>
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
--//間隔2秒上下呼叫getrusage.
23640 09:43:38.479233 getrusage(RUSAGE_SELF, {ru_utime={0, 21996}, ru_stime={0, 30995}, ...}) = 0 <0.000025>
23640 09:43:38.479359 semtimedop(43581440, 0x7fff24813d80, 1, {0, 710000000}) = -1 EAGAIN (Resource temporarily unavailable) <0.710692>
23640 09:43:39.190173 semtimedop(43581440, 0x7fff24813d80, 1, {1, 360000000}) = -1 EAGAIN (Resource temporarily unavailable) <1.360780>
23640 09:43:40.551075 getrusage(RUSAGE_SELF, {ru_utime={0, 21996}, ru_stime={0, 30995}, ...}) = 0 <0.000028>
23640 09:43:40.551204 getrusage(RUSAGE_SELF, {ru_utime={0, 21996}, ru_stime={0, 30995}, ...}) = 0 <0.000025>
23640 09:43:40.551330 semtimedop(43581440, 0x7fff24813d80, 1, {1, 370000000}) = -1 EAGAIN (Resource temporarily unavailable) <1.370597>
23640 09:43:41.922044 getrusage(RUSAGE_SELF, {ru_utime={0, 21996}, ru_stime={0, 30995}, ...}) = 0 <0.000028>
23640 09:43:41.922172 getrusage(RUSAGE_SELF, {ru_utime={0, 21996}, ru_stime={0, 30995}, ...}) = 0 <0.000026>
23640 09:43:41.922297 semtimedop(43581440, 0x7fff24813d80, 1, {2, 660000000}) = -1 EAGAIN (Resource temporarily unavailable) <2.660649>
23640 09:43:44.583103 getrusage(RUSAGE_SELF, {ru_utime={0, 22996}, ru_stime={0, 30995}, ...}) = 0 <0.000033>
23640 09:43:44.583236 getrusage(RUSAGE_SELF, {ru_utime={0, 22996}, ru_stime={0, 30995}, ...}) = 0 <0.000026>
23640 09:43:44.583363 semtimedop(43581440, 0x7fff24813d80, 1, {2, 710000000}) = -1 EAGAIN (Resource temporarily unavailable) <2.710690>
23640 09:43:47.294166 getrusage(RUSAGE_SELF, {ru_utime={0, 22996}, ru_stime={0, 30995}, ...}) = 0 <0.000061>
23640 09:43:47.314943 getrusage(RUSAGE_SELF, {ru_utime={0, 22996}, ru_stime={0, 30995}, ...}) = 0 <0.000020>
23640 09:43:47.315069 semtimedop(43581440, 0x7fff24813d80, 1, {5, 0}) = -1 EAGAIN (Resource temporarily unavailable) <5.000956>
23640 09:43:52.316151 getrusage(RUSAGE_SELF, {ru_utime={0, 22996}, ru_stime={0, 30995}, ...}) = 0 <0.000060>