[20190401]关于semtimedop函数调用.txt

喜欢ヅ旅行 2022-01-10 02:53 228阅读 0赞

\[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说明.

转载于:https://www.cnblogs.com/lfree/p/10637207.html