Content-Type: multipart/alternative;
 boundary="------------gVVZsLkjC2yH5Vg8AtWyOlra"
Message-ID: <5c336778-df1a-f440-8feb-31c5ffbc9188@gmail.com>
Date: Wed, 6 Oct 2021 14:54:59 -0400
MIME-Version: 1.0
User-Agent: Mozilla/5.0 (X11; Linux x86_64; rv:91.0) Gecko/20100101
 Thunderbird/91.1.0
Subject: Re: Troubleshooting a long running delete statement
Content-Language: en-US
To: pgsql-performance@lists.postgresql.org
References: 
 <DM6PR03MB43323A813F2489B43B50195AFAB09@DM6PR03MB4332.namprd03.prod.outlook.com>
From: Mladen Gogala <gogala.mladen@gmail.com>
In-Reply-To: 
 <DM6PR03MB43323A813F2489B43B50195AFAB09@DM6PR03MB4332.namprd03.prod.outlook.com>
Archived-At: 
 <https://www.postgresql.org/message-id/5c336778-df1a-f440-8feb-31c5ffbc9188%40gmail.com>
Precedence: bulk

This is a multi-part message in MIME format.
--------------gVVZsLkjC2yH5Vg8AtWyOlra
Content-Type: text/plain; charset=UTF-8; format=flowed
Content-Transfer-Encoding: 8bit

On 10/6/21 14:00, Dirschel, Steve wrote:

