Why neo4j suddenly all connection time out?

Singleton Chiu

unread,

Sep 12, 2015, 10:20:20 AM9/12/15

to Neo4j

I'm running v2.2.3 on linux, the server sometimes refuse any connection like this:

bin/neo4j-shell -port 8474
ERROR (-v for expanded information):
error during JRMP connection establishment; nested exception is:
java.net.SocketTimeoutException: Read timed out

My application which using Py2neo also got connection timeout:

[2015-09-12 15:21:06] [INFO] [32094:MainThread] [core:331 commit()] commit
[2015-09-12 15:21:06] [INFO] [32094:MainThread] [http:312 send()] > POST http://10.181.168.86:8474/db/data/transaction/commit [122]
[2015-09-12 15:21:20] [INFO] [32094:MainThread] [http:306 send()] ~ Reconnecting (timeout)
[2015-09-12 15:21:20] [INFO] [32094:MainThread] [http:312 send()] > POST http://10.181.168.86:8474/db/data/transaction/commit [122]
[2015-09-12 15:21:34] [ERROR] [32094:MainThread] [http:168 __init__()] ! SocketError: timed out

And the neo4j browser also down.:(

The top info:

28569 mylinuxname 20 0 31.2g 21g(RES) 1.1g S 8.6(cpu) 16.9(mem) 206:12.73

free -m:

total used free shared buffers cached
Mem: 129169 127970 1198 0 967 68919

and the console.log:

2015-09-11 15:39:52.306+0000 INFO [API] Remote interface ready and available at [http://0.0.0.0:8474/]
15:24:19.844 [qtp346100719-748140] WARN org.eclipse.jetty.http.HttpParser - badMessage: 400 Illegal character 0x0 in state=METHOD in 'JRMI\x00<<<\x02K>>>b/data/transactio...\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00' for HttpChannelOverHttp@3d2ec258{r=0,c=false,a=IDLE,uri=-}
15:31:49.788 [qtp346100719-164] WARN org.eclipse.jetty.http.HttpParser - badMessage: 400 Illegal character 0x0 in state=METHOD in 'JRMI\x00<<<\x02K>>>b/data/transactio...\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00' for HttpChannelOverHttp@26c4bd8c{r=0,c=false,a=IDLE,uri=-}
15:31:49.818 [qtp346100719-746043] WARN org.eclipse.jetty.http.HttpParser - badMessage: 400 Illegal character 0x0 in state=METHOD in 'JRMI\x00<<<\x02K>>>b/data/transactio...\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00' for HttpChannelOverHttp@68468866{r=0,c=false,a=IDLE,uri=-}
15:36:19.818 [qtp346100719-753367] WARN org.eclipse.jetty.http.HttpParser - badMessage: 400 Illegal character 0x0 in state=METHOD in 'JRMI\x00<<<\x02K>>>b/data/transactio...7ed9\\u4e86\\u5c0' for HttpChannelOverHttp@1aa7047a{r=0,c=false,a=IDLE,uri=-}

the messages.log:

2015-09-12 07:30:19.780+0000 INFO [o.n.s.r.t.TransactionRegistry]: Transaction with id 1312558 has been automatically rolled back.
2015-09-12 07:31:49.779+0000 INFO [o.n.s.r.t.TransactionRegistry]: Transaction with id 1297137 has been automatically rolled back.
2015-09-12 07:33:19.780+0000 INFO [o.n.s.r.t.TransactionRegistry]: Transaction with id 1277529 has been automatically rolled back.
2015-09-12 07:34:49.780+0000 INFO [o.n.s.r.t.TransactionRegistry]: Transaction with id 1344182 has been automatically rolled back.
2015-09-12 07:36:19.780+0000 INFO [o.n.s.r.t.TransactionRegistry]: Transaction with id 1302838 has been automatically rolled back.
2015-09-12 07:37:49.780+0000 INFO [o.n.s.r.t.TransactionRegistry]: Transaction with id 1309317 has been automatically rolled back.
2015-09-12 07:39:19.779+0000 INFO [o.n.s.r.t.TransactionRegistry]: Transaction with id 1325375 has been automatically rolled back.

If I restart the server can solve this problem, but I don't want to always restart it,

Can u help me? Thanks a lot!

Michael Hunger

unread,

Sep 12, 2015, 11:50:49 AM9/12/15

to ne...@googlegroups.com

Looks like sth on you network

What is in graph.db/messages.log?

Von meinem iPhone gesendet

--
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+un...@googlegroups.com.
For more options, visit https://groups.google.com/d/optout.

Singleton Chiu

unread,

Sep 12, 2015, 9:42:45 PM9/12/15

to Neo4j

the messages.log:

2015-09-12 07:30:19.780+0000 INFO [o.n.s.r.t.TransactionRegistry]: Transaction with id 1312558 has been automatically rolled back.
2015-09-12 07:31:49.779+0000 INFO [o.n.s.r.t.TransactionRegistry]: Transaction with id 1297137 has been automatically rolled back.
2015-09-12 07:33:19.780+0000 INFO [o.n.s.r.t.TransactionRegistry]: Transaction with id 1277529 has been automatically rolled back.
2015-09-12 07:34:49.780+0000 INFO [o.n.s.r.t.TransactionRegistry]: Transaction with id 1344182 has been automatically rolled back.
2015-09-12 07:36:19.780+0000 INFO [o.n.s.r.t.TransactionRegistry]: Transaction with id 1302838 has been automatically rolled back.
2015-09-12 07:37:49.780+0000 INFO [o.n.s.r.t.TransactionRegistry]: Transaction with id 1309317 has been automatically rolled back.
2015-09-12 07:39:19.779+0000 INFO [o.n.s.r.t.TransactionRegistry]: Transaction with id 1325375 has been automatically rolled back.

did it help?

Michael Hunger

unread,

Sep 12, 2015, 9:45:47 PM9/12/15

to ne...@googlegroups.com

No, it seems that your network connection to the server has problems.

Singleton Chiu

unread,

Sep 13, 2015, 10:39:51 PM9/13/15

to Neo4j

Hi Mike,

Thanks for your reply!

I tried local shell to connect my server,

bin/neo4j-shell -port 8474
ERROR (-v for expanded information):
error during JRMP connection establishment; nested exception is:
java.net.SocketTimeoutException: Read timed out

If it's a network connection problems,

the shell connection won't be error, right?

Michael Hunger

unread,

Sep 14, 2015, 1:12:03 AM9/14/15

to ne...@googlegroups.com

Why not?

Also you have to provide a host.

Singleton Chiu

unread,

Sep 15, 2015, 8:12:07 PM9/15/15

to Neo4j

Just Now, I encounter the same situation, here's the more specific info,

I would very much appreciate for your time.

neo4j v2.2.3 java1.7 on linux 64bit 96GB mem

node nums

Node ID 9058830
Property ID 80189638
Relationship ID 37459428

config:

org.neo4j.server.webserver.address=0.0.0.0 
org.neo4j.server.webserver.port=8474 
remote_shell_port=1390

Problem: REST API suddenly very slow response, situation for hours. When I restart the server, API return to normal.


$time wget localhost:8474/db/data
--2015-09-16 07:36:09--  http://localhost:8474/db/data
Resolving localhost... 127.0.0.1
Connecting to localhost|127.0.0.1|:8474... connected.
HTTP request sent, awaiting response... 302 Found
Location: http://localhost:8474/db/data/ [following]
--2015-09-16 07:36:43--  http://localhost:8474/db/data/
Reusing existing connection to localhost:8474.
HTTP request sent, awaiting response... 200 OK
Length: 730 [application/json]
Saving to: `index.html.1'

100%[===========================================================================================================================================>] 730         --.-K/s   in 0s

2015-09-16 07:36:43 (60.4 MB/s) - `index.html.1' saved [730/730]

real    0m34.547s
user    0m0.001s
sys     0m0.002s

See, it took 34s to get /db/data/

But, shell works just fine!



$bin/neo4j-shell -port 1390
Welcome to the Neo4j Shell! Enter 'help' for a list of commands
NOTE: Remote Neo4j graph database service 'shell' at port 1390

neo4j-sh (?)$ match (n:entity) return n limit 1;
+--------------------------------------------------------------------------------------------------------------------------------------------------------------------+
| n                                                                                                                                                                  |
+--------------------------------------------------------------------------------------------------------------------------------------------------------------------+
| Node[5161]{xxxxxxxx}
+--------------------------------------------------------------------------------------------------------------------------------------------------------------------+
1 row
19 ms

Here's network IO:




sar -n DEV 1 3
Average:        IFACE   rxpck/s   txpck/s   rxbyt/s   txbyt/s   rxcmp/s   txcmp/s  rxmcst/s
Average:           lo      9.15      9.15   3347.80   3347.80      0.00      0.00      0.00
Average:         eth0     33.56     32.20   2277.63   5508.14      0.00      0.00      0.68
Average:         eth1     35.93     36.95   2694.24   3387.80      0.00      0.00      0.00
Average:        bond0     69.15     69.15   4949.49   8895.93      0.00      0.00      0.68

And When I did nothing except restart the neo4j server, The REST API looks just fine:



$bin/neo4j restart
Stopping Neo4j Server [15300]................................................... done
Starting Neo4j Server...WARNING: not changing user
process [15742]... waiting for server to be ready............ OK.
http://localhost:8474/ is ready.

[xin.qiuqx@rsih16603.et2 /home/xxxx/neoserver]
$time wget localhost:8474/db/data
--2015-09-16 07:42:32--  http://localhost:8474/db/data
Resolving localhost... 127.0.0.1
Connecting to localhost|127.0.0.1|:8474... connected.
HTTP request sent, awaiting response... 302 Found
Location: http://localhost:8474/db/data/ [following]
--2015-09-16 07:42:32--  http://localhost:8474/db/data/
Reusing existing connection to localhost:8474.
HTTP request sent, awaiting response... 200 OK
Length: 730 [application/json]
Saving to: `index.html.2'

100%[===========================================================================================================================================>] 730         --.-K/s   in 0s

2015-09-16 07:42:32 (51.9 MB/s) - `index.html.2' saved [730/730]


real    0m0.032s
user    0m0.001s
sys     0m0.003s

See, only 32ms normal.

Here's my operation on the server before the REST API timeout:

I created more than 1 million nodes or relations by py2neo, The server REST API suddenly goes timeout... And it happened several times..

Flowing tail -100 log before restart:



log
tail -100 data/log/neo4j.0.0.log
INFO: Initiating Jersey application, version 'Jersey: 1.19 02/11/2015 03:25 AM'
Sep 11, 2015 11:39:51 PM com.sun.jersey.server.impl.application.WebApplicationImpl _initiate
INFO: Initiating Jersey application, version 'Jersey: 1.19 02/11/2015 03:25 AM'
Sep 11, 2015 11:39:51 PM com.sun.jersey.server.impl.application.WebApplicationImpl _initiate
INFO: Initiating Jersey application, version 'Jersey: 1.19 02/11/2015 03:25 AM'
Sep 12, 2015 4:40:51 PM com.sun.jersey.server.impl.application.WebApplicationImpl _initiate
INFO: Initiating Jersey application, version 'Jersey: 1.19 02/11/2015 03:25 AM'
Sep 12, 2015 4:40:52 PM com.sun.jersey.server.impl.application.WebApplicationImpl _initiate
INFO: Initiating Jersey application, version 'Jersey: 1.19 02/11/2015 03:25 AM'
Sep 12, 2015 4:40:52 PM com.sun.jersey.server.impl.application.WebApplicationImpl _initiate
INFO: Initiating Jersey application, version 'Jersey: 1.19 02/11/2015 03:25 AM'
Sep 14, 2015 1:32:30 PM com.sun.jersey.server.impl.application.WebApplicationImpl _initiate
INFO: Initiating Jersey application, version 'Jersey: 1.19 02/11/2015 03:25 AM'
Sep 14, 2015 1:32:30 PM com.sun.jersey.server.impl.application.WebApplicationImpl _initiate
INFO: Initiating Jersey application, version 'Jersey: 1.19 02/11/2015 03:25 AM'
Sep 14, 2015 1:32:30 PM com.sun.jersey.server.impl.application.WebApplicationImpl _initiate
INFO: Initiating Jersey application, version 'Jersey: 1.19 02/11/2015 03:25 AM'
Sep 14, 2015 2:45:55 PM com.sun.jersey.server.impl.application.WebApplicationImpl _initiate
INFO: Initiating Jersey application, version 'Jersey: 1.19 02/11/2015 03:25 AM'
Sep 14, 2015 2:45:56 PM com.sun.jersey.server.impl.application.WebApplicationImpl _initiate
INFO: Initiating Jersey application, version 'Jersey: 1.19 02/11/2015 03:25 AM'
Sep 14, 2015 2:45:56 PM com.sun.jersey.server.impl.application.WebApplicationImpl _initiate
INFO: Initiating Jersey application, version 'Jersey: 1.19 02/11/2015 03:25 AM'
Sep 14, 2015 11:29:14 PM com.sun.jersey.server.impl.application.WebApplicationImpl _initiate
INFO: Initiating Jersey application, version 'Jersey: 1.19 02/11/2015 03:25 AM'
Sep 14, 2015 11:29:15 PM com.sun.jersey.server.impl.application.WebApplicationImpl _initiate
INFO: Initiating Jersey application, version 'Jersey: 1.19 02/11/2015 03:25 AM'
Sep 14, 2015 11:29:15 PM com.sun.jersey.server.impl.application.WebApplicationImpl _initiate
INFO: Initiating Jersey application, version 'Jersey: 1.19 02/11/2015 03:25 AM'


$tail -100 data/graph.db/messages.log
        at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1125) [jetty-server-9.2.4.v20141103.jar:9.2.4.v20141103]
        at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:515) [jetty-servlet-9.2.4.v20141103.jar:9.2.4.v20141103]
        at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:185) [jetty-server-9.2.4.v20141103.jar:9.2.4.v20141103]
        at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1059) [jetty-server-9.2.4.v20141103.jar:9.2.4.v20141103]
        at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:141) [jetty-server-9.2.4.v20141103.jar:9.2.4.v20141103]
        at org.eclipse.jetty.server.handler.HandlerList.handle(HandlerList.java:52) [jetty-server-9.2.4.v20141103.jar:9.2.4.v20141103]
        at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:97) [jetty-server-9.2.4.v20141103.jar:9.2.4.v20141103]
        at org.eclipse.jetty.server.Server.handle(Server.java:497) [jetty-server-9.2.4.v20141103.jar:9.2.4.v20141103]
        at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:310) [jetty-server-9.2.4.v20141103.jar:9.2.4.v20141103]
        at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:248) [jetty-server-9.2.4.v20141103.jar:9.2.4.v20141103]
        at org.eclipse.jetty.io.AbstractConnection$2.run(AbstractConnection.java:540) [jetty-io-9.2.4.v20141103.jar:9.2.4.v20141103]
        at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:620) [jetty-util-9.2.4.v20141103.jar:9.2.4.v20141103]
        at org.eclipse.jetty.util.thread.QueuedThreadPool$3.run(QueuedThreadPool.java:540) [jetty-util-9.2.4.v20141103.jar:9.2.4.v20141103]
        at java.lang.Thread.run(Thread.java:745) [na:1.7.0_85]
