3个节点的ob集群，重启一个observer之后，落在该节点上的sql都非常慢

luhongwei · 2023 年2 月 22 日 15:08

【使用环境】生产环境
OB
【使用版本】3.1.2
【问题描述】
我们有一个3个节点的ob集群，昨天有个节点因为负载太高（32核的机器负载直接到了1600），observer进程挂了，再重启之后发现，此节点上的sql非常慢，cpu时间很长，请问该如何排查？有可能是什么原因。

【问题现象及影响】
查询和插入均很慢，只有在这个节点上sql很慢，如果sql落在别的节点上，是很快的。

【附件】
查询系统表偶发也慢

插入1000条数据要9到10秒

黑屏我看了节点正常重启了

绵阳 · 2023 年2 月 22 日 15:15

机器之间时延正常吗？如果正常的话可能需要抓包查看下

luhongwei · 2023 年2 月 22 日 15:19

监控指标看着是一切正常，ping的延迟也很低。是需要直接抓2882端口的包么？

那个断层就是挂了的时候

luhongwei · 2023 年2 月 22 日 15:21

磁盘我看了也都没有损坏

绵阳 · 2023 年2 月 22 日 15:21

抓一下延迟高的那个节点的端口接受包的时间和返回时间

luhongwei · 2023 年2 月 22 日 15:27

比如这个sql应该抓170.8和170.11之间的时延？

绵阳 · 2023 年2 月 22 日 15:30

抓170.10的2882端口收到客户端170.8发送的包的时间和返回的时间

luhongwei · 2023 年2 月 22 日 16:21

目前看是正常的

绵阳 · 2023 年2 月 22 日 16:25

是不是设置了这个节点是leader？我看这个节点昨天就因为负载高挂过了

luhongwei · 2023 年2 月 22 日 16:50

目前来看这个节点不是leader，是只有leader才能提供读写吗？

luhongwei · 2023 年2 月 22 日 17:02

[root@db08 ~]# traceroute 192.168.170.10
traceroute to 192.168.170.10 (192.168.170.10), 30 hops max, 60 byte packets
1 192.168.170.10 (192.168.170.10) 0.090 ms 0.076 ms 0.089 ms
[root@db08 ~]#
我们这两机器都是直接连接的核心交换机，中间只有一跳。所以网络延迟是非常低的

luhongwei · 2023 年2 月 23 日 10:22

我们这个节点在上次挂了重启之后一直在时不时的报以下信息，上次只是挂了进程服务器还是正常的。奇怪的是挂前之前是没有报此类信息，挂完恢复之后才出现的。

luhongwei · 2023 年2 月 23 日 10:26

昨天我们对ob做了三个方面的调整。

重启了这个节点的observer进程；但是现在依旧在报这个事件；
减少了一批数据回填任务（insert），降低了部分负载；
调整了昨天这个慢的租户的zone顺序，将170.10放置最低优先级。
现在观察，insert 1000条数据没有出现昨天要10多秒的情况，大约300ms，但目前不确定是哪一个调整所致。上述事件也一直没有停止。

luhongwei · 2023 年2 月 23 日 10:30

另外，上次一次挂的原因没有找出来，日志看不太懂，可否帮忙看看日志。
如附件。
这是挂了之前的最后一个日志文件。
observer.log.tar.gz (5.6 MB)

绵阳 · 2023 年2 月 23 日 10:41

ob节点挂掉可能是core住了，可以看下obx.zx下有没有core文件，有的话在该目录下执行
gdb ./bin/observer core文件名
输入bt 查到的堆栈发一下

张雨齐 · 2023 年2 月 23 日 10:44

● 当正在运行的 OBServer 异常退出时，通过操作系统（ ps -ef 命令）查询不到 OBServer 进程的存在，此时，如果不是硬件损坏或者操作系统的问题，可尝试拉起 observer 进程作为应急手段；OBServer 在退出时会生成 core dump 文件，可以此为依据进行 OBServer 的异常退出根因分析（版本不同，core dump排查的方法不同）

○ 可以填入 addr2line -pCfe $observer $symbol_addr 命令中的$symbol_addr以获得CRASH原始信息和线程栈信息

绵阳 · 2023 年2 月 23 日 11:25