> Question:
> How would one troubleshoot this issue in Postgres as to why the delete 
> was running so long?  My background is Oracle and there are various 
> statistics I may look at:
>
>   * One could estimate the number of logical reads the delete should
>     do based on expected number of rows to delete, expected logical
>     reads against the table per row, expected logical reads against
>     each index per row.
>   * One could look in V$SQL and see how many logical reads the query
>     was actually doing.
>   * One could look at V$SESS_IO and see how many logical reads the
>     session was doing.
>
> In this case you would see the query was doing way more logical reads 
> that expected and then try and think of scenarios that would cause that.
> Here is what I could see in Postgres:
>
>   * When I did an explain on the delete I could see it was full
>     scanning the table. I did a full scan of the table interactively
>     in less than 1 second so the long runtime was not due to the full
>     tablescan.
>   * I could not find the query in pg_stat_statements to see how many
>     shared block reads/hits the query was doing to see if the numbers
>     were extremely high.  Based on documentation queries do not show
>     up in pg_stat_statements until after they complete.
>   * pg_stat_activity showed wait_event_type and wait_event were null
>     for the session every time I looked.  So the session was
>     continually using CPU.
>
> I started looking at table definitions (indexes, FK's, etc.) and 
> comparing to Oracle and noticed some indexes missing.  I then could 
> see the table being deleted from was a child table with a FK pointing 
> to a parent table.  Finally I was able to see that the parent table 
> was missing an index on the FK column so for every row being deleted 
> from the child it was full scanning the parent.  All makes sense after 
> the fact but I'm looking for a more methodical way to come to that 
> conclusion by looking at database statistics.
> Are there other statistics in Postgres I may have looked at to 
> methodically come to the conclusion that the problem was the missing 
> index on the parent FK column?
> Thanks
> This e-mail is for the sole use of the intended recipient and contains 
> information that may be privileged and/or confidential. If you are not 
> an intended recipient, please notify the sender by return e-mail and 
> delete this e-mail and any attachments. Certain required legal entity 
> disclosures can be accessed on our website: 
> https://www.thomsonreuters.com/en/resources/disclosures.html


Hi Steve,

First, check whether you have any triggers on the table. The best way of 
doing it is to use information_schema.triggers. I have seen triggers 
introduce some "mysterious" functionality in Oracle as well. Second, 
check constraints. Is the table you're deleting from the parent table of 
a foreign key constraint(s)? If the constraints are defined with "ON 
DELETE CASCADE", you maybe deleting more than you think. If it is not 
defined with "ON DELETE CASCADE" or "ON DELETE SET NULL", you would get 
an error. If that passes the muster, then check the processes doing the 
most of IO using "iotop" or "atop". I like the latter. You can then 
check what the busy processes are doing using strace -e trace=file and, 
for good measure, 'perf top".

Regards

-- 
Mladen Gogala
Database Consultant
Tel: (347) 321-1217
https://dbwhisperer.wordpress.com

--------------gVVZsLkjC2yH5Vg8AtWyOlra
Content-Type: text/html; charset=UTF-8
Content-Transfer-Encoding: 8bit

<html>
  <head>
    <meta http-equiv="Content-Type" content="text/html; charset=UTF-8">
  </head>
  <body>
    <p>On 10/6/21 14:00, Dirschel, Steve wrote:<br>
    </p>
    <blockquote type="cite"
cite="mid:DM6PR03MB43323A813F2489B43B50195AFAB09@DM6PR03MB4332.namprd03.prod.outlook.com">
      <meta http-equiv="Content-Type" content="text/html; charset=UTF-8">
      <meta name="Generator" content="Microsoft Exchange Server">
      <!-- converted from rtf -->
      <style>.EmailQuote { margin-left: 1pt; padding-left: 4pt; border-left: #800000 2px solid; }</style>
      <font size="2" face="Calibri"><span style="font-size:11pt;">
          <div>Question:</div>
          <div> </div>
          <div>How would one troubleshoot this issue in Postgres as to
            why the delete was running so long?  My background is Oracle
            and there are various statistics I may look at:</div>
          <ul style="margin:0;padding-left:36pt;">
            <li>One could estimate the number of logical reads the
              delete should do based on expected number of rows to
              delete, expected logical reads against the table per row,
              expected logical reads against each index per row.  </li>
            <li>One could look in V$SQL and see how many logical reads
              the query was actually doing.</li>
            <li>One could look at V$SESS_IO and see how many logical
              reads the session was doing.</li>
          </ul>
          <div> </div>
          <div>In this case you would see the query was doing way more
            logical reads that expected and then try and think of
            scenarios that would cause that.</div>
          <div> </div>
          <div>Here is what I could see in Postgres:</div>
          <ul style="margin:0;padding-left:36pt;">
            <li>When I did an explain on the delete I could see it was
              full scanning the table. I did a full scan of the table
              interactively in less than 1 second so the long runtime
              was not due to the full tablescan.</li>
            <li>I could not find the query in pg_stat_statements to see
              how many shared block reads/hits the query was doing to
              see if the numbers were extremely high.  Based on
              documentation queries do not show up in pg_stat_statements
              until after they complete.</li>
            <li>pg_stat_activity showed wait_event_type and wait_event
              were null for the session every time I looked.  So the
              session was continually using CPU.</li>
          </ul>
          <div> </div>
          <div>I started looking at table definitions (indexes, FK's,
            etc.) and comparing to Oracle and noticed some indexes
            missing.  I then could see the table being deleted from was
            a child table with a FK pointing to a parent table.  Finally
            I was able to see that
            the parent table was missing an index on the FK column so
            for every row being deleted from the child it was full
            scanning the parent.  All makes sense after the fact but I'm
            looking for a more methodical way to come to that conclusion
            by looking at database
            statistics.</div>
          <div> </div>
          <div>Are there other statistics in Postgres I may have looked
            at to methodically come to the conclusion that the problem
            was the missing index on the parent FK column?</div>
          <div> </div>
          <div>Thanks</div>
          <div> </div>
          <div><font face="Times New Roman">This e-mail is for the sole
              use of the intended recipient and contains information
              that may be privileged and/or confidential. If you are not
              an intended recipient, please notify the sender by return
              e-mail and delete this
              e-mail and any attachments. Certain required legal entity
              disclosures can be accessed on our website:
              <a
                href="https://www.thomsonreuters.com/en/resources/disclosures.html"
                moz-do-not-send="true" class="moz-txt-link-freetext">https://www.thomsonreuters.com/en/resources/disclosures.html</a></font></div>
        </span></font></blockquote>
    <p><br>
    </p>
    <p><font size="2"><font face="Times New Roman">Hi Steve,</font></font></p>
    <p><font size="2"><font face="Times New Roman">First, check whether
          you have any triggers on the table. The best way of doing it
          is to use information_schema.triggers. I have seen triggers
          introduce some "mysterious" functionality in Oracle as well.
          Second, check constraints. Is the table you're deleting from
          the parent table of a foreign key constraint(s)? If the
          constraints are defined with "ON DELETE CASCADE", you maybe
          deleting more than you think. If it is not defined with "ON
          DELETE CASCADE" or "ON DELETE SET NULL", you would get an
          error. If that passes the muster, then check the processes
          doing the most of IO using "iotop" or "atop". I like the
          latter. You can then check what the busy processes are doing
          using strace -e trace=file and, for good measure, 'perf top".</font></font></p>
    <p><font size="2"><font face="Times New Roman">Regards</font></font><br>
    </p>
    <pre class="moz-signature" cols="72">-- 
Mladen Gogala
Database Consultant
Tel: (347) 321-1217
<a class="moz-txt-link-freetext" href="https://dbwhisperer.wordpress.com">https://dbwhisperer.wordpress.com</a>
</pre>
  </body>
</html>
--------------gVVZsLkjC2yH5Vg8AtWyOlra--