Received: from malur.postgresql.org ([217.196.149.56]) by arkaria.postgresql.org with esmtps (TLS1.2:ECDHE_RSA_AES_256_CBC_SHA1:256) (Exim 4.89) (envelope-from ) id 1idHkm-0002Pw-Bn for pgsql-performance@arkaria.postgresql.org; Fri, 06 Dec 2019 17:50:56 +0000 Received: from localhost ([127.0.0.1] helo=malur.postgresql.org) by malur.postgresql.org with esmtp (Exim 4.89) (envelope-from ) id 1idHkl-0001WP-3u for pgsql-performance@arkaria.postgresql.org; Fri, 06 Dec 2019 17:50:55 +0000 Received: from magus.postgresql.org ([2a02:c0:301:0:ffff::29]) by malur.postgresql.org with esmtps (TLS1.2:ECDHE_RSA_AES_256_CBC_SHA1:256) (Exim 4.89) (envelope-from ) id 1idHkk-0001TN-Oj for pgsql-performance@lists.postgresql.org; Fri, 06 Dec 2019 17:50:54 +0000 Received: from mout.perfora.net ([74.208.4.194]) by magus.postgresql.org with esmtps (TLS1.2:ECDHE_RSA_AES_256_CBC_SHA1:256) (Exim 4.89) (envelope-from ) id 1idHki-0000f7-BY for pgsql-performance@postgresql.org; Fri, 06 Dec 2019 17:50:54 +0000 Received: from [192.168.1.101] ([98.169.208.73]) by mrelay.perfora.net (mreueus001 [74.208.5.2]) with ESMTPSA (Nemesis) id 0MgMYS-1iQgXg2xQk-00Nk1f; Fri, 06 Dec 2019 18:50:46 +0100 Subject: Re: autovacuum locking question To: Jeff Janes Cc: Mike Schanne , "pgsql-performance@postgresql.org" References: <0871fcf35ceb4caa8a2204ca9c38e330@USEPRDEX1.corp.kns.com> From: MichaelDBA Message-ID: <3b91b82c-6fa0-04db-80ad-24b7939d80c7@sqlexec.com> Date: Fri, 6 Dec 2019 12:50:44 -0500 User-Agent: Mozilla/5.0 (Windows NT 10.0; WOW64; rv:52.0) Gecko/20100101 PostboxApp/7.0.9 MIME-Version: 1.0 In-Reply-To: Content-Type: multipart/alternative; boundary="------------764CD427BDB1714990A0ADDB" Content-Language: en-US X-Provags-ID: V03:K1:IjUIqE+lj4BTYiuPnnoKL6V3m9DXnb4cFWFpsrHeafK0FLH4P4l DQlfkqQ1XJxSHCAv0UU1T9iSx+WEMJZQKb9DcumBGwkMIaZOsiQlaAf1g2TCRDKB5mGJ2NO bJw6wYCE6SESlq+0z00oCzNwQhizwSz3FfJzRKeiweiU97ljiA6P9f2iKNJVbfYOBswKQAg R8Dnju0mhmc4Sa6G4t1TA== X-Spam-Flag: NO X-UI-Out-Filterresults: notjunk:1;V03:K0:F+uHY5TbbCc=:62dkNrxfErvfI9UgmBYEcG 0jQhEvHUPSbyV13xs1LSOZ+YdozjvfVOk/BQKcIEno1etuxLi9A3krga43QXWv9u6Nj13A+xB M+8VBVCYuC+ApIh6J+iy8nYWjqAPVNZxDaymeeYqMPHT/BR3+P3vcIczQitHaaggr/RfYxQpd F8nY+mhagCdltEDMpeJlFDKP9cGoLvJu339ojPNRLzQli1QkIHmUMGIsBZJ2fSR8K27HJwQTD xZrlrFaXjGFYOZg1LJGZCi27kjLzNEkb/+2jcpUfuz0qbjBrUK6zPBexiifPpFtCfuFDePkWA mOKWm8i8iUCdxwC+sErAI6uuyRpQxgcuvJ2epxfnm7FODG+zeq6pq4BFljJpSrSBVdlzU7uPh 1Q7l8uo9Vt1Gny1H/9blnsc+kS98ZMNbLZRhC9AU/gOsBDwOlH2M3p9Y4Z4VZheL3X1p2N2oF JMGwZvGsNy8r79RzX1D/WI8EchF3Dc8CDi9cqeEPmgtarGPF7AUodlXp9eNW/Jr1ZP3+/jMwR KV+xWB9XjFmRe4PowVhpeEwAK/Di+lhK/GEzoRBK0aykoj+6HiD6S1DJ1yfIpyMILakDoq1fj n3g5msyL5DXR46EpukoFiwkD1PpJ//K5ZMqr1IzlsKdglixrADPR9Xx2pZZVG3upGZnW128yL ZqIDDXNwS2rrCEIHa09B9MKLZKMCjtB/cc769Si5LIJcvabd1nWV5+xThWY5hAzFtm/54RIin TlnnIAbovqu5axMz4Lz3w9hwiO8AZOAuN9BDdTA65V2CsYeofLCi+B5hrtenqqxPzr0p1zHQf bvFJC0IxPnI0s51yo6/IYo4LT4yi3+pNYLc2QDQwjXE3vWokIpLz4pJE91BnHFAsssel80eqM RWtO27Lcx9bldrYYHDSmagg3ZQsbco3p4yaGVRZNE= List-Id: List-Help: List-Subscribe: List-Post: List-Owner: List-Archive: Precedence: bulk This is a multi-part message in MIME format. --------------764CD427BDB1714990A0ADDB Content-Type: text/plain; charset=utf-8; format=flowed Content-Transfer-Encoding: 8bit And Just to reiterate my own understanding of this... autovacuum priority is less than a user-initiated request, so issuing a manual vacuum (user-initiated request) will not result in being cancelled. Regards, Michael Vitale Jeff Janes wrote on 12/6/2019 12:47 PM: > On Fri, Dec 6, 2019 at 10:55 AM Mike Schanne > wrote: > > The error is not actually showing up very often (I have 8 > occurrences from 11/29 and none since then).  So maybe I should > not be concerned about it.  I suspect we have an I/O bottleneck > from other logs (i.e. long checkpoint sync times), so this error > may be a symptom rather than the cause. > > > I think that at the point it is getting cancelled, it has done all the > work except the truncation of the empty pages, and reporting the > results (for example, updating n_live_tup  and n_dead_tup).  If this > happens every single time (neither last_autovacuum nor last_vacuum > ever advances) it will eventually cause problems.  So this is mostly a > symptom, but not entirely.  Simply running a manual vacuum should fix > the reporting problem.  It is not subject to cancelling, so it will > detect it is blocking someone and gracefully bow.  Meaning it will > suspend the truncation, but will still report its results as normal. > Reading the table backwards in order to truncate it might be > contributing to the IO problems as well as being a victim of those > problems.  Upgrading to v10 might help with this, as it implemented a > prefetch where it reads the table forward in 128kB chunks, and then > jumps backwards one chunk at a time.  Rather than just reading > backwards 8kB at a time. > > Cheers, > > Jeff > --------------764CD427BDB1714990A0ADDB Content-Type: text/html; charset=utf-8 Content-Transfer-Encoding: 8bit And Just to reiterate my own understanding of this...

