You are viewing a plain text version of this content. The canonical link for it is here.
Posted to users@jena.apache.org by Mark Feblowitz <Ma...@comcast.net> on 2014/05/30 15:36:31 UTC
Jena/Fuseki/TDB Java heap space and OutOfMemory errors
I have a setup where there can be many, rapid-fire updates sent to Jena TDB via UPDATE posts to Fuseki.
After some amount of time I see a series of messages after update posts
WARN [xxxxxx] RC = 500 : Java heap space
And I’m seeing "java.lang.OutOfMemoryError: Java heap space” errors.
I’ve bumped heap space to 3072M, on a machine that has 32 GB of memory.
Can this be dealt with, simply by doubling heap space? Or is there something about how I’m posting that could be leading to the problem.
What I’m doing is creating an OntModel in the client, which then posts that model as an update to Fuseki. Fuseki is configured with TDB and OWLFBRuleReasoner.
As I mentioned in my prior posts on retries, there are flurries of posts to Fuseki, and roughly concurrent queries - often on things that are in the process of being posted. All of the posts come from a single client, while the queries come from multiple queries initiated from separately run queries (from separate JVMs).
Here’s a snippet of the console log after a series of other interactions and errors. I’ll have to save out the entire log (but it will be huge) to identify the circumstances of the first errors.
00:55:33 INFO [79927] 500 Java heap space (5.393 s)
00:55:39 INFO [79929] POST http://localhost:3030/km4sp/update
00:55:43 WARN [79929] RC = 500 : Java heap space
java.lang.OutOfMemoryError: Java heap space
at org.apache.jena.atlas.io.CharStreamBuffered.<init>(CharStreamBuffered
.java:53)
at org.apache.jena.atlas.io.PeekReader.make(PeekReader.java:81)
at org.apache.jena.atlas.io.PeekReader.make(PeekReader.java:75)
at org.apache.jena.atlas.io.PeekReader.makeUTF8(PeekReader.java:92)
at com.hp.hpl.jena.sparql.lang.UpdateParser.parse(UpdateParser.java:51)
at com.hp.hpl.jena.update.UpdateFactory.make(UpdateFactory.java:278)
at com.hp.hpl.jena.update.UpdateFactory.read(UpdateFactory.java:267)
at org.apache.jena.fuseki.servlets.SPARQL_Update.execute(SPARQL_Update.j
ava:228)
at org.apache.jena.fuseki.servlets.SPARQL_Update.executeBody(SPARQL_Upda
te.java:194)
at org.apache.jena.fuseki.servlets.SPARQL_Update.perform(SPARQL_Update.j
ava:106)
at org.apache.jena.fuseki.servlets.SPARQL_ServletBase.executeLifecycle(S
PARQL_ServletBase.java:171)
at org.apache.jena.fuseki.servlets.SPARQL_ServletBase.executeAction(SPAR
QL_ServletBase.java:152)
at org.apache.jena.fuseki.servlets.SPARQL_ServletBase.execCommonWorker(S
PARQL_ServletBase.java:140)
at org.apache.jena.fuseki.servlets.SPARQL_ServletBase.doCommon(SPARQL_Se
rvletBase.java:69)
at org.apache.jena.fuseki.servlets.SPARQL_Update.doPost(SPARQL_Update.ja
va:81)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:755)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:848)
at org.eclipse.jetty.servlet.ServletHolder.handle(ServletHolder.java:684
)
at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java
:457)
at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandl
er.java:229)
at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandl
er.java:1075)
at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:
384)
at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandle
r.java:193)
at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandle
r.java:1009)
at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.j
ava:135)
at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper
.java:116)
at org.eclipse.jetty.server.Server.handle(Server.java:370)
at org.eclipse.jetty.server.AbstractHttpConnection.handleRequest(Abstrac
tHttpConnection.java:489)
at org.eclipse.jetty.server.BlockingHttpConnection.handleRequest(Blockin
gHttpConnection.java:53)
at org.eclipse.jetty.server.AbstractHttpConnection.content(AbstractHttpC
onnection.java:960)
at org.eclipse.jetty.server.AbstractHttpConnection$RequestHandler.conten
t(AbstractHttpConnection.java:1021)
at org.eclipse.jetty.http.HttpParser.parseNext(HttpParser.java:865)
00:55:45 INFO [79929] 500 Java heap space (5.597 s)
00:55:51 INFO [79930] POST http://localhost:3030/km4sp/update
00:56:59 INFO [79928] exec/select
Re: Jena/Fuseki/TDB Java heap space and OutOfMemory errors
Posted by Osma Suominen <os...@helsinki.fi>.
Hi Rob!
Many thanks for your quick and informative reply. Your explanation
matches my experience exactly and now I think I understand what happens.
I will try to find ways to deal with it and test whether your suggestion
works on OpenJDK.
Is there any downside (except the obvious downtime) to killing Fuseki
when it has ended up in this state? When it gets restarted, will it just
soon end up in the same situation if the continuous query load
continues? At least that happened yesterday a couple of times before it
eventually settled. Is there a way to force a journal flush, either
during startup or later on when Fuseki is running normally?
This is a backend server for a web application which is frequented by
GoogleBot and others (including local pings to test that the service is
up every 5 minutes or so) which together pretty much ensure that there
is always some activity going on. But there is an alternate backend
server running another Fuseki to which I can divert query traffic
temporarily if necessary.
-Osma
On 05/06/14 13:43, Rob Vesse wrote:
> Osma
>
> Comments inline:
>
> On 05/06/2014 10:11, "Osma Suominen" <os...@helsinki.fi> wrote:
>
>> Hi all!
>>
>> On 30/05/14 16:36, Mark Feblowitz wrote:
>>
>>> After some amount of time I see a series of messages after update posts
>>>
>>> WARN [xxxxxx] RC = 500 : Java heap space
>>>
>>> And I’m seeing "java.lang.OutOfMemoryError: Java heap space” errors.
>>
>> I also got this error yesterday on an important machine.
>>
>> My setup is this: Fuseki 1.0.1 with a single TDB (no inference) that has
>> grown to 13GB and an additional jena-text index of 200MB. Fuseki is
>> given approx. 6GB of heap (-Xmx6000M) on a machine with 16GB RAM. The
>> machine is a virtual machine running 64bit CentOS 6, kernel
>> 2.6.32-431.11.2.el6.x86_64, java -version gives this:
>> java version "1.7.0_51"
>> OpenJDK Runtime Environment (rhel-2.4.4.1.el6_5-x86_64 u51-b02)
>> OpenJDK 64-Bit Server VM (build 24.45-b08, mixed mode)
>>
>>
>> At the time this happened there were no updates (we usually only update
>> during the night), just read-only SELECT and CONSTRUCT queries coming in
>> at around 8 queries per second on average.
>
> As has been explained in this thread the problem is that the continuous
> query load prevents the in-memory transaction journal from being fully
> flushed to disk. If the read only queries continue through the night
> while you do updates then they will block the journal flush and you will
> eventually hit this case
>
> JENA-703 (https://issues.apache.org/jira/browse/JENA-703) describes the
> proposed fix for this issue but the side effect of that fix (as and when
> it gets implemented) will be that for a system under continuous load reads
> will be occasionally blocked and therefore some queries may experience
> delays.
>
>>
>> Suddenly queries stop working and CPU usage rises to around 350% (the
>> machine has 4 cores). Errors like this appear in the Fuseki log:
>>
>> 2014-06-04 11:42:52,293 WARN Fuseki :: [14739636] RC = 500
>> : Java heap space
>> java.lang.OutOfMemoryError: Java heap space
>> 2014-06-04 11:39:06,670 WARN Fuseki :: [14739587] RC = 500
>> : GC overhead limit exceeded
>> java.lang.OutOfMemoryError: GC overhead limit exceeded
>> 2014-06-04 11:43:54,817 INFO Fuseki :: [14739587] 500 GC
>> overhead limit exceeded (1,032.111 s)
>> 2014-06-04 12:24:56,868 WARN Fuseki :: [14739738] RC = 500
>> : GC overhead limit exceeded
>> java.lang.OutOfMemoryError: GC overhead limit exceeded
>> 2014-06-04 12:24:04,660 WARN Fuseki :: [14739862] RC = 500
>> : Java heap space
>> java.lang.OutOfMemoryError: Java heap space
>> 2014-06-04 12:43:44,167 INFO Fuseki :: [14739738] 500 GC
>> overhead limit exceeded (2,227.717 s)
>> 2014-06-04 12:43:44,167 INFO Fuseki :: [14739862] 500 Java
>> heap space (2,227.719 s)
>> 2014-06-04 14:33:30,906 WARN Fuseki :: [14740021] RC = 500
>> : GC overhead limit exceeded
>> java.lang.OutOfMemoryError: GC overhead limit exceeded
>> 2014-06-04 14:34:21,722 INFO Fuseki :: [14740021] 500 GC
>> overhead limit exceeded (4,850.886 s)
>>
>>
>> The timestamps in the log entries are not always in order, as you can
>> see above. Sometimes it takes more than an hour for an individual query
>> to fail (see last entry).
>>
>> Needless to say this is a bit nasty way of failing - the process is
>> running, consuming nearly all CPU, but responding to queries very slowly
>> or not at all. It would even be better if the process just died, so
>> something else could restart it. I am considering using a tool such as
>> Monit to watch the Fuseki process and restart it if it starts behaving
>> oddly.
>
> This is really a JVM issue and not something we can control. The JVM
> allows catching OOM errors (for better or worse) but in doing so it often
> leaves applications in a state where they are extremely close to the heap
> limit and so the user code hangs while the JVM furiously tries to GC
> enough memory for it to continue.
>
>>
>> Am I doing something obviously wrong here?
>
> No, this is a known limitation of TDBs architecture
>
>
>> Should I just give the JVM
>> even more memory, or adjust some of the other JVM options?
>
> That only prolongs the time to failure and TDB relies heavily on memory
> mapped files which are off heap so increasing the heap size impacts
> performance because it cause more swapping at the OS level
>
>> Is there any
>> way to force the GC to fail faster, or otherwise avoid futile attempts
>> of freeing more memory?
>
> You can try the solution detailed at
> http://stackoverflow.com/a/3878199/107591
>
> Add -XX:OnOutOfMemoryError="kill -9 %p"
>
> That is an Oracle JVM option so no guarantee it works on OpenJDK
>
> Rob
>
>> Even better, could Fuseki just stick to the
>> memory it is given?
>>
>> Thanks,
>> Osma
>>
>> --
>> Osma Suominen
>> D.Sc. (Tech), Information Systems Specialist
>> National Library of Finland
>> P.O. Box 26 (Teollisuuskatu 23)
>> 00014 HELSINGIN YLIOPISTO
>> Tel. +358 50 3199529
>> osma.suominen@helsinki.fi
>> http://www.nationallibrary.fi
>
>
>
>
--
Osma Suominen
D.Sc. (Tech), Information Systems Specialist
National Library of Finland
P.O. Box 26 (Teollisuuskatu 23)
00014 HELSINGIN YLIOPISTO
Tel. +358 50 3199529
osma.suominen@helsinki.fi
http://www.nationallibrary.fi
Re: Jena/Fuseki/TDB Java heap space and OutOfMemory errors
Posted by Osma Suominen <os...@helsinki.fi>.
>> We also use max=3 on the httpd front end to limit the impact of parallel
>> requests. Not perfect by any means but it does no harm.
>
> Good idea, I could see if I can implement this kind of restriction in
> Varnish which is in front of Fuseki.
Thanks again Andy, this turned out to be the key.
My current understanding of the situation: With lots of parallel
requests, Fuseki simply gets overwhelmed, eats too much memory and the
JVM GC starts thrashing. By default, there is either no limit on the
number of parallel requests in Fuseki or the limits are pretty high (I
couldn't tell which). Also the queue for incoming requests has no upper
limit, so even when the situation starts clearing up there may be a long
backlog of requests to process. I also found ARQ query timeouts
ineffective, I think they only consider the query phase but not all the
waiting which affects total request time. So if a query has to wait in
some queue for a long time before processing starts, it will not time
out regardless of the timeout setting.
Limiting parallel requests in Varnish using the .max_connections
setting, as I tried first, is maybe not such a good idea, because
Varnish will fail fast when the limit is reached and return with an HTTP
error. It would be better to wait a while, in case the congestion is
just temporary.
I found out that Fuseki can use a custom Jetty configuration (using the
--jetty-config=jetty.xml parameter) where limits can be set on the
thread count and the queue size for waiting requests. I determined by
experimentation that a Jetty thread count close to the number of CPU
cores (4) in the system makes the most sense - at least for me, queries
are generally CPU bound as the TDB database usually fits in disk cache.
Anything above that will generally just increase Fuseki memory
consumption with no improvement in performance.
My jetty.xml is attached. I have set the thread count to between 4 and 6
and the size of the request queue to 100 (never reached in my tests). In
my stress tests, memory consumption (Fuseki process RSS) maxed at 6.6GB
and I have set -Xmx to 8GB, so there is still some breathing space.
-Osma
--
Osma Suominen
D.Sc. (Tech), Information Systems Specialist
National Library of Finland
P.O. Box 26 (Teollisuuskatu 23)
00014 HELSINGIN YLIOPISTO
Tel. +358 50 3199529
osma.suominen@helsinki.fi
http://www.nationallibrary.fi
Re: Jena/Fuseki/TDB Java heap space and OutOfMemory errors
Posted by Osma Suominen <os...@helsinki.fi>.
On 05/06/14 15:19, Andy Seaborne wrote:
> (the query in question may just be syp[tom and not the root cause - that
> is, it's not expensive but something else at the same time caue it to
> go wrong)
That's what I thought too.
> At a quick look:
>
> ?s text:query ('ampumavä*' 100000000)
>
> Lucene is also taking RAM, partly the Lucene engine, partly to deal with
> limit/unique results.
>
> (and if Solr then it has to completely buffer responses as well).
It is Lucene, not Solr.
> How many results are there to "?s text:query ("ampumavä*" 100000000 )"?
In fact zero, with that graph restriction (and I'm using the
graph-specific text index that I implemented). The large number is just
so that results would not be cut off by the text index for some edge
cases. So while this is a rather complex query, it should give an empty
result set fairly quickly.
>> It's too late now to check what size the journal was when this happened
>> yesterday, but I checked it for today, and all the three *jrnl files had
>> a size of zero and a timestamp of 04:57, which was the time when the
>> last updates finished. So at least last night, the flush completed very
>> soon after the update.
>
> OK - it's highly unlikely to be updates then.
Good to know.
Though looking at how Fuseki behaves when I give it data, it seems that
the journal file size goes down to zero as soon as the update query
(using LOAD) completes, but there is still quite a lot of CPU usage for
at least 10 seconds after that even without any further queries. So
something is still happening after the journal has been emptied.
> We have had to make sure bots didn't trigger expensive queries - for
> example sorts. And had bots that ignore "no follow" (and robots.txt).
Right. I'm not worried about bot traffic, they don't normally generate
any more expensive queries than normal users.
> We also use max=3 on the httpd front end to limit the impact of parallel
> requests. Not perfect by any means but it does no harm.
Good idea, I could see if I can implement this kind of restriction in
Varnish which is in front of Fuseki.
-Osma
--
Osma Suominen
D.Sc. (Tech), Information Systems Specialist
National Library of Finland
P.O. Box 26 (Teollisuuskatu 23)
00014 HELSINGIN YLIOPISTO
Tel. +358 50 3199529
osma.suominen@helsinki.fi
http://www.nationallibrary.fi
Re: Jena/Fuseki/TDB Java heap space and OutOfMemory errors
Posted by Andy Seaborne <an...@apache.org>.
On 05/06/14 12:47, Osma Suominen wrote:
> Hi Andy!
>
> On 05/06/14 14:28, Andy Seaborne wrote:
>> Osma,
>>
>> What are the long running queries?
>
> Here's one (sorry for the messed up line breaks):
(the query in question may just be syp[tom and not the root cause - that
is, it's not expensive but something else at the same time caue it to
go wrong)
At a quick look:
?s text:query ('ampumavä*' 100000000)
Lucene is also taking RAM, partly the Lucene engine, partly to deal with
limit/unique results.
(and if Solr then it has to completely buffer responses as well).
How many results are there to "?s text:query ("ampumavä*" 100000000 )"?
...
> This type of query normally takes less than one second. Now it took more
> than 15 minutes.
>
>> It is possible that updates are unflushed (a bit surprising given the
>> length of time since over night updates) - you can check this by looking
>> the the journal file and if is zero length, there are no outstanding
>> commits waiting to be flushed.
>
> It's too late now to check what size the journal was when this happened
> yesterday, but I checked it for today, and all the three *jrnl files had
> a size of zero and a timestamp of 04:57, which was the time when the
> last updates finished. So at least last night, the flush completed very
> soon after the update.
OK - it's highly unlikely to be updates then.
>> But the size locked down by unflushed commits does not change due to
>> read load.
>>
>> Queries can uses a lot of memory and several in parallel would also
>> cause OOME.
>
> It is possible that there happened to be a large number of parallel
> queries. However, looking at the log files, I couldn't find any notable
> peak.
>
>> How many datasets are on this server?
>
> Only one TDB dataset (no inference), with a jena-text index. Within this
> dataset there are about thirty named graphs, and most queries are
> limited to a single named graph.
>
>> On AWS, we have seen virtualization hardware "go bad" (I can't explain
>> it any better). Only seen on old hardware, m1 generation) . A server,
>> for no reason we can determine [*], simply starts having very high load,
>> makes very slow progress but is functionally fine. But it's randomly
>> going slow, queries build up which can means more memory in active use
>> at anyone point meaning OOME is possible. This is not a common
>> occurrence.
>>
>> [*] We allowed for cycle stealing from co-resident VMs - the slow down
>> is 10x scale.
>
> This is not AWS, but a VMware setup. It is possible that there was some
> contention for resources from other VMs running on the same hardware
> that could have caused queries to run slower and thus build up and use
> lots of memory.
>
> As first aid, I will increase the amount of memory to 8GB (from 6GB) and
> am investigating ways to detect this situation from outside Fuseki
> (which means I must be able to replicate the situation - will try
> running Fuseki with low amounts of memory) so that I can give it a kick
> if it happens again.
>
> -Osma
>
>
On 05/06/14 12:29, Osma Suominen wrote:
> This is a backend server for a web application which is frequented by
> GoogleBot and others (including local pings to test that the service
> is up every 5 minutes or so) which together pretty much ensure that
> there
> is always some activity going on. But there is an alternate backend
> server running another Fuseki to which I can divert query traffic
> temporarily if necessary.
We have had to make sure bots didn't trigger expensive queries - for
example sorts. And had bots that ignore "no follow" (and robots.txt).
We also use max=3 on the httpd front end to limit the impact of parallel
requests. Not perfect by any means but it does no harm.
Andy
Re: Jena/Fuseki/TDB Java heap space and OutOfMemory errors
Posted by Osma Suominen <os...@helsinki.fi>.
Hi Andy!
On 05/06/14 14:28, Andy Seaborne wrote:
> Osma,
>
> What are the long running queries?
Here's one (sorry for the messed up line breaks):
2014-06-04 11:26:42,705 INFO Fuseki :: [14739587] Query =
PREFIX owl: <http://www.w3.org/2002/07/owl#> PREFIX rdf:
<http://www.w3.org/1999/02/22-rdf-syntax-ns#> PREFIX skos:
<http://www.w3.org/2004/02/skos/core#> PREFIX text:
<http://jena.apache.org/text#> SELECT DISTINCT ?s ?label ?alabel
?hlabel ?graph (GROUP_CONCAT(?type) as ?types) WHERE { GRAPH
<http://www.yso.fi/onto/puho/> { { ?s text:query ('ampumavä*' 100000000)
} { ?s rdf:type
<http://www.w3.org/2004/02/skos/core#Concept> } {
?s skos:prefLabel ?label . ?s
rdf:type ?type . ?s ?prop ?match . FILTER (
strstarts(lcase(str(?match)), 'ampumavä') && !(?match !=
?label && strstarts(lcase(str(?label)), 'ampumavä'))
&& langMatches(lang(?label), lang(?match))
) } FILTER NOT EXISTS {?s owl:deprecated
true } } BIND(IF(?prop = skos:altLabel, ?match,
?unbound) as ?alabel) BIND(IF(?prop = skos:hiddenLabel, ?match,
?unbound) as ?hlabel) VALUES (?prop) { (skos:prefLabel)
(skos:altLabel) (skos:hiddenLabel) } } GROUP BY ?match ?s
?label ?alabel ?hlabel ?graph ?prop ORDER BY lcase(str(?match))
lang(?match)
2014-06-04 11:39:06,670 WARN Fuseki :: [14739587] RC = 500
: GC overhead limit exceeded
java.lang.OutOfMemoryError: GC overhead limit exceeded
2014-06-04 11:43:54,817 INFO Fuseki :: [14739587] 500 GC
overhead limit exceeded (1,032.111 s)
This type of query normally takes less than one second. Now it took more
than 15 minutes.
> It is possible that updates are unflushed (a bit surprising given the
> length of time since over night updates) - you can check this by looking
> the the journal file and if is zero length, there are no outstanding
> commits waiting to be flushed.
It's too late now to check what size the journal was when this happened
yesterday, but I checked it for today, and all the three *jrnl files had
a size of zero and a timestamp of 04:57, which was the time when the
last updates finished. So at least last night, the flush completed very
soon after the update.
> But the size locked down by unflushed commits does not change due to
> read load.
>
> Queries can uses a lot of memory and several in parallel would also
> cause OOME.
It is possible that there happened to be a large number of parallel
queries. However, looking at the log files, I couldn't find any notable
peak.
> How many datasets are on this server?
Only one TDB dataset (no inference), with a jena-text index. Within this
dataset there are about thirty named graphs, and most queries are
limited to a single named graph.
> On AWS, we have seen virtualization hardware "go bad" (I can't explain
> it any better). Only seen on old hardware, m1 generation) . A server,
> for no reason we can determine [*], simply starts having very high load,
> makes very slow progress but is functionally fine. But it's randomly
> going slow, queries build up which can means more memory in active use
> at anyone point meaning OOME is possible. This is not a common occurrence.
>
> [*] We allowed for cycle stealing from co-resident VMs - the slow down
> is 10x scale.
This is not AWS, but a VMware setup. It is possible that there was some
contention for resources from other VMs running on the same hardware
that could have caused queries to run slower and thus build up and use
lots of memory.
As first aid, I will increase the amount of memory to 8GB (from 6GB) and
am investigating ways to detect this situation from outside Fuseki
(which means I must be able to replicate the situation - will try
running Fuseki with low amounts of memory) so that I can give it a kick
if it happens again.
-Osma
--
Osma Suominen
D.Sc. (Tech), Information Systems Specialist
National Library of Finland
P.O. Box 26 (Teollisuuskatu 23)
00014 HELSINGIN YLIOPISTO
Tel. +358 50 3199529
osma.suominen@helsinki.fi
http://www.nationallibrary.fi
Re: Jena/Fuseki/TDB Java heap space and OutOfMemory errors
Posted by Andy Seaborne <an...@apache.org>.
Osma,
What are the long running queries?
It is possible that updates are unflushed (a bit surprising given the
length of time since over night updates) - you can check this by looking
the the journal file and if is zero length, there are no outstanding
commits waiting to be flushed.
But the size locked down by unflushed commits does not change due to
read load.
Queries can uses a lot of memory and several in parallel would also
cause OOME.
How many datasets are on this server?
Andy
PS Random other experience
On AWS, we have seen virtualization hardware "go bad" (I can't explain
it any better). Only seen on old hardware, m1 generation) . A server,
for no reason we can determine [*], simply starts having very high load,
makes very slow progress but is functionally fine. But it's randomly
going slow, queries build up which can means more memory in active use
at anyone point meaning OOME is possible. This is not a common occurrence.
[*] We allowed for cycle stealing from co-resident VMs - the slow down
is 10x scale.
On 05/06/14 11:43, Rob Vesse wrote:
> Osma
>
> Comments inline:
>
> On 05/06/2014 10:11, "Osma Suominen" <os...@helsinki.fi> wrote:
>
>> Hi all!
>>
>> On 30/05/14 16:36, Mark Feblowitz wrote:
>>
>>> After some amount of time I see a series of messages after update posts
>>>
>>> WARN [xxxxxx] RC = 500 : Java heap space
>>>
>>> And I’m seeing "java.lang.OutOfMemoryError: Java heap space” errors.
>>
>> I also got this error yesterday on an important machine.
>>
>> My setup is this: Fuseki 1.0.1 with a single TDB (no inference) that has
>> grown to 13GB and an additional jena-text index of 200MB. Fuseki is
>> given approx. 6GB of heap (-Xmx6000M) on a machine with 16GB RAM. The
>> machine is a virtual machine running 64bit CentOS 6, kernel
>> 2.6.32-431.11.2.el6.x86_64, java -version gives this:
>> java version "1.7.0_51"
>> OpenJDK Runtime Environment (rhel-2.4.4.1.el6_5-x86_64 u51-b02)
>> OpenJDK 64-Bit Server VM (build 24.45-b08, mixed mode)
>>
>>
>> At the time this happened there were no updates (we usually only update
>> during the night), just read-only SELECT and CONSTRUCT queries coming in
>> at around 8 queries per second on average.
>
> As has been explained in this thread the problem is that the continuous
> query load prevents the in-memory transaction journal from being fully
> flushed to disk. If the read only queries continue through the night
> while you do updates then they will block the journal flush and you will
> eventually hit this case
>
> JENA-703 (https://issues.apache.org/jira/browse/JENA-703) describes the
> proposed fix for this issue but the side effect of that fix (as and when
> it gets implemented) will be that for a system under continuous load reads
> will be occasionally blocked and therefore some queries may experience
> delays.
>
>>
>> Suddenly queries stop working and CPU usage rises to around 350% (the
>> machine has 4 cores). Errors like this appear in the Fuseki log:
>>
>> 2014-06-04 11:42:52,293 WARN Fuseki :: [14739636] RC = 500
>> : Java heap space
>> java.lang.OutOfMemoryError: Java heap space
>> 2014-06-04 11:39:06,670 WARN Fuseki :: [14739587] RC = 500
>> : GC overhead limit exceeded
>> java.lang.OutOfMemoryError: GC overhead limit exceeded
>> 2014-06-04 11:43:54,817 INFO Fuseki :: [14739587] 500 GC
>> overhead limit exceeded (1,032.111 s)
>> 2014-06-04 12:24:56,868 WARN Fuseki :: [14739738] RC = 500
>> : GC overhead limit exceeded
>> java.lang.OutOfMemoryError: GC overhead limit exceeded
>> 2014-06-04 12:24:04,660 WARN Fuseki :: [14739862] RC = 500
>> : Java heap space
>> java.lang.OutOfMemoryError: Java heap space
>> 2014-06-04 12:43:44,167 INFO Fuseki :: [14739738] 500 GC
>> overhead limit exceeded (2,227.717 s)
>> 2014-06-04 12:43:44,167 INFO Fuseki :: [14739862] 500 Java
>> heap space (2,227.719 s)
>> 2014-06-04 14:33:30,906 WARN Fuseki :: [14740021] RC = 500
>> : GC overhead limit exceeded
>> java.lang.OutOfMemoryError: GC overhead limit exceeded
>> 2014-06-04 14:34:21,722 INFO Fuseki :: [14740021] 500 GC
>> overhead limit exceeded (4,850.886 s)
>>
>>
>> The timestamps in the log entries are not always in order, as you can
>> see above. Sometimes it takes more than an hour for an individual query
>> to fail (see last entry).
>>
>> Needless to say this is a bit nasty way of failing - the process is
>> running, consuming nearly all CPU, but responding to queries very slowly
>> or not at all. It would even be better if the process just died, so
>> something else could restart it. I am considering using a tool such as
>> Monit to watch the Fuseki process and restart it if it starts behaving
>> oddly.
>
> This is really a JVM issue and not something we can control. The JVM
> allows catching OOM errors (for better or worse) but in doing so it often
> leaves applications in a state where they are extremely close to the heap
> limit and so the user code hangs while the JVM furiously tries to GC
> enough memory for it to continue.
>
>>
>> Am I doing something obviously wrong here?
>
> No, this is a known limitation of TDBs architecture
>
>
>> Should I just give the JVM
>> even more memory, or adjust some of the other JVM options?
>
> That only prolongs the time to failure and TDB relies heavily on memory
> mapped files which are off heap so increasing the heap size impacts
> performance because it cause more swapping at the OS level
>
>> Is there any
>> way to force the GC to fail faster, or otherwise avoid futile attempts
>> of freeing more memory?
>
> You can try the solution detailed at
> http://stackoverflow.com/a/3878199/107591
>
> Add -XX:OnOutOfMemoryError="kill -9 %p"
>
> That is an Oracle JVM option so no guarantee it works on OpenJDK
>
> Rob
>
>> Even better, could Fuseki just stick to the
>> memory it is given?
>>
>> Thanks,
>> Osma
>>
>> --
>> Osma Suominen
>> D.Sc. (Tech), Information Systems Specialist
>> National Library of Finland
>> P.O. Box 26 (Teollisuuskatu 23)
>> 00014 HELSINGIN YLIOPISTO
>> Tel. +358 50 3199529
>> osma.suominen@helsinki.fi
>> http://www.nationallibrary.fi
>
>
>
>
Re: Jena/Fuseki/TDB Java heap space and OutOfMemory errors
Posted by Rob Vesse <rv...@dotnetrdf.org>.
Osma
Comments inline:
On 05/06/2014 10:11, "Osma Suominen" <os...@helsinki.fi> wrote:
>Hi all!
>
>On 30/05/14 16:36, Mark Feblowitz wrote:
>
>> After some amount of time I see a series of messages after update posts
>>
>> WARN [xxxxxx] RC = 500 : Java heap space
>>
>> And I’m seeing "java.lang.OutOfMemoryError: Java heap space” errors.
>
>I also got this error yesterday on an important machine.
>
>My setup is this: Fuseki 1.0.1 with a single TDB (no inference) that has
>grown to 13GB and an additional jena-text index of 200MB. Fuseki is
>given approx. 6GB of heap (-Xmx6000M) on a machine with 16GB RAM. The
>machine is a virtual machine running 64bit CentOS 6, kernel
>2.6.32-431.11.2.el6.x86_64, java -version gives this:
>java version "1.7.0_51"
>OpenJDK Runtime Environment (rhel-2.4.4.1.el6_5-x86_64 u51-b02)
>OpenJDK 64-Bit Server VM (build 24.45-b08, mixed mode)
>
>
>At the time this happened there were no updates (we usually only update
>during the night), just read-only SELECT and CONSTRUCT queries coming in
>at around 8 queries per second on average.
As has been explained in this thread the problem is that the continuous
query load prevents the in-memory transaction journal from being fully
flushed to disk. If the read only queries continue through the night
while you do updates then they will block the journal flush and you will
eventually hit this case
JENA-703 (https://issues.apache.org/jira/browse/JENA-703) describes the
proposed fix for this issue but the side effect of that fix (as and when
it gets implemented) will be that for a system under continuous load reads
will be occasionally blocked and therefore some queries may experience
delays.
>
>Suddenly queries stop working and CPU usage rises to around 350% (the
>machine has 4 cores). Errors like this appear in the Fuseki log:
>
>2014-06-04 11:42:52,293 WARN Fuseki :: [14739636] RC = 500
>: Java heap space
>java.lang.OutOfMemoryError: Java heap space
>2014-06-04 11:39:06,670 WARN Fuseki :: [14739587] RC = 500
>: GC overhead limit exceeded
>java.lang.OutOfMemoryError: GC overhead limit exceeded
>2014-06-04 11:43:54,817 INFO Fuseki :: [14739587] 500 GC
>overhead limit exceeded (1,032.111 s)
>2014-06-04 12:24:56,868 WARN Fuseki :: [14739738] RC = 500
>: GC overhead limit exceeded
>java.lang.OutOfMemoryError: GC overhead limit exceeded
>2014-06-04 12:24:04,660 WARN Fuseki :: [14739862] RC = 500
>: Java heap space
>java.lang.OutOfMemoryError: Java heap space
>2014-06-04 12:43:44,167 INFO Fuseki :: [14739738] 500 GC
>overhead limit exceeded (2,227.717 s)
>2014-06-04 12:43:44,167 INFO Fuseki :: [14739862] 500 Java
>heap space (2,227.719 s)
>2014-06-04 14:33:30,906 WARN Fuseki :: [14740021] RC = 500
>: GC overhead limit exceeded
>java.lang.OutOfMemoryError: GC overhead limit exceeded
>2014-06-04 14:34:21,722 INFO Fuseki :: [14740021] 500 GC
>overhead limit exceeded (4,850.886 s)
>
>
>The timestamps in the log entries are not always in order, as you can
>see above. Sometimes it takes more than an hour for an individual query
>to fail (see last entry).
>
>Needless to say this is a bit nasty way of failing - the process is
>running, consuming nearly all CPU, but responding to queries very slowly
>or not at all. It would even be better if the process just died, so
>something else could restart it. I am considering using a tool such as
>Monit to watch the Fuseki process and restart it if it starts behaving
>oddly.
This is really a JVM issue and not something we can control. The JVM
allows catching OOM errors (for better or worse) but in doing so it often
leaves applications in a state where they are extremely close to the heap
limit and so the user code hangs while the JVM furiously tries to GC
enough memory for it to continue.
>
>Am I doing something obviously wrong here?
No, this is a known limitation of TDBs architecture
>Should I just give the JVM
>even more memory, or adjust some of the other JVM options?
That only prolongs the time to failure and TDB relies heavily on memory
mapped files which are off heap so increasing the heap size impacts
performance because it cause more swapping at the OS level
>Is there any
>way to force the GC to fail faster, or otherwise avoid futile attempts
>of freeing more memory?
You can try the solution detailed at
http://stackoverflow.com/a/3878199/107591
Add -XX:OnOutOfMemoryError="kill -9 %p"
That is an Oracle JVM option so no guarantee it works on OpenJDK
Rob
>Even better, could Fuseki just stick to the
>memory it is given?
>
>Thanks,
>Osma
>
>--
>Osma Suominen
>D.Sc. (Tech), Information Systems Specialist
>National Library of Finland
>P.O. Box 26 (Teollisuuskatu 23)
>00014 HELSINGIN YLIOPISTO
>Tel. +358 50 3199529
>osma.suominen@helsinki.fi
>http://www.nationallibrary.fi
Re: Jena/Fuseki/TDB Java heap space and OutOfMemory errors
Posted by Osma Suominen <os...@helsinki.fi>.
Hi all!
On 30/05/14 16:36, Mark Feblowitz wrote:
> After some amount of time I see a series of messages after update posts
>
> WARN [xxxxxx] RC = 500 : Java heap space
>
> And I’m seeing "java.lang.OutOfMemoryError: Java heap space” errors.
I also got this error yesterday on an important machine.
My setup is this: Fuseki 1.0.1 with a single TDB (no inference) that has
grown to 13GB and an additional jena-text index of 200MB. Fuseki is
given approx. 6GB of heap (-Xmx6000M) on a machine with 16GB RAM. The
machine is a virtual machine running 64bit CentOS 6, kernel
2.6.32-431.11.2.el6.x86_64, java -version gives this:
java version "1.7.0_51"
OpenJDK Runtime Environment (rhel-2.4.4.1.el6_5-x86_64 u51-b02)
OpenJDK 64-Bit Server VM (build 24.45-b08, mixed mode)
At the time this happened there were no updates (we usually only update
during the night), just read-only SELECT and CONSTRUCT queries coming in
at around 8 queries per second on average.
Suddenly queries stop working and CPU usage rises to around 350% (the
machine has 4 cores). Errors like this appear in the Fuseki log:
2014-06-04 11:42:52,293 WARN Fuseki :: [14739636] RC = 500
: Java heap space
java.lang.OutOfMemoryError: Java heap space
2014-06-04 11:39:06,670 WARN Fuseki :: [14739587] RC = 500
: GC overhead limit exceeded
java.lang.OutOfMemoryError: GC overhead limit exceeded
2014-06-04 11:43:54,817 INFO Fuseki :: [14739587] 500 GC
overhead limit exceeded (1,032.111 s)
2014-06-04 12:24:56,868 WARN Fuseki :: [14739738] RC = 500
: GC overhead limit exceeded
java.lang.OutOfMemoryError: GC overhead limit exceeded
2014-06-04 12:24:04,660 WARN Fuseki :: [14739862] RC = 500
: Java heap space
java.lang.OutOfMemoryError: Java heap space
2014-06-04 12:43:44,167 INFO Fuseki :: [14739738] 500 GC
overhead limit exceeded (2,227.717 s)
2014-06-04 12:43:44,167 INFO Fuseki :: [14739862] 500 Java
heap space (2,227.719 s)
2014-06-04 14:33:30,906 WARN Fuseki :: [14740021] RC = 500
: GC overhead limit exceeded
java.lang.OutOfMemoryError: GC overhead limit exceeded
2014-06-04 14:34:21,722 INFO Fuseki :: [14740021] 500 GC
overhead limit exceeded (4,850.886 s)
The timestamps in the log entries are not always in order, as you can
see above. Sometimes it takes more than an hour for an individual query
to fail (see last entry).
Needless to say this is a bit nasty way of failing - the process is
running, consuming nearly all CPU, but responding to queries very slowly
or not at all. It would even be better if the process just died, so
something else could restart it. I am considering using a tool such as
Monit to watch the Fuseki process and restart it if it starts behaving
oddly.
Am I doing something obviously wrong here? Should I just give the JVM
even more memory, or adjust some of the other JVM options? Is there any
way to force the GC to fail faster, or otherwise avoid futile attempts
of freeing more memory? Even better, could Fuseki just stick to the
memory it is given?
Thanks,
Osma
--
Osma Suominen
D.Sc. (Tech), Information Systems Specialist
National Library of Finland
P.O. Box 26 (Teollisuuskatu 23)
00014 HELSINGIN YLIOPISTO
Tel. +358 50 3199529
osma.suominen@helsinki.fi
http://www.nationallibrary.fi
Fwd: Jena/Fuseki/TDB Java heap space and OutOfMemory errors
Posted by Mark Feblowitz <Ma...@comcast.net>.
The update rates look to be around 40 updates per second (at least during catch-up, after restarting Fuseki. For regular processing, I’m seeing bursts of many such flurries of updates, at the same time I’m seeing perhaps a dozen queries.
Begin forwarded message:
> From: Mark Feblowitz <Ma...@comcast.net>
> Subject: Jena/Fuseki/TDB Java heap space and OutOfMemory errors
> Date: May 30, 2014 at 9:36:31 AM EDT
> To: "users@jena.apache.org" <us...@jena.apache.org>
>
> I have a setup where there can be many, rapid-fire updates sent to Jena TDB via UPDATE posts to Fuseki.
>
> After some amount of time I see a series of messages after update posts
>
> WARN [xxxxxx] RC = 500 : Java heap space
>
> And I’m seeing "java.lang.OutOfMemoryError: Java heap space” errors.
>
> I’ve bumped heap space to 3072M, on a machine that has 32 GB of memory.
>
> Can this be dealt with, simply by doubling heap space? Or is there something about how I’m posting that could be leading to the problem.
>
> What I’m doing is creating an OntModel in the client, which then posts that model as an update to Fuseki. Fuseki is configured with TDB and OWLFBRuleReasoner.
>
> As I mentioned in my prior posts on retries, there are flurries of posts to Fuseki, and roughly concurrent queries - often on things that are in the process of being posted. All of the posts come from a single client, while the queries come from multiple queries initiated from separately run queries (from separate JVMs).
>
>
> Here’s a snippet of the console log after a series of other interactions and errors. I’ll have to save out the entire log (but it will be huge) to identify the circumstances of the first errors.
>
>
> 00:55:33 INFO [79927] 500 Java heap space (5.393 s)
> 00:55:39 INFO [79929] POST http://localhost:3030/km4sp/update
> 00:55:43 WARN [79929] RC = 500 : Java heap space
> java.lang.OutOfMemoryError: Java heap space
> at org.apache.jena.atlas.io.CharStreamBuffered.<init>(CharStreamBuffered
> .java:53)
> at org.apache.jena.atlas.io.PeekReader.make(PeekReader.java:81)
> at org.apache.jena.atlas.io.PeekReader.make(PeekReader.java:75)
> at org.apache.jena.atlas.io.PeekReader.makeUTF8(PeekReader.java:92)
> at com.hp.hpl.jena.sparql.lang.UpdateParser.parse(UpdateParser.java:51)
> at com.hp.hpl.jena.update.UpdateFactory.make(UpdateFactory.java:278)
> at com.hp.hpl.jena.update.UpdateFactory.read(UpdateFactory.java:267)
> at org.apache.jena.fuseki.servlets.SPARQL_Update.execute(SPARQL_Update.j
> ava:228)
> at org.apache.jena.fuseki.servlets.SPARQL_Update.executeBody(SPARQL_Upda
> te.java:194)
> at org.apache.jena.fuseki.servlets.SPARQL_Update.perform(SPARQL_Update.j
> ava:106)
> at org.apache.jena.fuseki.servlets.SPARQL_ServletBase.executeLifecycle(S
> PARQL_ServletBase.java:171)
> at org.apache.jena.fuseki.servlets.SPARQL_ServletBase.executeAction(SPAR
> QL_ServletBase.java:152)
> at org.apache.jena.fuseki.servlets.SPARQL_ServletBase.execCommonWorker(S
> PARQL_ServletBase.java:140)
> at org.apache.jena.fuseki.servlets.SPARQL_ServletBase.doCommon(SPARQL_Se
> rvletBase.java:69)
> at org.apache.jena.fuseki.servlets.SPARQL_Update.doPost(SPARQL_Update.ja
> va:81)
> at javax.servlet.http.HttpServlet.service(HttpServlet.java:755)
> at javax.servlet.http.HttpServlet.service(HttpServlet.java:848)
> at org.eclipse.jetty.servlet.ServletHolder.handle(ServletHolder.java:684
> )
> at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java
> :457)
> at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandl
> er.java:229)
> at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandl
> er.java:1075)
> at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:
> 384)
> at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandle
> r.java:193)
> at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandle
> r.java:1009)
> at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.j
> ava:135)
> at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper
> .java:116)
> at org.eclipse.jetty.server.Server.handle(Server.java:370)
> at org.eclipse.jetty.server.AbstractHttpConnection.handleRequest(Abstrac
> tHttpConnection.java:489)
> at org.eclipse.jetty.server.BlockingHttpConnection.handleRequest(Blockin
> gHttpConnection.java:53)
> at org.eclipse.jetty.server.AbstractHttpConnection.content(AbstractHttpC
> onnection.java:960)
> at org.eclipse.jetty.server.AbstractHttpConnection$RequestHandler.conten
> t(AbstractHttpConnection.java:1021)
> at org.eclipse.jetty.http.HttpParser.parseNext(HttpParser.java:865)
> 00:55:45 INFO [79929] 500 Java heap space (5.597 s)
> 00:55:51 INFO [79930] POST http://localhost:3030/km4sp/update
> 00:56:59 INFO [79928] exec/select
>