分区表的一个SQL偶尔变得很慢

  1. 请问您这边的的dashboard方便给个地址我们查看下吗? 告诉下出问题的时间点,多谢。
  2. 或者帮忙查看下问题发生时,coprocessor 耗时多的sql有哪些

1:公司内网并没有做映射,所以现在还访问不到
2:有一点新发现,最开始显示insert变慢,然后再是select变慢





1 个赞

您好,读和写是两个不同的流程,看了集群资源没有瓶颈,所以写应该不会影响读。当前查看读慢,可以重点看下是否有扫描多个key 的读sql存在,多谢。

我也觉得不会影响,因为生产系统的只有这个慢SQL,不存在这个表的insert慢。
我检查了这个点的所有SQL,都是这一个类的SQL,并没有哪个有什么特别的异常,是不是因为分区多了,调用的coprocessor出现资源争抢呢?

当前主要怀疑是有某些扫描多个 key 的大 sql ,或者就是有很多并发加在一起扫描了很多key,从dashboard上看不来是吗?

首先 ,在这个时间段只有我一个人做测试,对这张表进行并发insert和select,都是单一的SQL,不存在其他SQL在执行,所以这个时间段也只有这两个的慢SQL,如果排除insert,那就只有select引起的。但是select我检查了这十多个SQL都没有哪个扫描了多个key,所以我怀疑是多个coprocessor扫描同一个key造成的资源争抢,不过也只是猜测,这个时间段没有其他大SQL的
这个时间段的所有慢SQL:




  1. 从慢日志看,没有特别占用多的,这些是慢sql,可能还有正常的sql也在同时执行, 请问select查询的并发是多少?
  2. T_DEVICE_REQUEST 表的数据量是多少?
  3. 您这边检查下 tidb.log 里有搜索下 expensivequery 吗?
  4. 如果只是用 select 这一条sql 并发,不写入 , 会出现慢吗? 多谢。

1:最开始有这两个SQL:

SELECT
table_id,
is_index,
hist_id,
distinct_count,
version,
null_count,
tot_col_size,
stats_ver,
flag,
correlation,
last_analyze_pos
FROM
mysql.stats_histograms
WHERE
table_id = 14364;
SELECT
table_id,
is_index,
hist_id,
distinct_count,
version,
null_count,
tot_col_size,
stats_ver,
flag,
correlation,
last_analyze_pos
FROM
mysql.stats_histograms
WHERE
table_id = 14364;
都很慢,版本数感觉非常多


另外select的并发在50个线程
2:表数量在200w (测试库),生产在8000w
3:这个时间段没有这种日志,但是发现了一些这种:

