Can you try to run the same workload with a different driver? e.g. Javascript or Java ?
It seems that the client aborts the connection. Michael On Thu, Sep 7, 2017 at 4:52 AM, Ray Chengr <[email protected]> wrote: > Three findings: > 1) Tried to use bolt instead of http. The same error still happened. > 2) Using bolt resulted in slower Neo4j insertion by three times than http > in our busy insertion Neo4j-py2neo Python 3 case, i.e. the time period for > exactly the same input data took three times longer than using http. So, we > went back to http. > 3) See similar error message from neo4j.log, the part above neo4j.server > is different from the one I posted, but the part from neo4j.server is the > same: > 2017-09-07 00:24:50.554+0000 ERROR Failed to generate JSON output. > org.eclipse.jetty.io.EofException > at org.eclipse.jetty.io.ChannelEndPoint.flush( > ChannelEndPoint.java:192) > at org.eclipse.jetty.io.WriteFlusher.flush(WriteFlusher.java:408) > at org.eclipse.jetty.io.WriteFlusher.write(WriteFlusher.java:302) > at org.eclipse.jetty.io.AbstractEndPoint.write( > AbstractEndPoint.java:129) > at org.eclipse.jetty.server.HttpConnection$SendCallback. > process(HttpConnection.java:684) > at org.eclipse.jetty.util.IteratingCallback.processing( > IteratingCallback.java:246) > at org.eclipse.jetty.util.IteratingCallback.iterate( > IteratingCallback.java:208) > at org.eclipse.jetty.server.HttpConnection.send( > HttpConnection.java:480) > at org.eclipse.jetty.server.HttpChannel.sendResponse( > HttpChannel.java:768) > at org.eclipse.jetty.server.HttpChannel.write(HttpChannel.java:801) > at org.eclipse.jetty.server.HttpOutput.write(HttpOutput.java:142) > at org.eclipse.jetty.server.HttpOutput.write(HttpOutput.java:135) > 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:420) > 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$164/1266049947.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.io.IOException: Connection reset by peer > at sun.nio.ch.FileDispatcherImpl.writev0(Native Method) > at sun.nio.ch.SocketDispatcher.writev(SocketDispatcher.java:51) > at sun.nio.ch.IOUtil.write(IOUtil.java:148) > at sun.nio.ch.SocketChannelImpl.write(SocketChannelImpl.java:504) > at org.eclipse.jetty.io.ChannelEndPoint.flush( > ChannelEndPoint.java:172) > ... 55 more > 2017-09-07 00:24:50.838+0000 ERROR Unable to reply to request, because the > client has closed the connection (Broken pipe). > 2017-09-07 00:24:50.839+0000 ERROR Unable to reply to request, because the > client has closed the connection (Broken pipe). > > Any idea? > > Thanks, > Ray > > > > On Tuesday, September 5, 2017 at 7:23:52 PM UTC-7, [email protected] wrote: >> >> > Would you mind raising an issue at github.com/neo4j/neo4j ? >> Just raised an issue at github.com/neo4j/neo4j . >> > Can you try to use bolt instead of http? >> Trying bolt in our environment now. Will report back if timeout happens >> with bolt or does not happen after a couple of days. >> >> Thanks Michael. >> >> Ray >> >> On Saturday, September 2, 2017 at 9:22:39 PM UTC-7, Michael Hunger wrote: >>> >>> Would you mind raising an issue at github.com/neo4j/neo4j ? >>> Seems like a server side http issue. >>> >>> Can you try to use bolt instead of http? >>> >>> Michael >>> >>> >>> On Sat, Sep 2, 2017 at 2:08 AM, <[email protected]> wrote: >>> >>>> 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.ht >>>> tp.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.wri >>>> te(WebComponent.java:300) >>>> >>>> at com.sun.jersey.spi.container.ContainerResponse$CommittingOut >>>> putStream.write(ContainerResponse.java:135) >>>> >>>> at org.neo4j.server.rest.web.TransactionalService$InterruptingO >>>> utputStream.write(TransactionalService.java:283) >>>> >>>> at org.codehaus.jackson.impl.Utf8Generator._flushBuffer(Utf8Gen >>>> erator.java:1754) >>>> >>>> at org.codehaus.jackson.impl.Utf8Generator._writeFieldName(Utf8 >>>> Generator.java:432) >>>> >>>> at org.codehaus.jackson.impl.Utf8Generator.writeFieldName(Utf8G >>>> enerator.java:282) >>>> >>>> at org.codehaus.jackson.JsonGenerator.writeNumberField(JsonGene >>>> rator.java:956) >>>> >>>> at org.neo4j.server.rest.transactional.ExecutionResultSerialize >>>> r.writeStats(ExecutionResultSerializer.java:209) >>>> >>>> at org.neo4j.server.rest.transactional.ExecutionResultSerialize >>>> r.statementResult(ExecutionResultSerializer.java:115) >>>> >>>> at org.neo4j.server.rest.transactional.TransactionHandle.execut >>>> eStatements(TransactionHandle.java:316) >>>> >>>> at org.neo4j.server.rest.transactional.TransactionHandle. >>>> commit(TransactionHandle.java:150) >>>> >>>> at org.neo4j.server.rest.web.TransactionalService.lambda$execut >>>> eStatementsAndCommit$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.StreamingOutputProv >>>> ider.writeTo(StreamingOutputProvider.java:71) >>>> >>>> at com.sun.jersey.core.impl.provider.entity.StreamingOutputProv >>>> ider.writeTo(StreamingOutputProvider.java:57) >>>> >>>> at com.sun.jersey.spi.container.ContainerResponse.write(Contain >>>> erResponse.java:302) >>>> >>>> at com.sun.jersey.server.impl.application.WebApplicationImpl._h >>>> andleRequest(WebApplicationImpl.java:1510) >>>> >>>> at com.sun.jersey.server.impl.application.WebApplicationImpl.ha >>>> ndleRequest(WebApplicationImpl.java:1419) >>>> >>>> at com.sun.jersey.server.impl.application.WebApplicationImpl.ha >>>> ndleRequest(WebApplicationImpl.java:1409) >>>> >>>> at com.sun.jersey.spi.container.servlet.WebComponent.service(We >>>> bComponent.java:409) >>>> >>>> at com.sun.jersey.spi.container.servlet.ServletContainer.servic >>>> e(ServletContainer.java:558) >>>> >>>> at com.sun.jersey.spi.container.servlet.ServletContainer.servic >>>> e(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.doFilte >>>> r(ServletHandler.java:1669) >>>> >>>> at org.neo4j.server.rest.web.CollectUserAgentFilter.doFilter(Co >>>> llectUserAgentFilter.java:69) >>>> >>>> at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilte >>>> r(ServletHandler.java:1652) >>>> >>>> at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHan >>>> dler.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(ServletHand >>>> ler.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(Scoped >>>> Handler.java:141) >>>> >>>> at org.eclipse.jetty.server.handler.HandlerList.handle(HandlerL >>>> ist.java:52) >>>> >>>> at org.eclipse.jetty.server.handler.HandlerWrapper.handle(Handl >>>> erWrapper.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(HttpConne >>>> ction.java:257) >>>> >>>> at org.eclipse.jetty.io.AbstractConnection$2.run(AbstractConnec >>>> tion.java:540) >>>> >>>> at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(Queued >>>> ThreadPool.java:635) >>>> >>>> at org.eclipse.jetty.util.thread.QueuedThreadPool$3.run(QueuedT >>>> hreadPool.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(IdleTimeou >>>> t.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$ScheduledFu >>>> tureTask.access$201(ScheduledThreadPoolExecutor.java:180) >>>> >>>> at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFu >>>> tureTask.run(ScheduledThreadPoolExecutor.java:293) >>>> >>>> at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPool >>>> Executor.java:1142) >>>> >>>> at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoo >>>> lExecutor.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/databas >>>> es/graph.db/neostore.counts.db.a], from [/data/ddna/neo4j/data/databas >>>> es/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/databas >>>> es/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. >>>> >>> >>> -- 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.
