慢查询中出现sql:commitTxn

为提高效率,提问时请尽量提供详细背景信息,问题描述清晰可优先响应。以下信息点请尽量提供:

  • 系统版本 & kernel 版本
  • TiDB 版本】2.1.4
  • 磁盘型号】ssd
  • 集群节点分布】2tidb,3pd,5tikv
  • 数据量 & region 数量 & 副本数
  • 问题描述(我做了什么)
  • 关键词】 监控报警突然出现超时,查询发现tidb的慢查询日志中有以下信息: 2019/10/08 15:21:57.558 adapter.go:391: [warning] [SLOW_QUERY] cost_time:3.844022869s prewrite_time:3.841386476s commit_time:1.142963ms get_commit_ts_time:798.309µs write_keys:7 write_size:667 prewrite_reg ion:7 succ:true con:6688983 user:zzjgdm@192.168.244.18 txn_start_ts:411702214964019213 database:zzjgdm sql:commitTxn 2019/10/08 15:21:57.591 adapter.go:391: [warning] [SLOW_QUERY] cost_time:3.792387034s prewrite_time:3.790422144s commit_time:978.811µs get_commit_ts_time:317.846µs write_keys:7 write_size:1612 prewrite_reg ion:7 succ:true con:6688985 user:zzjgdm@192.168.244.18 txn_start_ts:411702214990233605 database:zzjgdm sql:commitTxn 2019/10/08 15:21:57.593 adapter.go:391: [warning] [SLOW_QUERY] cost_time:3.789606275s prewrite_time:3.787824367s commit_time:943.673µs get_commit_ts_time:353.733µs write_keys:7 write_size:1581 prewrite_reg ion:7 succ:true con:6688984 user:zzjgdm@192.168.244.19 txn_start_ts:411702214990233606 database:zzjgdm sql:commitTxn 2019/10/08 15:21:57.614 adapter.go:391: [warning] [SLOW_QUERY] cost_time:3.862151203s prewrite_time:3.818986817s commit_time:42.382751ms get_commit_ts_time:171.304µs write_keys:7 write_size:2179 prewrite_r egion:7 succ:true con:6688972 user:zzjgdm@192.168.244.19 txn_start_ts:411702214977126405 database:zzjgdm sql:commitTxn 2019/10/08 15:21:57.621 adapter.go:391: [warning] [SLOW_QUERY] cost_time:3.817874457s prewrite_time:3.787833226s commit_time:29.241782ms get_commit_ts_time:331.884µs write_keys:7 write_size:1824 prewrite_r egion:7 succ:true con:6688986 user:zzjgdm@192.168.244.18 txn_start_ts:411702214990233607 database:zzjgdm sql:commitTxn 2019/10/08 15:21:57.650 adapter.go:391: [warning] [SLOW_QUERY] cost_time:3.401907467s prewrite_time:3.399355079s commit_time:1.462362ms get_commit_ts_time:407.32µs write_keys:7 write_size:682 prewrite_regi on:7 succ:true con:6688976 user:zzjgdm@192.168.244.18 txn_start_ts:411702215108198402 database:zzjgdm sql:commitTxn 2019/10/08 15:21:57.671 adapter.go:391: [warning] [SLOW_QUERY] cost_time:3.116211906s prewrite_time:3.11295669s commit_time:2.785254ms get_commit_ts_time:429.42µs write_keys:2 write_size:1805 prewrite_regi on:2 succ:true con:6688973 user:zzjgdm@192.168.244.18 txn_start_ts:411702215186841603 database:zzjgdm sql:commitTxn 2019/10/08 15:21:57.748 adapter.go:391: [warning] [SLOW_QUERY] cost_time:2.960949992s prewrite_time:2.91137596s commit_time:48.590533ms get_commit_ts_time:450.968µs write_keys:7 write_size:666 prewrite_reg ion:7 succ:true con:6688971 user:zzjgdm@192.168.244.19 txn_start_ts:411702215252377606 database:zzjgdm sql:commitTxn 2019/10/08 15:21:57.756 adapter.go:391: [warning] [SLOW_QUERY] cost_time:2.09925503s prewrite_time:2.09687344s commit_time:1.397345ms get_commit_ts_time:357.698µs write_keys:7 write_size:674 prewrite_regio n:7 succ:true con:6688993 user:zzjgdm@192.168.244.19 txn_start_ts:411702215475200001 database:zzjgdm sql:commitTxn 2019/10/08 15:21:57.764 adapter.go:391: [warning] [SLOW_QUERY] cost_time:2.956625722s prewrite_time:2.901022657s commit_time:54.473538ms get_commit_ts_time:625.854µs write_keys:7 write_size:1771 prewrite_r egion:7 succ:true con:6688990 user:zzjgdm@192.168.244.18 txn_start_ts:411702215252377620 database:zzjgdm sql:commitTxn 2019/10/08 15:21:57.764 adapter.go:391: [warning] [SLOW_QUERY] cost_time:3.98058464s prewrite_time:3.800245126s commit_time:179.463349ms get_commit_ts_time:357.219µs write_keys:7 write_size:1940 prewrite_r egion:7 succ:true con:6688966 user:zzjgdm@192.168.244.19 txn_start_ts:411702214990233604 database:zzjgdm sql:commitTxn 2019/10/08 15:21:57.764 adapter.go:391: [warning] [SLOW_QUERY] cost_time:2.956698201s prewrite_time:2.901534323s commit_time:54.735455ms get_commit_ts_time:400.737µs write_keys:2 write_size:1886 prewrite_r egion:2 succ:true con:6688991 user:zzjgdm@192.168.244.19 txn_start_ts:411702215252377619 database:zzjgdm sql:commitTxn 2019/10/08 15:21:57.771 adapter.go:391: [warning] [SLOW_QUERY] cost_time:2.30934051s prewrite_time:2.283280081s commit_time:25.787206ms get_commit_ts_time:241.418µs write_keys:2 write_size:1263 prewrite_re gion:2 succ:true con:6688967 user:zzjgdm@192.168.244.18 txn_start_ts:411702215422771211 database:zzjgdm sql:commitTxn 2019/10/08 15:21:57.824 adapter.go:391: [warning] [SLOW_QUERY] cost_time:2.449712062s prewrite_time:2.369530189s commit_time:79.820437ms get_commit_ts_time:323.199µs write_keys:2 write_size:1730 prewrite_r egion:2 succ:true con:6688992 user:zzjgdm@192.168.244.19 txn_start_ts:411702215396556823 database:zzjgdm sql:commitTxn 2019/10/08 15:21:57.985 adapter.go:391: [warning] [SLOW_QUERY] cost_time:2.094879466s prewrite_time:1.914765841s commit_time:179.201212ms get_commit_ts_time:427.947µs write_keys:7 write_size:2387 prewrite_ region:7 succ:true con:6688975 user:zzjgdm@192.168.244.19 txn_start_ts:411702215540736001 database:zzjgdm sql:commitTxn 2019/10/08 15:21:58.052 adapter.go:391: [warning] [SLOW_QUERY] cost_time:4.33818295s prewrite_time:3.842014268s commit_time:495.759473ms get_commit_ts_time:373.552µs write_keys:2 write_size:2117 prewrite_r egion:2 succ:true con:6688982 user:zzjgdm@192.168.244.19 txn_start_ts:411702214964019214 database:zzjgdm sql:commitTxn 2019/10/08 15:21:58.052 adapter.go:391: [warning] [SLOW_QUERY] cost_time:4.303111245s prewrite_time:3.821145934s commit_time:481.044595ms get_commit_ts_time:259.094µs write_keys:7 write_size:1825 prewrite_ region:7 succ:true con:6688970 user:zzjgdm@192.168.244.19 txn_start_ts:411702214977126404 database:zzjgdm sql:commitTxn 2019/10/08 15:21:58.053 adapter.go:391: [warning] [SLOW_QUERY] cost_time:4.218116538s prewrite_time:3.768759736s commit_time:448.477007ms get_commit_ts_time:340.64µs write_keys:7 write_size:677 prewrite_re gion:7 succ:true con:6688987 user:zzjgdm@192.168.244.18 txn_start_ts:411702215003340801 database:zzjgdm sql:commitTxn 2019/10/08 15:21:58.053 adapter.go:391: [warning] [SLOW_QUERY] cost_time:4.206789115s prewrite_time:3.762617105s commit_time:443.741142ms get_commit_ts_time:384.968µs write_keys:2 write_size:3316 prewrite_ region:2 succ:true con:6688988 user:zzjgdm@192.168.244.19 txn_start_ts:411702215003340802 database:zzjgdm sql:commitTxn 2019/10/08 15:21:58.058 adapter.go:391: [warning] [SLOW_QUERY] cost_time:3.821833704s prewrite_time:3.410887487s commit_time:409.538131ms get_commit_ts_time:304.461µs write_keys:7 write_size:674 prewrite_r egion:7 succ:true con:6688989 user:zzjgdm@192.168.244.19 txn_start_ts:411702215108198401 database:zzjgdm sql:commitTxn 2019/10/08 15:25:45.254 adapter.go:391: [warning] [SLOW_QUERY] cost_time:3.394047299s prewrite_time:3.392577582s commit_time:669.79µs get_commit_ts_time:244.551µs write_keys:7 write_size:671 prewrite_regio n:7 succ:true con:6692514 user:zzjgdm@192.168.244.18 txn_start_ts:411702274772172808 database:zzjgdm sql:commitTxn 2019/10/08 15:30:33.130 adapter.go:391: [warning] [SLOW_QUERY] cost_time:2.448654106s prewrite_time:2.444199514s commit_time:814.459µs get_commit_ts_time:411.166µs write_keys:7 write_size:2246 prewrite_reg ion:7 succ:true con:6696838 user:zzjgdm@192.168.244.19 txn_start_ts:411702350492467229 database:zzjgdm sql:commitTxn

请问sql:commitTxn个信息是tikv负载较大造成的吗?

是的,写入负载高,或者锁冲突等都有可能造成提交时间慢,可以针对性看下写入量(是否出现了 write stall)、锁冲突等监控。

请问,怎么查看写入量呢?? 因为没有update和delete操作,基本可以排除锁冲突了。

看监控吧,具体如何看可以看官网:https://pingcap.com/docs-cn/v3.0/how-to/monitor/monitor-a-cluster/

另外,因为你的版本是 2.1.4 也有可能是版本 bug 所致,下面是相关 PR,你可以对比一下,解决方案就是升级到 2.1.8 之后的版本。

https://github.com/tikv/tikv/pull/4484