使用TiFlash做SQL查询时，CPU利用率低

Topstail · 2021 年8 月 19 日 03:05

为提高效率，请提供以下信息，问题描述清晰能够更快得到解决：
【 TiDB 使用环境】
ID Role Host

10.10.10.207:9093 alertmanager 10.10.10.207
10.10.10.207:3000 grafana 10.10.10.207
10.10.10.207:2379 pd 10.10.10.207
10.10.10.208:2379 pd 10.10.10.208
10.10.10.209:2379 pd 10.10.10.209
10.10.10.207:9090 prometheus 10.10.10.207
10.10.10.207:4000 tidb 10.10.10.207
10.10.10.208:4000 tidb 10.10.10.208
10.10.10.209:4000 tidb 10.10.10.209
10.10.10.207:9000 tiflash 10.10.10.207
10.10.10.207:20160 tikv 10.10.10.207
10.10.10.208:20160 tikv 10.10.10.208
10.10.10.209:20160 tikv 10.10.10.209

[root@dbserver01 ~]# lscpu
Architecture: x86_64
CPU op-mode(s): 32-bit, 64-bit
Byte Order: Little Endian
CPU(s): 96
On-line CPU(s) list: 0-95
Thread(s) per core: 2
Core(s) per socket: 24
Socket(s): 2
NUMA node(s): 2

【概述】场景 + 问题概述
我想要使用TPC-H测试TiDB环境在引入了 TiFlash组件之后的性能指标，我发现在我执行TPC-H的SQL语句时，TiFlash进程只能创建出48个线程(我的CPU的物理核数量就是48)，从top的结果来看，几乎只用了50%的逻辑核，剩余的核都处于几乎闲置的状态

【背景】做过哪些优化

set @@tidb_isolation_read_engines=‘tidb,tiflash’;
set @@tidb_allow_mpp=1;
set @@tidb_mem_quota_query = 10 << 30;

当前的TiFlash配置文件：

[root@dbserver01 ~]# cat /tidb-deploy/tiflash-9000/conf/tiflash.toml
default_profile = “default”
display_name = “TiFlash”
http_port = 8123
listen_host = “0.0.0.0”
mark_cache_size = 5368709120
path = “/tiflash_data/tiflash-9000”
tcp_port = 9000
tmp_path = “/tiflash_data/tiflash-9000/tmp”
[application]
runAsDaemon = true
[flash]
service_addr = “10.10.10.207:3930”
tidb_status_addr = “10.10.10.207:10080,10.10.10.208:10080,10.10.10.209:10080”
[flash.flash_cluster]
cluster_manager_path = “/tidb-deploy/tiflash-9000/bin/tiflash/flash_cluster_manager”
log = “/tidb-deploy/tiflash-9000/log/tiflash_cluster_manager.log”
master_ttl = 60
refresh_interval = 20
update_rule_interval = 5
[flash.proxy]
config = “/tidb-deploy/tiflash-9000/conf/tiflash-learner.toml”
[logger]
count = 20
errorlog = “/tidb-deploy/tiflash-9000/log/tiflash_error.log”
level = “info”
log = “/tidb-deploy/tiflash-9000/log/tiflash.log”
size = “1000M”
[profiles]
[profiles.default]
max_memory_usage = 10000000000000
cop_pool_size = 80
batch_cop_pool_size = 80
[raft]
pd_addr = “10.10.10.207:2379,10.10.10.208:2379,10.10.10.209:2379”
[status]
metrics_port = 8234

[root@dbserver01 ~]# cat /tidb-deploy/tiflash-9000/conf/tiflash-learner.toml
log-file = “/tidb-deploy/tiflash-9000/log/tiflash_tikv.log”
log-level = “info”
[raftstore]
apply-pool-size = 4
store-pool-size = 4
[rocksdb]
wal-dir = “”
[security]
ca-path = “”
cert-path = “”
key-path = “”
[server]
addr = “0.0.0.0:20170”
advertise-addr = “10.10.10.207:20170”
advertise-status-addr = “10.10.10.207:20292”
engine-addr = “10.10.10.207:3930”
status-addr = “0.0.0.0:20292”
[storage]
data-dir = “/tiflash_data/tiflash-9000/flash”

