SYS 租户队列积压，集群异常

适用版本

OceanBase 数据库 V3.X 版本。

问题描述

集群无法正常使用，DDL 任务都卡住，部分业务失败，包括内部视图 clog_stat 无法查询都是报错 RPC，init fast sqc cb async interrupt qc:。

过滤 observer.log 发现如下报错信息。

grep YB420CF00056-0005FBE1B87F031A-0-0 observer.log
[2023-07-04 10:01:34.873643] WARN [SQL.ENG] process (ob_px_rpc_processor.cpp:456) [80930][0][Y0-0000000000000000-0-0] [lt=12] [dc=0] init fast sqc cb async interrupt qc(trace_id=YB420CF00056-0005FBE1B87F031A-0-0,addr_="192.xxx.x.x:2882", timeout_ts_=1688436104853926, interrupt_id_=task(44009210,38654706679), ret=-4019)
[2023-07-04 10:01:34.933993] WARN [SQL.SESSION] inner_get_sys_var (ob_basic_session_info.cpp:1105) [79606][0][YB420CF00056-0005FBE1B87F031A-0-0] [lt=9] [dc=0] sys var is NULL(ret=-4018, store_idx=6)
[2023-07-04 10:01:34.934006] WARN [SQL.SESSION] get_charset_sys_var (ob_basic_session_info.cpp:2560) [79606][0][YB420CF00056-0005FBE1B87F031A-0-0] [lt=11] [dc=0] fail to inner get sys var(ret=-4018, sys_var_id=6)
[2023-07-04 10:01:34.963285] INFO [SERVER] ob_all_virtual_clog_stat.cpp:67 [79606][0][YB420CF00056-0005FBE1B87F031A-0-0] [lt=4] [dc=0] get_clog_stat finish(ret=-4008)
[2023-07-04 10:01:44.854499] WARN [SQL.DTL] process_base (ob_dtl_channel_loop.cpp:246) [79602][0][YB420CF00056-0005FBE1B87F031A-0-0] [lt=8] [dc=0] message loop is interrupted(code={code:-4012, info:{msg:"tid:80931,from:"192.xxx.x.x:2882",RPC ABORT PX"}}, ret=-4012)
[2023-07-04 10:01:44.854513] WARN [SQL.ENG] fetch_rows (ob_px_fifo_coord_op.cpp:187) [79602][0][YB420CF00056-0005FBE1B87F031A-0-0] [lt=13] [dc=0] fail process message(ret=-4012)
[2023-07-04 10:01:44.854542] INFO [SQL.ENG] ob_px_interruption.cpp:85 [79602][0][YB420CF00056-0005FBE1B87F031A-0-0] [lt=6] [dc=0] success to send interrupt message(int_code={code:-4662, info:{msg:"tid:79602,from:"192.xxx.x.x:2882",PX ABORT DFO"}}, addr="192.xxx.x.x:2882", interrupt_id=task(44009210,38658900989))
[2023-07-04 10:01:44.854560] INFO [SQL.ENG] ob_px_interruption.cpp:85 [79602][0][YB420CF00056-0005FBE1B87F031A-0-0] [lt=9] [dc=0] success to send interrupt message(int_code={code:-4662, info:{msg:"tid:79602,from:"192.xxx.x.x:2882",PX ABORT DFO"}}, addr="192.xxx.x.x:2882", interrupt_id=task(44009210,38658900989))
[2023-07-04 10:01:44.854669] WARN [SQL.ENG] fetch_rows (ob_px_fifo_coord_op.cpp:214) [79602][0][YB420CF00056-0005FBE1B87F031A-0-0] [lt=6] [dc=0] QC get error code(ret=-4012, ret_terminate=0)

查询内部视图卡住。

obclient[ocean base] >select * from oceanbase.gv$tenant_px_worker_stat where tenant_id=1;
ERROR 4012(HY 000) ：Timeout

此时 DDL 也执行不了。

