PostgreSQL log AND trace AND debug 详解

9 minute read

背景

PostgreSQL在代码中放了大量的输出数据库运行状态的函数, 例如这段代码, 在参数文件postgresql.conf中开启了log_connections的情况下, 将输出数据库接收到连接请求时的客户端主机和端口信息.

src/backend/postmaster/postmaster.c

        if (Log_connections)  
        {  
                if (remote_port[0])  
                        ereport(LOG,  
                                        (errmsg("connection received: host=%s port=%s",  
                                                        remote_host,  
                                                        remote_port)));  
                else  
                        ereport(LOG,  
                                        (errmsg("connection received: host=%s",  
                                                        remote_host)));  
        }  

PostgreSQL一般使用elog或ereport来输出消息. 输出消息时包含了消息级别, 这些级别被用于日志文件或客户端作为过滤条件, 定义如下 :

src/include/utils/elog.h

#ifdef HAVE__BUILTIN_CONSTANT_P  
#define elog(elevel, ...)  \  
        do { \  
                elog_start(__FILE__, __LINE__, PG_FUNCNAME_MACRO); \  
                elog_finish(elevel, __VA_ARGS__); \  
                if (__builtin_constant_p(elevel) && (elevel) >= ERROR) \  
                        pg_unreachable(); \  
        } while(0)  
#else                                                   /* !HAVE__BUILTIN_CONSTANT_P */  
#define elog(elevel, ...)  \  
        do { \  
                int             elevel_; \  
                elog_start(__FILE__, __LINE__, PG_FUNCNAME_MACRO); \  
                elevel_ = (elevel); \  
                elog_finish(elevel_, __VA_ARGS__); \  
                if (elevel_ >= ERROR) \  
                        pg_unreachable(); \  
        } while(0)  
#endif   /* HAVE__BUILTIN_CONSTANT_P */  
#define ereport(elevel, rest)   \  
        ereport_domain(elevel, TEXTDOMAIN, rest)  

消息级别的定义如下 :

/* Error level codes */  
#define DEBUG5          10                      /* Debugging messages, in categories of  
                                                                 * decreasing detail. */  
#define DEBUG4          11  
#define DEBUG3          12  
#define DEBUG2          13  
#define DEBUG1          14                      /* used by GUC debug_* variables */  
#define LOG                     15                      /* Server operational messages; sent only to  
                                                                 * server log by default. */  
#define COMMERROR       16                      /* Client communication problems; same as LOG  
                                                                 * for server reporting, but never sent to  
                                                                 * client. */  
#define INFO            17                      /* Messages specifically requested by user (eg  
                                                                 * VACUUM VERBOSE output); always sent to  
                                                                 * client regardless of client_min_messages,  
                                                                 * but by default not sent to server log. */  
#define NOTICE          18                      /* Helpful messages to users about query  
                                                                 * operation; sent to client and server log by  
                                                                 * default. */  
#define WARNING         19                      /* Warnings.  NOTICE is for expected messages  
                                                                 * like implicit sequence creation by SERIAL.  
                                                                 * WARNING is for unexpected messages. */  
#define ERROR           20                      /* user error - abort transaction; return to  
                                                                 * known state */  
#ifdef WIN32  
#define PGERROR         20  
#endif  
#define FATAL           21                      /* fatal error - abort process */  
#define PANIC           22                      /* take down the other backends with me */  

那么这些信息都输出到哪里去了呢?

正文

PostgreSQL日志信息输出位置配置, 如下举例 :

log_destination = 'csvlog'              # Valid values are combinations of  
                                        # stderr, csvlog, syslog, and eventlog,  
                                        # depending on platform.  csvlog  
                                        # requires logging_collector to be on.  
log_directory = '/mnt/csvlog'           # directory where log files are written,  
                                        # can be absolute or relative to PGDATA  
#log_filename = 'postgresql-%Y-%m-%d_%H%M%S.log'        # log file name pattern,  
                                        # can include strftime() escapes  
log_error_verbosity = verbose           # terse, default, or verbose messages  

