lightning卡在99%,一直不动

为提高效率,请提供以下信息,问题描述清晰能够更快得到解决:
【 TiDB 使用环境】
生产环境

【概述】 场景 + 问题概述
lightning同步一千万数据
【背景】 做过哪些操作
dumpling拉取数据,lightning摄入数据
【现象】 业务和数据库现象
不影响生产业务
【问题】 当前遇到的问题
lightning卡在99%不动了


【业务影响】

【TiDB 版本】
v5.0.1
【应用软件及版本】

【附件】 相关日志及配置信息
dumpling命令:

tiup dumpling
-u tpcc
-p tpcc
-P 3306
–host “172.16.116.206”
–filetype sql
-f “data_warehouse.t_info_submit_log”
–where “send_time>‘2021-07-15 00:00:00’”
-t 8
-o /tmp/tidb/dumpling/t_info_submit_log
-r 200000
-F 256MiB

tidb-lightning.log (103.4 KB) t_info_submit_log.toml (10.2 KB)


若提问为性能优化、故障排查类问题,请下载脚本运行。终端输出的打印结果,请务必全选并复制粘贴上传。

3赞

杀掉lightning进程重启之后,看日志是执行完成了,但是数据量感觉对不上。tidb-lightning.log (165.1 KB)

2赞

同步多少数据 ?可以用 sync-diff-inspector 做一下数据对比。执行时间卡住这部分,应该是在做 checksum ,校验数据完整性的阶段,但是数据量比较大,所以迟迟没有返回

2赞

数据量在992万左右,同步到900万左右的时候就不动了,这个量级也不是很大。

2赞

那下游 Lightning 导入的 TiDB 的集群可以看一下他的资源情况,可以通过写性能排查手册定位一下问题。

2赞

https://asktug.com/t/topic/68031/9

参考一下这个文档,排查一些下游集群的写入情况,是否存在瓶颈。另外直接点可以看一下 tikv、tidb log 。

2赞

大致看一下,感觉问题不大,不至于卡死不动。
业务正常写入这块儿和平时没有区别





2赞

这是两个tidb节点使用lightning的最后写入记录,都是INFO日志,没有报错
image

2赞

你们是什么盘 ?写入延迟有点高呀 ~

2赞

我们这个是普通的硬盘,没用SSD。
又使用loader加载了一遍,没有什么问题。
使用lightning的时候,必须kill一次重新拉起才能同步完,不然会一直卡着,我找了个五百万的小表,也会卡在90%多。
不过lightning的速度要比loader快很多倍

3赞

建议还是考虑 NVME SSD,毕竟设计开发产品性能也是以 SSD 盘为参考的,所以普通机械盘不能达到预期的性能。

2赞

@peng-xin 使用 tidb backend 的话,应该盘不太会成为瓶颈。

从两次执行的日志里面看,执行到 99% 之后卡住是在等其中一个文件执行完成,对应如下条日志:

[2021/09/14 19:45:52.506 +08:00] [INFO] [restore.go:2626] ["restore file completed"] [table=`data_warehouse`.`t_info_submit_log_week`] [engineNumber=0] [fileIndex=25] [path=data_warehouse.t_info_submit_log.0000016580000.sql:0] [readDur=216.600324ms] [encodeDur=105.620479ms] [deliverDur=21.429286932s] [checksum="{cksum=0,size=175288782,kvs=103152}"] [takeTime=21.580014045s] []

在第一次启动之后,这个文件一直未跑完,直到第二次重启后,只用了 21s 就迅速跑完了,并且第二次启动时其他文件都是瞬间执行完(因为第一次已执行完成)。

麻烦确认一下 data_warehouse.t_info_submit_log.0000016580000.sql 这个文件的内容或大小是不是和其他源文件有明显的不同导致执行可能会卡住。

另外,如果方便重试的话,也可以重跑一下然后在卡住的时候抓一下当前的 go routing 具体操作如下:
在 tidb-lightning.toml 中添加如下配置:

[lightning]
status-addr = ":8289"

然后在 lightning 卡住的时候,访问如下地址:

http://127.0.0.1:8289/debug/pprof/goroutine?debug=2

看一下这个返回的结果,看看线程卡在哪里的话,基本就可以定位原因了

3赞

:rofl:我们这个集群已经跑了两年多了,感觉普通盘也能支撑起来需求,就是第一次用lightning(之前都是用的loader),一直卡住感觉很奇怪。整体用起来体验还是很好的:100:

感谢反馈,如果可以的话,帮忙做一下复现吧。如果是产品问题,我们尽快定位一下。:pray:

您好,这是卡住的时候goroutine返回的内容,我对GO不是很熟,有劳老师看一下。



tidb-lightning-restart.log (466.7 KB) goroutine (59.5 KB) tidb-lightning-firststart.log (405.0 KB) goroutine-block-2 (59.5 KB) goroutine-restart (54.8 KB)

可以参考一下这个文档哈 ,https://studygolang.com/articles/23909

好的,多谢老师。但是这个应该不是火焰图:sweat_smile:

如果问题可以复现,可以按照楼上老师操作,访问这个地址就会抓取一个 pprof ,然后我们再用这个做一下分析。

