Received: from maia.hub.org (unknown [200.46.208.211]) by mail.postgresql.org (Postfix) with ESMTP id 36A69633731 for ; Mon, 5 Apr 2010 22:02:30 -0300 (ADT) Received: from mail.postgresql.org ([200.46.204.86]) by maia.hub.org (mx1.hub.org [200.46.208.211]) (amavisd-maia, port 10024) with ESMTP id 01439-07 for ; Tue, 6 Apr 2010 01:02:11 +0000 (UTC) X-Greylist: from auto-whitelisted by SQLgrey-1.7.6 Received: from smtp1.ca.com (smtp1.ca.com [141.202.248.21]) by mail.postgresql.org (Postfix) with ESMTP id 8EEBC632CA6 for ; Mon, 5 Apr 2010 22:02:19 -0300 (ADT) Received: from athena.ca.com ([130.200.164.17]) by smtp1.ca.com with Microsoft SMTPSVC(6.0.3790.3959); Mon, 5 Apr 2010 21:02:13 -0400 Message-ID: <4BBA87DC.1030205@ca.com> Date: Mon, 05 Apr 2010 18:01:16 -0700 From: Brian Cox User-Agent: Mozilla/5.0 (X11; U; Linux i686; en-US; rv:1.9.1.5) Gecko/20091204 Lightning/1.0b1 Thunderbird/3.0 MIME-Version: 1.0 To: "pgsql-performance@postgresql.org" Subject: query slow; strace output worrisome Content-Type: text/plain; charset=ISO-8859-1; format=flowed Content-Transfer-Encoding: 7bit X-OriginalArrivalTime: 06 Apr 2010 01:02:14.0432 (UTC) FILETIME=[CB915A00:01CAD524] X-Virus-Scanned: Maia Mailguard 1.0.1 X-Spam-Status: No, hits=0.779 tagged_above=-10 required=5 tests=AWL=0.778, BAYES_50=0.001 X-Spam-Level: X-Archive-Number: 201004/42 X-Sequence-Number: 38292 The SELECT show below has been running for 30+mins and the strace output is alarming: [root@dione ~]# strace -p 10083 Process 10083 attached - interrupt to quit creat(umovestr: Input/output error 0x2, 037777777777) = 1025220608 creat(umovestr: Input/output error 0x2, 037777777777) = 1025220608 creat(umovestr: Input/output error 0x2, 037777777777) = 1025220608 creat(NULL, 037777777777) = 216203264 restart_syscall(<... resuming interrupted call ...>) = 8192 creat(umovestr: Input/output error 0x2, 037777777777) = 1025220608 creat(umovestr: Input/output error 0x2, 037777777777) = 1025220608 creat(umovestr: Input/output error 0x2, 037777777777) = 1025220608 creat(umovestr: Input/output error 0x2, 037777777777) = 1025220608 however, I can find no indication of I/O errors in the postgres log. Anyone have any idea what's going on here? postgres 8.3.7 [root@dione ~]# uname -a Linux dione.ca.com 2.6.18-164.el5 #1 SMP Tue Aug 18 15:51:48 EDT 2009 x86_64 x86_64 x86_64 GNU/Linux Thanks, Brian top: PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND 10083 postgres 25 0 2288m 822m 817m R 100.0 1.7 28:08.79 postgres cemdb=# select procpid,query_start,current_query from pg_stat_activity; 10083 | 2010-04-05 17:18:34.989022-07 | select b.ts_id from ts_stats_transetgroup_usergroup_daily b , ts_stats_transet_user_interval c, ts_transetgroup_transets_map tm, ts_usergroup_users_map um where b.ts_transet_group_id = tm.ts_transet_group_id and tm.ts_transet_incarnation_id = c.ts_transet_incarnation_id and b.ts_usergroup_id = um.ts_usergroup_id and um.ts_user_incarnation_id = c.ts_user_incarnation_id and c.ts_interval_start_time >= '2010-03-29 21:00' and c.ts_interval_start_time < '2010-03-29 22:00' and b.ts_interval_start_time >= '2010-03-29 00:00' and b.ts_interval_start_time < '2010-03-30 00:00' cemdb=# explain select b.ts_id from ts_stats_transetgroup_usergroup_daily b , ts_stats_transet_user_interval c, ts_transetgroup_transets_map tm, ts_usergroup_users_map um where b.ts_transet_group_id = tm.ts_transet_group_id and tm.ts_transet_incarnation_id = c.ts_transet_incarnation_id and b.ts_usergroup_id = um.ts_usergroup_id and um.ts_user_incarnation_id = c.ts_user_incarnation_id and c.ts_interval_start_time >= '2010-03-29 21:00' and c.ts_interval_start_time < '2010-03-29 22:00' and b.ts_interval_start_time >= '2010-03-29 00:00' and b.ts_interval_start_time < '2010-03-30 00:00'; QUERY PLAN --------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------- Hash Join (cost=1169.95..7046.23 rows=1 width=8) Hash Cond: ((b.ts_transet_group_id = tm.ts_transet_group_id) AND (c.ts_transet_incarnation_id = tm.ts_transet_incarnation_id)) -> Nested Loop (cost=1159.95..7036.15 rows=10 width=24) -> Nested Loop (cost=0.00..28.16 rows=6 width=24) -> Index Scan using ts_stats_transetgroup_usergroup_daily_starttimeindex on ts_stats_transetgroup_usergroup_daily b (cost=0.00..8.86 rows=1 width=24) Index Cond: ((ts_interval_start_time >= '2010-03-29 00:00:00-07'::timestamp with time zone) AND (ts_interval_start_time < '2010-03-30 00:00:00-07'::timestamp with time zone)) -> Index Scan using ts_usergroup_users_map_usergroupindex on ts_usergroup_users_map um (cost=0.00..19.23 rows=6 width=16) Index Cond: (um.ts_usergroup_id = b.ts_usergroup_id) -> Bitmap Heap Scan on ts_stats_transet_user_interval c (cost=1159.95..1167.97 rows=2 width=16) Recheck Cond: ((c.ts_user_incarnation_id = um.ts_user_incarnation_id) AND (c.ts_interval_start_time >= '2010-03-29 21:00:00-07'::timestamp with time zone) AND (c.ts_interval_start_time < '2010-03-29 22:00:00-07'::timestamp with time zone)) -> BitmapAnd (cost=1159.95..1159.95 rows=2 width=0) -> Bitmap Index Scan on ts_stats_transet_user_interval_userincarnationidindex (cost=0.00..14.40 rows=438 width=0) Index Cond: (c.ts_user_incarnation_id = um.ts_user_incarnation_id) -> Bitmap Index Scan on ts_stats_transet_user_interval_starttime (cost=0.00..1134.09 rows=44856 width=0) Index Cond: ((c.ts_interval_start_time >= '2010-03-29 21:00:00-07'::timestamp with time zone) AND (c.ts_interval_start_time < '2010-03-29 22:00:00-07'::timestamp with time zone)) -> Hash (cost=7.00..7.00 rows=200 width=16) -> Seq Scan on ts_transetgroup_transets_map tm (cost=0.00..7.00 rows=200 width=16) (17 rows)