tidb 4.0.13并发查询数据透传问题

【 TiDB 使用环境】生产环境
【 TiDB 版本】4.0.13
【遇到的问题】并发查询数据透传问题
【复现路径】就一个简单的inner join查询
【问题现象及影响】生产级大bug

一个select where id=* 条件的查询,在并发情况下查询条件和最终得到的结果是混乱的
比如接口并发多人在请求这个查询 where id=111这一个请求返回的理应是id=111的数据,现在问题是请求id=111的查询,返回的结果有可能是另一个请求id=222 所返回的数据,就是查id=111得到了同时另一个请求id=222的数据

以下详细介绍触发这个bug的流程

先上一段代码这是我复现问题的测试代码,下面去掉了很多没必要的代码
golang写的
github.com/go-sql-driver/mysql” 数据库连接驱动器
sql Prepare 预处理查询

触发这个问题的条件之一就是下面这段sql用到了 inner join ,去掉inner join关联表就不会有这个问题
users表有两千多万数据,另一个表只有几十条数据

数据表是这样的结构

users表

Id other
111 ….
222 ….

userORDER表

tid disabled other
111 1 ….
222 1
stmt, err := db.Prepare(SELECT u.id FROM users as u inner join userOrder as o on u.id=o.tid WHERE u.id = (?) and o.disabled=1)
userID := []string{"111", "222"}
for i := 0; i < 60; i++ {//60个并发去查询userID里的两个数据
	go func(b int) {
		queryID := userID[b%2]
		rows, err := stmt.Query(queryID)

		var users []Users
		for rows.Next() {
			var u user
			rows.Scan(&u.id)
			
            //验证这个bug
			if u.id != queryID {
				//这里的不等于条件会成功,查询的id=queryID  那么我得到的c.id也应该是queryID  他们是相等的才对
				fmt.Println(queryID, u.id, "----")
			}
			users = append(users, u)
		}
	}(i)
}

return

原来怀疑是我代码问题,后面结果各种排查无果,就用 WireShark抓了下包,发现{“111”, “222”}这两个数据的确各发了30次请求,查看Response神奇的事情发生了, 发现上面查询 111结果返回了29次,222返回了31次
所以就发生了上面那个现象,当查询id=1111 得到了一次 id=222的数据,下面有抓包截图

%E5%BE%AE%E4%BF%A1%E5%9B%BE%E7%89%87_20220407163123

%E5%BE%AE%E4%BF%A1%E5%9B%BE%E7%89%87_20220407163115

补充说明下,我重新申请了一套服务器另外搭了一套全新的集群版本拓扑图和数据都一样,没重现出这个问题

【附件】

  1. TiUP Cluster Display 信息
    %E5%BE%AE%E4%BF%A1%E5%9B%BE%E7%89%87_20220407161612
3 个赞
  1. 麻烦发送下完整的抓包 cap 文件
  2. 生产环境的信息能否反馈下,另外连接是直连的 tidb-server 吗? 有没有什么中间件?
  3. 其他表有类似的 inner join 连接吗? 只有这两个特定表有问题吗?
  4. 生产上最开始执行的什么 SQL,如何发现的?
1 个赞

请问,没问题的是哪个版本?

1 个赞

这段代码似乎没有使用 channel 或者 waitgroup 来保证所有 goroutine 执行完成。比如,我这里,

	stmt, err := db.Prepare("select * from t")
	if err != nil {
		t.Fatal(err)
	}
	defer stmt.Close()

	//var wg sync.WaitGroup
	for i := 0; i < 30; i++ {
		//wg.Add(1)
		go func() {
			rows, err := stmt.Query()
			if err != nil {
				t.Fail()
			}
			defer rows.Close()

			var id int
			for rows.Next() {
				rows.Scan(&id)
				fmt.Println(id)
			}
			//wg.Done()
		}()
	}
	//wg.Wait()
	return

也打不出完整的 response 就返回了。

如果把上面代码的 wg 相关的注释掉,就可以了。

	stmt, err := db.Prepare("select * from t")
	if err != nil {
		t.Fatal(err)
	}
	defer stmt.Close()

	var wg sync.WaitGroup
	for i := 0; i < 30; i++ {
		wg.Add(1)
		go func() {
			rows, err := stmt.Query()
			if err != nil {
				t.Fail()
			}
			defer rows.Close()

			var id int
			for rows.Next() {
				rows.Scan(&id)
				fmt.Println(id)
			}
			wg.Done()
		}()
	}
	wg.Wait()
	return
