Postgres select query with exclusice lock performance issue

Question

Recently while fixing a production bug I used PostgreSQL exclusive lock and learned a lesson the hard way. Just a simple lock drastically impacted the performance of the server and I had to revert the code while leaving the bug again in the system. I was certain that it would impact the performance but had no idea of its severity.

A query exclusive lock on 10000 rows took 70 millis. While the same query without the lock took just 10 millis.

I still need to fix this issue and have no idea of a better mechanism to do so. Is there a way to improve the performance of such queries. Or do I need to look for an alternative solution?

I did find a few articles about the performance impact of locks on queries but nothing really good!

Edit 1:

Maybe it was too quick to come to that conclusion that locks were the problem.

explain (analyze,buffers, timing) select * from job where id in (1642390498,1642392044,1642393079,1642391026,1642393074,1642391037,1642390526,1642390527,1642391544,1642392056,1642392568,1642390520,1642393081,1642391035,1642390468,1642392005,1642392006,1642390470,1642389959,1642390471,1641402865,1642390466,1642390476,1642392525,1642393039,1642389960,1642391511,1642392528,1642393040,1642390993,1642391507,1642393052,1642390492,1642393048,1642390488,1642390491,1642389927,1642390947,1642392483,1642391976,1642390953,1641401243,1642389940,1642391478,1642389943,1642389938,1642393021,1642390971,1642391428,1642390918,1642389888,1642390925,1642392458,1642391440,1642390416,1642390931,1642391443,1642390428,1642391966,1642392472,1642390937,1642392474,1642392475,1642390372,1642391397,1642391392,1642391906,1642392428,1642387311,1642390383,1642391403,1642391924,1642389878,1642392433,1642390385,1642390393,1642390394,1642390860,1642391886,1642387273,1642387274,1642393419,1642392404,1642390878,1642391390,1642393383,1642391330,1642392874,1642391857,1642527493,1642390785,1642390283,1642391318,1642391319,1642390800,1642390290,1642391326,1642392346,1642390811,1642390299,1642392293,1642536677,1642390752,1642391265,1642391276,1642391788,1642391789,1642390253,1642391279,1642392296,1642390763,1642391284,1642391283,1642393331,1642391288,1642392313,1642390265,1642391238,1642393286,1642391239,1642390208,1642391234,1642392268,1642392270,1642391759,1642391240,1642391241,1642391242,1642391243,1642390231,1642390226,1642392796,1642390237,1642391771,1642390235,1642390692,1642390180,1642390688,1642390689,1642391713,1642390177,1642390690,1642393250,1642393260,1642391726,1642392239,1642391208,1642390185,1642392244,1642391221,1642393270,1642392752,1642392753,1642391218,1642392754,1642390194,1642391219,1642391229,1642390712,1642391225,1642392250,1642390715,1642393275,1642390662,1642391175,1642538627,1642392707,1642538624,1642391178,1642391690,1642392715,1642390155,1642390678,1642392209,1642390161,1642393235,1642392220,1642390684,1642390686,1642391654,1642392166,1642392160,1642390632,1642538602,1642390633,1642391158,1642391153,1641402944,1642391676,1642393213,1642391166,1642392696,1642393208,1642393209,1642390650,1642392187,1642391620,1642537031,1642390085,1642390086,1642392640,1642391105,1642390605,1642391113,1642390613,1642390102,1642393175,1642390615,1642391132,1642392670,1642392664,1642392097,1642393121,1642391084,1642390060,1642392621,1642393130,1642390570,1642390068,1642393142,1642393143,1642390064,1642392113,1642392627,1642390579,1642390589,1642392126,1642390079,1642390073,1642393147,1642392583,1642390528,1642391042,1641402931,1642391566,1642387466,1642393099,1641401914,1642387467,1642390037,1642393111,1642387475,1642390559,1642391579) for update;




 LockRows  (cost=0.00..3757.09 rows=1347 width=250) (actual time=0.358..1.554 rows=505 loops=1)
   Buffers: shared hit=3227
   ->  Append  (cost=0.00..3743.62 rows=1347 width=250) (actual time=0.350..1.301 rows=505 loops=1)
         Buffers: shared hit=2717
         ->  Seq Scan on job  (cost=0.00..0.00 rows=1 width=1622) (actual time=0.002..0.002 rows=0 loops=1)
               Filter: (id = ANY ('{1642390498,1642392044,1642393079,1642391026,1642393074,1642391037,1642390526,1642390527,1642391544,1642392056,1642392568,1642390520,1642393081,1642391035,1642390468,1642392005,1642392006,1642390470,1642389959,1642390471,1641402865,1642390466,1642390476,1642392525,1642393039,1642389960,1642391511,1642392528,1642393040,1642390993,1642391507,1642393052,1642390492,1642393048,1642390488,1642390491,1642389927,1642390947,1642392483,1642391976,1642390953,1641401243,1642389940,1642391478,1642389943,1642389938,1642393021,1642390971,1642391428,1642390918,1642389888,1642390925,1642392458,1642391440,1642390416,1642390931,1642391443,1642390428,1642391966,1642392472,1642390937,1642392474,1642392475,1642390372,1642391397,1642391392,1642391906,1642392428,1642387311,1642390383,1642391403,1642391924,1642389878,1642392433,1642390385,1642390393,1642390394,1642390860,1642391886,1642387273,1642387274,1642393419,1642392404,1642390878,1642391390,1642393383,1642391330,1642392874,1642391857,1642527493,1642390785,1642390283,1642391318,1642391319,1642390800,1642390290,1642391326,1642392346,1642390811,1642390299,1642392293,1642536677,1642390752,1642391265,1642391276,1642391788,1642391789,1642390253,1642391279,1642392296,1642390763,1642391284,1642391283,1642393331,1642391288,1642392313,1642390265,1642391238,1642393286,1642391239,1642390208,1642391234,1642392268,1642392270,1642391759,1642391240,1642391241,1642391242,1642391243,1642390231,1642390226,1642392796,1642390237,1642391771,1642390235,1642390692,1642390180,1642390688,1642390689,1642391713,1642390177,1642390690,1642393250,1642393260,1642391726,1642392239,1642391208,1642390185,1642392244,1642391221,1642393270,1642392752,1642392753,1642391218,1642392754,1642390194,1642391219,1642391229,1642390712,1642391225,1642392250,1642390715,1642393275,1642390662,1642391175,1642538627,1642392707,1642538624,1642391178,1642391690,1642392715,1642390155,1642390678,1642392209,1642390161,1642393235,1642392220,1642390684,1642390686,1642391654,1642392166,1642392160,1642390632,1642538602,1642390633,1642391158,1642391153,1641402944,1642391676,1642393213,1642391166,1642392696,1642393208,1642393209,1642390650,1642392187,1642391620,1642537031,1642390085,1642390086,1642392640,1642391105,1642390605,1642391113,1642390613,1642390102,1642393175,1642390615,1642391132,1642392670,1642392664,1642392097,1642393121,1642391084,1642390060,1642392621,1642393130,1642390570,1642390068,1642393142,1642393143,1642390064,1642392113,1642392627,1642390579,1642390589,1642392126,1642390079,1642390073,1642393147,1642392583,1642390528,1642391042,1641402931,1642391566,1642387466,1642393099,1641401914,1642387467,1642390037,1642393111,1642387475,1642390559,1642391579}'::bigint[]))
               ...
               ...
               ...
               ...
              Index Cond: (id = ANY ('{1642390498,1642392044,1642393079,1642391026,1642393074,1642391037,1642390526,1642390527,1642391544,1642392056,1642392568,1642390520,1642393081,1642391035,1642390468,1642392005,1642392006,1642390470,1642389959,1642390471,1641402865,1642390466,1642390476,1642392525,1642393039,1642389960,1642391511,1642392528,1642393040,1642390993,1642391507,1642393052,1642390492,1642393048,1642390488,1642390491,1642389927,1642390947,1642392483,1642391976,1642390953,1641401243,1642389940,1642391478,1642389943,1642389938,1642393021,1642390971,1642391428,1642390918,1642389888,1642390925,1642392458,1642391440,1642390416,1642390931,1642391443,1642390428,1642391966,1642392472,1642390937,1642392474,1642392475,1642390372,1642391397,1642391392,1642391906,1642392428,1642387311,1642390383,1642391403,1642391924,1642389878,1642392433,1642390385,1642390393,1642390394,1642390860,1642391886,1642387273,1642387274,1642393419,1642392404,1642390878,1642391390,1642393383,1642391330,1642392874,1642391857,1642527493,1642390785,1642390283,1642391318,1642391319,1642390800,1642390290,1642391326,1642392346,1642390811,1642390299,1642392293,1642536677,1642390752,1642391265,1642391276,1642391788,1642391789,1642390253,1642391279,1642392296,1642390763,1642391284,1642391283,1642393331,1642391288,1642392313,1642390265,1642391238,1642393286,1642391239,1642390208,1642391234,1642392268,1642392270,1642391759,1642391240,1642391241,1642391242,1642391243,1642390231,1642390226,1642392796,1642390237,1642391771,1642390235,1642390692,1642390180,1642390688,1642390689,1642391713,1642390177,1642390690,1642393250,1642393260,1642391726,1642392239,1642391208,1642390185,1642392244,1642391221,1642393270,1642392752,1642392753,1642391218,1642392754,1642390194,1642391219,1642391229,1642390712,1642391225,1642392250,1642390715,1642393275,1642390662,1642391175,1642538627,1642392707,1642538624,1642391178,1642391690,1642392715,1642390155,1642390678,1642392209,1642390161,1642393235,1642392220,1642390684,1642390686,1642391654,1642392166,1642392160,1642390632,1642538602,1642390633,1642391158,1642391153,1641402944,1642391676,1642393213,1642391166,1642392696,1642393208,1642393209,1642390650,1642392187,1642391620,1642537031,1642390085,1642390086,1642392640,1642391105,1642390605,1642391113,1642390613,1642390102,1642393175,1642390615,1642391132,1642392670,1642392664,1642392097,1642393121,1642391084,1642390060,1642392621,1642393130,1642390570,1642390068,1642393142,1642393143,1642390064,1642392113,1642392627,1642390579,1642390589,1642392126,1642390079,1642390073,1642393147,1642392583,1642390528,1642391042,1641402931,1642391566,1642387466,1642393099,1641401914,1642387467,1642390037,1642393111,1642387475,1642390559,1642391579}'::bigint[]))

               Buffers: shared hit=1253

 Planning time: 2.177 ms

 Execution time: 1.778 ms

