OceanBase 数据库中执行 SQL 语句 select dbms_utility.port_string() from dual；卡住的原因和解决方法

问题现象

ARM 平台下，ODC 链接 OceanBase 数据库中的 oracle 租户卡住，黑屏 2881 测试连接 Oracle 租户正常，但执行 SQL 语句 select dbms_utility.port_string() from dual; 也卡住无法返回结果。

关键信息

1. 根据 sqlaudit 过滤 trace_id，因为执行不出结果，中断执行了，并没有什么异常。

   grep 'xxxxx-xxxxx-xxxxx-xxxxx' observer*
   

   输出结果如下：

   observer.log.20240612150648587:[2024-06-12 15:06:14.865347] INFO  [SQL.SESSION] kill_query (ob_sql_session_info.cpp:1815) [654124][T1004_L0_G0][T1004][xxxxx-xxxxx-xxxxx-xxxxx] [lt=8] kill query(get_sessid()=3221678447, get_proxy_sessid()=0, get_current_query_string()=select dbms_utility.port_string() from dual)
   observer.log.20240612150648587:[2024-06-12 15:06:14.865406] INFO  [SHARE] add_event (ob_event_history_table_operator.h:290) [654124][T1004_L0_G0][T1004][xxxxx-xxxxx-xxxxx-xxxxx] [lt=13] event table add task(ret=0, event_table_name="__all_server_event_history", sql=INSERT INTO __all_server_event_history (gmt_create, module, event, name1, value1, name2, value2, name3, value3, svr_ip, svr_port) VALUES (usec_to_time(1718175974865364), 'sql', 'execute_cmd', 'cmd_type', 71, 'sql_text', X'4B494C4C2051554552592033323231363738343437', 'return_code', 0, 'xxx.xxx.xxx.xxx', xxxx))
   observer.log.20240612150648587:[2024-06-12 15:06:15.069065] INFO  [RPC.OBMYSQL] destroy (obsm_conn_callback.cpp:243) [480741][sql_nio6][T0][Y0-0000000000000000-0-0] [lt=11] connection close(sessid=3221582093, proxy_sessid=0, tenant_id=1004, server_id=1, from_proxy=false, 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=xxxxx-xxxxx-xxxxx-xxxxx, conn.pkt_rec_wrapper_=[start_pkt_pos_:8, cur_pkt_pos_:10, pkt_rec[0]:{send:obp_mysql_header_{len_:172, seq_:3}, pkt_name:"PKT_OKP", obp_mysql_header_.is_send_:1}, pkt_rec[1]:{receive:obp20_header_:{payload_len:68, pkt_seq:0, req_id:8070137, flag_.flags:0, ext_flags:0}, obp_mysql_header_{len_:64, rec_:68, seq_:0}, obp_mysql_header_.type_:3, obp_mysql_header_.is_send_:0}, pkt_rec[2]:{send:obp_compess_header_{com_len:348, com_seq:1}, obp20_header_:{payload_len:320, pkt_seq:1, req_id:8070137, flag_.flags:11, ext_flags:0}, obp_mysql_header_{len_:84, seq_:2}, pkt_name:"PKT_RESHEAD", obp_mysql_header_.is_send_:1}, pkt_rec[3]:{send:obp_compess_header_{com_len:348, com_seq:1}, obp20_header_:{payload_len:320, pkt_seq:1, req_id:8070137, flag_.flags:11, ext_flags:0}, obp_mysql_header_{pkt_num_:2, seq_:4}, pkt_name:"PKT_FIELD", obp_mysql_header_.is_send_:1}, pkt_rec[4]:{send:obp_compess_header_{com_len:348, com_seq:1}, obp20_header_:{payload_len:320, pkt_seq:1, req_id:8070137, flag_.flags:11, ext_flags:0}, obp_mysql_header_{len_:9, seq_:5}, pkt_name:"PKT_EOF", obp_mysql_header_.is_send_:1}, pkt_rec[5]:{send:obp_compess_header_{com_len:348, com_seq:1}, obp20_header_:{payload_len:320, pkt_seq:1, req_id:8070137, flag_.flags:11, ext_flags:0}, obp_mysql_header_{pkt_num_:1, seq_:6}, pkt_name:"PKT_ROW", obp_mysql_header_.is_send_:1}, pkt_rec[6]:{send:obp_compess_header_{com_len:348, com_seq:1}, obp20_header_:{payload_len:320, pkt_seq:1, req_id:8070137, flag_.flags:11, ext_flags:0}, obp_mysql_header_{len_:9, seq_:7}, pkt_name:"PKT_EOF", obp_mysql_header_.is_send_:1}, pkt_rec[7]:{receive:obp20_header_:{payload_len:26, pkt_seq:0, req_id:8070138, flag_.flags:2, ext_flags:0}, obp_mysql_header_{len_:22, rec_:26, seq_:0}, obp_mysql_header_.type_:3, obp_mysql_header_.is_send_:0}, pkt_rec[8]:{send:obp_compess_header_{com_len:81, com_seq:1}, obp20_header_:{payload_len:53, pkt_seq:1, req_id:8070138, flag_.flags:10, ext_flags:0}, obp_mysql_header_{len_:53, seq_:2}, pkt_name:"PKT_OKP", obp_mysql_header_.is_send_:1}, pkt_rec[9]:{receive:obp20_header_:{payload_len:5, pkt_seq:0, req_id:8070139, flag_.flags:2, ext_flags:0}, obp_mysql_header_{len_:1, rec_:5, seq_:0}, obp_mysql_header_.type_:1, obp_mysql_header_.is_send_:0}], disconnect_state=3
   

2. 当时会有很多 ODC 在链接，看下问题发生时有无异常 ERROR，打印了非常多的 4013 内存报错信息。

   grep 'ERROR' observer*
   

   输出结果如下：

   observer.log.20240612150222369:[2024-06-12 14:59:45.746707] ERROR issue_dba_error (ob_log.cpp:1868) [2119604][T1039_L0_G0][T1039][xxxxx-xxxxx-xxxxx-xxxxx] [lt=22][errcode=-4388] Unexpected internal error happen, please checkout the internal errcode(errcode=-4013, file="ob_jit_allocator.cpp", line_no=116, info="allocate jit memory failed")
   observer.log.20240612150222369:[2024-06-12 14:59:46.018755] ERROR issue_dba_error (ob_log.cpp:1868) [887243][T1034_L0_G0][T1034][xxxxx-xxxxx-xxxxx-xxxxx] [lt=11][errcode=-4388] Unexpected internal error happen, please checkout the internal errcode(errcode=-4070, file="obmp_stmt_execute.cpp", line_no=2273, info="decode varchar param value failed")
   observer.log.20240612150222369:[2024-06-12 14:59:48.486747] ERROR issue_dba_error (ob_log.cpp:1868) [887243][T1034_L0_G0][T1034][xxxxx-xxxxx-xxxxx-xxxxx] [lt=24][errcode=-4388] Unexpected internal error happen, please checkout the internal errcode(errcode=-4070, file="obmp_stmt_execute.cpp", line_no=2273, info="decode varchar param value failed")
   observer.log.20240612150222369:[2024-06-12 14:59:51.286955] ERROR issue_dba_error (ob_log.cpp:1868) [887243][T1034_L0_G0][T1034][xxxxx-xxxxx-xxxxx-xxxxx] [lt=5][errcode=-4388] Unexpected internal error happen, please checkout the internal errcode(errcode=-4070, file="obmp_stmt_execute.cpp", line_no=2273, info="decode varchar param value failed")
   observer.log.20240612150222369:[2024-06-12 14:59:55.758649] ERROR issue_dba_error (ob_log.cpp:1868) [2119604][T1039_L0_G0][T1039][xxxxx-xxxxx-xxxxx-xxxxx] [lt=24][errcode=-4388] Unexpected internal error happen, please checkout the internal errcode(errcode=-4013, file="ob_jit_allocator.cpp", line_no=116, info="allocate jit memory failed")
   observer.log.20240612150222369:[2024-06-12 15:00:05.770928] ERROR issue_dba_error (ob_log.cpp:1868) [2119604][T1039_L0_G0][T1039][xxxxx-xxxxx-xxxxx-xxxxx] [lt=24][errcode=-4388] Unexpected internal error happen, please checkout the internal errcode(errcode=-4013, file="ob_jit_allocator.cpp", line_no=116, info="allocate jit memory failed")
   observer.log.20240612150222369:[2024-06-12 15:00:15.782816] ERROR issue_dba_error (ob_log.cpp:1868) [2119604][T1039_L0_G0][T1039][xxxxx-xxxxx-xxxxx-xxxxx] [lt=23][errcode=-4388] Unexpected internal error happen, please checkout the internal errcode(errcode=-4013, file="ob_jit_allocator.cpp", line_no=116, info="allocate jit memory failed")
   observer.log.20240612150222369:[2024-06-12 15:00:25.794672] ERROR issue_dba_error (ob_log.cpp:1868) [2119604][T1039_L0_G0][T1039][xxxxx-xxxxx-xxxxx-xxxxx] [lt=21][errcode=-4388] Unexpected internal error happen, please checkout the internal errcode(errcode=-4013, file="ob_jit_allocator.cpp", line_no=116, info="allocate jit memory failed")
   observer.log.20240612150222369:[2024-06-12 15:00:35.806378] ERROR issue_dba_error (ob_log.cpp:1868) [2119604][T1039_L0_G0][T1039][xxxxx-xxxxx-xxxxx-xxxxx] [lt=19][errcode=-4388] Unexpected internal error happen, please checkout the internal errcode(errcode=-4013, file="ob_jit_allocator.cpp", line_no=116, info="allocate jit memory failed")
   observer.log.20240612150222369:[2024-06-12 15:00:45.818412] ERROR issue_dba_error (ob_log.cpp:1868) [2119604][T1039_L0_G0][T1039][xxxxx-xxxxx-xxxxx-xxxxx] [lt=24][errcode=-4388] Unexpected internal error happen, please checkout the internal errcode(errcode=-4013, file="ob_jit_allocator.cpp", line_no=116, info="allocate jit memory failed")
   observer.log.20240612150222369:[2024-06-12 15:00:46.709147] ERROR issue_dba_error (ob_log.cpp:1868) [2169377][T1034_L0_G0][T1034]
   

3. 查看一直在循环打印获取内存的信息，这个 trace_id 同时出现问题租户上，也是同一个时间，block alloc over limit 表示获取的内存超限制了，而 allocate jit memory failed 表示获取不到内存。

   observer.log.20240612150222369:[2024-06-12 15:00:14.881710] INFO  [SQL.CG] allocate_mapped_memory (ob_jit_allocator.cpp:125) [2119604][T1039_L0_G0][T1039][xxxxx-xxxxx-xxxxx-xxxxx] [lt=24] aarch64 memory allocated not safe, try again(addr=0xffeeffff0000, start=281406257102847, page_size=65536, num_pages=1)
   observer.log.20240612150222369:[2024-06-12 15:00:14.981829] INFO  [SQL.CG] allocate_mapped_memory (ob_jit_allocator.cpp:125) [2119604][T1039_L0_G0][T1039][xxxxx-xxxxx-xxxxx-xxxxx] [lt=21] aarch64 memory allocated not safe, try again(addr=0xffeeffff0000, start=281406257102847, page_size=65536, num_pages=1)
   observer.log.20240612150222369:[2024-06-12 15:00:15.021466] WDIAG [SERVER] record_request (ob_mysql_request_manager.cpp:177) [480565][DBMS_SCHEDULER][T1043][xxxxx-xxxxx-xxxxx-xxxxx] [lt=6][errcode=0] record concurrent fifoallocator alloc mem failed(total_size=1535, tenant_id_=1043, mem_limit_=128849018, request_id_=0, ret=0)
   observer.log.20240612150222369:[2024-06-12 15:00:15.057870] WDIAG alloc_block (ob_block_alloc_mgr.h:40) [480565][DBMS_SCHEDULER][T1053][xxxxx-xxxxx-xxxxx-xxxxx] [lt=6][errcode=-4016] block alloc over limit, limit=38654705 alloc_size=2079744
   observer.log.20240612150222369:[2024-06-12 15:00:15.081951] INFO  [SQL.CG] allocate_mapped_memory (ob_jit_allocator.cpp:125) [2119604][T1039_L0_G0][T1039][xxxxx-xxxxx-xxxxx-xxxxx] [lt=21] aarch64 memory allocated not safe, try again(addr=0xffeeffff0000, start=281406257102847, page_size=65536, num_pages=1)
   observer.log.20240612150222369:[2024-06-12 15:00:15.182068] INFO  [SQL.CG] allocate_mapped_memory (ob_jit_allocator.cpp:125) [2119604][T1039_L0_G0][T1039][xxxxx-xxxxx-xxxxx-xxxxx] [lt=19] aarch64 memory allocated not safe, try again(addr=0xffeeffff0000, start=281406257102847, page_size=65536, num_pages=1)
   observer.log.20240612150222369:[2024-06-12 15:00:15.282189] INFO  [SQL.CG] allocate_mapped_memory (ob_jit_allocator.cpp:125) [2119604][T1039_L0_G0][T1039][xxxxx-xxxxx-xxxxx-xxxxx] [lt=18] aarch64 memory allocated not safe, try again(addr=0xffeeffff0000, start=281406257102847, page_size=65536, num_pages=1)
   observer.log.20240612150222369:[2024-06-12 15:00:15.382311] INFO  [SQL.CG] allocate_mapped_memory (ob_jit_allocator.cpp:125) [2119604][T1039_L0_G0][T1039][xxxxx-xxxxx-xxxxx-xxxxx] [lt=22] aarch64 memory allocated not safe, try again(addr=0xffeeffff0000, start=281406257102847, page_size=65536, num_pages=1)
   observer.log.20240612150222369:[2024-06-12 15:00:15.482432] INFO  [SQL.CG] allocate_mapped_memory (ob_jit_allocator.cpp:125) [2119604][T1039_L0_G0][T1039][xxxxx-xxxxx-xxxxx-xxxxx] [lt=21] aarch64 memory allocated not safe, try again(addr=0xffeeffff0000, start=281406257102847, page_size=65536, num_pages=1)
   observer.log.20240612150222369:[2024-06-12 15:00:15.582548] INFO  [SQL.CG] allocate_mapped_memory (ob_jit_allocator.cpp:125) [2119604][T1039_L0_G0][T1039][xxxxx-xxxxx-xxxxx-xxxxx] [lt=22] aarch64 memory allocated not safe, try again(addr=0xffeeffff0000, start=281406257102847, page_size=65536, num_pages=1)
   observer.log.20240612150222369:[2024-06-12 15:00:15.682661] INFO  [SQL.CG] allocate_mapped_memory (ob_jit_allocator.cpp:125) [2119604][T1039_L0_G0][T1039][xxxxx-xxxxx-xxxxx-xxxxx] [lt=17] aarch64 memory allocated not safe, try again(addr=0xffeeffff0000, start=281406257102847, page_size=65536, num_pages=1)
   observer.log.20240612150222369:[2024-06-12 15:00:15.782776] INFO  [SQL.CG] allocate_mapped_memory (ob_jit_allocator.cpp:125) [2119604][T1039_L0_G0][T1039][xxxxx-xxxxx-xxxxx-xxxxx] [lt=20] aarch64 memory allocated not safe, try again(addr=0xffeeffff0000, start=281406257102847, page_size=65536, num_pages=1)
   observer.log.20240612150222369:[2024-06-12 15:00:15.782816] ERROR issue_dba_error (ob_log.cpp:1868) [2119604][T1039_L0_G0][T1039][xxxxx-xxxxx-xxxxx-xxxxx] [lt=23][errcode=-4388] Unexpected internal error happen, please checkout the internal errcode(errcode=-4013, file="ob_jit_allocator.cpp", line_no=116, info="allocate jit memory failed")
   observer.log.20240612150222369:[2024-06-12 15:00:15.782831] EDIAG [SQL.CG] allocate_mapped_memory (ob_jit_allocator.cpp:116) [2119604][T1039_L0_G0][T1039][xxxxx-xxxxx-xxxxx-xxxxx] [lt=15][errcode=-4013] allocate jit memory failed(addr=0xffeeffff0000, num_bytes=925, page_size=65536, num_pages=1) BACKTRACE:0x10ce9450 0x5f8fe60 0x5f8fa24 0x5f8f6c0 0x5f8f4c0 0x10bbaa94 0x10bba8f4 0x10bbb8f0 0x538f9f4 0x53a19a4 0x538a904 0x10bb9710 0x10bba578 0x10bb72e4 0x10bb700c 0x10b9a2d0 0x68b9b04 0x68b8354 0x68ac200 0x68db678 0x68fa42c 0x6789fc0 0x6767ca4 0xa752704 0xa532588 0xb0dde90 0xafdb9cc 0xafd97dc 0xb224230 0xb223c74 0xb22270c 0xb2deb40 0x8c7bef4 0xb251884 0x8c7bc40 0xb182d40 0x854ef80 0x85525e4 0x8565554 0xb26c9cc 0xaf33c1c 0xaf2dbec 0x893a63c 0x112b0768 0xffff0e5a878c 0xffff0e4f50dc
   observer.log.20240612150222369:[2024-06-12 15:00:15.883022] INFO  [SQL.CG] allocate_mapped_memory (ob_jit_allocator.cpp:125) [2119604][T1039_L0_G0][T1039][xxxxx-xxxxx-xxxxx-xxxxx] [lt=107]  REACH SYSLOG RATE LIMIT [bandwidth]
   observer.log.20240612150222369:[2024-06-12 15:00:15.983142] INFO  [SQL.CG] allocate_mapped_memory (ob_jit_allocator.cpp:125) [2119604][T1039_L0_G0][T1039][xxxxx-xxxxx-xxxxx-xxxxx] [lt=20] aarch64 memory allocated not safe, try again(addr=0xffeeffff0000, start=281406257102847, page_size=65536, num_pages=1)
   observer.log.20240612150222369:[2024-06-12 15:00:16.083264] INFO  [SQL.CG] allocate_mapped_memory (ob_jit_allocator.cpp:125) [2119604][T1039_L0_G0][T1039][xxxxx-xxxxx-xxxxx-xxxxx] [lt=21] aarch64 memory allocated not safe, try again(addr=0xffeeffff0000, start=281406257102847, page_size=65536, num_pages=1)
   observer.log.20240612150222369:[2024-06-12 15:00:16.183386] INFO  [SQL.CG] allocate_mapped_memory (ob_jit_allocator.cpp:125) [2119604][T1039_L0_G0][T1039][xxxxx-xxxxx-xxxxx-xxxxx] [lt=20] aarch64 memory allocated not safe, try again(addr=0xffeeffff0000, start=281406257102847, page_size=65536, num_pages=1)
   observer.log.20240612150222369:[2024-06-12 15:00:16.283514] INFO  [SQL.CG] allocate_mapped_memory (ob_jit_allocator.cpp:125) [2119604][T1039_L0_G0][T1039][xxxxx-xxxxx-xxxxx-xxxxx] [lt=19] aarch64 memory allocated not safe, try again(addr=0xffeeffff0000, start=281406257102847, page_size=65536, num_pages=1)
   

4. 在执行 SQL 卡住的节点上采集 obstack 信息，更能清晰的看到执行的 SQL 卡在内存上。

   ##-- 获取到 OBServer 进程的 pid。
   ps -ef | grep observer 
   ## -- 定位 OBServer 的热点线程栈，利用 obstack 的快速聚集选项 -ao 来捕获热点线程栈。
   obstack obpid -ao  > obstack_ao.trc
   

问题原因

ODC 失败的原因是 ODC 在创建链接的时候会去执行 select dbms_utility.port_string() from dual;，这个 SQL 卡住无法返回结果，ODC 就表现为卡住。

在 ARM 平台下，问题 SQL 涉及 PL 编译，如果分配内存跨越了 4G 边界，会有 core 掉的风险，所以遇到这种情况会重新分配内存。本 case 每次分配结果地址恰好一样，还是跨越了4G边界，就导致循环分配，现象就是问题 SQL 卡着无法返回结果。

问题的风险及影响

执行问题 SQL 卡着。

影响租户

影响 OceanBase 数据库中的 SYS 租户和 Oracle 租户以及 MySQL 租户。

适用版本

OceanBase 数据库 V4.2.1 BP8（oceanbase-4.2.1.8-108000052024072217）之前的版本。

解决方法

• 升级至问题已修复版本。目前已修复的版本包括 V4.2.1 BP8（oceanbase-4.2.1.8-108000052024072217）及之后版本。

• 应急重启问题节点 OBServer。