Apache Doris PreparedStatement 之谜

Apache Doris PreparedStatement 之谜

使用的 Apache Doris 版本:3.0.3, 对应的 Doris 源码如果没有特意说明,均为 3.0.3 版本。

背景 #

运营反馈了一些业务异常,这些异常都指向了一个 Doris 数据查询服务(后都用 DQ-1 指代),该服务日志中存在大量的错误日志,如下:

platformAwardBiz.GetByID failed: Error 1047 (08S01): msg: Not supported such prepared statement

日志中发现,全部的查询均报了 Not supported such prepared statement 错误,而不是存在特定的查询语句。而与此同时,另外的 Doris 查询服务 (后使用 DQ-2 指代) 并没有出现该错误日志。

DQ-1 使用 golang 编写,使用了 gorm 作为连接 Doris 的查询工具。DQ-2 使用了 python3编写,使用了 pymysql 作为连接 Doris 的查询工具。

发现问题后,猜测是 prepared statement 机制的相关问题,快速解决方案选择了重启 DQ-1 和 Doris FE 节点,然后错误消失。

问题分析 #

首先从日志入手,采集了 FE 的错误日志,但经过排查没有发现明显的异常日志。经过检索搜索引擎和社区,也没有发现有相关的 issue。

那只能从源码入手了。在进去源码分析之前,这里带着几个疑问:

  1. 为什么 DQ-1 会报这个错误,而 DQ-2 不会报这个错误?
  2. 为什么重启 DQ-1 和 Doris FE 节点可以解决问题?
  3. 是 Doris FE 节点的问题,还是 DQ-1 的问题?

DQ-1 的嫌疑非常小,因为项目内有相同的代码连接另外的 MySQL 数据库,并没有出现类似的问题。

Apache Doris 源码分析1 #

尝试在客户端检索 Not supported such prepared statement 关键词,发现没有任何结果,说明这个错误信息是 Doris FE 节点报出的。

在源码中搜索 Not supported such prepared statement,发现该错误信息定义在 fe/fe-core/src/main/java/org/apache/doris/qe/MysqlConnectProcessor.java 文件中:

    // process COM_EXECUTE, parse binary row data
    // https://dev.mysql.com/doc/dev/mysql-server/latest/page_protocol_com_stmt_execute.html
    private void handleExecute() {
        packetBuf = packetBuf.order(ByteOrder.LITTLE_ENDIAN);
        // parse stmt_id, flags, params
        int stmtId = packetBuf.getInt();
        // flag
        packetBuf.get();
        // iteration_count always 1,
        packetBuf.getInt();

        // nererids
        PreparedStatementContext preparedStatementContext = ctx.getPreparedStementContext(String.valueOf(stmtId));
        if (preparedStatementContext == null) {
            if (LOG.isDebugEnabled()) {
                LOG.debug("No such statement in context, stmtId:{}", stmtId);
            }
            ctx.getState().setError(ErrorCode.ERR_UNKNOWN_COM_ERROR,
                    "msg: Not supported such prepared statement");
            return;
        }
        handleExecute(preparedStatementContext.command, stmtId, preparedStatementContext);
    }

从这一段代码,就可以得到以下几个结论:

  1. Doris 支持 MySQL 协议的 PreparedStatement 机制
  2. 这个错误是在COM_STMT_EXECUTE 阶段报出的
  3. 该错误是因为 PreparedStatementContext 对象为 null 导致的
  4. 这个 stmtId 是从客户端传递过来的

简单总结一下,这个错误的根本原因是 Doris FE 节点没有找到 stmtId 对应的 PreparedStatementContext 对象导致的。那为什么客户端会传递一个 FE 节点没有的 stmtId 呢?

再进一步深入代码前,发现自己对 MySQL 的 PreparedStatement 机制并不是很了解,于是先去补充了一下相关知识。

MySQL Prepared Statement 协议 #

MySQL 协议 - Prepared Statments

Prepared Statments 协议是从 MySQL 4.1 版本开始支持的,主要是为了提高 SQL 语句的执行效率和安全性。协议约定了以下几个命令:

