Thread: PostgreSQL server "idle in transaction"

Hello,

We face with our application servers (ESQL/C written) and a 14.1 server
on Linux, the situation that the PostgreSQL backend for servers are
saying "idle in transaction". One can see this in the table
pg_stat_activity and also on the shell:

$ ps -ef | grep transaction
postgres  6979 24002  0 11:05 ?  00:00:00 postgres: sisis testdb 127.0.0.1(58620) idle in transaction

testdb=# select * from pg_stat_activity where pid=6979;
 datid  | datname | pid  | leader_pid | usesysid | usename |        application_name        | client_addr |
client_hostname| client_port |         backend_start          |           xact_start           |          query_start
       |          state_change          | wait_event_type | wait_event |        state        | backend_xid |
backend_xmin| query_id |                    query                     |  backend_type
 

 734526 | testdb  | 6979 |            |    16384 | sisis   | SunRise DBCALL V7.3 (pid=6978) | 127.0.0.1   |
   |       58620 | 15.11.2022 11:05:50.153359 CET | 15.11.2022 11:05:50.173748 CET | 15.11.2022 11:05:50.174322 CET |
15.11.202211:05:50.174346 CET | Client          | ClientRead | idle in transaction |             |     17444593 |
  | select name from pg_cursors where name = $1  | client backend
 

The application server itself has done some initializations, updated a
table about the fact that it was started, commited the update and waits
for work to do (which would be come as commands over some network
socket). The last PostgreSQL related action was looking into the table
'pg_cursors' to see if some used CURSOR is still open, which was not the
case. This last query is still visible in pg_stat_activity.query.

I have below the full ESQL/C log and do not understand, why the
PostgreSQL server is thinking "idle in transaction". For me with the
"COMMIT" on the line below marked with ^^^^^ the transaction was closed.
Am I wrong?

[6978] [15.11.2022 11:05:50:152]: ECPGdebug: set to 1
[6978] [15.11.2022 11:05:50:152]: ECPGdebug: proc argv0 is Z39Targetd
[6978] [15.11.2022 11:05:50:152]: ECPGconnect: opening database testdb on localhost port 5432 with options
application_name=SunRiseDBCALL V7.3 (pid=6978) for user sisis
 
[6978] [15.11.2022 11:05:50:157]: ecpg_execute on line 859: query: select current_date; with 0 parameter(s) on
connectiontestdb
 
[6978] [15.11.2022 11:05:50:157]: ecpg_execute on line 859: using PQexec
[6978] [15.11.2022 11:05:50:157]: ecpg_process_output on line 859: correctly got 1 tuples with 1 fields
[6978] [15.11.2022 11:05:50:157]: ecpg_get_data on line 859: RESULT: 15.11.2022 offset: 80; array: no
[6978] [15.11.2022 11:05:50:159]: ecpg_execute on line 1191: query: declare sisisinst_seq cursor with hold for SELECT
ctid,* from sisisinst WHERE version  = $1; with 1 parameter(s) on connection testdb
 
[6978] [15.11.2022 11:05:50:160]: ecpg_execute on line 1191: using PQexecParams
[6978] [15.11.2022 11:05:50:160]: ecpg_free_params on line 1191: parameter 1 = V7.3
[6978] [15.11.2022 11:05:50:160]: ecpg_process_output on line 1191: OK: DECLARE CURSOR
[6978] [15.11.2022 11:05:50:160]: ecpg_execute on line 1678: query: fetch sisisinst_seq; with 0 parameter(s) on
connectiontestdb
 
[6978] [15.11.2022 11:05:50:160]: ecpg_execute on line 1678: using PQexec
[6978] [15.11.2022 11:05:50:160]: ecpg_process_output on line 1678: correctly got 1 tuples with 7 fields
[6978] [15.11.2022 11:05:50:160]: ecpg_get_data on line 1678: RESULT: (1,10) offset: 19; array: no
[6978] [15.11.2022 11:05:50:160]: ecpg_get_data on line 1678: RESULT: 10.03.2022 offset: 137; array: no
[6978] [15.11.2022 11:05:50:160]: ecpg_get_data on line 1678: RESULT: srap51dxr1-20220310       offset: 137; array: no
[6978] [15.11.2022 11:05:50:160]: ecpg_get_data on line 1678: RESULT: Upgrade V7.2 -> V7.3
 offset: 137; array: no
 
