排查慢 SQL 导致的任务延迟

本文为您介绍如何排查慢 SQL 导致的任务延迟。

适用版本

适用于 OceanBase 迁移服务（OceanBase Migration Service，OMS）V3.x 和 V4.x。

背景信息

导致任务延迟的原因有很多，本文为您介绍因慢 SQL 导致任务延迟的情况下，如何通过 OMS 的日志排查存在慢 SQL 的表。对于 store 进程的位点实时推进，但 JDBCWriter 组件同步缓慢，时间延迟不断增大的情况，您可以通过 rps 来锁定同步缓慢的时间，再通过 sql_msg.log 文件定位相应时间段的语句，进而找到缓慢的表。

指标 rps 的含义为组件每秒钟同步的记录数，默认情况下，OMS 会在 logs/msg/metrics.log 中每 10 秒更新一次包含 rps 在内的众多信息，通过 rps 的变化趋势您可以大致定位到哪个时间段内 JDBCWriter 进程出现同步缓慢的情况。 ​ 文件 logs/msg/sql_msg.log 为慢日志文件，默认情况下，会将打印执行时间大于 15ms 的语句以及值。结合从 metrics.log 获取的 rps 变化趋势，您可以最终获取 JDBCWriter 组件缓慢的时间段在操作什么表。请注意 sql_msg.log 有自动压缩的机制，会每小时归档文件并压缩。

操作步骤

下述步骤是基于 OMS V3.x 生成的，V4.x 可大致参考。

1. 登录 OMS 的 Docker。

   docker exec -it oms bash
   

2. 进入对应的组件目录

   您可以在 OMS 控制台获取组件 ID。

   cd /u01/ds/run/xxx.xxx.xxx.1-9000:p_4t****mx21s_dest-000-0:0000000073
   

3. 核查某个时间段的 rps 信息。

   tail -1000 logs/msg/metrics.log|sed 's/] {/]^/g'|sed 's/\"rps\"\:/^/g'|sed 's/,\"tps\":/^/g'|awk -F"^" '{print $1" "$3}'
   

   其中典型的异常记录如下，进程平时的 rps 约 3w，但 18:37:47~18:51:17 均值不足 200，低了 2 个数量级。

   [2023-06-28 18:37:17.115] 36300.55
   [2023-06-28 18:37:27.114] 29832.22
   [2023-06-28 18:37:37.115] 30203.5
   [2023-06-28 18:37:47.114] 182.91
   [2023-06-28 18:37:57.114] 184.91
   [2023-06-28 18:38:07.114] 190.66
   

   此间记录省略，大部分 rps 低于 200。

   [2023-06-28 18:51:17.114] 171.53
   [2023-06-28 18:51:27.114] 851.23
   [2023-06-28 18:51:37.221] 31493.67
   [2023-06-28 18:51:47.114] 37210.1
   

4. 查看 sql_msg.log 文件，如果为当前的小时，直接查看即可，其余时间则需要先解压。

   cd /u01/ds/run/xxx.xxx.xxx.1-9000:p_4ttyny0mx21s_dest-000-0:0000000073/logs/msg
   gzip -d  sql_msg.2023-06-28_18.log.gz
   

5. 根据时间截取文件

   1. 截取文件头以及尾部，如无返回记录，可相应增加或者减少秒数，直到返回记录为止。

      awk '/'"2023-06-28 18:37:47"'/ {print NR}' sql_msg.2023-06-28_18.log|head -1
      awk '/'"2023-06-28 18:51:17"'/ {print NR}' sql_msg.2023-06-28_18.log|tail -1
      

   2. 根据上文中的行数截取文件。

      awk -v N1="1020505" -v N2="1026653" 'NR==N1,NR==N2 {print $0}' sql_msg.2023-06-28_18.log>neigui_sql.txt
      

   3. 检查文件内容。

      more neigui_sql.txt
      

6. 获取对应的 SQL 语句。

   cat neigui_sql.txt|grep "sql:"|sort|uniq
   

   示例如下，您可以看到缓慢的为 NGCRM_XX.CS_REC_XXLOG 表。

   sql:DELETE FROM "NGCRM_XX"."CS_REC_XXLOG" WHERE "OMS_OBJECT_NUMBER" = ? and "OMS_RELATIVE_FNO" = ? and "OMS_BLOCK_NUMBER" = ? and "OMS_ROW_NUMBER" = ? and "CHECKDATE" = ?
   sql:INSERT INTO "NGCRM_XX"."CS_REC_XXLOG" ("SERVNUMBER","BBOSSWAYID","AUTHORIZATIONWAY","CHECKDATE","CHECKRESULT","OPRCODE","EXTEND1","EXTEND2","STATE","STATEDATE","FILENAME","MEMO","OMS_OBJECT_NUMBER","OMS_RELATIVE_FNO","OMS_BLOCK_NUMBER","OMS_ROW_NUMBER") VALUES (?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?)