Slow ext'd query via client native implementation vs. libpq & simple psql

Previous Topic Next Topic
 
classic Classic list List threaded Threaded
4 messages Options
Reply | Threaded
Open this post in threaded view
|

Slow ext'd query via client native implementation vs. libpq & simple psql

Richard Michael
Hello,

On PG 12.2, I am analyzing a performance problem when using a client
(Elixir/postgrex) querying via the extended query protocol.  I am comparing with
psql and a C program.  Logs for all three follow this short explanation.

The query is trivial: `SELECT [cols] FROM t WHERE id = X` on a 65K row table.

The Elixir client executes this as an extended query in >500-700ms, very slow.
If relevant, the client does not use libpq, it is a native implementation.

A simple query via psql `PREPARE q AS ... ; EXECUTE q;` executes in ~130ms.
(Aside, please let me know if psql can execute extended queries.)

To compare another extended query protocol client, I wrote a tiny C program
using libpq PQprepare()/PQexecPrepared() executes in ~100ms.

I have tried to make the three tests as similar as possible; all are via
localhost and use named statements.

All use an identical query plan. There is a btree index on the WHERE col, but
the table is small enough it is not used.

The above durations are consistent across server restart, reboot, and repetition
(i.e.  still >500ms if run multiple times), so it seems independent of
filesystem caching, buffers, etc.

Obviously the client's query execution is somehow different, but I do not know
what/why.

I have enabled auto_explain min_duration (0), analyze, buffers, verbose and
settings.  What more can I log or do to postgres to understand why the client is
behaving poorly?  Would wireshark on client messages reveal anything postgres
can't log?

Other suggestions much appreciated as well.

(I happen to be on OSX, but I can test elsewhere if necessary.)

Regards,
richard


Elixir/postgrex extended query: (always >500ms)
-------------------------------
2020-03-11 13:46:20.090 EDT [3401] LOG:  connection received: host=127.0.0.1 port=50128
2020-03-11 13:46:20.096 EDT [3401] LOG:  connection authorized: user=testuser database=biodata
2020-03-11 13:46:20.141 EDT [3401] LOG:  duration: 1.138 ms  parse ecto_98: SELECT g0."id", g0."genome_id", g0."seqid", g0."source", g0."feature", g0."start", g0."end", g0."score", g0."strand", g0."phase", g0."attribute" FROM "genes" AS g0 WHERE (g0."genome_id" = 1)
2020-03-11 13:46:20.144 EDT [3401] LOG:  duration: 2.292 ms  bind ecto_98: SELECT g0."id", g0."genome_id", g0."seqid", g0."source", g0."feature", g0."start", g0."end", g0."score", g0."strand", g0."phase", g0."attribute" FROM "genes" AS g0 WHERE (g0."genome_id" = 1)
2020-03-11 13:46:20.658 EDT [3401] LOG:  duration: 513.791 ms  execute ecto_98: SELECT g0."id", g0."genome_id", g0."seqid", g0."source", g0."feature", g0."start", g0."end", g0."score", g0."strand", g0."phase", g0."attribute" FROM "genes" AS g0 WHERE (g0."genome_id" = 1)
2020-03-11 13:46:20.658 EDT [3401] LOG:  duration: 513.792 ms  plan:
Query Text: SELECT g0."id", g0."genome_id", g0."seqid", g0."source", g0."feature", g0."start", g0."end", g0."score", g0."strand", g0."phase", g0."attribute" FROM "genes" AS g0 WHERE (g0."genome_id" = 1)
Seq Scan on public.genes g0  (cost=0.00..6591.62 rows=60632 width=224) (actual time=0.523..33.229 rows=60623 loops=1)
 Output: id, genome_id, seqid, source, feature, start, "end", score, strand, phase, attribute
 Filter: (g0.genome_id = 1)
 Rows Removed by Filter: 3907
 Buffers: shared read=5785
2020-03-11 13:46:20.887 EDT [3401] LOG:  disconnection: session time: 0:00:00.796 user=testuser database=biodata host=127.0.0.1 port=50128



