-- Demo case: Researching Oracle RAC cluster wait code instrumentation regarding place holder & block oriented waits -- Date: 06-08-2015 -- References: http://www.apress.com/9781430250449 (Expert Oracle RAC 12c) -- *** Page 303: "After sending a message to LMS process to access a block, an FG process must wait for a response back from LMS process. RAC code is instrumented such that the FG process will wait on a placeholder event such as gc cr request or gc current -- request. The response from LMS process will indicate the type of delay encountered while processing the block. After receiving the response, the FG will account the time correctly to an actual wait event." -- http://www.apress.com/9781430267096 (Expert Oracle RAC Performance Diagnostics and Tuning) -- *** Page 609: "The following waits are defined as place holder events (in a tree graphic): gc cr request, gc current request, gc cr multi block request and gc current multi block request. -- The following waits are defined as block oriented wait events (in a tree graphic as subtree of the place holder events): gc cr block 2-way, gc cr block 3-way, gc current block 2-way, gc current block 3-way, gc remaster." -- Demo run on Oracle version: 12.1.0.2 (2 node RAC cluster) and OEL 3.8.13-35.3.4.el7uek.x86_64 create table TEST as select * from dba_objects; .. or (depending on test data volume, but the wait event situation is always the same) .. create table TEST as select * from dba_objects where rownum < 2000; exec DBMS_STATS.GATHER_TABLE_STATS(NULL,'TEST'); alter system flush buffer_cache; *** Test with FTS (resource master for object TEST is RAC node 2) RAC Node 1 ---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------- alter session set "_serial_direct_read" = 'NEVER'; select /*+ INDEX_RS_ASC(TEST) */ count(owner) from TEST where object_id > 0 ===================== PARSING IN CURSOR #140388294612352 len=77 dep=0 uid=0 oct=3 lid=0 tim=7287084753 hv=4120275366 ad='647acc18' sqlid='5fczadbutcud6' select /*+ INDEX_RS_ASC(TEST) */ count(owner) from TEST where object_id > 0 END OF STMT PARSE #140388294612352:c=13000,e=131544,p=6,cr=23,cu=0,mis=1,r=0,dep=0,og=1,plh=1950795681,tim=7287084750 WAIT #140388294612352: nam='Disk file operations I/O' ela= 32 FileOperation=8 fileno=0 filetype=8 obj#=-1 tim=7287084847 EXEC #140388294612352:c=1000,e=274,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=1950795681,tim=7287085147 WAIT #140388294612352: nam='SQL*Net message to client' ela= 4 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=7287085200 WAIT #140388294612352: nam='gc cr grant 2-way' ela= 443 p1=1 p2=87064 p3=4 obj#=80704 tim=7287085875 WAIT #140388294612352: nam='db file sequential read' ela= 8889 file#=1 block#=87064 blocks=1 obj#=80704 tim=7287095457 WAIT #140388294612352: nam='gc cr multi block request' ela= 1842 file#=1 block#=87071 class#=1 obj#=80704 tim=7287098126 WAIT #140388294612352: nam='db file scattered read' ela= 863 file#=1 block#=87065 blocks=7 obj#=80704 tim=7287099095 WAIT #140388294612352: nam='gc cr multi block request' ela= 975 file#=1 block#=87079 class#=1 obj#=80704 tim=7287100595 WAIT #140388294612352: nam='db file scattered read' ela= 766 file#=1 block#=87072 blocks=8 obj#=80704 tim=7287101418 WAIT #140388294612352: nam='gc cr multi block request' ela= 1142 file#=1 block#=87087 class#=1 obj#=80704 tim=7287103134 WAIT #140388294612352: nam='db file scattered read' ela= 715 file#=1 block#=87080 blocks=8 obj#=80704 tim=7287103894 WAIT #140388294612352: nam='gc cr multi block request' ela= 986 file#=1 block#=87092 class#=1 obj#=80704 tim=7287105262 WAIT #140388294612352: nam='db file scattered read' ela= 537 file#=1 block#=87088 blocks=5 obj#=80704 tim=7287105861 FETCH #140388294612352:c=5000,e=20749,p=29,cr=31,cu=0,mis=0,r=1,dep=0,og=1,plh=1950795681,tim=7287105977 WAIT #140388294612352: nam='SQL*Net message from client' ela= 535 driver id=1650815232 #bytes=1 p3=0 obj#=80704 tim=7287106819 FETCH #140388294612352:c=0,e=4,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,plh=1950795681,tim=7287106867 WAIT #140388294612352: nam='SQL*Net message to client' ela= 4 driver id=1650815232 #bytes=1 p3=0 obj#=80704 tim=7287106896 WAIT #140388294612352: nam='SQL*Net message from client' ela= 438 driver id=1650815232 #bytes=1 p3=0 obj#=80704 tim=7287107389 CLOSE #140388294612352:c=0,e=11,dep=0,type=0,tim=7287107436 ===================== ---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------- RAC Node 2 ---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------- alter session set "_serial_direct_read" = 'NEVER'; select /*+ INDEX_RS_ASC(TEST) */ count(owner) from TEST where object_id > 0 ===================== PARSING IN CURSOR #140705103307600 len=77 dep=0 uid=0 oct=3 lid=0 tim=7287909369 hv=4120275366 ad='638eb458' sqlid='5fczadbutcud6' select /*+ INDEX_RS_ASC(TEST) */ count(owner) from TEST where object_id > 0 END OF STMT PARSE #140705103307600:c=9000,e=10623,p=0,cr=16,cu=0,mis=1,r=0,dep=0,og=1,plh=1950795681,tim=7287909366 WAIT #140705103307600: nam='Disk file operations I/O' ela= 31 FileOperation=8 fileno=0 filetype=8 obj#=0 tim=7287909461 EXEC #140705103307600:c=0,e=44,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=1950795681,tim=7287909536 WAIT #140705103307600: nam='SQL*Net message to client' ela= 4 driver id=1650815232 #bytes=1 p3=0 obj#=0 tim=7287909581 WAIT #140705103307600: nam='gc current block 2-way' ela= 752 p1=1 p2=87064 p3=4 obj#=80704 tim=7287910612 WAIT #140705103307600: nam='gc cr multi block request' ela= 1370 file#=1 block#=87071 class#=1 obj#=80704 tim=7287912738 WAIT #140705103307600: nam='gc cr multi block request' ela= 3829 file#=1 block#=87079 class#=1 obj#=80704 tim=7287917182 WAIT #140705103307600: nam='gc cr multi block request' ela= 7585 file#=1 block#=87087 class#=1 obj#=80704 tim=7287925508 WAIT #140705103307600: nam='gc cr multi block request' ela= 4754 file#=1 block#=87092 class#=1 obj#=80704 tim=7287930713 FETCH #140705103307600:c=7000,e=21501,p=0,cr=31,cu=0,mis=0,r=1,dep=0,og=1,plh=1950795681,tim=7287931109 WAIT #140705103307600: nam='SQL*Net message from client' ela= 443 driver id=1650815232 #bytes=1 p3=0 obj#=80704 tim=7287931651 FETCH #140705103307600:c=0,e=6,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,plh=1950795681,tim=7287931728 WAIT #140705103307600: nam='SQL*Net message to client' ela= 5 driver id=1650815232 #bytes=1 p3=0 obj#=80704 tim=7287931772 WAIT #140705103307600: nam='SQL*Net message from client' ela= 617 driver id=1650815232 #bytes=1 p3=0 obj#=80704 tim=7287932419 CLOSE #140705103307600:c=0,e=16,dep=0,type=0,tim=7287932488 ===================== ---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------- *** Test with index range scan (resource master for object TEST / TEST_I is RAC node 2) create index TEST_I on TEST(object_id); alter system flush buffer_cache; RAC Node 2 ---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------- select /*+ INDEX_RS_ASC(TEST) */ count(owner) from TEST where object_id > 0 ===================== PARSING IN CURSOR #140438630587168 len=77 dep=0 uid=0 oct=3 lid=0 tim=6942186068 hv=4120275366 ad='638eb458' sqlid='5fczadbutcud6' select /*+ INDEX_RS_ASC(TEST) */ count(owner) from TEST where object_id > 0 END OF STMT PARSE #140438630587168:c=0,e=694,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=999326654,tim=6942186064 WAIT #140438630587168: nam='Disk file operations I/O' ela= 89 FileOperation=8 fileno=0 filetype=8 obj#=-1 tim=6942186227 EXEC #140438630587168:c=0,e=112,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=999326654,tim=6942186369 WAIT #140438630587168: nam='SQL*Net message to client' ela= 4 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=6942186421 WAIT #140438630587168: nam='Disk file operations I/O' ela= 295 FileOperation=2 fileno=0 filetype=15 obj#=80705 tim=6942187106 WAIT #140438630587168: nam='db file sequential read' ela= 61350 file#=1 block#=87097 blocks=1 obj#=80705 tim=6942248428 WAIT #140438630587168: nam='db file sequential read' ela= 16441 file#=1 block#=87098 blocks=1 obj#=80705 tim=6942265089 WAIT #140438630587168: nam='db file sequential read' ela= 37841 file#=1 block#=87065 blocks=1 obj#=80704 tim=6942303132 WAIT #140438630587168: nam='db file sequential read' ela= 15022 file#=1 block#=87066 blocks=1 obj#=80704 tim=6942318604 WAIT #140438630587168: nam='db file sequential read' ela= 12292 file#=1 block#=87067 blocks=1 obj#=80704 tim=6942331198 WAIT #140438630587168: nam='db file sequential read' ela= 1006 file#=1 block#=87068 blocks=1 obj#=80704 tim=6942332426 WAIT #140438630587168: nam='db file sequential read' ela= 737 file#=1 block#=87069 blocks=1 obj#=80704 tim=6942333377 WAIT #140438630587168: nam='db file sequential read' ela= 576 file#=1 block#=87070 blocks=1 obj#=80704 tim=6942334116 WAIT #140438630587168: nam='db file sequential read' ela= 440 file#=1 block#=87071 blocks=1 obj#=80704 tim=6942334683 WAIT #140438630587168: nam='db file sequential read' ela= 346 file#=1 block#=87099 blocks=1 obj#=80705 tim=6942335136 WAIT #140438630587168: nam='db file sequential read' ela= 591 file#=1 block#=87072 blocks=1 obj#=80704 tim=6942335826 WAIT #140438630587168: nam='db file sequential read' ela= 428 file#=1 block#=87073 blocks=1 obj#=80704 tim=6942336379 WAIT #140438630587168: nam='db file sequential read' ela= 581 file#=1 block#=87074 blocks=1 obj#=80704 tim=6942337072 WAIT #140438630587168: nam='db file sequential read' ela= 473 file#=1 block#=87075 blocks=1 obj#=80704 tim=6942337654 WAIT #140438630587168: nam='db file sequential read' ela= 57624 file#=1 block#=87076 blocks=1 obj#=80704 tim=6942395449 *** 2015-08-06 14:44:15.094 WAIT #140438630587168: nam='db file sequential read' ela= 13937 file#=1 block#=87077 blocks=1 obj#=80704 tim=6942409660 WAIT #140438630587168: nam='db file sequential read' ela= 49058 file#=1 block#=87078 blocks=1 obj#=80704 tim=6942458958 WAIT #140438630587168: nam='db file sequential read' ela= 1197 file#=1 block#=87100 blocks=1 obj#=80705 tim=6942460429 WAIT #140438630587168: nam='db file sequential read' ela= 572 file#=1 block#=87079 blocks=1 obj#=80704 tim=6942461128 WAIT #140438630587168: nam='db file sequential read' ela= 2382 file#=1 block#=87080 blocks=1 obj#=80704 tim=6942463807 WAIT #140438630587168: nam='db file sequential read' ela= 4518 file#=1 block#=87081 blocks=1 obj#=80704 tim=6942468491 WAIT #140438630587168: nam='db file sequential read' ela= 3207 file#=1 block#=87082 blocks=1 obj#=80704 tim=6942471877 WAIT #140438630587168: nam='db file sequential read' ela= 4867 file#=1 block#=87083 blocks=1 obj#=80704 tim=6942476945 WAIT #140438630587168: nam='db file sequential read' ela= 446 file#=1 block#=87084 blocks=1 obj#=80704 tim=6942477574 WAIT #140438630587168: nam='db file sequential read' ela= 1111 file#=1 block#=87085 blocks=1 obj#=80704 tim=6942478895 WAIT #140438630587168: nam='db file sequential read' ela= 646 file#=1 block#=87101 blocks=1 obj#=80705 tim=6942479805 WAIT #140438630587168: nam='db file sequential read' ela= 756 file#=1 block#=87086 blocks=1 obj#=80704 tim=6942480706 WAIT #140438630587168: nam='db file sequential read' ela= 796 file#=1 block#=87087 blocks=1 obj#=80704 tim=6942481618 WAIT #140438630587168: nam='db file sequential read' ela= 515 file#=1 block#=87088 blocks=1 obj#=80704 tim=6942482264 WAIT #140438630587168: nam='db file sequential read' ela= 15446 file#=1 block#=87089 blocks=1 obj#=80704 tim=6942497818 WAIT #140438630587168: nam='db file sequential read' ela= 833 file#=1 block#=87090 blocks=1 obj#=80704 tim=6942499057 WAIT #140438630587168: nam='db file sequential read' ela= 868 file#=1 block#=87091 blocks=1 obj#=80704 tim=6942500298 WAIT #140438630587168: nam='db file sequential read' ela= 673 file#=1 block#=87102 blocks=1 obj#=80705 tim=6942501144 WAIT #140438630587168: nam='db file sequential read' ela= 528 file#=1 block#=87092 blocks=1 obj#=80704 tim=6942501828 FETCH #140438630587168:c=12000,e=315355,p=34,cr=37,cu=0,mis=0,r=1,dep=0,og=1,plh=999326654,tim=6942501916 WAIT #140438630587168: nam='SQL*Net message from client' ela= 349 driver id=1650815232 #bytes=1 p3=0 obj#=80704 tim=6942502458 FETCH #140438630587168:c=0,e=4,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,plh=999326654,tim=6942502513 WAIT #140438630587168: nam='SQL*Net message to client' ela= 4 driver id=1650815232 #bytes=1 p3=0 obj#=80704 tim=6942502543 WAIT #140438630587168: nam='SQL*Net message from client' ela= 13634 driver id=1650815232 #bytes=1 p3=0 obj#=80704 tim=6942516234 CLOSE #140438630587168:c=0,e=17,dep=0,type=0,tim=6942516340 ===================== ---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------- RAC Node 1 ---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------- select /*+ INDEX_RS_ASC(TEST) */ count(owner) from TEST where object_id > 0 ===================== PARSING IN CURSOR #140295344577312 len=77 dep=0 uid=0 oct=3 lid=0 tim=6947839850 hv=4120275366 ad='647acc18' sqlid='5fczadbutcud6' select /*+ INDEX_RS_ASC(TEST) */ count(owner) from TEST where object_id > 0 END OF STMT PARSE #140295344577312:c=0,e=229,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=999326654,tim=6947839846 WAIT #140295344577312: nam='Disk file operations I/O' ela= 25 FileOperation=8 fileno=0 filetype=8 obj#=-1 tim=6947839926 EXEC #140295344577312:c=0,e=147,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=999326654,tim=6947840099 WAIT #140295344577312: nam='SQL*Net message to client' ela= 4 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=6947840159 WAIT #140295344577312: nam='gc current block 2-way' ela= 995 p1=1 p2=87097 p3=1 obj#=80705 tim=6947841561 WAIT #140295344577312: nam='gc current block 2-way' ela= 1294 p1=1 p2=87098 p3=1 obj#=80705 tim=6947843224 WAIT #140295344577312: nam='gc current block 2-way' ela= 405 p1=1 p2=87065 p3=1 obj#=80704 tim=6947843857 WAIT #140295344577312: nam='gc current block 2-way' ela= 1043 p1=1 p2=87066 p3=1 obj#=80704 tim=6947845410 WAIT #140295344577312: nam='gc current block 2-way' ela= 644 p1=1 p2=87067 p3=1 obj#=80704 tim=6947846322 WAIT #140295344577312: nam='gc current block 2-way' ela= 459 p1=1 p2=87068 p3=1 obj#=80704 tim=6947847203 WAIT #140295344577312: nam='gc current block 2-way' ela= 418 p1=1 p2=87069 p3=1 obj#=80704 tim=6947847976 WAIT #140295344577312: nam='gc current block 2-way' ela= 733 p1=1 p2=87070 p3=1 obj#=80704 tim=6947849279 WAIT #140295344577312: nam='gc current block 2-way' ela= 551 p1=1 p2=87071 p3=1 obj#=80704 tim=6947850207 WAIT #140295344577312: nam='gc current block 2-way' ela= 773 p1=1 p2=87099 p3=1 obj#=80705 tim=6947851275 WAIT #140295344577312: nam='gc current block 2-way' ela= 331 p1=1 p2=87072 p3=1 obj#=80704 tim=6947851940 WAIT #140295344577312: nam='gc current block 2-way' ela= 482 p1=1 p2=87073 p3=1 obj#=80704 tim=6947852787 WAIT #140295344577312: nam='gc current block 2-way' ela= 337 p1=1 p2=87074 p3=1 obj#=80704 tim=6947853667 WAIT #140295344577312: nam='gc current block 2-way' ela= 815 p1=1 p2=87075 p3=1 obj#=80704 tim=6947854760 WAIT #140295344577312: nam='gc current block 2-way' ela= 922 p1=1 p2=87076 p3=1 obj#=80704 tim=6947856247 WAIT #140295344577312: nam='gc current block 2-way' ela= 814 p1=1 p2=87077 p3=1 obj#=80704 tim=6947857320 WAIT #140295344577312: nam='gc current block 2-way' ela= 411 p1=1 p2=87078 p3=1 obj#=80704 tim=6947857949 WAIT #140295344577312: nam='gc current block 2-way' ela= 505 p1=1 p2=87100 p3=1 obj#=80705 tim=6947858750 WAIT #140295344577312: nam='gc current block 2-way' ela= 360 p1=1 p2=87079 p3=1 obj#=80704 tim=6947859298 WAIT #140295344577312: nam='gc current block 2-way' ela= 632 p1=1 p2=87080 p3=1 obj#=80704 tim=6947860341 WAIT #140295344577312: nam='gc current block 2-way' ela= 1129 p1=1 p2=87081 p3=1 obj#=80704 tim=6947861813 WAIT #140295344577312: nam='gc current block 2-way' ela= 479 p1=1 p2=87082 p3=1 obj#=80704 tim=6947862494 WAIT #140295344577312: nam='gc current block 2-way' ela= 1083 p1=1 p2=87083 p3=1 obj#=80704 tim=6947863864 WAIT #140295344577312: nam='gc current block 2-way' ela= 446 p1=1 p2=87084 p3=1 obj#=80704 tim=6947864542 WAIT #140295344577312: nam='gc current block 2-way' ela= 894 p1=1 p2=87085 p3=1 obj#=80704 tim=6947865701 WAIT #140295344577312: nam='gc current block 2-way' ela= 650 p1=1 p2=87101 p3=1 obj#=80705 tim=6947866519 WAIT #140295344577312: nam='gc current block 2-way' ela= 594 p1=1 p2=87086 p3=1 obj#=80704 tim=6947867319 WAIT #140295344577312: nam='gc current block 2-way' ela= 677 p1=1 p2=87087 p3=1 obj#=80704 tim=6947868247 WAIT #140295344577312: nam='gc current block 2-way' ela= 649 p1=1 p2=87088 p3=1 obj#=80704 tim=6947869146 WAIT #140295344577312: nam='gc current block 2-way' ela= 490 p1=1 p2=87089 p3=1 obj#=80704 tim=6947869854 WAIT #140295344577312: nam='gc current block 2-way' ela= 704 p1=1 p2=87090 p3=1 obj#=80704 tim=6947870933 WAIT #140295344577312: nam='gc current block 2-way' ela= 791 p1=1 p2=87091 p3=1 obj#=80704 tim=6947872452 WAIT #140295344577312: nam='gc current block 2-way' ela= 921 p1=1 p2=87102 p3=1 obj#=80705 tim=6947873651 WAIT #140295344577312: nam='gc current block 2-way' ela= 684 p1=1 p2=87092 p3=1 obj#=80704 tim=6947874619 FETCH #140295344577312:c=20000,e=34603,p=0,cr=37,cu=0,mis=0,r=1,dep=0,og=1,plh=999326654,tim=6947874790 WAIT #140295344577312: nam='SQL*Net message from client' ela= 404 driver id=1650815232 #bytes=1 p3=0 obj#=80704 tim=6947875378 FETCH #140295344577312:c=0,e=4,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,plh=999326654,tim=6947875424 WAIT #140295344577312: nam='SQL*Net message to client' ela= 3 driver id=1650815232 #bytes=1 p3=0 obj#=80704 tim=6947875455 *** 2015-08-06 14:44:18.594 WAIT #140295344577312: nam='SQL*Net message from client' ela= 664734 driver id=1650815232 #bytes=1 p3=0 obj#=80704 tim=6948540249 CLOSE #140295344577312:c=0,e=26,dep=0,type=0,tim=6948540475 ===================== ----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------