Counting Queries: PostgreSQL SQL Analysis

March 16, 2004

Everyone wants their database-backed web application to run faster on the same hardware - if a software tweak can postpone a hardware upgrade for a year, it's usually well worth it. One way to improve performance is to examine how the application is interacting with the database, and see if there is anything that we can do to speed things up. We will take a look at a handy script that can examine PostgreSQL logs and let you know what queries are getting run the most.

It is worth a moment to think of the various types of optimization that you can do on a database. There's tuning the database server itself - for PostgreSQL this means tweaking the shared memory parameters and write-ahead log sizes and such in the PostgreSQL configuration file. There's tuning the operating system on which the database is running - making sure you have enough threads to prevent the server from starving, making sure you've got a proper filesystem selected, and so forth. We are going to tune things at a slightly higher level - the database queries themselves.

Naturally, "tuning the queries" can be further broken down as well. One option is to work on optimizing queries that will help make specific parts of your application run faster. For example, if you notice that bringing up a customer detail screen takes a long time - whatever "long" means in your environment - it might be worth seeing what queries are being run to bring up the information. If the application is doing twenty different queries to get the data for that screen, perhaps the queries can be combined, or perhaps an expensive table scan is being done on a large but infrequently updated table, and an index could be added somewhere.

Another type of optimization is a sort of general optimization that you can do by seeing what queries are being run the most and working on those. This does not have the immediate satisfaction of seeing a screen display faster, but it is not a bad idea if you have some time and you want to do some future load-proofing. That is the sort of optimization we are going to focus on here.

As background information, I help work on GForge, an Open Source collaborative software development tool that allows you to organize and manage any number of software development projects. I also administer a fairly active installation of GForge called RubyForge; it hosts 170 projects and over 500 users. It is backed by a PostgreSQL database that executes about 60,000 queries per day. Thus, I have a vested interest in helping GForge to run efficiently on commodity hardware. There are many other sites running GForge as well - you can find a list of sites here. Several of these installations are much larger than mine is, and general optimizations will help them as well.

Now that we have narrowed our focus a bit, we need to figure out how to get some data to analyze. A list of SQL queries that the database has executed is a good place to start, and fortunately, PostgreSQL provides an easy way to get that. Note that I am running PostgreSQL 7.3 installed from an RPM on a RedHat Linux machine - your PostgreSQL installation may be different if you are on another platform, but hopefully the principles will be the same.

To turn on query logging, edit your postgresql.conf - mine is at the path /var/lib/pgsql/data/postgresql.conf. We will need to set the following options:

log_statement = true
syslog = 2              
syslog_facility = 'LOCAL0'
syslog_ident = 'postgres'

You will need to not only uncomment the log_statement option, but also set it to "true." There are some other logging options like log_duration that can supply more information, but we will leave those for later. Now, tell PostgreSQL to reload the configuration file by issuing a "reload" command:

[root@rubyforge tom]# /etc/rc.d/init.d/postgresql reload

Click around your application a bit and PostgreSQL will start sending data to syslog. You can ensure this is happening by checking the last few lines of the syslog file:

[root@rubyforge tom]# tail -5 /var/log/messages
Mar  4 16:40:06 rubyforge postgres[24574]: [78] LOG:  query: SELECT * FROM groups WHERE group_id='1'
Mar  4 16:40:06 rubyforge postgres[24574]: [79-1] LOG:  query: SELECT * FROM user_group
Mar  4 16:40:06 rubyforge postgres[24574]: [79-2] ^I^I^IWHERE user_id='102'
Mar  4 16:40:06 rubyforge postgres[24574]: [79-3] ^I^I^IAND group_id='1'
Mar  4 16:40:06 rubyforge postgres[24574]: [80] LOG:  query: BEGIN;ROLLBACK;
[root@rubyforge tom]#

Yep, looks like we are collecting data. Now we need to leave it running for a while to collect "live" data. This is a bit of a balancing act - we don't want to let it run too long, since it's logging a lot of data and that slows things down, but at the same time we need to collect a fair bit of data to ensure we have useful results. In my case, I let the logging run for 4 hours, during which it collected about 2.5 MB of data representing around 10,000 SQL queries.

When you have enough data, you can turn off logging by editing your postgresql.conf and commenting out the changes you made earlier:

#log_statement = true
#syslog = 2              
#syslog_facility = 'LOCAL0'
#syslog_ident = 'postgres'

After you have commented those lines out, rerun the "reload" command again - i.e., /etc/rc.d/init.d/postgresql reload. Of course, if you are going to do this a few times, it is worth making both a postgresql.conf.nologging and a postgresql.conf.logging file and copying the appropriate one on top of the active postgresql.conf.