psql simple PREPARE/EXECUTE:
----------------------------
2020-03-11 13:46:40.021 EDT [3438] LOG:  connection received: host=::1 port=50129
2020-03-11 13:46:40.044 EDT [3438] LOG:  connection authorized: user=testuser database=biodata application_name=psql
2020-03-11 13:46:40.106 EDT [3438] LOG:  duration: 58.071 ms  plan:
Query Text: PREPARE q AS SELECT g0."id", g0."genome_id", g0."seqid", g0."source", g0."feature", g0."start", g0."end", g0."score", g0."strand", g0."phase", g0."attribute" FROM "genes" AS g0 WHERE (g0."genome_id" = 1); EXECUTE q;
Seq Scan on public.genes g0  (cost=0.00..6591.62 rows=60632 width=224) (actual time=0.060..25.542 rows=60623 loops=1)
 Output: id, genome_id, seqid, source, feature, start, "end", score, strand, phase, attribute
 Filter: (g0.genome_id = 1)
 Rows Removed by Filter: 3907
 Buffers: shared hit=42 read=5743
2020-03-11 13:46:40.182 EDT [3438] LOG:  duration: 136.173 ms  statement: PREPARE q AS SELECT g0."id", g0."genome_id", g0."seqid", g0."source", g0."feature", g0."start", g0."end", g0."score", g0."strand", g0."phase", g0."attribute" FROM "genes" AS g0 WHERE (g0."genome_id" = 1); EXECUTE q;
2020-03-11 13:46:40.182 EDT [3438] DETAIL:  prepare: PREPARE q AS SELECT g0."id", g0."genome_id", g0."seqid", g0."source", g0."feature", g0."start", g0."end", g0."score", g0."strand", g0."phase", g0."attribute" FROM "genes" AS g0 WHERE (g0."genome_id" = 1); EXECUTE q;
2020-03-11 13:46:41.140 EDT [3438] LOG:  disconnection: session time: 0:00:01.119 user=testuser database=biodata host=::1 port=50129



C libpq extended query:
-----------------------
2020-03-11 13:50:00.220 EDT [4299] LOG:  connection received: host=::1 port=50137
2020-03-11 13:50:00.232 EDT [4299] LOG:  connection authorized: user=testuser database=biodata
2020-03-11 13:50:00.234 EDT [4299] LOG:  duration: 0.437 ms  parse foo: SELECT g0."id", g0."genome_id", g0."seqid", g0."source", g0."feature", g0."start", g0."end", g0."score", g0."strand", g0."phase", g0."attribute" FROM genes AS g0 WHERE (g0."genome_id" = 1)
2020-03-11 13:50:00.235 EDT [4299] LOG:  duration: 0.489 ms  bind foo: SELECT g0."id", g0."genome_id", g0."seqid", g0."source", g0."feature", g0."start", g0."end", g0."score", g0."strand", g0."phase", g0."attribute" FROM genes AS g0 WHERE (g0."genome_id" = 1)
2020-03-11 13:50:00.342 EDT [4299] LOG:  duration: 106.874 ms  execute foo: SELECT g0."id", g0."genome_id", g0."seqid", g0."source", g0."feature", g0."start", g0."end", g0."score", g0."strand", g0."phase", g0."attribute" FROM genes AS g0 WHERE (g0."genome_id" = 1)
2020-03-11 13:50:00.342 EDT [4299] LOG:  duration: 106.861 ms  plan:
Query Text: SELECT g0."id", g0."genome_id", g0."seqid", g0."source", g0."feature", g0."start", g0."end", g0."score", g0."strand", g0."phase", g0."attribute" FROM genes AS g0 WHERE (g0."genome_id" = 1)
Seq Scan on public.genes g0  (cost=0.00..6591.62 rows=60632 width=224) (actual time=0.056..25.049 rows=60623 loops=1)
 Output: id, genome_id, seqid, source, feature, start, "end", score, strand, phase, attribute
 Filter: (g0.genome_id = 1)
 Rows Removed by Filter: 3907
 Buffers: shared hit=74 read=5711
