Re: [PERFORM] VACUUMs take twice as long across all nodes

2006-10-27 Thread Gavin Hamill
On Thu, 26 Oct 2006 18:09:37 -0400
Andrew Sullivan [EMAIL PROTECTED] wrote:

 On Thu, Oct 26, 2006 at 09:35:56PM +0100, Gavin Hamill wrote:
  
  I'm absolutely certain. The backups run from only one slave, given
  that it is a full copy of node 1. Our overnight traffic has not
  increased any, and the nightly backups show that the overall size
  of the DB has not increased more than usual growth.
 
 A couple things from your posts:
 
 1.Don't do VACUUM FULL, please.  It takes longer, and blocks
 other things while it's going on, which might mean you're having
 table bloat in various slony-related tables.

I know it takes longer, I know it blocks. It's never been a problem

 2.Are your slony logs showing increased time too?  Are your
 targets getting further behind?

Nope, the slaves are keeping up just great - once the vacuums are
finished, all machines are running at about 50%-75% of full load in
duty.
 
 3.Your backups from the slave aren't done with pg_dump,
 right?

Em, they are indeed. I assumed that MVCC would ensure I got a
consistent snapshot from the instant when pg_dump began. Am I wrong?

 But I suspect Slony has a role here, too.  I'd look carefully at the
 slony tables -- especially the sl_log and pg_listen things, which
 both are implicated.

Slony is an easy target to point the finger at, so I tried a
little test. I took one of the 'light' slaves (only 10 tables..),
stopped its slon daemon, removed it from the load-balancer, and
restarted postgres so there were no active connections.

With the removal of both replication overhead and normal queries from
clients, the machine should be completely clear to run at full tilt.

Then I launched a 'vacuum verbose' and I was able to see exactly the
same poor speeds as before, even with vacuum_cost_delay = 0 as it was
previously...

2006-10-27 08:37:12 UTC INFO:  vacuuming public.Allocation
2006-10-27 08:37:21 UTC INFO:  Allocation: found 56449 removable, 4989360 
nonremovable row versions in 47158 pages
2006-10-27 08:37:21 UTC DETAIL:  0 dead row versions cannot be removed yet.
Nonremovable row versions range from 64 to 72 bytes long.
There were 1 unused item pointers.
Total free space (including removable row versions) is 5960056 bytes.
13 pages are or will become empty, including 0 at the end of the table.
5258 pages containing 4282736 free bytes are potential move 
destinations.
CPU 0.16s/0.07u sec elapsed 9.55 sec.
2006-10-27 08:44:25 UTC INFO:  index allocation_pkey now contains 4989360 row 
versions in 102198 pages
2006-10-27 08:44:25 UTC DETAIL:  56449 index row versions were removed.
1371 index pages have been deleted, 1371 are currently reusable.
CPU 1.02s/0.38u sec elapsed 423.22 sec.

If I've read this correctly, then on an otherwise idle system, it has taken 
seven minutes to perform 1.4 seconds-worth of actual work. Surely that's 
nonsense? 

That would suggest that the issue is poor IO; vmstat 5 output during this run 
wasn't ripping performance - maybe averaging 3MB/sec in and out. 

I know the peak IO on this machine is rather much better than that:

joltpg2:/root# dd if=/dev/zero of=/tmp/t bs=1024k count=1000
1000+0 records in
1000+0 records out
1048576000 bytes (1.0 GB) copied, 8.02106 seconds, 131 MB/s

The test system is one CPU's-worth (two cores) of a 4 x Opteron 880 machine 
split up by Xen, and I can confirm the IO on the other Xen partitions was 
minimal.

I appreciate the time, help and advice people are offering, however I really 
don't think Slony is the culprit here.

Cheers,
Gavin.

---(end of broadcast)---
TIP 1: if posting/reading through Usenet, please send an appropriate
   subscribe-nomail command to [EMAIL PROTECTED] so that your
   message can get through to the mailing list cleanly


[PERFORM] query produces 1 GB temp file

2006-10-27 Thread Dirk Lutzebaeck

Hi,

here is a query which produces over 1G temp file in pgsql_tmp. This
is on pgsql 7.4.2, RHEL 3.0, XEON MP machine with 32GB RAM, 300MB
sort_mem and 320MB shared_mem.

Below is the query and results for EXPLAIN and EXPLAIN ANALYZE. All
tables have been analyzed before.

Can some please explain why the temp file is so huge? I understand
there are a lot of rows. All relevant indices seem to be used.

Thanks in advance,

Dirk

EXPLAIN 
SELECT DISTINCT ON (ft.val_9, ft.created, ft.flatid) ft.docstart, ft.flatobj, 
bi.oid, bi.en
FROM bi, en, df AS ft, es
WHERE bi.rc=130170467
AND bi.en=ft.en
AND bi.co=117305223
AND bi.hide=FALSE
AND ft.en=en.oid
AND es.en=bi.en
AND es.co=bi.co
AND es.spec=122293729
AND (ft.val_2='DG' OR ft.val_2='SK')
AND ft.docstart=1
ORDER BY ft.val_9 ASC, ft.created DESC
LIMIT 1000 OFFSET 0;

 Limit  (cost=8346.75..8346.78 rows=3 width=1361)
   -  Unique  (cost=8346.75..8346.78 rows=3 width=1361)
 -  Sort  (cost=8346.75..8346.76 rows=3 width=1361)
   Sort Key: ft.val_9, ft.created, ft.flatid
   -  Nested Loop  (cost=0.00..8346.73 rows=3 width=1361)
 -  Nested Loop  (cost=0.00..5757.17 rows=17 width=51)
   -  Nested Loop  (cost=0.00..5606.39 rows=30 
width=42)
 -  Index Scan using es_sc_index on es  