Now you have a pile of data in your syslog file. I usually run the SQL analysis on another machine, so I will tar up the syslog file and copy it to my workstation:

[root@rubyforge tmp]# tar -zcf sql_statement_data.tar.gz /var/log/messages

[root@rubyforge tmp]# scp sql_statement_data.tar.gz tom@hal:

Of course, you can run the analysis on the database server as well; just do whatever is appropriate for your environment.

The next step is to actually analyze the data and see what we find. We could just scroll through the raw data, but that would take forever. Therefore, I wrote a little Ruby library called PostgreSQL Query Analyzer (PQA) to parse the data file and analyze the queries. If you are not familiar with Ruby, it is an object-oriented scripting language that is great for various system administration and data manipulation tasks. To run PQA, you will need to have Ruby installed.

On to the results. Here is a sample run showing the top eight queries:

[tom@hal pqa]$ ./pqa.rb -top 8 -file overnight_query_data.txt
10077 queries (2826 unique) parsed in 1.984141 seconds
8 most frequent queries
931 times:  BEGIN;ROLLBACK;
780 times:  SELECT * FROM plugins
574 times:  SELECT language_code FROM supported_languages WHERE language_id='1'
574 times:  SELECT language_id FROM supported_languages WHERE classname='English'
295 times:  select * from supported_languages where language_code = 'en'
162 times:  select * from supported_languages where language_code = 'en-us'
85 times:  SELECT total FROM forum_group_list_vw WHERE group_forum_id='721'
[tom@hal pqa]$

Already we see something very interesting - the supported_languages table is queried the same number of times by two rather similar queries. This is an indication that there might be a sequence of two queries that could be combined into one, which is a big win - we will eliminate five percent of the total number of queries in one fell swoop. Looks like our analysis efforts have been repaid already. In addition, if we were to look at the top 30 or 40 queries, we could probably find some more instances of this sort of thing.

We can also see that we are selecting the entire contents of the plugins table. Is there a way we can add some constraints to the query to limit the results? Is that moving a lot of data around? In this specific case, this is not a problem since the plugins table is very small. Still this is a good thing to be aware of if we start adding plugins - this query may be one to watch.

However, let's not stop there - let's see what happens if we "normalize" the SQL queries. By that I mean we remove all the literal values, so that select language_id FROM supported_languages WHERE classname='English' is turned into select language_id FROM supported_languages WHERE classname=''. That way we can get an even better picture of what queries it might be helpful to rewrite as stored procedures. Let's see:

[tom@hal pqa]$ ./pqa.rb -top 8 -normalize -file overnight_query_data.txt
10077 queries (260 unique) parsed in 1.977645 seconds
8 most frequent queries
931 times:  BEGIN;ROLLBACK;
780 times:  SELECT * FROM plugins
780 times:  INSERT INTO activity_log (day,hour,group_id,browser,ver,platform,time,page,type) 
		VALUES (20040225,'','','','','','','','');
688 times:  SELECT language_id FROM supported_languages WHERE classname=''
688 times:  SELECT language_code FROM supported_languages WHERE language_id=''
644 times:  select * from supported_languages where language_code = ''
634 times:  SELECT total FROM forum_group_list_vw WHERE group_forum_id=''
[tom@hal pqa]$

Note that the number of unique queries has been reduced from 2826 to 260 - normalizing them shows that there really aren't that many unique queries. Now we can also see that combining those two supported_languages queries will save us even more than we thought - we will be able to eliminate almost 7% of our queries. Obviously, that activity_log query is a frequently used one - but with differing values each time, which is why it only showed up when we normalized. It might be a candidate for a stored procedure.

We have discussed a couple of different types of optimizations and when they are useful. We have poked around the PostgreSQL database configuration file and learned how to log SQL statements. We have seen how we can use the open source PostgreSQL Query Analyzer utility to analyze the data and report useful results, and we've done a bit of reasoning about the results to see what queries might actually be worthy of rewriting. Also, development on PQA will continue - drop by the project site if you have any suggestions, bug reports or comments. Thanks!

Many thanks to the folks on the #ruby-lang Internet Relay Chat (IRC) channel for helping me figure out some regular expressions that PQA uses. Thanks also to the folks on the #pgsql channel for a philosophical discussion on general optimization techniques. Finally, thanks to my co-workers Joe Coffman, Dave Craine, and Rich Kilmer, who helped me work through various technical issues in the development of PQA.