[20190401]關於semtimedop函式呼叫.txt

[20190401]關於semtimedop函式呼叫.txt

--//上個星期測試,連結http://blog.itpub.net/267265/viewspace-2639675/

--//關於sql語句中mutexes的問題,實際上僅僅涉及cursor: pin S.

--//我的測試說明這個mutexes在父游標的堆0中.

--//我當時相當然認為:

16:04:56.410785 semtimedop(309166080, 0x7fff83068fd0, 1, {0, 10000000}) = -1 EAGAIN (Resource temporarily unavailable) <0.010684>

--//{0, 10000000} 是 timespec. 前面單位是秒,後面單位是納秒(毫微秒) 1秒=10^9納秒, 10000000/10^9 = .01.

--//這樣每次呼叫semtimedop需要0.010xXX秒.

--//我的理解相當於不斷spin,檢查這個資源是否可用.2秒後呼叫getrusage.

--//我一直以為0.010684秒中的0.000684秒是spin的時間,犯了一個嚴重錯誤,主要不熟悉os函式呼叫.

--//實際上semtimedop函式呼叫.裡面的{0, 10000000}定義的是最大延遲，即睡眠。這裡是0.01是秒(注後面的單位是納秒).

--//做一個測試就很容易理解:

1.環境:

SCOTT@test> @ &r/ver1

PORT_STRING                    VERSION        BANNER

------------------------------ -------------- ----------------------------------------------------------------

x86_64/Linux 2.4.xx            10.2.0.4.0     Oracle Database 10g Enterprise Edition Release 10.2.0.4.0 - 64bi

--//注10g下好觀察一些.

2.測試:

$ ps -ef | grep ora_lgwr_tes[t]

oracle   19051     1  0 Mar20 ?        00:00:03 ora_lgwr_test

# strace -frT -e semtimedop -p 19051

Process 19051 attached - interrupt to quit

     0.000000 semtimedop(12320769, 0x7fff1bef85b0, 1, {2, 410000000}) = -1 EAGAIN (Resource temporarily unavailable) <2.411183>

     2.411526 semtimedop(12320769, 0x7fff1bef85b0, 1, {3, 0}) = -1 EAGAIN (Resource temporarily unavailable) <3.001731>

     3.002135 semtimedop(12320769, 0x7fff1bef85b0, 1, {3, 0}) = -1 EAGAIN (Resource temporarily unavailable) <3.001646>

     3.001937 semtimedop(12320769, 0x7fff1bef85b0, 1, {3, 0}) = -1 EAGAIN (Resource temporarily unavailable) <3.001758>

     3.002166 semtimedop(12320769, 0x7fff1bef85b0, 1, {3, 0}) = -1 EAGAIN (Resource temporarily unavailable) <3.001638>

...

--//在沒有任何事務的情況下,延遲3秒.開啟一個會話執行如下:

SCOTT@test> select * from t for update;

        ID

----------

         1

SCOTT@test> commit;

Commit complete.

# strace -frT -e semtimedop -p 19051

...

     3.001200 semtimedop(12320769, 0x7fff1bef85b0, 1, {3, 0}) = -1 EAGAIN (Resource temporarily unavailable) <3.001597>

     3.001884 semtimedop(12320769, 0x7fff1bef85b0, 1, {3, 0}) = -1 EAGAIN (Resource temporarily unavailable) <3.000763>

     3.001165 semtimedop(12320769, 0x7fff1bef85b0, 1, {3, 0}) = -1 EAGAIN (Resource temporarily unavailable) <3.001639>

     3.001925 semtimedop(12320769, 0x7fff1bef85b0, 1, {3, 0}) = -1 EAGAIN (Resource temporarily unavailable) <3.001772>

     3.002179 semtimedop(12320769, 0x7fff1bef85b0, 1, {3, 0}) = -1 EAGAIN (Resource temporarily unavailable) <3.001661>

     3.001949 semtimedop(12320769, 0x7fff1bef85b0, 1, {3, 0}) = -1 EAGAIN (Resource temporarily unavailable) <3.001761>

     3.002166 semtimedop(12320769, 0x7fff1bef85b0, 1, {3, 0}) = 0 <1.433330>

