23c–Fine Grained Locking–Lock Free Reservations - behind the scene

 Oracle 23c has a very interesting feature: Lock Free Reservations. There are great posts already which explain this feature, I'm more interested on the activities behind. For this post, please first read this article. My tests are following it's structure. 

In addition to the SQLs I also enabled SQL_TRACE.

But as the raw trace isn't easy to read at all, I processed them with mrskew - to be specific with a slightly modified calls.rc to get the sequence and dependency of SQLs. A specific SQL can generate some other calls in the background - this is indicated by the dep=x entries in the tracefile - in the parsed output it's shown as indent of the statement. 
I will reduce the content to a minimum to keep the post readable - the full tracefiles and parsed output can be found here. 

Back to Lock Free Reservations - following Lucas' method:

0 - CREATE TABLE 

14:49:39 SESSION_A > CREATE TABLE TICKETSALES(
  2  ID NUMBER PRIMARY KEY,
  3  NAME VARCHAR2(100),
  4  CAPACITY NUMBER RESERVABLE CONSTRAINT MINIMUM_CAPACITY CHECK (CAPACITY >= 10)
  5* );

Table TICKETSALES created.

14:49:39 SESSION_A >

this simple statement leads to a LOT of activities:

                   END-TIMe       LINE   PARSE-ID    EXEC-ID  CALL-NAME(BOUND-VALUES)                  STATEMENT-TEXT                                
