为什么 Amazon RDS 数据库实例的时间点还原需要很长时间?

上次更新日期:2022 年 7 月 6 日

我正在对我的 Amazon Relational Database Service(Amazon RDS)数据库实例执行时间点还原操作。此操作耗费很长时间才能完成。

简短描述

使用还原到时间点选项,您可以将数据库实例还原到启用了自动备份的特定时间点。启用了自动备份的 Amazon RDS 实例可以还原到最早的可还原时间。最早可还原时间指定在备份保留期内可以还原实例的时间。最大保留期设置为 35 天,即 5 个日历周。您可以通过修改实例将此值从 0 天更改为 35 天。在保留期内,您可以启动时间点还原并指定任何日期和时间,最多为最近可还原时间。最近可还原时间是您可以从中还原实例的最近时间。

您可以使用 AWS 命令行界面(AWS CLI)命令 describe-db-instances 返回实例的最近可还原时间。最迟可还原时间通常在最近五分钟内。您还可以通过在 Amazon RDS 控制台中选择自动备份来查找最近可还原时间。

当您为数据库实例启动时间点还原时,Amazon RDS 会代表您调用 RestoreDBInstanceToPointInTime API。此 API 在 AWS CloudTrail 中进行跟踪。有关更多信息,请参阅在 CloudTrail 控制台中查看 CloudTrail 事件

您还可以通过查看 RDS 日志文件来检查时间点还原的进度。从备份还原 RDS 实例后,您可以使用 RDS 日志文件跟踪恢复进度。

RDS 每五分钟将数据库实例的事务日志上传到 Amazon Simple Storage Service(Amazon S3)。在时间点还原期间,最接近时间点中提到的时间的快照将首先得到还原。然后,事务日志将一直应用到您在启动时间点还原时提到的时间为止。此操作可能需要更长的时间,具体取决于必须应用的事务日志的数量。

例如,假设您在今天 04:00 UTC 对数据库实例进行了自动备份,并且必须在 06:15 UTC 执行时间点还原。在这种情况下,实例会从 04:00 UTC 创建的备份中还原。然后,将 06:16 UTC 之前的事务日志应用于还原的实例,以便完成时间点还原过程。

解决方法

使用以下最佳实践来缩短将数据库实例还原到特定时间点所需的时间:

  • 如果您在源实例上启用了自动备份,则最佳实践是定期手动拍摄快照,避免大量增量更改堆积,从而降低恢复点目标
  • 请确保在时间点还原时源数据库上没有长时间运行的查询。长时间运行的事务会延长恢复时间,这意味着数据库可能需要更长的时间才可用。
  • 尽可能使用合适的事务日志大小。大型事务一次写入事务文件,不会拆分到不同的文件中。因此,事务日志文件最终超出了必要的规模,从而增加了崩溃恢复时间。
  • 在时间点还原期间,实例快照得到还原后,来自 S3 中快照的数据将被复制到底层 Amazon Elastic Block Store(Amazon EBS)卷中。此过程称为延迟加载。当您尝试访问尚未复制的数据块时,RDS 会从 S3 中提取该数据块,导致 I/O 延迟。为了减轻延迟加载对需要快速访问的表的影响,您可以执行涉及全表扫描的操作,例如 SELECT *。这允许 Amazon RDS 从 S3 下载所有备份的表数据。

示例:

将 RDS for PostgreSQL 数据库实例还原到特定时间点时,您可能会在日志文件中看到以下信息:

2022-06-01 13:16:19 UTC::@:[8613]:LOG: starting point-in-time recovery to 2022-06-01 12:54:30+00
2022-06-01 13:16:19 UTC::@:[8613]:LOG: redo starts at 0/48A3220
waiting for 000000010000000000000001 archive /rdsdbdata/log/restore/pg-wal-archive.1.* to be downloaded
2022-06-01 13:17:22 UTC:127.0.0.1(46110):rdsadmin@rdsadmin:[10322]:FATAL: the database system is starting up
2022-06-01 13:17:25 UTC::@:[8613]:LOG: restored log file "000000010000000000000001" from archive
recovering 000000010000000000000002
2022-06-01 13:17:26 UTC::@:[8613]:LOG: restored log file "000000010000000000000002" from archive
recovering 000000010000000000000003
2022-06-01 13:17:28 UTC::@:[8613]:LOG: restored log file "000000010000000000000003" from archive
recovering 000000010000000000000004
2022-06-01 13:18:54 UTC::@:[8613]:LOG: restored log file "000000010000000000000022" from archive
recovering 000000010000000000000023
.
.
2022-06-01 13:33:16 UTC::@:[8613]:LOG: restored log file "00000001000000060000000B" from archive
2022-06-01 13:33:16 UTC::@:[8613]:LOG: recovery stopping before commit of transaction 9266438, time 2022-06-01 12:56:14.648042+00
2022-06-01 13:33:16 UTC::@:[8613]:LOG: redo done at 6/2C0003C0
2022-06-01 13:33:16 UTC::@:[8613]:LOG: last completed transaction was at log time 2022-06-01 12:51:14.646151+00
recovering 00000002.history
2022-06-01 13:33:16 UTC::@:[8613]:LOG: selected new timeline ID: 2
2022-06-01 13:33:16 UTC::@:[8613]:LOG: archive recovery complete
recovering 00000001.history
2022-06-01 13:33:16 UTC::@:[8620]:LOG: checkpoint starting: end-of-recovery immediate wait
2022-06-01 13:33:16 UTC::@:[8620]:LOG: checkpoint complete: wrote 2 buffers (0.0%); 0 WAL file(s) added, 0 removed, 8 recycled; write=0.002 s, sync=0.003 s, total=0.031 s; sync files=2, longest=0.003 s, average=0.002 s; distance=655360 kB, estimate=1611806 
kB
2022-06-01 13:33:16 UTC::@:[8607]:LOG: database system is ready to accept connections
2022-06-01 13:37:18 UTC::@:[8607]:LOG: received fast shutdown request
2022-06-01 13:37:18 UTC::@:[8607]:LOG: aborting any active transactions
2022-06-01 13:37:18 UTC::@:[8607]:LOG: background worker "logical replication launcher" (PID 7394) exited with exit code 1
2022-06-01 13:37:18 UTC::@:[8620]:LOG: shutting down
2022-06-01 13:37:18 UTC::@:[8620]:LOG: checkpoint starting: shutdown immediate
2022-06-01 13:37:18 UTC::@:[8620]:LOG: checkpoint complete: wrote 9 buffers (0.0%); 0 WAL file(s) added, 0 removed, 1 recycled; write=0.003 s, sync=0.003 s, total=0.024 s; sync files=7, longest=0.003 s, average=0.001 s; distance=65535 kB, estimate=1457179
        kB
2022-06-01 13:37:20 UTC::@:[8607]:LOG: database system is shut down
2022-06-01 13:37:24 UTC::@:[10870]:LOG: starting PostgreSQL 13.4 on x86_64-pc-linux-gnu, compiled by gcc (GCC) 7.3.1 20180712 (Red Hat 7.3.1-12), 64-bit
2022-06-01 13:37:24 UTC::@:[10870]:LOG: listening on IPv4 address "0.0.0.0", port 5432
2022-06-01 13:37:24 UTC::@:[10870]:LOG: listening on IPv6 address "::", port 5432
2022-06-01 13:37:24 UTC::@:[10870]:LOG: listening on Unix socket "/tmp/.s.PGSQL.5432"
2022-06-01 13:37:24 UTC::@:[10875]:LOG: database system was shut down at 2022-06-01 13:37:18 UTC
2022-06-01 13:37:24 UTC::@:[10870]:LOG: database system is ready to accept connections