如何排查 RPC 失败的原因

本文介绍如何排查 RPC 失败的原因

问题描述

RPC 发送失败通常在日志中表现为包含 rpc***fail 字段的错误信息。

execute rpc fail(ret=-XXXX, dst="xxx.xxx.xx.xx:xxxx")
rpc ***execute fail
send rpc request fail(****ret = -XXXX)

RPC 发送失败的报错一般有 rpc****fail 字段，这样的日志最开始排查往往发现于上层模块，比如 SQL 远程 TASK 执行等。 在 Client 端 RPC 发送失败的报错，绝大部份的原因都在 dst 端，比如 dst 端处理超时，内存不够等。所以首先要找到 dst 端的地址，然后尽量找到报错上下文中的 trace id、session id、packet id、tenant id 等信息，以便于接下来到 dst 端去找线索。

排查步骤

1. 定位目标服务器（dst端）地址。 查找日志中的 dst 字段以获取目标服务器的 IP 地址和端口。 一般最先看到的报错都是在上层，调用 rpc_proxy 的接口发 rpc 的位置。比如：

   WARN  [SQL.EXE] task_execute_v2 (ob_executor_rpc_impl.cpp:249) [85354][2358][xxxxx-xxxxx] [lt=7] [dc=0] rpc task_execute fail(ret=-4121, tenant_id=1002, svr="100.xx.xxx.xxx:7328", timeout=35992570748, timeout_timestamp=1623161884727367)
   

   上述日志中已经有 tenant id（tenant_id=1002）和 dst 端的 IP (svr="100.xx.xxx.xxx:7328")。

2. 根据线程号寻找上下文信息。

   使用线程号或其他关键信息在 Client 端的日志文件中进行搜索，以收集更多关于出错的 RPC 请求的细节。

   本示例中，线程号为 2358，通过 grep 过滤出信息。

   grep '\[2358' -rI observer.log.[timestamp]
   

   日志包含 trace id 和 session id 信息。

   [xxxxx-xxxxx] [lt=6] [2358] send packet fail(dst="xxx.xxx.xxx.xxx:xxx", s=0x7f35064b6e80)
   

   日志包含 session id，packet id 信息。

   INFO  easy_connection.c:1783 [2358][0][xxxxx-xxxxx] [lt=23] [dc=0] Session has timed out, session(0x7fa035596920), time(9.000155s), packet_id(2903925132279), conn(xxx.xxx.xxx.xxx:xxx_xxx.xxx.xxx.xxx:xxx_xxx_0x7fa2392d2270 tp=1 t=0-1623125894988005 s=0 r=20 io=112248771/2965041847 sq=2964878955)
   

3. 在 dst 端搜索相关线索。

   到目标服务器的日志目录下，使用 trace id、packet id 或 session id 在相应的时间戳的日志文件中查找相关线索。

   理想情况下可以根据 trace_id 在对应时间的日志中查找线索，不限于 observer.log，rootservice.log 日志。命令如下所示。

   grep 'xxxxx-xxxxx' -rI [dst_dir]/observer.log.[timestamp]
   

   grep 'xxxxx-xxxxx' -rI [dst_dir]/rootservice.log.[timestamp]
   

4. 若无日志中包含如下信息，按照 xxxxxxx 进一步排查处理。若日志中不包含如下信息，跳转到步骤 5 进一步排查。

   easy_reqeust hold by upper-layer for too much time. req(0x7f6b78155378), timeout_warn_count(0), protocol(RPC), pcode(515), time(9.360041), packet_id(68569913622796), trace_id(xxxxx-xxxxx), trace_point(5)
   

5. 若无日志另外用 trace_id 查找不到线索或查找不到任何日志，尝试用 packet id 或者 session id 查找线索。

   grep '[packet id]' -rI [dst_dir]/observer.log.[timestamp]
   

   grep '[session id]' -rI [dst_dir]/observer.log.[timestamp]
   

   注意

   括号内要换成实际的 ID 值。

6. 如果通过上述方法无法在 dst 端找到日志，可以根据错误码，初步判断可能的错误原因。

   例如：

   1. 4012（超时）: 可能是对端的队列积压等情况。可以根据 tenant_id，继续在 dst 端查看 tenant 的队列积压情况。详细排查方法，参见 XXX。

   2. 4013（内存满等）: 检查内存使用情况，可能需要优化资源使用或扩容。

适用版本

OceanBase 数据库所有版本。