2015-09-15 23:29:13.859+0000 ERROR [o.n.s.r.t.TransactionFacade]: Unable to reply to request, because the client has closed the connection (Broken pipe).
2015-09-15 23:29:13.859+0000 ERROR [o.n.s.r.t.TransactionFacade]: Unable to reply to request, because the client has closed the connection (Broken pipe).
2015-09-15 23:29:13.863+0000 ERROR [o.n.s.r.t.TransactionFacade]: Failed to generate JSON output.
org.codehaus.jackson.JsonGenerationException: Current context not an ARRAY but OBJECT
        at org.codehaus.jackson.impl.JsonGeneratorBase._reportError(JsonGeneratorBase.java:480) ~[jackson-core-asl-1.9.13.jar:1.9.13]
        at org.codehaus.jackson.impl.Utf8Generator.writeEndArray(Utf8Generator.java:354) ~[jackson-core-asl-1.9.13.jar:1.9.13]
        at org.neo4j.server.rest.transactional.ExecutionResultSerializer.writeRows(ExecutionResultSerializer.java:388) ~[neo4j-server-2.2.3.jar:2.2.3]
        at org.neo4j.server.rest.transactional.ExecutionResultSerializer.statementResult(ExecutionResultSerializer.java:108) ~[neo4j-server-2.2.3.jar:2.2.3]
        at org.neo4j.server.rest.transactional.TransactionHandle.executeStatements(TransactionHandle.java:329) [neo4j-server-2.2.3.jar:2.2.3]
        at org.neo4j.server.rest.transactional.TransactionHandle.commit(TransactionHandle.java:146) [neo4j-server-2.2.3.jar:2.2.3]
        at org.neo4j.server.rest.web.TransactionalService$2.write(TransactionalService.java:211) [neo4j-server-2.2.3.jar:2.2.3]
        at com.sun.jersey.core.impl.provider.entity.StreamingOutputProvider.writeTo(StreamingOutputProvider.java:71) [jersey-core-1.19.jar:1.19]
        at com.sun.jersey.core.impl.provider.entity.StreamingOutputProvider.writeTo(StreamingOutputProvider.java:57) [jersey-core-1.19.jar:1.19]
        at com.sun.jersey.spi.container.ContainerResponse.write(ContainerResponse.java:302) [jersey-server-1.19.jar:1.19]
        at com.sun.jersey.server.impl.application.WebApplicationImpl._handleRequest(WebApplicationImpl.java:1510) [jersey-server-1.19.jar:1.19]
        at com.sun.jersey.server.impl.application.WebApplicationImpl.handleRequest(WebApplicationImpl.java:1419) [jersey-server-1.19.jar:1.19]
        at com.sun.jersey.server.impl.application.WebApplicationImpl.handleRequest(WebApplicationImpl.java:1409) [jersey-server-1.19.jar:1.19]
        at com.sun.jersey.spi.container.servlet.WebComponent.service(WebComponent.java:409) [jersey-servlet-1.19.jar:1.19]
        at com.sun.jersey.spi.container.servlet.ServletContainer.service(ServletContainer.java:558) [jersey-servlet-1.19.jar:1.19]
        at com.sun.jersey.spi.container.servlet.ServletContainer.service(ServletContainer.java:733) [jersey-servlet-1.19.jar:1.19]
        at javax.servlet.http.HttpServlet.service(HttpServlet.java:790) [javax.servlet-api-3.1.0.jar:3.1.0]
        at org.eclipse.jetty.servlet.ServletHolder.handle(ServletHolder.java:800) [jetty-servlet-9.2.4.v20141103.jar:9.2.4.v20141103]
        at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:587) [jetty-servlet-9.2.4.v20141103.jar:9.2.4.v20141103]
        at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:221) [jetty-server-9.2.4.v20141103.jar:9.2.4.v20141103]
        at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1125) [jetty-server-9.2.4.v20141103.jar:9.2.4.v20141103]
        at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:515) [jetty-servlet-9.2.4.v20141103.jar:9.2.4.v20141103]
        at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:185) [jetty-server-9.2.4.v20141103.jar:9.2.4.v20141103]
        at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1059) [jetty-server-9.2.4.v20141103.jar:9.2.4.v20141103]
        at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:141) [jetty-server-9.2.4.v20141103.jar:9.2.4.v20141103]
        at org.eclipse.jetty.server.handler.HandlerList.handle(HandlerList.java:52) [jetty-server-9.2.4.v20141103.jar:9.2.4.v20141103]
        at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:97) [jetty-server-9.2.4.v20141103.jar:9.2.4.v20141103]
        at org.eclipse.jetty.server.Server.handle(Server.java:497) [jetty-server-9.2.4.v20141103.jar:9.2.4.v20141103]
        at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:310) [jetty-server-9.2.4.v20141103.jar:9.2.4.v20141103]
        at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:248) [jetty-server-9.2.4.v20141103.jar:9.2.4.v20141103]
        at org.eclipse.jetty.io.AbstractConnection$2.run(AbstractConnection.java:540) [jetty-io-9.2.4.v20141103.jar:9.2.4.v20141103]
        at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:620) [jetty-util-9.2.4.v20141103.jar:9.2.4.v20141103]
        at org.eclipse.jetty.util.thread.QueuedThreadPool$3.run(QueuedThreadPool.java:540) [jetty-util-9.2.4.v20141103.jar:9.2.4.v20141103]
        at java.lang.Thread.run(Thread.java:745) [na:1.7.0_85]
