执行SQL报错，当使用select *执行成功后，又好了

Hacker_T3Ux0tQf · 2020 年3 月 31 日 02:09

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

【TiDB 版本】：2.1.19
【问题描述】： select col1,col2,col3 from table where 报如下当错误： ERROR 1105 (HY000): runtime error: invalid memory address or nil pointer dereference

当使用 select * from table where ，执行成功，正常了

再次执行，也正常了…… select col1,col2,col3 from table where

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

Lucien-卢西恩 · 2020 年3 月 31 日 02:15

你可以通过这样方式反馈给我问题，以便定位问题：

登陆对应的 TiDB Server 通过 tail -f 监控 TiDB log 文件输出；
mysql client 登陆 TiDB 数据库，然后执行 select col1,col2,col3 from table where xxx 操作触发报错；
执行 select * from table where xxx 操作证明可以执行成功
反馈 mysql client 执行任务的截图，包括报错的和正常执行的；
反馈对应的那段时间的 TiDB log 的文本数据。

Hacker_T3Ux0tQf · 2020 年3 月 31 日 02:28

Hacker_T3Ux0tQf · 2020 年3 月 31 日 02:32

[2020/03/31 09:48:21.594 +08:00] [ERROR] [coprocessor.go:632] [“copIteratorWork meet panic”] [r="“invalid memory address or nil pointer dereference”"] [“stack trace”=“github.com/pingcap/tidb/store/tikv.(*copIteratorWorker).handleTask.func1\ \t/home/jenkins/agent/workspace/release_tidb_2.1/go/src/github.com/pingcap/tidb/store/tikv/coprocessor.go:634\ runtime.gopanic\ \t/usr/local/go/src/runtime/panic.go:679\ runtime.panicmem\ \t/usr/local/go/src/runtime/panic.go:199\ runtime.sigpanic\ \t/usr/local/go/src/runtime/signal_unix.go:394\ngithub.com/pingcap/tidb/store/tikv.(*copIteratorWorker).logTimeCopTask\ \t/home/jenkins/agent/workspace/release_tidb_2.1/go/src/github.com/pingcap/tidb/store/tikv/coprocessor.go:719\ngithub.com/pingcap/tidb/store/tikv.(*copIteratorWorker).handleTaskOnce\ \t/home/jenkins/agent/workspace/release_tidb_2.1/go/src/github.com/pingcap/tidb/store/tikv/coprocessor.go:691\ngithub.com/pingcap/tidb/store/tikv.(*copIteratorWorker).handleTask\ \t/home/jenkins/agent/workspace/release_tidb_2.1/go/src/github.com/pingcap/tidb/store/tikv/coprocessor.go:643\ngithub.com/pingcap/tidb/store/tikv.(*copIteratorWorker).run\ \t/home/jenkins/agent/workspace/release_tidb_2.1/go/src/github.com/pingcap/tidb/store/tikv/coprocessor.go:472”] [stack=“github.com/pingcap/tidb/store/tikv.(*copIteratorWorker).handleTask.func1\ \t/home/jenkins/agent/workspace/release_tidb_2.1/go/src/github.com/pingcap/tidb/store/tikv/coprocessor.go:632\ runtime.gopanic\ \t/usr/local/go/src/runtime/panic.go:679\ runtime.panicmem\ \t/usr/local/go/src/runtime/panic.go:199\ runtime.sigpanic\ \t/usr/local/go/src/runtime/signal_unix.go:394\ngithub.com/pingcap/tidb/store/tikv.(*copIteratorWorker).logTimeCopTask\ \t/home/jenkins/agent/workspace/release_tidb_2.1/go/src/github.com/pingcap/tidb/store/tikv/coprocessor.go:719\ngithub.com/pingcap/tidb/store/tikv.(*copIteratorWorker).handleTaskOnce\ \t/home/jenkins/agent/workspace/release_tidb_2.1/go/src/github.com/pingcap/tidb/store/tikv/coprocessor.go:691\ngithub.com/pingcap/tidb/store/tikv.(*copIteratorWorker).handleTask\ \t/home/jenkins/agent/workspace/release_tidb_2.1/go/src/github.com/pingcap/tidb/store/tikv/coprocessor.go:643\ngithub.com/pingcap/tidb/store/tikv.(*copIteratorWorker).run\ \t/home/jenkins/agent/workspace/release_tidb_2.1/go/src/github.com/pingcap/tidb/store/tikv/coprocessor.go:472”]

Hacker_T3Ux0tQf · 2020 年3 月 31 日 02:33