[2020/08/12 12:09:52.981 +08:00] [INFO] [server.go:388] [“new connection”] [conn=9818733] [remoteAddr=192.168.0.250:56160]
[2020/08/12 12:09:52.982 +08:00] [INFO] [server.go:388] [“new connection”] [conn=9818746] [remoteAddr=192.168.0.250:56886]
[2020/08/12 12:09:52.982 +08:00] [INFO] [server.go:388] [“new connection”] [conn=9818745] [remoteAddr=192.168.0.250:56883]
[2020/08/12 12:09:53.855 +08:00] [INFO] [region_cache.go:772] [“switch region leader to specific leader due to kv return NotLeader”] [regionID=89717] [currIdx=0] [leaderStoreID=4]
[2020/08/12 12:09:53.858 +08:00] [INFO] [coprocessor.go:871] [“[TIME_COP_PROCESS] resp_time:2.376168954s txnStartTS:418697810143346690 region_id:89717 store_addr:192.168.0.242:20160”]
[2020/08/12 12:09:53.864 +08:00] [INFO] [coprocessor.go:871] [“[TIME_COP_WAIT] resp_time:1.88955298s txnStartTS:418697810261311496 region_id:89705 store_addr:192.168.0.241:20160 kv_wait_ms:1889”] [conn=9818699]
[2020/08/12 12:09:53.864 +08:00] [INFO] [coprocessor.go:871] [“[TIME_COP_WAIT] resp_time:887.344346ms txnStartTS:418697810523455532 region_id:89705 store_addr:192.168.0.241:20160 kv_wait_ms:885”] [conn=9818708]
[2020/08/12 12:09:53.864 +08:00] [INFO] [coprocessor.go:871] [“[TIME_COP_WAIT] resp_time:884.29119ms txnStartTS:418697810523455537 region_id:89705 store_addr:192.168.0.241:20160 kv_wait_ms:883”] [conn=9818723]
[2020/08/12 12:09:53.864 +08:00] [INFO] [coprocessor.go:871] [“[TIME_COP_WAIT] resp_time:888.823114ms txnStartTS:418697810523455513 region_id:89705 store_addr:192.168.0.241:20160 kv_wait_ms:888”] [conn=9818706]
[2020/08/12 12:09:53.864 +08:00] [INFO] [coprocessor.go:871] [“[TIME_COP_WAIT] resp_time:890.069837ms txnStartTS:418697810523455508 region_id:89705 store_addr:192.168.0.241:20160 kv_wait_ms:890”] [conn=9818718]
[2020/08/12 12:09:53.864 +08:00] [INFO] [coprocessor.go:871] [“[TIME_COP_WAIT] resp_time:888.040379ms txnStartTS:418697810523455532 region_id:89705 store_addr:192.168.0.241:20160 kv_wait_ms:887”] [conn=9818708]
[2020/08/12 12:09:53.864 +08:00] [INFO] [coprocessor.go:871] [“[TIME_COP_WAIT] resp_time:1.888288182s txnStartTS:418697810261311497 region_id:89705 store_addr:192.168.0.241:20160 kv_wait_ms:1888”] [conn=9818698]
[2020/08/12 12:09:53.864 +08:00] [INFO] [coprocessor.go:871] [“[TIME_COP_WAIT] resp_time:876.352269ms txnStartTS:418697810536562706 region_id:89705 store_addr:192.168.0.241:20160 kv_wait_ms:876”] [conn=9818726]
[2020/08/12 12:09:53.865 +08:00] [INFO] [coprocessor.go:871] [“[TIME_COP_WAIT] resp_time:879.173249ms txnStartTS:418697810536562729 region_id:89705 store_addr:192.168.0.241:20160 kv_wait_ms:878”] [conn=9818716]
[2020/08/12 12:09:53.865 +08:00] [INFO] [coprocessor.go:871] [“[TIME_COP_WAIT] resp_time:877.812031ms txnStartTS:418697810536562693 region_id:89705 store_addr:192.168.0.241:20160 kv_wait_ms:877”] [conn=9818710]
[2020/08/12 12:09:53.864 +08:00] [INFO] [coprocessor.go:871] [“[TIME_COP_WAIT] resp_time:1.889218233s txnStartTS:418697810261311496 region_id:89705 store_addr:192.168.0.241:20160 kv_wait_ms:1889”] [conn=9818699]
[2020/08/12 12:09:53.865 +08:00] [INFO] [coprocessor.go:871] [“[TIME_COP_WAIT] resp_time:878.759224ms txnStartTS:418697810536562701 region_id:89705 store_addr:192.168.0.241:20160 kv_wait_ms:877”] [conn=9818720]
[2020/08/12 12:09:53.865 +08:00] [INFO] [coprocessor.go:871] [“[TIME_COP_WAIT] resp_time:873.890299ms txnStartTS:418697810536562715 region_id:89705 store_addr:192.168.0.241:20160 kv_wait_ms:873”] [conn=9818725]
[2020/08/12 12:09:53.864 +08:00] [INFO] [coprocessor.go:871] [“[TIME_COP_WAIT] resp_time:1.888236846s txnStartTS:418697810261311497 region_id:89705 store_addr:192.168.0.241:20160 kv_wait_ms:1888”] [conn=9818698]
[2020/08/12 12:09:53.865 +08:00] [INFO] [coprocessor.go:871] [“[TIME_COP_WAIT] resp_time:884.400855ms txnStartTS:418697810523455515 region_id:89705 store_addr:192.168.0.241:20160 kv_wait_ms:883”] [conn=9818703]
[2020/08/12 12:09:53.864 +08:00] [INFO] [coprocessor.go:871] [“[TIME_COP_WAIT] resp_time:1.889471247s txnStartTS:418697810261311495 region_id:89705 store_addr:192.168.0.241:20160 kv_wait_ms:1889”] [conn=9818697]
[2020/08/12 12:09:53.864 +08:00] [INFO] [coprocessor.go:871] [“[TIME_COP_WAIT] resp_time:954.543174ms txnStartTS:418697810510348291 region_id:89705 store_addr:192.168.0.241:20160 kv_wait_ms:954”] [conn=9818700]
[2020/08/12 12:09:53.864 +08:00] [INFO] [coprocessor.go:871] [“[TIME_COP_WAIT] resp_time:890.603407ms txnStartTS:418697810523455508 region_id:89705 store_addr:192.168.0.241:20160 kv_wait_ms:890”] [conn=9818718]
[2020/08/12 12:09:53.864 +08:00] [INFO] [coprocessor.go:871] [“[TIME_COP_WAIT] resp_time:1.889853833s txnStartTS:418697810261311495 region_id:89705 store_addr:192.168.0.241:20160 kv_wait_ms:1889”] [conn=9818697]
[2020/08/12 12:09:53.864 +08:00] [INFO] [coprocessor.go:871] [“[TIME_COP_WAIT] resp_time:887.921987ms txnStartTS:418697810523455526 region_id:89705 store_addr:192.168.0.241:20160 kv_wait_ms:887”] [conn=9818705]
[2020/08/12 12:09:53.864 +08:00] [INFO] [coprocessor.go:871] [“[TIME_COP_WAIT] resp_time:877.096752ms txnStartTS:418697810536562701 region_id:89705 store_addr:192.168.0.241:20160 kv_wait_ms:876”] [conn=9818720]
[2020/08/12 12:09:53.865 +08:00] [INFO] [coprocessor.go:871] [“[TIME_COP_WAIT] resp_time:861.632893ms txnStartTS:418697810536562745 region_id:89705 store_addr:192.168.0.241:20160 kv_wait_ms:856”] [conn=9818732]
[2020/08/12 12:09:53.865 +08:00] [INFO] [coprocessor.go:871] [“[TIME_COP_WAIT] resp_time:873.893285ms txnStartTS:418697810536562716 region_id:89705 store_addr:192.168.0.241:20160 kv_wait_ms:873”] [conn=9818721]
[2020/08/12 12:09:53.865 +08:00] [INFO] [coprocessor.go:871] [“[TIME_COP_WAIT] resp_time:867.228208ms txnStartTS:418697810536562765 region_id:89705 store_addr:192.168.0.241:20160 kv_wait_ms:857”] [conn=9818734]
[2020/08/12 12:09:53.865 +08:00] [INFO] [coprocessor.go:871] [“[TIME_COP_WAIT] resp_time:878.370256ms txnStartTS:418697810536562692 region_id:89705 store_addr:192.168.0.241:20160 kv_wait_ms:877”] [conn=9818712]
[2020/08/12 12:09:53.865 +08:00] [INFO] [coprocessor.go:871] [“[TIME_COP_WAIT] resp_time:883.307319ms txnStartTS:418697810523455529 region_id:89705 store_addr:192.168.0.241:20160 kv_wait_ms:883”] [conn=9818711]
[2020/08/12 12:09:53.865 +08:00] [INFO] [coprocessor.go:871] [“[TIME_COP_WAIT] resp_time:856.287367ms txnStartTS:418697810536562736 region_id:89705 store_addr:192.168.0.241:20160 kv_wait_ms:854”] [conn=9818730]
[2020/08/12 12:09:53.865 +08:00] [INFO] [coprocessor.go:871] [“[TIME_COP_WAIT] resp_time:859.012317ms txnStartTS:418697810536562756 region_id:89705 store_addr:192.168.0.241:20160 kv_wait_ms:856”] [conn=9818735]
[2020/08/12 12:09:53.865 +08:00] [INFO] [coprocessor.go:871] [“[TIME_COP_WAIT] resp_time:877.420348ms txnStartTS:418697810536562704 region_id:89705 store_addr:192.168.0.241:20160 kv_wait_ms:877”] [conn=9818724]
[2020/08/12 12:09:53.865 +08:00] [INFO] [coprocessor.go:871] [“[TIME_COP_WAIT] resp_time:888.589477ms txnStartTS:418697810523455526 region_id:89705 store_addr:192.168.0.241:20160 kv_wait_ms:888”] [conn=9818705]
[2020/08/12 12:09:53.865 +08:00] [INFO] [coprocessor.go:871] [“[TIME_COP_WAIT] resp_time:878.018348ms txnStartTS:418697810536562703 region_id:89705 store_addr:192.168.0.241:20160 kv_wait_ms:876”] [conn=9818714]
[2020/08/12 12:09:53.865 +08:00] [INFO] [coprocessor.go:871] [“[TIME_COP_WAIT] resp_time:852.287368ms txnStartTS:418697810536562748 region_id:89705 store_addr:192.168.0.241:20160 kv_wait_ms:851”] [conn=9818739]
[2020/08/12 12:09:53.865 +08:00] [INFO] [coprocessor.go:871] [“[TIME_COP_WAIT] resp_time:885.151351ms txnStartTS:418697810523455540 region_id:89705 store_addr:192.168.0.241:20160 kv_wait_ms:884”] [conn=9818719]
[2020/08/12 12:09:53.865 +08:00] [INFO] [coprocessor.go:871] [“[TIME_COP_WAIT] resp_time:875.371562ms txnStartTS:418697810536562710 region_id:89705 store_addr:192.168.0.241:20160 kv_wait_ms:874”] [conn=9818701]
[2020/08/12 12:09:53.865 +08:00] [INFO] [coprocessor.go:871] [“[TIME_COP_WAIT] resp_time:861.615681ms txnStartTS:418697810536562739 region_id:89705 store_addr:192.168.0.241:20160 kv_wait_ms:856”] [conn=9818715]
[2020/08/12 12:09:53.865 +08:00] [INFO] [coprocessor.go:871] [“[TIME_COP_WAIT] resp_time:874.096245ms txnStartTS:418697810536562714 region_id:89705 store_addr:192.168.0.241:20160 kv_wait_ms:873”] [conn=9818704]
[2020/08/12 12:09:53.865 +08:00] [INFO] [coprocessor.go:871] [“[TIME_COP_WAIT] resp_time:875.73325ms txnStartTS:418697810536562707 region_id:89705 store_addr:192.168.0.241:20160 kv_wait_ms:874”] [conn=9818722]
[2020/08/12 12:09:53.865 +08:00] [INFO] [coprocessor.go:871] [“[TIME_COP_WAIT] resp_time:878.714019ms txnStartTS:418697810523455529 region_id:89705 store_addr:192.168.0.241:20160 kv_wait_ms:877”] [conn=9818711]
[2020/08/12 12:09:53.865 +08:00] [INFO] [coprocessor.go:871] [“[TIME_COP_WAIT] resp_time:878.040599ms txnStartTS:418697810536562695 region_id:89705 store_addr:192.168.0.241:20160 kv_wait_ms:878”] [conn=9818717]
[2020/08/12 12:09:53.865 +08:00] [INFO] [coprocessor.go:871] [“[TIME_COP_WAIT] resp_time:875.522014ms txnStartTS:418697810536562711 region_id:89705 store_addr:192.168.0.241:20160 kv_wait_ms:874”] [conn=9818702]
[2020/08/12 12:09:53.865 +08:00] [INFO] [coprocessor.go:871] [“[TIME_COP_WAIT] resp_time:871.841814ms txnStartTS:418697810536562754 region_id:89705 store_addr:192.168.0.241:20160 kv_wait_ms:854”] [conn=9818738]
[2020/08/12 12:09:53.865 +08:00] [INFO] [coprocessor.go:871] [“[TIME_COP_WAIT] resp_time:852.546403ms txnStartTS:418697810536562765 region_id:89705 store_addr:192.168.0.241:20160 kv_wait_ms:851”] [conn=9818734]
[2020/08/12 12:09:53.865 +08:00] [INFO] [coprocessor.go:871] [“[TIME_COP_WAIT] resp_time:884.180333ms txnStartTS:418697810523455542 region_id:89705 store_addr:192.168.0.241:20160 kv_wait_ms:883”] [conn=9818728]
[2020/08/12 12:09:53.865 +08:00] [INFO] [coprocessor.go:871] [“[TIME_COP_WAIT] resp_time:874.055259ms txnStartTS:418697810536562758 region_id:89705 store_addr:192.168.0.241:20160 kv_wait_ms:873”] [conn=9818740]
[2020/08/12 12:09:53.865 +08:00] [INFO] [coprocessor.go:871] [“[TIME_COP_WAIT] resp_time:878.16437ms txnStartTS:418697810536562703 region_id:89705 store_addr:192.168.0.241:20160 kv_wait_ms:877”] [conn=9818714]
[2020/08/12 12:09:53.865 +08:00] [INFO] [coprocessor.go:871] [“[TIME_COP_WAIT] resp_time:852.076764ms txnStartTS:418697810536562736 region_id:89705 store_addr:192.168.0.241:20160 kv_wait_ms:851”] [conn=9818730]
[2020/08/12 12:09:53.865 +08:00] [INFO] [coprocessor.go:871] [“[TIME_COP_WAIT] resp_time:852.681346ms txnStartTS:418697810536562748 region_id:89705 store_addr:192.168.0.241:20160 kv_wait_ms:851”] [conn=9818739]
[2020/08/12 12:09:53.865 +08:00] [INFO] [coprocessor.go:871] [“[TIME_COP_WAIT] resp_time:875.280683ms txnStartTS:418697810536562711 region_id:89705 store_addr:192.168.0.241:20160 kv_wait_ms:875”] [conn=9818702]
[2020/08/12 12:09:53.865 +08:00] [INFO] [coprocessor.go:871] [“[TIME_COP_WAIT] resp_time:879.899889ms txnStartTS:418697810536562724 region_id:89705 store_addr:192.168.0.241:20160 kv_wait_ms:879”] [conn=9818707]
[2020/08/12 12:09:53.865 +08:00] [INFO] [coprocessor.go:871] [“[TIME_COP_WAIT] resp_time:883.299854ms txnStartTS:418697810523455513 region_id:89705 store_addr:192.168.0.241:20160 kv_wait_ms:882”] [conn=9818706]
[2020/08/12 12:09:53.865 +08:00] [INFO] [coprocessor.go:871] [“[TIME_COP_WAIT] resp_time:880.275332ms txnStartTS:418697810536562729 region_id:89705 store_addr:192.168.0.241:20160 kv_wait_ms:878”] [conn=9818716]
[2020/08/12 12:09:53.865 +08:00] [INFO] [coprocessor.go:871] [“[TIME_COP_WAIT] resp_time:874.110401ms txnStartTS:418697810536562762 region_id:89705 store_addr:192.168.0.241:20160 kv_wait_ms:873”] [conn=9818733]
[2020/08/12 12:09:53.865 +08:00] [INFO] [coprocessor.go:871] [“[TIME_COP_WAIT] resp_time:873.855023ms txnStartTS:418697810536562715 region_id:89705 store_addr:192.168.0.241:20160 kv_wait_ms:873”] [conn=9818725]
[2020/08/12 12:09:53.865 +08:00] [INFO] [coprocessor.go:871] [“[TIME_COP_WAIT] resp_time:850.2317ms txnStartTS:418697810536562747 region_id:89705 store_addr:192.168.0.241:20160 kv_wait_ms:849”] [conn=9818741]
[2020/08/12 12:09:53.865 +08:00] [INFO] [coprocessor.go:871] [“[TIME_COP_WAIT] resp_time:885.503309ms txnStartTS:418697810523455542 region_id:89705 store_addr:192.168.0.241:20160 kv_wait_ms:884”] [conn=9818728]
[2020/08/12 12:09:53.865 +08:00] [INFO] [coprocessor.go:871] [“[TIME_COP_WAIT] resp_time:877.98224ms txnStartTS:418697810536562699 region_id:89705 store_addr:192.168.0.241:20160 kv_wait_ms:876”] [conn=9818709]
[2020/08/12 12:09:53.865 +08:00] [INFO] [coprocessor.go:871] [“[TIME_COP_WAIT] resp_time:873.334359ms txnStartTS:418697810536562762 region_id:89705 store_addr:192.168.0.241:20160 kv_wait_ms:872”] [conn=9818733]
[2020/08/12 12:09:53.865 +08:00] [INFO] [coprocessor.go:871] [“[TIME_COP_WAIT] resp_time:872.272942ms txnStartTS:418697810536562764 region_id:89705 store_addr:192.168.0.241:20160 kv_wait_ms:856”] [conn=9818745]
[2020/08/12 12:09:53.865 +08:00] [INFO] [coprocessor.go:871] [“[TIME_COP_WAIT] resp_time:873.783489ms txnStartTS:418697810536562756 region_id:89705 store_addr:192.168.0.241:20160 kv_wait_ms:871”] [conn=9818735]
[2020/08/12 12:09:53.865 +08:00] [INFO] [coprocessor.go:871] [“[TIME_COP_WAIT] resp_time:881.250899ms txnStartTS:418697810536562724 region_id:89705 store_addr:192.168.0.241:20160 kv_wait_ms:878”] [conn=9818707]
[2020/08/12 12:09:53.865 +08:00] [INFO] [coprocessor.go:871] [“[TIME_COP_WAIT] resp_time:873.46277ms txnStartTS:418697810536562754 region_id:89705 store_addr:192.168.0.241:20160 kv_wait_ms:872”] [conn=9818738]
[2020/08/12 12:09:53.866 +08:00] [INFO] [coprocessor.go:871] [“[TIME_COP_WAIT] resp_time:879.612502ms txnStartTS:418697810536562692 region_id:89705 store_addr:192.168.0.241:20160 kv_wait_ms:879”] [conn=9818712]
[2020/08/12 12:09:53.866 +08:00] [INFO] [coprocessor.go:871] [“[TIME_COP_WAIT] resp_time:874.930547ms txnStartTS:418697810536562713 region_id:89705 store_addr:192.168.0.241:20160 kv_wait_ms:873”] [conn=9818727]
[2020/08/12 12:09:53.866 +08:00] [INFO] [coprocessor.go:871] [“[TIME_COP_WAIT] resp_time:875.907316ms txnStartTS:418697810536562714 region_id:89705 store_addr:192.168.0.241:20160 kv_wait_ms:874”] [conn=9818704]
[2020/08/12 12:09:53.866 +08:00] [INFO] [coprocessor.go:871] [“[TIME_COP_WAIT] resp_time:879.268978ms txnStartTS:418697810536562699 region_id:89705 store_addr:192.168.0.241:20160 kv_wait_ms:877”] [conn=9818709]
[2020/08/12 12:09:53.866 +08:00] [INFO] [coprocessor.go:871] [“[TIME_COP_WAIT] resp_time:873.905508ms txnStartTS:418697810536562763 region_id:89705 store_addr:192.168.0.241:20160 kv_wait_ms:871”] [conn=9818746]
[2020/08/12 12:09:53.866 +08:00] [INFO] [coprocessor.go:871] [“[TIME_COP_WAIT] resp_time:874.558551ms txnStartTS:418697810536562716 region_id:89705 store_addr:192.168.0.241:20160 kv_wait_ms:873”] [conn=9818721]
[2020/08/12 12:09:53.866 +08:00] [INFO] [coprocessor.go:871] [“[TIME_COP_WAIT] resp_time:870.911984ms txnStartTS:418697810536562755 region_id:89705 store_addr:192.168.0.241:20160 kv_wait_ms:858”] [conn=9818742]
[2020/08/12 12:09:53.866 +08:00] [INFO] [server.go:391] [“connection closed”] [conn=9818718]
[2020/08/12 12:09:53.866 +08:00] [INFO] [coprocessor.go:871] [“[TIME_COP_WAIT] resp_time:873.498636ms txnStartTS:418697810536562761 region_id:89705 store_addr:192.168.0.241:20160 kv_wait_ms:871”] [conn=9818736]
[2020/08/12 12:09:53.866 +08:00] [INFO] [coprocessor.go:871] [“[TIME_COP_WAIT] resp_time:874.305587ms txnStartTS:418697810536562755 region_id:89705 store_addr:192.168.0.241:20160 kv_wait_ms:873”] [conn=9818742]
[2020/08/12 12:09:53.866 +08:00] [INFO] [coprocessor.go:871] [“[TIME_COP_WAIT] resp_time:874.970401ms txnStartTS:418697810536562705 region_id:89705 store_addr:192.168.0.241:20160 kv_wait_ms:873”] [conn=9818713]
[2020/08/12 12:09:53.866 +08:00] [INFO] [server.go:391] [“connection closed”] [conn=9818697]
[2020/08/12 12:09:53.866 +08:00] [INFO] [server.go:391] [“connection closed”] [conn=9818708]
[2020/08/12 12:09:53.865 +08:00] [INFO] [coprocessor.go:871] [“[TIME_COP_WAIT] resp_time:868.781255ms txnStartTS:418697810536562760 region_id:89705 store_addr:192.168.0.241:20160 kv_wait_ms:857”] [conn=9818737]
[2020/08/12 12:09:53.865 +08:00] [INFO] [coprocessor.go:871] [“[TIME_COP_WAIT] resp_time:859.80395ms txnStartTS:418697810536562739 region_id:89705 store_addr:192.168.0.241:20160 kv_wait_ms:856”] [conn=9818715]
[2020/08/12 12:09:53.865 +08:00] [INFO] [coprocessor.go:871] [“[TIME_COP_WAIT] resp_time:878.710162ms txnStartTS:418697810536562693 region_id:89705 store_addr:192.168.0.241:20160 kv_wait_ms:877”] [conn=9818710]
[2020/08/12 12:09:53.865 +08:00] [INFO] [coprocessor.go:871] [“[TIME_COP_WAIT] resp_time:885.860017ms txnStartTS:418697810523455537 region_id:89705 store_addr:192.168.0.241:20160 kv_wait_ms:885”] [conn=9818723]
[2020/08/12 12:09:53.865 +08:00] [INFO] [coprocessor.go:871] [“[TIME_COP_WAIT] resp_time:885.118479ms txnStartTS:418697810523455540 region_id:89705 store_addr:192.168.0.241:20160 kv_wait_ms:884”] [conn=9818719]
[2020/08/12 12:09:53.865 +08:00] [INFO] [coprocessor.go:871] [“[TIME_COP_WAIT] resp_time:877.700001ms txnStartTS:418697810536562704 region_id:89705 store_addr:192.168.0.241:20160 kv_wait_ms:877”] [conn=9818724]
[2020/08/12 12:09:53.867 +08:00] [INFO] [server.go:391] [“connection closed”] [conn=9818711]
[2020/08/12 12:09:53.865 +08:00] [INFO] [coprocessor.go:871] [“[TIME_COP_WAIT] resp_time:877.918971ms txnStartTS:418697810536562695 region_id:89705 store_addr:192.168.0.241:20160 kv_wait_ms:877”] [conn=9818717]
[2020/08/12 12:09:53.865 +08:00] [INFO] [coprocessor.go:871] [“[TIME_COP_WAIT] resp_time:858.847689ms txnStartTS:418697810536562744 region_id:89705 store_addr:192.168.0.241:20160 kv_wait_ms:857”] [conn=9818729]
[2020/08/12 12:09:53.867 +08:00] [INFO] [server.go:391] [“connection closed”] [conn=9818730]
[2020/08/12 12:09:53.865 +08:00] [INFO] [coprocessor.go:871] [“[TIME_COP_WAIT] resp_time:876.864367ms txnStartTS:418697810536562706 region_id:89705 store_addr:192.168.0.241:20160 kv_wait_ms:876”] [conn=9818726]
[2020/08/12 12:09:53.865 +08:00] [INFO] [coprocessor.go:871] [“[TIME_COP_WAIT] resp_time:860.474935ms txnStartTS:418697810536562760 region_id:89705 store_addr:192.168.0.241:20160 kv_wait_ms:856”] [conn=9818737]
[2020/08/12 12:09:53.867 +08:00] [INFO] [server.go:391] [“connection closed”] [conn=9818705]
[2020/08/12 12:09:53.865 +08:00] [INFO] [coprocessor.go:871] [“[TIME_COP_WAIT] resp_time:869.753065ms txnStartTS:418697810536562761 region_id:89705 store_addr:192.168.0.241:20160 kv_wait_ms:856”] [conn=9818736]
[2020/08/12 12:09:53.865 +08:00] [INFO] [coprocessor.go:871] [“[TIME_COP_WAIT] resp_time:852.488164ms txnStartTS:418697810536562751 region_id:89705 store_addr:192.168.0.241:20160 kv_wait_ms:851”] [conn=9818731]
[2020/08/12 12:09:53.865 +08:00] [INFO] [coprocessor.go:871] [“[TIME_COP_WAIT] resp_time:886.471251ms txnStartTS:418697810523455515 region_id:89705 store_addr:192.168.0.241:20160 kv_wait_ms:885”] [conn=9818703]
[2020/08/12 12:09:53.865 +08:00] [INFO] [coprocessor.go:871] [“[TIME_COP_WAIT] resp_time:864.378794ms txnStartTS:418697810536562744 region_id:89705 store_addr:192.168.0.241:20160 kv_wait_ms:856”] [conn=9818729]
[2020/08/12 12:09:53.865 +08:00] [INFO] [coprocessor.go:871] [“[TIME_COP_WAIT] resp_time:854.818406ms txnStartTS:418697810536562758 region_id:89705 store_addr:192.168.0.241:20160 kv_wait_ms:854”] [conn=9818740]
[2020/08/12 12:09:53.865 +08:00] [INFO] [coprocessor.go:871] [“[TIME_COP_WAIT] resp_time:875.644083ms txnStartTS:418697810536562707 region_id:89705 store_addr:192.168.0.241:20160 kv_wait_ms:874”] [conn=9818722]
[2020/08/12 12:09:53.865 +08:00] [INFO] [coprocessor.go:871] [“[TIME_COP_WAIT] resp_time:860.220509ms txnStartTS:418697810536562751 region_id:89705 store_addr:192.168.0.241:20160 kv_wait_ms:856”] [conn=9818731]
[2020/08/12 12:09:53.868 +08:00] [INFO] [server.go:391] [“connection closed”] [conn=9818699]
[2020/08/12 12:09:53.868 +08:00] [INFO] [server.go:391] [“connection closed”] [conn=9818734]
[2020/08/12 12:09:53.865 +08:00] [INFO] [coprocessor.go:871] [“[TIME_COP_WAIT] resp_time:874.539344ms txnStartTS:418697810536562713 region_id:89705 store_addr:192.168.0.241:20160 kv_wait_ms:873”] [conn=9818727]
[2020/08/12 12:09:53.865 +08:00] [INFO] [coprocessor.go:871] [“[TIME_COP_WAIT] resp_time:874.68077ms txnStartTS:418697810536562710 region_id:89705 store_addr:192.168.0.241:20160 kv_wait_ms:873”] [conn=9818701]
[2020/08/12 12:09:53.868 +08:00] [INFO] [server.go:391] [“connection closed”] [conn=9818710]
[2020/08/12 12:09:53.865 +08:00] [INFO] [coprocessor.go:871] [“[TIME_COP_WAIT] resp_time:872.805479ms txnStartTS:418697810536562763 region_id:89705 store_addr:192.168.0.241:20160 kv_wait_ms:856”] [conn=9818746]
[2020/08/12 12:09:53.865 +08:00] [INFO] [coprocessor.go:871] [“[TIME_COP_WAIT] resp_time:859.32853ms txnStartTS:418697810536562745 region_id:89705 store_addr:192.168.0.241:20160 kv_wait_ms:856”] [conn=9818732]
[2020/08/12 12:09:53.865 +08:00] [INFO] [coprocessor.go:871] [“[TIME_COP_WAIT] resp_time:850.655965ms txnStartTS:418697810536562747 region_id:89705 store_addr:192.168.0.241:20160 kv_wait_ms:850”] [conn=9818741]
[2020/08/12 12:09:53.865 +08:00] [INFO] [coprocessor.go:871] [“[TIME_COP_WAIT] resp_time:955.064239ms txnStartTS:418697810510348291 region_id:89705 store_addr:192.168.0.241:20160 kv_wait_ms:954”] [conn=9818700]
[2020/08/12 12:09:53.868 +08:00] [INFO] [server.go:391] [“connection closed”] [conn=9818717]
[2020/08/12 12:09:53.865 +08:00] [INFO] [coprocessor.go:871] [“[TIME_COP_WAIT] resp_time:852.522939ms txnStartTS:418697810536562764 region_id:89705 store_addr:192.168.0.241:20160 kv_wait_ms:852”] [conn=9818745]
[2020/08/12 12:09:53.869 +08:00] [INFO] [server.go:391] [“connection closed”] [conn=9818706]
[2020/08/12 12:09:53.865 +08:00] [INFO] [coprocessor.go:871] [“[TIME_COP_WAIT] resp_time:875.812388ms txnStartTS:418697810536562705 region_id:89705 store_addr:192.168.0.241:20160 kv_wait_ms:874”] [conn=9818713]
[2020/08/12 12:09:53.869 +08:00] [INFO] [server.go:391] [“connection closed”] [conn=9818707]
[2020/08/12 12:09:53.869 +08:00] [INFO] [server.go:388] [“new connection”] [conn=9818744] [remoteAddr=192.168.0.250:56871]
[2020/08/12 12:09:53.869 +08:00] [INFO] [server.go:388] [“new connection”] [conn=9818743] [remoteAddr=192.168.0.250:56847]
[2020/08/12 12:09:53.869 +08:00] [INFO] [server.go:391] [“connection closed”] [conn=9818740]
[2020/08/12 12:09:53.870 +08:00] [INFO] [server.go:391] [“connection closed”] [conn=9818727]
[2020/08/12 12:09:53.870 +08:00] [INFO] [server.go:391] [“connection closed”] [conn=9818720]
[2020/08/12 12:09:53.870 +08:00] [INFO] [server.go:391] [“connection closed”] [conn=9818733]
[2020/08/12 12:09:53.871 +08:00] [INFO] [server.go:391] [“connection closed”] [conn=9818738]
[2020/08/12 12:09:53.871 +08:00] [INFO] [server.go:391] [“connection closed”] [conn=9818715]
[2020/08/12 12:09:53.871 +08:00] [INFO] [server.go:391] [“connection closed”] [conn=9818714]
[2020/08/12 12:09:53.871 +08:00] [INFO] [server.go:388] [“new connection”] [conn=9818747] [remoteAddr=192.168.0.250:56910]
[2020/08/12 12:09:53.872 +08:00] [INFO] [server.go:391] [“connection closed”] [conn=9818723]
[2020/08/12 12:09:53.872 +08:00] [INFO] [server.go:391] [“connection closed”] [conn=9818728]
[2020/08/12 12:09:53.872 +08:00] [INFO] [server.go:391] [“connection closed”] [conn=9818709]
4:我测试一下,等会儿给答案

