Thread: Query planner / Analyse statistics bad estimate rows=1 with maximumstatistics 10000 on PostgreSQL 10.2

Hi Jeff, 

Thanks for your help. That is exactly what is happening.

I have a long running job which deletes all of the common_student table and then repopulates it. It takes long time to load all the other data and commit the transaction. I didn't think the delete inside the transaction would have any effect until it is commited or rolled back.

I will have to rewrite the application so it updates the existing rows rather than deleting all and then inserting.

Thanks again for helping me understand what's happening here. 

Proof:

db=> explain analyze select * from common_student where school_id = 36;

                                                              QUERY PLAN                                                              

--------------------------------------------------------------------------------------------------------------------------------------

 Bitmap Heap Scan on common_student  (cost=88.30..3846.49 rows=1533 width=384) (actual time=4.852..7.065 rows=1388 loops=1)

   Recheck Cond: (school_id = 36)

   Heap Blocks: exact=67

   ->  Bitmap Index Scan on idx_common_student_sid  (cost=0.00..87.91 rows=1533 width=0) (actual time=4.817..4.817 rows=1388 loops=1)

         Index Cond: (school_id = 36)

 Planning time: 0.097 ms

 Execution time: 8.084 ms

(7 rows)

db=> /* At this point I have started a long running transaction that deletes all of common_student for school_id 36  */ ;

db=> analyse verbose common_student(school_id); 

INFO:  analyzing "public.common_student"

INFO:  "common_student": scanned 7322 of 7322 pages, containing 65431 live rows and 8060 dead rows; 56818 rows in sample, 65431 estimated total rows

ANALYZE

db=> explain analyze select * from common_student where school_id = 36;

                                                                 QUERY PLAN                                                                 

--------------------------------------------------------------------------------------------------------------------------------------------

 Index Scan using idx_common_student_sid on common_student  (cost=0.41..8.43 rows=1 width=384) (actual time=0.017..1.498 rows=1388 loops=1)

   Index Cond: (school_id = 36)

 Planning time: 0.098 ms

 Execution time: 2.583 ms

(4 rows)

db=> /* At this point I have killed the long running transaction that deletes all of common_student for school_id 36  */ ;

db=> vacuum analyze common_student; 

VACUUM

db=> explain analyze select * from common_student where school_id = 36;

                                                              QUERY PLAN                                                              

--------------------------------------------------------------------------------------------------------------------------------------

 Bitmap Heap Scan on common_student  (cost=79.17..3357.79 rows=1388 width=383) (actual time=0.088..1.302 rows=1388 loops=1)

   Recheck Cond: (school_id = 36)

   Heap Blocks: exact=67

   ->  Bitmap Index Scan on idx_common_student_sid  (cost=0.00..78.83 rows=1388 width=0) (actual time=0.077..0.077 rows=1388 loops=1)

         Index Cond: (school_id = 36)

 Planning time: 0.327 ms

 Execution time: 2.311 ms

(7 rows)

On Sun, 23 Dec 2018 at 02:57 Jeff Janes <jeff.janes@gmail.com> wrote:

- Does the analyse output below mean that it only scanned 51538 of 65463 rows in the table? Is school_id 36 just being missed in the sample? (This happens when the analyse is repeated )

Is there a transaction which had deleted all of school_id=36, and then was just left open indefinitely without either committing or rolling back?

That would explain it, and I don't know of anything else that could.  The deleted but not committed tuples are still live, but don't get sampled.

Cheers,

Jeff

Hi Ron, 

Yes, my process will commit the transaction (or roll it back) eventually. It's the window where

one transaction has deleted all the rows (before committing) and an ANALYSE has ran.

The deleted rows won't make it into the sample even though the transaction has NOT been commited.

During this time I will get bad row estimates on rows for that ID. You can see this in the example below with two 

database connections (labelled 1 and 2).

I would have expected the DELETE to have no effect until it was committed.

connection 1=> create table test_table(school_id integer, note text); 

CREATE TABLE

connection 1=> insert into test_table(school_id, note) SELECT g.id,md5(random()::text) FROM generate_series(1,2) as g(id);

INSERT 0 2

connection 1=> insert into test_table(school_id, note) SELECT g.id,md5(random()::text) FROM generate_series(1,2) as g(id);

INSERT 0 2

