easy_reqeust hold by upper-layer for too much time 耗时问题

出现 easy_reqeust hold by upper-layer for too much time 时，表明 RPC/SQL 请求处理时间过长且没有结束。本文介绍如何诊断 easy_reqeust hold by upper-layer for too much time 问题。

确定请求的状态

OceanBase 数据库在处理 RPC (远程过程调用) 和 SQL (结构化查询语言) 请求时有详细的状态追踪机制，根据 protocol (RPC or SQL) 的类型，可以区分 SQL 请求还是 RPC 请求，以帮助开发人员和数据库管理员诊断处理过程中的延迟问题。

无论 SQL 请求还是 RPC 请求，在 OceanBase 数据库中通过 trace_point 的值来判断当前 RPC 或 SQL 请求的状态。每个 trace_point 的枚举值对应一个特定的处理阶段。下面是 trace_point 的枚举值及其含义：

• 0: 网络线程收到请求，初始状态。

• 1: 网络线程将收到的 RPC 报文解码成 RPC 请求。

• 2: 网络线程将收到的 SQL 报文解码成 SQL 请求。

• 3: 将要把请求放到对应租户的请求队列中，若卡在此状态，则请求卡在租户队列里。

• 4: 暂时未用。

• 5: 租户工作线程拿到请求，根据请求类型找到对应的 processor，准备处理请求。

• 6: mysql 登录等和租户关联不起来的请求，会放到对应队列线程中处理。

• 7: 工作线程的 processor 开始处理 RPC 请求。

• 8: 暂未使用。

• 9: 暂未使用。

• 10: 工作线程的 processor 开始处理 SQL 请求。

• 11: 租户工作线程处理 SQL query 请求中。

• 12: 未使用。

• 13: 未使用。

• 14: RPC 异步应答准备应答执行结果。

• 15: table api end_trans。

• 16: table api 异步提交事务。

• 255: 请求处理完成 (easy 网络框架)。

• 256: mysql 请求处理完成 (sql-nio 框架)。

找到耗时长的 SQL 并分析原因

SQL 请求分析示例

以下日志信息为例进行说明。

easy_reqeust hold by upper-layer for too much time. req(0x7f9722b55220), timeout_warn_count(512), protocol(SQL), time(10261.746331), session_id(3221971069), trace_point(11), bt().

通过 session_id (在本例为 3221971069) 可以直接 grep 3221971069 日志。根据 trace_point (本例为 11) 可以了解请求处理的当前阶段。

SQL 请求处在租户工作线程处理 mysql query 请求阶段。可以通过 session_id 和 trace_point 分析耗时原因。

RPC 请求分析示例

easy_reqeust hold by upper-layer for too much time. req(0x7f6b78155378), timeout_warn_count(0), protocol(RPC), pcode(515), time(9.360041), packet_id(68569913622796), trace_id(xxxxx-xxxxx), trace_point(5)

根据 pcode (本例中为 515，十六进制为 0x203) 可以确定 RPC 是哪个业务的，可以在 ob_rpc_packet_list.h 看到这个 pcode 是 DDL 建表相关的 RPC， trace_point 为 5 表示租户工作线程已经拿到请求并准备处理，之后通过 grep trace_id 可以跟踪具体的请求执行流程，从而找到问题所在。

通过理解和运用 trace_point 的枚举值，可以更好地监控和诊断数据库的性能问题。

适用版本

OceanBase 数据库所有版本。