并发增加后，联表查询性能变慢

[Hacker_zsqW7imZ]

为提高效率，提问时请提供以下信息，问题描述清晰可优先响应。

• 【TiDB 版本】：4.0.2
• 【问题描述】：简单两个表关联，慢查询去到几百毫秒，但是查看执行时间显示过程中的时间并不多，然后最后一步执行sql却耗时几百毫秒，这是什么原因呢？
  单独执行耗时很快统计显示也只有2到3ms，但是在并发上来后降几百毫秒

在压测中执行EXPLAIN ANALYZE，发现在root的执行计划会浮动很大：

IndexMergeJoin_18	0.00	0	root		time:124.825988ms, loops:1, Concurrency:OFF	inner join, inner:IndexReader_16, outer key:course.homework.clazz_plan_id, inner key:course.clazz_plan.id	0 Bytes	N/A
├─IndexMergeJoin_50(Build)	0.00	0	root		time:63.201669ms, loops:1, Concurrency:OFF	inner join, inner:Projection_48, outer key:course.student_paper.paper_id, inner key:course.homework.paper_id	0 Bytes	N/A
│ ├─IndexLookUp_75(Build)	0.01	0	root		time:63.217145ms, loops:1, rpc num: 1, rpc time:29.26465ms, proc keys:0		188 Bytes	N/A
│ │ ├─IndexRangeScan_72(Build)	10.00	0	cop[tikv]	table:sp, index:udx_student_paper_student_id_paper_id(student_id, paper_id)	time:0s, loops:1	range:[150607,150607], keep order:false, stats:pseudo	N/A	N/A
│ │ └─Selection_74(Probe)	0.01		cop[tikv]		time:0ns, loops:0	eq(course.student_paper.status, 1)	N/A	N/A
│ │ └─TableRowIDScan_73	10.00	0	cop[tikv]	table:sp	time:0s, loops:0	keep order:false, stats:pseudo	N/A	N/A
│ └─Projection_48(Probe)	0.00		root		time:0ns, loops:0	course.homework.id, course.homework.title, course.homework.type, course.homework.clazz_id, course.homework.clazz_plan_id, course.homework.paper_id, course.homework.arrange_time, course.homework.start_time, course.homework.expired_time, course.homework.status	N/A	N/A
│ └─IndexLookUp_47	0.00		root		time:0ns, loops:0		N/A	N/A
│ ├─Selection_45(Build)	9990.00		cop[tikv]		time:0ns, loops:0	not(isnull(course.homework.paper_id))	N/A	N/A
│ │ └─IndexRangeScan_43	10000.00		cop[tikv]	table:h, index:paper_id(paper_id)	time:0ns, loops:0	range: decided by [eq(course.homework.paper_id, course.student_paper.paper_id)], keep order:true, stats:pseudo	N/A	N/A
│ └─Selection_46(Probe)	0.00		cop[tikv]		time:0ns, loops:0	eq(course.homework.status, 1), gt(course.homework.expired_time, 2020-07-10 00:00:00.000000), in(course.homework.type, 1, 2), lt(course.homework.start_time, 2020-07-11 00:00:00.000000)	N/A	N/A
│ └─TableRowIDScan_44	9990.00		cop[tikv]	table:h	time:0ns, loops:0	keep order:false, stats:pseudo	N/A	N/A
└─IndexReader_16(Probe)	1.00		root		time:0ns, loops:0	index:IndexRangeScan_15	N/A	N/A
└─IndexRangeScan_15	1.00		cop[tikv]	table:cp, index:PRIMARY(id)	time:0ns, loops:0	range: decided by [eq(course.clazz_plan.id, course.homework.clazz_plan_id)], keep order:true	N/A	N/A

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

[yilong (yi888long)]

1. 单独查询快，说明在系统负载不高时是执行计划是正常的.
2. 并发后，先检查执行计划是否和之前相同，如果相同。 可以先检查系统资源是否存在瓶颈，可以按照排查流程检查 TiDB 调优辅助神器 TiDB Performance Map 即将上线！欢迎试用反馈 看看是哪个阶段消耗的时间长。

