client waits for end of update operation and server proc is idle - Mailing list pgsql-general

Hello,

We face (somehow reproducible) the following situation with a 13.1
server and a client written in ESQL/C:

# ps ax | grep post
...
27106 ?        Ss     0:00 postgres: sisis sisis ::1(49518) idle in transaction

# lsof | grep 49518
INDEX     27074                      sisis    2u     IPv6           26465150       0t0        TCP
localhost:49518->localhost:postgresql(ESTABLISHED)
 
postmaste 27106                   postgres    9u     IPv6           26464149       0t0        TCP
localhost:postgresql->localhost:49518(ESTABLISHED)
 


# psql -Usisis -dsisis
psql (11.4, server 13.1)
WARNING: psql major version 11, server major version 13.
         Some psql features might not work.
Type "help" for help.

sisis=# select * from pg_stat_activity where client_port = 49518;

 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        |  backend_type
 

--------+---------+-------+------------+----------+---------+---------------------------------+-------------+-----------------+-------------+---------------------------------+---------------------------------+---------------------------------+---------------------------------+-----------------+------------+---------------------+-------------+--------------+---------------------+----------------
 951941 | sisis   | 27106 |            |    16384 | sisis   | SunRise DBCALL V7.2 (pid=27074) | ::1         |
     |       49518 | 23.04.2021 05:57:19.536206 CEST | 23.04.2021 05:57:19.562102 CEST | 23.04.2021 05:57:19.664471
CEST| 23.04.2021 05:57:19.664495 CEST | Client          | ClientRead | idle in transaction |    18228156 |     18228156
|fetch per_kette_seq | client backend
 
(1 row)


i.e. the server is in 'ClientRead | idle in transaction';


The ESQL/C code the client is executing at this moment is:

  /*
   * update the actual row
   */
  posDebug(POSDEBUG_FLOW, "ES UPDATE per_kette set .. WHERE CURRENT OF hc_per_kette");
  EXEC SQL UPDATE per_kette
      SET  desknr =:hrec_per_kette.desknr,
      frei =:hrec_per_kette.frei,
      modif =:hrec_per_kette.modif,
      anz =:hrec_per_kette.anz,
      katlist =:hrec_per_kette.katlist
  WHERE CURRENT OF hc_per_kette;

An attached GDB shows:

# gdb /opt/lib/sisis/catserver/bin/INDEX 27074

#0  0x00007f1e65c1b5c4 in poll () from /lib64/libc.so.6
#1  0x00007f1e648ac22f in pqSocketPoll () from /usr/local/sisis-pap/pgsql/lib/libpq.so.5
#2  0x00007f1e648ac0ff in pqSocketCheck () from /usr/local/sisis-pap/pgsql/lib/libpq.so.5
#3  0x00007f1e648abf83 in pqWaitTimed () from /usr/local/sisis-pap/pgsql/lib/libpq.so.5
#4  0x00007f1e648abf55 in pqWait () from /usr/local/sisis-pap/pgsql/lib/libpq.so.5
#5  0x00007f1e648a7d3a in PQgetResult () from /usr/local/sisis-pap/pgsql/lib/libpq.so.5
#6  0x00007f1e648a8478 in PQexecFinish () from /usr/local/sisis-pap/pgsql/lib/libpq.so.5
#7  0x00007f1e648a812e in PQexecParams () from /usr/local/sisis-pap/pgsql/lib/libpq.so.5
#8  0x00007f1e65818216 in ecpg_execute ()
   from /usr/local/sisis-pap/pgsql/lib/libecpg.so.6
#9  0x00007f1e658195de in ecpg_do () from /usr/local/sisis-pap/pgsql/lib/libecpg.so.6
#10 0x00007f1e658196ef in ECPGdo () from /usr/local/sisis-pap/pgsql/lib/libecpg.so.6
#11 0x00007f1e67e091c6 in update_record () at per_kette.pgc:1968
#12 0x00007f1e67e04d16 in per_kette (zugriff=10, scroll=-20000, lock=-20000, key=-20000,
    sto=-20000, p_daten=0x7fff4e6db9b0, sel_anw=0x0, where_anw=0x0, p_btw_daten=0x0,
    order_by=0x0, auf_ab=0x0, group_by=0x0, having=0x0, into_temp=0x0,
    count=0x7fff4e6da6d0) at per_kette.pgc:497
