If you’re a web developer, I’m sure you’ve deployed code to production and found out afterward that your new “simple” database query is taking forever to return data and is causing major user issues.  Maybe even worse, your query takes up so many computing resources it affects other queries your application’s users depend on.

In the worst cases, you’re not even sure which queries are causing issues. Debugging these issues involves triaging, collecting, and analyzing a bunch of disparate logs and metrics to finally determine that your seemingly innocuous query is the culprit because it was doing a table scan (read: finding data takes a loooong time) on a table that kept increasing in size.  Once you add a simple index to a table, the issue quickly disappears.

But what if you had a way to catch the issue before it turns into a production issue?  Even better, what if you could catch it during your local development process? This was the motivation for creating our new Spring Boot SQL Explain library for Java/Spring.

We created this library for Spring applications so you can automatically execute an explain plan for all your queries and log the results. The results can then be monitored for potential issues from queries that have suboptimal ways of accessing data.  This will allow you to fix bad queries right away in local development environments or test environments.  For the database inclined, using explain plans can give you a glimpse of the performance of a query as you scale your data up.  A query that has a tablescan now may turn into a performance nightmare as your data grows.

We don’t recommend using this in production, of course!

We put it into JSON so it’s parseable by logging tools like Splunk.  Once configured, this is what the logging output looks like …

{
  "Query": "select customer0_.id as id1_0_0_, customer0_.first_name as first_na2_0_0_, customer0_.last_name as last_nam3_0_0_ from customer customer0_ where customer0_.id=?",
  "Explain": [
    {
      "Plan": {
        "Node Type": "Seq Scan",
        "Parallel Aware": false,
        "Async Capable": false,
        "Relation Name": "customer",
        "Alias": "customer0_",
        "Startup Cost": 0,
        "Total Cost": 1.01,
        "Plan Rows": 1,
        "Plan Width": 240,
        "Filter": "((last_name)::text = 'test_save'::text)"
      }
    }
  ]
}

{
  "Query": "select customer0_.id as id1_0_, customer0_.first_name as first_na2_0_, customer0_.last_name as last_nam3_0_ from customer customer0_ where customer0_.last_name=?",
  "Explain": {
    "query_block": {
      "select_id": 1,
      "cost_info": {
        "query_cost": "0.95"
      },
      "table": {
        "table_name": "customer0_",
        "access_type": "ALL",
        "rows_examined_per_scan": 7,
        "rows_produced_per_join": 0,
        "filtered": "14.29",
        "cost_info": {
          "read_cost": "0.85",
          "eval_cost": "0.10",
          "prefix_cost": "0.95",
          "data_read_per_join": "367"
        },
        "used_columns": [
          "id",
          "first_name",
          "last_name"
        ],
        "attached_condition": "(`sql_explain`.`customer0_`.`last_name` = 'test_save')"
      }
    }
  }
}

How To Use It

You can install it from our Github maven repo by adding this repository to your Maven/Gradle configs:

<dependency>
    <groupId>com.deptagency</groupId>
    <artifactId>spring-sql-explain-logger</artifactId>
    <version>0.0.3</version>
</dependency>

implementation 'com.deptagency:spring-sql-explain-logger:0.0.3'

Then, add the config property below wherever you usually set your application properties (for example src/main/resources/application.properties) and set value to true to enable explain plan logging:

com.deptagency.sqlexplain.enabled=true

Of course, we would definitely not turn on this tool in production!  Running it locally before committing code, or in a pinch, turning it on in a dev/test environment to get an idea of your heavy queries though might be a great use case.

Finally, add a Spring @ComponentScan for the package somewhere in your project.

@ComponentScan("com.deptagency.sqlexplain")
public class MyApplication {

    // amazing things happen here

}

There are a lot more details in the project's README!

Limitations

Right now, the library only supports PostgreSQL and MySQL.  If there's demand, we can support others as well though.

Also, right now there’s no way to customize the logging levels for different types of scans, but we plan on doing that soon.

How it was made

If you’re like us, you love the details of how things are made, so we’d love to tell you how we cooked this up.  If you’re interested in that stuff read on, otherwise, just enjoy using the library!

When we first had this idea, we thought it would be simple to do this, especially for applications that use Hibernate. We could easily get the SQL query of the prepared statement that Hibernate was executing. Then we started to look for a way to get the prepared statement bind parameters (the data that’s sent into the parameters) so we could execute the explain plan query.

That turned into a much harder problem: Neither Hibernate nor JDBC API provided an easy way to get the data for the parameters. One of the solutions we explored was proxying the Datasource and intercepting JDBC calls but we wanted the proxy to be as least intrusive as possible and easy to enable and disable per environment.

What we finally found was that the Spring BeanPostProcessor has a great way of accomplishing this. You can intercept any bean during creation and add a proxy and you can also make the proxy conditional based on a configuration property.  We were lead on to this solution when we stumbled across the general purpose Spring Boot Data Source Decorator on Github.  That project is excellent, but we wanted something purpose-built to help with database query profiling that was very easy to set up.

In the end, this is a bit of the magic that makes it work (full source here):

@Component
@ConditionalOnProperty(value = "com.deptagency.sqlexplain.enabled", havingValue = "true")
public class ExplainPlanDatasourceProxyBean implements BeanPostProcessor {
    ...
    @Override
    public Object postProcessAfterInitialization(final Object bean, final String beanName) throws BeansException {
        if (bean instanceof DataSource) {
            Optional<DatabaseDialect> dbDialect = DatabaseDialect.getDatabaseDialectByURL(jdbcURL);

            if (dbDialect.isPresent() && dbDialect.get().isSupported()) {
                ProxyFactory factory = new ProxyFactory(bean);
                factory.setProxyTargetClass(true);
                factory.addAdvice(new ProxyDataSourceInterceptor((DataSource) bean, dbDialect.get(), maxCacheSize, queryCacheExpiry));
                return factory.getProxy();
            } else {
                logger.warn("WARN database is not currently supported. Currently supported databases include {} ",
                        DatabaseDialect.getSupportedDatabases());
            }
        }
        return bean;
    } 
}