Neo4j timeout error happens occasionally with transaction size 4000

195 views

Skip to first unread message

rfc...@gmail.com

unread,

Sep 2, 2017, 9:37:13 PM9/2/17

to Neo4j

Our Python 3 program using version 3.1.2 py2neo on Neo4j Community Edition version 3.0.3. with transaction size about 4000, i.e. we do a transaction commit after we put 4,000 Cypher statements to a transaction.

We open the py2neo Graph as this

from py2neo import Graph

g = Graph(bolt = False, user = .., password = ..)

Once a long while we will get timeout error from Neo4j. Any idea why this kind of timeout happens? Stack trace of py2neo, exception log from neo4j.log and debug.log of when the timeout happened are included below. Note that our Python log time zone is 7 hours behind UTC.

Python 3 log including py2neo stack trace:

Sep 1 12:01:34 ddna-sjc 2017-09-01 12:01:34,886 - read_qosmos - INFO - /opt/trendmicro/ddna/engine/flow_processor.py, line 603: stack_list = traceback.extract_stack(limit=10) + \

Sep 1 12:01:34 ddna-sjc 2017-09-01 12:01:34,886 - read_qosmos - INFO - /opt/trendmicro/ddna/engine/flow_processor.py, line 4048: tx_b.commit()

Sep 1 12:01:34 ddna-sjc 2017-09-01 12:01:34,886 - read_qosmos - INFO - /opt/trendmicro/ddna/engine/venv-flow-processor/lib/python3.4/site-packages/py2neo/database/__init__.py, line 1059: self._post(commit=True)

Sep 1 12:01:34 ddna-sjc 2017-09-01 12:01:34,887 - read_qosmos - INFO - /opt/trendmicro/ddna/engine/venv-flow-processor/lib/python3.4/site-packages/py2neo/packages/httpstream/http.py, line 984: return rq.submit(**kwargs)

Sep 1 12:01:34 ddna-sjc 2017-09-01 12:01:34,887 - read_qosmos - WARNING - mp 0, ctx 1 Got an exception from commit(): timed out

Sep 1 12:01:34 ddna-sjc 2017-09-01 12:01:34,887 - read_qosmos - INFO - Type of Exception is <class 'py2neo.packages.httpstream.http.SocketError'>

from neo4j.log

2017-09-01 18:38:38.733+0000 WARN badMessage: java.lang.IllegalStateException: too much data after closed for HttpChannelOverHttp@4b2cc33{r=5,c=false,a=IDLE,uri=-}

2017-09-01 19:01:35.111+0000 ERROR Failed to generate JSON output. java.util.concurrent.TimeoutException: Idle timeout expired: 30000/30000 ms

java.io.IOException: java.util.concurrent.TimeoutException: Idle timeout expired: 30000/30000 ms

at org.eclipse.jetty.util.SharedBlockingCallback$Blocker.block(SharedBlockingCallback.java:234)

at org.eclipse.jetty.server.HttpOutput.write(HttpOutput.java:136)

at org.eclipse.jetty.server.HttpOutput.write(HttpOutput.java:350)

at com.sun.jersey.spi.container.servlet.WebComponent$Writer.write(WebComponent.java:300)

at com.sun.jersey.spi.container.ContainerResponse$CommittingOutputStream.write(ContainerResponse.java:135)

at org.neo4j.server.rest.web.TransactionalService$InterruptingOutputStream.write(TransactionalService.java:283)

at org.codehaus.jackson.impl.Utf8Generator._flushBuffer(Utf8Generator.java:1754)

at org.codehaus.jackson.impl.Utf8Generator._writeFieldName(Utf8Generator.java:432)

at org.codehaus.jackson.impl.Utf8Generator.writeFieldName(Utf8Generator.java:282)

at org.codehaus.jackson.JsonGenerator.writeNumberField(JsonGenerator.java:956)

at org.neo4j.server.rest.transactional.ExecutionResultSerializer.writeStats(ExecutionResultSerializer.java:209)

at org.neo4j.server.rest.transactional.ExecutionResultSerializer.statementResult(ExecutionResultSerializer.java:115)

at org.neo4j.server.rest.transactional.TransactionHandle.executeStatements(TransactionHandle.java:316)

at org.neo4j.server.rest.transactional.TransactionHandle.commit(TransactionHandle.java:150)

at org.neo4j.server.rest.web.TransactionalService.lambda$executeStatementsAndCommit$28(TransactionalService.java:202)

at org.neo4j.server.rest.web.TransactionalService$$Lambda$169/499200393.write(Unknown Source)

at com.sun.jersey.core.impl.provider.entity.StreamingOutputProvider.writeTo(StreamingOutputProvider.java:71)

at com.sun.jersey.core.impl.provider.entity.StreamingOutputProvider.writeTo(StreamingOutputProvider.java:57)

at com.sun.jersey.spi.container.ContainerResponse.write(ContainerResponse.java:302)

at com.sun.jersey.server.impl.application.WebApplicationImpl._handleRequest(WebApplicationImpl.java:1510)

at com.sun.jersey.server.impl.application.WebApplicationImpl.handleRequest(WebApplicationImpl.java:1419)

at com.sun.jersey.server.impl.application.WebApplicationImpl.handleRequest(WebApplicationImpl.java:1409)

at com.sun.jersey.spi.container.servlet.WebComponent.service(WebComponent.java:409)

at com.sun.jersey.spi.container.servlet.ServletContainer.service(ServletContainer.java:558)

