造数半小时左右，报错：unexpected end of stream ,read 0 bytes from 4

OceanBase 技术问题
#1

【 使用环境 】生产环境 or 测试环境
【 OB or 其他组件 】
4.2.1.0
【 使用版本 】
4.2.1.0
【问题描述】清晰明确描述问题
造数半小时左右，报错：unexpected end of stream ,read 0 bytes from 4

65944137efeafe464bb42549a83a87f
65944137efeafe464bb42549a83a87f1476×655 122 KB

【复现路径】问题出现前后相关操作
【附件及日志】推荐使用OceanBase敏捷诊断工具obdiag收集诊断信息,详情参见链接（右键跳转查看）：

【SOP系列 22 】——故障诊断第一步(自助诊断和诊断信息收集)

【备注】基于 LLM 和开源文档 RAG 的论坛小助手已开放测试，在发帖时输入 [@论坛小助手] 即可召唤小助手，欢迎试用！

2 个赞
造数脚本，一开始正常，造数10分钟后爆内存不足 -4013
#3

根据您的描述，您遇到了一个具体的错误信息，但这个错误信息并没有直接对应到已知的 OceanBase 错误码列表中。这可能意味着该错误是由特定的操作或环境因素引起的，或者是某个未记录的异常情况。为了更准确地定位问题，我们可以使用 obdiag 工具来收集相关信息并尝试进行根因分析。

由于错误信息与数据流或网络传输有关，这可能是由于网络问题、数据传输问题或是某些资源限制导致的。因此，我们首先考虑进行日志采集，以便进一步分析。

日志采集场景: 未知问题
日志采集命令: obdiag gather scene run --scene=observer.unknown

这条命令将会收集与问题相关的日志和配置信息，帮助我们理解问题发生的上下文。

请您执行上述命令，并将生成的日志压缩包发送给我们，以便我们能够进一步分析问题的具体原因。

为了更好地帮助您解决问题，请提供以下信息：

  1. 您能否提供更多关于错误发生时正在进行的操作的细节？例如，是在执行批量导入操作还是执行特定的 SQL 语句？
  2. 错误是否只在造数操作中出现，还是在其他操作中也会遇到类似的问题？
  3. 您的 OceanBase 集群配置如何？包括但不限于服务器规格、存储类型、网络配置等。
  4. 是否有其他任何相关的错误信息或警告出现在日志中？

具体信息可参考以下文档:

附上敏捷诊断工具 obdiag 使用帮助链接

2 个赞
#4

麻烦发下observer.log 以及使用obdiag分析下报错前后30分钟到日志，参考命令及文档如下

obdiag analyze log --from “2023-10-08 10:25:00” --to “2023-10-08 11:30:00”

https://www.oceanbase.com/docs/common-obdiag-cn-1000000001214443

2 个赞
#5

申请耗了点时间，文件发给您同事了

2 个赞
#6

好的

3 个赞
#7

再向您确认几个问题:

  1. 您提到的造数操作是指哪种具体的数据插入或生成操作
  2. 错误是否在特定的表或数据集上出现
  3. 在出现错误之前是否有过任何网络波动或者系统资源如CPU或内存的异常消耗
  4. 您是否有对集群进行过自定义配置例如网络参数或是连接池设置
1 个赞
#8

好的，辛苦帮忙看下

1 个赞
#9

根据您提供的错误信息和日志，这个错误似乎与数据传输过程中遇到的问题有关。错误信息提示“unexpected end of stream, read 0 bytes from 4”，这通常意味着在预期的数据流结束之前，读取到了零字节的数据，这可能是由多种原因造成的，比如网络问题、客户端或服务端的资源限制等。

分析思路

  1. 网络问题：检查客户端和服务端之间的网络连接是否稳定，是否存在丢包或延迟高的情况。
  2. 资源限制：检查客户端或服务端是否有资源限制，比如连接数限制、缓冲区大小限制等。
  3. 数据问题：检查正在传输的数据是否存在问题，比如数据格式不正确或数据量过大导致的溢出等问题。
  4. 软件兼容性问题：检查使用的客户端驱动版本是否与 OceanBase 版本兼容。