(cost=0.00..847.71 rows=301 width=8)
   Index Cond: ((spec = 122293729) AND (co 
= 117305223::oid))
 -  Index Scan using bi_env_index on bi  
(cost=0.00..15.80 rows=1 width=42)
   Index Cond: (outer.en = bi.en)
   Filter: ((rc = 130170467::oid) AND (co = 
117305223::oid) AND (hide = false))
   -  Index Scan using en_oid_index on en  
(cost=0.00..5.01 rows=1 width=9)
 Index Cond: (outer.en = en.oid)
 -  Index Scan using df_en on df ft  (cost=0.00..151.71 
rows=49 width=1322)
   Index Cond: (outer.en = ft.en)
   Filter: (((val_2 = 'DG'::text) OR (val_2 = 
'SK'::text)) AND (docstart = 1))
(17 rows)


--

EXPLAIN ANALYZE gives:


 Limit  (cost=8346.75..8346.78 rows=3 width=1361) (actual 
time=75357.465..75679.964 rows=1000 loops=1)
   -  Unique  (cost=8346.75..8346.78 rows=3 width=1361) (actual 
time=75357.459..75675.371 rows=1000 loops=1)
 -  Sort  (cost=8346.75..8346.76 rows=3 width=1361) (actual 
time=75357.448..75499.263 rows=22439 loops=1)
   Sort Key: ft.val_9, ft.created, ft.flatid
   -  Nested Loop  (cost=0.00..8346.73 rows=3 width=1361) (actual 
time=34.104..18016.005 rows=703677 loops=1)
 -  Nested Loop  (cost=0.00..5757.17 rows=17 width=51) 
(actual time=0.467..3216.342 rows=48563 loops=1)
   -  Nested Loop  (cost=0.00..5606.39 rows=30 
width=42) (actual time=0.381..1677.014 rows=48563 loops=1)
 -  Index Scan using es_sc_index on es  
(cost=0.00..847.71 rows=301 width=8) (actual time=0.184..46.519 rows=5863 
loops=1)
   Index Cond: ((spec = 122293729) AND (co 
= 117305223::oid))
 -  Index Scan using bi_env_index on bi  
(cost=0.00..15.80 rows=1 width=42) (actual time=0.052..0.218 rows=8 loops=5863)
   Index Cond: (outer.en = bi.en)
   Filter: ((rc = 130170467::oid) AND (co = 
117305223::oid) AND (hide = false))
   -  Index Scan using en_oid_index on en  
(cost=0.00..5.01 rows=1 width=9) (actual time=0.015..0.019 rows=1 loops=48563)
 Index Cond: (outer.en = en.oid)
 -  Index Scan using df_en on df ft  (cost=0.00..151.71 
rows=49 width=1322) (actual time=0.038..0.148 rows=14 loops=48563)
   Index Cond: (outer.en = ft.en)
   Filter: (((val_2 = 'DG'::text) OR (val_2 = 
'SK'::text)) AND (docstart = 1))
 Total runtime: 81782.052 ms
(18 rows)


---(end of broadcast)---
TIP 5: don't forget to increase your free space map settings


[PERFORM] client crashes in PQfinish

2006-10-27 Thread soni de
Hello,

My Server is crashed in PQfinish. Below is the core file details:

=[1] DLRemHead(0x2b7780, 0xfb6bc008, 0x319670, 0xfb6bc008, 0x21c40, 0x3106f8), at 0xfded10e4 [2] DLFreeList(0x2b7780, 0x0, 0x417b48, 0xfdec5aa4, 0x21c18, 0x0), at 0xfded0c64 [3] freePGconn(0x371ea0, 0x0, 0x289f48, 0xfbfb61b8, 0x21c18, 0x0), at 0xfdec5ac0
 [4] PQfinish(0x371ea0, 0x289ce8, 0x289ce8, 0xf9a0b65c, 0x20fa0, 0xfb0718dc), at 0xfdec5cc4 [5] abc(0x289ce0, 0xfafec000, 0xfb5b1d88, 0x0, 0xf9a0ba8c, 0x7), at 0xfb071aec

Server is crashed at DLRemHead. This crash is not easily reproducible.

Can anybody please tell me whether above problem is related to postgres or not?

Thanks,
Sonal


Re: [PERFORM] Regarding Bitmap Scan

2006-10-27 Thread soni de
Thanks a lot for your help.

Thanks,
Soni
On 10/17/06, Dawid Kuroczko [EMAIL PROTECTED] wrote:
On 10/17/06, soni de 
[EMAIL PROTECTED] wrote: 
 


I didn't understand theBitmap Scan andthe sentence indexes will be dynamically converted to bitmaps in memory. What does mean by Bitmap Scan in database? 


Can anybody help us regarding above query?

