Re: Slowness of extended protocol

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.

[image: 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

>