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
|
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 toTom> 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.

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: