Help understanding server-side logging (and more...)

From: Dominique Devienne <ddevienne(at)gmail(dot)com>
To: pgsql-general(at)lists(dot)postgresql(dot)org
Subject: Help understanding server-side logging (and more...)
Date: 2023-12-21 11:05:41
Message-ID: CAFCRh-_72x=8S1T5YXgJFmz8j6WKYViORqF-ndbFBesf4kAjNQ@mail.gmail.com
Views: Raw Message | Whole Thread | Download mbox | Resend email
Thread:
Lists: pgsql-general

Hi. Another team (than mine) has been trying to troubleshoot hang issues in
their Node/JS/TS-based mid-tier services,
after a switch from MySQL to PostgreSQL. They run PostgreSQL in a Linux
container (see PID [1] below), unlike us.
They started looking at the PostgreSQL server-side logs, but with little to
no experience reading them, we'd like to
confirm the extract below looks normal, notably whether the various
exit-related messages are OK or not.

I'm guessing it's fine/normal, especially since they use a Node PostgreSQL
module with Pooling (10 connections max by default)
that disconnects idle connections after 10s, which matches what the log
shows. Can anyone please confirm?

FWIW, the symptoms they are experiencing is that initially all queries are
fast, then they start to get longer and longer,
to the point all services accessing PostgreSQL grind to a halt and
basically hang. While that happens, one can connect
to the DB from a shell (that cluster has a single DB) w/o issues, and run
queries just fine (they have little data,
in the few dozens MBs spread in 2 schemas and probably 2 or 3 dozen tables
max), thus I personally think the problem
is more on the client Node.JS side, but given that the same code worked
fine with MySQL, maybe I'm wrong.

Their services are concurrent and accessed by maybe 50-100 users tops, with
queries coming in all the time.

If by any chance, anyone has seen this kind of behavior before, in a
similar context or not, and has suggestions
on how we could further troubleshoot this (on the PostgreSQL server-side,
but also the Node.JS client-side, why not),
that would be greatly appreciated.

Thanks, --DD

