weixin_39615596 2020-11-19 11:09
浏览 0

UnionFind with concurrency set 1 gives false ram reading

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


2019-04-11 06:13:20.767+0000 INFO [o.n.k.i.p.Procedures] [node-store-scan-0] LOADING 1% Memory usage: 33 GiB
2019-04-11 06:13:37.192+0000 INFO [o.n.k.i.p.Procedures] [node-store-scan-0] LOADING 3% Memory usage: 33 GiB
2019-04-11 06:13:53.405+0000 INFO [o.n.k.i.p.Procedures] [node-store-scan-0] LOADING 4% Memory usage: 33 GiB
2019-04-11 06:14:10.123+0000 INFO [o.n.k.i.p.Procedures] [node-store-scan-0] LOADING 6% Memory usage: 33 GiB
2019-04-11 06:14:27.511+0000 INFO [o.n.k.i.p.Procedures] [node-store-scan-0] LOADING 8% Memory usage: 33 GiB
2019-04-11 06:14:44.473+0000 INFO [o.n.k.i.p.Procedures] [node-store-scan-0] LOADING 9% Memory usage: 33 GiB
2019-04-11 06:15:01.050+0000 INFO [o.n.k.i.p.Procedures] [node-store-scan-0] LOADING 11% Memory usage: 33 GiB
2019-04-11 06:15:17.991+0000 INFO [o.n.k.i.p.Procedures] [node-store-scan-0] LOADING 13% Memory usage: 33 GiB
2019-04-11 06:15:34.922+0000 INFO [o.n.k.i.p.Procedures] [node-store-scan-0] LOADING 14% Memory usage: 33 GiB
2019-04-11 06:15:51.981+0000 INFO [o.n.k.i.p.Procedures] [node-store-scan-0] LOADING 16% Memory usage: 33 GiB
2019-04-11 06:16:09.320+0000 INFO [o.n.k.i.p.Procedures] [node-store-scan-0] LOADING 18% Memory usage: 33 GiB
2019-04-11 06:16:25.602+0000 INFO [o.n.k.i.p.Procedures] [node-store-scan-0] LOADING 19% Memory usage: 33 GiB
2019-04-11 06:16:42.660+0000 INFO [o.n.k.i.p.Procedures] [node-store-scan-0] LOADING 21% Memory usage: 33 GiB
2019-04-11 06:16:59.614+0000 INFO [o.n.k.i.p.Procedures] [node-store-scan-0] LOADING 23% Memory usage: 33 GiB
2019-04-11 06:17:16.206+0000 INFO [o.n.k.i.p.Procedures] [node-store-scan-0] LOADING 24% Memory usage: 33 GiB
2019-04-11 06:17:33.652+0000 INFO [o.n.k.i.p.Procedures] [node-store-scan-0] LOADING 26% Memory usage: 33 GiB
2019-04-11 06:17:50.722+0000 INFO [o.n.k.i.p.Procedures] [node-store-scan-0] LOADING 28% Memory usage: 33 GiB
2019-04-11 06:18:07.987+0000 INFO [o.n.k.i.p.Procedures] [node-store-scan-0] LOADING 29% Memory usage: 33 GiB
2019-04-11 06:18:25.203+0000 INFO [o.n.k.i.p.Procedures] [node-store-scan-0] LOADING 31% Memory usage: 33 GiB
2019-04-11 06:18:43.019+0000 INFO [o.n.k.i.p.Procedures] [node-store-scan-0] LOADING 33% Memory usage: 33 GiB
2019-04-11 06:19:00.258+0000 INFO [o.n.k.i.p.Procedures] [node-store-scan-0] LOADING 34% Memory usage: 33 GiB
2019-04-11 06:19:20.865+0000 INFO [o.n.k.i.p.Procedures] [node-store-scan-0] LOADING 36% Memory usage: 33 GiB
2019-04-11 06:19:37.898+0000 INFO [o.n.k.i.p.Procedures] [node-store-scan-0] LOADING 38% Memory usage: 33 GiB
2019-04-11 06:19:55.239+0000 INFO [o.n.k.i.p.Procedures] [node-store-scan-0] LOADING 39% Memory usage: 33 GiB
2019-04-11 06:20:12.452+0000 INFO [o.n.k.i.p.Procedures] [node-store-scan-0] LOADING 41% Memory usage: 33 GiB
2019-04-11 06:20:29.693+0000 INFO [o.n.k.i.p.Procedures] [node-store-scan-0] LOADING 42% Memory usage: 33 GiB
2019-04-11 06:20:47.397+0000 INFO [o.n.k.i.p.Procedures] [node-store-scan-0] LOADING 44% Memory usage: 33 GiB
2019-04-11 06:21:04.745+0000 INFO [o.n.k.i.p.Procedures] [node-store-scan-0] LOADING 46% Memory usage: 33 GiB
2019-04-11 06:21:22.526+0000 INFO [o.n.k.i.p.Procedures] [node-store-scan-0] LOADING 47% Memory usage: 33 GiB
2019-04-11 06:21:39.679+0000 INFO [o.n.k.i.p.Procedures] [node-store-scan-0] LOADING 49% Memory usage: 33 GiB
2019-04-11 06:21:56.370+0000 INFO [o.n.k.i.p.Procedures] [node-store-scan-0] LOADING 51% Memory usage: 33 GiB
2019-04-11 06:22:12.788+0000 INFO [o.n.k.i.p.Procedures] [node-store-scan-0] LOADING 52% Memory usage: 33 GiB
2019-04-11 06:22:29.402+0000 INFO [o.n.k.i.p.Procedures] [node-store-scan-0] LOADING 54% Memory usage: 33 GiB
2019-04-11 06:22:45.300+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 582.363 s, 7,823,878.92 Nodes/s, 111 MiB/s (117,358,641 bytes/s) (per thread: 7,823,878.92 Nodes/s, 111 MiB/s (117,358,641 bytes/s))
2019-04-11 06:23:22.869+0000 WARN [o.n.k.i.c.VmPauseMonitorComponent] Detected VM stop-the-world pause: {pauseTime=1775, gcTime=6, gcCount=1}
2019-04-11 06:23:24.900+0000 WARN [o.n.k.i.c.VmPauseMonitorComponent] Detected VM stop-the-world pause: {pauseTime=1630, gcTime=9, gcCount=1}
2019-04-11 06:23:26.751+0000 WARN [o.n.k.i.c.VmPauseMonitorComponent] Detected VM stop-the-world pause: {pauseTime=1751, gcTime=1, gcCount=1}
2019-04-11 06:23:28.958+0000 WARN [o.n.k.i.c.VmPauseMonitorComponent] Detected VM stop-the-world pause: {pauseTime=2106, gcTime=4, gcCount=1}
2019-04-11 06:23:30.829+0000 WARN [o.n.k.i.c.VmPauseMonitorComponent] Detected VM stop-the-world pause: {pauseTime=1771, gcTime=7972, gcCount=2}
2019-04-11 06:23:33.115+0000 WARN [o.n.k.i.c.VmPauseMonitorComponent] Detected VM stop-the-world pause: {pauseTime=1583, gcTime=8, gcCount=1}
2019-04-11 06:23:39.466+0000 INFO [o.n.k.i.p.Procedures] [relationship-store-scan-0] LOADING 56% Memory usage: 187 GiB
2019-04-11 06:25:17.945+0000 INFO [o.n.k.i.p.Procedures] [relationship-store-scan-0] LOADING 57% Memory usage: 188 GiB
2019-04-11 06:26:56.211+0000 INFO [o.n.k.i.p.Procedures] [relationship-store-scan-0] LOADING 59% Memory usage: 189 GiB
2019-04-11 06:28:33.595+0000 INFO [o.n.k.i.p.Procedures] [relationship-store-scan-0] LOADING 61% Memory usage: 190 GiB
2019-04-11 06:30:12.410+0000 INFO [o.n.k.i.p.Procedures] [relationship-store-scan-0] LOADING 62% Memory usage: 191 GiB
2019-04-11 06:31:57.570+0000 INFO [o.n.k.i.p.Procedures] [relationship-store-scan-0] LOADING 64% Memory usage: 192 GiB
2019-04-11 06:33:36.993+0000 INFO [o.n.k.i.p.Procedures] [relationship-store-scan-0] LOADING 66% Memory usage: 193 GiB
2019-04-11 06:35:17.555+0000 INFO [o.n.k.i.p.Procedures] [relationship-store-scan-0] LOADING 67% Memory usage: 194 GiB
2019-04-11 06:36:56.262+0000 INFO [o.n.k.i.p.Procedures] [relationship-store-scan-0] LOADING 69% Memory usage: 195 GiB
2019-04-11 06:38:48.674+0000 INFO [o.n.k.i.p.Procedures] [relationship-store-scan-0] LOADING 71% Memory usage: 195 GiB
2019-04-11 06:41:07.555+0000 INFO [o.n.k.i.p.Procedures] [relationship-store-scan-0] LOADING 72% Memory usage: 196 GiB
2019-04-11 06:43:27.016+0000 INFO [o.n.k.i.p.Procedures] [relationship-store-scan-0] LOADING 74% Memory usage: 197 GiB
2019-04-11 06:45:51.206+0000 INFO [o.n.k.i.p.Procedures] [relationship-store-scan-0] LOADING 76% Memory usage: 198 GiB
2019-04-11 06:48:15.246+0000 INFO [o.n.k.i.p.Procedures] [relationship-store-scan-0] LOADING 77% Memory usage: 198 GiB
2019-04-11 06:50:46.333+0000 INFO [o.n.k.i.p.Procedures] [relationship-store-scan-0] LOADING 79% Memory usage: 199 GiB
2019-04-11 06:53:10.406+0000 INFO [o.n.k.i.p.Procedures] [relationship-store-scan-0] LOADING 81% Memory usage: 200 GiB
2019-04-11 06:55:41.587+0000 INFO [o.n.k.i.p.Procedures] [relationship-store-scan-0] LOADING 82% Memory usage: 201 GiB
2019-04-11 06:58:06.466+0000 INFO [o.n.k.i.p.Procedures] [relationship-store-scan-0] LOADING 84% Memory usage: 201 GiB
2019-04-11 07:00:39.971+0000 INFO [o.n.k.i.p.Procedures] [relationship-store-scan-0] LOADING 85% Memory usage: 202 GiB
2019-04-11 07:02:58.472+0000 INFO [o.n.k.i.p.Procedures] [relationship-store-scan-0] LOADING 87% Memory usage: 203 GiB
  • 写回答

4条回答 默认 最新

  • weixin_39615596 2020-11-19 11:09
    关注

    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}
    评论

报告相同问题？