通过查看 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

通过 OCP 获取日志

您也可以通过 OCP 获取日志后，进行线下排查分析。

说明

不同 OCP 版本的操作界面可能不同，本节以 OCP V2.5.0 版本为例提供操作指导，OCP 其他版本的操作请参考对应版本的《OCP 用户指南》文档。

  1. 登录 OCP。

  2. 在左侧导航栏上单击 OBProxy，进入 OBProxy 页面。

  3. 在 集群列表 中找到 OBProxy 所在的集群，单击其集群名，进入 总览 页面。

  4. 在 OBProxy 列表 中，找到待排查的 OBProxy，在对应的 操作 列中，单击 … 图标，选择 下载日志。

  5. 在弹出的对话框中，选择时间范围及日志类型，并填写关键字为 slow query 后，单击 下载。

    下载日志