don’t shutdown postgresql before call pg_stop_backup() - 备份结束前,不要停库,源码分析

4 minute read

背景

在创建备份或STANDBY时,我们通常可以有两种方式一种是通过pg_basebackup,另一种是使用pg_start_backup然后COPY文件的方式。

在使用第二种方式时,正确的流程应该是:

pg_start_backup  
COPY file  
-- 拷贝完后,请不要停库,一定要调用pg_stop_backup()  
pg_stop_backup  

但是我们试想一下,如果在COPY完后,调用pg_stop_backup前,主库关闭了,然后又起来了。

这个备份还有效吗?

正文

先来试一试:

1. 执行pg_start_backup

do_pg_start_backup@src/backend/access/transam/xlog.c 被调用。  
postgres@digoal-> psql  
psql (9.4.4)  
Type "help" for help.  
postgres=# select pg_start_backup('a');  

2. 拷贝文件,并使用这个拷贝创建备库

postgres@digoal-> rm -f postmaster.pid  
postgres@digoal-> pg_ctl start -D .  
server starting  
postgres@digoal-> LOG:  00000: redirecting log output to logging collector process  
HINT:  Future log output will appear in directory "/data03/pg_log_1922".  
LOCATION:  SysLogger_Start, syslogger.c:645  
  
postgres@digoal-> top -c -u postgres  
top - 15:36:48 up  7:19,  4 users,  load average: 0.00, 0.00, 0.00  
Tasks: 159 total,   1 running, 158 sleeping,   0 stopped,   0 zombie  
Cpu(s):  0.0%us,  0.0%sy,  0.0%ni,100.0%id,  0.0%wa,  0.0%hi,  0.0%si,  0.0%st  
Mem:   1914436k total,   961196k used,   953240k free,   104048k buffers  
Swap:  1048572k total,        0k used,  1048572k free,   666808k cached  
  PID USER      PR  NI  VIRT  RES  SHR S %CPU %MEM    TIME+  COMMAND                                                                                       
 4082 postgres  20   0 15040 1272  936 R 33.2  0.1   0:00.25 top -c -u postgres                                                                                        
 1908 postgres  20   0  105m 1948 1452 S  0.0  0.1   0:00.64 -bash                                                                                                            
 3850 postgres  20   0  105m 1960 1448 S  0.0  0.1   0:00.28 -bash                                                                                                            
 3987 postgres  20   0  488m  34m  32m S  0.0  1.8   0:00.21 /opt/pgsql9.4.4/bin/postgres                                                                      
 3989 postgres  20   0  186m 3112  708 S  0.0  0.2   0:00.00 postgres: logger process                                                                            
 3991 postgres  20   0  488m 5928 3492 S  0.0  0.3   0:00.00 postgres: checkpointer process                                                                
 3992 postgres  20   0  488m 5544 3112 S  0.0  0.3   0:00.05 postgres: writer process                                                                            
 3993 postgres  20   0  488m  19m  16m S  0.0  1.0   0:00.31 postgres: wal writer process                                                                      
 3994 postgres  20   0  188m 3380  800 S  0.0  0.2   0:00.00 postgres: stats collector process                                                              
 4069 postgres  20   0  488m  34m  32m S  0.0  1.8   0:00.11 /opt/pgsql9.4.4/bin/postgres -D .                                                              
 4071 postgres  20   0  186m 3116  708 S  0.0  0.2   0:00.00 postgres: logger process                                                                            
 4072 postgres  20   0  488m 4040 1572 S  0.0  0.2   0:00.01 postgres: startup process   recovering 000000060000002900000033                                                                                                                   
 4076 postgres  20   0  488m 3344  912 S  0.0  0.2   0:00.00 postgres: checkpointer process                                                                
 4077 postgres  20   0  488m 3432 1000 S  0.0  0.2   0:00.00 postgres: writer process                                                                              
 4078 postgres  20   0  495m 5380 2840 S  0.0  0.3   0:00.00 postgres: wal receiver process                                                                
 4080 postgres  20   0  489m 4828 2216 S  0.0  0.3   0:00.00 postgres: wal sender process replica 192.168.150.128(26168) streaming 29/33000100                                                                                                 

3. 关闭主库,注意这个时候还没有在主库执行 pg_stop_backup

4. 此时, 备库CRASH掉了。并产生了一个CORE文件。

日志如下:

