本文汇总了项目实践中前辈的经验和笔者的理解，旨在帮助初学 OceanBase（以下简称 OB）的工程师，快速解决 SQL 执行缓慢等性能问题。当遇到性能问题时，很多工程师可能会感到无从下手，本文将根据关键日志提供多种分析方向，以加速问题排查。
应用连接 OB 的生产架构，一般有两种：
应⽤ -> OBProxy -> OBServer
应⽤ -> OBProxy-Sharding -> OBServer
前者是大多数客户使⽤场景，后者是少数客户使⽤的单元化架构场景，后文将 OBProxy 和 OBProxy-Sharding 统称为 ODP（OceanBase Database Proxy）。
当我们发现某条语句耗时较长时，我们需要排查的点有：应⽤到 ODP 的⽹络时间、ODP 的执行时间、ODP 到 OBServer 的⽹络时间、OBServer 的执行时间。
要诊断哪部分时间消耗长，以及原因是什么，大多数情况会从如下几个组件获取信息。
obproxy_digest.log ：审计⽇志，记录执⾏失败的 SQL 语句、执行时间大于参数 query_digest_time_threshold 阈值（默认是 2ms）请求。
obproxy_slow.log ：慢 SQL 请求日志，记录执⾏时间大于参数 slow_query_time_threshold 阈值（默认是 500ms）的请求。
在 obproxy_digest.log 和 obproxy_slow.log 中，第 15、16、17、18 列（即 8353us,179us,0us,5785us）分别表示：ODP 处理总时间、ODP 预处理时间、ODP 获取连接时间、OBServer 执⾏时间。示例如下：
2023-05-04test :ob_mysql:sbtest,OB_MYSQL,sbtest1,sbtest1,COM_QUERYwhere t1.id = t2.idwhere id <10000,8353us,179us,0us,5785us,Y0-7FA25BB4A2E0,YB420ABA3FAC-0005FA2415BE0F81-
ODP 处理总时间的起点：ODP 接收到客户端请求的时间；
ODP 处理总时间的终点：ODP 把所有的数据都写回给客户端；
ODP 预处理时间：包含去 oceanbase.__all_virtual_proxy_schema 查询 Leader 的时间；
ODP 获取连接时间：目前不做记录，看到的都是 0；
OBServer 执行时间：起点是 ODP 发送请求给 OBServer，终点是收到 OBServer 返回第一条记录。
从上面的原理可以看出，后三项时间相加并不等于第一项时间，比如 ODP 处理总时间比较长，但是预处理时间和 OBServer 执行时间都很短，有可能时间消耗在 OBServer 将第一条记录返回给 ODPServer 和 ODPServer 把所有数据写回给客户端之间，这在结果集较大的 SQL 语句中⽐较常⻅。
gv$audit_sql ：该视图⽤于展示所有 OBServer 上每⼀次 SQL 请求的来源、执⾏状态等统计信息。
该视图是按照租户拆分的，除了系统租户，其他租户不能跨租户查询。⼀般常⽤的字段有：request_time，sql_id， plan_id，plan_type，trace_id，svr_ip，client_ip，user_client_ip，user_name，db_name，elapsed_time，queue_time，get_plan_time，execute_time，retry_cnt，table_scan，ret_code，query_sql……
# 大致的归类如下
observer.log ：OBServer 运行的主要⽇志，这里面的信息非常全面，外部用户不易解读，很多情况下会根据 trace_id 去搜索，例如通过 OCP 的 SQL 诊断功能获取到 TraceID ，再进⾏查询。
当 SQL 的结果集很大，ODP 就需要较长时间将数据返回给应用，这时候会发现 OBServer 执行时间和 ODP 预处理时间相加，比 ODP 执行总时间要小，以下面的 obproxy.log 记录为例：
[2023-04-19 19:12:31.662602] WARN [PROXY.SM] update_cmd_stats (ob_mysql_sm.cpp:8633)where id =1)
client_response_bytes:185002181
client_response_write_time_us=1130104
该示例中，ODP 回写给应用的数据为 185MB，耗时 1.1s，可以通过该信息观测下是否是 SQL 的结果集较大。
ODP 要把 SQL 路由到准确的 OBServer 上，只需要知道每个 Table 的 Partition 的 Leader 所在位置，获取位置的过程叫做 “get location cache” 。通常这个过程很快，并且获取后会缓存在本地，少数情况下，这个时间消耗会慢，以下面为例：
[2023-05-07 00:01:04.506809] WARN [PROXY.SM] update_cmd_stats (ob_mysql_sm.cpp:8607)
pl_lookup_time_us=4998993
耗时 4s 明显有异常，获取到该日志后可以快速和 OB 研发缩小问题排查范围。
在 OceanBase 数据库中，有 Local 计划、Remote 计划和 Distributed 计划三种表路由。Local 计划、Remote 计划均为单分区的路由。ODP 的作⽤就是尽量消除 Remote 计划，将路由尽可能的变为 Local 计划。
如果表路由类型为 Remote 计划的 SQL 过多，则表示该 SQL 性能可能不是最优，通常的原因有 ODP 路由问题、无法计算表分区 ID、使用了全局索引、需要开启二次路由等等。
通过 gv$sql_audit 的 PLAN_TYPE 字段可以判断 SQL 的执行计划类型：
当 memstore 已使⽤的内存达到 writing_throttling_trigger_percentage 时（默认 100），触发写入限速。当该配置项的值为 100 时，表示关闭写入限速机制。在触发写入限速后，剩余 memstore 内存必须保证在writing_throttling_maximum_duration（默认 1h）内不会分配完，也就是写入速度上限为 memstore * (1- writing_throttling_trigger_percentage) / writing_throttling_maximum_duration。
通过监控 gv$memstore 可以知道 memstore 使用的百分比。当发生了写入限速，observer.log 中会看到如下记录：
[2023-04-10 10:52:09.076066] INFO [COMMON] ob_fifo_arena.cpp:301 [68425][1739]"0.000000005732" ,关键字：report，write，throttle，info
还有⼀种场景就是发现 QPS 异常下降时（尤其是包含⼤量写⼊，可以通过查询系统表的⽅式确认是否是由于写⼊限速导致。详见：技术分享 | OceanBase写入限速源码解读
select * from v$session_event where EVENT ='memstore memory page alloc wait' \G;#: 9 关键字：memstore，memory，page，alloc，wait
访问计划也是影响 SQL 耗时的⼀个因素，没有命中 plan cache、访问计划发生了预期外的变化都会造成 SQL 执行变慢。
没有命中 plan cache 可以在 gv$sql_audit 中看到 IS_HIT_PLAN=0。
要查看 SQL 具体的执行计划有两种⽅式：一是执行 explain extended <query_sql>，但这只能看到当前环境下，该语句的执行计划，可能并不是现场缓慢 SQL 的执行计划，需要查看缓慢 SQL 正在使用的访问计划，需要首先记录下 gv$sql_audit 中的四个值：SVR_IP，SVR_PORT，TENANT_ID，PLAN_ID。并在 gv$plan_cache_plan_explain中进行查询：
select SVR_IP, SVR_PORT, TENANT_ID, PLAN_ID from gv$sql_audit where query_sql ...select * from gv$plan_cache_plan_explain where ip=<SVR_IP> and port=<SVR_PORT> and and plan_id=<PLAN_ID>OceanBase 选择 MVCC 来实现事务并发性和一致性，支持读写不互斥。因此事务间的锁等待一般发生在写请求上（lock_for_write），极少情况下也会发生在读请求（lock_for_shared）。
当发生了锁等待，SQL执⾏耗时也会变长，通常的表现是：在 gv$sql_audit 中看到 elapsed_time 较大，execute_time 较小，retry_cnt 较大（>0），伴随 observer.log 可以观察到如下日志：
[2023-03-29 12:00:26.310172] WARN [STORAGE.TRANS] on_wlock_retryfalse has_read_relocated_row=false false ref=2 pkey=hash :4021727895899886621,"172.28.65.64:4882" , t:1680062426310046} data_relocated=0"BIGINT" :2024021}] ,"alloc_type=0 ctx_descriptor=700817301 trans_start_time=1680062426309892
关键字：lock_for_write，conflict
一般 SQL 语句查询慢排除上述问题后，大部分跟自身有关，例如 SQL 语句没有走到索引、写法有问题等。这种情况就需要:
通过 gv$sql_audit 表或 ODP 日志拿到具体的 SQL 文本。
# 查询以某个租户⼀段范围内执⾏耗时的SQL语句进⾏排序 SELECT usec_to_time(request_time) as request_time,FROM gv$sql_auditWHERE tenant_id=1001 AND request_time BETWEEN time_to_usec('2023_05_12 13:00:00' )AND time_to_usec('2023_05_13 13:10:00' ) AND is_executor_rpc = 0 ORDER BY elapsed_time DESC limit 10 ;
拿到 SQL 文本后，再通过 Explain 查询计划进⾏分析（例如对下文语句进⾏ Explain 分析，比如 name 中只有表名不包含索引列的话，则该 SQL 语句可能使用的主键或全表扫描）。
obclient [sbtest]> explain select * from sbtest1 where k like '%111181823%' \G1. row ***************************Query Plan: ========================================ID |OPERATOR |NAME |EST. ROWS |COST |---------------------------------------- 0 |TABLE SCAN |sbtest1|283098 |333648 |------------------------------------- 0 - output ([sbtest1.id], [sbtest1.k], [sbtest1.c], [sbtest1.pad]),cast (sbtest1.k, VARCHAR (1048576 )), '%111181823%' , '\\' )]),access ([sbtest1.k], [sbtest1.id], [sbtest1.c], [sbtest1.pad]), partitions (p0)1 row in set (0.004 sec)
排查 SQL 成本和执行计划中访问顺序是否有问题，就不具体展开了。
以上就是导致 OB 慢查询常见的原因及分析思路，希望对读者有所帮助。