After analyzing the RDS logs, it seems that the actual problem is queries waiting too long to acquire the lock.

Another type of queries logged in error logs was:

FAREYE@TRIP_SERVICE_PROD:
[8983]:LOG:
DURATION:
990.926 MS  EXECUTE
S_38:
UPDATE
    JOB_5_2020
SET
    ID                      =   $1
,   LATITUDE                =   $2
,   LONGITUDE               =   $3
WHERE
    UNIQUE_ID   =   $32

Now that I think about it, the 990 ms is mostly waiting for the lock rather than actually executing the query. How do I identify if it was waiting for the lock-in RDS Error logs? can I activate such logging in any way?

Answer 1

PostgreSQL implements row locking by writing some information into the row headers so this takes time. Doc says:

PostgreSQL doesn't remember any information about modified rows in memory, so there is no limit on the number of rows locked at one time. However, locking a row might cause a disk write, e.g., SELECT FOR UPDATE modifies selected rows to mark them locked, and so will result in disk writes.

On a simple table with 10000 rows I have without for UPDATE clause:

postgres=# explain (analyze,buffers, timing) select * from t ;
                                             QUERY PLAN                                              
-----------------------------------------------------------------------------------------------------
 Seq Scan on t  (cost=0.00..198.00 rows=10000 width=8) (actual time=0.060..1.207 rows=10000 loops=1)
   Buffers: shared hit=98
 Planning Time: 0.046 ms
 Execution Time: 1.860 ms
(4 rows)

with FOR UPDATE clause:

postgres=# explain (analyze,buffers, timing) select * from t  for update;
                                                 QUERY PLAN                                                 
------------------------------------------------------------------------------------------------------------
 LockRows  (cost=0.00..298.00 rows=10000 width=14) (actual time=0.066..9.158 rows=10000 loops=1)
   Buffers: shared hit=20098
   ->  Seq Scan on t  (cost=0.00..198.00 rows=10000 width=14) (actual time=0.045..1.474 rows=10000 loops=1)
         Buffers: shared hit=98
 Planning Time: 0.039 ms
 Execution Time: 9.807 ms
(6 rows)

In my case it's about 5 times slower with FOR UPDATE clause.

Maybe it takes more time because it seems you have partitions: maybe you have more data to read.

Did you run VACUUM or ANALYZE recently on these tables ?

Try to give code output as text instead of images: it is easier to read text than images.

Please post output of EXPLAIN(ANALYZE,BUFFERS,TIMING) for your queries with track_io_timing=on in your session.