~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~  

     1.433937 semtimedop(12320769, 0x7fff1bef85b0, 1, {1, 570000000}) = -1 EAGAIN (Resource temporarily unavailable) <1.571702>

     1.572208 semtimedop(12320769, 0x7fff1bef85b0, 1, {3, 0}) = -1 EAGAIN (Resource temporarily unavailable) <3.001549>

     3.001953 semtimedop(12320769, 0x7fff1bef85b0, 1, {3, 0}) = -1 EAGAIN (Resource temporarily unavailable) <3.000633>

     3.000920 semtimedop(12320769, 0x7fff1bef85b0, 1, {3, 0}) = -1 EAGAIN (Resource temporarily unavailable) <3.000752>

     3.001153 semtimedop(12320769, 0x7fff1bef85b0, 1, {3, 0} <unfinished ...>

--//注意看下劃線那行,如果有事務執行並提交,並沒有等待3秒就喚醒了寫日誌程式.

3.繼續測試:

--//再做一個測試看看:

$ cat b1.txt

host sleep 10

select t.*,systimestamp from t for update;

host sleep 10

select systimestamp from dual;

commit ;

select systimestamp from dual;

quit

# strace -fttT -e semtimedop -p 19051

...

$ sqlplus -s -l scott/btbtms @b1.txt

        ID SYSTIMESTAMP

---------- ---------------------------------

         1 2019-04-01 11:40:45.895129 +08:00

SYSTIMESTAMP

---------------------------------

2019-04-01 11:40:55.903089 +08:00

Commit complete.

SYSTIMESTAMP

---------------------------------

2019-04-01 11:40:55.905283 +08:00

# strace -fttT -e semtimedop -p 19051

...

11:40:40.857303 semtimedop(12320769, 0x7fff1bef85b0, 1, {3, 0}) = -1 EAGAIN (Resource temporarily unavailable) <3.000738>

11:40:43.858463 semtimedop(12320769, 0x7fff1bef85b0, 1, {3, 0}) = -1 EAGAIN (Resource temporarily unavailable) <3.000628>

11:40:46.859403 semtimedop(12320769, 0x7fff1bef85b0, 1, {3, 0}) = -1 EAGAIN (Resource temporarily unavailable) <3.000740>

11:40:49.860569 semtimedop(12320769, 0x7fff1bef85b0, 1, {3, 0}) = -1 EAGAIN (Resource temporarily unavailable) <3.000629>

11:40:52.861505 semtimedop(12320769, 0x7fff1bef85b0, 1, {3, 0}) = -1 EAGAIN (Resource temporarily unavailable) <3.000749>

11:40:55.862679 semtimedop(12320769, 0x7fff1bef85b0, 1, {3, 0}) = 0 <0.041530>

~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~

11:40:55.904831 semtimedop(12320769, 0x7fff1bef85b0, 1, {2, 960000000}) = -1 EAGAIN (Resource temporarily unavailable) <2.961459>

11:40:58.866605 semtimedop(12320769, 0x7fff1bef85b0, 1, {3, 0}) = -1 EAGAIN (Resource temporarily unavailable) <3.000734>

11:41:01.867766 semtimedop(12320769, 0x7fff1bef85b0, 1, {3, 0}) = -1 EAGAIN (Resource temporarily unavailable) <3.000631>

11:41:04.868703 semtimedop(12320769, 0x7fff1bef85b0, 1, {3, 0}) = -1 EAGAIN (Resource temporarily unavailable) <3.000733>

11:41:07.869856 semtimedop(12320769, 0x7fff1bef85b0, 1, {3, 0}) = -1 EAGAIN (Resource temporarily unavailable) <3.001637>

11:41:10.871801 semtimedop(12320769, 0x7fff1bef85b0, 1, {3, 0}) = -1 EAGAIN (Resource temporarily unavailable) <3.000741>

11:41:13.872963 semtimedop(12320769, 0x7fff1bef85b0, 1, {3, 0}) = -1 EAGAIN (Resource temporarily unavailable) <3.001630>

11:41:16.874922 semtimedop(12320769, 0x7fff1bef85b0, 1, {3, 0}) = -1 EAGAIN (Resource temporarily unavailable) <3.001737>

11:41:19.877089 semtimedop(12320769, 0x7fff1bef85b0, 1, {3, 0}) = -1 EAGAIN (Resource temporarily unavailable) <3.001619>

--//commit的時間在2019-04-01 11:40:55.903089- 2019-04-01 11:40:55.905283 之間.

--//strace看到的時間是       11:40:55.904831 ,正好在前面兩個時間之間.

--//注意下劃線這行顯示11:40:55.862679 semtimedop(12320769, 0x7fff1bef85b0, 1, {3, 0}) = 0 <0.041530> 的時間不是提交時間.

--//這行前面的時間是開始執行semtimedop呼叫的時間,在0.041530秒後有事務提交,喚醒.

--//0.862679+0.041530 = .904209,也就是11:40:55.904209 這行呼叫執行結束.

--//在11:40:55.904831開始執行新的semtimedop呼叫.

--//也就是commit應該在11:40:55.904209 - 11:40:55.904831 之間.

4.補充11g的lgwr程式的跟蹤:

$ ps -ef | grep ora_lgwr_boo[k]

oracle   56345     1  0 08:38 ?        00:00:02 ora_lgwr_book

$ strace -e semtimedop -fTr -p 56345

Process 56345 attached - interrupt to quit

     0.000000 semtimedop(309821440, 0x7fff39b50600, 1, {2, 980000000}) = 0 <0.629618>

     0.629992 semtimedop(309821440, 0x7fff39b50600, 1, {2, 350000000}) = 0 <1.000813>

     1.001257 semtimedop(309821440, 0x7fff39b50600, 1, {1, 350000000}) = 0 <1.000513>

     1.000871 semtimedop(309821440, 0x7fff39b50600, 1, {0, 350000000}) = -1 EAGAIN (Resource temporarily unavailable) <0.350287>

     0.350597 semtimedop(309821440, 0x7fff39b50600, 1, {3, 0}) = 0 <0.649906>

     0.650342 semtimedop(309821440, 0x7fff39b50600, 1, {2, 350000000}) = 0 <1.000628>

     1.000987 semtimedop(309821440, 0x7fff39b50600, 1, {1, 350000000}) = 0 <1.000696>

     1.001135 semtimedop(309821440, 0x7fff39b50600, 1, {0, 350000000}) = -1 EAGAIN (Resource temporarily unavailable) <0.350213>

     0.350491 semtimedop(309821440, 0x7fff39b50600, 1, {3, 0}) = 0 <0.649969>

     0.650330 semtimedop(309821440, 0x7fff39b50600, 1, {2, 350000000}) = 0 <1.000795>

     1.001246 semtimedop(309821440, 0x7fff39b50600, 1, {1, 350000000}) = 0 <1.000516>

     1.000890 semtimedop(309821440, 0x7fff39b50600, 1, {0, 350000000}) = -1 EAGAIN (Resource temporarily unavailable) <0.350268>

     0.350541 semtimedop(309821440, 0x7fff39b50600, 1, {3, 0}) = 0 <0.649974>

     0.650411 semtimedop(309821440, 0x7fff39b50600, 1, {2, 350000000}) = 0 <1.000721>

     1.001088 semtimedop(309821440, 0x7fff39b50600, 1, {1, 350000000}) = 0 <1.000562>

     1.001006 semtimedop(309821440, 0x7fff39b50600, 1, {0, 350000000}) = -1 EAGAIN (Resource temporarily unavailable) <0.350197>

     0.350476 semtimedop(309821440, 0x7fff39b50600, 1, {3, 0}) = 0 <0.649954>

     0.650309 semtimedop(309821440, 0x7fff39b50600, 1, {2, 350000000}) = 0 <1.000833>

     1.001281 semtimedop(309821440, 0x7fff39b50600, 1, {1, 350000000}) = 0 <1.000374>

     1.000735 semtimedop(309821440, 0x7fff39b50600, 1, {0, 350000000}) = -1 EAGAIN (Resource temporarily unavailable) <0.350394>

     0.350669 semtimedop(309821440, 0x7fff39b50600, 1, {3, 0}) = 0 <0.649987>

     0.650427 semtimedop(309821440, 0x7fff39b50600, 1, {2, 350000000}) = 0 <1.000708>

     1.001073 semtimedop(309821440, 0x7fff39b50600, 1, {1, 350000000}) = 0 <1.000603>

     1.001057 semtimedop(309821440, 0x7fff39b50600, 1, {0, 350000000}) = -1 EAGAIN (Resource temporarily unavailable) <0.350159>

     0.350610 semtimedop(309821440, 0x7fff39b50600, 1, {3, 0}) = 0 <0.649828>

     0.650185 semtimedop(309821440, 0x7fff39b50600, 1, {2, 350000000}) = 0 <1.000709>

     1.001164 semtimedop(309821440, 0x7fff39b50600, 1, {1, 350000000}) = 0 <1.000611>

     1.000971 semtimedop(309821440, 0x7fff39b50600, 1, {0, 340000000}) = -1 EAGAIN (Resource temporarily unavailable) <0.340228>

     0.340497 semtimedop(309821440, 0x7fff39b50600, 1, {3, 0}) = 0 <0.659984>

     0.660416 semtimedop(309821440, 0x7fff39b50600, 1, {2, 340000000}) = 0 <1.000653>

     1.001011 semtimedop(309821440, 0x7fff39b50600, 1, {1, 340000000}) = 0 <1.000685>

     1.001131 semtimedop(309821440, 0x7fff39b50600, 1, {0, 340000000}) = -1 EAGAIN (Resource temporarily unavailable) <0.340188>

     0.340463 semtimedop(309821440, 0x7fff39b50600, 1, {3, 0}) = 0 <0.659989>

     0.660341 semtimedop(309821440, 0x7fff39b50600, 1, {2, 340000000}) = 0 <1.000807>

     1.001257 semtimedop(309821440, 0x7fff39b50600, 1, {1, 340000000}) = 0 <1.000387>

     1.000759 semtimedop(309821440, 0x7fff39b50600, 1, {0, 340000000}) = -1 EAGAIN (Resource temporarily unavailable) <0.340378>

     0.340654 semtimedop(309821440, 0x7fff39b50600, 1, {3, 0}) = 0 <0.659976>

     0.660422 semtimedop(309821440, 0x7fff39b50600, 1, {2, 340000000}) = 0 <1.000706>

     1.001074 semtimedop(309821440, 0x7fff39b50600, 1, {1, 340000000}) = 0 <1.000505>

     1.000949 semtimedop(309821440, 0x7fff39b50600, 1, {0, 340000000}) = -1 EAGAIN (Resource temporarily unavailable) <0.340262>

     0.340545 semtimedop(309821440, 0x7fff39b50600, 1, {3, 0}) = 0 <0.660729>

     0.661088 semtimedop(309821440, 0x7fff39b50600, 1, {2, 340000000}) = 0 <1.001027>

     1.001473 semtimedop(309821440, 0x7fff39b50600, 1, {1, 330000000}) = 0 <1.000509>

     1.000870 semtimedop(309821440, 0x7fff39b50600, 1, {0, 330000000}) = -1 EAGAIN (Resource temporarily unavailable) <0.330292>

     0.330581 semtimedop(309821440, 0x7fff39b50600, 1, {3, 0}) = 0 <0.669970>

     0.670416 semtimedop(309821440, 0x7fff39b50600, 1, {2, 330000000}) = 0 <1.000633>

     1.001002 semtimedop(309821440, 0x7fff39b50600, 1, {1, 330000000}) = 0 <1.000676>

     1.001127 semtimedop(309821440, 0x7fff39b50600, 1, {0, 330000000}) = -1 EAGAIN (Resource temporarily unavailable) <0.330172>

     0.330447 semtimedop(309821440, 0x7fff39b50600, 1, {3, 0}) = 0 <0.669963>

     0.670316 semtimedop(309821440, 0x7fff39b50600, 1, {2, 330000000}^C <unfinished ...>

Process 56345 detached

--//還記得連結:http://blog.itpub.net/267265/viewspace-2638170/的測試嗎?

--//在沒有事務的情況下.每秒scn增加1,日誌塊增加1,我開始懷疑是否跟我訪問這些記憶體"表"有關.

--//換1個方式測試,取消check.sql後面的host sleep 1,改成sleep 30後,看到的情況每秒scn增加1,日誌塊增加1.

--//從跟蹤上也基本驗證我看到的情況.11G會"空轉",導致在沒有事務產生的情況下,日誌也在不斷增加.

--//這樣11g的日誌即使是很空閒的資料庫日誌增加也會比10g大.

5.最後:

--//理解這些就知道如何測試11g下mutext相關隱含引數,特別是_mutex_spin_count:

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> @ hide mutex

NAME               DESCRIPTION        DEFAULT_VALUE SESSION_VALUE SYSTEM_VALUE

------------------ ------------------ ------------- ------------- -------------

_mutex_spin_count  Mutex spin count   TRUE          255           255

_mutex_wait_scheme Mutex wait scheme  TRUE          2             2

_mutex_wait_time   Mutex wait time    TRUE          1             1

--//另外寫一篇blog說明.