obclient> drop tablet 1；
Query OK， Orows affected(4.12 sec)
obclient> drop tablet 1；
ERROR 1051 (42502) : Unknown table 'dbdb.t1'
obclient> create table t1 (id bigint) ；
--卡住

问题诊断

1. 查看队列请求统计，发现 sys 租户存在队列积压：req_queue:total_size > 0。

   [2023-07-04 10:19:21.723800] INFO [SERVER.OMT] ob_multi_tenant.cpp:819 [3381][0][Y0-0000000000000000-0-0] [lt=2] [dc=0] dump tenant info(tenant={id:1, compat_mode:0, unit_min_cpu:"2.500000000000000000e+00", unit_max_cpu:"5.000000000000000000e+00", slice:"0.000000000000000000e+00", slice_remain:"0.000000000000000000e+00", token_cnt:20, sug_token_cnt:20, ass_token_cnt:20, lq_tokens:6, used_lq_tokens:0, stopped:false, idle_us:2986429, recv_hp_rpc_cnt:9195582, recv_np_rpc_cnt:78481716, recv_lp_rpc_cnt:0, recv_mysql_ps_close_cnt:4193, recv_mysql_cnt:107614346, recv_task_cnt:15192887, recv_large_req_cnt:0, tt_large_quries:7370, pop_normal_cnt:6126885684, actives:20, workers:20, nesting workers:7, lq waiting workers:0, req_queue:total_size=65537 queue[0]=0 queue[1]=0 queue[2]=51900 queue[3]=800 queue[4]=12837 queue[5]=0 , large queued:0, reserve queued:0, multi_level_queue:total_size=0 queue[0]=0 queue[1]=0 queue[2]=0 queue[3]=0 queue[4]=0 queue[5]=0 queue[6]=0 queue[7]=0 , recv_level_rpc_cnt:cnt[0]=0 cnt[1]=0 cnt[2]=436 cnt[3]=2 cnt[4]=0 cnt[5]=6256 cnt[6]=413 cnt[7]=0 , group_map:null, rpc_stat_info: pcode=0x701:cnt=2219 pcode=0x1ee:cnt=8 pcode=0x515:cnt=6 pcode=0x23e:cnt=2 pcode=0x51f:cnt=2})
   