connection 1=> insert into test_table(school_id, note) SELECT g.id,md5(random()::text) FROM generate_series(1,2) as g(id);

INSERT 0 2

connection 1=> select * from test_table ;

 school_id |               note               

-----------+----------------------------------

         1 | 0e08cf3990a04f0e943584517c564d31

         2 | 96bf83ae5f8eb9342e8408b1ac25cb14

         1 | f8fd943012edfe42a03a421df660bc33

         2 | cd5d7ff0abca61f18857df9b21d234e0

         1 | 60d731f430cb68c7285ddbcd9186eaa0

         2 | 635e6c9cf305147ad8684213f0a9299c

(6 rows)

connection 1=> analyse verbose test_table ;

INFO:  analyzing "public.test_table"

INFO:  "test_table": scanned 1 of 1 pages, containing 6 live rows and 0 dead rows; 6 rows in sample, 6 estimated total rows

ANALYZE

connection 1=> explain analyse select * from test_table where school_id = 2 ;

                                             QUERY PLAN                                              

-----------------------------------------------------------------------------------------------------

 Seq Scan on test_table  (cost=0.00..1.07 rows=3 width=37) (actual time=0.011..0.015 rows=3 loops=1)

   Filter: (school_id = 2)

   Rows Removed by Filter: 3

 Planning time: 0.164 ms

 Execution time: 0.043 ms

(5 rows)

connection 2=> BEGIN ;

BEGIN

connection 2=> delete from test_table where school_id = 2 ;

DELETE 3

connection 2=> /* This connection is now idle */

connection 1=> analyse verbose test_table ;

INFO:  analyzing "public.test_table"

INFO:  "test_table": scanned 1 of 1 pages, containing 6 live rows and 0 dead rows; 3 rows in sample, 6 estimated total rows

ANALYZE

connection 1=> explain analyse select * from test_table where school_id = 2 ;

                                             QUERY PLAN                                              

-----------------------------------------------------------------------------------------------------

 Seq Scan on test_table  (cost=0.00..1.07 rows=1 width=37) (actual time=0.009..0.014 rows=3 loops=1)

   Filter: (school_id = 2)

   Rows Removed by Filter: 3

 Planning time: 0.095 ms

 Execution time: 0.039 ms

(5 rows)

On Wed, 2 Jan 2019 at 14:04 Ron <ronljohnsonjr@gmail.com> wrote:

But Jeff said "left open indefinitely without either committing or rolling back".  Your process is committing the transaction.

On 1/2/19 6:15 AM, Mark wrote:

Hi Jeff, 

Thanks for your help. That is exactly what is happening.

I have a long running job which deletes all of the common_student table and then repopulates it. It takes long time to load all the other data and commit the transaction. I didn't think the delete inside the transaction would have any effect until it is commited or rolled back.

I will have to rewrite the application so it updates the existing rows rather than deleting all and then inserting.

Thanks again for helping me understand what's happening here. 

Proof:

db=> explain analyze select * from common_student where school_id = 36;

                                                              QUERY PLAN                                                              

--------------------------------------------------------------------------------------------------------------------------------------

 Bitmap Heap Scan on common_student  (cost=88.30..3846.49 rows=1533 width=384) (actual time=4.852..7.065 rows=1388 loops=1)

   Recheck Cond: (school_id = 36)

   Heap Blocks: exact=67

   ->  Bitmap Index Scan on idx_common_student_sid  (cost=0.00..87.91 rows=1533 width=0) (actual time=4.817..4.817 rows=1388 loops=1)

         Index Cond: (school_id = 36)

 Planning time: 0.097 ms

 Execution time: 8.084 ms

(7 rows)

db=> /* At this point I have started a long running transaction that deletes all of common_student for school_id 36  */ ;

db=> analyse verbose common_student(school_id); 

INFO:  analyzing "public.common_student"

INFO:  "common_student": scanned 7322 of 7322 pages, containing 65431 live rows and 8060 dead rows; 56818 rows in sample, 65431 estimated total rows

ANALYZE

db=> explain analyze select * from common_student where school_id = 36;

                                                                 QUERY PLAN                                                                 

