Neo4j-admin check-consistency problem

[joshua_madan]

Desktop version: 1.2.3
Neoj version: 3.5.14
OS: macOS Catalina
Java version: openjdk version "1.8.0_232"

I am trying to run check-consistency on a database. I have tried this on both Ubuntu and MacOS with identical behavior. Running a Full Consistency Check the first 85% or so completes and then the process just pegs the CPU with no noticeable change in memory consumption or disk IO. I have allowed the neo4j-admin process to run for over 12 hours like this before interrupting it.

Memory settings from the config:
dbms.memory.heap.initial_size=12G
dbms.memory.heap.max_size=12G
dbms.memory.pagecache.size=16G

The output:

➜ bin/neo4j-admin check-consistency --database=graph.db --verbose
2020-01-14 09:02:15.914+0000 INFO [o.n.k.i.s.f.RecordFormatSelector] Selected RecordFormat:StandardV3_4[v0.A.9] record format from store /Users/njm/Library/Application Support/Neo4j Desktop/Application/neo4jDatabases/database-cd7d7a0e-cd92-42dd-8867-6755f5b9b621/installation-3.5.14/data/databases/graph.db
2020-01-14 09:02:15.915+0000 INFO [o.n.k.i.s.f.RecordFormatSelector] Format not configured. Selected format from the store: RecordFormat:StandardV3_4[v0.A.9]
SLF4J: Class path contains multiple SLF4J bindings.
SLF4J: Found binding in [jar:file:/Users/njm/Library/Application%20Support/Neo4j%20Desktop/Application/neo4jDatabases/database-cd7d7a0e-cd92-42dd-8867-6755f5b9b621/installation-3.5.14/lib/slf4j-nop-1.7.25.jar!/org/slf4j/impl/StaticLoggerBinder.class]
SLF4J: Found binding in [jar:file:/Users/njm/Library/Application%20Support/Neo4j%20Desktop/Application/neo4jDatabases/database-cd7d7a0e-cd92-42dd-8867-6755f5b9b621/installation-3.5.14/plugins/neo4j-gl-plugin-2.2.4.jar!/org/slf4j/impl/StaticLoggerBinder.class]
SLF4J: See http://www.slf4j.org/codes.html#multiple_bindings for an explanation.
SLF4J: Actual binding is of type [org.slf4j.helpers.NOPLoggerFactory]
Full Consistency Check
...........2020-01-14 09:02:53.216+0000 INFO [o.n.c.ConsistencyCheckService] === Stage1_NS_PropsLabels ===
2020-01-14 09:02:53.216+0000 INFO [o.n.c.ConsistencyCheckService] I/Os
RelationshipGroupStore
Reads: 91122
Random Reads: 81894
ScatterIndex: 89

2020-01-14 09:02:53.216+0000 INFO [o.n.c.ConsistencyCheckService] Counts:
99262277 nodeSparse
91122 nodeDense
2020-01-14 09:02:53.219+0000 INFO [o.n.c.ConsistencyCheckService] Memory[used:524.19 MB, free:11.45 GB, total:11.96 GB, max:11.96 GB]
2020-01-14 09:02:53.220+0000 INFO [o.n.c.ConsistencyCheckService] Done in 35s 897ms
......... 10%
.................... 20%
.............2020-01-14 09:05:40.461+0000 INFO [o.n.c.ConsistencyCheckService] === Stage2_RS_Labels ===
2020-01-14 09:05:40.470+0000 INFO [o.n.c.ConsistencyCheckService] I/Os

2020-01-14 09:05:40.472+0000 INFO [o.n.c.ConsistencyCheckService] Counts:
2020-01-14 09:05:40.477+0000 INFO [o.n.c.ConsistencyCheckService] Memory[used:3.32 GB, free:8.68 GB, total:12.00 GB, max:12.00 GB]
2020-01-14 09:05:40.478+0000 INFO [o.n.c.ConsistencyCheckService] Done in 2m 47s 257ms
....... 30%
.................... 40%
...........2020-01-14 09:17:23.964+0000 INFO [o.n.c.ConsistencyCheckService] === Stage4_RS_NextRel ===
2020-01-14 09:17:23.965+0000 INFO [o.n.c.ConsistencyCheckService] I/Os
NodeStore
Reads: 625001
Random Reads: 526029
ScatterIndex: 84
PropertyStore
Reads: 5130316
Random Reads: 1260862
ScatterIndex: 24