[Hacker_zsqW7imZ]

这里变高：

看文档get token应该是在纳秒内，但是去到了几秒。然后对比cpu占用并不高：

这是什么原因呢？

[yilong (yi888long)]

1. Get Token Duration：建立连接后获取 Token 耗时， 如果这里时长较久，需要判断 PD 到 TDB-Server 的链路。
2. 检查 PD 整体性能，CPU，内存 ,IO
3. 检查 PD 到 TiDB 的网络是否正常
4. 检查 TiDB 整体性能，CPU，内存，IO
5. 或者检查是否有 pd，tidb，tikv 共同部署的情况，导致消耗资源过高。

[Hacker_zsqW7imZ]

之前的sql已经被业务方优化掉了(走缓存)。
刚才我拿另一条sql重现了一下。PD资源消耗很低。

下面是tidb-server的get token和cpu截图：

[AilinKid-PingCAP (Arenatlx)]

您好，方便看一下 TiKV Coprocessor 部分的负载情况和延迟情况嘛

[Hacker_zsqW7imZ]

是这些吗？

[yilong (yi888long)]

1. 看您这边的并发在5K --10K，tidb-server 的 token-limit默认是 1000，所以获取token会排队，并发太多了。
2. 可以考虑增大token-limit 参数值。 https://github.com/pingcap/tidb/blob/a99fdc098cb3bccc63ca74dad3d682b6f80a0fbd/config/config.toml.example#L32

[AilinKid-PingCAP (Arenatlx)]

多谢，看起 cop duration 不高，SQL 列出的那条计划中包含 pseudo 关键词，说明该表的统计信息暂时不准确。可以尝试 analyse table table_name 来对该表执行真正的统计信息收集。以便能更优计划的生成。

上图列出的那个执行计划由于 range[150607,150607] 范围是单点，并且只有0条数据，所以返回会很快，如果是 result 数据量比较大，indexMergeJoin 可能不是一个很好的执行计划，造成延迟很高，所以统计信息表关键。

[Hacker_zsqW7imZ]

增大之后是一样的表现，这个已经试过了。

[Hacker_zsqW7imZ]

已经analyse过了，但是没有作用。并发的时候还是会很差。
是啊，单独查询返回很快，但是并发就很慢。

[Hacker_zsqW7imZ]

get token除了跟token-limit参数有关，跟pd的哪方面性能有关系呢？ 我们目前参考是的官方部署，但是硬盘使用的是云ssd，只有4000左右的iops，这个有关系吗？

[yilong (yi888long)]

麻烦发一下这个时间段的 over-view，tidb， detail-tikv 多谢

(1)、chrome 安装这个插件https://chrome.google.com/webstore/detail/full-page-screen-capture/fdpohaocaechififmbbbbbknoalclacl

(2)、鼠标焦点置于 Dashboard 上，按 ?可显示所有快捷键，先按 d 再按 E 可将所有 Rows 的 Panels 打开，需等待一段时间待页面加载完成。

(3)、使用这个 full-page-screen-capture 插件进行截屏保存

[Hacker_zsqW7imZ]

ov.pdf

tidb_server.pdf

tikv_server.pdf

[yilong (yi888long)]

1. 从监控来看，基本都在12这个节点，而且有读热点和写热点
   

   
   
   
   

2. 麻烦参考热点文章，尝试打散后看看是否有效，多谢。
   如何分析和解决 TiDB 4.0 的写热点问题

3. empty region 较多，请检查 region merge 是否正常
   [FAQ] 解决已经开启 region merge， empty-region-count 仍然很多问题

[Hacker_zsqW7imZ]

是14点30左右的，后面是压其他的sql了。小表压测成绩很好的，都能去到4w qps左右。这个联表查询单独简单分开查能去到8 9w，但是join了之后只有3 4q，这个性能跌太多了。单独执行只有60-80ms左右的sql。
empty region应该没什么影响吧，我看都是没有fullscan的，这个只会吃一部分心跳资源但是现在服务器资源还有很多冗余。

