PostgreSQL中的tempfile探究

Posted 2021-06-13 PostgreSQLChina

一、概念简介

Tempfile，即临时文件。大家都熟悉的是当pgsql进程私有buffer不够用时，会将buffer内容dump到tempfile供postgres进程使用。常见的几个功能场景：ExecSorts、ExecHashJoin、ExecMergejoin、tempTable、CTE等，当work_mem或者是temp_buffers不足以容纳sql中间功能环节结果集时会产生tempfile。

这篇博文简单探讨下tempfile的生命周期，何时产生，何时消除，以及对于可能存在的问题的一些思考。

二、原理简析

1.tempfile产生场景

以下图片是从sourceinsight中截取的BufFileWrite函数的所有调用分支，这里并未完全展开调用链。圈起来的函数入口有ExecSort、ExecHashJoin等。

BufFileWrite函数功能是写tempfile，通过调用BufFileDumpBuffer函数，再调入FileWrite函数去写tempfile。

那这里其实有个小点，tempfile一次写多少？总计能写多大？

一般我们会配置temp_file_limit参数来限制单个进程写入量（默认为-1，也就是不限制大小），如果未配置那就是按需分配，结果集多大对应文件就多大。另外比如产生了10MB tempfile，是一次完成，还是分多次写，一次写多少。

答案是一次写8192byte，也就是8K。来看下BufFileWrite函数定义。

可以看到当写入偏移量大于等于BLCKSZ时，并且产生脏页才会去写。也就是每次写入量为BLCKSZ（默认为8192byte，代码编译时可修改）。

通过gdb跟踪来证实这个过程，数据库work_mem 和temp_buffers均配置为4MB，通过cte方式查询500MB的表的全量数据，理论上会产生490MB左右的文件。

Session1：执行sql

Session2：attach session1 sql的pid进行跟踪

/* 给FileWrite函数设置断点，直接跳转至该断点 */
(gdb) b FileWrite
Breakpoint 1 at 0x7e607f: file fd.c, line 1726.
(gdb) c
Continuing.
Breakpoint 1, FileWrite (file=4, buffer=0x14af958 '/', amount=8192, wait_event_info=167772161) at fd.c:1726
1726            returnCode = FileAccess(file);
(gdb) c
Continuing.
Breakpoint 1, FileWrite (file=4, buffer=0x14af958 'C2e27888fb795074b9819d8d61fc57a29/', amount=8192, wait_event_info=167772161) at fd.c:1726
1726            returnCode = FileAccess(file);
## 打印vfdP可以看到第一次写入的偏移量为8192
(gdb) p *vfdP
$1 = {fd = 9, fdstate = 3, resowner = 0x13ce858, nextFree = 5, lruMoreRecently = 0, lruLessRecently = 3, seekPos = 8192, fileSize = 8192, 
  fileName = 0x13b7bf0 'base/pgsql_tmp/pgsql_tmp9902.0', fileFlags = 2, fileMode = 384}
(gdb) c
Continuing.
Breakpoint 1, FileWrite (file=4, buffer=0x14af958 '978ca6ff43a5ca70e0b/', amount=8192, wait_event_info=167772161) at fd.c:1726
1726            returnCode = FileAccess(file);
/* 可以看到第二次写入的偏移量为16384，差值刚好为8192 */
(gdb) p *vfdP
$2 = {fd = 9, fdstate = 3, resowner = 0x13ce858, nextFree = 5, lruMoreRecently = 0, lruLessRecently = 3, seekPos = 16384, fileSize = 16384, 
  fileName = 0x13b7bf0 'base/pgsql_tmp/pgsql_tmp9902.0', fileFlags = 2, fileMode = 384}
(gdb)

ll查看本地文件，可以看到第一次写入后文件大小为8192，第二次写入后大小为16384。

[postgres@postgres:pg10.4:5404 ~/postgresql-10.4]$ll /data/pg10-4debug/data/base/pgsql_tmp
total 8
-rw------- 1 postgres postgres 8192 May 15 22:21 pgsql_tmp9902.0
[postgres@postgres:pg10.4:5404 ~/postgresql-10.4]$ll /data/pg10-4debug/data/base/pgsql_tmp
total 16
-rw------- 1 postgres postgres 16384 May 15 22:41 pgsql_tmp9902.0
[postgres@postgres:pg10.4:5404 ~/postgresql-10.4]$

