Re: "idle in transaction" entry in pg_logs

On Fri, Nov 11, 2011 at 4:18 AM, Raghavendra <
raghavendra(dot)rao(at)enterprisedb(dot)com> 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(at)%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(at)postgres-[0]-22398-idle LOG:
> statement: begin;
> 2011-10-05 18:28:22.029 IST-postgres(at)postgres-[0]-22398-BEGIN LOG:
> duration: 0.703 ms
> 2011-10-05 18:28:39.847 IST-postgres(at)postgres-*[0]*-22398-idle in
> transaction LOG: statement: insert into abc VALUES (11);
> 2011-10-05 18:28:39.848 IST-postgres(at)postgres-[682]-22398-INSERT LOG:
> duration: 0.474 ms
> 2011-10-05 18:29:00.591 IST-postgres(at)postgres-[682]-22398-idle in
> transaction LOG: statement: end;
> 2011-10-05 18:29:00.595 IST-postgres(at)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(at)postgres-[0]-22398-idle LOG:
> statement: begin;
> 2011-10-05 18:20:15.922 IST-postgres(at)postgres-[0]-22398-idle in
> transaction LOG: statement: insert into abc VALUES (10);
> 2011-10-05 18:20:27.633 IST-postgres(at)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