推荐步骤

  1. 检查网络连接：确保客户端和服务端之间的网络连接稳定，可以尝试 ping 服务端地址以检查网络连通性。
  2. 检查资源限制：检查客户端和服务端的配置文件，确认是否有连接数或缓冲区大小的限制。
  3. 检查数据：如果可能的话，尝试使用较小的数据集重复造数操作，观察是否还会出现同样的错误。
  4. 检查兼容性：确认客户端驱动版本与 OceanBase 版本兼容，如果不兼容，尝试更新客户端驱动版本。

日志分析

从您提供的日志来看，错误发生在 AbstractQueryProtocol.handleIoException 方法中，这表明问题很可能出现在数据传输的过程中。此外，错误发生在 Thread-7 和 Thread-8 上，这可能意味着多线程操作时出现了问题。

建议

  1. 排查网络问题：检查客户端和服务端之间的网络连接。
  2. 调整资源限制：如果存在资源限制，尝试调整客户端或服务端的配置。
  3. 使用最新版本：确保客户端驱动版本与 OceanBase 版本兼容，如果不确定，可以尝试升级客户端驱动版本。
  4. 监控系统资源：在造数操作期间，监控系统的 CPU、内存使用情况以及网络状态。

如果您已经进行了上述步骤但仍无法解决问题，建议联系 OceanBase 的技术支持团队，他们可以提供更深入的技术支持和帮助。

希望以上信息能帮到您！如果有任何疑问或需要进一步的帮助，请随时告知。

具体信息可参考以下文档:

(小助手的答复已结束，如未能解决您的问题，请继续提问并等待其他同学的回复，谢谢！)

1 个赞
#10

在查看中

1 个赞
#11

这个报错时间麻烦发下

1 个赞
#12

目前在observer.log看到大量 4389的报错，clog日志同步太慢，和IO调度相关，使用的什么类型的磁盘呢？

grep “errcode=-4389” observer.log|more

[2024-08-26 15:54:16.204850] WDIAG [STORAGE.TRANS] test_lock (ob_trans_ctx.cpp:235) [6864][T1003_ApplySrv0][T1003][Y0-0000000000000000-0-0] [lt=30][errcode=-4389] transaction log sync use too much time(log_cb={ObTxBaseLogCb:{log_ts:{val:1724658854714052537, v:0}, lsn:{lsn:34922955004}, submit_ts:1724658854714074}, this:0x7f8e9fb557c8, is_inited_:true, trans_id:{txid:57052414}, ls_id:{id:1}, ctx:0x7f8e9fb52950, tx_data_guard:{tx_data:NULL}, is_callbacked_:false, is_dynamic_:false, mds_range_:{range_array_.count():0, range_array_:[]}, cb_arg_array_:[{log_type:0x1, arg:null}, {log_type:0x40, arg:null}, {log_type:0x100, arg:null}], first_part_scn_:{val:18446744073709551615, v:3}}, log_sync_used_time=1490775, ctx_lock_wait_time=1)

[2024-08-26 15:54:16.204995] WDIAG [STORAGE.TRANS] test_lock (ob_trans_ctx.cpp:235) [6864][T1003_ApplySrv0][T1003][Y0-0000000000000000-0-0] [lt=30][errcode=-4389] transaction log sync use too much time(log_cb={ObTxBaseLogCb:{log_ts:{val:1724658854551892861, v:0}, lsn:{lsn:34922953352}, submit_ts:1724658854551918}, this:0x7f8e9fa66f88, is_inited_:true, trans_id:{txid:57052412}, ls_id:{id:1}, ctx:0x7f8e9fa64110, tx_data_guard:{tx_data:NULL}, is_callbacked_:false, is_dynamic_:false, mds_range_:{range_array_.count():0, range_array_:[]}, cb_arg_array_:[{log_type:0x1, arg:null}, {log_type:0x40, arg:null}, {log_type:0x100, arg:null}], first_part_scn_:{val:18446744073709551615, v:3}}, log_sync_used_time=1653076, ctx_lock_wait_time=0)