2023-12-20 00:00:16.185 UTC [3605] DEBUG: InitPostgres
2023-12-20 00:00:16.185 UTC [3605] DEBUG: my backend ID is 4
2023-12-20 00:00:16.186 UTC [1] DEBUG: forked new backend, pid=3606
socket=10
2023-12-20 00:00:16.187 UTC [3606] DEBUG: InitPostgres
2023-12-20 00:00:16.187 UTC [3606] DEBUG: my backend ID is 6
2023-12-20 00:00:16.188 UTC [3605] DEBUG: StartTransaction(1) name:
unnamed; blockState: DEFAULT; state: INPROGRESS, xid/subid/cid: 0/1/0
2023-12-20 00:00:16.189 UTC [3605] DEBUG: processing received SASL
response of length 51
2023-12-20 00:00:16.189 UTC [3605] DEBUG: sending SASL challenge of length
84
2023-12-20 00:00:16.190 UTC [3606] DEBUG: StartTransaction(1) name:
unnamed; blockState: DEFAULT; state: INPROGRESS, xid/subid/cid: 0/1/0
2023-12-20 00:00:16.191 UTC [3606] DEBUG: processing received SASL
response of length 51
2023-12-20 00:00:16.191 UTC [3606] DEBUG: sending SASL challenge of length
84
2023-12-20 00:00:16.193 UTC [3605] DEBUG: processing received SASL
response of length 104
2023-12-20 00:00:16.193 UTC [3605] DEBUG: sending SASL challenge of length
46
2023-12-20 00:00:16.195 UTC [3606] DEBUG: processing received SASL
response of length 104
2023-12-20 00:00:16.195 UTC [3606] DEBUG: sending SASL challenge of length
46
2023-12-20 00:00:16.200 UTC [3605] DEBUG: CommitTransaction(1) name:
unnamed; blockState: STARTED; state: INPROGRESS, xid/subid/cid: 0/1/0
2023-12-20 00:00:16.201 UTC [3605] DEBUG: StartTransaction(1) name:
unnamed; blockState: DEFAULT; state: INPROGRESS, xid/subid/cid: 0/1/0
2023-12-20 00:00:16.201 UTC [3605] STATEMENT: SELECT * FROM "NSP"."T1"
2023-12-20 00:00:16.202 UTC [3606] DEBUG: CommitTransaction(1) name:
unnamed; blockState: STARTED; state: INPROGRESS, xid/subid/cid: 0/1/0
2023-12-20 00:00:16.203 UTC [3606] DEBUG: StartTransaction(1) name:
unnamed; blockState: DEFAULT; state: INPROGRESS, xid/subid/cid: 0/1/0
2023-12-20 00:00:16.203 UTC [3606] STATEMENT: SELECT * FROM "NSP"."T2"
2023-12-20 00:00:16.205 UTC [3605] DEBUG: CommitTransaction(1) name:
unnamed; blockState: STARTED; state: INPROGRESS, xid/subid/cid: 0/1/0
2023-12-20 00:00:16.205 UTC [3605] STATEMENT: SELECT * FROM "NSP"."T1"
2023-12-20 00:00:16.207 UTC [3606] DEBUG: CommitTransaction(1) name:
unnamed; blockState: STARTED; state: INPROGRESS, xid/subid/cid: 0/1/0
2023-12-20 00:00:16.207 UTC [3606] STATEMENT: SELECT * FROM "NSP"."T2"
2023-12-20 00:00:26.209 UTC [3605] DEBUG: shmem_exit(0): 4
before_shmem_exit callbacks to make
2023-12-20 00:00:26.209 UTC [3605] DEBUG: shmem_exit(0): 6 on_shmem_exit
callbacks to make
2023-12-20 00:00:26.209 UTC [3606] DEBUG: shmem_exit(0): 4
before_shmem_exit callbacks to make
2023-12-20 00:00:26.209 UTC [3605] DEBUG: proc_exit(0): 2 callbacks to make
2023-12-20 00:00:26.209 UTC [3605] DEBUG: exit(0)
2023-12-20 00:00:26.209 UTC [3605] DEBUG: shmem_exit(-1): 0
before_shmem_exit callbacks to make
2023-12-20 00:00:26.209 UTC [3605] DEBUG: shmem_exit(-1): 0 on_shmem_exit
callbacks to make
2023-12-20 00:00:26.209 UTC [3605] DEBUG: proc_exit(-1): 0 callbacks to
make
2023-12-20 00:00:26.209 UTC [3606] DEBUG: shmem_exit(0): 6 on_shmem_exit
callbacks to make
2023-12-20 00:00:26.209 UTC [3606] DEBUG: proc_exit(0): 2 callbacks to make
2023-12-20 00:00:26.209 UTC [3606] DEBUG: exit(0)
2023-12-20 00:00:26.209 UTC [3606] DEBUG: shmem_exit(-1): 0
before_shmem_exit callbacks to make
2023-12-20 00:00:26.209 UTC [3606] DEBUG: shmem_exit(-1): 0 on_shmem_exit
callbacks to make
2023-12-20 00:00:26.209 UTC [3606] DEBUG: proc_exit(-1): 0 callbacks to
make
2023-12-20 00:00:26.211 UTC [1] DEBUG: reaping dead processes
2023-12-20 00:00:26.211 UTC [1] DEBUG: server process (PID 3605) exited
with exit code 0
2023-12-20 00:00:26.211 UTC [1] DEBUG: server process (PID 3606) exited
with exit code 0
2023-12-20 00:00:31.377 UTC [1] DEBUG: forked new backend, pid=3607
socket=10

Responses

Browse pgsql-general by date

  From Date Subject
Next Message Julien Rouhaud 2023-12-21 11:55:55 Re: Help understanding server-side logging (and more...)
Previous Message Adrien Nayrat 2023-12-21 10:36:38 Re: "invalid contrecord" error on replica