技术分享 | OceanBase 查询缓慢故障排除思路--从哪些信息入手？

要诊断哪部分时间消耗长，以及原因是什么，大多数情况会从如下几个组件获取信息。

ODP 组件

• obproxy_digest.log：审计⽇志，记录执⾏失败的 SQL 语句、执行时间大于参数 query_digest_time_threshold 阈值（默认是 2ms）请求。
• obproxy_slow.log：慢 SQL 请求日志，记录执⾏时间大于参数 slow_query_time_threshold 阈值（默认是 500ms）的请求。
• obproxy.log：ODP 总日志。

在 obproxy_digest.log 和 obproxy_slow.log 中，第 15、16、17、18 列（即 8353us,179us,0us,5785us）分别表示：ODP 处理总时间、ODP 预处理时间、ODP 获取连接时间、OBServer 执⾏时间。示例如下：

2023-05-04
16:46:03.513268,test_obproxy,,,,test:ob_mysql:sbtest,OB_MYSQL,sbtest1,sbtest1,COM_QUERY
,SELECT,failed,1064,select t1.*%2Ct2.* from sbtest1 t1%2Csbtest2 t2 where t1.id = t2.id
where id <10000,8353us,179us,0us,5785us,Y0-7FA25BB4A2E0,YB420ABA3FAC-0005FA2415BE0F81-
0-0,,,0,10.186.63.172:2881

• ODP 处理总时间的起点：ODP 接收到客户端请求的时间；
• ODP 处理总时间的终点：ODP 把所有的数据都写回给客户端；
• ODP 预处理时间：包含去 oceanbase.__all_virtual_proxy_schema 查询 Leader 的时间；
• ODP 获取连接时间：目前不做记录，看到的都是 0；
• OBServer 执行时间：起点是 ODP 发送请求给 OBServer，终点是收到  OBServer 返回第一条记录。

从上面的原理可以看出，后三项时间相加并不等于第一项时间，比如 ODP 处理总时间比较长，但是预处理时间和 OBServer 执行时间都很短，有可能时间消耗在 OBServer 将第一条记录返回给 ODPServer 和 ODPServer 把所有数据写回给客户端之间，这在结果集较大的 SQL 语句中⽐较常⻅。