-----------------------------------------------------------------------------------------------------------------------------------------------------
 2023-10-26T14:49:39.434617        309        309          0  PARSE                                    CREATE TABLE TICKETSALES( ID NUMBER PRIMARY KE
 2023-10-26T14:49:39.435165        327        164        327  · EXEC(1,"TICKETSALES",1)                · select obj#,type#,ctime,mtime,stime, status,
 2023-10-26T14:49:39.435714        342        334        342  · EXEC(98174)                            · select o.owner#,o.name,o.namespace,o.remoteo
 2023-10-26T14:49:39.435971        352        351        352  · EXEC                                   · select obj# from objerror$                  
 2023-10-26T14:49:39.440226        376        362        376  · EXEC("TICKETSALES","BERX")             · select obj#, owner, node from syn$ where nam
 2023-10-26T14:49:39.444092        395        385        395  · EXEC("TICKETSALES")                    · select user#,password,datats#,tempts#,type#,
 2023-10-26T14:49:39.450749        543        404        543  · EXEC(131,"TICKETSALES",1,98174,2,"10/2 · insert into obj$(owner#,name,namespace,obj#,
 2023-10-26T14:49:39.452329        552        550        552  · · EXEC                                 · · select 1 from dba_tables where owner = 'SY
 2023-10-26T14:49:39.455737        629        621        629  · · EXEC("BERX")                         · · select 1 from sys.bc$ bc, sys.user$ ur whe
 2023-10-26T14:49:39.456191        637        636        637  · · EXEC                                 · · select 1 from dba_tables where owner = 'SY
 2023-10-26T14:49:39.456597        648        640        648  · · EXEC("BERX")                         · · select 1 from sys.bc$ bc, sys.user$ ur whe
 2023-10-26T14:49:39.456992        655        655          0  · PARSE                                  · create table BERX.SYS_RESERVJRNL_98174 (ORA_
 2023-10-26T14:49:39.457295        673        164        673  · · EXEC(131,"SYS_RESERVJRNL_98174",1)   · · select obj#,type#,ctime,mtime,stime, statu
 2023-10-26T14:49:39.457786        693        164        693  · · EXEC(1,"SYS_RESERVJRNL_98174",1)     · · select obj#,type#,ctime,mtime,stime, statu
 2023-10-26T14:49:39.466683        832        700        832  · · EXEC(1,0,"3/26/2023 2:26:24","10/26/ · · update obj$ set obj#=:4, type#=:5,ctime=:6
 2023-10-26T14:49:39.467141        843        334        843  · · EXEC(98175)                          · · select o.owner#,o.name,o.namespace,o.remot
 2023-10-26T14:49:39.467702        851        850        851  · · EXEC                                 · · select obj# from objerror$                
 2023-10-26T14:49:39.469494        872        859        872  · · EXEC("SYS_RESERVJRNL_98174","BERX")  · · select obj#, owner, node from syn$ where n
 2023-10-26T14:49:39.469915        884        385        884  · · EXEC("SYS_RESERVJRNL_98174")         · · select user#,password,datats#,tempts#,type
 2023-10-26T14:49:39.471682       1025        404       1025  · · EXEC(131,"SYS_RESERVJRNL_98174",1,98 · · insert into obj$(owner#,name,namespace,obj
 2023-10-26T14:49:39.474984       1039       1031       1039  · · · EXEC(81)                           · · · select annotation_name, annotation_value
 2023-10-26T14:49:39.477871       1056       1048       1056  · · · EXEC(81)                           · · · select con#,obj#,rcon#,enabled,nvl(defer
 2023-10-26T14:49:39.482689       1073       1065       1073  · · · EXEC(81)                           · · · select con#,type#,condlength,intcols,rob
 2023-10-26T14:49:39.482904       1087       1079       1087  · · · EXEC(188)                          · · · select intcol#,nvl(pos#,0),col#,nvl(spar
 2023-10-26T14:49:39.483590       1111       1101       1111  · · · EXEC(81)                           · · · select col#, grantee#, privilege#,max(mo
 2023-10-26T14:49:39.483848       1129       1121       1129  · · · EXEC(81)                           · · · select grantee#,privilege#,nvl(col#,0),m
 2023-10-26T14:49:39.485398       1249       1139       1249  · · EXEC(98175,,,,2,2,,,,,,,,,,,,16392,, · · insert into deferred_stg$ (obj#, pctfree_s
 2023-10-26T14:49:39.487987       1269       1256       1269  · · EXEC(131,"SYS_C008243")              · · select con#,spare1 from con$ where owner#=
 2023-10-26T14:49:39.490429       1301       1278       1301  · · EXEC(131,"SYS_C008243",8243,0)       · · insert into con$(owner#,name,con#,spare1)v
 2023-10-26T14:49:39.492926       1316       1308       1316  · · EXEC(8243)                           · · delete from con$recycle where con#=:1     
 2023-10-26T14:49:39.498339       1515       1324       1515  · · EXEC(98175,6,0,0,0,,0,,7,7,0,,"----- · · insert into tab$(obj#,ts#,file#,block#,bob
 2023-10-26T14:49:39.504496       1710       1522       1710  · · EXEC(98175,"ORA_SAGA_ID$",1,1,23,16, · · insert into col$(obj#,name,intcol#,segcol#
 2023-10-26T14:49:39.506437       1898       1522       1898  · · EXEC(98175,"ORA_TXN_ID$",2,2,23,8,,0 · · insert into col$(obj#,name,intcol#,segcol#
 2023-10-26T14:49:39.509384       2085       1522       2085  · · EXEC(98175,"ORA_STATUS$",3,3,96,12,, · · insert into col$(obj#,name,intcol#,segcol#
 2023-10-26T14:49:39.512042       2272       1522       2272  · · EXEC(98175,"ORA_STMT_TYPE$",4,4,96,1 · · insert into col$(obj#,name,intcol#,segcol#
 2023-10-26T14:49:39.513666       2459       1522       2459  · · EXEC(98175,"ID",5,5,2,22,,0,,,,,-127 · · insert into col$(obj#,name,intcol#,segcol#
 2023-10-26T14:49:39.516135       2646       1522       2646  · · EXEC(98175,"CAPACITY_OP",6,6,96,7,,0 · · insert into col$(obj#,name,intcol#,segcol#
 2023-10-26T14:49:39.516954       2833       1522       2833  · · EXEC(98175,"CAPACITY_RESERVED",7,7,2 · · insert into col$(obj#,name,intcol#,segcol#
 2023-10-26T14:49:39.520255       2874       2839       2874  · · EXEC(8243,98175,5,0,,5,0)            · · insert into ccol$(con#,obj#,intcol#,pos#,c
 2023-10-26T14:49:39.523326       2985       2881       2985  · · EXEC(98175,8243,7,1,,16,,""ID" IS NO · · insert into cdef$(obj#,con#,type#,intcols,
 2023-10-26T14:49:39.523695       2989       2988       2989  · · EXEC                                 · · select 1 from dba_tables where owner = 'SY
 2023-10-26T14:49:39.524253       3000       2992       3000  · · EXEC("BERX")                         · · select 1 from sys.bc$ bc, sys.user$ ur whe
 2023-10-26T14:49:39.532592       3033       3007       3033  · · EXEC(76530)                          · · select owner#,name,namespace,remoteowner,l
 2023-10-26T14:49:39.536179       3060       3052       3060  · · EXEC(76530)                          · · select order#,columns,types from access$ w
 2023-10-26T14:49:39.536500       3078       3070       3078  · · EXEC(76530)                          · · select actionsize from trigger$ where obj#
 2023-10-26T14:49:39.536800       3095       3087       3095  · · EXEC(76530)                          · · select action# from trigger$ where obj# = 
 2023-10-26T14:49:39.537322       3112       3104       3112  · · EXEC(76530)                          · · select baseobject,type#,update$,insert$,de
 2023-10-26T14:49:39.538067       3169       3121       3169  · · EXEC(76530,0,0,0,0,0,76530,1001,7653 · · select tc.type#,tc.intcol#,tc.position#,c.
 2023-10-26T14:49:39.539134       3199       3191       3199  · · EXEC(76530)                          · · select case when (bitand(u.spare1, 16) = 0
 2023-10-26T14:49:39.539757       3208        655       3208  · EXEC                                   · create table BERX.SYS_RESERVJRNL_98174 (ORA_
 2023-10-26T14:49:39.541061       3330       1256       3330  · EXEC(131,"SYS_C008244")                · select con#,spare1 from con$ where owner#=:1
 2023-10-26T14:49:39.541381       3355       1278       3355  · EXEC(131,"SYS_C008244",8244,0)         · insert into con$(owner#,name,con#,spare1)val
 2023-10-26T14:49:39.541466       3364       1308       3364  · EXEC(8244)                             · delete from con$recycle where con#=:1       
 2023-10-26T14:49:39.541624       3378       1256       3378  · EXEC(131,"MINIMUM_CAPACITY")           · select con#,spare1 from con$ where owner#=:1
 2023-10-26T14:49:39.541755       3393       1256       3393  · EXEC(0,"_NEXT_CONSTRAINT")             · select con#,spare1 from con$ where owner#=:1
 2023-10-26T14:49:39.546000       3423       3400       3423  · EXEC(8250,0,0,"_NEXT_CONSTRAINT")      · update con$ set con#=:3,spare1=:4 where owne
 2023-10-26T14:49:39.546560       3449       1278       3449  · EXEC(131,"MINIMUM_CAPACITY",8245,0)    · insert into con$(owner#,name,con#,spare1)val
 2023-10-26T14:49:39.547694       3458       1308       3458  · EXEC(8245)                             · delete from con$recycle where con#=:1       
 2023-10-26T14:49:39.548030       3472       1256       3472  · EXEC(131,"SYS_C008246")                · select con#,spare1 from con$ where owner#=:1
 2023-10-26T14:49:39.548358       3497       1278       3497  · EXEC(131,"SYS_C008246",8246,0)         · insert into con$(owner#,name,con#,spare1)val
 2023-10-26T14:49:39.548454       3506       1308       3506  · EXEC(8246)                             · delete from con$recycle where con#=:1       
 2023-10-26T14:49:39.550422       3520       3512       3520  · · EXEC(98174)                          · · select pctfree_stg, pctused_stg, size_stg,
 2023-10-26T14:49:39.551848       3542       3529       3542  · · EXEC(98174,1)                        · · select /*+ rule */ bucket_cnt, row_cnt, ca
 2023-10-26T14:49:39.552463       3551       3551          0  · PARSE                                  · CREATE UNIQUE INDEX "BERX"."SYS_C008246" on 
 2023-10-26T14:49:39.553196       3576       3558       3576  · · EXEC("BERX","TICKETSALES","PUBLISH") · · select p.valchar from sys.optstat_user_pre
 2023-10-26T14:49:39.554124       3598       3590       3598  · · EXEC("PUBLISH")                      · · select /*+ no_parallel */ spare4 from sys.
 2023-10-26T14:49:39.554385       3618        164       3618  · · EXEC(131,"SYS_C008246",4)            · · select obj#,type#,ctime,mtime,stime, statu
 2023-10-26T14:49:39.554526       3628        334       3628  · · EXEC(98176)                          · · select o.owner#,o.name,o.namespace,o.remot
 2023-10-26T14:49:39.554625       3632       3631       3632  · · EXEC                                 · · select obj# from objerror$                
 2023-10-26T14:49:39.554806       3642        385       3642  · · EXEC("SYS_C008246")                  · · select user#,password,datats#,tempts#,type
 2023-10-26T14:49:39.556352       3783        404       3783  · · EXEC(131,"SYS_C008246",4,98176,1,"10 · · insert into obj$(owner#,name,namespace,obj
 2023-10-26T14:49:39.557560       3912        700       3912  · · EXEC(98175,2,"10/26/2023 14:49:39"," · · update obj$ set obj#=:4, type#=:5,ctime=:6
 2023-10-26T14:49:39.558893       4026       1139       4026  · · EXEC(98176,10,,,,,,,,,,,2,255,,,,0,, · · insert into deferred_stg$ (obj#, pctfree_s
 2023-10-26T14:49:39.559206       4049       4031       4049  · · EXEC("BERX","TICKETSALES","PUBLISH") · · select p.valchar from sys.optstat_user_pre
 2023-10-26T14:49:39.559370       4059       4051       4059  · · EXEC("PUBLISH")                      · · select /*+ no_parallel */ spare4 from sys.
 2023-10-26T14:49:39.563126       4074       4066       4074  · · EXEC(98174)                          · · select parttype, partcnt, partkeycols, fla
 2023-10-26T14:49:39.563253       4079       3551       4079  · EXEC                                   · CREATE UNIQUE INDEX "BERX"."SYS_C008246" on 
 2023-10-26T14:49:39.566973       4133       4088       4131  · CLOSE(98176,98174,1,1,1,0,0,0)         · insert into icol$(obj#,bo#,intcol#,pos#,segc
 2023-10-26T14:49:39.571249       4317       4138       4317  · EXEC(98174,98176,6,0,0,1,1,67108864,40 · insert into ind$(bo#,obj#,ts#,file#,block#,i
 2023-10-26T14:49:39.572322       4510       1324       4510  · EXEC(98174,6,0,0,0,,0,,3,3,0,,"------- · insert into tab$(obj#,ts#,file#,block#,bobj#
 2023-10-26T14:49:39.573326       4697       1522       4697  · EXEC(98174,"ID",1,1,2,22,,0,,,,,-127,, · insert into col$(obj#,name,intcol#,segcol#,t
 2023-10-26T14:49:39.575378       4884       1522       4884  · EXEC(98174,"NAME",2,2,1,100,,0,,,,,0,, · insert into col$(obj#,name,intcol#,segcol#,t
 2023-10-26T14:49:39.576473       5071       1522       5071  · EXEC(98174,"CAPACITY",3,3,2,22,,0,,,,, · insert into col$(obj#,name,intcol#,segcol#,t
 2023-10-26T14:49:39.577298       5107       2839       5107  · EXEC(8244,98174,3,0,,3,0)              · insert into ccol$(con#,obj#,intcol#,pos#,col
 2023-10-26T14:49:39.578361       5212       2881       5212  · EXEC(98174,8244,7,1,,22,,""CAPACITY" I · insert into cdef$(obj#,con#,type#,intcols,co
 2023-10-26T14:49:39.578730       5248       2839       5248  · EXEC(8245,98174,3,0,,3,0)              · insert into ccol$(con#,obj#,intcol#,pos#,col
 2023-10-26T14:49:39.580397       5353       2881       5353  · EXEC(98174,8245,1,1,,14,,"CAPACITY >=  · insert into cdef$(obj#,con#,type#,intcols,co
 2023-10-26T14:49:39.580609       5389       2839       5389  · EXEC(8246,98174,1,1,,1,0)              · insert into ccol$(con#,obj#,intcol#,pos#,col
 2023-10-26T14:49:39.580989       5493       2881       5493  · EXEC(98174,8246,2,1,,0,,,0,,0,,0,,0,,9 · insert into cdef$(obj#,con#,type#,intcols,co
 2023-10-26T14:49:39.581629       5496       5495       5496  · EXEC                                   · select 1 from dba_tables where owner = 'SYS'
 2023-10-26T14:49:39.582183       5507       5499       5507  · EXEC("BERX")                           · select 1 from sys.bc$ bc, sys.user$ ur where
 2023-10-26T14:49:39.582290       5510          0          0  XCTEND                                   #():C:\Users\berx\Downloads\FREE_ora_53177_SES
 2023-10-26T14:49:39.583916       5638        700       5638  · EXEC(98174,2,"10/26/2023 14:49:39","10 · update obj$ set obj#=:4, type#=:5,ctime=:6,m
 2023-10-26T14:49:39.584434       5640        309       5640  EXEC                                     CREATE TABLE TICKETSALES( ID NUMBER PRIMARY KE

.

In line 309 the parse of CREATE TABLE statement began. After some checks, in line 6565 the CREATE TABLE for BERX.SYS_RESERVJRNL_98174 is parsed - and executed in line 3208. The UNIQUE INDEX SYS_C008246 is parsed at line 3551 and executed in 4079. All these activities are completed by a COMMIT (XCTEND) in line 5510 and the finish of CREATE TABLE in line 5640. 

A lot of work to be done for a simple CREATE TABLE. 

1 - INSERT 

14:49:40 SESSION_A > insert into ticketsales values (

  2       1
  3     , 'Faster'
  4     , 2000
  5*    );

1 row inserted.

14:49:40 SESSION_A >

                   END-TIMe       LINE   PARSE-ID    EXEC-ID  CALL-NAME(BOUND-VALUES)                  STATEMENT-TEXT                                
-----------------------------------------------------------------------------------------------------------------------------------------------------
2023-10-26T14:49:39.959350       5750       5750          0  PARSE                                    insert into ticketsales values ( 1 , 'Faster' 
 2023-10-26T14:49:39.959587       5758       3512       5758  · EXEC(98174)                            · select pctfree_stg, pctused_stg, size_stg,in
 2023-10-26T14:49:39.961213       5773       5765       5773  · EXEC(98174)                            · delete from deferred_stg$ where obj# = :1   
 2023-10-26T14:49:39.961868       5800       5782       5800  · EXEC(6,15,202)                         · select type#,blocks,extents,minexts,maxexts,
 2023-10-26T14:49:39.964075       5909       5809       5909  · EXEC(15,202,3,6,8,1,1,2147483645,128,0 · insert into seg$ (file#,block#,type#,ts#,blo
 2023-10-26T14:49:39.964592       5924       5916       5924  · EXEC(98176)                            · select indmethod# from ind$ where obj#=:1   
 2023-10-26T14:49:39.964835       5936       3512       5936  · EXEC(98176)                            · select pctfree_stg, pctused_stg, size_stg,in
 2023-10-26T14:49:39.965039       5946       5765       5946  · EXEC(98176)                            · delete from deferred_stg$ where obj# = :1   
 2023-10-26T14:49:39.965318       5965       5782       5965  · EXEC(6,15,210)                         · select type#,blocks,extents,minexts,maxexts,
 2023-10-26T14:49:39.966085       6067       5809       6067  · EXEC(15,210,3,6,8,1,1,2147483645,128,0 · insert into seg$ (file#,block#,type#,ts#,blo
 2023-10-26T14:49:39.966481       6081       6073       6081  · EXEC(98174)                            · delete from superobj$ where subobj# = :1    
 2023-10-26T14:49:39.967966       6097       6089       6097  · EXEC(98174)                            · select /*+ index(ts) */ spare1 from sys.tab_
 2023-10-26T14:49:39.968547       6109       1048       6109  · · EXEC(73)                             · · select con#,obj#,rcon#,enabled,nvl(defer,0
 2023-10-26T14:49:39.968699       6119       1065       6119  · · EXEC(73)                             · · select con#,type#,condlength,intcols,robj#
 2023-10-26T14:49:39.968823       6128       1079       6128  · · EXEC(173)                            · · select intcol#,nvl(pos#,0),col#,nvl(spare1
 2023-10-26T14:49:39.971061       6141       1101       6141  · · EXEC(73)                             · · select col#, grantee#, privilege#,max(mod(
 2023-10-26T14:49:39.971203       6151       1121       6151  · · EXEC(73)                             · · select grantee#,privilege#,nvl(col#,0),max
 2023-10-26T14:49:39.972250       6166       6158       6166  · EXEC(98174)                            · delete from tab_stats$ where obj#=:1        
 2023-10-26T14:49:39.976431       6380       6174       6380  · EXEC(6,15,202,0,,0,,3,3,0,,"---------- · update tab$ set ts#=:2,file#=:3,block#=:4,bo
 2023-10-26T14:49:39.976978       6392       1048       6392  · · EXEC(75)                             · · select con#,obj#,rcon#,enabled,nvl(defer,0
 2023-10-26T14:49:39.977121       6402       1065       6402  · · EXEC(75)                             · · select con#,type#,condlength,intcols,robj#
 2023-10-26T14:49:39.977231       6411       1079       6411  · · EXEC(174)                            · · select intcol#,nvl(pos#,0),col#,nvl(spare1
 2023-10-26T14:49:39.977703       6424       1101       6424  · · EXEC(75)                             · · select col#, grantee#, privilege#,max(mod(
 2023-10-26T14:49:39.977851       6434       1121       6434  · · EXEC(75)                             · · select grantee#,privilege#,nvl(col#,0),max
 2023-10-26T14:49:39.979098       6449       6441       6449  · EXEC(98176)                            · delete from ind_stats$ where obj#=:1        
 2023-10-26T14:49:39.982440       6626       6457       6626  · EXEC(6,15,210,1,1,0,4097,10,2,255,,,,, · update ind$ set ts#=:2,file#=:3,block#=:4,in
 2023-10-26T14:49:39.985174       6738       6634       6738  · EXEC(5,8,1,1,2147483645,128,0,131,8,0, · update seg$ set type#=:4,blocks=:5,extents=:
 2023-10-26T14:49:39.985908       6846       6634       6846  · EXEC(6,8,1,1,2147483645,128,0,131,8,0, · update seg$ set type#=:4,blocks=:5,extents=:
 2023-10-26T14:49:39.987619       6856       6848       6856  · EXEC(00008151.001C.0001)               · select condition from cdef$ where rowid=:1  
 2023-10-26T14:49:39.993765       6859       5750       6859  EXEC                                     insert into ticketsales values ( 1 , 'Faster' 
 2023-10-26T14:49:40.392046       6866       5750       6859  CLOSE                                    insert into ticketsales values ( 1 , 'Faster' 
 

Less work, still some background activities (you can see deferred segment creation at work, have a close look!)

2 - COMMIT

14:49:40 SESSION_A > commit;

Commit complete.

14:49:40 SESSION_A >

 2023-10-26T14:49:40.393714       6871       6871          0  PARSE                                    commit                                        
 2023-10-26T14:49:40.393792       6872          0          0  XCTEND                                   #():C:\Users\berx\Downloads\FREE_ora_53177_SES
 2023-10-26T14:49:40.394001       6873       6871       6873  EXEC                                     commit                                        
 2023-10-26T14:50:15.673448       6879       6871       6873  CLOSE                                    commit  

COMMITs are quite boring - at least in tracefiles.

 

3 - UPDATE in Session A

14:50:27 SESSION_A > update ticketsales set capacity = capacity-200 where id = 1;

1 row updated.

14:50:46 SESSION_A >
14:50:46 SESSION_A > select xid from v$transaction where addr=(select taddr from v$session where sid=  SYS_CONTEXT ('USERENV', 'SID') ) ;

XID
___________________
070015001B050000

14:50:52 SESSION_A > select * from SYS_RESERVJRNL_98174;

ORA_SAGA_ID$    ORA_TXN_ID$         ORA_STATUS$     ORA_STMT_TYPE$         ID CAPACITY_OP       CAPACITY_RESERVED
_______________ ___________________ _______________ ___________________ _____ ______________ ____________________
                070015001B050000    ACTIVE          UPDATE                  1 -                               200

14:50:54 SESSION_A >

2023-10-26T14:50:46.208878       7127       7127          0  PARSE                                    update ticketsales set capacity = capacity-200
 2023-10-26T14:50:46.209519       7135       3512       7135  · · EXEC(98175)                          · · select pctfree_stg, pctused_stg, size_stg,
 2023-10-26T14:50:46.209750       7145       3512       7145  · · EXEC(98175)                          · · select pctfree_stg, pctused_stg, size_stg,
 2023-10-26T14:50:46.210172       7152       7152          0  · PARSE                                  · SELECT NVL(((select NVL(sum(CAPACITY_RESERVE
 2023-10-26T14:50:46.210540       7160       3512       7160  · · EXEC(98175)                          · · select pctfree_stg, pctused_stg, size_stg,
 2023-10-26T14:50:46.210649       7170       3512       7170  · · EXEC(98175)                          · · select pctfree_stg, pctused_stg, size_stg,
 2023-10-26T14:50:46.212027       7180       3512       7180  · · · EXEC(98175)                        · · · select pctfree_stg, pctused_stg, size_st
 2023-10-26T14:50:46.212371       7187       7187          0  · · PARSE                                · · SELECT /* OPT_DYN_SAMP */ /*+ ALL_ROWS IGN
 2023-10-26T14:50:46.212629       7195       3512       7195  · · · EXEC(98175)                        · · · select pctfree_stg, pctused_stg, size_st
 2023-10-26T14:50:46.213665       7210       7187       7210  · · EXEC(070015001B0500,1)               · · SELECT /* OPT_DYN_SAMP */ /*+ ALL_ROWS IGN
 2023-10-26T14:50:46.214495       7223       3512       7223  · · · EXEC(98175)                        · · · select pctfree_stg, pctused_stg, size_st
 2023-10-26T14:50:46.214884       7230       7230          0  · · PARSE                                · · SELECT /* OPT_DYN_SAMP */ /*+ ALL_ROWS IGN
 2023-10-26T14:50:46.215153       7238       3512       7238  · · · EXEC(98175)                        · · · select pctfree_stg, pctused_stg, size_st
 2023-10-26T14:50:46.216372       7248       7230       7248  · · EXEC(1)                              · · SELECT /* OPT_DYN_SAMP */ /*+ ALL_ROWS IGN
 2023-10-26T14:50:46.217385       7268       7152       7268  · EXEC(070015001B0500,1,)                · SELECT NVL(((select NVL(sum(CAPACITY_RESERVE
 2023-10-26T14:50:46.218076       7282       3512       7282  · · EXEC(98175)                          · · select pctfree_stg, pctused_stg, size_stg,
 2023-10-26T14:50:46.262524       7307       7289       7307  · · EXEC("SYS_RESERVJRNL_98174",131,2)   · · select decode(u.type#, 2, u.ext_username, 
 2023-10-26T14:50:46.263063       7330       7330          0  · PARSE                                  · INSERT INTO "SYS_RESERVJRNL_98174" (ORA_SAGA
 2023-10-26T14:50:46.263423       7338       3512       7338  · · EXEC(98175)                          · · select pctfree_stg, pctused_stg, size_stg,
 2023-10-26T14:50:46.264027       7348       3512       7348  · · EXEC(98175)                          · · select pctfree_stg, pctused_stg, size_stg,
 2023-10-26T14:50:46.264234       7358       5765       7358  · · EXEC(98175)                          · · delete from deferred_stg$ where obj# = :1 
 2023-10-26T14:50:46.264475       7377       5782       7377  · · EXEC(6,15,218)                       · · select type#,blocks,extents,minexts,maxext
 2023-10-26T14:50:46.265060       7479       5809       7479  · · EXEC(15,218,3,6,8,1,1,2147483645,2,0 · · insert into seg$ (file#,block#,type#,ts#,b
 2023-10-26T14:50:46.265305       7493       7485       7493  · · EXEC(98175)                          · · delete from superobj$ where subobj# = :1  
 2023-10-26T14:50:46.265439       7504       6089       7504  · · EXEC(98175)                          · · select /*+ index(ts) */ spare1 from sys.ta
 2023-10-26T14:50:46.267489       7519       7511       7519  · · EXEC(98175)                          · · delete from tab_stats$ where obj#=:1      
 2023-10-26T14:50:46.268302       7728       6174       7728  · · EXEC(6,15,218,0,,0,,7,7,0,,"-------- · · update tab$ set ts#=:2,file#=:3,block#=:4,
 2023-10-26T14:50:46.268724       7833       6634       7833  · · EXEC(5,8,1,1,2147483645,2,0,131,2,0, · · update seg$ set type#=:4,blocks=:5,extents
 2023-10-26T14:50:46.269629       7871       7330       7871  · EXEC(,070015001B0500,"ACTIVE","UPDATE" · INSERT INTO "SYS_RESERVJRNL_98174" (ORA_SAGA
 2023-10-26T14:50:46.269699       7873       7127       7873  EXEC                                     update ticketsales set capacity = capacity-200
 2023-10-26T14:50:51.931299       7881       7127       7873  CLOSE                                    update ticketsales set capacity = capacity-200

The update on TICKETSALES also inititates an INSERT INTO "SYS_RESERVJRNL_98174" to reflect this reservation.

 

4 - UPDATE in Session B

14:51:11 SESSION_B > update ticketsales set capacity = capacity - 800 where id = 1;

1 row updated.

14:51:11 SESSION_B >

 2023-10-26T14:51:11.342290         64         64          0  PARSE                                    update ticketsales set capacity = capacity - 8
 2023-10-26T14:51:11.343719         69         69          0  · PARSE                                  · SELECT NVL(((select NVL(sum(CAPACITY_RESERVE
 2023-10-26T14:51:11.346632         76         76          0  · · PARSE                                · · SELECT /* OPT_DYN_SAMP */ /*+ ALL_ROWS IGN
 2023-10-26T14:51:11.349277         91         76         91  · · EXEC(070015001B0500,1)               · · SELECT /* OPT_DYN_SAMP */ /*+ ALL_ROWS IGN
 2023-10-26T14:51:11.351477        109        101        109  · · EXEC(1)                              · · SELECT /* OPT_DYN_SAMP */ /*+ ALL_ROWS IGN
 2023-10-26T14:51:11.352846        129         69        129  · EXEC(0A000B00150500,1,)                · SELECT NVL(((select NVL(sum(CAPACITY_RESERVE
 2023-10-26T14:51:11.353405        177        140        177  · EXEC(,0A000B00150500,"ACTIVE","UPDATE" · INSERT INTO "SYS_RESERVJRNL_98174" (ORA_SAGA
 2023-10-26T14:51:11.353495        179         64        179  EXEC                                     update ticketsales set capacity = capacity - 8
 2023-10-26T14:51:11.641520        184         64        179  CLOSE                                    update ticketsales set capacity = capacity - 8

This shows the same pattern: the update is reflected as an INSERT INTO "SYS_RESERVJRNL_98174".

 

5 - SELECT in Session B

14:51:11 SESSION_B > select capacity from ticketsales where id = 1
  2  -- 2000
  3* ;

   CAPACITY
___________
       2000

14:51:12 SESSION_B >
14:51:12 SESSION_B >
14:51:12 SESSION_B >
14:51:12 SESSION_B >
14:51:12 SESSION_B > select xid from v$transaction where addr=(select taddr from v$session where sid=  SYS_CONTEXT ('USERENV', 'SID') ) ;

XID
___________________
0A000B0015050000

14:51:22 SESSION_B > select * from SYS_RESERVJRNL_98174;

ORA_SAGA_ID$    ORA_TXN_ID$         ORA_STATUS$     ORA_STMT_TYPE$         ID CAPACITY_OP       CAPACITY_RESERVED
_______________ ___________________ _______________ ___________________ _____ ______________ ____________________
                0A000B0015050000    ACTIVE          UPDATE                  1 -                               800

 2023-10-26T14:51:11.644507        201        201          0  PARSE                                    select capacity from ticketsales where id = 1 
 2023-10-26T14:51:11.644574        202        201        202  EXEC                                     select capacity from ticketsales where id = 1 
 2023-10-26T14:51:11.644648        204        201        202  FETCH                                    select capacity from ticketsales where id = 1 
 2023-10-26T14:51:11.645034        208        201        202  FETCH                                    select capacity from ticketsales where id = 1 
 2023-10-26T14:51:21.707923        213        201        202  CLOSE                                    select capacity from ticketsales where id = 1 

On this layer, each SEssion sees only its own transaction in SYS_RESERVJRNL_98174.

 

6 - UPDATE in Session C

14:51:54 SESSION_C > update ticketsales
  2*   set capacity = capacity - 500 where id = 1;

1 row updated.

14:51:55 SESSION_C > select xid from v$transaction where addr=(select taddr from v$session where sid=  SYS_CONTEXT ('USERENV', 'SID') ) ;

XID
___________________
0400010033050000

14:52:02 SESSION_C >
14:52:02 SESSION_C > select * from SYS_RESERVJRNL_98174;

ORA_SAGA_ID$    ORA_TXN_ID$         ORA_STATUS$     ORA_STMT_TYPE$         ID CAPACITY_OP       CAPACITY_RESERVED
_______________ ___________________ _______________ ___________________ _____ ______________ ____________________
                0400010033050000    ACTIVE          UPDATE                  1 -                               500

14:52:10 SESSION_C >
14:52:10 SESSION_C > select capacity from ticketsales where id = 1
  2* ;

   CAPACITY
___________
       2000

14:52:24 SESSION_C >

2023-10-26T14:51:55.202602         67         67          0  PARSE                                    update ticketsales set capacity = capacity - 5
 2023-10-26T14:51:55.203106         87         72         87  · EXEC(04000100330500,1,)                · SELECT NVL(((select NVL(sum(CAPACITY_RESERVE
 2023-10-26T14:51:55.203951        135         98        135  · EXEC(,04000100330500,"ACTIVE","UPDATE" · INSERT INTO "SYS_RESERVJRNL_98174" (ORA_SAGA
 2023-10-26T14:51:55.204026        137         67        137  EXEC                                     update ticketsales set capacity = capacity - 5
 2023-10-26T14:52:02.051276        144         67        137  CLOSE                                    update ticketsales set capacity = capacity - 5

7 - 2nd UPDATE in Session C

14:52:24 SESSION_C > update ticketsales
  2    set capacity = capacity - 700 where id = 1
  3  -- ORA-2290
  4* ;

Error starting at line : 1 in command -
update ticketsales
  set capacity = capacity - 700 where id = 1
-- ORA-2290;
Error report -
ORA-02290: check constraint (BERX.MINIMUM_CAPACITY) violated

14:52:33 SESSION_C >

2023-10-26T14:52:33.244339        239        239          0  PARSE                                    update ticketsales set capacity = capacity - 7
 2023-10-26T14:52:33.244482        254         72        254  · EXEC(04000100330500,1,)                · SELECT NVL(((select NVL(sum(CAPACITY_RESERVE
 2023-10-26T14:52:33.245893        268        260        268  · EXEC(8245)                             · select o.name, c.name, decode(bitand(cd.defe
 2023-10-26T14:52:33.246097        279        239        279  EXEC                                     update ticketsales set capacity = capacity - 7
                                   280        239        279  ERROR                                    update ticketsales set capacity = capacity - 7
 2023-10-26T14:52:33.255272        287        239        279  CLOSE                                    update ticketsales set capacity = capacity - 7

This 2nd update fails - as in trace line 280:

ERROR #140437751612752:err=2290 tim=6674195429

with error code 2290. For me it's not visible how Lock Free Reservations knows about all the "others" reservations, as Session C only see it's own reservation.

 

8 - COMMIT in Session A

14:53:01 SESSION_A > commit;

Commit complete.

14:53:01 SESSION_A > 

 2023-10-26T14:53:01.129023       7942       7942          0  PARSE                                    commit                                        
 2023-10-26T14:53:01.129045       7943          0          0  XCTEND                                   #():C:\Users\berx\Downloads\FREE_ora_53177_SES

9 - ROLLBACK in Session B

14:53:30 SESSION_B > rollback;

Rollback complete.

14:53:30 SESSION_B >
14:53:30 SESSION_B > select capacity from ticketsales where id = 1
  2  -- 1800
  3* ;

   CAPACITY
___________
       1800

14:53:30 SESSION_B >

2023-10-26T14:53:29.985587        263          0          0  XCTEND                                   #():C:\Users\berx\Downloads\FREE_ora_53652_SES
 2023-10-26T14:53:30.212122        269        269          0  · PARSE                                  · select condition from cdef$ where rowid=:1  
 2023-10-26T14:53:30.212606        277        269        277  · EXEC(00008151.001C.0001)               · select condition from cdef$ where rowid=:1  
 2023-10-26T14:53:30.212672        278        269        277  · FETCH(00008151.001C.0001)              · select condition from cdef$ where rowid=:1  
 2023-10-26T14:53:30.212716        279        269        277  · CLOSE(00008151.001C.0001)              · select condition from cdef$ where rowid=:1  
 2023-10-26T14:53:30.214397        285        285          0  PARSE                                    select capacity from ticketsales where id = 1 
 2023-10-26T14:53:30.214519        286        285        286  EXEC                                     select capacity from ticketsales where id = 1 

10 - UPDATE in Session C 

14:53:50 SESSION_C > update ticketsales
  2    set capacity = capacity - 700 where id = 1
  3* ;

1 row updated.

14:53:50 SESSION_C >
14:53:50 SESSION_C > commit;

Commit complete.

14:53:50 SESSION_C >
14:53:50 SESSION_C > select capacity from ticketsales where id = 1
  2  -- 600
  3* ;

   CAPACITY
___________
        600

14:53:51 SESSION_C >

 2023-10-26T14:53:50.227511        470        470          0  PARSE                                    update ticketsales set capacity = capacity - 7
 2023-10-26T14:53:50.227762        485         72        485  · EXEC(04000100330500,1,)                · SELECT NVL(((select NVL(sum(CAPACITY_RESERVE
 2023-10-26T14:53:50.228238        523         98        523  · EXEC(,04000100330500,"ACTIVE","UPDATE" · INSERT INTO "SYS_RESERVJRNL_98174" (ORA_SAGA
 2023-10-26T14:53:50.228267        524        470        524  EXEC                                     update ticketsales set capacity = capacity - 7
 2023-10-26T14:53:50.473869        536        536          0  PARSE                                    commit                                        
 2023-10-26T14:53:50.473927        537          0          0  XCTEND                                   #():C:\Users\berx\Downloads\FREE_ora_53693_SES
 2023-10-26T14:53:50.474444        550        542        550  · EXEC(04000100330500)                   · update (select B$.ID,B$.CAPACITY,ORA_ESCR_AG
 2023-10-26T14:53:50.474984        571        563        571  · EXEC(04000100330500)                   · delete from BERX.SYS_RESERVJRNL_98174 where 
 2023-10-26T14:53:50.475307        574        536        574  EXEC                                     commit                                        
 2023-10-26T14:53:51.270715        578        536        574  CLOSE                                    commit                                        
 2023-10-26T14:53:51.272280        587        579        587  · EXEC(00008151.001C.0001)               · select condition from cdef$ where rowid=:1  
 2023-10-26T14:53:51.273447        595        595          0  PARSE                                    select capacity from ticketsales where id = 1 
 2023-10-26T14:53:51.273513        596        595        596  EXEC                                     select capacity from ticketsales where id = 1 

A lot is going on behind the scene for making Lock Free Reservations work.
Not all details are clear to me yet, at least I should have given some insights about one method to investigate such questions. 

23c free - DBMS_USERDIAG

In Oracles 23c free Database, among other new packages which still need to be discovered, there is one which warms my heart. It's called DBMS_USERDIAG. 
Unfortunately it is not documented yet - this makes it worth to have a look at it. 

As the Package definition is human readable and proper comments are provided by developers, this can be taken as a first summary:

create or replace NONEDITIONABLE PACKAGE dbms_userdiag AUTHID CURRENT_USER AS

  PRAGMA SUPPLEMENTAL_LOG_DATA(default, READ_ONLY);

  -- last call did not return an error
  NOERROR                   CONSTANT INTEGER := 0;

  -- **********************************************************************
  -- enable_sql_trace_event
  --   Enable sql_trace event at a given level
  --   Optionally a sql_id can also be specified in which case tracing will be
  --   enabled for that sql_id alone. Default is to enable events without sql
  --   scope.
  --   Default is to set event in current session alone. Event can be disabled
  --   by setting disable to non-zero value (default zero).
  --
  -- **********************************************************************
  PROCEDURE enable_sql_trace_event
  (
    level     IN BINARY_INTEGER DEFAULT 1,
    sid       IN BINARY_INTEGER DEFAULT 0,
    ser       IN BINARY_INTEGER DEFAULT 0,
    binds     IN BINARY_INTEGER DEFAULT 0,
    waits     IN BINARY_INTEGER DEFAULT 0,
    plan_stat IN VARCHAR2       DEFAULT NULL,
    sql_id    IN VARCHAR2       DEFAULT NULL,
    disable   IN BINARY_INTEGER DEFAULT 0,
    sys       IN BINARY_INTEGER DEFAULT 0
  );

  -- **********************************************************************
  -- check_sql_trace_event
  --   Checks current sql_trace event and retrieves the level
  --   sql_id is currently ignored.
  --
  -- **********************************************************************
  PROCEDURE check_sql_trace_event
  (
    level     OUT BINARY_INTEGER,
    sql_id    IN VARCHAR2 DEFAULT NULL,
    sys       IN BINARY_INTEGER DEFAULT 0
  );

  -- **********************************************************************
  -- trace
  --   Write a message to "user trace file". (default)
  --   If alert is set to non-zero value, then message is written to alert log.
  --
  -- **********************************************************************
  PROCEDURE trace
  (
    message IN VARCHAR2,
    alert   IN BINARY_INTEGER DEFAULT 0
  );

  -- **********************************************************************
  -- set_tracefile_identifier
  --    This routine is used to set a custom trace file identifier
  --    for the active tracefile.
  -- **********************************************************************

  PROCEDURE set_tracefile_identifier
  (
    trc_identifier          IN VARCHAR2
  );

  -- **********************************************************************
  -- set_exception_mode
  --    This routine sets the exception mode for the package.
  --    If exception mode is set to true, then all the exceptions
  --    will be raised to client. If it is set to false, then all the
  --    exceptions will be suppressed, and the client will not see any
  --    exception, even if underlying APIs are raising exceptions.
  --
  --    Since this is a diagnosability API, clients might not expect these
  --    API calls to raise their own exceptions.
  --    By default, exception mode will be set to false.
  --    Clients can change it any time by calling this function.
  -- **********************************************************************

  PROCEDURE set_exception_mode
  (
    exc_mode                IN BOOLEAN DEFAULT FALSE       /* exception mode */
  );

  -- **********************************************************************
  -- get_call_status
  --    This routine is used to obtain the status of the last call to the
  --    DBMS_USERDIAG API. In case the previous call was successful, the value
  --    of this call will be NOERROR(0).
  -- **********************************************************************

  FUNCTION get_call_status RETURN NUMBER;

  -- **********************************************************************
  -- get_call_error_msg
  --    This routine is used to obtain the error message if the last call
  --    to DBMS_USERDIAG API returned an error. In case the previous call was
  --    successful, the value returned by this API will be NULL.
  -- **********************************************************************

  FUNCTION get_call_error_msg RETURN VARCHAR2;

END dbms_userdiag;

By default, this package is only granted to the DBA role. 

But when granted to an user, this user can use all procedures without additional grants (like ALTER SESSION or ALTER SYSTEM). 

I managed to set_tracefile_identifier, enable trace for a level and also for a specific SQL_ID - both for the current session and also system-wide (PDB) . It seems this package can be a replacement for some functionality of DBMS_SESSION.session_trace_enable and DBMS_SYSTEM.ksdwrt.  

---

For completion, the list of internal functions called by these procedures - as far as I could observe them: 

ENABLE_SQL_TRACE_EVENT	dbkpls_enable_sql_trace_event
CHECK_SQL_TRACE_EVENT	dbkpls_check_sql_trace_event
TRACE	dbkpls_trace
SET_TRACEFILE_IDENTIFIER	dbkpls_set_tracefile_id

tracing network ACLs

If there are problems with ACLs (Access Control Lists) in Oracle, the note SRDC - How to Collect Standard Information for Access Control Lists (ACLs) (Doc ID 1905572.1) is an important starting point.
Basically it suggests to enable these events.

Bild von OpenClipart-Vectors auf Pixabay

alter session set events '10937 trace name context forever, level 7'; 
alter session set events '24247 trace name errorstack level 3';

But the only suggestion is to open a SR at oracle and send the results in. Sometimes, it already helps to understand parts of the trace file to identify an issue - no need to invest precious time on MOS. First the events itself. Their meaning are:

10937, 00000, "trace name context forever"
// * Cause:
// * Action: When set, this event enables tracing of PL/SQL packages.
// * Comment: Setting this event could result in some performance slowdown.

and

24247, 00000, "network access denied by access control list (ACL)"
// *Cause:    No access control list (ACL) has been assigned to the target
//            host or the privilege necessary to access the target host has not
//            been granted to the user in the access control list.
// *Action:   Ensure that an access control list (ACL) has been assigned to
//            the target host and the privilege necessary to access the target
//            host has been granted to the user.

Unfortunately I did not find a comprehensive documentation of these events levels, maybe this is area for some other posts.

A first try with a newly created user (grants: connect, resource & alter session) fails as expected:

SQL> select utl_http.request(url => 'http://www.google.com') from dual;

Error starting at line : 1 in command -
select utl_http.request(url => 'http://www.google.com') from dual
Error report -
ORA-29273: HTTP request failed
ORA-06512: at "SYS.UTL_HTTP", line 1530
ORA-24247: network access denied by access control list (ACL)
ORA-06512: at "SYS.UTL_HTTP", line 380
ORA-06512: at "SYS.UTL_HTTP", line 1470
ORA-06512: at line 1

With no ACLS at all, it's obvious.

According tho the documentation of UTL_HTTP:

This package is an invoker's rights package. The invoking user will need the connect privilege granted in the access control list assigned to the remote network host to which he wants to connect, as well as the use-client-certificates or the use-passwords privilege to authenticate himself with the remote Web server using the credentials stored in an Oracle wallet.

So connect it is: 

BEGIN
  DBMS_NETWORK_ACL_ADMIN.append_host_ace (
    host       => 'www.google.com', 
    lower_port => 80,
    upper_port => 443,
    ace        => xs$ace_type(privilege_list => xs$name_list('connect'),
                              principal_name => 'BERX',
                              principal_type => xs_acl.ptype_db)); 
END;
/

With this privilege, let's see what the ACL trace file says. (I have to set event 10937 to level 6 (not 7) in my lab env - lvl7 did not generate anything). 

SQL> alter session set events '10937 trace name context forever, level 6';

Session altered.

SQL> alter session set events '24247 trace name errorstack level 3';

Session altered.

SQL> select utl_http.request(url => 'http://www.google.com') from dual;

UTL_HTTP.REQUEST(URL=>'HTTP://WWW.GOOGLE.COM')

____________________________________________________________________________
<html code="" itemscope="" itemtype="http://schema.org/WebPage" lan...

The select is fine now - and what's in the trace?

Trace file /u01/app/oracle/diag/rdbms/cdb1/cdb1/trace/cdb1_ora_5483.trc
Oracle Database 19c Enterprise Edition Release 19.0.0.0.0 - Production
Version 19.3.0.0.0
Build label:    RDBMS_19.3.0.0.0DBRU_LINUX.X64_190417
ORACLE_HOME:    /u01/app/oracle/product/19.0.0/dbhome_1
System name:    Linux
Node name:      localhost.localdomain
Release:        5.4.17-2011.5.3.el8uek.x86_64
Version:        #2 SMP Wed Jul 29 22:09:11 PDT 2020
Machine:        x86_64
Instance name: cdb1
Redo thread mounted by this instance: 1
Oracle process number: 53
Unix process pid: 5483, image: oracle@localhost.localdomain


*** 2021-05-02T07:43:38.309047+00:00 (PDB1(3))
*** SESSION ID:(270.62847) 2021-05-02T07:43:38.309125+00:00
*** CLIENT ID:() 2021-05-02T07:43:38.309135+00:00
*** SERVICE NAME:(pdb1) 2021-05-02T07:43:38.309144+00:00
*** MODULE NAME:(java@localhost.localdomain (TNS V1-V3)) 2021-05-02T07:43:38.309153+00:00
*** ACTION NAME:() 2021-05-02T07:43:38.309162+00:00
*** CLIENT DRIVER:(jdbcoci : 19.3.0.0.0) 2021-05-02T07:43:38.309170+00:00
*** CONTAINER ID:(3) 2021-05-02T07:43:38.309210+00:00

psdnop: BERX 120 3 www.google.com:80
psdnopCheckAcl: priv 2147483693 cnt 1
psdnopCheckAcl: aclid 2147493757 status 3
psdnop: denied
psdnop: BERX 120 2 www.google.com:80
psdnopCheckAcl: priv 2147483690 cnt 1
psdnopCheckAcl: aclid 2147493757 status 1
psdnop: granted

According to the last line, everything is fine - access is granted. But there is more! 

the first line of interest is psdnop: BERX 120 3 www.google.com:80. The username is obvious (well, not so if I think about PLSQL with PL/SQL AUTHID CURRENT_USER|DEFINER ).

120 is the USER_ID of user BERX. 

I have no idea what the 3rd parameter of psdnop is - any suggestion is very welcome! 

The last entry is the host & port I try to connect to. 

For me it's the summary what will be checked against ACLs. 

The last line of this first block is psdnop: denied. Even in the 2nd block it's granted, I still 

The second line in this block is psdnopCheckAcl: priv 2147483693 cnt 1. It checks if an ACL is granted. But which one? 
It's first parameter tells us it's a priviliege the number is 2147483693. Unfortunately it's not written in the tracefile, so we need to identify this privilege.

  SQL> select name, id  from sys.xs$obj where id = 2147483693 ;
   NAME            ID
_______ _____________
HTTP       2147483693

This means Oracle first checks if the HTTP privilege is present - as I did not grant it, it's not there. 

The last 2 parameters of psdnopCheckAcl are unclear: cnt 1 - I have no explanation. 

In case you don't want to query sys.xs$obj for a given privilege, have a peek in $ORACLE_HOME/rdbms/admin/catts.sql. The 3 important parts there (for privilege HTTP) are 

RESERVED_ID              NUMBER := 2147483648;
...
PRIV_HTTP                   NUMBER := RESERVED_ID + 45;
...
-- Create http privilege
insert into xs$obj(name, owner, tenant, id, type, status, flags)
            values('HTTP', DEFAULT_OWNER, DEFAULT_TENANT,
                   PRIV_HTTP,4,1,1);

Next line is psdnopCheckAcl: aclid 2147493757 status 3. Again a check, just for an aclid now.  Also this one can be identified, in our case: 

SQL> select * from nacl$_HOST where acl#=2147493757;

             HOST    LOWER_PORT    UPPER_PORT          ACL#
_________________ _____________ _____________ _____________
www.google.com               80           443    2147493757

Now it's clear why the first block is denied: for this host that privilege is just not granted.

To crosscheck on the second (granted) block: 

SQL> select name, id  from sys.xs$obj where id = 2147483690 ;

      NAME            ID
__________ _____________
CONNECT       2147483690

This is by far not a comprehensive introduction into ACL traces, but at least it might help to identify, WHAT is missing when hitting ORA-24247. 

comparison between SQL*TRACE and ASH - get the right information

I'm quite interested in analyzing and improving Performance in Oracle databases. 

There are different approaches. A lot was discussed already if tracing or sampling is appropriate. Namely SQL*Trace or ASH/AWR. 

I will not favor one side here, just pick one aspect and compare both methods. 

Todays aspect is to compare how a specific user experience can be identified. As samples (ASH) are always enabled, it means to filter the right data out of this heap of data; In SQL*Trace it's to scope what or where SQL*Trace should be enabled. 

As I'm a lazy guy, I refer to Cary Millsaps Mastering Oracle Trace Data. In my copy of the book, Chapter 3 (Tracing Oracle) he shows an ordered list of tracing preferences. I will follow this list:

1. If the application set a distinct client ID for each business task execution ...
   SQL*Trace can be enabled by DBMS_MONITOR.CLIENT_ID_TRACE_ENABLE
   ASH can be filtered on column CLIENT_ID
2. If the application set a distinct module and action name ... 
   SQL*Trace can be enabled by DBMS_MONITOR.SERV_MODE_ACT_TRACE_ENABLE
   ASH can be filtered on columns MODULE and ACTION
3. If the program run long enough to be identified ... and still run long enough ... 
   SQL*Trace can be enabled for this session by DBMS_MONITOR.SESSION_TRACE_ENABLE 
   ASH can be filtered on columns SESSION_ID and SESSION_SERIAL# 
4. If there is any x such as SYS_CONTEXT('USERENV', x)  ...
   SQL*Trace can be enabled by an AFTER LOGON trigger
   ASH use this AFTER LOGON trigger to set CLIENT_ID, MODULE or ACTION and then filter on any of those
5. If a new service can be created for the problematic experience ... 
   SQL*Trace can be enabled by DBMS_MONITOR.SERV_MODE_ACT_TRACE_ENABLE
   ASH can be filtered on column SERVICE_HASH (with a little join of DBA_SERVICES)
6. If nothing else helps ... 
   SQL*Trace can be enabled for everything a short period of time by DBMS_MONITOR.DATABASE_TRACE_ENABLE and the user experience can be identified later
   ASH is on all the time, still the user experience mist be identified by the same investigation effort 

This comparison seems to be equal between SQL*Trace and ASH sampling. But I know of a small but specific difference: Wherever the user experience can not be accurately enabled by any setting, it must be filtered by other means. Here SQL*Trace has a big advantage, especially when investigated by a toolset like mrskew in Method-R Workbench: Some activities can be identified by specific start and stop statements, e.g. getting some parameters from a configuration table with a SELECT at the beginning, and write a trace line at the end. mrskew can be used to generate an artificial experience-ID for every experience between these 2 markers. In ASH, as the sampling might not catch any of these statements for a specific execution. This needs additional triggers on the statements to set any CLIENT_ID, MODULE or ACTION as in point 4 above. For sure more work in  this case, especially for SELECTs. 

My high level summary on identifying the users experience: both SQL*Trace and ASH are comparable. The big advantage of ASH is it's always on implementation, whereas SQL*Trace has advantages when it's about specific SQLs as markers. 

wrong LINE_NUMBER in v$diag_trace_file_contents

V$DIAG_TRACE_FILE_CONTENTS is a very nice way to access Oracle trace files without direct access to the instances host.

But for very long lines there is a problem, as PAYLOAD is limited to VARCHAR2(4000)

PAYLOAD

VARCHAR2(4000)

Displays the trace record payload (contents)

Oracle tries to do it's best and presents the one-line in multiple rows. In my 19.7 sandbox it looks like: 

This excerpt was created by a SQL which shows exactly the problem:

SELECT parsing_line,
       line_number,
       payload
FROM
    v$diag_trace_file_contents MATCH_RECOGNIZE (
        PARTITION BY trace_filename
        ORDER BY line_number, timestamp
        MEASURES
            parse.line_number AS parsing_line
        ALL ROWS PER MATCH
    PATTERN ( parse lines_ + endline nextline ) DEFINE
        parse    AS ( payload LIKE 'PARSING IN CURSOR%' ),
        lines_   AS ( line_number = prev(line_number) ),
        endline  AS ( line_number = prev(line_number) + 1 ),
        nextline AS ( line_number = prev(line_number) + 1 )
    )
WHERE trace_filename = '&trace_file'
/

Here you see the beauty of MATCH_RECOGNIZE: it describes quite clear, what I want to show. 

The pattern shown 

• Starts with a row payload LIKE 'PARSING IN CURSOR%'
• show all row where it's line_number is equal to previous rows line_number
• the 2 lines afterwards which increases their line_number (in comparison to previous row) again

The wring line number can be seen easily: All the rows with the SQLs PAYLOAD have LINE_NUMBER 57. But in fact 57 is only 

PARSING IN CURSOR #140574625525808 len=20604 dep=1 uid=0 oct=3 lid=0 tim=529427750 hv=1387884324 ad='63388040' sqlid='9ygdp6j9bkvt4'

Only the last SQLs fragment is shown as LINE_NUMBER 58.

An additional problem is the missing capability of order these multiple rows properly. 

The ORDER BY line_number, timestamp is not sufficient, as all the lines 57 and 58 share the same timestamp. The fixed view x$DBGTFVIEW has a column INDX which is a good candidate for such purpose, but it's not available right now. 

I have created a Database Idea for this issue:
extend v$diag_trace_file_contents so multiple chunks of a line can be ordered

For those who read my previous post: if the .trm file is missing, v$diag_trace_file_contents provides one row per line and the payload is truncated to 4000 characters. 

---

Update 2020-06-23: Oracle created Bug 31528203 - V$DIAG_TRACE_FILE_CONTENTS SHOWS WRONG LINE_NUMBER WHEN PAYLOAD > 4000 CHAR for this issue.

one purpose of trm files

Since Oracle version 11g, beside trace files (.trc) there are also trace metadata files (.trm). They are often quite small. Still often they are seen as useless and cleaned up. 

Oracle Support Document TRM Trace Files Getting Generated (Doc ID 750982.1) claims:

The metadata in .trm files describes the trace records stored inside of .trc trace files.

The Trace metadata allows tools, such as Adrci, to post-process the trace information.

By deleting the .trm file, you make the .trc file unusable for post processing from ADR using ADRCI tool.

One additional purpose is to assist in proper results in V$DIAG_TRACE_FILE_CONTENTS.

Here a small example of a SQL_TRACE file: 

In a text editor, you can see the line numbers and it's content:

But V$DIAG_TRACE_FILE_CONTENTS shows it slightly different:

You can see a gap between LINE_NUMBER 28 and 40. 

The full payload of line 40 is 

declare
    stm varchar2(32767) := 'select payload from v$diag_trace_file_contents where trace_filename = ''cdb1_ora_3435.trc'' and rownum = 1';
    app varchar2(1000) := ' and trace_filename = ''cdb1_ora_3435.trc''';
    val varchar2(4000);
    n number;
begin
    for i in 1 .. 500 loop
        stm := stm || app;
    end loop;
    execute immediate stm into val;
end;

The full content of original lines 29..40 is proposed in only 1 line here - with the real line number of it's last line as LINE_NUMBER. 

This can be useful, e.g. to identify the SQL at one entity, instead of parsing the result set line by line. 

It is one of several ways how trace metadata files help interpreting the trace files content. 

---

If the .trm file is removed, the result looks slightly different: 

every line on the tracefile is a real line in V$DIAG_TRACE_FILE_CONTENTS. 

There is also no COMPONENT_NAME visible. 

The simple content if the tracefile without any additional metadata or interpretation.

Simple getTracefile

Tracefiles are a very valuable source of information in Oracle databases.
In Versions prior to 12.2 quite complicated objects (with java dependency) were required.
Fortunately, in 12.2 Oracle introduced (& documented) the View V$DIAG_TRACE_FILE_CONTENTS. Unfortunately for some (only good from an internal technical perspective) reasons it does not contain the file itself, or a LOB locator, but several chunks as VARCHAR2. So it's still worth to write some code for a simple interface to access the tracefiles.

Again it's a SQLDeveloper report. But the structure is so simple, it can be implemented in any preferred tool.



There is a simple list of tracefiles and their MODIFY_TIME as FILEDATE - based on V$DIAG_TRACE_FILE.



When a specific tracefile name is selected, the file is presented as text and BLOB. The content is identical, just BLOBs can be downloaded which is useful for huge tracefiles, whereas the CLOB representation is simple to directly read small tracefiles.

---

Fortunately no objects are required in the database, only proper grants on V$DIAG_TRACE_FILE and V$DIAG_TRACE_FILE_CONTENTS. These can be roles also.

As I have limited access to databases right now, I could not test a lot of settings, e.g. RAC or different character sets.

Just import this Report as an User Defined Report:

<?xml version="1.0" encoding="UTF-8" ?>
<displays>
<display id="04e5e018-014a-1000-8001-ac193119805c" type="" style="Table" enable="true">
<name><![CDATA[get tracefiles]]></name>
<description><![CDATA[create a list of tracefiles as listed in V$DIAG_TRACE_FILE and makes specific files available]]></description>
<tooltip><![CDATA[create a list of tracefiles in DIAG directory and makes specific files available ]]></tooltip>
<drillclass><![CDATA[null]]></drillclass>
<CustomValues>
<TYPE>horizontal</TYPE>
</CustomValues>
<query>
<sql><![CDATA[select TRACE_FILENAME as TRACE_NAME ,
 MODIFY_TIME as FILEDATE
from V$DIAG_TRACE_FILE
Order By MODIFY_TIME desc]]></sql>
</query>
<pdf version="VERSION_1_7" compression="CONTENT">
<docproperty title="-" author="berx" subject="-" keywords="-" />
<cell toppadding="2" bottompadding="2" leftpadding="2" rightpadding="2" horizontalalign="LEFT" verticalalign="TOP" wrap="true" />
<column>
<heading font="null" size="10" style="NORMAL" color="-16777216" rowshading="-1" labeling="FIRST_PAGE" />
<footing font="null" size="10" style="NORMAL" color="-16777216" rowshading="-1" labeling="NONE" />
<blob blob="EMBED" zip="false" />
</column>
<table font="Agency FB" size="10" style="NORMAL" color="-16777216" userowshading="false" oddrowshading="-1" evenrowshading="-1" showborders="true" spacingbefore="12" spacingafter="12" horizontalalign="LEFT" />
<header enable="false" generatedate="false">
<data>
 
null                                                               </data>
</header>
<footer enable="false" generatedate="false">
<data value="null" />
</footer>
<security enable="false" useopenpassword="false" openpassword="null" encryption="EXCLUDE_METADATA">
<permission enable="false" permissionpassword="null" allowcopying="true" allowprinting="true" allowupdating="false" allowaccessdevices="true" />
</security>
<pagesetup papersize="LETTER" orientation="1" measurement="in" margintop="1.0" marginbottom="1.0" marginleft="1.0" marginright="1.0" />
</pdf>
<display id="null" type="" style="Table" enable="true">
<name><![CDATA[get tracefile]]></name>
<description><![CDATA[access the specific tracefile ]]></description>
<tooltip><![CDATA[Specific tracefile from list above ]]></tooltip>
<drillclass><![CDATA[null]]></drillclass>
<CustomValues>
<TYPE>horizontal</TYPE>
</CustomValues>
<query>
<sql><![CDATA[with function get_tracefile (filename varchar2) return CLOB IS
-- PRAGMA AUTONOMOUS_TRANSACTION;
-- to avoid ORA-14553: cannot perform a lob write operation inside a query 
-- only required in dedicated function
--
-- in a dedicated function, this grant is required:
-- grant select on sys.V_$DIAG_TRACE_FILE_CONTENTS to xxx;
  l_out CLOB := EMPTY_CLOB;
  CURSOR all_payload (fn varchar2)
  is 
  Select Payload
  from V$DIAG_TRACE_FILE_CONTENTS 
  where trace_filename=fn
    and payload is not null
  order by line_number asc;
begin
  NULL;
   
   DBMS_LOB.CREATETEMPORARY(l_out, FALSE, DBMS_LOB.CALL);

  for r_payload in all_payload(filename)
  loop
    DBMS_lob.append(l_out, r_payload.payload);
  end loop;
  return l_out;
  DBMS_LOB.FREETEMPORARY(l_out);
end get_tracefile;
function get_tracefile_blob (filename varchar2) return BLOB IS
-- PRAGMA AUTONOMOUS_TRANSACTION;
-- to avoid ORA-14553: cannot perform a lob write operation inside a query 
-- only required in dedicated function
--
-- in a dedicated function, this grant is required:
-- grant select on sys.V_$DIAG_TRACE_FILE_CONTENTS to xxx;
  l_out BLOB := EMPTY_BLOB;
  CURSOR all_payload (fn varchar2)
  is 
  Select Payload
  from V$DIAG_TRACE_FILE_CONTENTS 
  where trace_filename=fn
    and payload is not null
  order by line_number asc;
begin
  NULL;
   DBMS_LOB.CREATETEMPORARY(l_out, FALSE, DBMS_LOB.CALL);
  for r_payload in all_payload(filename)
  loop
    DBMS_lob.append(l_out, utl_raw.cast_to_raw(r_payload.payload));
  end loop;
  return l_out;
  DBMS_LOB.FREETEMPORARY(l_out);
end get_tracefile_blob ;
select get_tracefile(:TRACE_NAME) as " Tracefile", get_tracefile_blob(:TRACE_NAME) as " Binary Tracefile " from dual]]></sql>
<binds>
<bind id="TRACE_NAME">
<prompt><![CDATA[TRACE_NAME]]></prompt>
<tooltip><![CDATA[TRACE_NAME]]></tooltip>
<value><![CDATA[NULL_VALUE]]></value>
<bracket><![CDATA[null]]></bracket>
</bind>
</binds>
</query>
<pdf version="VERSION_1_7" compression="CONTENT">
<docproperty title="-" author="-" subject="-" keywords="-" />
<cell toppadding="2" bottompadding="2" leftpadding="2" rightpadding="2" horizontalalign="LEFT" verticalalign="TOP" wrap="true" />
<column>
<heading font="null" size="10" style="NORMAL" color="-16777216" rowshading="-1" labeling="FIRST_PAGE" />
<footing font="null" size="10" style="NORMAL" color="-16777216" rowshading="-1" labeling="NONE" />
<blob blob="EMBED" zip="false" />
</column>
<table font="null" size="10" style="NORMAL" color="-16777216" userowshading="false" oddrowshading="-1" evenrowshading="-1" showborders="true" spacingbefore="12" spacingafter="12" horizontalalign="LEFT" />
<header enable="false" generatedate="false">
<data>
 
null          </data>
</header>
<footer enable="false" generatedate="false">
<data value="null" />
</footer>
<security enable="false" useopenpassword="false" openpassword="null" encryption="EXCLUDE_METADATA">
<permission enable="false" permissionpassword="null" allowcopying="true" allowprinting="true" allowupdating="false" allowaccessdevices="false" />
</security>
<pagesetup papersize="LETTER" orientation="1" measurement="in" margintop="1.0" marginbottom="1.0" marginleft="1.0" marginright="1.0" />
</pdf>
</display>
</display>
</displays>

Any comments, hints or recommendations are highly welcome!

Tracing the Database Configuration Assistant

I am struggling with DBCA right now so a little tracing is advised.
Note Tracing the Database Configuration Assistant (DBCA) (Doc ID 188134.1) gives a nice suggestion to add these parameters:

-DTRACING.ENABLED=true -DTRACING.LEVEL=2

but it's no elegant solution to edit the shell script in $ORACLE_HOME/bin/dbca

I prefer my new swiss knife for java parameters. A simple environment variable:

_JAVA_OPTIONS= -DTRACING.ENABLED=true -DTRACING.LEVEL=3

This is very useful for any java program. As Oracle has many such programs, there is often use for _JAVA_OPTIONS

don't look to close, it might change the results

We all know, if we try to look to close on some details, the results we get may change from the original observation.
This is also sometimes true for Oracle Trace events:
During analyses of a query with XMLTYPE which fails with ORA-12850 (in a 4 node RAC DB), Oracle Support asked for some trace files. the query itself is something like

SELECT XMLTYPE(
CURSOR( SELECT ...
FROM gv$lock l
JOIN gv$session s
... ) )

and the original error is

ORA-19202: Error occurred in XML processing 
ORA-12850: Could not allocate slaves on all specified instances: 4 needed, 1 allocated 
ORA-06512: at "SYS.XMLTYPE", line 343 
ORA-06512: at line 1 

But with a specific trace event:

alter session set events 'trace [SQL_Compiler.*] disk highest'; 

the error changes to

ORA-19202: Error occurred in XML processing 
ORA-00918: column ambiguously defined 
ORA-06512: at "SYS.XMLTYPE", line 343 
ORA-06512: at line 1 

As there are 2 different Errors now Oracle Support has more to analyze 😂

digging into mrskew internals

I'm spending some time working with Method-Rs trace file analyzer mrskew.
As the requirements are beyond simple analyses (here an example about the uncommon things to do) I'm consulting the documentation and all available information in detail. After many readings I started to take this part of the documentation serious:

EXPRESSIONS
Wherever mrskew requires an expression (such as in --group and --where option arguments), you may use any valid Perl expression consisting of:
Perl operators
Operators such as or xor and not , = ?: || && | ^ < > <= >= lt gt le ge == != <=> eq ne cmp + - . * / % =~ !~ ! ~ ** ...and so on. See http://perldoc.perl.org/perlop.html for details.
Perl builtin functions
Functions such as lc uc s/// int join split sprintf substr ...and so on. See http://perldoc.perl.org/perlfunc.html for details.
File::Basename functions
The functions fileparse, basename, and dirname. See http://perldoc.perl.org/File/Basename.html for details.
mrskew expression variables
Any of the variable names described in "EXPRESSION VARIABLES".
For more information about Perl expression syntax, see http://perldoc.perl.org/perl.html#Tutorials.

It's written "any valid Perl expression" and Jeff showed me a very clever example on StackOverflow. But that's not the end, it raised some questions:
Where in the work of mrskew is the specific expression executed?
What's the order of these expressions?
Can they interact?

A small testcase can answer some of these questions.

I used a very simple artificial tracefile:

Oracle Release 11.2
PARSING IN CURSOR #1 len=20 dep=0 uid=7 oct=6 lid=7 tim=2 hv=1 ad='1' sqlid='A'
insert
END OF STMT

EXEC #1:c=1,e=1,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=3,tim=100
EXEC #1:c=2,e=4,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=6,tim=400

a small rc file (rc file is used here to store parameters whenever it's boring to type them on command line):

--init='
 my $trace_string = "trace: ";
 my $test_string;
    sub xfrm {
   if ($_[0] eq "where0") {
     $test_string = $test_string . "x";}
   if ($_[0] eq "where1") {
     $test_string =~ s/x/u/g ;}  
      $trace_string = $trace_string . "$_[0]" . "{ $test_string } " . "[$line] -> ";
   
   if ($_[0] eq "group") {
     return $trace_string;}
  else {
    return $_[1]}
    }
'

this uses the --init parameter:

--init=stringExecute string, which must contain syntactically correct Perl code, before beginning file processing. The default value is --init=''.

There I'm setting 2 variables which will be used later.
Also a function xfrm is defined. Depending of the 1st parameter it does different things, always it extends the variable $trace_string with some additional parameters. When the 1st parameter is "group", this $trace_string is returned - my dirty hack for a print of a debug value.

Checking the manpage where an expression ls allowed for a parameter gives me this execution:
(slightly modified for better readability

mrskew --rc martin3.rc  \
  --select='xfrm( "select", 1)' \
  --where0='xfrm( "where0", 1)==1' \
  --where1='xfrm( "where1", 1)==1' \
  --group='xfrm( "group",1)' \
  berx2.trc

The idea is simple: wherever a expression is allowed, my generic function xfrm is called with the name of the mrskew-parameter as it's 1st parameter.

It's result provides some interesting insights:

Summary information by file (modified)
mrskew --rc martin3.rc  --select='xfrm( "select", 1)' --where0='xfrm( "where0", 1)==1' --where1='xfrm( "where1", 1)==1' --group='xfrm( "group",1)' berx2.trc "D:\TEMP\berx2.trc"
Run began 2017-09-25T09:54:40, lasted 0,445000 seconds

input files:
 'D:\TEMP\berx2.trc'

where expression:
 ((xfrm( "where0", 1)==1) and (xfrm( "where1", 1)==1)) and ($nam=~/(?^:(?i).+)/)

group expression:
 xfrm( "group",1)

matched call names:
 'EXEC'

'xfrm( "group",1)'                                                                                                                                                                                                                                                                                                 'xfrm( "select", 1)'       %  CALLS      MEAN       MIN       MAX
-----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------  --------------------  ------  -----  --------  --------  --------
trace: where0{ x } [1] -> where1{ u } [1] -> where0{ ux } [4] -> where1{ uu } [4] -> where0{ uux } [5] -> where1{ uuu } [5] -> where0{ uuux } [6] -> where1{ uuuu } [6] -> select{ uuuu } [6] -> group{ uuuu } [6] ->                                                                                                          1.000000   50.0%      1  1.000000  1.000000  1.000000
trace: where0{ x } [1] -> where1{ u } [1] -> where0{ ux } [4] -> where1{ uu } [4] -> where0{ uux } [5] -> where1{ uuu } [5] -> where0{ uuux } [6] -> where1{ uuuu } [6] -> select{ uuuu } [6] -> group{ uuuu } [6] -> where0{ uuuux } [7] -> where1{ uuuuu } [7] -> select{ uuuuu } [7] -> group{ uuuuu } [7] ->               1.000000   50.0%      1  1.000000  1.000000  1.000000
-----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------  --------------------  ------  -----  --------  --------  --------
TOTAL (2)                                                                                                                                                                                                                                                                                                                      2.000000  100.0%      2  1.000000  1.000000  1.000000
mrskew: file 'berx2.trc' does not exist

As the $trace_string is quite long I cut it down into pieces and my interpretation:

trace: where0{ x } [1] -> where1{ u } [1] -> 

where0 is called before where1
where1 can modify a variable set by where0 (the x becomes an u).

where0{ ux } [4] -> where1{ uu } [4] -> where0{ uux } [5] -> where1{ uuu } [5] -> 

where0 and where1 are NOT used in lines 2 & 3 of the trace file (PARSING IN CURSOR and the insert statement)

where0{ uuux } [6] -> where1{ uuuu } [6] -> select{ uuuu } [6] -> group{ uuuu } [6] -> 

in line 6 (EXEC) where0, where1, select and group functions are used (in that order)

where0{ uuuux } [7] -> where1{ uuuuu } [7] -> select{ uuuuu } [7] -> group{ uuuuu } [7] ->

the same is true for line 7.

There is probably more to identify as my simplified tracefile did not show all possible lines and their combination. But the possibility to run code inside mrskew at different positions, and even manipulate some values is shown. Even manipulating mrskews own variables might be of some interest, but it must be identified first where/when they are set and changed. This is open for the readers exercise, the method is shown here :-)

Method R Profiler 7.0 available

I'm seldom doing product announcements on my blog. So there must be a reason why I do not follow this rule.

Method-R recently released a new version of it's powerful SQL-Trace profiler.
Of course there are many improvements on the profiler engine itself, but as the prodict was very stable already they will only help in rare edge cases, most people would not benefit dramatically.

But there is a new featuere which brings a lot of added value to the tool and improves time to repair/fix/enlightenment for many readers of the trace file:
They added an explanatory text to many sections.
Here an example (from their sample file - slightly edited to better fit the size of this blog):

Your experience duration was dominated by “cell single block physical read” and “CPU: FETCH dbcalls” calls. These are all high-productivity calls; their dominance means that the Oracle Database is working hard for your application. Now you should determine whether all of that work is actually necessary. Consult the Profile by Cursor and Profile by Statement sections for the next step of your diagnosis.

	Subroutine	Duration		Calls	Duration per call (seconds)
		seconds	% R		mean	min	skew	max
1	cell single block physical read	4.644	69.9%	6,899	0.0007	0.0005	▁▁▁█▁▁▁▁▁▁▁	0.028
2	CPU: FETCH dbcalls	2.381	35.8%	7,947	0.0003	0.0000	▁▁▁▁▁▁▁▁▁▁▁▁▁▁▂▁█▁▁	2.071

Unfortunately I did not manage to copy all the nice formatting into this blog, so i created a screenshot to show the original picture.

As you can see there is a new text with more in detail explanation about the Subroutine and where to go next for deeper analysis. I see this as a big advantage for everyone who does not work with SQL-Trace files every day. (well, even for those it's helpful).

There is a very nice demo version available, so if you have a trace file to analyze and want to check, if you see added value by this suggestion, give it a try.

Beside the new Profiler, Method-R has redone their web page as well (and I expect more news to follow). It's worth to invest some minutes and have a glimpse.