URL
date
AI summary
slug
status
tags
summary
type
背景
最近在部署一套新环境,刚运行没几天,
canal-instance
就开始有如下持续报错:2024-05-29 11:47:31.300 [destination = haoduo-be , address = /192.168.0.63:3306 , EventParser] ERROR com.alibaba.otter.canal.common.alarm.LogAlarmHandler - destination:haoduo-be[com.alibaba.otter.canal.parse.exception.CanalParseException: java.lang.IllegalArgumentException: unknow type : 255 Caused by: java.lang.IllegalArgumentException: unknow type : 255 at com.taobao.tddl.dbsync.binlog.event.TableMapLogEvent.<init>(TableMapLogEvent.java:488) at com.taobao.tddl.dbsync.binlog.LogDecoder.decode(LogDecoder.java:182) at com.taobao.tddl.dbsync.binlog.LogDecoder.decode(LogDecoder.java:111) at com.alibaba.otter.canal.parse.inbound.mysql.MysqlMultiStageCoprocessor$SimpleParserStage.onEvent(MysqlMultiStageCoprocessor.java:269) at com.alibaba.otter.canal.parse.inbound.mysql.MysqlMultiStageCoprocessor$SimpleParserStage.onEvent(MysqlMultiStageCoprocessor.java:251) at com.lmax.disruptor.BatchEventProcessor.processEvents(BatchEventProcessor.java:168) at com.lmax.disruptor.BatchEventProcessor.run(BatchEventProcessor.java:125) at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) at java.util.concurrent.FutureTask.run(FutureTask.java:266) at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) at java.lang.Thread.run(Thread.java:748)
从报错信息来看,像是解析table_map_event事件时遇到了一个未知的类型,255。如果你对mysql binlog event不太了解的话,可以看看我之前写的带你了解MySQL binlog event
本篇文章基于mysql-8.0.18、canal-1.1.5
分析
上面这段报错信息量有点少,比如缺少问题点位。我们先从zk上定位到canal最后解析的点位,由于这个环境还在测试中,所以问题点位应该在这个点位之后的不远处。
定位问题点位
[zk: 192.168.0.65:2181(CONNECTED) 1] get /otter/canal/destinations/haoduo-be/1001/cursor {"@type":"com.alibaba.otter.canal.protocol.position.LogPosition","identity":{"slaveId":-1,"sourceAddress":{"address":"192.168.0.63","port":3306}},"postion":{"gtid":"","included":false,"journalName":"binlog.000002","position":54654455,"serverId":1001,"timestamp":1716884851000}}
如果着急的话,就把cursor的点位往后推或者是直接清空,如果不再产生新的”问题”binlog可以临时解决。但是这会造成binlog的丢失,可能还需要做一些人为补偿。
再拿这个点位
54654455
去mysql里看看有没有什么异常看起来一切正常,那我们再通过
mysqlbinlog
解析一下mysqlbinlog --no-defaults -vv --base64-output=decode-rows /var/lib/mysql/binlog.000002
解析出来的内容看着也都挺正常的。既然官方的解析工具没问题,那我们再试试民间的,我们先尝试用基于canal开发的canal2sql来解析。因为底层基于canal,所以和
canal-instance
报出了一样的错误。我们又尝试了基于go开发的bingo2sql,但是这次抛出了binlog里
course.course
表的的列数(128)和实际表里的列数(127)不一致的异常。[root@wocloud-hd-middleware1 bingo2sql]# ./bingo2sql -h=host -P 3306 -u username -p password --start-file='binlog.000002' --stop-file='binlog.000002' --start-pos=54654455 # 54df1cb9-02ed-11ef-b6ee-fa163e8a01ef:52029 UPDATE `user`.`message_log` SET `status`=1 WHERE `id`=59; # 2024-05-28 16:27:31 ERRO[2024-06-03T11:54:25+08:00] binlog解析操作失败 file=bingo2sql.go line=187 ERRO[2024-06-03T11:54:25+08:00] 表`course`.`course`缺少列!当前列数:127,binlog的列数128 file=bingo2sql.go line=188
这种问题一般是binlog记录时的表结构和当前实时表结构不一致产生的,而binlog里列数更多那只能是删除字段的情况,但是我们在binlog里并没有找到
course.course
表的DDL变更,并且实际上我们也没有变更过表结构。我们再结合前面从mysql里查的binlog信息,发现course.course
表的这条insert刚好是zk里记录点位之后的第二条DML,并且前一条也被bingo2sql正常解析出来了,看来问题点位已经呼之欲出了。为了做实问题点位,我们通过
canal2sql
也定位到了相同的位置:这里的logPos其实是next_position,也就是本条binlog event的末尾位置,这是binlog在5.0版本改的,4.0版本记录的是起始位置,所以这里的命名看起来有点怪怪的,不然直接命名next_position语义更清晰。
canal2sql
和bingo2sql
都无法成功解析54655494~54655791
这条table_map_event
事件,虽然两者的报错不一样。而在debugcanal2sql
的过程中,我发现canal解析出来的column_count也是128。只是解析顺序的原因,先抛出了unknow type : 255
这个异常。消失的字段
所以,我们先来搞清楚这个128的问题,我仔细看了一下这张表的表结构,其中有一个多值索引引起了我的注意:
KEY `idx_collocationalCourseIds` ((cast(json_extract(`collocational_course_ids`,_utf8mb4'$[*]') as unsigned array)))
我印象里多值索引是通过增加了一个虚拟列来实现的,是不是就是这个虚拟列被包含在了column_count里?于是我查询了一下多值索引的相关资料
You can create a multi-valued index in a CREATE TABLE, ALTER TABLE, or CREATE INDEX statement. This requires using CAST(... AS ... ARRAY) in the index definition, which casts same-typed scalar values in a JSON array to an SQL data type array. A virtual column is then generated transparently with the values in the SQL data type array; finally, a functional index (also referred to as a virtual index) is created on the virtual column. It is the functional index defined on the virtual column of values from the SQL data type array that forms the multi-valued index.
可以看到,多值索引的实现的确是增加了一个虚拟列。为了验证这个点,我直接把这个多值索引去掉了,发现去掉之后一切就正常了,不仅是这个
column_count
变成了127,canal对于binlog的解析也都正常了。但是我们在生产环境的使用都很正常,照理说应该不是canal的问题,而两边唯一的区别是mysql版本,生产是8.0.25。带着这个疑惑我看了生产8.0.25下这张表产生的binlog
table_map_event
,发现里面的column_count
居然是127,多值索引增加的虚拟列并没有包含在里面。看起来不同版本的mysql对于虚拟列的binlog记录方式是有差别的。深入table_map_event
多了一列虚拟列为什么就解析不出来了呢?我们根据报错信息定位到源码,不过在分析源码之前,我们先了解一下
table_map_event
的格式。首先它是一种binlog事件类型,所以它会包含三个部分:eventHeader
、postHeader
和body
,其中eventHeader
是所有事件具有的结构,当前的版本是19个字节,这里不展开介绍。而postHeader
则是类型特定的头部结构,和具体的类型相关,长度也各不一样。而body
则是主要的数据载体了,这里我们重点关注table_map_event
的body部分:字段 | 字节数 | 描述 |
database_name | database_name_len + 1字节 | 1个字节表示字符串长度,之后接一个null-terminated类型的字符串。因为行日志事件很多时候并不指定数据库名,所以在该事件中有必要记录数据库名。长度不含 null |
table_name | table_name_len+1字节 | 1个字节表示字符串长度,之后接一个null-terminated类型的字符串表示行日志事件所发生的表名 |
column_count | Packed Integer (1或3或4或9个字节, 当有大量小数值的时候用于节省存储空间的一种编码格式,详见 net_store_length: https://github.com/mysql/mysql-server/blob/mysql-cluster-8.0.22/mysys/pack.cc#L128) | 数据表所含列数 |
column_type | column_count 长度的字节数组 | 每字节代表一列数据的类型,枚举值见 enum_field_types(https://github.com/mysql/mysql-server/blob/mysql-cluster-8.0.22/include/field_types.h#L52) |
metadata_length | Packed Integer | 对应字段的元数据长度 |
metadata | metadata_length 个字节 | |
null_bits | 字节数组,数组长度 = int((column_count + 7) / 8) | 每一位表示对应列是否可以为 NULL。顺序是:第一个字节的最低位开始向最高位增长,之后第二个字节的最低位开始向最高位增长,以此类推 |
optional metadata fields | Type(byte), Length(Packed Interge), Value(Length byte) | |
check_sum | 4字节 | 校验码 |
有了上面的知识储备之后,我们再来看看源码:
public TableMapLogEvent(LogHeader header, LogBuffer buffer, FormatDescriptionLogEvent descriptionEvent){ // 省略非核心代码 // 解析column_type columnCnt = (int) buffer.getPackedLong(); columnInfo = new ColumnInfo[columnCnt]; for (int i = 0; i < columnCnt; i++) { ColumnInfo info = new ColumnInfo(); info.type = buffer.getUint8(); columnInfo[i] = info; } if (buffer.position() < buffer.limit()) { final int fieldSize = (int) buffer.getPackedLong(); // 这一步在解析metadata decodeFields(buffer, fieldSize); // 这一步在解析null_bits nullBits = buffer.getBitmap(columnCnt); for (int i = 0; i < columnCnt; i++) { if (nullBits.get(i)) { columnInfo[i].nullable = true; } } /* * After null_bits field, there are some new fields for extra * metadata. * * null_bits之后,就是额外的metadata optional metadata fields * */ existOptionalMetaData = false; List<TableMapLogEvent.Pair> defaultCharsetPairs = null; List<Integer> columnCharsets = null; while (buffer.hasRemaining()) { // optional metadata fields int type = buffer.getUint8(); int len = (int) buffer.getPackedLong(); switch (type) { case SIGNEDNESS: parse_signedness(buffer, len); break; case DEFAULT_CHARSET: defaultCharsetPairs = parse_default_charset(buffer, len); break; case COLUMN_CHARSET: columnCharsets = parse_column_charset(buffer, len); break; case COLUMN_NAME: // set @@global.binlog_row_metadata='FULL' // 主要是补充列名相关信息 existOptionalMetaData = true; parse_column_name(buffer, len); break; case SET_STR_VALUE: parse_set_str_value(buffer, len, true); break; case ENUM_STR_VALUE: parse_set_str_value(buffer, len, false); break; case GEOMETRY_TYPE: parse_geometry_type(buffer, len); break; case SIMPLE_PRIMARY_KEY: parse_simple_pk(buffer, len); break; case PRIMARY_KEY_WITH_PREFIX: parse_pk_with_prefix(buffer, len); break; default: throw new IllegalArgumentException("unknow type : " + type); } } if (existOptionalMetaData) { int index = 0; int char_col_index = 0; for (int i = 0; i < columnCnt; i++) { int cs = -1; int type = getRealType(columnInfo[i].type, columnInfo[i].meta); if (is_character_type(type)) { if (defaultCharsetPairs != null && !defaultCharsetPairs.isEmpty()) { if (index < defaultCharsetPairs.size() && char_col_index == defaultCharsetPairs.get(index).col_index) { cs = defaultCharsetPairs.get(index).col_charset; index++; } else { cs = default_charset; } char_col_index++; } else if (columnCharsets != null) { cs = columnCharsets.get(index); index++; } columnInfo[i].charset = cs; } } } } }
上面的代码是从解析
column_type
开始,然后依次是metadata
(这一步在decodeFields()
方法里)、null_bits
,剩下的除了最后4个字节的check_sum
之外,就是optional metadata fields
。而报错就是出现在解析optional metadata fields
时,获取到了一个未定义的类型255。查询了一下mysql 8.0.18的源码,确实没有这种类型enum Optional_metadata_field_type { SIGNEDNESS = 1, // UNSIGNED flag of numeric columns DEFAULT_CHARSET, /* Character set of string columns, optimized to minimize space when many columns have the same charset. */ COLUMN_CHARSET, /* Character set of string columns, optimized to minimize space when columns have many different charsets. */ COLUMN_NAME, SET_STR_VALUE, // String value of SET columns ENUM_STR_VALUE, // String value of ENUM columns GEOMETRY_TYPE, // Real type of geometry columns SIMPLE_PRIMARY_KEY, // Primary key without prefix PRIMARY_KEY_WITH_PREFIX, // Primary key with prefix ENUM_AND_SET_DEFAULT_CHARSET, /* Character set of enum and set columns, optimized to minimize space when many columns have the same charset. */ ENUM_AND_SET_COLUMN_CHARSET, /* Character set of enum and set columns, optimized to minimize space when many columns have the same charset. */ };
在C语言中,如果你没有为枚举(enum)中的某个成员指定值,那么它将会自动取前一个成员的值加1。所以上述的值域是1-11。
那似乎只有一种原因——可能是解析错位了。我们通过
010 Editor
来观测一下binlog,并debug到canal解析出错的具体binlog事件内的相对位置:其中下面这张图里:
- 红色部分是
column_count
+column_type
- 绿色部分是
metadata_length
+metadata
- 黄色部分是
null_bits
可以看到,canal在解析的时候,把
null_bits
的最后一个字节当成了optional metadata fields
的第一个字节了。也就是说前面少解析了1个字节。而column_type
这一段是直接按照column_count
取的,没有任何问题。问题就出在metadata
的解析上,它并不是直接根据metadata_length
取的,而是根据每个字段的不同类型分别取它对应的元数据长度,阅读下面的代码应该很容易理解前面这句话:private final void decodeFields(LogBuffer buffer, final int len) { final int limit = buffer.limit(); buffer.limit(len + buffer.position()); for (int i = 0; i < columnCnt; i++) { ColumnInfo info = columnInfo[i]; switch (info.type) { case MYSQL_TYPE_TINY_BLOB: case MYSQL_TYPE_BLOB: case MYSQL_TYPE_MEDIUM_BLOB: case MYSQL_TYPE_LONG_BLOB: case MYSQL_TYPE_DOUBLE: case MYSQL_TYPE_FLOAT: case MYSQL_TYPE_GEOMETRY: case MYSQL_TYPE_JSON: /* * These types store a single byte. */ info.meta = buffer.getUint8(); break; case MYSQL_TYPE_SET: case MYSQL_TYPE_ENUM: /* * log_event.h : MYSQL_TYPE_SET & MYSQL_TYPE_ENUM : This * enumeration value is only used internally and cannot * exist in a binlog. */ logger.warn("This enumeration value is only used internally " + "and cannot exist in a binlog: type=" + info.type); break; case MYSQL_TYPE_STRING: { /* * log_event.h : The first byte is always * MYSQL_TYPE_VAR_STRING (i.e., 253). The second byte is the * field size, i.e., the number of bytes in the * representation of size of the string: 3 or 4. */ int x = (buffer.getUint8() << 8); // real_type x += buffer.getUint8(); // pack or field length info.meta = x; break; } case MYSQL_TYPE_BIT: info.meta = buffer.getUint16(); break; case MYSQL_TYPE_VARCHAR: /* * These types store two bytes. */ info.meta = buffer.getUint16(); break; case MYSQL_TYPE_NEWDECIMAL: { int x = buffer.getUint8() << 8; // precision x += buffer.getUint8(); // decimals info.meta = x; break; } case MYSQL_TYPE_TIME2: case MYSQL_TYPE_DATETIME2: case MYSQL_TYPE_TIMESTAMP2: { info.meta = buffer.getUint8(); break; } default: info.meta = 0; break; } } buffer.limit(limit); }
可以看到,不同的字段类型对应不同的元数据长度,而
metadata_length
只是起到了一个限制的作用,但是如果说没有取完的话,canal是无感知的,也就是这样造成了错位。问题肯定还是出在那个虚拟列上,我们看一下最后一列的类型,也就是上图红色部分的最后一个字节,十进制是20。这种类型在canal里并没有定义,应该是后面新增的,所以canal也没有处理。20表示多值索引产生的虚拟列的类型——
MYSQL_TYPE_TYPED_ARRAY
,并且8.0.17刚开始引入的时候它的值是244,后面8.0.18改成了20(参考),而从代码注释里看,定义的又是15(有点凌乱)。而这种类型,按照代码注释的描述,存在1-4个字节的metadata,第一个字节表示数组元素的类型,而后面的0-3个字节携带了元素类型的metadata。<tr> <td>MYSQL_TYPE_TYPED_ARRAY</td><td>15</td> <td>up to 4 bytes</td> <td> - The first byte holds the MySQL type for the elements. - The following 0, 1, 2, or 3 bytes holds the metadata for the MySQL type for the elements. The contents of these bytes depends on the element type, as described in the other rows of this table. </td> </tr>rows_event.hmysql
而在我这个场景里,元素类型是bigint,bigint本身没有metadata。所以对于
MYSQL_TYPE_TYPED_ARRAY列
来说总共只有一个字节的metadata。也就说canal-1.1.6
那次的改动恰好可以用。于是我把相关代码应用过来测试,发现虽然解析不错位了,但是还是会报列不一致的问题。所以,感觉这个commit只解决了一半甚至一半都不到的问题,没有任何意义。结论
问题原因
至此,问题我们已经很明确了:
mysql 8.0.18
版本对于多值索引产生的虚拟列会写入binlog,而一些第三方的binlog解析工具在做列数量比对,并不识别这一虚拟列,所以就解析失败了。以canal为例,由于代码缺乏健壮性,甚至会导致解析错位,可能会引发其他更难排查的问题。比较典型的报错信息如下:unknow type : 后面可能是任意值
但是如果错位解析出的这个字节刚好在opt type的值域内,就可能会造成其他的解析异常了。这里也是canal不够健壮的地方,这里我提几个优化意见:
- 可以对解析到的metadata长度和实际的metadata的长度字段做对比,如果不一致就报错
- 对于不识别的类型也可以直接做报错处理,不能简单归为默认没有metadata
- 或者是有些metadata其实对于后续binlog解析没有影响,那也可以直接忽略未读完的metadata,继续往后读取(这种方案不太严谨)
而
mysql 8.0.25
版本对于多值索引产生的虚拟列则并没有写入binlog,下游也就没有任何感知。回溯修复过程
我想要找到关于这次修复的相关记录,但是翻了MySQL 8.0.18 - 8.0.25版本的更新记录却没有找到相关内容。由于对c的代码也不熟悉,对mysql的代码也不熟悉,从代码里找答案的难度太高了(我也尝试了,然而没有悬念的失败了)。只找到binlog解析相关的代码,而没有找到binlog写入的相关代码,我主要想找table_map_event里column_count的写入逻辑~
下面是我在查找过程中几个疑似的修复提交,可能并不是解决的这个问题,但是也挺有学习价值的,在这里也记录一下
从库独有的generated column
这是8.0.24版本的一项修复
Replication: With row-based replication in use (binlog_format=ROW), stored generated columns that existed only on the replica were not being updated when the other fields in the row were inserted or updated. These columns are now evaluated when the row image is unpacked, and their value is updated in the row image before it is applied. (Bug #32292413, Bug #101978)
bug里反馈的是一个主从同步的问题:从库比主库多了一些生成列(有
VIRTUAL GENERATED
也有STORED GENERATED
),而从主库同步过来的数据,VIRTUAL GENERATED
列都表现正常,而STORED GENERATED
列都为null。原因是MySQL对于STORED GENERATED
列在同步逻辑里没有重新计算,而是和普通列类似的处理方式。所以假如主库没有这个字段,从库就没法同步了。而这个BugFix就是把STORED GENERATED
列也采用和VIRTUAL GENERATED
一样的做法,在从库重新计算一遍。但是这个似乎和我们碰到的问题不一样,并且我进去大概看了下修复代码,好像也没有改到column_count。我也搜索了好久相关的关键字:
multi-valued index
、MYSQL_TYPE_TYPED_ARRAY
等等,都找不到相关的信息,并且对于c的代码,我也不太能看得懂。重构
这是在8.0.22版本上的更新,应该是个重构优化,优化的是DML的处理流程,让每个statement只被prepared一次。但是在里面我看了一些关于
MYSQL_TYPE_TYPED_ARRAY
的失效。不确定是不是这次的重构,刚好fix了之前的bug。扩展阅读
不可见列
WL#10905 - Support for INVISIBLE columns
这是我在本次查阅资料的过程中看到的,canal在支持
MYSQL_TYPE_TYPED_ARRAY
的附近有一个支持invisibleColumn的提交,就顺带学习了一下。invisible信息保存在optional metadata fields
里,增加了一种新的类型。这是
mysql 8.0.23
新增的特性,主要是影响select *
语句的,不可见列(invisible column)不会被select *
查出来,必须要显式指定。可以避免对原有代码的影响。我想到另外一个场景,是不是对于大字段我们可以定义为invisible,这样必须显式才允许查,可以减少不必要的大字段查询。
生成列
生成列(generated column)可以理解成派生列,是基于普通列计算而来的。它有点视图的感觉,但是使用起来更方便。生成列有两种类型:
VIRTUAL GENERATED
和STORED GENERATED
。两种类型的区别就是在存储不存储到聚簇索引中,前者不存储,而后者存储。存储就是空间换时间,在查询时不需要再重新计算,直接当成普通列取出即可,所以
STORED GENERATED
应该可以近似理解成普通列,但是缺点就是占用更多的空间,可能会导致更差的性能。所以默认值是VIRTUAL GENERATED
。VIRTUAL GENERATED
列上也支持创建二级索引。最小化实验
上面是生产环境的问题,杂音比较多。我自己尝试用一个最小化的实验来模拟测试一下,顺带观察一下两种生成列产生的binlog。
我们分别在
MySQL 8.0.18
和MySQL 8.0.25
的实例里,创建一张包含1个STORED GENERATED
列、1个VIRTUAL GENERATED
列以及1个多值索引的表,并插入一条记录:CREATE TABLE `generated_column_test` ( `id` bigint NOT NULL, `json_array` json NULL, `gen_stored` varchar(255) AS (concat(id, ':stored-generated')) STORED NULL, `gen_virtual` varchar(255) AS (concat(id, ':virtual-generated')) VIRTUAL NULL, PRIMARY KEY (`id`), KEY `idx_array` ((cast(json_extract(`json_array`,_utf8mb4'$[*]') as unsigned array))) ); insert into generated_column_test(id, json_array) values (1, '[1,2,3]');
我们观察两个实例产生的binlog,可以看到:
- 只要是generated column,无论是virtual还是stored,都会写入binlog
- 对于多值索引产生的虚拟列,8.0.18会写入binlog,主要影响的是table_map_event和row_event,也就是下图红色、绿色、黄色以及未标注出来的rows_event里的相关信息
- 8.0.18 虽然增加了一列,但是在具体的row_event里,并没有具体的列值,只有列描述信息。在列值方面,和8.0.25一模一样(图中两个竖线包围的67个字节)
忍不住好奇又去看了一下ibd文件,发现:
- 只有stored列是被存储到聚簇索引中,virtual不会
- 多值索引列值也没有存储到聚簇索引中,只存在于多值索引页中
- 多值索引页也就是普通的二级索引页,只是把多值打散了,比如这里的二级索引里会有三条记录,分别是 1-1、2-1、3-1
- 8.0.18和8.0.25版本下,ibd文件的表现一致
参考
- 作者:黑微狗
- 链接:https://blog.hwgzhu.com/article/mysql-8.0.18-multi-index-with-canal
- 声明:本文采用 CC BY-NC-SA 4.0 许可协议,转载请注明出处。
相关文章