Thread: Locks analysis after-the-fact
Hello all, PostgreSQL version 9.4.17 We have a number of queries running on the same DB from many systems. Among other things, we need to INSERT / UPDATE on atable based on external events - this is done via a pool of 5 SQL connections which process an average of 500 events / second.The table is used by other systems as well... We have more and more locks on this table, which prevents it to be updated as it should - and I'm trying to see how to improvethings without setting up an external queue system just to manage those events. I've enabled "log_lock_waits = on" in the configuration, which generates the following kind of log entries: 2018-04-27 07:48:07 CEST [1419.269] "[unknown]" xx@yy LOG: process 1419 still waiting for ExclusiveLock on advisory lock[16417,1653339453,2672182422,2] after 1000.166 ms 2018-04-27 07:48:07 CEST [1419.270] "[unknown]" xx@yy DETAIL: Process holding the lock: 16418. Wait queue: 1419. 2018-04-27 07:48:07 CEST [1419.271] "[unknown]" xx@yy STATEMENT: SELECT pg_advisory_xact_lock(1653339453, -1622784874); 2018-04-27 07:48:07 CEST [1419.272] "[unknown]" xx@yy LOG: process 1419 acquired ExclusiveLock on advisory lock [16417,1653339453,2672182422,2]after 1318.721 ms 2018-04-27 07:48:07 CEST [1419.273] "[unknown]" xx@yy STATEMENT: SELECT pg_advisory_xact_lock(1653339453, -1622784874); I can easily identify the session owner of the different processes, but the process holding the lock belong to an ERP whichgenerates a lot of different kind of queries - I'd like to identify precisely which one is causing this long-lastinglock. It doesn't look like this is possible via the PostgreSQL logging features, and doing the usual lock troubleshooting "on thespot" using pg_locks is not practical due to the short duration and odd timing of those locks. Does anyone have an idea on how to process in such a case? Thank you, Olivier
Attachment
On 2018-04-27 10:55, Olivier Macchioni wrote: > Does anyone have an idea on how to process in such a case? > Log statments too. :)
> On 27 Apr 2018, at 11:58, Olleg Samoylov <splarv@ya.ru> wrote: > > On 2018-04-27 10:55, Olivier Macchioni wrote: >> Does anyone have an idea on how to process in such a case? >> > Log statments too. :) > Thank you - I was afraid of such an answer and on the load it may generate... I'll give it a try during a quiet hour of the day Olivier
Attachment
Olleg Samoylov <splarv@ya.ru> writes:
> On 2018-04-27 10:55, Olivier Macchioni wrote:
>> Does anyone have an idea on how to process in such a case?
> Log statments too. :)
Another idea is to get the app to set application_name differently for
each session (and be sure to include %a in log_line_prefix). It might
not be practical in this particular case, but it's a good tool to keep
in mind.
regards, tom lane
On Fri, Apr 27, 2018 at 2:55 AM, Olivier Macchioni <olivier.macchioni@wingo.ch> wrote: > Hello all, > > PostgreSQL version 9.4.17 > > We have a number of queries running on the same DB from many systems. Among other things, we need to INSERT / UPDATE ona table based on external events - this is done via a pool of 5 SQL connections which process an average of 500 events/ second. The table is used by other systems as well... > > We have more and more locks on this table, which prevents it to be updated as it should - and I'm trying to see how toimprove things without setting up an external queue system just to manage those events. > > I've enabled "log_lock_waits = on" in the configuration, which generates the following kind of log entries: > > 2018-04-27 07:48:07 CEST [1419.269] "[unknown]" xx@yy LOG: process 1419 still waiting for ExclusiveLock on advisory lock[16417,1653339453,2672182422,2] after 1000.166 ms > 2018-04-27 07:48:07 CEST [1419.270] "[unknown]" xx@yy DETAIL: Process holding the lock: 16418. Wait queue: 1419. > 2018-04-27 07:48:07 CEST [1419.271] "[unknown]" xx@yy STATEMENT: SELECT pg_advisory_xact_lock(1653339453, -1622784874); > 2018-04-27 07:48:07 CEST [1419.272] "[unknown]" xx@yy LOG: process 1419 acquired ExclusiveLock on advisory lock [16417,1653339453,2672182422,2]after 1318.721 ms > 2018-04-27 07:48:07 CEST [1419.273] "[unknown]" xx@yy STATEMENT: SELECT pg_advisory_xact_lock(1653339453, -1622784874); > > I can easily identify the session owner of the different processes, but the process holding the lock belong to an ERP whichgenerates a lot of different kind of queries - I'd like to identify precisely which one is causing this long-lastinglock. > > It doesn't look like this is possible via the PostgreSQL logging features, and doing the usual lock troubleshooting "onthe spot" using pg_locks is not practical due to the short duration and odd timing of those locks. > > Does anyone have an idea on how to process in such a case? Here, the locking query is obvious: "SELECT pg_advisory_xact_lock". If this is an ERP application I bet advisory locks are being used to simulate pessimistic locking in some way. Unfortunately this is no help as the real operation is elsewhere in this transaction. Echoing the advice above you need to enable full statement logging and make sure your log_line_prefix contains pid in some easily searched for way such as [%p]. Once you have that, you can trace back in the file based on the locking pid and get to the bottom of the situation pretty easily. Be mindful statement logging, it can consume disk space really quickly and add a lot of overhead to the database. merlin