2015-09-15 23:29:13.863+0000 ERROR [o.n.s.r.t.TransactionFacade]: Unable to reply to request, because the client has closed the connection (Broken pipe).
2015-09-15 23:29:13.863+0000 ERROR [o.n.s.r.t.TransactionFacade]: Unable to reply to request, because the client has closed the connection (Broken pipe).
2015-09-15 23:29:13.867+0000 ERROR [o.n.s.r.t.TransactionFacade]: Failed to generate JSON output.
org.codehaus.jackson.JsonGenerationException: Current context not an ARRAY but OBJECT
        at org.codehaus.jackson.impl.JsonGeneratorBase._reportError(JsonGeneratorBase.java:480) ~[jackson-core-asl-1.9.13.jar:1.9.13]
        at org.codehaus.jackson.impl.Utf8Generator.writeEndArray(Utf8Generator.java:354) ~[jackson-core-asl-1.9.13.jar:1.9.13]
        at org.neo4j.server.rest.transactional.ExecutionResultSerializer.writeRows(ExecutionResultSerializer.java:388) ~[neo4j-server-2.2.3.jar:2.2.3]
        at org.neo4j.server.rest.transactional.ExecutionResultSerializer.statementResult(ExecutionResultSerializer.java:108) ~[neo4j-server-2.2.3.jar:2.2.3]
        at org.neo4j.server.rest.transactional.TransactionHandle.executeStatements(TransactionHandle.java:329) [neo4j-server-2.2.3.jar:2.2.3]
        at org.neo4j.server.rest.transactional.TransactionHandle.commit(TransactionHandle.java:146) [neo4j-server-2.2.3.jar:2.2.3]
        at org.neo4j.server.rest.web.TransactionalService$2.write(TransactionalService.java:211) [neo4j-server-2.2.3.jar:2.2.3]
        at com.sun.jersey.core.impl.provider.entity.StreamingOutputProvider.writeTo(StreamingOutputProvider.java:71) [jersey-core-1.19.jar:1.19]
        at com.sun.jersey.core.impl.provider.entity.StreamingOutputProvider.writeTo(StreamingOutputProvider.java:57) [jersey-core-1.19.jar:1.19]
        at com.sun.jersey.spi.container.ContainerResponse.write(ContainerResponse.java:302) [jersey-server-1.19.jar:1.19]
        at com.sun.jersey.server.impl.application.WebApplicationImpl._handleRequest(WebApplicationImpl.java:1510) [jersey-server-1.19.jar:1.19]
        at com.sun.jersey.server.impl.application.WebApplicationImpl.handleRequest(WebApplicationImpl.java:1419) [jersey-server-1.19.jar:1.19]
        at com.sun.jersey.server.impl.application.WebApplicationImpl.handleRequest(WebApplicationImpl.java:1409) [jersey-server-1.19.jar:1.19]
        at com.sun.jersey.spi.container.servlet.WebComponent.service(WebComponent.java:409) [jersey-servlet-1.19.jar:1.19]
        at com.sun.jersey.spi.container.servlet.ServletContainer.service(ServletContainer.java:558) [jersey-servlet-1.19.jar:1.19]
        at com.sun.jersey.spi.container.servlet.ServletContainer.service(ServletContainer.java:733) [jersey-servlet-1.19.jar:1.19]
        at javax.servlet.http.HttpServlet.service(HttpServlet.java:790) [javax.servlet-api-3.1.0.jar:3.1.0]
        at org.eclipse.jetty.servlet.ServletHolder.handle(ServletHolder.java:800) [jetty-servlet-9.2.4.v20141103.jar:9.2.4.v20141103]
        at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:587) [jetty-servlet-9.2.4.v20141103.jar:9.2.4.v20141103]
        at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:221) [jetty-server-9.2.4.v20141103.jar:9.2.4.v20141103]
        at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1125) [jetty-server-9.2.4.v20141103.jar:9.2.4.v20141103]
        at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:515) [jetty-servlet-9.2.4.v20141103.jar:9.2.4.v20141103]
        at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:185) [jetty-server-9.2.4.v20141103.jar:9.2.4.v20141103]
        at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1059) [jetty-server-9.2.4.v20141103.jar:9.2.4.v20141103]
        at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:141) [jetty-server-9.2.4.v20141103.jar:9.2.4.v20141103]
        at org.eclipse.jetty.server.handler.HandlerList.handle(HandlerList.java:52) [jetty-server-9.2.4.v20141103.jar:9.2.4.v20141103]
        at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:97) [jetty-server-9.2.4.v20141103.jar:9.2.4.v20141103]
        at org.eclipse.jetty.server.Server.handle(Server.java:497) [jetty-server-9.2.4.v20141103.jar:9.2.4.v20141103]
        at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:310) [jetty-server-9.2.4.v20141103.jar:9.2.4.v20141103]
        at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:248) [jetty-server-9.2.4.v20141103.jar:9.2.4.v20141103]
        at org.eclipse.jetty.io.AbstractConnection$2.run(AbstractConnection.java:540) [jetty-io-9.2.4.v20141103.jar:9.2.4.v20141103]
        at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:620) [jetty-util-9.2.4.v20141103.jar:9.2.4.v20141103]
        at org.eclipse.jetty.util.thread.QueuedThreadPool$3.run(QueuedThreadPool.java:540) [jetty-util-9.2.4.v20141103.jar:9.2.4.v20141103]
        at java.lang.Thread.run(Thread.java:745) [na:1.7.0_85]
