tylerrussell.dev

Problem: The default Sentry configuration for Spring Boot does not provide enough granularity to trace performance problems. Developers can augment code paths by specifically auditing them, but that feels too manual.

Initial Setup

Sentry is a great visibility tool for startups. Having used other options at larger companies, we choose Sentry at Masset for its pricing and ease of setup. It doesn’t meet all needs for monitoring and logging; there are better options out there for that. But when building a margin-focused company, you can’t go and spend a lot on vendors right up front. We’ve gotta get some revenue to make that worth it.

The initial setup of Sentry with Spring Boot (our backend framework) was dead simple. Follow the Getting Started instructions to configure the Sentry DSN and configure a few beans. With that, we get Exception reporting and basic APM functionality, if enabled. But if we look into our transactions and spans, we realize there isn’t much there.

Not extremely helpful for debugging. Let’s add some more spans.

What is already traced?

The default Sentry configuration integrates with Spring MVC to create Transactions on web requests. So we don’t need to worry about creating Transactions in most cases, just adding some new spans.

One option is to wrap trace paths with the @SentrySpan annotation. Definitely a valid option, but often you need to identify performance problems on historical transactions. If you haven’t manually annotated, you’re out of luck. Instead, it’s often better to over-trace and limit volume using sampling.

So what do we trace by default? Every method would be too much, but full web transactions are too little. There’s no perfect answer here, but we’ve found that public methods on Spring Beans are a fairly good representation of things we want traced at Masset.

Span Creation on Beans

The default Sentry setup provides a pointcut in SentrySpanPointcutConfiguration.

@Bean
public @NotNull Pointcut sentrySpanPointcut() {
  return new ComposablePointcut(new AnnotationClassFilter(SentrySpan.class, true))
    .union(new AnnotationMatchingPointcut(null, SentrySpan.class));
}

Overriding the sentrySpanPointcut bean gives us an easy place to setup our own span configuration. Note that if you don’t have Spring AOP in your project already, you may need to add spring-boot-starter-aop or configure it for your application manaully.

After some thoughts, we decided we wanted to keep the same behavior for SentrySpan, but also augment with a large set of the Spring Beans. The easiest way to do this is simply to include a few more annotations in the pointcut.

@Bean
fun sentrySpanPointcut() =
      // Spring repositories
  ComposablePointcut(AnnotationClassFilter(Repository::class.java, true))
      // Spring services
      .union(AnnotationClassFilter(Service::class.java, true))
      // Spring components
      .union(AnnotationClassFilter(Component::class.java, true))
      // MyBatis Mappers
      .union(AnnotationClassFilter(Mapper::class.java, true))
      // functions/classes annotated with @SentrySpan
      .union(AnnotationMatchingPointcut(null, SentrySpan::class.java))
      .union(AnnotationClassFilter(SentrySpan::class.java, true))

Let’s rerun our web request and see what we get.

Awesome! That looks much better. But a few things are not quite right.

1. We’re getting tracing on Spring code. This isn’t wrong based on our definition, but not really what we want.
2. Where are our MyBatis Mappers? We have a pointcut on the @Mapper annotation, so why aren’t they showing up? The AssetSearchMapper shows up, but it’s registered manually using the @Component annotation. Where are the mappers from @MapperScan?

Let’s tackle #1 first. We’ll do two things, 1. Scope tracing to items in our root package and 2. allow developers to turn off tracing using a custom @NoTrace annotation.

@Bean
fun sentrySpanPointcut() =
    // Spring repositories
  ComposablePointcut(AnnotationClassFilter(Repository::class.java, true))
    // Spring services
    .union(AnnotationClassFilter(Service::class.java, true))
    // Spring components
    .union(AnnotationClassFilter(Component::class.java, true))
    // MyBatis Mappers - NOT WORKING. NEEDS FIXIN'
    .union(AnnotationClassFilter(Mapper::class.java, true))
    // functions/classes annotated with @SentrySpan
    .union(AnnotationMatchingPointcut(null, SentrySpan::class.java))
    .union(AnnotationClassFilter(SentrySpan::class.java, true))
    // filter out anything outside of the masset root package
    .intersection { it.packageName.contains("com.masset") }
    // filter out anything 
    .intersection{ !AnnotationClassFilter(NoTrace::class.java, true).matches(it) }

Using MyBatis interceptors

Alright, now let’s tackle that MyBatis Mapper problem. To understand what’s going on there, we have to understand a little bit of the innards of Mappers. MyBatis is a bit unique in how it registers beans. Using @MapperScan, it scans for all interfaces annotated with @Mapper and proxies those beans to actual implementations, which are injected into the DI container.

So the Mapper beans in the DI container are actually not annotated with @Mapper once they are created. One might think you could do a pointcut to the concrete class that MyBatis creates, but attempting to do that led to failure as well. After digging into some documentation, code, and Github issues online, it appears that Spring AOP simply doesn’t work well with MyBatis Mappers.

We could implement AspectJ, or continue digging further to find a workaround, but we’ve already wasted a lot of time on this. It’s probably best to find a valid solution and move on. We are a startup afterall!

Some quick Googling leads to the concept of MyBatis plugins/interceptors. Interceptors allow us to run a piece of code whenever a MyBatis Mapper method is called. This will allow us to intercept things like selects, updates, etc. In combination with Sentry’s documentation on manually adding custom spans, we should be able to intercept function calls relatively easily.

We could use this same method to include the queries executed and their run times, but at Masset we monitor queries directly at the database level using Postgres’s slow query log. So for our purposes today, knowing the Mapper methods that were called is more than sufficient.

After a bit of trial and error, we end up with two basic Interceptors on MyBatis methods. We could intercept a few more methods if needed, but these give us what we want for now.

@Intercepts(
    Signature(
        type = Executor::class,
        method = "query",
        args = [MappedStatement::class, Any::class, RowBounds::class, ResultHandler::class]
    )
)
class MybatisQueryInterceptor : Interceptor {
    override fun intercept(invocation: Invocation) = wrapWithSpan(invocation)
}

@Intercepts(
    Signature(
        type = Executor::class,
        method = "update",
        args = [MappedStatement::class, Any::class]
    )
)
class MybatisUpdateInterceptor : Interceptor {
    override fun intercept(invocation: Invocation) = wrapWithSpan(invocation)
}

private fun wrapWithSpan(invocation: Invocation): Any {
    val inner = Sentry.getSpan()?.startChild(getMapperName(invocation))
    return try {
        invocation.proceed()
    } finally {
        inner?.finish()
    }
}

private fun getMapperName(invocation: Invocation) =
    (invocation.args[0] as MappedStatement).id
        .split(".")
        .takeLast(2)
        .joinToString(",")

Make sure to add your interceptors to your SqlSessionFactoryBean! Otherwise you might be chasing your tail for a while trying to figure out why the interceptors aren’t being called.

@Bean
fun defaultSqlSessionFactoryBean(): SqlSessionFactoryBean {
    val factoryBean = SqlSessionFactoryBean()
    val config = Configuration()
    // ...
    config.addInterceptor(MybatisQueryInterceptor())
    config.addInterceptor(MybatisUpdateInterceptor())
    // ...
    factoryBean.setConfiguration(config)
    return factoryBean
}

Let’s run our request one last time and make sure we get what we want.

Success! We’ve got spans for our Controller, public Service methods, and our MyBatis Mappers. That should give us plenty of information to narrow down performance concerns as they arise in the future. Now let’s go build some customer-facing deliverables!