autovacuum priority is less than a user-initiated request, so issuing a manual vacuum (user-initiated request) will not result in being cancelled.

Regards,
Michael Vitale

Jeff Janes wrote on 12/6/2019 12:47 PM:
On Fri, Dec 6, 2019 at 10:55 AM Mike Schanne <mschanne@kns.com> wrote:

The error is not actually showing up very often (I have 8 occurrences from 11/29 and none since then).  So maybe I should not be concerned about it.  I suspect we have an I/O bottleneck from other logs (i.e. long checkpoint sync times), so this error may be a symptom rather than the cause.


I think that at the point it is getting cancelled, it has done all the work except the truncation of the empty pages, and reporting the results (for example, updating n_live_tup  and n_dead_tup).  If this happens every single time (neither last_autovacuum nor last_vacuum ever advances) it will eventually cause problems.  So this is mostly a symptom, but not entirely.  Simply running a manual vacuum should fix the reporting problem.  It is not subject to cancelling, so it will detect it is blocking someone and gracefully bow.  Meaning it will suspend the truncation, but will still report its results as normal.
 
Reading the table backwards in order to truncate it might be contributing to the IO problems as well as being a victim of those problems.  Upgrading to v10 might help with this, as it implemented a prefetch where it reads the table forward in 128kB chunks, and then jumps backwards one chunk at a time.  Rather than just reading backwards 8kB at a time.

Cheers,

Jeff

--------------764CD427BDB1714990A0ADDB--