2015-09-15 23:29:13.868+0000 ERROR [o.n.s.r.t.TransactionFacade]: Unable to reply to request, because the client has closed the connection (Broken pipe).
2015-09-15 23:29:13.868+0000 ERROR [o.n.s.r.t.TransactionFacade]: Unable to reply to request, because the client has closed the connection (Broken pipe).
2015-09-15 23:30:43.846+0000 INFO  [o.n.s.r.t.TransactionRegistry]: Transaction with id 4871017 has been automatically rolled back.
2015-09-15 23:32:13.846+0000 INFO  [o.n.s.r.t.TransactionRegistry]: Transaction with id 4871050 has been automatically rolled back.
2015-09-15 23:33:43.846+0000 INFO  [o.n.s.r.t.TransactionRegistry]: Transaction with id 4876089 has been automatically rolled back.
2015-09-15 23:33:43.846+0000 INFO  [o.n.s.r.t.TransactionRegistry]: Transaction with id 4876090 has been automatically rolled back.
2015-09-15 23:33:43.846+0000 INFO  [o.n.s.r.t.TransactionRegistry]: Transaction with id 4871080 has been automatically rolled back.
2015-09-15 23:33:43.846+0000 INFO  [o.n.s.r.t.TransactionRegistry]: Transaction with id 4876085 has been automatically rolled back.
2015-09-15 23:35:13.846+0000 INFO  [o.n.s.r.t.TransactionRegistry]: Transaction with id 4871109 has been automatically rolled back.
2015-09-15 23:36:43.846+0000 INFO  [o.n.s.r.t.TransactionRegistry]: Transaction with id 4871139 has been automatically rolled back.

