The query speed of TiFlash is inconsistent

Note:
This topic has been translated from a Chinese forum by GPT and might contain errors.

Original topic: tiflash查询速度时快时慢

| username: shuyu_zhihui

[TiDB Usage Environment] Test Environment
[TiDB Version] 6.15
[Reproduction Path] The operations that led to the issue: executing the same SQL on Navicat and checking the execution plan on the dashboard.
[Encountered Issue: Phenomenon and Impact] With the same data, executing the same SQL twice within 5 minutes, both using TiFlash, the first query takes one minute, while the second query takes 695.5ms.

[Resource Configuration] Navigate to TiDB Dashboard - Cluster Info - Hosts and take a screenshot of this page
[Attachments: Screenshots/Logs/Monitoring]
Execution plan for the faster query:

id task estRows operator info actRows execution info memory disk
TableReader_97 root 1 data:ExchangeSender_96 3 time:687.8ms, loops:2, cop_task: {num: 4, max: 0s, min: 0s, avg: 0s, p95: 0s, copr_cache_hit_ratio: 0.00} N/A N/A
└─ExchangeSender_96 cop[tiflash] 1 ExchangeType: PassThrough 3 tiflash_task:{proc max:684.9ms, min:684ms, p80:684.9ms, p95:684.9ms, iters:2, tasks:2, threads:40} N/A N/A
└─Projection_7 cop[tiflash] 1 crm_biz.t_coupon_item.member_id, crm_biz.t_coupon_item.coupon_type, crm_biz.t_coupon_item.create_time, case(gt(Column#55, 0), 已使用, 未使用)->Column#57, case(Column#55, 1, 0)->Column#58, Column#56 3 tiflash_task:{proc max:684.9ms, min:684ms, p80:684.9ms, p95:684.9ms, iters:2, tasks:2, threads:40} N/A N/A
└─Projection_91 cop[tiflash] 1 Column#55, Column#56, crm_biz.t_coupon_item.member_id, crm_biz.t_coupon_item.coupon_type, crm_biz.t_coupon_item.create_time 3 tiflash_task:{proc max:684.9ms, min:684ms, p80:684.9ms, p95:684.9ms, iters:2, tasks:2, threads:40} N/A N/A
└─HashAgg_89 cop[tiflash] 1 group by:Column#115, Column#116, Column#117, funcs:count(Column#110)->Column#55, funcs:sum(Column#111)->Column#56, funcs:firstrow(Column#112)->crm_biz.t_coupon_item.member_id, funcs:firstrow(Column#113)->crm_biz.t_coupon_item.coupon_type, funcs:firstrow(Column#114)->crm_biz.t_coupon_item.create_time 3 tiflash_task:{proc max:684.9ms, min:684ms, p80:684.9ms, p95:684.9ms, iters:2, tasks:2, threads:2} N/A N/A
└─Projection_98 cop[tiflash] 0.00 if(eq(crm_biz.t_coupon_item.coupon_status, YHQDZT03), 1, )->Column#110, if(eq(crm_biz.t_coupon_item.coupon_status, YHQDZT03), crm_biz.t_coupon_item.amount, 0)->Column#111, crm_biz.t_coupon_item.member_id, crm_biz.t_coupon_item.coupon_type, crm_biz.t_coupon_item.create_time, crm_biz.t_coupon_item.member_id, crm_biz.t_coupon_item.coupon_id, crm_biz.t_coupon_item.create_time 3 tiflash_task:{proc max:684.9ms, min:683ms, p80:684.9ms, p95:684.9ms, iters:3, tasks:2, threads:40} N/A N/A
└─ExchangeReceiver_68 cop[tiflash] 0.00 3 tiflash_task:{proc max:683.9ms, min:682ms, p80:683.9ms, p95:683.9ms, iters:3, tasks:2, threads:40} N/A N/A
└─ExchangeSender_67 cop[tiflash] 0.00 ExchangeType: HashPartition, Hash Cols: [name: crm_biz.t_coupon_item.member_id, collate: binary], [name: crm_biz.t_coupon_item.coupon_id, collate: binary], [name: crm_biz.t_coupon_item.create_time, collate: binary] 3 tiflash_task:{proc max:680.1ms, min:0s, p80:680.1ms, p95:680.1ms, iters:2, tasks:2, threads:40} N/A N/A
└─Selection_66 cop[tiflash] 0.00 eq(crm_biz.t_coupon_item.coupon_id, 1628558630971002882), eq(crm_biz.t_coupon_item.is_deleted, 0), eq(crm_biz.t_coupon_item.status, 1), eq(crm_biz.t_coupon_item.tenant_id, 135490), in(crm_biz.t_coupon_item.coupon_status, YHQDZT02, YHQDZT03), in(crm_biz.t_coupon_item.user_id, 1384806815250747393, 1384807774307717122, 1384807936941854722, 1384808144899641346, 1384808174008111105, 1384808207046643713, 1548974653208727554, 1552597006505000961, 1560492491632398338) 3 tiflash_task:{proc max:680.1ms, min:0s, p80:680.1ms, p95:680.1ms, iters:2, tasks:2, threads:40} N/A N/A
└─TableFullScan_65 cop[tiflash] 75720941 table:t_coupon_item, keep order:false 76501629 tiflash_task:{proc max:539.1ms, min:0s, p80:539.1ms, p95:539.1ms, iters:1210, tasks:2, threads:40} N/A N/A

Execution plan for the slower query:

id task estRows operator info actRows execution info memory disk
TableReader_97 root 1 data:ExchangeSender_96 0 time:1m0.6s, loops:1 N/A N/A
└─ExchangeSender_96 cop[tiflash] 1 ExchangeType: PassThrough 0 N/A N/A
└─Projection_7 cop[tiflash] 1 crm_biz.t_coupon_item.member_id, crm_biz.t_coupon_item.coupon_type, crm_biz.t_coupon_item.create_time, case(gt(Column#55, 0), 已使用, 未使用)->Column#57, case(Column#55, 1, 0)->Column#58, Column#56 0 N/A N/A
└─Projection_91 cop[tiflash] 1 Column#55, Column#56, crm_biz.t_coupon_item.member_id, crm_biz.t_coupon_item.coupon_type, crm_biz.t_coupon_item.create_time 0 N/A N/A
└─HashAgg_89 cop[tiflash] 1 group by:Column#115, Column#116, Column#117, funcs:count(Column#110)->Column#55, funcs:sum(Column#111)->Column#56, funcs:firstrow(Column#112)->crm_biz.t_coupon_item.member_id, funcs:firstrow(Column#113)->crm_biz.t_coupon_item.coupon_type, funcs:firstrow(Column#114)->crm_biz.t_coupon_item.create_time 0 N/A N/A
└─Projection_98 cop[tiflash] 0.00 if(eq(crm_biz.t_coupon_item.coupon_status, YHQDZT03), 1, )->Column#110, if(eq(crm_biz.t_coupon_item.coupon_status, YHQDZT03), crm_biz.t_coupon_item.amount, 0)->Column#111, crm_biz.t_coupon_item.member_id, crm_biz.t_coupon_item.coupon_type, crm_biz.t_coupon_item.create_time, crm_biz.t_coupon_item.member_id, crm_biz.t_coupon_item.coupon_id, crm_biz.t_coupon_item.create_time 0 N/A N/A
└─ExchangeReceiver_68 cop[tiflash] 0.00 0 N/A N/A
└─ExchangeSender_67 cop[tiflash] 0.00 ExchangeType: HashPartition, Hash Cols: [name: crm_biz.t_coupon_item.member_id, collate: binary], [name: crm_biz.t_coupon_item.coupon_id, collate: binary], [name: crm_biz.t_coupon_item.create_time, collate: binary] 0 N/A N/A
└─Selection_66 cop[tiflash] 0.00 eq(crm_biz.t_coupon_item.coupon_id, 1628558630971002882), eq(crm_biz.t_coupon_item.is_deleted, 0), eq(crm_biz.t_coupon_item.status, 1), eq(crm_biz.t_coupon_item.tenant_id, 135490), in(crm_biz.t_coupon_item.coupon_status, YHQDZT02, YHQDZT03), in(crm_biz.t_coupon_item.user_id, 1384806815250747393, 1384807774307717122, 1384807936941854722, 1384808144899641346, 1384808174008111105, 1384808207046643713, 1548974653208727554, 1552597006505000961, 1560492491632398338) 0 N/A N/A
└─TableFullScan_65 cop[tiflash] 75720941 table:t_coupon_item, keep order:false 0 N/A N/A

SQL:
EXPLAIN ANALYZE
SELECT
member_id memberId,
coupon_type couponType,
create_time collectionTime,
CASE
WHEN count(
IF (coupon_status = ‘YHQDZT03’, 1, NULL)
) > 0 THEN ‘已使用’
ELSE ‘未使用’
END couponStatus,
CASE
WHEN count(
IF (coupon_status = ‘YHQDZT03’, 1, NULL)
) THEN 1
ELSE 0
END type,
sum(
IF (coupon_status = ‘YHQDZT03’, amount, 0)
) relateSales
FROM
(
SELECT
member_id,
coupon_type,
create_time,
coupon_status,
coupon_id,
amount
FROM
t_coupon_item
WHERE
STATUS = 1
AND is_deleted = 0
AND coupon_status IN (‘YHQDZT02’, ‘YHQDZT03’)
AND user_id IN (
1384806815250747393,
1384807774307717122,
1384807936941854722,
1384808144899641346,
1384808174008111105,
1384808207046643713,
1548974653208727554,
1552597006505000961,
1560492491632398338
)
AND coupon_id IN (1628558630971002882)
AND tenant_id = ‘135490’
) t1
GROUP BY
member_id,
coupon_id,
create_time;

| username: tidb菜鸟一只 | Original post link

Isn’t it because the data was already cached the first time, so it’s faster the second time?

| username: shuyu_zhihui | Original post link

How long does TiFlash cache data?

| username: tidb菜鸟一只 | Original post link

Adding SQL_NO_CACHE to the SQL statement can prevent data from being cached, right?

| username: shuyu_zhihui | Original post link

Sure, the execution time is 0.6s without caching.

| username: shuyu_zhihui | Original post link

Without using the cache, the execution plan looks normal, unlike the first execution where the execution information only had one row of data:

└─Projection_91 1.00 3 mpp[tiflash] tiflash_task:{proc max:635.6ms, min:426ms, p80:635.6ms, p95:635.6ms, iters:2, tasks:2, threads:40} Column#55, Column#56, crm_biz.t_coupon_item.member_id, crm_biz.t_coupon_item.coupon_type, crm_biz.t_coupon_item.create_time N/A N/A
└─HashAgg_89 1.00 3 mpp[tiflash] tiflash_task:{proc max:634.6ms, min:426ms, p80:634.6ms, p95:634.6ms, iters:2, tasks:2, threads:2} group by:Column#107, Column#108, Column#109, funcs:count(Column#102)->Column#55, funcs:sum(Column#103)->Column#56, funcs:firstrow(Column#104)->crm_biz.t_coupon_item.member_id, funcs:firstrow(Column#105)->crm_biz.t_coupon_item.coupon_type, funcs:firstrow(Column#106)->crm_biz.t_coupon_item.create_time N/A N/A
└─Projection_98 0.00 3 mpp[tiflash] tiflash_task:{proc max:634.6ms, min:425ms, p80:634.6ms, p95:634.6ms, iters:3, tasks:2, threads:40} if(eq(crm_biz.t_coupon_item.coupon_status, YHQDZT03), 1, )->Column#102, if(eq(crm_biz.t_coupon_item.coupon_status, YHQDZT03), crm_biz.t_coupon_item.amount, 0)->Column#103, crm_biz.t_coupon_item.member_id, crm_biz.t_coupon_item.coupon_type, crm_biz.t_coupon_item.create_time, crm_biz.t_coupon_item.member_id, crm_biz.t_coupon_item.coupon_id, crm_biz.t_coupon_item.create_time N/A N/A
└─ExchangeReceiver_68 0.00 3 mpp[tiflash] tiflash_task:{proc max:634.6ms, min:425ms, p80:634.6ms, p95:634.6ms, iters:3, tasks:2, threads:40} N/A N/A
└─ExchangeSender_67 0.00 3 mpp[tiflash] tiflash_task:{proc max:654.5ms, min:0s, p80:654.5ms, p95:654.5ms, iters:2, tasks:2, threads:40} ExchangeType: HashPartition, Hash Cols: [name: crm_biz.t_coupon_item.member_id, collate: binary], [name: crm_biz.t_coupon_item.coupon_id, collate: binary], [name: crm_biz.t_coupon_item.create_time, collate: binary] N/A N/A
└─Selection_66 0.00 3 mpp[tiflash] tiflash_task:{proc max:654.5ms, min:0s, p80:654.5ms, p95:654.5ms, iters:2, tasks:2, threads:40} eq(crm_biz.t_coupon_item.coupon_id, 1628558630971002882), eq(crm_biz.t_coupon_item.is_deleted, 0), eq(crm_biz.t_coupon_item.status, 1), eq(crm_biz.t_coupon_item.tenant_id, 135490), in(crm_biz.t_coupon_item.coupon_status, YHQDZT02, YHQDZT03), in(crm_biz.t_coupon_item.user_id, 1384806815250747393, 1384807774307717122, 1384807936941854722, 1384808144899641346, 1384808174008111105, 1384808207046643713, 1548974653208727554, 1552597006505000961, 1560492491632398338) N/A N/A
└─TableFullScan_65 75720941.00 76467608 mpp[tiflash] table:t_coupon_item tiflash_task:{proc max:494.5ms, min:0s, p80:494.5ms, p95:494.5ms, iters:1216, tasks:2, threads:40} keep order:false N/A N/A
| username: tidb菜鸟一只 | Original post link

Even with sql_no_cache, is the first run still slow and the second run fast?

| username: Running | Original post link

The caching mechanism of TiFlash seems to be still incomplete, and queries involving multiple table joins do not cache results.

| username: Running | Original post link

This is more effective than tikv.

| username: shuyu_zhihui | Original post link

Yes, after adding it, the first query takes 1.6 seconds, and the second query takes 0.86 seconds.

| username: tidb菜鸟一只 | Original post link

But I see that originally there was a difference of 1 minute and 0.6 milliseconds, and now it has become a difference of 1.6 seconds and 0.8 seconds?

| username: system | Original post link

This topic was automatically closed 60 days after the last reply. New replies are no longer allowed.