LINE 株式会社 B2B Platform 開発担当フェローの Matsuno です。

LINE の Business Platform ではメインのデータベースとして MySQL を利用しています。MySQL は非常に高速に動く OSS の RDBMS なので、とても便利に利用させていただいております。

MySQL はとても高速なのですが、うっかり index を使わないクエリを発行した場合に実行がとても遅くなってしまうことがあります。LINE の Business Platform はとても多くのお客様が利用されるので、B2B としては異例なほどトラフィックが多く、少し遅いクエリが発生した結果としてサイト全体がダウンしてしまう可能性もあります。

そこで、防御策として我々は ExplainPolice とよんでいる手法を長年採用しているので、それを今回はご紹介しようと思います。

ExplainPolice とは

複雑なクエリを実装する際には、クエリの実行計画をきちんと考えて実装することが大事ですね。

MySQL では EXPLAIN 文を利用することで、クエリの実行計画を調べることができます。ですから、複雑なクエリを実装する前には毎回 EXPLAIN を発行して、クエリが想定した実行計画になっているかを確認することが大事です。

しかし、常にすべてのクエリを EXPLAIN していては時間がとてもかかりますし、日々の業務におわれているなかでは忘れてしまったりしがちです。

そこで、機械ができることは機械に自動的にやってもらおうということで導入されているのが ExplainPolice です。クエリの実行時に EXPLIAN つきでもう一度クエリを実行する仕組みを導入して、その結果を解析することで重いクエリを発見します。

ExplainPolice はどのように動くのか

EXPLAIN 文を自動的に実行する方法はいくつか考えられると思うのですが、我々の組織では MyBatis の interceptor として実装しています。

MyBatis は Java のデータベースアクセスライブラリで、SQL を直接書けるタイプのライブラリです。JPA などの O/R Mapper を利用してもいいのですが、LINE の Business Platform の場合、トラフィックが非常に多く、複雑なクエリを発行したいケースも多いため Mybatis を利用するケースが多いです。

特定のクエリが遅いことが問題になった場合の原因の検出が非常に高速にできるのがメリットになっています。

MyBatis には Interceptor 機構があり、クエリの実行時にフックできるようになっているため、これを利用して発行クエリの実行計画を取得しています。以下のような形で実装しています。

/*
 * Copyright (c) 2022 LINE Corporation. All rights reserved.
 * LINE Corporation PROPRIETARY/CONFIDENTIAL. Use is subject to license terms.
 */
 
package com.example.interceptor.expainpolice
 
import mu.KLogger
import mu.KotlinLogging
import org.apache.ibatis.builder.StaticSqlSource
import org.apache.ibatis.cache.CacheKey
import org.apache.ibatis.executor.Executor
import org.apache.ibatis.mapping.BoundSql
import org.apache.ibatis.mapping.MappedStatement
import org.apache.ibatis.mapping.SqlCommandType
import org.apache.ibatis.plugin.Interceptor
import org.apache.ibatis.plugin.Intercepts
import org.apache.ibatis.plugin.Invocation
import org.apache.ibatis.plugin.Signature
import org.apache.ibatis.scripting.defaults.DefaultParameterHandler
import org.apache.ibatis.session.ResultHandler
import org.apache.ibatis.session.RowBounds
import java.sql.Connection
import java.sql.ResultSet
import java.util.concurrent.ConcurrentHashMap
 
@Intercepts(
    Signature(
        type = Executor::class,
        method = "query",
        args = [MappedStatement::class, Any::class, RowBounds::class, ResultHandler::class,
            CacheKey::class, BoundSql::class]
    ),
    Signature(
        type = Executor::class,
        method = "query",
        args = [MappedStatement::class, Any::class, RowBounds::class, ResultHandler::class]
    )
)
class ExplainPoliceInterceptor : Interceptor {
    override fun intercept(invocation: Invocation): Any {
        try {
            val connection = (invocation.target as Executor).transaction.connection
            val statement = invocation.args[0] as MappedStatement
            val parameter = invocation.args[1]
            val boundSql = statement.getBoundSql(parameter)
            val sqlContext = SqlContextHelper.getSqlContext(statement.id)
 
            // EXPLAINを実行して違反がないかチェック
            val violations = checkViolations(sqlContext, connection, statement, parameter, boundSql)
            if (violations.isNotEmpty()) {
                sqlContext.logger.error(reportMessage(sqlContext.sqlId, violations))
            }
        } catch (expected: Exception) {
            // error log出して処理を継続
            log.error("Unexpected error in explain process.", expected)
        }
        return invocation.proceed()
    }
 
