From: | Sam Saffron <sam(dot)saffron(at)gmail(dot)com> |
---|---|
To: | pgsql-general(at)postgresql(dot)org |
Subject: | Performance issue with libpq prepared queries on 9.3 and 9.4 |
Date: | 2014-11-13 23:23:21 |
Message-ID: | CAAtdryOvyNibvSnp9ErO48d_i8R7da3=Fdqn1qxPqZE0pJLwXw@mail.gmail.com |
Views: | Raw Message | Whole Thread | Download mbox | Resend email |
Thread: | |
Lists: | pgsql-general pgsql-hackers |
I have hit a rather odd issue with prepared queries on both pg 9.3 and 9.4 beta.
I have this table (copy at http://samsaffron.com/testing.db.gz) with a
very odd performance profile:
When I run the following prepared query it is running significantly
slower than the raw counterpart:
```
select * from topics where archetype = $1 limit 1
```
Full test harness here:
```
#include <stdio.h>
#include <stdlib.h>
#include <string.h>
#include <errno.h>
#include <sys/time.h>
#include <time.h>
#include <libpq-fe.h>
static void
exit_nicely(PGconn *conn)
{
PQfinish(conn);
exit(1);
}
static double get_wall_time(){
struct timeval time;
if (gettimeofday(&time,NULL)){
// Handle error
return 0;
}
return (double)time.tv_sec + (double)time.tv_usec * .000001;
}
int
main(int argc, char **argv)
{
const char *conninfo;
PGconn *conn;
PGresult *res;
PGresult *stmt;
int i;
Oid textOid = 25;
char *paramValues[1];
int paramLengths[1];
paramLengths[0] = 6;
paramValues[0] = "banner";
if (argc > 1)
conninfo = argv[1];
else
conninfo = "dbname = testing";
printf("connecting database\n");
/* Make a connection to the database */
conn = PQconnectdb(conninfo);
/* Check to see that the backend connection was successfully made */
if (PQstatus(conn) != CONNECTION_OK)
{
fprintf(stderr, "Connection to database failed: %s",
PQerrorMessage(conn));
exit_nicely(conn);
}
stmt = PQprepare(conn,
"test",
"select * from topics where archetype = $1 limit 1",
1,
&textOid);
printf("prepared statement\n");
double start = get_wall_time();
for(i=0; i<2000; i++){
res = PQexecPrepared(conn, "test", 1, paramValues, paramLengths, NULL, 0);
if (PQresultStatus(res) != PGRES_TUPLES_OK)
{
fprintf(stderr, "command failed: %s", PQerrorMessage(conn));
PQclear(res);
exit_nicely(conn);
}
PQclear(res);
}
double finish = get_wall_time();
fprintf(stderr, "Prepared %f \n", (finish-start));
start = get_wall_time();
for(i=0; i<2000; i++){
res = PQexec(conn, "select * from topics where archetype = 'banner' limit 1");
if (PQresultStatus(res) != PGRES_TUPLES_OK)
{
fprintf(stderr, "command failed: %s", PQerrorMessage(conn));
PQclear(res);
exit_nicely(conn);
}
PQclear(res);
}
finish = get_wall_time();
fprintf(stderr, "raw %f \n", (finish-start));
/* close the connection to the database and cleanup */
PQfinish(conn);
return 0;
}
```
Results:
```text
sam(at)ubuntu pq_play % cc -o play -I/usr/include/postgresql play.c -lpq
-L/usr/include/postgresql/libpq && ./play
connecting database
prepared statement
Prepared 9.936938
Raw 1.369071
```
So my prepared counterpart is running at an 8th the speed of the raw.
I had a nightmare of a time generating a workload that exhibits the
issue via script but managed to anonymise the data which is linked
above.
Very strangely when I run the query in "psql" it does not exhibit the issue:
```text
sam(at)ubuntu pq_play % psql testing
psql (9.3.5)
Type "help" for help.
testing=# prepare test as select * from topics where archetype = $1 limit 1;
PREPARE
testing=# explain analyze execute test('banner');
QUERY PLAN
------------------------------------------------------------------------------------------------------------------------
Limit (cost=0.29..651.49 rows=1 width=520) (actual time=0.983..0.983
rows=0 loops=1)
-> Index Scan using idx11 on topics (cost=0.29..651.49 rows=1
width=520) (actual time=0.980..0.980 rows=0 loops=1)
Index Cond: ((archetype)::text = 'banner'::text)
Total runtime: 1.037 ms
(4 rows)
testing=# explain analyze select * from topics where archetype =
'banner' limit 1;
QUERY PLAN
------------------------------------------------------------------------------------------------------------------------
Limit (cost=0.29..651.49 rows=1 width=520) (actual time=0.642..0.642
rows=0 loops=1)
-> Index Scan using idx11 on topics (cost=0.29..651.49 rows=1
width=520) (actual time=0.641..0.641 rows=0 loops=1)
Index Cond: ((archetype)::text = 'banner'::text)
Total runtime: 0.673 ms
(4 rows)
```
Something about running this from libpq is causing it to scan the
table as opposed to scanning the index.
Any idea why is this happening?
(note: Rails 4.2 is moving to a pattern of using prepared statements
far more often which is why I discovered this issue)
ps. also posted on our meta to keep track of it:
https://meta.discourse.org/t/performance-issue-with-prepared-queries/22141
From | Date | Subject | |
---|---|---|---|
Next Message | Tom Lane | 2014-11-14 00:34:39 | Re: [GENERAL] Performance issue with libpq prepared queries on 9.3 and 9.4 |
Previous Message | David G Johnston | 2014-11-13 23:01:38 | Re: hstore, but with fast range comparisons? |
From | Date | Subject | |
---|---|---|---|
Next Message | Tom Lane | 2014-11-13 23:24:53 | Re: Segmentation fault in pg_dumpall from master down to 9.1 and other bug introduced by RLS |
Previous Message | Andres Freund | 2014-11-13 23:15:20 | Re: Segmentation fault in pg_dumpall from master down to 9.1 and other bug introduced by RLS |