【问题】当前遇到的问题
问题一：是什么原因，导致TiFlash进程只能创建和物理核数量的一致的线程数？
问题二：如何修改配置文件或者修改global/session变量可以使TiFlash占用更高的CPU呢？
【TiDB 版本】
Cluster version: v5.1.0

yilong · 2021 年8 月 19 日 08:28

可以先检查下 grafana over-view 监控，是不是有其他资源到达瓶颈了，比如内存或者IO，多谢。

Topstail · 2021 年8 月 19 日 09:34

这是我在执行期间的io和内存情况，看上去这两个方面并不是限制TiFlash线程数的原因，我的网络使用也是万兆网络，看上去应该也不是这些限制了并发数啊，有参数可以修改TiFlash的并发线程数么？

yilong · 2021 年8 月 20 日 03:42

请问你做绑核了吗？
tpch 具体怎么测试的，方便发下步骤吗？是否有配置

Topstail · 2021 年8 月 20 日 05:37

1，我现在没有绑核，总体CPU利用率低；
但是用top查看每个vCPU的使用情况，会发现部分vCPU使用率大于80%，部分vCPU的使用率小于10%，比例几乎为1:1 ，截图请看我在概述一栏中放置的截图

2，tpch大概的操作是：

使用tiup bench tpch prepare
–host 10.10.10.207 --port 4000 --db tpch_100 --password *****
–sf 100
–tiflash
–analyze --tidb_build_stats_concurrency 8 --tidb_distsql_scan_concurrency 30
去创建并导入数据

下载 TPC-H 的 SQL 查询文件：
git clone https://github.com/pingcap/tidb-bench.git && cd tpch/queries

然后修改配置文件调优，重启cluster，使用client连接，做session/global变量的优化，之后就执行从github上下载的sql语句

过程都是按照 TiDB TPC-H 性能对比测试报告 - v4.0 对比 v3.0 | PingCAP Docs这个文档去做的

yilong · 2021 年8 月 20 日 06:06

没有绑核，上面截图 numa node0 和 node1的主要区别是什么？
麻烦反馈下 tiflash 日志和操作系统 message 日志吧，多谢。

Topstail · 2021 年8 月 20 日 06:39

截图主要是为了看tiflash进程在均匀的使用所有的逻辑核还是只是分布到了部分的逻辑核，
事实证明我现在的环境只是使用了部分的逻辑核，使用逻辑核的数量似乎和tiflash创建的线程数有关系，所以我想知道有什么参数，或者配置可以修改tiflash并发的线程数么？
我只能给一些tiflash的日志，由于日志太大，我只截取了近五天的日志tiflash.log (2.3 MB)

yilong · 2021 年8 月 23 日 06:49

能否麻烦反馈下 message 日志，通常在 /var/log 目录下，多谢。

Topstail · 2021 年8 月 24 日 01:36

messages (3.3 MB)
这是message日志

Topstail · 2021 年8 月 24 日 08:44

我刚又找了一台2socket 36core 双线程的服务器，开启HT一共144个核，使用tiflash默认的配置，按照我上边的方式导入TPC-H测试数据，之后执行TPC-H的第一条SQL，这次TiFlash进程可以fork出72个ParalInputsProc线程，还是只能使用一半的core，不知道这是不是一个BUG，还是有什么配置可以修改一下

zz-jason · 2021 年8 月 25 日 00:34

你跑的是 TPC-H 哪个 Query，对应的执行计划也贴一下呢？

Topstail · 2021 年8 月 25 日 01:45

这是我执行的SQL Query:
[root@dbserver01 chihn]# cat /root/tidb-bench/tpch/queries/1.sql
– using 1365545250 as a seed to the RNG

