Postgresql Logging Questions

Question

I'm seeking some help understanding my PostgreSQL 9.3 log file.

(Note: maybe this should be multiple questions, they are all involve the same general topic - which is understanding my log file). In my postgresql.conf file I have the following log related settings:

log_min_duration_statement = 0
log_line_prefix = '%m session_id: %c; trans_id: %x '
log_statement = 'all'

If I have the following in my log:

2014年01月15日 21:39:22.217 PST session_id: 52d7708a.eb7; trans_id: 0 LOG: statement: BEGIN
2014年01月15日 21:39:22.217 PST session_id: 52d7708a.eb7; trans_id: 0 LOG: duration: 0.132 ms
2014年01月15日 21:39:22.218 PST session_id: 52d7708a.eb7; trans_id: 0 LOG: statement: SELECT t.oid, typarray
 FROM pg_type t JOIN pg_namespace ns
 ON typnamespace = ns.oid
 WHERE typname = 'hstore';
2014年01月15日 21:39:22.219 PST session_id: 52d7708a.eb7; trans_id: 0 LOG: duration: 1.651 ms
2014年01月15日 21:39:22.220 PST session_id: 52d7708a.eb7; trans_id: 0 LOG: statement: ROLLBACK
2014年01月15日 21:39:22.220 PST session_id: 52d7708a.eb7; trans_id: 0 LOG: duration: 0.043 ms
2014年01月15日 21:39:22.220 PST session_id: 52d7708a.eb7; trans_id: 0 LOG: statement: BEGIN
2014年01月15日 21:39:22.220 PST session_id: 52d7708a.eb7; trans_id: 0 LOG: duration: 0.028 ms
2014年01月15日 21:39:22.220 PST session_id: 52d7708a.eb7; trans_id: 0 LOG: statement: select version()
2014年01月15日 21:39:22.221 PST session_id: 52d7708a.eb7; trans_id: 0 LOG: duration: 0.204 ms
2014年01月15日 21:39:22.222 PST session_id: 52d7708a.eb7; trans_id: 0 LOG: statement: select current_schema()
2014年01月15日 21:39:22.222 PST session_id: 52d7708a.eb7; trans_id: 0 LOG: duration: 0.136 ms
2014年01月15日 21:39:22.222 PST session_id: 52d7708a.eb7; trans_id: 0 LOG: statement: show transaction isolation level
2014年01月15日 21:39:22.222 PST session_id: 52d7708a.eb7; trans_id: 0 LOG: duration: 0.065 ms
2014年01月15日 21:39:22.223 PST session_id: 52d7708a.eb7; trans_id: 0 LOG: statement: SELECT CAST('test plain returns' AS VARCHAR(60)) AS anon_1
2014年01月15日 21:39:22.223 PST session_id: 52d7708a.eb7; trans_id: 0 LOG: duration: 0.281 ms
2014年01月15日 21:39:22.223 PST session_id: 52d7708a.eb7; trans_id: 0 LOG: statement: SELECT CAST('test unicode returns' AS VARCHAR(60)) AS anon_1
2014年01月15日 21:39:22.223 PST session_id: 52d7708a.eb7; trans_id: 0 LOG: duration: 0.063 ms
2014年01月15日 21:39:22.224 PST session_id: 52d7708a.eb7; trans_id: 0 LOG: statement: SELECT 'x' AS some_label
2014年01月15日 21:39:22.224 PST session_id: 52d7708a.eb7; trans_id: 0 LOG: duration: 0.053 ms
2014年01月15日 21:39:22.224 PST session_id: 52d7708a.eb7; trans_id: 0 LOG: statement: ROLLBACK
2014年01月15日 21:39:22.224 PST session_id: 52d7708a.eb7; trans_id: 0 LOG: duration: 0.032 ms
2014年01月15日 21:39:22.224 PST session_id: 52d7708a.eb7; trans_id: 0 LOG: statement: BEGIN
2014年01月15日 21:39:22.224 PST session_id: 52d7708a.eb7; trans_id: 0 LOG: duration: 0.023 ms
2014年01月15日 21:39:22.224 PST session_id: 52d7708a.eb7; trans_id: 0 LOG: statement: show standard_conforming_strings
2014年01月15日 21:39:22.224 PST session_id: 52d7708a.eb7; trans_id: 0 LOG: duration: 0.035 ms
2014年01月15日 21:39:22.225 PST session_id: 52d7708a.eb7; trans_id: 0 LOG: statement: SELECT api_log_entry.id AS api_log_entry_id 
 FROM api_log_entry
2014年01月15日 21:39:22.227 PST session_id: 52d7708a.eb7; trans_id: 0 LOG: duration: 1.319 ms

Questions:

In this log snipped, does each log entry (everything with a duration) represent a call from the client app (and is a round trip)?

Given my log_line_prefix, why is trans_id showing up as zero? It scare me to say but I thought Id see a new trans_id for each "BEGIN" that was logged.

Answer 1

Everything there is probably a client round-trip, but you'll find that multistatements show individual durations for each component statement. The times are for the time spent executing it on the server, not the time including network access.

Entries with no transaction ID appear because PostgreSQL uses "virtual transaction IDs" to reduce the rate of consumption of transaction IDs, only assigning a real txid when there's a write or lock operation.

• David S: Thank you for the reply. I understand about the durations not include network access. Is there anyway to tell the difference between single and multi-statement queries?
• Craig Ringer: @DavidS Not AFAIK from the logs, but you could try comparing. IIRC psql -c "select ...; select ...;" sends a multi-statement query. To confirm I'd need to attach gdb to the server and check the query exec which I don't have time for at the moment, but see if it produces different results in the logs to each statement running separate.