How_to_use_zsql_backup_gaussdb?

任何数据库我们最关注的是数据安全；毫无疑问gaussdb也提供了较多的备份恢复工具；其中最常见的就是命令行zsql工具；我们首先尝试用zsql工具对数据库进行备份恢复；如下是相关测试，供大家参考。

–开始归档

SQL> alter database roger archivelog;

Succeed.

SQL> alter database open;

Succeed.

SQL>

–差异增量0 级备份（压缩）

SQL> BACKUP DATABASE INCREMENTAL LEVEL 0 FORMAT '/tmp/gaussdb_backup/roger_level0_01.bak' as compressed backupset;

Succeed.

SQL> exit

这里需要注意的是，我使用的是差异增量备份方式。

–查看备份进程情况

SQL> select * from V$BACKUP_PROCESS;

TYPE PROGRESS STAGE STATUS ERR_NO ERR_MSG TOTAL_PROC FREE_PROC

---------- ------------ ---------- ---------- ------------ ---------- ------------ ------------

backup 64 data files processing 0 4 3

1 rows fetched.

SQL> select * from V$BACKUP_PROCESS;

TYPE PROGRESS STAGE STATUS ERR_NO ERR_MSG TOTAL_PROC FREE_PROC

---------- ------------ ---------- ---------- ------------ ---------- ------------ ------------

backup 100 end success 0 0 0

1 rows fetched.

–check备份文件是否产生

[roger@mysqldb gaussdb_backup]$ ls -ltr /tmp/gaussdb_backup/roger_level0_01.bak

total 70376

-rw------- 1 roger roger 60722 Feb 14 17:58 ctrl_0_0.bak

-rw------- 1 roger roger 87 Feb 14 17:58 data_TEMP_1_0.bak

-rw------- 1 roger roger 632414 Feb 14 17:58 data_SYSTEM_0_0.bak

-rw------- 1 roger roger 88 Feb 14 17:58 data_TEMP2_9_0.bak

-rw------- 1 roger roger 86 Feb 14 17:58 data_TEMP2_UNDO_11_0.bak

-rw------- 1 roger roger 1862162 Feb 14 17:58 data_SYSAUX_12_0.bak

-rw------- 1 roger roger 23299905 Feb 14 17:58 data_UNDO_3_1.bak

-rw------- 1 roger roger 23307726 Feb 14 17:58 data_USERS_4_0.bak

-rw------- 1 roger roger 22854569 Feb 14 17:58 data_UNDO_3_0.bak

-rw------- 1 roger roger 14164 Feb 14 17:58 arch_12_0.bak

-rw------- 1 roger roger 4424 Feb 14 17:58 backupset

这里比较奇怪的是以为指定是备份集文件名字，其实是会创建该名称的目录，然后在目录下存放备份文件；可以看到是针对每个文件进行了备份。

—继续进行1级增量备份

SQL> conn roger/Roger007@127.0.0.1:1611

connected.

SQL> insert into test values(100,'www.modb.pro');

1 rows affected.

SQL> commit;

Succeed.

SQL> BACKUP DATABASE INCREMENTAL LEVEL 1 FORMAT '/tmp/gaussdb_backup/roger_level1_01.bak' as compressed backupset;

Succeed.

 

+++ 恢复测试

[roger@mysqldb gaussdata]$ rm -rf user*

[roger@mysqldb gaussdata]$ rm -rf sys*

[roger@mysqldb gaussdata]$ rm -rf undo*

[roger@mysqldb gaussdata]$ rm -rf temp*

[roger@mysqldb gaussdata]$ zsql / as sysdba -q

connected.

SQL> RESTORE DATABASE FROM '/tmp/gaussdb_backup/roger_level0_01.bak';

GS-00855, restore failed, Failed to create the file /opt/gauss/gaussdata/data/cntl1, the error code was 17

提示控制文件已经存在。在nomount下，居然不能覆盖控制文件。。。。好吧，我rm掉。

[roger@mysqldb gaussdata]$ rm cntl*

[roger@mysqldb gaussdata]$ cd data/

[roger@mysqldb data]$ ls -ltr

total 30720

-rw------- 1 roger roger 10485760 Feb 14 18:09 cntl1

-rw------- 1 roger roger 10485760 Feb 14 18:09 cntl2

-rw------- 1 roger roger 10485760 Feb 14 18:09 cntl3

[roger@mysqldb data]$ rm -rf *

[roger@mysqldb gaussdata]$ zengine nomount -D /opt/gauss/gaussdata &

[1] 91990

[roger@mysqldb gaussdata]$ starting instance(nomount)

instance started

 

–继续恢复测试

[roger@mysqldb data]$ zsql / as sysdba -q

connected.

SQL> restore database from '/tmp/gaussdb_backup/roger_level0_01.bak';

GS-00855, restore failed, Failed to create the file /opt/gauss/gaussdata/log1, the error code was 17

SQL>

 