[yilong (yi888long)]

监控信息我们再分析下，另外是否有压测时的执行计划，可以清楚看到这个sql为什么慢，多谢。

[Hacker_zsqW7imZ]

ok,我重现一下。

执行sql:
SELECT
user.id AS id,
user.username AS username,
user.phone AS phone,
user.role AS role,
user.verify_code AS verify_code,
user.verify_time AS verify_time,
user.is_verified AS is_verified,
user.avatar_oss_id AS avatar_oss_id,
user.access_token AS access_token,
user.is_staff AS is_staff,
user.status AS status,
user.school_id AS school_id,
user.school_name AS school_name,
user.score AS score,
user.grade AS grade,
user.sex AS sex,
user.real_name AS real_name,
user.create_time AS create_time,
user.is_destroy AS is_destroy,
user.destroy_time AS destroy_time,
user.register_activity AS register_activity,
user.register_source AS register_source,
user.ppt_id AS ppt_id,
user.member_id AS member_id,
user.secret AS secret,
user.hash AS hash,
official_a.id AS official_a__id,
official_a.wx_open_id AS official_a__wx_open_id,
official_a.wx_username AS official_a__wx_username,
official_a.wx_avatar AS official_a__wx_avatar,
official_a.wx_phone AS official_a__wx_phone
FROM
users user
LEFT JOIN users_official_account official_a ON user.id = official_a.user_id
AND official_a.status = 1
WHERE
1 = 1
AND user.role = 3
AND user.member_id = ‘11100060923’;

执行计划：
Projection_6 root 1.212497569286898 course.users.id, course.users.username, course.users.phone, course.users.role, course.users.verify_code, course.users.verify_time, course.users.is_verified, course.users.avatar_oss_id, course.users.access_token, course.users.is_staff, course.users.status, course.users.school_id, course.users.school_name, course.users.score, course.users.grade, course.users.sex, course.users.real_name, course.users.create_time, course.users.is_destroy, course.users.destroy_time, course.users.register_activity, course.users.register_source, course.users.ppt_id, course.users.member_id, course.users.secret, course.users.hash, course.users_official_account.id, course.users_official_account.wx_open_id, course.users_official_account.wx_username, course.users_official_account.wx_avatar, course.users_official_account.wx_phone
└─IndexMergeJoin_18 root 1.212497569286898 left outer join, inner:Projection_16, outer key:course.users.id, inner key:course.users_official_account.user_id
├─Selection_24 root 1 eq(course.users.role, 3)
│ └─Point_Get_23 root 1 table:users, index:udx_memberid(member_id)
└─Projection_16 root 1.25 course.users_official_account.id, course.users_official_account.user_id, course.users_official_account.wx_username, course.users_official_account.wx_phone, course.users_official_account.wx_open_id, course.users_official_account.wx_avatar, course.users_official_account.status
└─IndexLookUp_15 root 1.25
├─IndexScan_12 cop 1250 table:official_a, index:idx_uoa_user_id(user_id), range: decided by [eq(course.users_official_account.user_id, course.users.id)], keep order:true, stats:pseudo
└─Selection_14 cop 1.25 eq(course.users_official_account.status, 1)
└─TableScan_13 cop 1250 table:official_a, keep order:false, stats:pseudo

相关监控，查看22:36分后的监控。
https://test.dianbo.zycourse.com/tidb/pdf/ov_2236.pdf
https://test.dianbo.zycourse.com/tidb/pdf/tikv_2236.pdf
https://test.dianbo.zycourse.com/tidb/pdf/ov_2236.pdf

这是我从业务方扣出来了另一个简单join表查询也存在同样问题。这条sql拆开来执行单查user可以去到10wqps,单查office可以去到6w8qps，但是联表之后只有2kqps。非常令人疑惑。

[yilong (yi888long)]

麻烦了，我们再查看一下，多谢。 另外，是说查看 26分以后的监控？ 只到 35 分

[Hacker_zsqW7imZ]

22:36之后，我在这个时间点开始压测的。26-35的不用看。