［PostgreSQL］ fd.cのデバッグメッセージを表示する

起動時とかのファイル関連の処理を把握するために試してみた。
ビルド時の手順。

$ make clean
$ ./configure CFLAGS=-DFDDEBUG
$ make
$ sudo make install

fd.cはデバッグメッセージ出力用にマクロDO_DBが定義されており、FDDEBUGが定義されているときだけログ出力用関数のelogを呼ぶような記述が多くされている。上のconfigureの引数CFLAGSではそれを指定している。

src/backend/storage/file/fd.c

 147 /* Debugging.... */
 148          
 149 #ifdef FDDEBUG
 150 #define DO_DB(A) \                                                                                   
 151     do { \
 152         int         _do_db_save_errno = errno; \
 153         A; \
 154         errno = _do_db_save_errno; \
 155     } while (0)
 156 #else    
 157 #define DO_DB(A) \
 158     ((void) 0)
 159 #endif 

起動時の標準出力はこんな感じ。

$ pg_ctl start
waiting for server to start....LOG:  00000: AllocateDir: Allocated 0 (/usr/local/pgsql/lib)
LOCATION:  AllocateDir, fd.c:2374
LOG:  00000: FreeDir: Allocated 1
LOCATION:  FreeDir, fd.c:2482
2018-02-17 08:09:38.201 GMT [17037] LOG:  AllocateFile: Allocated 0 (/home/matsu/pgsql/postgresql.conf)
2018-02-17 08:09:38.203 GMT [17037] LOG:  FreeFile: Allocated 1
2018-02-17 08:09:38.203 GMT [17037] LOG:  AllocateFile: Allocated 0 (/home/matsu/pgsql/postgresql.conf)
2018-02-17 08:09:38.206 GMT [17037] LOG:  FreeFile: Allocated 1
2018-02-17 08:09:38.206 GMT [17037] LOG:  AllocateFile: Allocated 0 (/home/matsu/pgsql/postgresql.auto.conf)
2018-02-17 08:09:38.206 GMT [17037] LOG:  FreeFile: Allocated 1
2018-02-17 08:09:38.206 GMT [17037] LOG:  AllocateDir: Allocated 0 (/usr/local/pgsql/share/timezone)
2018-02-17 08:09:38.206 GMT [17037] LOG:  FreeDir: Allocated 1
2018-02-17 17:09:38.207 JST [17037] LOG:  AllocateFile: Allocated 0 (/usr/local/pgsql/share/timezonesets/Default)
2018-02-17 17:09:38.208 JST [17037] LOG:  FreeFile: Allocated 1
2018-02-17 17:09:38.208 JST [17037] LOG:  AllocateFile: Allocated 0 (/home/matsu/pgsql/PG_VERSION)
2018-02-17 17:09:38.208 JST [17037] LOG:  FreeFile: Allocated 1
2018-02-17 17:09:38.208 JST [17037] LOG:  AllocateFile: Allocated 0 (/home/matsu/pgsql/global/pg_control)
2018-02-17 17:09:38.208 JST [17037] LOG:  FreeFile: Allocated 1
2018-02-17 17:09:38.219 JST [17037] LOG:  listening on IPv4 address "127.0.0.1", port 5432
2018-02-17 17:09:38.225 JST [17037] LOG:  listening on Unix socket "/tmp/.s.PGSQL.5432"
2018-02-17 17:09:38.228 JST [17037] LOG:  AllocateFile: Allocated 0 (/proc/meminfo)
2018-02-17 17:09:38.229 JST [17037] LOG:  FreeFile: Allocated 1
2018-02-17 17:09:38.246 JST [17037] LOG:  AllocateDir: Allocated 0 (pg_notify)
2018-02-17 17:09:38.246 JST [17037] LOG:  FreeDir: Allocated 1
2018-02-17 17:09:38.246 JST [17037] LOG:  OpenTransientFile: Allocated 0 (pg_notify/0000)
2018-02-17 17:09:38.246 JST [17037] LOG:  CloseTransientFile: Allocated 1
2018-02-17 17:09:38.247 JST [17037] LOG:  AllocateDir: Allocated 0 (base/pgsql_tmp)
2018-02-17 17:09:38.247 JST [17037] LOG:  AllocateDir: Allocated 0 (base)
2018-02-17 17:09:38.247 JST [17037] LOG:  AllocateDir: Allocated 1 (base/12362)
2018-02-17 17:09:38.247 JST [17037] LOG:  FreeDir: Allocated 2
2018-02-17 17:09:38.247 JST [17037] LOG:  AllocateDir: Allocated 1 (base/1)
2018-02-17 17:09:38.248 JST [17037] LOG:  FreeDir: Allocated 2
2018-02-17 17:09:38.248 JST [17037] LOG:  AllocateDir: Allocated 1 (base/16384)
2018-02-17 17:09:38.248 JST [17037] LOG:  FreeDir: Allocated 2
2018-02-17 17:09:38.248 JST [17037] LOG:  AllocateDir: Allocated 1 (base/12361)
2018-02-17 17:09:38.248 JST [17037] LOG:  FreeDir: Allocated 2
2018-02-17 17:09:38.248 JST [17037] LOG:  FreeDir: Allocated 1
2018-02-17 17:09:38.248 JST [17037] LOG:  AllocateDir: Allocated 0 (pg_tblspc)
2018-02-17 17:09:38.248 JST [17037] LOG:  FreeDir: Allocated 1
2018-02-17 17:09:38.249 JST [17037] LOG:  AllocateFile: Allocated 0 (/home/matsu/pgsql/pg_hba.conf)
2018-02-17 17:09:38.249 JST [17037] LOG:  FreeFile: Allocated 1
2018-02-17 17:09:38.249 JST [17037] LOG:  AllocateFile: Allocated 0 (/home/matsu/pgsql/pg_ident.conf)
2018-02-17 17:09:38.249 JST [17037] LOG:  FreeFile: Allocated 1
2018-02-17 17:09:38.255 JST [17037] LOG:  #IK testparam1 is FALSE
2018-02-17 17:09:38.255 JST [17038] LOG:  AllocateFile: Allocated 0 (/home/matsu/pgsql/PG_VERSION)
2018-02-17 17:09:38.255 JST [17038] LOG:  FreeFile: Allocated 1
2018-02-17 17:09:38.255 JST [17038] LOG:  database system was shut down at 2018-02-17 17:07:13 JST
2018-02-17 17:09:38.255 JST [17038] LOG:  AllocateFile: Allocated 0 (recovery.conf)
2018-02-17 17:09:38.255 JST [17038] LOG:  AllocateFile: Allocated 0 (backup_label)
2018-02-17 17:09:38.255 JST [17038] LOG:  AllocateDir: Allocated 0 (base)
2018-02-17 17:09:38.255 JST [17038] LOG:  FreeDir: Allocated 1
2018-02-17 17:09:38.255 JST [17038] LOG:  AllocateDir: Allocated 0 (pg_tblspc)
2018-02-17 17:09:38.255 JST [17038] LOG:  FreeDir: Allocated 1
2018-02-17 17:09:38.255 JST [17038] LOG:  AllocateDir: Allocated 0 (pg_replslot)
2018-02-17 17:09:38.255 JST [17038] LOG:  FreeDir: Allocated 1
2018-02-17 17:09:38.255 JST [17038] LOG:  AllocateDir: Allocated 0 (pg_replslot)
2018-02-17 17:09:38.255 JST [17038] LOG:  FreeDir: Allocated 1
2018-02-17 17:09:38.255 JST [17038] LOG:  OpenTransientFile: Allocated 0 (pg_logical/replorigin_checkpoint)
2018-02-17 17:09:38.255 JST [17038] LOG:  CloseTransientFile: Allocated 1
2018-02-17 17:09:38.255 JST [17038] LOG:  AllocateDir: Allocated 0 (pg_twophase)
2018-02-17 17:09:38.255 JST [17038] LOG:  FreeDir: Allocated 1
2018-02-17 17:09:38.255 JST [17038] LOG:  OpenTransientFile: Allocated 0 (pg_xact/0000)
2018-02-17 17:09:38.255 JST [17038] LOG:  CloseTransientFile: Allocated 1
2018-02-17 17:09:38.255 JST [17038] LOG:  OpenTransientFile: Allocated 0 (pg_multixact/offsets/0000)
2018-02-17 17:09:38.256 JST [17038] LOG:  CloseTransientFile: Allocated 1
2018-02-17 17:09:38.256 JST [17038] LOG:  AllocateDir: Allocated 0 (pg_commit_ts)
2018-02-17 17:09:38.256 JST [17038] LOG:  FreeDir: Allocated 1
2018-02-17 17:09:38.259 JST [17039] LOG:  AllocateFile: Allocated 0 (/home/matsu/pgsql/PG_VERSION)
2018-02-17 17:09:38.259 JST [17040] LOG:  AllocateFile: Allocated 0 (/home/matsu/pgsql/PG_VERSION)
2018-02-17 17:09:38.259 JST [17041] LOG:  AllocateFile: Allocated 0 (/home/matsu/pgsql/PG_VERSION)
2018-02-17 17:09:38.259 JST [17039] LOG:  FreeFile: Allocated 1
2018-02-17 17:09:38.259 JST [17037] LOG:  database system is ready to accept connections
2018-02-17 17:09:38.259 JST [17040] LOG:  FreeFile: Allocated 1
2018-02-17 17:09:38.259 JST [17041] LOG:  FreeFile: Allocated 1
2018-02-17 17:09:38.259 JST [17043] LOG:  AllocateFile: Allocated 0 (pg_stat/global.stat)
2018-02-17 17:09:38.259 JST [17043] LOG:  AllocateFile: Allocated 1 (pg_stat/db_16384.stat)
2018-02-17 17:09:38.259 JST [17044] LOG:  OpenTransientFile: Allocated 0 (global/pg_filenode.map)
2018-02-17 17:09:38.259 JST [17043] LOG:  FreeFile: Allocated 2
2018-02-17 17:09:38.259 JST [17044] LOG:  CloseTransientFile: Allocated 1
2018-02-17 17:09:38.259 JST [17044] LOG:  AllocateFile: Allocated 0 (global/pg_internal.init)
2018-02-17 17:09:38.259 JST [17042] LOG:  OpenTransientFile: Allocated 0 (global/pg_filenode.map)
2018-02-17 17:09:38.259 JST [17042] LOG:  CloseTransientFile: Allocated 1
2018-02-17 17:09:38.259 JST [17042] LOG:  AllocateFile: Allocated 0 (global/pg_internal.init)
2018-02-17 17:09:38.259 JST [17043] LOG:  AllocateFile: Allocated 1 (pg_stat/db_0.stat)
2018-02-17 17:09:38.259 JST [17043] LOG:  FreeFile: Allocated 2
2018-02-17 17:09:38.260 JST [17044] LOG:  PathNameOpenFilePerm: global/24654 2 600
2018-02-17 17:09:38.260 JST [17044] LOG:  AllocateVfd. Size 1
2018-02-17 17:09:38.260 JST [17043] LOG:  FreeFile: Allocated 1
2018-02-17 17:09:38.260 JST [17042] LOG:  PathNameOpenFilePerm: global/24815 2 600
2018-02-17 17:09:38.260 JST [17044] LOG:  PathNameOpenFile: success 3
2018-02-17 17:09:38.260 JST [17042] LOG:  AllocateVfd. Size 1
2018-02-17 17:09:38.260 JST [17044] LOG:  Insert 1 ((null))
2018-02-17 17:09:38.260 JST [17042] LOG:  PathNameOpenFile: success 3
2018-02-17 17:09:38.260 JST [17044] LOG:  LRU: MOST 0 LEAST
2018-02-17 17:09:38.260 JST [17042] LOG:  Insert 1 ((null))
2018-02-17 17:09:38.260 JST [17044] LOG:  LRU: MOST 1 0 LEAST
2018-02-17 17:09:38.260 JST [17042] LOG:  LRU: MOST 0 LEAST
2018-02-17 17:09:38.260 JST [17042] LOG:  LRU: MOST 1 0 LEAST
2018-02-17 17:09:38.260 JST [17044] LOG:  FileSeek: 1 (global/24654) 0 0 2
2018-02-17 17:09:38.260 JST [17042] LOG:  FileSeek: 1 (global/24815) 0 0 2
2018-02-17 17:09:38.260 JST [17042] LOG:  FileSeek: 1 (global/24815) 8192 0 0
2018-02-17 17:09:38.260 JST [17044] LOG:  FileSeek: 1 (global/24654) 0 0 2
2018-02-17 17:09:38.260 JST [17042] LOG:  FileRead: 1 (global/24815) 0 8192 0x7ff776178080
2018-02-17 17:09:38.260 JST [17042] LOG:  FileAccess 1 (global/24815)
2018-02-17 17:09:38.260 JST [17042] LOG:  AllocateFile: Allocated 0 (pg_stat_tmp/global.stat)
2018-02-17 17:09:38.260 JST [17043] LOG:  AllocateFile: Allocated 0 (pg_stat_tmp/global.tmp)
2018-02-17 17:09:38.260 JST [17043] LOG:  AllocateFile: Allocated 1 (pg_stat_tmp/db_0.tmp)
2018-02-17 17:09:38.260 JST [17043] LOG:  FreeFile: Allocated 2
2018-02-17 17:09:38.260 JST [17043] LOG:  FreeFile: Allocated 1
2018-02-17 17:09:38.270 JST [17042] LOG:  AllocateFile: Allocated 0 (pg_stat_tmp/global.stat)
2018-02-17 17:09:38.270 JST [17042] LOG:  FreeFile: Allocated 1
2018-02-17 17:09:38.270 JST [17042] LOG:  AllocateFile: Allocated 0 (pg_stat_tmp/global.stat)
2018-02-17 17:09:38.270 JST [17042] LOG:  FreeFile: Allocated 1
 done
server started

ちょっと量が多いので、まずは単純にファイルオープン・クローズだけ出力するようにした方が理解はすすみそう。