search

neo4j-contrib / neo4j-graph-algorithms

Efficient Graph Algorithms for Neo4j
https://github.com/neo4j/graph-data-science/
GNU General Public License v3.0
769 stars 195 forks source link

Locking issue for UNIONFIND on latest release #883

Closed bsquire0128 closed 5 years ago

bsquire0128 commented 5 years ago

It has gotten stuck twice. It worked at a smaller dataset size but upgrading to 2 TB datastore seems to kill it.

Config: Heap 410 GB PC: 30 GB GC - Shenandoah

cmd:

CALL algo.unionFind(null, 'OBSERVED_WITH', {write:true, graph:'huge', partitionProperty:"community",concurrency:2})
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

2019-04-11 05:18:05.494+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 430.866 s, 10,574,838.47 Nodes/s, 151 MiB/s (158,623,196 bytes/s) (per thread: 5,287,419.24 Nodes/s, 75 MiB/s (79,311,598 bytes/s))
2019-04-11 05:18:41.953+0000 WARN [o.n.k.i.c.VmPauseMonitorComponent] Detected VM stop-the-world pause: {pauseTime=870, gcTime=7, gcCount=1}
2019-04-11 05:18:43.090+0000 WARN [o.n.k.i.c.VmPauseMonitorComponent] Detected VM stop-the-world pause: {pauseTime=736, gcTime=9, gcCount=1}
2019-04-11 05:18:44.036+0000 WARN [o.n.k.i.c.VmPauseMonitorComponent] Detected VM stop-the-world pause: {pauseTime=844, gcTime=0, gcCount=1}
2019-04-11 05:18:45.242+0000 WARN [o.n.k.i.c.VmPauseMonitorComponent] Detected VM stop-the-world pause: {pauseTime=804, gcTime=6, gcCount=1}
2019-04-11 05:18:46.219+0000 WARN [o.n.k.i.c.VmPauseMonitorComponent] Detected VM stop-the-world pause: {pauseTime=876, gcTime=4231, gcCount=2}
2019-04-11 05:18:47.469+0000 WARN [o.n.k.i.c.VmPauseMonitorComponent] Detected VM stop-the-world pause: {pauseTime=748, gcTime=7, gcCount=1}
2019-04-11 05:18:48.428+0000 WARN [o.n.k.i.c.VmPauseMonitorComponent] Detected VM stop-the-world pause: {pauseTime=858, gcTime=1, gcCount=1}
2019-04-11 05:18:49.732+0000 WARN [o.n.k.i.c.VmPauseMonitorComponent] Detected VM stop-the-world pause: {pauseTime=702, gcTime=4, gcCount=1}
2019-04-11 05:18:50.718+0000 WARN [o.n.k.i.c.VmPauseMonitorComponent] Detected VM stop-the-world pause: {pauseTime=886, gcTime=4531, gcCount=2}
2019-04-11 05:18:51.995+0000 WARN [o.n.k.i.c.VmPauseMonitorComponent] Detected VM stop-the-world pause: {pauseTime=675, gcTime=8, gcCount=1}
2019-04-11 05:18:55.765+0000 INFO [o.n.k.i.p.Procedures] [relationship-store-scan-0] LOADING 56% Memory usage: 175 GiB
2019-04-11 05:19:44.851+0000 INFO [o.n.k.i.p.Procedures] [relationship-store-scan-1] LOADING 57% Memory usage: 176 GiB
2019-04-11 05:20:33.963+0000 INFO [o.n.k.i.p.Procedures] [relationship-store-scan-0] LOADING 59% Memory usage: 177 GiB
2019-04-11 05:21:26.715+0000 INFO [o.n.k.i.p.Procedures] [relationship-store-scan-0] LOADING 61% Memory usage: 178 GiB
2019-04-11 05:22:15.855+0000 INFO [o.n.k.i.p.Procedures] [relationship-store-scan-1] LOADING 62% Memory usage: 179 GiB
2019-04-11 05:23:08.188+0000 INFO [o.n.k.i.p.Procedures] [relationship-store-scan-1] LOADING 64% Memory usage: 180 GiB
2019-04-11 05:24:00.327+0000 INFO [o.n.k.i.p.Procedures] [relationship-store-scan-1] LOADING 66% Memory usage: 181 GiB
2019-04-11 05:24:51.014+0000 INFO [o.n.k.i.p.Procedures] [relationship-store-scan-0] LOADING 67% Memory usage: 182 GiB
2019-04-11 05:25:41.496+0000 INFO [o.n.k.i.p.Procedures] [relationship-store-scan-1] LOADING 69% Memory usage: 183 GiB
2019-04-11 05:26:38.531+0000 INFO [o.n.k.i.p.Procedures] [relationship-store-scan-0] LOADING 71% Memory usage: 183 GiB
2019-04-11 05:27:50.569+0000 INFO [o.n.k.i.p.Procedures] [relationship-store-scan-1] LOADING 72% Memory usage: 184 GiB
2019-04-11 05:29:06.525+0000 INFO [o.n.k.i.p.Procedures] [relationship-store-scan-0] LOADING 74% Memory usage: 185 GiB
2019-04-11 05:30:20.294+0000 INFO [o.n.k.i.p.Procedures] [relationship-store-scan-0] LOADING 76% Memory usage: 186 GiB
2019-04-11 05:31:32.893+0000 INFO [o.n.k.i.p.Procedures] [relationship-store-scan-0] LOADING 77% Memory usage: 186 GiB
2019-04-11 05:32:48.474+0000 INFO [o.n.k.i.p.Procedures] [relationship-store-scan-1] LOADING 79% Memory usage: 187 GiB
2019-04-11 05:34:02.460+0000 INFO [o.n.k.i.p.Procedures] [relationship-store-scan-1] LOADING 81% Memory usage: 188 GiB
2019-04-11 05:35:22.125+0000 INFO [o.n.k.i.p.Procedures] [relationship-store-scan-0] LOADING 82% Memory usage: 189 GiB
2019-04-11 05:36:36.140+0000 INFO [o.n.k.i.p.Procedures] [relationship-store-scan-1] LOADING 84% Memory usage: 189 GiB
2019-04-11 05:37:53.681+0000 INFO [o.n.k.i.p.Procedures] [relationship-store-scan-1] LOADING 85% Memory usage: 190 GiB
2019-04-11 05:39:02.143+0000 INFO [o.n.k.i.p.Procedures] [relationship-store-scan-0] LOADING 87% Memory usage: 191 GiB
2019-04-11 05:40:15.070+0000 INFO [o.n.k.i.p.Procedures] [relationship-store-scan-0] LOADING 89% Memory usage: 192 GiB
2019-04-11 05:41:19.121+0000 INFO [o.n.k.i.p.Procedures] [relationship-store-scan-1] LOADING 90% Memory usage: 192 GiB
2019-04-11 05:42:26.312+0000 INFO [o.n.k.i.p.Procedures] [relationship-store-scan-1] LOADING 92% Memory usage: 193 GiB
2019-04-11 05:43:31.926+0000 INFO [o.n.k.i.p.Procedures] [relationship-store-scan-1] LOADING 94% Memory usage: 194 GiB
2019-04-11 05:44:39.117+0000 INFO [o.n.k.i.p.Procedures] [relationship-store-scan-0] LOADING 95% Memory usage: 195 GiB
2019-04-11 05:45:51.709+0000 INFO [o.n.k.i.p.Procedures] [relationship-store-scan-0] LOADING 97% Memory usage: 195 GiB
2019-04-11 05:46:57.321+0000 INFO [o.n.k.i.p.Procedures] [relationship-store-scan-1] LOADING 99% Memory usage: 196 GiB
2019-04-11 05:50:49.778+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 1917.780 s, 1,857,628.93 Relationships/s, 124 MiB/s (130,187,346 bytes/s) (per thread: 928,814.47 Relationships/s, 62 MiB/s (65,093,673 bytes/s))
2019-04-11 05:50:49.798+0000 INFO [o.n.k.i.p.Procedures] [neo4j.BoltWorker-5 [bolt] [/127.0.0.1:44134] ] LOADING 100% Memory usage: 172 GiB
2019-04-11 05:51:15.949+0000 INFO [o.n.k.i.p.Procedures] [algo-16] CC(HugeParallelUnionFindQueue) 100%
2019-04-11 05:51:42.376+0000 INFO [o.n.k.i.p.Procedures] [algo-15] CC(HugeParallelUnionFindQueue) 94%
jexp commented 5 years ago

Was this resolved with 3.5.4.0 ?

bsquire0128 commented 5 years ago

yes. Can be closed