Command Description
COM_STMT_PREPARE 准备一个 SQL 语句,返回一个 stmt_id
COM_STMT_EXECUTE 执行一个已经准备好的 SQL 语句,使用 stmt_id
COM_STMT_CLOSE 关闭一个已经准备好的 SQL 语句,释放资源
COM_STMT_RESET 重置 COM_STMT_SEND_LONG_DATA 命令发送的参数, 并关闭 COM_STMT_EXECUTE 打开的游标
COM_STMT_SEND_LONG_DATA 发送长数据参数给一个已经准备好的 SQL 语句
COM_STMT_FETCH 获取一个已经准备好的 SQL 语句的结果集

PreparedStatement 的工作流程如下:

PreparedStatement 流程图
PreparedStatement 流程图

从 Doris 源码中,已经得知是在 COM_STMT_EXECUTE 阶段报出的错误,而 COM_STMT_EXECUTE 传递的 stmt_id来自于 COM_STMT_PREPARE 阶段。那么这里再重点关注下这两个命令的协议细节。

COM_STMT_PREPARE #

COM_STMT_PREPARE 命令的请求包格式如下:

Type Name Description
int<1> status [0x16] COM_STMT_PREPARE
string query The query to prepare

响应包格式如下:

Type Name Description
int<1> status [0x00] OK
int<4> statement_id The statement identifier
int<2> num_columns The number of columns in the result set
int<2> num_params The number of parameters in the statement
int<1> reserved_1 [0x00] Filler
int<2> warning_count The number of warnings
省略其余字段

COM_STMT_EXECUTE #

COM_STMT_EXECUTE 命令的请求包格式如下:

Type Name Description
int<1> status [0x17] COM_STMT_EXECUTE
int<4> statement_id ID of the prepared statement to execute
int<1> flags Flags. See enum_cursor_type
int<4> iteration_count Number of times to execute the statement. Currently always 1.
省略其余字段

响应包格式于 COM_QUERY 类似,返回 OK 包、错误包和结果集包之一,取决于执行结果。与这里的问题无关,就不赘述了。

到这里,已经对 PreparedStatement 协议有了一个基本的了解,也得到了以下信息:

  1. stmt_id 是由服务端在 COM_STMT_PREPARE 阶段生成的,并返回给客户端。
  2. 客户端在 COM_STMT_EXECUTE 阶段会携带 stmt_id 来执行对应的 SQL 语句。
  3. stmt_id 是一个 int<4>(四字节) 的整数。

那么这个问题的指向更清晰了,还是要回到 Doris 源码中,继续深入分析 stmt_id 的生成和管理。

Apache Doris 源码分析2 #

继续深入 Doris 源码,重点关注 statement_id 的生成和管理。

PrepareCommand.java 文件中,发现了返回给客户端的 statement_id 是通过 ConnectionContext 对象的 getStmtId() 方法获取:

    // register prepared statement with attached statement id
    @Override
    public void run(ConnectContext ctx, StmtExecutor executor) throws Exception {
        List<String> labels = getLabels();
        // register prepareStmt
        // ...
        if (logicalPlan instanceof InsertIntoTableCommand
                    && ((InsertIntoTableCommand) logicalPlan).getLabelName().isPresent()) {
            throw new org.apache.doris.common.UserException("Only support prepare InsertStmt without label now");
        }
        ctx.addPreparedStatementContext(name,
                new PreparedStatementContext(this, ctx, ctx.getStatementContext(), name));
        if (ctx.getCommand() == MysqlCommand.COM_STMT_PREPARE) {
            // !!!! 关键线索 !!!!
            executor.sendStmtPrepareOK((int) ctx.getStmtId(), labels);
        }
    }

executor.sendStmtPrepareOK((int) ctx.getStmtId(), labels); 这一行代码中有一个关键的线索就是 ctx.getStmtId() 返回的值进行了类型转换,转换成了 int 类型。这不禁让人联想到一个可能性:

stmtId 超过了 int 的范围,但是由于这里的类型转换,导致了客户端接收到的 stmtId 和服务端实际存储的不一致,进而导致在 COM_STMT_EXECUTE 阶段,Doris FE 节点找不到对应的 stmtId

再检查下 ConnectionContext 类中的 stmtID 属性:

// ConnectionContext
protected volatile long stmtId;