2020-01-14 09:17:23.965+0000 INFO [o.n.c.ConsistencyCheckService] Counts:
2020-01-14 09:17:23.967+0000 INFO [o.n.c.ConsistencyCheckService] Memory[used:666.43 MB, free:11.35 GB, total:12.00 GB, max:12.00 GB]
2020-01-14 09:17:23.967+0000 INFO [o.n.c.ConsistencyCheckService] Done in 11m 28s 472ms
......... 50%
.................... 60%
.........2020-01-14 09:21:55.733+0000 INFO [o.n.c.ConsistencyCheckService] === Stage6_RS_Forward ===
2020-01-14 09:21:55.734+0000 INFO [o.n.c.ConsistencyCheckService] I/Os
RelationshipStore
Reads: 380163053
Random Reads: 280311990
ScatterIndex: 73

2020-01-14 09:21:55.734+0000 INFO [o.n.c.ConsistencyCheckService] Counts:
1012900731 skipCheck
359078123 missCheck
862425795 checked
1012900731 correctSkipCheck
25913971 skipBackup
488851003 overwrite
101863398 noCacheSkip
319024863 activeCache
159512348 clearCache
187466869 relSourcePrevCheck
295797484 relSourceNextCheck
157556691 relTargetPrevCheck
221604751 relTargetNextCheck
829381316 forwardLinks
989028440 backLinks
158780168 nullLinks
2020-01-14 09:21:55.734+0000 INFO [o.n.c.ConsistencyCheckService] Memory[used:1.52 GB, free:10.48 GB, total:12.00 GB, max:12.00 GB]
2020-01-14 09:21:55.735+0000 INFO [o.n.c.ConsistencyCheckService] Done in 4m 29s 544ms
........... 70%
.................... 80%
........2020-01-14 09:26:37.348+0000 INFO [o.n.c.ConsistencyCheckService] === Stage7_RS_Backward ===
2020-01-14 09:26:37.348+0000 INFO [o.n.c.ConsistencyCheckService] I/Os
RelationshipStore
Reads: 384803432
Random Reads: 284446960
ScatterIndex: 73

2020-01-14 09:26:37.349+0000 INFO [o.n.c.ConsistencyCheckService] Counts:
1110142662 skipCheck
366686998 missCheck
866996114 checked
1110142662 correctSkipCheck
22875415 skipBackup
488851038 overwrite
51148 noCacheSkip
319024828 activeCache
159512348 clearCache
298714008 relSourcePrevCheck
183956028 relSourceNextCheck
219049232 relTargetPrevCheck
165276846 relTargetNextCheck
829381316 forwardLinks
989028440 backLinks
158780168 nullLinks
2020-01-14 09:26:37.349+0000 INFO [o.n.c.ConsistencyCheckService] Memory[used:2.85 GB, free:9.15 GB, total:12.00 GB, max:12.00 GB]
2020-01-14 09:26:37.349+0000 INFO [o.n.c.ConsistencyCheckService] Done in 4m 41s 614ms
2020-01-14 09:26:38.242+0000 INFO [o.n.c.ConsistencyCheckService] === RelationshipGroupStore-RelGrp ===
2020-01-14 09:26:38.242+0000 INFO [o.n.c.ConsistencyCheckService] I/Os
RelationshipStore
Reads: 624606
Random Reads: 648545
ScatterIndex: 103
RelationshipGroupStore
Reads: 465503
Random Reads: 303619
ScatterIndex: 65
NodeStore
Reads: 529612
Random Reads: 541849
ScatterIndex: 102