好吧。restore 跟log居然也有关系。好吧。 重新删干净后再次运行(注意：我这里只是删除了redo log；并没有删除归档日志文件）。

[roger@mysqldb gaussdata]$ zsql / as sysdba -q

connected.

SQL> restore database from '/tmp/gaussdb_backup/roger_level0_01.bak';

Succeed.

可以看到全备恢复成功了。此时的全备restore的log信息如下：

UTC+8 2020-02-14 18:17:06.398|ZENGINE|00053|92312|INFO>[BACKUP] restore start, device:0, policy:, paral count 4, path:/tmp/gaussdb_backup/roger_level0_01.bak [knl_restore.c:1947]

UTC+8 2020-02-14 18:17:06.398|ZENGINE|00053|92312|INFO>[ARCH] Already initialized [knl_archive.c:803]

UTC+8 2020-02-14 18:17:06.403|ZENGINE|00000|95864|INFO>[BACKUP] parallel process 2 start [knl_bak_paral.c:996]

UTC+8 2020-02-14 18:17:06.403|ZENGINE|00000|95865|INFO>[BACKUP] parallel process 3 start [knl_bak_paral.c:996]

UTC+8 2020-02-14 18:17:06.403|ZENGINE|00000|95866|INFO>[BACKUP] parallel process 4 start [knl_bak_paral.c:996]

UTC+8 2020-02-14 18:17:06.403|ZENGINE|00000|95863|INFO>[BACKUP] parallel process 1 start [knl_bak_paral.c:996]

UTC+8 2020-02-14 18:17:06.532|ZENGINE|00053|94871532693656|INFO>[RESTORE] restore data_0_0, recent filesize 0K, section [0K, 16528K], bakcup id 1 [knl_bak_paral.c:374]

UTC+8 2020-02-14 18:17:06.634|ZENGINE|00053|94871532693656|INFO>[RESTORE] restore data_1_0, recent filesize 0K, section [0K, 16K], bakcup id 2 [knl_bak_paral.c:374]

UTC+8 2020-02-14 18:17:06.668|ZENGINE|00000|139818365449847|INFO>[RESTORE] fill datafile tail, start 16472K, end 16528K, backup id 1 [knl_bak_paral.c:763]

UTC+8 2020-02-14 18:17:06.733|ZENGINE|00053|94871532693656|INFO>[RESTORE] restore data_3_0, recent filesize 0K, section [0K, 393216K], bakcup id 3 [knl_bak_paral.c:374]

UTC+8 2020-02-14 18:17:06.733|ZENGINE|00053|94871532693656|INFO>[RESTORE] restore data_3_1, recent filesize 0K, section [393216K, 531920K], bakcup id 4 [knl_bak_paral.c:374]

UTC+8 2020-02-14 18:17:06.947|ZENGINE|00053|94871532693656|INFO>[RESTORE] restore data_4_0, recent filesize 0K, section [0K, 204240K], bakcup id 5 [knl_bak_paral.c:374]

UTC+8 2020-02-14 18:17:07.261|ZENGINE|00053|94871532693656|INFO>[RESTORE] restore data_9_0, recent filesize 0K, section [0K, 16K], bakcup id 6 [knl_bak_paral.c:374]

UTC+8 2020-02-14 18:17:07.588|ZENGINE|00053|94871532693656|INFO>[RESTORE] restore data_11_0, recent filesize 0K, section [0K, 16K], bakcup id 7 [knl_bak_paral.c:374]

UTC+8 2020-02-14 18:17:07.892|ZENGINE|00053|94871532693656|INFO>[RESTORE] restore data_12_0, recent filesize 0K, section [0K, 89648K], bakcup id 8 [knl_bak_paral.c:374]

UTC+8 2020-02-14 18:17:08.586|ZENGINE|00000|139818365449849|INFO>[RESTORE] fill datafile tail, start 204192K, end 204240K, backup id 5 [knl_bak_paral.c:763]

UTC+8 2020-02-14 18:17:09.043|ZENGINE|00000|95862|INFO>[RESTORE] restore datafiles finished [knl_restore.c:949]

UTC+8 2020-02-14 18:17:09.043|ZENGINE|00000|95862|INFO>[BACKUP] create logfiles completed [knl_restore.c:565]

UTC+8 2020-02-14 18:17:09.052|ZENGINE|00000|139818365449847|INFO>[RESTORE] start restore arch_12_0, backup id 9, log name /tmp/gaussdb_backup/roger_level0_01.bak/arch_12_0.bak [knl_bak_paral.c:673]

UTC+8 2020-02-14 18:17:09.054|ZENGINE|00000|139818365449847|INFO>[ARCH] Record archive log file /opt/gauss/gaussdata/archive_log/arch_0_12.arc for log [0-12] start 0 end 1 [knl_archive.c:284]

UTC+8 2020-02-14 18:17:09.146|ZENGINE|00000|95862|INFO>[RESTORE] restore logfiles finished, current backupset /tmp/gaussdb_backup/roger_level0_01.bak [knl_restore.c:964]

UTC+8 2020-02-14 18:17:42.642|ZENGINE|00000|95862|INFO>[ARCH] Record archive log file /opt/gauss/gaussdata/archive_log/arch_0_13.arc for log [0-13] start 0 end 2 [knl_archive.c:284]

UTC+8 2020-02-14 18:17:42.665|ZENGINE|00000|95863|INFO>[BACKUP] parallel process 1 stop [knl_bak_paral.c:1022]

UTC+8 2020-02-14 18:17:42.672|ZENGINE|00000|95864|INFO>[BACKUP] parallel process 2 stop [knl_bak_paral.c:1022]

UTC+8 2020-02-14 18:17:42.683|ZENGINE|00000|95865|INFO>[BACKUP] parallel process 3 stop [knl_bak_paral.c:1022]

UTC+8 2020-02-14 18:17:42.685|ZENGINE|00000|95866|INFO>[BACKUP] parallel process 4 stop [knl_bak_paral.c:1022]

UTC+8 2020-02-14 18:17:42.685|ZENGINE|00053|4995142158903240856|INFO>[BACKUP] restore success [knl_bak_common.c:1762]

可以看到默认情况下即会启动4个进程进行恢复操作。同时我们可以看到restore进程在完成数据文件restore之后，还自动注册了归档。

+++进行数据恢复操作

SQL> recover database;

Succeed.

SQL> alter database open;

Succeed.

SQL> conn roger/Roger007@127.0.0.1:1611

connected.

SQL> select * from test;

A B

---------------------------------------- --------------------

1 www.enmotech.com

1 www.killdb.com

100 www.modb.pro

3 rows fetched.

SQL>

可以看到，成功恢复了最新数据，无丢失。进一步观察此时recover的操作日志：

UTC+8 2020-02-14 18:21:00.863|ZENGINE|00053|92312|INFO>sucessfully alter database MOUNT [knl_database.c:1103]

UTC+8 2020-02-14 18:21:00.899|ZENGINE|00053|92312|INFO>database start recovery [knl_recovery.c:1457]

UTC+8 2020-02-14 18:21:00.899|ZENGINE|00053|92312|INFO>recovery from file:12,point:112,lfn:27160 [knl_recovery.c:1459]

UTC+8 2020-02-14 18:21:00.899|ZENGINE|00053|92312|INFO>recovery expected least end with file:12,point:112,lfn:27160 [knl_recovery.c:1461]

UTC+8 2020-02-14 18:21:01.010|ZENGINE|00053|139818365446296|INFO>[RCY] recovery real end with file:14,point:1,lfn:27247 [knl_recovery.c:1423]

UTC+8 2020-02-14 18:21:01.010|ZENGINE|00053|139818365446296|INFO>[RCY] current lfn 27247, rcy point lfn 27160, consistent point 27160, lrp point lfn 27160 [knl_recovery.c:1425]

UTC+8 2020-02-14 18:21:16.990|ZENGINE|00053|206158522520|INFO>start to alter database OPEN [knl_database.c:1322]

UTC+8 2020-02-14 18:21:17.071|ZENGINE|00053|139818365446296|INFO>[ARCH] Start ARCH thread for ARCHIVE_DEST_1[/opt/gauss/gaussdata/archive_log] [knl_archive.c:881]

UTC+8 2020-02-14 18:21:17.071|ZENGINE|00053|15214422880117942424|INFO>The last shutdown is inconsistent [knl_database.c:1379]

UTC+8 2020-02-14 18:21:17.071|ZENGINE|00053|92312|INFO>database start recovery [knl_recovery.c:1457]

UTC+8 2020-02-14 18:21:17.071|ZENGINE|00053|92312|INFO>recovery from file:13,point:750,lfn:27247 [knl_recovery.c:1459]

UTC+8 2020-02-14 18:21:17.071|ZENGINE|00053|92312|INFO>recovery expected least end with file:13,point:750,lfn:27247 [knl_recovery.c:1461]

UTC+8 2020-02-14 18:21:17.082|ZENGINE|00053|139818365446296|INFO>[RCY] recovery real end with file:14,point:1,lfn:27247 [knl_recovery.c:1423]

UTC+8 2020-02-14 18:21:17.082|ZENGINE|00053|139818365446296|INFO>[RCY] current lfn 27247, rcy point lfn 27247, consistent point 27247, lrp point lfn 27247 [knl_recovery.c:1425]

UTC+8 2020-02-14 18:21:17.148|ZENGINE|00053|139822660413592|INFO>no valid standby configuration [knl_lns.c:1727]

UTC+8 2020-02-14 18:21:17.152|ZENGINE|00053|92312|INFO>[DB] sse42 available 1 [knl_database.c:1440]

UTC+8 2020-02-14 18:21:17.152|ZENGINE|00053|92312|INFO>sucessfully alter database OPEN [knl_database.c:1441]

UTC+8 2020-02-14 18:21:17.300|ZENGINE|00000|92000|INFO>rollback thread closed [knl_tran.c:1203]

UTC+8 2020-02-14 18:21:17.304|ZENGINE|00000|91999|INFO>rollback thread closed [knl_tran.c:1203]

UTC+8 2020-02-14 18:21:17.924|ZENGINE|00054|99048|INFO>load index parts: load index parts, uid: 0, tid: 278, iid: 0, index partcnt: 4032 [knl_dc_part.c:993]

UTC+8 2020-02-14 18:21:17.926|ZENGINE|00054|99048|INFO>load index parts: load index parts, uid: 0, tid: 302, iid: 0, index partcnt: 4032 [knl_dc_part.c:993]

UTC+8 2020-02-14 18:21:17.928|ZENGINE|00054|99048|INFO>load index parts: load index parts, uid: 0, tid: 274, iid: 0, index partcnt: 4032 [knl_dc_part.c:993]

UTC+8 2020-02-14 18:21:17.933|ZENGINE|00054|99048|INFO>load index parts: load index parts, uid: 0, tid: 276, iid: 0, index partcnt: 4032 [knl_dc_part.c:993]

可以看到recover的起点：lfn:27160；recover的终点：lfn 27247 。

为了更好的熟悉gaussdb的备份相关原理；我进行了第二次恢复测试！

++++ 第二次恢复测试

删掉所有数据文件，redo文件，控制文件以及归档文件。

[roger@mysqldb gaussdata]$ rm -rf log4 log3 log2 log5 log6 log1

[roger@mysqldb gaussdata]$ rm -rf sys*

[roger@mysqldb gaussdata]$ rm -rf undo

[roger@mysqldb gaussdata]$ rm -rf temp*

[roger@mysqldb gaussdata]$ cd data/

[roger@mysqldb data]$ ls -ltr

total 30720

-rw------- 1 roger roger 10485760 Feb 14 18:51 cntl1

-rw------- 1 roger roger 10485760 Feb 14 18:51 cntl2

-rw------- 1 roger roger 10485760 Feb 14 18:51 cntl3

[roger@mysqldb data]$ rm -rf *

[roger@mysqldb gaussdata]$ cd archive_log/

[roger@mysqldb archive_log]$ ls -ltr

total 1335616

-rw------- 1 roger roger 133393920 Feb 14 12:55 arch_0_1.arc

-rw------- 1 roger roger 133582848 Feb 14 12:55 arch_0_2.arc

-rw------- 1 roger roger 133707776 Feb 14 12:55 arch_0_3.arc

-rw------- 1 roger roger 133812736 Feb 14 12:56 arch_0_4.arc

-rw------- 1 roger roger 132929536 Feb 14 16:32 arch_0_5.arc

-rw------- 1 roger roger 134062592 Feb 14 16:32 arch_0_6.arc

-rw------- 1 roger roger 132893184 Feb 14 16:32 arch_0_7.arc

-rw------- 1 roger roger 134105088 Feb 14 16:39 arch_0_8.arc

-rw------- 1 roger roger 134017536 Feb 14 16:48 arch_0_9.arc

-rw------- 1 roger roger 134163456 Feb 14 16:48 arch_0_10.arc

-rw------- 1 roger roger 30539264 Feb 14 17:53 arch_0_11.arc

-rw------- 1 roger roger 57344 Feb 14 17:58 arch_0_12.arc

-rw------- 1 roger roger 384000 Feb 14 18:06 arch_0_13.arc

[roger@mysqldb archive_log]$ rm -rf *

[roger@mysqldb archive_log]$ ls

[roger@mysqldb archive_log]$ cd ..

[roger@mysqldb gaussdata]$ ls -ltr

total 5083144

drwx------ 2 roger roger 42 Feb 13 16:23 dbs

-rw------- 1 roger roger 0 Feb 13 16:23 zengine.lck

drwx------ 5 roger roger 87 Feb 13 16:39 log

drwx------ 2 roger roger 4096 Feb 13 21:50 trc

-rw------- 1 roger roger 134217728 Feb 14 16:48 log3_bak

-rw------- 1 roger roger 134217728 Feb 14 16:48 log4_bak

-rw------- 1 roger roger 134217728 Feb 14 17:53 log5_bak

-rw------- 1 roger roger 134217728 Feb 14 17:58 log6_bak

-rw------- 1 roger roger 134217728 Feb 14 18:06 log1_bak

-rw------- 1 roger roger 134217728 Feb 14 18:06 log2_bak

drwx------ 2 roger roger 85 Feb 14 18:12 protect

-rw------- 1 roger roger 104857600 Feb 14 18:17 user5

-rw------- 1 roger roger 1073741824 Feb 14 18:17 user2

-rw------- 1 roger roger 1073741824 Feb 14 18:17 user3

-rw------- 1 roger roger 1073741824 Feb 14 18:17 user4

drwx------ 2 roger roger 62 Feb 14 18:20 cfg

-rw------- 1 roger roger 1073741824 Feb 14 18:26 user1

drwx------ 2 roger roger 6 Feb 14 18:57 data

drwx------ 2 roger roger 6 Feb 14 18:57 archive_log

[roger@mysqldb gaussdata]$ rm -rf user*

[roger@mysqldb gaussdata]$ rm -rf log*

[roger@mysqldb gaussdata]$ ls -ltr

total 4

drwx------ 2 roger roger 42 Feb 13 16:23 dbs

-rw------- 1 roger roger 0 Feb 13 16:23 zengine.lck

drwx------ 2 roger roger 4096 Feb 13 21:50 trc

drwx------ 2 roger roger 85 Feb 14 18:12 protect

drwx------ 2 roger roger 62 Feb 14 18:20 cfg

drwx------ 2 roger roger 6 Feb 14 18:57 data

drwx------ 2 roger roger 6 Feb 14 18:57 archive_log

[roger@mysqldb gaussdata]$ mkdir log

–启动实例到nomount

[roger@mysqldb gaussdata]$ zengine nomount -D /opt/gauss/gaussdata &

[1] 127423

[roger@mysqldb gaussdata]$ starting instance(nomount)

instance started

[roger@mysqldb gaussdata]$

[roger@mysqldb gaussdata]$ zsql / as sysdba -q

connected.

 

–进行restore & recover

SQL> restore database from '/tmp/gaussdb_backup/roger_level0_01.bak';

Succeed.

SQL> recover database;

Succeed.

SQL> alter database open;

Succeed.

SQL>

SQL> conn roger/Roger007@127.0.0.1:1611

connected.

SQL> select * from test;

A B

---------------------------------------- --------------------

1 www.enmotech.com

1 www.killdb.com

2 rows fetched. ----丢失了最新的一条数据

为什么会这样呢？我们进一步看一下此时的日志：

---如下是相关日志
TC+8 2020-02-14 18:58:54.292|ZENGINE|00053|127593|INFO>[BACKUP] restore start, device:0, policy:, paral count 4, path:/tmp/gaussdb_backup/roger_level0_01.bak [knl_restore.c:1947]
UTC+8 2020-02-14 18:58:54.292|ZENGINE|00053|127593|INFO>[ARCH] Initialization complete [knl_archive.c:824]
UTC+8 2020-02-14 18:58:54.304|ZENGINE|00000|127988|INFO>[BACKUP] parallel process 1 start [knl_bak_paral.c:996]
UTC+8 2020-02-14 18:58:54.316|ZENGINE|00000|127989|INFO>[BACKUP] parallel process 2 start [knl_bak_paral.c:996]
UTC+8 2020-02-14 18:58:54.316|ZENGINE|00000|127990|INFO>[BACKUP] parallel process 3 start [knl_bak_paral.c:996]
UTC+8 2020-02-14 18:58:54.316|ZENGINE|00000|127991|INFO>[BACKUP] parallel process 4 start [knl_bak_paral.c:996]
UTC+8 2020-02-14 18:58:54.420|ZENGINE|00053|93849330512489|INFO>[RESTORE] restore data_0_0, recent filesize 0K, section [0K, 16528K], bakcup id 1 [knl_bak_paral.c:374]
UTC+8 2020-02-14 18:58:54.520|ZENGINE|00053|93849330512489|INFO>[RESTORE] restore data_1_0, recent filesize 0K, section [0K, 16K], bakcup id 2 [knl_bak_paral.c:374]
UTC+8 2020-02-14 18:58:54.576|ZENGINE|00000|139693811430388|INFO>[RESTORE] fill datafile tail, start 16472K, end 16528K, backup id 1 [knl_bak_paral.c:763]
UTC+8 2020-02-14 18:58:54.621|ZENGINE|00053|93849330512489|INFO>[RESTORE] restore data_3_0, recent filesize 0K, section [0K, 393216K], bakcup id 3 [knl_bak_paral.c:374]
UTC+8 2020-02-14 18:58:54.621|ZENGINE|00053|93849330512489|INFO>[RESTORE] restore data_3_1, recent filesize 0K, section [393216K, 531920K], bakcup id 4 [knl_bak_paral.c:374]
UTC+8 2020-02-14 18:58:54.843|ZENGINE|00053|93849330512489|INFO>[RESTORE] restore data_4_0, recent filesize 0K, section [0K, 204240K], bakcup id 5 [knl_bak_paral.c:374]
UTC+8 2020-02-14 18:58:55.156|ZENGINE|00053|93849330512489|INFO>[RESTORE] restore data_9_0, recent filesize 0K, section [0K, 16K], bakcup id 6 [knl_bak_paral.c:374]
UTC+8 2020-02-14 18:58:55.477|ZENGINE|00053|93849330512489|INFO>[RESTORE] restore data_11_0, recent filesize 0K, section [0K, 16K], bakcup id 7 [knl_bak_paral.c:374]
UTC+8 2020-02-14 18:58:55.806|ZENGINE|00053|93849330512489|INFO>[RESTORE] restore data_12_0, recent filesize 0K, section [0K, 89648K], bakcup id 8 [knl_bak_paral.c:374]
UTC+8 2020-02-14 18:58:57.431|ZENGINE|00000|139693811430390|INFO>[RESTORE] fill datafile tail, start 204192K, end 204240K, backup id 5 [knl_bak_paral.c:763]
UTC+8 2020-02-14 18:58:58.019|ZENGINE|00000|127987|INFO>[RESTORE] restore datafiles finished [knl_restore.c:949]
UTC+8 2020-02-14 18:58:58.019|ZENGINE|00000|127987|INFO>[BACKUP] create logfiles completed [knl_restore.c:565]
UTC+8 2020-02-14 18:58:58.031|ZENGINE|00000|139693811430388|INFO>[RESTORE] start restore arch_12_0, backup id 9, log name /tmp/gaussdb_backup/roger_level0_01.bak/arch_12_0.bak [knl_bak_paral.c:673]
UTC+8 2020-02-14 18:58:58.031|ZENGINE|00000|139693811430388|INFO>[BACKUP] Create /opt/gauss/gaussdata/archive_log/arch_0_12.arc [knl_restore.c:362]
UTC+8 2020-02-14 18:58:58.035|ZENGINE|00000|139693811430388|INFO>[ARCH] Record archive log file /opt/gauss/gaussdata/archive_log/arch_0_12.arc for log [0-12] start 0 end 1 [knl_archive.c:284]
UTC+8 2020-02-14 18:58:58.122|ZENGINE|00000|127987|INFO>[RESTORE] restore logfiles finished, current backupset /tmp/gaussdb_backup/roger_level0_01.bak [knl_restore.c:964]
UTC+8 2020-02-14 18:59:19.783|ZENGINE|00000|127988|INFO>[BACKUP] parallel process 1 stop [knl_bak_paral.c:1022]
UTC+8 2020-02-14 18:59:19.785|ZENGINE|00000|127989|INFO>[BACKUP] parallel process 2 stop [knl_bak_paral.c:1022]
UTC+8 2020-02-14 18:59:19.792|ZENGINE|00000|127990|INFO>[BACKUP] parallel process 3 stop [knl_bak_paral.c:1022]
UTC+8 2020-02-14 18:59:19.802|ZENGINE|00000|127991|INFO>[BACKUP] parallel process 4 stop [knl_bak_paral.c:1022]
UTC+8 2020-02-14 18:59:19.804|ZENGINE|00053|4995142158903276137|INFO>[BACKUP] restore success [knl_bak_common.c:1762]
UTC+8 2020-02-14 18:59:40.516|ZENGINE|00053|7162257363678917225|INFO>[BACKUP] restore start, device:0, policy:, paral count 4, path:/tmp/gaussdb_backup/roger_level1_01.bak [knl_restore.c:1947]
.......
UTC+8 2020-02-14 18:59:46.691|ZENGINE|00053|206158557801|INFO>start to alter database MOUNT [knl_database.c:1047]
UTC+8 2020-02-14 18:59:46.745|ZENGINE|00053|127593|INFO>[ARCH] Already initialized [knl_archive.c:803]
UTC+8 2020-02-14 18:59:46.745|ZENGINE|00053|127593|INFO>sucessfully alter database MOUNT [knl_database.c:1103]
UTC+8 2020-02-14 18:59:46.762|ZENGINE|00053|127593|INFO>database start recovery [knl_recovery.c:1457]
UTC+8 2020-02-14 18:59:46.762|ZENGINE|00053|127593|INFO>recovery from file:12,point:112,lfn:27160 [knl_recovery.c:1459]
UTC+8 2020-02-14 18:59:46.762|ZENGINE|00053|127593|INFO>recovery expected least end with file:12,point:112,lfn:27160 [knl_recovery.c:1461]
UTC+8 2020-02-14 18:59:46.807|ZENGINE|00053|139693811429993|INFO>[RCY] recovery real end with file:13,point:1,lfn:27160 [knl_recovery.c:1423]
UTC+8 2020-02-14 18:59:46.807|ZENGINE|00053|139693811429993|INFO>[RCY] current lfn 27160, rcy point lfn 27160, consistent point 27160, lrp point lfn 27160 [knl_recovery.c:1425]
UTC+8 2020-02-14 19:00:06.205|ZENGINE|00053|206158557801|INFO>start to alter database OPEN [knl_database.c:1322]
UTC+8 2020-02-14 19:00:06.286|ZENGINE|00053|139693811429993|INFO>[ARCH] Start ARCH thread for ARCHIVE_DEST_1[/opt/gauss/gaussdata/archive_log] [knl_archive.c:881]
UTC+8 2020-02-14 19:00:06.286|ZENGINE|00053|8527087606868079209|INFO>The last shutdown is inconsistent [knl_database.c:1379]
UTC+8 2020-02-14 19:00:06.286|ZENGINE|00053|127593|INFO>database start recovery [knl_recovery.c:1457]
UTC+8 2020-02-14 19:00:06.286|ZENGINE|00053|127593|INFO>recovery from file:12,point:112,lfn:27160 [knl_recovery.c:1459]
UTC+8 2020-02-14 19:00:06.286|ZENGINE|00053|127593|INFO>recovery expected least end with file:12,point:112,lfn:27160 [knl_recovery.c:1461]
UTC+8 2020-02-14 19:00:06.296|ZENGINE|00053|139693811429993|INFO>[RCY] recovery real end with file:13,point:1,lfn:27160 [knl_recovery.c:1423]
UTC+8 2020-02-14 19:00:06.296|ZENGINE|00053|139693811429993|INFO>[RCY] current lfn 27160, rcy point lfn 27160, consistent point 27160, lrp point lfn 27160 [knl_recovery.c:1425]
UTC+8 2020-02-14 19:00:06.386|ZENGINE|00053|139693811429993|INFO>no valid standby configuration [knl_lns.c:1727]
UTC+8 2020-02-14 19:00:06.388|ZENGINE|00053|127593|INFO>[DB] sse42 available 1 [knl_database.c:1440]
UTC+8 2020-02-14 19:00:06.388|ZENGINE|00053|127593|INFO>sucessfully alter database OPEN [knl_database.c:1441]
UTC+8 2020-02-14 19:00:06.495|ZENGINE|00000|127432|INFO>rollback thread closed [knl_tran.c:1203]
UTC+8 2020-02-14 19:00:06.495|ZENGINE|00000|127433|INFO>rollback thread closed [knl_tran.c:1203]
UTC+8 2020-02-14 19:00:06.897|ZENGINE|00054|128941|INFO>load index parts: load index parts, uid: 0, tid: 278, iid: 0, index partcnt: 4032 [knl_dc_part.c:993]

我们可以看到此时恢复到的点居然是：onsistent point 27160 这比之前归档存在的情况下恢复的点要小的多。因此最后一条增量数据丢失。这里应该是没有应用到增量备份。

为了进一步探明原因；我再次模拟了测试，恢复到mount状态后；dump了控制文件，发现内容如下：

[roger@mysqldb trc]$ cat ctrl_page.trc

information of page 0-1
        lsn: 0  pcn: 0  size: 16384     type: ctrl      next_ext: 1023-0
core information:
        version:                1-0-1-0
        startup times:        4
        dbid times:           773766796
        database name:        ROGER
        init time:            2020-02-13 16:50:50
        scn:                  388345312780289
        table$ entry:         2
        ix_table$1 entry:     34
        ix_table$2 entry:     42
        column$ entry:        10
        ix_column$ entry:     50
        index$ entry:         18
        ix_index$1 entry:     58
        ix_index$2 entry:     66
        user$_entry:          26
        ix_user$1 entry:      74
        ix_user$2 entry:      82
        rcy point:            0-12-112-27160
        lrp point:            0-12-112-27160
        raft flush point:     scn(0)-lfn(0)-raft_index(0)
        ckpt_id:              308
        dw_start:             4
        dw_end:               4
        lsn:                  8775411
        lfn:                  27160
        build completed:      1
        log count:            6
        log hwm:              6
        log first:            0
        log last:             0
        archive mode:         1
        archive logs:         0-0-0-0-0-0-0-0-0-0
        db_role:              0
        protect mode:         0
        space count:          7
        device count:         13
        page size:            8192
        undo segments:        32
        reset logs:           0-0-0
        archived_start:          0
        archived_end:            1
        logic replication mode:  0
        shutdown consistency:    0
        open inconsistency:      0
        consistent lfn:          27160
storage information:
        logfiles information:
        id      name    size    hwm     seq     block_size      flg     type    status  forward backward
        #0      /opt/gauss/gaussdata/log1       134217728       0       0       512     0       1       3       0       0
        #1      /opt/gauss/gaussdata/log2       134217728       0       0       512     0       1       1       0       0
        #2      /opt/gauss/gaussdata/log3       134217728       0       0       512     0       1       1       0       0
        #3      /opt/gauss/gaussdata/log4       134217728       0       0       512     0       1       1       0       0
        #4      /opt/gauss/gaussdata/log5       134217728       0       0       512     0       1       1       0       0
        #5      /opt/gauss/gaussdata/log6       134217728       0       0       512     0       1       1       0       0
        spaces information:
        id      spaceid used    name    flg     block_size      extent_size     file_hwm        org_scn files
        #0      0       1       SYSTEM  1       8192    8       1       6762045441      0
        #1      1       1       TEMP    1       8192    16      2       9270042625      1, 2
        #2      2       1       UNDO    1       8192    1       1       10840301569     3
        #3      3       1       USERS   9       8192    8       5       16813305857     4, 5, 6, 7, 8
        #4      4       1       TEMP2   9       8192    8       2       106346856449    9, 10
        #5      5       1       TEMP2_UNDO      1       8192    1       1       108784082945    11
        #6      6       1       SYSAUX  1       8192    8       1       110029156353    12
        datafiles information:
        id      dfileid used    name    size    block_size      flg     type    auto_extend_size        auto_extend_maxsize
        archive log information:
        id      recid   dest_id rst_id  asn     stamp   blocks  block_size      first   last    name
        #0      1       0       0       12      635025690515372 112     512     387183961239553 388346659434497 /opt/gauss/gaussdata/archive_log/arch_0_12.arc

我们可以控制文件记录的arc信息是比较旧的。我甚至再次进行了测试，在open之前对进程进行strace跟踪；

[roger@mysqldb roger_level1_01.bak]$ strace -fr -F -o /tmp/gauss_recover.log -p 59647
Process 59647 attached with 17 threads
Process 61870 attached
Process 61871 attached
Process 61872 attached
Process 61873 attached
Process 61874 attached
Process 62876 attached
Process 62916 attached
Process 62915 attached
^CProcess 59647 detached
Process 59648 detached
Process 59649 detached
Process 59650 detached
Process 59651 detached
Process 59652 detached
Process 59653 detached
Process 59654 detached
Process 59655 detached
Process 59658 detached
Process 59659 detached
Process 59660 detached
Process 59661 detached
Process 59662 detached
Process 59888 detached
Process 62876 detached
[root@mysqldb tmp]# cat /tmp/gauss_recover.log |grep 'open'
59888      0.000236 open("/tmp/gaussdb_backup/roger_level0_01.bak/backupset", O_RDWR|O_SYNC) = 17
59888      0.000049 open("/opt/gauss/gaussdata/cfg/zengine.ini", O_RDONLY) = 18
59888      0.000062 open("/opt/gauss/gaussdata/cfg/zengine.ini_bak", O_RDWR|O_CREAT|O_TRUNC, 0600) = 19
59888      0.000074 open("/opt/gauss/gaussdata/cfg/zengine.ini_tmp", O_RDWR|O_CREAT|O_TRUNC|O_SYNC, 0600) = 18
59888      0.000044 open("/tmp/gaussdb_backup/roger_level0_01.bak/ctrl_0_0.bak", O_RDWR|O_SYNC) = 17
61870      0.000701 open("/opt/gauss/gaussdata/cfg/zengine.ini", O_RDONLY) = 18
61870      0.000610 open("/opt/gauss/gaussdata/cfg/zengine.ini_bak", O_RDWR|O_CREAT|O_TRUNC, 0600 <unfinished ...>
61870      0.000321 <... open resumed> ) = 19
61870      0.000038 open("/opt/gauss/gaussdata/cfg/zengine.ini_tmp", O_RDWR|O_CREAT|O_TRUNC|O_SYNC, 0600) = 18
61870      0.000046 open("/opt/gauss/gaussdata/data/cntl1", O_RDWR|O_CREAT|O_EXCL|O_TRUNC|O_SYNC, 0600) = 18
61870      0.000053 open("/opt/gauss/gaussdata/data/cntl2", O_RDWR|O_CREAT|O_EXCL|O_TRUNC|O_SYNC, 0600) = 19
61870      0.000044 open("/opt/gauss/gaussdata/data/cntl3", O_RDWR|O_CREAT|O_EXCL|O_TRUNC|O_SYNC, 0600) = 20
61870      0.000453 open("/opt/gauss/gaussdata/system", O_RDWR|O_CREAT|O_EXCL|O_TRUNC|O_SYNC, 0600) = 17
61870      0.000174 open("/opt/gauss/gaussdata/temp1_01", O_RDWR|O_CREAT|O_EXCL|O_TRUNC|O_SYNC, 0600) = 18
61870      0.000288 open("/opt/gauss/gaussdata/temp1_02", O_RDWR|O_CREAT|O_EXCL|O_TRUNC|O_SYNC, 0600) = 19
61870      0.000362 open("/opt/gauss/gaussdata/undo", O_RDWR|O_CREAT|O_EXCL|O_TRUNC|O_SYNC, 0600) = 20
61870      0.000314 open("/opt/gauss/gaussdata/user1", O_RDWR|O_CREAT|O_EXCL|O_TRUNC|O_SYNC, 0600) = 21
61870      0.000046 open("/opt/gauss/gaussdata/user2", O_RDWR|O_CREAT|O_EXCL|O_TRUNC|O_SYNC, 0600) = 22
61870      0.000032 open("/opt/gauss/gaussdata/user3", O_RDWR|O_CREAT|O_EXCL|O_TRUNC|O_SYNC, 0600) = 23
61870      0.000039 open("/opt/gauss/gaussdata/user4", O_RDWR|O_CREAT|O_EXCL|O_TRUNC|O_SYNC, 0600) = 24
61870      0.000025 open("/opt/gauss/gaussdata/user5", O_RDWR|O_CREAT|O_EXCL|O_TRUNC|O_SYNC, 0600) = 25
61870      0.000024 open("/opt/gauss/gaussdata/temp2_01", O_RDWR|O_CREAT|O_EXCL|O_TRUNC|O_SYNC, 0600) = 26
61870      0.000025 open("/opt/gauss/gaussdata/temp2_02", O_RDWR|O_CREAT|O_EXCL|O_TRUNC|O_SYNC, 0600) = 27
61870      0.000026 open("/opt/gauss/gaussdata/temp2_undo", O_RDWR|O_CREAT|O_EXCL|O_TRUNC|O_SYNC, 0600) = 28
61870      0.000044 open("/opt/gauss/gaussdata/sysaux", O_RDWR|O_CREAT|O_EXCL|O_TRUNC|O_SYNC, 0600) = 29
59888      0.000007 open("/tmp/gaussdb_backup/roger_level0_01.bak/data_SYSTEM_0_0.bak", O_RDWR|O_SYNC <unfinished ...>
59888      0.000007 <... open resumed> ) = 30
61871      0.005724 open("/opt/gauss/gaussdata/system", O_RDWR|O_SYNC <unfinished ...>
61871      0.000268 <... open resumed> ) = 31
59888      0.000036 open("/tmp/gaussdb_backup/roger_level0_01.bak/data_TEMP_1_0.bak", O_RDWR|O_SYNC) = 32
61872      0.000275 open("/opt/gauss/gaussdata/temp1_01", O_RDWR|O_SYNC <unfinished ...>
61872      0.000046 <... open resumed> ) = 33
59888      0.000058 open("/tmp/gaussdb_backup/roger_level0_01.bak/data_UNDO_3_0.bak", O_RDWR|O_SYNC <unfinished ...>
59888      0.000040 <... open resumed> ) = 32
61872      0.000004 open("/opt/gauss/gaussdata/undo", O_RDWR|O_SYNC <unfinished ...>
61872      0.000705 <... open resumed> ) = 33
59888      0.000051 open("/tmp/gaussdb_backup/roger_level0_01.bak/data_UNDO_3_1.bak", O_RDWR|O_SYNC) = 34
61873      0.001613 open("/opt/gauss/gaussdata/undo", O_RDWR|O_SYNC <unfinished ...>
61873      0.000354 <... open resumed> ) = 35
59888      0.000035 open("/tmp/gaussdb_backup/roger_level0_01.bak/data_USERS_4_0.bak", O_RDWR|O_SYNC <unfinished ...>
59888      0.000053 <... open resumed> ) = 30
59888      0.000033 open("/tmp/gaussdb_backup/roger_level0_01.bak/data_TEMP2_9_0.bak", O_RDWR|O_SYNC) = 31
61871      0.000476 open("/opt/gauss/gaussdata/temp2_01", O_RDWR|O_SYNC) = 36
61874      0.009655 open("/opt/gauss/gaussdata/user1", O_RDWR|O_SYNC <unfinished ...>
61874      0.000268 <... open resumed> ) = 31
59888      0.000045 open("/tmp/gaussdb_backup/roger_level0_01.bak/data_TEMP2_UNDO_11_0.bak", O_RDWR|O_SYNC) = 36
61871      0.000040 open("/opt/gauss/gaussdata/temp2_undo", O_RDWR|O_SYNC) = 37
59888      0.000064 open("/tmp/gaussdb_backup/roger_level0_01.bak/data_SYSAUX_12_0.bak", O_RDWR|O_SYNC) = 36
61871      0.007274 open("/opt/gauss/gaussdata/sysaux", O_RDWR|O_SYNC <unfinished ...>
61871      0.000811 <... open resumed> ) = 37
61870      0.000046 open("/opt/gauss/gaussdata/log1", O_RDWR|O_CREAT|O_EXCL|O_TRUNC|O_SYNC, 0600) = 30
61870      0.000052 open("/opt/gauss/gaussdata/log2", O_RDWR|O_CREAT|O_EXCL|O_TRUNC|O_SYNC, 0600) = 30
61870      0.000030 open("/opt/gauss/gaussdata/log3", O_RDWR|O_CREAT|O_EXCL|O_TRUNC|O_SYNC, 0600) = 30
61870      0.000024 open("/opt/gauss/gaussdata/log4", O_RDWR|O_CREAT|O_EXCL|O_TRUNC|O_SYNC, 0600) = 30
61870      0.000046 open("/opt/gauss/gaussdata/log5", O_RDWR|O_CREAT|O_EXCL|O_TRUNC|O_SYNC, 0600) = 30
61870      0.000025 open("/opt/gauss/gaussdata/log6", O_RDWR|O_CREAT|O_EXCL|O_TRUNC|O_SYNC, 0600) = 30
59888      0.000006 open("/tmp/gaussdb_backup/roger_level0_01.bak/arch_12_0.bak", O_RDWR|O_SYNC <unfinished ...>
59888      0.000008 <... open resumed> ) = 30
61871      0.000037 open("/opt/gauss/gaussdata/archive_log/arch_0_12.arc", O_RDWR|O_CREAT|O_EXCL|O_TRUNC|O_SYNC, 0600) = 31
61871      0.000036 open("/opt/gauss/gaussdata/data/cntl1", O_RDWR|O_SYNC) = 32
61871      0.000143 open("/opt/gauss/gaussdata/data/cntl2", O_RDWR|O_SYNC) = 33
61871      0.000024 open("/opt/gauss/gaussdata/data/cntl3", O_RDWR|O_SYNC) = 34
61871      0.000007 open("/opt/gauss/gaussdata/system", O_RDWR|O_SYNC) = 30
61872      0.000008 open("/opt/gauss/gaussdata/temp1_01", O_RDWR|O_SYNC) = 31
61873      0.000023 open("/opt/gauss/gaussdata/temp1_02", O_RDWR|O_SYNC <unfinished ...>
61873      0.015932 <... open resumed> ) = 35
61874      0.000069 open("/opt/gauss/gaussdata/undo", O_RDWR|O_SYNC) = 36
61872      0.000145 open("/opt/gauss/gaussdata/user1", O_RDWR|O_SYNC <unfinished ...>
61872      0.000746 <... open resumed> ) = 31
61873      0.000295 open("/opt/gauss/gaussdata/user2", O_RDWR|O_SYNC <unfinished ...>
61873      0.000058 <... open resumed> ) = 35
61871      0.000154 open("/opt/gauss/gaussdata/user3", O_RDWR|O_SYNC <unfinished ...>
61871      0.000042 <... open resumed> ) = 30
61874      0.000047 open("/opt/gauss/gaussdata/user4", O_RDWR|O_SYNC) = 36
61872      0.000066 open("/opt/gauss/gaussdata/user5", O_RDWR|O_SYNC) = 31
61872      0.000082 open("/opt/gauss/gaussdata/temp2_01", O_RDWR|O_SYNC <unfinished ...>
61872      0.000040 <... open resumed> ) = 31
61873      0.000123 open("/opt/gauss/gaussdata/temp2_02", O_RDWR|O_SYNC <unfinished ...>
61871      0.000084 open("/opt/gauss/gaussdata/temp2_undo", O_RDWR|O_SYNC <unfinished ...>
61873      0.001027 <... open resumed> ) = 30
61871      0.000030 <... open resumed> ) = 35
61872      0.000126 open("/opt/gauss/gaussdata/sysaux", O_RDWR|O_SYNC <unfinished ...>
61872      0.000046 <... open resumed> ) = 31
61871      0.000003 open("/opt/gauss/gaussdata/log1", O_RDWR|O_SYNC) = 30
61872      0.000004 open("/opt/gauss/gaussdata/log2", O_RDWR|O_SYNC <unfinished ...>
61872      0.000036 <... open resumed> ) = 31
61873      0.000031 open("/opt/gauss/gaussdata/log3", O_RDWR|O_SYNC <unfinished ...>
61873      0.000079 <... open resumed> ) = 35
61874      0.000051 open("/opt/gauss/gaussdata/log4", O_RDWR|O_SYNC <unfinished ...>
61874      0.000038 <... open resumed> ) = 36
61874      0.000169 open("/opt/gauss/gaussdata/log5", O_RDWR|O_SYNC <unfinished ...>
61871      0.000025 open("/opt/gauss/gaussdata/log6", O_RDWR|O_SYNC <unfinished ...>
61874      0.000098 <... open resumed> ) = 36
61871      0.000010 <... open resumed> ) = 30
61870      0.000129 open("/opt/gauss/gaussdata/log1", O_RDWR|O_SYNC) = 30
59888      0.000075 open("/opt/gauss/gaussdata/data/cntl1", O_RDONLY) = 17
59888      0.000047 open("/opt/gauss/gaussdata/data/cntl1", O_RDWR|O_SYNC <unfinished ...>
59888      0.000026 <... open resumed> ) = 17
59888      0.002681 open("/opt/gauss/gaussdata/data/cntl2", O_RDWR|O_SYNC <unfinished ...>
59888      0.000420 <... open resumed> ) = 17
59888      0.000415 open("/opt/gauss/gaussdata/data/cntl3", O_RDWR|O_SYNC) = 17
59888      0.000441 open("/opt/gauss/gaussdata/data/cntl2", O_RDWR|O_SYNC <unfinished ...>
59888      0.000207 <... open resumed> ) = 17
59888      0.000470 open("/opt/gauss/gaussdata/data/cntl3", O_RDWR|O_SYNC <unfinished ...>
59888      0.000189 <... open resumed> ) = 17
59888      0.000445 open("/opt/gauss/gaussdata/log1", O_RDWR|O_SYNC <unfinished ...>
59888      0.000224 <... open resumed> ) = 17
59888      0.000235 open("/opt/gauss/gaussdata/log2", O_RDWR|O_SYNC) = 18
59888      0.000430 open("/opt/gauss/gaussdata/log3", O_RDWR|O_SYNC) = 19
59888      0.000428 open("/opt/gauss/gaussdata/log4", O_RDWR|O_SYNC) = 20
59888      0.000466 open("/opt/gauss/gaussdata/log5", O_RDWR|O_SYNC) = 21
59888      0.000232 open("/opt/gauss/gaussdata/log6", O_RDWR|O_SYNC) = 22
59888      0.000046 open("/opt/gauss/gaussdata/system", O_RDWR|O_SYNC) = 23
59888      0.000370 open("/opt/gauss/gaussdata/data/cntl1", O_RDWR|O_SYNC) = 24
59888      0.000818 open("/opt/gauss/gaussdata/data/cntl2", O_RDWR|O_SYNC) = 25
59888      0.000243 open("/opt/gauss/gaussdata/data/cntl3", O_RDWR|O_SYNC) = 26
59888      0.000407 open("/opt/gauss/gaussdata/temp1_01", O_RDWR) = 27
59888      0.000036 open("/opt/gauss/gaussdata/temp1_02", O_RDWR) = 28
59888      0.001069 open("/opt/gauss/gaussdata/undo", O_RDWR|O_SYNC) = 29
59888      0.000492 open("/opt/gauss/gaussdata/user1", O_RDWR|O_SYNC) = 30
59888      0.000604 open("/opt/gauss/gaussdata/user2", O_RDWR|O_SYNC) = 31
59888      0.001332 open("/opt/gauss/gaussdata/user3", O_RDWR|O_SYNC <unfinished ...>
59888      0.000041 <... open resumed> ) = 32
59888      0.000023 open("/opt/gauss/gaussdata/user4", O_RDWR|O_SYNC) = 33
59888      0.000036 open("/opt/gauss/gaussdata/user5", O_RDWR|O_SYNC) = 34
59888      0.000433 open("/opt/gauss/gaussdata/temp2_01", O_RDWR|O_SYNC) = 35
59888      0.000240 open("/opt/gauss/gaussdata/temp2_02", O_RDWR|O_SYNC) = 36
59888      0.000039 open("/opt/gauss/gaussdata/temp2_undo", O_RDWR|O_SYNC) = 37
59888      0.000532 open("/opt/gauss/gaussdata/sysaux", O_RDWR|O_SYNC <unfinished ...>
59888      0.000027 <... open resumed> ) = 38
59888      0.000035 open("/opt/gauss/gaussdata/archive_log/arch_0_12.arc", O_RDWR|O_SYNC <unfinished ...>
59888      0.000022 <... open resumed> ) = 39
59888      0.000027 open("/opt/gauss/gaussdata/log1", O_RDWR|O_SYNC) = 40
59888      0.000351 open("/opt/gauss/gaussdata/log1", O_RDWR|O_SYNC) = 39
59888      0.000062 recvfrom(15, "123alter database openo", 32, 0, NULL, NULL) = 32
59888      0.000294 open("/opt/gauss/gaussdata/archive_log/arch_0_12.arc", O_RDWR|O_SYNC) = 39
59888      0.000026 open("/opt/gauss/gaussdata/log1", O_RDWR|O_SYNC) = 40
59653      0.000017 open("/opt/gauss/gaussdata/system", O_RDWR|O_SYNC <unfinished ...>
59653      0.000009 <... open resumed> ) = 39
59662      0.000143 open("/opt/gauss/gaussdata/system", O_RDWR|O_SYNC) = 40
62916      0.000106 open("/opt/gauss/gaussdata/system", O_RDWR|O_SYNC <unfinished ...>
62916      0.000294 <... open resumed> ) = 41
62916      0.002062 open("/opt/gauss/gaussdata/undo", O_RDWR|O_SYNC <unfinished ...>
62915      0.000409 open("/opt/gauss/gaussdata/undo", O_RDWR|O_SYNC) = 42
62916      0.000762 <... open resumed> ) = 43
62915      0.000365 open("/opt/gauss/gaussdata/system", O_RDWR|O_SYNC) = 44
62915      0.000053 open("/opt/gauss/gaussdata/sysaux", O_RDWR|O_SYNC) = 45
62916      0.000694 open("/opt/gauss/gaussdata/sysaux", O_RDWR|O_SYNC <unfinished ...>
62916      0.000835 <... open resumed> ) = 46
62916      0.000038 open("/sys/devices/system/cpu/cpu0/topology/thread_siblings", O_RDONLY) = 47
62916      0.000040 open("/sys/devices/system/cpu/cpu0/topology/core_siblings", O_RDONLY) = 47
62916      0.000033 open("/proc/stat", O_RDONLY) = 47
62916      0.000109 open("/proc/vmstat", O_RDONLY) = 47
62916      0.000028 open("/proc/meminfo", O_RDONLY) = 47
62916      0.000035 open("/proc/loadavg", O_RDONLY) = 47
62916      0.009910 openat(AT_FDCWD, "/opt/gauss/gaussdata/log/longsql", O_RDONLY|O_NONBLOCK|O_DIRECTORY|O_CLOEXEC <unfinished ...>
62916      0.000243 <... openat resumed> ) = -1 ENOENT (No such file or directory)
[root@mysqldb tmp]# 
[root@mysqldb tmp]# 
[root@mysqldb tmp]# cat /tmp/gauss_recover.log |grep 'roger_level1_01'

由此可见应该是gaussdb在restore时默认是使用0级备份去进行恢复数据文件和控制文件；而不会寻找最新的控制文件备份。

测试了几次，strace跟踪发现根本就不会读最新的备份集合；应该是控制文件惹的祸。 0级备份的控制文件中信息是比较旧的。或者是我恢复的方法不对；还请知道的朋友指点一下；谢谢！

 

那么正确的姿势应该是什么样呢，我再次进行了测试，找到了原因。

[roger@mysqldb gaussdata]$ rm -rf user*

[roger@mysqldb gaussdata]$ rm -rf temp*

[roger@mysqldb gaussdata]$ rm -rf sys*

[roger@mysqldb gaussdata]$ rm -rf undo*

[roger@mysqldb gaussdata]$ rm -rf log1 log2 log3 log4 log5 log6

[roger@mysqldb gaussdata]$ rm -rf data/cntl*

[roger@mysqldb gaussdata]$ rm -rf archive_log/*

[roger@mysqldb gaussdata]$ ls -ltr

total 4

drwx------ 2 roger roger 42 Feb 13 16:23 dbs

-rw------- 1 roger roger 0 Feb 13 16:23 zengine.lck

drwx------ 2 roger roger 4096 Feb 13 21:50 trc

drwx------ 5 roger roger 64 Feb 14 18:58 log

drwx------ 2 roger roger 62 Feb 15 11:11 cfg

drwx------ 2 roger roger 85 Feb 15 20:10 protect

drwx------ 2 roger roger 6 Feb 16 13:23 data

drwx------ 2 roger roger 6 Feb 16 13:23 archive_log

 

–restore（直接指定增量备份备份集；而不是指定全备的备份集）

[roger@mysqldb gaussdata]$ zengine nomount -D /opt/gauss/gaussdata &

[1] 127251

[roger@mysqldb gaussdata]$ starting instance(nomount)

instance started

[roger@mysqldb gaussdata]$

[roger@mysqldb gaussdata]$ zsql / as sysdba -q

connected.

SQL> restore database from '/tmp/gaussdb_backup/roger_level1_01.bak';

Succeed.

SQL> recover database;

Succeed.

SQL> alter database open;

Succeed.

SQL> select * from roger.test;

A B

---------------------------------------- --------------------

1 www.enmotech.com

1 www.killdb.com

100 www.modb.pro

3 rows fetched.

 

可以看到可以恢复出最新的数据。我们可以看到restore时直接使用增量备集时可以恢复到最新时间点的数据的。

那么这种情况下，gaussdb会自动去从0级全备中先恢复文件；然后再应用增量吗 ？我们先来看下此时的日志：

UTC+8 2020-02-16 13:28:53.494|ZENGINE|00000|127251|INFO>instance started

UTC+8 2020-02-16 13:28:53.496|ZENGINE|00000|127266|INFO>job master thread started [srv_job.c:638]

UTC+8 2020-02-16 13:29:50.222|ZENGINE|00000|128028|INFO>agent thread started, tid:139651462735616, close:0 [srv_agent.c:359]

UTC+8 2020-02-16 13:29:50.222|ZENGINE|00053|128028|INFO>[LOG] file '/opt/gauss/gaussdata/log/audit/zengine.aud' is added [cm_log.c:641]

UTC+8 2020-02-16 13:29:56.323|ZENGINE|00053|128028|INFO>[BACKUP] restore start, device:0, policy:, paral count 4, path:/tmp/gaussdb_backup/roger_level1_01.bak [knl_restore.c:1947]

UTC+8 2020-02-16 13:29:56.323|ZENGINE|00053|128028|INFO>[ARCH] Initialization complete [knl_archive.c:824]

UTC+8 2020-02-16 13:29:56.331|ZENGINE|00000|128107|INFO>[BACKUP] parallel process 1 start [knl_bak_paral.c:996]

UTC+8 2020-02-16 13:29:56.331|ZENGINE|00000|128108|INFO>[BACKUP] parallel process 2 start [knl_bak_paral.c:996]

UTC+8 2020-02-16 13:29:56.333|ZENGINE|00000|128109|INFO>[BACKUP] parallel process 3 start [knl_bak_paral.c:996]

UTC+8 2020-02-16 13:29:56.333|ZENGINE|00000|128110|INFO>[BACKUP] parallel process 4 start [knl_bak_paral.c:996]

UTC+8 2020-02-16 13:29:56.409|ZENGINE|00053|94592359855132|INFO>[RESTORE] restore data_0_0, recent filesize 0K, section [0K, 16528K], bakcup id 1 [knl_bak_paral.c:374]

UTC+8 2020-02-16 13:29:56.509|ZENGINE|00053|94592359855132|INFO>[RESTORE] restore data_1_0, recent filesize 0K, section [0K, 16K], bakcup id 2 [knl_bak_paral.c:374]

UTC+8 2020-02-16 13:29:56.566|ZENGINE|00000|139650861757547|INFO>[RESTORE] fill datafile tail, start 16472K, end 16528K, backup id 1 [knl_bak_paral.c:763]

UTC+8 2020-02-16 13:29:56.609|ZENGINE|00053|94592359855132|INFO>[RESTORE] restore data_3_0, recent filesize 0K, section [0K, 393216K], bakcup id 3 [knl_bak_paral.c:374]

UTC+8 2020-02-16 13:29:56.611|ZENGINE|00053|94592359855132|INFO>[RESTORE] restore data_3_1, recent filesize 0K, section [393216K, 531920K], bakcup id 4 [knl_bak_paral.c:374]

UTC+8 2020-02-16 13:29:56.830|ZENGINE|00053|94592359855132|INFO>[RESTORE] restore data_4_0, recent filesize 0K, section [0K, 204240K], bakcup id 5 [knl_bak_paral.c:374]

UTC+8 2020-02-16 13:29:57.155|ZENGINE|00053|94592359855132|INFO>[RESTORE] restore data_9_0, recent filesize 0K, section [0K, 16K], bakcup id 6 [knl_bak_paral.c:374]

UTC+8 2020-02-16 13:29:57.472|ZENGINE|00053|94592359855132|INFO>[RESTORE] restore data_11_0, recent filesize 0K, section [0K, 16K], bakcup id 7 [knl_bak_paral.c:374]

UTC+8 2020-02-16 13:29:57.803|ZENGINE|00053|94592359855132|INFO>[RESTORE] restore data_12_0, recent filesize 0K, section [0K, 89648K], bakcup id 8 [knl_bak_paral.c:374]

UTC+8 2020-02-16 13:29:58.836|ZENGINE|00000|139650861757549|INFO>[RESTORE] fill datafile tail, start 204192K, end 204240K, backup id 5 [knl_bak_paral.c:763]

UTC+8 2020-02-16 13:29:59.549|ZENGINE|00000|128106|INFO>[RESTORE] restore datafiles finished [knl_restore.c:949]

UTC+8 2020-02-16 13:29:59.635|ZENGINE|00053|94592359855132|INFO>[RESTORE] restore data_0_0, recent filesize 16528K, section [0K, 16528K], bakcup id 1 [knl_bak_paral.c:374]

UTC+8 2020-02-16 13:29:59.736|ZENGINE|00053|94592359855132|INFO>[RESTORE] restore data_1_0, recent filesize 16K, section [0K, 16K], bakcup id 2 [knl_bak_paral.c:374]

UTC+8 2020-02-16 13:29:59.736|ZENGINE|00053|94592359855132|INFO>[RESTORE] restore data_3_0, recent filesize 531920K, section [0K, 393216K], bakcup id 3 [knl_bak_paral.c:374]

UTC+8 2020-02-16 13:29:59.837|ZENGINE|00053|94592359855132|INFO>[RESTORE] restore data_3_1, recent filesize 531920K, section [393216K, 531920K], bakcup id 4 [knl_bak_paral.c:374]

UTC+8 2020-02-16 13:29:59.837|ZENGINE|00053|94592359855132|INFO>[RESTORE] restore data_4_0, recent filesize 204240K, section [0K, 204240K], bakcup id 5 [knl_bak_paral.c:374]

UTC+8 2020-02-16 13:29:59.938|ZENGINE|00053|94592359855132|INFO>[RESTORE] restore data_9_0, recent filesize 16K, section [0K, 16K], bakcup id 6 [knl_bak_paral.c:374]

UTC+8 2020-02-16 13:29:59.938|ZENGINE|00053|94592359855132|INFO>[RESTORE] restore data_11_0, recent filesize 16K, section [0K, 16K], bakcup id 7 [knl_bak_paral.c:374]

UTC+8 2020-02-16 13:30:00.039|ZENGINE|00053|94592359855132|INFO>[RESTORE] restore data_12_0, recent filesize 89648K, section [0K, 90032K], bakcup id 8 [knl_bak_paral.c:374]

UTC+8 2020-02-16 13:30:00.062|ZENGINE|00000|139650861757548|INFO>[RESTORE] fill datafile tail, start 89984K, end 90032K, backup id 8 [knl_bak_paral.c:763]

UTC+8 2020-02-16 13:30:00.140|ZENGINE|00000|128106|INFO>[RESTORE] restore datafiles finished [knl_restore.c:949]

UTC+8 2020-02-16 13:30:00.146|ZENGINE|00000|128106|INFO>[BACKUP] create logfiles completed [knl_restore.c:565]

UTC+8 2020-02-16 13:30:00.157|ZENGINE|00000|139650861757547|INFO>[RESTORE] start restore arch_13_0, backup id 9, log name /tmp/gaussdb_backup/roger_level1_01.bak/arch_13_0.bak [knl_bak_paral.c:673]

UTC+8 2020-02-16 13:30:00.160|ZENGINE|00000|139650861757547|INFO>[BACKUP] Create /opt/gauss/gaussdata/archive_log/arch_0_13.arc [knl_restore.c:362]

UTC+8 2020-02-16 13:30:00.172|ZENGINE|00000|139650861757547|INFO>[ARCH] Record archive log file /opt/gauss/gaussdata/archive_log/arch_0_13.arc for log [0-13] start 0 end 1 [knl_archive.c:284]

UTC+8 2020-02-16 13:30:00.250|ZENGINE|00000|128106|INFO>[RESTORE] restore logfiles finished, current backupset /tmp/gaussdb_backup/roger_level1_01.bak [knl_restore.c:964]

UTC+8 2020-02-16 13:30:25.853|ZENGINE|00000|128107|INFO>[BACKUP] parallel process 1 stop [knl_bak_paral.c:1022]

UTC+8 2020-02-16 13:30:25.855|ZENGINE|00000|128108|INFO>[BACKUP] parallel process 2 stop [knl_bak_paral.c:1022]

UTC+8 2020-02-16 13:30:25.864|ZENGINE|00000|128109|INFO>[BACKUP] parallel process 3 stop [knl_bak_paral.c:1022]

UTC+8 2020-02-16 13:30:25.875|ZENGINE|00000|128110|INFO>[BACKUP] parallel process 4 stop [knl_bak_paral.c:1022]

UTC+8 2020-02-16 13:30:25.877|ZENGINE|00053|4995142158903276572|INFO>[BACKUP] restore success [knl_bak_common.c:1762]

UTC+8 2020-02-16 13:30:43.488|ZENGINE|00053|206158558236|INFO>start to alter database MOUNT [knl_database.c:1047]

UTC+8 2020-02-16 13:30:43.522|ZENGINE|00053|128028|INFO>[ARCH] Already initialized [knl_archive.c:803]

UTC+8 2020-02-16 13:30:43.524|ZENGINE|00053|128028|INFO>sucessfully alter database MOUNT [knl_database.c:1103]

UTC+8 2020-02-16 13:30:43.557|ZENGINE|00053|128028|INFO>database start recovery [knl_recovery.c:1457]

UTC+8 2020-02-16 13:30:43.557|ZENGINE|00053|128028|INFO>recovery from file:13,point:750,lfn:27247 [knl_recovery.c:1459]

UTC+8 2020-02-16 13:30:43.557|ZENGINE|00053|128028|INFO>recovery expected least end with file:13,point:750,lfn:27247 [knl_recovery.c:1461]

UTC+8 2020-02-16 13:30:43.593|ZENGINE|00053|139650861757468|INFO>[RCY] recovery real end with file:14,point:1,lfn:27247 [knl_recovery.c:1423]

UTC+8 2020-02-16 13:30:43.595|ZENGINE|00053|139650861757468|INFO>[RCY] current lfn 27247, rcy point lfn 27247, consistent point 27247, lrp point lfn 27247 [knl_recovery.c:1425]

UTC+8 2020-02-16 13:31:40.820|ZENGINE|00053|206158558236|INFO>start to alter database OPEN [knl_database.c:1322]

UTC+8 2020-02-16 13:31:40.944|ZENGINE|00053|139650861757468|INFO>[ARCH] Start ARCH thread for ARCHIVE_DEST_1[/opt/gauss/gaussdata/archive_log] [knl_archive.c:881]

UTC+8 2020-02-16 13:31:40.946|ZENGINE|00053|2581544450367026204|INFO>The last shutdown is inconsistent [knl_database.c:1379]

UTC+8 2020-02-16 13:31:40.946|ZENGINE|00053|128028|INFO>database start recovery [knl_recovery.c:1457]

UTC+8 2020-02-16 13:31:40.946|ZENGINE|00053|128028|INFO>recovery from file:13,point:750,lfn:27247 [knl_recovery.c:1459]

UTC+8 2020-02-16 13:31:40.946|ZENGINE|00053|128028|INFO>recovery expected least end with file:13,point:750,lfn:27247 [knl_recovery.c:1461]

UTC+8 2020-02-16 13:31:40.957|ZENGINE|00053|139650861757468|INFO>[RCY] recovery real end with file:14,point:1,lfn:27247 [knl_recovery.c:1423]

UTC+8 2020-02-16 13:31:40.957|ZENGINE|00053|139650861757468|INFO>[RCY] current lfn 27247, rcy point lfn 27247, consistent point 27247, lrp point lfn 27247 [knl_recovery.c:1425]

UTC+8 2020-02-16 13:31:41.061|ZENGINE|00053|139650861757468|INFO>no valid standby configuration [knl_lns.c:1727]

UTC+8 2020-02-16 13:31:41.066|ZENGINE|00053|128028|INFO>[DB] sse42 available 1 [knl_database.c:1440]

UTC+8 2020-02-16 13:31:41.066|ZENGINE|00053|128028|INFO>sucessfully alter database OPEN [knl_database.c:1441]

UTC+8 2020-02-16 13:31:41.125|ZENGINE|00000|127260|INFO>rollback thread closed [knl_tran.c:1203]

UTC+8 2020-02-16 13:31:41.125|ZENGINE|00000|127261|INFO>rollback thread closed [knl_tran.c:1203]

UTC+8 2020-02-16 13:31:41.653|ZENGINE|00054|129476|INFO>load index parts: load index parts, uid: 0, tid: 278, iid: 0, index partcnt: 4032 [knl_dc_part.c:993]

UTC+8 2020-02-16 13:31:41.658|ZENGINE|00054|129476|INFO>load index parts: load index parts, uid: 0, tid: 302, iid: 0, index partcnt: 4032 [knl_dc_part.c:993]

 

可以看到日志中并没有记录有过去访问0级备份的信息。还好我再restore时开启了strace跟踪；下面看trace log：

[root@mysqldb bin]# strace -fr -F -o /tmp/strace_rec.log -p 127251

Process 127251 attached with 16 threads

Process 128028 attached

Process 128106 attached

Process 128107 attached

Process 128108 attached

Process 128109 attached

Process 128110 attached

Process 129475 attached

Process 129476 attached

Process 129477 attached

Process 129478 attached

Process 129479 attached

^CProcess 127251 detached

Process 127252 detached

Process 127253 detached

Process 127254 detached

Process 127255 detached

Process 127256 detached

Process 127257 detached

Process 127258 detached

Process 127259 detached

Process 127262 detached

Process 127263 detached

Process 127264 detached

Process 127265 detached

Process 127266 detached

Process 128028 detached

Process 129475 detached

[root@mysqldb tmp]# cat strace_rec.log |grep 'roger_level0'

128028 0.000045 open("/tmp/gaussdb_backup/roger_level0_01.bak/backupset", O_RDWR|O_SYNC <unfinished ...>

128028 0.000023 open("/tmp/gaussdb_backup/roger_level0_01.bak/ctrl_0_0.bak", O_RDWR|O_SYNC) = 17

128028 0.000004 open("/tmp/gaussdb_backup/roger_level0_01.bak/data_SYSTEM_0_0.bak", O_RDWR|O_SYNC) = 30

128028 0.000018 open("/tmp/gaussdb_backup/roger_level0_01.bak/data_TEMP_1_0.bak", O_RDWR|O_SYNC) = 32

128028 0.000021 open("/tmp/gaussdb_backup/roger_level0_01.bak/data_UNDO_3_0.bak", O_RDWR|O_SYNC) = 30

128028 0.000029 open("/tmp/gaussdb_backup/roger_level0_01.bak/data_UNDO_3_1.bak", O_RDWR|O_SYNC <unfinished ...>

128028 0.000005 open("/tmp/gaussdb_backup/roger_level0_01.bak/data_USERS_4_0.bak", O_RDWR|O_SYNC <unfinished ...>

128028 0.000005 open("/tmp/gaussdb_backup/roger_level0_01.bak/data_TEMP2_9_0.bak", O_RDWR|O_SYNC <unfinished ...>

128028 0.000007 open("/tmp/gaussdb_backup/roger_level0_01.bak/data_TEMP2_UNDO_11_0.bak", O_RDWR|O_SYNC) = 36

128028 0.000004 open("/tmp/gaussdb_backup/roger_level0_01.bak/data_SYSAUX_12_0.bak", O_RDWR|O_SYNC <unfinished ...>

[root@mysqldb tmp]#

不难看出；确实会去寻找0级备份；然后再应用增量。这也验证了前面的分析。

由此可见；对于使用zsql来进行备份和恢复；再进行restore恢复时，正确的姿势是直接使用增量备份进行恢复；而不是指定全备；

然后再去应用增量，这也会报错。