以csvlog为例, 日志信息记录在/mnt/csvlog中, 信息举例 :

pg93@db-172-16-3-150-> less postgresql-2014-03-19_171700.csv  
2014-03-19 17:17:02.870 CST,,,17705,"",5329608e.4529,1,"",2014-03-19 17:17:02 CST,,0,LOG,00000,"connection received: host=[local]",,,,,,,,"BackendInitialize, postmaster.c:3854",""  

因为设置了log_error_verbosity = verbose, 将输出代码信息, 指这条log信息是哪个函数输出的.

哪些日志会打印到csvlog, 或者客户端会话呢? 由以下参数决定, 级别越高, 输出的消息越多 :

需要注意log_min_messages的log位置在比较低的级别, 如果设置为log, 将不会在csvlog中输出error级别以及以上级别的消息.

但是client_min_messages的log位置在error之上, 所以设置为log的话, 客户端能看到错误级别的消息.

#client_min_messages = notice           # values in order of decreasing detail:  
                                        #   debug5  
                                        #   debug4  
                                        #   debug3  
                                        #   debug2  
                                        #   debug1  
                                        #   log  
                                        #   notice  
                                        #   warning  
                                        #   error  
#log_min_messages = warning             # values in order of decreasing detail:  
                                        #   debug5  
                                        #   debug4  
                                        #   debug3  
                                        #   debug2  
                                        #   debug1  
                                        #   info  
                                        #   notice  
                                        #   warning  
                                        #   error  
                                        #   log  
                                        #   fatal  
                                        #   panic  
#log_min_error_statement = error        # values in order of decreasing detail:  
                                        #   debug5  
                                        #   debug4  
                                        #   debug3  
                                        #   debug2  
                                        #   debug1  
                                        #   info  
                                        #   notice  
                                        #   warning  
                                        #   error  
                                        #   log  
                                        #   fatal  
                                        #   panic (effectively off)  

例如 :

把客户端的日志打印级别改为error, 那么notice级别的消息将不会被打印.

digoal=# set client_min_messages=error;  
SET  
digoal=# do language plpgsql $$  
digoal$# declare  
digoal$# begin  
digoal$#   raise notice 'this is a test.';  
digoal$# end;  
digoal$# $$;  
DO  

把客户端的日志打印级别改为notice, 那么这个例子的notice级别的消息会被打印出来.

digoal=# set client_min_messages=notice;  
SET  
digoal=# do language plpgsql $$  
declare  
begin  
  raise notice 'this is a test.';  
end;  
$$;  
NOTICE:  this is a test.  
DO  

因此要输出最详细的全局信息, 把log_min_messages设置为debug5, 如果要得到当前会话的最详细的信息, 把client_min_messages设置为debug5即可.

除此之外, 数据库还定义了一些隐藏的消息输出, 需要开启某些参数, 或者在编译前打开一些定义才会输出, 例如 :

1. 开发参数中提到的某些参数需要在编译时开启某些宏的定义, 这些参数才能生效.

http://www.postgresql.org/docs/9.3/static/runtime-config-developer.html

debug_assertions 需要开启宏USE_ASSERT_CHECKING   
  
trace_locks , trace_lwlocks , trace_userlocks , trace_lock_oidmin , trace_lock_table , debug_deadlocks 需要开启宏LOCK_DEBUG   
  
log_btree_build_stats 需要开启宏BTREE_BUILD_STATS   
  
wal_debug 需要开启宏WAL_DEBUG.  

2. 在参数文件What To Log中提到的一些

http://www.postgresql.org/docs/9.3/static/runtime-config-logging.html#RUNTIME-CONFIG-LOGGING-WHAT

