Thread: very slow selects on a small table

very slow selects on a small table

From
Brian Cox
Date:
There are 4 threads (4 postgres processes) loading all rows from a table
with 50,018 rows. The table has a int8 PK that is incremented by 1 for
each new row and the PK is used by the threads to partition the rows so
that each loads distinct rows. As you can see below, these 4 SELECTs
have been running since 6:30am (it's now 11:30am) -- sluggish at best --
and each of the postgres processes is using 100% CPU. The table schema
is long (~160 cols), so I'm omitting it but will provide it if deemed
necessary. Any ideas about the cause of this are appreciated.

Thanks,
Brian

cemdb=# select procpid, xact_start, current_query from pg_stat_activity;
  procpid |          xact_start           |
                                current_query

---------+-------------------------------+------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
-----------------------------------------------------------------------------
    27825 |                               | <IDLE>
    27826 |                               | <IDLE>
    27824 |                               | <IDLE>
    27828 |                               | <IDLE>
    27827 |                               | <IDLE>
    27829 |                               | <IDLE>
    27830 |                               | <IDLE>
    27831 |                               | <IDLE>
    27832 |                               | <IDLE>
    27833 |                               | <IDLE>
    14031 | 2009-06-17 05:48:02.931503-07 | autovacuum: VACUUM ANALYZE
public.ts_stats_transet_user_weekly
    16044 |                               | <IDLE>
    32169 | 2009-06-17 08:17:39.034142-07 | autovacuum: VACUUM ANALYZE
public.ts_stats_transetgroup_user_weekly
     7165 |                               | <IDLE>
    16043 |                               | <IDLE>
    22130 | 2009-06-17 11:22:05.339582-07 | select procpid, xact_start,
current_query from pg_stat_activity;
     7169 | 2009-06-17 06:31:26.997641-07 | select a.ts_id as id1_0_,
a.version_info as versionI2_1_0_, a.ts_user_id as userId1_0_, null as
tranSetId1_0_, null as tranUnitId1_0_, null as userGro10_1_0_,
a.ts_transet_group_id as tranSetG7_1_0_, a.ts_last_aggregated_row as
lastAgg12_1_0_, null as tranSetI5_1_0_, a.ts_user_incarnation_id as
userInca9_1_0_, a.ts_interval_start_time as interva11_1_0_,
a.ts_interval_wire_time as interva13_1_0_, a.ts_total_transactions as
totalTr14_1_0_, a.ts_bad_transactions as badTran15_1_0_,
a.ts_opportunities as opportu16_1_0_, a.ts_defects as defects1_0_,
a.ts_data_type as dataType1_0_, a.ts_tth_type as tthType1_0_,
a.ts_tth_lower_spec as tthLowe20_1_0_, a.ts_tth_upper_spec as
tthUppe21_1_0_, a.ts_tth_b0 as tthB22_1_0_, a.ts_tth_b1 as tthB23_1_0_,
a.ts_tth_b2 as tthB24_1_0_, a.ts_tth_b3 as tthB25_1_0_, a.ts_tth_b4 as
tthB26_1_0_, a.ts_tth_b5 as tthB27_1_0_, a.ts_tth_b6 as tthB28_1_0_,
a.ts_tth_b7 as tthB29_1_0_, a.ts_tth_b8 as tthB30_1_0_, a.ts_tth_b9 as
tthB31_1_0_, a.ts_tth_b10 as tthB32_1_0_, a.ts_tth_b11 as tthB33_1
     7171 |                               | <IDLE>
     7172 |                               | <IDLE>
    28106 |                               | <IDLE>
     7392 | 2009-06-17 06:31:26.997985-07 | select a.ts_id as id1_0_,
a.version_info as versionI2_1_0_, a.ts_user_id as userId1_0_, null as
tranSetId1_0_, null as tranUnitId1_0_, null as userGro10_1_0_,
a.ts_transet_group_id as tranSetG7_1_0_, a.ts_last_aggregated_row as
lastAgg12_1_0_, null as tranSetI5_1_0_, a.ts_user_incarnation_id as
userInca9_1_0_, a.ts_interval_start_time as interva11_1_0_,
a.ts_interval_wire_time as interva13_1_0_, a.ts_total_transactions as
totalTr14_1_0_, a.ts_bad_transactions as badTran15_1_0_,
a.ts_opportunities as opportu16_1_0_, a.ts_defects as defects1_0_,
a.ts_data_type as dataType1_0_, a.ts_tth_type as tthType1_0_,
a.ts_tth_lower_spec as tthLowe20_1_0_, a.ts_tth_upper_spec as
tthUppe21_1_0_, a.ts_tth_b0 as tthB22_1_0_, a.ts_tth_b1 as tthB23_1_0_,
a.ts_tth_b2 as tthB24_1_0_, a.ts_tth_b3 as tthB25_1_0_, a.ts_tth_b4 as
tthB26_1_0_, a.ts_tth_b5 as tthB27_1_0_, a.ts_tth_b6 as tthB28_1_0_,
a.ts_tth_b7 as tthB29_1_0_, a.ts_tth_b8 as tthB30_1_0_, a.ts_tth_b9 as
tthB31_1_0_, a.ts_tth_b10 as tthB32_1_0_, a.ts_tth_b11 as tthB33_1
     7396 |                               | <IDLE>
     7397 | 2009-06-17 06:31:26.998013-07 | select a.ts_id as id1_0_,
a.version_info as versionI2_1_0_, a.ts_user_id as userId1_0_, null as
tranSetId1_0_, null as tranUnitId1_0_, null as userGro10_1_0_,
a.ts_transet_group_id as tranSetG7_1_0_, a.ts_last_aggregated_row as
lastAgg12_1_0_, null as tranSetI5_1_0_, a.ts_user_incarnation_id as
userInca9_1_0_, a.ts_interval_start_time as interva11_1_0_,
a.ts_interval_wire_time as interva13_1_0_, a.ts_total_transactions as
totalTr14_1_0_, a.ts_bad_transactions as badTran15_1_0_,
a.ts_opportunities as opportu16_1_0_, a.ts_defects as defects1_0_,
a.ts_data_type as dataType1_0_, a.ts_tth_type as tthType1_0_,
a.ts_tth_lower_spec as tthLowe20_1_0_, a.ts_tth_upper_spec as
tthUppe21_1_0_, a.ts_tth_b0 as tthB22_1_0_, a.ts_tth_b1 as tthB23_1_0_,
a.ts_tth_b2 as tthB24_1_0_, a.ts_tth_b3 as tthB25_1_0_, a.ts_tth_b4 as
tthB26_1_0_, a.ts_tth_b5 as tthB27_1_0_, a.ts_tth_b6 as tthB28_1_0_,
a.ts_tth_b7 as tthB29_1_0_, a.ts_tth_b8 as tthB30_1_0_, a.ts_tth_b9 as
tthB31_1_0_, a.ts_tth_b10 as tthB32_1_0_, a.ts_tth_b11 as tthB33_1
     7403 | 2009-06-17 06:31:26.998273-07 | select a.ts_id as id1_0_,
a.version_info as versionI2_1_0_, a.ts_user_id as userId1_0_, null as
tranSetId1_0_, null as tranUnitId1_0_, null as userGro10_1_0_,
a.ts_transet_group_id as tranSetG7_1_0_, a.ts_last_aggregated_row as
lastAgg12_1_0_, null as tranSetI5_1_0_, a.ts_user_incarnation_id as
userInca9_1_0_, a.ts_interval_start_time as interva11_1_0_,
a.ts_interval_wire_time as interva13_1_0_, a.ts_total_transactions as
totalTr14_1_0_, a.ts_bad_transactions as badTran15_1_0_,
a.ts_opportunities as opportu16_1_0_, a.ts_defects as defects1_0_,
a.ts_data_type as dataType1_0_, a.ts_tth_type as tthType1_0_,
a.ts_tth_lower_spec as tthLowe20_1_0_, a.ts_tth_upper_spec as
tthUppe21_1_0_, a.ts_tth_b0 as tthB22_1_0_, a.ts_tth_b1 as tthB23_1_0_,
a.ts_tth_b2 as tthB24_1_0_, a.ts_tth_b3 as tthB25_1_0_, a.ts_tth_b4 as
tthB26_1_0_, a.ts_tth_b5 as tthB27_1_0_, a.ts_tth_b6 as tthB28_1_0_,
a.ts_tth_b7 as tthB29_1_0_, a.ts_tth_b8 as tthB30_1_0_, a.ts_tth_b9 as
tthB31_1_0_, a.ts_tth_b10 as tthB32_1_0_, a.ts_tth_b11 as tthB33_1
    32571 | 2009-06-16 19:03:16.645352-07 | autovacuum: VACUUM ANALYZE
public.ts_stats_transet_user_daily
(25 rows)

cemdb=# select c.oid,c.relname,l.pid,l.mode,l.granted from pg_class c
join pg_locks l on c.oid=l.relation order by l.pid;
    oid    |                         relname                          |
  pid  |           mode           | granted
----------+----------------------------------------------------------+-------+--------------------------+---------
  26612634 | ts_stats_transetgroup_user_daily_monthindex              |
  7169 | AccessShareLock          | t
  26612631 | ts_stats_transetgroup_user_daily_dayindex                |
  7169 | AccessShareLock          | t
  26612532 | ts_stats_transet_user_interval_monthindex                |
  7169 | AccessShareLock          | t
  26612322 | ts_stats_transet_user_interval_pkey                      |
  7169 | AccessShareLock          | t
  26611729 | ts_stats_transet_user_interval                           |
  7169 | AccessShareLock          | t
  26612639 | ts_stats_transetgroup_user_daily_yearindex               |
  7169 | AccessShareLock          | t
  26612638 | ts_stats_transetgroup_user_daily_weekindex               |
  7169 | AccessShareLock          | t
  26612635 | ts_stats_transetgroup_user_daily_starttimeindex          |
  7169 | AccessShareLock          | t
  26612538 | ts_stats_transet_user_interval_yearindex                 |
  7169 | AccessShareLock          | t
  26612530 | ts_stats_transet_user_interval_dayindex                  |
  7169 | AccessShareLock          | t
  26612531 | ts_stats_transet_user_interval_hourindex                 |
  7169 | AccessShareLock          | t
  26612633 | ts_stats_transetgroup_user_daily_lastaggregatedrowindex  |
  7169 | AccessShareLock          | t
  26611806 | ts_stats_transetgroup_user_daily                         |
  7169 | AccessShareLock          | t
  26612835 | ts_transetgroup_transets_map_transetgroupidindex         |
  7169 | AccessShareLock          | t
  26612534 | ts_stats_transet_user_interval_transetindex              |
  7169 | AccessShareLock          | t
  26612637 | ts_stats_transetgroup_user_daily_userindex               |
  7169 | AccessShareLock          | t
  26611350 | ts_transetgroup_transets_map                             |
  7169 | AccessShareLock          | t
  26612636 | ts_stats_transetgroup_user_daily_transetgroupindex       |
  7169 | AccessShareLock          | t
  26612836 | ts_transetgroup_transets_map_transetidindex              |
  7169 | AccessShareLock          | t
  26612632 | ts_stats_transetgroup_user_daily_hourindex               |
  7169 | AccessShareLock          | t
  26612401 | ts_transetgroup_transets_map_pkey                        |
  7169 | AccessShareLock          | t
  26612351 | ts_stats_transetgroup_user_daily_pkey                    |
  7169 | AccessShareLock          | t
  26612536 | ts_stats_transet_user_interval_userindex                 |
  7169 | AccessShareLock          | t
  26612537 | ts_stats_transet_user_interval_weekindex                 |
  7169 | AccessShareLock          | t
  26612837 | ts_transetgroup_transets_map_transetincarnationindex     |
  7169 | AccessShareLock          | t
  26612533 | ts_stats_transet_user_interval_starttime                 |
  7169 | AccessShareLock          | t
  26612535 | ts_stats_transet_user_interval_userincarnationidindex    |
  7169 | AccessShareLock          | t
  26612537 | ts_stats_transet_user_interval_weekindex                 |
  7392 | AccessShareLock          | t
  26612634 | ts_stats_transetgroup_user_daily_monthindex              |
  7392 | AccessShareLock          | t
  26612632 | ts_stats_transetgroup_user_daily_hourindex               |
  7392 | AccessShareLock          | t
  26612530 | ts_stats_transet_user_interval_dayindex                  |
  7392 | AccessShareLock          | t
  26612633 | ts_stats_transetgroup_user_daily_lastaggregatedrowindex  |
  7392 | AccessShareLock          | t
  26612533 | ts_stats_transet_user_interval_starttime                 |
  7392 | AccessShareLock          | t
  26612637 | ts_stats_transetgroup_user_daily_userindex               |
  7392 | AccessShareLock          | t
  26612351 | ts_stats_transetgroup_user_daily_pkey                    |
  7392 | AccessShareLock          | t
  26612534 | ts_stats_transet_user_interval_transetindex              |
  7392 | AccessShareLock          | t
  26612631 | ts_stats_transetgroup_user_daily_dayindex                |
  7392 | AccessShareLock          | t
  26612535 | ts_stats_transet_user_interval_userincarnationidindex    |
  7392 | AccessShareLock          | t
  26612636 | ts_stats_transetgroup_user_daily_transetgroupindex       |
  7392 | AccessShareLock          | t
  26612639 | ts_stats_transetgroup_user_daily_yearindex               |
  7392 | AccessShareLock          | t
  26611729 | ts_stats_transet_user_interval                           |
  7392 | AccessShareLock          | t
  26612322 | ts_stats_transet_user_interval_pkey                      |
  7392 | AccessShareLock          | t
  26612538 | ts_stats_transet_user_interval_yearindex                 |
  7392 | AccessShareLock          | t
  26612837 | ts_transetgroup_transets_map_transetincarnationindex     |
  7392 | AccessShareLock          | t
  26612635 | ts_stats_transetgroup_user_daily_starttimeindex          |
  7392 | AccessShareLock          | t
  26612532 | ts_stats_transet_user_interval_monthindex                |
  7392 | AccessShareLock          | t
  26612835 | ts_transetgroup_transets_map_transetgroupidindex         |
  7392 | AccessShareLock          | t
  26612638 | ts_stats_transetgroup_user_daily_weekindex               |
  7392 | AccessShareLock          | t
  26612401 | ts_transetgroup_transets_map_pkey                        |
  7392 | AccessShareLock          | t
  26612536 | ts_stats_transet_user_interval_userindex                 |
  7392 | AccessShareLock          | t
  26612836 | ts_transetgroup_transets_map_transetidindex              |
  7392 | AccessShareLock          | t
  26611806 | ts_stats_transetgroup_user_daily                         |
  7392 | AccessShareLock          | t
  26612531 | ts_stats_transet_user_interval_hourindex                 |
  7392 | AccessShareLock          | t
  26611350 | ts_transetgroup_transets_map                             |
  7392 | AccessShareLock          | t
  26612538 | ts_stats_transet_user_interval_yearindex                 |
  7397 | AccessShareLock          | t
  26612537 | ts_stats_transet_user_interval_weekindex                 |
  7397 | AccessShareLock          | t
  26612533 | ts_stats_transet_user_interval_starttime                 |
  7397 | AccessShareLock          | t
  26612639 | ts_stats_transetgroup_user_daily_yearindex               |
  7397 | AccessShareLock          | t
  26612632 | ts_stats_transetgroup_user_daily_hourindex               |
  7397 | AccessShareLock          | t
  26612531 | ts_stats_transet_user_interval_hourindex                 |
  7397 | AccessShareLock          | t
  26612835 | ts_transetgroup_transets_map_transetgroupidindex         |
  7397 | AccessShareLock          | t
  26611350 | ts_transetgroup_transets_map                             |
  7397 | AccessShareLock          | t
  26612532 | ts_stats_transet_user_interval_monthindex                |
  7397 | AccessShareLock          | t
  26612836 | ts_transetgroup_transets_map_transetidindex              |
  7397 | AccessShareLock          | t
  26612322 | ts_stats_transet_user_interval_pkey                      |
  7397 | AccessShareLock          | t
  26612535 | ts_stats_transet_user_interval_userincarnationidindex    |
  7397 | AccessShareLock          | t
  26612637 | ts_stats_transetgroup_user_daily_userindex               |
  7397 | AccessShareLock          | t
  26612631 | ts_stats_transetgroup_user_daily_dayindex                |
  7397 | AccessShareLock          | t
  26612634 | ts_stats_transetgroup_user_daily_monthindex              |
  7397 | AccessShareLock          | t
  26611729 | ts_stats_transet_user_interval                           |
  7397 | AccessShareLock          | t
  26611806 | ts_stats_transetgroup_user_daily                         |
  7397 | AccessShareLock          | t
  26612636 | ts_stats_transetgroup_user_daily_transetgroupindex       |
  7397 | AccessShareLock          | t
  26612351 | ts_stats_transetgroup_user_daily_pkey                    |
  7397 | AccessShareLock          | t
  26612536 | ts_stats_transet_user_interval_userindex                 |
  7397 | AccessShareLock          | t
  26612638 | ts_stats_transetgroup_user_daily_weekindex               |
  7397 | AccessShareLock          | t
  26612530 | ts_stats_transet_user_interval_dayindex                  |
  7397 | AccessShareLock          | t
  26612837 | ts_transetgroup_transets_map_transetincarnationindex     |
  7397 | AccessShareLock          | t
  26612633 | ts_stats_transetgroup_user_daily_lastaggregatedrowindex  |
  7397 | AccessShareLock          | t
  26612401 | ts_transetgroup_transets_map_pkey                        |
  7397 | AccessShareLock          | t
  26612534 | ts_stats_transet_user_interval_transetindex              |
  7397 | AccessShareLock          | t
  26612635 | ts_stats_transetgroup_user_daily_starttimeindex          |
  7397 | AccessShareLock          | t
  26612639 | ts_stats_transetgroup_user_daily_yearindex               |
  7403 | AccessShareLock          | t
  26612351 | ts_stats_transetgroup_user_daily_pkey                    |
  7403 | AccessShareLock          | t
  26612536 | ts_stats_transet_user_interval_userindex                 |
  7403 | AccessShareLock          | t
  26612634 | ts_stats_transetgroup_user_daily_monthindex              |
  7403 | AccessShareLock          | t
  26612635 | ts_stats_transetgroup_user_daily_starttimeindex          |
  7403 | AccessShareLock          | t
  26612538 | ts_stats_transet_user_interval_yearindex                 |
  7403 | AccessShareLock          | t
  26612633 | ts_stats_transetgroup_user_daily_lastaggregatedrowindex  |
  7403 | AccessShareLock          | t
  26612530 | ts_stats_transet_user_interval_dayindex                  |
  7403 | AccessShareLock          | t
  26612837 | ts_transetgroup_transets_map_transetincarnationindex     |
  7403 | AccessShareLock          | t
  26612532 | ts_stats_transet_user_interval_monthindex                |
  7403 | AccessShareLock          | t
  26612322 | ts_stats_transet_user_interval_pkey                      |
  7403 | AccessShareLock          | t
  26611729 | ts_stats_transet_user_interval                           |
  7403 | AccessShareLock          | t
  26612535 | ts_stats_transet_user_interval_userincarnationidindex    |
  7403 | AccessShareLock          | t
  26612637 | ts_stats_transetgroup_user_daily_userindex               |
  7403 | AccessShareLock          | t
  26612836 | ts_transetgroup_transets_map_transetidindex              |
  7403 | AccessShareLock          | t
  26611350 | ts_transetgroup_transets_map                             |
  7403 | AccessShareLock          | t
  26612401 | ts_transetgroup_transets_map_pkey                        |
  7403 | AccessShareLock          | t
  26612631 | ts_stats_transetgroup_user_daily_dayindex                |
  7403 | AccessShareLock          | t
  26612636 | ts_stats_transetgroup_user_daily_transetgroupindex       |
  7403 | AccessShareLock          | t
  26611806 | ts_stats_transetgroup_user_daily                         |
  7403 | AccessShareLock          | t
  26612534 | ts_stats_transet_user_interval_transetindex              |
  7403 | AccessShareLock          | t
  26612835 | ts_transetgroup_transets_map_transetgroupidindex         |
  7403 | AccessShareLock          | t
  26612632 | ts_stats_transetgroup_user_daily_hourindex               |
  7403 | AccessShareLock          | t
  26612531 | ts_stats_transet_user_interval_hourindex                 |
  7403 | AccessShareLock          | t
  26612537 | ts_stats_transet_user_interval_weekindex                 |
  7403 | AccessShareLock          | t
  26612533 | ts_stats_transet_user_interval_starttime                 |
  7403 | AccessShareLock          | t
  26612638 | ts_stats_transetgroup_user_daily_weekindex               |
  7403 | AccessShareLock          | t
  26611743 | ts_stats_transet_user_weekly                             |
14031 | ShareUpdateExclusiveLock | t
  26612553 | ts_stats_transet_user_weekly_starttimeindex              |
14031 | RowExclusiveLock         | t
  26612326 | ts_stats_transet_user_weekly_pkey                        |
14031 | RowExclusiveLock         | t
  26612551 | ts_stats_transet_user_weekly_lastaggregatedrowindex      |
14031 | RowExclusiveLock         | t
  26612550 | ts_stats_transet_user_weekly_hourindex                   |
14031 | RowExclusiveLock         | t
  26612552 | ts_stats_transet_user_weekly_monthindex                  |
14031 | RowExclusiveLock         | t
  26612549 | ts_stats_transet_user_weekly_dayindex                    |
14031 | RowExclusiveLock         | t
  26612558 | ts_stats_transet_user_weekly_yearindex                   |
14031 | RowExclusiveLock         | t
  26612554 | ts_stats_transet_user_weekly_transetindex                |
14031 | RowExclusiveLock         | t
  26612556 | ts_stats_transet_user_weekly_userindex                   |
14031 | RowExclusiveLock         | t
  26612557 | ts_stats_transet_user_weekly_weekindex                   |
14031 | RowExclusiveLock         | t
  26612555 | ts_stats_transet_user_weekly_userincarnationidindex      |
14031 | RowExclusiveLock         | t
     10969 | pg_locks                                                 |
22130 | AccessShareLock          | t
      1259 | pg_class                                                 |
22130 | AccessShareLock          | t
      2662 | pg_class_oid_index                                       |
22130 | AccessShareLock          | t
      2663 | pg_class_relname_nsp_index                               |
22130 | AccessShareLock          | t
  26612659 | ts_stats_transetgroup_user_weekly_hourindex              |
32169 | AccessShareLock          | t
  26612658 | ts_stats_transetgroup_user_weekly_dayindex               |
32169 | AccessShareLock          | t
  26612666 | ts_stats_transetgroup_user_weekly_yearindex              |
32169 | AccessShareLock          | t
  26612665 | ts_stats_transetgroup_user_weekly_weekindex              |
32169 | AccessShareLock          | t
  26612661 | ts_stats_transetgroup_user_weekly_monthindex             |
32169 | AccessShareLock          | t
  26612663 | ts_stats_transetgroup_user_weekly_transetgroupindex      |
32169 | AccessShareLock          | t
  26612662 | ts_stats_transetgroup_user_weekly_starttimeindex         |
32169 | AccessShareLock          | t
  26611827 | ts_stats_transetgroup_user_weekly                        |
32169 | ShareUpdateExclusiveLock | t
  26612660 | ts_stats_transetgroup_user_weekly_lastaggregatedrowindex |
32169 | AccessShareLock          | t
  26612664 | ts_stats_transetgroup_user_weekly_userindex              |
32169 | AccessShareLock          | t
  26612357 | ts_stats_transetgroup_user_weekly_pkey                   |
32169 | AccessShareLock          | t
  27208304 | ts_stats_transet_user_daily_starttimeindex               |
32571 | RowExclusiveLock         | t
  26612320 | ts_stats_transet_user_daily_pkey                         |
32571 | RowExclusiveLock         | t
  27208300 | ts_stats_transet_user_daily_dayindex                     |
32571 | RowExclusiveLock         | t
  27208305 | ts_stats_transet_user_daily_transetincarnationidindex    |
32571 | RowExclusiveLock         | t
  27208302 | ts_stats_transet_user_daily_lastaggregatedrowindex       |
32571 | RowExclusiveLock         | t
  27208310 | ts_stats_transet_user_daily_yearindex                    |
32571 | RowExclusiveLock         | t
  27208309 | ts_stats_transet_user_daily_weekindex                    |
32571 | RowExclusiveLock         | t
  27208307 | ts_stats_transet_user_daily_userincarnationidindex       |
32571 | RowExclusiveLock         | t
  26611722 | ts_stats_transet_user_daily                              |
32571 | ShareUpdateExclusiveLock | t
  27208301 | ts_stats_transet_user_daily_hourindex                    |
32571 | RowExclusiveLock         | t
  27208306 | ts_stats_transet_user_daily_transetindex                 |
32571 | RowExclusiveLock         | t
  27208303 | ts_stats_transet_user_daily_monthindex                   |
32571 | RowExclusiveLock         | t
  27208308 | ts_stats_transet_user_daily_userindex                    |
32571 | RowExclusiveLock         | t
(148 rows)

[root@rdl64xeoserv01 log]# strace -p 7397
Process 7397 attached - interrupt to quit
munmap(0x95393000, 1052672)             = 0
munmap(0x95494000, 528384)              = 0
munmap(0x95515000, 266240)              = 0
brk(0x8603000)                          = 0x8603000
brk(0x85fb000)                          = 0x85fb000
_llseek(144, 0, [292618240], SEEK_END)  = 0
brk(0x85eb000)                          = 0x85eb000
_llseek(65, 897179648, [897179648], SEEK_SET) = 0
read(65, "\276\2\0\0\320\337\275\315\1\0\0\0|\3`\22\360\37\4 \0\0"...,
8192) = 8192
_llseek(65, 471457792, [471457792], SEEK_SET) = 0
read(65, "\276\2\0\0\320\337\275\315\1\0\0\0t\6\200\6\360\37\4 \0"...,
8192) = 8192
read(65, "\276\2\0\0\354\271\355\312\1\0\0\0\374\5`\10\360\37\4 "...,
8192) = 8192
read(65, "\0\0\0\0\0\0\0\0\1\0\0\0\324\5\0\t\360\37\4 \0\0\0\0\0"...,
8192) = 8192
brk(0x8613000)                          = 0x8613000
mmap2(NULL, 266240, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1,
0) = 0x95515000
mmap2(NULL, 528384, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1,
0) = 0x95494000
mmap2(NULL, 1052672, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS,
-1, 0) = 0x95393000
munmap(0x95393000, 1052672)             = 0
munmap(0x95494000, 528384)              = 0
munmap(0x95515000, 266240)              = 0
brk(0x8603000)                          = 0x8603000
brk(0x85fb000)                          = 0x85fb000
_llseek(144, 0, [292618240], SEEK_END)  = 0
brk(0x85eb000)                          = 0x85eb000
_llseek(65, 86941696, [86941696], SEEK_SET) = 0
read(65, "\304\2\0\0\30\333\v\244\1\0\0\0\324\5\0\t\360\37\4 \0\0"...,
8192) = 8192
_llseek(65, 892682240, [892682240], SEEK_SET) = 0
read(65, "\276\2\0\0\fq\231\310\1\0\0\0|\3`\22\360\37\4 \0\0\0\0"...,
8192) = 8192
_llseek(65, 86949888, [86949888], SEEK_SET) = 0
read(65, "\276\2\0\0\fq\231\310\1\0\0\0t\6\200\6\360\37\4 \0\0\0"...,
8192) = 8192
read(65, "\276\2\0\0\270*\341\305\1\0\0\0\364\5\200\10\360\37\4 "...,
8192) = 8192
read(65, "\0\0\0\0\0\0\0\0\1\0\0\0\324\5\0\t\360\37\4 \0\0\0\0\0"...,
8192) = 8192
read(65, "\304\2\0\0\320`\225\242\1\0\0\0000\4\220\17\360\37\4 \0"...,
8192) = 8192
brk(0x8613000)                          = 0x8613000
mmap2(NULL, 266240, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1,
0) = 0x95515000
mmap2(NULL, 528384, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1,
0) = 0x95494000
mmap2(NULL, 1052672, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS,
-1, 0) = 0x95393000
munmap(0x95393000, 1052672)             = 0
munmap(0x95494000, 528384)              = 0
munmap(0x95515000, 266240)              = 0
brk(0x8603000)                          = 0x8603000
brk(0x85fb000)                          = 0x85fb000
_llseek(144, 0, [292618240], SEEK_END)  = 0
brk(0x85eb000)                          = 0x85eb000
brk(0x8613000)                          = 0x8613000
mmap2(NULL, 266240, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1,
0) = 0x95515000
mmap2(NULL, 528384, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1,
0) = 0x95494000
mmap2(NULL, 1052672, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS,
-1, 0) = 0x95393000
munmap(0x95393000, 1052672)             = 0
munmap(0x95494000, 528384)              = 0
munmap(0x95515000, 266240)              = 0
brk(0x8603000)                          = 0x8603000
brk(0x85fb000)                          = 0x85fb000
_llseek(144, 0, [292618240], SEEK_END)  = 0
brk(0x85eb000)                          = 0x85eb000
_llseek(65, 115359744, [115359744], SEEK_SET) = 0
read(65, "\304\2\0\0\200e\331\243\1\0\0\0`\6\320\6\360\37\4 \0\0"...,
8192) = 8192
_llseek(65, 827695104, [827695104], SEEK_SET) = 0
read(65, "\273\2\0\0\20\36uY\1\0\0\0|\3`\22\360\37\4 \0\0\0\0\340"...,
8192) = 8192
_llseek(65, 115367936, [115367936], SEEK_SET) = 0
read(65, "\273\2\0\0\20\36uY\1\0\0\0\10\0060\10\360\37\4 \0\0\0\0"...,
8192) = 8192
read(65, "\0\0\0\0\0\0\0\0\1\0\0\0\324\5\0\t\360\37\4 \0\0\0\0\0"...,
8192) = 8192
read(65, "\0\0\0\0\0\0\0\0\1\0\0\0\324\5\0\t\360\37\4 \0\0\0\0\0"...,
8192) = 8192
read(65, "\304\2\0\0\344M>\242\1\0\0\0L\3 \23\360\37\4 \0\0\0\0\340"...,
8192) = 8192
brk(0x8613000)                          = 0x8613000
mmap2(NULL, 266240, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1,
0) = 0x95515000
mmap2(NULL, 528384, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1,
0) = 0x95494000
mmap2(NULL, 1052672, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS,
-1, 0) = 0x95393000
munmap(0x95393000, 1052672)             = 0
munmap(0x95494000, 528384)              = 0
munmap(0x95515000, 266240)              = 0

strace output from the other 3 postgres processes looks the same.

Re: very slow selects on a small table

From
Tom Lane
Date:
Brian Cox <brian.cox@ca.com> writes:
> [root@rdl64xeoserv01 log]# strace -p 7397
> Process 7397 attached - interrupt to quit
> munmap(0x95393000, 1052672)             = 0
> munmap(0x95494000, 528384)              = 0
> munmap(0x95515000, 266240)              = 0
> brk(0x8603000)                          = 0x8603000
> brk(0x85fb000)                          = 0x85fb000
> _llseek(144, 0, [292618240], SEEK_END)  = 0
> brk(0x85eb000)                          = 0x85eb000
> _llseek(65, 897179648, [897179648], SEEK_SET) = 0
> read(65, "\276\2\0\0\320\337\275\315\1\0\0\0|\3`\22\360\37\4 \0\0"...,
> 8192) = 8192
> _llseek(65, 471457792, [471457792], SEEK_SET) = 0
> read(65, "\276\2\0\0\320\337\275\315\1\0\0\0t\6\200\6\360\37\4 \0"...,
> 8192) = 8192
> read(65, "\276\2\0\0\354\271\355\312\1\0\0\0\374\5`\10\360\37\4 "...,
> 8192) = 8192
> read(65, "\0\0\0\0\0\0\0\0\1\0\0\0\324\5\0\t\360\37\4 \0\0\0\0\0"...,
> 8192) = 8192
> brk(0x8613000)                          = 0x8613000
> mmap2(NULL, 266240, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1,
> 0) = 0x95515000
> mmap2(NULL, 528384, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1,
> 0) = 0x95494000
> mmap2(NULL, 1052672, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS,
> -1, 0) = 0x95393000
> munmap(0x95393000, 1052672)             = 0
> munmap(0x95494000, 528384)              = 0
> munmap(0x95515000, 266240)              = 0
> [ lather, rinse, repeat ]

That is a pretty odd trace for a Postgres backend; apparently it's
repeatedly acquiring and releasing a meg or two worth of memory, which
is not very normal within a single query.  Can you tell us more about
the query it's running?  An EXPLAIN plan would be particularly
interesting.  Also, could you try to determine which files 144 and 65
refer to (see lsof)?

            regards, tom lane

Re: very slow selects on a small table

From
Brian Cox
Date:
Tom Lane [tgl@sss.pgh.pa.us] wrote:
> That is a pretty odd trace for a Postgres backend; apparently it's
> repeatedly acquiring and releasing a meg or two worth of memory, which
> is not very normal within a single query.  Can you tell us more about
> the query it's running?  An EXPLAIN plan would be particularly
> interesting.  Also, could you try to determine which files 144 and 65
> refer to (see lsof)?

Here's the explain and a current strace and lsof. The strace shows even
less I/O activity.

Thanks,
Brian


cemdb=# explain select * from ts_stats_transetgroup_user_daily a where
a.ts_id in (select b.ts_id from ts_stats_transetgroup_user_daily
b,ts_stats_transet_user_interval c, ts_transetgroup_transets_map m where
b.ts_transet_group_id = m.ts_transet_group_id and
m.ts_transet_incarnation_id = c.ts_transet_incarnation_id and
c.ts_user_incarnation_id = b.ts_user_incarnation_id and
c.ts_interval_start_time >= '2009-6-16 01:00' and
c.ts_interval_start_time < '2009-6-16 02:00');

                          QUERY PLAN

----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
  Hash IN Join  (cost=128162.63..211221.43 rows=231127 width=779)
    Hash Cond: (a.ts_id = b.ts_id)
    ->  Seq Scan on ts_stats_transetgroup_user_daily a
(cost=0.00..80511.26 rows=247451 width=779)
    ->  Hash  (cost=126718.09..126718.09 rows=231127 width=8)
          ->  Hash Join  (cost=82370.45..126718.09 rows=231127 width=8)
                Hash Cond: ((m.ts_transet_group_id =
b.ts_transet_group_id) AND (c.ts_user_incarnation_id =
b.ts_user_incarnation_id))
                ->  Hash Join  (cost=3.32..27316.61 rows=211716 width=16)
                      Hash Cond: (c.ts_transet_incarnation_id =
m.ts_transet_incarnation_id)
                      ->  Index Scan using
ts_stats_transet_user_interval_starttime on
ts_stats_transet_user_interval c  (cost=0.00..25857.75 rows=211716 width=16)
                            Index Cond: ((ts_interval_start_time >=
'2009-06-16 01:00:00-07'::timestamp with time zone) AND
(ts_interval_start_time < '2009-06-16 02:00:00-07'::timestamp with time
zone))
                      ->  Hash  (cost=2.58..2.58 rows=117 width=16)
                            ->  Seq Scan on ts_transetgroup_transets_map
m  (cost=0.00..2.58 rows=117 width=16)
                ->  Hash  (cost=80511.26..80511.26 rows=247451 width=24)
                      ->  Seq Scan on ts_stats_transetgroup_user_daily b
  (cost=0.00..80511.26 rows=247451 width=24)
(14 rows)


[root@rdl64xeoserv01 log]# strace -p 7397
Process 7397 attached - interrupt to quit
mmap2(NULL, 266240, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1,
0) = 0x95515000
mmap2(NULL, 528384, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1,
0) = 0x95494000
mmap2(NULL, 1052672, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS,
-1, 0) = 0x95393000
munmap(0x95393000, 1052672)             = 0
munmap(0x95494000, 528384)              = 0
munmap(0x95515000, 266240)              = 0
brk(0x8603000)                          = 0x8603000
brk(0x85fb000)                          = 0x85fb000
_llseek(164, 0, [201940992], SEEK_END)  = 0
brk(0x85eb000)                          = 0x85eb000
brk(0x8613000)                          = 0x8613000
mmap2(NULL, 266240, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1,
0) = 0x95515000
mmap2(NULL, 528384, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1,
0) = 0x95494000
mmap2(NULL, 1052672, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS,
-1, 0) = 0x95393000
munmap(0x95393000, 1052672)             = 0
munmap(0x95494000, 528384)              = 0
munmap(0x95515000, 266240)              = 0
brk(0x8603000)                          = 0x8603000
brk(0x85fb000)                          = 0x85fb000
_llseek(164, 0, [201940992], SEEK_END)  = 0
brk(0x85eb000)                          = 0x85eb000
brk(0x8613000)                          = 0x8613000
mmap2(NULL, 266240, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1,
0) = 0x95515000
mmap2(NULL, 528384, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1,
0) = 0x95494000
mmap2(NULL, 1052672, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS,
-1, 0) = 0x95393000
munmap(0x95393000, 1052672)             = 0
munmap(0x95494000, 528384)              = 0
munmap(0x95515000, 266240)              = 0
brk(0x8603000)                          = 0x8603000
brk(0x85fb000)                          = 0x85fb000
_llseek(164, 0, [201940992], SEEK_END)  = 0
brk(0x85eb000)                          = 0x85eb000
brk(0x8613000)                          = 0x8613000
mmap2(NULL, 266240, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1,
0) = 0x95515000
mmap2(NULL, 528384, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1,
0) = 0x95494000
mmap2(NULL, 1052672, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS,
-1, 0) = 0x95393000
munmap(0x95393000, 1052672)             = 0
munmap(0x95494000, 528384)              = 0
munmap(0x95515000, 266240)              = 0
brk(0x8603000)                          = 0x8603000
brk(0x85fb000)                          = 0x85fb000
_llseek(164, 0, [201940992], SEEK_END)  = 0


[root@rdl64xeoserv01 log]# lsof -p 7397
COMMAND    PID     USER   FD   TYPE   DEVICE       SIZE     NODE NAME
postmaste 7397 postgres  cwd    DIR      8,2       4096 12681488
/var/lib/pgsql/data
postmaste 7397 postgres  rtd    DIR      8,2       4096        2 /
postmaste 7397 postgres  txt    REG      8,2    3304132  3514609
/usr/bin/postgres
postmaste 7397 postgres  mem    REG      8,2      45889  4718642
/lib/libnss_files-2.3.4.so
postmaste 7397 postgres  mem    REG      8,2     136016  3510667
/usr/lib/libk5crypto.so.3.0
postmaste 7397 postgres  mem    REG      8,2     202976  3514362
/usr/lib/libldap-2.2.so.7.0.6
postmaste 7397 postgres  mem    REG      8,2      48548  3514621
/usr/lib/liblber-2.2.so.7.0.6
postmaste 7397 postgres  mem    REG      8,2      82320  3514622
/usr/lib/libsasl2.so.2.0.19
postmaste 7397 postgres  mem    REG      8,2     106397  4719545
/lib/ld-2.3.4.so
postmaste 7397 postgres  mem    REG      8,2       7004  4719556
/lib/libcom_err.so.2.1
postmaste 7397 postgres  mem    REG      8,2    1454802  4719546
/lib/tls/libc-2.3.4.so
postmaste 7397 postgres  mem    REG      8,2      15324  4719549
/lib/libdl-2.3.4.so
postmaste 7397 postgres  mem    REG      8,2     178019  4719550
/lib/tls/libm-2.3.4.so
postmaste 7397 postgres  mem    REG      8,2      63624  3512751
/usr/lib/libz.so.1.2.1.2
postmaste 7397 postgres  mem    REG      8,2      27191  4719553
/lib/libcrypt-2.3.4.so
postmaste 7397 postgres  mem    REG      8,2      79488  4719551
/lib/libresolv-2.3.4.so
postmaste 7397 postgres  mem    REG      8,2      32024  4718594
/lib/libpam.so.0.77
postmaste 7397 postgres  mem    REG      8,2      60116  4718721
/lib/libaudit.so.0.0.0
postmaste 7397 postgres  mem    REG      8,2      82944  3514353
/usr/lib/libgssapi_krb5.so.2.2
postmaste 7397 postgres  mem    REG      8,2     415188  3514352
/usr/lib/libkrb5.so.3.2
postmaste 7397 postgres  mem    REG      8,2     213600 24708638
/opt/PostgreSQL/8.3/lib/libssl.so.0.9.7a
postmaste 7397 postgres  mem    REG      8,2     945120 24708627
/opt/PostgreSQL/8.3/lib/libcrypto.so.0.9.7a
postmaste 7397 postgres  DEL    REG      0,6             5177344
/SYSV0052e2c1
postmaste 7397 postgres  mem    REG      8,2   48533072  3509415
/usr/lib/locale/locale-archive
postmaste 7397 postgres    0r   CHR      1,3                1969 /dev/null
postmaste 7397 postgres    1w  FIFO      0,7             9913597 pipe
postmaste 7397 postgres    2w  FIFO      0,7             9913597 pipe
postmaste 7397 postgres    3u   REG      8,2     368640 12812420
/var/lib/pgsql/data/base/26611279/1259
postmaste 7397 postgres    4u   REG      8,2       8192 12812368
/var/lib/pgsql/data/base/26611279/2601
postmaste 7397 postgres    5u   REG      8,2       8192 12812341
/var/lib/pgsql/data/base/26611279/2615
postmaste 7397 postgres    6u   REG      8,2      16384 12812326
/var/lib/pgsql/data/base/26611279/2684
postmaste 7397 postgres    7u  IPv4  9913600                 UDP
localhost.localdomain:35057->localhost.localdomain:35057
postmaste 7397 postgres    8u  IPv4 10045960                 TCP
localhost.localdomain:postgres->localhost.localdomain:53377 (ESTABLISHED)
postmaste 7397 postgres    9u   REG      8,2      16384 12812366
/var/lib/pgsql/data/base/26611279/2685
postmaste 7397 postgres   10u   REG      8,2     253952 12812354
/var/lib/pgsql/data/base/26611279/2662
postmaste 7397 postgres   11u   REG      8,2     286720 12812359
/var/lib/pgsql/data/base/26611279/2663
postmaste 7397 postgres   12u   REG      8,2     131072 12812365
/var/lib/pgsql/data/base/26611279/2609
postmaste 7397 postgres   13u   REG      8,2      98304 12812430
/var/lib/pgsql/data/base/26611279/2675
postmaste 7397 postgres   14u   REG      8,2    2097152 12812406
/var/lib/pgsql/data/base/26611279/1249
postmaste 7397 postgres   15u   REG      8,2    1130496 12812363
/var/lib/pgsql/data/base/26611279/2659
postmaste 7397 postgres   16u   REG      8,2     122880 12812373
/var/lib/pgsql/data/base/26611279/2604
postmaste 7397 postgres   17u   REG      8,2      16384 12813349
/var/lib/pgsql/data/base/26611279/27241082
postmaste 7397 postgres   18u   REG      8,2   16777216 26427412
/var/lib/pgsql/data/pg_xlog/00000001000002C30000001E (deleted)
postmaste 7397 postgres   19u   REG      8,2      16384 12813350
/var/lib/pgsql/data/base/26611279/27241083
postmaste 7397 postgres   20u   REG      8,2      16384 12813351
/var/lib/pgsql/data/base/26611279/27241084
postmaste 7397 postgres   21u   REG      8,2      16384 12813352
/var/lib/pgsql/data/base/26611279/27241085
postmaste 7397 postgres   22u   REG      8,2      16384 12813353
/var/lib/pgsql/data/base/26611279/27241086
postmaste 7397 postgres   23u   REG      8,2      16384 12813354
/var/lib/pgsql/data/base/26611279/27241087
postmaste 7397 postgres   24u   REG      8,2      16384 12813355
/var/lib/pgsql/data/base/26611279/27241088
postmaste 7397 postgres   25u   REG      8,2      16384 12813356
/var/lib/pgsql/data/base/26611279/27241089
postmaste 7397 postgres   26u   REG      8,2      16384 12813357
/var/lib/pgsql/data/base/26611279/27241090
postmaste 7397 postgres   27u   REG      8,2      16384 12813358
/var/lib/pgsql/data/base/26611279/27241091
postmaste 7397 postgres   28u   REG      8,2 1073741824 12813640
/var/lib/pgsql/data/base/26611279/27236833
postmaste 7397 postgres   29u   REG      8,2 1073741824 12812645
/var/lib/pgsql/data/base/26611279/27236833.1
postmaste 7397 postgres   30u   REG      8,2 1073741824 12812681
/var/lib/pgsql/data/base/26611279/27236833.2
postmaste 7397 postgres   31u   REG      8,2 1073741824 24133635
/var/lib/pgsql/data/base/26611279/27236833.3
postmaste 7397 postgres   32u   REG      8,2 1073741824 24133636
/var/lib/pgsql/data/base/26611279/27236833.4
postmaste 7397 postgres   33u   REG      8,2 1073741824 24133664
/var/lib/pgsql/data/base/26611279/27236833.5
postmaste 7397 postgres   34u   REG      8,2 1073741824 12813227
/var/lib/pgsql/data/base/26611279/27236833.6
postmaste 7397 postgres   35u   REG      8,2 1073741824 12812305
/var/lib/pgsql/data/base/26611279/27236833.7
postmaste 7397 postgres   36u   REG      8,2 1073741824 24133637
/var/lib/pgsql/data/base/26611279/27236833.8
postmaste 7397 postgres   37u   REG      8,2 1073741824 24133634
/var/lib/pgsql/data/base/26611279/27236833.9
postmaste 7397 postgres   38u   REG      8,2 1073741824 24133639
/var/lib/pgsql/data/base/26611279/27236833.10
postmaste 7397 postgres   39u   REG      8,2 1073741824 24133640
/var/lib/pgsql/data/base/26611279/27236833.11
postmaste 7397 postgres   40u   REG      8,2 1073741824 24133641
/var/lib/pgsql/data/base/26611279/27236833.12
postmaste 7397 postgres   41u   REG      8,2 1073741824 24133643
/var/lib/pgsql/data/base/26611279/27236833.13
postmaste 7397 postgres   42u   REG      8,2 1073741824 24133646
/var/lib/pgsql/data/base/26611279/27236833.14
postmaste 7397 postgres   43u   REG      8,2 1073741824 24133652
/var/lib/pgsql/data/base/26611279/27236833.15
postmaste 7397 postgres   44u   REG      8,2 1073741824 24133654
/var/lib/pgsql/data/base/26611279/27236833.16
postmaste 7397 postgres   45u   REG      8,2 1073741824 28295169
/var/lib/pgsql/data/base/26611279/27236833.17
postmaste 7397 postgres   46u   REG      8,2 1073741824 32489473
/var/lib/pgsql/data/base/26611279/27236833.18
postmaste 7397 postgres   47u   REG      8,2 1073741824 12812808
/var/lib/pgsql/data/base/26611279/27236833.19
postmaste 7397 postgres   48u   REG      8,2 1073741824 12812811
/var/lib/pgsql/data/base/26611279/27236833.20
postmaste 7397 postgres   49u   REG      8,2 1073741824 12812812
/var/lib/pgsql/data/base/26611279/27236833.21
postmaste 7397 postgres   50u   REG      8,2 1073741824 32489475
/var/lib/pgsql/data/base/26611279/27236833.22
postmaste 7397 postgres   51u   REG      8,2 1073741824 32489487
/var/lib/pgsql/data/base/26611279/27236833.23
postmaste 7397 postgres   52u   REG      8,2 1073741824 32489488
/var/lib/pgsql/data/base/26611279/27236833.24
postmaste 7397 postgres   53u   REG      8,2 1073741824 12812838
/var/lib/pgsql/data/base/26611279/27236833.25
postmaste 7397 postgres   54u   REG      8,2 1073741824 32489486
/var/lib/pgsql/data/base/26611279/27236833.26
postmaste 7397 postgres   55u   REG      8,2 1073741824 32489490
/var/lib/pgsql/data/base/26611279/27236833.27
postmaste 7397 postgres   56u   REG      8,2 1073741824 32489476
/var/lib/pgsql/data/base/26611279/27236833.28
postmaste 7397 postgres   57u   REG      8,2 1073741824 32489477
/var/lib/pgsql/data/base/26611279/27236833.29
postmaste 7397 postgres   58u   REG      8,2 1073741824 12812862
/var/lib/pgsql/data/base/26611279/27236833.30
postmaste 7397 postgres   59u   REG      8,2  977092608 32489492
/var/lib/pgsql/data/base/26611279/27241806
postmaste 7397 postgres   60u   REG      8,2  824860672 32489493
/var/lib/pgsql/data/base/26611279/27241838
postmaste 7397 postgres   61u   REG      8,2  824303616 32489494
/var/lib/pgsql/data/base/26611279/27241839
postmaste 7397 postgres   62u   REG      8,2  824770560 32489495
/var/lib/pgsql/data/base/26611279/27241840
postmaste 7397 postgres   63u   REG      8,2 1024270336 32489496
/var/lib/pgsql/data/base/26611279/27241841
postmaste 7397 postgres   64u   REG      8,2 1024016384 32489497
/var/lib/pgsql/data/base/26611279/27241842
postmaste 7397 postgres   65u   REG      8,2 1073741824 32489498
/var/lib/pgsql/data/base/26611279/27241843
postmaste 7397 postgres   66u   REG      8,2 1073741824 32489499
/var/lib/pgsql/data/base/26611279/27241844
postmaste 7397 postgres   67u   REG      8,2  824172544 32489500
/var/lib/pgsql/data/base/26611279/27241845
postmaste 7397 postgres   68u   REG      8,2  824639488 32489501
/var/lib/pgsql/data/base/26611279/27241846
postmaste 7397 postgres   69u   REG      8,2      16384 12812471
/var/lib/pgsql/data/base/26611279/26611350
postmaste 7397 postgres   70u   REG      8,2     155648 12812401
/var/lib/pgsql/data/base/26611279/2610
postmaste 7397 postgres   71u   REG      8,2      16384 12812744
/var/lib/pgsql/data/base/26611279/26612401
postmaste 7397 postgres   72u   REG      8,2      16384 12813163
/var/lib/pgsql/data/base/26611279/26612835
postmaste 7397 postgres   73u   REG      8,2      16384 12813164
/var/lib/pgsql/data/base/26611279/26612836
postmaste 7397 postgres   74u   REG      8,2      16384 12813165
/var/lib/pgsql/data/base/26611279/26612837
postmaste 7397 postgres   75u   REG      8,2     352256 12812314
/var/lib/pgsql/data/base/26611279/2696
postmaste 7397 postgres   76u   REG      8,2    9469952 12812377
/var/lib/pgsql/data/base/26611279/2619
postmaste 7397 postgres   77u   REG      8,2       8192 12813369
/var/lib/pgsql/data/base/26611279/27241102
postmaste 7397 postgres   78u   REG      8,2      16384 12813370
/var/lib/pgsql/data/base/26611279/27241103
postmaste 7397 postgres   79u   REG      8,2      16384 12813371
/var/lib/pgsql/data/base/26611279/27241104
postmaste 7397 postgres   80u   REG      8,2      16384 12813372
/var/lib/pgsql/data/base/26611279/27241105
postmaste 7397 postgres   81u   REG      8,2      16384 12813373
/var/lib/pgsql/data/base/26611279/27241106
postmaste 7397 postgres   82u   REG      8,2      16384 12813374
/var/lib/pgsql/data/base/26611279/27241107
postmaste 7397 postgres   83u   REG      8,2      16384 12813375
/var/lib/pgsql/data/base/26611279/27241108
postmaste 7397 postgres   84u   REG      8,2      16384 12813376
/var/lib/pgsql/data/base/26611279/27241109
postmaste 7397 postgres   85u   REG      8,2      16384 12813377
/var/lib/pgsql/data/base/26611279/27241110
postmaste 7397 postgres   86u   REG      8,2      16384 12813378
/var/lib/pgsql/data/base/26611279/27241111
postmaste 7397 postgres   87u   REG      8,2       8192 12813401
/var/lib/pgsql/data/base/26611279/27241134
postmaste 7397 postgres   88u   REG      8,2      16384 12813402
/var/lib/pgsql/data/base/26611279/27241135
postmaste 7397 postgres   89u   REG      8,2      16384 12813403
/var/lib/pgsql/data/base/26611279/27241136
postmaste 7397 postgres   90u   REG      8,2      16384 12813404
/var/lib/pgsql/data/base/26611279/27241137
postmaste 7397 postgres   91u   REG      8,2      16384 12813405
/var/lib/pgsql/data/base/26611279/27241138
postmaste 7397 postgres   92u   REG      8,2      16384 12813406
/var/lib/pgsql/data/base/26611279/27241139
postmaste 7397 postgres   93u   REG      8,2      16384 12813407
/var/lib/pgsql/data/base/26611279/27241140
postmaste 7397 postgres   94u   REG      8,2      16384 12813408
/var/lib/pgsql/data/base/26611279/27241141
postmaste 7397 postgres   95u   REG      8,2      16384 12813409
/var/lib/pgsql/data/base/26611279/27241142
postmaste 7397 postgres   96u   REG      8,2      16384 12813410
/var/lib/pgsql/data/base/26611279/27241143
postmaste 7397 postgres   97u   REG      8,2      16384 12813411
/var/lib/pgsql/data/base/26611279/27241144
postmaste 7397 postgres   98u   REG      8,2      32768 12813451
/var/lib/pgsql/data/base/26611279/26630701
postmaste 7397 postgres   99u   REG      8,2      32768 24133805
/var/lib/pgsql/data/base/26611279/27172990
postmaste 7397 postgres  100u   REG      8,2      32768 12812473
/var/lib/pgsql/data/base/26611279/27172991
postmaste 7397 postgres  101u   REG      8,2      32768 12812504
/var/lib/pgsql/data/base/26611279/27172993
postmaste 7397 postgres  102u   REG      8,2      32768 12812474
/var/lib/pgsql/data/base/26611279/27172992
postmaste 7397 postgres  103u   REG      8,2  716111872 12813434
/var/lib/pgsql/data/base/26611279/27241167
postmaste 7397 postgres  104u   REG      8,2    7602176 12813438
/var/lib/pgsql/data/base/26611279/27241168
postmaste 7397 postgres  105u   REG      8,2   24600576 12813441
/var/lib/pgsql/data/base/26611279/27241169
postmaste 7397 postgres  106u   REG      8,2   24502272 12813442
/var/lib/pgsql/data/base/26611279/27241170
postmaste 7397 postgres  107u   REG      8,2   30048256 12813443
/var/lib/pgsql/data/base/26611279/27241171
postmaste 7397 postgres  108u   REG      8,2   24559616 12813444
/var/lib/pgsql/data/base/26611279/27241172
postmaste 7397 postgres  109u   REG      8,2   29745152 12813445
/var/lib/pgsql/data/base/26611279/27241173
postmaste 7397 postgres  110u   REG      8,2   29851648 12813446
/var/lib/pgsql/data/base/26611279/27241174
postmaste 7397 postgres  111u   REG      8,2   27992064 12813447
/var/lib/pgsql/data/base/26611279/27241175
postmaste 7397 postgres  112u   REG      8,2   24674304 12813448
/var/lib/pgsql/data/base/26611279/27241176
postmaste 7397 postgres  113u   REG      8,2   24690688 12813449
/var/lib/pgsql/data/base/26611279/27241177
postmaste 7397 postgres  114u   REG      8,2  763609088 12813423
/var/lib/pgsql/data/base/26611279/27241156
postmaste 7397 postgres  115u   REG      8,2    4513792 12813424
/var/lib/pgsql/data/base/26611279/27241157
postmaste 7397 postgres  116u   REG      8,2   24756224 12813425
/var/lib/pgsql/data/base/26611279/27241158
postmaste 7397 postgres  117u   REG      8,2   24387584 12813426
/var/lib/pgsql/data/base/26611279/27241159
postmaste 7397 postgres  118u   REG      8,2   29843456 12813427
/var/lib/pgsql/data/base/26611279/27241160
postmaste 7397 postgres  119u   REG      8,2   24641536 12813428
/var/lib/pgsql/data/base/26611279/27241161
postmaste 7397 postgres  120u   REG      8,2   30130176 12813429
/var/lib/pgsql/data/base/26611279/27241162
postmaste 7397 postgres  121u   REG      8,2   30023680 12813430
/var/lib/pgsql/data/base/26611279/27241163
postmaste 7397 postgres  122u   REG      8,2   29220864 12813431
/var/lib/pgsql/data/base/26611279/27241164
postmaste 7397 postgres  123u   REG      8,2   24592384 12813432
/var/lib/pgsql/data/base/26611279/27241165
postmaste 7397 postgres  124u   REG      8,2   24674304 12813433
/var/lib/pgsql/data/base/26611279/27241166
postmaste 7397 postgres  125u   REG      8,2 1073741824 12812865
/var/lib/pgsql/data/base/26611279/27236833.31
postmaste 7397 postgres  126u   REG      8,2  649412608 12813412
/var/lib/pgsql/data/base/26611279/27241145
postmaste 7397 postgres  127u   REG      8,2   18046976 12813413
/var/lib/pgsql/data/base/26611279/27241146
postmaste 7397 postgres  128u   REG      8,2   23617536 12813414
/var/lib/pgsql/data/base/26611279/27241147
postmaste 7397 postgres  129u   REG      8,2   23568384 12813415
/var/lib/pgsql/data/base/26611279/27241148
postmaste 7397 postgres  130u   REG      8,2   28614656 12813416
/var/lib/pgsql/data/base/26611279/27241149
postmaste 7397 postgres  131u   REG      8,2   23306240 12813417
/var/lib/pgsql/data/base/26611279/27241150
postmaste 7397 postgres  132u   REG      8,2   28483584 12813418
/var/lib/pgsql/data/base/26611279/27241151
postmaste 7397 postgres  133u   REG      8,2   28499968 12813419
/var/lib/pgsql/data/base/26611279/27241152
postmaste 7397 postgres  134u   REG      8,2   21676032 12813420
/var/lib/pgsql/data/base/26611279/27241153
postmaste 7397 postgres  135u   REG      8,2   23429120 12813421
/var/lib/pgsql/data/base/26611279/27241154
postmaste 7397 postgres  136u   REG      8,2   23445504 12813422
/var/lib/pgsql/data/base/26611279/27241155
postmaste 7397 postgres  137u   REG      8,2  205619200 12813778
/var/lib/pgsql/data/base/26611279/27236971
postmaste 7397 postgres  138u   REG      8,2      65536 12813513
/var/lib/pgsql/data/base/26611279/27236747
postmaste 7397 postgres  139u   REG      8,2  170000384 12813779
/var/lib/pgsql/data/base/26611279/27236972
postmaste 7397 postgres  140u   REG      8,2  170262528 12813780
/var/lib/pgsql/data/base/26611279/27236973
postmaste 7397 postgres  141u   REG      8,2  149225472 12813310
/var/lib/pgsql/data/base/26611279/27241048
postmaste 7397 postgres  142u   REG      8,2      65536 12813559
/var/lib/pgsql/data/base/26611279/27236793
postmaste 7397 postgres  143u   REG      8,2  149168128 12813312
/var/lib/pgsql/data/base/26611279/27241050
postmaste 7397 postgres  144u   REG      8,2 1073741824 32489478
/var/lib/pgsql/data/base/26611279/27236833.32
postmaste 7397 postgres  145u   REG      8,2   53567488 32489479
/var/lib/pgsql/data/base/26611279/27241844.1
postmaste 7397 postgres  146u   REG      8,2  170016768 12813772
/var/lib/pgsql/data/base/26611279/27236965
postmaste 7397 postgres  147u   REG      8,2 1073741824 12813770
/var/lib/pgsql/data/base/26611279/27236963
postmaste 7397 postgres  148u   REG      8,2 1073741824 12813228
/var/lib/pgsql/data/base/26611279/27236963.1
postmaste 7397 postgres  149u   REG      8,2 1073741824 24133642
/var/lib/pgsql/data/base/26611279/27236963.2
postmaste 7397 postgres  150u   REG      8,2 1073741824 32489474
/var/lib/pgsql/data/base/26611279/27236963.3
postmaste 7397 postgres  151u   REG      8,2 1073741824 32489489
/var/lib/pgsql/data/base/26611279/27236963.4
postmaste 7397 postgres  152u   REG      8,2  573038592 12812863
/var/lib/pgsql/data/base/26611279/27236963.5
postmaste 7397 postgres  153u   REG      8,2  207003648 12813776
/var/lib/pgsql/data/base/26611279/27236969
postmaste 7397 postgres  154u   REG      8,2   52887552 32489480
/var/lib/pgsql/data/base/26611279/27241843.1
postmaste 7397 postgres  155u   REG      8,2  206692352 12813774
/var/lib/pgsql/data/base/26611279/27236967
postmaste 7397 postgres  156u   REG      8,2  206381056 12813777
/var/lib/pgsql/data/base/26611279/27236970
postmaste 7397 postgres  157u   REG      8,2  170360832 12813773
/var/lib/pgsql/data/base/26611279/27236966
postmaste 7397 postgres  158u   REG      8,2      16384 12813686
/var/lib/pgsql/data/base/26611279/27236879
postmaste 7397 postgres  159u   REG      8,2  162889728 12813771
/var/lib/pgsql/data/base/26611279/27236964
postmaste 7397 postgres  160u   REG      8,2  190480384 12813315
/var/lib/pgsql/data/base/26611279/27241053
postmaste 7397 postgres  161u   REG      8,2  169484288 12813775
/var/lib/pgsql/data/base/26611279/27236968
postmaste 7397 postgres  162u   REG      8,2      65536 12813512
/var/lib/pgsql/data/base/26611279/27236746
postmaste 7397 postgres  163u   REG      8,2      16384 12813728
/var/lib/pgsql/data/base/26611279/27236921
postmaste 7397 postgres  164u   REG      8,2  201940992 32489481
/var/lib/pgsql/data/base/26611279/27236833.33
postmaste 7397 postgres  165u   REG      8,2      16384 12813692
/var/lib/pgsql/data/base/26611279/27236885
postmaste 7397 postgres  166u   REG      8,2      16384 12813693
/var/lib/pgsql/data/base/26611279/27236886

Re: very slow selects on a small table

From
Tom Lane
Date:
Brian Cox <brian.cox@ca.com> writes:
> Here's the explain and a current strace and lsof. The strace shows even
> less I/O activity.

> cemdb=# explain select * from ts_stats_transetgroup_user_daily a where
> a.ts_id in (select b.ts_id from ts_stats_transetgroup_user_daily
> b,ts_stats_transet_user_interval c, ts_transetgroup_transets_map m where
> b.ts_transet_group_id = m.ts_transet_group_id and
> m.ts_transet_incarnation_id = c.ts_transet_incarnation_id and
> c.ts_user_incarnation_id = b.ts_user_incarnation_id and
> c.ts_interval_start_time >= '2009-6-16 01:00' and
> c.ts_interval_start_time < '2009-6-16 02:00');

Um, are you sure that is the query that PID 7397 is running?  It doesn't
match your previous pg_stat_activity printout, nor do I see anything
about partitioning by PKs.

            regards, tom lane

Re: very slow selects on a small table

From
Brian Cox
Date:
Tom Lane [tgl@sss.pgh.pa.us] wrote:
> Um, are you sure that is the query that PID 7397 is running?  It doesn't
> match your previous pg_stat_activity printout, nor do I see anything
> about partitioning by PKs.

Umm, indeed. I had to construct the query by hand and left out the
partition part. Here's the full query. Also, I took the liberty of
reducing the completely expanded column list (shown in part in the
pg_stat_activity printout) in the actual query to "*".

Thanks,
Brian

cemdb=# explain select * from ts_stats_transetgroup_user_daily a where
a.ts_id in (select b.ts_id from ts_stats_transetgroup_user_daily
b,ts_stats_transet_user_interval c, ts_transetgroup_transets_map m where
b.ts_transet_group_id = m.ts_transet_group_id and
m.ts_transet_incarnation_id = c.ts_transet_incarnation_id and
c.ts_user_incarnation_id = b.ts_user_incarnation_id and
c.ts_interval_start_time >= '2009-6-16 01:00' and
c.ts_interval_start_time < '2009-6-16 02:00') and a.ts_id > 0 and
a.ts_id < 100000 order by a.ts_id;

                       QUERY PLAN

----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
  Nested Loop IN Join  (cost=82370.45..128489.59 rows=1 width=779)
    Join Filter: (b.ts_id = a.ts_id)
    ->  Index Scan using ts_stats_transetgroup_user_daily_pkey on
ts_stats_transetgroup_user_daily a  (cost=0.00..8.22 rows=1 width=779)
          Index Cond: ((ts_id > 0) AND (ts_id < 100000))
    ->  Hash Join  (cost=82370.45..127026.87 rows=232721 width=8)
          Hash Cond: ((m.ts_transet_group_id = b.ts_transet_group_id)
AND (c.ts_user_incarnation_id = b.ts_user_incarnation_id))
          ->  Hash Join  (cost=3.32..27507.92 rows=213176 width=16)
                Hash Cond: (c.ts_transet_incarnation_id =
m.ts_transet_incarnation_id)
                ->  Index Scan using
ts_stats_transet_user_interval_starttime on
ts_stats_transet_user_interval c  (cost=0.00..26039.02 rows=213176 width=16)
                      Index Cond: ((ts_interval_start_time >=
'2009-06-16 01:00:00-07'::timestamp with time zone) AND
(ts_interval_start_time < '2009-06-16 02:00:00-07'::timestamp with time
zone))
                ->  Hash  (cost=2.58..2.58 rows=117 width=16)
                      ->  Seq Scan on ts_transetgroup_transets_map m
(cost=0.00..2.58 rows=117 width=16)
          ->  Hash  (cost=80511.26..80511.26 rows=247451 width=24)
                ->  Seq Scan on ts_stats_transetgroup_user_daily b
(cost=0.00..80511.26 rows=247451 width=24)
(14 rows)



Re: very slow selects on a small table

From
Tom Lane
Date:
Brian Cox <brian.cox@ca.com> writes:
> Tom Lane [tgl@sss.pgh.pa.us] wrote:
>> Um, are you sure that is the query that PID 7397 is running?  It doesn't
>> match your previous pg_stat_activity printout, nor do I see anything
>> about partitioning by PKs.

> Umm, indeed. I had to construct the query by hand and left out the
> partition part. Here's the full query. Also, I took the liberty of
> reducing the completely expanded column list (shown in part in the
> pg_stat_activity printout) in the actual query to "*".

Okay ... I think the problem is right here:

>   Nested Loop IN Join  (cost=82370.45..128489.59 rows=1 width=779)
>     Join Filter: (b.ts_id = a.ts_id)
>     ->  Index Scan using ts_stats_transetgroup_user_daily_pkey on
> ts_stats_transetgroup_user_daily a  (cost=0.00..8.22 rows=1 width=779)
>           Index Cond: ((ts_id > 0) AND (ts_id < 100000))
>     ->  Hash Join  (cost=82370.45..127026.87 rows=232721 width=8)

It's choosing this plan shape because it thinks that the indexscan on
ts_stats_transetgroup_user_daily will return only one row, which I bet
is off by something close to 100000x.  The memory usage pulsation
corresponds to re-executing the inner hash join, from scratch (including
rebuilding its hash table) for each outer row.  Ouch.

This seems like kind of a stupid plan anyway (which PG version was this
exactly?) but certainly the big issue is the catastrophically bad
rowcount estimate for the indexscan.  Do you have ANALYZE stats for
ts_stats_transetgroup_user_daily at all (look in pg_stats)?

            regards, tom lane

Re: very slow selects on a small table

From
Brian Cox
Date:
Tom Lane [tgl@sss.pgh.pa.us] wrote:
> This seems like kind of a stupid plan anyway (which PG version was this
> exactly?) but certainly the big issue is the catastrophically bad
> rowcount estimate for the indexscan.  Do you have ANALYZE stats for
> ts_stats_transetgroup_user_daily at all (look in pg_stats)?
postgres 8.3.5. Yes, here's a count(*) from pg_stats:

cemdb=# select count(*) from pg_stats where
tablename='ts_stats_transetgroup_user_daily';
  count
-------
    186
(1 row)


Thanks,
Brian

Re: very slow selects on a small table

From
Tom Lane
Date:
Brian Cox <brian.cox@ca.com> writes:
> Tom Lane [tgl@sss.pgh.pa.us] wrote:
>> ...  Do you have ANALYZE stats for
>> ts_stats_transetgroup_user_daily at all (look in pg_stats)?

> postgres 8.3.5. Yes, here's a count(*) from pg_stats:
>     186

OK, so what's the entry for column ts_id?

            regards, tom lane

Re: very slow selects on a small table

From
Brian Cox
Date:
Tom Lane [tgl@sss.pgh.pa.us] wrote:
> OK, so what's the entry for column ts_id?

Is this what you requested? Brian

cemdb=# select * from pg_stats where
tablename='ts_stats_transetgroup_user_daily' and attname = 'ts_id';
  schemaname |            tablename             | attname | null_frac |
avg_width | n_distinct | most_common_vals | most_common_freqs |

                               histogram_bounds

| correlation

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

------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
----------------------------------------------------------------------------+-------------
  public     | ts_stats_transetgroup_user_daily | ts_id   |         0 |
         8 |         -1 |                  |           |

{600000000000000001,600000000000002537,600000000000005139,600000000000007918,600000000000010330,600000000000013206,600000000000015829,600000000000018440,600000000000021018,600000000000023430,600000000000025887,600000000000028165,600000000000030571,600000000000033290,600000000000036434,600000000000038845,600000000000041276,600000000000043702,600000000000045978,600000000000048385,600000000000050648,600000000000053220,600000000000055602,600000000000058138,600000000000060613,600000000000063114,600000000000065750,600000000000068440,600000000000070859,600000000000073162,600000000000075597,600000000000078199,600000000000081054,600000000000083455,600000000000086049,600000000000088753,600000000000091231,600000000000093942,600000000000096229,600000000000098598,600000000000101190,600000000000103723,600000000000105917,600000000000108273,600000000000110687,600000000000113114,600000000000115528,600000000000118024,600000000000121085,600000000000123876,600000000000126548,600000000000128749,6

00000000000131260,600000000000133668,600000000000135988,600000000000138755,600000000000141251,600000000000143855,600000000000146302,600000000000148963,600000000000151424,600000000000153772,600000000000156222,600000000000159005,600000000000161293,600000000000163783,600000000000166624,600000000000168913,600000000000171220,600000000000173349,600000000000175584,600000000000177882,600000000000180605,600000000000183207,600000000000185420,600000000000187949,600000000000190128,600000000000192738,600000000000195452,600000000000197843,600000000000200173,600000000000202838,600000000000205245,600000000000207579,600000000000210566,600000000000212935,600000000000215382,600000000000218095,600000000000220940,600000000000223634,600000000000226196,600000000000228596,600000000000230733,600000000000232988,600000000000235066,600000000000237064,600000000000239736,600000000000242470,600000000000244915,600000000000247102,600000000000250068}

|     0.94954
(1 row)

Re: very slow selects on a small table

From
Tom Lane
Date:
Brian Cox <brian.cox@ca.com> writes:
> Tom Lane [tgl@sss.pgh.pa.us] wrote:
>> OK, so what's the entry for column ts_id?

> Is this what you requested? Brian

Yup.  So according to those stats, all ts_id values fall in the range
600000000000000001 .. 600000000000250068.  It's no wonder it's not
expecting to find anything between 0 and 100000.  I think maybe you
forgot to re-analyze after loading data ... although this being 8.3,
I'd have expected autovacuum to update the stats at some point ...

Recommendation: re-ANALYZE, check that the plan changes to something
with a higher estimate for the number of rows for this table, and then
abort and restart those processes.  Lord knows how long you'll be
waiting for them to finish with their current plans :-(

            regards, tom lane

Re: very slow selects on a small table

From
Brian Cox
Date:
Tom Lane [tgl@sss.pgh.pa.us] wrote:
> Yup.  So according to those stats, all ts_id values fall in the range
> 600000000000000001 .. 600000000000250068.  It's no wonder it's not
> expecting to find anything between 0 and 100000.  I think maybe you
> forgot to re-analyze after loading data ... although this being 8.3,
> I'd have expected autovacuum to update the stats at some point ...
yes, this is a concern. I may have to do the vacuum analyze myself or
learn how to make autovacuum run more frequently.
>
> Recommendation: re-ANALYZE, check that the plan changes to something
> with a higher estimate for the number of rows for this table, and then
> abort and restart those processes.  Lord knows how long you'll be
> waiting for them to finish with their current plans :-(
these queries are still running now 27.5 hours later... These queries
are generated by some java code and in putting it into a test program so
I could capture the queries, I failed to get the id range correct --
sorry for wasting your time with bogus data. Below is the EXPLAIN output
from the 4 correct queries. I can't tell which one is being executed by
PID 7397, but the query plans, except the last, do look very similar. In
any event, as I mentioned, all 4 are still running.

Thanks,
Brian

cemdb=# explain select * from ts_stats_transetgroup_user_daily a where
a.ts_id in (select b.ts_id from ts_stats_transetgroup_user_daily
b,ts_stats_transet_user_interval c, ts_transetgroup_transets_map m where
b.ts_transet_group_id = m.ts_transet_group_id and
m.ts_transet_incarnation_id = c.ts_transet_incarnation_id and
c.ts_user_incarnation_id = b.ts_user_incarnation_id and
c.ts_interval_start_time >= '2009-6-16 01:00' and
c.ts_interval_start_time < '2009-6-16 02:00') and a.ts_id >
600000000000010000 and a.ts_id < 600000000000020000 order by a.ts_id;

                             QUERY PLAN

----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
  Sort  (cost=138722.75..138734.37 rows=9299 width=779)
    Sort Key: a.ts_id
    ->  Hash IN Join  (cost=131710.94..138416.28 rows=9299 width=779)
          Hash Cond: (a.ts_id = b.ts_id)
          ->  Index Scan using ts_stats_transetgroup_user_daily_pkey on
ts_stats_transetgroup_user_daily a  (cost=0.00..6602.21 rows=9299 width=779)
                Index Cond: ((ts_id > 600000000000010000::bigint) AND
(ts_id < 600000000000020000::bigint))
          ->  Hash  (cost=130113.34..130113.34 rows=255616 width=8)
                ->  Hash Join  (cost=82370.45..130113.34 rows=255616
width=8)
                      Hash Cond: ((m.ts_transet_group_id =
b.ts_transet_group_id) AND (c.ts_user_incarnation_id =
b.ts_user_incarnation_id))
                      ->  Hash Join  (cost=3.32..29255.47 rows=229502
width=16)
                            Hash Cond: (c.ts_transet_incarnation_id =
m.ts_transet_incarnation_id)
                            ->  Index Scan using
ts_stats_transet_user_interval_starttime on
ts_stats_transet_user_interval c  (cost=0.00..27674.33 rows=229502 width=16)
                                  Index Cond: ((ts_interval_start_time
 >= '2009-06-16 01:00:00-07'::timestamp with time zone) AND
(ts_interval_start_time < '2009-06-16 02:00:00-07'::timestamp with time
zone))
                            ->  Hash  (cost=2.58..2.58 rows=117 width=16)
                                  ->  Seq Scan on
ts_transetgroup_transets_map m  (cost=0.00..2.58 rows=117 width=16)
                      ->  Hash  (cost=80511.26..80511.26 rows=247451
width=24)
                            ->  Seq Scan on
ts_stats_transetgroup_user_daily b  (cost=0.00..80511.26 rows=247451
width=24)
(17 rows)

cemdb=# explain select * from ts_stats_transetgroup_user_daily a where
a.ts_id in (select b.ts_id from ts_stats_transetgroup_user_daily
b,ts_stats_transet_user_interval c, ts_transetgroup_transets_map m where
b.ts_transet_group_id = m.ts_transet_group_id and
m.ts_transet_incarnation_id = c.ts_transet_incarnation_id and
c.ts_user_incarnation_id = b.ts_user_incarnation_id and
c.ts_interval_start_time >= '2009-6-16 01:00' and
c.ts_interval_start_time < '2009-6-16 02:00') and a.ts_id >
600000000000020000 and a.ts_id < 600000000000030000 order by a.ts_id;

                             QUERY PLAN

----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
  Sort  (cost=139430.64..139443.43 rows=10237 width=779)
    Sort Key: a.ts_id
    ->  Hash IN Join  (cost=131710.94..139089.71 rows=10237 width=779)
          Hash Cond: (a.ts_id = b.ts_id)
          ->  Index Scan using ts_stats_transetgroup_user_daily_pkey on
ts_stats_transetgroup_user_daily a  (cost=0.00..7265.23 rows=10237
width=779)
                Index Cond: ((ts_id > 600000000000020000::bigint) AND
(ts_id < 600000000000030000::bigint))
          ->  Hash  (cost=130113.34..130113.34 rows=255616 width=8)
                ->  Hash Join  (cost=82370.45..130113.34 rows=255616
width=8)
                      Hash Cond: ((m.ts_transet_group_id =
b.ts_transet_group_id) AND (c.ts_user_incarnation_id =
b.ts_user_incarnation_id))
                      ->  Hash Join  (cost=3.32..29255.47 rows=229502
width=16)
                            Hash Cond: (c.ts_transet_incarnation_id =
m.ts_transet_incarnation_id)
                            ->  Index Scan using
ts_stats_transet_user_interval_starttime on
ts_stats_transet_user_interval c  (cost=0.00..27674.33 rows=229502 width=16)
                                  Index Cond: ((ts_interval_start_time
 >= '2009-06-16 01:00:00-07'::timestamp with time zone) AND
(ts_interval_start_time < '2009-06-16 02:00:00-07'::timestamp with time
zone))
                            ->  Hash  (cost=2.58..2.58 rows=117 width=16)
                                  ->  Seq Scan on
ts_transetgroup_transets_map m  (cost=0.00..2.58 rows=117 width=16)
                      ->  Hash  (cost=80511.26..80511.26 rows=247451
width=24)
                            ->  Seq Scan on
ts_stats_transetgroup_user_daily b  (cost=0.00..80511.26 rows=247451
width=24)
(17 rows)

cemdb=# explain select * from ts_stats_transetgroup_user_daily a where
a.ts_id in (select b.ts_id from ts_stats_transetgroup_user_daily
b,ts_stats_transet_user_interval c, ts_transetgroup_transets_map m where
b.ts_transet_group_id = m.ts_transet_group_id and
m.ts_transet_incarnation_id = c.ts_transet_incarnation_id and
c.ts_user_incarnation_id = b.ts_user_incarnation_id and
c.ts_interval_start_time >= '2009-6-16 01:00' and
c.ts_interval_start_time < '2009-6-16 02:00') and a.ts_id >
600000000000030000 and a.ts_id < 600000000000040000 order by a.ts_id;

                             QUERY PLAN

----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
  Sort  (cost=138685.25..138696.81 rows=9247 width=779)
    Sort Key: a.ts_id
    ->  Hash IN Join  (cost=131710.94..138380.68 rows=9247 width=779)
          Hash Cond: (a.ts_id = b.ts_id)
          ->  Index Scan using ts_stats_transetgroup_user_daily_pkey on
ts_stats_transetgroup_user_daily a  (cost=0.00..6567.19 rows=9247 width=779)
                Index Cond: ((ts_id > 600000000000030000::bigint) AND
(ts_id < 600000000000040000::bigint))
          ->  Hash  (cost=130113.34..130113.34 rows=255616 width=8)
                ->  Hash Join  (cost=82370.45..130113.34 rows=255616
width=8)
                      Hash Cond: ((m.ts_transet_group_id =
b.ts_transet_group_id) AND (c.ts_user_incarnation_id =
b.ts_user_incarnation_id))
                      ->  Hash Join  (cost=3.32..29255.47 rows=229502
width=16)
                            Hash Cond: (c.ts_transet_incarnation_id =
m.ts_transet_incarnation_id)
                            ->  Index Scan using
ts_stats_transet_user_interval_starttime on
ts_stats_transet_user_interval c  (cost=0.00..27674.33 rows=229502 width=16)
                                  Index Cond: ((ts_interval_start_time
 >= '2009-06-16 01:00:00-07'::timestamp with time zone) AND
(ts_interval_start_time < '2009-06-16 02:00:00-07'::timestamp with time
zone))
                            ->  Hash  (cost=2.58..2.58 rows=117 width=16)
                                  ->  Seq Scan on
ts_transetgroup_transets_map m  (cost=0.00..2.58 rows=117 width=16)
                      ->  Hash  (cost=80511.26..80511.26 rows=247451
width=24)
                            ->  Seq Scan on
ts_stats_transetgroup_user_daily b  (cost=0.00..80511.26 rows=247451
width=24)
(17 rows)

cemdb=# explain select * from ts_stats_transetgroup_user_daily a where
a.ts_id in (select b.ts_id from ts_stats_transetgroup_user_daily
b,ts_stats_transet_user_interval c, ts_transetgroup_transets_map m where
b.ts_transet_group_id = m.ts_transet_group_id and
m.ts_transet_incarnation_id = c.ts_transet_incarnation_id and
c.ts_user_incarnation_id = b.ts_user_incarnation_id and
c.ts_interval_start_time >= '2009-6-16 01:00' and
c.ts_interval_start_time < '2009-6-16 02:00') and a.ts_id >
600000000000040000 and a.ts_id < 9223372036854775807 order by a.ts_id;

                          QUERY PLAN

----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
  Merge IN Join  (cost=141592.81..290873.68 rows=209136 width=779)
    Merge Cond: (a.ts_id = b.ts_id)
    ->  Index Scan using ts_stats_transetgroup_user_daily_pkey on
ts_stats_transetgroup_user_daily a  (cost=0.00..147334.73 rows=209136
width=779)
          Index Cond: ((ts_id > 600000000000040000::bigint) AND (ts_id <
9223372036854775807::bigint))
    ->  Sort  (cost=141592.81..141912.33 rows=255616 width=8)
          Sort Key: b.ts_id
          ->  Hash Join  (cost=82370.45..130113.34 rows=255616 width=8)
                Hash Cond: ((m.ts_transet_group_id =
b.ts_transet_group_id) AND (c.ts_user_incarnation_id =
b.ts_user_incarnation_id))
                ->  Hash Join  (cost=3.32..29255.47 rows=229502 width=16)
                      Hash Cond: (c.ts_transet_incarnation_id =
m.ts_transet_incarnation_id)
                      ->  Index Scan using
ts_stats_transet_user_interval_starttime on
ts_stats_transet_user_interval c  (cost=0.00..27674.33 rows=229502 width=16)
                            Index Cond: ((ts_interval_start_time >=
'2009-06-16 01:00:00-07'::timestamp with time zone) AND
(ts_interval_start_time < '2009-06-16 02:00:00-07'::timestamp with time
zone))
                      ->  Hash  (cost=2.58..2.58 rows=117 width=16)
                            ->  Seq Scan on ts_transetgroup_transets_map
m  (cost=0.00..2.58 rows=117 width=16)
                ->  Hash  (cost=80511.26..80511.26 rows=247451 width=24)
                      ->  Seq Scan on ts_stats_transetgroup_user_daily b
  (cost=0.00..80511.26 rows=247451 width=24)
(16 rows)



Re: very slow selects on a small table

From
Grzegorz Jaśkiewicz
Date:
On Thu, Jun 18, 2009 at 6:06 PM, Brian Cox<brian.cox@ca.com> wrote:

> these queries are still running now 27.5 hours later... These queries are
> generated by some java code and in putting it into a test program so I could
> capture the queries, I failed to get the id range correct -- sorry for
> wasting your time with bogus data. Below is the EXPLAIN output from the 4
> correct queries. I can't tell which one is being executed by PID 7397, but
> the query plans, except the last, do look very similar. In any event, as I
> mentioned, all 4 are still running.
this might be quite bogus question, just a hit - but what is your
work_mem set to ?
Guys, isn't postgresql giving hudge cost, when it can't sort in memory ?

--
GJ

Re: very slow selects on a small table

From
Brian Cox
Date:
Grzegorz Jakiewicz [gryzman@gmail.com] wrote:
> this might be quite bogus question, just a hit - but what is your
> work_mem set to ?
> Guys, isn't postgresql giving hudge cost, when it can't sort in memory ?
work_mem = 64MB

Re: very slow selects on a small table

From
Grzegorz Jaśkiewicz
Date:


On Thu, Jun 18, 2009 at 6:16 PM, Brian Cox <brian.cox@ca.com> wrote:
Grzegorz Jakiewicz [gryzman@gmail.com] wrote:
this might be quite bogus question, just a hit - but what is your
work_mem set to ?
Guys, isn't postgresql giving hudge cost, when it can't sort in memory ?
work_mem = 64MB
try increasing it please, to say 256MB

8.4 in explain analyze actually informs you whether sorting was done on disc or in memory, but you probably don't run stuff on cutting edge ;)



--
GJ

Re: very slow selects on a small table

From
Tom Lane
Date:
Brian Cox <brian.cox@ca.com> writes:
> these queries are still running now 27.5 hours later... These queries
> are generated by some java code and in putting it into a test program so
> I could capture the queries, I failed to get the id range correct --
> sorry for wasting your time with bogus data. Below is the EXPLAIN output
> from the 4 correct queries. I can't tell which one is being executed by
> PID 7397, but the query plans, except the last, do look very similar. In
> any event, as I mentioned, all 4 are still running.

Strange as can be.  Can you do an EXPLAIN ANALYZE on just the IN's
sub-select and confirm that the runtime of that is reasonable?  I'd
be interested to know how many rows it really returns, too.

One thing that strikes me is that the cost estimates seem a bit on the
low side for the rowcounts.  Are you using nondefault planner cost
parameters, and if so what?

            regards, tom lane