大数据量情况下(单表数据 630亿)插入性能急剧下降

【TiDB 版本】:

Release Version: v3.0.7
Git Commit Hash: 84e4386c7a77d4b8df5db7f2303fb7fd3370eb9a
Git Branch: HEAD
UTC Build Time: 2019-12-04 10:08:24
GoVersion: go version go1.13 linux/amd64
Race Enabled: false
TiKV Min Version: v3.0.0-60965b006877ca7234adaced7890d7b029ed1306
Check Table Before Drop: false

【集群配置】:

  • TiDB + PD: (16CPU + 32GB) * 3
  • TiKV: (16CPU + 32GB + 5T disk) * 10
  • OS: Ubuntu 18.04

note:

  • disk 是用的 aws 的 io1 类型的磁盘

【问题描述】:

背景:

  • 单表数据量:630亿 (通过 tidb-lightning 导入)
  • 磁盘空间占用:3T * 10 (3副本)
  • 表的主键字段类型是 UUID,并且还有一个额外的索引

问题:

  • 导完数据之后,我们继续接即时流量向该表插入数据,QPS 只能达到 2k 左右, 我们最开始做过一亿数据量下的插入测试,只有四台机器的情况下就可以达到 2w QPS
  • 插入的时侯,通过监控可以看到磁盘会产生大量的读请求,下面是一台 tikv 的 iotop 在插入数据时(2k QPS)的截图:
  • 所以,在上述环境下 insert 的 QPS 还有没有办法提高?
  • insert 的时侯,磁盘的读请求远大于写请求,是否合理?如果合理有没有相关配置可以来缓解这个问题?
  • 还有,像我们这种单表大数据量有没有什么指导方针或者最佳实践?

您好: 1. 先手工尝试转到normal模式

   2. 如果还是写入慢,请用长图工具,采集over-view, tidb, tikv-detail, pd 的监控信息上传,多谢

已经确认是 normal 模式了。我还做过另外一个测试:在当前集群新建一张表插入,插入速度可以达到 3w QPS。 新表和旧表的区别就是那 600 多亿条数据。

over-view

tidb

tikv-detail

PD

从监控看,gc时候占用了大量的时间,当前进行了大量的delete操作? 这个业务会不断的删除大量的数据吗?能否查看下?

1、从监控看,可能存在数据热点,建议修改下 tikv-detail --> grpc --> grpc message count 监控面板的公式,查看下各个 tikv 节点 grpc 消息的数量是否均衡:

sum(rate(tikv_grpc_msg_duration_seconds_count{instance=~"$instance", type!="kv_gc"}[1m])) by (type,instance)

{{type}}{{instance}}

2、tikv-detail 监控面板中 raft io --> apply log duration 耗时比较长,表示应用日志耗时较长,并且 rocksdb-kv 以及 rocksdb raft write duraiton 以及 sst read duration 等监控项耗时都比较长,建议查看下 disk performance 监控面板中磁盘的读写延时,以及磁盘带宽情况.

没有 delete 操作,主要是 insert 和少量的 update 操作

  1. kv_get 有热点

  2. 这是一台 tikv aws 这边的磁盘监控:

红色框出来的时间是我在 insert,从上面的图中看,我在 insert 的时侯,却产生了 300MB/s 的读流量

上面这张图是 10 台 tikv 读磁盘的带宽,可以看出确实不均匀,但是所有的流量加起来估计都超过 1GB/s, 而我自己插入程序的日志显示 insert QPS 只有 2k多一点,下面这张图也可以看出:

从这个图看有一个 tikv 使用率 100% ,有热点现象。 写入量较小,PD 的监控图中并未出现热点。 需要看一下 insert 的这个表结构是什么样,还有 insert 的方式是什么样,另外看一下 slow query 里面这个 insert 语句的记录看一下。 这个 100% 使用率的 tikv 磁盘在达到 100% util 时的 iops 与响应时间。

是磁盘 io 撑满了,我贴了 aws 磁盘的监控,insert 的时侯,读的流量非常大,上面贴的盘 300MB/s 的读。我没想明白为什么 insert 会导致读流量这么大?而且insert 的qps 并不大,当然我可以给磁盘继续增加 iops,但是不解决问题。

下面是我的数据表:

CREATE TABLE `g_chat_messages` (
  `message_id` binary(16) NOT NULL,
  `client_ref_id` int(10) unsigned DEFAULT '0',
  `created_time` int(10) unsigned NOT NULL,
  `media_type` tinyint(3) unsigned DEFAULT '0',
  `message_type` tinyint(3) unsigned DEFAULT '0',
  `ndc_id` int(10) unsigned NOT NULL,
  `thread_id` binary(16) NOT NULL,
  `uid` binary(16) NOT NULL,
  `content` mediumtext COLLATE utf8mb4_general_ci DEFAULT NULL,
  `extensions` mediumtext COLLATE utf8mb4_general_ci DEFAULT NULL,
  `media_value` varchar(1000) COLLATE utf8mb4_general_ci DEFAULT NULL,
  PRIMARY KEY (`message_id`),
  KEY `idx_tid` (`thread_id`,`created_time`)
) ENGINE=InnoDB DEFAULT CHARSET=utf8mb4 COLLATE=utf8mb4_general_ci/*!90000 SHARD_ROW_ID_BITS=4 */