--------------------------------------------------------------------------------------------------------------------------------------------

 Index Scan using idx_common_student_sid on common_student  (cost=0.41..8.43 rows=1 width=384) (actual time=0.017..1.498 rows=1388 loops=1)

   Index Cond: (school_id = 36)

 Planning time: 0.098 ms

 Execution time: 2.583 ms

(4 rows)

db=> /* At this point I have killed the long running transaction that deletes all of common_student for school_id 36  */ ;

db=> vacuum analyze common_student; 

VACUUM

db=> explain analyze select * from common_student where school_id = 36;

                                                              QUERY PLAN                                                              

--------------------------------------------------------------------------------------------------------------------------------------

 Bitmap Heap Scan on common_student  (cost=79.17..3357.79 rows=1388 width=383) (actual time=0.088..1.302 rows=1388 loops=1)

   Recheck Cond: (school_id = 36)

   Heap Blocks: exact=67

   ->  Bitmap Index Scan on idx_common_student_sid  (cost=0.00..78.83 rows=1388 width=0) (actual time=0.077..0.077 rows=1388 loops=1)

         Index Cond: (school_id = 36)

 Planning time: 0.327 ms

 Execution time: 2.311 ms

(7 rows)

On Sun, 23 Dec 2018 at 02:57 Jeff Janes <jeff.janes@gmail.com> wrote:

- Does the analyse output below mean that it only scanned 51538 of 65463 rows in the table? Is school_id 36 just being missed in the sample? (This happens when the analyse is repeated )

Is there a transaction which had deleted all of school_id=36, and then was just left open indefinitely without either committing or rolling back?

That would explain it, and I don't know of anything else that could.  The deleted but not committed tuples are still live, but don't get sampled.

Cheers,

Jeff

--
Angular momentum makes the world go 'round.

Mark <mwchambers@gmail.com> writes:
> I have a long running job which deletes all of the common_student table and
> then repopulates it. It takes long time to load all the other data and
> commit the transaction. I didn't think the delete inside the transaction
> would have any effect until it is commited or rolled back.
> I will have to rewrite the application so it updates the existing rows
> rather than deleting all and then inserting.

Hmm ... I'm not sure if that will actually make things better.  The root
of the issue is what analyze.c does with DELETE_IN_PROGRESS tuples:

                     * We count delete-in-progress rows as still live, using
                     * the same reasoning given above; but we don't bother to
                     * include them in the sample.

The "reasoning given above" is a reference to what happens for
INSERT_IN_PROGRESS tuples:

                     * Insert-in-progress rows are not counted.  We assume
                     * that when the inserting transaction commits or aborts,
                     * it will send a stats message to increment the proper
                     * count.  This works right only if that transaction ends
                     * after we finish analyzing the table; if things happen
                     * in the other order, its stats update will be
                     * overwritten by ours.  However, the error will be large
                     * only if the other transaction runs long enough to
                     * insert many tuples, so assuming it will finish after us
                     * is the safer option.

Now the problem with this, from your perspective, is that *neither*
INSERT_IN_PROGRESS nor DELETE_IN_PROGRESS tuples are included in
ANALYZE's data sample.  So a long-running update transaction will
cause all the rows it changes to be excluded from the sample until
commit.  This seems like a bad thing, and it definitely means that
adjusting your app as you're contemplating won't help.

In order to handle the bulk-update scenario sanely, it seems like
we ought to allow one of INSERT_IN_PROGRESS and DELETE_IN_PROGRESS tuples
to be included.  And it looks like, for consistency with the row-counting
logic, the one that's included needs to be DELETE_IN_PROGRESS.  This
is a slightly annoying conclusion, because it means we're accumulating
stats that we know are likely to soon be obsolete, but I think sampling
INSERT_IN_PROGRESS tuples instead would lead to very strange results
in some cases.

In short, I think we want to do this to the DELETE_IN_PROGRESS logic:

                    if (TransactionIdIsCurrentTransactionId(HeapTupleHeaderGetUpdateXid(targtuple.t_data)))
                        deadrows += 1;
                    else
+                   {
+                       sample_it = true;
                        liverows += 1;
+                   }

with suitable adjustment of the adjacent comment.

Thoughts?

            regards, tom lane

Mark <mwchambers@gmail.com> writes:
> I have a long running job which deletes all of the common_student table and
> then repopulates it. It takes long time to load all the other data and
> commit the transaction. I didn't think the delete inside the transaction
> would have any effect until it is commited or rolled back.
> I will have to rewrite the application so it updates the existing rows
> rather than deleting all and then inserting.

