Counting Queries: PostgreSQL SQL Analysis
March 16, 2004By Tom Copeland
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
log_statement = true syslog = 2 syslog_facility = 'LOCAL0' syslog_ident = 'postgres'
You will need to not only uncomment the
[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:  LOG: query: SELECT * FROM groups WHERE group_id='1' Mar 4 16:40:06 rubyforge postgres: [79-1] LOG: query: SELECT * FROM user_group Mar 4 16:40:06 rubyforge postgres: [79-2] ^I^I^IWHERE user_id='102' Mar 4 16:40:06 rubyforge postgres: [79-3] ^I^I^IAND group_id='1' Mar 4 16:40:06 rubyforge postgres:  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
#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.,
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
We can also see that we are selecting the entire contents of the
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
[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
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.