We have spring application on java that work with Oracle 19.14.
In our application we have such code:
@Transactional(isolation = Isolation.SERIALIZABLE, propagation = NESTED)
public importCollection() {
// some select and insert statements here
}
When we call this function (when we call importCollection() there is no parallel threads that interact with DB), we get ORA-08177 (Cannot serialize access for this transaction) error message.
Some strange thing that this error happens on different insert statements.
And after some many tries this function executed without errors, and after that this error doesn't happen again. (When we deploy our application on the new virtual machine with the new Oracle instance the usecase is occurred again).
We tried to set hikari pool for only one connection (to put away parallel sessions) - the problem is here. When we call importCollection there is no parallel threads that interact with db.
I have read what for using serializable isolation level it is important to set initran >=3.
I made it by alert table - error is here.
So, how can I debug the root of the problem? How to find the second transaction, which may lead to such an error?
Part of trace log with error:
=====================
PARSING IN CURSOR #140495296748256 len=216 dep=0 uid=109 oct=2 lid=109 tim=14479044068 hv=772606070 ad='760a5048' sqlid='541sxycr0u23q'
INSERT ALL INTO SAM_COLLECTION_ACTION(COLLECTION_ID, ACTION_ID, TRANSITIVE) VALUES ( :1 , :2 , :3 ) INTO SAM_COLLECTION_ACTION(COLLECTION_ID, ACTION_ID, TRANSITIVE) VALUES ( :4 , :5 , :6 ) SELECT * FROM dual
END OF STMT
PARSE #140495296748256:c=161,e=161,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,plh=0,tim=14479044068
EXEC #140495297789296:c=14,e=14,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,plh=866645418,tim=14479044240
FETCH #140495297789296:c=11,e=11,p=0,cr=3,cu=0,mis=0,r=1,dep=1,og=4,plh=866645418,tim=14479044266
CLOSE #140495297789296:c=0,e=0,dep=1,type=3,tim=14479044278
EXEC #140495297789296:c=7,e=7,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,plh=866645418,tim=14479044312
FETCH #140495297789296:c=4,e=4,p=0,cr=3,cu=0,mis=0,r=1,dep=1,og=4,plh=866645418,tim=14479044323
CLOSE #140495297789296:c=0,e=0,dep=1,type=3,tim=14479044331
EXEC #140495297789296:c=5,e=5,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,plh=866645418,tim=14479044361
FETCH #140495297789296:c=4,e=4,p=0,cr=3,cu=0,mis=0,r=1,dep=1,og=4,plh=866645418,tim=14479044372
CLOSE #140495297789296:c=0,e=0,dep=1,type=3,tim=14479044379
EXEC #140495297789296:c=4,e=4,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,plh=866645418,tim=14479044392
FETCH #140495297789296:c=4,e=4,p=0,cr=3,cu=0,mis=0,r=1,dep=1,og=4,plh=866645418,tim=14479044410
CLOSE #140495297789296:c=0,e=0,dep=1,type=3,tim=14479044418
EXEC #140495297789296:c=14,e=14,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,plh=866645418,tim=14479045382
FETCH #140495297789296:c=9,e=9,p=0,cr=3,cu=0,mis=0,r=1,dep=1,og=4,plh=866645418,tim=14479045413
CLOSE #140495297789296:c=0,e=0,dep=1,type=3,tim=14479045424
=====================
PARSING IN CURSOR #140495293613264 len=41 dep=1 uid=0 oct=7 lid=0 tim=14479045703 hv=766663521 ad='8231d2c8' sqlid='9rzjf5cqv4qv1'
delete from deferred_stg$ where obj# = :1
END OF STMT
EXEC #140495293613264:c=266,e=266,p=0,cr=2,cu=4,mis=0,r=1,dep=1,og=4,plh=2714355898,tim=14479045703
CLOSE #140495293613264:c=0,e=0,dep=1,type=3,tim=14479045733
=====================
PARSING IN CURSOR #140495297059344 len=226 dep=1 uid=0 oct=3 lid=0 tim=14479045975 hv=1011610568 ad='885d2010' sqlid='9tgj4g8y4rwy8'
select type#,blocks,extents,minexts,maxexts,extsize,extpct,user#,iniexts,NVL(lists,65535),NVL(groups,65535),cachehint,hwmincr, NVL(spare1,0),NVL(scanhint,0),NVL(bitmapranges,0) from seg$ where ts#=:1 and file#=:2 and block#=:3
END OF STMT
EXEC #140495297059344:c=16,e=16,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,plh=3755742892,tim=14479045975
FETCH #140495297059344:c=5,e=5,p=0,cr=2,cu=0,mis=0,r=0,dep=1,og=4,plh=3755742892,tim=14479046023
CLOSE #140495297059344:c=0,e=0,dep=1,type=3,tim=14479046037
=====================
PARSING IN CURSOR #140495297050960 len=259 dep=1 uid=0 oct=2 lid=0 tim=14479046414 hv=1814305607 ad='824a4ba0' sqlid='g7mt7ptq286u7'
insert into seg$ (file#,block#,type#,ts#,blocks,extents,minexts,maxexts,extsize,extpct,user#,iniexts,lists,groups,cachehint,hwmincr, spare1, scanhint, bitmapranges) values (:1,:2,:3,:4,:5,:6,:7,:8,:9,:10,:11,:12,:13,:14,:15,:16,DECODE(:17,0,NULL,:17),:18,:19)
END OF STMT
EXEC #140495297050960:c=128,e=255,p=0,cr=3,cu=7,mis=0,r=1,dep=1,og=4,plh=0,tim=14479046412
CLOSE #140495297050960:c=0,e=1,dep=1,type=3,tim=14479046450
=====================
PARSING IN CURSOR #140495297361056 len=41 dep=1 uid=0 oct=3 lid=0 tim=14479046627 hv=4138818835 ad='82317d68' sqlid='95nx0kvvb2r8m'
select indmethod# from ind$ where obj#=:1
END OF STMT
PARSE #140495297361056:c=26,e=26,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,plh=3312860272,tim=14479046627
EXEC #140495297361056:c=20,e=20,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,plh=3312860272,tim=14479046676
FETCH #140495297361056:c=21,e=21,p=0,cr=3,cu=0,mis=0,r=1,dep=1,og=4,plh=3312860272,tim=14479046704
STAT #140495297361056 id=1 cnt=1 pid=0 pos=1 obj=19 op='TABLE ACCESS BY INDEX ROWID IND$ (cr=3 pr=0 pw=0 str=1 time=22 us cost=2 size=7 card=1)'
STAT #140495297361056 id=2 cnt=1 pid=1 pos=1 obj=41 op='INDEX UNIQUE SCAN I_IND1 (cr=2 pr=0 pw=0 str=1 time=6 us cost=1 size=0 card=1)'
CLOSE #140495297361056:c=8,e=8,dep=1,type=1,tim=14479046760
EXEC #140495297789296:c=8,e=8,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,plh=866645418,tim=14479046796
FETCH #140495297789296:c=8,e=8,p=0,cr=3,cu=0,mis=0,r=1,dep=1,og=4,plh=866645418,tim=14479046811
CLOSE #140495297789296:c=0,e=0,dep=1,type=3,tim=14479046819
EXEC #140495293613264:c=79,e=79,p=0,cr=2,cu=3,mis=0,r=1,dep=1,og=4,plh=2714355898,tim=14479046905
CLOSE #140495293613264:c=0,e=0,dep=1,type=3,tim=14479046916
EXEC #140495297059344:c=24,e=24,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,plh=3755742892,tim=14479047020
FETCH #140495297059344:c=3,e=3,p=0,cr=2,cu=0,mis=0,r=0,dep=1,og=4,plh=3755742892,tim=14479047037
CLOSE #140495297059344:c=0,e=0,dep=1,type=3,tim=14479047046
EXEC #140495297050960:c=131,e=131,p=0,cr=3,cu=6,mis=0,r=1,dep=1,og=4,plh=0,tim=14479049162
CLOSE #140495297050960:c=1,e=1,dep=1,type=3,tim=14479049189
=====================
PARSING IN CURSOR #140495297362384 len=40 dep=1 uid=0 oct=7 lid=0 tim=14479049542 hv=2579434614 ad='82318dc0' sqlid='gsfnqdfcvy33q'
delete from superobj$ where subobj# = :1
END OF STMT
PARSE #140495297362384:c=44,e=45,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,plh=2453887050,tim=14479049542
EXEC #140495297362384:c=24,e=24,p=0,cr=1,cu=0,mis=0,r=0,dep=1,og=4,plh=2453887050,tim=14479049599
STAT #140495297362384 id=1 cnt=0 pid=0 pos=1 obj=0 op='DELETE SUPEROBJ$ (cr=1 pr=0 pw=0 str=1 time=5 us)'
STAT #140495297362384 id=2 cnt=0 pid=1 pos=1 obj=98 op='INDEX UNIQUE SCAN I_SUPEROBJ1 (cr=1 pr=0 pw=0 str=1 time=3 us cost=0 size=26 card=1)'
CLOSE #140495297362384:c=1,e=1,dep=1,type=0,tim=14479049659
=====================
PARSING IN CURSOR #140495297362384 len=36 dep=1 uid=0 oct=7 lid=0 tim=14479049698 hv=1175925690 ad='822fc1d8' sqlid='3kywng531fcxu'
delete from tab_stats$ where obj#=:1
END OF STMT
PARSE #140495297362384:c=15,e=15,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,plh=2667651180,tim=14479049698
EXEC #140495297362384:c=18,e=17,p=0,cr=1,cu=0,mis=0,r=0,dep=1,og=4,plh=2667651180,tim=14479049738
STAT #140495297362384 id=1 cnt=0 pid=0 pos=1 obj=0 op='DELETE TAB_STATS$ (cr=1 pr=0 pw=0 str=1 time=4 us)'
STAT #140495297362384 id=2 cnt=0 pid=1 pos=1 obj=74 op='INDEX UNIQUE SCAN I_TAB_STATS$_OBJ# (cr=1 pr=0 pw=0 str=1 time=3 us cost=0 size=13 card=1)'
CLOSE #140495297362384:c=1,e=1,dep=1,type=0,tim=14479049778
=====================
PARSING IN CURSOR #140495297035352 len=651 dep=1 uid=0 oct=6 lid=0 tim=14479049960 hv=1254766863 ad='822f7f30' sqlid='9g9a7195cnf8g'
update tab$ set ts#=:2,file#=:3,block#=:4,bobj#=decode(:5,0,null,:5),tab#=decode(:6,0,null,:6),intcols=:7,kernelcols=:8,clucols=decode(:9,0,null,:9),audit$=:10,flags=:11,pctfree$=:12,pctused$=:13,initrans=:14,maxtrans=:15,rowcnt=:16,blkcnt=:17,empcnt=:18,avgspc=:19,chncnt=:20,avgrln=:21,analyzetime=:22,samplesize=:23,cols=:24,property=:25,degree=decode(:26,1,null,:26),instances=decode(:27,1,null,:27),dataobj#=:28,avgspc_flb=:29,flbcnt=:30,trigflag=:31,spare1=:32,spare2=decode(:33,0,null,:33),spare4=:34,spare6=:35,acdrflags=decode(:36,0,null,:36),acdrtsobj#=decode(:37,0,null,:37),acdrdefaulttime=:38,acdrrowtsintcol#=:39,spare7=:40 where obj#=:1
END OF STMT
EXEC #140495297035352:c=152,e=152,p=0,cr=4,cu=3,mis=0,r=1,dep=1,og=4,plh=2918346288,tim=14479049960
CLOSE #140495297035352:c=0,e=0,dep=1,type=3,tim=14479049994
=====================
PARSING IN CURSOR #140495297362384 len=36 dep=1 uid=0 oct=7 lid=0 tim=14479050078 hv=1784203153 ad='822f1e88' sqlid='3axxxnjp5jjwj'
delete from ind_stats$ where obj#=:1
END OF STMT
PARSE #140495297362384:c=21,e=21,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,plh=1596536394,tim=14479050077
EXEC #140495297362384:c=22,e=22,p=0,cr=1,cu=0,mis=0,r=0,dep=1,og=4,plh=1596536394,tim=14479050127
STAT #140495297362384 id=1 cnt=0 pid=0 pos=1 obj=0 op='DELETE IND_STATS$ (cr=1 pr=0 pw=0 str=1 time=4 us)'
STAT #140495297362384 id=2 cnt=0 pid=1 pos=1 obj=76 op='INDEX UNIQUE SCAN I_IND_STATS$_OBJ# (cr=1 pr=0 pw=0 str=1 time=3 us cost=0 size=13 card=1)'
CLOSE #140495297362384:c=5,e=5,dep=1,type=1,tim=14479050173
=====================
PARSING IN CURSOR #140495293558184 len=533 dep=1 uid=0 oct=6 lid=0 tim=14479050271 hv=625199886 ad='822edbe0' sqlid='gg8cpx0kn7ksf'
update ind$ set ts#=:2,file#=:3,block#=:4,intcols=:5,type#=:6,flags=:7,property=:8,pctfree$=:9,initrans=:10,maxtrans=:11,blevel=:12,leafcnt=:13,distkey=:14,lblkkey=:15,dblkkey=:16,clufac=:17,cols=:18,analyzetime=:19,samplesize=:20,dataobj#=:21,degree=decode(:22,1,null,:22),instances=decode(:23,1,null,:23),rowcnt=:24,pctthres$=:31*256+:25, indmethod#=:26, trunccnt=:27,evaledition#=decode(:33,1,null,:33),unusablebefore#=decode(:34,0,null,:34),unusablebeginning#=decode(:35,0,null,:35),spare4=:29,spare2=:30,spare6=:32 where obj#=:1
END OF STMT
EXEC #140495293558184:c=77,e=77,p=0,cr=2,cu=1,mis=0,r=1,dep=1,og=4,plh=2580332476,tim=14479050271
CLOSE #140495293558184:c=1,e=1,dep=1,type=3,tim=14479050307
=====================
PARSING IN CURSOR #140495297025144 len=314 dep=1 uid=0 oct=6 lid=0 tim=14479050406 hv=3096556448 ad='8245a2a0' sqlid='0kkhhb2w93cx0'
update seg$ set type#=:4,blocks=:5,extents=:6,minexts=:7,maxexts=:8,extsize=:9,extpct=:10,user#=:11,iniexts=:12,lists=decode(:13, 65535, NULL, :13),groups=decode(:14, 65535, NULL, :14), cachehint=:15, hwmincr=:16, spare1=DECODE(:17,0,NULL,:17),scanhint=:18, bitmapranges=:19 where ts#=:1 and file#=:2 and block#=:3
END OF STMT
EXEC #140495297025144:c=70,e=70,p=0,cr=3,cu=1,mis=0,r=1,dep=1,og=4,plh=2170058777,tim=14479050406
CLOSE #140495297025144:c=0,e=0,dep=1,type=3,tim=14479050441
EXEC #140495297025144:c=35,e=35,p=0,cr=3,cu=1,mis=0,r=1,dep=1,og=4,plh=2170058777,tim=14479050488
CLOSE #140495297025144:c=0,e=0,dep=1,type=3,tim=14479050498
EXEC #140495296748256:c=7217,e=7911,p=0,cr=58,cu=126,mis=1,r=0,dep=0,og=1,plh=2939908344,tim=14479052017
ERROR #140495296748256:err=8177 tim=14479052040
STAT #140495296748256 id=1 cnt=0 pid=0 pos=1 obj=0 op='MULTI-TABLE INSERT (cr=0 pr=0 pw=0 str=1 time=3 us)'
STAT #140495296748256 id=2 cnt=1 pid=1 pos=1 obj=0 op='FAST DUAL (cr=0 pr=0 pw=0 str=1 time=1 us cost=2 size=0 card=1)'
STAT #140495296748256 id=3 cnt=0 pid=1 pos=2 obj=76144 op='INTO SAM_COLLECTION_ACTION (cr=0 pr=0 pw=0 str=0 time=0 us)'
STAT #140495296748256 id=4 cnt=0 pid=1 pos=3 obj=76144 op='INTO SAM_COLLECTION_ACTION (cr=0 pr=0 pw=0 str=0 time=0 us)'
WAIT #140495296748256: nam='SQL*Net break/reset to client' ela= 7 driver id=1413697536 break?=1 p3=0 obj#=-1 tim=14479052122
WAIT #140495296748256: nam='SQL*Net break/reset to client' ela= 338 driver id=1413697536 break?=0 p3=0 obj#=-1 tim=14479052468
WAIT #140495296748256: nam='SQL*Net message to client' ela= 1 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=14479052541
WAIT #140495296748256: nam='SQL*Net message from client' ela= 2210 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=14479054802
CLOSE #140495296748256:c=6,e=6,dep=0,type=0,tim=14479054841
XCTEND rlbk=1, rd_only=0, tim=14479054875
WAIT #0: nam='log file sync' ela= 3529 buffer#=4257 sync scn=2413495 p3=0 obj#=-1 tim=14479058850
WAIT #0: nam='SQL*Net message to client' ela= 1 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=14479058893
WAIT #0: nam='SQL*Net message from client' ela= 508 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=14479059410
PARSE #140495297001416:c=4,e=4,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,plh=0,tim=14479059444
EXEC #140495297001416:c=7,e=8,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,plh=0,tim=14479059462
XCTEND rlbk=0, rd_only=1, tim=14479059470
WAIT #140495297001416: nam='SQL*Net message to client' ela= 1 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=14479059478
Based on "When we deploy our application on the new virtual machine with the new Oracle instance the usecase is occurred again"
a possible cause here is deferred segment creation. By default, when you create a table, we don't allocate any space for it, because you might never insert a row into it, so why waste the space. When you perform your first INSERT, only then do we perform a recursive transaction to allocate the space.
Try creating your table as
CREATE TABLE SAM_COLLECTION_ACTION ( ... ) SEGMENT CREATION IMMEDIATE
and see if that fixes the issue.
Addenda: Take a long look to see if you really need SERIALIZABLE at all. It's pretty rare.