Waldomiro | 1 Dec 2009 02:02
Picon

Server Freezing

Hi everybody,

I have an java application like this:

while ( true ) {
     Thread.sleep( 1000 ) // sleeps 1 second

      SELECT field1
      FROM TABLE1
      WHERE field2 = '10'

      if ( field1 != null ) {
          BEGIN;

          processSomething( field1 );

          UPDATE TABLE1
          SET field2 = '20'
          WHERE field1 = '10';

          COMMIT;
     }
}

This is a simple program which is waiting for a record inserted by 
another workstation, after I process that record I update to an 
processed status.

That table receives about 3000 inserts and 60000 updates each day, but 
at night I do a TRUNCATE TABLE1 (Every Night), so the table is very 
(Continue reading)

Greg Smith | 1 Dec 2009 01:08
Favicon

Re: Server Freezing

Waldomiro wrote:
> Is It possible the checkpoint is doing that? Or the archiving? How can 
> I see?
If you're using PostgreSQL 8.3 or later, you can turn on log_checkpoints 
and you'll get a note when each checkpoint finishes.  The parts that are 
more likely to slow the server down are right at the end, so if you see 
a bunch of slow queries around the same time as the checkpoint message 
appears in the logs, that's the likely cause.  Bad checkpoint behavior 
can certainly cause several seconds of freezing on a system with 32GB of 
RAM, because with that much data you can have quite a bit in the OS 
write cache that all gets forced out at the end of the checkpoint.

Finding when the checkpoints happen on 8.2 or earlier is much harder; I 
can tell you what to look for on Linux for example, but it's kind of 
painful to track them down.

-- 
Greg Smith    2ndQuadrant   Baltimore, MD
PostgreSQL Training, Services and Support
greg <at> 2ndQuadrant.com  www.2ndQuadrant.com

--

