You are viewing a plain text version of this content. The canonical link for it is here.
Posted to users@jena.apache.org by "Rouquette, Nicolas F (US 319K)" <ni...@jpl.nasa.gov.INVALID> on 2022/01/05 20:32:12 UTC
Help troubleshooting problems loading a large dataset
Unfortunately, I cannot share the data that causes problems when we upload data via s-put to a Fuseki 4.3.2 server.
I start the server like this (on windows):
java -Xmx12G -D'log4j.configuration'=file:log4j2.properties -jar fuseki-server.jar
(I edited the log4j2.properties file to set the levels to DEBUG or TRACE to see if I could get more info)
We create a dataset with the union graph by expanding this Bash template:
createDataset() {
cat <<EOF
@prefix fu: <http://jena.apache.org/fuseki#> .
@prefix fuseki: <http://jena.apache.org/fuseki#> .
@prefix rdf: <http://www.w3.org/1999/02/22-rdf-syntax-ns#> .
@prefix rdfs: <http://www.w3.org/2000/01/rdf-schema#> .
@prefix tdb: <http://jena.hpl.hp.com/2008/tdb#> .
@prefix ja: <http://jena.hpl.hp.com/2005/11/Assembler#> .
<#${FUSEKI_DATASET}-service> rdf:type fuseki:Service;
fu:name "${FUSEKI_DATASET}";
fu:dataset <#${FUSEKI_DATASET}> ;
fu:serviceQuery "sparql" ;
fu:serviceQuery "query" ;
fu:serviceUpdate "update" ;
fu:serviceUpload "upload" ;
fu:serviceReadWriteGraphStore "data" ;
fu:serviceReadGraphStore "get" ;
.
<#${FUSEKI_DATASET}> rdf:type tdb:DatasetTDB ;
tdb:location "--mem--" ;
tdb:unionDefaultGraph true;
.
EOF
}
We upload a bunch of files in rdf/xml and 3 in ttl format for the entailments calculated by an owl2-dl/swrl reasoner for classes, properties and individuals.
The error happens systematically at the last file for individual entailments. This file is fairly big – about 600 KB and has about 1.8 M lines of ttl statements/spaces.
Once, I got a server error like this:
18:00:40 INFO Fuseki :: [45] PUT http://localhost:3030/00afdacb677fce276d5463bc8f09aa909a8e9755/data?graph=http%3A%2F%2Feuropa.jpl.nasa.gov%2Fbundle%2F___I%2Fexported-user-models
18:00:40 INFO Fuseki :: [45] => User-Agent: SOH/Fuseki 1.0.0
18:00:40 INFO Fuseki :: [45] => Host: localhost:3030
18:00:40 INFO Fuseki :: [45] => Content-Length: 588975765
18:00:40 INFO Fuseki :: [45] => Content-Type: text/turtle;charset=utf-8;charset=utf-8
19:10:59 INFO Fuseki :: [44] <= Content-Type: application/json
19:10:59 INFO Fuseki :: [44] <= Content-Length: 73
19:10:59 INFO Fuseki :: [44] 201 Created (4,595.635 s)
19:11:15 INFO Fuseki :: [45] <= Content-Type: text/plain
19:11:15 INFO Fuseki :: [45] <= Content-Length: 97
19:11:15 INFO Fuseki :: [45] <= Cache-Control: must-revalidate,no-cache,no-store
19:11:15 INFO Fuseki :: [45] <= Pragma: no-cache
19:11:15 INFO Fuseki :: [45] 500 Server Error (4,234.691 s)
Is there a way to make sure that any such 500 error is logged with additional information about it cause?
Could there be an unlogged internal exception?
If so, how can we force all internal exceptions to be logged no matter what?
I tried to turn on debugging to see what is happening by changing most INFO to DEBUG levels and adding the –debug flag.
Below is the partial log of loading the large entailments: C = class, P = property, I = individuals.
There are lots of JournalControl log messages that I have elided.
12:08:46 INFO Fuseki :: [61] PUT http://localhost:3030/00afdacb677fce276d5463bc8f09aa909a8e9755/data?graph=http%3A%2F%2Feuropa.jpl.nasa.gov%2Fbundle%2F_C__%2Fexported-user-models
12:08:46 INFO Fuseki :: [61] => User-Agent: SOH/Fuseki 1.0.0
12:08:46 INFO Fuseki :: [61] => Host: localhost:3030
12:08:46 INFO Fuseki :: [61] => Content-Length: 3514749
12:08:46 INFO Fuseki :: [61] => Content-Type: text/turtle;charset=utf-8;charset=utf-8
12:08:46 DEBUG TDB :: Txn[45]/W: begin$
12:08:46 DEBUG LockMRSW :: Lock : qtp665565246-28
12:08:46 DEBUG TDB :: Txn[45]/W: begin
12:08:46 DEBUG LockMRSW :: qtp665565246-28 >> enterCS: Thread R/W: 0/0 :: Model R/W: 0/0 (thread: qtp665565246-28)
12:08:46 DEBUG LockMRSW :: qtp665565246-28 << enterCS: Thread R/W: 1/0 :: Model R/W: 1/0 (thread: qtp665565246-28)
12:08:46 DEBUG Fuseki :: PUT->target:<http://europa.jpl.nasa.gov/bundle/_C__/exported-user-models>
12:08:46 INFO Fuseki :: [61] Body: Content-Length=3514749, Content-Type=text/turtle, Charset=utf-8;charset=utf-8 => Turtle : Count=35378 Triples=35378 Quads=0
12:08:46 DEBUG TDB :: Txn[45]/W: commit
12:08:46 DEBUG LockMRSW :: qtp665565246-28 >> leaveCS: Thread R/W: 1/0 :: Model R/W: 1/0 (thread: qtp665565246-28)
12:08:46 DEBUG LockMRSW :: qtp665565246-28 << leaveCS: Thread R/W: 0/0 :: Model R/W: 0/0 (thread: qtp665565246-28)
12:08:46 DEBUG TDB :: Txn[45]/W: Commit immediately
12:08:46 DEBUG TDB :: Replay Txn[45]/W
12:08:46 DEBUG JournalControl :: Replay: fileref(35):node2id.dat Block: 769 (posn=0, limit=8192, cap=8192)
…
12:08:46 DEBUG JournalControl :: Replay: fileref(28):SPOG.dat Block: 5119 (posn=0, limit=8192, cap=8192)
12:08:46 DEBUG JournalControl :: Replay: fileref(37):prefixIdx.dat Block: 0 (posn=0, limit=8192, cap=8192)
12:08:46 INFO Fuseki :: [61] <= Content-Type: application/json
12:08:46 INFO Fuseki :: [61] <= Content-Length: 69
12:08:46 INFO Fuseki :: [61] 201 Created (566 ms)
127.0.0.1 - - [05/Jan/2022:20:08:46 +0000] "PUT /00afdacb677fce276d5463bc8f09aa909a8e9755/data" 201 69 "" "SOH/Fuseki 1.0.0"
12:08:47 INFO Fuseki :: [62] PUT http://localhost:3030/00afdacb677fce276d5463bc8f09aa909a8e9755/data?graph=http%3A%2F%2Feuropa.jpl.nasa.gov%2Fbundle%2F__P_%2Fexported-user-models
12:08:47 INFO Fuseki :: [62] => User-Agent: SOH/Fuseki 1.0.0
12:08:47 INFO Fuseki :: [62] => Host: localhost:3030
12:08:47 INFO Fuseki :: [62] => Content-Length: 607158
12:08:47 INFO Fuseki :: [62] => Content-Type: text/turtle;charset=utf-8;charset=utf-8
12:08:47 DEBUG TDB :: Txn[46]/W: begin$
12:08:47 DEBUG LockMRSW :: Lock : qtp665565246-47
12:08:47 DEBUG TDB :: Txn[46]/W: begin
12:08:47 DEBUG LockMRSW :: qtp665565246-47 >> enterCS: Thread R/W: 0/0 :: Model R/W: 0/0 (thread: qtp665565246-47)
12:08:47 DEBUG LockMRSW :: qtp665565246-47 << enterCS: Thread R/W: 1/0 :: Model R/W: 1/0 (thread: qtp665565246-47)
12:08:47 DEBUG Fuseki :: PUT->target:<http://europa.jpl.nasa.gov/bundle/__P_/exported-user-models>
12:08:47 INFO Fuseki :: [62] Body: Content-Length=607158, Content-Type=text/turtle, Charset=utf-8;charset=utf-8 => Turtle : Count=5012 Triples=5012 Quads=0
12:08:47 DEBUG TDB :: Txn[46]/W: commit
12:08:47 DEBUG LockMRSW :: qtp665565246-47 >> leaveCS: Thread R/W: 1/0 :: Model R/W: 1/0 (thread: qtp665565246-47)
12:08:47 DEBUG LockMRSW :: qtp665565246-47 << leaveCS: Thread R/W: 0/0 :: Model R/W: 0/0 (thread: qtp665565246-47)
12:08:47 DEBUG TDB :: Txn[46]/W: Commit immediately
12:08:47 DEBUG TDB :: Replay Txn[46]/W
12:08:47 DEBUG JournalControl :: Replay: fileref(35):node2id.dat Block: 80 (posn=0, limit=8192, cap=8192)
…
12:08:47 DEBUG JournalControl :: Replay: fileref(28):SPOG.dat Block: 5119 (posn=0, limit=8192, cap=8192)
12:08:47 DEBUG JournalControl :: Replay: fileref(37):prefixIdx.dat Block: 0 (posn=0, limit=8192, cap=8192)
12:08:47 INFO Fuseki :: [62] <= Content-Type: application/json
12:08:47 INFO Fuseki :: [62] <= Content-Length: 67
12:08:47 INFO Fuseki :: [62] 201 Created (164 ms)
127.0.0.1 - - [05/Jan/2022:20:08:47 +0000] "PUT /00afdacb677fce276d5463bc8f09aa909a8e9755/data" 201 67 "" "SOH/Fuseki 1.0.0"
12:08:47 INFO Fuseki :: [63] PUT http://localhost:3030/00afdacb677fce276d5463bc8f09aa909a8e9755/data?graph=http%3A%2F%2Feuropa.jpl.nasa.gov%2Fbundle%2F___I%2Fexported-user-models
12:08:47 INFO Fuseki :: [63] => User-Agent: SOH/Fuseki 1.0.0
12:08:47 INFO Fuseki :: [63] => Host: localhost:3030
12:08:47 INFO Fuseki :: [63] => Content-Length: 588975765
12:08:47 INFO Fuseki :: [63] => Content-Type: text/turtle;charset=utf-8;charset=utf-8
12:08:47 DEBUG TDB :: Txn[47]/W: begin$
12:08:47 DEBUG LockMRSW :: Lock : qtp665565246-39
12:08:47 DEBUG TDB :: Txn[47]/W: begin
12:08:47 DEBUG LockMRSW :: qtp665565246-39 >> enterCS: Thread R/W: 0/0 :: Model R/W: 0/0 (thread: qtp665565246-39)
12:08:47 DEBUG LockMRSW :: qtp665565246-39 << enterCS: Thread R/W: 1/0 :: Model R/W: 1/0 (thread: qtp665565246-39)
12:08:47 DEBUG Fuseki :: PUT->target:<http://europa.jpl.nasa.gov/bundle/___I/exported-user-models>
12:09:22 INFO Fuseki :: [63] Body: Content-Length=588975765, Content-Type=text/turtle, Charset=utf-8;charset=utf-8 => Turtle : Count=2050519 Triples=2050519 Quads=0
12:14:52 INFO Fuseki :: [64] PUT http://localhost:3030/00afdacb677fce276d5463bc8f09aa909a8e9755/data?graph=http%3A%2F%2Feuropa.jpl.nasa.gov%2Fbundle%2F___I%2Fexported-user-models
12:14:52 INFO Fuseki :: [64] => User-Agent: SOH/Fuseki 1.0.0
12:14:52 INFO Fuseki :: [64] => Host: localhost:3030
12:14:52 INFO Fuseki :: [64] => Content-Length: 588975765
12:14:52 INFO Fuseki :: [64] => Content-Type: text/turtle;charset=utf-8;charset=utf-8
On the client side where we use s-put, I got this info:
#----------------------------------
# IRI=http://europa.jpl.nasa.gov/bundle/_C__/exported-user-models
# /data/outputs/process/auxiliary/owl/europa.jpl.nasa.gov/bundle/_C__/exported-user-models.ttl
# /data/inputs/auxiliary/owl/europa.jpl.nasa.gov/bundle/_C__/exported-user-models.ttl
# Uploading http://europa.jpl.nasa.gov/bundle/_C__/exported-user-models from /data/inputs/auxiliary/owl/europa.jpl.nasa.gov/bundle/_C__/exported-user-models.ttl
#----------------------------------
# IRI=http://europa.jpl.nasa.gov/bundle/__P_/exported-user-models
# /data/outputs/process/auxiliary/owl/europa.jpl.nasa.gov/bundle/__P_/exported-user-models.ttl
# /data/inputs/auxiliary/owl/europa.jpl.nasa.gov/bundle/__P_/exported-user-models.ttl
# Uploading http://europa.jpl.nasa.gov/bundle/__P_/exported-user-models from /data/inputs/auxiliary/owl/europa.jpl.nasa.gov/bundle/__P_/exported-user-models.ttl
#----------------------------------
# IRI=http://europa.jpl.nasa.gov/bundle/___I/exported-user-models
# /data/outputs/process/auxiliary/owl/europa.jpl.nasa.gov/bundle/___I/exported-user-models.ttl
# /data/inputs/auxiliary/owl/europa.jpl.nasa.gov/bundle/___I/exported-user-models.ttl
# Uploading http://europa.jpl.nasa.gov/bundle/___I/exported-user-models from /data/inputs/auxiliary/owl/europa.jpl.nasa.gov/bundle/___I/exported-user-models.ttl
Failed to connect: localhost:3030: end of file reached
That is, the server did not crash but it was busy for a few minutes, then strangely it logged the PUT a second time. Then a few minutes later, the client stopped with ‘Failed to connect…’
Is there a way to get additional log visibility into what is happening during these minutes?
Nicolas F. Rouquette
Principal Computer Scientist
Jet Propulsion Laboratory, California Institute of Technology M/S 301-490, 4800 Oak Grove Dr, Pasadena, CA 91189, USA
email: nicolas.f.rouquette@jpl.nasa.gov<ma...@jpl.nasa.gov>
cell: +1 (626) 639-5282
Re: Help troubleshooting problems loading a large dataset
Posted by Andy Seaborne <an...@apache.org>.
Hi Nicolas
On 05/01/2022 20:32, Rouquette, Nicolas F (US 319K) wrote:
> Once, I got a server error like this:
>
> 18:00:40 INFO Fuseki :: [45] PUThttp://localhost:3030/00afdacb677fce276d5463bc8f09aa909a8e9755/data?graph=http%3A%2F%2Feuropa.jpl.nasa.gov%2Fbundle%2F___I%2Fexported-user-models
> 18:00:40 INFO Fuseki :: [45] => User-Agent: SOH/Fuseki 1.0.0
> 18:00:40 INFO Fuseki :: [45] => Host: localhost:3030
> 18:00:40 INFO Fuseki :: [45] => Content-Length: 588975765
> 18:00:40 INFO Fuseki :: [45] => Content-Type: text/turtle;charset=utf-8;charset=utf-8
> 19:10:59 INFO Fuseki :: [44] <= Content-Type: application/json
> 19:10:59 INFO Fuseki :: [44] <= Content-Length: 73
> 19:10:59 INFO Fuseki :: [44] 201 Created (4,595.635 s)
> 19:11:15 INFO Fuseki :: [45] <= Content-Type: text/plain
> 19:11:15 INFO Fuseki :: [45] <= Content-Length: 97
> 19:11:15 INFO Fuseki :: [45] <= Cache-Control: must-revalidate,no-cache,no-store
> 19:11:15 INFO Fuseki :: [45] <= Pragma: no-cache
> 19:11:15 INFO Fuseki :: [45] 500 Server Error (4,234.691 s)
Could we see the log from, say request [40] and a few after the 500 to
understand the overlap? And after "Server Error" there is normally a
stacktrace.
Do you need to use TDB in memory?
TDB2 is better for large transactions (you have a 0.5G file) and even
in-memory it should have less overhead.
Have you tried with TDB2 backed by disk?
Andy