Order by (for 15 rows) adds 30 seconds to query time

Dear All,

I don't know if this is a stupid question, or not, but I can't
understand the following.

I have a pretty simple query, which runs in about 7ms

SELECT * FROM h.inventory WHERE demand_id =289276563;

The result of this is a 15 row x 17 column table. However, I want this
to be sorted by id, so I changed the query to:

SELECT * FROM h.inventory WHERE demand_id =289276563 ORDER BY id;

which makes it take 32 seconds!

That surprises me - I'd expect the ORDER BY to be the last thing that
runs, and for a sort of such a small dataset to be almost
instantaneous. Indeed, if I do ORDER BY random(), then it's fast.

The system is running 8.4.1, and is otherwise lightly loaded, I can do
this repeatedly with similar results.

Is this normal? Have I hit a bug?

I attach the view definition, the result set, and the output from
explain analyze (both ways).

Thanks,

Richard

View "h.inventory"
Column | Type | Modifiers
---------------+--------------------------+-----------
id | bigint |
material_id | bigint |
material_tag | text |
material_name | text |
location_id | bigint |
location_tag | text |
location_name | text |
qty | integer |
divergence | integer |
ctime | timestamp with time zone |
actor_id | bigint |
actor_tag | text |
actor_name | text |
demand_id | bigint |
target_id | bigint |
target_tag | text |
target_name | text |
View definition:
SELECT inventory.id, inventory.material_id, h_material.tag AS
material_tag, h_material.name AS material_name, inventory.location_id,
h_location.tag AS location_tag, h_location.name AS location_name,
inventory.qty, inventory.divergence, inventory.ctime,
inventory.actor_id, h_actor.tag AS actor_tag, h_actor.name AS
actor_name, inventory.demand_id, h_demand.target_id,
h_demand.target_tag, h_demand.target_name
FROM core.inventory
LEFT JOIN h.material h_material ON inventory.material_id = h_material.id
LEFT JOIN h.location h_location ON inventory.location_id = h_location.id
LEFT JOIN h.actor h_actor ON inventory.actor_id = h_actor.id
LEFT JOIN h.demand h_demand ON inventory.demand_id = h_demand.id;