Michael Hunger

unread,

Sep 15, 2015, 8:22:40 PM9/15/15

to ne...@googlegroups.com

Hmm,

1. first of all you should use the / at the end otherwise you also measure redirect time.

2. you should use accept header of application/json

as you don't want to measure html generation.

Please try that and report back, for me i does

time curl -L http://neo.jexp.de:12474/db/data/ 

{

  "extensions" : { },

  "node" : "http://neo.jexp.de:12474/db/data/node",

  "node_index" : "http://neo.jexp.de:12474/db/data/index/node",

  "relationship_index" : "http://neo.jexp.de:12474/db/data/index/relationship",

  "extensions_info" : "http://neo.jexp.de:12474/db/data/ext",

  "relationship_types" : "http://neo.jexp.de:12474/db/data/relationship/types",

  "batch" : "http://neo.jexp.de:12474/db/data/batch",

  "cypher" : "http://neo.jexp.de:12474/db/data/cypher",

  "indexes" : "http://neo.jexp.de:12474/db/data/schema/index",

  "constraints" : "http://neo.jexp.de:12474/db/data/schema/constraint",

  "transaction" : "http://neo.jexp.de:12474/db/data/transaction",

  "node_labels" : "http://neo.jexp.de:12474/db/data/labels",

  "neo4j_version" : "2.3-SNAPSHOT"

}

