Performance issue with libpq prepared queries on 9.3 and 9.4 - Mailing list pgsql-general

From Sam Saffron
Subject Performance issue with libpq prepared queries on 9.3 and 9.4
Date
Msg-id CAAtdryOvyNibvSnp9ErO48d_i8R7da3=Fdqn1qxPqZE0pJLwXw@mail.gmail.com
Whole thread Raw
Responses Re: Performance issue with libpq prepared queries on 9.3 and 9.4  (Tom Lane <tgl@sss.pgh.pa.us>)
List pgsql-general
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@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@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


pgsql-general by date:

Previous
From: David G Johnston
Date:
Subject: Re: hstore, but with fast range comparisons?
Next
From: Tom Lane
Date:
Subject: Re: Performance issue with libpq prepared queries on 9.3 and 9.4