Re: Slowness of extended protocol - Mailing list pgsql-hackers

From Vladimir Sitnikov
Subject Re: Slowness of extended protocol
Date
Msg-id CAB=Je-Fu0gEa0X7ftWtTaUesqAqBLBPA1c+=x74MA7n+Di-jzw@mail.gmail.com
Whole thread Raw
In response to Re: Slowness of extended protocol  (Shay Rojansky <roji@roji.org>)
Responses Re: Slowness of extended protocol  (Vladimir Sitnikov <sitnikov.vladimir@gmail.com>)
List pgsql-hackers
Tom>  I think the tie-in to the plan cache is a
Tom> significant part of the added overhead, and so is the fact that we have to
Tom> iterate the per-message loop in PostgresMain five times not once, with
Tom> overheads like updating the process title incurred several times in that.

Shay>I was thinking that something like that may be the cause. Is it worth looking into the loop and trying to optimize? For example, updating the
Shay>process title doesn't seem to make sense for every single extended message...

Shay> just discussing what may or may not be a problem...

Shay, why don't you use a profiler? Seriously.
I'm afraid "iterate the per-message loop in PostgresMain five times not once" /"just discussing what may or may not be a problem..."  is just hand-waving.

Come on, it is not that hard.

Here's what I get with Instruments, OS X 10.11.5, Intel(R) Core(TM) i7-4960HQ CPU @ 2.60GHz, running with power plugged in. There are lots of applications running, however I believe it should not matter much since I'm using just 1 load thread and the 5-second averages are consistent and CPU is not overloaded.

test.sql:
SELECT 1;

PostgreSQL 9.5.3 on x86_64-apple-darwin15.4.0, compiled by Apple LLVM version 7.0.2 (clang-700.1.81), 64-bit

Command line:
/opt/local/lib/postgresql95/bin/pgbench -M extended -f test.sql -j 1 -P 5 -T 120

Profiler is activated at seconds 30...60

It looks strange to see copyObject calls from within BuildCachedPlan/CreateCachedPlan.
I would expect one-shot plan to be reused without copying, however exec_parse_message does not seem to bother setting is_oneshot=true flag on a CachedPlanSource.
It it a bug? It think exec_parse_message should set is_oneshot=true for parse message with empty statement names.

pg_extended_topdown.png

Here's the detailed list for the run:
postgres$ /opt/local/lib/postgresql95/bin/pgbench -M extended -f test.sql -j 1 -P 5 -T 120
starting vacuum...ERROR:  relation "pgbench_branches" does not exist
(ignoring this error and continuing anyway)
ERROR:  relation "pgbench_tellers" does not exist
(ignoring this error and continuing anyway)
ERROR:  relation "pgbench_history" does not exist
(ignoring this error and continuing anyway)
end.
progress: 5.0 s, 30061.1 tps, lat 0.033 ms stddev 0.013
progress: 10.0 s, 31407.4 tps, lat 0.032 ms stddev 0.008
progress: 15.0 s, 31332.4 tps, lat 0.032 ms stddev 0.008
progress: 20.0 s, 31812.3 tps, lat 0.031 ms stddev 0.007
progress: 25.0 s, 31560.9 tps, lat 0.031 ms stddev 0.008
progress: 30.0 s, 31492.3 tps, lat 0.031 ms stddev 0.008
vvv profiler activated
progress: 35.0 s, 29972.2 tps, lat 0.033 ms stddev 0.011
progress: 40.0 s, 28965.8 tps, lat 0.034 ms stddev 0.010
progress: 45.0 s, 29127.0 tps, lat 0.034 ms stddev 0.011
progress: 50.0 s, 29464.0 tps, lat 0.034 ms stddev 0.008
progress: 55.0 s, 29072.2 tps, lat 0.034 ms stddev 0.011
progress: 60.0 s, 29405.2 tps, lat 0.034 ms stddev 0.008
^^^ profiler deactivated
progress: 65.0 s, 28848.0 tps, lat 0.034 ms stddev 0.013
progress: 70.0 s, 31175.8 tps, lat 0.032 ms stddev 0.010
progress: 75.0 s, 32042.8 tps, lat 0.031 ms stddev 0.007
progress: 80.0 s, 31277.8 tps, lat 0.032 ms stddev 0.008
progress: 85.0 s, 31373.3 tps, lat 0.032 ms stddev 0.009
progress: 90.0 s, 31171.0 tps, lat 0.032 ms stddev 0.008

Vladimir
Attachment

pgsql-hackers by date:

Previous
From: Fujii Masao
Date:
Subject: Re: pg_basebackup wish list
Next
From: Aleksander Alekseev
Date:
Subject: Re: [Patch] Temporary tables that do not bloat pg_catalog (a.k.a fast temp tables)