jena
jena copied to clipboard
apache
Compaction getting stuck
Version
5.5.0
What happened?
We do an automated nightly compaction starting at 02:00 UTC.
Recently compaction has stopped working and getting stuck indefinitely increasingly commonly. Once a compaction has gotten stuck, any subsequent compactions the following nights are guaranteed to either fail or also be stuck indefinitely until Fuseki is restarted.
Whenever this happens, it creates a seemingly fully compacted Data-XXXX directory which is never cleaned up (we do use ?deleteOld=true):
$ ls -lat
total 36
drwxr-xr-x 8 root root 4096 Oct 2 04:39 .
drwxr-xr-x 2 root root 4096 Oct 2 04:00 Data-0790
-rw-r--r-- 1 root root 2 Oct 1 08:40 tdb.lock
drwxr-xr-x 2 root root 4096 Sep 29 04:00 Data-0789
drwxr-xr-x 2 root root 4096 Sep 27 04:00 Data-0788
drwxr-xr-x 2 root root 4096 Sep 26 04:00 Data-0787
drwxr-xr-x 2 root root 4096 Sep 24 04:00 Data-0785
drwxr-xr-x 2 root root 4096 Sep 18 04:00 Data-0783
drwxr-xr-x 3 root root 4096 Mar 29 2023 ..
$ du -ha --max-depth=1
38G ./Data-0787
38G ./Data-0783
4.0K ./tdb.lock
40G ./Data-0789
38G ./Data-0790
38G ./Data-0785
38G ./Data-0788
228G .
This used to happen infrequently for quite a while already, also with Fuseki 5.2.0 before we updated to 5.5.0, but wasn't common enough to be a big problem. However, recently it has become very likely to get stuck.
We know the compaction is stuck because our compaction script queries http://db:3030/$/tasks/${taskId} and aborts when .success != true ("Failed compacting dsp-repo") or with a timeout ("Timed out while compacting dsp-repo") after 12h of compaction not finishing (it usually finishes in ca. 45min. when it works).
Otherwise there are no indications that something is wrong. Besides the sometimes random stacktrace there are no logs (we only log WARN and above) and the DB continues to seemingly work fine otherwise (queries, updates).
We run Fuseki in a docker container based on eclipse-temurin:21-jre-jammy.
Full command running in container:
/opt/java/openjdk/bin/java -Xmx2G -Dlog4j2.formatMsgNoLookups=true --enable-native-access=ALL-UNNAMED --add-modules=jdk.incubator.vector -Dlog4j.configurationFile=/jena-fuseki/log4j2.properties -cp /jena-fuseki/fuseki-server.jar org.apache.jena.fuseki.main.cmds.FusekiServerCmd
Config file:
@prefix : <http://base/#> .
@prefix fuseki: <http://jena.apache.org/fuseki#> .
@prefix ja: <http://jena.hpl.hp.com/2005/11/Assembler#> .
@prefix tdb2: <http://jena.apache.org/2016/tdb#> .
@prefix rdf: <http://www.w3.org/1999/02/22-rdf-syntax-ns#> .
@prefix rdfs: <http://www.w3.org/2000/01/rdf-schema#> .
@prefix text: <http://jena.apache.org/text#> .
@prefix knora-base: <http://www.knora.org/ontology/knora-base#> .
:service_tdb_all a fuseki:Service ;
rdfs:label "TDB2 dsp-repo" ;
fuseki:dataset :text_dataset ;
fuseki:name "dsp-repo" ;
fuseki:serviceQuery "query" , "sparql" ;
fuseki:serviceReadGraphStore "get" ;
fuseki:serviceReadWriteGraphStore "data" ;
fuseki:serviceUpdate "update" ;
fuseki:serviceUpload "upload" .
## ---------------------------------------------------------------
## This URI must be fixed - it's used to assemble the text dataset.
:text_dataset rdf:type text:TextDataset ;
text:dataset :tdb_dataset_readwrite ;
text:index :indexLucene .
# A TDB datset used for RDF storage
:tdb_dataset_readwrite a tdb2:DatasetTDB2 ;
tdb2:unionDefaultGraph true ;
tdb2:location "/fuseki/databases/dsp-repo" .
# Text index description
:indexLucene a text:TextIndexLucene ;
text:directory "/fuseki/lucene/dsp-repo" ;
text:entityMap :entMap ;
text:analyzer [ a text:ConfigurableAnalyzer ;
text:tokenizer text:WhitespaceTokenizer ;
text:filters ( text:ASCIIFoldingFilter text:LowerCaseFilter)
] .
# Mapping in the index
# URI stored in field "uri"
# knora-base:valueHasString is mapped to field "text"
:entMap a text:EntityMap ;
text:entityField "uri" ;
text:defaultField "text" ;
text:uidField "uid" ;
text:map (
[ text:field "text" ; text:predicate rdfs:label ]
[ text:field "text" ; text:predicate knora-base:valueHasString ]
[ text:field "text" ; text:predicate knora-base:valueHasComment ]
) .
Relevant output and stacktrace
There doesn't seem to be a consistent exception when this happens.
However, sometimes there's an exception around the time I'd expect the compaction to finish (after ca. 45min.):
Exception in insertPrefixes: Not in a transaction
org.apache.jena.dboe.transaction.txn.TransactionException: Not in a transaction
at org.apache.jena.dboe.transaction.txn.TransactionalComponentLifecycle.checkTxn(TransactionalComponentLifecycle.java:350)
at org.apache.jena.dboe.trans.bplustree.BPlusTree.getRootRead(BPlusTree.java:156)
at org.apache.jena.dboe.trans.bplustree.BPlusTree.find(BPlusTree.java:231)
at org.apache.jena.tdb2.store.nodetable.NodeTableNative.accessIndex(NodeTableNative.java:130)
at org.apache.jena.tdb2.store.nodetable.NodeTableNative._idForNode(NodeTableNative.java:116)
at org.apache.jena.tdb2.store.nodetable.NodeTableNative.getNodeIdForNode(NodeTableNative.java:57)
at org.apache.jena.tdb2.store.nodetable.NodeTableCache._idForNode(NodeTableCache.java:241)
at org.apache.jena.tdb2.store.nodetable.NodeTableCache.getNodeIdForNode(NodeTableCache.java:143)
at org.apache.jena.tdb2.store.nodetable.NodeTableWrapper.getNodeIdForNode(NodeTableWrapper.java:47)
at org.apache.jena.tdb2.store.nodetable.NodeTableInline.getNodeIdForNode(NodeTableInline.java:57)
at org.apache.jena.tdb2.store.nodetupletable.NodeTupleTableConcrete.idForNode(NodeTupleTableConcrete.java:188)
at org.apache.jena.tdb2.store.nodetupletable.NodeTupleTableConcrete.findAsNodeIds(NodeTupleTableConcrete.java:141)
at org.apache.jena.tdb2.store.nodetupletable.NodeTupleTableConcrete.find(NodeTupleTableConcrete.java:119)
at org.apache.jena.tdb2.store.StoragePrefixesTDB.get(StoragePrefixesTDB.java:71)
at org.apache.jena.dboe.storage.prefixes.StoragePrefixesView.stream(StoragePrefixesView.java:98)
at org.apache.jena.dboe.storage.prefixes.PrefixMapOverStorage.getMappingCopy(PrefixMapOverStorage.java:48)
at org.apache.jena.dboe.storage.prefixes.PrefixMapOverStorage.getMapping(PrefixMapOverStorage.java:43)
at org.apache.jena.riot.system.PrefixMapWrapper.getMapping(PrefixMapWrapper.java:41)
at org.apache.jena.riot.system.PrefixMapBase.putAll(PrefixMapBase.java:65)
at org.apache.jena.sparql.exec.QueryExecDataset.insertPrefixesInto(QueryExecDataset.java:547)
at org.apache.jena.sparql.exec.QueryExecDataset.constructDataset(QueryExecDataset.java:247)
at org.apache.jena.sparql.exec.QueryExec.constructDataset(QueryExec.java:166)
at org.apache.jena.fuseki.servlets.SPARQLQueryProcessor.executeQuery(SPARQLQueryProcessor.java:401)
at org.apache.jena.fuseki.servlets.SPARQLQueryProcessor.execute(SPARQLQueryProcessor.java:284)
at org.apache.jena.fuseki.servlets.SPARQLQueryProcessor.executeWithParameter(SPARQLQueryProcessor.java:224)
at org.apache.jena.fuseki.servlets.SPARQLQueryProcessor.execute(SPARQLQueryProcessor.java:209)
at org.apache.jena.fuseki.servlets.ActionService.executeLifecycle(ActionService.java:58)
at org.apache.jena.fuseki.servlets.SPARQLQueryProcessor.execPost(SPARQLQueryProcessor.java:84)
at org.apache.jena.fuseki.servlets.ActionProcessor.process(ActionProcessor.java:34)
at org.apache.jena.fuseki.servlets.ActionBase.process(ActionBase.java:54)
at org.apache.jena.fuseki.servlets.ActionExecLib.execActionSub(ActionExecLib.java:124)
at org.apache.jena.fuseki.servlets.ActionExecLib.execAction(ActionExecLib.java:98)
at org.apache.jena.fuseki.server.Dispatcher.dispatchAction(Dispatcher.java:239)
at org.apache.jena.fuseki.server.Dispatcher.process(Dispatcher.java:229)
at org.apache.jena.fuseki.server.Dispatcher.dispatch(Dispatcher.java:147)
at org.apache.jena.fuseki.servlets.FusekiFilter.doFilter(FusekiFilter.java:49)
at org.eclipse.jetty.ee10.servlet.FilterHolder.doFilter(FilterHolder.java:205)
at org.eclipse.jetty.ee10.servlet.ServletHandler$Chain.doFilter(ServletHandler.java:1594)
at org.apache.shiro.web.servlet.ProxiedFilterChain.doFilter(ProxiedFilterChain.java:65)
at org.apache.shiro.web.servlet.AdviceFilter.executeChain(AdviceFilter.java:109)
at org.apache.shiro.web.servlet.AdviceFilter.doFilterInternal(AdviceFilter.java:138)
at org.apache.shiro.web.servlet.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:156)
at org.apache.shiro.web.servlet.ProxiedFilterChain.doFilter(ProxiedFilterChain.java:70)
at org.apache.shiro.web.servlet.AdviceFilter.executeChain(AdviceFilter.java:109)
at org.apache.shiro.web.servlet.AdviceFilter.doFilterInternal(AdviceFilter.java:138)
at org.apache.shiro.web.servlet.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:156)
at org.apache.shiro.web.servlet.ProxiedFilterChain.doFilter(ProxiedFilterChain.java:70)
at org.apache.shiro.web.servlet.AdviceFilter.executeChain(AdviceFilter.java:109)
at org.apache.shiro.web.servlet.AdviceFilter.doFilterInternal(AdviceFilter.java:138)
at org.apache.shiro.web.servlet.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:156)
at org.apache.shiro.web.servlet.ProxiedFilterChain.doFilter(ProxiedFilterChain.java:70)
at org.apache.shiro.web.servlet.AbstractShiroFilter.executeChain(AbstractShiroFilter.java:463)
at org.apache.shiro.web.servlet.AbstractShiroFilter.lambda$doFilterInternal$0(AbstractShiroFilter.java:378)
at org.apache.shiro.subject.support.SubjectCallable.doCall(SubjectCallable.java:91)
at org.apache.shiro.subject.support.SubjectCallable.call(SubjectCallable.java:84)
at org.apache.shiro.subject.support.DelegatingSubject.execute(DelegatingSubject.java:389)
at org.apache.shiro.web.servlet.AbstractShiroFilter.doFilterInternal(AbstractShiroFilter.java:376)
at org.apache.shiro.web.servlet.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:156)
at org.eclipse.jetty.ee10.servlet.FilterHolder.doFilter(FilterHolder.java:205)
at org.eclipse.jetty.ee10.servlet.ServletHandler$Chain.doFilter(ServletHandler.java:1594)
at org.apache.jena.fuseki.servlets.CrossOriginFilter.handle(CrossOriginFilter.java:351)
at org.apache.jena.fuseki.servlets.CrossOriginFilter.doFilter(CrossOriginFilter.java:304)
at org.eclipse.jetty.ee10.servlet.FilterHolder.doFilter(FilterHolder.java:205)
All compaction logs and DB logs around the compaction timeframe (02:00 - 03:59 UTC) over the last month on this server:
1759370400714 2025-10-02T02:00:00.714Z [Task 1] starts : Compact
1759370400709 2025-10-02T02:00:00.709Z Task : 1 : Compact
1759284000701 2025-10-01T02:00:00.701Z [Task 3] starts : Compact
1759284000700 2025-10-01T02:00:00.700Z Task : 3 : Compact
1759240863739 2025-09-30T14:01:03.739Z Tue Sep 30 16:01:03 CEST 2025: Timed out while compacting dsp-repo
1759197600792 2025-09-30T02:00:00.792Z [Task 2] starts : Compact
1759197600791 2025-09-30T02:00:00.791Z Task : 2 : Compact
1759154465935 2025-09-29T14:01:05.935Z Mon Sep 29 16:01:05 CEST 2025: Timed out while compacting dsp-repo
1759111200933 2025-09-29T02:00:00.933Z [Task 1] starts : Compact
1759111200924 2025-09-29T02:00:00.924Z Task : 1 : Compact
1759024801161 2025-09-28T02:00:01.161Z [Task 3] starts : Compact
1759024801144 2025-09-28T02:00:01.144Z Task : 3 : Compact
1758981663937 2025-09-27T14:01:03.937Z Sat Sep 27 16:01:03 CEST 2025: Timed out while compacting dsp-repo
1758941302902 2025-09-27T02:48:22.902Z Exception in insertPrefixes: Not in a transaction
org.apache.jena.dboe.transaction.txn.TransactionException: Not in a transaction
at org.apache.jena.dboe.transaction.txn.TransactionalComponentLifecycle.checkTxn(TransactionalComponentLifecycle.java:350)
at org.apache.jena.dboe.trans.bplustree.BPlusTree.getRootRead(BPlusTree.java:156)
at org.apache.jena.dboe.trans.bplustree.BPlusTree.find(BPlusTree.java:231)
at org.apache.jena.tdb2.store.nodetable.NodeTableNative.accessIndex(NodeTableNative.java:130)
at org.apache.jena.tdb2.store.nodetable.NodeTableNative._idForNode(NodeTableNative.java:116)
at org.apache.jena.tdb2.store.nodetable.NodeTableNative.getNodeIdForNode(NodeTableNative.java:57)
at org.apache.jena.tdb2.store.nodetable.NodeTableCache._idForNode(NodeTableCache.java:241)
at org.apache.jena.tdb2.store.nodetable.NodeTableCache.getNodeIdForNode(NodeTableCache.java:143)
at org.apache.jena.tdb2.store.nodetable.NodeTableWrapper.getNodeIdForNode(NodeTableWrapper.java:47)
at org.apache.jena.tdb2.store.nodetable.NodeTableInline.getNodeIdForNode(NodeTableInline.java:57)
at org.apache.jena.tdb2.store.nodetupletable.NodeTupleTableConcrete.idForNode(NodeTupleTableConcrete.java:188)
at org.apache.jena.tdb2.store.nodetupletable.NodeTupleTableConcrete.findAsNodeIds(NodeTupleTableConcrete.java:141)
at org.apache.jena.tdb2.store.nodetupletable.NodeTupleTableConcrete.find(NodeTupleTableConcrete.java:119)
at org.apache.jena.tdb2.store.StoragePrefixesTDB.get(StoragePrefixesTDB.java:71)
at org.apache.jena.dboe.storage.prefixes.StoragePrefixesView.stream(StoragePrefixesView.java:98)
at org.apache.jena.dboe.storage.prefixes.PrefixMapOverStorage.getMappingCopy(PrefixMapOverStorage.java:48)
at org.apache.jena.dboe.storage.prefixes.PrefixMapOverStorage.getMapping(PrefixMapOverStorage.java:43)
at org.apache.jena.riot.system.PrefixMapWrapper.getMapping(PrefixMapWrapper.java:41)
at org.apache.jena.riot.system.PrefixMapBase.putAll(PrefixMapBase.java:65)
at org.apache.jena.sparql.exec.QueryExecDataset.insertPrefixesInto(QueryExecDataset.java:547)
at org.apache.jena.sparql.exec.QueryExecDataset.constructDataset(QueryExecDataset.java:247)
at org.apache.jena.sparql.exec.QueryExec.constructDataset(QueryExec.java:166)
at org.apache.jena.fuseki.servlets.SPARQLQueryProcessor.executeQuery(SPARQLQueryProcessor.java:401)
at org.apache.jena.fuseki.servlets.SPARQLQueryProcessor.execute(SPARQLQueryProcessor.java:284)
at org.apache.jena.fuseki.servlets.SPARQLQueryProcessor.executeWithParameter(SPARQLQueryProcessor.java:224)
at org.apache.jena.fuseki.servlets.SPARQLQueryProcessor.execute(SPARQLQueryProcessor.java:209)
at org.apache.jena.fuseki.servlets.ActionService.executeLifecycle(ActionService.java:58)
at org.apache.jena.fuseki.servlets.SPARQLQueryProcessor.execPost(SPARQLQueryProcessor.java:84)
at org.apache.jena.fuseki.servlets.ActionProcessor.process(ActionProcessor.java:34)
at org.apache.jena.fuseki.servlets.ActionBase.process(ActionBase.java:54)
at org.apache.jena.fuseki.servlets.ActionExecLib.execActionSub(ActionExecLib.java:124)
at org.apache.jena.fuseki.servlets.ActionExecLib.execAction(ActionExecLib.java:98)
at org.apache.jena.fuseki.server.Dispatcher.dispatchAction(Dispatcher.java:239)
at org.apache.jena.fuseki.server.Dispatcher.process(Dispatcher.java:229)
at org.apache.jena.fuseki.server.Dispatcher.dispatch(Dispatcher.java:147)
at org.apache.jena.fuseki.servlets.FusekiFilter.doFilter(FusekiFilter.java:49)
at org.eclipse.jetty.ee10.servlet.FilterHolder.doFilter(FilterHolder.java:205)
at org.eclipse.jetty.ee10.servlet.ServletHandler$Chain.doFilter(ServletHandler.java:1594)
at org.apache.shiro.web.servlet.ProxiedFilterChain.doFilter(ProxiedFilterChain.java:65)
at org.apache.shiro.web.servlet.AdviceFilter.executeChain(AdviceFilter.java:109)
at org.apache.shiro.web.servlet.AdviceFilter.doFilterInternal(AdviceFilter.java:138)
at org.apache.shiro.web.servlet.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:156)
at org.apache.shiro.web.servlet.ProxiedFilterChain.doFilter(ProxiedFilterChain.java:70)
at org.apache.shiro.web.servlet.AdviceFilter.executeChain(AdviceFilter.java:109)
at org.apache.shiro.web.servlet.AdviceFilter.doFilterInternal(AdviceFilter.java:138)
at org.apache.shiro.web.servlet.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:156)
at org.apache.shiro.web.servlet.ProxiedFilterChain.doFilter(ProxiedFilterChain.java:70)
at org.apache.shiro.web.servlet.AdviceFilter.executeChain(AdviceFilter.java:109)
at org.apache.shiro.web.servlet.AdviceFilter.doFilterInternal(AdviceFilter.java:138)
at org.apache.shiro.web.servlet.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:156)
at org.apache.shiro.web.servlet.ProxiedFilterChain.doFilter(ProxiedFilterChain.java:70)
at org.apache.shiro.web.servlet.AbstractShiroFilter.executeChain(AbstractShiroFilter.java:463)
at org.apache.shiro.web.servlet.AbstractShiroFilter.lambda$doFilterInternal$0(AbstractShiroFilter.java:378)
at org.apache.shiro.subject.support.SubjectCallable.doCall(SubjectCallable.java:91)
at org.apache.shiro.subject.support.SubjectCallable.call(SubjectCallable.java:84)
at org.apache.shiro.subject.support.DelegatingSubject.execute(DelegatingSubject.java:389)
at org.apache.shiro.web.servlet.AbstractShiroFilter.doFilterInternal(AbstractShiroFilter.java:376)
at org.apache.shiro.web.servlet.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:156)
at org.eclipse.jetty.ee10.servlet.FilterHolder.doFilter(FilterHolder.java:205)
at org.eclipse.jetty.ee10.servlet.ServletHandler$Chain.doFilter(ServletHandler.java:1594)
at org.apache.jena.fuseki.servlets.CrossOriginFilter.handle(CrossOriginFilter.java:351)
at org.apache.jena.fuseki.servlets.CrossOriginFilter.doFilter(CrossOriginFilter.java:304)
at org.eclipse.jetty.ee10.servlet.FilterHolder.doFilter(FilterHolder.java:205)
1758938400104 2025-09-27T02:00:00.104Z [Task 2] starts : Compact
1758938400101 2025-09-27T02:00:00.101Z Task : 2 : Compact
1758854725922 2025-09-26T02:45:25.922Z Fri Sep 26 04:45:25 CEST 2025: Successfully compacted dsp-repo
1758854719260 2025-09-26T02:45:19.260Z [Task 1] finishes : Compact
1758852000630 2025-09-26T02:00:00.630Z [Task 1] starts : Compact
1758852000626 2025-09-26T02:00:00.626Z Task : 1 : Compact
1758765600991 2025-09-25T02:00:00.991Z [Task 2] starts : Compact
1758765600988 2025-09-25T02:00:00.988Z Task : 2 : Compact
1758682025239 2025-09-24T02:47:05.239Z Wed Sep 24 04:47:05 CEST 2025: Successfully compacted dsp-repo
1758682015746 2025-09-24T02:46:55.746Z [Task 1] finishes : Compact
1758679200557 2025-09-24T02:00:00.557Z [Task 1] starts : Compact
1758679200549 2025-09-24T02:00:00.549Z Task : 1 : Compact
1758603019093 2025-09-23T04:50:19.093Z Tue Sep 23 06:50:18 CEST 2025: Failed compacting dsp-repo
1758592801011 2025-09-23T02:00:01.011Z [Task 2] starts : Compact
1758592801008 2025-09-23T02:00:01.008Z Task : 2 : Compact
1758549665049 2025-09-22T14:01:05.049Z Mon Sep 22 16:01:04 CEST 2025: Timed out while compacting dsp-repo
1758509099221 2025-09-22T02:44:59.221Z Exception in insertPrefixes: Not in a transaction
org.apache.jena.dboe.transaction.txn.TransactionException: Not in a transaction
at org.apache.jena.dboe.transaction.txn.TransactionalComponentLifecycle.checkTxn(TransactionalComponentLifecycle.java:350)
at org.apache.jena.dboe.trans.bplustree.BPlusTree.getRootRead(BPlusTree.java:156)
at org.apache.jena.dboe.trans.bplustree.BPlusTree.find(BPlusTree.java:231)
at org.apache.jena.tdb2.store.nodetable.NodeTableNative.accessIndex(NodeTableNative.java:130)
at org.apache.jena.tdb2.store.nodetable.NodeTableNative._idForNode(NodeTableNative.java:116)
at org.apache.jena.tdb2.store.nodetable.NodeTableNative.getNodeIdForNode(NodeTableNative.java:57)
at org.apache.jena.tdb2.store.nodetable.NodeTableCache._idForNode(NodeTableCache.java:241)
at org.apache.jena.tdb2.store.nodetable.NodeTableCache.getNodeIdForNode(NodeTableCache.java:143)
at org.apache.jena.tdb2.store.nodetable.NodeTableWrapper.getNodeIdForNode(NodeTableWrapper.java:47)
at org.apache.jena.tdb2.store.nodetable.NodeTableInline.getNodeIdForNode(NodeTableInline.java:57)
at org.apache.jena.tdb2.store.nodetupletable.NodeTupleTableConcrete.idForNode(NodeTupleTableConcrete.java:188)
at org.apache.jena.tdb2.store.nodetupletable.NodeTupleTableConcrete.findAsNodeIds(NodeTupleTableConcrete.java:141)
at org.apache.jena.tdb2.store.nodetupletable.NodeTupleTableConcrete.find(NodeTupleTableConcrete.java:119)
at org.apache.jena.tdb2.store.StoragePrefixesTDB.get(StoragePrefixesTDB.java:71)
at org.apache.jena.dboe.storage.prefixes.StoragePrefixesView.stream(StoragePrefixesView.java:98)
at org.apache.jena.dboe.storage.prefixes.PrefixMapOverStorage.getMappingCopy(PrefixMapOverStorage.java:48)
at org.apache.jena.dboe.storage.prefixes.PrefixMapOverStorage.getMapping(PrefixMapOverStorage.java:43)
at org.apache.jena.riot.system.PrefixMapWrapper.getMapping(PrefixMapWrapper.java:41)
at org.apache.jena.riot.system.PrefixMapBase.putAll(PrefixMapBase.java:65)
at org.apache.jena.sparql.exec.QueryExecDataset.insertPrefixesInto(QueryExecDataset.java:547)
at org.apache.jena.sparql.exec.QueryExecDataset.constructDataset(QueryExecDataset.java:247)
at org.apache.jena.sparql.exec.QueryExec.constructDataset(QueryExec.java:166)
at org.apache.jena.fuseki.servlets.SPARQLQueryProcessor.executeQuery(SPARQLQueryProcessor.java:401)
at org.apache.jena.fuseki.servlets.SPARQLQueryProcessor.execute(SPARQLQueryProcessor.java:284)
at org.apache.jena.fuseki.servlets.SPARQLQueryProcessor.executeWithParameter(SPARQLQueryProcessor.java:224)
at org.apache.jena.fuseki.servlets.SPARQLQueryProcessor.execute(SPARQLQueryProcessor.java:209)
at org.apache.jena.fuseki.servlets.ActionService.executeLifecycle(ActionService.java:58)
at org.apache.jena.fuseki.servlets.SPARQLQueryProcessor.execPost(SPARQLQueryProcessor.java:84)
at org.apache.jena.fuseki.servlets.ActionProcessor.process(ActionProcessor.java:34)
at org.apache.jena.fuseki.servlets.ActionBase.process(ActionBase.java:54)
at org.apache.jena.fuseki.servlets.ActionExecLib.execActionSub(ActionExecLib.java:124)
at org.apache.jena.fuseki.servlets.ActionExecLib.execAction(ActionExecLib.java:98)
at org.apache.jena.fuseki.server.Dispatcher.dispatchAction(Dispatcher.java:239)
at org.apache.jena.fuseki.server.Dispatcher.process(Dispatcher.java:229)
at org.apache.jena.fuseki.server.Dispatcher.dispatch(Dispatcher.java:147)
at org.apache.jena.fuseki.servlets.FusekiFilter.doFilter(FusekiFilter.java:49)
at org.eclipse.jetty.ee10.servlet.FilterHolder.doFilter(FilterHolder.java:205)
at org.eclipse.jetty.ee10.servlet.ServletHandler$Chain.doFilter(ServletHandler.java:1594)
at org.apache.shiro.web.servlet.ProxiedFilterChain.doFilter(ProxiedFilterChain.java:65)
at org.apache.shiro.web.servlet.AdviceFilter.executeChain(AdviceFilter.java:109)
at org.apache.shiro.web.servlet.AdviceFilter.doFilterInternal(AdviceFilter.java:138)
at org.apache.shiro.web.servlet.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:156)
at org.apache.shiro.web.servlet.ProxiedFilterChain.doFilter(ProxiedFilterChain.java:70)
at org.apache.shiro.web.servlet.AdviceFilter.executeChain(AdviceFilter.java:109)
at org.apache.shiro.web.servlet.AdviceFilter.doFilterInternal(AdviceFilter.java:138)
at org.apache.shiro.web.servlet.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:156)
at org.apache.shiro.web.servlet.ProxiedFilterChain.doFilter(ProxiedFilterChain.java:70)
at org.apache.shiro.web.servlet.AdviceFilter.executeChain(AdviceFilter.java:109)
at org.apache.shiro.web.servlet.AdviceFilter.doFilterInternal(AdviceFilter.java:138)
at org.apache.shiro.web.servlet.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:156)
at org.apache.shiro.web.servlet.ProxiedFilterChain.doFilter(ProxiedFilterChain.java:70)
at org.apache.shiro.web.servlet.AbstractShiroFilter.executeChain(AbstractShiroFilter.java:463)
at org.apache.shiro.web.servlet.AbstractShiroFilter.lambda$doFilterInternal$0(AbstractShiroFilter.java:378)
at org.apache.shiro.subject.support.SubjectCallable.doCall(SubjectCallable.java:91)
at org.apache.shiro.subject.support.SubjectCallable.call(SubjectCallable.java:84)
at org.apache.shiro.subject.support.DelegatingSubject.execute(DelegatingSubject.java:389)
at org.apache.shiro.web.servlet.AbstractShiroFilter.doFilterInternal(AbstractShiroFilter.java:376)
at org.apache.shiro.web.servlet.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:156)
at org.eclipse.jetty.ee10.servlet.FilterHolder.doFilter(FilterHolder.java:205)
at org.eclipse.jetty.ee10.servlet.ServletHandler$Chain.doFilter(ServletHandler.java:1594)
at org.apache.jena.fuseki.servlets.CrossOriginFilter.handle(CrossOriginFilter.java:351)
at org.apache.jena.fuseki.servlets.CrossOriginFilter.doFilter(CrossOriginFilter.java:304)
at org.eclipse.jetty.ee10.servlet.FilterHolder.doFilter(FilterHolder.java:205)
1758506401288 2025-09-22T02:00:01.288Z [Task 1] starts : Compact
1758506401270 2025-09-22T02:00:01.270Z Task : 1 : Compact
1758420000748 2025-09-21T02:00:00.748Z [Task 4] starts : Compact
1758420000747 2025-09-21T02:00:00.747Z Task : 4 : Compact
1758376864088 2025-09-20T14:01:04.088Z Sat Sep 20 16:01:04 CEST 2025: Timed out while compacting dsp-repo
1758333600759 2025-09-20T02:00:00.759Z [Task 3] starts : Compact
1758333600759 2025-09-20T02:00:00.759Z Task : 3 : Compact
1758290464794 2025-09-19T14:01:04.794Z Fri Sep 19 16:01:04 CEST 2025: Timed out while compacting dsp-repo
1758247200797 2025-09-19T02:00:00.797Z [Task 2] starts : Compact
1758247200795 2025-09-19T02:00:00.795Z Task : 2 : Compact
1758204067516 2025-09-18T14:01:07.516Z Thu Sep 18 16:01:07 CEST 2025: Timed out while compacting dsp-repo
1758160800766 2025-09-18T02:00:00.766Z [Task 1] starts : Compact
1758160800764 2025-09-18T02:00:00.764Z Task : 1 : Compact
1758074401461 2025-09-17T02:00:01.461Z Wed Sep 17 04:00:00 CEST 2025: Failed compacting dsp-repo
1758074400602 2025-09-17T02:00:00.602Z Task : 7 : Compact
1757988000659 2025-09-16T02:00:00.659Z Tue Sep 16 04:00:00 CEST 2025: Failed compacting dsp-repo
1757988000225 2025-09-16T02:00:00.225Z Task : 6 : Compact
1757901601772 2025-09-15T02:00:01.772Z Mon Sep 15 04:00:00 CEST 2025: Failed compacting dsp-repo
1757901600862 2025-09-15T02:00:00.862Z Task : 5 : Compact
1757858464212 2025-09-14T14:01:04.212Z Sun Sep 14 16:01:03 CEST 2025: Timed out while compacting dsp-repo
1757815200873 2025-09-14T02:00:00.873Z [Task 4] starts : Compact
1757815200873 2025-09-14T02:00:00.873Z Task : 4 : Compact
1757772065114 2025-09-13T14:01:05.114Z Sat Sep 13 16:01:04 CEST 2025: Timed out while compacting dsp-repo
1757728800901 2025-09-13T02:00:00.901Z [Task 3] starts : Compact
1757728800901 2025-09-13T02:00:00.901Z Task : 3 : Compact
1757685665830 2025-09-12T14:01:05.830Z Fri Sep 12 16:01:05 CEST 2025: Timed out while compacting dsp-repo
1757642400981 2025-09-12T02:00:00.981Z [Task 2] starts : Compact
1757642400980 2025-09-12T02:00:00.980Z Task : 2 : Compact
1757599268073 2025-09-11T14:01:08.073Z Thu Sep 11 16:01:07 CEST 2025: Timed out while compacting dsp-repo
1757562474780 2025-09-11T03:47:54.780Z URI is too large >524288
1757556000903 2025-09-11T02:00:00.903Z [Task 1] starts : Compact
1757556000902 2025-09-11T02:00:00.902Z Task : 1 : Compact
1757472607036 2025-09-10T02:50:07.036Z Wed Sep 10 04:50:06 CEST 2025: Successfully compacted dsp-repo
1757472606136 2025-09-10T02:50:06.136Z [Task 2] finishes : Compact
1757469600816 2025-09-10T02:00:00.816Z [Task 2] starts : Compact
1757469600815 2025-09-10T02:00:00.815Z Task : 2 : Compact
1757385976167 2025-09-09T02:46:16.167Z Tue Sep 9 04:46:15 CEST 2025: Successfully compacted dsp-repo
1757385968573 2025-09-09T02:46:08.573Z [Task 1] finishes : Compact
1757383200877 2025-09-09T02:00:00.877Z [Task 1] starts : Compact
1757383200874 2025-09-09T02:00:00.874Z Task : 1 : Compact
1757340061352 2025-09-08T14:01:01.352Z Mon Sep 8 16:01:00 CEST 2025: Failed compacting dsp-repo
1757296800741 2025-09-08T02:00:00.741Z [Task 3] starts : Compact
1757296800740 2025-09-08T02:00:00.740Z Task : 3 : Compact
1757213185175 2025-09-07T02:46:25.175Z Sun Sep 7 04:46:25 CEST 2025: Successfully compacted dsp-repo
1757213181882 2025-09-07T02:46:21.882Z [Task 2] finishes : Compact
1757210400356 2025-09-07T02:00:00.356Z [Task 2] starts : Compact
1757210400353 2025-09-07T02:00:00.353Z Task : 2 : Compact
1757126736064 2025-09-06T02:45:36.064Z Sat Sep 6 04:45:35 CEST 2025: Successfully compacted dsp-repo
1757126730223 2025-09-06T02:45:30.223Z [Task 1] finishes : Compact
1757124000931 2025-09-06T02:00:00.931Z [Task 1] starts : Compact
1757124000927 2025-09-06T02:00:00.927Z Task : 1 : Compact
1757080867562 2025-09-05T14:01:07.562Z Fri Sep 5 16:01:07 CEST 2025: Timed out while compacting dsp-repo
1757037600896 2025-09-05T02:00:00.896Z [Task 2] starts : Compact
1757037600895 2025-09-05T02:00:00.895Z Task : 2 : Compact
1756994466239 2025-09-04T14:01:06.239Z Thu Sep 4 16:01:05 CEST 2025: Timed out while compacting dsp-repo
1756951200962 2025-09-04T02:00:00.962Z [Task 1] starts : Compact
1756951200960 2025-09-04T02:00:00.960Z Task : 1 : Compact
1756867636065 2025-09-03T02:47:16.065Z Wed Sep 3 04:47:15 CEST 2025: Successfully compacted dsp-repo
1756867633300 2025-09-03T02:47:13.300Z [Task 3] finishes : Compact
1756864800839 2025-09-03T02:00:00.839Z [Task 3] starts : Compact
1756864800836 2025-09-03T02:00:00.836Z Task : 3 : Compact
1756781235902 2025-09-02T02:47:15.902Z Tue Sep 2 04:47:15 CEST 2025: Successfully compacted dsp-repo
1756781229618 2025-09-02T02:47:09.618Z [Task 2] finishes : Compact
1756778400445 2025-09-02T02:00:00.445Z [Task 2] starts : Compact
1756778400442 2025-09-02T02:00:00.442Z Task : 2 : Compact
I found one other single exception on another server on another night related to compaction which I haven't seen anywhere else, but the compaction that time DID "successfully fail" (i.e. task reported as failed), so it may or may not be related to the "getting stuck" problem:
[12540] **** Exception in compact
java.lang.InternalError: a fault occurred in an unsafe memory access operation
at org.apache.jena.dboe.base.buffer.BufferBase.copy(BufferBase.java:84)
at org.apache.jena.dboe.trans.bplustree.BPTreeRecords.split(BPTreeRecords.java:211)
at org.apache.jena.dboe.trans.bplustree.BPTreeNode.split(BPTreeNode.java:565)
at org.apache.jena.dboe.trans.bplustree.BPTreeNode.internalInsert(BPTreeNode.java:506)
at org.apache.jena.dboe.trans.bplustree.BPTreeNode.internalInsert(BPTreeNode.java:519)
at org.apache.jena.dboe.trans.bplustree.BPTreeNode.internalInsert(BPTreeNode.java:519)
at org.apache.jena.dboe.trans.bplustree.BPTreeNode.insert(BPTreeNode.java:203)
at org.apache.jena.dboe.trans.bplustree.BPlusTree.insertAndReturnOld(BPlusTree.java:274)
at org.apache.jena.dboe.trans.bplustree.BPlusTree.insert(BPlusTree.java:266)
at org.apache.jena.tdb2.store.tupletable.TupleIndexRecord.performAdd(TupleIndexRecord.java:92)
at org.apache.jena.tdb2.store.tupletable.TupleIndexBase.add(TupleIndexBase.java:66)
at org.apache.jena.tdb2.store.tupletable.TupleTable.add(TupleTable.java:95)
at org.apache.jena.tdb2.store.nodetupletable.NodeTupleTableConcrete.addRow(NodeTupleTableConcrete.java:79)
at org.apache.jena.tdb2.store.QuadTable.add(QuadTable.java:57)
at org.apache.jena.tdb2.store.StorageTDB.add(StorageTDB.java:82)
at org.apache.jena.dboe.storage.StorageRDF.add(StorageRDF.java:69)
at org.apache.jena.dboe.storage.system.DatasetGraphStorage.add(DatasetGraphStorage.java:165)
at org.apache.jena.atlas.iterator.Iter$IterMap.lambda$forEachRemaining$0(Iter.java:448)
at java.base/java.util.Iterator.forEachRemaining(Unknown Source)
at org.apache.jena.atlas.iterator.Iter$IterMap.forEachRemaining(Iter.java:448)
at org.apache.jena.atlas.iterator.IteratorWrapper.forEachRemaining(IteratorWrapper.java:52)
at org.apache.jena.tdb2.sys.CopyDSG.lambda$copy$0(CopyDSG.java:38)
at org.apache.jena.system.Txn.exec(Txn.java:79)
at org.apache.jena.system.Txn.executeWrite(Txn.java:127)
at org.apache.jena.tdb2.sys.CopyDSG.lambda$copy$1(CopyDSG.java:36)
at org.apache.jena.system.Txn.exec(Txn.java:79)
at org.apache.jena.system.Txn.executeRead(Txn.java:117)
at org.apache.jena.tdb2.sys.CopyDSG.copy(CopyDSG.java:35)
at org.apache.jena.tdb2.sys.DatabaseOps.lambda$compaction$3(DatabaseOps.java:432)
at org.apache.jena.dboe.transaction.txn.TransactionalSystemControl.execReadOnlyDatabase(TransactionalSystemControl.java:45)
at org.apache.jena.tdb2.sys.DatabaseOps.compaction(DatabaseOps.java:420)
at org.apache.jena.tdb2.sys.DatabaseOps.compact(DatabaseOps.java:359)
at org.apache.jena.tdb2.DatabaseMgr.compact(DatabaseMgr.java:92)
at org.apache.jena.fuseki.ctl.ActionCompact$CompactTask.run(ActionCompact.java:110)
at org.apache.jena.fuseki.async.AsyncPool.lambda$submit$0(AsyncPool.java:66)
at org.apache.jena.fuseki.async.AsyncTask.call(AsyncTask.java:100)
at java.base/java.util.concurrent.FutureTask.run(Unknown Source)
at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source)
at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)
at java.base/java.lang.Thread.run(Unknown Source)
Are you interested in making a pull request?
None
Hi @SamuelBoerlin
There seem to be several potentially different things going on here.
Exception in insertPrefixes: Not in a transaction org.apache.jena.dboe.transaction.txn.TransactionException: Not in a transaction at org.apache.jena.dboe.transaction.txn.TransactionalComponentLifecycle.checkTxn(TransactionalComponentLifecycle.java:350) at org.apache.jena.dboe.trans.bplustree.BPlusTree.getRootRead(BPlusTree.java:156) . . .
Do you happen to know what the CONSTRUCT query is? Have other CONSTRUCT queries succeeded? I think this is different problem but made likely to happen around the time of compaction finishing. It may (I'm still investigating) leave the system in a broken state but something triggered it in the first place.
[12540] **** Exception in compact java.lang.InternalError: a fault occurred in an unsafe memory access operation at org.apache.jena.dboe.base.buffer.BufferBase.copy(BufferBase.java:84) at org.apache.jena.dboe.trans.bplustree.BPTreeRecords.split(BPTreeRecords.java:211) . . .
It's inside the JVM to get a java.lang.InternalError - it is accessing a memory mapped file.
Would it be possible to run without --add-modules=jdk.incubator.vector and with a 2G heap -Xmx2G?
Do you happen to know what the CONSTRUCT query is? Have other CONSTRUCT queries succeeded? I think this is different problem but made likely to happen around the time of compaction finishing. It may (I'm still investigating) leave the system in a broken state but something triggered it in the first place.
Unfortunately not. But queries in general work fine and don't seem to be affected by the compaction getting stuck. The DB has been in this state for days several times now and we haven't observed any problems other than more and more disk space getting used up and memory usage not going down (usually it drops quite a lot after a successful compaction).
It's inside the JVM to get a
java.lang.InternalError- it is accessing a memory mapped file. Would it be possible to run without--add-modules=jdk.incubator.vectorand with a 2G heap-Xmx2G?
Ah sorry, I had copied the wrong line. We are already running with -Xmx2G:
/opt/java/openjdk/bin/java -Xmx2G -Dlog4j2.formatMsgNoLookups=true --enable-native-access=ALL-UNNAMED --add-modules=jdk.incubator.vector -Dlog4j.configurationFile=/jena-fuseki/log4j2.properties -cp /jena-fuseki/fuseki-server.jar org.apache.jena.fuseki.main.cmds.FusekiServerCmd
The --add-modules=jdk.incubator.vector was only added when we upgraded from 5.2.0 to 5.5.0.
This problem was also happening already before that (though less frequently) on 5.2.0 and without --add-modules=jdk.incubator.vector, so I don't think it is the root cause.
I'll give it a try, but it'll take a while.
Some additional points that are interesting (both from when we still used 5.2.0, haven't tried yet with 5.5.0):
- I tried reproducing the problem by running the compaction script in a loop for quite a while on a less busy server with the same data and was unable to reproduce it this way. So it seems that it might only be triggered when other stuff is happening at the same time as compaction.
- Starting a backup via
GET http://db:3030/dsp-repowithAccept: application/trigca. half an hour after starting the compaction and before it has finished, led to compaction getting stuck and the .trig file being truncated at some random point and being smaller than expected (and yet no error was detected bycurl --fail ...). This led us to change the schedules such that backups and compaction don't overlap, which seems to have solved the occasional corrupted/truncated backups, but didn't solve the compaction getting stuck.
The
--add-modules=jdk.incubator.vectorwas only added when we upgraded from 5.2.0 to 5.5.0. This problem was also happening already before that (though less frequently) on 5.2.0 and without--add-modules=jdk.incubator.vector, so I don't think it is the root cause.
Agreed - it's not the cause of compaction getting stuck. This is just trying to simplify the problem space.
Is the java.lang.InternalError new at 5.5.0 or was it occurring for 5.2.0?
java.lang.InternalError is coming from inside the JVM. Either some external process is affecting the memory mapped files, or an unrelated error JVM-internal has occurred and this is a symptom later. jdk.incubator.vector support in Lucene is quite new and I believe experimental - it also depends on the underlying hardware capabilities.
Lucene itself is capable of using memory mapped files.
INFO: Using MemorySegmentIndexInput and native madvise support with Java 21 or later; to disable start with -Dorg.apache.lucene.store.MMapDirectory.enableMemorySegments=false
Jena is shipping with Lucene9 because Lucene10 requires Java21; Jena supports Java17 until the upcoming Jena 6.0.0.
tl;dr: Lucene is complicated!
Is the java.lang.InternalError new at 5.5.0 or was it occurring for 5.2.0? java.lang.InternalError is coming from inside the JVM. Either some external process is affecting the memory mapped files, or an unrelated error JVM-internal has occurred and this is a symptom later. jdk.incubator.vector support in Lucene is quite new and I believe experimental - it also depends on the underlying hardware capabilities.
That error was with 5.5.0. That's the only instance I ever saw that error, so perhaps it was indeed some external problem.