"idle in transaction" entry in pg_logs - Mailing list pgsql-general

From Raghavendra
Subject "idle in transaction" entry in pg_logs
Date
Msg-id CA+h6AhjMwjcbj0i=94GUJC1Q+yKP3_5=4JymM1NL1Mha_NMk2w@mail.gmail.com
Whole thread Raw
Responses Re: "idle in transaction" entry in pg_logs  (Raghavendra <raghavendra.rao@enterprisedb.com>)
List pgsql-general
Respected,

All the time we see 'idle in transaction' in pg_stat_activity and dig details with process pid from pg_logs for the query,query execution time etc.. 
Instead of searching with process pid, am trying to pull the information with shell scripting for lines prefixed with 'idle in transaction' in pg_logs line.
With log_line_prefix  %i option I can see logs are prefixing 'idle in transaction'. 

log_line_prefix =  '%m-%u@%d-[%x]-%p-%i'

Case 1: [ log_min_duration_statement = 0, log_statement='all', log_duration=off or log_duration=on ] 
In logs:

2011-10-05 18:28:22.028 IST-postgres@postgres-[0]-22398-idle LOG:  statement: begin;
2011-10-05 18:28:22.029 IST-postgres@postgres-[0]-22398-BEGIN LOG:  duration: 0.703 ms
2011-10-05 18:28:39.847 IST-postgres@postgres-[0]-22398-idle in transaction LOG:  statement: insert into abc VALUES (11);
2011-10-05 18:28:39.848 IST-postgres@postgres-[682]-22398-INSERT LOG:  duration: 0.474 ms
2011-10-05 18:29:00.591 IST-postgres@postgres-[682]-22398-idle in transaction LOG:  statement: end;
2011-10-05 18:29:00.595 IST-postgres@postgres-[0]-22398-COMMIT LOG:  duration: 3.216 ms

Case 2: [ log_min_duration_statement = -1, log_statement='all', log_duration=off ] 
In logs:

2011-10-05 18:20:04.612 IST-postgres@postgres-[0]-22398-idle LOG:  statement: begin;
2011-10-05 18:20:15.922 IST-postgres@postgres-[0]-22398-idle in transaction LOG:  statement: insert into abc VALUES (10);
2011-10-05 18:20:27.633 IST-postgres@postgres-[681]-22398-idle in transaction LOG:  statement: end;

Sample transaction did twice with above changes to log parameters:
postgres=# begin;
BEGIN
postgres=# insert into abc VALUES (11);
INSERT 0 1
postgres=# end;
COMMIT

Question:

1. Is it a standard behavior in Case 1, that every transaction will write two lines in logs ? (i.e., if log_statement='all' and log_duration=on and log_min_duration=0 and log_statement='all')

2. I used %x in log_line_prefix to get transaction id, but I see transaction-id written in logs only when its committed. You can see in both the cases. Why its not written at first occurrence ?

Thanks in Advance. 

---
Regards,
Raghavendra
EnterpriseDB Corporation

pgsql-general by date:

Previous
From: John R Pierce
Date:
Subject: Re: PostgreSQL uninstall fails
Next
From: slavix
Date:
Subject: Re: troubleshooting PGError