Performance issue with libpq prepared queries on 9.3 and 9.4

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

Responses

Browse pgsql-general by date

  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?

Browse pgsql-hackers by date

  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