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 1k8kkh-00042I-Jt for pgsql-performance@arkaria.postgresql.org; Thu, 20 Aug 2020 13:37:11 +0000 Received: from localhost ([127.0.0.1] helo=malur.postgresql.org) by malur.postgresql.org with esmtp (Exim 4.92) (envelope-from ) id 1k8kkg-0003xU-Hj for pgsql-performance@arkaria.postgresql.org; Thu, 20 Aug 2020 13:37:10 +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 1k8kkg-0003xM-68 for pgsql-performance@lists.postgresql.org; Thu, 20 Aug 2020 13:37:10 +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 1k8kkZ-0001IZ-LF for pgsql-performance@lists.postgresql.org; Thu, 20 Aug 2020 13:37:05 +0000 Received: from messaging.network-systems-solutions.net (unknown [192.168.242.37]) by mail4.network-systems-solutions.net (Postfix) with ESMTP id D86D812021E; Thu, 20 Aug 2020 14:36:55 +0100 (BST) Received: from aox (localhost [127.0.0.1]) by messaging.network-systems-solutions.net (Postfix) with ESMTP id 3BF8A8E0596; Thu, 20 Aug 2020 09:36:56 -0400 (EDT) Received: from jim@talentstack.to by aox (Archiveopteryx 3.2.0) with esmtpsa id 1597930615-23382-23378/6/85; Thu, 20 Aug 2020 13:36:55 +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: Date: Thu, 20 Aug 2020 09:35:38 -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=------------CB772F4A61F450AC2D77FE5B Content-Language: en-CA X-NSSLTD-SpamTemp: 1255995 X-Spam-Score: -1.105 () BAYES_00,HTML_MESSAGE,RDNS_NONE,SPF_FAIL X-NSSLTD-Archiving: Added to store 1 as 84392 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 --------------CB772F4A61F450AC2D77FE5B Content-Type: text/plain; charset=utf-8; format=flowed Content-Transfer-Encoding: quoted-printable Updates added, mixture of good and bad news: On 18-Aug.-2020 20:39, Michael Lewis wrote: > How long does each process take in total? How strict does that FIFO = really > need to be when you are already doing SKIP LOCKED anyway? The processes all bottleneck[ed] for several minutes, approximately=20 exponential to the number above the threshold where the problem=20 happened.=C2=A0 Up to around 60 concurrent worked with minimal delay but=20 beyond that a few more added about a minute, 70 about 5 minutes, 80=20 about 30 minutes and beyond that was hours (I left up to 12 hours one = time). However, I removed the order by clause which eliminated [only] the high=20 CPU.=C2=A0 The processes all stopped in the same pattern, just without = the=20 high CPU use.=C2=A0 So the ordering was the factor in the CPU use, but = was=20 not responsible for the - forgive the pun - lock up. I then added a random few seconds of delay to each process before it=20 executes the select in order to prevent too many of them colliding on=20 simultaneous selects.=C2=A0 That was enough to make the lock-up disappear= and=20 individual selects complete in a few ms, regardless of how many other=20 concurrent transactions are in progress (tested up to 192 concurrent).=C2= =A0=20 But still not quite out the woods - read below. > Can you expound on the partitioning? Are all consumers of the queue = always > hitting one active partition and anytime a row is processed, it always > moves to one of many? archived type partitions? Partitions are list partitioned as 'incoming', 'processing', 'retry',=20 'ok', 'failed': Incoming: This is itself hash partitioned (64 partitions) approx 10M=20 rows added/day so partitioned to allow incoming throughput; this works = well. Processing: Simple partition, data is moved into this in blocks as the=20 rows count drops below a threshold, another block is added, coming from=20 the incoming. Retry: simple partition, non fatal errors go in here and go back into=20 the processing queue for retries later. Failed: simple partition, fatal errors go here.=C2=A0 Thankfully very = few. OK: hash partition, as everything that was in incoming should eventually=20 end up here.=C2=A0 64 partitions currently. There is one interesting thing about this.=C2=A0 When the SELECT FOR = UPDATE=20 SKIP LOCKED is executed, reasonably frequently, the select aborts with=20 the error: Tuple to be locked was already moved to another partition due to=20 concurrent update. This error still persists even though the lock-up has been removed by=20 the time delay, so there is a regular stream of transactions aborting=20 due to this (I just re-run the transaction to recover). Now, if locking worked as I understand it, if another process locked and=20 migrated, this should still have left the lock in place on the original=20 partition and created a new one on the newly inserted partition until a=20 commit was done.=C2=A0 The second process should not have visibility on = the=20 newly inserted row and the skip locked should simply have skipped over=20 the locked but deleted row on the original partition. What am I missing?=C2=A0 All of this feels like some locking/partitioning= =20 issue but I'm unsure exactly what. > Is that done via FDW or otherwise within the same database transaction?= Are > you connecting some queue consumer application code to Postgres, = select for > update, doing work on some remote system that is slow, and then coming = back > and committing the DB work? Alas not FDW, an actual external system elsewhere in the world which=20 sends an ACK when it has processed the message.=C2=A0 I have no control = or=20 influence on this. > By the way, top-posting is discouraged here and partial quotes with > interspersed comments are common practice. Noted! --------------CB772F4A61F450AC2D77FE5B Content-Type: text/html; charset=utf-8 Content-Transfer-Encoding: quoted-printable