下面是一条 slow query 的log:

# Time: 2019-12-27T20:55:14.070916822+08:00
# Txn_start_ts: 413519396325032016
# User: root@10.12.10.217
# Conn_ID: 284418
# Query_time: 3.612195236
# Parse_time: 0.000078978
# Compile_time: 0.000035423
# DB: ndchat
# Is_internal: false
# Digest: 21ac279396eca3f13ae706353ccdb1a8cae894f0e8e3d656ce72859a9a19251d
# Num_cop_tasks: 0
# Prepared: true
# Has_more_results: false
# Succ: true
insert IGNORE INTO g_chat_messages (message_id, client_ref_id, created_time, media_type, message_type, ndc_id, thread_id, uid, content, extensions, media_value) values (?,?,?,?,?,?,?,?,?,?,?) [arguments: (���t�GT�>�U�-��, 646995120, 1576469952, 0, 0, 244304829, �4�q�rF�g�b��, ۙ$�Le����4�, CLEUR, {}, NULL)];

非正常字符是 binary 的 uuid

从上面的 slow log 上可以看出 query 非常耗时,为啥 insert 要去 query,而且从磁盘侧监控看 query 的量如此巨大?

还有是不是单表数据量太大的原因,这张表里插了 630 亿的数据,我在同样的这个集群开一个新表,insert iops 很容易上 2w。

看这个 slow query 信息,这个 sql 不是在 autocommit on 的模式下进行的? 这个 insert 具体是怎么执行的,多少并行,多少行提交一次。 另外能否提供一个 autocommit on 模式下的 slow query 信息

我开了 1000 个 goroutine, 每个 goroutine 里 for 循环不断 insert,每次提交一行。 你说的 autocommit on 是指事物提交吗?

这是我 insert 的 go 代码

func InsertMessage(db *sql.DB, event ChatMsgEvent) (err error) {
	insertSQL := "insert IGNORE INTO g_chat_messages (message_id, client_ref_id, created_time, media_type, message_type, ndc_id, thread_id, uid, content, extensions, media_value) values (?,?,?,?,?,?,?,?,?,?,?)"

	newImage := event.Dynamodb.NewImage

	var mediaValue interface{}
	if len(newImage.Media_value.S) > 0 {
		mediaValue = newImage.Media_value.S
	}

	_, err = db.Exec(insertSQL,
		newImage.Message_id.S[:],
		toInt(newImage.Client_ref_id.N),
		toInt(newImage.Created_time.N),
		toInt(newImage.Media_type.N),
		toInt(newImage.Message_type.N),
		toInt(newImage.Ndc_id.N),
		newImage.Thread_id.S[:],
		newImage.Uid.S[:],
		newImage.Content.S,
		newImage.Extensions.S,
		mediaValue)

	if err != nil {
		return
	}
	return
}

关于自动提交可以看一下这个,看下 autocommit 打开的模式下,慢日志是什么样的。 这个 slow query 里面显示的 3s ,没有提交相关的信息,还没开始写数据,少量的达到 3s 还是大批量是这样? 另外 1000 个线程连 1 个 tidb ,还是 三个?

这是 autocommit=true 的情况下的 slow log:

# Time: 2019-12-28T16:22:37.230001593+08:00
# Txn_start_ts: 413537757913153618
# User: root@10.2.10.27
# Conn_ID: 335317
# Query_time: 2.865894127
# Parse_time: 0.000007463
# Compile_time: 0.000051751
# DB: ndchat
# Is_internal: false
# Digest: 21ac279396eca3f13ae706353ccdb1a8cae894f0e8e3d656ce72859a9a19251d
# Num_cop_tasks: 0
# Prepared: true
# Has_more_results: false
# Succ: true
insert IGNORE INTO g_chat_messages (message_id, client_ref_id, created_time, media_type, message_type, ndc_id, thread_id, uid, content, extensions, media_value) values (?,?,?,?,?,?,?,?,?,?,?) [arguments: �c�t�B�>�S�I<j, 647571192, 1576475711, 0, 0, 211663547, •.��GF�����R�, �Ɂ�]PO����ԥ�0, you light up like a christmad tree, {}, NULL)];

看起来和上一次贴的没有区别。

slow log 刷的很快,每秒 50 条的样子

tikv_trouble_shooting.jsontidb_summary.json 这两个面板的 grafana 数据看一下,这个看起来比较奇怪,slow query 里面有出现大量只有 commit 的语句吗?

上面说的其它表测试 2W 每秒跟这个表结构一致吗?

trouble shooting

tidb summary

16:30 这一波是我刚压的,还是只能到2k左右。

上面说的 2w qps 是在同一集群,完全相同的表结构并且是同一个程序插入的。所以我猜测是这 600亿的数据导致了在 insert 的时侯某些地方要做很重的查询或 get 操作,导致磁盘i的读 io 马上就飙上来了。

tidb_constraint_check_in_place tidb 中这个变量值是什么?

就默认值: 0

global 也是0

大兄弟,有兴趣专门看看这个问题吗?如果解决了,TiDB 单表无压力支撑 630亿数据也可以一段佳话!

kv get 应该是确认是否唯一时的操作,这个问题我们先分析一下。

这个测试 insert 的同时还有少量的 delete 跟 update ,这两个操作语句看一下是不是产生了大量的读?