出现4016报错

liolay · 2023 年12 月 20 日 13:01

【使用环境】测试环境
【 OB or 其他组件】OCP,OceanBase
【使用版本】4.2.1
【问题描述】
OBServer 程序日志] 集群：xnzn，主机：172.16.24.163，日志类型：observer，日志文件：/home/admin/oceanbase/log/observer.log，日志级别：ERROR，关键字=，错误码=4388，日志详情=[2023-12-20 00:26:48.828573] ERROR issue_dba_error (ob_log.cpp:1866) [58469][RpcIO][T0][Y0-0000000000000000-0-0] [lt=7][errcode=-4388] Unexpected internal error happen, please checkout the internal errcode(errcode=-4016, file=“ob_rpc_protocol_processor.cpp”, line_no=242, info=“invalid mflag”) 」

【复现路径】未做任何操作
【附件及日志】[2023-12-20 12:58:13.973278] WDIAG [SQL.SESSION] get_cursor (ob_sql_session_info.cpp:1350) [61153][T1004_L0_G0][T1004][YB42AC1018A3-00060AB6EDFACB3F-0-0] [lt=23][errcode=-4016] get cursor info failed(cursor_id=1, get_sessid()=3221684341)
[2023-12-20 12:58:13.979285] WDIAG get_refactored (ob_hashtable.h:1100) [61153][T1004_L0_G0][T1004][YB42AC1018A3-00060AB6EDFACB41-0-0] [lt=7][errcode=-4201] hashtable not init

[2023-12-20 12:58:14.692644] WDIAG alloc_block (ob_block_alloc_mgr.h:40) [60956][T1004_TeRec][T1003][YB42AC1018A3-00060AB6ED273EC7-0-0] [lt=18][errcode=-4016] block alloc over limit, limit=51539607 alloc_size=2079744
[2023-12-20 12:58:14.692658] WDIAG [SERVER] record_request (ob_mysql_request_manager.cpp:177) [60956][T1004_TeRec][T1003][YB42AC1018A3-00060AB6ED273EC7-0-0] [lt=13][errcode=0] record concurrent fifoallocator alloc mem failed(total_size=1449, tenant_id_=1003, mem_limit_=171798691, request_id_=0, ret=0)

其灵 · 2023 年12 月 20 日 14:19

麻烦提供下observer的commit id，可以通过以下命令查看：
./observer -V
以及提供下相关的observer.log日志，可以先通过 invalid mflag 搜索，找到报错日志的TRACE ID，然后根据TRACE ID 把相关日志grep出来，我们会找技术人员分析。
描述一下大概的用法和测试场景，使用的sql等信息，有助于我们排查问题。

liolay · 2023 年12 月 20 日 14:24

顺便说下, 刚才又发生了, 代码执行一个查询, 50%的概率出现4016问题, 但通过navicat客户端没有出现过
sql如附件
E1A6AB6C-8EE3-4414-9F80-3974F91C5518.txt (12.1 KB)

秃蛙 · 2023 年12 月 20 日 14:41

附上用户侧日志：
程序报错信息

相关trace对应的observer.log日志