real	0m0.055s

user	0m0.004s

sys	0m0.004s

Singleton Chiu

unread,

Sep 15, 2015, 8:37:14 PM9/15/15

to Neo4j

Thanks for you quick response, I have already restart the server, I need to wait the problem situation, coz I can't re-product it.

I have checked the py2neo log:

[2015-09-16 07:27:19] [INFO] [28681:MainThread] [http:310 send()] > GET http://10.181.205.198:8474/db/data/ [2015-09-16 07:27:37] [INFO] [28681:MainThread] [http:306 send()] ~ Reconnecting (timeout)

Normally, it response 200 OK within 1 second.

Not only this REST API, but all encounter time out for hours, not one moment.

And I'm sure the IP and port are certainly right, coz It have run for long time, and after restart the neo4j server,

I get the log:

[2015-09-16 07:47:16] [INFO] [7557:MainThread] [http:310 send()] > GET http://10.181.205.198:8474/db/data/
[2015-09-16 07:47:16] [INFO] [7557:MainThread] [http:511 __init__()] < 200 OK [785]

How's that possible after server running normal for hours (have response millions of read/write REST API normally),

and suddenly goes time out? and seems not recover to normal...

...

Michael Hunger

unread,

Sep 15, 2015, 8:44:52 PM9/15/15