2015-09-10 15:36:56.065 CST,,,4072,,55f1330a.fe8,5,,2015-09-10 15:36:42 CST,1/0,0,PANIC,XX000,"online backup was canceled, recovery cannot continue",,,,,"xlog redo checkpoint: redo 29/33000100; tli 6; prev tli 6; fpw true; xid 0/639272964; oid 151900; multi 788; offset 1711; oldest xid 600048491 in DB 1; oldest multi 631 in DB 1; oldest running xid 0; shutdown",,,"xlog_redo, xlog.c:9310",""  

CORE文件

[root@digoal pg_root_1922]# ll  
total 10540  
-rw------- 1 postgres postgres       193 Sep 10 15:36 backup_label.old  
drwx------ 6 postgres postgres      4096 Sep 10 15:36 base  
-rw------- 1 postgres postgres 318500864 Sep 10 15:36 core.4072  
drwx------ 2 postgres postgres      4096 Sep 10 15:36 global  
drwx------ 2 postgres postgres      4096 Sep 10 15:36 pg_clog  

分析这个CORE文件:

# gdb -c ./core.4072 /opt/pgsql/bin/postgres  

截取最后一部分信息如下:

Loaded symbols for /lib64/libnss_files.so.2  
Reading symbols from /lib/modules/2.6.32-504.el6.x86_64/vdso/vdso.so...Reading symbols from /usr/lib/debug/lib/modules/2.6.32-504.el6.x86_64/vdso/vdso.so.debug...done.  
done.  
Loaded symbols for /lib/modules/2.6.32-504.el6.x86_64/vdso/vdso.so  
Core was generated by `postgres: startup process   recovering 00000006000000'.  
Program terminated with signal 6, Aborted.  
#0  0x00000038b9032625 in raise () from /lib64/libc.so.6  
Missing separate debuginfos, use: debuginfo-install audit-libs-2.3.7-5.el6.x86_64 cyrus-sasl-lib-2.1.23-15.el6.x86_64 glibc-2.12-1.149.el6_6.9.x86_64 keyutils-libs-1.4-5.el6.x86_64 krb5-libs-1.10.3-33.el6.x86_64 libcom_err-1.41.12-21.el6.x86_64 libselinux-2.0.94-5.8.el6.x86_64 libxml2-2.7.6-17.el6_6.1.x86_64 nspr-4.10.6-1.el6_5.x86_64 nss-3.16.1-14.el6.x86_64 nss-softokn-freebl-3.14.3-17.el6.x86_64 nss-util-3.16.1-3.el6.x86_64 openldap-2.4.39-8.el6.x86_64 openssl-1.0.1e-42.el6.x86_64 pam-1.1.1-20.el6.x86_64 zlib-1.2.3-29.el6.x86_64  
  
  
(gdb) bt  
#0  0x00000038b9032625 in raise () from /lib64/libc.so.6  
#1  0x00000038b9033e05 in abort () from /lib64/libc.so.6  
#2  0x0000000000b64a3a in errfinish (dummy=0) at elog.c:572  
#3  0x0000000000547058 in xlog_redo (lsn=176848634272, record=0x2311328) at xlog.c:9309  
#4  0x0000000000540909 in StartupXLOG () at xlog.c:6920  
#5  0x00000000008b7455 in StartupProcessMain () at startup.c:224  
#6  0x000000000055a61a in AuxiliaryProcessMain (argc=2, argv=0x7fffa1f9d130) at bootstrap.c:422  
#7  0x00000000008b57e3 in StartChildProcess (type=StartupProcess) at postmaster.c:5155  
#8  0x00000000008abc59 in PostmasterMain (argc=3, argv=0x22cb280) at postmaster.c:1237  
#9  0x00000000007a8f01 in main (argc=3, argv=0x22cb280) at main.c:228  

可以看到PG的错误日志是由xlog_redo 引起,相关的代码:

xlog_redo是在数据恢复时被调用,XLOG_CHECKPOINT_SHUTDOWN是一笔数据库关闭的xlog.

        else if (info == XLOG_CHECKPOINT_SHUTDOWN)  
        {  
                CheckPoint      checkPoint;  
  
                memcpy(&checkPoint, XLogRecGetData(record), sizeof(CheckPoint));  
                /* In a SHUTDOWN checkpoint, believe the counters exactly */  
                LWLockAcquire(XidGenLock, LW_EXCLUSIVE);  
                ShmemVariableCache->nextXid = checkPoint.nextXid;  
                LWLockRelease(XidGenLock);  
                LWLockAcquire(OidGenLock, LW_EXCLUSIVE);  
                ShmemVariableCache->nextOid = checkPoint.nextOid;  
                ShmemVariableCache->oidCount = 0;  
                LWLockRelease(OidGenLock);  
                MultiXactSetNextMXact(checkPoint.nextMulti,  
                                                          checkPoint.nextMultiOffset);  
                SetTransactionIdLimit(checkPoint.oldestXid, checkPoint.oldestXidDB);  
                SetMultiXactIdLimit(checkPoint.oldestMulti, checkPoint.oldestMultiDB);  
                MultiXactSetSafeTruncate(checkPoint.oldestMulti);  
  
                /*  
                 * If we see a shutdown checkpoint while waiting for an end-of-backup  
                 * record, the backup was canceled and the end-of-backup record will  
                 * never arrive.  
                 */    此时ControlFile->backupStartPoint <>0 并且ControlFile->backupEndPoint = 0 说明备份未结束。  
                if (ArchiveRecoveryRequested &&  
                        !XLogRecPtrIsInvalid(ControlFile->backupStartPoint) &&  
                        XLogRecPtrIsInvalid(ControlFile->backupEndPoint))  
                        ereport(PANIC,  
                        (errmsg("online backup was canceled, recovery cannot continue")));  

我们可以看到,正常情况下是这样的:

postgres@digoal-> pg_controldata |grep -i backup  
Backup start location:                0/0  
Backup end location:                  0/0  
End-of-backup record required:        no  

但是当前备库的情况是这样的:

postgres@digoal-> pg_controldata /data01/pg_root_1922|grep -i back  
Minimum recovery ending location:     29/2D000028  
Min recovery ending loc's timeline:   6  
Backup start location:                29/2D000028  
Backup end location:                  0/0  
End-of-backup record required:        no  

如果我们调用了pg_stop_backend,那么会在XLOG写一笔XLOG_BACKUP_END的RECORD。

do_pg_stop_backup@src/backend/access/transam/xlog.c  
  
        stoppoint = XLogInsert(RM_XLOG_ID, XLOG_BACKUP_END, &rdata);  
......  
        /*  
         * Force a switch to a new xlog segment file, so that the backup is valid  
         * as soon as archiver moves out the current segment file.  
         */  
        RequestXLogSwitch();  

然后,在恢复时,如果遇到这个RECORD,会把 ControlFile->backupStartPoint 改成0,也就是我们看到的正常的数据。

/*  
 * XLOG resource manager's routines  
 *  
 * Definitions of info values are in include/catalog/pg_control.h, though  
 * not all record types are related to control file updates.  
 */  
void  
xlog_redo(XLogRecPtr lsn, XLogRecord *record)  
{  
......  
        else if (info == XLOG_BACKUP_END)  
        {  
......  
                if (ControlFile->backupStartPoint == startpoint)  
                {  
......  
                        ControlFile->backupStartPoint = InvalidXLogRecPtr;  

那么ControlFile->backupStartPoint == startpoint又是什么情况下会满足呢?

其实是在启动STARTUP进程时,判断有没有一个LABEL文件,有的话,就会将ControlFile->backupStartPoint改为checkPoint.redo。

/*  
 * This must be called ONCE during postmaster or standalone-backend startup  
 */  
void  
StartupXLOG(void)  
{  
......  
        /* REDO */  
        if (InRecovery)  
        {  
.......  
                /*  
                 * Set backupStartPoint if we're starting recovery from a base backup.  
                 *  
                 * Also set backupEndPoint and use minRecoveryPoint as the backup end  
                 * location if we're starting recovery from a base backup which was  
                 * taken from a standby. In this case, the database system status in  
                 * pg_control must indicate that the database was already in  
                 * recovery. Usually that will be DB_IN_ARCHIVE_RECOVERY but also can  
                 * be DB_SHUTDOWNED_IN_RECOVERY if recovery previously was interrupted  
                 * before reaching this point; e.g. because restore_command or  
                 * primary_conninfo were faulty.  
                 *  
                 * Any other state indicates that the backup somehow became corrupted  
                 * and we can't sensibly continue with recovery.  
                 */  
                if (haveBackupLabel)  
                {  
                        ControlFile->backupStartPoint = checkPoint.redo;  
                        ControlFile->backupEndRequired = backupEndRequired;  

参考

1. src/backend/access/transam/xlog.c

Flag Counter

digoal’s 大量PostgreSQL文章入口