Assume you have a table:CREATE TABLE foo ( some_key int, some_time timestamp with time zone, some_data text);And two indexes:CREATE INDEX foo_key ON foo (some_key);CREATE INDEX foo_time ON foo (some_time);
Now, you make a query:SELECT * from foo WHERE some_key  10 AND some_time  '2006-10-01'::timestamptz;...originally planner would choose only one index to use -- and would use theone which it think its best.
The 8.1 version does differently: It will scan foo_key index -- make a bitmap out of it,scan foo_time index -- make another bitmap out of it, binary AND these bitmaps,and will read the data from the table using such combined bitmap. It could as well
use OR if you used OR in your query.Hence -- it can be faster, especially for large tables and selective queries.Regards, DAwid


Re: [PERFORM] query produces 1 GB temp file

2006-10-27 Thread Merlin Moncure

On 2/5/05, Dirk Lutzebaeck [EMAIL PROTECTED] wrote:

here is a query which produces over 1G temp file in pgsql_tmp. This
is on pgsql 7.4.2, RHEL 3.0, XEON MP machine with 32GB RAM, 300MB
sort_mem and 320MB shared_mem.

Below is the query and results for EXPLAIN and EXPLAIN ANALYZE. All
tables have been analyzed before.

Can some please explain why the temp file is so huge? I understand
there are a lot of rows. All relevant indices seem to be used.


how much memory have you set aside for sorting? also, this query will
likely run better in a more recent version of postgresql if thats
possible.

merlin

---(end of broadcast)---
TIP 3: Have you checked our extensive FAQ?

  http://www.postgresql.org/docs/faq


Re: [PERFORM] query produces 1 GB temp file

2006-10-27 Thread Bricklen Anderson

Merlin Moncure wrote:

On 2/5/05, Dirk Lutzebaeck [EMAIL PROTECTED] wrote:

snip
Was the original message actually from 2/5/05?

---(end of broadcast)---
TIP 1: if posting/reading through Usenet, please send an appropriate
  subscribe-nomail command to [EMAIL PROTECTED] so that your
  message can get through to the mailing list cleanly


Re: [PERFORM] query produces 1 GB temp file

2006-10-27 Thread Alexander Staubo
While I can't explain why PostgreSQL would use that memory, I  
recommend looking into tweaking the work_mem parameter. This setting  
specifies how much memory PostgreSQL on certain temporary data  
structures (hash tables, sort vectors) until it starts using  
temporary files. Quoting the docs:



work_mem (integer)
Specifies the amount of memory to be used by internal sort  
operations and hash tables before switching to temporary disk  
files. The value is specified in kilobytes, and defaults to 1024  
kilobytes (1 MB). Note that for a complex query, several sort or  
hash operations might be running in parallel; each one will be  
allowed to use as much memory as this value specifies before it  
starts to put data into temporary files. Also, several running  
sessions could be doing such operations concurrently. So the total  
memory used could be many times the value of work_mem; it is  
necessary to keep this fact in mind when choosing the value. Sort  
operations are used for ORDER BY, DISTINCT, and merge joins. Hash  
tables are used in hash joins, hash-based aggregation, and hash- 
based processing of IN subqueries.


Alexander.

On Feb 5, 2005, at 18:25 , Dirk Lutzebaeck wrote:


Hi,

here is a query which produces over 1G temp file in pgsql_tmp. This
is on pgsql 7.4.2, RHEL 3.0, XEON MP machine with 32GB RAM, 300MB
sort_mem and 320MB shared_mem.

Below is the query and results for EXPLAIN and EXPLAIN ANALYZE. All
tables have been analyzed before.

Can some please explain why the temp file is so huge? I understand
there are a lot of rows. All relevant indices seem to be used.

Thanks in advance,

Dirk

EXPLAIN
SELECT DISTINCT ON (ft.val_9, ft.created, ft.flatid) ft.docstart,  
ft.flatobj, bi.oid, bi.en

FROM bi, en, df AS ft, es
WHERE bi.rc=130170467
AND bi.en=ft.en
AND bi.co=117305223
AND bi.hide=FALSE
AND ft.en=en.oid
AND es.en=bi.en
AND es.co=bi.co
AND es.spec=122293729
AND (ft.val_2='DG' OR ft.val_2='SK')
AND ft.docstart=1
ORDER BY ft.val_9 ASC, ft.created DESC
LIMIT 1000 OFFSET 0;

 Limit  (cost=8346.75..8346.78 rows=3 width=1361)
   -  Unique  (cost=8346.75..8346.78 rows=3 width=1361)
 -  Sort  (cost=8346.75..8346.76 rows=3 width=1361)
   Sort Key: ft.val_9, ft.created, ft.flatid
   -  Nested Loop  (cost=0.00..8346.73 rows=3 width=1361)
 -  Nested Loop  (cost=0.00..5757.17 rows=17  
width=51)
   -  Nested Loop  (cost=0.00..5606.39  
rows=30 width=42)
 -  Index Scan using es_sc_index  
on es  (cost=0.00..847.71 rows=301 width=8)
   Index Cond: ((spec =  
122293729) AND (co = 117305223::oid))
 -  Index Scan using bi_env_index  
on bi  (cost=0.00..15.80 rows=1 width=42)
   Index Cond: (outer.en =  
bi.en)
   Filter: ((rc =  
130170467::oid) AND (co = 117305223::oid) AND (hide = false))
   -  Index Scan using en_oid_index on en   
(cost=0.00..5.01 rows=1 width=9)

 Index Cond: (outer.en = en.oid)
 -  Index Scan using df_en on df ft   
