知识库

提交检查点后找到提交的 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

并看到从 `开始恢复存储` 到 `完成恢复存储` 有一个较长的暂停（例如 5 分钟以上）。

需要注意的是，在产生屏幕输出的同时，我们也正在将日志记录到备份目标路径的 debug.log.<epochtime> 中，在这种情况下为 /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）中。然后，备份将从运行中的数据/数据库/graph.db 文件复制到备份目标。复制完所有文件后，它将回溯查看自初始文件复制到备份目标后是否添加了任何事务，如果有事务，它将执行上面描述的“恢复”。例如，如果备份是在 09:00 开始的，从 09:00 到 09:04 它将所有数据/数据库/graph.db 文件复制到备份目标，在这 4 分钟内，有 10k 个新事务提交到数据库，那么备份将执行“恢复”，以便捕获这些额外的 10k 个事务，以便它们也写入备份目标。