Thread: very slow selects on a small table
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.
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
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
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
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)
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
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
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
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)
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
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)
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
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
On Thu, Jun 18, 2009 at 6:16 PM, Brian Cox <brian.cox@ca.com> wrote:
try increasing it please, to say 256MBGrzegorz Jakiewicz [gryzman@gmail.com] wrote:work_mem = 64MBthis 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 ?
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
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