1

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.

Improve this question

1 Answer 1

Reset to default
2

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.

Improve this answer
2
  • 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?
    – David S
    Commented Jan 16, 2014 at 6:47
  • @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.
    – Craig Ringer
    Commented Jan 16, 2014 at 7:40

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service and acknowledge you have read our privacy policy.

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