(cost=0.00..151.71 rows=49 width=1322)

   Index Cond: (outer.en = ft.en)
   Filter: (((val_2 = 'DG'::text) OR (val_2  
= 'SK'::text)) AND (docstart = 1))

(17 rows)


--

EXPLAIN ANALYZE gives:


 Limit  (cost=8346.75..8346.78 rows=3 width=1361) (actual  
time=75357.465..75679.964 rows=1000 loops=1)
   -  Unique  (cost=8346.75..8346.78 rows=3 width=1361) (actual  
time=75357.459..75675.371 rows=1000 loops=1)
 -  Sort  (cost=8346.75..8346.76 rows=3 width=1361)  
(actual time=75357.448..75499.263 rows=22439 loops=1)

   Sort Key: ft.val_9, ft.created, ft.flatid
   -  Nested Loop  (cost=0.00..8346.73 rows=3  
width=1361) (actual time=34.104..18016.005 rows=703677 loops=1)
 -  Nested Loop  (cost=0.00..5757.17 rows=17  
width=51) (actual time=0.467..3216.342 rows=48563 loops=1)
   -  Nested Loop  (cost=0.00..5606.39  
rows=30 width=42) (actual time=0.381..1677.014 rows=48563 loops=1)
 -  Index Scan using es_sc_index  
on es  (cost=0.00..847.71 rows=301 width=8) (actual  
time=0.184..46.519 rows=5863 loops=1)
   Index Cond: ((spec =  
122293729) AND (co = 117305223::oid))
 -  Index Scan using bi_env_index  
on bi  (cost=0.00..15.80 rows=1 width=42) (actual time=0.052..0.218  
rows=8 loops=5863)
   Index Cond: (outer.en =  
bi.en)
   Filter: ((rc =  
130170467::oid) AND (co = 117305223::oid) AND (hide = false))
   -  Index Scan using en_oid_index on en   
(cost=0.00..5.01 rows=1 width=9) (actual time=0.015..0.019 rows=1  

Re: [PERFORM] query produces 1 GB temp file

2006-10-27 Thread Dirk Lutzebäck




Hi,

I'm sorry but it look like my computer has resent older posts from me,
sigh...


Dirk

Alexander Staubo wrote:
While I can't explain why PostgreSQL would use that
memory, I recommend looking into tweaking the work_mem parameter. This
setting specifies how much memory PostgreSQL on certain temporary data
structures (hash tables, sort vectors) until it starts using temporary
files. Quoting the docs:
  
  
  work_mem (integer)

Specifies the amount of memory to be used by internal sort operations
and hash tables before switching to temporary disk files. The value is
specified in kilobytes, and defaults to 1024 kilobytes (1 MB). Note
that for a complex query, several sort or hash operations might be
running in parallel; each one will be allowed to use as much memory as
this value specifies before it starts to put data into temporary files.
Also, several running sessions could be doing such operations
concurrently. So the total memory used could be many times the value of
work_mem; it is necessary to keep this fact in mind when choosing the
value. Sort operations are used for ORDER BY, DISTINCT, and merge
joins. Hash tables are used in hash joins, hash-based aggregation, and
hash-based processing of IN subqueries.

  
  
Alexander.
  
  
On Feb 5, 2005, at 18:25 , Dirk Lutzebaeck wrote:
  
  
  Hi,


here is a query which produces over 1G temp file in pgsql_tmp. This

is on pgsql 7.4.2, RHEL 3.0, XEON MP machine with 32GB RAM, 300MB

sort_mem and 320MB shared_mem.


Below is the query and results for EXPLAIN and EXPLAIN ANALYZE. All

tables have been analyzed before.


Can some please explain why the temp file is so huge? I understand

there are a lot of rows. All relevant indices seem to be used.


Thanks in advance,


Dirk


EXPLAIN

SELECT DISTINCT ON (ft.val_9, ft.created, ft.flatid) ft.docstart,
ft.flatobj, bi.oid, bi.en

FROM bi, en, df AS ft, es

WHERE bi.rc=130170467

AND bi.en=ft.en

AND bi.co=117305223

AND bi.hide=FALSE

AND ft.en=en.oid

AND es.en=bi.en

AND es.co=bi.co

AND es.spec=122293729

AND (ft.val_2='DG' OR ft.val_2='SK')

AND ft.docstart=1

ORDER BY ft.val_9 ASC, ft.created DESC

LIMIT 1000 OFFSET 0;


Limit (cost=8346.75..8346.78 rows=3 width=1361)

 - Unique (cost=8346.75..8346.78 rows=3 width=1361)

 - Sort (cost=8346.75..8346.76 rows=3 width=1361)

 Sort Key: ft.val_9, ft.created, ft.flatid

 - Nested Loop (cost=0.00..8346.73 rows=3
width=1361)

 - Nested Loop (cost=0.00..5757.17 rows=17
width=51)

 - Nested Loop (cost=0.00..5606.39
rows=30 width=42)

 - Index Scan using es_sc_index on
es (cost=0.00..847.71 rows=301 width=8)

 Index Cond: ((spec = 122293729)
AND (co = 117305223::oid))

 - Index Scan using bi_env_index
on bi (cost=0.00..15.80 rows=1 width=42)

 Index Cond: ("outer".en = bi.en)

 Filter: ((rc = 130170467::oid)
AND (co = 117305223::oid) AND (hide = false))

 - Index Scan using en_oid_index on en
(cost=0.00..5.01 rows=1 width=9)

 Index Cond: ("outer".en = en.oid)

 - Index Scan using df_en on df ft
(cost=0.00..151.71 rows=49 width=1322)

 Index Cond: ("outer".en = ft.en)

 Filter: (((val_2 = 'DG'::text) OR (val_2 =
'SK'::text)) AND (docstart = 1))

(17 rows)



--


EXPLAIN ANALYZE gives:



Limit (cost=8346.75..8346.78 rows=3 width=1361) (actual
time=75357.465..75679.964 rows=1000 loops=1)

 - Unique (cost=8346.75..8346.78 rows=3 width=1361) (actual
time=75357.459..75675.371 rows=1000 loops=1)

 - Sort (cost=8346.75..8346.76 rows=3 width=1361) (actual
time=75357.448..75499.263 rows=22439 loops=1)

 Sort Key: ft.val_9, ft.created, ft.flatid

 - Nested Loop (cost=0.00..8346.73 rows=3
width=1361) (actual time=34.104..18016.005 rows=703677 loops=1)

 - Nested Loop (cost=0.00..5757.17 rows=17
width=51) (actual time=0.467..3216.342 rows=48563 loops=1)

 - Nested Loop (cost=0.00..5606.39
rows=30 width=42) (actual time=0.381..1677.014 rows=48563 loops=1)

 - Index Scan using es_sc_index on
es (cost=0.00..847.71 rows=301 width=8) (actual time=0.184..46.519
rows=5863 loops=1)

 Index Cond: ((spec = 122293729)
AND (co = 117305223::oid))

 - Index Scan using bi_env_index
on bi (cost=0.00..15.80 rows=1 width=42) (actual time=0.052..0.218
rows=8 loops=5863)

 Index Cond: ("outer".en = bi.en)

 Filter: ((rc = 130170467::oid)
AND (co = 117305223::oid) AND (hide = false))

 - Index Scan using en_oid_index on en
(cost=0.00..5.01 rows=1 width=9) (actual time=0.015..0.019 rows=1
loops=48563)

 Index Cond: ("outer".en = en.oid)

 - Index Scan using df_en on df ft
(cost=0.00..151.71 rows=49 width=1322) (actual time=0.038..0.148
rows=14 loops=48563)

 Index Cond: ("outer".en = ft.en)

 Filter: (((val_2 = 'DG'::text) OR (val_2 =
'SK'::text)) AND (docstart = 1))

Total 

Re: [PERFORM] query produces 1 GB temp file

2006-10-27 Thread Thomas Burdairon
He is probably using IPOT (IP Other Time) : http://kadreg.free.fr/ipot/  :-) (sorry only french page ) On Oct 27, 2006, at 16:33, Bricklen Anderson wrote:Merlin Moncure wrote: On 2/5/05, Dirk Lutzebaeck [EMAIL PROTECTED] wrote: snipWas the original message actually from 2/5/05?---(end of broadcast)---TIP 1: if posting/reading through Usenet, please send an appropriate      subscribe-nomail command to [EMAIL PROTECTED] so that your      message can get through to the mailing list cleanly 

Re: [PERFORM] query produces 1 GB temp file

2006-10-27 Thread Scott Marlowe
On Sat, 2005-02-05 at 11:25, Dirk Lutzebaeck wrote:
 Hi,
 
 here is a query which produces over 1G temp file in pgsql_tmp. This
 is on pgsql 7.4.2, RHEL 3.0, XEON MP machine with 32GB RAM, 300MB
 sort_mem and 320MB shared_mem.

First step, upgrade to the latest 7.4.x version.  7.4.2 is an OLD
version of 7.4  I think the latest version is 7.4.13.

 Below is the query and results for EXPLAIN and EXPLAIN ANALYZE. All
 tables have been analyzed before.

SNIP

 EXPLAIN ANALYZE gives:
 
 
  Limit  (cost=8346.75..8346.78 rows=3 width=1361) (actual 
 time=75357.465..75679.964 rows=1000 loops=1)
-  Unique  (cost=8346.75..8346.78 rows=3 width=1361) (actual 
 time=75357.459..75675.371 rows=1000 loops=1)
  -  Sort  (cost=8346.75..8346.76 rows=3 width=1361) (actual 
 time=75357.448..75499.263 rows=22439 loops=1)
Sort Key: ft.val_9, ft.created, ft.flatid
-  Nested Loop  (cost=0.00..8346.73 rows=3 width=1361) 
 (actual time=34.104..18016.005 rows=703677 loops=1)
  -  Nested Loop  (cost=0.00..5757.17 rows=17 width=51) 
 (actual time=0.467..3216.342 rows=48563 loops=1)
-  Nested Loop  (cost=0.00..5606.39 rows=30 
 width=42) (actual time=0.381..1677.014 rows=48563 loops=1)
  -  Index Scan using es_sc_index on es  
 (cost=0.00..847.71 rows=301 width=8) (actual time=0.184..46.519 rows=5863 
 loops=1)
Index Cond: ((spec = 122293729) AND 
 (co = 117305223::oid))
  -  Index Scan using bi_env_index on bi  
 (cost=0.00..15.80 rows=1 width=42) (actual time=0.052..0.218 rows=8 
 loops=5863)
Index Cond: (outer.en = bi.en)
Filter: ((rc = 130170467::oid) AND (co 
 = 117305223::oid) AND (hide = false))
-  Index Scan using en_oid_index on en  
 (cost=0.00..5.01 rows=1 width=9) (actual time=0.015..0.019 rows=1 loops=48563)
  Index Cond: (outer.en = en.oid)
  -  Index Scan using df_en on df ft  (cost=0.00..151.71 
 rows=49 width=1322) (actual time=0.038..0.148 rows=14 loops=48563)
Index Cond: (outer.en = ft.en)
Filter: (((val_2 = 'DG'::text) OR (val_2 = 
 'SK'::text)) AND (docstart = 1))
  Total runtime: 81782.052 ms
 (18 rows)

Why do you have an index scan on en_oid_index that thinks it will return
1 row when it returns 48563, and one on df_en that thinks it will return
49 and returns 48563 as well?   Is this database analyzed often?  Are
oids even analyzed?  I'd really recommend switching off of them as they
complicate backups and restores.

If analyze doesn't help, you can try brute forcing off nested loops for
this query and see if that helps.  nested loop is really slow for large
numbers of rows.

---(end of broadcast)---
TIP 6: explain analyze is your friend


Re: [PERFORM] VACUUMs take twice as long across all nodes

2006-10-27 Thread Tom Lane
Gavin Hamill [EMAIL PROTECTED] writes:
 2006-10-27 08:37:12 UTC INFO:  vacuuming public.Allocation
 2006-10-27 08:37:21 UTC INFO:  Allocation: found 56449 removable, 4989360 
 nonremovable row versions in 47158 pages
 2006-10-27 08:37:21 UTC DETAIL:  0 dead row versions cannot be removed yet.
 Nonremovable row versions range from 64 to 72 bytes long.
 There were 1 unused item pointers.
 Total free space (including removable row versions) is 5960056 bytes.
 13 pages are or will become empty, including 0 at the end of the 
 table.
 5258 pages containing 4282736 free bytes are potential move 
 destinations.
 CPU 0.16s/0.07u sec elapsed 9.55 sec.
 2006-10-27 08:44:25 UTC INFO:  index allocation_pkey now contains 4989360 
 row versions in 102198 pages
 2006-10-27 08:44:25 UTC DETAIL:  56449 index row versions were removed.
 1371 index pages have been deleted, 1371 are currently reusable.
 CPU 1.02s/0.38u sec elapsed 423.22 sec.

So the time is all in index vacuuming, eh?  I think what's happening is
that the physical order of the index is degrading over time, and so the
vacuum scan takes longer due to more seeking.  Can you afford to do a
REINDEX?  If this theory is correct that should drive the time back
down.

8.2 has rewritten btree index vacuuming code that scans the index in
physical not logical order, so this problem should largely go away in
8.2, but in existing releases I can't see much you can do about it
except REINDEX when things get slow.

regards, tom lane

---(end of broadcast)---
TIP 6: explain analyze is your friend


Re: [PERFORM] Best COPY Performance

2006-10-27 Thread Worky Workerson

I do have a dirty little secret, one which I wasn't completely aware
of until a little while ago.  Apparently, someone decided to install
Oracle on the server, and use the SAN as the primary tablespace, so
that might have something to do with the poor performance of the SAN.
At least, I'm hoping that's what is involved.  I'll be able to tell
for sure when I can rerun the benchmarks on Monday without Oracle.

Thank you all for all your help so far.  I've learned a ton about
Postgres (and life!) from both this thread and this list in general,
and the support has been nothing less than spectacular.

I'm hoping that the corporate Oracle machine won't shut down my pg
projects.  On total side note, if anyone knows how to best limit
Oracle's impact on a system (i.e. memory usage, etc), I'd be
interested.

I hate shared DB servers.

Thanks!

---(end of broadcast)---
TIP 5: don't forget to increase your free space map settings


Re: [PERFORM] Best COPY Performance

2006-10-27 Thread Merlin Moncure

On 10/27/06, Worky Workerson [EMAIL PROTECTED] wrote:

I'm hoping that the corporate Oracle machine won't shut down my pg
projects.  On total side note, if anyone knows how to best limit
Oracle's impact on a system (i.e. memory usage, etc), I'd be
interested.



rm -rf /usr/local/oracle?

merlin

---(end of broadcast)---
TIP 4: Have you searched our list archives?

  http://archives.postgresql.org


Re: [PERFORM] Best COPY Performance

2006-10-27 Thread Worky Workerson

The read speed on your /data volume is awful to the point where you should
consider it broken and find a fix.  A quick comparison: the same number on a
16 drive internal SATA array with 7200 RPM disks gets 950 MB/s read, about
25 times faster for about 1/4 the price.


I'm hoping that the poor performance is a result of Oracle doing
random reads while I try and do the sequential read.  If not (I'll
test on Monday), I'll start looking other places.  Any immediate
suggestions?


Can you provide about 10 seconds worth of vmstat 1 while running your COPY
so we can get a global view of the I/O and CPU?


Here it is, taken from a spot about halfway through a 'cat file |
psql' load, with the Oracle-is-installed-and-running caveat:

r b   swpd  free   buffcache si so bibo   in   cs us sy id wa
1 0 345732 29328 770980 12947212  0  0 20 16552 1223 3677 12  2 85  1
1 0 345732 29840 770520 12946924  0  0 20 29244 1283 2955 11  2 85  1
1 0 345732 32144 770560 12944436  0  0 12 16436 1204 2936 11  2 86  1
1 0 345732 33744 770464 12942764  0  0 20 16460 1189 2005 10  2 86  1
2 0 345732 32656 770140 12943972  0  0 16  7068 1057 3434 13  2 85  0
1 0 345732 34832 770184 12941820  0  0 20  9368 1170 3120 11  2 86  1
1 0 345732 36528 770228 12939804  0  0 16 32668 1297 2109 11  2 85  1
1 0 345732 29304 770272 12946764  0  0 16 16428 1192 3105 12  2 85  1
1 0 345732 30840 770060 12945480  0  0 20 16456 1196 3151 12  2 84  1
1 0 345732 32760 769972 12943528  0  0 12 16460 1185 3103 11  2 86  1

---(end of broadcast)---
TIP 5: don't forget to increase your free space map settings


Re: [PERFORM] VACUUMs take twice as long across all nodes

2006-10-27 Thread Gavin Hamill
On Fri, 27 Oct 2006 14:07:43 -0400
Tom Lane [EMAIL PROTECTED] wrote:

 So the time is all in index vacuuming, eh?  I think what's happening
 is that the physical order of the index is degrading over time, and
 so the vacuum scan takes longer due to more seeking.  Can you afford
 to do a REINDEX?  If this theory is correct that should drive the
 time back down.

Tom,

You wonderful, wonderful man.

I tried a test reindex on Allocation, and noticed a vacuum had
turbo-charged... then reindexed the whole db, did a vacuum, and lo! The
whole db had turbo-charged :)

