Received: from malur.postgresql.org ([217.196.149.56]) by arkaria.postgresql.org with esmtps (TLS1.3:ECDHE_RSA_AES_256_GCM_SHA384:256) (Exim 4.92) (envelope-from ) id 1k8tFB-0000IG-0s for pgsql-performance@arkaria.postgresql.org; Thu, 20 Aug 2020 22:41:13 +0000 Received: from localhost ([127.0.0.1] helo=malur.postgresql.org) by malur.postgresql.org with esmtp (Exim 4.92) (envelope-from ) id 1k8tEc-0006DD-Dj for pgsql-performance@arkaria.postgresql.org; Thu, 20 Aug 2020 22:40:38 +0000 Received: from makus.postgresql.org ([2001:4800:3e1:1::229]) by malur.postgresql.org with esmtps (TLS1.3:ECDHE_RSA_AES_256_GCM_SHA384:256) (Exim 4.92) (envelope-from ) id 1k8tEc-0006D6-1s for pgsql-performance@lists.postgresql.org; Thu, 20 Aug 2020 22:40:38 +0000 Received: from mail4.network-systems-solutions.net ([162.222.184.250]) by makus.postgresql.org with esmtps (TLS1.2:ECDHE_RSA_AES_256_GCM_SHA384:256) (Exim 4.92) (envelope-from ) id 1k8tEW-0005yp-I9 for pgsql-performance@lists.postgresql.org; Thu, 20 Aug 2020 22:40:34 +0000 Received: from messaging.network-systems-solutions.net (unknown [192.168.242.37]) by mail4.network-systems-solutions.net (Postfix) with ESMTP id C3878120050; Thu, 20 Aug 2020 23:40:25 +0100 (BST) Received: from aox (localhost [127.0.0.1]) by messaging.network-systems-solutions.net (Postfix) with ESMTP id 4838A8E0596; Thu, 20 Aug 2020 18:40:26 -0400 (EDT) Received: from jim@talentstack.to by aox (Archiveopteryx 3.2.0) with esmtpsa id 1597963225-23382-23378/6/90; Thu, 20 Aug 2020 22:40:25 +0000 Subject: Re: CPU hogged by concurrent SELECT..FOR UPDATE SKIP LOCKED To: Michael Lewis Cc: Pgsql Performance References: <5e5ba420-9365-265d-c62a-4586cfb7c418@talentstack.to> From: Jim Jarvie Message-Id: <0e537a50-a43f-3404-27ed-3de9c3f7c281@talentstack.to> Date: Thu, 20 Aug 2020 18:39:59 -0400 User-Agent: Mozilla/5.0 (Windows NT 6.1; rv:68.0) Gecko/20100101 Thunderbird/68.11.0 Mime-Version: 1.0 In-Reply-To: Content-Type: multipart/alternative; boundary=------------929D6E83CE69D9A3A154DC5F Content-Language: en-CA X-NSSLTD-SpamTemp: 1256247 X-Spam-Score: -1.105 () BAYES_00,HTML_MESSAGE,RDNS_NONE,SPF_FAIL X-NSSLTD-Archiving: Added to store 1 as 84400 X-Scanned-By: MIMEDefang 2.71 on 192.168.241.40 List-Id: List-Help: List-Subscribe: List-Post: List-Owner: List-Archive: Precedence: bulk --------------929D6E83CE69D9A3A154DC5F Content-Type: text/plain; charset=utf-8; format=flowed Content-Transfer-Encoding: quoted-printable On 20-Aug.-2020 17:42, Michael Lewis wrote: > Can you share an explain analyze for the query that does the select for > update? I wouldn't assume that partition pruning is possible at all = with > hash, and it would be interesting to see how it is finding those rows. Well this got interesting=C2=A0 - the already moved error showed up: = Note,=20 the actual process partitions are regular table partitions, these are=20 not hashed.=C2=A0 Only the incoming and completed are hashed due to row=20 counts at either end of the processing; in flight (where the issue shows=20 up) is quite small: [queuedb] # explain analyze select queueid,txobject,objectid,state from=20 mq.queue where (state =3D 'tx_active' or state=3D'tx_fail_retryable') = and=20 txobject =3D 'ticket' limit 250 for update skip locked; ERROR: =C2=A040001: tuple to be locked was already moved to another = partition=20 due to concurrent update LOCATION: =C2=A0heapam_tuple_lock, heapam_handler.c:405 Time: 579.131 ms [queuedb] # explain analyze select queueid,txobject,objectid,state from=20 mq.queue where (state =3D 'tx_active' or state=3D'tx_fail_retryable') = and=20 txobject =3D 'ticket' limit 250 for update skip locked; ERROR: =C2=A040001: tuple to be locked was already moved to another = partition=20 due to concurrent update LOCATION: =C2=A0heapam_tuple_lock, heapam_handler.c:405 Time: 568.008 ms [queuedb] # explain analyze select queueid,txobject,objectid,state from=20 mq.queue where (state =3D 'tx_active' or state=3D'tx_fail_retryable') = and=20 txobject =3D 'ticket' limit 250 for update skip locked; =C2=A0 =C2=A0 =C2=A0 QUERY PLAN =2D----------------------------------------------------------------------= =2D----------------------------------------------------------------------= =2D----------- =C2=A0Limit =C2=A0(cost=3D0.00..25.71 rows=3D250 width=3D34) (actual=20 time=3D1306.041..1306.338 rows=3D250 loops=3D1) =C2=A0 =C2=A0-> =C2=A0LockRows =C2=A0(cost=3D0.00..7934.38 rows=3D77150 = width=3D34) (actual=20 time=3D1306.040..1306.315 rows=3D250 loops=3D1) =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0-> =C2=A0Append =C2=A0(cost=3D0.00..71= 62.88 rows=3D77150 width=3D34) (actual=20 time=3D520.685..1148.347 rows=3D31500 loops=3D1) =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0-> =C2=A0Seq = Scan on queue_tx_active =C2=A0(cost=3D0.00..6764.50=20 rows=3D77000 width=3D34) (actual time=3D520.683..1145.258 rows=3D31500 = loops=3D1) =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 = =C2=A0Filter: ((txobject =3D 'ticket'::mq.queue_object)=20 AND ((state =3D 'tx_active'::mq.tx_state) OR (state =3D=20 'tx_fail_retryable'::mq.tx_state))) =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0-> =C2=A0Seq = Scan on queue_tx_fail_retryable=20 =C2=A0(cost=3D0.00..12.62 rows=3D150 width=3D34) (never executed) =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 = =C2=A0Filter: ((txobject =3D 'ticket'::mq.queue_object)=20 AND ((state =3D 'tx_active'::mq.tx_state) OR (state =3D=20 'tx_fail_retryable'::mq.tx_state))) =C2=A0Planning Time: 0.274 ms =C2=A0Execution Time: 1306.380 ms (9 rows) Time: 1317.150 ms (00:01.317) [queuedb] # --------------929D6E83CE69D9A3A154DC5F Content-Type: text/html; charset=utf-8 Content-Transfer-Encoding: quoted-printable