1 个赞
  1. 从您的截图看在这个时间段访问不到leader后,感觉开始出现了一些cop proce 时长变长,进而 cop wait 变长

  2. 如果只是查询,从您的监控信息看,没有看到太高的资源占用,不知道是不是可能这个region分裂了,再往前是否有这个region 89717 的信息? 这个只是猜测

  3. 如果只测试select应该不会有分裂,所以是不是不会出现延迟? 请问有验证吗?多谢。

2:发现一些东西
[2020/08/12 12:09:18.486 +08:00] [INFO] [region_cache.go:772] ["switch region leader to specific leader due to kv return NotLeader"] [regionID=89717] [currIdx=1] [leaderStoreID=1]
它在09:18的时候还是leaderStoreID=1
但是到了出问题的那个时间,它切换到4 ,然后开始出现慢SQL

[2020/08/12 12:09:53.855 +08:00] [INFO] [region_cache.go:772] [“switch region leader to specific leader due to kv return NotLeader”] [regionID=89717] [currIdx=0] [leaderStoreID=4]
[2020/08/12 12:09:53.858 +08:00] [INFO] [coprocessor.go:871] ["[TIME_COP_PROCESS] resp_time:2.376168954s txnStartTS:418697810143346690 region_id:89717 store_addr:192.168.0.242:20160"]
3:这个问题只是偶尔出现,昨天测试了2小时也没出现,我今天继续测一下