When I say 'turbo-charged', I mean it. The vacuum times have dropped to
20% of what we were seeing even before it 'got much slower a
couple of days ago.'

It sucks that the new reindex code is only in 8.2, but now that I know
this is an issue in 8.1 I can plan for it.

Thanks so much :)

Cheers,
Gavin.

---(end of broadcast)---
TIP 1: if posting/reading through Usenet, please send an appropriate
   subscribe-nomail command to [EMAIL PROTECTED] so that your
   message can get through to the mailing list cleanly


Re: [PERFORM] Best COPY Performance

2006-10-27 Thread Luke Lonergan
Worky (that your real name? :-)


On 10/27/06 12:08 PM, Worky Workerson [EMAIL PROTECTED] wrote:

 Here it is, taken from a spot about halfway through a 'cat file |
 psql' load, with the Oracle-is-installed-and-running caveat:
 
 r b   swpd  free   buffcache si so bibo   in   cs us sy id wa
 1 0 345732 29328 770980 12947212  0  0 20 16552 1223 3677 12  2 85  1
 1 0 345732 29840 770520 12946924  0  0 20 29244 1283 2955 11  2 85  1
 1 0 345732 32144 770560 12944436  0  0 12 16436 1204 2936 11  2 86  1
 1 0 345732 33744 770464 12942764  0  0 20 16460 1189 2005 10  2 86  1
 2 0 345732 32656 770140 12943972  0  0 16  7068 1057 3434 13  2 85  0
 1 0 345732 34832 770184 12941820  0  0 20  9368 1170 3120 11  2 86  1
 1 0 345732 36528 770228 12939804  0  0 16 32668 1297 2109 11  2 85  1
 1 0 345732 29304 770272 12946764  0  0 16 16428 1192 3105 12  2 85  1
 1 0 345732 30840 770060 12945480  0  0 20 16456 1196 3151 12  2 84  1
 1 0 345732 32760 769972 12943528  0  0 12 16460 1185 3103 11  2 86  1

