Re: [Neo4j] Unable to start server: (javax.transaction.SystemException: TM has encountered some problem)

[Michael Hunger]

Justin,

could you please share your servers data/graph.db/messages.log
as well as the logs in data/log ?

And please don't delete the database (yet) we might ask you for it.

Thanks a lot

Michael

Am 10.08.2012 um 01:08 schrieb Justin Pincar:

> I'm just starting with neo4j and running into some issues, and was hoping to get some help here.
>
> I created a graph with about 600k nodes and 11M relationships - I have plenty of disk space left. I have three types of nodes and two indices. My data import script seemed to be running fine, and then inexplicably starting returning 400s.
>
> I googled parts of the stack trace but couldn't find any relevant details. Every time I try to start the server I get the trace below.
>
> Any help would be greatly appreciated. Thanks!
>
> - Justin
>
>
> 21:14:04.884 [18183221@qtp-11467963-4103] ERROR org.mortbay.log - /db/data/node
> org.neo4j.graphdb.TransactionFailureException: Unable to begin transaction
> at org.neo4j.kernel.InternalAbstractGraphDatabase.beginTx(InternalAbstractGraphDatabase.java:747) ~[neo4j-kernel-1.8.M06.jar:1.8.M06]
> at org.neo4j.kernel.TransactionBuilderImpl.begin(TransactionBuilderImpl.java:39) ~[neo4j-kernel-1.8.M06.jar:1.8.M06]
> at org.neo4j.server.rest.web.DatabaseActions.beginTx(DatabaseActions.java:228) ~[neo4j-server-1.8.M06.jar:1.8.M06]
> at org.neo4j.server.rest.web.DatabaseActions.createNode(DatabaseActions.java:210) ~[neo4j-server-1.8.M06.jar:1.8.M06]
> at org.neo4j.server.rest.web.RestfulGraphDatabase.createNode(RestfulGraphDatabase.java:195) ~[neo4j-server-1.8.M06.jar:1.8.M06]
> at sun.reflect.GeneratedMethodAccessor83.invoke(Unknown Source) ~[na:na]
> at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[na:1.6.0_20]
> at java.lang.reflect.Method.invoke(Method.java:616) ~[na:1.6.0_20]
> at com.sun.jersey.spi.container.JavaMethodInvokerFactory$1.invoke(JavaMethodInvokerFactory.java:60) ~[jersey-server-1.9.jar:1.9]
> at com.sun.jersey.server.impl.model.method.dispatch.AbstractResourceMethodDispatchProvider$ResponseOutInvoker._dispatch(AbstractResourceMethodDispatchProvider.java:205) ~[jersey-server-1.9.jar:1.9] at com.sun.jersey.server.impl.model.method.dispatch.ResourceJavaMethodDispatcher.dispatch(ResourceJavaMethodDispatcher.java:75) ~[jersey-server-1.9.jar:1.9]
> at com.sun.jersey.server.impl.uri.rules.HttpMethodRule.accept(HttpMethodRule.java:288) ~[jersey-server-1.9.jar:1.9]
> at com.sun.jersey.server.impl.uri.rules.RightHandPathRule.accept(RightHandPathRule.java:147) ~[jersey-server-1.9.jar:1.9]
> at com.sun.jersey.server.impl.uri.rules.ResourceClassRule.accept(ResourceClassRule.java:108) ~[jersey-server-1.9.jar:1.9]
> at com.sun.jersey.server.impl.uri.rules.RightHandPathRule.accept(RightHandPathRule.java:147) ~[jersey-server-1.9.jar:1.9]
> at com.sun.jersey.server.impl.uri.rules.RootResourceClassesRule.accept(RootResourceClassesRule.java:84) ~[jersey-server-1.9.jar:1.9]
> at com.sun.jersey.server.impl.application.WebApplicationImpl._handleRequest(WebApplicationImpl.java:1469) ~[jersey-server-1.9.jar:1.9]
> at com.sun.jersey.server.impl.application.WebApplicationImpl._handleRequest(WebApplicationImpl.java:1400) ~[jersey-server-1.9.jar:1.9]
> at com.sun.jersey.server.impl.application.WebApplicationImpl.handleRequest(WebApplicationImpl.java:1349) ~[jersey-server-1.9.jar:1.9]
> at com.sun.jersey.server.impl.application.WebApplicationImpl.handleRequest(WebApplicationImpl.java:1339) ~[jersey-server-1.9.jar:1.9]
> at com.sun.jersey.spi.container.servlet.WebComponent.service(WebComponent.java:416) ~[jersey-server-1.9.jar:1.9]
> at com.sun.jersey.spi.container.servlet.ServletContainer.service(ServletContainer.java:537) ~[jersey-server-1.9.jar:1.9]
> at com.sun.jersey.spi.container.servlet.ServletContainer.service(ServletContainer.java:699) ~[jersey-server-1.9.jar:1.9]
> at javax.servlet.http.HttpServlet.service(HttpServlet.java:820) ~[servlet-api-2.5-20081211.jar:na]
> at org.mortbay.jetty.servlet.ServletHolder.handle(ServletHolder.java:511) ~[jetty-6.1.25.jar:6.1.25]
> at org.mortbay.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1166) ~[jetty-6.1.25.jar:6.1.25]
> at org.neo4j.server.statistic.StatisticFilter.doFilter(StatisticFilter.java:62) ~[neo4j-server-1.8.M06.jar:1.8.M06]
> at org.mortbay.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1157) ~[jetty-6.1.25.jar:6.1.25]
> at org.mortbay.jetty.servlet.ServletHandler.handle(ServletHandler.java:388) ~[jetty-6.1.25.jar:6.1.25]
> at org.mortbay.jetty.servlet.SessionHandler.handle(SessionHandler.java:182) [jetty-6.1.25.jar:6.1.25]
> at org.mortbay.jetty.handler.ContextHandler.handle(ContextHandler.java:765) [jetty-6.1.25.jar:6.1.25]
> at org.mortbay.jetty.handler.HandlerCollection.handle(HandlerCollection.java:114) [jetty-6.1.25.jar:6.1.25]
> at org.mortbay.jetty.handler.HandlerWrapper.handle(HandlerWrapper.java:152) [jetty-6.1.25.jar:6.1.25]
> at org.mortbay.jetty.Server.handle(Server.java:326) [jetty-6.1.25.jar:6.1.25]
> at org.mortbay.jetty.HttpConnection.handleRequest(HttpConnection.java:542) [jetty-6.1.25.jar:6.1.25]
> at org.mortbay.jetty.HttpConnection$RequestHandler.content(HttpConnection.java:943) [jetty-6.1.25.jar:6.1.25]
> at org.mortbay.jetty.HttpParser.parseNext(HttpParser.java:756) [jetty-6.1.25.jar:6.1.25]
> at org.mortbay.jetty.HttpParser.parseAvailable(HttpParser.java:212) [jetty-6.1.25.jar:6.1.25]
> at org.mortbay.jetty.HttpConnection.handle(HttpConnection.java:404) [jetty-6.1.25.jar:6.1.25]
> at org.mortbay.io.nio.SelectChannelEndPoint.run(SelectChannelEndPoint.java:410) [jetty-6.1.25.jar:6.1.25]
> at org.mortbay.thread.QueuedThreadPool$PoolThread.run(QueuedThreadPool.java:582) [jetty-util-6.1.25.jar:6.1.25]
> Caused by: javax.transaction.SystemException: TM has encountered some problem, please perform neccesary action (tx recovery/restart)
> at org.neo4j.kernel.impl.transaction.TxManager.assertTmOk(TxManager.java:362) ~[neo4j-kernel-1.8.M06.jar:1.8.M06]
> at org.neo4j.kernel.impl.transaction.TxManager.begin(TxManager.java:339) ~[neo4j-kernel-1.8.M06.jar:1.8.M06]
> at org.neo4j.kernel.InternalAbstractGraphDatabase.beginTx(InternalAbstractGraphDatabase.java:742) ~[neo4j-kernel-1.8.M06.jar:1.8.M06]
> ... 40 common frames omitted
>
>

