Content-Type: text/plain; charset=utf-8; format=flowed; delsp=yes
To: "Mario Splivalo" <mario.splivalo@megafon.hr>
Cc: mark.kirkwood@catalyst.net.nz, pgsql-performance@postgresql.org
Subject: Re: SELECT INTO large FKyed table is slow
References: <4CF24103.8030209@megafon.hr> <4CF3522B.2050203@catalyst.net.nz>
	<4CF39CF4.2050506@megafon.hr> <op.vmxyi50oeorkce@apollo13>
	<4CF587B0.5020003@megafon.hr>
Date: Wed, 01 Dec 2010 09:43:07 +0100
MIME-Version: 1.0
Content-Transfer-Encoding: 8bit
From: "Pierre C" <lists@peufeu.com>
Message-ID: <op.vm0055s0eorkce@apollo13>
In-Reply-To: <4CF587B0.5020003@megafon.hr>
User-Agent: Opera Mail/10.62 (Linux)


> So, I did. I run the whole script in psql, and here is the result for  
> the INSERT:
>
> realm_51=# explain analyze INSERT INTO drones_history (2771, drone_id,  
> drone_log_notice, drone_temperature, drone_pressure) SELECT * FROM  
> tmp_drones_history;
>                                                        QUERY PLAN  
> ----------------------------------------------------------------------------------------------------------------------
>   Seq Scan on tmp_drones_history  (cost=0.00..81.60 rows=4160 width=48)  
> (actual time=0.008..5.296 rows=5150 loops=1)
>   Trigger for constraint drones_history_fk__drones: time=92.948  
> calls=5150
>   Total runtime: 16779.644 ms
> (3 rows)
>
>
> Now, this is only 16 seconds. In this 'batch' I've inserted 5150 rows.
> The batch before, I run that one 'the usual way', it inserted 9922 rows,  
> and it took 1 minute and 16 seconds.
>
> I did not, however, enclose the process into begin/end.
>
> So, here are results when I, in psql, first issued BEGIN:
>
> realm_51=# explain analyze INSERT INTO drones_history (2772, drone_id,  
> drone_log_notice, drone_temperature, drone_pressure) SELECT * FROM  
> tmp_drones_history;
>                                                        QUERY PLAN  
> ----------------------------------------------------------------------------------------------------------------------
>   Seq Scan on tmp_drones_history  (cost=0.00..79.56 rows=4056 width=48)  
> (actual time=0.008..6.490 rows=5059 loops=1)
>   Trigger for constraint drones_history_fk__drones: time=120.224  
> calls=5059
>   Total runtime: 39658.250 ms
> (3 rows)
>
> Time: 39658.906 ms
>
>
>
> 	Mario
>

Note that in both cases postgres reports that the FK checks take 92-120  
milliseconds... which is a normal time for about 4000 rows.
Inserting 4000 lines with just a few fields like you got should take quite  
much less than 1 s...

Where the rest of the time goes, I have no idea. Disk thrashing ? Locks ?  
Gremlins ?

- try it on a fresh copy of all your tables (CREATE TABLE, INSERT INTO  
SELECT)
- try to put the WAL on a separate physical disk (or do a check with  
fsync=off)
- try it on another computer
- try it on another harddisk
- run oprofile on a debug compile of postgres
- it could even be the process title updates (I don't think so but...)
- try a ramdisk tablespace