由于对一些报错信息的不熟悉，导致分析过程有点曲折，也作为一个案例分享给大家。

一、故障现象

客户人员反馈程序报错, 发过来的业务日志是:

任务编号[PTSK2024.....] Unable to commit against JDBC Connection;
nested exception is org.hibernate.TransactionException:Unable to commit against JDBC Connection

上面信息太简短, 让提取完整的java日志报错call stack, 得到如下日志:

Unable to commit against JDBC Connection;
nested exception is org.hibernate.TransactionException:Unable to commit against JDBC Connection
...
    at java.lang.Thread.run(Thread.java:750) ~[?:1.8.0_342]

Caused by: org.hibernate.TransactionException: Unable to commit against JDBC Connection
 at org.hibernate.resouce.jdbc.internal.AbstractLogicalConnectionImplementor.commit...
...

Caused by: java.sql.SQLException: assertion failed: key: 74800000000007bb725f69800000000000000103800000004d6c6412, assertion: Exist, start_ts:454418906515767360, existing start ts: 0, existing commit ts:0
...
... 12 more

看到真实的报错原因是assertion failed, 也给了key的值。

二、初次判断失误

如果熟悉assertion failed的含义, 或是tidb把错误信息写得更明白一些, 那基本能猜到原因了。

但这里作者判断失误了: “可能是表中某个key已经存在, 业务代码想insert, 发生了主键冲突”。

沿着上面这个思路排查：

(1) 首先查key的信息

select tidb_decode_key('74800000000007bb725f69800000000000000103800000004d6c6412')
得到 
{"index_id":1,"index_vals":"1298949138","table_id":506738}

有了table_id=506738, 有index对象编号, 一般index_id=1是表的主键, 也就是PK=1298949138的记录有冲突。

(2)查看相关表的信息

select * from information_schema.tables where tidb_table_id=506738; 
-- 查出表名是gen_mdl, 
-- Show create table gen_mdl 得到表的定义如下
create table gen_mdl( id bigint(20) primary key auto_increment, ...)

(3)查看PK的信息

select * from gen_mdl where id=1298949138

没有记录。

到这里觉得事情很诡异, 一是表中没有查到这条记录, 二是如果insert 导致auto_increment自动分配id, 而当前表的auto id值已经远大于1298949138, 好象不可能。

在tidb日志中找到如下的日志, 与java的报错相对应。

[Error] [asertion failed] message="[tikv:8141]assertion failed: key: 74800000000007bb725f69800000000000000103800000004d6c6412,... " 
    mvcc history={key:74800000000007bb725f69800000000000000103800000004d6c6412}, start_ts:xxx, primary:dIAAAA....
[Warn] [can not retry txn] ... IsPessimistic=true
[Warn] [commit failed]
[Warn] [run statement failed] [error=previous statement: update hist_tbl where ...:[tikv:8141]assertion failed:...]
[Info] [command dispatched failed] ... [status:"inTxn:0, autocommit:0"] [sql=commit] [txn_mode=PESSIMISTIC] [error="...., previous statement: update hist_tbl ..."]

由于报错没有提示是哪个sql引发错误（这个判断也是错的），所以让客户查一下insert gen_mdl相关的程序代码，客户回复说相关insert语句看着都正常。

到这里排查陷入僵局。

三、分析的转机

几小时后，客户找过来说，他对相关事务代码中每行DML语句进行逐一提交, 找到了报错的sql, 是一个delete gen_mdl where xxx语句。

delete语句也报主键冲突？然后隐约猜到了, 报错中assertion failed不是说主键冲突，而是这个键值有问题。

查询 select * from gen_mdl where xxx语句，发现了id=1298949138这个记录。

前面查询 select * from gen_mdl where id=1298949138为空，使用的是主键索引。

至此，明白了是主键索引和表数据不一致，导致的异常现象。

分别使用全表扫描统计全表数量，以及主键索引统计全表数量，查得全表条数比主键条数多了几百万。

四、几点小结

4.1 tidb日志有提示报错的sql

复盘时仔细看了tidb日志, 发现里面明确写了是执行commit语句时报的错（虽然对排错没什么作用）:

[Info] [command dispatched failed] ... [status:"inTxn:0, autocommit:0"] [sql=commit] [txn_mode=PESSIMISTIC] [error="...., previous statement: update hist_tbl ..."]

以前认为是insert相关语句的问题, 因此忽略了日志中的提示。

客记事后反馈说, 相关事务代码结构如下：

begin
delete gen_mdl where xxx
...
update hist_tbl ...
commit;

4.2 assertion failed 与duplicate entry的区别

主键重复, 报错是 duplicate entry, 且会直接抛出有问题的DML语句，故障排查比较简单。

键值异常（比如通过某个key去找数据行时失败）, 报错是 assertion failed, 但它给分析增加难度的地方是，即使在悲观模式下，delete语句在上锁时也不会发现数据不一致（可以正常对数据行上锁），而是在commit时才会处理全部相关的表行和索引行，然后才抛出错误, 此时已经不知道是事务中哪个DML语句导致的。

所以前面提到，如果熟悉assertion failed，则一开始就可以猜到是数据不一致。

4.3 表与主键不一致是怎么产生的

由于表的条数比主键多几百万，且客户曾经对表使用过lightning物理导入，这里的判断也比较简单，就是物理导入时，重复导入了csv文件数据（如果没有过物理导入，则要仔细分析其它可能）。

lightning物理导入数据有特别的地方：

lightning把csv组成表的sst并且ingest到tikv中，基本会成功, 即表数据一定会写入；
lightning把csv组成唯一索引的sst时，会进行唯一性检查, 不满足的数据会被剔除, 即索引数据不一定会全部写入；

比如，物理方式重复导入了某个10万条的csv文件, 则表中数据会多出10万条, 但是主键索引不变（因为不满足唯一性），此时ligthning导入日志中会有duplicated key found, checksum mismatched remote vs local之类报错信息，要引起重视。

案例分析"assertion failed"