at com.sun.jersey.spi.container.servlet.ServletContainer.service(ServletContainer.java:733)

at javax.servlet.http.HttpServlet.service(HttpServlet.java:790)

at org.eclipse.jetty.servlet.ServletHolder.handle(ServletHolder.java:808)

at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1669)

at org.neo4j.server.rest.web.CollectUserAgentFilter.doFilter(CollectUserAgentFilter.java:69)

at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1652)

at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:585)

at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:221)

at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1127)

at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:515)

at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:185)

at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1061)

at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:141)

at org.eclipse.jetty.server.handler.HandlerList.handle(HandlerList.java:52)

at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:97)

at org.eclipse.jetty.server.Server.handle(Server.java:497)

at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:310)

at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:257)

at org.eclipse.jetty.io.AbstractConnection$2.run(AbstractConnection.java:540)

at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:635)

at org.eclipse.jetty.util.thread.QueuedThreadPool$3.run(QueuedThreadPool.java:555)

at java.lang.Thread.run(Thread.java:745)

Caused by: java.util.concurrent.TimeoutException: Idle timeout expired: 30000/30000 ms

at org.eclipse.jetty.io.IdleTimeout.checkIdleTimeout(IdleTimeout.java:161)

at org.eclipse.jetty.io.IdleTimeout$1.run(IdleTimeout.java:50)

at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)

at java.util.concurrent.FutureTask.run(FutureTask.java:266)

at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180)

at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293)

at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)

at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)

... 1 more

from debug.log

2017-09-01 18:58:33.634+0000 INFO [o.n.k.i.t.l.p.LogPruningImpl] Log Rotation [8720]: Starting log pruning.

2017-09-01 18:58:33.635+0000 INFO [o.n.k.i.t.l.p.LogPruningImpl] Log Rotation [8720]: Log pruning complete.

2017-09-01 19:03:33.641+0000 INFO [o.n.k.i.t.l.c.CheckPointerImpl] Check Pointing triggered by scheduler for time threshold [100911780]: Starting check pointing...2017-09-01 19:03:33.641+0000 INFO [o.n.k.i.t.l.c.CheckPointerImpl] Check Pointing triggered by scheduler for time threshold [100911780]: Starting store flush...2017-09-01 19:03:33.778+0000 INFO [o.n.k.i.s.c.CountsTracker] About to rotate counts store at transaction 100911780 to [/data/ddna/neo4j/data/databases/graph.db/neostore.counts.db.a], from [/data/ddna/neo4j/data/databases/graph.db/neostore.counts.db.b].2017-09-01 19:03:33.780+0000 INFO [o.n.k.i.s.c.CountsTracker] Successfully rotated counts store at transaction 100911780 to [/data/ddna/neo4j/data/databases/graph.db/neostore.counts.db.a], from [/data/ddna/neo4j/data/databases/graph.db/neostore.counts.db.b].2017-09-01 19:03:37.653+0000 INFO [o.n.k.i.t.l.c.CheckPointerImpl] Check Pointing triggered by scheduler for time threshold [100911780]: Store flush completed2017-09-01 19:03:37.653+0000 INFO [o.n.k.i.t.l.c.CheckPointerImpl] Check Pointing triggered by scheduler for time threshold [100911780]: Starting appending check point entry into the tx log...2017-09-01 19:03:37.654+0000 INFO [o.n.k.i.t.l.c.CheckPointerImpl] Check Pointing triggered by scheduler for time threshold [100911780]: Appending check point entry into the tx log completed2017-09-01 19:03:37.654+0000 INFO [o.n.k.i.t.l.c.CheckPointerImpl] Check Pointing triggered by scheduler for time threshold [100911780]: Check pointing completed2017-09-01 19:03:37.654+0000 INFO [o.n.k.i.t.l.p.LogPruningImpl] Log Rotation [8720]: Starting log pruning.2017-09-01 19:03:37.655+0000 INFO [o.n.k.i.t.l.p.LogPruningImpl] Log Rotation [8720]: Log pruning complete.

2017-09-01 19:08:37.662+0000 INFO [o.n.k.i.t.l.c.CheckPointerImpl] Check Pointing triggered by scheduler for time threshold [100911792]: Starting check pointing...2017-09-01 19:08:37.662+0000 INFO [o.n.k.i.t.l.c.CheckPointerImpl] Check Pointing triggered by scheduler for time threshold [100911792]: Starting store flush...

2017-09-01 19:08:37.747+0000 INFO [o.n.k.i.s.c.CountsTracker] About to rotate counts store at transaction 100911792 to [/data/ddna/neo4j/data/databases/graph.d

b/neostore.counts.db.b], from [/data/ddna/neo4j/data/databases/graph.db/neostore

.counts.db.a].

2017-09-01 19:08:37.749+0000 INFO [o.n.k.i.s.c.CountsTracker] Successfully rotated counts store at transaction 100911792 to [/data/ddna/neo4j/data/databases/graph.db/neostore.counts.db.b], from [/data/ddna/neo4j/data/databases/graph.db/neostore.counts.db.a].

Nigel Small

unread,

Sep 6, 2017, 7:19:46 AM9/6/17

to Neo4j

Have you tried with a smaller batch size?

Nigel

--
You received this message because you are subscribed to the Google Groups "Neo4j" group.
To unsubscribe from this group and stop receiving emails from it, send an email to neo4j+unsubscribe@googlegroups.com.
For more options, visit https://groups.google.com/d/optout.

Reply all

Reply to author

Forward

0 new messages