[Justin Pincar]

Hi Michael,

I've uploaded the logs to S3:

http://justinpincar-public.s3.amazonaws.com/neo4j/console.log

http://justinpincar-public.s3.amazonaws.com/neo4j/messages.log

http://justinpincar-public.s3.amazonaws.com/neo4j/neo4j.0.0.log

http://justinpincar-public.s3.amazonaws.com/neo4j/neo4j.0.1.log

http://justinpincar-public.s3.amazonaws.com/neo4j/neo4j.0.2.log

http://justinpincar-public.s3.amazonaws.com/neo4j/neo4j.0.3.log

http://justinpincar-public.s3.amazonaws.com/neo4j/neo4j.0.4.log

http://justinpincar-public.s3.amazonaws.com/neo4j/neo4j.0.5.log

http://justinpincar-public.s3.amazonaws.com/neo4j/neo4j.0.6.log

http://justinpincar-public.s3.amazonaws.com/neo4j/neo4j.0.7.log

http://justinpincar-public.s3.amazonaws.com/neo4j/neo4j.0.8.log

http://justinpincar-public.s3.amazonaws.com/neo4j/neo4j.0.9.log

Let me know if there's anything else you need. Thanks for taking a look!

- Justin

[Jacob Hansson]

Hey Justin, thanks for uploading the logs.