[2024-08-26 15:54:16.205816] WDIAG [PALF] sliding_cb (log_sliding_window.cpp:2227) [31061][T1004_L0_G1][T1004][YB42C0A80574-00062054D7FBF8D3-0-0] [lt=6][errcode=-4389] log_task life cost too much time(palf_id=1001, self=“192.168.5.114:2882”, log_id=169917714, log_task={header:{begin_lsn:{lsn:364506380552}, end_lsn:{lsn:364506380674}, log_id:169917714, min_scn:{val:1724658854805515280, v:0}, max_scn:{val:1724658854805515280, v:0}, data_len:66, proposal_id:576, prev_lsn:{lsn:18446744073709551615}, prev_proposal_id:9223372036854775807, committed_end_lsn:{lsn:364506380552}, data_checksum:2222604892, accum_checksum:563024905, is_padding_log:false, is_raw_write:false}, state_map:{val:62}, ref_cnt:0, gen_ts:1724658854952721, freeze_ts:1724658854952725, submit_ts:1724658854952752, flushed_ts:1724658855428015, first_ack_ts:1724658856205785, committed_ts:1724658856205786, gen_to_freeze cost time:4, gen_to_submit cost time:31, submit_to_flush cost time:475263, submit_to_first_ack cost time:1253033, submit_to_commit cost time:1253034}, fs_cb_begin_ts=1724658856205788, log_life_time=1253067)

[2024-08-26 15:54:16.205902] WDIAG [LIB] ~ObTimeGuard (utility.h:855) [6961][T1003_TenantWea][T1003][Y0-0000000000000000-0-0] [lt=43][errcode=-4389] destruct(*this=time guard ‘[WRS] [TENANT_WEAK_READ_SERVICE] tenant_id=1003, thread_timer_task’ cost too much time, used=1492648, time_dist: do_cluster_heartbeat=8, generate_cluster_version=1491765)

[2024-08-26 15:54:16.206296] WDIAG [LIB] ~ObTimeGuard (utility.h:855) [5116][IO_SCHEDULE0][T0][YB42C0A80572-00062054C68BD45B-0-0] [lt=17][errcode=-4389] destruct(*this=time guard ‘LocalDevice’ cost too much time, used=307992, time_dist: LocalDevice_submit=307984)

[2024-08-26 15:54:16.206338] WDIAG [LIB] ~ObTimeGuard (utility.h:855) [5116][IO_SCHEDULE0][T0][YB42C0A80572-00062054C68BD45B-0-0] [lt=32][errcode=-4389] destruct(*this=time guard ‘submit_req’ cost too much time, used=308038, time_dist: prepare_req=3, device_submit=307999)

[2024-08-26 15:54:16.206519] WDIAG [LIB] ~ObTimeGuard (utility.h:855) [5119][IO_SCHEDULE0][T0][YB42C0A80572-00062054C55F1AB7-0-0] [lt=8][errcode=-4389] destruct(*this=time guard ‘LocalDevice’ cost too much time, used=408677, time_dist: LocalDevice_submit=408664)

[2024-08-26 15:54:16.206564] WDIAG [LIB] ~ObTimeGuard (utility.h:855) [5119][IO_SCHEDULE0][T0][YB42C0A80572-00062054C55F1AB7-0-0] [lt=30][errcode=-4389] destruct(*this=time guard ‘submit_req’ cost too much time, used=408720, time_dist: prepare_req=2, device_submit=408684)

[2024-08-26 15:54:16.207060] WDIAG [LIB] ~ObTimeGuard (utility.h:855) [5122][IO_SCHEDULE0][T0][YB42C0A80572-00062054C7387457-0-0] [lt=7][errcode=-4389] destruct(*this=time guard ‘LocalDevice’ cost too much time, used=410718, time_dist: LocalDevice_submit=410707)

[2024-08-26 15:54:16.207125] WDIAG [LIB] ~ObTimeGuard (utility.h:855) [5122][IO_SCHEDULE0][T0][YB42C0A80572-00062054C7387457-0-0] [lt=51][errcode=-4389] destruct(*this=time guard ‘submit_req’ cost too much time, used=410782, time_dist: prepare_req=1, device_submit=410725)

[2024-08-26 15:54:16.329830] WDIAG [LIB] ~ObTimeGuard (utility.h:855) [5121][IO_SCHEDULE0][T0][YB42C0A80572-00062054BE285F26-0-0] [lt=18][errcode=-4389] destruct(*this=time guard ‘LocalDevice’ cost too much time, used=535379, time_dist: LocalDevice_submit=535363)

