Performance issue with prepared queries


(Sam Saffron) #1

(note I am sending this to the pg mailing list, but wanted to keep a copy here as well)

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:

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:

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)

Posted here: Performance issue with libpq prepared queries on 9.3 and 9.4