It doesn't look like there's anything else running - the runnable r is
about 1.  Your bo blocks output rate is about 16MB/s, so divide by 3 and
you're about in range with your 5MB/s COPY rate.  The interesting thing is
that the I/O wait is pretty low.

How many CPUs on the machine?  Can you send the result of cat
/proc/cpuinfo?

Is your cat file | psql being done on the DBMS server or is it on the
network?

- Luke 



---(end of broadcast)---
TIP 1: if posting/reading through Usenet, please send an appropriate
   subscribe-nomail command to [EMAIL PROTECTED] so that your
   message can get through to the mailing list cleanly


Re: [PERFORM] Best COPY Performance

2006-10-27 Thread Merlin Moncure

On 10/28/06, Luke Lonergan [EMAIL PROTECTED] wrote:

Worky (that your real name? :-)


On 10/27/06 12:08 PM, Worky Workerson [EMAIL PROTECTED] wrote:

 Here it is, taken from a spot about halfway through a 'cat file |
 psql' load, with the Oracle-is-installed-and-running caveat:

 r b   swpd  free   buffcache si so bibo   in   cs us sy id wa
 1 0 345732 29328 770980 12947212  0  0 20 16552 1223 3677 12  2 85  1
 1 0 345732 29840 770520 12946924  0  0 20 29244 1283 2955 11  2 85  1
 1 0 345732 32144 770560 12944436  0  0 12 16436 1204 2936 11  2 86  1
 1 0 345732 33744 770464 12942764  0  0 20 16460 1189 2005 10  2 86  1
 2 0 345732 32656 770140 12943972  0  0 16  7068 1057 3434 13  2 85  0
 1 0 345732 34832 770184 12941820  0  0 20  9368 1170 3120 11  2 86  1
 1 0 345732 36528 770228 12939804  0  0 16 32668 1297 2109 11  2 85  1
 1 0 345732 29304 770272 12946764  0  0 16 16428 1192 3105 12  2 85  1
 1 0 345732 30840 770060 12945480  0  0 20 16456 1196 3151 12  2 84  1
 1 0 345732 32760 769972 12943528  0  0 12 16460 1185 3103 11  2 86  1

