Re: autovacuum locking question

--0000000000000a29550598fda9e2
Content-Type: text/plain; charset="UTF-8"

On Thu, Dec 5, 2019 at 5:26 PM Mike Schanne <[email protected]> wrote:

> Hi,
>
> I am investigating a performance problem in our application and am seeing
> something unexpected in the postgres logs regarding the autovacuum.
>
>
>
> 2019-12-01 13:05:39.029 UTC,"wb","postgres",6966,"127.0.0.1:53976",5ddbd990.1b36,17099,"INSERT
> waiting",2019-11-25 13:39:28 UTC,12/1884256,12615023,LOG,00000,"process
> 6966 still waiting for RowExclusiveLock on relation 32938 of database 32768
> after 1000.085 ms","Process holding the lock: 6045. Wait queue:
> 6966.",,,,,"INSERT INTO myschema.mytable (...) VALUES (...) RETURNING
> process.mytable.mytable_id",13,,""
>
> 2019-12-01 13:05:39.458 UTC,,,6045,,5de3b800.179d,1,,2019-12-01 12:54:24
> UTC,10/417900,0,ERROR,57014,"canceling autovacuum task",,,,,"automatic
> vacuum of table ""postgres.myschema.mytable""",,,,""
>
>
>
> My understanding from reading the documentation was that a vacuum can run
> concurrently with table inserts/updates, but from reading the logs it
> appears they are conflicting over a row lock.  This particular table gets
> very frequent inserts/updates (10-100 inserts / sec) so I am concerned that
> if the autovacuum is constantly canceled, then the table never gets cleaned
> and its performance will continue to degrade over time.  Is it expected for
> the vacuum to be canceled by an insert in this way?
>
>
>
> We are using postgres 9.6.10.
>

If the vacuum finds a lot of empty pages at the end of the table, it will
try to truncate them and takes a strong lock to do so.  It is supposed to
check every 20ms to see if anyone else is blocked on that lock, at which
point it stops doing the truncation and releases the lock.  So it should
never get "caught" holding the lock in order to be cancelled.  Is your
setting for deadlock_timeout much lower than usual?  Also, if the
truncation is bogged down in very slow IO, perhaps it doesn't actually get
around to checking ever 20ms despite its intentionsl

How often have you seen it in the logs?

Cheers,

Jeff

>

--0000000000000a29550598fda9e2
Content-Type: text/html; charset="UTF-8"
Content-Transfer-Encoding: quoted-printable

<div dir=3D"ltr"><div dir=3D"ltr">On Thu, Dec 5, 2019 at 5:26 PM Mike Schan=
ne &lt;<a href=3D"mailto:[email protected]">[email protected]</a>&gt; wrote:<=
br></div><div class=3D"gmail_quote"><blockquote class=3D"gmail_quote" style=
=3D"margin:0px 0px 0px 0.8ex;border-left:1px solid rgb(204,204,204);padding=
-left:1ex">





<div lang=3D"EN-US">
<div class=3D"gmail-m_-1995735985906220789WordSection1">
<p class=3D"MsoNormal">Hi,<u></u><u></u></p>
<p class=3D"MsoNormal">I am investigating a performance problem in our appl=
ication and am seeing something unexpected in the postgres logs regarding t=
he autovacuum.<u></u><u></u></p>
<p class=3D"MsoNormal"><u></u>=C2=A0<u></u></p>
<p class=3D"MsoNormal">2019-12-01 13:05:39.029 UTC,&quot;wb&quot;,&quot;pos=
tgres&quot;,6966,&quot;<a href=3D"http://127.0.0.1:53976" target=3D"_blank"=
>127.0.0.1:53976</a>&quot;,5ddbd990.1b36,17099,&quot;INSERT waiting&quot;,2=
019-11-25 13:39:28 UTC,12/1884256,12615023,LOG,00000,&quot;process 6966 sti=
ll waiting for RowExclusiveLock on relation 32938 of database
 32768 after 1000.085 ms&quot;,&quot;Process holding the lock: 6045. Wait q=
ueue: 6966.&quot;,,,,,&quot;INSERT INTO myschema.mytable (...) VALUES (...)=
 RETURNING process.mytable.mytable_id&quot;,13,,&quot;&quot;<u></u><u></u><=
/p>
<p class=3D"MsoNormal">2019-12-01 13:05:39.458 UTC,,,6045,,5de3b800.179d,1,=
,2019-12-01 12:54:24 UTC,10/417900,0,ERROR,57014,&quot;canceling autovacuum=
 task&quot;,,,,,&quot;automatic vacuum of table &quot;&quot;postgres.mysche=
ma.mytable&quot;&quot;&quot;,,,,&quot;&quot;<u></u><u></u></p>
<p class=3D"MsoNormal"><u></u>=C2=A0<u></u></p>
<p class=3D"MsoNormal">My understanding from reading the documentation was =
that a vacuum can run concurrently with table inserts/updates, but from rea=
ding the logs it appears they are conflicting over a row lock.=C2=A0 This p=
articular table gets very frequent inserts/updates
 (10-100 inserts / sec) so I am concerned that if the autovacuum is constan=
tly canceled, then the table never gets cleaned and its performance will co=
ntinue to degrade over time.=C2=A0 Is it expected for the vacuum to be canc=
eled by an insert in this way?<u></u><u></u></p>
<p class=3D"MsoNormal"><u></u>=C2=A0<u></u></p>
<p class=3D"MsoNormal">We are using postgres 9.6.10.</p></div></div></block=
quote><div><br></div><div>If the vacuum finds a lot of empty pages at the e=
nd of the table, it will try to truncate them and takes a strong lock to do=
 so.=C2=A0 It is supposed to check every 20ms to see if anyone else is bloc=
ked on that lock, at which point it stops doing the truncation and releases=
 the lock.=C2=A0 So it should never get &quot;caught&quot; holding the lock=
 in order to be cancelled.=C2=A0 Is your setting for deadlock_timeout much =
lower than usual?=C2=A0 Also, if the truncation is bogged down in very slow=
 IO, perhaps it doesn&#39;t actually get around to checking ever 20ms despi=
te its intentionsl</div><div><br></div><div>How often have you seen it in t=
he logs?</div><div><br></div><div>Cheers,</div><div><br></div><div>Jeff</di=
v><blockquote class=3D"gmail_quote" style=3D"margin:0px 0px 0px 0.8ex;borde=
r-left:1px solid rgb(204,204,204);padding-left:1ex"><div lang=3D"EN-US">
</div>

</blockquote></div></div>

--0000000000000a29550598fda9e2--