OBProxy 有自己的慢查询日志打印功能，通过 OBProxy 的以下两个配置项可控制打印到日志中的 SQL 或事务的处理时间阈值。

配置项

说明

slow_transaction_time_threshold

指慢查询或事务的整个生命周期的时间阈值，超过了该时间，就会打印相关日志。

slow_proxy_process_time_threshold

在发往 Server 前 Proxy 本身的处理时间，包括获取集群信息、路由信息、黑名单信息等。

slow_query_time_threshold

指从 OBProxy 获取 SQL 直到返回给客户端之前的这段时间的阈值，超过了该时间，也会打印相关日志。

查看和修改 OBProxy 慢查询配置项

  1. 在 OceanBase 数据库支持的客户端工具中使用 root 用户登录集群的 sys 租户。

  2. 运行下述语句查看 OBProxy 的配置项。

    1. obclient> SHOW PROXYCONFIG LIKE 'slow_transaction_time_threshold';
    2. obclient> SHOW PROXYCONFIG LIKE 'slow_proxy_process_time_threshold';
    3. obclient> SHOW PROXYCONFIG LIKE 'slow_query_time_threshold';

  3. 修改 OBProxy 配置项的值。

    示例语句如下所示，一般修改配置项slow_transaction_time_threshold即可，配置项 slow_proxy_process_time_threshold默认值为 2 ms，该值适用于绝大多数场景。

    1. obclient> ALTER PROXYCONFIG SET slow_transaction_time_threshold='100ms';
    3. obclient> alter proxyconfig set slow_proxy_process_time_threshold='5ms';

排查慢查询

通过查看 OBProxy 慢查询日志找到运行缓慢的 SQL 语句。

OBProxy 的日志路径为/opt/taobao/install/[obproxy目录]/log。其中，[obproxy目录]在 OBProxy 不同版本下可能不同，早期版本为obproxy；较新版本为obproxy-[具体版本号]，例如obproxy-1.5.7。

在 OBProxy 宿主机的命令行工具中，进入上述目录后，运行下述语句以查看运行缓慢的 SQL 语句：

  1. grep -i 'slow query'

您也可以运行下述命令对慢查询日志进行格式化调整以方便您解读其中的内容：

  1. grep -i 'slow query' obproxy.xxx.log | sed "s/, /,\n/g

下述为格式化后的示例日志。

  1. [2020-02-19 15:17:01.072491] WARN  [PROXY.SM] update_cmd_stats (ob_mysql_sm.cpp:5673) [103335][Y0-7FF57C8613A0] [lt=10] [dc=0] Slow Query: (client_ip={127.0.0.1:44228}, // 执行SQL client IP
  2. server_ip={xxx.xxx.xxx.xxx:2881} // SQL 被路由到的 OBServer
  3. server_trace_id=YB420BA65786-00059E5922A874E6 // 目标 OBServer 中执行过程中的 trace id
  4. route_type=ROUTE_TYPE_LEADER // SQL 使用的路由策略
  5. user_name=root // 连接用户名
  6. tenant_name=xxx // 连接租户名
  7. cluster_name=xxx // 连接 OceanBase 集群名称
  8. use_compress_protocol=true // SQL 传输是否使用压缩协议
  9. cs_id=365 // client login 时看到的 connection id 和 OBProxy 分配
  10. proxy_sessid=7 // client 访问 OceanBase 时内部记录的 connection id
  11. ss_id=10
  12. server_sessid=3221946244 // SQL 在目标 OBServer 中的 connection id 和 OBServer 分配
  13. sm_id=9535
  14. cmd_size_stats={client_request_bytes:31 // 客户端请求 SQL 大小
  15.     server_request_bytes:49 // 路由到 OBServer SQL 大小
  16.     server_response_bytes:0 // OBServer 转发给 OBProxy 数据大小
  17.     client_response_bytes:76} // OBProxy 转发给 client 数据大小 
  18. cmd_time_stats={
  19.     client_transaction_idle_time_us=0 // 在事务中该条 SQL 与上一条 SQL 执行结束之间的间隔时间，即 client 事务间隔时间
  20.     client_request_read_time_us=27 // Proxy 从 client socket 读取请求包的耗时
  21.     client_request_analyze_time_us=25 // Proxy 分析 client 的 SQL 耗时
  22.     cluster_resource_create_time_us=0 // Proxy 创建集群资源耗时(仅首次访问集群时需要创建)
  23.     pl_lookup_time_us=16 // 根据 SQL 获取涉及路由表的耗时
  24.     pl_process_time_us=34 // 对涉及路由表进行筛选排序的耗时
  25.     congestion_control_time_us=5 // 根据 SQL 获取涉及黑名单信息的耗时
  26.     congestion_process_time_us=0 // 对涉及黑名单的进行检查过滤的耗时
  27.     do_observer_open_time_us=198 // 对目标 OBServer 获取可用连接的耗时, 包含 connect_time
  28.     server_connect_time_us=166 // 对目标 OBServer 创建连接的耗时
  29.     server_sync_session_variable_time_us=1127 // 对选择的目标连接进行初始化的耗时, 包括 saved_login，同步 DB，同步系统变量，同步 last_insert_id，同步 start_trans
  30.     server_send_saved_login_time_us=571 // 对选择的目标连接进行 saved login 耗时
  31.     server_send_use_database_time_us=189 // 对选择的目标连接同步 DB 耗时
  32.     server_send_session_variable_time_us=366 // 对选择的目标连接同步已修改的系统变量耗时
  33.     server_send_all_session_variable_time_us=0 // 对选择的目标连接同步所有系统耗时
  34.     server_send_last_insert_id_time_us=0 // 对选择的目标连接同步 last_insert_id 耗时
  35.     server_send_start_trans_time_us=0 // 对选择的目标连接同步 start_trans/begin 耗时
  36.     build_server_request_time_us=37 // 构建对目标 Server 的请求包的耗时
  37.     plugin_compress_request_time_us=0 // 对请求包进行压缩耗时
  38.     prepare_send_request_to_server_time_us=1606 // 从 Proxy 接受到客户端请求，到转发到 OBServer 执行前总计时间，正常应该是前面所有时间之和                                      
  39.     server_request_write_time_us=8 // Proxy 向目标 Server socket 发送请求包的耗时                                
  40.     server_process_request_time_us=381489 // 目标 Server 执行该条 SQL 的耗时
  41.     server_response_read_time_us=9 // Proxy从目标 Server socket 读取响应包的耗时
  42.     plugin_decompress_response_time_us=13 // 对响应包进行解压缩耗时
  43.     server_response_analyze_time_us=10 // 对响应包进行分析的耗时                                                                              
  44.     ok_packet_trim_time_us=0 // 对响应包 trim 掉最后一个 ok 包的耗时
  45.     client_response_write_time_us=34 // Proxy 向 client socket 发送响应包的耗时
  46.     request_total_time_us=383233} // Proxy 处理该请求总时间, 等于前面所有耗时之和
  47. sql=select count(1) from test1) //client 的请求 SQL