来看下stack,可以看到sql执行时tempfile产生的整个函数调用栈。

(gdb) bt 
#0  FileWrite (file=4, buffer=0x14af958 '978ca6ff43a5ca70e0b/', amount=8192, wait_event_info=167772161) at fd.c:1726
#1  0x00000000007e8814 in BufFileDumpBuffer (file=0x14af918) at buffile.c:324
#2  0x00000000007e8a9d in BufFileWrite (file=0x14af918, ptr=0x14bf808, size=5) at buffile.c:424
#3  0x00000000009b16a3 in writetup_heap (state=0x14a61c8, tup=0x14bf7d8) at tuplestore.c:1519
#4  0x00000000009b0e6c in dumptuples (state=0x14a61c8) at tuplestore.c:1223
#5  0x00000000009b047c in tuplestore_puttuple_common (state=0x14a61c8, tuple=0x7fcdf6bc9b68) at tuplestore.c:832
#6  0x00000000009b01f2 in tuplestore_puttupleslot (state=0x14a61c8, slot=0x14a5d38) at tuplestore.c:720
#7  0x00000000006aa525 in CteScanNext (node=0x14a60b8) at nodeCtescan.c:124
#8  0x0000000000682b2a in ExecScanFetch (node=0x14a60b8, accessMtd=0x6aa39c <CteScanNext>, recheckMtd=0x6aa548 <CteScanRecheck>) at execScan.c:97
#9  0x0000000000682b99 in ExecScan (node=0x14a60b8, accessMtd=0x6aa39c <CteScanNext>, recheckMtd=0x6aa548 <CteScanRecheck>) at execScan.c:147
#10 0x00000000006aa585 in ExecCteScan (pstate=0x14a60b8) at nodeCtescan.c:164
#11 0x000000000067a3d8 in ExecProcNode (node=0x14a60b8) at ../../../src/include/executor/executor.h:250
#12 0x000000000067c81b in ExecutePlan (estate=0x14a5828, planstate=0x14a60b8, use_parallel_mode=0 '\\000', operation=CMD_SELECT, 
    sendTuples=1 '\\001', numberTuples=0, direction=ForwardScanDirection, dest=0x14a8318, execute_once=1 '\\001') at execMain.c:1722
#13 0x000000000067a874 in standard_ExecutorRun (queryDesc=0x1493a58, direction=ForwardScanDirection, count=0, execute_once=1 '\\001')
    at execMain.c:363
#14 0x00007fcdfff256bb in pgss_ExecutorRun (queryDesc=0x1493a58, direction=ForwardScanDirection, count=0, execute_once=1 '\\001')
    at pg_stat_statements.c:889
#15 0x000000000067a6f6 in ExecutorRun (queryDesc=0x1493a58, direction=ForwardScanDirection, count=0, execute_once=1 '\\001') at execMain.c:304
#16 0x000000000081ca66 in PortalRunSelect (portal=0x1494618, forward=1 '\\001', count=0, dest=0x14a8318) at pquery.c:932
#17 0x000000000081c73c in PortalRun (portal=0x1494618, count=9223372036854775807, isTopLevel=1 '\\001', run_once=1 '\\001', dest=0x14a8318, 
    altdest=0x14a8318, completionTag=0x7ffe2d2ae7b0 '') at pquery.c:773
#18 0x0000000000816cc9 in exec_simple_query (query_string=0x13b01f8 'with c as (select * from tbl_test) select * from c;') at postgres.c:1099
#19 0x000000000081ac90 in PostgresMain (argc=1, argv=0x13c7e60, dbname=0x13c7d08 'postgres', username=0x1393da8 'postgres') at postgres.c:4088
#20 0x000000000078dd6c in BackendRun (port=0x13b7a10) at postmaster.c:4405
#21 0x000000000078d515 in BackendStartup (port=0x13b7a10) at postmaster.c:4077
#22 0x0000000000789d96 in ServerLoop () at postmaster.c:1755
#23 0x000000000078941d in PostmasterMain (argc=1, argv=0x1391c70) at postmaster.c:1363
#24 0x00000000006d1616 in main (argc=1, argv=0x1391c70) at main.c:228
(gdb)

2.tempfile消除过程

同样从FileClose函数调用分支可以看到，函数入口有ExecHashJoinTableDestroy、CommitTransaction、AbortTransaction等。也就是在hashjoin结束后，以及sql提交或者回滚执行完成后，会调用FileClose消除tempfile。

