Battling Database Performance

What we found was that this issue was fairly widespread—there was no single connection pool affected.

We'd been hoping for it to be a single pool, as that would have made it a little simpler to hone in on the work in that pool and optimize it.

In lieu of that, we started looking at general database health. Historical HTTP traffic and PubSub metrics didn't suggest that anything we received at that time was out of the ordinary. Heroku's Postgres stats also suggested a fairly normal database load, though it did highlight some neglected queries that had been getting slower as our database grew.

Having no obvious place to start, we decided to fix anything that looked slow and was a quick win. We'd shipped a number of optimizations, including:

At this point, we felt we'd sunk a decent amount of time into investigating this outage, and we'd shipped a good amount of low-hanging fruit; we called it a day and closed the incident.

One of our engineers, Lawrence, joined the incident and suggested, rather than playing whack-a-mole and patching query after query, adding a one-second lock timeout to all of our transactions.

As we weren't in a great state, this would at least let us quickly identify which requests were holding onto transactions longer than we'd like.

We deployed this change, and fortunately, nothing broke, but unfortunately, this meant we were still no closer to identifying the cause of our slowdowns.

Originally, we would receive this event from Slack, and within the lifetime of that HTTP request, we'd perform any responses we needed to, e.g., offering to attach a GitHub link that a user has just posted in the channel. Regardless of the operation, we'd always do some database queries, like looking up the organization with that Slack team ID.

To help alleviate periods of high traffic, we began processing these events asynchronously instead. So when a Slack webhook comes in, we now just forward that straight to PubSub and avoid making any database queries.

By using PubSub, we can throttle access to the database a bit more, and if we want, we get some retry logic for free. The downside is that we've introduced some additional latency in the time it takes us to process events, but we feel that's a reasonable tradeoff.

This felt like quite a significant change, so we again called it a day and hoped that was the last of our timeouts.

The golden egg we wanted was to be able to group operations over a time period and sum up the total time that operation spent holding a connection pool. This would give us the ability to query things like "Which API endpoints are hanging onto database connections for the longest?".

We already log a metric whenever we process a PubSub message or handle an HTTP request. With this, we know "How long did this operation take," "What operation is it," "What group of services does it belong to?" So, we looked at updating that log with additional info about connection pool usage.

In theory, calculating the time we spend in connection pools sounds easy enough, but it, unfortunately, wasn't as simple as 'start timer, run query, end timer.' For starters, we couldn't put a timer around every database query we run, so we needed a middleware to apply this globally. Additionally, whenever we open a database transaction, a connection pool is held for the lifetime of the transaction, so we needed to devise a way to detect if we're in a transaction and alter our counting logic as required.

For the middleware, we initially looked at plugging something into Gorm—our ORM. But we soon realized that the hooks provided by Gorm included the time we spent waiting on a connection pool, so we'd be counting the stuff we already knew.

Instead, we implemented a middleware in the ngrok/sqlmw package which allowed us to hook into code right before and right after a query or transaction occurred. Here, we called out a new method we added - trackUsage —that utilized go's Context to maintain our new counter.

func trackUsage(ctx context.Context) (end func()) {
    inTransaction, _ := ctx.Value(InTransactionContextKey).(bool)
    startTime := time.Now()
    return func() {
        duration := time.Since(startTime)
        log.AddCounter(ctx, log.DatabaseDurationCounterKey, duration)
        // If we're inside a transaction, the connection is held for the entire
        // transaction duration, so we avoid double-counting each individual
        // statement within the transaction
        if !inTransaction {
            log.AddCounter(ctx, log.DatabaseConnectionDurationCounterKey, duration)
        }
    }
}

Now, we can filter both our logs and traces by the time each operation spends holding a database connection pool.

Using tools like Grafana, we can group this by the type of operation and sum up the value over a time period. But, we've yet to really make use of this. While we were waiting for some useful data, we shipped another change that solved the root cause of our slowdowns.

While sifting through our logs to check: "How are we looking after yesterday's fixes," and "Is our connection pool counter working?" we noticed an unnecessary transaction we were opening whenever we were handling the submission of a Slack modal. This is an HTTP endpoint that Slack calls whenever a user presses the confirmation button in the view you see when you use a slash command like /inc.

We removed the transaction for most modal submissions, and in cases where we needed transactional guarantees, we added it for those code paths explicitly.

It wasn't until a few days later that we realized this was the root of our problems. As the timeouts were intermittent and didn't occur every day, it took a little while to confirm the issue. But it's now been four months, and we've been database timeout free.

This did confirm our suspicions from earlier on—there wasn't one noticeably slow thing that caused this issue. Instead, it was many short transactions that, when added together, caused us some real problems.

It was a little disappointing to fight with this issue for days and for there to not be an aha! moment, where we solved everything in one fell swoop.

But, on the upside, we're now much better equipped to diagnose problems like this in the future. And we've made some legitimate performance improvements that should make our application faster for our users.

Had we been using different databases for different parts of our application, we'd likely have been able to track down this issue sooner. However, that's certainly not free to do that either. With that, we'd have to start thinking about distributed transactions, and our development environments would be less slick, but we're happy with the tradeoffs we've made for now.