public long getStmtId() {
    return stmtId;
}

// 由 StmtExecutor 调用
public void setStmtId(long stmtId) {
    this.stmtId = stmtId;
}

继续追踪 stmtId 的生成,发现是在 StmtExecutor 类中:

// StmtExecutor
private static final AtomicLong STMT_ID_GENERATOR = new AtomicLong(0); // 初始值为 0

private void executeByNereids(TUniqueId queryId) throws Exception {
    // ...

    // stmtId 原子自增
    context.setStmtId(STMT_ID_GENERATOR.incrementAndGet());
    // ...
}

至此,答案也已经呼之欲出了: stmtId 在内存中类型是 long (八字节),而返回给客户端的时候进行了强制类型转换成了 int (四字节)。stmtId 一直自增,当 stmtId 超过了四字节的容量时,就会出现客户端接收到的 stmtId 和服务端实际存储的不一致,进而导致此问题。

解决 #

找到问题后,再去 Doris 仓库切换到最新的代码时,发现这部分逻辑已经被修改了,相关的 PR 在:https://github.com/apache/doris/pull/47950

那就更简单了,直接升级 Doris 版本到最新即可。

新版本中的逻辑是:ConnectionContext 新增了一个 preparedStmtId 属性,类型是 int

    // range [Integer.MIN_VALUE, Integer.MAX_VALUE]
    protected int preparedStmtId = Integer.MIN_VALUE;

    public void incPreparedStmtId() {
        ++preparedStmtId;
    }

Wireshark 抓包 #

在测试环境中升级 Doris 版本后,使用 Wireshark 抓包,验证一下 stmtId 是否如新版本中的逻辑工作。

在以前的版本 stmtId 从 0 开始自增,而在新版本中 preparedStmtIdInteger.MIN_VALUE 开始自增。因此只需要关注前面几个 COM_STMT_PREPARE 包的响应,其中的 statement_id 是从 0 开始,还是 2147483648 (即 Integer.MIN_VALUE 无符号数) 开始。

Wireshark 抓包 - COM_STMT_PREPARE
Wireshark 抓包 - COM_STMT_PREPARE

很明显,statement_id 是从 2147483648 开始的,说明新版本中的逻辑已经生效。

答疑 #

  1. 为什么 DQ-1 会报这个错误,而 DQ-2 不会报这个错误?

    DQ-2 使用的客户端拼接 SQL 语句,并没有使用到 PreparedStatement 机制。而 DQ-1 (golang) 底层 mysql 驱动 (github.com/go-sql-driver/mysql) 会优先尝试客户端 prepare (使用 query 而不是服务器 prepare), 如果没有开启则会使用服务器 prepare, 使用 interpolateParams 控制开启

    也就是说如果想要避免这个问题,可以在 DQ-1 的数据库连接字符串中添加 interpolateParams=true 参数,避免使用服务器 prepare 规避 statement_id 增长溢出。

    另外 gorm 也由一个 PrepareStmt 的配置选项,会缓存已经 prepared 的 sql.Stmt, 才会合理利用上服务端 prepare 机制,同时减少客户端的 prepare 次数。

  2. 为什么重启 DQ-1 和 Doris FE 节点可以解决问题?

    实际上是重启 Doris FE 节点解决了问题,重启后 stmtId 重新从 0 开始自增,暂时避免了溢出。

  3. 是 Doris FE 节点的问题,还是 DQ-1 的问题?

    是 Doris FE 中 PreparedStatement 实现存在缺陷。

总结 #

本文复盘了在使用 Apache Doris PreparedStatement 机制时出现 “Not supported such prepared statement” 错误的排查历程。通过源码追踪,发现 Doris FE 节点在管理 stmtId 时存在类型转换问题,导致溢出后客户端与服务端的 stmtId 不一致,最终引发异常。

升级 Doris 至最新版本或在客户端配置参数避免服务端 prepare,均可有效规避该问题。

在排查过程,系统性的了解 MySQL 的 PreparedStatement 协议以及服务端和客户端在 PreparedStatement 机制中的实现细节。

总的来说,知其然更要知其所以然,理解底层原理才能更好地解决问题。

访问量 访客数