【深度】ArteryBase事务日志（4）– 事务日志误删怎么办
【深度】ArteryBase事务日志（4）– 事务日志误删怎么办
@(arterybase)
概述
在实际使用中，由于各种各样等原因，可能会将事务日志删掉，这种情况如何处理，是不是就整个库就完全不能用了？
例子1
数据库启动后，连到数据库上，插入1千万条数据。然后关闭数据库
pg_ctl start -w
psql postgres sa -c "insert into test1 select generate_series(1, 10000000)"
pg_ctl stop
删除事务日志
cd $PGDATA/pg_xlog
rm 0000*
重启数据库，无法启动
pg_ctl start
LOG: database system was shut down at 2016-10-20 11:24:06 CST
LOG: invalid primary checkpoint record
LOG: invalid secondary checkpoint record
PANIC: could not locate a valid checkpoint record
LOG: startup process (PID 52721) was terminated by signal 6: Aborted
LOG: aborting startup due to startup process failure
使用pg_controldata工具查看控制文件中的信息，得到后一个检查点的信息，如nextXID、nextOID。
$ pg_controldata | grep "Latest checkpoint's Next"
Latest checkpoint's NextXID: 0/1875
Latest chekpoint's NextOID: 40975
Latest checkpoint's NextMultiXactId: 1
Latest checkpoint's NextMultiOffset:
下一步，我们根据以上信息使用pg_resetxlog将事务日志初始化
注意： 我们一定只把它用作后的方法，就是说只有因为这样的崩溃导致服务器无法启动的时候才使用。
$ pg_resetxlog -o 40975 -x 1875 -f $PGDATA
Transaction log reset
启动数据库，可正常启动
$ pg_ctl start -w
waiting for server to start....LOG: database system was shut down at 2016-10-20 11:28:14 CST
LOG: MultiXact member wraparound protections are now enabled
LOG: database system is ready to accept connections
LOG: autovacuum launcher started
done
server started
访问及导出所有的表，均没有错误
psql postgres sa -c "select count(*) from test1"
count
---------
1000000
(1 row)
pg_dumpall -U sa >test.dmp
通过以上例子，说明在数据库正常关机情况下，删除事务日志文件，数据库是可以恢复正常的。 根据前文《【深度】ArteryBase事务日志（2）--从关机中恢复》一文中，正常关机情况下（pg_ctl stop，不加-m immediate参数）会创建关机检查点，事务日志和数据文件保持一致。重新启动时，无需重做即可恢复。
例子2
数据库启动后，待psql连到数据库上后，杀掉数据库守护进程；
$ ps -ef | grep postgres
appuser 44913 25901 04:31 pts/2 00:00:00 psql postgres appuser
appuser 52758 1 11:28 pts/ 00:00:00 /home/appuser/workspace/arterybase/bin/postgres
appuser 52760 52758 11:28 ? 00:00:00 postgres: checkpointer process
appuser 52761 52758 11:28 ? 00:00:00 postgres: writer process
appuser 52762 52758 11:28 ? 00:00:00 postgres: wal writer process
appuser 52763 52758 11:28 ? 00:00:00 postgres: autovacuum launcher process
appuser 52764 52758 11:28 ? 00:00:00 postgres: stats collector process
appuser 52834 52497 11:34 pts/ 00:00:00 grep postgres
$ kill -9 52758
在psql窗口写sql插入一千万条数据后，杀掉psql对应的服务进程
psql postgres sa
#select pg_backend_pid();
pg_backend_pid
----------------
52877
(1 row)
#insert into test1 select generate_series(1, 10000000);
Kill -9 52877
然后将pg_xlog下的事务日志都删除，然后启动数据库，数据库报错：
$ pg_ctl start
LOG: database system was interrupted; last known up at 2016-10-20 13:36:28 CST
LOG: invalid primary checkpoint record
LOG: invalid secondary checkpoint record
PANIC: could not locate a valid checkpoint record
LOG: startup process (PID 53557) was terminated by signal 6: Aborted
LOG: aborting startup due to startup process failure
跟踪源码：在读取xlog文件时，找不到文件，以下为报错堆栈：
(gdb) backtrace
#0 XLogFileRead (segno=3915, emode=13, tli=1, source=2, notfoundOk=1 '\001') at xlog.c:3351
#1 0x0000000000521342 in XLogFileReadAnyTLI (segno=3915, emode=13, source=2) at xlog.c:3436
#2 0x000000000052fcc3 in WaitForWALToBecomeAvailable (RecPtr=65682808832, randAccess=1 '\001', fetching_ckpt=1 '\001', tliRecPtr=65682920312) at xlog.c:11291
#3 0x000000000052f560 in XLogPageRead (xlogreader=0xe7af18, targetPagePtr=65682800640, reqLen=8192, targetRecPtr=65682920312, readBuf=0xe7b838 "", readTLI=0xe7b7c0) at xlog.c:10956
#4 0x0000000000534a24 in ReadPageInternal (state=0xe7af18, pageptr=65682915328, reqLen=5008) at xlogreader.c:524
#5 0x0000000000534264 in XLogReadRecord (state=0xe7af18, RecPtr=65682920312, errormsg=0x7fffffffd2f8) at xlogreader.c:243
#6 0x00000000005221e1 in ReadRecord (xlogreader=0xe7af18, RecPtr=65682920312, emode=15, fetching_ckpt=1 '\001') at xlog.c:3922
#7 0x0000000000529632 in ReadCheckpointRecord (xlogreader=0xe7af18, RecPtr=65682920312, whichChkpt=1, report=1 '\001') at xlog.c:7660
#8 0x000000000052717b in StartupXLOG () at xlog.c:6175
#9 0x000000000076e394 in StartupProcessMain () at startup.c:215
#10 0x000000000053af6f in AuxiliaryProcessMain (argc=2, argv=0x7fffffffdf80) at bootstrap.c:418
#11 0x000000000076d557 in StartChildProcess (type=StartupProcess) at postmaster.c:5203
#12 0x00000000007683b3 in PostmasterMain (argc=1, argv=0xe50f90) at postmaster.c:1288
#13 0x00000000006c018a in main (argc=1, argv=0xe50f90) at main.c:228
由于无法读取到xlog文件，系统返回NULL，在xlog.c文件中的ReadCheckpointRecord方法，输出错误日志后退出。(处理过程中，后一个检查点对应的xlog未找到，又往前找前一个检查点的xlog，如果都未找到，才退出)
record = ReadCheckpointRecord(xlogreader, checkPointLoc, 1, true);
if (record != NULL)
{
...
}
/* 从库模式 */
else if (StandbyMode)
{
...
}
/* 未找到继续找前一个检查点 */
else
{
checkPointLoc = ControlFile->prevCheckPoint;
record = ReadCheckpointRecord(xlogreader, checkPointLoc, 2, true);
if (record != NULL)
{
...
}
else
ereport(PANIC,
(errmsg("could not locate a valid checkpoint record")));
}
守护进程检测到startup process非正常退出，输出无法启动数据库，退出。
while ((pid = waitpid(-1, &exitstatus, WNOHANG)) > )
{
if (pid == StartupPID)
{
......
/* 状态不为0，退出 */
if (pmState == PM_STARTUP && !EXIT_STATUS_0(exitstatus))
{
LogChildExit(LOG, _("startup process"),
pid, exitstatus);
ereport(LOG,
(errmsg("aborting startup due to startup process failure")));
ExitPostmaster(1);
}
......
使用pg_controldata工具查看控制文件$PGDATA/global/pg_control中的信息，得到后一个检查点的信息，如nextXID、nextOID。
$ pg_controldata | grep "Latest checkpoint's Next"
Latest checkpoint's NextXID: 0/1864
Latest checkpoint's NextOID: 40971
Latest checkpoint's NextMultiXactId: 1
Latest checkpoint's NextMultiOffset:
下一步，我们将系统从后一个检查点接起来，忽略在检查点之间产生的信息
使用pg_resetxlog恢复
注意： 我们一定只把它用作后的方法，就是说只有因为这样的崩溃导致服务器无法启动的时候才使用。
$ pg_resetxlog -o 40971 -x 1864 -f $PGDATA
Transaction log reset
启动数据库
$ pg_ctl start -w
waiting for server to start....LOG: database system was shut down at 2016-10-19 14:04:37 CST
LOG: MultiXact member wraparound protections are now enabled
LOG: database system is ready to accept connections
LOG: autovacuum launcher started
done
server started
数据库虽然已经启动，但启动后一段时间，查看后台日志，频繁报错：
CONTEXT: writing block 625696 of relation base/13241/40970
ERROR: xlog flush request E/DA06ED78 is not satisfied --- flushed only to E/DA014238
DETAIL: Multiple failures --- write error might be permanent.
根据日志查看是哪个表出了问题，是被杀掉的进程对应的表test1出问题了。
select relname from pg_class where relfilenode = 40970;
relname
---------
test1
(1 row)
此时，其他操作均无法进行，重启数据库，访问该表部分数据ok，访问全部数据报错，报错后系统无法使用。
select * from test1 limit 10;
---ok
select count(*) from test1;
--报错
LOG: request to flush past end of generated WAL; request E/DB0D7368, currpos E/DB0AD130
CONTEXT: writing block 626882 of relation base/13241/40970
FATAL: xlog flush request E/DB0D7368 is not satisfied --- flushed only to E/DB0AD130
重启后将该表的数据导出。
pg_dump -d postgres -U sa -t test1 >test1.dmp
导出过程中也报上述错误，但该数据确实可以导出。
清空test1表，并导入备份数据。
psql postgres sa -c "truncate table test1"
psql postgres sa -f test1.dmp
成功导入，但数据不完整。因为在杀进程时，部分脏页写回磁盘，部分未写，又没有事务日志来redo。因此，应该从业务上校正这些数据。
注意： 以上报错情形只是可能出现的一种情形，如果脏页完全未写入磁盘，也有可能数据完全未插入。总之，可能出现各种奇怪的数据。
后续处理
虽然进行了恢复，但数据完整性得不到保证。应该将实例A作为保留实例，新建一个数据库实例B，并将实例A中的数据导入到实例B，并进行数据校正，校正后方可使用。
总结
事务日志系列文章4篇，详细介绍了事务日志原理、事务日志文件为什么不能通过直接删除文件的方式删除、事务日志膨胀原因解决办法以及事务日志误删的处理方法，希望能够了解事务日志的运行机理，避免因为不了解导致严重问题，当出现严重问题时，能够迅速想到解决办法，提高数据库的可用性。
来自：https://mp.weixin.qq.com/s/nwV0gSANAysRCKif3mx0nQ
相关文章