-- 
Sent via pgsql-performance mailing list (pgsql-performance <at> postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-performance

Waldomiro | 1 Dec 2009 12:02
Picon

Re: Server Freezing

I´m using PostgreSQL 8.1. There is a way to see that?

Waldomiro

Greg Smith escreveu:
> Waldomiro wrote:
>> Is It possible the checkpoint is doing that? Or the archiving? How 
>> can I see?
> If you're using PostgreSQL 8.3 or later, you can turn on 
> log_checkpoints and you'll get a note when each checkpoint finishes.  
> The parts that are more likely to slow the server down are right at 
> the end, so if you see a bunch of slow queries around the same time as 
> the checkpoint message appears in the logs, that's the likely cause.  
> Bad checkpoint behavior can certainly cause several seconds of 
> freezing on a system with 32GB of RAM, because with that much data you 
> can have quite a bit in the OS write cache that all gets forced out at 
> the end of the checkpoint.
>
> Finding when the checkpoints happen on 8.2 or earlier is much harder; 
> I can tell you what to look for on Linux for example, but it's kind of 
> painful to track them down.
>

--

-- 
Sent via pgsql-performance mailing list (pgsql-performance <at> postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-performance

Waldomiro | 1 Dec 2009 12:18
Picon

Re: Server Freezing

I´m using PostgreSQL 8.1, and my settings are:

checkpoint_segments=50
checkpoint_timeout=300
checkpoint_warning=30
commit_delay=0
commit_siblings=5
archive_command= cp -i %p/BACKUP/LOGS/%f
autovacuum=off
bgwriter_all_maxpages=5
bgwriter_all_percent=0.333
bgwriter_delay=200
bgwriter_lru_maxpages=5
bgwriter_lru_percent=1
fsync=on
full_page_writes=on
stats_block_level=on
stats_command_string=on
stats_reset_on_server_start=off
stats_row_level=on
stats_start_collector=on

Waldomiro

Fernando Hevia escreveu:
-----Mensaje original----- De: pgsql-performance-owner <at> postgresql.org [mailto:pgsql-performance-owner <at> postgresql.org] En nombre de Waldomiro Enviado el: Lunes, 30 de Noviembre de 2009 22:03 Para: pgsql-performance <at> postgresql.org Asunto: [PERFORM] Server Freezing Hi everybody, ... That table receives about 3000 inserts and 60000 updates each day, but at night I do a TRUNCATE TABLE1 (Every Night), so the table is very small. There is an index by field1 too. Some days It works very good all day, but somedays I have 7 seconds freeze, I mean, my serves delays 7 seconds on this statement: SELECT field1 FROM TABLE1 WHERE field2 = '10'
Hi. You should probably consider creating a partial index on field2 = '10'.
I looked up to the statistics for that table, but the statistics says that postgres is reading memory, not disk, becouse the table is very small and I do a select every second, so the postgres keeps the table in shared buffers.
You say you dont vacuum this table, but considering 60000 updates on 3000 records, assuming you are updating each record 20 times, your table could eat up the space of 60M records. ¿Have you considered this? Though, I am not sure how this impacts when the whole table is held in shared buffers.
Why this 7 seconds delay? How could I figure out what is happening?
Turn log_checkpoints = on to see in the logs if these occur during the freeze. Also log_lock_waits = on will help diagnose the situation. What version of postgres are you running and how are your checkpoints configured? Regards, Fernando.


--
Waldomiro Caraiani Neto
|||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
GRUPO SHX

Desenvolvimento
+ 55 (16) 3331.3268
waldomiro <at> shx.com.br
www.shx.com.br
Fernando Hevia | 1 Dec 2009 16:50
Picon

Re: Server Freezing


> -----Mensaje original-----
> De: Waldomiro
> 
> I´m using PostgreSQL 8.1, 

Sorry, log_checkpoints isn't supported till 8.3

> and my settings are:
> 
> checkpoint_segments=50
> checkpoint_timeout=300
> checkpoint_warning=30
> commit_delay=0
> commit_siblings=5
> archive_command= cp -i %p/BACKUP/LOGS/%f autovacuum=off
> bgwriter_all_maxpages=5
> bgwriter_all_percent=0.333
> bgwriter_delay=200
> bgwriter_lru_maxpages=5
> bgwriter_lru_percent=1
> fsync=on
> full_page_writes=on
> stats_block_level=on
> stats_command_string=on
> stats_reset_on_server_start=off
> stats_row_level=on
> stats_start_collector=on
> 

As tempting as it is to decrease checkpoint_segments, better confirm it is a
checkpoint related problem before fiddling with these settings.

I recommend reading Greg Smith's post on checkpoints & bg writer. It's about
8.3 improvements but it includes good advice on how to diagnose checkpoint
issues on prior versions:
http://www.westnet.com/~gsmith/content/postgresql/chkp-bgw-83.htm

In fact, one of his recomendations should be very helpful here: set
checkpoint_warning=3600 and log_min_duration_statement=1000, that way you
should see in the log if statements over 1 sec occur simultaneously with
checkpoints being reached.

Pay attention to the chapter on the bg_writer too.

Regards,
Fernando.

--

-- 
Sent via pgsql-performance mailing list (pgsql-performance <at> postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-performance

Richard Neill | 1 Dec 2009 19:52
Picon
Picon
Favicon

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)

--

-- 
Sent via pgsql-performance mailing list (pgsql-performance <at> postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-performance

Kevin Grittner | 1 Dec 2009 21:06
Favicon

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

Richard Neill <rn214 <at> cam.ac.uk> wrote:

> I'd expect the ORDER BY to be the last thing that runs

>   Nested Loop Left Join  (cost=0.00..727737158.77
> rows=806903677108 width=195) (actual time=31739.052..32862.322
> rows=15 loops=1)

It probably would if it knew there were going to be 15 rows to sort.
It is estimating that there will be 806,903,677,108 rows, in which
case it thinks that using the index will be faster.  The question is
why it's 10 or 11 orders of magnitude off on the estimate of result
rows.  Could you show us the table definitions underlying that view?

-Kevin

--

-- 
Sent via pgsql-performance mailing list (pgsql-performance <at> postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-performance

Jean-Michel Pouré | 1 Dec 2009 21:06
Picon
Favicon

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

Le mardi 01 décembre 2009 à 18:52 +0000, Richard Neill a écrit :
> Is this normal? Have I hit a bug?

PostgreSQL query analyzer needs to run a couple of times before it can
rewrite and optimize the query. Make sure demand_id, id and join IDs
carry indexes.

Run EXPLAIN ANALYSE your_query to understand how the parser works and
post it back here.

Kind regards,
Jean-Michel
Richard Neill | 1 Dec 2009 23:46
Picon
Picon
Favicon

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


Jean-Michel Pouré wrote:
> Le mardi 01 décembre 2009 à 18:52 +0000, Richard Neill a écrit :
>> Is this normal? Have I hit a bug?
> 
> PostgreSQL query analyzer needs to run a couple of times before it can
> rewrite and optimize the query. Make sure demand_id, id and join IDs
> carry indexes.
> 

I did, and they do. This table has been in place for ages, with 
autovacuum on, and a manual vacuum analyze every night. I checked by 
running analyze explicitly on all the relevant tables just before 
posting this.

> Run EXPLAIN ANALYSE your_query to understand how the parser works and
> post it back here.
> 

Already in previous email :-)

> Kind regards,
> Jean-Michel

Kevin Grittner wrote:
 > Richard Neill <rn214 <at> cam.ac.uk> wrote:
 >
 >> I'd expect the ORDER BY to be the last thing that runs
 >
 >>   Nested Loop Left Join  (cost=0.00..727737158.77
 >> rows=806903677108 width=195) (actual time=31739.052..32862.322
 >> rows=15 loops=1)
 >
 > It probably would if it knew there were going to be 15 rows to sort.
 > It is estimating that there will be 806,903,677,108 rows, in which
 > case it thinks that using the index will be faster.  The question is
 > why it's 10 or 11 orders of magnitude off on the estimate of result
 > rows.  Could you show us the table definitions underlying that view?
 >
 > -Kevin
 >

Am I wrong in thinking that ORDER BY is always applied after the main 
query is run?

Even if I run it this way:

select * from (select * from h.inventory where demand_id =289276563) as 
sqry order by id;

which should(?) surely force it to run the first select, then sort, it's 
still very slow. On the other hand, it's quick if I do order by id+1

The table definitions are as follows (sorry there are so many).

Richard

fswcs=# \d h.demand
            View "h.demand"
     Column     |  Type   | Modifiers
---------------+---------+-----------
  id            | bigint  |
  target_id     | bigint  |
  target_tag    | text    |
  target_name   | text    |
  material_id   | bigint  |
  material_tag  | text    |
  material_name | text    |
  qty           | integer |
  benefit       | integer |
View definition:
  SELECT demand.id, demand.target_id, h_target_waypoint.tag AS 
target_tag, h_target_waypoint.name AS target_name, demand.material_id, 
h_material.tag AS material_tag, h_material.name AS material_name, 
demand.qty, demand.benefit
    FROM core.demand
    LEFT JOIN h.waypoint h_target_waypoint ON demand.target_id = 
h_target_waypoint.id
    LEFT JOIN h.material h_material ON demand.material_id = h_material.id;

fswcs=# \d core.demand
                   Table "core.demand"
    Column    |  Type   |           Modifiers
-------------+---------+--------------------------------
  id          | bigint  | not null default core.new_id()
  target_id   | bigint  | not null
  material_id | bigint  | not null
  qty         | integer | not null
  benefit     | integer | not null default 0
Indexes:
     "demand_pkey" PRIMARY KEY, btree (id) CLUSTER
     "demand_target_id_key" UNIQUE, btree (target_id, material_id)
     "demand_material_id" btree (material_id)
     "demand_target_id" btree (target_id)
Foreign-key constraints:
     "demand_material_id_fkey" FOREIGN KEY (material_id) REFERENCES 
core.__material_id(id)
     "demand_target_id_fkey" FOREIGN KEY (target_id) REFERENCES 
core.waypoint(id)
Referenced by:
     TABLE "viwcs.du_report_contents" CONSTRAINT 
"du_report_contents_demand_id_fkey" FOREIGN KEY (demand_id) REFERENCES 
core.demand(id)
     TABLE "core.inventory" CONSTRAINT "inventory_demand_id_fkey" 
FOREIGN KEY (demand_id) REFERENCES core.demand(id)
     TABLE "viwcs.wave_demand" CONSTRAINT "wave_demand_demand_id_fkey" 
FOREIGN KEY (demand_id) REFERENCES core.demand(id)

fswcs=# \d h.waypoint
         View "h.waypoint"
   Column   |  Type   | Modifiers
-----------+---------+-----------
  id        | bigint  |
  tag       | text    |
  name      | text    |
  is_router | boolean |
  is_target | boolean |
  is_packer | boolean |
View definition:
  SELECT waypoint.id, waypoint.tag, waypoint.name, waypoint.is_router, 
waypoint.is_target, waypoint.is_packer
    FROM core.waypoint;

fswcs=# \d h.material
       View "h.material"
  Column |  Type   | Modifiers
--------+---------+-----------
  id     | bigint  |
  tag    | text    |
  name   | text    |
  mass   | integer |
  volume | integer |
View definition:
  SELECT material.id, material.tag, material.name, material.mass, 
material.volume
    FROM core.material;

fswcs=# \d core.wa
core.waypoint           core.waypoint_name_key  core.waypoint_pkey 
core.waypoint_tag_key
fswcs=# \d core.waypoint
                 Table "core.waypoint"
   Column   |  Type   |           Modifiers
-----------+---------+--------------------------------
  id        | bigint  | not null default core.new_id()
  tag       | text    | not null
  name      | text    | not null
  is_router | boolean | not null
  is_target | boolean | not null
  is_packer | boolean | not null
Indexes:
     "waypoint_pkey" PRIMARY KEY, btree (id) CLUSTER
     "waypoint_tag_key" UNIQUE, btree (tag)
     "waypoint_name_key" btree (name)
Referenced by:
     TABLE "core.demand" CONSTRAINT "demand_target_id_fkey" FOREIGN KEY 
(target_id) REFERENCES core.waypoint(id)
     TABLE "viwcs.du_report" CONSTRAINT "du_report_target_id_fkey" 
FOREIGN KEY (target_id) REFERENCES core.waypoint(id)
     TABLE "viwcs.mss_actor_state" CONSTRAINT 
"mss_actor_state_last_demand_tag_fkey" FOREIGN KEY (last_demand_tag) 
REFERENCES core.waypoint(tag)
     TABLE "viwcs.mss_actor_state" CONSTRAINT 
"mss_actor_state_last_racking_tag_fkey" FOREIGN KEY (last_racking_tag) 
REFERENCES core.waypoint(tag)
     TABLE "viwcs.mss_rack_action_queue" CONSTRAINT 
"mss_rack_action_queue_racking_tag_fkey" FOREIGN KEY (racking_tag) 
REFERENCES core.waypoint(tag)
     TABLE "core.route_cache" CONSTRAINT "route_cache_next_hop_id_fkey" 
FOREIGN KEY (next_hop_id) REFERENCES core.waypoint(id) ON DELETE CASCADE
     TABLE "core.route_cache" CONSTRAINT "route_cache_router_id_fkey" 
FOREIGN KEY (router_id) REFERENCES core.waypoint(id) ON DELETE CASCADE
     TABLE "core.route_cache" CONSTRAINT "route_cache_target_id_fkey" 
FOREIGN KEY (target_id) REFERENCES core.waypoint(id) ON DELETE CASCADE
     TABLE "core.route" CONSTRAINT "route_dst_id_fkey" FOREIGN KEY 
(dst_id) REFERENCES core.waypoint(id)
     TABLE "core.route" CONSTRAINT "route_src_id_fkey" FOREIGN KEY 
(src_id) REFERENCES core.waypoint(id)
     TABLE "viwcs.wave_genreorders_map" CONSTRAINT 
"wave_genreorders_map_ERR_GENREID_UNKNOWN" FOREIGN KEY (target_id) 
REFERENCES core.waypoint(id)
Triggers:
     __waypoint__location_id_delete BEFORE DELETE ON core.waypoint FOR 
EACH ROW EXECUTE PROCEDURE core.__location_id_delete()
     __waypoint__location_id_insert BEFORE INSERT ON core.waypoint FOR 
EACH ROW EXECUTE PROCEDURE core.__location_id_insert()
     __waypoint__location_id_update BEFORE UPDATE ON core.waypoint FOR 
EACH ROW EXECUTE PROCEDURE core.__location_id_update()
     __waypoint__tag_id_delete BEFORE DELETE ON core.waypoint FOR EACH 
ROW EXECUTE PROCEDURE core.__tag_id_delete()
     __waypoint__tag_id_insert BEFORE INSERT ON core.waypoint FOR EACH 
ROW EXECUTE PROCEDURE core.__tag_id_insert()
     __waypoint__tag_id_update BEFORE UPDATE ON core.waypoint FOR EACH 
ROW EXECUTE PROCEDURE core.__tag_id_update()
     __waypoint__tag_tag_delete BEFORE DELETE ON core.waypoint FOR EACH 
ROW EXECUTE PROCEDURE core.__tag_tag_delete()
     __waypoint__tag_tag_insert BEFORE INSERT ON core.waypoint FOR EACH 
ROW EXECUTE PROCEDURE core.__tag_tag_insert()
     __waypoint__tag_tag_update BEFORE UPDATE ON core.waypoint FOR EACH 
ROW EXECUTE PROCEDURE core.__tag_tag_update()
Inherits: core.location

fswcs=# \d core.ma
core.material           core.material_name_key  core.material_pkey 
core.material_tag_key
fswcs=# \d core.material
                Table "core.material"
  Column |  Type   |           Modifiers
--------+---------+--------------------------------
  id     | bigint  | not null default core.new_id()
  tag    | text    | not null
  name   | text    | not null
  mass   | integer | not null
  volume | integer | not null
Indexes:
     "material_pkey" PRIMARY KEY, btree (id)
     "material_tag_key" UNIQUE, btree (tag)
     "material_name_key" btree (name)
Check constraints:
     "material_mass_check" CHECK (mass >= 0)
     "material_volume_check" CHECK (volume >= 0)
Triggers:
     __material__material_id_delete BEFORE DELETE ON core.material FOR 
EACH ROW EXECUTE PROCEDURE core.__material_id_delete()
     __material__material_id_insert BEFORE INSERT ON core.material FOR 
EACH ROW EXECUTE PROCEDURE core.__material_id_insert()
     __material__material_id_update BEFORE UPDATE ON core.material FOR 
EACH ROW EXECUTE PROCEDURE core.__material_id_update()
     __material__tag_id_delete BEFORE DELETE ON core.material FOR EACH 
ROW EXECUTE PROCEDURE core.__tag_id_delete()
     __material__tag_id_insert BEFORE INSERT ON core.material FOR EACH 
ROW EXECUTE PROCEDURE core.__tag_id_insert()
     __material__tag_id_update BEFORE UPDATE ON core.material FOR EACH 
ROW EXECUTE PROCEDURE core.__tag_id_update()
     __material__tag_tag_delete BEFORE DELETE ON core.material FOR EACH 
ROW EXECUTE PROCEDURE core.__tag_tag_delete()
     __material__tag_tag_insert BEFORE INSERT ON core.material FOR EACH 
ROW EXECUTE PROCEDURE core.__tag_tag_insert()
     __material__tag_tag_update BEFORE UPDATE ON core.material FOR EACH 
ROW EXECUTE PROCEDURE core.__tag_tag_update()
Inherits: core.tag

--

-- 
Sent via pgsql-performance mailing list (pgsql-performance <at> postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-performance

Kevin Grittner | 2 Dec 2009 00:36
Favicon

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

Richard Neill <rn214 <at> cam.ac.uk> wrote:

> Am I wrong in thinking that ORDER BY is always applied after the
> main query is run?

Yes, you are wrong to think that.  It compares the costs of various
plans, and when it has an index with the high order portion matching
your ORDER BY clause, it may think that it can scan that index to
generate the correct sequence.  If the sort is estimated to be
expensive enough compared to the index scan, it will use the index
scan and skip the sort.  Sorting hundreds of billions of rows can be
expensive.

> Even if I run it this way:
> 
> select * from (select * from h.inventory where demand_id
> =289276563) as sqry order by id;
> 
> which should(?) surely force it to run the first select, then
> sort,

I wouldn't necessarily assume that.  You can EXPLAIN that form of
the query and find out easily enough.  Does it say:

                            ->  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)

or:

                            ->  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)

> it's quick if I do order by id+1

You don't have an index on id+1.

> The table definitions are as follows (sorry there are so many).

I'll poke around to try to get a clue why the estimated result rows
are so far off, but I may be in over my head there, so hopefully
others will look, too.  For one thing, I haven't used inheritance,
and I don't know how that might be playing into the bad estimates. 
(At first glance, it does seem to get into trouble about the time it
estimates the rows for the outer joins to those.)

The real problem to solve here is that it's estimating the rows
count for the result so badly.  If you need a short-term
work-around, you've already discovered that you can keep it from
using the index on id for ordering by creating an expression using
id which causes it not to consider the index a match.  That's kind
of ugly to keep long term, though.

-Kevin

--

-- 
Sent via pgsql-performance mailing list (pgsql-performance <at> postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-performance


Gmane