    /**
     * @return key: table, value: violations
     */
    private fun checkViolations(
        sqlContext: SqlContext,
        connection: Connection,
        statement: MappedStatement,
        parameter: Any?,
        boundSql: BoundSql,
    ): Map<String, List<String>> {
        return executeQuery(
            connection = connection,
            query = "EXPLAIN ${boundSql.sql}",
            statement = statement,
            parameter = parameter,
            boundSql = boundSql
        ) {
            processResultSet(it, sqlContext)
        }
    }
 
    /**
     * @return key: table, value: violations
     */
    private fun processResultSet(
        rs: ResultSet,
        sqlContext: SqlContext,
    ): Map<String, List<String>> {
        return buildMap {
            while (rs.next()) {
                val table: String = rs.getString("table") ?: "UNKNOWN"
                val extra = rs.getString("Extra") ?: ""
                val type = rs.getString("type") ?: ""
                val rows = try {
                    rs.getString("rows")?.toLong() ?: 0
                } catch (ignored: NumberFormatException) {
                    0
                }
                sqlContext.logger.trace(
                    "Explain result: sqlId={}, table={}, type={}, rows={}, extra={}",
                    sqlContext.sqlId, table, type, rows, extra
                )
 
                val violations = buildList {
                    if (extra.contains("filesort", ignoreCase = true) &&
                        !sqlContext.explainPoliceOptions.allowFileSort
                    ) {
                        add("filesort")
                    }
                    if (extra.contains("temporary", ignoreCase = true) &&
                        !sqlContext.explainPoliceOptions.allowTemporary
                    ) {
                        add("temporary")
                    }
                    if (type.contains("all", ignoreCase = true) &&
                        !sqlContext.explainPoliceOptions.allowFullScan
                    ) {
                        add("full scan")
                    }
                }
                if (violations.isNotEmpty()) {
                    put(table, violations) // buildMap
                }
            }
        }
    }
 
    private fun reportMessage(
        sqlId: String,
        violations: Map<String, List<String>>,
    ): String {
        return """
            Detect Bad SQL!!
            sqiId: $sqlId
            violations:
            ${violations.map { "  ${it.key}: ${it.value.joinToString(", ")}" }.joinToString("\n")}
        """.trimIndent()
    }
 
    private fun <T> executeQuery(
        connection: Connection,
        query: String,
        statement: MappedStatement,
        parameter: Any?,
        boundSql: BoundSql,
        block: (ResultSet) -> T
    ): T {
        val sqlSource = StaticSqlSource(statement.configuration, query, boundSql.parameterMappings)
        val queryStatement =
            MappedStatement.Builder(statement.configuration, "explain_sql", sqlSource, SqlCommandType.SELECT)
                .resultMaps(statement.resultMaps)
                .resultSetType(statement.resultSetType)
                .statementType(statement.statementType)
                .build()
        val handler = DefaultParameterHandler(queryStatement, parameter, boundSql)
 
        return connection.prepareStatement(query).use { stmt ->
            handler.setParameters(stmt)
            stmt.executeQuery().use { block(it) }
        }
    }
 
    companion object {
        private val log = KotlinLogging.logger {}
    }
}
 
internal object SqlContextHelper {
    private val log = KotlinLogging.logger {}
 
    private val CLASS_AND_METHOD_MATCHER = """(?<class>.*)\.(?<method>[\w_]+)""".toPattern()
 