2020-01-14 09:26:38.244+0000 INFO [o.n.c.ConsistencyCheckService] Counts:
2020-01-14 09:26:38.245+0000 INFO [o.n.c.ConsistencyCheckService] Memory[used:3.33 GB, free:8.67 GB, total:12.00 GB, max:12.00 GB]
2020-01-14 09:26:38.245+0000 INFO [o.n.c.ConsistencyCheckService] Done in 895ms
....

[nielsson4711]

Could you please check if the database engine on database instance "graph.db" starts without observeable anomalies by calling "bin/neo4j console" ?

[joshua_madan]

Yes, it's fine:

➜ bin/neo4j console
Active database: graph.db
Directories in use:
home: /Users/njm/Library/Application Support/Neo4j Desktop/Application/neo4jDatabases/database-cd7d7a0e-cd92-42dd-8867-6755f5b9b621/installation-3.5.14
config: /Users/njm/Library/Application Support/Neo4j Desktop/Application/neo4jDatabases/database-cd7d7a0e-cd92-42dd-8867-6755f5b9b621/installation-3.5.14/conf
logs: /Users/njm/Library/Application Support/Neo4j Desktop/Application/neo4jDatabases/database-cd7d7a0e-cd92-42dd-8867-6755f5b9b621/installation-3.5.14/logs
plugins: /Users/njm/Library/Application Support/Neo4j Desktop/Application/neo4jDatabases/database-cd7d7a0e-cd92-42dd-8867-6755f5b9b621/installation-3.5.14/plugins
import: /Users/njm/Library/Application Support/Neo4j Desktop/Application/neo4jDatabases/database-cd7d7a0e-cd92-42dd-8867-6755f5b9b621/installation-3.5.14/import
data: /Users/njm/Library/Application Support/Neo4j Desktop/Application/neo4jDatabases/database-cd7d7a0e-cd92-42dd-8867-6755f5b9b621/installation-3.5.14/data
certificates: /Users/njm/Library/Application Support/Neo4j Desktop/Application/neo4jDatabases/database-cd7d7a0e-cd92-42dd-8867-6755f5b9b621/installation-3.5.14/certificates
run: /Users/njm/Library/Application Support/Neo4j Desktop/Application/neo4jDatabases/database-cd7d7a0e-cd92-42dd-8867-6755f5b9b621/installation-3.5.14/run
Starting Neo4j.
2020-01-15 13:43:52.302+0000 INFO ======== Neo4j 3.5.14 ========
2020-01-15 13:43:52.309+0000 INFO Starting...
SLF4J: Class path contains multiple SLF4J bindings.
SLF4J: Found binding in [jar:file:/Users/njm/Library/Application%20Support/Neo4j%20Desktop/Application/neo4jDatabases/database-cd7d7a0e-cd92-42dd-8867-6755f5b9b621/installation-3.5.14/lib/slf4j-nop-1.7.25.jar!/org/slf4j/impl/StaticLoggerBinder.class]
SLF4J: Found binding in [jar:file:/Users/njm/Library/Application%20Support/Neo4j%20Desktop/Application/neo4jDatabases/database-cd7d7a0e-cd92-42dd-8867-6755f5b9b621/installation-3.5.14/plugins/neo4j-gl-plugin-2.2.4.jar!/org/slf4j/impl/StaticLoggerBinder.class]
SLF4J: See http://www.slf4j.org/codes.html#multiple_bindings for an explanation.
SLF4J: Actual binding is of type [org.slf4j.helpers.NOPLoggerFactory]
2020-01-15 13:43:53.093+0000 INFO Initiating metrics...
2020-01-15 13:44:07.142+0000 INFO Sending metrics to CSV file at /Users/njm/Library/Application Support/Neo4j Desktop/Application/neo4jDatabases/database-cd7d7a0e-cd92-42dd-8867-6755f5b9b621/installation-3.5.14/metrics
2020-01-15 13:44:07.816+0000 INFO Bolt enabled on 127.0.0.1:7687.
2020-01-15 13:44:10.168+0000 WARN Server thread metrics not available (missing neo4j.server.threads.jetty.all)
2020-01-15 13:44:10.170+0000 WARN Server thread metrics not available (missing neo4j.server.threads.jetty.idle)
2020-01-15 13:44:10.725+0000 INFO Started.
2020-01-15 13:44:10.831+0000 INFO Mounted REST API at: /db/manage
2020-01-15 13:44:10.877+0000 INFO Loaded server plugin "NodeIndexerPlugin"
2020-01-15 13:44:10.878+0000 INFO GraphDatabaseService.enable: Enable reindexer and starts reindexing.
2020-01-15 13:44:10.880+0000 INFO GraphDatabaseService.disable: Disable reindexer which means reindexer is not automaticly indexing data.
2020-01-15 13:44:10.880+0000 INFO GraphDatabaseService.start: Start reindex of all nodes with specified label and specified properties. Use configure to chage label and properties.
2020-01-15 13:44:10.880+0000 INFO GraphDatabaseService.interrupt: Interrupt reindex process.
2020-01-15 13:44:10.881+0000 INFO GraphDatabaseService.pluginInfo: Return information about plugin.
2020-01-15 13:44:10.881+0000 INFO GraphDatabaseService.initIndex: Initialize nodes index.
2020-01-15 13:44:10.881+0000 INFO GraphDatabaseService.configure: Configure index.
2020-01-15 13:44:10.881+0000 INFO GraphDatabaseService.status: Status of indexer.
2020-01-15 13:44:10.884+0000 INFO Mounted unmanaged extension [org.neo4j.graphql] at [/graphql]
2020-01-15 13:44:10.992+0000 INFO Server thread metrics have been registered successfully
2020-01-15 13:44:11.937+0000 WARN The following warnings have been detected with resource and/or provider classes:
WARNING: A sub-resource method, public final javax.ws.rs.core.Response org.neo4j.graphql.GraphQLResourceExperimental.executeOperation(java.lang.String), with URI template, "", is treated as a resource method
WARNING: A sub-resource method, public final javax.ws.rs.core.Response org.neo4j.graphql.GraphQLResourceExperimental.get(java.lang.String,java.lang.String), with URI template, "", is treated as a resource method
WARNING: A sub-resource method, public final javax.ws.rs.core.Response org.neo4j.graphql.GraphQLResourceExperimental.options(javax.ws.rs.core.HttpHeaders), with URI template, "", is treated as a resource method
WARNING: A sub-resource method, public final javax.ws.rs.core.Response org.neo4j.graphql.ManagementResource.executeOperation(java.lang.String), with URI template, "", is treated as a resource method
WARNING: A sub-resource method, public final javax.ws.rs.core.Response org.neo4j.graphql.ManagementResource.get(java.lang.String,java.lang.String), with URI template, "", is treated as a resource method
WARNING: A sub-resource method, public final javax.ws.rs.core.Response org.neo4j.graphql.ManagementResource.options(javax.ws.rs.core.HttpHeaders), with URI template, "", is treated as a resource method
WARNING: A sub-resource method, public final javax.ws.rs.core.Response org.neo4j.graphql.GraphQLResource.executeOperation(java.lang.String), with URI template, "", is treated as a resource method
WARNING: A sub-resource method, public final javax.ws.rs.core.Response org.neo4j.graphql.GraphQLResource.get(java.lang.String,java.lang.String), with URI template, "", is treated as a resource method
WARNING: A sub-resource method, public final javax.ws.rs.core.Response org.neo4j.graphql.GraphQLResource.options(javax.ws.rs.core.HttpHeaders), with URI template, "", is treated as a resource method
2020-01-15 13:44:12.729+0000 INFO Remote interface available at http://localhost:7474/

[nielsson4711]

Hi Joshua
From my experience intermittent hung consistency checks on a certain community edition database where assumingly caused by inconsistencies in combination with heavy write load.
As you seem to use EE Desktop, I have no specific clue, except a more general suggestion to switch from openjdk 1.8 to 11 or 12. (I'm not particularly expecting this to solve your issue, but as I quite often experienced astonishing effects in applied IT I would give it a try).