Updates added, mixture of good and bad news:

On 18-Aug.-2020 20:39, Michael Lewis wrote:

      
How long does each process =
take in total? How strict does that FIFO really
need to be when you are already doing SKIP LOCKED anyway?


    

    
The processes all bottleneck[ed] for several minutes,
      approximately exponential to the number above the threshold where
      the problem happened.=C2=A0 Up to around 60 concurrent worked with
      minimal delay but beyond that a few more added about a minute, 70
      about 5 minutes, 80 about 30 minutes and beyond that was hours (I
      left up to 12 hours one time).

    
However, I removed the order by clause which eliminated [only]
      the high CPU.=C2=A0 The processes all stopped in the same pattern, =
just
      without the high CPU use.=C2=A0 So the ordering was the factor in =
the
      CPU use, but was not responsible for the - forgive the pun - lock
      up.

    
I then added a random few seconds of delay to each process before
      it executes the select in order to prevent too many of them
      colliding on simultaneous selects.=C2=A0 That was enough to make =
the
      lock-up disappear and individual selects complete in a few ms,
      regardless of how many other concurrent transactions are in
      progress (tested up to 192 concurrent).=C2=A0 But still not quite =
out
      the woods - read below.

    

    

      
Can you expound on the =
partitioning? Are all consumers of the queue always
hitting one active partition and anytime a row is processed, it always
moves to one of many? archived type partitions?

    

    
Partitions are list partitioned as 'incoming', 'processing',
      'retry', 'ok', 'failed':

    
Incoming: This is itself hash partitioned (64 partitions) approx
      10M rows added/day so partitioned to allow incoming throughput;
      this works well.

    
Processing: Simple partition, data is moved into this in blocks
      as the rows count drops below a threshold, another block is added,
      coming from the incoming.

    
Retry: simple partition, non fatal errors go in here and go back
      into the processing queue for retries later.

    
Failed: simple partition, fatal errors go here.=C2=A0 Thankfully =
very
      few.

    
OK: hash partition, as everything that was in incoming should
      eventually end up here.=C2=A0 64 partitions currently.

    
There is one interesting thing about this.=C2=A0 When the SELECT =
FOR
      UPDATE SKIP LOCKED is executed, reasonably frequently, the select
      aborts with the error:

    
Tuple to be locked was already moved to another partition due to
      concurrent update.

    
This error still persists even though the lock-up has been
      removed by the time delay, so there is a regular stream of
      transactions aborting due to this (I just re-run the transaction
      to recover).

    

    
Now, if locking worked as I understand it, if another process
      locked and migrated, this should still have left the lock in place
      on the original partition and created a new one on the newly
      inserted partition until a commit was done.=C2=A0 The second =
process
      should not have visibility on the newly inserted row and the skip
      locked should simply have skipped over the locked but deleted row
      on the original partition.

    
What am I missing?=C2=A0 All of this feels like some
      locking/partitioning issue but I'm unsure exactly what.

    

    

      
Is that done via FDW or =
otherwise within the same database transaction? Are
you connecting some queue consumer application code to Postgres, select =
for
update, doing work on some remote system that is slow, and then coming =
back
and committing the DB work?


    

    Alas not FDW, an actual external system elsewhere in the world which
    sends an ACK when it has processed the message.=C2=A0 I have no =
control
    or influence on this.

    

      
By the way, top-posting is discouraged here and partial quotes with
interspersed comments are common practice.


    

    Noted!

    

      

    

  


--------------CB772F4A61F450AC2D77FE5B--