网络线程关键打印汇总

packet wait too much time before encode

工作线程通过 rpc_proxy 发送 RPC 后，会将对应的 RPC 请求挂在 IO 线程的对应目的端 TCP 连接的发送队列上，并且通过异步的方式通知 IO 线程处理对应连接上的 IO 事件。出现这个打印信息时，表明 IO 线程处理 IO 事件延迟比较大，有可能是 IO 线程 hung 住了，也可能是因为线程被某些请求占用太久，遇到过的案例是被 RPC 的异步回调处理占用较长时间 （异步回调里会有一些拿锁之类的逻辑）。

关键打印信息如下。

async_cb handler cost too much time

可以根据线程 ID 号来查看下线程在附近时间在处理什么。

grep "\[11120" observer.log

如果多个网络线程都有这个打印信息，目前遇到过的情况就是所有线程都被挂起了，若干时间，这种情况下有可能是进程被 pstack/gdb 了，也有可能是 OS 层面的原因，这种情况下 OBServer 的日志打印信息也同样会暂停一段时间，可以通过 tsar 命令查看对应时间点各个监控指标。

check_easy_request_rt

首先这个函数是对从本端发出的 RPC 以及目的端处理后应答回来结果的整个执行流各个阶段耗时的追踪，需要在发送 RPC 的时候 .trace_time(true)才可以，出现此打印时证明 RPC 在整个执行流过程中某个阶段的时间超过预期了，以下是各个字段的含义解析。

• client_start_time：业务发起 RPC 调用的时间。

• start_send_diff：网络线程被唤醒准备发送时间-业务发起 RPC 调用的时间。

• send_connect_diff：通常为 0，没有太大含义，这里的 connect 指的是选中一个到目标机器的 connection。

• connect_write_diff：socket write 时间-选中一个到目标机器的 connection 的时间，这之间包括 RPC 包的 encode 操作。

• request_fly_ts：请求从本端 socket 发出到对端 socket 接收到的时间差，也就是 RPC 请求在网络上传输的时间。

• arrival_push_diff：在对端，从收到请求解码到准备放入队列的时间差。

• wait_queue_diff：在对端，在工作队列里等待的时间。

• pop_process_start_diff：在对端，处理请求时，deserialize 和 before_process 调用的时间，也就是正式处理请求之前的耗时。

• process_handler_diff：在对端，调用 process 处理请求的耗时。

• process_end_response_diff：在对端，从处理请求结束到准备应答结果的时间。通常为 0。

• response_fly_ts：RPC 请求的应答结果在网络上传输的时间（统计有误，将修改）。

• read_end_diff：读取应答后到记录 trace 之前的耗时，通常为 0 或者很小，主要动作是停止定时器，将应答结果从发送列表中摘除等。

packet fly cost too much time

详细信息参见 packet fly cost too much time 的问题诊断

easy_reqeust hold by upper-layer for too much time

详细信息参见 easy_reqeust hold by upper-layer for too much time 耗时问题。

适用版本

OceanBase 数据库所有版本。