[2024-08-26 15:54:16.329931] WDIAG [LIB] ~ObTimeGuard (utility.h:855) [5121][IO_SCHEDULE0][T0][YB42C0A80572-00062054BE285F26-0-0] [lt=52][errcode=-4389] destruct(*this=time guard ‘submit_req’ cost too much time, used=535479, time_dist: prepare_req=3, device_submit=535418)

[2024-08-26 15:54:16.330474] WDIAG [LIB] ~ObTimeGuard (utility.h:855) [5113][IO_SCHEDULE0][T0][YB42C0A80572-00062054DEC88B21-0-0] [lt=5][errcode=-4389] destruct(*this=time guard ‘LocalDevice’ cost too much time, used=534758, time_dist: LocalDevice_submit=534746)

[2024-08-26 15:54:16.330535] WDIAG [LIB] ~ObTimeGuard (utility.h:855) [5113][IO_SCHEDULE0][T0][YB42C0A80572-00062054DEC88B21-0-0] [lt=30][errcode=-4389] destruct(*this=time guard ‘submit_req’ cost too much time, used=534817, time_dist: prepare_req=2, device_submit=534780)

[2024-08-26 15:54:16.330884] WDIAG [LIB] ~ObTimeGuard (utility.h:855) [5115][IO_SCHEDULE0][T0][Y0-0000000000000000-0-0] [lt=7][errcode=-4389] destruct(*this=time guard ‘LocalDevice’ cost too much time, used=125484, time_dist: LocalDevice_submit=125472)

[2024-08-26 15:54:16.330948] WDIAG [LIB] ~ObTimeGuard (utility.h:855) [5115][IO_SCHEDULE0][T0][Y0-0000000000000000-0-0] [lt=29][errcode=-4389] destruct(*this=time guard ‘submit_req’ cost too much time, used=125549, time_dist: prepare_req=4, device_submit=125511)

[2024-08-26 15:54:16.334500] WDIAG [PALF] inner_append_log (palf_handle_impl.cpp:2123) [6236][T1002_IOWorker][T1002][Y0-0000000000000000-0-0] [lt=12][errcode=-4389] write log cost too much time(ret=-4389, this={palf_id:1002, self:“192.168.5.114:2882”, has_set_deleted:false}, lsn_array=[{lsn:50271464260}], scn_array=[{val:1724658854551918415, v:0}], curr_size=122, accum_size=1586, time_cost=679951)

[2024-08-26 15:54:16.334498] WDIAG [PALF] inner_append_log (palf_handle_impl.cpp:2123) [7105][T1004_IOWorker][T1004][Y0-0000000000000000-0-0] [lt=16][errcode=-4389] write log cost too much time(ret=-4389, this={palf_id:1003, self:“192.168.5.114:2882”, has_set_deleted:false}, lsn_array=[{lsn:422478926881}, {lsn:422478927125}, {lsn:422478927285}, {lsn:422478927406}, {lsn:422478927528}], scn_array=[{val:1724658854725622893, v:0}, {val:1724658854725657199, v:0}, {val:1724658854725657200, v:0}, {val:1724658854725657201, v:0}, {val:1724658854725657202, v:0}], curr_size=1294, accum_size=23019, time_cost=681254)

[2024-08-26 15:54:16.334623] WDIAG [PALF] sliding_cb (log_sliding_window.cpp:2227) [6233][T1002_LogIOCb0][T1002][Y0-0000000000000000-0-0] [lt=8][errcode=-4389] log_task life cost too much time(palf_id=1002, self=“192.168.5.114:2882”, log_id=45783731, log_task={header:{begin_lsn:{lsn:50271464260}, end_lsn:{lsn:50271464382}, log_id:45783731, min_scn:{val:1724658854551918415, v:0}, max_scn:{val:1724658854551918415, v:0}, data_len:66, proposal_id:555, prev_lsn:{lsn:50271464138}, prev_proposal_id:555, committed_end_lsn:{lsn:50271464260}, data_checksum:1715074492, accum_checksum:2817635375, is_padding_log:false, is_raw_write:false}, state_map:{val:58}, ref_cnt:0, gen_ts:1724658855654407, freeze_ts:1724658855654408, submit_ts:1724658855654411, flushed_ts:1724658856334561, first_ack_ts:-1, committed_ts:1724658856204438, gen_to_freeze cost time:1, gen_to_submit cost time:4, submit_to_flush cost time:680150, submit_to_first_ack cost time:0, submit_to_commit cost time:550027}, fs_cb_begin_ts=1724658856334600, log_life_time=680193)

