[pgpool-general: 1995] Re: 40% performance loss when using pgpool with postgres foreign data wrapper
Tatsuo Ishii
ishii at postgresql.org
Mon Aug 5 13:01:29 JST 2013
Hi Lonni,
I finally had a chance to try it out. I have a Laptop with SSD, 2 CORE
i5, mem 8GB machine running Linux. First of all, I noticed
Postgres_fdw addes quite performance loss even without pgpool-II. The
performance drops from test case #4(Without pgpool & without FDW) to
test case #3(without pgpool & with FDW) is 75.3%. This is because
Postgres_fdw adds lots of query to the original. Without FDW, the
query looks like this:
13083 2013-08-05 12:14:44 JST LOG: statement: SELECT abalance FROM pgbench_accounts WHERE aid = 25806;
With FDW:
12987 2013-08-05 12:12:57 JST LOG: statement: START TRANSACTION ISOLATION LEVEL REPEATABLE READ
12987 2013-08-05 12:12:57 JST LOG: execute <unnamed>: DECLARE c1 CURSOR FOR
SELECT abalance FROM public.pgbench_accounts WHERE ((aid = 79891))
12987 2013-08-05 12:12:57 JST LOG: statement: FETCH 100 FROM c1
12987 2013-08-05 12:12:57 JST LOG: statement: CLOSE c1
12987 2013-08-05 12:12:57 JST LOG: statement: COMMIT TRANSACTION
As you can see the number of quries grows from 1 to 5.
Remeber that pgpool needs to read and write packets from clients. Thus
if the number of packets needed to be processed grows, the performance
penalty will be larger. In fact, the performance loss #2(with pgpool &
without FDW) vs. #1(with pgpool & FDW) is 76.8%, which is almost same
as the loss above.
In short, I see no strange behavior with pgpool-II+Postgres_fdw.
1) With pgpool & FDW:
pgbench->PostgreSQL 9.3 beta2, fdw(port 11000)->pgpool-II 3.3.0 (port 11002)->PostgreSQL 9.3 beta2(port 11001)
[t-ishii at localhost fdw]$ pgbench -n -S -c 1 -T30 -p 11000 test
transaction type: SELECT only
scaling factor: 1
query mode: simple
number of clients: 1
number of threads: 1
duration: 30 s
number of transactions actually processed: 37871
tps = 1262.356526 (including connections establishing)
tps = 1262.481595 (excluding connections establishing)
2) With pgpool & without FDW:
pgbench->pgpool-II 3.3.0 (port 11002)->PostgreSQL 9.3 beta2(port 11001)
[t-ishii at localhost fdw]$ pgbench -n -S -c 1 -T30 -p 11002 test
transaction type: SELECT only
scaling factor: 1
query mode: simple
number of clients: 1
number of threads: 1
duration: 30 s
number of transactions actually processed: 163473
tps = 5449.067306 (including connections establishing)
tps = 5449.106357 (excluding connections establishing)
3) Without pgpool & with FDW:
pgbench->PostgreSQL 9.3 beta2, fdw(port 11000)->PostgreSQL 9.3 beta2(port 11001)
[t-ishii at localhost fdw]$ pgbench -n -S -c 1 -T30 -p 11000 test2
transaction type: SELECT only
scaling factor: 1
query mode: simple
number of clients: 1
number of threads: 1
duration: 30 s
number of transactions actually processed: 60157
tps = 2005.152526 (including connections establishing)
tps = 2005.247571 (excluding connections establishing)
4) Without pgpool & without FDW:
pgbench->PostgreSQL 9.3 beta2(port 11001)
[t-ishii at localhost fdw]$ pgbench -n -S -c 1 -T30 -p 11001 test
transaction type: SELECT only
scaling factor: 1
query mode: simple
number of clients: 1
number of threads: 1
duration: 30 s
number of transactions actually processed: 244106
tps = 8136.839544 (including connections establishing)
tps = 8137.810924 (excluding connections establishing)
> Hi Tatsuo,
> Have you had a chance to replicate this problem yet?
>
> thanks
>
> On Fri, Jul 26, 2013 at 9:35 AM, Lonni J Friedman <netllama at gmail.com> wrote:
>> On Thu, Jul 25, 2013 at 5:11 PM, Tatsuo Ishii <ishii at postgresql.org> wrote:
>>>> On Wed, Jul 24, 2013 at 6:27 PM, Tatsuo Ishii <ishii at postgresql.org> wrote:
>>>>>> On Wed, Jul 24, 2013 at 5:19 PM, Tatsuo Ishii <ishii at postgresql.org> wrote:
>>>>>>>> On Tue, Jul 23, 2013 at 9:59 PM, Tatsuo Ishii <ishii at postgresql.org> wrote:
>>>>>>>>>> On Tue, Jul 23, 2013 at 5:42 PM, Tatsuo Ishii <ishii at postgresql.org> wrote:
>>>>>>>>>>> Not sure how is like your configuration. Did you actually test like this?
>>>>>>>>>>>
>>>>>>>>>>> pgbench/psql -> CLUSTER_A -> PG_FDW -> pgpool_B -> CLUSTER_B
>>>>>>>>>>
>>>>>>>>>> Yes, that's the config that exhibited the 40% performance loss.
>>>>>>>>>
>>>>>>>>> If you try this:
>>>>>>>>>
>>>>>>>>> pgbench/psql -> pgpool_B -> CLUSTER_B
>>>>>>>>>
>>>>>>>>> How is the performance?
>>>>>>>>
>>>>>>>> Perf is pretty good, nearly the same as:
>>>>>>>> pgbench/psql -> CLUSTER_A
>>>>>>>
>>>>>>> Interesting.
>>>>>>>
>>>>>>>> Actual output:
>>>>>>>> ########
>>>>>>>> Scale option ignored, using pgbench_branches table count = 10000
>>>>>>>> transaction type: TPC-B (sort of)
>>>>>>>> scaling factor: 10000
>>>>>>>> query mode: simple
>>>>>>>> number of clients: 10
>>>>>>>> number of threads: 10
>>>>>>>> duration: 3600 s
>>>>>>>> number of transactions actually processed: 7922742
>>>>>>>> tps = 2200.752746 (including connections establishing)
>>>>>>>> tps = 2200.760460 (excluding connections establishing)
>>>>>>>> ########
>>>>>>>>
>>>>>>>> It seems conclusive that pgpool is somehow not handling the FDW stuff
>>>>>>>> well. Can you try setting something similar up on your end, and see
>>>>>>>> if you can reproduce the perf loss? It doesn't require any special
>>>>>>>> data, just the normal default pgbench schema.
>>>>>>>
>>>>>>> I'll give it a try when I have spare time. At this point my wild guess
>>>>>>> is PG_FDW does not generate good enough query plan. Can you show
>>>>>>> EXPLAIN VERBOSE result?
>>>>>>
>>>>>> How do I run pgbench with EXPLAIN?
>>>>>
>>>>> In this configuration:
>>>>> pgbench/psql -> CLUSTER_A -> PG_FDW -> pgpool_B -> CLUSTER_B
>>>>>
>>>>> 1) enable query log at CLUSTER_A
>>>>>
>>>>> 2) run pgbench
>>>>>
>>>>> 3) you will get some SELECTs, INSERTs, UPDATEs query. Choose one of
>>>>> them from each type of query as samples.
>>>>>
>>>>> 4) EXPLAIN ANALYZE query_sample
>>>
>>> Sorry, you need to execute EXPLAIN ANALYZE VEBOSE to get the remote
>>> execution plan. Also the PostgreSQL manual suggests that ANALYZE on
>>> the foreign table helps to update the remote table statistics.
>>
>> I re-ran the commands with VERBOSE, but that still had no impact, as
>> the queries without pgpool had the same cost as with pgpool. Here's
>> the output:
>> ######
>> nightly=# EXPLAIN ANALYZE VERBOSE SELECT aid, bid, abalance, filler,
>> ctid FROM public.pgbench_accounts WHERE ((aid = 708983046)) FOR UPDATE
>> ;
>> QUERY PLAN
>> ---------------------------------------------------------------------------------------------------------------------------------
>> LockRows (cost=100.00..111.38 rows=1 width=734) (actual
>> time=0.801..0.803 rows=1 loops=1)
>> Output: aid, bid, abalance, filler, ctid, pgbench_accounts.*
>> -> Foreign Scan on public.pgbench_accounts (cost=100.00..111.37
>> rows=1 width=734) (actual time=0.800..0.801 rows=1 loops=1)
>> Output: aid, bid, abalance, filler, ctid, pgbench_accounts.*
>> Remote SQL: SELECT aid, bid, abalance, filler, ctid FROM
>> public.pgbench_accounts WHERE ((aid = 708983046)) FOR UPDATE
>> Total runtime: 1.448 ms
>> (6 rows)
>>
>> nightly=# EXPLAIN ANALYZE VERBOSE SELECT NULL FROM public.pgbench_branches ;
>> QUERY PLAN
>> ----------------------------------------------------------------------------------------------------------------------------------
>> Foreign Scan on public.pgbench_branches (cost=100.00..212.39
>> rows=3413 width=0) (actual time=1.537..267.226 rows=10000 loops=1)
>> Output: NULL::unknown
>> Remote SQL: SELECT NULL FROM public.pgbench_branches
>> Total runtime: 268.820 ms
>> (4 rows)
>>
>> nightly=# EXPLAIN ANALYZE VERBOSE SELECT abalance FROM
>> public.pgbench_accounts WHERE ((aid = 346327473)) ;
>> QUERY PLAN
>> --------------------------------------------------------------------------------------------------------------------------
>> Foreign Scan on public.pgbench_accounts (cost=100.00..146.86 rows=15
>> width=4) (actual time=0.931..0.933 rows=1 loops=1)
>> Output: abalance
>> Remote SQL: SELECT abalance FROM public.pgbench_accounts WHERE
>> ((aid = 346327473))
>> Total runtime: 1.634 ms
>> (4 rows)
>>
>> nightly=# EXPLAIN ANALYZE VERBOSE UPDATE public.pgbench_branches SET
>> bbalance = '85975' WHERE ctid = '(123,130)';
>> QUERY PLAN
>> ---------------------------------------------------------------------------------------------------------------------------------
>> Update on public.pgbench_branches (cost=100.00..112.65 rows=1
>> width=366) (actual time=0.968..0.968 rows=0 loops=1)
>> Remote SQL: UPDATE public.pgbench_branches SET bbalance = $2 WHERE ctid = $1
>> -> Foreign Scan on public.pgbench_branches (cost=100.00..112.65
>> rows=1 width=366) (actual time=0.956..0.956 rows=0 loops=1)
>> Output: bid, 85975, filler, ctid
>> Remote SQL: SELECT bid, filler, ctid FROM
>> public.pgbench_branches WHERE ((ctid = '(123,130)'::tid)) FOR UPDATE
>> Total runtime: 1.660 ms
>> (6 rows)
>>
>> nightly=# EXPLAIN ANALYZE VERBOSE INSERT INTO
>> public.pgbench_history(tid, bid,aid, delta, mtime, filler) VALUES
>> ('10526','8889','708983046','1806','2013-07-25 13:30:35.078487',NULL);
>> QUERY PLAN
>> ------------------------------------------------------------------------------------------------------------------------------
>> Insert on public.pgbench_history (cost=0.00..0.01 rows=1 width=0)
>> (actual time=1.164..1.164 rows=0 loops=1)
>> Remote SQL: INSERT INTO public.pgbench_history(tid, bid, aid,
>> delta, mtime, filler) VALUES ($1, $2, $3, $4, $5, $6)
>> -> Result (cost=0.00..0.01 rows=1 width=0) (actual
>> time=0.001..0.002 rows=1 loops=1)
>> Output: 10526, 8889, 708983046, 1806, '2013-07-25
>> 13:30:35.078487'::timestamp without time zone, NULL::character(22)
>> Total runtime: 1.976 ms
>> (5 rows)
>> ######
>>
>>
>>
>>
>>
>>>> ok, I did as you suggested, however it didn't really provide any
>>>> useful clues. The EXPLAIN cost ranges were identical regardless of
>>>> whether pgpool_B was in the configuration. However, the pgbench tps
>>>> numbers remained dramatically different (by about 40%). Anyway,
>>>> here's the EXPLAIN output for the most common queries:
>>>>
>>>> nightly=# EXPLAIN ANALYZE SELECT aid, bid, abalance, filler, ctid FROM
>>>> public.pgbench_accounts WHERE ((aid = 708983046)) FOR UPDATE ;
>>>> QUERY PLAN
>>>> --------------------------------------------------------------------------------------------------------------------------
>>>> LockRows (cost=100.00..111.38 rows=1 width=734) (actual
>>>> time=2.729..2.731 rows=1 loops=1)
>>>> -> Foreign Scan on pgbench_accounts (cost=100.00..111.37 rows=1
>>>> width=734) (actual time=2.728..2.730 rows=1 loops=1)
>>>> Total runtime: 4.297 ms
>>>> (3 rows)
>>>>
>>>> nightly=# EXPLAIN ANALYZE SELECT NULL FROM public.pgbench_branches ;
>>>> QUERY PLAN
>>>> ---------------------------------------------------------------------------------------------------------------------------
>>>> Foreign Scan on pgbench_branches (cost=100.00..212.39 rows=3413
>>>> width=0) (actual time=3.148..174.946 rows=10000 loops=1)
>>>> Total runtime: 177.309 ms
>>>> (2 rows)
>>>>
>>>> nightly=# EXPLAIN ANALYZE SELECT abalance FROM public.pgbench_accounts
>>>> WHERE ((aid = 346327473)) ;
>>>> QUERY PLAN
>>>> -------------------------------------------------------------------------------------------------------------------
>>>> Foreign Scan on pgbench_accounts (cost=100.00..146.86 rows=15
>>>> width=4) (actual time=2.365..2.366 rows=1 loops=1)
>>>> Total runtime: 3.587 ms
>>>> (2 rows)
>>>>
>>>> nightly=# EXPLAIN ANALYZE UPDATE public.pgbench_branches SET bbalance
>>>> = '85975' WHERE ctid = '(123,130)';
>>>> QUERY PLAN
>>>> --------------------------------------------------------------------------------------------------------------------------
>>>> Update on pgbench_branches (cost=100.00..112.65 rows=1 width=366)
>>>> (actual time=3.043..3.043 rows=0 loops=1)
>>>> -> Foreign Scan on pgbench_branches (cost=100.00..112.65 rows=1
>>>> width=366) (actual time=3.037..3.037 rows=0 loops=1)
>>>> Total runtime: 4.321 ms
>>>> (3 rows
>>>>
>>>> nightly=# EXPLAIN ANALYZE INSERT INTO public.pgbench_history(tid, bid,
>>>> aid, delta, mtime, filler) VALUES
>>>> ('10526','8889','708983046','1806','2013-07-25 13:30:35.078487',NULL);
>>>> QUERY PLAN
>>>> -------------------------------------------------------------------------------------------------------
>>>> Insert on pgbench_history (cost=0.00..0.01 rows=1 width=0) (actual
>>>> time=2.576..2.576 rows=0 loops=1)
>>>> -> Result (cost=0.00..0.01 rows=1 width=0) (actual
>>>> time=0.002..0.002 rows=1 loops=1)
>>>> Total runtime: 4.042 ms
>>>> (3 rows)
More information about the pgpool-general
mailing list