[6978] [15.11.2022 11:05:50:160]: ecpg_get_data on line 1678: RESULT: sisisbase                 offset: 137; array: no
[6978] [15.11.2022 11:05:50:160]: ecpg_get_data on line 1678: RESULT:  offset: 137; array: no
[6978] [15.11.2022 11:05:50:160]: ecpg_get_data on line 1678: RESULT: V7.3       offset: 137; array: no
[6978] [15.11.2022 11:05:50:160]: ecpg_execute on line 1208: query: declare z39t_user_seq cursor with hold for SELECT
ctid,* from z39t_user WHERE groupid  = $1 AND loginid  = $2; with 2 parameter(s) on connection testdb
 
[6978] [15.11.2022 11:05:50:164]: ecpg_execute on line 1208: using PQexecParams
[6978] [15.11.2022 11:05:50:164]: ecpg_free_params on line 1208: parameter 1 = gast
[6978] [15.11.2022 11:05:50:164]: ecpg_free_params on line 1208: parameter 2 = gast
[6978] [15.11.2022 11:05:50:164]: ecpg_process_output on line 1208: OK: DECLARE CURSOR
[6978] [15.11.2022 11:05:50:164]: ecpg_execute on line 1709: query: fetch z39t_user_seq; with 0 parameter(s) on
connectiontestdb
 
[6978] [15.11.2022 11:05:50:165]: ecpg_execute on line 1709: using PQexec
[6978] [15.11.2022 11:05:50:165]: ecpg_process_output on line 1709: correctly got 1 tuples with 4 fields
[6978] [15.11.2022 11:05:50:165]: ecpg_get_data on line 1709: RESULT: (0,1) offset: 19; array: no
[6978] [15.11.2022 11:05:50:166]: ecpg_get_data on line 1709: RESULT: gast                 offset: 93; array: no
[6978] [15.11.2022 11:05:50:166]: ecpg_get_data on line 1709: RESULT: gast                 offset: 93; array: no
[6978] [15.11.2022 11:05:50:166]: ecpg_get_data on line 1709: RESULT: gast
offset: 93; array: no
 
[6978] [15.11.2022 11:05:50:167]: ecpg_execute on line 1161: query: declare z39t_report_seq cursor with hold for SELECT
ctid,* from z39t_report WHERE associd  = $1; with 1 parameter(s) on connection testdb
 
[6978] [15.11.2022 11:05:50:168]: ecpg_execute on line 1161: using PQexecParams
[6978] [15.11.2022 11:05:50:168]: ecpg_free_params on line 1161: parameter 1 = 1
[6978] [15.11.2022 11:05:50:168]: ecpg_process_output on line 1161: OK: DECLARE CURSOR
[6978] [15.11.2022 11:05:50:168]: ecpg_execute on line 1634: query: fetch z39t_report_seq; with 0 parameter(s) on
connectiontestdb
 
[6978] [15.11.2022 11:05:50:170]: ecpg_execute on line 1634: using PQexec
[6978] [15.11.2022 11:05:50:170]: ecpg_process_output on line 1634: correctly got 1 tuples with 7 fields
[6978] [15.11.2022 11:05:50:170]: ecpg_get_data on line 1634: RESULT: (0,39) offset: 19; array: no
[6978] [15.11.2022 11:05:50:170]: ecpg_get_data on line 1634: RESULT: 1 offset: 168; array: no
[6978] [15.11.2022 11:05:50:170]: ecpg_get_data on line 1634: RESULT: gast;gast;gast
                                                                      offset: 168; array: no
 
[6978] [15.11.2022 11:05:50:170]: ecpg_get_data on line 1634: RESULT: 0 offset: 168; array: no
[6978] [15.11.2022 11:05:50:170]: ecpg_get_data on line 1634: RESULT: 0 offset: 168; array: no
[6978] [15.11.2022 11:05:50:170]: ecpg_get_data on line 1634: RESULT: 3 offset: 168; array: no
[6978] [15.11.2022 11:05:50:170]: ecpg_get_data on line 1634: RESULT: 0 offset: 168; array: no
[6978] [15.11.2022 11:05:50:170]: ecpg_execute on line 2310: query: select currtid2 ( 'z39t_report' :: text , $1  ::
tid); with 1 parameter(s) on connection testdb
 
[6978] [15.11.2022 11:05:50:171]: ecpg_execute on line 2310: using PQexecParams
[6978] [15.11.2022 11:05:50:171]: ecpg_free_params on line 2310: parameter 1 = (0,39)
[6978] [15.11.2022 11:05:50:171]: ecpg_process_output on line 2310: correctly got 1 tuples with 1 fields
[6978] [15.11.2022 11:05:50:171]: ecpg_get_data on line 2310: RESULT: (0,39) offset: 80; array: no
[6978] [15.11.2022 11:05:50:171]: ecpg_execute on line 1427: query: declare hc_z39t_report cursor for SELECT * FROM
z39t_reportWHERE ctid = $1 FOR UPDATE; with 1 parameter(s) on connection testdb
 
