使用的 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。
那只能从源码入手了。在进去源码分析之前,这里带着几个疑问:
- 为什么 
DQ-1会报这个错误,而DQ-2不会报这个错误? - 为什么重启 
DQ-1和 Doris FE 节点可以解决问题? - 是 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);
    }
从这一段代码,就可以得到以下几个结论:
- Doris 支持 MySQL 协议的 
PreparedStatement机制 - 这个错误是在
COM_STMT_EXECUTE阶段报出的 - 该错误是因为 
PreparedStatementContext对象为null导致的 - 这个 
stmtId是从客户端传递过来的 
简单总结一下,这个错误的根本原因是 Doris FE 节点没有找到 stmtId 对应的 PreparedStatementContext 对象导致的。那为什么客户端会传递一个 FE 节点没有的 stmtId 呢?
再进一步深入代码前,发现自己对 MySQL 的 PreparedStatement 机制并不是很了解,于是先去补充了一下相关知识。
MySQL Prepared Statement 协议 #
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 的工作流程如下:
  从 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 协议有了一个基本的了解,也得到了以下信息:
stmt_id是由服务端在COM_STMT_PREPARE阶段生成的,并返回给客户端。- 客户端在 
COM_STMT_EXECUTE阶段会携带stmt_id来执行对应的 SQL 语句。 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 开始自增,而在新版本中 preparedStmtId 从 Integer.MIN_VALUE 开始自增。因此只需要关注前面几个 COM_STMT_PREPARE 包的响应,其中的 statement_id 是从 0 开始,还是 2147483648 (即 Integer.MIN_VALUE 无符号数) 开始。
  很明显,statement_id 是从 2147483648 开始的,说明新版本中的逻辑已经生效。
答疑 #
- 
为什么
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 次数。 - 
为什么重启
DQ-1和 Doris FE 节点可以解决问题?实际上是重启 Doris FE 节点解决了问题,重启后 stmtId 重新从 0 开始自增,暂时避免了溢出。
 - 
是 Doris FE 节点的问题,还是
DQ-1的问题?是 Doris FE 中 PreparedStatement 实现存在缺陷。
 
总结 #
本文复盘了在使用 Apache Doris PreparedStatement 机制时出现 “Not supported such prepared statement” 错误的排查历程。通过源码追踪,发现 Doris FE 节点在管理 stmtId 时存在类型转换问题,导致溢出后客户端与服务端的 stmtId 不一致,最终引发异常。
升级 Doris 至最新版本或在客户端配置参数避免服务端 prepare,均可有效规避该问题。
在排查过程,系统性的了解 MySQL 的 PreparedStatement 协议以及服务端和客户端在 PreparedStatement 机制中的实现细节。
总的来说,知其然更要知其所以然,理解底层原理才能更好地解决问题。