Hi all,
I have a webapp running oak version 1.42.0, it has been running fine for
quite some time but recently I'm seeing a behavior I can't understand. The
versioning of nodes hangs and then eventually fails because it exceeds the
transaction timeout.
The process hangs on the checkin and I've seen that, when it happens, the
ChangeCollectorProvider is never called after the checkout.
I've collected two example of the log, the first one taken when everything
works fine, the second when there's the transaction timeout.
Anyone has any idea why it is happening?
This is a part of the log where everything works fine:
2024-12-04 15:38:48,752 ij350-gpu quarkus-run.jar[2289676] DEBUG
[org.apa.jac.oak.audit] (executor-thread-13) [administrator] [session-664]
checkout
2024-12-04 15:38:48,752 ij350-gpu quarkus-run.jar[2289676] DEBUG
[org.apa.jac.oak.plu.ind.pro.PropertyIndex] (executor-thread-13) property
cost for uuid is 2.0
2024-12-04 15:38:48,752 ij350-gpu quarkus-run.jar[2289676] DEBUG
[org.apa.jac.oak.que.QueryImpl] (executor-thread-13) minCost: 2.05 of index
:nodeType < best Cost: 2.0 from index: property. Further index evaluation
will be skipped
2024-12-04 15:38:48,754 ij350-gpu quarkus-run.jar[2289676] DEBUG
[org.apa.jac.oak.plu.ind.pro.PropertyIndex] (executor-thread-13) property
cost for uuid is 2.0
2024-12-04 15:38:48,754 ij350-gpu quarkus-run.jar[2289676] DEBUG
[org.apa.jac.oak.plu.ind.pro.PropertyIndex] (executor-thread-13) property
cost for uuid is 2.0
2024-12-04 15:38:48,755 ij350-gpu quarkus-run.jar[2289676] DEBUG
[org.apa.jac.oak.plu.obs.ChangeCollectorProvider] (executor-thread-13)
Collected changeSet for commit CommitInfo{sessionId=session-664,
userId=administrator, external=false, date=1733294328754,
info={oak.commitAttributes=CommitContext[attrs={oak.observation.changeSet=ChangeSet{....}
2024-12-04 15:38:48,755 ij350-gpu quarkus-run.jar[2289676] DEBUG
[org.apa.jac.oak.plu.ind.IndexUpdate] (executor-thread-13) Indexing report
- /oak:index/idVersionIndex(1)
- /oak:index/uuid(1)
- /oak:index/idIndex(1)
- /oak:index/nodetype(2)
2024-12-04 15:38:48,756 ij350-gpu quarkus-run.jar[2289676] DEBUG
[org.apa.jac.oak.plu.ind.pro.PropertyIndex] (executor-thread-13) property
cost for uuid is 2.0
2024-12-04 15:38:48,756 ij350-gpu quarkus-run.jar[2289676] DEBUG
[org.apa.jac.oak.que.QueryImpl] (executor-thread-13) minCost: 2.05 of index
:nodeType < best Cost: 2.0 from index: property. Further index evaluation
will be skipped
2024-12-04 15:38:48,756 ij350-gpu quarkus-run.jar[2289676] DEBUG
[org.apa.jac.oak.audit] (executor-thread-13) [administrator] [session-664]
checkin
This is a part of the log where the error happens:
2024-12-04 15:54:23,398 ij350-gpu quarkus-run.jar[2289676] DEBUG
[org.apa.jac.oak.audit] (executor-thread-15) [administrator] [session-907]
checkout
2024-12-04 15:54:23,398 ij350-gpu quarkus-run.jar[2289676] DEBUG
[org.apa.jac.oak.plu.ind.pro.PropertyIndex] (executor-thread-15) property
cost for uuid is 2.0
2024-12-04 15:54:23,398 ij350-gpu quarkus-run.jar[2289676] DEBUG
[org.apa.jac.oak.que.QueryImpl] (executor-thread-15) minCost: 2.05 of index
:nodeType < best Cost: 2.0 from index: property. Further index evaluation
will be skipped
2024-12-04 15:54:23,986 ij350-gpu quarkus-run.jar[2289676] DEBUG
[org.qua.cor.JobRunShell] (ApplicationScheduler_Worker-12) Calling execute
on job DEFAULT.EventQueueTimer
2024-12-04 15:54:23,986 ij350-gpu quarkus-run.jar[2289676] FINE
[it.est.som.que.obs.EventQueueObserver] (ApplicationScheduler_Worker-12)
checking for messages within the event queue
2024-12-04 15:54:23,986 ij350-gpu quarkus-run.jar[2289676] DEBUG
[org.qua.cor.QuartzSchedulerThread]
(ApplicationScheduler_QuartzSchedulerThread) batch acquisition of 1 triggers
2024-12-04 15:54:24,452 ij350-gpu quarkus-run.jar[2289676] DEBUG
[org.apa.jac.oak.seg.SegmentBufferWriter] (TarMK flush
[/data1/app/content]) Writing data segment:
id=e12f72b5-b6ab-4596-abc8-e28c4f7de3c8,size=24448,segmentIdCount=100,recordIdCount=2386,recordCount=415
2024-12-04 15:54:24,452 ij350-gpu quarkus-run.jar[2289676] DEBUG
[org.apa.jac.oak.seg.fil.tar.SegmentTarWriter] (TarMK flush
[/data1/app/content]) Writing segment e12f72b5-b6ab-4596-abc8-e28c4f7de3c8
to /data1/app/content/data00025a.tar
2024-12-04 15:54:24,465 ij350-gpu quarkus-run.jar[2289676] DEBUG
[org.apa.jac.oak.seg.fil.TarRevisions] (TarMK flush [/data1/app/content])
TarMK journal update 8933849a-9726-4d60-af71-c30882c13f00.0000004a ->
e12f72b5-b6ab-4596-abc8-e28c4f7de3c8.0000019e
2024-12-04 15:54:24,616 ij350-gpu quarkus-run.jar[2289676] DEBUG
[org.apa.jac.oak.seg.fil.TarRevisions] (TarMK flush
[/data1/app/alt/content]) Head state did not change, skipping flush
2024-12-04 15:54:25,291 ij350-gpu quarkus-run.jar[2289676] DEBUG
[org.apa.jac.oak.plu.ind.AsyncIndexUpdate] (oak-scheduled-executor-4398)
[async] Running background index task
2024-12-04 15:54:25,291 ij350-gpu quarkus-run.jar[2289676] DEBUG
[org.apa.jac.oak.plu.ind.AsyncIndexUpdate] (oak-scheduled-executor-4398)
[async] No changes since last checkpoint; skipping the index update
2024-12-04 15:54:25,310 ij350-gpu quarkus-run.jar[2289676] DEBUG
[org.apa.jac.oak.plu.ind.AsyncIndexUpdate] (oak-scheduled-executor-4372)
[async] Running background index task
2024-12-04 15:54:25,312 ij350-gpu quarkus-run.jar[2289676] DEBUG
[org.apa.jac.oak.plu.ind.AsyncIndexUpdate] (async-index-update-async)
[async] Releasing temporary checkpoint
f9a4d935-84a0-40ca-b32a-8705ded6aea9: true
2024-12-04 15:54:25,314 ij350-gpu quarkus-run.jar[2289676] DEBUG
[org.apa.jac.oak.plu.ind.AsyncIndexUpdate] (async-index-update-async)
[async] AsyncIndex update run completed in 2.088 ms. Indexed 0 nodes,
changedNodeCount 28, changedPropertyCount 70
2024-12-04 15:54:30,801 ij350-gpu quarkus-run.jar[2289676] DEBUG
[org.apa.jac.oak.seg.SegmentBufferWriter] (TarMK flush
[/data1/app/content]) Writing data segment:
id=ab6c355e-df2c-4084-a333-3fed3176cf73,size=3408,segmentIdCount=13,recordIdCount=322,recordCount=75
2024-12-04 15:54:30,802 ij350-gpu quarkus-run.jar[2289676] DEBUG
[org.apa.jac.oak.seg.fil.tar.SegmentTarWriter] (TarMK flush
[/data1/app/content]) Writing segment ab6c355e-df2c-4084-a333-3fed3176cf73
to /data1/app/content/data00025a.tar
2024-12-04 15:54:30,815 ij350-gpu quarkus-run.jar[2289676] DEBUG
[org.apa.jac.oak.seg.fil.TarRevisions] (TarMK flush [/data1/app/content])
TarMK journal update e12f72b5-b6ab-4596-abc8-e28c4f7de3c8.0000019e ->
ab6c355e-df2c-4084-a333-3fed3176cf73.0000004a
2024-12-04 15:54:30,951 ij350-gpu quarkus-run.jar[2289676] DEBUG
[org.apa.jac.oak.seg.fil.TarRevisions] (TarMK flush
[/data1/app/alt/content]) Head state did not change, skipping flush
......
2024-12-04 15:55:24,530 ij350-gpu quarkus-run.jar[2289676] WARN
[com.arj.ats.arjuna] (Transaction Reaper) ARJUNA012117:
TransactionReaper::check processing TX 0:ffffa15ea93d:87f1:674fc568:1751 in
state RUN
2024-12-04 15:55:24,530 ij350-gpu quarkus-run.jar[2289676] WARN
[com.arj.ats.arjuna] (Transaction Reaper) ARJUNA012117:
TransactionReaper::check processing TX 0:ffffa15ea93d:87f1:674fc568:1752 in
state RUN
2024-12-04 15:55:24,533 ij350-gpu quarkus-run.jar[2289676] WARN
[com.arj.ats.arjuna] (Transaction Reaper Worker 0) ARJUNA012121:
TransactionReaper::doCancellations worker Thread[Transaction Reaper Worker
0,5,main] successfully canceled TX 0:ffffa15ea93d:87f1:674fc568:1751
2024-12-04 15:55:24,535 ij350-gpu quarkus-run.jar[2289676] WARN
[com.arj.ats.arjuna] (Transaction Reaper Worker 0) ARJUNA012095: Abort of
action id 0:ffffa15ea93d:87f1:674fc568:1752 invoked while multiple threads
active within it.
2024-12-04 15:55:24,536 ij350-gpu quarkus-run.jar[2289676] WARN
[com.arj.ats.arjuna] (Transaction Reaper Worker 0) ARJUNA012381: Action id
0:ffffa15ea93d:87f1:674fc568:1752 completed with multiple threads - thread
executor-thread-15 was in progress with
[email protected]/java.lang.Object.wait(Native
Method)
[email protected]/java.lang.Object.wait(Object.java:462)
org.apache.jackrabbit.oak.stats.Clock.getTimeIncreasing(Clock.java:111)
org.apache.jackrabbit.oak.stats.Clock.waitUntil(Clock.java:157)
org.apache.jackrabbit.oak.jcr.version.ReadWriteVersionManager.checkin(ReadWriteVersionManager.java:130)
org.apache.jackrabbit.oak.jcr.delegate.VersionManagerDelegate.checkin(VersionManagerDelegate.java:67)
org.apache.jackrabbit.oak.jcr.version.VersionManagerImpl$7.perform(VersionManagerImpl.java:372)
org.apache.jackrabbit.oak.jcr.version.VersionManagerImpl$7.perform(VersionManagerImpl.java:363)
org.apache.jackrabbit.oak.jcr.delegate.SessionDelegate.perform(SessionDelegate.java:209)
org.apache.jackrabbit.oak.jcr.version.VersionManagerImpl.checkin(VersionManagerImpl.java:363)
--
<https://25.esteco.com>