Hmm ... I'm not sure if that will actually make things better.  The root
of the issue is what analyze.c does with DELETE_IN_PROGRESS tuples:

                     * We count delete-in-progress rows as still live, using
                     * the same reasoning given above; but we don't bother to
                     * include them in the sample.

The "reasoning given above" is a reference to what happens for
INSERT_IN_PROGRESS tuples:

                     * Insert-in-progress rows are not counted.  We assume
                     * that when the inserting transaction commits or aborts,
                     * it will send a stats message to increment the proper
                     * count.  This works right only if that transaction ends
                     * after we finish analyzing the table; if things happen
                     * in the other order, its stats update will be
                     * overwritten by ours.  However, the error will be large
                     * only if the other transaction runs long enough to
                     * insert many tuples, so assuming it will finish after us
                     * is the safer option.

Now the problem with this, from your perspective, is that *neither*
INSERT_IN_PROGRESS nor DELETE_IN_PROGRESS tuples are included in
ANALYZE's data sample.  So a long-running update transaction will
cause all the rows it changes to be excluded from the sample until
commit.  This seems like a bad thing, and it definitely means that
adjusting your app as you're contemplating won't help.

In order to handle the bulk-update scenario sanely, it seems like
we ought to allow one of INSERT_IN_PROGRESS and DELETE_IN_PROGRESS tuples
to be included.  And it looks like, for consistency with the row-counting
logic, the one that's included needs to be DELETE_IN_PROGRESS.  This
is a slightly annoying conclusion, because it means we're accumulating
stats that we know are likely to soon be obsolete, but I think sampling
INSERT_IN_PROGRESS tuples instead would lead to very strange results
in some cases.

In short, I think we want to do this to the DELETE_IN_PROGRESS logic:

                    if (TransactionIdIsCurrentTransactionId(HeapTupleHeaderGetUpdateXid(targtuple.t_data)))
                        deadrows += 1;
                    else
+                   {
+                       sample_it = true;
                        liverows += 1;
+                   }

with suitable adjustment of the adjacent comment.

Thoughts?

            regards, tom lane

Mark <mwchambers@gmail.com> writes:
> Am I correct in my understanding that any row that has been modified (i.e.
> UPDATE) is in state HEAPTUPLE_INSERT_IN_PROGRESS so it will not be included
> in the sample?

An update will mark the existing tuple as delete-in-progress and then
insert a new tuple (row version) that's insert-in-progress.

A concurrent ANALYZE scan will definitely see the old tuple (modulo
sampling considerations) but it's timing-dependent which state it sees it
in --- it could still be "live" when we see it, or already
delete-in-progress.  ANALYZE might or might not see the new tuple at all,
depending on timing and where the new tuple gets placed.  So "count/sample
delete-in-progress but not insert-in-progress" seems like a good rule to
minimize the timing sensitivity of the results.  It's not completely
bulletproof, but I think it's better than what we're doing now.

> I'm going to rework the application so there is less time between the
> DELETE and the COMMIT so I will only see the problem if ANALYZE runs during
> this smaller time window.

Yeah, that's about the best you can do from the application side.

            regards, tom lane

Mark <mwchambers@gmail.com> writes:
> Am I correct in my understanding that any row that has been modified (i.e.
> UPDATE) is in state HEAPTUPLE_INSERT_IN_PROGRESS so it will not be included
> in the sample?

An update will mark the existing tuple as delete-in-progress and then
insert a new tuple (row version) that's insert-in-progress.

A concurrent ANALYZE scan will definitely see the old tuple (modulo
sampling considerations) but it's timing-dependent which state it sees it
in --- it could still be "live" when we see it, or already
delete-in-progress.  ANALYZE might or might not see the new tuple at all,
depending on timing and where the new tuple gets placed.  So "count/sample
delete-in-progress but not insert-in-progress" seems like a good rule to
minimize the timing sensitivity of the results.  It's not completely
bulletproof, but I think it's better than what we're doing now.

> I'm going to rework the application so there is less time between the
> DELETE and the COMMIT so I will only see the problem if ANALYZE runs during
> this smaller time window.

Yeah, that's about the best you can do from the application side.

            regards, tom lane