知识库

debug.log 消息“上次检查点后发现的提交”解释

例如，在运行备份时

$ bin/neo4j-admin backup --backup-dir=/home/neo4j/backups/01172020/ --name=graph.db

您可能会在所述命令的输出中观察到类似的详细信息：

2020-01-17 12:54:06.767+0000 INFO [o.n.b.i.BackupOutputMonitor] Finish receiving store file /home/neo4j/backups/backups/01172020/graph.db/temp-copy/schema/index/lucene_native-2.0/5/native-1.0/profiles/index-5.708254.cacheprof
2020-01-17 12:54:06.767+0000 INFO [o.n.b.i.BackupOutputMonitor] Start receiving store file /home/neo4j/backups/backups/01172020/graph.db/temp-copy/schema/index/lucene_native-2.0/5/string-1.0/profiles/index-5.708254.cacheprof
2020-01-17 12:54:06.767+0000 INFO [o.n.b.i.BackupOutputMonitor] Finish receiving store file /home/neo4j/backups/backups/01172020/graph.db/temp-copy/schema/index/lucene_native-2.0/5/string-1.0/profiles/index-5.708254.cacheprof
2020-01-17 12:54:06.767+0000 INFO [o.n.b.i.BackupOutputMonitor] Start receiving store file /home/neo4j/backups/backups/01172020/graph.db/temp-copy/neostore
2020-01-17 12:54:06.767+0000 INFO [o.n.b.i.BackupOutputMonitor] Finish receiving store file /home/neo4j/backups/backups/01172020/graph.db/temp-copy/neostore
2020-01-17 12:54:06.769+0000 INFO [o.n.b.i.BackupOutputMonitor] Finish receiving store files, took 9s 552ms
2020-01-17 12:54:06.869+0000 INFO [o.n.b.i.BackupOutputMonitor] Start recovering store
2020-01-17 12:59:34.411+0000 INFO [o.n.b.i.BackupOutputMonitor] Finish recovering store, took 5m 27s 542ms
2020-01-17 12:59:37.370+0000 INFO [o.n.b.i.BackupOutputMonitor] Finished, took 5m 40s 157m

并且会看到从 Start Recovering store 到 Finished recovering store 之间存在长时间的停顿（例如 5 分钟以上）。

需要注意的是，在屏幕输出产生的同时，我们还将 debug.log. 文件记录到备份目标的路径下，在此例中是 /home/neo4j/backups/01172020/，您会看到类似以下的消息：

2020-01-17 12:54:06.869+0000 INFO [o.n.k.NeoStoreDataSource] Commits found after last check point (which is at LogPosition{logVersion=26059, byteOffset=219081898}). First txId after last checkpoint: 643034051
2020-01-17 12:54:06.929+0000 INFO [o.n.k.NeoStoreDataSource] Recovery required from position LogPosition{logVersion=26059, byteOffset=219081898}
2020-01-17 12:54:34.411+0000 INFO [o.n.k.r.Recovery]   10% completed
2020-01-17 12:54:35.232+0000 INFO [o.n.k.r.Recovery]   20% completed
2020-01-17 12:54:35.338+0000 INFO [o.n.k.r.Recovery]   30% completed
2020-01-17 12:56:02.151+0000 INFO [o.n.k.r.Recovery]   40% completed
2020-01-17 12:56:21.642+0000 INFO [o.n.k.r.Recovery]   50% completed
2020-01-17 12:56:49.419+0000 INFO [o.n.k.r.Recovery]   60% completed
2020-01-17 12:58:06.401+0000 INFO [o.n.k.r.Recovery]   70% completed
2020-01-17 12:58:14.209+0000 INFO [o.n.k.r.Recovery]   80% completed
2020-01-17 12:58:48.040+0000 INFO [o.n.k.r.Recovery]   90% completed
2020-01-17 12:59:34.411+0000 INFO [o.n.k.r.Recovery]   100% completed
2020-01-17 12:59:34.411+0000 INFO [o.n.k.NeoStoreDataSource] Recovery completed. 215589 transactions, first:643034051, last:643249639 recovered

这些消息和延迟的原因是由于备份运行方式以及其执行检查点的方式。当运行备份时，首先执行数据库检查点，这将所有页面缓存数据刷新到存储文件（即 graph.db/neostore.*.db）中。然后备份会将文件从正在运行的 data/databases/graph.db 复制到备份目标。一旦所有文件复制完成，它会回头查看自文件最初复制到备份目标以来是否添加了任何事务，如果存在事务，它将执行上述“恢复”操作。例如，如果备份在 09:00 开始，并且从 09:00 到 09:04，它将所有 data/database/graph.db 文件复制到备份目标，而在这 4 分钟内有 10k 个新事务提交到数据库，那么备份将执行“恢复”操作，以便捕获这额外的 10k 个事务，并将它们也写入备份目标。

© . All rights reserved.