Thread: plan not correct?
Dear all,
I am not sure if I am looking at a bug, or I am just doing something wrong. # select count(1) from dlp.st_itemseat;
count
-------
0
(1 row)
count
-------
12
(1 row)
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)
# select count(1) from dlp.st_itemseat;
count
-------
12
(1 row)
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
0477/305361
Attachment
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
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
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