application_name (string) 输出客户端指定的应用名  
debug_print_parse (boolean) 输出parse阶段的信息  
debug_print_rewritten (boolean) 输出rewritten阶段的信息  
debug_print_plan (boolean) 输出执行计划信息  
debug_pretty_print (boolean) 以比较易读的方式输出以上三个参数的信息  
log_checkpoints (boolean) 输出检查点信息  
log_connections (boolean) 输出连接信息  
log_disconnections (boolean) 输出断开连接信息  
log_duration (boolean) 输出SQL语句执行时间信息  
log_error_verbosity (enum) 输出详细级别, 例如函数以及代码文件名  
log_hostname (boolean) 主机名  
log_line_prefix (string) 输出位置为标准输出或者系统日志时, 指定输出格式  
log_lock_waits (boolean) 输出锁等待  
log_statement (enum) 按过滤条件输出SQL语句, 例如ddl, mod, all  
log_temp_files (integer)  按过滤条件输出临时文件相关信息  
log_timezone (string) 指定时区  

3. 在代码中定义的宏, 可以开启一些隐藏的输出, 例如:

src/include/pg_config_manual.h

/*  
 * Define this to force all parse and plan trees to be passed through  
 * copyObject(), to facilitate catching errors and omissions in  
 * copyObject().  
 */  
/* #define COPY_PARSE_PLAN_TREES */  
/*  
 * Enable debugging print statements for lock-related operations.  
 */  
/* #define LOCK_DEBUG */  
/*  
 * Enable debugging print statements for WAL-related operations; see  
 * also the wal_debug GUC var.  
 */  
/* #define WAL_DEBUG */  
/*  
 * Enable tracing of resource consumption during sort operations;  
 * see also the trace_sort GUC var.  For 8.1 this is enabled by default.  
 */  
#define TRACE_SORT 1  
/*  
 * Enable tracing of syncscan operations (see also the trace_syncscan GUC var).  
 */  
/* #define TRACE_SYNCSCAN */  
/*  
 * Other debug #defines (documentation, anyone?)  
 */  
/* #define HEAPDEBUGALL */  
/* #define ACLDEBUG */  
/* #define RTDEBUG */  

src/backend/optimizer/path/allpaths.c

#ifdef OPTIMIZER_DEBUG  
        debug_print_rel(root, rel);  
#endif  

src/backend/optimizer/geqo/geqo_main.c

#ifdef GEQO_DEBUG  
        elog(DEBUG1, "GEQO best is %.2f after %d generations",  
                 pool->data[0].worth, number_generations);  
#endif  

src/backend/regex/regcomp.c

#ifdef REG_DEBUG  
        if (debug != NULL)  
        {  
                fprintf(debug, "\n\n\n========= TREE FIXED ==========\n");  
                dumpst(v->tree, debug, 1);  
        }  
#endif  

src/backend/utils/adt/acl.c

#ifdef ACLDEBUG  
        elog(LOG, "aclparse: input = \"%s\"", s);  
#endif  

src/backend/utils/adt/arrayfuncs.c

#ifdef ARRAYDEBUG  
        printf("array_in- ndim %d (", ndim);  
        for (i = 0; i < ndim; i++)  
        {  
                printf(" %d", dim[i]);  
        };  
        printf(") for %s\n", string);  
#endif  
...  

PostgreSQL还有专门的统计信息收集进程, 用来收集数据库运行过程的信息.

例如在postgresql.conf文件中可以定义的参数如下 :

#track_activities = on    # 跟踪SQL语句的状态以及SQL语句的内容. 输出到pg_stat_activity  
#track_counts = on    # 计数器, 例如表被插入了多少次, 更新了多少次  
#track_io_timing = off   #  跟踪IO操作的时间, 例如一个SQL语句带来的IO时间是多少.   
#track_functions = none                 # none, pl, all   # 跟踪函数的调用次数, 时间.  
track_activity_query_size = 4096        # (change requires restart)  # 输出SQL语句的最大长度, 超出截断  
#update_process_title = on   # 更新进程状态信息, 例如从select到idle, 显示进程当前的状态.  
#stats_temp_directory = 'pg_stat_tmp'    
# - Statistics Monitoring -  
#log_parser_stats = off  
#log_planner_stats = off  
#log_executor_stats = off  
#log_statement_stats = off  