老师您好,这个是复现之后收集的log信息,也是分为第一次启动和重新启动两部分,restart的都是重新启动的日志,其他的都是第一次卡住时候的日志。每次都卡在90%多

从日志和 goroutine 里面看,两次执行确实都有部分文件在执行的过程中卡住了,具体卡在了 mysql client 创建连接的地方,具体的 routine 如下:

goroutine 4051 [IO wait, 19 minutes]:
internal/poll.runtime_pollWait(0x7fdc79fdfa30, 0x72, 0xffffffffffffffff)
        runtime/netpoll.go:184 +0x55
internal/poll.(*pollDesc).wait(0xc11bb43a98, 0x72, 0x1000, 0x1000, 0xffffffffffffffff)
        internal/poll/fd_poll_runtime.go:87 +0x45
internal/poll.(*pollDesc).waitRead(...)
        internal/poll/fd_poll_runtime.go:92
internal/poll.(*FD).Read(0xc11bb43a80, 0xc16a821000, 0x1000, 0x1000, 0x0, 0x0, 0x0)
        internal/poll/fd_unix.go:169 +0x1cf
net.(*netFD).Read(0xc11bb43a80, 0xc16a821000, 0x1000, 0x1000, 0xc043f52b00, 0x1415ad2, 0xc11bb43a80)
        net/fd_unix.go:202 +0x4f
net.(*conn).Read(0xc03cc1a468, 0xc16a821000, 0x1000, 0x1000, 0x0, 0x0, 0x0)
        net/net.go:184 +0x68
github.com/go-sql-driver/mysql.(*buffer).fill(0xc127eda120, 0x4, 0x300000002, 0xc001020c00)
        github.com/go-sql-driver/mysql@v1.5.0/buffer.go:90 +0x13c
github.com/go-sql-driver/mysql.(*buffer).readNext(0xc127eda120, 0x4, 0xc001020c00, 0xc000069400, 0x203133, 0x203133, 0x203133)
        github.com/go-sql-driver/mysql@v1.5.0/buffer.go:119 +0x9c
github.com/go-sql-driver/mysql.(*mysqlConn).readPacket(0xc127eda120, 0xc4cfea2658, 0xc766a22f20, 0xc043f52d08, 0x1344fd6, 0xc000480700)
        github.com/go-sql-driver/mysql@v1.5.0/packets.go:31 +0x91
github.com/go-sql-driver/mysql.(*mysqlConn).readHandshakePacket(0xc127eda120, 0x1000, 0x1000, 0xc16a821000, 0x0, 0xc000a002ce, 0x13, 0x4083bc0)
        github.com/go-sql-driver/mysql@v1.5.0/packets.go:187 +0x40
github.com/go-sql-driver/mysql.(*connector).Connect(0xc000010c18, 0x4056720, 0xc0000efc40, 0x0, 0x0, 0x0, 0x0)
        github.com/go-sql-driver/mysql@v1.5.0/connector.go:81 +0x45f
database/sql.(*DB).conn(0xc000b4c9c0, 0x4056720, 0xc0000efc40, 0xc043f53201, 0x1345131, 0xc000480700, 0xc50051a000)
        database/sql/sql.go:1228 +0x201
database/sql.(*DB).exec(0xc000b4c9c0, 0x4056720, 0xc0000efc40, 0xc50051a000, 0x10019c, 0x0, 0x0, 0x0, 0xc5000f8001, 0xebe27, ...)
        database/sql/sql.go:1495 +0x66
database/sql.(*DB).ExecContext(0xc000b4c9c0, 0x4056720, 0xc0000efc40, 0xc50051a000, 0x10019c, 0x0, 0x0, 0x0, 0x4020c20, 0xc16a418680, ...)
        database/sql/sql.go:1477 +0xde
github.com/pingcap/br/pkg/lightning/backend/tidb.(*tidbBackend).WriteRowsToDB(0xc0002f3800, 0x4056720, 0xc0000efc40, 0xc000b57440, 0x29, 0x0, 0x0, 0x0, 0x4021220, 0xc090b2a4a0, ...)
        github.com/pingcap/br@/pkg/lightning/backend/tidb/tidb.go:421 +0x577
github.com/pingcap/br/pkg/lightning/backend/tidb.(*tidbBackend).WriteRows(0xc0002f3800, 0x4056720, 0xc0000efc40, 0xc95db5245ddc45a0, 0x9612377a5a82139b, 0xc000b57440, 0x29, 0x0, 0x0, 0x0, ...)
        github.com/pingcap/br@/pkg/lightning/backend/tidb/tidb.go:366 +0x13d
github.com/pingcap/br/pkg/lightning/backend/tidb.(*Writer).AppendRows(0xc220e7ecc0, 0x4056720, 0xc0000efc40, 0xc000b57440, 0x29, 0x0, 0x0, 0x0, 0x0, 0x4021220, ...)
        github.com/pingcap/br@/pkg/lightning/backend/tidb/tidb.go:599 +0xd8

两次执行卡住的文件数不同,然后对应的文件也不同,并且每次重启就能回复,推测可能是 tidb 在处理创建连接请求的时候逻辑有问题导致会卡住,可能需要看一下在卡住的时候,对应的 tidb 的堆栈里面,处理 mysql 连接请求部分的逻辑是否正常