2. 针对队列打满的节点收集 obstack，发现 sys 租户线程卡在 startup_normal_sqc，这个地方是 sys 租户 RPC 线程在等启动 px 线程等不到，wait 在这个地方。

   Thread 2062 (TNT_L0_1)#0 0x00007f59c94c3239 in syscall from /usr/lib64/libc-2.17.so#1 
   0x00000000051a6463 in oceanbase::lib::CoFutex::wait(int, long) from /home/admin/oceanbase/bin/observer.debug#2 
   0x000000000c6a3bd5 in oceanbase::sql::ObInitSqcP::startup_normal_sqc(oceanbase::sql::ObPxSqcHandler&) from /home/admin/oceanbase/bin/observer.debug#3 
   0x000000000c6a57d7 in oceanbase::sql::ObInitSqcP::after_process(int) from /home/admin/oceanbase/bin/observer.debug#4 
   0x00000000051a69ff in oceanbase::obrpc::ObRpcProcessorBase::run() from /home/admin/oceanbase/bin/observer.debug#5 
   0x000000000ba9e6d1 in oceanbase::omt::ObWorkerProcessor::process_one(oceanbase::rpc::ObRequest&) from /home/admin/oceanbase/bin/observer.debug#6 
   0x000000000512bc8f in oceanbase::omt::ObWorkerProcessor::process(oceanbase::rpc::ObRequest&) from /home/admin/oceanbase/bin/observer.debug#7 
   0x000000000ba9c061 in oceanbase::omt::ObThWorker::process_request(oceanbase::rpc::ObRequest&) from /home/admin/oceanbase/bin/observer.debug#8 
   0x00000000051278f6 in oceanbase::omt::ObThWorker::worker(long&, long&, int&) from /home/admin/oceanbase/bin/observer.debug#9 
   0x000000000ba9c667 in non-virtual thunk to oceanbase::omt::ObThWorker::run(long) from /home/admin/oceanbase/bin/observer.debug#10 
   0x000000000f4bef53 in std::_Function_handler<void (), 
   oceanbase::lib::UserThread::start()::$_14::operator()(oblib::Thread*) const::{lambda()#1}>::_M_invoke(std::_Any_data const&) from /home/admin/oceanbase/bin/observer.debug#11 
   0x000000000f4bedaf in eeentry(boost::context::detail::transfer_t) from /home/admin/oceanbase/bin/observer.debug#12 
   0x000000000f75a7ff in make_fcontext from /home/admin/oceanbase/bin/observer.debug
   

3. 登录 SYS 租户，查询队列情况，发现 94、85 节点存在队列挤压情况。

   obclient [oceanbase]> select svr_ip,req_queue_total_size,queue_0,queue_1,queue_2,queue_3,queue_4 from __all_virtual_dump_tenant_info where req_queue_total_size > 0;
   +--------------+----------------------+---------+---------+---------+---------+---------+
   | svr_ip       | req_queue_total_size | queue_0 | queue_1 | queue_2 | queue_3 | queue_4 |
   +--------------+----------------------+---------+---------+---------+---------+---------+
   | xxx.xx.x.85  |                65537 |       0 |       0 |   62649 |    1094 |    1794 |
   | xxx.xx.x.94  |                54167 |       0 |       0 |   49974 |    1603 |    2590 |
   | xxx.xx.x.71  |                  202 |       0 |       0 |       0 |       4 |     198 |
   | xxx.xx.x.71  |                   42 |       0 |       0 |       0 |       2 |      40 |
   | xxx.xx.x.11  |                  122 |       0 |       0 |       0 |      13 |     109 |
   | xxx.xx.x.13  |                   62 |       0 |       0 |       0 |       0 |      62 |
   +--------------+----------------------+---------+---------+---------+---------+---------+
   6 rows in set (0.02 sec)
   

4. 收集存在队列挤压的 observer 的 obstack,

   同样的堆栈 startup_normal_sqc。

   Thread 125745 (TNT_L0_1)
   #0    0x00007f2db579b239 in syscall from /usr/lib64/libc-2.17.so
   #1    0x00000000051a6463 in oceanbase::lib::CoFutex::wait(int, long) from /home/admin/oceanbase/bin/observer.debug
   #2    0x000000000c6a3bd5 in oceanbase::sql::ObInitSqcP::startup_normal_sqc(oceanbase::sql::ObPxSqcHandler&) from /home/admin/oceanbase/bin/observer.debug
   #3    0x000000000c6a57d7 in oceanbase::sql::ObInitSqcP::after_process(int) from /home/admin/oceanbase/bin/observer.debug
   #4    0x00000000051a69ff in oceanbase::obrpc::ObRpcProcessorBase::run() from /home/admin/oceanbase/bin/observer.debug
   #5    0x000000000ba9e6d1 in oceanbase::omt::ObWorkerProcessor::process_one(oceanbase::rpc::ObRequest&) from /home/admin/oceanbase/bin/observer.debug
   #6    0x000000000512bc8f in oceanbase::omt::ObWorkerProcessor::process(oceanbase::rpc::ObRequest&) from /home/admin/oceanbase/bin/observer.debug
   #7    0x000000000ba9c061 in oceanbase::omt::ObThWorker::process_request(oceanbase::rpc::ObRequest&) from /home/admin/oceanbase/bin/observer.debug
   #8    0x00000000051278f6 in oceanbase::omt::ObThWorker::worker(long&, long&, int&) from /home/admin/oceanbase/bin/observer.debug
   #9    0x000000000ba9c667 in non-virtual thunk to oceanbase::omt::ObThWorker::run(long) from /home/admin/oceanbase/bin/observer.debug
   #10   0x000000000f4bef53 in std::_Function_handler<void (), oceanbase::lib::UserThread::start()::$_14::operator()(oblib::Thread*) const::{lambda()#1}>::_M_invoke(std::_Any_data const&) from /home/admin/oceanbase/bi
   

5. 查看 __all_virtual_session_info 发现了几天前的 SQL 请求依然卡在 85、94 节点上。

   obclient [oceanbase]> select host,svr_ip,id,sql_id,info,state,time,thread_id from __all_virtual_session_info order by time desc limit 130 ;
   +--------------------+--------------+------------+----------------------------------+--------------------+----------------+---------+-----------+
   | host               | svr_ip       | id         | sql_id                           | info               | state          | time    | thread_id |
   +--------------------+--------------+------------+----------------------------------+--------------------+----------------+---------+-----------+
   | xxx.xx.x.30:2882   | xxx.xx.x.85  | 3223430613 | 24A4A8D20822CA9E0D07A7A28429415A | PX SUB COORDINATOR | ACTIVE         | 1207844 |    126704 |
   | xxx.xx.x.30:2882   | xxx.xx.x.85  | 3223141802 | 24A4A8D20822CA9E0D07A7A28429415A | PX SUB COORDINATOR | ACTIVE         | 1207844 |     71678 |
   | xxx.xx.x.30:2882   | xxx.xx.x.85  | 3222599135 | 24A4A8D20822CA9E0D07A7A28429415A | PX SUB COORDINATOR | ACTIVE         | 1207844 |    122672 |
   | xxx.xx.x.30:2882   | xxx.xx.x.85  | 3223385484 | 24A4A8D20822CA9E0D07A7A28429415A | PX SUB COORDINATOR | ACTIVE         | 1207844 |    126763 |
   

6. 由于 sql_audit 已经被刷掉，基于上述 sql_id 在 OCP monitor 租户中查找 SQL 文本，发现是很久之前创建的并行查询 sql_audit 表的 SQL。

   obclient [ocp_monitor]> select * from ob_hist_sqltext where sql_id='24A4A8D20822CA9E0D07A7A28429415A' \G;
   *************************** 1. row ***************************
   collect_time: 1687219200000000
   ob_cluster_id: 100009
   cluster_name: xxxx
   ob_tenant_id: 1100
     tenant_name: xxxx
   ob_server_id: 1
       ob_db_id: 1209462790553601
         db_name: oceanbase
     ob_user_id: 1209462790553601
       user_name: root
         sql_id: 24A4A8D20822CA9E0D07A7A28429415A
       sql_text: SELECT/*+ PARALLEL(15)*/ SQL_ID, COUNT(*) AS QPS, AVG(t1.elapsed_time) RT
   FROM oceanbase.gv$sql_audit t1 WHERE tenant_id = 1001 AND
   IS_EXECUTOR_RPC = 0 AND request_time > (time_to_usec(now()) - 10000000) AND
   request_time < time_to_usec (now())
   GROUP BY t1.sql_id ORDER BY QPS DESC LIMIT 10
       statement: SELECT/*+ PARALLEL(15)*/ SQL_ID, COUNT(*) AS QPS, AVG(t1.elapsed_time) RT
   FROM oceanbase.gv$sql_audit t1 WHERE tenant_id = ? AND
   IS_EXECUTOR_RPC = ? AND request_time > (time_to_usec(now()) - ?) AND
   request_time < time_to_usec (now())
   GROUP BY t1.sql_id ORDER BY QPS DESC LIMIT 10
       sql_type: SELECT
     create_time: 2023-06-20 15:42:19
   

问题原因

SYS 租户收到执行的查询 sql_audit 的 PX 语句，RPC 线程需要启动 N 个 PX 线程，因为异常原因部分 PX 线程启动失败，导致这些 RPC 线程一直不释放，RS 队列堵塞。分析代码发现 OOM 场景下可能会出现该问题。

解决方法

升级 OceanBase 数据库版到问题已修复的版本。问题已修复的版本包括 2023 年 7 月的版本。

应急处理办法：

• 重启出现问题的 OBServer 节点。
• 禁止在查询内部表、视图时使用较大的并行度。