Looking at the messages.log, two items stick out. One is the amount of GC pauses you are seeing, you might want to look into tuning your garbage collector. Specifically, try and make sure there are available cores for the GC thread (by for instance limiting the number of threads given to jetty in the neo4j server config), it seems it is getting paused by the OS almost constantly. 

The other issue, which appears to be the cause of your Transaction Manager (TM) problems, is that Lucene has broken with this exception:

java.io.IOException: Illegal seek: NIOFSIndexInput(path="/mnt/neo4j-community-1.8.M06/data/graph.db/index/lucene/node/users/_7j5r.cfs") 

I've googled to try and find anyone else seeing this issue, and haven't had any luck. One hypothesis is that the shaky environment created by the continuous GC pauses has rustled up a race condition that hasn't been noticed in Lucene before.

You can try running the Lucene checkindex tool to make sure your indexes are intact. The various indexes are stored under graph.db/index/lucene/node|relationship/. Take a look here for how to use checkindex:

http://solr.pl/en/2011/01/17/checkindex-for-the-rescue/

Please let us know what checkindex tells you and if you were able to resolve the issue with it, it will help tracing down what caused this in the first place.

/jake

[Justin Pincar]

Thanks Jake, I'll try these things tonight and let you know how it turns out.
- Justin

--
 
 

[Justin Pincar]

The garbage collection seems very likely - I switched to a higher memory instance and things seem like they're going faster and smoother.

The index seems to be fine, output below.

At this point I'm just moving on with the new setup and making sure to backup frequently, so I'm not going to worry about this issue too much. Thanks for all the help!

- Justin

ubuntu@ip-10-170-99-9:/mnt/neo4j-community-1.8.M06/data-old/graph.db$ java -cp ../../lib/lucene-core-3.5.0.jar -ea:org.apache.lucene... org.apache.lucene.index.CheckIndex index/lucene/node/apps/ -fix

Opening index @ index/lucene/node/apps/

Segments file=segments_3 numSegments=2 version=3.5 format=FORMAT_3_1 [Lucene 3.1+]

  1 of 2: name=_2xr8 docCount=123355

    compound=false

    hasProx=true

    numFiles=8

    size (MB)=7.114

    diagnostics = {mergeFactor=10, os.version=2.6.32-345-ec2, os=Linux, lucene.version=3.5.0 1204988 - simon - 2011-11-22 14:46:51, source=merge, os.arch=i386, mergeMaxNumSegments=-1, java.version=1.6.0_20, java.vendor=Sun Microsystems Inc.}

    no deletions

    test: open reader.........OK

    test: fields..............OK [2 fields]

    test: field norms.........OK [2 fields]

    test: terms, freq, prox...OK [246705 terms; 246710 terms/docs pairs; 246710 tokens]

    test: stored fields.......OK [246710 total field count; avg 2 fields per doc]

    test: term vectors........OK [0 total vector count; avg 0 term/freq vector fields per doc]

  2 of 2: name=_2xr9 docCount=1

    compound=true

    hasProx=true

    numFiles=1

    size (MB)=0

    diagnostics = {os.version=2.6.32-345-ec2, os=Linux, lucene.version=3.5.0 1204988 - simon - 2011-11-22 14:46:51, source=flush, os.arch=i386, java.version=1.6.0_20, java.vendor=Sun Microsystems Inc.}

    no deletions

    test: open reader.........OK

    test: fields..............OK [2 fields]

    test: field norms.........OK [2 fields]

    test: terms, freq, prox...OK [2 terms; 2 terms/docs pairs; 2 tokens]

    test: stored fields.......OK [2 total field count; avg 2 fields per doc]

    test: term vectors........OK [0 total vector count; avg 0 term/freq vector fields per doc]

No problems were detected with this index.