Skip to content

Performance Testing in PostgreSQL

June 28, 2010

You can’t control what you can’t measure — Tom DeMarco

Testing performance in general measures how fast some aspect of a system performs under a particular workload. The scope of this post consists of limiting the workload to the execution of SQL statements in PostgreSQL.

In the end, the objective is to understand how to accurately test performance while mitigating side effects on both the client and server sides.

Test Plan

A test plan is a document detailing a systematic approach to testing the performance of a system. The most obvious part of the plan defines test cases which can be expressed as simply as SQL statements.

Another part of the plan defines the environment requirements which usually consist of the hardware and software used for testing. However, this should also attempt to define potential side effects on the server side which might impact performance, such as processes running periodically or the state of the buffer cache:

# CREATE TABLE foo (id SERIAL NOT NULL PRIMARY KEY, value INTEGER NOT NULL);
# INSERT INTO foo (value) SELECT i FROM generate_series(1, 1000000) i;
# \timing
# SELECT * FROM foo WHERE value = 1;
Time: 124.278 ms
# \! sudo sync
# \! echo 3 | sudo tee -a /proc/sys/vm/drop_caches
# SELECT * FROM foo WHERE value = 1;
Time: 265.871 ms

In order to mitigate the impact of the environment on performance, the test execution part of the plan should make the necessary provisions for running multiple times. So, in the final result analysis part, it could then be possible to produce mean or median values of the performance.

Cost

The cost in PostgreSQL is the planner’s guess at how long it will take to execute a statement measured in units of disk page fetches. To obtain the cost of a statement, prepend the explain command to the statement:

# CREATE TABLE foo (id SERIAL NOT NULL PRIMARY KEY, value INTEGER NOT NULL);
# INSERT INTO foo (value) VALUES (0);
# EXPLAIN SELECT * FROM foo WHERE value = 0;
Seq Scan on foo  (cost=0.00..36.75 rows=11 width=8)

If the test plan consists of repeatedly inserting rows, this may impact the cost of later statements. Furthermore, if the test plan deletes rows after they are inserted, this may also impact cost:

# INSERT INTO foo (value) SELECT i FROM generate_series(1, 1000000) i;
# DELETE FROM foo;
# INSERT INTO foo (value) VALUES (0);
# EXPLAIN SELECT * FROM foo WHERE value = 0;
Seq Scan on foo  (cost=0.00..4425.01 rows=1 width=8)

Even though the cost is more than a hundred times higher, the execution time is actually comparable. So, the concept of cost is not necessarily an accurate measure of performance, it is mostly useful when compared against itself on the same version of PostgreSQL.

Timing

The timing is the actual wallclock time measured in milliseconds to execute a statement. To enable timing of all statements, simply enter the \timing switch and make sure the current status is on:

# \timing
Timing is on.

As opposed to cost, the load of the database and the overall system may impact the timing of statements:

# CREATE TABLE foo (id SERIAL NOT NULL PRIMARY KEY, value INTEGER NOT NULL);
# INSERT INTO foo (value) SELECT i FROM generate_series(1, 1000000) i;
# SELECT * FROM foo WHERE value = 1;
Time: 126.964 ms
# \! sudo updatedb &
# SELECT * FROM foo WHERE value = 1;
Time: 195.682 ms

Even though timing provides a more accurate measure of performance than cost, the result must also be obtained from the interactive terminal. The side effect on the client side is that this makes it difficult to define test cases which must also parse this information.

Logs

Instead of using the interactive terminal, the logs can also be used for timing statements. To enable logging of timing information for all statements, set the following configuration variable in postgresql.conf and make sure to restart the postgres service after applying the changes:

log_min_duration_statement = 0

The separation of timing information from test execution essentially removes the side effect on the client side which no longer needs to parse additional information. This makes it simpler to define test cases which can now be executed from anywhere. For example, the following test cases can be executed a hundred times directly from the command line to measure the performance of inserts:

$ echo "CREATE TABLE foo (id SERIAL NOT NULL PRIMARY KEY, value INTEGER NOT NULL);" | psql
$ for i in `seq 100`; do cat >>'EOF' | psql; done
INSERT INTO foo (value) VALUES (0);
INSERT INTO foo (value) VALUES (0), (1);
INSERT INTO foo (value) VALUES (0), (1), (2), (3), (4), (5), (6), (7), (8), (9);
INSERT INTO foo (value) VALUES (0), (1), (2), (3), (4), (5), (6), (7), (8), (9)... (99);
EOF

The logs can then be parsed and analysed to produce reports as defined in the test plan. For example, the following report provides the median values for running each test case:

2.102 ms: INSERT INTO foo (value) VALUES (?);
1.295 ms: INSERT INTO foo (value) VALUES (?), (?);
1.314 ms: INSERT INTO foo (value) VALUES (?), (?), (?), (?), (?), (?), (?), (?), (?), (?);
2.982 ms: INSERT INTO foo (value) VALUES (?), (?), (?), (?), (?), (?), (?), (?), (?), (?)... (?);

The problem with this report is that the first statement seems to have a timing inconsistent with the other statements. After executing the test cases in the reverse order, the same problem occurs for the first statement which has a timing approximately 0.8 ms higher. Even though logs mitigate some side effects on the client side, the order when executing test cases might also have side effects.

Summary

This post demonstrated how side effects can significantly impact accuracy when testing performance. To mitigate these side effects on the server side, executing test cases multiple times makes it possible to produce mean or median values of the performance. On the client side, using logs instead of the interactive terminal makes it simpler to define test cases. However, there are so many possible side effects that critical attention to inconsistencies must be given throughout the test plan.

