golang中mysql建立连接超时时间timeout 测试

雨点打透心脏的1/2处 2023-06-10 13:21 22阅读 0赞

本文测试连接mysql的超时时间。

这里的“连接”是建立连接的意思。

连接mysql的超时时间是通过参数timeout设置的。

# 1.建立连接超时测试 #

下面例子中，设置连接超时时间为5s，读超时时间6s。  
MySQL server IP是192.168.0.101，端口3306。

每3s执行一次SQL。

// simple.go
    
    package main
    
    import (
            "database/sql"
            "log"
            "time"
    
            _ "github.com/go-sql-driver/mysql"
    )
    
    var DB *sql.DB
    var dataBase = "root:Aa123456@tcp(192.168.0.101:3306)/?timeout=5s&readTimeout=6s"
    
    func mysqlInit() {
            var err error
            DB, err = sql.Open("mysql", dataBase)
            if err != nil {
                    log.Fatalln("open db fail:", err)
            }
    
            DB.SetMaxOpenConns(3)
            DB.SetMaxIdleConns(3)
    }
    
    func main() {
            mysqlInit()
    
            for {
                    log.Println("start")
                    execSql()
                    time.Sleep(3*time.Second)
            }
    }
    
    func execSql() {
            var value int
            err := DB.QueryRow("select 1").Scan(&value)
            if err != nil {
                    log.Println("query failed:", err)
                    return
            }
    
            log.Println("value:", value)
    }

启动程序：

go run simple.go

之后，接着在客户端使用iptables将所有发送到MySQL服务的数据包drop掉.

清除所有的过滤规则，防止干扰:

sudo iptables -F

设置drop策略：

sudo iptables -A OUTPUT -p tcp --dport 3306 -d 192.168.0.101 -j DROP

查看策略：

[root@localhost lanyang]# iptables -nxvL
    Chain INPUT (policy ACCEPT 4 packets, 505 bytes)
        pkts      bytes target     prot opt in     out     source               destination         
    
    Chain FORWARD (policy ACCEPT 0 packets, 0 bytes)
        pkts      bytes target     prot opt in     out     source               destination         
    
    Chain OUTPUT (policy ACCEPT 4 packets, 304 bytes)
        pkts      bytes target     prot opt in     out     source               destination         
          49     3025 DROP       tcp  --  *      *       0.0.0.0/0            192.168.0.101       tcp dpt:3306

或者在MySQL上设置iptables规则，效果是一样的：

sudo iptables -A INPUT -p tcp --dport 3306 -d 192.168.0.101 -j DROP

这样就会触发重试机制，最后超时。

output:

2019/10/27 18:34:52 start
    2019/10/27 18:34:52 value: 1
    2019/10/27 18:34:55 start
    2019/10/27 18:34:55 value: 1
    2019/10/27 18:34:58 start
    2019/10/27 18:34:58 value: 1
    2019/10/27 18:35:01 start
    [mysql] 2019/10/27 18:35:07 packets.go:36: read tcp 192.168.0.104:54462->192.168.0.101:3306: i/o timeout
    2019/10/27 18:35:07 query failed: invalid connection
    2019/10/27 18:35:10 start
    [mysql] 2019/10/27 18:35:15 driver.go:81: net.Error from Dial()': dial tcp 192.168.0.101:3306: i/o timeout
    [mysql] 2019/10/27 18:35:20 driver.go:81: net.Error from Dial()': dial tcp 192.168.0.101:3306: i/o timeout
    2019/10/27 18:35:20 query failed: driver: bad connection
    2019/10/27 18:35:23 start
    [mysql] 2019/10/27 18:35:28 driver.go:81: net.Error from Dial()': dial tcp 192.168.0.101:3306: i/o timeout
    [mysql] 2019/10/27 18:35:33 driver.go:81: net.Error from Dial()': dial tcp 192.168.0.101:3306: i/o timeout
    [mysql] 2019/10/27 18:35:38 driver.go:81: net.Error from Dial()': dial tcp 192.168.0.101:3306: i/o timeout
    2019/10/27 18:35:38 query failed: driver: bad connection
    2019/10/27 18:35:41 start
    [mysql] 2019/10/27 18:35:46 driver.go:81: net.Error from Dial()': dial tcp 192.168.0.101:3306: i/o timeout
    [mysql] 2019/10/27 18:35:51 driver.go:81: net.Error from Dial()': dial tcp 192.168.0.101:3306: i/o timeout
    [mysql] 2019/10/27 18:35:56 driver.go:81: net.Error from Dial()': dial tcp 192.168.0.101:3306: i/o timeout
    2019/10/27 18:35:56 query failed: driver: bad connection
    2019/10/27 18:35:59 start
    [mysql] 2019/10/27 18:36:04 driver.go:81: net.Error from Dial()': dial tcp 192.168.0.101:3306: i/o timeout
    [mysql] 2019/10/27 18:36:09 driver.go:81: net.Error from Dial()': dial tcp 192.168.0.101:3306: i/o timeout
    [mysql] 2019/10/27 18:36:14 driver.go:81: net.Error from Dial()': dial tcp 192.168.0.101:3306: i/o timeout
    2019/10/27 18:36:14 query failed: driver: bad connection

从输出结果可以看到，首先打印读超时错误，6s超时(即readTimeout):

2019/10/27 18:35:01 start
    [mysql] 2019/10/27 18:35:07 packets.go:36: read tcp 192.168.0.104:54462->192.168.0.101:3306: i/o timeout
    2019/10/27 18:35:07 query failed: invalid connection

接着，每次执行SQL，都有3条连接错误日志，表示建立连接时，会尝试3次，每次超时时间5s(即设置的timeout)。

这里就引出一个问题，为什么每次执行SQL时，会进行3次建立连接尝试呢？

查一下`QueryRow`底层实现代码:

func (db *DB) QueryRow(query string, args ...interface{}) *Row {
    	return db.QueryRowContext(context.Background(), query, args...)
    }
    
    func (db *DB) QueryRowContext(ctx context.Context, query string, args ...interface{}) *Row {
    	rows, err := db.QueryContext(ctx, query, args...)
    	return &Row{rows: rows, err: err}
    }
    
    // QueryContext executes a query that returns rows, typically a SELECT.
    // The args are for any placeholder parameters in the query.
    func (db *DB) QueryContext(ctx context.Context, query string, args ...interface{}) (*Rows, error) {
    	var rows *Rows
    	var err error
    	for i := 0; i < maxBadConnRetries; i++ {
    		rows, err = db.query(ctx, query, args, cachedOrNewConn)
    		if err != driver.ErrBadConn {
    			break
    		}
    	}
    	if err == driver.ErrBadConn {
    		return db.query(ctx, query, args, alwaysNewConn)
    	}
    	return rows, err
    }

其中，maxBadConnRetries定义为2：

// maxBadConnRetries is the number of maximum retries if the driver returns
    // driver.ErrBadConn to signal a broken connection before forcing a new
    // connection to be opened.
    const maxBadConnRetries = 2

当err是`driver.ErrBadConn`时，会尝试3次进行连接。这就是为什么刚才的日志中有3次连接错误。

# 2.reject测试 #

另外，如果在客户端使用iptables将所有发送到MySQL服务的数据包reject掉:

sudo iptables -A OUTPUT -p tcp --dport 3306 -d 192.168.0.101 -j REJECT

sudo iptables -nxvL
    Chain INPUT (policy ACCEPT 5 packets, 515 bytes)
        pkts      bytes target     prot opt in     out     source               destination         
    
    Chain FORWARD (policy ACCEPT 0 packets, 0 bytes)
        pkts      bytes target     prot opt in     out     source               destination         
    
    Chain OUTPUT (policy ACCEPT 4 packets, 372 bytes)
        pkts      bytes target     prot opt in     out     source               destination         
           4      260 REJECT     tcp  --  *      *       0.0.0.0/0            192.168.0.101      tcp dpt:3306 reject-with icmp-port-unreachable

或者在MySQL上设置iptables规则，效果是一样的：

sudo iptables -A INPUT -p tcp --dport 3306 -d 192.168.0.101 -j REJECT

## 2.1 测试1：timeout=5s&readTimeout=6s ##

此时，  
reject会直接返回RESET操作，将连接重置，不会触发连接建立超时时间。

日志输出：

2019/10/27 21:39:55 start
    2019/10/27 21:39:55 value: 1
    2019/10/27 21:39:58 start
    2019/10/27 21:39:58 value: 1
    2019/10/27 21:40:01 start
    2019/10/27 21:40:01 value: 1
    2019/10/27 21:40:04 start
    2019/10/27 21:40:04 value: 1
    2019/10/27 21:40:07 start
    [mysql] 2019/10/27 21:40:13 packets.go:36: read tcp 192.168.0.104:54536->192.168.0.101:3306: i/o timeout
    2019/10/27 21:40:13 query failed: invalid connection
    2019/10/27 21:40:16 start
    2019/10/27 21:40:17 query failed: dial tcp 192.168.0.101:3306: connect: connection refused
    2019/10/27 21:40:20 start
    2019/10/27 21:40:21 query failed: dial tcp 192.168.0.101:3306: connect: connection refused
    2019/10/27 21:40:24 start
    2019/10/27 21:40:25 query failed: dial tcp 192.168.0.101:3306: connect: connection refused
    2019/10/27 21:40:28 start
    2019/10/27 21:40:29 query failed: dial tcp 192.168.0.101:3306: connect: connection refused
    2019/10/27 21:40:32 start
    2019/10/27 21:40:33 query failed: dial tcp 192.168.0.101:3306: connect: connection refused

从输出中可以看到，首先打印读超时错误，读超时readTimeout设置为6s:

[mysql] 2019/10/27 21:40:13 packets.go:36: read tcp 192.168.0.104:54536->192.168.0.101:3306: i/o timeout

后续的日志，都是连接被reset，无法连接的错误。

## 2.2 测试2：timeout=1s&readTimeout=6s ##

在测试结果表现上，与测试1基本相同。  
唯一不同的是，有时会触发i/o timeout。

因为测试2中设置的timeout是1s，比测试1中timeout 5s小。

日志输出：

2020/03/29 16:35:09 start
    2020/03/29 16:35:09 value: 1
    2020/03/29 16:35:12 start
    2020/03/29 16:35:12 value: 1
    2020/03/29 16:35:15 start
    [mysql] 2020/03/29 16:35:21 packets.go:36: read tcp 192.168.1.107:49654->192.168.1.107:3306: i/o timeout
    2020/03/29 16:35:21 query failed: invalid connection
    2020/03/29 16:35:24 start
    [mysql] 2020/03/29 16:35:25 driver.go:81: net.Error from Dial()': dial tcp 192.168.1.107:3306: i/o timeout
    [mysql] 2020/03/29 16:35:26 driver.go:81: net.Error from Dial()': dial tcp 192.168.1.107:3306: i/o timeout
    2020/03/29 16:35:26 query failed: driver: bad connection
    2020/03/29 16:35:29 start
    2020/03/29 16:35:30 query failed: dial tcp 192.168.1.107:3306: connect: connection refused
    2020/03/29 16:35:33 start
    2020/03/29 16:35:34 query failed: dial tcp 192.168.1.107:3306: connect: connection refused
    2020/03/29 16:35:37 start
    2020/03/29 16:35:38 query failed: dial tcp 192.168.1.107:3306: connect: connection refused
    2020/03/29 16:35:41 start
    [mysql] 2020/03/29 16:35:42 driver.go:81: net.Error from Dial()': dial tcp 192.168.1.107:3306: i/o timeout
    2020/03/29 16:35:43 query failed: dial tcp 192.168.1.107:3306: connect: connection refused
    2020/03/29 16:35:46 start
    [mysql] 2020/03/29 16:35:47 driver.go:81: net.Error from Dial()': dial tcp 192.168.1.107:3306: i/o timeout
    [mysql] 2020/03/29 16:35:48 driver.go:81: net.Error from Dial()': dial tcp 192.168.1.107:3306: i/o timeout
    [mysql] 2020/03/29 16:35:49 driver.go:81: net.Error from Dial()': dial tcp 192.168.1.107:3306: i/o timeout
    2020/03/29 16:35:49 query failed: driver: bad connection
    2020/03/29 16:35:52 start
    [mysql] 2020/03/29 16:35:53 driver.go:81: net.Error from Dial()': dial tcp 192.168.1.107:3306: i/o timeout
    [mysql] 2020/03/29 16:35:54 driver.go:81: net.Error from Dial()': dial tcp 192.168.1.107:3306: i/o timeout
    [mysql] 2020/03/29 16:35:55 driver.go:81: net.Error from Dial()': dial tcp 192.168.1.107:3306: i/o timeout
    2020/03/29 16:35:55 query failed: driver: bad connection
    2020/03/29 16:35:58 start
    [mysql] 2020/03/29 16:35:59 driver.go:81: net.Error from Dial()': dial tcp 192.168.1.107:3306: i/o timeout
    [mysql] 2020/03/29 16:36:00 driver.go:81: net.Error from Dial()': dial tcp 192.168.1.107:3306: i/o timeout
    [mysql] 2020/03/29 16:36:01 driver.go:81: net.Error from Dial()': dial tcp 192.168.1.107:3306: i/o timeout
    2020/03/29 16:36:01 query failed: driver: bad connection
    2020/03/29 16:36:04 start
    [mysql] 2020/03/29 16:36:05 driver.go:81: net.Error from Dial()': dial tcp 192.168.1.107:3306: i/o timeout
    [mysql] 2020/03/29 16:36:06 driver.go:81: net.Error from Dial()': dial tcp 192.168.1.107:3306: i/o timeout
    2020/03/29 16:36:07 query failed: dial tcp 192.168.1.107:3306: connect: connection refused
    2020/03/29 16:36:10 start
    [mysql] 2020/03/29 16:36:11 driver.go:81: net.Error from Dial()': dial tcp 192.168.1.107:3306: i/o timeout
    [mysql] 2020/03/29 16:36:12 driver.go:81: net.Error from Dial()': dial tcp 192.168.1.107:3306: i/o timeout
    2020/03/29 16:36:13 query failed: dial tcp 192.168.1.107:3306: connect: connection refused
    2020/03/29 16:36:16 start
    [mysql] 2020/03/29 16:36:17 driver.go:81: net.Error from Dial()': dial tcp 192.168.1.107:3306: i/o timeout
    [mysql] 2020/03/29 16:36:18 driver.go:81: net.Error from Dial()': dial tcp 192.168.1.107:3306: i/o timeout
    [mysql] 2020/03/29 16:36:19 driver.go:81: net.Error from Dial()': dial tcp 192.168.1.107:3306: i/o timeout
    2020/03/29 16:36:19 query failed: driver: bad connection

# 3.参考 #

[golang database sql DSN (Data Source Name)中的timeout, readTimeout][golang database sql DSN _Data Source Name_timeout_ readTimeout]

[go-sql-driver/mysql][go-sql-driver_mysql]

[golang database sql DSN _Data Source Name_timeout_ readTimeout]: https://blog.csdn.net/lanyang123456/article/details/85224319
[go-sql-driver_mysql]: https://github.com/go-sql-driver/mysql