Help us understand the problem. What is going on with this article?

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

More than 1 year has passed since last update.

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

$ 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

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

ma273c
Why not register and get more from Qiita?
  1. We will deliver articles that match you
    By following users and tags, you can catch up information on technical fields that you are interested in as a whole
  2. you can read useful information later efficiently
    By "stocking" the articles you like, you can search right away