#13

报错时间15:50:00左右，但是服务器系统时间不一定，在50分前后
磁盘类型是问的下面这个吗？

image
image821×371 44.2 KB

1 个赞
#14

磁盘类型是说 是SSD类型磁盘 还是普通类型磁盘，因为你在做大量数据插入，如果磁盘性能跟不上会出现这个问题，也可以监控下磁盘IO等租户资源是否紧张

1.造数过程中，在服务器上监控下磁盘IO情况 iostat -mxdt 3
2.在ocp 租户–> 性能监控–>存储与缓存 物理 IO 次数，物理IO吞吐量，物理IO耗时
3.在ocp 租户–> 性能监控–>性能与SQL 看下 clog同步延迟 ， 租户 CPU 消耗，内存使用率

1 个赞
#15

好的，用的是普通硬盘，我们再复现监控下磁盘情况

1 个赞
#16

造数前：

b7e61c6eb5bfc217a621a07f3de59c7
b7e61c6eb5bfc217a621a07f3de59c71316×717 88.2 KB

75ae7d97781f61058f01a33ff4d6280
75ae7d97781f61058f01a33ff4d62802244×1042 228 KB

974d9268495d9c8c16acc354a950203
974d9268495d9c8c16acc354a9502032267×1132 258 KB

aa89a86348434ae6f1d8a9a85c4c0d0
aa89a86348434ae6f1d8a9a85c4c0d02284×1020 282 KB

造数中：
291d3fc79d6391904c0ada2842cb1a7
291d3fc79d6391904c0ada2842cb1a71356×806 105 KB

43de9a6ed68d3c7b808d24a0d41e5be
43de9a6ed68d3c7b808d24a0d41e5be2287×1085 339 KB

be3979a10377d1600ee101bbc8e0924
be3979a10377d1600ee101bbc8e09242239×1094 327 KB

791e6f9b7f683ee15e787f843a04939
791e6f9b7f683ee15e787f843a049392264×1001 272 KB

目前测试了两小时了，还没出现报错，还在继续造数，后续有报错会将报错后的监控数据发出

#17

50分左右报错了，监控数据如下：

image
image1304×821 219 KB

image
image2272×1169 285 KB

image
image2224×1049 262 KB

image
image2269×1110 323 KB

#18

补一下造数前的监控，上面的图看起来不对，当时在起ocp的时候让同事有开启造数，后面停了，可能是开启的时候截的图，下面补新的：

image
image1331×812 111 KB

image
image2266×1142 290 KB

image
image2261×1141 282 KB

image
image2301×1087 351 KB

#20

从监控数据分析：插入 删除平均响应时间在2500ms以上 峰值接近9000ms，IO吞吐 读 写平均 5M 峰值 写 20M 读未出现峰值，IOPS峰值 300 ，IO耗时 10ms以上，主机IO监控磁盘利用了90%以上 磁盘队列明显，cpu 内存 使用率正常；
另外“clog 同步延迟”的监控你没有发截图，也可以发下看看

“[errcode=-4389] write log cost too much time(ret=-4389, this={palf_id:1003, self:“192.168.5.114:2882”, has_set_deleted:false}“

“[errcode=-4389] log_task life cost too much time(palf_id=1002, self=“192.168.5.114:2882”, log_id=45783731, log_task={header:{begin_lsn:{lsn:50271464260}, end_lsn:{lsn:50271464382}”

“WDIAG [LIB] ~ObTimeGuard (utility.h:855) [5115][IO_SCHEDULE0][T0][Y0-0000000000000000-0-0] [lt=29][errcode=-4389] destruct(*this=time guard ‘submit_req’ cost too much time, used=125549, time_dist: prepare_req=4, device_submit=125511)”

结合报错日志，监控数据 及故障分析文档 ，问题是磁盘IO能力不足，建议使用更高性能的磁盘，比如SSD 或者降低数据写入频率

https://www.oceanbase.com/knowledge-base/oceanbase-database-1000000000532684?back=kb

image
image1972×1144 194 KB

1 个赞