Thread: plan not correct?

plan not correct?

From
Bert
Date:
Dear all,

I am not sure if I am looking at a bug, or I am just doing something wrong.
Anyhow, to me it seems that the plan for an upsert is wrong. (I can not find how many rows are inserted in the table)

Regard the following setup:
# select count(1) from dlp.st_itemseat;
 count
-------
     0
(1 row)

# select count(1) from loaddlp.st_itemseat_insert where loadtabletime = '2016-03-21 14:53:28.771467';
 count
-------
    12
(1 row)

# explain analyze <upsert query>*
                                                                       QUERY PLAN                                                                       
---------------------------------------------------------------------------------------------------------------------------------------------------------
 Insert on st_itemseat  (cost=26.14..41.39 rows=1 width=228) (actual time=1.282..1.282 rows=0 loops=1)
   CTE upsert
     ->  Update on st_itemseat et  (cost=0.15..26.11 rows=1 width=240) (actual time=0.066..0.066 rows=0 loops=1)
           ->  Nested Loop  (cost=0.15..26.11 rows=1 width=240) (actual time=0.061..0.061 rows=0 loops=1)
                 ->  Seq Scan on st_itemseat_insert st_itemseat_insert_1  (cost=0.00..13.75 rows=2 width=234) (actual time=0.031..0.040 rows=12 loops=1)
                       Filter: (loadtabletime = '2016-03-21 14:53:28.771467'::timestamp without time zone)
                       Rows Removed by Filter: 75
                 ->  Index Scan using pk_st_itemseat on st_itemseat et  (cost=0.15..6.17 rows=1 width=14) (actual time=0.001..0.001 rows=0 loops=12)
                       Index Cond: ((tick_server_id = st_itemseat_insert_1.tick_server_id) AND (itemseat_id = st_itemseat_insert_1.itemseat_id))
   ->  Seq Scan on st_itemseat_insert  (cost=0.02..15.27 rows=1 width=228) (actual time=0.175..0.201 rows=12 loops=1)
         Filter: ((loadtabletime = '2016-03-21 14:53:28.771467'::timestamp without time zone) AND (NOT (hashed SubPlan 2)))
         Rows Removed by Filter: 75
         SubPlan 2
           ->  CTE Scan on upsert  (cost=0.00..0.02 rows=1 width=8) (actual time=0.068..0.068 rows=0 loops=1)
 Planning time: 1.022 ms
 Execution time: 1.596 ms
(16 rows)


# <upsert query>*
INSERT 0 0

# select count(1) from dlp.st_itemseat;
 count
-------
    12
(1 row)

* the upsert query is added as an attachment to this mail.


In the query plan it seems that 0 rows are inserted; although 12 rows are inserted when we compare the 2 counts.
When an update happens, the rows reported in the 'update' statement are correct.

Is this a bug? Or am I looking at the wrong part of the plan? I would like to check how many rows are actually inserted from the plan.

wkr,
Bert

--
Bert Desmet
0477/305361
Attachment

Re: plan not correct?