    private val DEFAULT_EXPLAIN_POLICE_OPTIONS: ExplainPoliceOptions = object {
        @ExplainPoliceOptions
        fun method() {
            // NOOP
        }
    }.let { it.javaClass.getMethod("method").getAnnotation(ExplainPoliceOptions::class.java)!! }
 
    // key: sqlId, value: SqlContext
    // (ConcurrentHashMapで全部保持しても問題ないだろう)
    private val CACHE: ConcurrentHashMap<String, SqlContext> = ConcurrentHashMap<String, SqlContext>()
 
    fun getSqlContext(sqlId: String): SqlContext {
        return CACHE.computeIfAbsent(sqlId) {
            log.debug("Build SqlContext for $sqlId")
 
            val matcher = CLASS_AND_METHOD_MATCHER.matcher(sqlId)
 
            if (!matcher.matches()) {
                SqlContext(
                    sqlId = sqlId,
                    className = "UNKNOWN",
                    methodName = "UNKNOWN",
                    logger = KotlinLogging.logger(sqlId),
                    explainPoliceOptions = DEFAULT_EXPLAIN_POLICE_OPTIONS,
                )
            } else {
                val className = matcher.group("class")
                val methodName = matcher.group("method")
                val explainPoliceMetadata = try {
                    Class.forName(className)
                        .methods
                        .firstOrNull { it.name == methodName }
                        ?.getAnnotation(ExplainPoliceOptions::class.java)
                        ?: DEFAULT_EXPLAIN_POLICE_OPTIONS
                } catch (ignored: ClassNotFoundException) {
                    log.info("Cannot find class. class={}, sqlId={}", className, sqlId)
                    DEFAULT_EXPLAIN_POLICE_OPTIONS
                }
 
                SqlContext(
                    sqlId = sqlId,
                    className = className,
                    methodName = methodName,
                    logger = KotlinLogging.logger(sqlId),
                    explainPoliceOptions = explainPoliceMetadata,
                )
            }
        }
    }
}
 
/**
 * 実行するSQLに関する情報
 */
data class SqlContext(
    val sqlId: String,
    val className: String,
    val methodName: String,
    val logger: KLogger,
    val explainPoliceOptions: ExplainPoliceOptions,
)

ExplainPolice をどう動かすか

LINE では企画者の動作確認や QA に利用する Beta 環境、最終の動作確認・結合テストに利用する RC 環境、エンドユーザーが実際にアクセスする Real 環境の３セットの環境を構築するのが基本となっています。

EXPLAIN を本番で実行していたらオーバーヘッドが大きいので本番環境では ExplainPolice を有効化することはできません。我々は Beta 環境と RC 環境で ExplainPolice を有効化しています。

2つの環境で有効化しているのは異なる目的で有効化しているのです。Beta 環境で適用しているのは、Beta 環境での QA の中で実際にクエリが実行されて実行計画を得たいということです。Beta QA は通常、RC QA よりも前の段階で実施されるので、クエリの根本的な見直しなどもこのタイミングであればやりやすいです。

一方、RC 環境で有効化している理由は、本番のデータベースを利用して実行計画を得るためです。MySQL はデータが増えたときに実行計画が変化して、急に重くなったりすることがあります。そういう場合を警戒して、都度都度 EXPLAIN を手で実行するというのはとても手間がかかります。ExplainPolice では RC 環境での結合試験をしている際に自動的に検出できますので非常に便利です。

無視リストの管理

もちろん、バッチ処理の場合や replica に対するアクセスである場合などはわざと EXPLAIN の結果が filesort や temporary なクエリを発行しているケースもあるでしょう。

そういった場合には、アノテーションをつけることで許容できるようになっています。イメージ的には以下のように書けるようになっています。

/**
 *
 */
@ExplainPoliceOptions(
    reason = "管理画面における利用なので全件取得している",
    allowFullScan = true, allowFileSort = true, allowTemporary = true,
)
@Select(
    """
        SELECT * FROM items ORDER BY id DESC /* 実際にはもっと複雑なクエリがあると思ってください */
    """
)
fun selectAll(

どうやって ExplainPolice の通知に気づくか

Explain 結果の通知を Slack でする