[6978] [15.11.2022 11:05:50:171]: ecpg_execute on line 1427: using PQexecParams
[6978] [15.11.2022 11:05:50:171]: ecpg_free_params on line 1427: parameter 1 = (0,39)
[6978] [15.11.2022 11:05:50:171]: ecpg_process_output on line 1427: OK: DECLARE CURSOR
[6978] [15.11.2022 11:05:50:171]: ecpg_execute on line 1432: query: fetch hc_z39t_report; with 0 parameter(s) on
connectiontestdb 
[6978] [15.11.2022 11:05:50:171]: ecpg_execute on line 1432: using PQexec
[6978] [15.11.2022 11:05:50:171]: ecpg_process_output on line 1432: correctly got 1 tuples with 6 fields
[6978] [15.11.2022 11:05:50:171]: ecpg_get_data on line 1432: RESULT: 1 offset: 168; array: no
[6978] [15.11.2022 11:05:50:171]: ecpg_get_data on line 1432: RESULT: gast;gast;gast
                                                                      offset: 168; array: no
 
[6978] [15.11.2022 11:05:50:171]: ecpg_get_data on line 1432: RESULT: 0 offset: 168; array: no
[6978] [15.11.2022 11:05:50:171]: ecpg_get_data on line 1432: RESULT: 0 offset: 168; array: no
[6978] [15.11.2022 11:05:50:171]: ecpg_get_data on line 1432: RESULT: 3 offset: 168; array: no
[6978] [15.11.2022 11:05:50:171]: ecpg_get_data on line 1432: RESULT: 0 offset: 168; array: no
[6978] [15.11.2022 11:05:50:171]: ecpg_execute on line 2025: query: update z39t_report set associd = $1  , tuser = $2
,searchrecords = $3  , presentrecords = $4  , assoctime = $5  , assoccost = $6  where current of hc_z39t_report; with 6
parameter(s)on connection testdb
 
[6978] [15.11.2022 11:05:50:172]: ecpg_execute on line 2025: using PQexecParams
[6978] [15.11.2022 11:05:50:172]: ecpg_free_params on line 2025: parameter 1 = 1
[6978] [15.11.2022 11:05:50:172]: ecpg_free_params on line 2025: parameter 2 = gast;gast;gast
[6978] [15.11.2022 11:05:50:172]: ecpg_free_params on line 2025: parameter 3 = 0
[6978] [15.11.2022 11:05:50:172]: ecpg_free_params on line 2025: parameter 4 = 0
[6978] [15.11.2022 11:05:50:172]: ecpg_free_params on line 2025: parameter 5 = 7
[6978] [15.11.2022 11:05:50:172]: ecpg_free_params on line 2025: parameter 6 = 0
[6978] [15.11.2022 11:05:50:172]: ecpg_process_output on line 2025: OK: UPDATE 1
[6978] [15.11.2022 11:05:50:172]: ecpg_execute on line 2310: query: select currtid2 ( 'z39t_report' :: text , $1  ::
tid); with 1 parameter(s) on connection testdb
 
[6978] [15.11.2022 11:05:50:172]: ecpg_execute on line 2310: using PQexecParams
[6978] [15.11.2022 11:05:50:172]: ecpg_free_params on line 2310: parameter 1 = (0,39)
[6978] [15.11.2022 11:05:50:172]: ecpg_process_output on line 2310: correctly got 1 tuples with 1 fields
[6978] [15.11.2022 11:05:50:172]: ecpg_get_data on line 2310: RESULT: (0,41) offset: 80; array: no
[6978] [15.11.2022 11:05:50:172]: ECPGtrans on line 1211: action "commit"; connection "testdb"
^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
[6978] [15.11.2022 11:05:50:173]: ecpg_execute on line 543: query: select name from pg_cursors where name = $1 ; with 1
parameter(s)on connection testdb
 
[6978] [15.11.2022 11:05:50:174]: ecpg_execute on line 543: using PQexecParams
[6978] [15.11.2022 11:05:50:174]: ecpg_free_params on line 543: parameter 1 = hc_z39t_report
[6978] [15.11.2022 11:05:50:174]: ecpg_process_output on line 543: correctly got 0 tuples with 1 fields
-- 
Matthias Apitz, ✉ guru@unixarea.de, http://www.unixarea.de/ +49-176-38902045
Public GnuPG key: http://www.unixarea.de/key.pub