From
Adrian Klaver
Date:
On 03/21/2016 07:03 AM, Bert wrote:
> Dear all,
>
> I am not sure if I am looking at a bug, or I am just doing something wrong.
> Anyhow, to me it seems that the plan for an upsert is wrong. (I can not
> find how many rows are inserted in the table)
>
> Regard the following setup:
> # select count(1) from dlp.st_itemseat;
>   count
> -------
>       0
> (1 row)
>
> # select count(1) from loaddlp.st_itemseat_insert where loadtabletime =
> '2016-03-21 14:53:28.771467';
>   count
> -------
>      12
> (1 row)
>
> # explain analyze <upsert query>*
>
> QUERY PLAN
>
---------------------------------------------------------------------------------------------------------------------------------------------------------
>   Insert on st_itemseat  (cost=26.14..41.39 rows=1 width=228) (actual
> time=1.282..1.282 rows=0 loops=1)
>     CTE upsert
>       ->  Update on st_itemseat et  (cost=0.15..26.11 rows=1 width=240)
> (actual time=0.066..0.066 rows=0 loops=1)
>             ->  Nested Loop  (cost=0.15..26.11 rows=1 width=240) (actual
> time=0.061..0.061 rows=0 loops=1)
>                   ->  Seq Scan on st_itemseat_insert
> st_itemseat_insert_1  (cost=0.00..13.75 rows=2 width=234) (actual
> time=0.031..0.040 rows=12 loops=1)
>                         Filter: (loadtabletime = '2016-03-21
> 14:53:28.771467'::timestamp without time zone)
>                         Rows Removed by Filter: 75
>                   ->  Index Scan using pk_st_itemseat on st_itemseat et
> (cost=0.15..6.17 rows=1 width=14) (actual time=0.001..0.001 rows=0 loops=12)
>                         Index Cond: ((tick_server_id =
> st_itemseat_insert_1.tick_server_id) AND (itemseat_id =
> st_itemseat_insert_1.itemseat_id))
>     ->  Seq Scan on st_itemseat_insert  (cost=0.02..15.27 rows=1
> width=228) (actual time=0.175..0.201 rows=12 loops=1)
>           Filter: ((loadtabletime = '2016-03-21
> 14:53:28.771467'::timestamp without time zone) AND (NOT (hashed SubPlan 2)))
>           Rows Removed by Filter: 75
>           SubPlan 2
>             ->  CTE Scan on upsert  (cost=0.00..0.02 rows=1 width=8)
> (actual time=0.068..0.068 rows=0 loops=1)
>   Planning time: 1.022 ms
>   Execution time: 1.596 ms
> (16 rows)
>
>
> # <upsert query>*
> INSERT 0 0
>
> # select count(1) from dlp.st_itemseat;
>   count
> -------
>      12
> (1 row)
>
> * the upsert query is added as an attachment to this mail.
>
>
> In the query plan it seems that 0 rows are inserted; although 12 rows
> are inserted when we compare the 2 counts.
> When an update happens, the rows reported in the 'update' statement are
> correct.

Do you get a row count or the rows?

The reason I ask is that in the UPDATE section you have '...returning 
ET.*', but not in the INSERT section.

Not sure if it matters in this case, but the Postgres version might 
provide context.

>
> Is this a bug? Or am I looking at the wrong part of the plan? I would
> like to check how many rows are actually inserted from the plan.
>
> wkr,
> Bert
>
> --
> Bert Desmet
> 0477/305361
>
>
>


-- 
Adrian Klaver
adrian.klaver@aklaver.com



Re: plan not correct?

From
Adrian Klaver
Date:
On 03/21/2016 08:29 AM, Bert wrote:

My mistake I Cced the wrong list.
> That is easy to check.
>
> Let's do the same test again:
> # select count(1) from dlp.st_itemseat;
>   count
> -------
>      12
> (1 row)
>
> # select count(1) from loaddlp.st_itemseat_insert;
>   count
> -------
>      87      --> of which 12 are already in the dlp.st_itemseat table
> (1 row)
>
> # explain analyze <upsert query>*
>                                                                             QUERY PLAN
>
-----------------------------------------------------------------------------------------------------------------------------------------------------------------
>   Insert on st_itemseat  (cost=55.47..69.97 rows=150 width=228) (actual
> time=2.345..2.345 rows=0 loops=1)
>     CTE upsert
>       ->  Update on st_itemseat et  (cost=17.50..55.42 rows=2 width=240)
> (actual time=0.493..0.545 rows=12 loops=1)
>             ->  Hash Join  (cost=17.50..55.42 rows=2 width=240) (actual
> time=0.303..0.318 rows=12 loops=1)
>                   Hash Cond: ((et.tick_server_id =
> st_itemseat_insert_1.tick_server_id) AND (et.itemseat_id =
> st_itemseat_insert_1.itemseat_id))
>                   ->  Seq Scan on st_itemseat et  (cost=0.00..13.10
> rows=310 width=14) (actual time=0.025..0.028 rows=12 loops=1)
>                   ->  Hash  (cost=13.00..13.00 rows=300 width=234)
> (actual time=0.244..0.244 rows=87 loops=1)
>                         Buckets: 1024  Batches: 1  Memory Usage: 13kB
>                         ->  Seq Scan on st_itemseat_insert
> st_itemseat_insert_1  (cost=0.00..13.00 rows=300 width=234) (actual
> time=0.005..0.120 rows=87 loops=1)
>     ->  Seq Scan on st_itemseat_insert  (cost=0.04..14.54 rows=150
> width=228) (actual time=0.637..0.726 rows=75 loops=1)
>           Filter: (NOT (hashed SubPlan 2))
>           Rows Removed by Filter: 12
>           SubPlan 2
>             ->  CTE Scan on upsert  (cost=0.00..0.04 rows=2 width=8)
> (actual time=0.498..0.561 rows=12 loops=1)
>   Planning time: 1.122 ms
>   Execution time: 2.682 ms
>
> # <upsert query>*
> INSERT 0 0
>
> # select count(1) from dlp.st_itemseat;
>   count
> -------
>      87
> (1 row)
>
>
> * the upsert query can be found attached to the first mail, but the
> difference is that the 'where loadtabletime' is removed
>
> As you can see the in the update part of the explain the 'rows' nr is
> 12. Which is what is expected.
> But the rows on the insert are again 0, while it should be 75.
>
> wkr,
> Bert
>
> On Mon, Mar 21, 2016 at 4:01 PM, Adrian Klaver
> <adrian.klaver@aklaver.com <mailto:adrian.klaver@aklaver.com>> wrote:
>
>     On 03/21/2016 07:54 AM, Bert wrote:
>
>     Ccing list
>
>         Hello Ardian,
>
>         The PostgreSQL version is 9.4.5
>
>         The reason I have the 'returning' statement in the update section is
>         because I only insert the data that has not been updated. I
>         don't see
>         why I would need to return anything in the insert section?
>
>
>     Well it was more about what you saw as the result of the UPDATE. It
>     is not clear to me whether that is 'UPDATE count' or the rows from
>     RETURNING?
>
>
>         On Mon, Mar 21, 2016 at 3:39 PM, Adrian Klaver
>         <adrian.klaver@aklaver.com <mailto:adrian.klaver@aklaver.com>
>         <mailto:adrian.klaver@aklaver.com
>         <mailto:adrian.klaver@aklaver.com>>> wrote:
>
>              On 03/21/2016 07:03 AM, Bert wrote:
>
>                  Dear all,
>
>                  I am not sure if I am looking at a bug, or I am just doing
>                  something wrong.
>                  Anyhow, to me it seems that the plan for an upsert is
>         wrong. (I
>                  can not
>                  find how many rows are inserted in the table)
>
>                  Regard the following setup:
>                  # select count(1) from dlp.st_itemseat;
>                     count
>                  -------
>                         0
>                  (1 row)
>
>                  # select count(1) from loaddlp.st_itemseat_insert where
>                  loadtabletime =
>                  '2016-03-21 14:53:28.771467';
>                     count
>                  -------
>                        12
>                  (1 row)
>
>                  # explain analyze <upsert query>*
>
>                  QUERY PLAN
>
>
---------------------------------------------------------------------------------------------------------------------------------------------------------
>                     Insert on st_itemseat  (cost=26.14..41.39 rows=1
>         width=228)
>                  (actual
>                  time=1.282..1.282 rows=0 loops=1)
>                       CTE upsert
>                         ->  Update on st_itemseat et  (cost=0.15..26.11
>         rows=1
>                  width=240)
>                  (actual time=0.066..0.066 rows=0 loops=1)
>                               ->  Nested Loop  (cost=0.15..26.11 rows=1
>                  width=240) (actual
>                  time=0.061..0.061 rows=0 loops=1)
>                                     ->  Seq Scan on st_itemseat_insert
>                  st_itemseat_insert_1  (cost=0.00..13.75 rows=2
>         width=234) (actual
>                  time=0.031..0.040 rows=12 loops=1)
>                                           Filter: (loadtabletime =
>         '2016-03-21
>                  14:53:28.771467'::timestamp without time zone)
>                                           Rows Removed by Filter: 75
>                                     ->  Index Scan using pk_st_itemseat on
>                  st_itemseat et
>                  (cost=0.15..6.17 rows=1 width=14) (actual time=0.001..0.001
>                  rows=0 loops=12)
>                                           Index Cond: ((tick_server_id =
>                  st_itemseat_insert_1.tick_server_id) AND (itemseat_id =
>                  st_itemseat_insert_1.itemseat_id))
>                       ->  Seq Scan on st_itemseat_insert
>         (cost=0.02..15.27 rows=1
>                  width=228) (actual time=0.175..0.201 rows=12 loops=1)
>                             Filter: ((loadtabletime = '2016-03-21
>                  14:53:28.771467'::timestamp without time zone) AND (NOT
>         (hashed
>                  SubPlan 2)))
>                             Rows Removed by Filter: 75
>                             SubPlan 2
>                               ->  CTE Scan on upsert  (cost=0.00..0.02
>         rows=1
>                  width=8)
>                  (actual time=0.068..0.068 rows=0 loops=1)
>                     Planning time: 1.022 ms
>                     Execution time: 1.596 ms
>                  (16 rows)
>
>
>                  # <upsert query>*
>                  INSERT 0 0
>
>                  # select count(1) from dlp.st_itemseat;
>                     count
>                  -------
>                        12
>                  (1 row)
>
>                  * the upsert query is added as an attachment to this mail.
>
>
>                  In the query plan it seems that 0 rows are inserted;
>         although 12
>                  rows
>                  are inserted when we compare the 2 counts.
>                  When an update happens, the rows reported in the 'update'
>                  statement are
>                  correct.
>
>
>              Do you get a row count or the rows?
>
>              The reason I ask is that in the UPDATE section you have
>              '...returning ET.*', but not in the INSERT section.
>
>              Not sure if it matters in this case, but the Postgres
>         version might
>              provide context.
>
>
>
>                  Is this a bug? Or am I looking at the wrong part of the
>         plan? I
>                  would
>                  like to check how many rows are actually inserted from
>         the plan.
>
>                  wkr,
>                  Bert
>
>                  --
>                  Bert Desmet
>         0477/305361 <tel:0477%2F305361> <tel:0477%2F305361>
>
>
>
>
>
>              --
>              Adrian Klaver
>         adrian.klaver@aklaver.com <mailto:adrian.klaver@aklaver.com>
>         <mailto:adrian.klaver@aklaver.com
>         <mailto:adrian.klaver@aklaver.com>>
>
>
>
>
>         --
>         Bert Desmet
>         0477/305361 <tel:0477%2F305361>
>
>
>
>     --
>     Adrian Klaver
>     adrian.klaver@aklaver.com <mailto:adrian.klaver@aklaver.com>
>
>
>
>
> --
> Bert Desmet
> 0477/305361


-- 
Adrian Klaver
adrian.klaver@aklaver.com



Re: plan not correct?

From
Adrian Klaver
Date:
On 03/21/2016 08:29 AM, Bert wrote:
> That is easy to check.
>
> Let's do the same test again:
> # select count(1) from dlp.st_itemseat;
>   count
> -------
>      12
> (1 row)
>
> # select count(1) from loaddlp.st_itemseat_insert;
>   count
> -------
>      87      --> of which 12 are already in the dlp.st_itemseat table
> (1 row)
>
> # explain analyze <upsert query>*
>                                                                             QUERY PLAN
>
-----------------------------------------------------------------------------------------------------------------------------------------------------------------
>   Insert on st_itemseat  (cost=55.47..69.97 rows=150 width=228) (actual
> time=2.345..2.345 rows=0 loops=1)
>     CTE upsert
>       ->  Update on st_itemseat et  (cost=17.50..55.42 rows=2 width=240)
> (actual time=0.493..0.545 rows=12 loops=1)
>             ->  Hash Join  (cost=17.50..55.42 rows=2 width=240) (actual
> time=0.303..0.318 rows=12 loops=1)
>                   Hash Cond: ((et.tick_server_id =
> st_itemseat_insert_1.tick_server_id) AND (et.itemseat_id =
> st_itemseat_insert_1.itemseat_id))
>                   ->  Seq Scan on st_itemseat et  (cost=0.00..13.10
> rows=310 width=14) (actual time=0.025..0.028 rows=12 loops=1)
>                   ->  Hash  (cost=13.00..13.00 rows=300 width=234)
> (actual time=0.244..0.244 rows=87 loops=1)
>                         Buckets: 1024  Batches: 1  Memory Usage: 13kB
>                         ->  Seq Scan on st_itemseat_insert
> st_itemseat_insert_1  (cost=0.00..13.00 rows=300 width=234) (actual
> time=0.005..0.120 rows=87 loops=1)
>     ->  Seq Scan on st_itemseat_insert  (cost=0.04..14.54 rows=150
> width=228) (actual time=0.637..0.726 rows=75 loops=1)
>           Filter: (NOT (hashed SubPlan 2))
>           Rows Removed by Filter: 12
>           SubPlan 2
>             ->  CTE Scan on upsert  (cost=0.00..0.04 rows=2 width=8)
> (actual time=0.498..0.561 rows=12 loops=1)
>   Planning time: 1.122 ms
>   Execution time: 2.682 ms
>
> # <upsert query>*
> INSERT 0 0
>
> # select count(1) from dlp.st_itemseat;
>   count
> -------
>      87
> (1 row)
>
>
> * the upsert query can be found attached to the first mail, but the
> difference is that the 'where loadtabletime' is removed
>
> As you can see the in the update part of the explain the 'rows' nr is
> 12. Which is what is expected.
> But the rows on the insert are again 0, while it should be 75.

They are seen, including the 12 rows that are filtered out for updating:

" ->  Seq Scan on st_itemseat_insert  (cost=0.04..14.54 rows=150 
width=228) (actual time=0.637..0.726 rows=75 loops=1)         Filter: (NOT (hashed SubPlan 2))         Rows Removed by
Filter:12         SubPlan 2
 
"

I do not know why that value is not propagated up to 'Insert on 
st_itemseat ...'.

>
> wkr,
> Bert
>



-- 
Adrian Klaver
adrian.klaver@aklaver.com