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?
[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=SunRise DBCALL 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 connection testdb
[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 connection testdb
[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 connection testdb
[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 connection testdb
[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_report WHERE 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 connection testdb
[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, ✉ g...@unixarea.de, http://www.unixarea.de/ +49-176-38902045
Public GnuPG key: http://www.unixarea.de/key.pub