id | material_id | material_tag | material_name | location_id
| location_tag | location_name | qty | divergence |
ctime | actor_id | actor_tag | actor_name
| demand_id | target_id | target_tag | target_name
-----------+-------------+---------------+---------------+-------------+--------------+------------------------+-----+------------+-------------------------------+----------+-----------+------------------------------+-----------+-----------+----------------+----------------------------------------
292904293 | 289238938 | 1000001113980 | | 280410977
| 1030576 | Container 1030576 | 0 | 0 | 2009-12-01
14:53:35.010023+00 | 5543 | 139664 | Joanna Mikolajczak
| 289276563 | 3153 | 300244 EMBARGO | 300244 308/09 HAYWARDS
HEATH / EMBARGO
292904294 | 289238938 | 1000001113980 | | 280410977
| 1030576 | Container 1030576 | 1 | 0 | 2009-12-01
14:53:35.060378+00 | | |
| 289276563 | 3153 | 300244 EMBARGO | 300244 308/09 HAYWARDS
HEATH / EMBARGO
292904292 | 289238938 | 1000001113980 | | 4008
| 308 | Chute 308 | 0 | 0 | 2009-12-01
14:53:34.925801+00 | 5543 | 139664 | Joanna Mikolajczak
| 289276563 | 3153 | 300244 EMBARGO | 300244 308/09 HAYWARDS
HEATH / EMBARGO
292817907 | 289238938 | 1000001113980 | | 5137
| 991 | Chute 991 (not needed) | 0 | 0 | 2009-12-01
14:38:00.819189+00 | 6282 | CW 991 | Chute 991 worker
| 289276563 | 3153 | 300244 EMBARGO | 300244 308/09 HAYWARDS
HEATH / EMBARGO
291755251 | 289238938 | 1000001113980 | | 5137
| 991 | Chute 991 (not needed) | 0 | 0 | 2009-12-01
12:03:05.957424+00 | 6282 | CW 991 | Chute 991 worker
| 289276563 | 3153 | 300244 EMBARGO | 300244 308/09 HAYWARDS
HEATH / EMBARGO
291543235 | 289238938 | 1000001113980 | | 5137
| 991 | Chute 991 (not needed) | 0 | 0 | 2009-12-01
11:35:19.28846+00 | 6282 | CW 991 | Chute 991 worker
| 289276563 | 3153 | 300244 EMBARGO | 300244 308/09 HAYWARDS
HEATH / EMBARGO
291524046 | 289238938 | 1000001113980 | | 4008
| 308 | Chute 308 | 0 | 0 | 2009-12-01
11:31:49.40378+00 | | |
| 289276563 | 3153 | 300244 EMBARGO | 300244 308/09 HAYWARDS
HEATH / EMBARGO
291524045 | 289238938 | 1000001113980 | | 4008
| 308 | Chute 308 | 0 | 0 | 2009-12-01
11:31:49.402217+00 | 6300 | FSC | Flow System Controller (FSC)
| 289276563 | 3153 | 300244 EMBARGO | 300244 308/09 HAYWARDS HEATH
/ EMBARGO
291522067 | 289238938 | 1000001113980 | | 5143
| CAM2 | North Camera | 0 | 0 | 2009-12-01
11:31:22.931085+00 | 6300 | FSC | Flow System Controller (FSC)
| 289276563 | 3153 | 300244 EMBARGO | 300244 308/09 HAYWARDS HEATH
/ EMBARGO
291518675 | 289238938 | 1000001113980 | | 5137
| 991 | Chute 991 (not needed) | 0 | 0 | 2009-12-01
11:30:32.10016+00 | 6282 | CW 991 | Chute 991 worker
| 289276563 | 3153 | 300244 EMBARGO | 300244 308/09 HAYWARDS
HEATH / EMBARGO
291506067 | 289238938 | 1000001113980 | | 5137
| 991 | Chute 991 (not needed) | 0 | 0 | 2009-12-01
11:26:38.065565+00 | 6282 | CW 991 | Chute 991 worker
| 289276563 | 3153 | 300244 EMBARGO | 300244 308/09 HAYWARDS
HEATH / EMBARGO
291491123 | 289238938 | 1000001113980 | | 5137
| 991 | Chute 991 (not needed) | 0 | 0 | 2009-12-01
11:21:33.009506+00 | 6282 | CW 991 | Chute 991 worker
| 289276563 | 3153 | 300244 EMBARGO | 300244 308/09 HAYWARDS
HEATH / EMBARGO
291322415 | 289238938 | 1000001113980 | | 4008
| 308 | Chute 308 | 0 | 0 | 2009-12-01
10:45:08.281846+00 | | |
| 289276563 | 3153 | 300244 EMBARGO | 300244 308/09 HAYWARDS
HEATH / EMBARGO
291322414 | 289238938 | 1000001113980 | | 4008
| 308 | Chute 308 | 0 | 0 | 2009-12-01
10:45:08.280018+00 | 6300 | FSC | Flow System Controller (FSC)
| 289276563 | 3153 | 300244 EMBARGO | 300244 308/09 HAYWARDS HEATH
/ EMBARGO
291319302 | 289238938 | 1000001113980 | | 5143
| CAM2 | North Camera | 0 | 0 | 2009-12-01
10:44:41.807128+00 | 6300 | FSC | Flow System Controller (FSC)
| 289276563 | 3153 | 300244 EMBARGO | 300244 308/09 HAYWARDS HEATH
/ EMBARGO
(15 rows)

explain analyze select * from h.inventory where demand_id =289276563;
Time: 7.251 ms