On 20-Aug.-2020 17:42, Michael Lewis wrote:
Can you share an explain =
analyze for the query that does the select for
update? I wouldn't assume that partition pruning is possible at all with
hash, and it would be interesting to see how it is finding those rows.

Well this got interesting=C2=A0 - the already moved error showed = up:=C2=A0 Note, the actual process partitions are regular table partitions, these are not hashed.=C2=A0 Only the incoming and completed are = hashed due to row counts at either end of the processing; in flight (where the issue shows up) is quite small:

[queuedb] # explain analyze select queueid,txobject,objectid,state from mq.queue where (state =3D 'tx_active' or state=3D'tx_fail_retryable') and txobject =3D = 'ticket' limit 250 for update skip locked;
ERROR: =C2=A040001: tuple to be locked was already moved to another partition due to concurrent update
LOCATION: =C2=A0heapam_tuple_lock, heapam_handler.c:405
Time: 579.131 ms
[queuedb] # explain analyze select queueid,txobject,objectid,state from mq.queue where (state =3D 'tx_active' or state=3D'tx_fail_retryable') and txobject =3D 'ticket' limit 250 = for update skip locked;
ERROR: =C2=A040001: tuple to be locked was already moved to another partition due to concurrent update
LOCATION: =C2=A0heapam_tuple_lock, heapam_handler.c:405
Time: 568.008 ms
[queuedb] # explain analyze select queueid,txobject,objectid,state from mq.queue where (state =3D 'tx_active' or state=3D'tx_fail_retryable') and txobject =3D 'ticket' limit 250 = for update skip locked;
=C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 = =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 = =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 = =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 QUERY PLAN
-------------------------------------------------------------------------= -------------------------------------------------------------------------= --------
=C2=A0Limit =C2=A0(cost=3D0.00..25.71 rows=3D250 width=3D34) = (actual time=3D1306.041..1306.338 rows=3D250 loops=3D1)
=C2=A0 =C2=A0-> =C2=A0LockRows =C2=A0(cost=3D0.00..7934.38 = rows=3D77150 width=3D34) (actual time=3D1306.040..1306.315 rows=3D250 loops=3D1)
=C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0-> =C2=A0Append =C2=A0(cost=3D= 0.00..7162.88 rows=3D77150 width=3D34) (actual time=3D520.685..1148.347 rows=3D31500 loops=3D1)
=C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0-> = =C2=A0Seq Scan on queue_tx_active =C2=A0(cost=3D0.00..6764.50 rows=3D77000 width=3D34) (actual time=3D520.683..1145.258 rows=3D31500 loops=3D1)
=C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 = =C2=A0 =C2=A0Filter: ((txobject =3D 'ticket'::mq.queue_object) AND ((state =3D 'tx_active'::mq.tx_state= ) OR (state =3D 'tx_fail_retryable'::mq.tx_state)))
=C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0-> = =C2=A0Seq Scan on queue_tx_fail_retryable =C2=A0(cost=3D0.00..12.62 rows=3D150 width=3D34) (never executed) =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 = =C2=A0 =C2=A0Filter: ((txobject =3D 'ticket'::mq.queue_object) AND ((state =3D 'tx_active'::mq.tx_state= ) OR (state =3D 'tx_fail_retryable'::mq.tx_state)))
=C2=A0Planning Time: 0.274 ms
=C2=A0Execution Time: 1306.380 ms
(9 rows)

Time: 1317.150 ms (00:01.317)
[queuedb] #


    

  


--------------929D6E83CE69D9A3A154DC5F--