On 11/15/22 04:28, Matthias Apitz wrote:
> 
> Hello,
> 
> We face with our application servers (ESQL/C written) and a 14.1 server
> on Linux, the situation that the PostgreSQL backend for servers are
> saying "idle in transaction". One can see this in the table
> pg_stat_activity and also on the shell:
> 
> $ ps -ef | grep transaction
> postgres  6979 24002  0 11:05 ?  00:00:00 postgres: sisis testdb 127.0.0.1(58620) idle in transaction
> 
> testdb=# select * from pg_stat_activity where pid=6979;
>   datid  | datname | pid  | leader_pid | usesysid | usename |        application_name        | client_addr |
client_hostname| client_port |         backend_start          |           xact_start           |          query_start
       |          state_change          | wait_event_type | wait_event |        state        | backend_xid |
backend_xmin| query_id |                    query                     |  backend_type
 
> 
>   734526 | testdb  | 6979 |            |    16384 | sisis   | SunRise DBCALL V7.3 (pid=6978) | 127.0.0.1   |
      |       58620 | 15.11.2022 11:05:50.153359 CET | 15.11.2022 11:05:50.173748 CET | 15.11.2022 11:05:50.174322 CET
|15.11.2022 11:05:50.174346 CET | Client          | ClientRead | idle in transaction |             |     17444593 |
    | select name from pg_cursors where name = $1  | client backend
 
> 
> The application server itself has done some initializations, updated a
> table about the fact that it was started, commited the update and waits
> for work to do (which would be come as commands over some network
> socket). The last PostgreSQL related action was looking into the table
> 'pg_cursors' to see if some used CURSOR is still open, which was not the
> case. This last query is still visible in pg_stat_activity.query.
> 
> I have below the full ESQL/C log and do not understand, why the
> PostgreSQL server is thinking "idle in transaction". For me with the
> "COMMIT" on the line below marked with ^^^^^ the transaction was closed.
> Am I wrong?

The query being shown 'idle in transaction' is:

select name from pg_cursors where name = $1

 From your log:

[6978] [15.11.2022 11:05:50:172]: ECPGtrans on line 1211: action 
"commit"; connection "testdb"
^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
[6978] [15.11.2022 11:05:50:173]: ecpg_execute on line 543: query: 
select name from pg_cursors where name = $1 ; with 1 parameter(s) on 
connection testdb

So that query is being executed after the COMMIT.

-- 
Adrian Klaver
adrian.klaver@aklaver.com

Adrian Klaver <adrian.klaver@aklaver.com> writes:
> On 11/15/22 04:28, Matthias Apitz wrote:
>> I have below the full ESQL/C log and do not understand, why the
>> PostgreSQL server is thinking "idle in transaction". For me with the
>> "COMMIT" on the line below marked with ^^^^^ the transaction was closed.

> From your log:

> [6978] [15.11.2022 11:05:50:172]: ECPGtrans on line 1211: action
> "commit"; connection "testdb"
> ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
> [6978] [15.11.2022 11:05:50:173]: ecpg_execute on line 543: query:
> select name from pg_cursors where name = $1 ; with 1 parameter(s) on
> connection testdb

> So that query is being executed after the COMMIT.

Right.  By default, ecpg would start a new transaction block for that.
See

https://www.postgresql.org/docs/current/ecpg-commands.html#ECPG-TRANSACTIONS

            regards, tom lane

El día Dienstag, November 15, 2022 a las 10:28:11 -0500, Tom Lane escribió:

> Adrian Klaver <adrian.klaver@aklaver.com> writes:
> > On 11/15/22 04:28, Matthias Apitz wrote:
> >> I have below the full ESQL/C log and do not understand, why the
> >> PostgreSQL server is thinking "idle in transaction". For me with the
> >> "COMMIT" on the line below marked with ^^^^^ the transaction was closed.
> 
> > From your log:
> 
> > [6978] [15.11.2022 11:05:50:172]: ECPGtrans on line 1211: action 
> > "commit"; connection "testdb"
> > ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
> > [6978] [15.11.2022 11:05:50:173]: ecpg_execute on line 543: query: 
> > select name from pg_cursors where name = $1 ; with 1 parameter(s) on 
> > connection testdb
> 
> > So that query is being executed after the COMMIT.
> 
> Right.  By default, ecpg would start a new transaction block for that.
> See
> 
> https://www.postgresql.org/docs/current/ecpg-commands.html#ECPG-TRANSACTIONS
> 

Thank you. This page makes it clear why the last search started a
transaction, which at the end is pending due to a missing COMMIT.