About these ads
One Comment leave one →
  1. June 28, 2010 01:26
    #!/usr/bin/env python
    #
    # PostgreSQL log parser which assumes the configuration:
    # log_min_duration_statement = 0
    
    import re
    import sys
    
    from copy import copy
    from datetime import datetime
    from optparse import Option, OptionParser, OptionValueError
    
    
    DEFAULT_AGGREGATE = False
    DEFAULT_IGNORE_CASE = False
    DEFAULT_MEDIAN = False
    
    
    class ParserOption(Option):
    
        def _check_datetime(option, opt, value):
            date_format = "%Y-%m-%d"
            datetime_format = date_format + " %H:%M:%S"
            datetime_timezone_format = datetime_format + " %Z"
    
            for format in datetime_timezone_format, datetime_format, date_format:
                try:
                    return datetime.strptime(value, format)
                except ValueError:
                    pass
    
            else:
                raise OptionValueError(
                    "option %s: invalid datetime value: %r."
                    " Should have a format like \"YYYY-mm-dd (HH:MM:SS (ZZZ))\""
                    % (opt, value))
    
        def _check_regex(option, opt, value):
            try:
                re.compile(value)
            except re.error:
                raise OptionValueError(
                    "option %s: invalid regular expression value: %r."
                    " Should have valid format."
                    % (opt, value))
    
            return value
    
        TYPES = Option.TYPES + ("datetime", "regex",)
        TYPE_CHECKER = copy(Option.TYPE_CHECKER)
        TYPE_CHECKER["datetime"] = _check_datetime
        TYPE_CHECKER["regex"] = _check_regex
    
    
    def get_median(values):
        length = len(values)
        values = sorted(values)
    
        if length % 2:
            return values[(length-1)/2]
    
        else:
            lower = values[length/2-1]
            upper = values[length/2]
    
            return float(lower + upper) / 2
    
    def get_mean(values):
        return float(sum(values)) / len(values)
    
    def parse_file(file, begin=None, end=None, pattern=None,
            ignore_case=DEFAULT_IGNORE_CASE):
        patterns = {
            "datetime": r"(?P<datetime>\d{4}-\d{2}-\d{2} " \
                "\d{2}:\d{2}:\d{2} [A-Z]{3})",
            "duration": r"(?P<duration>\d+\.\d{3}) ms",
            "log": r"((?P<log>\d+): )?",
            "statement": r"(?P<statement>.*)"}
    
        # Log and statement regular expressions
        log_regex = re.compile(r"%(datetime)s "
            "LOG:  %(log)s"
            "duration: %(duration)s  "
            "statement: %(statement)s" % patterns)
        if pattern is not None:
            statement_regex = re.compile(pattern, re.I if ignore_case else 0)
    
        for line in file.readlines():
            match = log_regex.match(line)
            if not match:
                continue
    
            # Check for begin and end datetime
            current = datetime.strptime(match.group("datetime"),
                "%Y-%m-%d %H:%M:%S %Z")
            if (begin and current < begin) or (end and current >= end):
                continue
    
            # Check for pattern and case
            if pattern and not statement_regex.match(match.group("statement")):
                continue
    
            # Convert statement and duration
            statement = match.group("statement")
            duration = float(match.group("duration"))
    
            yield (statement, duration)
    
    def get_file(filename):
        if filename == "-":
            file = sys.stdin
        else:
            file = open(filename, "r")
    
        return file
    
    def get_files(filenames):
        for filename in filenames:
            yield get_file(filename)
    
    def main(args):
        usage = "Usage: %prog [OPTIONS] [FILE...]"
        parser = OptionParser(option_class=ParserOption, usage=usage)
        parser.add_option("-a", "--aggregate",
            action="store_true",
            default=DEFAULT_AGGREGATE,
            help="Aggregate statements by replacing parameters with ?")
        parser.add_option("-b", "--begin",
            type="datetime",
            help="Datetime when to begin parsing inclusively")
        parser.add_option("-e", "--end",
            type="datetime",
            help="Datetime when to end parsing exclusively")
        parser.add_option("-i", "--ignore-case",
            action="store_true",
            default=DEFAULT_IGNORE_CASE,
            help="Ignore case distinction when matching pattern")
        parser.add_option("-m", "--median",
            action="store_true",
            default=DEFAULT_MEDIAN,
            help="Calculate the median instead of the mean")
        parser.add_option("-p", "--pattern",
            type="regex",
            help="Regular expression pattern on which to match")
        (options, args) = parser.parse_args(args)
    
        if not args:
            filenames = ["-"]
        else:
            filenames = args
    
        # Aggregation regular expressions
        number_regex = re.compile(r"\b\d+(\.\d+)?\b")
        string_regex = re.compile(r"E'[^']+'")
    
        statements = {}
        for file in get_files(filenames):
            for statement, duration in parse_file(file, options.begin,
                    options.end, options.pattern, options.ignore_case):
                if options.aggregate:
                    statement = string_regex.sub("?", statement)
                    statement = number_regex.sub("?", statement)
    
                statements.setdefault(statement, [])
                statements[statement].append(duration)
    
        if not statements:
            return 1
    
        for statement, durations in statements.iteritems():
            duration = get_median(durations) \
                if options.median \
                else get_mean(durations)
            print '%.3f ms: %d: %s' % (duration, len(durations), statement)
    
        return 0
    
    
    if __name__ == "__main__":
        sys.exit(main(sys.argv[1:]))
    

Leave a Reply

Fill in your details below or click an icon to log in:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out / Change )

Twitter picture

You are commenting using your Twitter account. Log Out / Change )

Facebook photo

You are commenting using your Facebook account. Log Out / Change )

Google+ photo

You are commenting using your Google+ account. Log Out / Change )

Connecting to %s

Follow

Get every new post delivered to your Inbox.

%d bloggers like this: