问题现象
当集群中的一台主机 hang 时,直接表现为 ssh 登录卡住,外部无法访问到此节点。若 hang 住的主机上存在租户 leader,则租户会不可用(QPS 跌 0),同时可能伴随 sys 租户的租户 cpu 使用率达到 100%(sys租户队列积压),引发一系列雪崩现象,最后整个集群不可用。
问题表现:
- hang 的主机 ssh 登录卡住。
- 如果此节点是业务租户的 leader unit,则此业务租户 QPS 会跌 0。
- 可能伴随 sys 租户 cpu 使用率达到 100%(队列积压),sys 租户的登录和使用卡顿或无响应。
- 一段时间后可能伴随有其他业务租户 cpu 使用率达到 100%,其他业务租户 QPS 可能会跌 0。
- 从其他正常节点尝试登录业务租户,提示登录超时。
触发条件:
- 主机 hang 但是并未宕机,hang 的节点无法收到网络包。
- hang 的节点 observer 进程还在,observer 可以正常发送网络包。
- hang 的节点是租户的 leader 节点(节点所在 zone 是租户的 primary zone,并且租户 unit 在此节点上)。
问题原因
不自动切主的原因:此节点上的 leader 租约一直续约正常,从此节点的视角来看集群一切正常。无主选举依赖租约过期,如果分区的 leader 持续续约成功,则不会卸任,也就不会触发无主选举。分区 leader 不发生切主,但此节点已经无法连通,SQL 执行会卡住超时,所以 QPS 会跌 0。
sys 租户 cpu 达到 100% 的原因:因为 sys 租户可能会去切租户切换到业务租户下去查询业务租户的内部视图,业务租户的内部视图 leader 依然在 hang 的节点上,所以 SQL 会长时间卡住超时,占用 sys 租户的工作线程,最终导致 cpu 达到 100%。
登录失败的原因排查
在对应节点搜索 observer 日志关键词。
grep "MySQL LOGIN" observer.log| grep -v "proc_ret=0"通过此关键词,可以找到登录失败的日志,内容示例:
[2024-04-17 17:45:30.046817] INFO [SERVER] obmp_connect.cpp:374 [1716714][0][Y0-0000000000000000-0-0] [lt=6] [dc=0] MySQL LOGIN(direct_client_ip="xxx.xxx.xxx.xxx", client_ip=xxx.xxx.xxx.xxx, tenant_name=xxx, tenant_id=1001, user_name=xxx, host_name=xxx.xxx.xxx.xxx, sessid=3222107046, proxy_sessid=783989401821858485, sess_create_time=0, from_proxy=true, from_java_client=false, capability=683647754, proxy_capability=2631, use_ssl=false, c/s protocol="OB_MYSQL_CS_TYPE", proc_ret=-4012, ret=0)proc_ret即为登录失败的报错码,-4012 代表登录超时。根据此条日志的前几条找到登录失败的原因,注意线程号需要一致,所以使用线程号进行过滤。
grep "\[1716714" observer.log* |less返回结果如下:
observer.log.20240417175120154:[2024-04-17 17:45:30.005342] INFO [SERVER] ob_inner_sql_connection.cpp:499 [1716714][0][XXXXXXXXXXX-XXXXXXXXXXXXXXXXX-0-0] [l t=2] [dc=0] sql execute need retry(ret=0, last_ret=-4265, retry_cnt=4, sleep_time_us=40000) observer.log.20240417175120154:[2024-04-17 17:45:30.045521] INFO [SHARE.PT] ob_partition_location_cache.cpp:3354 [1716714][0][XXXXXXXXXXX-XXXXXXXXXXXXXXXXX-0-0]] [lt=4] [dc=0] add_update_task success(task={table_id:{value:1100611139403781, first:1001, second:5}, partition_id:0, add_timestamp:1713347130045498, clu ster_id:1687678324, type:0}, leader_inactive_async_update=true, now=1713347130045498, location={table_id:{value:1100611139403781, first:1001, second:5}, part ition_id:0, partition_cnt:0, pg_key:{tid:18446744073709551615, partition_id:-1, part_idx:268435455, subpart_idx:268435455}, replica_locations:[{server:"10.22 5.76.36:2882", role:2, sql_port:2881, replica_type:0, reserved:0, property:{memstore_percent_:100}}, {server:"10.225.76.41:2882", role:1, sql_port:2881, repl ica_type:0, reserved:0, property:{memstore_percent_:100}}, {server:"10.225.76.44:2882", role:2, sql_port:2881, replica_type:0, reserved:0, property:{memstore _percent_:100}}], renew_time:1713347130006061, sql_renew_time:1713347130006061, is_mark_fail:false}, is_nonblock=true) observer.log.20240417175120154:[2024-04-17 17:45:30.046634] INFO [SERVER] ob_inner_sql_connection.cpp:718 [1716714][0][XXXXXXXXXXX-XXXXXXXXXXXXXXXXX-0-0]] [lt=9] [dc=0] slow inner sql(last_ret=-4012, sql={ObIExecutor:, sql:"SELECT MAX(schema_version) as version, host_ip() as myip, rpc_port() as myport FROM __all_ddl_operation"}, process_time=30041160) observer.log.20240417175120154:[2024-04-17 17:45:30.046752] INFO [SERVER] obmp_packet_sender.cpp:296 [1716714][0][Y0-0000000000000000-0-0] [lt=8] [dc=0] sending error packet(err=-4012, extra_err_info=NULL) observer.log.20240417175120154:[2024-04-17 17:45:30.046801] INFO [SERVER] obmp_base.cpp:298 [1716714][0][Y0-0000000000000000-0-0] [lt=7] [dc=0] free session successfully(ctx={has_inc_active_num:false, tenant_id:1001, sessid:3222107046, proxy_sessid:783989401821858485}) observer.log.20240417175120154:[2024-04-17 17:45:30.046817] INFO [SERVER] obmp_connect.cpp:374 [1716714][0][Y0-0000000000000000-0-0] [lt=6] [dc=0] MySQL LOGIN(direct_client_ip="10.225.74.53", client_ip=10.225.75.52, tenant_name=yxdb, tenant_id=1001, user_name=GOMP, host_name=xxx.xxx.xxx.xxx, sessid=3222107046, proxy_sessid=783989401821858485, sess_create_time=0, from_proxy=true, from_java_client=false, capability=683647754, proxy_capability=2631, use_ssl=false, c/s protocol="OB_MYSQL_CS_TYPE", proc_ret=-4012, ret=0)可以发现登录失败的直接原因为:
observer.log.20240417175120154:[2024-04-17 17:45:30.046634] INFO [SERVER] ob_inner_sql_connection.cpp:718 [1716714][0][XXXXXXXXXXX-XXXXXXXXXXXXXXXXX-0-0] [lt=9] [dc=0] slow inner sql(last_ret=-4012, sql={ObIExecutor:, sql:"SELECT MAX(schema_version) as version, host_ip() as myip, rpc_port() as myport FROM __all_ddl_operation"}, process_time=30041160)如上日志的意思是有一条 inner sql(内部 SQL)执行到达 30s 超时(30s 是内部 SQL 默认的超时时间),SQL 需要查询
__all_ddl_operation,此 SQL 是业务租户登录时必须要查询的一条内部 SQL,属于登录的必经路径,此 SQL 查询失败登录就会失败。为了找到此 SQL 超时的原因,还需要根据 trace_id 进行过滤。
grep "YB420AE14C24-0006040F2A4D2B0C-0-0" observer.log*|less可以看到如下日志,此日志记录了此表 __all_ddl_operation 的 leader 信息,其中可以看到
{server:"xxx.xxx.xxx.41:2882", role:1,即 observer 发现__all_ddl_operation的 leader 在 hang 的节点上,因为 leader 所在节点已经 hang 了,sql 查询肯定会超时。[2024-04-17 17:45:30.045521] INFO [SHARE.PT] ob_partition_location_cache.cpp:3354 [1716714][0][XXXXXXXXXXX-XXXXXXXXXXXXXXXXX-0-0] [lt=4] [dc=0] add_update_task success(task={table_id:{value:1100611139403781, first:1001, second:5}, partition_id:0, add_timestamp:1713347130045498, cluster_id:1687678324, type:0}, leader_inactive_async_update=true, now=1713347130045498, location={table_id:{value:1100611139403781, first:1001, second:5}, partition_id:0, partition_cnt:0, pg_key:{tid:18446744073709551615, partition_id:-1, part_idx:268435455, subpart_idx:268435455}, replica_locations:[{server:"xx.xx.xx.36:2882", role:2, sql_port:2881, replica_type:0, reserved:0, property:{memstore_percent_:100}}, {server:"xxx.xxx.xxx.41:2882", role:1, sql_port:2881, replica_type:0, reserved:0, property:{memstore_percent_:100}}, {server:"xxx.xxx.xxx.44:2882", role:2, sql_port:2881, replica_type:0, reserved:0, property:{memstore_percent_:100}}], renew_time:1713347130006061, sql_renew_time:1713347130006061, is_mark_fail:false}, is_nonblock=true)所以登录失败的原因是此租户的表的 leader 还在 hang 的节点上。
问题的风险及影响
当发生 leader 节点的主机 hang 时,业务租户会立即不可用。sys 租户的租户 cpu 可能会达到 100%,其他租户在一段时间后也可能不可用。
影响的版本
OceanBase 数据库 V2.x、V3.x、V4.x 版本。
影响的租户
OceanBase 数据库的 SYS 租户、MySQL 租户、Oracle 租户。
解决方法及规避方式
立即将 hang 的节点重启或将 observer 进程杀掉;
立即将此 server 进行隔离:
alter system stop server 'xxx.xxx.xxx.xxx:2882';立即将此 server 上的 leader 都手动切换到其他节点上:
alter tenant xxx set primary_zone='zoneX';