1 个赞

这里贴的是精简的测试代码 我原来的代码里面wait group有的

1 个赞

tidb跟正式环境一模一样的版本 拓扑图,机器配置略不一样,centos版本略不一样

1 个赞

如果稳定复现的话 tidb 可以开 debug 级别日志 先确认一下发过来的查询是 30 条 111 30 条 222 还是 29 条 111 31 条 222,这样可以先缩小问题是在 client 还是 db 端,方便确定排查方向。

1 个赞

回答:

  1. 下面附近里上传了全部的cap文件

  2. 生产环境操作系统是 centos7.8,原来上面有层getway,我在测试复现这个问题的时候是直接连接的tidb-server,我们有3台tidb-server(连接任何一台都能复现这个问题)

  3. 目前业务其它地方还真没用到inner join,不过我们有n个数据库相同的表(按品牌划分的数据库 业务一样的),大概测了下在其它数据库里执行相似的查询没有复现(没有深入测试)

  4. 业务代码上api进来第一个sql查询就是执行这个inner join,发现问题是因为用户在调用这个接口查询自己数据的时候,发现返回的是其他人的数据

all-tidb.pcapng (14.5 MB)

能贴下这几个不同 SQL 的执行计划,以及出问题表的 admin check table [table_name] 的结果吗?

  1. 最后直连 TiDB-Server 这次的报文能不能麻烦上传下,Tcpdump port xxx -w xxx.cap 抓包时带上 -w 参数
  2. 麻烦测试的同时开启 debug 日志。也反馈下 debug 日志内容。
  3. 对生产环境不影响的情况下,如果有可能最好可以新建一个 tidb-server 测试。多谢。

这样沟通效率太低了,能否加个微信,等讨论出结果了再贴回这个issues
我微信号:lanse619592413

1.附件里上传了客户端和服务端的tcp抓包
2.附件里上传了dashboard上下载的日志,没有tikv的 tikv加载不出来
3.目前没机器预算了,我这是生产环境

logs.zip (52.8 KB)

tidb-client.pcapng (6.3 MB) tidb-server.cap (309.8 KB)

执行计划

	id                        	task     	estRows	operator info                                                                                                                                                                                                                                                                                              	actRows	execution info                                                                                                                                                                                                                                                                                                                                              	memory  	disk
Projection_8              	root     	9.59   	lrl.coupons.id, lrl.coupons.coupontypeid, lrl.coupons.consumerrefid, lrl.coupons.channelid, lrl.coupons.state, lrl.coupons.properties, lrl.coupons.createdtime, lrl.coupons.appointtime, lrl.coupons.counters, lrl.coupons.appointcounter, lrl.coupons.extrainfo, lrl.coupons.appointid, lrl.coupons.bacode	62     	time:9.95ms, loops:2, Concurrency:OFF                                                                                                                                                                                                                                                                                                                       	47.0 KB 	N/A
└─SelectLock_9            	root     	9.59   	for update                                                                                                                                                                                                                                                                                                 	0      	                                                                                                                                                                                                                                                                                                                                                            	N/A     	N/A
  └─IndexHashJoin_15      	root     	9.59   	inner join, inner:IndexLookUp_12, outer key:lrl.published_coupon_type.coupontypeid, inner key:lrl.coupons.coupontypeid, equal cond:eq(lrl.published_coupon_type.coupontypeid, lrl.coupons.coupontypeid)                                                                                                    	62     	time:9.93ms, loops:2, inner:{total:7.42ms, concurrency:4, task:1, construct:103.7µs, fetch:7.18ms, build:51.6µs, join:135.2µs}                                                                                                                                                                                                                           	227.9 KB	N/A
    ├─TableReader_27      	root     	0.06   	data:Selection_26                                                                                                                                                                                                                                                                                          	62     	time:2.28ms, loops:3, cop_task: {num: 1, max: 2.27ms, proc_keys: 62, rpc_num: 1, rpc_time: 2.25ms, copr_cache_hit_ratio: 0.00}                                                                                                                                                                                                                              	3.90 KB 	N/A
    │ └─Selection_26      	cop[tikv]	0.06   	eq(lrl.published_coupon_type.disabled, 1)                                                                                                                                                                                                                                                                  	62     	tikv_task:{time:0s, loops:2}, scan_detail: {total_process_keys: 62, total_keys: 162}                                                                                                                                                                                                                                                                        	N/A     	N/A
    │   └─TableFullScan_25	cop[tikv]	62     	table:t, keep order:false, stats:pseudo                                                                                                                                                                                                                                                                    	62     	tikv_task:{time:0s, loops:2}                                                                                                                                                                                                                                                                                                                                	N/A     	N/A
    └─IndexLookUp_12      	root     	154.72 	                                                                                                                                                                                                                                                                                                           	62     	time:7.03ms, loops:2, index_task: {total_time: 4.52ms, fetch_handle: 4.52ms, build: 1.2µs, wait: 4.9µs}, table_task: {total_time: 20.6ms, num: 1, concurrency: 4}                                                                                                                                                                                         	58.4 KB 	N/A
      ├─IndexRangeScan_10 	cop[tikv]	154.72 	table:c, index:cousumer_coupontype_index(consumerID, couponTypeID), range: decided by [eq(lrl.coupons.coupontypeid, lrl.published_coupon_type.coupontypeid) eq(lrl.coupons.consumerid, 0FEC45DF-328B-4050-BD3A-94A6301E56FB)], keep order:false                                                            	62     	time:4.51ms, loops:3, cop_task: {num: 1, max: 4.43ms, proc_keys: 62, tot_proc: 3ms, rpc_num: 1, rpc_time: 4.41ms, copr_cache_hit_ratio: 0.00}, tikv_task:{time:3ms, loops:2}, scan_detail: {total_process_keys: 62, total_keys: 124}                                                                                                                        	N/A     	N/A
      └─TableRowIDScan_11 	cop[tikv]	154.72 	table:c, keep order:false                                                                                                                                                                                                                                                                                  	62     	time:2.09ms, loops:2, cop_task: {num: 15, max: 1.87ms, min: 930.8µs, avg: 1.13ms, p95: 1.87ms, max_proc_keys: 23, p95_proc_keys: 23, tot_proc: 1ms, tot_wait: 3ms, rpc_num: 15, rpc_time: 16.7ms, copr_cache_hit_ratio: 0.00}, tikv_task:{proc max:1ms, min:0s, p80:0s, p95:1ms, iters:15, tasks:15}, scan_detail: {total_process_keys: 62, total_keys: 70}	N/A     	N/A

  1. 是不是开了 prepare plan cache?
  2. 是不是用的分区表?
  3. admin check table users 和 userOrder 的结果有报错吗?
  1. 从 tidb-client.pcapng 里查看,prepare 了 60 次,30 次 wangyufu1 和 30 次Value: 004794775538,但是 resopnse 的时候,29 次wangyufu1 和 31 次 004794775538
  2. 对比发现Des port 5141 这里有些问题
  3. 从客户端来看,您可以确认下,一个程序单线程是否有出现过这种情况,都是多线程时出错的吗?能详细描述下,客户端到db端的链接方法和代码吗?
  4. 从db端,麻烦按照上面的反馈下信息,多谢。同时麻烦反馈下表结构。
1 个赞

就是这个问题 prepare-plan-cache,以前做压测的时候打开的没有关掉,但是为什么只有inner join才有这个问题呢,单表sql没这问题:rofl:

感谢各位!:smiley:

@ jackysp-PingCAP

1 个赞

能否麻烦给一下测试代码,我们试试复现这个问题。
麻烦给一下相关完整的表结构吧。
我在测试环境无法复现这个问题,多谢。

测试脚本及数据

两个表里的数据都是我重现问题的真实数据,只不过coupons表在我的环境里有两千多万数据published_coupon_type表有几十条数据

prepare-plan-cache = true的情况下就能重现

tidb.go (1.2 KB) tidb test.sql (19.7 KB)

我试试,非常感谢。
不知道是不是数据量的问题,使用这些数据和代码。测试还是无法复现。
尝试 INL_HASH_JOIN 走 indexhashjoin 还是没有复现:sweat_smile:

集群拓扑图一样的吗,附件是我线上系统 tiup cluster edit-config [] 的配置文件

可能跟数据量也有关系

tidb.config (3.9 KB)