5

I need to improve my database performance, in order to achieve that, I enabled the log in my postgresql.conf:

log_statement = 'all'
log_connections = on
log_disconnections = on

Why do I have 3 duration output in this 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

EDIT

More information:

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

Another example:

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

With csvlog as output:

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",,,,,,,,,""
3

For clients using the extended query protocol, durations of PARSE, BIND, and EXECUTE steps are logged independently. See also the description of log_min_duration_statement.

Note: when not using csvlog as log_destination, one can still collect all the necessary information by configuring the log_line_prefix setting in postgresql.conf (and reload PostgreSQL when done).

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>'

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service, privacy policy and cookie policy

Not the answer you're looking for? Browse other questions tagged or ask your own question.