另外在数据库启动时PostMaster守护进程会调用RemovePgTempFiles()函数删除之前可能残留的tempfile。（为什么会出现临时文件残留的情况文章最后会重点讨论）

当配置了temp_file_limit参数，文件超过配置大小，会进入Abortransaction流程释放文件。

接着调试文件消除过程。

Session2：继续attach session sql pid

Session3：使用pg_terminate_backend()函数终止sql查询，查询回滚

来看跟踪过程

/* 设置断点2 */ 
(gdb) b FileClose
Breakpoint 2 at 0x7e5c4d: file fd.c, line 1507.
(gdb) n
## 这时session 3执行了pg_terminate_backend(), sql进程收到了signal SIGTERM 
Program received signal SIGTERM, Terminated.
(gdb) c
Continuing.
/* 跳转至FileClose */
Breakpoint 2, FileClose (file=4) at fd.c:1507
1507            vfdP = &VfdCache[file];
1509            if (!FileIsNotOpen(file))
(gdb) 
1512                    if (close(vfdP->fd))
/* 打印vfdP，注意fileName，稍后使用unlink删除该文件 */
(gdb) p *vfdP    
$3 = {fd = 9, fdstate = 3, resowner = 0x13ce858, nextFree = 5, lruMoreRecently = 0, lruLessRecently = 3, seekPos = 2236416, fileSize = 2236416, 
  fileName = 0x13b7bf0 'base/pgsql_tmp/pgsql_tmp9902.0', fileFlags = 2, fileMode = 384}
(gdb) n
1515                    --nfile;
(gdb) 
1516                    vfdP->fd = VFD_CLOSED;
(gdb) 
1519                    Delete(file);
(gdb) 
1525            if (vfdP->fdstate & FD_TEMPORARY)
(gdb) 
1537                    vfdP->fdstate &= ~FD_TEMPORARY;
(gdb) 
1540                    temporary_files_size -= vfdP->fileSize;
(gdb) 
1541                    vfdP->fileSize = 0;
(gdb) 
1544                    if (stat(vfdP->fileName, &filestats))
(gdb) 
1547                            stat_errno = 0;
(gdb) 
/* 这里删除了fileName，即tempfile */
1550                    if (unlink(vfdP->fileName))
(gdb) 
1554                    if (stat_errno == 0)
(gdb)

ll查看文件已经被删除

[postgres@postgres:pg10.4:5404 ~/postgresql-10.4]$ll /data/pg10-4debug/data/base/pgsql_tmp
total 0
[postgres@postgres:pg10.4:5404 ~/postgresql-10.4]$

来看下删除逻辑的stack

(gdb) bt
#0  FileClose (file=4) at fd.c:1507
#1  0x00000000009a17c1 in ResourceOwnerReleaseInternal (owner=0x13ce858, phase=RESOURCE_RELEASE_AFTER_LOCKS, isCommit=0 '\\000', 
    isTopLevel=1 '\\001') at resowner.c:669
#2  0x00000000009a1435 in ResourceOwnerReleaseInternal (owner=0x13d3980, phase=RESOURCE_RELEASE_AFTER_LOCKS, isCommit=0 '\\000', 
    isTopLevel=1 '\\001') at resowner.c:506
#3  0x00000000009a1393 in ResourceOwnerRelease (owner=0x13d3980, phase=RESOURCE_RELEASE_AFTER_LOCKS, isCommit=0 '\\000', isTopLevel=1 '\\001')
    at resowner.c:482
#4  0x000000000050bc1f in AbortTransaction () at xact.c:2603
#5  0x000000000050d7d2 in AbortOutOfAnyTransaction () at xact.c:4267
#6  0x000000000097e406 in ShutdownPostgres (code=1, arg=0) at postinit.c:1146
#7  0x00000000007ee75b in shmem_exit (code=1) at ipc.c:228
#8  0x00000000007ee64f in proc_exit_prepare (code=1) at ipc.c:185
#9  0x00000000007ee5bd in proc_exit (code=1) at ipc.c:102
#10 0x000000000096ad15 in errfinish (dummy=0) at elog.c:543
#11 0x00000000008196b6 in ProcessInterrupts () at postgres.c:2882
#12 0x00000000006829b5 in ExecScanFetch (node=0x14a60b8, accessMtd=0x6aa39c <CteScanNext>, recheckMtd=0x6aa548 <CteScanRecheck>) at execScan.c:43
#13 0x0000000000682b99 in ExecScan (node=0x14a60b8, accessMtd=0x6aa39c <CteScanNext>, recheckMtd=0x6aa548 <CteScanRecheck>) at execScan.c:147
#14 0x00000000006aa585 in ExecCteScan (pstate=0x14a60b8) at nodeCtescan.c:164
#15 0x000000000067a3d8 in ExecProcNode (node=0x14a60b8) at ../../../src/include/executor/executor.h:250
#16 0x000000000067c81b in ExecutePlan (estate=0x14a5828, planstate=0x14a60b8, use_parallel_mode=0 '\\000', operation=CMD_SELECT, 
    sendTuples=1 '\\001', numberTuples=0, direction=ForwardScanDirection, dest=0x14a8318, execute_once=1 '\\001') at execMain.c:1722
