[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/ver1PORT_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 19051Process 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---------- 1SCOTT@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.txthost sleep 10select t.*,systimestamp from t for update;host sleep 10select 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:00SYSTIMESTAMP---------------------------------2019-04-01 11:40:55.903089 +08:00Commit 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 56345Process 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> @ ver1PORT_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 ProductionSYS@book> @ hide mutexNAME 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说明.