It doesn't look like there's anything else running - the runnable r is
about 1.  Your bo blocks output rate is about 16MB/s, so divide by 3 and
you're about in range with your 5MB/s COPY rate.  The interesting thing is
that the I/O wait is pretty low.

How many CPUs on the machine?  Can you send the result of cat
/proc/cpuinfo?

Is your cat file | psql being done on the DBMS server or is it on the
network?


iirc, he is running quad opteron 885 (8 cores), so if my math is
correct he can split up his process for an easy gain.

merlin

---(end of broadcast)---
TIP 4: Have you searched our list archives?

  http://archives.postgresql.org


Re: [PERFORM] Best COPY Performance

2006-10-27 Thread Worky Workerson

Worky (that your real name? :-)


Nope, its Mike.  worky.workerson is just the email that I use for work :)


How many CPUs on the machine?  Can you send the result of cat
/proc/cpuinfo?


Not at work at the moment, however I do have quad dual-core opterons,
like Merlin mentioned.


Is your cat file | psql being done on the DBMS server or is it on the
network?


Everything is currently being done on the same DB server.  The data
that is being loaded is on the same 2-disk RAID10 as the OS and WAL.

---(end of broadcast)---
TIP 9: In versions below 8.0, the planner will ignore your desire to
  choose an index scan if your joining column's datatypes do not
  match


Re: [PERFORM] Best COPY Performance

2006-10-27 Thread Worky Workerson

On 10/27/06, Merlin Moncure [EMAIL PROTECTED] wrote:

  r b   swpd  free   buffcache si so bibo   in   cs us sy id wa
  1 0 345732 29328 770980 12947212  0  0 20 16552 1223 3677 12  2 85  1
  1 0 345732 29840 770520 12946924  0  0 20 29244 1283 2955 11  2 85  1
  1 0 345732 32144 770560 12944436  0  0 12 16436 1204 2936 11  2 86  1
  1 0 345732 33744 770464 12942764  0  0 20 16460 1189 2005 10  2 86  1
  2 0 345732 32656 770140 12943972  0  0 16  7068 1057 3434 13  2 85  0
  1 0 345732 34832 770184 12941820  0  0 20  9368 1170 3120 11  2 86  1
  1 0 345732 36528 770228 12939804  0  0 16 32668 1297 2109 11  2 85  1
  1 0 345732 29304 770272 12946764  0  0 16 16428 1192 3105 12  2 85  1
  1 0 345732 30840 770060 12945480  0  0 20 16456 1196 3151 12  2 84  1
  1 0 345732 32760 769972 12943528  0  0 12 16460 1185 3103 11  2 86  1

 It doesn't look like there's anything else running - the runnable r is
 about 1.  Your bo blocks output rate is about 16MB/s, so divide by 3 and
 you're about in range with your 5MB/s COPY rate.  The interesting thing is
 that the I/O wait is pretty low.

 How many CPUs on the machine?  Can you send the result of cat
 /proc/cpuinfo?

iirc, he is running quad opteron 885 (8 cores), so if my math is
correct he can split up his process for an easy gain.


Are you saying that I should be able to issue multiple COPY commands
because my I/O wait is low?  I was under the impression that I am I/O
bound, so multiple simeoultaneous loads would have a detrimental
effect ...

---(end of broadcast)---
TIP 4: Have you searched our list archives?

  http://archives.postgresql.org


Re: [PERFORM] Best COPY Performance

2006-10-27 Thread Luke Lonergan
Worky,

On 10/27/06 8:47 PM, Worky Workerson [EMAIL PROTECTED] wrote:

 1 0 345732 29304 770272 12946764  0  0 16 16428 1192 3105 12  2 85  1
 1 0 345732 30840 770060 12945480  0  0 20 16456 1196 3151 12  2 84  1
 1 0 345732 32760 769972 12943528  0  0 12 16460 1185 3103 11  2 86  1
 
 iirc, he is running quad opteron 885 (8 cores), so if my math is
 correct he can split up his process for an easy gain.
 
 Are you saying that I should be able to issue multiple COPY commands
 because my I/O wait is low?  I was under the impression that I am I/O
 bound, so multiple simeoultaneous loads would have a detrimental
 effect ...

The reason I asked how many CPUs was to make sense of the 12% usr CPU time
in the above.  That means you are CPU bound and are fully using one CPU.  So
you aren't being limited by the I/O in this case, it's the CPU.

I agree with Merlin that you can speed things up by breaking the file up.
Alternately you can use the OSS Bizgres java loader, which lets you specify
the number of I/O threads with the -n option on a single file.

OTOH, you should find that you will only double your COPY speed with this
approach because your write speed as you previously found was limited to 30
MB/s.

For now, you could simply split the file in two pieces and load two copies
at once, then watch the same vmstat 1 for 10 seconds and look at your bo
rate.

If this does speed things up, you really should check out the Bizgres Java
loader.

The other thing to wonder about though is why you are so CPU bound at 5
MB/s.  What version of Postgres is this?

- Luke 



---(end of broadcast)---
TIP 3: Have you checked our extensive FAQ?

   http://www.postgresql.org/docs/faq