#17 0x000000000067a874 in standard_ExecutorRun (queryDesc=0x1493a58, direction=ForwardScanDirection, count=0, execute_once=1 '\\001')
    at execMain.c:363
#18 0x00007fcdfff256bb in pgss_ExecutorRun (queryDesc=0x1493a58, direction=ForwardScanDirection, count=0, execute_once=1 '\\001')
    at pg_stat_statements.c:889
#19 0x000000000067a6f6 in ExecutorRun (queryDesc=0x1493a58, direction=ForwardScanDirection, count=0, execute_once=1 '\\001') at execMain.c:304
#20 0x000000000081ca66 in PortalRunSelect (portal=0x1494618, forward=1 '\\001', count=0, dest=0x14a8318) at pquery.c:932
#21 0x000000000081c73c in PortalRun (portal=0x1494618, count=9223372036854775807, isTopLevel=1 '\\001', run_once=1 '\\001', dest=0x14a8318, 
    altdest=0x14a8318, completionTag=0x7ffe2d2ae7b0 '') at pquery.c:773
#22 0x0000000000816cc9 in exec_simple_query (query_string=0x13b01f8 'with c as (select * from tbl_test) select * from c;') at postgres.c:1099
#23 0x000000000081ac90 in PostgresMain (argc=1, argv=0x13c7e60, dbname=0x13c7d08 'postgres', username=0x1393da8 'postgres') at postgres.c:4088
#24 0x000000000078dd6c in BackendRun (port=0x13b7a10) at postmaster.c:4405
#25 0x000000000078d515 in BackendStartup (port=0x13b7a10) at postmaster.c:4077
#26 0x0000000000789d96 in ServerLoop () at postmaster.c:1755
#27 0x000000000078941d in PostmasterMain (argc=1, argv=0x1391c70) at postmaster.c:1363
#28 0x00000000006d1616 in main (argc=1, argv=0x1391c70) at main.c:228
(gdb)

三、 问题讨论

之前提到了临时文件残留，那什么情况下会发生？

刚才分析了文件正常消除过程，sql执行完成，commit或者rollback。或者sql进程postgres发生ProcessInterrupts，即query cancel（recive signal SIGINT）或者query terminating (recive signal SIGTERM，query timeout)等。这些情况都有一个共同特点，sql进程未发生异常退出，也就是未发生crash。

列举几种常见的会使数据库发生crash的信号，crash之后临时文件不会删除，因为sql进程postgres收到这些信号会立即退出。

6) SIGABRT          #abort
9) SIGKILL          #kill -9
11) SIGSEGV         #segment fault

那这里是有风险的，设想一种极端的case，所有实例未配置temp_file_limit，机器上多个实例同时产生临时文件，并且依次发生多次OOM。那是不是有磁盘写满的风险。

我们使用signal SIGKILL即kill -9来模拟

Session1：查询

psql (10.4)
PG干O,天天象上!
Type 'help' for help.
postgres=# select pg_backend_pid();
 pg_backend_pid 
----------------
           9396
(1 row)
postgres=# with c as (select * from tbl_test) select * from c;

Session2：kill -9 9396

[postgres@postgres:pg10.4:5404 ~/postgresql-10.4]$kill -9 9396
[postgres@postgres:pg10.4:5404 ~/postgresql-10.4]$ll /data/pg10-4debug/data/base/pgsql_tmp
total 300344
-rw------- 1 postgres postgres 307552256 May 16 00:14 pgsql_tmp9396.0
[postgres@postgres:pg10.4:5404 ~/postgresql-10.4]

