Lze zjistit příkaz, který způsobil zámek když není posledním příkazem v blokující session?

[Aleš Zelený]

Ahoj,

========================
zkratka -- dotaz je v posledním řádku, zbytek je jen omáčka, co jsem dohledával.
========================

Uzivatele volali ze jim tuhne aplikace a ze nad aplikacni tabulkou nejde ani select count(*), pgadmin zatuhne.

Kdyz jsem se prihlasil, tak zadne blokujici session v DB nebyly, ale to uz taky aplikace byla vypnuta (nastesti to bylo na test prostredi).

Nasel jsem jednu session, ktera byla pres hodinu dobu idle_in_transaction, zkusil z psql describe na tabulku, kde uzivatele hlasili problem a opravdu session ve stavu idle_in_transaction byla tou blokujici (asi nejaky pohrobek v JBoss connection poolu).


Zamky drzene blokujici idle in transaction session:

relname		mode	granted
XXXXX_name_lock		AccessShareLock	t
pg_largeobject		RowExclusiveLock	t
pg_namespace_oid_index		AccessShareLock	t
pg_namespace_nspname_index		AccessShareLock	t
pg_proc_proname_args_nsp_index		AccessShareLock	t
pg_proc_oid_index		AccessShareLock	t
pg_namespace		AccessShareLock	t
pg_proc		AccessShareLock	t
batch_audit_data_idx		AccessShareLock	t
batch_audit_data_pk		AccessShareLock	t
batch_audit_data		AccessShareLock	t
XXXXX_name_lock_pk		AccessShareLock	t
pg_largeobject_loid_pn_index		RowExclusiveLock	t
XXXXX_name_lock		AccessExclusiveLock	t
XXXXX_name_lock		RowExclusiveLock	t

Čekající session (psql describe na tabulku) nezískala AccessShareLock na aplikační tabulku:

pg_constraint_conname_nsp_index		AccessShareLock	t
pg_index_indexrelid_index		AccessShareLock	t
pg_index_indrelid_index		AccessShareLock	t
pg_class_tblspc_relfilenode_index		AccessShareLock	t
pg_class_relname_nsp_index		AccessShareLock	t
pg_class_oid_index		AccessShareLock	t
pg_constraint		AccessShareLock	t
pg_index		AccessShareLock	t
pg_class		AccessShareLock	t
XXXXX_name_lock		AccessShareLock	f
pg_constraint_oid_index		AccessShareLock	t
pg_constraint_contypid_index		AccessShareLock	t
pg_constraint_conrelid_index		AccessShareLock	t

protože ta blokující měla AccessExclusiveLock, to dává smysl.

Poslední SQL pro sesion idle in transaction bylo:

SELECT p.proname,p.oid  FROM pg_catalog.pg_proc p, pg_catalog.pg_namespace n  WHERE p.pronamespace=n.oid AND n.nspname='pg_catalog' AND ( proname = 'lo_open' or proname = 'lo_close' or proname = 'lo_creat' or proname = 'lo_unlink' or proname = 'lo_lseek' or proname = 'lo_lseek64' or proname = 'lo_tell' or proname = 'lo_tell64' or proname = 'loread' or proname = 'lowrite' or proname = 'lo_truncate' or proname = 'lo_truncate64')

V logu byl connect, jeden delší select a jinak nic až čekání psql na describe:

gzip -dc postgresql.log-20170421* | egrep "CEST 55326|CEST 9224"
2017-04-21 12:58:18 CEST 55326 58f9e5c9.d81e 3 xx.xx.xx.xx(62309) xxxdb xxx_app 226336369 46/1118667 [unknown] SELECT:LOG:  duration: 753.354 ms  execute <unnamed>: SELECT id FROM ZZZZ_FFF_Data ORDER BY datum LIMIT $1
2017-04-21 12:58:18 CEST 55326 58f9e5c9.d81e 4 xx.xx.xx.xx(62309) xxxdb xxx_app 226336369 46/1118667 [unknown] SELECT:DETAIL:  parameters: $1 = '500000'
2017-04-21 14:32:15 CEST 9224 58f9fbcf.2408 1  [unknown] [unknown] 0  [unknown] :LOG:  connection received: host=[local]
2017-04-21 14:32:15 CEST 9224 58f9fbcf.2408 2 [local] xxxdb postgres 0 35/241335 [unknown] authentication:LOG:  connection authorized: user=postgres database=xxxdb
2017-04-21 14:32:58 CEST 9224 58f9fbcf.2408 3 [local] xxxdb postgres 0 35/241340 psql SELECT waiting:LOG:  process 9224 still waiting for AccessShareLock on relation 21796305 of database 21795798 after 1000.061 ms
2017-04-21 14:32:58 CEST 9224 58f9fbcf.2408 4 [local] xxxdb postgres 0 35/241340 psql SELECT waiting:DETAIL:  Process holding the lock: 55326. Wait queue: 9224.
2017-04-21 14:32:58 CEST 9224 58f9fbcf.2408 5 [local] xxxdb postgres 0 35/241340 psql SELECT waiting:STATEMENT:  SELECT c2.relname, i.indisprimary, i.indisunique, i.indisclustered, i.indisvalid, pg_catalog.pg_get_indexdef(i.indexrelid, 0, true),
2017-04-21 14:48:33 CEST 55326 58f9e5c9.d81e 5 xx.xx.xx.xx(62309) xxxdb xxx_app 226336369 46/1118667 [unknown] idle in transaction:FATAL:  terminating connection due to administrator command

