Hi,
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 in a long while we will get timeout error from Neo4j. Any idea why
this kind of timeout happens? Are there any way to prevent this timeout
errors from happening?
(If I increase transaction size to 8000 or 9000, timeout occurs more often,
at transaction size 4000 timeout happens only occasionally. But it we use
transaction size less than 4000, the insertion throughput is affected, and
we are not sure if timeout will not happen with transaction size 3000.)
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,886 - read_qosmos - INFO -
/opt/trendmicro/ddna/engine/venv-flow-processor/lib/python3.4/site-packages/py2neo/database/__init__.py,
line 1220: rs = resource.post({"statements": self.statements})
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/http.py,
line 203: response = self.__base.post(body, headers, **kwargs)
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 - INFO -
/opt/trendmicro/ddna/engine/venv-flow-processor/lib/python3.4/site-packages/py2neo/packages/httpstream/http.py,
line 362: raise SocketError(code, description, host_port=uri.host_port)
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].
Thanks!
Ray
--
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 [email protected].
For more options, visit https://groups.google.com/d/optout.