可以看到进程kill掉后，tempfile残留。

pg本身在PostMaster启动时会清理残留tempfile，但发生crash后，没有考虑清理crash进程残留的tempfile？是设计缺陷？

其实不是，清理函数注释中有这么一句话。

NOTE：we could, but don’t, call this during a post-backend-crash restart cycle. The argument for not doing it is that someone might want to examine the temp files for debugging purposes.

就是说，在crash后没清理残留tempfile，是考虑有些情况下需要调试这些文件。

仅仅因为这个原因的话感觉没有考虑到极端情况的风险，因此我尝试加入crash后清理tempfile的逻辑。(这里其实可以考虑加一个控制参数，选择crash后清理或者不清理)

Crash后具体会发生什么不详细讨论，我们都知道数据库要进行recovery，也就是主进程会干掉syslogger之外的所有的子进程，并重新拉起startup进行redo，之后再拉起其余子进程恢复。

那可以在startup 中加入清理逻辑，代码修改如下：

/* ----------------------------------
 *      Startup Process main entry point
 * ----------------------------------
 */
void
StartupProcessMain(void)
{
        /*
         * Properly accept or ignore signals the postmaster might send us.
         */
        pqsignal(SIGHUP, StartupProcSigHupHandler); /* reload config file */
        pqsignal(SIGINT, SIG_IGN);      /* ignore query cancel */
        pqsignal(SIGTERM, StartupProcShutdownHandler);  /* request shutdown */
        pqsignal(SIGQUIT, startupproc_quickdie);        /* hard crash time */
        InitializeTimeouts();           /* establishes SIGALRM handler */
        pqsignal(SIGPIPE, SIG_IGN);
        pqsignal(SIGUSR1, StartupProcSigUsr1Handler);
        pqsignal(SIGUSR2, StartupProcTriggerHandler);
        /*
         * Reset some signals that are accepted by postmaster but not here
         */
        pqsignal(SIGCHLD, SIG_DFL);
        pqsignal(SIGTTIN, SIG_DFL);
        pqsignal(SIGTTOU, SIG_DFL);
        pqsignal(SIGCONT, SIG_DFL);
        pqsignal(SIGWINCH, SIG_DFL);
        /*
         * Register timeouts needed for standby mode
         */
        RegisterTimeout(STANDBY_DEADLOCK_TIMEOUT, StandbyDeadLockHandler);
        RegisterTimeout(STANDBY_TIMEOUT, StandbyTimeoutHandler);
        RegisterTimeout(STANDBY_LOCK_TIMEOUT, StandbyLockTimeoutHandler);
        /*
         * Unblock signals (they were blocked when the postmaster forked us)
         */
        PG_SETMASK(&UnBlockSig);
        /* Modify by Nickxyang at 2021-05-15 PM 
         * After the database crash, clean up the tempfile that may remain
         */
        /* 调用清理函数 */
        RemovePgTempFiles();
        /*
         * Do what we came for.
         */
        StartupXLOG();
        /*
         * Exit normally. Exit code 0 tells postmaster that we completed recovery
         * successfully.
         */
        proc_exit(0);
}

重新编译后重启并测试

Session1：查询

[postgres@postgres:pg10.4:5404 ~]$psql
psql (10.4)
PG干O,天天象上!
Type 'help' for help.
postgres=# select pg_backend_pid();
 pg_backend_pid 
----------------
          16153
(1 row)
postgres=# with c as (select * from tbl_test) select * from c;

Session2：kill -9 16153

[postgres@postgres:pg10.4:5404 ~/postgresql-10.4]$kill -9 16153
[postgres@postgres:pg10.4:5404 ~/postgresql-10.4]$ll /data/pg10-4debug/data/base/pgsql_tmp
total 0
[postgres@posgres:pg10.4:5404 ~/postgresql-10.4]$

可以看到tempfile已经被清理，经过多次测试，符合预期。

RemovePgTempFiles函数定义位于fd.c，有兴趣可以翻阅对应源码。

了解更多PostgreSQL热点资讯、新闻动态、精彩活动，请访问中国PostgreSQL官方网站：www.postgresqlchina.com

解决更多PostgreSQL相关知识、技术、工作问题，请访问中国PostgreSQL官方问答社区：www.pgfans.cn

下载更多PostgreSQL相关资料、工具、插件问题，请访问中国PostgreSQL官方下载网站：www.postgreshub.cn