选举是不断重复发生的事件，应该是该副本选举超时导致的报错，可能跟执行sql慢是一个原因
请问这个节点有没有缓存池不足的问题，检查下该节点是否有大量磁盘IO，网络IO，内存占比等性能指标

luhongwei · 2023 年2 月 23 日 13:46

core文件查到的信息如下

[Thread debugging using libthread_db enabled]
Using host libthread_db library "/lib64/libthread_db.so.1".
Core was generated by `/home/admin/oceanbase/bin/observer'.
Program terminated with signal 11, Segmentation fault.
#0  0x00007f4feb6784fb in raise () from /usr/lib64/libpthread.so.0
Missing separate debuginfos, use: debuginfo-install oceanbase-3.1.2-20210920114401.el7.x86_64
(gdb) bt
#0  0x00007f4feb6784fb in raise () from /usr/lib64/libpthread.so.0
#1  0x0000000009e8f669 in oceanbase::common::coredump_cb(int, siginfo_t*) ()
#2  <signal handler called>
#3  0x000000000683661a in oceanbase::storage::ObTableScanStoreRowIterator::release_table_ref() ()
#4  0x00000000068366c8 in oceanbase::storage::ObTableScanRangeArrayRowIterator::release_table_ref() ()
#5  0x00000000083b9542 in oceanbase::sql::ObExecContext::release_table_ref() ()
#6  0x00000000083bd60a in oceanbase::sql::ObExecContext::check_status() ()
#7  0x0000000008524d17 in oceanbase::sql::ObPxCoordOp::wait_all_running_dfos_exit() ()
#8  0x000000000851bdd4 in oceanbase::sql::ObPxCoordOp::terminate_running_dfos(oceanbase::sql::ObDfoMgr&) ()
#9  0x000000000852625f in oceanbase::sql::ObPxCoordOp::inner_close() ()
#10 0x0000000008537c48 in oceanbase::sql::ObPxFifoCoordOp::inner_close() ()
#11 0x00000000028b6725 in oceanbase::sql::ObOperator::close() ()
#12 0x00000000028b65ee in oceanbase::sql::ObOperator::close() ()
#13 0x00000000028b65ee in oceanbase::sql::ObOperator::close() ()
#14 0x00000000028b6471 in oceanbase::sql::ObExecuteResult::close() const ()
#15 0x00000000028b5d9e in oceanbase::sql::ObExecuteResult::close(oceanbase::sql::ObExecContext&) ()
#16 0x00000000028bd963 in oceanbase::sql::ObResultSet::close(bool) ()
#17 0x000000000289293e in oceanbase::observer::ObSyncPlanDriver::response_result(oceanbase::observer::ObMySQLResultSet&) ()
#18 0x0000000002879152 in oceanbase::observer::ObMPQuery::process_single_stmt(oceanbase::sql::ObMultiStmtItem const&, oceanbase::sql::ObSQLSessionInfo&, bool, bool, bool&, bool&) ()
#19 0x0000000002873fb6 in oceanbase::observer::ObMPQuery::process() ()
#20 0x00000000028708a7 in oceanbase::rpc::frame::ObReqProcessor::run() ()
#21 0x000000000286e6a3 in oceanbase::omt::ObWorkerProcessor::process(oceanbase::rpc::ObRequest&) ()
#22 0x00000000028694e5 in oceanbase::omt::ObThWorker::worker(long&, long&, int&) ()
#23 0x000000000722084b in oceanbase::omt::ObThWorker::run(long) ()
#24 0x0000000003176030 in std::_Function_handler<void (), oceanbase::lib::CoKThreadTemp<oceanbase::lib::CoUserThreadTemp<oceanbase::lib::CoSetSched> >::start()::{lambda()#1}>::_M_invoke(std::_Any_data const&) ()
#25 0x0000000009ca9287 in oceanbase::lib::CoSetSched::Worker::run() ()
#26 0x0000000009ca6570 in oceanbase::lib::CoRoutine::__start(boost::context::detail::transfer_t) ()
#27 0x0000000009ca1bcf in make_fcontext ()
#28 0x0000000000000000 in ?? ()

绵阳 · 2023 年2 月 23 日 14:36

能看下
#3 0x000000000683661a in oceanbase::storage::ObTableScanStoreRowIterator::release_table_ref() 这个里面main_iter_变量内容是什么吗

绵阳 · 2023 年2 月 23 日 15:08

这个可以确认下吗