使用举例

默认情况下可跟踪的信息举例

1. 跟踪排序

digoal=# set client_min_messages=log;  
digoal=# set trace_sort=on;  
digoal=# select count(*) from (select * from pg_class order by relpages) t;  
LOG:  begin tuple sort: nkeys = 1, workMem = 1024, randomAccess = f  
LOG:  performsort starting: CPU 0.00s/0.00u sec elapsed 0.00 sec  
LOG:  performsort done: CPU 0.00s/0.00u sec elapsed 0.00 sec  
LOG:  internal sort ended, 108 KB used: CPU 0.00s/0.00u sec elapsed 0.00 sec  
 count   
-------  
   304  
(1 row)  

2. 跟踪执行计划

digoal=# set client_min_messages=log;  
digoal=# set debug_pretty_print = on;  
digoal=# set debug_print_parse=on;  
SET  
digoal=# select count(*) from (select * from pg_class order by relpages) t;  
LOG:  parse tree:  
DETAIL:     {QUERY   
... 略  
digoal=# set debug_print_rewritten = on;  
LOG:  rewritten parse tree:  
DETAIL:  (  
   {QUERY   
... 略  
digoal=# set debug_print_plan = on;  
digoal=# select count(*) from (select * from pg_class order by relpages) t;  
LOG:  plan:  
DETAIL:     {PLANNEDSTMT   
   :commandType 1   
... 略  

3. 跟踪死锁

SESSION A :   
digoal=# create table t(id int, info text);  
CREATE TABLE  
digoal=# insert into t values (1,'test'),(2,'test');  
INSERT 0 2  
digoal=# begin;  
BEGIN  
digoal=# update t set info='new' where id=1;  
UPDATE 1  
  
  
SESSOIN B :   
digoal=# begin;  
BEGIN  
digoal=# update t set info='new' where id=2;  
UPDATE 1  
digoal=# update t set info='new' where id=1;  
  
  
SESSION A :   
digoal=# update t set info='new' where id=2;  
  
ERROR:  deadlock detected  
DETAIL:  Process 6173 waits for ShareLock on transaction 3268512748; blocked by process 6214.  
Process 6214 waits for ShareLock on transaction 3268512747; blocked by process 6173.  
HINT:  See server log for query details.  

4. 跟踪锁超时SQL

log_lock_waits = on  
deadlock_timeout = 1s  
  
SESSION A :   
digoal=# begin;  
BEGIN  
digoal=# update t set info='new' where id=1;  
UPDATE 1  
  
  
SESSION B :   
digoal=# set client_min_messages=log;  
SET  
digoal=# begin;  
BEGIN  
digoal=# update t set info='new' where id=1;  
LOG:  statement: update t set info='new' where id=1;  
LOG:  process 6499 still waiting for ShareLock on transaction 3268512749 after 1000.177 ms  

5. 跟踪超时SQL

log_min_duration_statement = 100ms  # 记录执行时间超过100毫秒的SQL  

6. 跟踪检查点,连接和断开连接信息

log_checkpoints = on  
log_connections = on  
log_disconnections = on  

7. 跟踪函数

track_functions = all  

需要打开某些宏才可以跟踪的信息

不推荐在生产环境中使用, 举例

[root@db-172-16-3-150 postgresql-9.3.3]# vi src/Makefile.custom  
CFLAGS+=-DLOCK_DEBUG  
CFLAGS+=-DBTREE_BUILD_STATS  
CFLAGS+=-DWAL_DEBUG  
CFLAGS+=-DOPTIMIZER_DEBUG  
CFLAGS+=-DGEQO_DEBUG  
CFLAGS+=-DCOPY_PARSE_PLAN_TREES  
CFLAGS+=-DTRACE_SYNCSCAN  

重新编译安装PostgreSQL.

1. 跟踪btree索引建立时的信息

digoal=# create table test(id int, info text);  
digoal=# set client_min_messages=log;  
digoal=# insert into test select generate_series(1,100000),'test';  
LOG:  statement: insert into test select generate_series(1,100000),'test';  
INSERT 0 100000  
digoal=# set log_btree_build_stats =on;  
SET  
digoal=# \set VERBOSITY verbose  
digoal=# create index idx_test_1 on test(id);  
LOG:  00000: statement: create index idx_test_1 on test(id);  
LOCATION:  exec_simple_query, postgres.c:890  
LOG:  00000: BTREE BUILD (Spool) STATISTICS  
DETAIL:  ! system usage stats:  
!       0.048502 elapsed 0.040993 user 0.006999 system sec  
!       [0.328949 user 0.038994 sys total]  
!       0/0 [0/13888] filesystem blocks in/out  
!       0/1706 [0/8926] page faults/reclaims, 0 [0] swaps  
!       0 [0] signals rcvd, 0/0 [0/0] messages rcvd/sent  
!       0/0 [74/1] voluntary/involuntary context switches  
LOCATION:  ShowUsage, postgres.c:4400  
LOG:  00000: BTREE BUILD STATS  
DETAIL:  ! system usage stats:  
!       0.043534 elapsed 0.031996 user 0.002999 system sec  
!       [0.360945 user 0.041993 sys total]  
!       0/4864 [0/18752] filesystem blocks in/out  
!       0/741 [0/9667] page faults/reclaims, 0 [0] swaps  
!       0 [0] signals rcvd, 0/0 [0/0] messages rcvd/sent  
!       9/1 [83/2] voluntary/involuntary context switches  
LOCATION:  ShowUsage, postgres.c:4400  
CREATE INDEX  

2. 跟踪锁

digoal=# set trace_locks=on;  
LOG:  00000: LockReleaseAll: lockmethod=1  
LOCATION:  LockReleaseAll, lock.c:1954  
LOG:  00000: LockReleaseAll done  
LOCATION:  LockReleaseAll, lock.c:2199  
SET  
digoal=# update t set info='test' where id=1;  
LOG:  00000: statement: update t set info='test' where id=1;  
LOCATION:  exec_simple_query, postgres.c:890  
LOG:  00000: LockAcquire: lock [16384,26061] RowExclusiveLock  
LINE 1: update t set info='test' where id=1;  
               ^  
LOCATION:  LockAcquireExtended, lock.c:729  
LOG:  00000: LockAcquire: lock [16384,26061] RowExclusiveLock  
LOCATION:  LockAcquireExtended, lock.c:729  
LOG:  00000: LockAcquire: lock [16384,26061] ExclusiveLock  
LOCATION:  LockAcquireExtended, lock.c:729  
LOG:  00000: LockAcquire: new: lock(0x7f6970d12b00) id(16384,26061,0,1,3,1) grantMask(0) req(0,0,0,0,0,0,0)=0 grant(0,0,0,0,0,0,0)=0 wait(0) type(ExclusiveLock)  
LOCATION:  LOCK_PRINT, lock.c:318  
LOG:  00000: LockAcquire: new: proclock(0x7f6970d98440) lock(0x7f6970d12b00) method(1) proc(0x7f6971004860) hold(0)  
LOCATION:  PROCLOCK_PRINT, lock.c:330  
LOG:  00000: LockCheckConflicts: no conflict: proclock(0x7f6970d98440) lock(0x7f6970d12b00) method(1) proc(0x7f6971004860) hold(0)  
LOCATION:  PROCLOCK_PRINT, lock.c:330  
LOG:  00000: GrantLock: lock(0x7f6970d12b00) id(16384,26061,0,1,3,1) grantMask(80) req(0,0,0,0,0,0,1)=1 grant(0,0,0,0,0,0,1)=1 wait(0) type(ExclusiveLock)  
LOCATION:  LOCK_PRINT, lock.c:318  
LOG:  00000: process 6499 still waiting for ShareLock on transaction 3268512749 after 1000.118 ms  
LOCATION:  ProcSleep, proc.c:1246  
LOG:  00000: process 6499 acquired ShareLock on transaction 3268512749 after 5021.627 ms  
LOCATION:  ProcSleep, proc.c:1250  
LOG:  00000: LockRelease: lock [16384,26061] ExclusiveLock  
LOCATION:  LockRelease, lock.c:1761  
LOG:  00000: LockRelease: found: lock(0x7f6970d12b00) id(16384,26061,0,1,3,1) grantMask(80) req(0,0,0,0,0,0,1)=1 grant(0,0,0,0,0,0,1)=1 wait(0) type(ExclusiveLock)  
LOCATION:  LOCK_PRINT, lock.c:318  
LOG:  00000: LockRelease: found: proclock(0x7f6970d98440) lock(0x7f6970d12b00) method(1) proc(0x7f6971004860) hold(80)  
LOCATION:  PROCLOCK_PRINT, lock.c:330  
LOG:  00000: UnGrantLock: updated: lock(0x7f6970d12b00) id(16384,26061,0,1,3,1) grantMask(0) req(0,0,0,0,0,0,0)=0 grant(0,0,0,0,0,0,0)=0 wait(0) type(ExclusiveLock)  
LOCATION:  LOCK_PRINT, lock.c:318  
LOG:  00000: UnGrantLock: updated: proclock(0x7f6970d98440) lock(0x7f6970d12b00) method(1) proc(0x7f6971004860) hold(0)  
LOCATION:  PROCLOCK_PRINT, lock.c:330  
LOG:  00000: CleanUpLock: deleting: proclock(0x7f6970d98440) lock(0x7f6970d12b00) method(1) proc(0x7f6971004860) hold(0)  
LOCATION:  PROCLOCK_PRINT, lock.c:330  
LOG:  00000: CleanUpLock: deleting: lock(0x7f6970d12b00) id(16384,26061,0,1,3,1) grantMask(0) req(0,0,0,0,0,0,0)=0 grant(0,0,0,0,0,0,0)=0 wait(0) type(INVALID)  
LOCATION:  LOCK_PRINT, lock.c:318  
LOG:  00000: LockReleaseAll: lockmethod=1  
LOCATION:  LockReleaseAll, lock.c:1954  
LOG:  00000: LockReleaseAll done  
LOCATION:  LockReleaseAll, lock.c:2199  
UPDATE 1  

3. 跟踪wal

#ifdef WAL_DEBUG  
  
static void  
xlog_outrec(StringInfo buf, XLogRecord *record)  
{  
        int                     i;  
  
        appendStringInfo(buf, "prev %X/%X; xid %u",  
                                         (uint32) (record->xl_prev >> 32),  
                                         (uint32) record->xl_prev,  
                                         record->xl_xid);  
  
        appendStringInfo(buf, "; len %u",  
                                         record->xl_len);  
  
        for (i = 0; i < XLR_MAX_BKP_BLOCKS; i++)  
        {  
                if (record->xl_info & XLR_BKP_BLOCK(i))  
                        appendStringInfo(buf, "; bkpb%d", i);  
        }  
  
        appendStringInfo(buf, ": %s", RmgrTable[record->xl_rmid].rm_name);  
}  
#endif   /* WAL_DEBUG */  
  
digoal=# set wal_debug=on;  
digoal=# select pg_switch_xlog();  
LOG:  00000: INSERT @ 20E/D4BB2878: prev 20E/D4BB2848; xid 0; len 0: XLOG  
LOCATION:  XLogInsert, xlog.c:1077  
 pg_switch_xlog   
----------------  
 20E/D4BB2898  
(1 row)  

其他跟踪方法, 本文不再举例.

1. stap

2. strace

3. gdb

4. perf

参考

1. http://blog.163.com/digoal@126/blog/static/163877040201302843359574/

2. src/include/utils/elog.h

3. http://www.postgresql.org/docs/9.3/static/runtime-config-developer.html

4. http://www.postgresql.org/docs/9.3/static/runtime-config-logging.html#RUNTIME-CONFIG-LOGGING-WHAT

Flag Counter

digoal’s 大量PostgreSQL文章入口