koldfront

Speed alerts #activitypub #postgresql

I have configured PostgreSQL to log queries that take more than some-number of milliseconds, so I can notice which queries are slow and perhaps do something about it.

Recently I have been noticing - in the window I have running tail -F on various logfiles (using autossh to my various servers, and piping it through ccze for colours) - that sometimes I had queries logged taking around 650 ms.

Last Sunday I finally decided to look at it. It was a whopper of a query coming from illuminant-nntp, when Gnus was fetching an article from illuminant.timeline by number.

The article numbers are generated by the query, so this had become slower as the number of toots in Illuminant's database has grown. Looking closer at the query, I realized that the sub-query finding the toots matching the article number also did a lot of the processing to get the information to return. Which is sub-optimal (haha) because it was doing that for all toots up until the article number that was actually needed.

So I fought the SQL for a while, changing the sub-query to only fetch/do as much as necessary to get the object id matching the wanted article number, and then moving all the formatting and information gathering "outside", to the top-query that now only had the one object and accompanying activities to get and convert to an article.

With that change the queries went from around 650 ms to around 200-220 ms. A nice improvement.

What's interesting is that I did not feel opening an article in illuminant.timeline in Gnus was slow - I guess the rule of thumb of a second is pretty good. But after making the improvement, opening articles feels snappy - so the preemptive optimization was a boon. And hopefully it will be a while until I have to figure out some other optimization to drop the query time again.

Yay monitoring!