Closed bsquire0128 closed 5 years ago
When it finally got past the sequential union find portion it seems to have gotten stuck here:
2019-04-11 14:08:14.211+0000 WARN [o.n.k.i.c.VmPauseMonitorComponent] Detected VM stop-the-world pause: {pauseTime=95995, gcTime=295623, gcCount=3}
2019-04-11 14:08:14.212+0000 INFO [o.n.k.i.p.Procedures] [neo4j.BoltWorker-5 [bolt] [/127.0.0.1:44146] ] EXPORT 9%
2019-04-11 14:09:37.185+0000 WARN [o.n.k.i.c.VmPauseMonitorComponent] Detected VM stop-the-world pause: {pauseTime=82874, gcTime=165927, gcCount=2}
2019-04-11 14:09:37.185+0000 INFO [o.n.k.i.p.Procedures] [neo4j.BoltWorker-5 [bolt] [/127.0.0.1:44146] ] EXPORT 9%
2019-04-11 14:10:39.375+0000 WARN [o.n.k.i.c.VmPauseMonitorComponent] Detected VM stop-the-world pause: {pauseTime=62089, gcTime=124358, gcCount=2}
2019-04-11 14:10:39.375+0000 INFO [o.n.k.i.p.Procedures] [neo4j.BoltWorker-5 [bolt] [/127.0.0.1:44146] ] EXPORT 9%
2019-04-11 14:12:00.420+0000 WARN [o.n.k.i.c.VmPauseMonitorComponent] Detected VM stop-the-world pause: {pauseTime=80945, gcTime=162071, gcCount=2}
2019-04-11 14:12:00.420+0000 INFO [o.n.k.i.p.Procedures] [neo4j.BoltWorker-5 [bolt] [/127.0.0.1:44146] ] EXPORT 9%
2019-04-11 14:13:37.764+0000 WARN [o.n.k.i.c.VmPauseMonitorComponent] Detected VM stop-the-world pause: {pauseTime=97244, gcTime=194666, gcCount=2}
2019-04-11 14:13:37.764+0000 INFO [o.n.k.i.p.Procedures] [neo4j.BoltWorker-5 [bolt] [/127.0.0.1:44146] ] EXPORT 9%
2019-04-11 14:14:53.990+0000 WARN [o.n.k.i.c.VmPauseMonitorComponent] Detected VM stop-the-world pause: {pauseTime=76125, gcTime=152432, gcCount=2}
2019-04-11 14:14:53.990+0000 INFO [o.n.k.i.p.Procedures] [neo4j.BoltWorker-5 [bolt] [/127.0.0.1:44146] ] EXPORT 9%
2019-04-11 14:16:30.666+0000 WARN [o.n.k.i.c.VmPauseMonitorComponent] Detected VM stop-the-world pause: {pauseTime=96576, gcTime=96666, gcCount=1}
2019-04-11 14:16:30.666+0000 INFO [o.n.k.i.p.Procedures] [neo4j.BoltWorker-5 [bolt] [/127.0.0.1:44146] ] EXPORT 9%
2019-04-11 14:17:18.551+0000 WARN [o.n.k.i.c.VmPauseMonitorComponent] Detected VM stop-the-world pause: {pauseTime=47785, gcTime=192417, gcCount=3}
2019-04-11 14:17:18.551+0000 INFO [o.n.k.i.p.Procedures] [neo4j.BoltWorker-5 [bolt] [/127.0.0.1:44146] ] EXPORT 9%
2019-04-11 14:19:08.414+0000 WARN [o.n.k.i.c.VmPauseMonitorComponent] Detected VM stop-the-world pause: {pauseTime=109762, gcTime=109851, gcCount=1}
2019-04-11 14:19:08.414+0000 INFO [o.n.k.i.p.Procedures] [neo4j.BoltWorker-5 [bolt] [/127.0.0.1:44146] ] EXPORT 9%
2019-04-11 14:21:46.321+0000 WARN [o.n.k.i.c.VmPauseMonitorComponent] Detected VM stop-the-world pause: {pauseTime=157807, gcTime=267747, gcCount=2}
2019-04-11 14:21:46.321+0000 INFO [o.n.k.i.p.Procedures] [neo4j.BoltWorker-5 [bolt] [/127.0.0.1:44146] ] EXPORT 9%
2019-04-11 14:23:02.681+0000 WARN [o.n.k.i.c.VmPauseMonitorComponent] Detected VM stop-the-world pause: {pauseTime=76259, gcTime=310594, gcCount=3}
2019-04-11 14:23:02.681+0000 INFO [o.n.k.i.p.Procedures] [neo4j.BoltWorker-5 [bolt] [/127.0.0.1:44146] ] EXPORT 9%
2019-04-11 14:25:29.645+0000 WARN [o.n.k.i.c.VmPauseMonitorComponent] Detected VM stop-the-world pause: {pauseTime=146863, gcTime=293906, gcCount=2}
2019-04-11 14:25:29.645+0000 INFO [o.n.k.i.p.Procedures] [neo4j.BoltWorker-5 [bolt] [/127.0.0.1:44146] ] EXPORT 9%
2019-04-11 14:26:31.325+0000 WARN [o.n.k.i.c.VmPauseMonitorComponent] Detected VM stop-the-world pause: {pauseTime=61580, gcTime=123339, gcCount=2}
2019-04-11 14:26:31.326+0000 INFO [o.n.k.i.p.Procedures] [neo4j.BoltWorker-5 [bolt] [/127.0.0.1:44146] ] EXPORT 9%
2019-04-11 14:28:11.198+0000 WARN [o.n.k.i.c.VmPauseMonitorComponent] Detected VM stop-the-world pause: {pauseTime=99772, gcTime=199726, gcCount=2}
2019-04-11 14:28:11.198+0000 INFO [o.n.k.i.p.Procedures] [neo4j.BoltWorker-5 [bolt] [/127.0.0.1:44146] ] EXPORT 9%
2019-04-11 14:29:46.196+0000 WARN [o.n.k.i.c.VmPauseMonitorComponent] Detected VM stop-the-world pause: {pauseTime=94898, gcTime=94988, gcCount=1}
2019-04-11 14:29:46.197+0000 INFO [o.n.k.i.p.Procedures] [neo4j.BoltWorker-5 [bolt] [/127.0.0.1:44146] ] EXPORT 9%
2019-04-11 14:31:05.830+0000 WARN [o.n.k.i.c.VmPauseMonitorComponent] Detected VM stop-the-world pause: {pauseTime=79533, gcTime=174611, gcCount=2}
2019-04-11 14:31:05.830+0000 INFO [o.n.k.i.p.Procedures] [neo4j.BoltWorker-5 [bolt] [/127.0.0.1:44146] ] EXPORT 9%
2019-04-11 14:32:34.541+0000 WARN [o.n.k.i.c.VmPauseMonitorComponent] Detected VM stop-the-world pause: {pauseTime=88611, gcTime=168322, gcCount=2}
2019-04-11 14:33:22.105+0000 INFO [o.n.k.i.p.Procedures] [neo4j.BoltWorker-5 [bolt] [/127.0.0.1:44146] ] EXPORT 9%
2019-04-11 14:33:22.105+0000 WARN [o.n.k.i.c.VmPauseMonitorComponent] Detected VM stop-the-world pause: {pauseTime=47463, gcTime=183807, gcCount=3}
2019-04-11 14:35:42.713+0000 INFO [o.n.k.i.p.Procedures] [neo4j.BoltWorker-5 [bolt] [/127.0.0.1:44146] ] EXPORT 9%
2019-04-11 14:35:42.714+0000 WARN [o.n.k.i.c.VmPauseMonitorComponent] Detected VM stop-the-world pause: {pauseTime=140508, gcTime=281193, gcCount=2}
2019-04-11 14:35:42.714+0000 INFO [o.n.k.i.p.Procedures] [neo4j.BoltWorker-5 [bolt] [/127.0.0.1:44146] ] EXPORT 9%
2019-04-11 14:36:59.218+0000 WARN [o.n.k.i.c.VmPauseMonitorComponent] Detected VM stop-the-world pause: {pauseTime=76404, gcTime=152989, gcCount=2}
2019-04-11 14:36:59.218+0000 INFO [o.n.k.i.p.Procedures] [neo4j.BoltWorker-5 [bolt] [/127.0.0.1:44146] ] EXPORT 9%
2019-04-11 14:38:25.257+0000 WARN [o.n.k.i.c.VmPauseMonitorComponent] Detected VM stop-the-world pause: {pauseTime=85939, gcTime=86028, gcCount=1}
2019-04-11 14:38:25.258+0000 INFO [o.n.k.i.p.Procedures] [neo4j.BoltWorker-5 [bolt] [/127.0.0.1:44146] ] EXPORT 9%
2019-04-11 14:40:25.852+0000 WARN [o.n.k.i.c.VmPauseMonitorComponent] Detected VM stop-the-world pause: {pauseTime=120495, gcTime=327196, gcCount=3}
also tried Latest release and G1GC: Config: Heap 410 GB PC: 30 GB GC - G1GC
cmd: CALL algo.unionFind(null, 'OBSERVED_WITH', {write:true, graph:'huge', partitionProperty:"community",concurrency:3}) YIELD nodes, setCount, loadMillis, computeMillis, writeMillis,p1, p5,p10,p25,p50,p75,p90,p95,p100;
Neo4j graph algorithms 3.5.4 Neo4j Enterprise 3.5.3 Running from cypher-shell Linux - Fedora JVM 1.8 64 CPU 488 Ram Large graph of 4.5 Billion Nodes
2019-04-11 16:56:30.130+0000 INFO [o.n.k.i.p.Procedures] [node-store-scan-2] LOADING 8% Memory usage: 33 GiB 2019-04-11 16:56:31.491+0000 INFO [o.n.k.i.i.l.NativeLabelScanStore] Label index cleanup job finished: Number of pages visited: 319084, Number of cleaned crashed pointers: 0, Time spent: 6s 948ms 2019-04-11 16:56:31.492+0000 INFO [o.n.k.i.i.l.NativeLabelScanStore] Label index cleanup job closed 2019-04-11 16:56:41.693+0000 INFO [o.n.k.i.p.Procedures] [node-store-scan-1] LOADING 9% Memory usage: 33 GiB 2019-04-11 16:56:46.669+0000 INFO [o.n.k.i.p.PageCacheWarmer] Page cache warmup completed. 3916764 pages loaded. Duration: 11m 9s 876ms. 2019-04-11 16:56:52.999+0000 INFO [o.n.k.i.p.Procedures] [node-store-scan-0] LOADING 11% Memory usage: 33 GiB 2019-04-11 16:57:09.448+0000 INFO [o.n.k.i.p.Procedures] [node-store-scan-2] LOADING 14% Memory usage: 33 GiB 2019-04-11 16:57:26.500+0000 INFO [o.n.k.i.p.Procedures] [node-store-scan-1] LOADING 18% Memory usage: 33 GiB 2019-04-11 16:57:39.991+0000 INFO [o.n.k.i.p.Procedures] [node-store-scan-0] LOADING 19% Memory usage: 33 GiB 2019-04-11 16:57:55.888+0000 INFO [o.n.k.i.p.Procedures] [node-store-scan-1] LOADING 23% Memory usage: 33 GiB 2019-04-11 16:58:13.290+0000 INFO [o.n.k.i.p.Procedures] [node-store-scan-2] LOADING 26% Memory usage: 33 GiB 2019-04-11 16:58:29.816+0000 INFO [o.n.k.i.p.Procedures] [node-store-scan-2] LOADING 29% Memory usage: 33 GiB 2019-04-11 16:58:47.006+0000 INFO [o.n.k.i.p.Procedures] [node-store-scan-0] LOADING 33% Memory usage: 33 GiB 2019-04-11 16:59:03.721+0000 INFO [o.n.k.i.p.Procedures] [node-store-scan-2] LOADING 36% Memory usage: 33 GiB 2019-04-11 16:59:19.724+0000 INFO [o.n.k.i.p.Procedures] [node-store-scan-2] LOADING 39% Memory usage: 33 GiB 2019-04-11 16:59:36.309+0000 INFO [o.n.k.i.p.Procedures] [node-store-scan-1] LOADING 42% Memory usage: 33 GiB 2019-04-11 16:59:49.866+0000 WARN [o.n.k.i.c.VmPauseMonitorComponent] Detected VM stop-the-world pause: {pauseTime=182, gcTime=257, gcCount=1} 2019-04-11 16:59:52.546+0000 INFO [o.n.k.i.p.Procedures] [node-store-scan-1] LOADING 46% Memory usage: 33 GiB 2019-04-11 17:00:13.528+0000 INFO [o.n.k.i.p.Procedures] [node-store-scan-0] LOADING 49% Memory usage: 33 GiB 2019-04-11 17:00:31.974+0000 INFO [o.n.k.i.p.Procedures] [node-store-scan-2] LOADING 52% Memory usage: 33 GiB 2019-04-11 17:00:48.656+0000 INFO [o.n.k.i.p.Procedures] Node Store Scan: Imported 4,556,334,204 records from 63 GiB (68,345,279,730 bytes); took 601.116 s, 7,579,789.66 Nodes/s, 108 MiB/s (113,697,288 bytes/s) (per thread: 2,526,596.55 Nodes/s, 36 MiB/s (37,899,096 bytes/s))
More of the same with the concurrency set to 3 as stated above:
2019-04-11 17:33:19.349+0000 INFO [o.n.k.i.p.Procedures] Relationship Store Scan: Imported 3,562,523,363 records from 232 GiB (249,670,671,360 bytes); took 1905.818 s, 1,869,288.55 Relationships/s, 124 MiB/s (131,004,482 bytes/s) (per thread: 623,096.18 Relationships/s, 41 MiB/s (43,668,160 bytes/s))
2019-04-11 17:33:19.372+0000 INFO [o.n.k.i.p.Procedures] [neo4j.BoltWorker-1 [bolt] [/127.0.0.1:44220] ] LOADING 100% Memory usage: 166 GiB
2019-04-11 17:33:21.644+0000 WARN [o.n.k.i.c.VmPauseMonitorComponent] Detected VM stop-the-world pause: {pauseTime=1360, gcTime=1414, gcCount=1}
2019-04-11 17:33:23.888+0000 WARN [o.n.k.i.c.VmPauseMonitorComponent] Detected VM stop-the-world pause: {pauseTime=941, gcTime=956, gcCount=1}
2019-04-11 17:33:26.433+0000 WARN [o.n.k.i.c.VmPauseMonitorComponent] Detected VM stop-the-world pause: {pauseTime=1242, gcTime=1282, gcCount=1}
2019-04-11 17:33:28.237+0000 WARN [o.n.k.i.c.VmPauseMonitorComponent] Detected VM stop-the-world pause: {pauseTime=100, gcTime=0, gcCount=0}
2019-04-11 17:33:29.170+0000 WARN [o.n.k.i.c.VmPauseMonitorComponent] Detected VM stop-the-world pause: {pauseTime=1233, gcTime=907, gcCount=1}
2019-04-11 17:33:31.468+0000 WARN [o.n.k.i.c.VmPauseMonitorComponent] Detected VM stop-the-world pause: {pauseTime=895, gcTime=921, gcCount=1}
2019-04-11 17:33:33.808+0000 WARN [o.n.k.i.c.VmPauseMonitorComponent] Detected VM stop-the-world pause: {pauseTime=837, gcTime=913, gcCount=1}
2019-04-11 17:33:36.268+0000 WARN [o.n.k.i.c.VmPauseMonitorComponent] Detected VM stop-the-world pause: {pauseTime=956, gcTime=1025, gcCount=1}
2019-04-11 17:33:39.390+0000 WARN [o.n.k.i.c.VmPauseMonitorComponent] Detected VM stop-the-world pause: {pauseTime=1285, gcTime=1348, gcCount=1}
2019-04-11 17:33:43.175+0000 WARN [o.n.k.i.c.VmPauseMonitorComponent] Detected VM stop-the-world pause: {pauseTime=1379, gcTime=1312, gcCount=1}
2019-04-11 17:33:46.079+0000 WARN [o.n.k.i.c.VmPauseMonitorComponent] Detected VM stop-the-world pause: {pauseTime=1301, gcTime=1327, gcCount=1}
2019-04-11 17:33:49.212+0000 WARN [o.n.k.i.c.VmPauseMonitorComponent] Detected VM stop-the-world pause: {pauseTime=1329, gcTime=1339, gcCount=1}
2019-04-11 17:33:50.661+0000 WARN [o.n.k.i.c.VmPauseMonitorComponent] Detected VM stop-the-world pause: {pauseTime=101, gcTime=0, gcCount=0}
2019-04-11 17:33:58.722+0000 WARN [o.n.k.i.c.VmPauseMonitorComponent] Detected VM stop-the-world pause: {pauseTime=4053, gcTime=0, gcCount=0}
2019-04-11 17:34:01.158+0000 WARN [o.n.k.i.c.VmPauseMonitorComponent] Detected VM stop-the-world pause: {pauseTime=1033, gcTime=1079, gcCount=1}
2019-04-11 17:34:11.752+0000 WARN [o.n.k.i.c.VmPauseMonitorComponent] Detected VM stop-the-world pause: {pauseTime=182, gcTime=0, gcCount=0}
2019-04-11 17:34:16.556+0000 INFO [o.n.k.i.p.Procedures] [algo-25] CC(HugeParallelUnionFindQueue) 66%
2019-04-11 17:41:17.898+0000 WARN [o.n.k.i.c.VmPauseMonitorComponent] Detected VM stop-the-world pause: {pauseTime=176, gcTime=0, gcCount=0}
2019-04-11 17:54:07.698+0000 WARN [o.n.k.i.c.VmPauseMonitorComponent] Detected VM stop-the-world pause: {pauseTime=134, gcTime=0, gcCount=0}
2019-04-11 17:57:59.774+0000 INFO [o.n.k.i.p.Procedures] [algo-24] CC(HugeParallelUnionFindQueue) 33%
2019-04-11 18:07:29.546+0000 WARN [o.n.k.i.c.VmPauseMonitorComponent] Detected VM stop-the-world pause: {pauseTime=161, gcTime=0, gcCount=0}
2019-04-11 18:09:43.001+0000 WARN [o.n.b.r.MetricsReportingBoltConnection] The client is unauthorized due to authentication failure.
2019-04-11 18:24:05.771+0000 WARN [o.n.k.i.c.VmPauseMonitorComponent] Detected VM stop-the-world pause: {pauseTime=177, gcTime=0, gcCount=0}
2019-04-11 18:33:43.614+0000 WARN [o.n.b.r.MetricsReportingBoltConnection] The client is unauthorized due to authentication failure.
2019-04-11 18:49:11.254+0000 WARN [o.n.k.i.c.VmPauseMonitorComponent] Detected VM stop-the-world pause: {pauseTime=137, gcTime=0, gcCount=0}
2019-04-11 18:51:52.158+0000 WARN [o.n.k.i.c.VmPauseMonitorComponent] Detected VM stop-the-world pause: {pauseTime=328, gcTime=341, gcCount=1}
2019-04-11 18:53:00.213+0000 WARN [o.n.k.i.c.VmPauseMonitorComponent] Detected VM stop-the-world pause: {pauseTime=633, gcTime=618, gcCount=1}
2019-04-11 18:53:50.767+0000 WARN [o.n.k.i.c.VmPauseMonitorComponent] Detected VM stop-the-world pause: {pauseTime=668, gcTime=731, gcCount=1}
2019-04-11 18:54:25.922+0000 WARN [o.n.k.i.c.VmPauseMonitorComponent] Detected VM stop-the-world pause: {pauseTime=795, gcTime=853, gcCount=1}
2019-04-11 18:54:59.344+0000 WARN [o.n.k.i.c.VmPauseMonitorComponent] Detected VM stop-the-world pause: {pauseTime=864, gcTime=921, gcCount=1}
2019-04-11 18:55:32.566+0000 WARN [o.n.k.i.c.VmPauseMonitorComponent] Detected VM stop-the-world pause: {pauseTime=164, gcTime=204, gcCount=1}
2019-04-11 18:56:40.511+0000 WARN [o.n.k.i.c.VmPauseMonitorComponent] Detected VM stop-the-world pause: {pauseTime=199, gcTime=0, gcCount=0}
2019-04-11 19:00:57.792+0000 ERROR [o.n.b.t.p.HouseKeeper] Fatal error occurred when handling a client connection: [id: 0x3f05a9d7, L:/10.76.130.128:7687 - R:/10.186.56.65:57371] readAddress(..) failed: Connection timed out
io.netty.channel.unix.Errors$NativeIoException: readAddress(..) failed: Connection timed out
at io.netty.channel.unix.Errors.newIOException(Errors.java:122)
at io.netty.channel.unix.Errors.ioResult(Errors.java:146)
at io.netty.channel.unix.FileDescriptor.readAddress(FileDescriptor.java:178)
at io.netty.channel.epoll.AbstractEpollChannel.doReadBytes(AbstractEpollChannel.java:343)
at io.netty.channel.epoll.AbstractEpollStreamChannel$EpollStreamUnsafe.epollInReady(AbstractEpollStreamChannel.java:785)
at io.netty.channel.epoll.EpollEventLoop.processReady(EpollEventLoop.java:433)
at io.netty.channel.epoll.EpollEventLoop.run(EpollEventLoop.java:330)
at io.netty.util.concurrent.SingleThreadEventExecutor$5.run(SingleThreadEventExecutor.java:909)
at java.lang.Thread.run(Thread.java:748)
2019-04-11 19:00:57.798+0000 ERROR [o.n.b.t.p.HouseKeeper] Fatal error occurred when handling a client connection: [id: 0xfd93e9e1, L:/10.76.130.128:7687 - R:/10.186.56.65:57370] readAddress(..) failed: Connection timed out
io.netty.channel.unix.Errors$NativeIoException: readAddress(..) failed: Connection timed out
at io.netty.channel.unix.Errors.newIOException(Errors.java:122)
at io.netty.channel.unix.Errors.ioResult(Errors.java:146)
at io.netty.channel.unix.FileDescriptor.readAddress(FileDescriptor.java:178)
at io.netty.channel.epoll.AbstractEpollChannel.doReadBytes(AbstractEpollChannel.java:343)
at io.netty.channel.epoll.AbstractEpollStreamChannel$EpollStreamUnsafe.epollInReady(AbstractEpollStreamChannel.java:785)
at io.netty.channel.epoll.EpollEventLoop.processReady(EpollEventLoop.java:433)
at io.netty.channel.epoll.EpollEventLoop.run(EpollEventLoop.java:330)
at io.netty.util.concurrent.SingleThreadEventExecutor$5.run(SingleThreadEventExecutor.java:909)
at java.lang.Thread.run(Thread.java:748)
2019-04-11 19:07:43.242+0000 ERROR [o.n.b.t.p.HouseKeeper] Fatal error occurred when handling a client connection: [id: 0x6f16051b, L:/10.76.130.128:7687 - R:/10.186.56.65:57369] readAddress(..) failed: Connection timed out
io.netty.channel.unix.Errors$NativeIoException: readAddress(..) failed: Connection timed out
at io.netty.channel.unix.Errors.newIOException(Errors.java:122)
at io.netty.channel.unix.Errors.ioResult(Errors.java:146)
at io.netty.channel.unix.FileDescriptor.readAddress(FileDescriptor.java:178)
at io.netty.channel.epoll.AbstractEpollChannel.doReadBytes(AbstractEpollChannel.java:343)
at io.netty.channel.epoll.AbstractEpollStreamChannel$EpollStreamUnsafe.epollInReady(AbstractEpollStreamChannel.java:785)
at io.netty.channel.epoll.EpollEventLoop.processReady(EpollEventLoop.java:433)
at io.netty.channel.epoll.EpollEventLoop.run(EpollEventLoop.java:330)
at io.netty.util.concurrent.SingleThreadEventExecutor$5.run(SingleThreadEventExecutor.java:909)
at java.lang.Thread.run(Thread.java:748)
2019-04-11 19:20:09.190+0000 INFO [o.n.k.i.p.Procedures] [algo-31] EXPORT 0%
2019-04-11 19:20:18.863+0000 INFO [o.n.k.NeoStoreDataSource] Rotated to transaction log [/var/lib/neo4j/data/databases/graph.db/neostore.transaction.db.1] version=1, last transaction in previous log=61
2019-04-11 19:20:19.191+0000 INFO [o.n.k.i.p.Procedures] [algo-49] EXPORT 0%
2019-04-11 19:20:19.379+0000 INFO [o.n.k.i.t.l.c.CheckPointerImpl] Checkpoint triggered by scheduler for time threshold @ txId: 61 checkpoint started...
2019-04-11 19:20:19.779+0000 INFO [o.n.k.i.s.c.CountsTracker] Rotated counts store at transaction 62 to [/var/lib/neo4j/data/databases/graph.db/neostore.counts.db.b], from [/var/lib/neo4j/data/databases/graph.db/neostore.counts.db.a].
2019-04-11 19:20:28.264+0000 INFO [o.n.k.NeoStoreDataSource] Rotated to transaction log [/var/lib/neo4j/data/databases/graph.db/neostore.transaction.db.2] version=2, last transaction in previous log=80
2019-04-11 19:20:28.740+0000 INFO [o.n.k.i.t.l.c.CheckPointerImpl] Checkpoint triggered by scheduler for time threshold @ txId: 61 checkpoint completed in 9s 361ms
2019-04-11 19:20:28.750+0000 INFO [o.n.k.i.t.l.p.LogPruningImpl] No log version pruned, last checkpoint was made in version 0
2019-04-11 19:20:29.192+0000 INFO [o.n.k.i.p.Procedures] [algo-5] EXPORT 0%
2019-04-11 19:20:37.979+0000 INFO [o.n.k.NeoStoreDataSource] Rotated to transaction log [/var/lib/neo4j/data/databases/graph.db/neostore.transaction.db.3] version=3, last transaction in previous log=99
2019-04-11 19:20:39.193+0000 INFO [o.n.k.i.p.Procedures] [algo-25] EXPORT 0%
2019-04-11 19:20:47.342+0000 INFO [o.n.k.NeoStoreDataSource] Rotated to transaction log [/var/lib/neo4j/data/databases/graph.db/neostore.transaction.db.4] version=4, last transaction in previous log=118
2019-04-11 19:20:49.194+0000 INFO [o.n.k.i.p.Procedures] [algo-44] EXPORT 0%
2019-04-11 19:20:56.377+0000 INFO [o.n.k.NeoStoreDataSource] Rotated to transaction log [/var/lib/neo4j/data/databases/graph.db/neostore.transaction.db.5] version=5, last transaction in previous log=137
2019-04-11 19:20:59.195+0000 INFO [o.n.k.i.p.Procedures] [algo-2] EXPORT 0%
2019-04-11 19:21:05.852+0000 INFO [o.n.k.NeoStoreDataSource] Rotated to transaction log [/var/lib/neo4j/data/databases/graph.db/neostore.transaction.db.6] version=6, last transaction in previous log=156
2019-04-11 19:21:09.196+0000 INFO [o.n.k.i.p.Procedures] [algo-7] EXPORT 0%
2019-04-11 19:21:13.440+0000 WARN [o.n.k.i.c.VmPauseMonitorComponent] Detected VM stop-the-world pause: {pauseTime=187, gcTime=268, gcCount=1}
2019-04-11 19:21:15.043+0000 INFO [o.n.k.NeoStoreDataSource] Rotated to transaction log [/var/lib/neo4j/data/databases/graph.db/neostore.transaction.db.7] version=7, last transaction in previous log=175
2019-04-11 19:21:19.197+0000 INFO [o.n.k.i.p.Procedures] [algo-42] EXPORT 0%
2019-04-11 19:21:23.996+0000 INFO [o.n.k.NeoStoreDataSource] Rotated to transaction log [/var/lib/neo4j/data/databases/graph.db/neostore.transaction.db.8] version=8, last transaction in previous log=194
2019-04-11 19:21:26.896+0000 WARN [o.n.k.i.c.VmPauseMonitorComponent] Detected VM stop-the-world pause: {pauseTime=432, gcTime=451, gcCount=1}
2019-04-11 19:21:29.198+0000 INFO [o.n.k.i.p.Procedures] [algo-63] EXPORT 0%
2019-04-11 19:21:33.200+0000 INFO [o.n.k.NeoStoreDataSource] Rotated to transaction log [/var/lib/neo4j/data/databases/graph.db/neostore.transaction.db.9] version=9, last transaction in previous log=213
2019-04-11 19:21:39.199+0000 INFO [o.n.k.i.p.Procedures] [algo-10] EXPORT 0%
2019-04-11 19:21:40.250+0000 WARN [o.n.k.i.c.VmPauseMonitorComponent] Detected VM stop-the-world pause: {pauseTime=531, gcTime=564, gcCount=1}
2019-04-11 19:21:42.725+0000 INFO [o.n.k.NeoStoreDataSource] Rotated to transaction log [/var/lib/neo4j/data/databases/graph.db/neostore.transaction.db.10] version=10, last transaction in previous log=232
2019-04-11 19:21:49.200+0000 INFO [o.n.k.i.p.Procedures] [algo-35] EXPORT 0%
2019-04-11 19:21:53.738+0000 INFO [o.n.k.NeoStoreDataSource] Rotated to transaction log [/var/lib/neo4j/data/databases/graph.db/neostore.transaction.db.11] version=11, last transaction in previous log=251
2019-04-11 19:21:56.404+0000 WARN [o.n.k.i.c.VmPauseMonitorComponent] Detected VM stop-the-world pause: {pauseTime=626, gcTime=709, gcCount=1}
2019-04-11 19:21:59.203+0000 INFO [o.n.k.i.p.Procedures] [algo-55] EXPORT 0%
2019-04-11 19:22:03.708+0000 INFO [o.n.k.NeoStoreDataSource] Rotated to transaction log [/var/lib/neo4j/data/databases/graph.db/neostore.transaction.db.12] version=12, last transaction in previous log=270
2019-04-11 19:22:09.204+0000 INFO [o.n.k.i.p.Procedures] [algo-18] EXPORT 0%
2019-04-11 19:22:09.983+0000 WARN [o.n.k.i.c.VmPauseMonitorComponent] Detected VM stop-the-world pause: {pauseTime=156, gcTime=207, gcCount=1}
2019-04-11 19:22:13.046+0000 INFO [o.n.k.NeoStoreDataSource] Rotated to transaction log [/var/lib/neo4j/data/databases/graph.db/neostore.transaction.db.13] version=13, last transaction in previous log=289
2019-04-11 19:22:19.205+0000 INFO [o.n.k.i.p.Procedures] [algo-29] EXPORT 0%
2019-04-11 19:22:22.803+0000 INFO [o.n.k.NeoStoreDataSource] Rotated to transaction log [/var/lib/neo4j/data/databases/graph.db/neostore.transaction.db.14] version=14, last transaction in previous log=308
2019-04-11 19:22:29.206+0000 INFO [o.n.k.i.p.Procedures] [algo-48] EXPORT 0%
2019-04-11 19:22:33.820+0000 INFO [o.n.k.NeoStoreDataSource] Rotated to transaction log [/var/lib/neo4j/data/databases/graph.db/neostore.transaction.db.15] version=15, last transaction in previous log=327
2019-04-11 19:22:39.207+0000 INFO [o.n.k.i.p.Procedures] [algo-6] EXPORT 0%
2019-04-11 19:22:43.312+0000 INFO [o.n.k.NeoStoreDataSource] Rotated to transaction log [/var/lib/neo4j/data/databases/graph.db/neostore.transaction.db.16] version=16, last transaction in previous log=346
2019-04-11 19:22:49.208+0000 INFO [o.n.k.i.p.Procedures] [algo-24] EXPORT 0%
2019-04-11 19:22:52.297+0000 INFO [o.n.k.NeoStoreDataSource] Rotated to transaction log [/var/lib/neo4j/data/databases/graph.db/neostore.transaction.db.17] version=17, last transaction in previous log=365
2019-04-11 19:22:59.209+0000 INFO [o.n.k.i.p.Procedures] [algo-37] EXPORT 0%
2019-04-11 19:23:09.213+0000 INFO [o.n.k.i.p.Procedures] [algo-44] EXPORT 0%
2019-04-11 19:23:16.308+0000 INFO [o.n.k.NeoStoreDataSource] Rotated to transaction log [/var/lib/neo4j/data/databases/graph.db/neostore.transaction.db.18] version=18, last transaction in previous log=384
2019-04-11 19:23:19.214+0000 INFO [o.n.k.i.p.Procedures] [algo-52] EXPORT 0%
2019-04-11 19:23:29.219+0000 INFO [o.n.k.i.p.Procedures] [algo-61] EXPORT 0%
2019-04-11 19:23:39.230+0000 INFO [o.n.k.i.p.Procedures] [algo-5] EXPORT 0%
2019-04-11 19:23:40.072+0000 INFO [o.n.k.NeoStoreDataSource] Rotated to transaction log [/var/lib/neo4j/data/databases/graph.db/neostore.transaction.db.19] version=19, last transaction in previous log=403
2019-04-11 19:23:49.231+0000 INFO [o.n.k.i.p.Procedures] [algo-17] EXPORT 0%
2019-04-11 19:23:54.196+0000 INFO [o.n.k.NeoStoreDataSource] Rotated to transaction log [/var/lib/neo4j/data/databases/graph.db/neostore.transaction.db.20] version=20, last transaction in previous log=422
2019-04-11 19:23:59.232+0000 INFO [o.n.k.i.p.Procedures] [algo-35] EXPORT 0%
2019-04-11 19:24:03.717+0000 INFO [o.n.k.NeoStoreDataSource] Rotated to transaction log [/var/lib/neo4j/data/databases/graph.db/neostore.transaction.db.21] version=21, last transaction in previous log=441
2019-04-11 19:24:09.233+0000 INFO [o.n.k.i.p.Procedures] [algo-55] EXPORT 0%
2019-04-11 19:24:12.438+0000 INFO [o.n.k.NeoStoreDataSource] Rotated to transaction log [/var/lib/neo4j/data/databases/graph.db/neostore.transaction.db.22] version=22, last transaction in previous log=460
2019-04-11 19:24:19.234+0000 INFO [o.n.k.i.p.Procedures] [algo-21] EXPORT 0%
2019-04-11 19:24:21.401+0000 INFO [o.n.k.NeoStoreDataSource] Rotated to transaction log [/var/lib/neo4j/data/databases/graph.db/neostore.transaction.db.23] version=23, last transaction in previous log=479
2019-04-11 19:24:29.235+0000 INFO [o.n.k.i.p.Procedures] [algo-34] EXPORT 0%
2019-04-11 19:24:30.350+0000 INFO [o.n.k.NeoStoreDataSource] Rotated to transaction log [/var/lib/neo4j/data/databases/graph.db/neostore.transaction.db.24] version=24, last transaction in previous log=498
2019-04-11 19:24:39.237+0000 INFO [o.n.k.i.p.Procedures] [algo-55] EXPORT 1%
2019-04-11 19:24:39.425+0000 INFO [o.n.k.NeoStoreDataSource] Rotated to transaction log [/var/lib/neo4j/data/databases/graph.db/neostore.transaction.db.25] version=25, last transaction in previous log=517
2019-04-11 19:24:49.046+0000 INFO [o.n.k.NeoStoreDataSource] Rotated to transaction log [/var/lib/neo4j/data/databases/graph.db/neostore.transaction.db.26] version=26, last transaction in previous log=536
2019-04-11 19:24:49.240+0000 INFO [o.n.k.i.p.Procedures] [algo-18] EXPORT 1%
2019-04-11 19:24:59.241+0000 INFO [o.n.k.i.p.Procedures] [algo-28] EXPORT 1%
2019-04-11 19:24:59.533+0000 ERROR [o.n.b.t.p.HouseKeeper] Fatal error occurred when handling a client connection: [id: 0x93ef68aa, L:/10.76.130.128:7687 - R:/10.186.56.65:58538] readAddress(..) failed: Connection timed out
io.netty.channel.unix.Errors$NativeIoException: readAddress(..) failed: Connection timed out
at io.netty.channel.unix.Errors.newIOException(Errors.java:122)
at io.netty.channel.unix.Errors.ioResult(Errors.java:146)
at io.netty.channel.unix.FileDescriptor.readAddress(FileDescriptor.java:178)
at io.netty.channel.epoll.AbstractEpollChannel.doReadBytes(AbstractEpollChannel.java:343)
at io.netty.channel.epoll.AbstractEpollStreamChannel$EpollStreamUnsafe.epollInReady(AbstractEpollStreamChannel.java:785)
at io.netty.channel.epoll.EpollEventLoop.processReady(EpollEventLoop.java:433)
at io.netty.channel.epoll.EpollEventLoop.run(EpollEventLoop.java:330)
at io.netty.util.concurrent.SingleThreadEventExecutor$5.run(SingleThreadEventExecutor.java:909)
at java.lang.Thread.run(Thread.java:748)
2019-04-11 19:25:03.461+0000 INFO [o.n.k.NeoStoreDataSource] Rotated to transaction log [/var/lib/neo4j/data/databases/graph.db/neostore.transaction.db.27] version=27, last transaction in previous log=555
2019-04-11 19:25:09.257+0000 INFO [o.n.k.i.p.Procedures] [algo-33] EXPORT 1%
2019-04-11 19:25:19.258+0000 INFO [o.n.k.i.p.Procedures] [algo-40] EXPORT 1%
2019-04-11 19:25:29.265+0000 INFO [o.n.k.i.p.Procedures] [algo-49] EXPORT 1%
2019-04-11 19:25:30.790+0000 INFO [o.n.k.NeoStoreDataSource] Rotated to transaction log [/var/lib/neo4j/data/databases/graph.db/neostore.transaction.db.28] version=28, last transaction in previous log=574
2019-04-11 19:25:39.266+0000 INFO [o.n.k.i.p.Procedures] [algo-55] EXPORT 1%
2019-04-11 19:25:49.267+0000 INFO [o.n.k.i.p.Procedures] [algo-64] EXPORT 1%
2019-04-11 19:25:50.633+0000 INFO [o.n.k.NeoStoreDataSource] Rotated to transaction log [/var/lib/neo4j/data/databases/graph.db/neostore.transaction.db.29] version=29, last transaction in previous log=593
2019-04-11 19:25:59.268+0000 INFO [o.n.k.i.p.Procedures] [algo-7] EXPORT 1%
2019-04-11 19:25:59.629+0000 INFO [o.n.k.NeoStoreDataSource] Rotated to transaction log [/var/lib/neo4j/data/databases/graph.db/neostore.transaction.db.30] version=30, last transaction in previous log=612
2019-04-11 19:26:09.152+0000 INFO [o.n.k.NeoStoreDataSource] Rotated to transaction log [/var/lib/neo4j/data/databases/graph.db/neostore.transaction.db.31] version=31, last transaction in previous log=631
2019-04-11 19:26:09.269+0000 INFO [o.n.k.i.p.Procedures] [algo-42] EXPORT 1%
2019-04-11 19:26:18.141+0000 INFO [o.n.k.NeoStoreDataSource] Rotated to transaction log [/var/lib/neo4j/data/databases/graph.db/neostore.transaction.db.32] version=32, last transaction in previous log=650
2019-04-11 19:26:19.270+0000 INFO [o.n.k.i.p.Procedures] [algo-62] EXPORT 1%
2019-04-11 19:26:27.639+0000 INFO [o.n.k.NeoStoreDataSource] Rotated to transaction log [/var/lib/neo4j/data/databases/graph.db/neostore.transaction.db.33] version=33, last transaction in previous log=669
2019-04-11 19:26:29.271+0000 INFO [o.n.k.i.p.Procedures] [algo-16] EXPORT 1%
2019-04-11 19:26:36.554+0000 INFO [o.n.k.NeoStoreDataSource] Rotated to transaction log [/var/lib/neo4j/data/databases/graph.db/neostore.transaction.db.34] version=34, last transaction in previous log=688
2019-04-11 19:26:39.272+0000 INFO [o.n.k.i.p.Procedures] [algo-40] EXPORT 1%
2019-04-11 19:26:45.064+0000 INFO [o.n.k.NeoStoreDataSource] Rotated to transaction log [/var/lib/neo4j/data/databases/graph.db/neostore.transaction.db.35] version=35, last transaction in previous log=707
2019-04-11 19:26:49.273+0000 INFO [o.n.k.i.p.Procedures] [algo-63] EXPORT 1%
2019-04-11 19:26:57.576+0000 INFO [o.n.k.NeoStoreDataSource] Rotated to transaction log [/var/lib/neo4j/data/databases/graph.db/neostore.transaction.db.36] version=36, last transaction in previous log=726
2019-04-11 19:26:59.274+0000 INFO [o.n.k.i.p.Procedures] [algo-20] EXPORT 1%
2019-04-11 19:27:09.275+0000 INFO [o.n.k.i.p.Procedures] [algo-9] EXPORT 1%
2019-04-11 19:27:10.606+0000 ERROR [o.n.b.t.p.HouseKeeper] Fatal error occurred when handling a client connection: [id: 0xeea10a98, L:/10.76.130.128:7687 - R:/10.186.56.65:58557] readAddress(..) failed: Connection timed out
io.netty.channel.unix.Errors$NativeIoException: readAddress(..) failed: Connection timed out
at io.netty.channel.unix.Errors.newIOException(Errors.java:122)
at io.netty.channel.unix.Errors.ioResult(Errors.java:146)
at io.netty.channel.unix.FileDescriptor.readAddress(FileDescriptor.java:178)
at io.netty.channel.epoll.AbstractEpollChannel.doReadBytes(AbstractEpollChannel.java:343)
at io.netty.channel.epoll.AbstractEpollStreamChannel$EpollStreamUnsafe.epollInReady(AbstractEpollStreamChannel.java:785)
at io.netty.channel.epoll.EpollEventLoop.processReady(EpollEventLoop.java:433)
at io.netty.channel.epoll.EpollEventLoop.run(EpollEventLoop.java:330)
at io.netty.util.concurrent.SingleThreadEventExecutor$5.run(SingleThreadEventExecutor.java:909)
at java.lang.Thread.run(Thread.java:748)
2019-04-11 19:27:15.286+0000 INFO [o.n.k.NeoStoreDataSource] Rotated to transaction log [/var/lib/neo4j/data/databases/graph.db/neostore.transaction.db.37] version=37, last transaction in previous log=745
2019-04-11 19:27:19.276+0000 INFO [o.n.k.i.p.Procedures] [algo-35] EXPORT 1%
2019-04-11 19:27:28.952+0000 INFO [o.n.k.NeoStoreDataSource] Rotated to transaction log [/var/lib/neo4j/data/databases/graph.db/neostore.transaction.db.38] version=38, last transaction in previous log=764
2019-04-11 19:27:29.278+0000 INFO [o.n.k.i.p.Procedures] [algo-46] EXPORT 1%
2019-04-11 19:27:39.283+0000 INFO [o.n.k.i.p.Procedures] [algo-55] EXPORT 1%
2019-04-11 19:27:49.284+0000 INFO [o.n.k.i.p.Procedures] [algo-63] EXPORT 1%
2019-04-11 19:27:51.392+0000 INFO [o.n.k.NeoStoreDataSource] Rotated to transaction log [/var/lib/neo4j/data/databases/graph.db/neostore.transaction.db.39] version=39, last transaction in previous log=783
2019-04-11 19:27:59.286+0000 INFO [o.n.k.i.p.Procedures] [algo-20] EXPORT 1%
2019-04-11 19:28:05.150+0000 INFO [o.n.k.NeoStoreDataSource] Rotated to transaction log [/var/lib/neo4j/data/databases/graph.db/neostore.transaction.db.40] version=40, last transaction in previous log=802
2019-04-11 19:28:09.287+0000 INFO [o.n.k.i.p.Procedures] [algo-31] EXPORT 1%
2019-04-11 19:28:14.656+0000 INFO [o.n.k.NeoStoreDataSource] Rotated to transaction log [/var/lib/neo4j/data/databases/graph.db/neostore.transaction.db.41] version=41, last transaction in previous log=821
2019-04-11 19:28:19.289+0000 INFO [o.n.k.i.p.Procedures] [algo-45] EXPORT 1%
2019-04-11 19:28:29.296+0000 INFO [o.n.k.i.p.Procedures] [algo-53] EXPORT 1%
2019-04-11 19:28:34.864+0000 INFO [o.n.k.NeoStoreDataSource] Rotated to transaction log [/var/lib/neo4j/data/databases/graph.db/neostore.transaction.db.42] version=42, last transaction in previous log=840
2019-04-11 19:28:39.292+0000 INFO [o.n.k.i.p.Procedures] [algo-63] EXPORT 1%
2019-04-11 19:28:49.292+0000 INFO [o.n.k.i.p.Procedures] [algo-18] EXPORT 1%
2019-04-11 19:28:50.521+0000 INFO [o.n.k.NeoStoreDataSource] Rotated to transaction log [/var/lib/neo4j/data/databases/graph.db/neostore.transaction.db.43] version=43, last transaction in previous log=859
2019-04-11 19:28:59.293+0000 INFO [o.n.k.i.p.Procedures] [algo-24] EXPORT 1%
2019-04-11 19:29:02.904+0000 INFO [o.n.k.NeoStoreDataSource] Rotated to transaction log [/var/lib/neo4j/data/databases/graph.db/neostore.transaction.db.44] version=44, last transaction in previous log=878
2019-04-11 19:29:09.294+0000 INFO [o.n.k.i.p.Procedures] [algo-44] EXPORT 1%
2019-04-11 19:29:12.787+0000 INFO [o.n.k.NeoStoreDataSource] Rotated to transaction log [/var/lib/neo4j/data/databases/graph.db/neostore.transaction.db.45] version=45, last transaction in previous log=897
2019-04-11 19:29:19.295+0000 INFO [o.n.k.i.p.Procedures] [algo-63] EXPORT 1%
2019-04-11 19:29:21.686+0000 ERROR [o.n.b.t.p.HouseKeeper] Fatal error occurred when handling a client connection: [id: 0xc0421e73, L:/10.76.130.128:7687 - R:/10.186.56.65:58571] readAddress(..) failed: Connection timed out
io.netty.channel.unix.Errors$NativeIoException: readAddress(..) failed: Connection timed out
at io.netty.channel.unix.Errors.newIOException(Errors.java:122)
at io.netty.channel.unix.Errors.ioResult(Errors.java:146)
at io.netty.channel.unix.FileDescriptor.readAddress(FileDescriptor.java:178)
at io.netty.channel.epoll.AbstractEpollChannel.doReadBytes(AbstractEpollChannel.java:343)
at io.netty.channel.epoll.AbstractEpollStreamChannel$EpollStreamUnsafe.epollInReady(AbstractEpollStreamChannel.java:785)
at io.netty.channel.epoll.EpollEventLoop.processReady(EpollEventLoop.java:433)
at io.netty.channel.epoll.EpollEventLoop.run(EpollEventLoop.java:330)
at io.netty.util.concurrent.SingleThreadEventExecutor$5.run(SingleThreadEventExecutor.java:909)
at java.lang.Thread.run(Thread.java:748)
2019-04-11 19:29:23.288+0000 INFO [o.n.k.NeoStoreDataSource] Rotated to transaction log [/var/lib/neo4j/data/databases/graph.db/neostore.transaction.db.46] version=46, last transaction in previous log=916
2019-04-11 19:29:29.296+0000 INFO [o.n.k.i.p.Procedures] [algo-13] EXPORT 1%
2019-04-11 19:29:34.346+0000 INFO [o.n.k.NeoStoreDataSource] Rotated to transaction log [/var/lib/neo4j/data/databases/graph.db/neostore.transaction.db.47] version=47, last transaction in previous log=935
2019-04-11 19:29:39.297+0000 INFO [o.n.k.i.p.Procedures] [algo-34] EXPORT 1%
2019-04-11 19:29:44.635+0000 INFO [o.n.k.NeoStoreDataSource] Rotated to transaction log [/var/lib/neo4j/data/databases/graph.db/neostore.transaction.db.48] version=48, last transaction in previous log=954
2019-04-11 19:29:49.298+0000 INFO [o.n.k.i.p.Procedures] [algo-53] EXPORT 2%
2019-04-11 19:29:53.669+0000 INFO [o.n.k.NeoStoreDataSource] Rotated to transaction log [/var/lib/neo4j/data/databases/graph.db/neostore.transaction.db.49] version=49, last transaction in previous log=973
2019-04-11 19:29:59.299+0000 INFO [o.n.k.i.p.Procedures] [algo-12] EXPORT 2%
2019-04-11 19:30:03.742+0000 INFO [o.n.k.NeoStoreDataSource] Rotated to transaction log [/var/lib/neo4j/data/databases/graph.db/neostore.transaction.db.50] version=50, last transaction in previous log=992
2019-04-11 19:30:09.305+0000 INFO [o.n.k.i.p.Procedures] [algo-30] EXPORT 2%
2019-04-11 19:30:16.190+0000 INFO [o.n.k.NeoStoreDataSource] Rotated to transaction log [/var/lib/neo4j/data/databases/graph.db/neostore.transaction.db.51] version=51, last transaction in previous log=1011
2019-04-11 19:30:19.306+0000 INFO [o.n.k.i.p.Procedures] [algo-43] EXPORT 2%
2019-04-11 19:30:25.585+0000 INFO [o.n.k.NeoStoreDataSource] Rotated to transaction log [/var/lib/neo4j/data/databases/graph.db/neostore.transaction.db.52] version=52, last transaction in previous log=1030
2019-04-11 19:30:29.307+0000 INFO [o.n.k.i.p.Procedures] [algo-64] EXPORT 2%
2019-04-11 19:30:35.018+0000 INFO [o.n.k.NeoStoreDataSource] Rotated to transaction log [/var/lib/neo4j/data/databases/graph.db/neostore.transaction.db.53] version=53, last transaction in previous log=1049
2019-04-11 19:30:39.308+0000 INFO [o.n.k.i.p.Procedures] [algo-7] EXPORT 2%
2019-04-11 19:30:44.985+0000 INFO [o.n.k.NeoStoreDataSource] Rotated to transaction log [/var/lib/neo4j/data/databases/graph.db/neostore.transaction.db.54] version=54, last transaction in previous log=1068
2019-04-11 19:30:49.310+0000 INFO [o.n.k.i.p.Procedures] [algo-40] EXPORT 2%
2019-04-11 19:30:59.313+0000 INFO [o.n.k.i.p.Procedures] [algo-48] EXPORT 2%
2019-04-11 19:31:02.652+0000 INFO [o.n.k.NeoStoreDataSource] Rotated to transaction log [/var/lib/neo4j/data/databases/graph.db/neostore.transaction.db.55] version=55, last transaction in previous log=1087
2019-04-11 19:31:09.315+0000 INFO [o.n.k.i.p.Procedures] [algo-55] EXPORT 2%
2019-04-11 19:31:19.321+0000 INFO [o.n.k.i.p.Procedures] [algo-61] EXPORT 2%
2019-04-11 19:31:29.320+0000 INFO [o.n.k.i.p.Procedures] [algo-6] EXPORT 2%
2019-04-11 19:31:29.452+0000 INFO [o.n.k.NeoStoreDataSource] Rotated to transaction log [/var/lib/neo4j/data/databases/graph.db/neostore.transaction.db.56] version=56, last transaction in previous log=1106
2019-04-11 19:31:32.750+0000 ERROR [o.n.b.t.p.HouseKeeper] Fatal error occurred when handling a client connection: [id: 0x16b2c3fa, L:/10.76.130.128:7687 - R:/10.186.56.65:58583] readAddress(..) failed: Connection timed out
io.netty.channel.unix.Errors$NativeIoException: readAddress(..) failed: Connection timed out
at io.netty.channel.unix.Errors.newIOException(Errors.java:122)
at io.netty.channel.unix.Errors.ioResult(Errors.java:146)
at io.netty.channel.unix.FileDescriptor.readAddress(FileDescriptor.java:178)
at io.netty.channel.epoll.AbstractEpollChannel.doReadBytes(AbstractEpollChannel.java:343)
at io.netty.channel.epoll.AbstractEpollStreamChannel$EpollStreamUnsafe.epollInReady(AbstractEpollStreamChannel.java:785)
at io.netty.channel.epoll.EpollEventLoop.processReady(EpollEventLoop.java:433)
at io.netty.channel.epoll.EpollEventLoop.run(EpollEventLoop.java:330)
at io.netty.util.concurrent.SingleThreadEventExecutor$5.run(SingleThreadEventExecutor.java:909)
at java.lang.Thread.run(Thread.java:748)
2019-04-11 19:31:32.753+0000 ERROR [o.n.b.t.p.HouseKeeper] Fatal error occurred when handling a client connection: [id: 0xe822293b, L:/10.76.130.128:7687 - R:/10.186.56.65:58599] readAddress(..) failed: Connection timed out
io.netty.channel.unix.Errors$NativeIoException: readAddress(..) failed: Connection timed out
at io.netty.channel.unix.Errors.newIOException(Errors.java:122)
at io.netty.channel.unix.Errors.ioResult(Errors.java:146)
at io.netty.channel.unix.FileDescriptor.readAddress(FileDescriptor.java:178)
at io.netty.channel.epoll.AbstractEpollChannel.doReadBytes(AbstractEpollChannel.java:343)
at io.netty.channel.epoll.AbstractEpollStreamChannel$EpollStreamUnsafe.epollInReady(AbstractEpollStreamChannel.java:785)
at io.netty.channel.epoll.EpollEventLoop.processReady(EpollEventLoop.java:433)
at io.netty.channel.epoll.EpollEventLoop.run(EpollEventLoop.java:330)
at io.netty.util.concurrent.SingleThreadEventExecutor$5.run(SingleThreadEventExecutor.java:909)
at java.lang.Thread.run(Thread.java:748)
2019-04-11 19:31:39.321+0000 INFO [o.n.k.i.p.Procedures] [algo-21] EXPORT 2%
2019-04-11 19:31:49.322+0000 INFO [o.n.k.i.p.Procedures] [algo-7] EXPORT 2%
2019-04-11 19:31:50.816+0000 INFO [o.n.k.NeoStoreDataSource] Rotated to transaction log [/var/lib/neo4j/data/databases/graph.db/neostore.transaction.db.57] version=57, last transaction in previous log=1125
2019-04-11 19:31:59.333+0000 INFO [o.n.k.i.p.Procedures] [algo-29] EXPORT 2%
2019-04-11 19:32:09.422+0000 INFO [o.n.k.i.p.Procedures] [algo-35] EXPORT 2%
2019-04-11 19:32:19.474+0000 INFO [o.n.k.i.p.Procedures] [algo-42] EXPORT 2%
2019-04-11 19:32:25.077+0000 INFO [o.n.k.NeoStoreDataSource] Rotated to transaction log [/var/lib/neo4j/data/databases/graph.db/neostore.transaction.db.58] version=58, last transaction in previous log=1144
2019-04-11 19:32:29.478+0000 INFO [o.n.k.i.p.Procedures] [algo-43] EXPORT 2%
2019-04-11 19:32:39.479+0000 INFO [o.n.k.i.p.Procedures] [algo-50] EXPORT 2%
2019-04-11 19:32:49.480+0000 INFO [o.n.k.i.p.Procedures] [algo-56] EXPORT 2%
2019-04-11 19:32:56.741+0000 INFO [o.n.k.NeoStoreDataSource] Rotated to transaction log [/var/lib/neo4j/data/databases/graph.db/neostore.transaction.db.59] version=59, last transaction in previous log=1163
2019-04-11 19:32:59.482+0000 INFO [o.n.k.i.p.Procedures] [algo-63] EXPORT 2%
2019-04-11 19:33:09.483+0000 INFO [o.n.k.i.p.Procedures] [algo-6] EXPORT 2%
2019-04-11 19:33:19.484+0000 INFO [o.n.k.i.p.Procedures] [algo-22] EXPORT 2%
2019-04-11 19:33:29.486+0000 INFO [o.n.k.i.p.Procedures] [algo-13] EXPORT 2%
2019-04-11 19:33:31.453+0000 INFO [o.n.k.NeoStoreDataSource] Rotated to transaction log [/var/lib/neo4j/data/databases/graph.db/neostore.transaction.db.60] version=60, last transaction in previous log=1182
2019-04-11 19:33:39.498+0000 INFO [o.n.k.i.p.Procedures] [algo-7] EXPORT 2%
2019-04-11 19:33:49.499+0000 INFO [o.n.k.i.p.Procedures] [algo-27] EXPORT 2%
2019-04-11 19:33:58.203+0000 INFO [o.n.k.NeoStoreDataSource] Rotated to transaction log [/var/lib/neo4j/data/databases/graph.db/neostore.transaction.db.61] version=61, last transaction in previous log=1201
2019-04-11 19:33:59.507+0000 INFO [o.n.k.i.p.Procedures] [algo-37] EXPORT 2%
2019-04-11 19:34:09.508+0000 INFO [o.n.k.i.p.Procedures] [algo-43] EXPORT 2%
2019-04-11 19:34:19.509+0000 INFO [o.n.k.i.p.Procedures] [algo-51] EXPORT 2%
2019-04-11 19:34:22.327+0000 INFO [o.n.k.NeoStoreDataSource] Rotated to transaction log [/var/lib/neo4j/data/databases/graph.db/neostore.transaction.db.62] version=62, last transaction in previous log=1220
2019-04-11 19:34:29.514+0000 INFO [o.n.k.i.p.Procedures] [algo-59] EXPORT 2%
2019-04-11 19:34:39.515+0000 INFO [o.n.k.i.p.Procedures] [algo-5] EXPORT 2%
2019-04-11 19:34:47.365+0000 INFO [o.n.k.NeoStoreDataSource] Rotated to transaction log [/var/lib/neo4j/data/databases/graph.db/neostore.transaction.db.63] version=63, last transaction in previous log=1239
2019-04-11 19:34:49.517+0000 INFO [o.n.k.i.p.Procedures] [algo-17] EXPORT 2%
2019-04-11 19:34:59.519+0000 INFO [o.n.k.i.p.Procedures] [algo-23] EXPORT 2%
2019-04-11 19:35:09.718+0000 INFO [o.n.k.i.p.Procedures] [algo-27] EXPORT 2%
2019-04-11 19:35:10.617+0000 INFO [o.n.k.NeoStoreDataSource] Rotated to transaction log [/var/lib/neo4j/data/databases/graph.db/neostore.transaction.db.64] version=64, last transaction in previous log=1258
2019-04-11 19:35:19.719+0000 INFO [o.n.k.i.p.Procedures] [algo-40] EXPORT 2%
2019-04-11 19:35:23.840+0000 INFO [o.n.k.NeoStoreDataSource] Rotated to transaction log [/var/lib/neo4j/data/databases/graph.db/neostore.transaction.db.65] version=65, last transaction in previous log=1277
2019-04-11 19:35:28.771+0000 INFO [o.n.k.i.t.l.c.CheckPointerImpl] Checkpoint triggered by scheduler for time threshold @ txId: 1286 checkpoint started...
2019-04-11 19:35:29.514+0000 INFO [o.n.k.i.s.c.CountsTracker] Rotated counts store at transaction 1288 to [/var/lib/neo4j/data/databases/graph.db/neostore.counts.db.a], from [/var/lib/neo4j/data/databases/graph.db/neostore.counts.db.b].
2019-04-11 19:35:29.720+0000 INFO [o.n.k.i.p.Procedures] [algo-60] EXPORT 2%
2019-04-11 19:35:33.993+0000 INFO [o.n.k.NeoStoreDataSource] Rotated to transaction log [/var/lib/neo4j/data/databases/graph.db/neostore.transaction.db.66] version=66, last transaction in previous log=1296
2019-04-11 19:35:39.721+0000 INFO [o.n.k.i.p.Procedures] [algo-12] EXPORT 2%
2019-04-11 19:35:46.327+0000 INFO [o.n.k.NeoStoreDataSource] Rotated to transaction log [/var/lib/neo4j/data/databases/graph.db/neostore.transaction.db.67] version=67, last transaction in previous log=1315
2019-04-11 19:35:49.722+0000 INFO [o.n.k.i.p.Procedures] [algo-24] EXPORT 2%
2019-04-11 19:35:54.894+0000 ERROR [o.n.b.t.p.HouseKeeper] Fatal error occurred when handling a client connection: [id: 0x324cb1fb, L:/10.76.130.128:7687 - R:/10.186.56.65:58612] readAddress(..) failed: Connection timed out
io.netty.channel.unix.Errors$NativeIoException: readAddress(..) failed: Connection timed out
at io.netty.channel.unix.Errors.newIOException(Errors.java:122)
at io.netty.channel.unix.Errors.ioResult(Errors.java:146)
at io.netty.channel.unix.FileDescriptor.readAddress(FileDescriptor.java:178)
at io.netty.channel.epoll.AbstractEpollChannel.doReadBytes(AbstractEpollChannel.java:343)
at io.netty.channel.epoll.AbstractEpollStreamChannel$EpollStreamUnsafe.epollInReady(AbstractEpollStreamChannel.java:785)
at io.netty.channel.epoll.EpollEventLoop.processReady(EpollEventLoop.java:433)
at io.netty.channel.epoll.EpollEventLoop.run(EpollEventLoop.java:330)
at io.netty.util.concurrent.SingleThreadEventExecutor$5.run(SingleThreadEventExecutor.java:909)
at java.lang.Thread.run(Thread.java:748)
2019-04-11 19:35:59.723+0000 INFO [o.n.k.i.p.Procedures] [algo-29] EXPORT 2%
2019-04-11 19:36:09.724+0000 INFO [o.n.k.i.p.Procedures] [algo-35] EXPORT 2%
2019-04-11 19:36:19.744+0000 INFO [o.n.k.i.p.Procedures] [algo-40] EXPORT 2%
2019-04-11 19:36:21.447+0000 INFO [o.n.k.NeoStoreDataSource] Rotated to transaction log [/var/lib/neo4j/data/databases/graph.db/neostore.transaction.db.68] version=68, last transaction in previous log=1334
2019-04-11 19:36:29.744+0000 INFO [o.n.k.i.p.Procedures] [algo-46] EXPORT 2%
2019-04-11 19:36:39.745+0000 INFO [o.n.k.i.p.Procedures] [algo-50] EXPORT 2%
2019-04-11 19:36:49.749+0000 INFO [o.n.k.i.p.Procedures] [algo-59] EXPORT 2%
2019-04-11 19:36:49.888+0000 INFO [o.n.k.NeoStoreDataSource] Rotated to transaction log [/var/lib/neo4j/data/databases/graph.db/neostore.transaction.db.69] version=69, last transaction in previous log=1353
2019-04-11 19:36:59.750+0000 INFO [o.n.k.i.p.Procedures] [algo-14] EXPORT 2%
2019-04-11 19:37:03.081+0000 INFO [o.n.k.NeoStoreDataSource] Rotated to transaction log [/var/lib/neo4j/data/databases/graph.db/neostore.transaction.db.70] version=70, last transaction in previous log=1372
2019-04-11 19:37:09.751+0000 INFO [o.n.k.i.p.Procedures] [algo-24] EXPORT 2%
2019-04-11 19:37:15.348+0000 INFO [o.n.k.NeoStoreDataSource] Rotated to transaction log [/var/lib/neo4j/data/databases/graph.db/neostore.transaction.db.71] version=71, last transaction in previous log=1391
2019-04-11 19:37:19.752+0000 INFO [o.n.k.i.p.Procedures] [algo-39] EXPORT 2%
2019-04-11 19:37:29.772+0000 INFO [o.n.k.i.p.Procedures] [algo-44] EXPORT 2%
2019-04-11 19:37:39.772+0000 INFO [o.n.k.i.p.Procedures] [algo-50] EXPORT 2%
2019-04-11 19:37:46.611+0000 INFO [o.n.k.NeoStoreDataSource] Rotated to transaction log [/var/lib/neo4j/data/databases/graph.db/neostore.transaction.db.72] version=72, last transaction in previous log=1410
2019-04-11 19:37:49.794+0000 INFO [o.n.k.i.p.Procedures] [algo-54] EXPORT 3%
2019-04-11 19:37:59.795+0000 INFO [o.n.k.i.p.Procedures] [algo-61] EXPORT 3%
2019-04-11 19:38:09.796+0000 INFO [o.n.k.i.p.Procedures] [algo-3] EXPORT 3%
2019-04-11 19:38:19.803+0000 INFO [o.n.k.i.p.Procedures] [algo-14] EXPORT 3%
2019-04-11 19:38:21.598+0000 INFO [o.n.k.NeoStoreDataSource] Rotated to transaction log [/var/lib/neo4j/data/databases/graph.db/neostore.transaction.db.73] version=73, last transaction in previous log=1429
2019-04-11 19:38:29.806+0000 INFO [o.n.k.i.p.Procedures] [algo-21] EXPORT 3%
2019-04-11 19:38:39.807+0000 INFO [o.n.k.i.p.Procedures] [algo-13] EXPORT 3%
2019-04-11 19:38:49.808+0000 INFO [o.n.k.i.p.Procedures] [algo-26] EXPORT 3%
2019-04-11 19:38:50.575+0000 INFO [o.n.k.NeoStoreDataSource] Rotated to transaction log [/var/lib/neo4j/data/databases/graph.db/neostore.transaction.db.74] version=74, last transaction in previous log=1448
2019-04-11 19:38:59.819+0000 INFO [o.n.k.i.p.Procedures] [algo-33] EXPORT 3%
2019-04-11 19:39:09.889+0000 INFO [o.n.k.i.p.Procedures] [algo-36] EXPORT 3%
2019-04-11 19:39:19.891+0000 INFO [o.n.k.i.p.Procedures] [algo-45] EXPORT 3%
2019-04-11 19:39:22.771+0000 INFO [o.n.k.NeoStoreDataSource] Rotated to transaction log [/var/lib/neo4j/data/databases/graph.db/neostore.transaction.db.75] version=75, last transaction in previous log=1467
2019-04-11 19:39:29.892+0000 INFO [o.n.k.i.p.Procedures] [algo-50] EXPORT 3%
YIELD nodes, setCount, loadMillis, computeMillis, writeMillis,p1, p5,p10,p25,p50,p75,p90,p95,p100;
Failed to invoke procedure `algo.unionFind`: Caused by: com.carrotsearch.hppc.BufferAllocationException: Maximum array size exceeded for this load factor (elements: 805306369, load factor: 0.750000)
Based on a more detail review of the debug log it appears all the data loaded correctly to the 99%, the issue is probably related to the p1,p5..etc I think it can't load the ~4 Billion cluster sizes into an array to determine the percentiles of size for each cluster.
Config: Heap 410 GB PC: 30 GB GC - Shenandoah
cmd: CALL algo.unionFind(null, 'OBSERVED_WITH', {write:true, graph:'huge', partitionProperty:"community",concurrency:1}) YIELD nodes, setCount, loadMillis, computeMillis, writeMillis,p1, p5,p10,p25,p50,p75,p90,p95,p100;
Neo4j graph algorithms 3.5.3.4 Neo4j Enterprise 3.5.3 Running from cypher-shell Linux - Fedora JVM 1.8 64 CPU 488 Ram Large graph of 4.5 Billion Nodes