[2020/03/31 09:48:22.427 +08:00] [INFO] [coprocessor.go:740] ["[TIME_COP_PROCESS] resp_time:1.834705388s txnStartTS:415660585897951433 region_id:143856 store_addr:10.218.61.243:20160 kv_process_ms:1831 scan_total_write:2 scan_processed_write:2 scan_total_data:2 scan_processed_data:2 scan_total_lock:2 scan_processed_lock:0"] [2020/03/31 09:48:22.427 +08:00] [WARN] [conn.go:535] [“dispatch error”] [conn=41811225] [connInfo=“id:41811225, addr:127.0.0.1:58546 status:10, collation:utf8_general_ci, user:dba”] [command=Query] [status=“inTxn:0, autocommit:1”] [sql=“SELECT poc_inv_alloc_log_id, transaction_id, poc_inv_alloc_id, poc_sku_id, scheduled_selling_id, scheduled_type, warehouse, barcode, oper_type, oper_num, oper_time, oper_result, operator, remark, create_time, retry_times FROM poc_inv_alloc_log where scheduled_selling_id = 10094556 AND barcode = ‘5C685051201140’ AND oper_time >= ‘2019-03-31 00:00:00’ AND oper_time <= ‘2020-03-31 00:00:00’ ORDER BY poc_inv_alloc_log_id+0 DESC LIMIT 0,20”] [err=“runtime error: invalid memory address or nil pointer dereference\ngithub.com/pingcap/tidb/store/tikv.(*copIteratorWorker).handleTask.func1\ \t/home/jenkins/agent/workspace/release_tidb_2.1/go/src/github.com/pingcap/tidb/store/tikv/coprocessor.go:635\ runtime.gopanic\ \t/usr/local/go/src/runtime/panic.go:679\ runtime.panicmem\ \t/usr/local/go/src/runtime/panic.go:199\ runtime.sigpanic\ \t/usr/local/go/src/runtime/signal_unix.go:394\ngithub.com/pingcap/tidb/store/tikv.(*copIteratorWorker).logTimeCopTask\ \t/home/jenkins/agent/workspace/release_tidb_2.1/go/src/github.com/pingcap/tidb/store/tikv/coprocessor.go:719\ngithub.com/pingcap/tidb/store/tikv.(*copIteratorWorker).handleTaskOnce\ \t/home/jenkins/agent/workspace/release_tidb_2.1/go/src/github.com/pingcap/tidb/store/tikv/coprocessor.go:691\ngithub.com/pingcap/tidb/store/tikv.(*copIteratorWorker).handleTask\ \t/home/jenkins/agent/workspace/release_tidb_2.1/go/src/github.com/pingcap/tidb/store/tikv/coprocessor.go:643\ngithub.com/pingcap/tidb/store/tikv.(*copIteratorWorker).run\ \t/home/jenkins/agent/workspace/release_tidb_2.1/go/src/github.com/pingcap/tidb/store/tikv/coprocessor.go:472\ runtime.goexit\ \t/usr/local/go/src/runtime/asm_amd64.s:1357”] [2020/03/31 09:48:22.429 +08:00] [INFO] [server.go:361] [“close connection”] [conn=41855493] [2020/03/31 09:48:22.429 +08:00] [INFO] [server.go:361] [“close connection”] [conn=41855494]

Hacker_T3Ux0tQf · 2020 年3 月 31 日 02:38

之后又成功了

Hacker_T3Ux0tQf · 2020 年3 月 31 日 02:50

invalid_memory_address.log.gz (2.4 MB)

Lucien-卢西恩 · 2020 年3 月 31 日 03:22

感谢反馈，我们需要对这个问题进行一次仔细分析，还需要提供一下对应 SQL 的执行计划，SQL 文本可以脱敏一下。感谢～

方式：

登陆 TiDB Server
执行 explain analyze SQL
反馈这个执行计划和 SQL 文本以及对应的 table schema；

再次感谢～

Hacker_T3Ux0tQf · 2020 年3 月 31 日 03:30

explain.txt (4.0 KB)

Hacker_T3Ux0tQf · 2020 年3 月 31 日 03:32