2020-03-11 13:50:00.345 EDT [4299] LOG:  disconnection: session time: 0:00:00.125 user=testuser database=biodata host=::1 port=50137
Reply | Threaded
Open this post in threaded view
|

Re: Slow ext'd query via client native implementation vs. libpq & simple psql

Justin Pryzby
On Wed, Mar 11, 2020 at 03:31:48PM -0400, Richard Michael wrote:
> The query is trivial: `SELECT [cols] FROM t WHERE id = X` on a 65K row
> table.

> The Elixir client executes this as an extended query in >500-700ms, very
> slow.
> If relevant, the client does not use libpq, it is a native implementation.

> A simple query via psql `PREPARE q AS ... ; EXECUTE q;` executes in ~130ms.
> (Aside, please let me know if psql can execute extended queries.)
> To compare another extended query protocol client, I wrote a tiny C program
> using libpq PQprepare()/PQexecPrepared() executes in ~100ms.

psql can't do it, but pygres can do it since last year.

> Would wireshark on client messages reveal anything postgres can't log?

I think maybe, like how many round trips there are.  
Does the difference between the clients scale linearly with the number of rows
returned?

> Elixir/postgrex extended query: (always >500ms)
> -------------------------------

> 2020-03-11 13:46:20.658 EDT [3401] LOG:  duration: 513.792 ms  plan:
...
> Seq Scan on public.genes g0  (cost=0.00..6591.62 rows=60632 width=224)
> (actual time=0.523..33.229 rows=60623 loops=1)

You can see the "actual time" is low (that's postgres running the query), so
the rest seems to comes from something like sending data back to the client or
the client parsing the results.

--
Justin


Reply | Threaded
Open this post in threaded view
|

Re: Slow ext'd query via client native implementation vs. libpq & simple psql

Tom Lane-2
In reply to this post by Richard Michael
Richard Michael <[hidden email]> writes:
> On PG 12.2, I am analyzing a performance problem when using a client
> (Elixir/postgrex) querying via the extended query protocol.  I am comparing
> with
> psql and a C program.  Logs for all three follow this short explanation.

Hmm, your auto-explain log entries show all three queries having
server-side execution times of a couple dozen msec.  It seems like
the excess time must be involved in transmitting the data to the
client.  So I guess I'd be looking at whether the client is really
slow at absorbing data for some reason.

IIRC, auto-explain's 'actual time' for the top-level query node does not
count the time to format data or transmit it to the client.  Still, we
have an upper bound of ~80 msec for that to happen with the libpq client,
and there's no obvious reason why it'd be different for the other client.

[ thinks for a bit... ]  You might double check that those two clients
are using the same client_encoding setting.  400ms doing encoding
conversion seems excessive, but there aren't that many other possibilities
for the I/O time to be different.

                        regards, tom lane


Reply | Threaded
Open this post in threaded view
|

Re: Slow ext'd query via client native implementation vs. libpq & simple psql

Justin Pryzby
In reply to this post by Justin Pryzby
On Thu, Mar 12, 2020 at 04:27:54PM -0400, Richard Michael wrote:
> > psql can't do it, but pygres can do it since last year.
>
> Thank you for mentioning it.  Do you mean this:
> https://github.com/rogamba/pygres ?

Ugh, no.  I'm referring to PyGreSQL, which was at one point a part of the
postgres source tree.
https://www.pygresql.org/

$ python -c "import pg; print(pg.DB('postgres').query('SELECT 1').getresult())"
[(1,)]

$ python -c "import pg; p=pg.DB('postgres'); p.prepare('q', 'SELECT 1'); print(p.query_prepared('q').getresult())"
[(1,)]

--
Justin

(I'm having trouble believe someone made a project called "pygres", which uses
python, postgres, and psycopg...  Will mail D'Arcy)