current community

your communities

more stack exchange communities

company blog
Stack Exchange Inbox Reputation and Badges
tour help
Database Administrators Stack Exchange is a question and answer site for database professionals who wish to improve their database skills and learn from others in the community. Join them; it only takes a minute:

Sign up
Here's how it works:
  1. Anybody can ask a question
  2. Anybody can answer
  3. The best answers are voted up and rise to the top
up vote 3 down vote favorite
1

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",,,,,,,,,""
share|improve this question
up vote 2 down vote accepted

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>'
share|improve this answer

Your Answer

 
discard

By posting your answer, you agree to the privacy policy and terms of service.

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