联系我们
18591797788
hubin@rlctech.com
北京市海淀区中关村南大街乙12号院天作国际B座1708室
18681942657
lvyuan@rlctech.com
上海市浦东新区商城路660号乐凯大厦26c-1
18049488781
xieyi@rlctech.com
广州市越秀区东风东路华宫大厦808号1608房
029-81109312
service@rlctech.com
西安市高新区天谷七路996号西安国家数字出版基地C座501
在OceanBase生产环境中,大数据量增量抽数、数据导出场景经常遇到两类棘手问题:抽数任务长时间卡死不结束、程序报流中断连接异常。SQL本身执行仅需1-2分钟,但完整抽数导出流程耗时高达1-2小时,甚至直接报错失败,严重影响数据同步、汇聚任务稳定性。
本文结合真实生产故障,完整复盘问题现象、排查思路、根因分析及解决方案,适配OceanBase 4.2.5版本。
环境:生产环境;
OB 版本:4.2.5.4-104000082025052817;
集群规格:3-3-3
租户模式:Oracle 模式;
CPU 架构:x86_64
【抽取汇聚库增量案件】任务问题现象总结:
【现象1】抽数任务程序【从 OB 查询数据导出到文件】步骤执行慢甚至直接卡死(执行很久不结束也不输出日志),经过几次验证发现整个步骤需要 1-2 个小时,但是 sql 语句执行一般仅需要 1-2 分钟;
【现象2】抽数任务程序报错:【java.sql.SQLNonTransientConnectionException: (conn=96472963) unexpected end of stream, read 72 bytes from 4】;其数据流向为:observer > odp > 程序客户端;
因 ob server 中的 sql_audit 执行记录被覆盖了,所以从 ocp 的 ocp_monitor 中查询到 sql 执行记录,执行记录如下:发现在【2026-aa-bb cc:dd:02.013923】执行的 sql 执行报错了,其报错代码为:ret_code: -4009其 trace_id 为YB42C00A0202-0006444348AF7642-0-0;
select /*+ query_timeout(1000000000) parallel(8)*/ usec_to_time(request_time),*
from ocp_monitor.ob_hist_v2_sql_audit_sample
where ob_cluster_id = 1723444288 and cluster_name = 'xxx' and ob_tenant_id = 1006
and sql_id = 'E70ED2B569470185FE646C989B7E1F28'
order by request_time asc\G
*************************** 1. row ***************************
usec_to_time(request_time): 2026-aa-bb cc:dd:02.013923
ob_cluster_id: 1723444288
cluster_name: xxx
ob_tenant_id: 1006
ob_server_id: 2
ob_db_id: 500006
ob_user_id: 639959
sql_id: E70ED2B569470185FE646C989B7E1F28
cause: slow
cause_type: 3
is_sampled: 1
request_id: 13097169749
trace_id: YB42C00A0202-0006444348AF7642-0-0
client_ip: xxx.xxx.xxx.xxx
client_port: 53012
user_client_ip: xxx.xxx.xxx.xxx
request_time: 1773932942013923
plan_id: 2732288
affected_rows: 0
return_rows: 15342536
partition_cnt: 288
ret_code: -4009
event: event:, p1text:, p1:0, p2text:, p2:0, p3text:, p3:0
wait_time: 54276829
total_wait_time: 6413958166
total_waits: 262642
rpc_count: 7
plan_type: 3
is_inner_sql: 0
is_executor_rpc: 0
is_hit_plan: 0
elapsed_time: 7220241890
net_time: 0
net_wait_time: 1
queue_time: 28
decode_time: 0
get_plan_time: 85895
execute_time: 7220155947
cpu_time: 806283676
application_wait_time: 0
concurrency_wait_time: 0
user_io_wait_time: 0
schedule_time: 0
row_cache_hit: 0
bloom_filter_cache_hit: 0
block_cache_hit: 0
block_index_cache_hit: 0
disk_reads: 0
retry_cnt: 0
is_table_scan: 0
consistency_level: 2
memstore_read_row_count: 0
ssstore_read_row_count: 0
expected_worker_count: 24
used_worker_count: 24
memory_used: 21359157181
transaction_hash: 0
sql_text: NULL
sql_text_long: xxx(不提供 sql 语句)
params_value:
flt_trace_id: NULL
db_name: xxx
user_name: xxx
format_sql_id: 83E4B266BB8CDEE34A5C5B86174F1BC9
通过上面获取的【trace_id】过滤 observer.log 日志;
# 过滤 observer.log 日志grep 'YB42C00A0202-0006444348AF7642-0-0' ./observer.log | head # 通过 trace_id 过滤 observer.log 日志
分析 observer.log 日志过滤结果:从该段日志中可看到 【disconnect_state=4】该数值为 4 表示 TCP disconnect 客户端(此处客户端代表 OBserver 的前序组件)主动断开连接,其中对应的【sessid=3221871681, proxy_sessid=13837874802398417894】,可以通过该关键字在 ODP 日志中过滤相关日志;
[2026-aa-bb cc:dd:22.327618] INFO [RPC.OBMYSQL] destroy (obsm_conn_callback.cpp:245) [92532][sql_nio6][T0][Y0-0000000000000000-0-0] [lt=20] connection close(sessid=3221871681, proxy_sessid=13837874802398417894, tenant_id=1006, server_id=2, from_proxy=true, from_java_client=false, c/s protocol="OB_2_0_CS_TYPE", is_need_clear_sessid_=true, is_sess_alloc_=true, ret=0, trace_id=YB42C00A0202-0006444348AF7642-0-0, conn.pkt_rec_wrapper_=[start_pkt_pos_:107, cur_pkt_pos_:109, pkt_rec[77]:{send:obp_compess_header_{com_len:916, com_seq:136}, obp20_header_:{payload_len:888, pkt_seq:136, req_id:5509782, flag_.flags:11, ext_flags:0}, obp_mysql_header_{len_:783, seq_:214}, pkt_name:"PKT_EOF", obp_mysql_header_.is_send_:1}, pkt_rec[78]:{send:obp_compess_header_{com_len:916, com_seq:136}, obp20_header_:{payload_len:888, pkt_seq:136, req_id:5509782, flag_.flags:11, ext_flags:0}, obp_mysql_header_{len_:105, seq_:215}, pkt_name:"PKT_OKP", obp_mysql_header_.is_send_:1}, pkt_rec[79]:{send:obp20_header_:{payload_len:23, pkt_seq:0, req_id:5509783, flag_.flags:46, ext_flags:0}, obp_mysql_header_{len_:790, seq_:2}, pkt_name:"PKT_OKP", obp_mysql_header_.is_send_:1}, pkt_rec[80]:{send:obp20_header_:{payload_len:23, pkt_seq:0, req_id:5509784, flag_.flags:46, ext_flags:0}, obp_mysql_header_{len_:806, seq_:2}, pkt_name:"PKT_OKP", obp_mysql_header_.is_send_:1}, pkt_rec[81]:{send:obp20_header_:{payload_len:64, pkt_seq:0, req_id:5509785, flag_.flags:46, ext_flags:0}, obp_mysql_header_{len_:831, seq_:2}, pkt_name:"PKT_OKP", obp_mysql_header_.is_send_:1}, pkt_rec[82]:{receive:obp20_header_:{payload_len:832, pkt_seq:0, req_id:5509786, flag_.flags:58, ext_flags:0}, obp_mysql_header_{len_:828, rec_:1002, seq_:0}, pkt_name:"COM_QUERY", obp_mysql_header_.type_:3, obp_mysql_header_.is_send_:0}, pkt_rec[83]:{send:obp_compess_header_{com_len:13269, com_seq:1}, obp20_header_:{payload_len:13241, pkt_seq:1, req_id:5509786, flag_.flags:8, ext_flags:0}, obp_mysql_header_{len_:5, seq_:2}, pkt_name:"PKT_RESHEAD", obp_mysql_header_.is_send_:1}, pkt_rec[84]:{send:obp_compess_header_{com_len:13269, com_seq:1}, obp20_header_:{payload_len:13241, pkt_seq:1, req_id:5509786, flag_.flags:8, ext_flags:0}, obp_mysql_header_{pkt_num_:813, seq_:9}, pkt_name:"PKT_FIELD", obp_mysql_header_.is_send_:1}, pkt_rec[85]:{send:obp_compess_header_{com_len:13269, com_seq:1}, obp20_header_:{payload_len:13241, pkt_seq:1, req_id:5509786, flag_.flags:8, ext_flags:0}, obp_mysql_header_{len_:9, seq_:10}, pkt_name:"PKT_EOF", obp_mysql_header_.is_send_:1}, pkt_rec[86]:{send:obp_compess_header_{com_len:13269, com_seq:1}, obp20_header_:{payload_len:13241, pkt_seq:1, req_id:5509786, flag_.flags:8, ext_flags:0}, obp_mysql_header_{pkt_num_:1172751, seq_:120}, pkt_name:"PKT_ROW", obp_mysql_header_.is_send_:1}, pkt_rec[87]:{send:obp_compess_header_{com_len:916, com_seq:58}, obp20_header_:{payload_len:888, pkt_seq:58, req_id:5509786, flag_.flags:11, ext_flags:0}, obp_mysql_header_{len_:783, seq_:121}, pkt_name:"PKT_EOF", obp_mysql_header_.is_send_:1}, pkt_rec[88]:{send:obp_compess_header_{com_len:916, com_seq:58}, obp20_header_:{payload_len:888, pkt_seq:58, req_id:5509786, flag_.flags:11, ext_flags:0}, obp_mysql_header_{len_:105, seq_:122}, pkt_name:"PKT_OKP", obp_mysql_header_.is_send_:1}, pkt_rec[89]:{send:obp20_header_:{payload_len:23, pkt_seq:0, req_id:5509787, flag_.flags:46, ext_flags:0}, obp_mysql_header_{len_:790, seq_:2}, pkt_name:"PKT_OKP", obp_mysql_header_.is_send_:1}, pkt_rec[90]:{send:obp20_header_:{payload_len:23, pkt_seq:0, req_id:5509788, flag_.flags:46, ext_flags:0}, obp_mysql_header_{len_:806, seq_:2}, pkt_name:"PKT_OKP", obp_mysql_header_.is_send_:1}, pkt_rec[91]:{send:obp20_header_:{payload_len:64, pkt_seq:0, req_id:5509789, flag_.flags:46, ext_flags:0}, obp_mysql_header_{len_:831, seq_:2}, pkt_name:"PKT_OKP", obp_mysql_header_.is_send_:1}, pkt_rec[92]:{receive:obp20_header_:{payload_len:1075, pkt_seq:0, req_id:5509790, flag_.flags:58, ext_flags:0}, obp_mysql_header_{len_:1071, rec_:1075, seq_:0}, pkt_name:"COM_QUERY", obp_mysql_header_.type_:3, obp_mysql_header_.is_send_:0}, pkt_rec[93]:{send:obp_compess_header_{com_len:13190, com_seq:1}, obp20_header_:{payload_len:13162, pkt_seq:1, req_id:5509790, flag_.flags:8, ext_flags:0}, obp_mysql_header_{len_:5, seq_:2}, pkt_name:"PKT_RESHEAD", obp_mysql_header_.is_send_:1}, pkt_rec[94]:{send:obp_compess_header_{com_len:13190, com_seq:1}, obp20_header_:{payload_len:13162, pkt_seq:1, req_id:5509790, flag_.flags:8, ext_flags:0}, obp_mysql_header_{pkt_num_:825, seq_:21}, pkt_name:"PKT_FIELD", obp_mysql_header_.is_send_:1}, pkt_rec[95]:{send:obp_compess_header_{com_len:13190, com_seq:1}, obp20_header_:{payload_len:13162, pkt_seq:1, req_id:5509790, flag_.flags:8, ext_flags:0}, obp_mysql_header_{len_:9, seq_:22}, pkt_name:"PKT_EOF", obp_mysql_header_.is_send_:1}, pkt_rec[96]:{send:obp_compess_header_{com_len:13190, com_seq:1}, obp20_header_:{payload_len:13162, pkt_seq:1, req_id:5509790, flag_.flags:8, ext_flags:0}, obp_mysql_header_{pkt_num_:232118, seq_:66}, pkt_name:"PKT_ROW", obp_mysql_header_.is_send_:1}, pkt_rec[97]:{send:obp_compess_header_{com_len:916, com_seq:11}, obp20_header_:{payload_len:888, pkt_seq:11, req_id:5509790, flag_.flags:11, ext_flags:0}, obp_mysql_header_{len_:783, seq_:67}, pkt_name:"PKT_EOF", obp_mysql_header_.is_send_:1}, pkt_rec[98]:{send:obp_compess_header_{com_len:916, com_seq:11}, obp20_header_:{payload_len:888, pkt_seq:11, req_id:5509790, flag_.flags:11, ext_flags:0}, obp_mysql_header_{len_:105, seq_:68}, pkt_name:"PKT_OKP", obp_mysql_header_.is_send_:1}, pkt_rec[99]:{send:obp20_header_:{payload_len:23, pkt_seq:0, req_id:5509791, flag_.flags:46, ext_flags:0}, obp_mysql_header_{len_:790, seq_:2}, pkt_name:"PKT_OKP", obp_mysql_header_.is_send_:1}, pkt_rec[100]:{send:obp20_header_:{payload_len:23, pkt_seq:0, req_id:5509792, flag_.flags:46, ext_flags:0}, obp_mysql_header_{len_:806, seq_:2}, pkt_name:"PKT_OKP", obp_mysql_header_.is_send_:1}, pkt_rec[101]:{send:obp20_header_:{payload_len:64, pkt_seq:0, req_id:5509793, flag_.flags:46, ext_flags:0}, obp_mysql_header_{len_:831, seq_:2}, pkt_name:"PKT_OKP", obp_mysql_header_.is_send_:1}, pkt_rec[102]:{receive:obp20_header_:{payload_len:1082, pkt_seq:0, req_id:5509794, flag_.flags:58, ext_flags:0}, obp_mysql_header_{len_:1078, rec_:1105, seq_:0}, pkt_name:"COM_QUERY", obp_mysql_header_.type_:3, obp_mysql_header_.is_send_:0}, pkt_rec[103]:{send:obp_compess_header_{com_len:13103, com_seq:1}, obp20_header_:{payload_len:13075, pkt_seq:1, req_id:5509794, flag_.flags:8, ext_flags:0}, obp_mysql_header_{len_:5, seq_:2}, pkt_name:"PKT_RESHEAD", obp_mysql_header_.is_send_:1}, pkt_rec[104]:{send:obp_compess_header_{com_len:13103, com_seq:1}, obp20_header_:{payload_len:13075, pkt_seq:1, req_id:5509794, flag_.flags:8, ext_flags:0}, obp_mysql_header_{pkt_num_:1009, seq_:18}, pkt_name:"PKT_FIELD", obp_mysql_header_.is_send_:1}, pkt_rec[105]:{send:obp_compess_header_{com_len:13103, com_seq:1}, obp20_header_:{payload_len:13075, pkt_seq:1, req_id:5509794, flag_.flags:8, ext_flags:0}, obp_mysql_header_{len_:9, seq_:19}, pkt_name:"PKT_EOF", obp_mysql_header_.is_send_:1}, pkt_rec[106]:{send:obp_compess_header_{com_len:13103, com_seq:1}, obp20_header_:{payload_len:13075, pkt_seq:1, req_id:5509794, flag_.flags:8, ext_flags:0}, obp_mysql_header_{pkt_num_:15343354, seq_:218}, pkt_name:"PKT_ROW", obp_mysql_header_.is_send_:1}, pkt_rec[107]:{send:obp_compess_header_{com_len:204, com_seq:77}, obp20_header_:{payload_len:176, pkt_seq:77, req_id:5509794, flag_.flags:10, ext_flags:0}, obp_mysql_header_{len_:71, seq_:219}, pkt_name:"PKT_ERR", obp_mysql_header_.is_send_:1}, pkt_rec[108]:{send:obp_compess_header_{com_len:204, com_seq:77}, obp20_header_:{payload_len:176, pkt_seq:77, req_id:5509794, flag_.flags:10, ext_flags:0}, obp_mysql_header_{len_:105, seq_:220}, pkt_name:"PKT_OKP", obp_mysql_header_.is_send_:1}], disconnect_state=4)
通过【proxy_sessid=13837874802398417894】关键字过滤 obproxy.log 日志
# 过滤 obproxy.log 日志grep 'proxy_sessid=13837874802398417894' ./obproxy.log | head
[2026-aa-bb 01:09:22.198897] WDIAG [PROXY.SM] tunnel_handler_client (ob_mysql_sm.cpp:6432) [123642][Y0-00007F9F0734CB50] [lt=0] [dc=0] ObMysqlSM::tunnel_handler_client(event="VC_EVENT_INACTIVITY_TIMEOUT", sm_id=64438826)
[2026-aa-bb 01:09:22.198917] WDIAG [PROXY.SM] set_client_abort (ob_mysql_sm.cpp:8651) [123642][Y0-00007F9F0734CB50] [lt=0] [dc=0] client will abort soon((sm_id=64438826, cs_id=96995915, proxy_sessid=13837874802398417894, ss_id=94151949, server_sessid=3221871681, client_ip={x.x.x.x:41106}, server_ip={x.x.x.x:2881}, cluster_name=xxx, tenant_name=xxx, user_name=xxx, db=xxx, event="VC_EVENT_INACTIVITY_TIMEOUT", request_cmd="Query", sql_cmd="Query", sql=select
在过滤后的【obproxy.log】日志中发现报错 VC_EVENT_INACTIVITY_TIMEOUT;
ODP 在往应用发包的时候,在 net_write_timeout 限制时间内没有把数据写出去,所以报了VC_EVENT_INACTIVITY_TIMEOUT 的错误,并把应用和 OBServer 断连,ODP 一直没能把数据写出去的原因是应用侧对数据的消费不够及时,导致发送的速度远大于接收的速度,最后接收端的【tcp recv buffer】满了;
另外还和驱动端对【tcp recv buffer】的读取策略有关:驱动是从【tcp recv buffer】读一部分数据然后本地 fetch 处理,全部处理完之后再读下一部分数据;如果在 net_write_timeout 的时间内没有把上次读取的数据处理完,ODP 就会报错;
错误信息: "Could not read resultset: unexpected end of stream, read 0 bytes from 4";这是在与服务器通信时出现的问题;
在大多数情况下,这是由读取大量结果集的查询引起的。服务器通常希望客户端相对快速地读取结果集。 net_write_timeout 服务器变量控制此行为(默认为 60s)。如果客户端在这段时间内没有读取整个结果集,则服务器将丢弃该连接。如果不希望在此时间内处理结果,则可以使用查询 SET STATEMENT net_write_timeout = 10000 FOR XXX,其中 XXX 是指"常规"查询。针对此查询将 net_write_timeout 设置为更长的时间(在此示例中为 10000)。
如果应用程序通常使用很多具有 FetchSize 的长查询,则可以使用 sessionVariables = net_write_timeout = xxx 选项设置连接;
该报错经过排查原因为:sql 语句执行完成后,在【odp > 程序客户端】时 ObProxy 触发了 net_write_timeout 参数限制,从而导致断联;
net_write_timeout:用于设置中断写数据之前等待块写入连接的秒数;即客户端接收服务端查询返回的数据最多消耗的时间,若超过该时间则会中断连接;建议通过【set session net_write_timeout = 600】命令调整 net_write_timeout 参数或在程序的 jdbc 连接字符串中设置;
-- 查询变量
SHOW VARIABLES LIKE 'net_write_timeout';
SHOW GLOBAL VARIABLES LIKE 'net_write_timeout';
-- 设置变量
SET SESSION net_write_timeout = 1000;
-- SET GLOBAL net_write_timeout = 1000; -- 设置 Global 级别变量,【谨慎执行】