select
l_returnflag,
l_linestatus,
sum(l_quantity) as sum_qty,
sum(l_extendedprice) as sum_base_price,
sum(l_extendedprice * (1 - l_discount)) as sum_disc_price,
sum(l_extendedprice * (1 - l_discount) * (1 + l_tax)) as sum_charge,
avg(l_quantity) as avg_qty,
avg(l_extendedprice) as avg_price,
avg(l_discount) as avg_disc,
count(*) as count_order
from
lineitem
where
l_shipdate <= date_sub(‘1998-12-01’, interval 108 day)
group by
l_returnflag,
l_linestatus
order by
l_returnflag,
l_linestatus;

这是这条sql的执行计划
MySQL [tpch_100]> explain . /root/tidb-bench/tpch/queries/1.sql
±-------------±-------------±--------------±------------------±--------------------±----------------------±----------±-------------±---------±------------+
| l_returnflag | l_linestatus | sum_qty | sum_base_price | sum_disc_price | sum_charge | avg_qty | avg_price | avg_disc | count_order |
±-------------±-------------±--------------±------------------±--------------------±----------------------±----------±-------------±---------±------------+
| A | F | 3775127758.00 | 5660776097194.45 | 5377736398183.9374 | 5592847429515.927026 | 25.499370 | 38236.116984 | 0.050002 | 148047881 |
| N | F | 98553062.00 | 147771098385.98 | 140384965965.0348 | 145999793032.775829 | 25.501557 | 38237.199389 | 0.049985 | 3864590 |
| N | O | 7342080795.00 | 11009436637601.92 | 10458972164526.1722 | 10877338569719.857732 | 25.499852 | 38236.981291 | 0.049998 | 287926407 |
| R | F | 3775724970.00 | 5661603032745.34 | 5378513563915.4097 | 5593662252666.916161 | 25.500066 | 38236.697258 | 0.050001 | 148067261 |
±-------------±-------------±--------------±------------------±--------------------±----------------------±----------±-------------±---------±------------+
4 rows in set (7.577 sec)

windtalker · 2021 年8 月 25 日 02:28

你能贴一下q1的plan吗？
关于只有物理核数个线程的现象，原理上是这样的：
TiFlash 在跑 query 的时候，如果走了 mpp 的话，query 会被切分为多个mpp task，而每个 mpp task 最多是用的线程默认情况下就是该节点的物理核数，所以如果这个query只有一个mpp task，那么只用了物理核数个线程是符合预期的，你可以试一下复杂点的query，比如q5或者q9，再看看TiFlash的线程使用情况。
另外，关于一个mpp task最多使用多少线程这个可以在配置文件里面配置的，在tiup里面可以用config edit修改下TiFlash的max threads
profiles.default.max_threads: 20
这样的话，每个mpp task就能使用20个threads

Topstail · 2021 年8 月 25 日 03:07

MySQL [tpch_100]> . /root/tidb-bench/tpch/queries/1.sql
±-----------------------------------±-------------±----------±------------------±---------------±------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------±-----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------±---------±--------+
| id | estRows | actRows | task | access object | execution info | operator info | memory | disk |
±-----------------------------------±-------------±----------±------------------±---------------±------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------±-----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------±---------±--------+
| Sort_6 | 2.94 | 4 | root | | time:7.3s, loops:2 | tpch_100.lineitem.l_returnflag, tpch_100.lineitem.l_linestatus | 45.4 KB | 0 Bytes |
| └─Projection_8 | 2.94 | 4 | root | | time:7.3s, loops:5, Concurrency:OFF | tpch_100.lineitem.l_returnflag, tpch_100.lineitem.l_linestatus, Column#18, Column#19, Column#20, Column#21, Column#22, Column#23, Column#24, Column#25 | 11.4 KB | N/A |
| └─HashAgg_19 | 2.94 | 4 | root | | time:7.3s, loops:5, partial_worker:{wall_time:7.296835054s, concurrency:16, task_num:1, tot_wait:1m56.746792022s, tot_exec:45.234µs, tot_time:1m56.746866706s, max:7.296735862s, p95:7.296735862s}, final_worker:{wall_time:7.296866946s, concurrency:16, task_num:4, tot_wait:1m56.748746506s, tot_exec:177.468µs, tot_time:1m56.748934104s, max:7.296827525s, p95:7.296827525s} | group by:tpch_100.lineitem.l_linestatus, tpch_100.lineitem.l_returnflag, funcs:sum(Column#26)->Column#18, funcs:sum(Column#27)->Column#19, funcs:sum(Column#28)->Column#20, funcs:sum(Column#29)->Column#21, funcs:avg(Column#30, Column#31)->Column#22, funcs:avg(Column#32, Column#33)->Column#23, funcs:avg(Column#34, Column#35)->Column#24, funcs:count(Column#36)->Column#25, funcs:firstrow(tpch_100.lineitem.l_returnflag)->tpch_100.lineitem.l_returnflag, funcs:firstrow(tpch_100.lineitem.l_linestatus)->tpch_100.lineitem.l_linestatus | 411.2 KB | N/A |
| └─TableReader_20 | 2.94 | 4 | root | | time:7.3s, loops:2, cop_task: {num: 1, max: 0s, proc_keys: 0, copr_cache_hit_ratio: 0.00} | data:HashAgg_10 | 1.54 KB | N/A |
| └─HashAgg_10 | 2.94 | 4 | batchCop[tiflash] | | tiflash_task:{time:7.26s, loops:256, threads:1} | group by:Column#81, Column#82, funcs:sum(Column#71)->Column#26, funcs:sum(Column#72)->Column#27, funcs:sum(Column#73)->Column#28, funcs:sum(Column#74)->Column#29, funcs:count(Column#75)->Column#30, funcs:sum(Column#76)->Column#31, funcs:count(Column#77)->Column#32, funcs:sum(Column#78)->Column#33, funcs:count(Column#79)->Column#34, funcs:sum(Column#80)->Column#35, funcs:count(1)->Column#36 | N/A | N/A |
| └─Projection_40 | 587586521.96 | 587906139 | batchCop[tiflash] | | tiflash_task:{time:5.35s, loops:9898, threads:48} | tpch_100.lineitem.l_quantity, tpch_100.lineitem.l_extendedprice, mul(tpch_100.lineitem.l_extendedprice, minus(1, tpch_100.lineitem.l_discount))->Column#73, mul(mul(tpch_100.lineitem.l_extendedprice, minus(1, tpch_100.lineitem.l_discount)), plus(1, tpch_100.lineitem.l_tax))->Column#74, tpch_100.lineitem.l_quantity, tpch_100.lineitem.l_quantity, tpch_100.lineitem.l_extendedprice, tpch_100.lineitem.l_extendedprice, tpch_100.lineitem.l_discount, tpch_100.lineitem.l_discount, tpch_100.lineitem.l_returnflag, tpch_100.lineitem.l_linestatus | N/A | N/A |
| └─Selection_18 | 587586521.96 | 587906139 | batchCop[tiflash] | | tiflash_task:{time:1.45s, loops:9898, threads:48} | le(tpch_100.lineitem.l_shipdate, 1998-08-15) | N/A | N/A |
| └─TableFullScan_17 | 600037902.00 | 600037902 | batchCop[tiflash] | table:lineitem | tiflash_task:{time:1.08s, loops:9898, threads:48} | keep order:false | N/A | N/A |
±-----------------------------------±-------------±----------±------------------±---------------±------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------±-----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------±---------±--------+

Topstail · 2021 年8 月 25 日 03:10

我整理了q1的plan，sql_1_explain_analyze_result.log (12.3 KB)

windtalker · 2021 年8 月 25 日 03:52

你这个plan没有走mpp 模式，TiFlash 节点仅运行了一个 batchCop 的task，这个task最多使用物理核数个thread，所以和你观察到的现象是符合预期的。你可以配置max_threads来增加TiFlash使用的线程数

Topstail · 2021 年8 月 25 日 05:33

非常感谢，max_threads参数确实可以使我的TiFlash在执行SQL查询期间fork出更多的线程，这次的CPU利用率可以上升到80%以上的性能，
非常感谢

system · 2022 年10 月 31 日 19:05

此话题已在最后回复的 1 分钟后被自动关闭。不再允许新回复。