[root@iZ0jl8e9o1v93gfsk9cuxcZ opt]# grep "YB42AC1018A3-00060AB6EDFB50B1"  observer.log 
[2023-12-20 14:05:09.756513] WDIAG [SQL.RESV] resolve_table_column_ref (ob_select_resolver.cpp:4921) [61153][T1004_L0_G0][T1004][YB42AC1018A3-00060AB6EDFB50B1-0-0] [lt=15][errcode=-5217] resolve table column expr failed(ret=-5217, q_name={database_name:"", table_name:"", column:"canteen_stall_id", dblink_name:"", is_star:false, ref_expr:{item_type:"T_REF_COLUMN", result_type:{meta:{type:"", collation:"binary", coercibility:"NUMERIC"}, accuracy:{length:-1, precision:-1, scale:-1}, flag:0, calc_type:{type:"NULL", collation:"invalid_type", coercibility:"INVALID"}}, expr_info:["IS_COLUMN", "CNT_COLUMN"], rel_id:[], table_id:18446744073709551615, column_id:18446744073709551615, database_name:"", table_name:"", synonym_name:"", synonym_db_name:"", column_name:"", column_flags:0, enum_set_values:[], is_lob_column:false, is_joined_dup_column:false, is_unpivot_mocked_column:false, is_hidden:false, from_alias_table:false, is_rowkey_column:false, is_unique_key_column:false, is_mul_key_column:false, is_strict_json_column:0, srs_id:18446744073709551615, udt_set_id:0}, parents_expr_info:[], parent_aggr_level:-1, access_idents:[{access_name:"canteen_stall_id", access_index:-1, type:-1, params:[]}], current_resolve_level:0, is_access_root:true}, lbt()="0x1143006c 0xacc53e3 0xacc530f 0xacc37f9 0xacc461c 0xab2ef29 0xaa9fc17 0xacb7c20 0xac95b6a 0xac89098 0xac9bff0 0xabee686 0xab658fd 0xab64ec1 0xab0f862 0xab53896 0xab0f71e 0xac8b326 0xac89001 0xac9bff0 0xabee686 0xab658fd 0xab64ec1 0xab0f862 0xac8b326 0xac89001 0xac9bff0 0xabee686 0xab658fd 0xab64ec1 0xab0f862 0xac8b326 0xac89001 0xac9bff0 0xc0cf9be 0x4b9441d 0x4b8b976 0x4b89dcc 0x4b85139 0xc778b35 0xc776b38 0x944c267 0x945339a 0x945738d 0x48b318b 0x48ae61b 0x92f7094 0x116e68cf 0x7fa6035b53fb 0x7fa603061e83")
[2023-12-20 14:05:09.756582] WDIAG [SQL.RESV] resolve_table_column_ref (ob_select_resolver.cpp:4921) [61153][T1004_L0_G0][T1004][YB42AC1018A3-00060AB6EDFB50B1-0-0] [lt=44][errcode=-5217] resolve table column expr failed(ret=-5217, q_name={database_name:"", table_name:"", column:"canteen_stall_name", dblink_name:"", is_star:false, ref_expr:{item_type:"T_REF_COLUMN", result_type:{meta:{type:"", collation:"binary", coercibility:"NUMERIC"}, accuracy:{length:-1, precision:-1, scale:-1}, flag:0, calc_type:{type:"NULL", collation:"invalid_type", coercibility:"INVALID"}}, expr_info:["IS_COLUMN", "CNT_COLUMN"], rel_id:[], table_id:18446744073709551615, column_id:18446744073709551615, database_name:"", table_name:"", synonym_name:"", synonym_db_name:"", column_name:"", column_flags:0, enum_set_values:[], is_lob_column:false, is_joined_dup_column:false, is_unpivot_mocked_column:false, is_hidden:false, from_alias_table:false, is_rowkey_column:false, is_unique_key_column:false, is_mul_key_column:false, is_strict_json_column:0, srs_id:18446744073709551615, udt_set_id:0}, parents_expr_info:[], parent_aggr_level:-1, access_idents:[{access_name:"canteen_stall_name", access_index:-1, type:-1, params:[]}], current_resolve_level:0, is_access_root:true}, lbt()="0x1143006c 0xacc53e3 0xacc530f 0xacc37f9 0xacc461c 0xab2ef29 0xaa9fc17 0xacb7c20 0xac95b6a 0xac89098 0xac9bff0 0xabee686 0xab658fd 0xab64ec1 0xab0f862 0xab53896 0xab0f71e 0xac8b326 0xac89001 0xac9bff0 0xabee686 0xab658fd 0xab64ec1 0xab0f862 0xac8b326 0xac89001 0xac9bff0 0xabee686 0xab658fd 0xab64ec1 0xab0f862 0xac8b326 0xac89001 0xac9bff0 0xc0cf9be 0x4b9441d 0x4b8b976 0x4b89dcc 0x4b85139 0xc778b35 0xc776b38 0x944c267 0x945339a 0x945738d 0x48b318b 0x48ae61b 0x92f7094 0x116e68cf 0x7fa6035b53fb 0x7fa603061e83")
[2023-12-20 14:05:09.757161] WDIAG [SQL.RESV] resolve_table_column_ref (ob_select_resolver.cpp:4921) [61153][T1004_L0_G0][T1004][YB42AC1018A3-00060AB6EDFB50B1-0-0] [lt=26][errcode=-5217] resolve table column expr failed(ret=-5217, q_name={database_name:"", table_name:"", column:"canteen_stall_id", dblink_name:"", is_star:false, ref_expr:{item_type:"T_REF_COLUMN", result_type:{meta:{type:"", collation:"binary", coercibility:"NUMERIC"}, accuracy:{length:-1, precision:-1, scale:-1}, flag:0, calc_type:{type:"NULL", collation:"invalid_type", coercibility:"INVALID"}}, expr_info:["IS_COLUMN", "CNT_COLUMN"], rel_id:[], table_id:18446744073709551615, column_id:18446744073709551615, database_name:"", table_name:"", synonym_name:"", synonym_db_name:"", column_name:"", column_flags:0, enum_set_values:[], is_lob_column:false, is_joined_dup_column:false, is_unpivot_mocked_column:false, is_hidden:false, from_alias_table:false, is_rowkey_column:false, is_unique_key_column:false, is_mul_key_column:false, is_strict_json_column:0, srs_id:18446744073709551615, udt_set_id:0}, parents_expr_info:[], parent_aggr_level:-1, access_idents:[{access_name:"canteen_stall_id", access_index:-1, type:-1, params:[]}], current_resolve_level:0, is_access_root:true}, lbt()="0x1143006c 0xacc53e3 0xacc530f 0xacc37f9 0xacc461c 0xab2ef29 0xaa9fc17 0xacb7c20 0xac95b6a 0xac89098 0xac9bff0 0xabee686 0xab658fd 0xab64ec1 0xab0f862 0xab53896 0xab0f71e 0xac8b326 0xac89001 0xac9bff0 0xabee686 0xab658fd 0xab64ec1 0xab0f862 0xac8b326 0xac89001 0xac9bff0 0xabee686 0xab658fd 0xab64ec1 0xab0f862 0xac8b326 0xac89001 0xac9bff0 0xc0cf9be 0x4b9441d 0x4b8b976 0x4b89dcc 0x4b85139 0xc778b35 0xc776b38 0x944c267 0x945339a 0x945738d 0x48b318b 0x48ae61b 0x92f7094 0x116e68cf 0x7fa6035b53fb 0x7fa603061e83")
[2023-12-20 14:05:09.757221] WDIAG [SQL.RESV] resolve_table_column_ref (ob_select_resolver.cpp:4921) [61153][T1004_L0_G0][T1004][YB42AC1018A3-00060AB6EDFB50B1-0-0] [lt=29][errcode=-5217] resolve table column expr failed(ret=-5217, q_name={database_name:"", table_name:"", column:"canteen_stall_name", dblink_name:"", is_star:false, ref_expr:{item_type:"T_REF_COLUMN", result_type:{meta:{type:"", collation:"binary", coercibility:"NUMERIC"}, accuracy:{length:-1, precision:-1, scale:-1}, flag:0, calc_type:{type:"NULL", collation:"invalid_type", coercibility:"INVALID"}}, expr_info:["IS_COLUMN", "CNT_COLUMN"], rel_id:[], table_id:18446744073709551615, column_id:18446744073709551615, database_name:"", table_name:"", synonym_name:"", synonym_db_name:"", column_name:"", column_flags:0, enum_set_values:[], is_lob_column:false, is_joined_dup_column:false, is_unpivot_mocked_column:false, is_hidden:false, from_alias_table:false, is_rowkey_column:false, is_unique_key_column:false, is_mul_key_column:false, is_strict_json_column:0, srs_id:18446744073709551615, udt_set_id:0}, parents_expr_info:[], parent_aggr_level:-1, access_idents:[{access_name:"canteen_stall_name", access_index:-1, type:-1, params:[]}], current_resolve_level:0, is_access_root:true}, lbt()="0x1143006c 0xacc53e3 0xacc530f 0xacc37f9 0xacc461c 0xab2ef29 0xaa9fc17 0xacb7c20 0xac95b6a 0xac89098 0xac9bff0 0xabee686 0xab658fd 0xab64ec1 0xab0f862 0xab53896 0xab0f71e 0xac8b326 0xac89001 0xac9bff0 0xabee686 0xab658fd 0xab64ec1 0xab0f862 0xac8b326 0xac89001 0xac9bff0 0xabee686 0xab658fd 0xab64ec1 0xab0f862 0xac8b326 0xac89001 0xac9bff0 0xc0cf9be 0x4b9441d 0x4b8b976 0x4b89dcc 0x4b85139 0xc778b35 0xc776b38 0x944c267 0x945339a 0x945738d 0x48b318b 0x48ae61b 0x92f7094 0x116e68cf 0x7fa6035b53fb 0x7fa603061e83")
[2023-12-20 14:05:09.757616] WDIAG [SQL.RESV] get_table_schema (ob_schema_checker.cpp:850) [61153][T1004_L0_G0][T1004][YB42AC1018A3-00060AB6EDFB50B1-0-0] [lt=20][errcode=-4002] invalid arguments(table_id=18446744073709551615, ret=-4002, lbt()="0x1143006c 0xc152059 0xc133295 0xaab3c80 0xab5ff9f 0xaaa5796 0xacc51cb 0xacc37f9 0xacc461c 0xab2ef29 0xaa9fc17 0xac90023 0xac89913 0xac9bff0 0xabee686 0xab658fd 0xab64ec1 0xab0f862 0xac8b326 0xac89001 0xac9bff0 0xc0cf9be 0x4b9441d 0x4b8b976 0x4b89dcc 0x4b85139 0xc778b35 0xc776b38 0x944c267 0x945339a 0x945738d 0x48b318b 0x48ae61b 0x92f7094 0x116e68cf 0x7fa6035b53fb 0x7fa603061e83")
[2023-12-20 14:05:09.757657] WDIAG [SQL.RESV] get_table_schema (ob_schema_checker.cpp:850) [61153][T1004_L0_G0][T1004][YB42AC1018A3-00060AB6EDFB50B1-0-0] [lt=11][errcode=-4002] invalid arguments(table_id=18446744073709551615, ret=-4002, lbt()="0x1143006c 0xc152059 0xc133295 0xaab3c80 0xab5ff9f 0xaaa5796 0xacc51cb 0xacc37f9 0xacc461c 0xab2ef29 0xaa9fc17 0xac90023 0xac89913 0xac9bff0 0xabee686 0xab658fd 0xab64ec1 0xab0f862 0xac8b326 0xac89001 0xac9bff0 0xc0cf9be 0x4b9441d 0x4b8b976 0x4b89dcc 0x4b85139 0xc778b35 0xc776b38 0x944c267 0x945339a 0x945738d 0x48b318b 0x48ae61b 0x92f7094 0x116e68cf 0x7fa6035b53fb 0x7fa603061e83")
[2023-12-20 14:05:09.757699] WDIAG [SQL.RESV] get_table_schema (ob_schema_checker.cpp:850) [61153][T1004_L0_G0][T1004][YB42AC1018A3-00060AB6EDFB50B1-0-0] [lt=10][errcode=-4002] invalid arguments(table_id=18446744073709551615, ret=-4002, lbt()="0x1143006c 0xc152059 0xc133295 0xaab3c80 0xab5ff9f 0xaaa5796 0xacc51cb 0xacc37f9 0xacc461c 0xab2ef29 0xaa9fc17 0xac90023 0xac89913 0xac9bff0 0xabee686 0xab658fd 0xab64ec1 0xab0f862 0xac8b326 0xac89001 0xac9bff0 0xc0cf9be 0x4b9441d 0x4b8b976 0x4b89dcc 0x4b85139 0xc778b35 0xc776b38 0x944c267 0x945339a 0x945738d 0x48b318b 0x48ae61b 0x92f7094 0x116e68cf 0x7fa6035b53fb 0x7fa603061e83")
[2023-12-20 14:05:09.757737] WDIAG [SQL.RESV] get_table_schema (ob_schema_checker.cpp:850) [61153][T1004_L0_G0][T1004][YB42AC1018A3-00060AB6EDFB50B1-0-0] [lt=9][errcode=-4002] invalid arguments(table_id=18446744073709551615, ret=-4002, lbt()="0x1143006c 0xc152059 0xc133295 0xaab3c80 0xab5ff9f 0xaaa5796 0xacc51cb 0xacc37f9 0xacc461c 0xab2ef29 0xaa9fc17 0xac90023 0xac89913 0xac9bff0 0xabee686 0xab658fd 0xab64ec1 0xab0f862 0xac8b326 0xac89001 0xac9bff0 0xc0cf9be 0x4b9441d 0x4b8b976 0x4b89dcc 0x4b85139 0xc778b35 0xc776b38 0x944c267 0x945339a 0x945738d 0x48b318b 0x48ae61b 0x92f7094 0x116e68cf 0x7fa6035b53fb 0x7fa603061e83")
[2023-12-20 14:05:09.757758] WDIAG [SQL.RESV] get_table_schema (ob_schema_checker.cpp:850) [61153][T1004_L0_G0][T1004][YB42AC1018A3-00060AB6EDFB50B1-0-0] [lt=9][errcode=-4002] invalid arguments(table_id=18446744073709551615, ret=-4002, lbt()="0x1143006c 0xc152059 0xc133295 0xaab3c80 0xab5ff9f 0xaaa5796 0xacc51cb 0xacc37f9 0xacc461c 0xab2ef29 0xaa9fc17 0xac90023 0xac89913 0xac9bff0 0xabee686 0xab658fd 0xab64ec1 0xab0f862 0xac8b326 0xac89001 0xac9bff0 0xc0cf9be 0x4b9441d 0x4b8b976 0x4b89dcc 0x4b85139 0xc778b35 0xc776b38 0x944c267 0x945339a 0x945738d 0x48b318b 0x48ae61b 0x92f7094 0x116e68cf 0x7fa6035b53fb 0x7fa603061e83")
[2023-12-20 14:05:09.757798] WDIAG [SQL.RESV] get_table_schema (ob_schema_checker.cpp:850) [61153][T1004_L0_G0][T1004][YB42AC1018A3-00060AB6EDFB50B1-0-0] [lt=9][errcode=-4002] invalid arguments(table_id=18446744073709551615, ret=-4002, lbt()="0x1143006c 0xc152059 0xc133295 0xaab3c80 0xab5ff9f 0xaaa5796 0xacc51cb 0xacc37f9 0xacc461c 0xab2ef29 0xaa9fc17 0xac90023 0xac89913 0xac9bff0 0xabee686 0xab658fd 0xab64ec1 0xab0f862 0xac8b326 0xac89001 0xac9bff0 0xc0cf9be 0x4b9441d 0x4b8b976 0x4b89dcc 0x4b85139 0xc778b35 0xc776b38 0x944c267 0x945339a 0x945738d 0x48b318b 0x48ae61b 0x92f7094 0x116e68cf 0x7fa6035b53fb 0x7fa603061e83")
[2023-12-20 14:05:09.757843] WDIAG [SQL.RESV] get_table_schema (ob_schema_checker.cpp:850) [61153][T1004_L0_G0][T1004][YB42AC1018A3-00060AB6EDFB50B1-0-0] [lt=11][errcode=-4002] invalid arguments(table_id=18446744073709551615, ret=-4002, lbt()="0x1143006c 0xc152059 0xc133295 0xaab3c80 0xab5ff9f 0xaaa5796 0xacc51cb 0xacc37f9 0xacc461c 0xab2ef29 0xaa9fc17 0xac90023 0xac89913 0xac9bff0 0xabee686 0xab658fd 0xab64ec1 0xab0f862 0xac8b326 0xac89001 0xac9bff0 0xc0cf9be 0x4b9441d 0x4b8b976 0x4b89dcc 0x4b85139 0xc778b35 0xc776b38 0x944c267 0x945339a 0x945738d 0x48b318b 0x48ae61b 0x92f7094 0x116e68cf 0x7fa6035b53fb 0x7fa603061e83")
[2023-12-20 14:05:09.757883] WDIAG [SQL.RESV] get_table_schema (ob_schema_checker.cpp:850) [61153][T1004_L0_G0][T1004][YB42AC1018A3-00060AB6EDFB50B1-0-0] [lt=16][errcode=-4002] invalid arguments(table_id=18446744073709551615, ret=-4002, lbt()="0x1143006c 0xc152059 0xc133295 0xaab3c80 0xab5ff9f 0xaaa5796 0xacc51cb 0xacc37f9 0xacc461c 0xab2ef29 0xaa9fc17 0xac90023 0xac89913 0xac9bff0 0xabee686 0xab658fd 0xab64ec1 0xab0f862 0xac8b326 0xac89001 0xac9bff0 0xc0cf9be 0x4b9441d 0x4b8b976 0x4b89dcc 0x4b85139 0xc778b35 0xc776b38 0x944c267 0x945339a 0x945738d 0x48b318b 0x48ae61b 0x92f7094 0x116e68cf 0x7fa6035b53fb 0x7fa603061e83")
[2023-12-20 14:05:09.757912] WDIAG [SQL.RESV] get_table_schema (ob_schema_checker.cpp:850) [61153][T1004_L0_G0][T1004][YB42AC1018A3-00060AB6EDFB50B1-0-0] [lt=7][errcode=-4002] invalid arguments(table_id=18446744073709551615, ret=-4002, lbt()="0x1143006c 0xc152059 0xc133295 0xaab3c80 0xab5ff9f 0xaaa5796 0xacc51cb 0xacc37f9 0xacc461c 0xab2ef29 0xaa9fc17 0xac90023 0xac89913 0xac9bff0 0xabee686 0xab658fd 0xab64ec1 0xab0f862 0xac8b326 0xac89001 0xac9bff0 0xc0cf9be 0x4b9441d 0x4b8b976 0x4b89dcc 0x4b85139 0xc778b35 0xc776b38 0x944c267 0x945339a 0x945738d 0x48b318b 0x48ae61b 0x92f7094 0x116e68cf 0x7fa6035b53fb 0x7fa603061e83")
[2023-12-20 14:05:09.757936] WDIAG [SQL.RESV] get_table_schema (ob_schema_checker.cpp:850) [61153][T1004_L0_G0][T1004][YB42AC1018A3-00060AB6EDFB50B1-0-0] [lt=3][errcode=-4002] invalid arguments(table_id=18446744073709551615, ret=-4002, lbt()="0x1143006c 0xc152059 0xc133295 0xaab3c80 0xab5ff9f 0xaaa5796 0xacc51cb 0xacc37f9 0xacc461c 0xab2ef29 0xaa9fc17 0xac90023 0xac89913 0xac9bff0 0xabee686 0xab658fd 0xab64ec1 0xab0f862 0xac8b326 0xac89001 0xac9bff0 0xc0cf9be 0x4b9441d 0x4b8b976 0x4b89dcc 0x4b85139 0xc778b35 0xc776b38 0x944c267 0x945339a 0x945738d 0x48b318b 0x48ae61b 0x92f7094 0x116e68cf 0x7fa6035b53fb 0x7fa603061e83")
[2023-12-20 14:05:09.765449] INFO  [SQL.JO] compute_table_location (ob_join_order.cpp:245) [61153][T1004_L0_G0][T1004][YB42AC1018A3-00060AB6EDFB50B1-0-0] [lt=7] succeed to calculate base table sharding info(table_id=18446744073709551608, ref_table_id=507542, is_global_index=false)
[2023-12-20 14:05:09.765480] INFO  [SQL.JO] init_est_sel_info_for_access_path (ob_join_order.cpp:11905) [61153][T1004_L0_G0][T1004][YB42AC1018A3-00060AB6EDFB50B1-0-0] [lt=17] total rowcount, use statistics(table_meta_info_.table_row_count_=2637, table_meta_info_.average_row_size_=3.240000000000000000e+02, table_meta_info_.micro_block_count_=25, table_meta_info_.part_size_=8.543880000000000000e+05)
[2023-12-20 14:05:09.766105] INFO  [SQL.JO] compute_table_location (ob_join_order.cpp:245) [61153][T1004_L0_G0][T1004][YB42AC1018A3-00060AB6EDFB50B1-0-0] [lt=17] succeed to calculate base table sharding info(table_id=18446744073709551606, ref_table_id=506444, is_global_index=false)
[2023-12-20 14:05:09.766125] INFO  [SQL.JO] init_est_sel_info_for_access_path (ob_join_order.cpp:11905) [61153][T1004_L0_G0][T1004][YB42AC1018A3-00060AB6EDFB50B1-0-0] [lt=16] total rowcount, use statistics(table_meta_info_.table_row_count_=5, table_meta_info_.average_row_size_=4.940000000000000000e+02, table_meta_info_.micro_block_count_=1, table_meta_info_.part_size_=2.470000000000000000e+03)
[2023-12-20 14:05:09.766286] INFO  [SQL.JO] compute_table_location (ob_join_order.cpp:245) [61153][T1004_L0_G0][T1004][YB42AC1018A3-00060AB6EDFB50B1-0-0] [lt=13] succeed to calculate base table sharding info(table_id=18446744073709551605, ref_table_id=506475, is_global_index=false)
[2023-12-20 14:05:09.766300] INFO  [SQL.JO] init_est_sel_info_for_access_path (ob_join_order.cpp:11905) [61153][T1004_L0_G0][T1004][YB42AC1018A3-00060AB6EDFB50B1-0-0] [lt=11] total rowcount, use statistics(table_meta_info_.table_row_count_=5, table_meta_info_.average_row_size_=4.830000000000000000e+02, table_meta_info_.micro_block_count_=1, table_meta_info_.part_size_=2.415000000000000000e+03)
[2023-12-20 14:05:09.766425] INFO  [SQL.JO] compute_table_location (ob_join_order.cpp:245) [61153][T1004_L0_G0][T1004][YB42AC1018A3-00060AB6EDFB50B1-0-0] [lt=6] succeed to calculate base table sharding info(table_id=18446744073709551604, ref_table_id=507557, is_global_index=false)
[2023-12-20 14:05:09.766528] INFO  [SQL.JO] compute_table_location (ob_join_order.cpp:245) [61153][T1004_L0_G0][T1004][YB42AC1018A3-00060AB6EDFB50B1-0-0] [lt=10] succeed to calculate base table sharding info(table_id=18446744073709551603, ref_table_id=506441, is_global_index=false)
[2023-12-20 14:05:09.766541] INFO  [SQL.JO] init_est_sel_info_for_access_path (ob_join_order.cpp:11905) [61153][T1004_L0_G0][T1004][YB42AC1018A3-00060AB6EDFB50B1-0-0] [lt=10] total rowcount, use statistics(table_meta_info_.table_row_count_=5, table_meta_info_.average_row_size_=3.020000000000000000e+02, table_meta_info_.micro_block_count_=2, table_meta_info_.part_size_=1.510000000000000000e+03)
[2023-12-20 14:05:09.769334] WDIAG [SQL.OPT] allocate_expr_post (ob_logical_operator.cpp:2297) [61153][T1004_L0_G0][T1004][YB42AC1018A3-00060AB6EDFB50B1-0-0] [lt=6][errcode=-4016] expr can not be produced now(*expr={item_type:"T_REF_COLUMN", result_type:{meta:{type:"BIGINT", collation:"binary", coercibility:"NUMERIC"}, accuracy:{length:-1, precision:20, scale:0}, flag:1, calc_type:{type:"NULL", collation:"invalid_type", coercibility:"INVALID"}}, expr_info:["IS_COLUMN", "CNT_COLUMN"], rel_id:[1], table_id:18446744073709551602, column_id:16, database_name:"", table_name:"t", synonym_name:"", synonym_db_name:"", column_name:"canteen_stall_id", column_flags:0, enum_set_values:[], is_lob_column:false, is_joined_dup_column:false, is_unpivot_mocked_column:false, is_hidden:false, from_alias_table:false, is_rowkey_column:false, is_unique_key_column:false, is_mul_key_column:false, is_strict_json_column:0, srs_id:18446744073709551615, udt_set_id:0}, get_name()="GROUP BY", id_=11)
[2023-12-20 14:05:09.769371] WDIAG [SQL.OPT] do_post_traverse_operation (ob_logical_operator.cpp:1525) [61153][T1004_L0_G0][T1004][YB42AC1018A3-00060AB6EDFB50B1-0-0] [lt=36][errcode=-4016] failed to do allocate expr post(ret=-4016)
[2023-12-20 14:05:09.769377] WDIAG [SQL.OPT] do_plan_tree_traverse (ob_logical_operator.cpp:1626) [61153][T1004_L0_G0][T1004][YB42AC1018A3-00060AB6EDFB50B1-0-0] [lt=5][errcode=-4016] failed to perform post traverse action(ret=-4016, operation=0)
[2023-12-20 14:05:09.769382] WDIAG [SQL.OPT] do_plan_tree_traverse (ob_logical_operator.cpp:1619) [61153][T1004_L0_G0][T1004][YB42AC1018A3-00060AB6EDFB50B1-0-0] [lt=4][errcode=-4016] failed to bottom-up traverse operator(operator="SUBPLAN SCAN", operation=0, ret=-4016)
[2023-12-20 14:05:09.769391] WDIAG [SQL.OPT] do_plan_tree_traverse (ob_logical_operator.cpp:1619) [61153][T1004_L0_G0][T1004][YB42AC1018A3-00060AB6EDFB50B1-0-0] [lt=9][errcode=-4016] failed to bottom-up traverse operator(operator="GROUP BY", operation=0, ret=-4016)
[2023-12-20 14:05:09.769395] WDIAG [SQL.OPT] plan_tree_traverse (ob_log_plan.cpp:9937) [61153][T1004_L0_G0][T1004][YB42AC1018A3-00060AB6EDFB50B1-0-0] [lt=3][errcode=-4016] failed to apply operation to operator(operation=0, ret=-4016)
[2023-12-20 14:05:09.769401] WDIAG [SQL.OPT] plan_traverse_loop (ob_log_plan.h:1919) [61153][T1004_L0_G0][T1004][YB42AC1018A3-00060AB6EDFB50B1-0-0] [lt=3][errcode=-4016] failed to do plan traverse(ret=-4016, op=0)
[2023-12-20 14:05:09.769405] WDIAG [SQL.OPT] generate_plan (ob_log_plan.cpp:11388) [61153][T1004_L0_G0][T1004][YB42AC1018A3-00060AB6EDFB50B1-0-0] [lt=4][errcode=-4016] failed to do plan traverse(ret=-4016)
[2023-12-20 14:05:09.769408] WDIAG [SQL.OPT] optimize (ob_optimizer.cpp:60) [61153][T1004_L0_G0][T1004][YB42AC1018A3-00060AB6EDFB50B1-0-0] [lt=2][errcode=-4016] failed to perform optimization(ret=-4016)
[2023-12-20 14:05:09.769414] WDIAG [SQL] optimize_stmt (ob_sql.cpp:3523) [61153][T1004_L0_G0][T1004][YB42AC1018A3-00060AB6EDFB50B1-0-0] [lt=4][errcode=-4016] Failed to optimize logical plan(ret=-4016)
[2023-12-20 14:05:09.769424] WDIAG [SQL] generate_plan (ob_sql.cpp:3173) [61153][T1004_L0_G0][T1004][YB42AC1018A3-00060AB6EDFB50B1-0-0] [lt=9][errcode=-4016] Failed to optimizer stmt(ret=-4016)
[2023-12-20 14:05:09.769433] WDIAG [SQL] generate_physical_plan (ob_sql.cpp:2980) [61153][T1004_L0_G0][T1004][YB42AC1018A3-00060AB6EDFB50B1-0-0] [lt=3][errcode=-4016] failed to generate plan(ret=-4016)
[2023-12-20 14:05:09.769442] WDIAG [SQL] handle_physical_plan (ob_sql.cpp:4743) [61153][T1004_L0_G0][T1004][YB42AC1018A3-00060AB6EDFB50B1-0-0] [lt=7][errcode=-4016] Failed to generate plan(ret=-4016, result.get_exec_context().need_disconnect()=false)
[2023-12-20 14:05:09.769446] WDIAG [SQL] handle_ps_execute (ob_sql.cpp:2160) [61153][T1004_L0_G0][T1004][YB42AC1018A3-00060AB6EDFB50B1-0-0] [lt=4][errcode=-4016] fail to handle physical plan(ret=-4016)
[2023-12-20 14:05:09.769452] WDIAG [SQL] stmt_execute (ob_sql.cpp:252) [61153][T1004_L0_G0][T1004][YB42AC1018A3-00060AB6EDFB50B1-0-0] [lt=4][errcode=-4016] failed to handle ps execute(stmt_id=60, ret=-4016)
[2023-12-20 14:05:09.769459] WDIAG [SERVER] after_func (ob_query_retry_ctrl.cpp:932) [61153][T1004_L0_G0][T1004][YB42AC1018A3-00060AB6EDFB50B1-0-0] [lt=4][errcode=-4016] [RETRY] check if need retry(v={force_local_retry:false, stmt_retry_times:0, local_retry_times:0, err_:-4016, err_:"OB_ERR_UNEXPECTED", retry_type:0, client_ret:-4016}, need_retry=false, THIS_WORKER.can_retry()=true, v.ctx_.multi_stmt_item_={is_part_of_multi_stmt:false, seq_num:0, sql:"", batched_queries:NULL, is_ps_mode:false, ab_cnt:0})
[2023-12-20 14:05:09.769475] WDIAG [SERVER] execute_response (obmp_stmt_execute.cpp:1133) [61153][T1004_L0_G0][T1004][YB42AC1018A3-00060AB6EDFB50B1-0-0] [lt=16][errcode=-4016] run stmt_query failed, check if need retry(ret=-4016, cli_ret=-4016, retry_ctrl_.need_retry()=0, stmt_id=60)
[2023-12-20 14:05:09.769484] WDIAG [SERVER] do_process (obmp_stmt_execute.cpp:1295) [61153][T1004_L0_G0][T1004][YB42AC1018A3-00060AB6EDFB50B1-0-0] [lt=6][errcode=-4016] query failed(ret=-4016, retry_ctrl_.need_retry()=0, stmt_id=60)
[2023-12-20 14:05:09.769497] INFO  [SERVER] send_error_packet (obmp_packet_sender.cpp:315) [61153][T1004_L0_G0][T1004][YB42AC1018A3-00060AB6EDFB50B1-0-0] [lt=7] sending error packet(ob_error=-4016, client error=-4016, extra_err_info=NULL, lbt()="0x1143006c 0x9429b72 0x93d6381 0x944e49c 0x945339a 0x945738d 0x48b318b 0x48ae61b 0x92f7094 0x116e68cf 0x7fa6035b53fb 0x7fa603061e83")
[2023-12-20 14:05:09.769576] WDIAG [SQL.PC] common_free (ob_lib_cache_object_manager.cpp:141) [61153][T1004_L0_G0][T1004][YB42AC1018A3-00060AB6EDFB50B1-0-0] [lt=10][errcode=0] set logical del time(cache_obj->get_logical_del_time()=2429447449664, cache_obj->added_lc()=false, cache_obj->get_object_id()=151765, cache_obj->get_tenant_id()=1004, lbt()="0x1143006c 0x9bf6b80 0x48c97f4 0x48c63dc 0x944d73d 0x945339a 0x945738d 0x48b318b 0x48ae61b 0x92f7094 0x116e68cf 0x7fa6035b53fb 0x7fa603061e83")
[2023-12-20 14:05:09.769600] WDIAG [SERVER] process_execute_stmt (obmp_stmt_execute.cpp:1732) [61153][T1004_L0_G0][T1004][YB42AC1018A3-00060AB6EDFB50B1-0-0] [lt=11][errcode=-4016] fail to do process(ret=-4016, ctx_.cur_sql_=SELECT count(0) FROM (SELECT t.canteen_stall_id, IFNULL(t.canteen_stall_name, '-') AS canteen_stall_name, IFNULL(t.area_name, '-') AS area_name, sum(if(t.mealtime_type = 1, t.cust_num, 0)) AS breakfast_cust_num, sum(if(t.mealtime_type = 1, t.consume_num, 0)) AS breakfast_consume_num, sum(if(t.mealtime_type = 1, t.total_amount, 0)) AS breakfast_real_amount, sum(if(t.mealtime_type = 1, t.payable_amount, 0)) AS breakfast_payable_amount, sum(if(t.mealtime_type = 1, t.discount_amount, 0)) AS breakfast_discount_amount, sum(if(t.mealtime_type = 1, t.refund_amount, 0)) AS breakfast_refund_amount, sum(if(t.mealtime_type = 2, t.cust_num, 0)) AS lunch_cust_num, sum(if(t.mealtime_type = 2, t.consume_num, 0)) AS lunch_consume_num, sum(if(t.mealtime_type = 2, t.total_amount, 0)) AS lunch_real_amount, sum(if(t.mealtime_type = 2, t.payable_amount, 0)) AS lunch_payable_amount, sum(if(t.mealtime_type = 2, t.discount_amount, 0)) AS lunch_discount_amount, sum(if(t.mealtime_type = 2, t.refund_amount, 0)) AS lunch_refund_amount, sum(if(t.mealtime_type = 3, t.cust_num, 0)) AS afternoon_cust_num, sum(if(t.mealtime_type = 3, t.consume_num, 0)) AS afternoon_consume_num, sum(if(t.mealtime_type = 3, t.total_amount, 0)) AS afternoon_real_amount, sum(if(t.mealtime_type = 3, t.payable_amount, 0)) AS afternoon_payable_amount, sum(if(t.mealtime_type = 3, t.discount_amount, 0)) AS afternoon_discount_amount, sum(if(t.mealtime_type = 3, t.refund_amount, 0)) AS afternoon_refund_amount, sum(if(t.mealtime_type = 4, t.cust_num, 0)) AS dinner_cust_num, sum(if(t.mealtime_type = 4, t.consume_num, 0)) AS dinner_consume_num, sum(if(t.mealtime_type = 4, t.total_amount, 0)) AS dinner_real_amount, sum(if(t.mealtime_type = 4, t.payable_amount, 0)) AS dinner_payable_amount, sum(if(t.mealtime_type = 4, t.discount_amount, 0)) AS dinner_discount_amount, sum(if(t.mealtime_type = 4, t.refund_amount, 0)) AS dinner_refund_amount, sum(if(t.mealtime_type = 5, t.cust_num, 0)) AS supper_cust_num, sum(if(t.mealtime_type = 5, t.consume_num, 0)) AS supper_consume_num, sum(if(t.mealtime_type = 5, t.total_amount, 0)) AS supper_real_amount, sum(if(t.mealtime_type = 5, t.payable_amount, 0)) AS supper_payable_amount, sum(if(t.mealtime_type = 5, t.discount_amount, 0)) AS supper_discount_amount, sum(if(t.mealtime_type = 5, t.refund_amount, 0)) AS supper_refund_amount, sum(if(t.mealtime_type = -1, t.cust_num, 0)) AS other_cust_num, sum(if(t.mealtime_type = -1, t.consume_num, 0)) AS other_consume_num, sum(if(t.mealtime_type = -1, t.total_amount, 0)) AS other_real_amount, sum(if(t.mealtime_type = -1, t.payable_amount, 0)) AS other_payable_amount, sum(if(t.mealtime_type = -1, t.discount_amount, 0)) AS other_discount_amount, sum(if(t.mealtime_type = -1, t.refund_amount, 0)) AS other_refund_amount, sum(t.cust_num) AS total_cust_num, sum(t.consume_num) AS total_consume_num, sum(t.total_amount) AS total_real_amount, sum(t.payable_amount) AS total_payable_amount, sum(t.discount_amount) AS total_discount_amount, sum(t.refund_amount) AS total_refund_amount FROM (SELECT t.*, a.cust_num FROM (SELECT (CASE WHEN ? = 1 THEN a.canteen_id WHEN ? = 2 THEN a.stall_id ELSE a.canteen_id END) AS canteen_stall_id, (CASE WHEN ? = 1 THEN IFNULL(c.canteen_name, si.supermarket_name) WHEN ? = 2 THEN s.stall_name ELSE IFNULL(c.canteen_name, si.supermarket_name) END) AS canteen_stall_name, ar.area_name, a.mealtime_type, SUM(a.consume_num) consume_num, SUM(a.total_amount) total_amount, SUM(a.payable_amount) payable_amount, SUM(a.discount_amount) discount_amount, SUM(a.refund_amount) refund_amount FROM report_sum_mealtime a LEFT JOIN cust_org g ON g.org_id = a.org_id LEFT JOIN alloc_canteen c ON c.canteen_id = a.canteen_id LEFT JOIN alloc_stall s ON s.stall_id = a.stall_id LEFT JOIN supermarket_info si ON si.supermarket_id = a.canteen_id LEFT JOIN alloc_area ar ON c.area_id = ar.area_id WHERE a.statistic_date >= ? AND a.statistic_date <= ? GROUP BY canteen_stall_id, canteen_stall_name, area_name, mealtime_type) t LEFT JOIN (SELECT (CASE WHEN ? = 1 THEN o.canteen_id WHEN ? = 2 THEN o.stall_id ELSE o.canteen_id END) AS canteen_stall_id, (CASE WHEN ? = 1 THEN IFNULL(c.canteen_name, si.supermarket_name) WHEN ? = 2 THEN s.stall_name ELSE IFNULL(c.canteen_name, si.supermarket_name) END) AS canteen_stall_name, o.mealtime_type, count(DISTINCT o.cust_id) cust_num FROM report_order_info o LEFT JOIN cust_org g ON g.org_id = o.org_id LEFT JOIN alloc_canteen c ON c.canteen_id = o.canteen_id LEFT JOIN alloc_stall s ON s.stall_id = o.stall_id LEFT JOIN supermarket_info si ON si.supermarket_id = o.canteen_id WHERE o.pay_time >= concat(?, ' 00:00:00') AND o.pay_time <= concat(?, ' 23:59:59.999999999') GROUP BY canteen_stall_id, canteen_stall_name, mealtime_type) a ON a.canteen_stall_id = t.canteen_stall_id AND a.canteen_stall_name = t.canteen_stall_name AND a.mealtime_type = t.mealtime_type) t GROUP BY t.canteen_stall_id, t.canteen_stall_name, t.area_name) table_count)
[2023-12-20 14:05:09.769615] WDIAG [SERVER] process (obmp_stmt_execute.cpp:1889) [61153][T1004_L0_G0][T1004][YB42AC1018A3-00060AB6EDFB50B1-0-0] [lt=12][errcode=-4016] fail execute sql(sql_id="DF23A5872F6968A2EC919B3CB9EC5E8F", stmt_id=60, ret=-4016)