#13 0x00007f1e67d7d70f in DB_rewr (tabmodul=0x7f1e67e047ca <per_kette>,
    p_daten=0x7fff4e6db9b0) at dbcall.pgc:3274
#14 0x00007f1e68ade821 in BKDeskInsert (setid=FSTAB_Personen, kette=...,
    katkey=168952979) at ./BKDesk.c:1447
#15 0x00007f1e68ae79c1 in InvAufnehmen (setid=FSTAB_Personen, katkey=168952979)
#16 0x00007f1e68ae6e17 in BKBearbeiteIndexAuftrag (setid=FSTAB_Personen, auftrag=...)
    at ./BKInvert.c:109
#17 0x0000000000405384 in main (argc=3, argv=0x7fff4e6ec1d8) at ./INDEX.c:525

i.e. our client issued ECPGdo() and now waits on finish; the provided
data looks fine:

(gdb) p hrec_per_kette.desknr
$2 = 1384118
(gdb) p hrec_per_kette.katlist
value requires 130000 bytes, which is more than max-value-size

(gdb) x/1s hrec_per_kette.katlist
0x7f1e6864af6e <hrec_per_kette+14>:
"\\xee9e01001eaf010057af010005ce010082d20100d4f801008e0a0200af340200253a0200a58e0200ae8e020044a602003ea7020020f1030024f1030054170400a04304003f670400ba8904003bed000005490100925201007454010083600100828301"...

the server pocess is in epoll_pwait():

# gdb /usr/local/sisis-pap/pgsql-13.0/bin/postmaster 27106
...
(gdb) bt
#0  0x00007fe7ee953fe0 in epoll_pwait () from /lib64/libc.so.6
#1  0x00000000008acf10 in WaitEventSetWaitBlock ()
#2  0x00000000008acde9 in WaitEventSetWaitBlock ()
#3  0x000000000073c5a5 in check_ssl_key_file_permissions ()
#4  0x000000000074636e in RemoveSocketFiles ()
#5  0x000000000074662b in pq_getbyte_if_available ()
#6  0x000000000074697b in pq_getmessage ()
#7  0x00000000008d543b in pg_analyze_and_rewrite_params ()
#8  0x00007f54fec14780 in ?? ()
#9  0x00007ffffec148a0 in ?? ()
#10 0x00007ffffec14780 in ?? ()
#11 0x00000053008d3b1b in ?? ()
#12 0x00007ffffec14780 in ?? ()
#13 0x00000000008d5482 in pg_analyze_and_rewrite_params ()

The client has a log file for this update which shows the actual time of
this operation:

# ls -l --full-time /var/spool/sisis/catserver/tmp/.lock_index-A.sisis.2
-rw-rw---- 1 sisis sisis 6 2021-04-23 05:57:19.529476471 +0200 /var/spool/sisis/catserver/tmp/.lock_index-A.sisis.2


The serverlog has around this time (sorry for German):

2021-04-23 05:55:23.591 CEST [2317] LOG:  unvollständige Message vom Client
2021-04-23 05:55:23.593 CEST [2317] FEHLER:  Speicher aufgebraucht
2021-04-23 05:55:23.593 CEST [2317] DETAIL:  Kann Zeichenkettenpuffer mit 0 Bytes nicht um 1380986158 Bytes
vergrößern.
2021-04-23 05:55:23.593 CEST [2317] LOG:  konnte Daten nicht an den Client senden: Datenübergabe unterbrochen (broken
pipe)
2021-04-23 05:55:23.593 CEST [2317] FATAL:  Verbindung zum Client wurde verloren
2021-04-23 05:57:20.339 CEST [27190] LOG:  unerwartetes EOF auf Client-Verbindung mit einer offenen Transaktion
2021-04-23 05:59:17.419 CEST [26827] LOG:  unerwartetes EOF auf Client-Verbindung mit einer offenen Transaktion

What else could be checked for this? Any hints about this issue?

Thanks

    matthias
-- 
Matthias Apitz, ✉ guru@unixarea.de, http://www.unixarea.de/ +49-176-38902045
Public GnuPG key: http://www.unixarea.de/key.pub