ERROR 2013 (HY000) Lost connection to MySQL server during query 错误出现场景

select count(id) from account_user where id> 0; 
+----------+
| count(id) |
+----------+
|  2940245 |
+----------+
1 row in set (0.78 sec)

delete from account_user where id> 0; 
ERROR 2013 (HY000): Lost connection to MySQL server during query

tidb.log

2018/11/14 10:57:12.476 server.go:303: [info] con:261 new connection 10.1.88.32:54462
2018/11/14 10:57:15.387 coprocessor.go:689: [info] [TIME_COP_PROCESS] resp_time:792.561353ms txn_start_ts:404269101106331649 region_id:77367 store_addr:10.1.88.84:20160 kv_process_ms:537
2018/11/14 10:57:17.227 pd.go:107: [warning] get timestamp too slow: 135.012109ms
2018/11/14 10:57:17.812 pd.go:107: [warning] get timestamp too slow: 56.316863ms
2018/11/14 10:57:17.821 coprocessor.go:689: [info] [TIME_COP_PROCESS] resp_time:3.226284139s txn_start_ts:404269101106331649 region_id:77863 store_addr:10.1.88.85:20160 kv_process_ms:1580 scan_total_write:314161 scan_processed_write:314160 scan_total_data:314160 scan_processed_data:314160 scan_total_lock:1 scan_processed_lock:0
2018/11/14 10:57:17.826 coprocessor.go:689: [info] [TIME_COP_PROCESS] resp_time:3.231259247s txn_start_ts:404269101106331649 region_id:77590 store_addr:10.1.88.85:20160 kv_process_ms:1807 scan_total_write:355885 scan_processed_write:355884 scan_total_data:355884 scan_processed_data:355884 scan_total_lock:1 scan_processed_lock:0
2018/11/14 10:57:17.872 coprocessor.go:689: [info] [TIME_COP_PROCESS] resp_time:3.276994472s txn_start_ts:404269101106331649 region_id:77576 store_addr:10.1.88.86:20160 kv_process_ms:1684 scan_total_write:346208 scan_processed_write:346207 scan_total_data:346207 scan_processed_data:346207 scan_total_lock:1 scan_processed_lock:0
2018/11/14 10:57:18.074 coprocessor.go:689: [info] [TIME_COP_PROCESS] resp_time:3.48000411s txn_start_ts:404269101106331649 region_id:77448 store_addr:10.1.88.87:20160 kv_process_ms:2701 scan_total_write:431178 scan_processed_write:431177 scan_total_data:431177 scan_processed_data:431177 scan_total_lock:1 scan_processed_lock:0
2018/11/14 10:57:18.270 coprocessor.go:689: [info] [TIME_COP_PROCESS] resp_time:3.675012935s txn_start_ts:404269101106331649 region_id:77664 store_addr:10.1.88.87:20160 kv_process_ms:2221 scan_total_write:343732 scan_processed_write:343731 scan_total_data:343731 scan_processed_data:343731 scan_total_lock:1 scan_processed_lock:0
2018/11/14 10:57:18.273 coprocessor.go:689: [info] [TIME_COP_PROCESS] resp_time:3.679135567s txn_start_ts:404269101106331649 region_id:77463 store_addr:10.1.88.87:20160 kv_process_ms:2976 scan_total_write:363831 scan_processed_write:363830 scan_total_data:363830 scan_processed_data:363830 scan_total_lock:1 scan_processed_lock:0
2018/11/14 10:57:18.347 coprocessor.go:689: [info] [TIME_COP_PROCESS] resp_time:3.751382793s txn_start_ts:404269101106331649 region_id:77698 store_addr:10.1.88.87:20160 kv_process_ms:3110 scan_total_write:334840 scan_processed_write:334839 scan_total_data:334839 scan_processed_data:334839 scan_total_lock:1 scan_processed_lock:0
2018/11/14 10:57:18.402 coprocessor.go:689: [info] [TIME_COP_PROCESS] resp_time:3.807191939s txn_start_ts:404269101106331649 region_id:77509 store_addr:10.1.88.87:20160 kv_process_ms:3559 scan_total_write:354898 scan_processed_write:354897 scan_total_data:354897 scan_processed_data:354897 scan_total_lock:1 scan_processed_lock:0
2018/11/14 10:58:01.645 server.go:303: [info] con:264 new connection 10.1.88.87:42824
2018/11/14 10:58:01.647 set.go:180: [info] con:264 autocommit=0
2018/11/14 10:58:01.649 set.go:180: [info] con:264 autocommit=1
2018/11/14 10:58:01.657 server.go:305: [info] con:264 close connection
2018/11/14 10:58:01.665 server.go:303: [info] con:265 new connection 10.1.88.87:42826
2018/11/14 10:58:01.666 set.go:180: [info] con:265 autocommit=0
2018/11/14 10:58:01.668 set.go:180: [info] con:265 autocommit=1
2018/11/14 10:58:02.203 set.go:180: [info] con:265 autocommit=0
2018/11/14 10:58:02.219 set.go:180: [info] con:265 autocommit=1
2018/11/14 10:58:02.221 server.go:305: [info] con:265 close connection
2018/11/14 10:58:30.110 adapter.go:364: [warning] [SLOW_QUERY] cost_time:1m15.522737043s succ:true con:261 user:root@10.1.88.32 txn_start_ts:404269101106331649 database:uupassport2 table_ids:[4881],sql:delete from account_user where id> 0
2018/11/14 10:58:36.647 pd.go:107: [warning] get timestamp too slow: 1.573956217s
2018/11/14 10:58:38.888 pd.go:107: [warning] get timestamp too slow: 3.424160164s
2018/11/14 10:58:40.357 pd.go:107: [warning] get timestamp too slow: 2.661202907s
2018/11/14 10:58:42.318 pd.go:107: [warning] get timestamp too slow: 1.853675732s
2018/11/14 10:58:42.318 pd.go:107: [warning] get timestamp too slow: 1.018879057s
2018/11/14 10:58:43.093 pd.go:107: [warning] get timestamp too slow: 439.07566ms
2018/11/14 10:58:43.818 pd.go:107: [warning] get timestamp too slow: 708.746703ms
2018/11/14 10:58:44.127 pd.go:107: [warning] get timestamp too slow: 474.285287ms
2018/11/14 10:58:44.900 pd.go:107: [warning] get timestamp too slow: 605.943549ms
2018/11/14 10:58:45.904 pd.go:107: [warning] get timestamp too slow: 646.561164ms
2018/11/14 10:58:46.480 pd.go:107: [warning] get timestamp too slow: 1.119621965s
2018/11/14 10:58:47.590 pd.go:107: [warning] get timestamp too slow: 604.215764ms
2018/11/14 10:58:48.315 pd.go:107: [warning] get timestamp too slow: 1.117343532s
2018/11/14 10:58:48.827 coprocessor.go:689: [info] [TIME_COP_PROCESS] resp_time:3.782055966s txn_start_ts:404269123730931713 region_id:24 store_addr:10.1.88.87:20160 kv_process_ms:126 kv_wait_ms:1195
2018/11/14 10:58:48.920 pd.go:107: [warning] get timestamp too slow: 1.049299486s
2018/11/14 10:58:49.965 adapter.go:364: [warning] [SLOW_QUERY] cost_time:5.323485286s succ:true con:0 user:<nil> txn_start_ts:404269123730931713 database: table_ids:[19],index_ids:[1],sql:SELECT version, table_id, modify_count, count from mysql.stats_meta where version > 404269119627329538 order by version
2018/11/14 10:58:49.738 pd.go:107: [warning] get timestamp too slow: 1.390030711s
2018/11/14 10:58:50.338 pd.go:107: [warning] get timestamp too slow: 1.223162983s
2018/11/14 10:58:50.866 pd.go:107: [warning] get timestamp too slow: 226.798997ms
2018/11/14 10:58:51.229 pd.go:107: [warning] get timestamp too slow: 144.901666ms
2018/11/14 10:58:51.216 pd.go:107: [warning] get timestamp too slow: 136.546657ms
2018/11/14 10:58:53.679 pd.go:107: [warning] get timestamp too slow: 1.193092043s
2018/11/14 10:58:54.195 pd.go:107: [warning] get timestamp too slow: 1.115998075s
2018/11/14 10:58:54.621 pd.go:107: [warning] get timestamp too slow: 256.939543ms
2018/11/14 10:59:11.777 printer.go:38: [info] Welcome to TiDB.
2018/11/14 10:59:11.778 printer.go:39: [info] Release Version: v2.0.6
2018/11/14 10:59:11.778 printer.go:40: [info] Git Commit Hash: b13bc08462a584a085f377625a7bab0cc0351570
2018/11/14 10:59:11.778 printer.go:41: [info] Git Branch: release-2.0
2018/11/14 10:59:11.778 printer.go:42: [info] UTC Build Time:  2018-08-06 10:57:46
2018/11/14 10:59:11.778 printer.go:43: [info] GoVersion:  go version go1.10.2 linux/amd64
2018/11/14 10:59:11.778 printer.go:44: [info] TiKV Min Version: 2.0.0-rc.4.1
2018/11/14 10:59:11.779 printer.go:49: [info] Config: {"host":"0.0.0.0","port":4000,"store":"tikv","path":"10.1.88.33:2379,10.1.88.34:2379,10.1.88.35:2379,10.1.88.84:2379,10.1.88.85:2379,10.1.88.86:2379,10.1.88.87:2379,10.1.88.88:2379,10.1.88.89:2379","socket":"","lease":"45s","run-ddl":true,"split-table":true,"token-limit":1000,"oom-action":"log","mem-quota-query":34359738368,"enable-streaming":false,"lower-case-table-names":2,"log":{"level":"info","format":"text","disable-timestamp":false,"file":{"filename":"/data-deploy/log/tidb.log","log-rotate":true,"max-size":300,"max-days":0,"max-backups":0},"slow-query-file":"","slow-threshold":300,"expensive-threshold":10000,"query-log-max-len":2048},"security":{"skip-grant-table":false,"ssl-ca":"","ssl-cert":"","ssl-key":"","cluster-ssl-ca":"","cluster-ssl-cert":"","cluster-ssl-key":""},"status":{"report-status":true,"status-port":10080,"metrics-addr":"10.1.88.35:9091","metrics-interval":15},"performance":{"max-procs":0,"tcp-keep-alive":true,"retry-limit":10,"cross-join":true,"stats-lease":"3s","run-auto-analyze":true,"stmt-count-limit":5000,"feedback-probability":0,"query-feedback-limit":1024,"pseudo-estimate-ratio":0.7},"xprotocol":{"xserver":false,"xhost":"","xport":0,"xsocket":""},"plan-cache":{"enabled":false,"capacity":2560,"shards":256},"prepared-plan-cache":{"enabled":false,"capacity":100},"opentracing":{"enbale":false,"sampler":{"type":"const","param":1,"sampling-server-url":"","max-operations":0,"sampling-refresh-interval":0},"reporter":{"queue-size":0,"buffer-flush-interval":0,"log-spans":false,"local-agent-host-port":""},"rpc-metrics":false},"proxy-protocol":{"networks":"","header-timeout":5},"tikv-client":{"grpc-connection-count":16,"grpc-keepalive-time":10,"grpc-keepalive-timeout":3,"commit-timeout":"41s"},"binlog":{"binlog-socket":"","write-timeout":"15s","ignore-error":false}}
2018/11/14 10:59:11.779 main.go:193: [info] start Prometheus push client with server addr 10.1.88.35:9091 and interval 15s
2018/11/14 10:59:11.779 tidb.go:279: [info] new store
2018/11/14 10:59:11.779 systime_mon.go:24: [info] start system time monitor
2018/11/14 10:59:11.779 client.go:114: [info] [pd] create pd client with endpoints [10.1.88.33:2379 10.1.88.34:2379 10.1.88.35:2379 10.1.88.84:2379 10.1.88.85:2379 10.1.88.86:2379 10.1.88.87:2379 10.1.88.88:2379 10.1.88.89:2379]
2018/11/14 10:59:11.814 client.go:212: [info] [pd] leader switches to: http://10.1.88.86:2379, previous: 
2018/11/14 10:59:11.814 client.go:133: [info] [pd] init cluster id 6545315499519871548
2018/11/14 10:59:11.827 tidb.go:64: [info] store tikv-6545315499519871548 new domain, ddl lease 45s, stats lease 3000000000
2018/11/14 10:59:11.830 ddl.go:292: [info] [ddl] start delRangeManager OK, with emulator: false
2018/11/14 10:59:12.721 ddl.go:300: [info] [ddl] start DDL:c05296e4-e1bd-482a-a94d-918b59ef3682
2018/11/14 10:59:12.722 ddl_worker.go:71: [info] [ddl] cleaning jobs in the adding index queue finished.
2018/11/14 10:59:13.171 domain.go:117: [info] [ddl] full load InfoSchema from version 0 to 8513, in 85.842074ms
2018/11/14 10:59:13.295 domain.go:309: [info] [ddl] full load and reset schema validator.
2018/11/14 10:59:13.392 gc_worker.go:131: [info] [gc worker] 59c40a2455c0003 start.
2018/11/14 10:59:13.483 server.go:188: [warning] Secure connection is NOT ENABLED
2018/11/14 10:59:13.484 server.go:155: [info] Server is running MySQL Protocol at [0.0.0.0:4000]
2018/11/14 10:59:13.486 http_status.go:75: [info] Listening on :10080 for status and metrics report.
2018/11/14 10:59:13.797 domain.go:651: [info] [stats] init stats info takes 405.752354ms

官方对应解决方法

9.2.1 ERROR 2013 (HY000): Lost connection to MySQL server during query 问题的排查方法?
  • log 中是否有 panic

    未发现

  • dmesg 中是否有 oom,命令: dmesg -T | grep -i oom

    内存当时确实存在飙升,但是未达到溢出的程度 87.5%

  • 长时间没有访问,也会收到这个报错,一般是 tcp 超时导致的,tcp 长时间不用, 会被操作系统 kill。