秃蛙 · 2023 年12 月 20 日 14:55

日志报错解析表列失败，navicat里执行正常，代码执行异常。
目前用户侧使用mysql8.0.31驱动，当前ob对8的驱动还存在兼容性问题，建议代码换成5.1.47驱动测验下。

liolay · 2023 年12 月 20 日 15:50

已经试过5.1.47和8.0.31驱动, 问题依旧存在
客户端使用5.1.47未见异常, 怀疑和连接参数有关,
客户端连接参数不明
代码使用的链接参数如下
characterEncoding=utf8&zeroDateTimeBehavior=convertToNull&useSSL=false&useJDBCCompliantTimezoneShift=true&useLegacyDatetimeCode=false&serverTimezone=GMT%2B8&allowMultiQueries=true&allowPublicKeyRetrieval=true

配置项如下
cachePrepStmts: true
prepStmtCacheSize: 250
prepStmtCacheSqlLimit: 2048
useServerPrepStmts: true
useLocalSessionState: false
rewriteBatchedStatements: false
cacheResultSetMetadata: true
cacheServerConfiguration: true
elideSetAutoCommits: true
maintainTimeStats: false

秃蛙 · 2023 年12 月 20 日 18:30

目前定位确认为ps协议参数导致，用户已提供抓包信息，待确认，目前用户侧设置useServerPrepStmts：false后正常。