CREATE TABLE poc_inv_alloc_log ( poc_inv_alloc_log_id bigint(20) UNSIGNED NOT NULL AUTO_INCREMENT COMMENT ‘自增ID’, transaction_id varchar(64) NOT NULL DEFAULT ‘’, poc_inv_alloc_id bigint(20) NOT NULL DEFAULT ‘-1’ , poc_sku_id bigint(20) NOT NULL DEFAULT ‘-1’ , scheduled_selling_id bigint(20) NOT NULL DEFAULT ‘-1’ , scheduled_type tinyint(4) NOT NULL DEFAULT ‘1’ , warehouse varchar(50) NOT NULL DEFAULT ‘’ , barcode varchar(50) NOT NULL DEFAULT ‘’, oper_type int(11) NOT NULL DEFAULT ‘0’ , oper_num int(11) NOT NULL DEFAULT ‘0’ , oper_time timestamp NOT NULL DEFAULT CURRENT_TIMESTAMP ON UPDATE CURRENT_TIMESTAMP, oper_result tinyint(4) NOT NULL DEFAULT ‘-1’ , operator varchar(32) NOT NULL DEFAULT ‘’ , create_time timestamp NOT NULL DEFAULT ‘0000-00-00 00:00:00’ , remark varchar(1000) NOT NULL DEFAULT ‘’ , retry_times int(11) NOT NULL DEFAULT ‘0’, PRIMARY KEY (poc_inv_alloc_log_id), KEY idx_txt_id (transaction_id), KEY idx_oper_time (oper_time), KEY idx_create_time (create_time), KEY idx_schd_barcode_wh (scheduled_selling_id,barcode,warehouse) ) ENGINE=InnoDB DEFAULT CHARSET=utf8mb4 COLLATE=utf8mb4_bin AUTO_INCREMENT=6823541334 ’

Hacker_T3Ux0tQf · 2020 年3 月 31 日 03:34

SQL文本： SELECT poc_inv_alloc_log_id, transaction_id, poc_inv_alloc_id, poc_sku_id, scheduled_selling_id, scheduled_type, warehouse, barcode, oper_type, oper_num, oper_time, oper_result, operator, remark, create_time, retry_times FROM poc_inv_alloc_log where scheduled_selling_id = 10094556 AND barcode = ‘《CODE》’ AND oper_time >= ‘2019-03-31 00:00:00’ AND oper_time <= ‘2020-03-31 00:00:00’ ORDER BY poc_inv_alloc_log_id+0 DESC LIMIT 0,20;

备注： order by +0 是为了规避order by + LIMIT下，可能走了pk scan的问题

Lucien-卢西恩 · 2020 年3 月 31 日 05:29

麻烦提供一下具体的 TiDB、PD、 TIKV 版本信息

方法：

1. 登陆到 TiDB Server 节点，
# 确认对应的 tidb-server 服务
ps -ef  |grep tidb-server 
# 查看版本
./tidb-server  -V
2. 登陆到 TiKV Server 节点，
# 确认对应的 tikv-server 服务
ps -ef  |grep tikv-server 
# 查看版本
./tikv-server  -V
3. 登陆到 PD Server 节点，
# 确认对应的 pd-server 服务
ps -ef  |grep pd-server 
# 查看版本
./pd-server  -V

Hacker_T3Ux0tQf · 2020 年3 月 31 日 06:12

查看版本

./pd-server -V

Release Version: v2.1.19
Git Commit Hash: 4a22762aeb7858baae04e8e1d596f577a8cc18a2
Git Branch: HEAD
UTC Build Time: 2019-12-27 11:31

TiKV
Release Version: 2.1.19
Git Commit Hash: b3c27e3a76fd4ca401285375fc7b042775de08d5
Git Commit Branch: HEAD
UTC Build Time: 2019-12-27 11:31:45
Rust Version: rustc 1.29.0-nightly (4f3c7a472 2018-07-17)

./tidb-server -V
Release Version: v2.1.19
Git Commit Hash: fcbcc4569fbd7aba9eb92092149f092346b934ec
Git Branch: HEAD
UTC Build Time: 2019-12-27 11:32:43
GoVersion: go version go1.13 linux/amd64
Race Enabled: false
TiKV Min Version: 2.1.0-alpha.1-ff3dd160846b7d1aed9079c389fc188f7f5ea13e
Check Table Before Drop: false

Lucien-卢西恩 · 2020 年3 月 31 日 08:25

原因：

TiDB 处理机制，如果 coprocesser task 运行时间超过30ms，就回去拿详细的任务记录打印慢日志，这个时候进行 cop stream 流处理时候就会报错。

解决办法：

在 TiDB 配置文件中禁用掉 stream 处理模式，可以绕过这问题。通过 tidb-ansible/conf/tidb 修改 enable-streaming = false，然后滚动 tidb-server 重启生效。

参数链接

https://github.com/pingcap/tidb/blob/v2.1.19/config/config.toml.example#L41-L42