如何阅读 postgres.log 输出？

Question

我需要提高我的数据库性能，为了实现这一点，我启用了log我的postgresql.conf：

log_statement = 'all'
log_connections = on
log_disconnections = on

为什么我有 3 个duration输出SELECT？

2016-02-29 15:35:07 CET [3492-349] postgres@uat LOG:  execute <unnamed>: SELECT ID FROM public.document WHERE documentID is NULL AND StatusID = (SELECT ID FROM public.status WHERE status = 'New') ORDER BY PriorityID DESC, ModTime ASC FOR UPDATE LIMIT 1
2016-02-29 15:35:07 CET [3492-350] postgres@uat LOG:  duration: 31.096 ms
2016-02-29 15:35:08 CET [3494-223] postgres@uat LOG:  duration: 0.090 ms
2016-02-29 15:35:08 CET [3494-224] postgres@uat LOG:  duration: 0.061 ms

编辑

更多信息：

log_min_duration_statement = 2  
log_line_prefix = '%t [%p-%l] %q%u@%d '

另一个例子：

2016-02-29 16:56:14 CET [2145-1225] postgres@uat LOG:  execute <unnamed>: SELECT ID FROM public.document WHERE documentID is NULL AND StatusID = 1 ORDER BY PriorityID DESC, ModTime ASC FOR UPDATE LIMIT 1
2016-02-29 16:56:14 CET [2139-9001] postgres@uat LOG:  duration: 48.190 ms
2016-02-29 16:56:14 CET [2139-9002] postgres@uat LOG:  duration: 0.022 ms
2016-02-29 16:56:14 CET [2139-9003] postgres@uat LOG:  execute S_3: COMMIT
2016-02-29 16:56:14 CET [2139-9004] postgres@uat LOG:  duration: 0.207 ms
2016-02-29 16:56:14 CET [2145-1226] postgres@uat LOG:  duration: 51.172 ms
2016-02-29 16:56:15 CET [2143-1691] postgres@uat LOG:  duration: 0.079 ms
2016-02-29 16:56:15 CET [2143-1692] postgres@uat LOG:  duration: 0.055 ms

随着csvlog作为输出：

2016-02-29 17:06:28.475 CET,"postgres","uat",2317,"eniac:50690",56d46bee.90d,1765,"SELECT",2016-02-29 17:03:58 CET,15/442,0,LOG,00000,"execute <unnamed>: SELECT ID FROM public.document WHERE documentID is NULL AND StatusID = 1 ORDER BY PriorityID DESC, ModTime ASC FOR UPDATE LIMIT 1",,,,,,,,,""
2016-02-29 17:06:28.507 CET,"postgres","uat",2317,"eniac:50690",56d46bee.90d,1766,"SELECT",2016-02-29 17:03:58 CET,15/442,0,LOG,00000,"duration: 31.351 ms",,,,,,,,,""
2016-02-29 17:06:28.694 CET,"postgres","uat",2308,"eniac:50677",56d46bc2.904,3043,"PARSE",2016-02-29 17:03:14 CET,8/762,0,LOG,00000,"duration: 0.079 ms",,,,,,,,,""
2016-02-29 17:06:28.694 CET,"postgres","uat",2308,"eniac:50677",56d46bc2.904,3044,"BIND",2016-02-29 17:03:14 CET,8/762,0,LOG,00000,"duration: 0.053 ms",,,,,,,,,""

Answer 1

对于使用扩展查询协议的客户端， 、 和 步骤的持续时间PARSE是BIND独立EXECUTE记录的。另请参见 的描述log_min_duration_statement。

注意：当不使用csvlogas时log_destination，仍然可以通过log_line_prefix配置中的设置来收集所有必要的信息postgresql.conf（并在完成后重新加载 PostgreSQL）。

log_line_prefix = '%t %h %p %u '        # special values:
                                        #   %a = application name
                                        #   %u = user name
                                        #   %d = database name
                                        #   %r = remote host and port
                                        #   %h = remote host
                                        #   %p = process ID
                                        #   %t = timestamp without milliseconds
                                        #   %m = timestamp with milliseconds
                                        #   %i = command tag
                                        #   %e = SQL state
                                        #   %c = session ID
                                        #   %l = session line number
                                        #   %s = session start timestamp
                                        #   %v = virtual transaction ID
                                        #   %x = transaction ID (0 if none)
                                        #   %q = stop here in non-session
                                        #        processes
                                        #   %% = '%'
                                        # e.g. '<%u%%%d>'