QUERY PLAN
-----------------------------------------------------------------------------------------------------------------------------------------------------------------
Nested Loop Left Join (cost=0.00..726857452.94 rows=806903677108
width=195) (actual time=0.108..0.704 rows=15 loops=1)
Join Filter: (core.inventory.material_id = core.material.id)
-> Nested Loop Left Join (cost=0.00..183236.84 rows=203176856
width=166) (actual time=0.103..0.588 rows=15 loops=1)
Join Filter: (demand.material_id = core.material.id)
-> Nested Loop Left Join (cost=0.00..260.03 rows=51160
width=174) (actual time=0.090..0.462 rows=15 loops=1)
Join Filter: (core.inventory.location_id = core.location.id)
-> Nested Loop Left Join (cost=0.00..146.71 rows=28
width=128) (actual time=0.068..0.286 rows=15 loops=1)
-> Nested Loop Left Join (cost=0.00..125.36
rows=28 width=103) (actual time=0.058..0.225 rows=15 loops=1)
Join Filter: (core.inventory.demand_id =
demand.id)
-> Index Scan using inventory_demand_id on
inventory (cost=0.00..22.36 rows=28 width=56) (actual time=0.025..0.053
rows=15 loops=1)
Index Cond: (demand_id = 289276563)
-> Nested Loop Left Join (cost=0.00..3.67
rows=1 width=55) (actual time=0.009..0.010 rows=1 loops=15)
-> Index Scan using demand_pkey on
demand (cost=0.00..1.89 rows=1 width=24) (actual time=0.005..0.005
rows=1 loops=15)
Index Cond: (id = 289276563)
-> Index Scan using waypoint_pkey on
waypoint (cost=0.00..1.77 rows=1 width=39) (actual time=0.003..0.003
rows=1 loops=15)
Index Cond: (demand.target_id =
waypoint.id)
-> Index Scan using actor_pkey on actor
(cost=0.00..0.75 rows=1 width=33) (actual time=0.003..0.003 rows=1 loops=15)
Index Cond: (core.inventory.actor_id = actor.id)
-> Append (cost=0.00..4.00 rows=4 width=50) (actual
time=0.005..0.010 rows=1 loops=15)
-> Index Scan using location_pkey on location
(cost=0.00..0.56 rows=1 width=72) (actual time=0.001..0.001 rows=0 loops=15)
Index Cond: (core.inventory.location_id =
core.location.id)
-> Index Scan using waypoint_pkey on waypoint
location (cost=0.00..1.31 rows=1 width=39) (actual time=0.003..0.003
rows=1 loops=15)
Index Cond: (core.inventory.location_id =
core.location.id)
-> Index Scan using container_pkey on container
location (cost=0.00..1.78 rows=1 width=54) (actual time=0.004..0.004
rows=0 loops=15)
Index Cond: (core.inventory.location_id =
core.location.id)
-> Index Scan using supply_pkey on supply
location (cost=0.00..0.35 rows=1 width=36) (actual time=0.001..0.001
rows=0 loops=15)
Index Cond: (core.inventory.location_id =
core.location.id)
-> Append (cost=0.00..3.55 rows=2 width=8) (actual
time=0.004..0.007 rows=1 loops=15)
-> Index Scan using material_pkey on material
(cost=0.00..1.78 rows=1 width=8) (actual time=0.004..0.005 rows=1 loops=15)
Index Cond: (demand.material_id = core.material.id)
-> Index Scan using container_pkey on container
material (cost=0.00..1.78 rows=1 width=8) (actual time=0.002..0.002
rows=0 loops=15)
Index Cond: (demand.material_id = core.material.id)
-> Append (cost=0.00..3.55 rows=2 width=38) (actual
time=0.003..0.006 rows=1 loops=15)
-> Index Scan using material_pkey on material
(cost=0.00..1.78 rows=1 width=22) (actual time=0.003..0.003 rows=1 loops=15)
Index Cond: (core.inventory.material_id = core.material.id)
-> Index Scan using container_pkey on container material
(cost=0.00..1.78 rows=1 width=54) (actual time=0.003..0.003 rows=0 loops=15)
Index Cond: (core.inventory.material_id = core.material.id)
Total runtime: 0.858 ms
(38 rows)

explain analyze select * from h.inventory where demand_id =289276563
order by id;
Time: 32868.784 ms

