Thread: Why is PostgreSQL 9.2 slower than 9.1 in my tests?
I have upgraded from PostgreSQL 9.1.5 to 9.2.1:
"PostgreSQL 9.1.5 on x86_64-unknown-linux-gnu, compiled by gcc (GCC) 4.4.6 20120305 (Red Hat 4.4.6-4), 64-bit"
"PostgreSQL 9.2.1 on x86_64-unknown-linux-gnu, compiled by gcc (GCC) 4.4.6 20120305 (Red Hat 4.4.6-4), 64-bit"
It is on the same machine with default PostgreSQL configuration files (only port was changed).
For testing purpose I have simple table:
CREATE TEMP TABLE test_table_md_speed(id serial primary key, n integer);
Which I test using function:
CREATE OR REPLACE FUNCTION TEST_DB_SPEED(cnt integer) RETURNS text AS $$
DECLARE
time_start timestamp;
time_stop timestamp;
time_total interval;
BEGIN
time_start := cast(timeofday() AS TIMESTAMP);
FOR i IN 1..cnt LOOP
INSERT INTO test_table_md_speed(n) VALUES (i);
END LOOP;
time_stop := cast(timeofday() AS TIMESTAMP);
time_total := time_stop-time_start;
RETURN extract (milliseconds from time_total);
END;
$$ LANGUAGE plpgsql;
And I call:
SELECT test_db_speed(1000000);
I see strange results. For PostgreSQL 9.1.5 I get "8254.769", and for 9.2.1 I get: "9022.219". This means that new version is slower. I cannot find why.
Any ideas why those results differ?
--
Patryk Sidzina
On Wed, Dec 5, 2012 at 4:09 AM, Patryk Sidzina <patryk.sidzina@gmail.com> wrote: > > CREATE TEMP TABLE test_table_md_speed(id serial primary key, n integer); > > CREATE OR REPLACE FUNCTION TEST_DB_SPEED(cnt integer) RETURNS text AS $$ > DECLARE > time_start timestamp; > time_stop timestamp; > time_total interval; > BEGIN > time_start := cast(timeofday() AS TIMESTAMP); > FOR i IN 1..cnt LOOP > INSERT INTO test_table_md_speed(n) VALUES (i); > END LOOP; > time_stop := cast(timeofday() AS TIMESTAMP); > time_total := time_stop-time_start; > > RETURN extract (milliseconds from time_total); > END; > $$ LANGUAGE plpgsql; > > > SELECT test_db_speed(1000000); > > I see strange results. For PostgreSQL 9.1.5 I get "8254.769", and for 9.2.1 > I get: "9022.219". This means that new version is slower. I cannot find why. > > Any ideas why those results differ? Did you just run it once each? The run-to-run variability in timing can be substantial. I put the above into a custom file for "pgbench -f sidzina.sql -t 1 -p $port" and run it on both versions in random order for several hundred iterations. There was no detectable difference in timing. Cheers, Jeff
On Tue, Dec 11, 2012 at 2:50 AM, Patryk Sidzina
<patryk.sidzina@gmail.com> wrote:
> The differences come up when you change the "INSERT" to "EXECUTE 'INSERT'" (
> and i checked this time on 3 machines, one of which was Windows):
>
> CREATE TEMP TABLE test_table_md_speed(id serial primary key, n integer);
>
> CREATE OR REPLACE FUNCTION test_db_speed(cnt integer)
> RETURNS text
> LANGUAGE plpgsql
> AS $function$
> DECLARE
> time_start timestamp;
> time_stop timestamp;
> time_total interval;
> BEGIN
> time_start := cast(timeofday() AS TIMESTAMP);
> FOR i IN 1..cnt LOOP
> EXECUTE 'INSERT INTO test_table_md_speed(n) VALUES (' || i
> || ')';
> END LOOP;
>
> time_stop := cast(timeofday() AS TIMESTAMP);
> time_total := time_stop-time_start;
>
> RETURN extract (milliseconds from time_total);
> END;
> $function$;
>
> SELECT test_db_speed(100000);
The culprit is the commit below. I don't know exactly why this slows
down your case. A preliminary oprofile analysis suggests that it most
of the slowdown is that it calls AllocSetAlloc more often. I suspect
that this slow-down will be considered acceptable trade-off for
getting good parameterized plans.
commit e6faf910d75027bdce7cd0f2033db4e912592bcc
Author: Tom Lane <tgl@sss.pgh.pa.us>
Date: Fri Sep 16 00:42:53 2011 -0400
Redesign the plancache mechanism for more flexibility and efficiency.
Cheers,
Jeff
Jeff Janes <jeff.janes@gmail.com> writes:
> On Tue, Dec 11, 2012 at 2:50 AM, Patryk Sidzina
> <patryk.sidzina@gmail.com> wrote:
>> The differences come up when you change the "INSERT" to "EXECUTE 'INSERT'" (
>> and i checked this time on 3 machines, one of which was Windows):
>> FOR i IN 1..cnt LOOP
>> EXECUTE 'INSERT INTO test_table_md_speed(n) VALUES (' || i || ')';
>> END LOOP;
> The culprit is the commit below. I don't know exactly why this slows
> down your case. A preliminary oprofile analysis suggests that it most
> of the slowdown is that it calls AllocSetAlloc more often. I suspect
> that this slow-down will be considered acceptable trade-off for
> getting good parameterized plans.
I'm having a hard time getting excited about optimizing the above case:
the user can do far more to make it fast than we can, simply by not
using EXECUTE, which is utterly unnecessary in this example.
Having said that, though, it's not real clear to me why the plancache
changes would have affected the speed of EXECUTE at all --- the whole
point of that command is we don't cache a plan for the query.
regards, tom lane
On Mon, Dec 10, 2012 at 4:53 AM, Jeff Janes <jeff.janes@gmail.com> wrote:
On Wed, Dec 5, 2012 at 4:09 AM, Patryk Sidzina <patryk.sidzina@gmail.com> wrote:
>
> CREATE TEMP TABLE test_table_md_speed(id serial primary key, n integer);
>> CREATE OR REPLACE FUNCTION TEST_DB_SPEED(cnt integer) RETURNS text AS $$
> DECLARE
> time_start timestamp;
> time_stop timestamp;
> time_total interval;
> BEGIN
> time_start := cast(timeofday() AS TIMESTAMP);
> FOR i IN 1..cnt LOOP
> INSERT INTO test_table_md_speed(n) VALUES (i);
> END LOOP;
> time_stop := cast(timeofday() AS TIMESTAMP);
> time_total := time_stop-time_start;
>
> RETURN extract (milliseconds from time_total);
> END;
> $$ LANGUAGE plpgsql;
>
>> SELECT test_db_speed(1000000);Did you just run it once each?
>
> I see strange results. For PostgreSQL 9.1.5 I get "8254.769", and for 9.2.1
> I get: "9022.219". This means that new version is slower. I cannot find why.
>
> Any ideas why those results differ?
The run-to-run variability in timing can be substantial.
I put the above into a custom file for "pgbench -f sidzina.sql -t 1 -p
$port" and run it on both versions in random order for several hundred
iterations. There was no detectable difference in timing.
Sorry for the mix up. The above results are from one of our test machines. I wanted to simplify the function as much as possible.
Unfortunately, I didn't test this on a different machine. I did that after your post and like you said, there isn't much difference in the results.
The differences come up when you change the "INSERT" to "EXECUTE 'INSERT'" ( and i checked this time on 3 machines, one of which was Windows):
CREATE TEMP TABLE test_table_md_speed(id serial primary key, n integer);
CREATE OR REPLACE FUNCTION test_db_speed(cnt integer)
RETURNS text
LANGUAGE plpgsql
AS $function$
DECLARE
time_start timestamp;
time_stop timestamp;
time_total interval;
BEGIN
time_start := cast(timeofday() AS TIMESTAMP);
FOR i IN 1..cnt LOOP
EXECUTE 'INSERT INTO test_table_md_speed(n) VALUES (' || i || ')';
END LOOP;
time_stop := cast(timeofday() AS TIMESTAMP);
time_total := time_stop-time_start;
RETURN extract (milliseconds from time_total);
END;
$function$;
SELECT test_db_speed(100000);
I run the above several times and get "4029.356" on PGSQL 9.1.6 and "5015.073" on PGSQL 9.2.1.
Again, sorry for not double checking my results.
--
Patryk Sidzina
On Tuesday, December 11, 2012, Tom Lane wrote:
Jeff Janes <jeff.janes@gmail.com> writes:
> On Tue, Dec 11, 2012 at 2:50 AM, Patryk Sidzina
> <patryk.sidzina@gmail.com> wrote:
>> The differences come up when you change the "INSERT" to "EXECUTE 'INSERT'" (
>> and i checked this time on 3 machines, one of which was Windows):
>> FOR i IN 1..cnt LOOP
>> EXECUTE 'INSERT INTO test_table_md_speed(n) VALUES (' || i || ')';
>> END LOOP;
> The culprit is the commit below. I don't know exactly why this slows
> down your case. A preliminary oprofile analysis suggests that it most
> of the slowdown is that it calls AllocSetAlloc more often. I suspect
> that this slow-down will be considered acceptable trade-off for
> getting good parameterized plans.
I'm having a hard time getting excited about optimizing the above case:
the user can do far more to make it fast than we can, simply by not
using EXECUTE, which is utterly unnecessary in this example.
I assumed his example was an intentionally simplified test-case, not a real world use-case.
For a more realistic use, see "[PERFORM] Performance on Bulk Insert to Partitioned Table". There too it would probably be best to get rid of the EXECUTE, but doing so in that case would certainly have a high cost in trigger-code complexity and maintainability. (In my test case of loading 1e7 narrow tuples to 100 partitions, the plan cache change lead to a 26% slow down)
Having said that, though, it's not real clear to me why the plancache
changes would have affected the speed of EXECUTE at all --- the whole
point of that command is we don't cache a plan for the query.
Doing a bottom level profile isn't helpful because all of the extra time is in very low level code that is called from everywhere. Doing call-counts with gprof, I see that there is big increase in the calls to copyObject (which indirectly leads to a big increase in AllocSetAlloc). Before the change, each EXECUTE had one top-level (i.e. nonrecursive) copyObject call, coming from _SPI_prepare_plan.
After the change, each EXECUTE has 4 such top-level copyObject calls, one each from CreateCachedPlan and CompleteCachedPlan and two from BuildCachedPlan.
Cheers,
Jeff