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.

No correct solution

Licensed under: CC-BY-SA with attribution
Not affiliated with dba.stackexchange
scroll top