QUERY PLAN
------------------------------------------------------------------------------------------------------------------------------------------------------------------------
Nested Loop Left Join (cost=0.00..727737158.77 rows=806903677108
width=195) (actual time=31739.052..32862.322 rows=15 loops=1)
Join Filter: (core.inventory.material_id = core.material.id)
-> Nested Loop Left Join (cost=0.00..1062942.67 rows=203176856
width=166) (actual time=31739.044..32862.084 rows=15 loops=1)
Join Filter: (demand.material_id = core.material.id)
-> Nested Loop Left Join (cost=0.00..879965.86 rows=51160
width=174) (actual time=31739.025..32861.812 rows=15 loops=1)
Join Filter: (core.inventory.location_id = core.location.id)
-> Nested Loop Left Join (cost=0.00..879852.54 rows=28
width=128) (actual time=31739.006..32861.428 rows=15 loops=1)
-> Nested Loop Left Join (cost=0.00..879831.20
rows=28 width=103) (actual time=31738.994..32861.276 rows=15 loops=1)
Join Filter: (core.inventory.demand_id =
demand.id)
-> Index Scan using inventory_pkey on
inventory (cost=0.00..879728.20 rows=28 width=56) (actual
time=31738.956..32860.738 rows=15 loops=1)
Filter: (demand_id = 289276563)
-> Nested Loop Left Join (cost=0.00..3.67
rows=1 width=55) (actual time=0.030..0.031 rows=1 loops=15)
-> Index Scan using demand_pkey on
demand (cost=0.00..1.89 rows=1 width=24) (actual time=0.019..0.019
rows=1 loops=15)
Index Cond: (id = 289276563)
-> Index Scan using waypoint_pkey on
waypoint (cost=0.00..1.77 rows=1 width=39) (actual time=0.008..0.008
rows=1 loops=15)
Index Cond: (demand.target_id =
waypoint.id)
-> Index Scan using actor_pkey on actor
(cost=0.00..0.75 rows=1 width=33) (actual time=0.007..0.007 rows=1 loops=15)
Index Cond: (core.inventory.actor_id = actor.id)
-> Append (cost=0.00..4.00 rows=4 width=50) (actual
time=0.010..0.019 rows=1 loops=15)
-> Index Scan using location_pkey on location
(cost=0.00..0.56 rows=1 width=72) (actual time=0.003..0.003 rows=0 loops=15)
Index Cond: (core.inventory.location_id =
core.location.id)
-> Index Scan using waypoint_pkey on waypoint
location (cost=0.00..1.31 rows=1 width=39) (actual time=0.006..0.006
rows=1 loops=15)
Index Cond: (core.inventory.location_id =
core.location.id)
-> Index Scan using container_pkey on container
location (cost=0.00..1.78 rows=1 width=54) (actual time=0.006..0.006
rows=0 loops=15)
Index Cond: (core.inventory.location_id =
core.location.id)
-> Index Scan using supply_pkey on supply
location (cost=0.00..0.35 rows=1 width=36) (actual time=0.003..0.003
rows=0 loops=15)
Index Cond: (core.inventory.location_id =
core.location.id)
-> Append (cost=0.00..3.55 rows=2 width=8) (actual
time=0.011..0.014 rows=1 loops=15)
-> Index Scan using material_pkey on material
(cost=0.00..1.78 rows=1 width=8) (actual time=0.010..0.011 rows=1 loops=15)
Index Cond: (demand.material_id = core.material.id)
-> Index Scan using container_pkey on container
material (cost=0.00..1.78 rows=1 width=8) (actual time=0.002..0.002
rows=0 loops=15)
Index Cond: (demand.material_id = core.material.id)
-> Append (cost=0.00..3.55 rows=2 width=38) (actual
time=0.004..0.012 rows=1 loops=15)
-> Index Scan using material_pkey on material
(cost=0.00..1.78 rows=1 width=22) (actual time=0.003..0.004 rows=1 loops=15)
Index Cond: (core.inventory.material_id = core.material.id)
-> Index Scan using container_pkey on container material
(cost=0.00..1.78 rows=1 width=54) (actual time=0.008..0.008 rows=0 loops=15)
Index Cond: (core.inventory.material_id = core.material.id)
Total runtime: 32862.509 ms
(38 rows)