AccessExclusiveLock vysvětluje, proč nešel select count(), ale překvapilo mne, že i describe chce k tabulce přistoupit a tedy si nevystačí jen s katalogem.

Neuměl jsem odpovědět, kdy zámek vznikl (poslední select či změna stavu vzhledem k poslednímu dotazu nepomohly, začátek transakce zase neříká, že to byl okamžik získání  excl. zámku), ani z jakého statementu, tak se raději ptám, zda není způsob jako to zjistit (logovat všechny dotazy v běžném provozu nechci).

Díky Aleš

[Pavel Stehule]

Dne 27. dubna 2017 21:03 Aleš Zelený <ales....@gmail.com> napsal(a):

Nepřišel tam nějaký DDL příkaz? Zámky se drží do konce transakce - takže pokud někdo v transakci udělal ALTER, DROP nějakého závislého objektu, ... tak session mohla získat a držet EXCLUSIVE zámek.

Co zalogovat  všechny DDL příkazy? Nikoliv tedy všechny.

\dt není jenom čistě katalogová záležitost - občas se zavolá funkce pg_get_xxx - a u nich by mne nepřekvapilo, že by si chtěli minimalní zámek nad dotčený objekt - čistě jako ochranu proti race condition. 

Díky Aleš

--
Tuto zprávu jste obdrželi, protože jste přihlášeni k odběru skupiny „PostgreSQL-cz“ ve Skupinách Google.
Chcete-li zrušit odběr skupiny a přestat dostávat e-maily ze skupiny, zašlete e-mail na adresu postgresql-cz+unsubscribe@googlegroups.com.
Další možnosti najdete na https://groups.google.com/d/optout.

[David Turoň]

Ahoj,

fajn nastroj je pg_view - zobrazuje vice kritickych veci (blokujici transakce, idle in trans., dlouhe dotazy - podobne jako atop/htop), zpetne je to dohledatelne asi pouze pokud jak rika Pavel to byl DDL, a mate zaple logovani log_statement=ddl nebo log_min_duration_statement=0.

https://github.com/zalando/pg_view

David

Dne 27. dubna 2017 21:40 Pavel Stehule <pavel....@gmail.com> napsal(a):

[Aleš Zelený]

Ahoj,

zapomněl jsem napsat, DDL loguji standardně, v logu nic pro dany backend nebylo. Takže možná nějaký lock table ....;

Aleš

Dne čtvrtek 27. dubna 2017 21:41:19 UTC+2 Pavel Stěhule napsal(a):

Díky Aleš

Chcete-li zrušit odběr skupiny a přestat dostávat e-maily ze skupiny, zašlete e-mail na adresu postgresql-c...@googlegroups.com.

[Tomas Vondra]

Ahoj,

On 04/28/2017 08:43 PM, Aleš Zelený wrote:
> Ahoj,
>
> zapomněl jsem napsat, DDL loguji standardně, v logu nic pro dany backend
> nebylo. Takže možná nějaký lock table ....;
>

Možná. Podle dokumentace [1] se AccessExclusive zámky se dějí jenom v
těchto případech (alespoň pokud tam někdo něco nezapomněl přidat)

- DROP TABLE
- TRUNCATE
- REINDEX
- CLUSTER
- VACUUM FULL
- REFRESH MATERIALIZED VIEW
- LOCK TABLE

Takže jedno z toho to musí být. Akorát mne trochu mate že v tom grepu z
logu pro session 55326 nic relevantního není, akorát nějaký select.

[1] https://www.postgresql.org/docs/9.6/static/explicit-locking.html

>
> \dt není jenom čistě katalogová záležitost - občas se zavolá funkce
> pg_get_xxx - a u nich by mne nepřekvapilo, že by si chtěli minimalní
> zámek nad dotčený objekt - čistě jako ochranu proti race condition.
>

Ano, je to kvůli těm pg_get_* funkcím, a berou si AccessShare (nejnižší
možný) zámek přesně z těhle důvodů, aby se jim definice těch objektů
neměnily pod rukama.

T.

[Aleš Zelený]

Ahoj,

díky za náměty a tipy.

Aleš

Dne čtvrtek 27. dubna 2017 21:03:14 UTC+2 Aleš Zelený napsal(a):