Re: "idle in transaction" entry in pg_logs

[Raghavendra <raghavendra.rao@xxxxxxxxxxxxxxxx>]

On Fri, Nov 11, 2011 at 4:18 AM, Raghavendra <raghavendra.rao@xxxxxxxxxxxxxxxx> wrote:

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

Blog: http://raghavt.blogspot.com/

Apologies for not mentioning my PG version.

Am using PG 9.0.1

--Raghav