to ne...@googlegroups.com

It should definitely recover

do you run neo4j community or enterprise?

what are your settings?

perhaps you can pack together

conf/*

data/log/*

data/graph.db/messsages.log

for some analytics

it can also be that the heap memory is fully utilized by the 2nd level cache so it tries to make room by clearing memory, which can take a second or two but then should be back

so what you could also do is to enable gc-logging in neo4j-wrapper.conf and then also send the gc-logs together with the other information.

Singleton Chiu

unread,

Sep 16, 2015, 9:12:57 AM9/16/15

to Neo4j

I'm using the community version,

I have searched about my situation, and turned the gc log on.

And I found that the REST API got stuck during the Full GC.

29184.923: [GC 24510626K->23288671K(24643840K), 0.0907810 secs]
29185.932: [GC 24515487K->23310086K(24643840K), 0.1171710 secs]
29186.976: [GC 24536867K->23309125K(24643840K), 0.0917860 secs]
29187.988: [GC 24535807K->23322112K(24643840K), 0.1089120 secs]
29189.018: [GC 24548925K->23333210K(24643840K), 0.1097290 secs]
29190.054: [GC 24560025K->23350298K(24643840K), 0.1037740 secs]
29204.010: [Full GC 24573732K->23319822K(24643840K), 134.0548940 secs]
29338.275: [GC 23363153K(24643840K), 0.1082740 secs]
29367.432: [Full GC 24643839K->23328404K(24643840K), 133.3548790 secs]
29500.901: [GC 23366365K(24643840K), 0.1045400 secs]
29529.261: [Full GC 24643839K->23336254K(24643840K), 134.2712890 secs]
29663.733: [GC 23367649K(24643840K), 0.1222970 secs]
29691.674: [Full GC 24643839K->23343854K(24643840K), 133.6376480 secs]
29825.511: [GC 23369329K(24643840K), 0.1298200 secs]
29854.807: [Full GC 24643839K->23351726K(24643840K), 134.3462990 secs]
29989.364: [GC 23395476K(24643840K), 0.1952480 secs]
30018.853: [Full GC 24643839K->23359633K(24643840K), 133.7108280 secs]
30152.764: [GC 23395952K(24643840K), 0.1885450 secs]
30181.939: [Full GC

Exactly get stuck at the first Full GC.

I thought my problem is the jvm setting,

There are totally 96 GB mem, and my usage scenarios are lots of node,property,rel write and read, sometimes run a heavy time consuming cypher.

I think the heap size is not enough, so I change my setting into:

wrapper.java.additional=-XX:+UseConcMarkSweepGC
wrapper.java.additional=-XX:+CMSClassUnloadingEnabled
wrapper.java.additional=-XX:-OmitStackTraceInFastThrow
wrapper.java.additional=-XX:hashCode=5

wrapper.java.initmemory=50000
wrapper.java.maxmemory=50000

dbms.pagecache.memory=30g

Total Store Size 31.88 GiB

Is there a guide to set these settings?

The server now running for 6 hrs normally, with RES:26g, VIRT:61g

If it goes Full GC continuously or REST API get stuck again,

I'll come back to you with the packed info.

Many Thanks!

...

Michael Hunger

unread,

Sep 16, 2015, 9:28:59 AM9/16/15

to ne...@googlegroups.com

Set heap to at most 16-24G should be fine,

And switch to G1GC with -XX:+UseG1GC

instead of CMS.

CMS is not so good for larger heaps.

Depending on your store file-sizes (nodes + props + rels) set the pagecache to the sum of values, so in your case 35G

Which edition of Neo4j are you using?

Michael

Singleton Chiu

unread,

Sep 16, 2015, 7:24:02 PM9/16/15

to Neo4j

I'm using v2.2.3. community.

Sadly my server got timed out again.

Here I attached the conf and log: neo4j_info_pack.tar.gz as follows.

Could you pls help me analyse what's going on?

See the time out.

$time curl -L http://localhost:8474/db/data/
^@^@{
  "extensions" : { },
  "node" : "http://localhost:8474/db/data/node",
  "node_index" : "http://localhost:8474/db/data/index/node",
  "relationship_index" : "http://localhost:8474/db/data/index/relationship",
  "extensions_info" : "http://localhost:8474/db/data/ext",
  "relationship_types" : "http://localhost:8474/db/data/relationship/types",
  "batch" : "http://localhost:8474/db/data/batch",
  "cypher" : "http://localhost:8474/db/data/cypher",
  "indexes" : "http://localhost:8474/db/data/schema/index",
  "constraints" : "http://localhost:8474/db/data/schema/constraint",
  "transaction" : "http://localhost:8474/db/data/transaction",
  "node_labels" : "http://localhost:8474/db/data/labels",
  "neo4j_version" : "2.2.3"
}
real    2m57.123s
user    0m0.003s
sys     0m0.003s

RES: 57g used right now

To recovery the server, I'll take your suggest and restart.

Thanks again, I'll come back to you for further result.

...

neo4j_info_pack.tar.gz

Singleton Chiu

unread,

Sep 16, 2015, 7:37:39 PM9/16/15

to Neo4j

My settings right now:


wrapper.java.additional=-XX:+UseConcMarkSweepGC
#wrapper.java.additional=-XX:+CMSClassUnloadingEnabled
wrapper.java.additional=-XX:+UseG1GC
wrapper.java.additional=-XX:-OmitStackTraceInFastThrow
wrapper.java.additional=-XX:hashCode=5


# Uncomment the following lines to enable garbage collection logging
wrapper.java.additional=-Xloggc:data/log/neo4j-gc.log
wrapper.java.additional=-XX:+PrintGCDetails
wrapper.java.additional=-XX:+PrintGCDateStamps
wrapper.java.additional=-XX:+PrintGCApplicationStoppedTime
wrapper.java.additional=-XX:+PrintPromotionFailure
wrapper.java.additional=-XX:+PrintTenuringDistribution


# Java Heap Size: by default the Java heap size is dynamically
# calculated based on available system resources.
# Uncomment these lines to set specific initial and maximum
# heap size in MB.
wrapper.java.initmemory=20000
wrapper.java.maxmemory=20000

dbms.pagecache.memory=35g
cache_type=strong
keep_logical_logs=3 days

Is there anything wrong with the cache_type or keep_logical_logs setting?

I just wanna a great throughput, reduce time out moment, and hope the server recovery from stuck.

Thanks for your time again!

...

Message has been deleted

Singleton Chiu

unread,

Sep 16, 2015, 7:53:41 PM9/16/15

to Neo4j

My settings not right, coz server won't start, changed to :

#wrapper.java.additional=-XX:+UseConcMarkSweepGC
#wrapper.java.additional=-XX:+CMSClassUnloadingEnabled
wrapper.java.additional=-XX:+UseG1GC

Server started, I'll go and learn something about the java gc.

...

Michael Hunger

unread,

Sep 16, 2015, 8:10:01 PM9/16/15

to ne...@googlegroups.com

also cache-type strong will hold all nodes and relationships that were ever loaded in memory.

That means you have to have enough memory to hold everything (as java objects).

While that is fast if you have enough memory for all data it will churn memory and cause GC if you RAM is not enough.

I'd probably go for cache_type=weak

Michael

Singleton Chiu

unread,

Sep 16, 2015, 9:19:12 PM9/16/15

to Neo4j

Okay, when I set strong cache_type, my RAM > pagecache.mem(35g) > total disk store size: nodes,rels, properties(32g),

It won't trigger the GC, right?

...

Michael Hunger

unread,

Sep 17, 2015, 6:27:03 AM9/17/15

to ne...@googlegroups.com

the rels, and nodes are bigger in memory

from an old manual page:

http://neo4j.com/docs/1.8.3/configuration-caches.html#_object_cache

this is not up to date anymore but gives you an idea

that's why we removed the object cache in 2 .3

Heap memory usage

This table can be used to calculate how much memory the data in the object cache will occupy on a 64bit JVM:

Object	Size	Comment
Node	`344 B`	Size for each node (not counting its relationships or properties).
	`48 B`	Object overhead.
	`136 B`	Property storage (ArrayMap `48B`, HashMap `88B`).
	`136 B`	Relationship storage (ArrayMap `48B`, HashMap `88B`).
	`24 B`	Location of first / next set of relationships.
Relationship	`208 B`	Size for each relationship (not counting its properties).
	`48 B`	Object overhead.
	`136 B`	Property storage (ArrayMap `48B`, HashMap `88B`).
Property	`116 B`	Size for each property of a node or relationship.
	`32 B`	Data element — allows for transactional modification and keeps track of on disk location.
	`48 B`	Entry in the hash table where it is stored.
	`12 B`	Space used in hash table, accounts for normal fill ratio.
	`24 B`	Property key index.
Relationships	`108 B`	Size for each relationship type for a node that has a relationship of that type.
	`48 B`	Collection of the relationships of this type.
	`48 B`	Entry in the hash table where it is stored.
	`12 B`	Space used in hash table, accounts for normal fill ratio.
Relationships	`8 B`	Space used by each relationship related to a particular node (both incoming and outgoing).
Primitive	`24 B`	Size of a primitive property value.
String	`64+B`	Size of a string property value. `64 + 2len(string) B` (64 bytes, plus two bytes for each character in the string).*

Reply all

Reply to author

Forward