February 28, 2005

PostgreSQL | psql: a terminal question of \timing

PostgreSQL's command line utility psql provides a settings toggle \timing which displays the time it takes to run a statement, right down to thousandths of a millisecond. This is very useful for debugging speed-critical statements, especially for web-based applications where a few milliseconds either way can make a noticeable cumulative difference.

Recently I was struggling with a particular statement which normally executed in less than 10ms, but with the addition of a single additional condition in the WHERE clause, execution time went up by a factor of five to around 50ms. (In human terms that might not sound a lot, "only" 1/20th of a second, but the app should be able to deliver the entire dynamic web page within 250ms - in that case 40ms is suddenly a very long time).

The usual suspects in this kind of situation - differing query plans, lack of recent VACUUM ANALYZE etc. - were evidently not guilty, and no amount of SQL voodoo would make any difference.

After playing around for a while I noticed that occasionally the statement would execute about as fast as I was expecting it. Aha. I was using konsole, KDE's bundled terminal program. This is sorta nice because it has tabbed terminal sessions, but is occasionally a little sluggish. Running top it became evident that almost every time psql submits a query, a kdeinit process jumps to the top of the list, which is presumably what causes the execution slowdown.

Executing the same query in the venerable xterm produced the expected execution speed every time.

Time for a different terminal application methinks.

Posted at 7:14 AM