我们看下这个 region id 具体是什么吧,和慢的这个sql有没有关系,返回下下面这个结果

curl http://{TiDBIP}:10080/regions/{regionID}

刚刚测试又出现了:

[2020/09/08 10:35:37.490 +08:00] [INFO] [coprocessor.go:871] ["[TIME_COP_WAIT] resp_time:315.963008ms txnStartTS:419307857423106092 region_id:89545 store_addr:192.168.0.244:20160 kv_wait_ms:315"] [conn=11327973]
[2020/09/08 10:35:37.490 +08:00] [INFO] [coprocessor.go:871] ["[TIME_COP_WAIT] resp_time:315.395797ms txnStartTS:419307857423106092 region_id:89545 store_addr:192.168.0.244:20160 kv_wait_ms:315"] [conn=11327973]
[2020/09/08 10:35:37.490 +08:00] [INFO] [coprocessor.go:871] ["[TIME_COP_WAIT] resp_time:315.986191ms txnStartTS:419307857423106096 region_id:89545 store_addr:192.168.0.244:20160 kv_wait_ms:315"] [conn=11327987]
[2020/09/08 10:35:37.490 +08:00] [INFO] [coprocessor.go:871] ["[TIME_COP_WAIT] resp_time:304.550631ms txnStartTS:419307857423106211 region_id:89545 store_addr:192.168.0.244:20160 kv_wait_ms:304"] [conn=11328001]
[2020/09/08 10:35:37.490 +08:00] [INFO] [coprocessor.go:871] ["[TIME_COP_WAIT] resp_time:315.957207ms txnStartTS:419307857409998954 region_id:89545 store_addr:192.168.0.244:20160 kv_wait_ms:315"] [conn=11327949]