On the other hand, when we would set EXEC SQL SET AUTOCOMMIT TO ON, when does
the transaction block starts exactly (which could be rolled back), as
there is no EXEC SQL BEGIN?

Thanks again

    matthias

-- 
Matthias Apitz, ✉ guru@unixarea.de, http://www.unixarea.de/ +49-176-38902045
Public GnuPG key: http://www.unixarea.de/key.pub
May, 9: Спаси́бо освободители! Thank you very much, Russian liberators!

El día Dienstag, November 15, 2022 a las 10:28:11 -0500, Tom Lane escribió:

> Adrian Klaver <adrian.klaver@aklaver.com> writes:
> > On 11/15/22 04:28, Matthias Apitz wrote:
> >> I have below the full ESQL/C log and do not understand, why the
> >> PostgreSQL server is thinking "idle in transaction". For me with the
> >> "COMMIT" on the line below marked with ^^^^^ the transaction was closed.
> 
> > From your log:
> 
> > [6978] [15.11.2022 11:05:50:172]: ECPGtrans on line 1211: action 
> > "commit"; connection "testdb"
> > ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
> > [6978] [15.11.2022 11:05:50:173]: ecpg_execute on line 543: query: 
> > select name from pg_cursors where name = $1 ; with 1 parameter(s) on 
> > connection testdb
> 
> > So that query is being executed after the COMMIT.
> 
> Right.  By default, ecpg would start a new transaction block for that.
> See
> 
> https://www.postgresql.org/docs/current/ecpg-commands.html#ECPG-TRANSACTIONS
> 

Additional question: We're using COMMIT to commit data changes or
deletions into the database. What is the technical impact of such
backends sitting with "idle in transaction" because the application
after doing some work and now waiting for new work, have done before
going to wait such queries for open cursors without any result?

Thanks

    matthias
-- 
Matthias Apitz, ✉ guru@unixarea.de, http://www.unixarea.de/ +49-176-38902045
Public GnuPG key: http://www.unixarea.de/key.pub
May, 9: Спаси́бо освободители! Thank you very much, Russian liberators!

On 11/16/22 12:51 AM, Matthias Apitz wrote:
> El día Dienstag, November 15, 2022 a las 10:28:11 -0500, Tom Lane escribió:
> 
>> Adrian Klaver <adrian.klaver@aklaver.com> writes:
>>> On 11/15/22 04:28, Matthias Apitz wrote:
>>>> I have below the full ESQL/C log and do not understand, why the
>>>> PostgreSQL server is thinking "idle in transaction". For me with the
>>>> "COMMIT" on the line below marked with ^^^^^ the transaction was closed.
>>
>>>  From your log:
>>
>>> [6978] [15.11.2022 11:05:50:172]: ECPGtrans on line 1211: action
>>> "commit"; connection "testdb"
>>> ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
>>> [6978] [15.11.2022 11:05:50:173]: ecpg_execute on line 543: query:
>>> select name from pg_cursors where name = $1 ; with 1 parameter(s) on
>>> connection testdb
>>
>>> So that query is being executed after the COMMIT.
>>
>> Right.  By default, ecpg would start a new transaction block for that.
>> See
>>
>> https://www.postgresql.org/docs/current/ecpg-commands.html#ECPG-TRANSACTIONS
>>
> 
> Thank you. This page makes it clear why the last search started a
> transaction, which at the end is pending due to a missing COMMIT.
> 
> On the other hand, when we would set EXEC SQL SET AUTOCOMMIT TO ON, when does
> the transaction block starts exactly (which could be rolled back), as
> there is no EXEC SQL BEGIN?

I don't use ecpg, but the docs mention:

"The embedded SQL interface also supports autocommit of transactions 
(similar to psql's default behavior)"

In psql:

test_(postgres)(5432)=# select 1/0;
ERROR:  division by zero

test_(postgres)(5432)=# rollback ;
WARNING:  there is no transaction in progress
ROLLBACK

test_(postgres)(5432)=# select 1/1;
  ?column?
----------
         1

versus explicit transaction:

test_(postgres)(5432)=# begin ;
BEGIN

test_(postgres)(5432)=# select 1/0;
ERROR:  division by zero

test_(postgres)(5432)=# select 1/1;
ERROR:  current transaction is aborted, commands ignored until end of 
transaction block

test_(postgres)(5432)=# rollback ;
ROLLBACK

test_(postgres)(5432)=# select 1/1;
  ?column?
----------
         1

> 
> Thanks again
> 
>     matthias
> 


-- 
Adrian Klaver
adrian.klaver@aklaver.com