然后我查这个region(以前那个region太久了 ,现在已经查不到了)

{
“region_id”: 89545,
“start_key”: “dIAAAAAAADgd”,
“end_key”: “dIAAAAAAADge”,
“frames”: [
{
“db_name”: “test”,
“table_name”: “t_device_request(p20200706)”,
“table_id”: 14365,
“is_record”: false,
“index_name”: “PRIMARY”,
“index_id”: 1
},
{
“db_name”: “test”,
“table_name”: “t_device_request(p20200706)”,
“table_id”: 14365,
“is_record”: false,
“index_name”: “INDEX_REQUEST_ORI_SEQ”,
“index_id”: 2
},
{
“db_name”: “test”,
“table_name”: “t_device_request(p20200706)”,
“table_id”: 14365,
“is_record”: false,
“index_name”: “INDEX_REQUEST_REQ_SEQ”,
“index_id”: 3
},
{
“db_name”: “test”,
“table_name”: “t_device_request(p20200706)”,
“table_id”: 14365,
“is_record”: false,
“index_name”: “INDEX_REQUEST_TIME”,
“index_id”: 4
},
{
“db_name”: “test”,
“table_name”: “t_device_request(p20200706)”,
“table_id”: 14365,
“is_record”: true
}
]
}[

  1. 只有这些 time_cop_wait 慢的日志吗? 有没有switch的信息,麻烦把这些日志上传下吧
  2. 麻烦再看下dashboard上的慢日志,按照各种顺序排列,看看在问题出现前是否有大sql,多谢。

2:


除了有几个insert的慢SQL ,其他都没有
1:日志
tidb_10.rar (1.6 MB)

另外我把insert线程停了之后,已经测试了4个小时了,没再出现慢SQL,感觉就是和insert有关

还是出现了

不要按照结束时间,麻烦按照后面几个也排序反馈下,辛苦了,多谢。 时间范围可以长一些

最近一天的:
最长执行时间:


最长coprocessor消耗时间:

最大内存消耗:

  1. 多谢多谢,从慢日志看发生问题集中在上午的10:35 和 下午的 15:27, 麻烦您把下午 15:27 这段时间的日志也发我下,我查看一下这两个时间点的日志,多谢。

文件太大,我传到网盘了:
链接: https://pan.baidu.com/s/1TdXXr7l4jWjCkRhyIgHk2A 提取码: i6qj