TR2021_0000偶发数据库连接异常问题排查

【问题描述】

数据库连接异常是很难排查的一类问题。因为它牵涉到应用端，网络层和服务器端。任何一个组件异常，都会导致数据库连接失败。开发遇到数据库连接不上的问题，都会第一时间找DBA来协助查看，DBA除了需要懂得数据库以外，还需要对应用，对网络有所了解，知道在哪里看应用程序的日志，以及看网络交换机性能指标，才能清晰的定位问题。下面是一个数据库偶发连接不上的例子：

步骤	分析
S(主观)	某应用程序，有40台左右应用服务器，时不时的会报数据库连接异常。报错后迅速自愈。报错内容为: Communications link failure. The last packet sent successfully to the server was 0 milliseconds ago. The driver has not received any packets from the server. 报错频率大概每天有四五次左右。应用是新上的。
O(客观)	MySQL版本为5.7.23, 服务端操作系统版本为7.6.1810. 瞬间有20多台应用服务器都报这个错误。马上自愈。应用部署在同城两个机房，每个机房都有报错。每天总会出现四五次。
A(评估)	同时有20多台应用服务器报错，而且分布在两个机房。问题应该出在服务端。
P(计划)	建议在服务端抓网络包，进一步定位问题。并进一步查看服务端的性能计数器。

【问题分析】

通过问题的初步评估，故障应该是出现在服务端，也有可能是服务端的网络。我们随之查看了服务端MySQL的各项性能指标，在故障期间，性能指标都是正常的。在服务器端单边抓包，抓到的内容如下：

时间戳	源	目标	Info
2021-01-08 17:15:05.667331	应用	DB	48184 -> 3309 [SYN]
2021-01-08 17:15:06.717752	应用	DB	[TCP Retransmission] 48144 -> 3309 [SYN]
2021-01-08 17:15:06.717762	DB	应用	3309 -> 48184 [SYN, ACK]
2021-01-08 17:15:06.719101	应用	DB	48144 -> 3309 [RST]

上述网络包解读如下：

• 17:15:05.66 应用服务器(端口号48184)向DB服务器(端口号3309) 发送一个SYN请求。
• 过了1.05秒左右，应用服务器再次向DB服务器发送SYN请求
• 在17:15:06.71的时候，DB服务器响应了客户端的请求，发送了确认包ACK
• 在17:15:06.71的时候，应用服务器发送了连接重置的请求，要求中止连接。

从上述的特征来看，连接重置是客户端发起的。但这个情有可原，因为DB端超过1.05秒还没有响应客户端的SYN请求，客户端不耐烦，直接中止了连接。而这个1.05秒，恰好是开发在客户端的Tomcat JDBC connect Timeout连接超时设定。所以问题进一步缩小到服务端的TCP/IP连接层面。

我们用下面的命令，来监控服务端丢包情况：

# netstat -s | egrep "listen|LISTEN"
    5268 times the listen queue of a socket overflowed
    5268 SYNs to LISTEN sockets dropped

发现确实在服务端丢包，而且出现的频率和客户端报错的时间吻合。每次应用程序报错，服务端的drop数也会随之增加。

对于Linux服务器端，server端建连过程需要两个队列，一个是SYN queue，一个是accept queue。前者叫半开连接（或者半连接）队列，后者叫全连接队列。从服务器角度看，建立TCP连接的过程如下图：

SYNs to LISTEN sockets dropped的丢包类型，说明在半连接队列出现了问题。

分析发现，该实例部署的DB数量比较多，且对应的应用服务器数量也比较多，应用会有短时间创建大量连接的情况，导致半连接队列溢出。半连接队列的大小取决于linux的参数tcp_max_syn_backlog、somaxconn和应用程序调用Listen方法时的backlog参数。

关于tcp_max_syn_backlog、somaxconn与半连接队列的分析，网上的资料非常多，这里不展开细节分析，我们可以简单地认为：

全连接队列长度 = min(somaxconn, backlog)
半连接队列长度 = backlog*2

我们可以用下面的命令，来监控全连接的队列大小，发现值为128，可以说明我们somaxconn值或者mysqld的backlog设置比较小，从而导致半连接队列也比较小。

#ss -ntlp | more
LISTEN     0      128        :::3309                    :::*    

对于这次的案例，我们先调大了linux操作系统的两个参数。

#echo 'net.ipv4.tcp_max_syn_backlog=65535' >> /etc/sysctl.conf
#echo 'net.core.somaxconn=65535' >> /etc/sysctl.conf
#sysctl –p

接下来，我们分析下mysqld调用Listen方法时，backlog相关的代码。
MYSQLD在启动时会调用network_init的方法，会传入back_log参数，代码如下：

static bool network_init(void)
{
  if (opt_bootstrap)
    return false;
  set_ports();
  if (!opt_disable_networking || unix_sock_name != "")
  {
    std::string const bind_addr_str(my_bind_addr_str ? my_bind_addr_str : "");

    Mysqld_socket_listener *mysqld_socket_listener=
      new (std::nothrow) Mysqld_socket_listener(bind_addr_str,
                                                mysqld_port, back_log,
                                                mysqld_port_timeout,
                                                unix_sock_name);
    if (mysqld_socket_listener == NULL)
      return true;
    mysqld_socket_acceptor=
      new (std::nothrow) Connection_acceptor(mysqld_socket_listener);
}

创建出mysqld_socket_listener对象后，传递给Connection_acceptor后，最终会调用操作系统的Listen方法，代码如下：

static inline int inline_mysql_socket_listen
(
MYSQL_SOCKET mysql_socket, int backlog)
{
  int result;
  if (mysql_socket.m_psi != NULL)
  {
    /* Instrumentation start */
    PSI_socket_locker *locker;
    PSI_socket_locker_state state;
    locker= PSI_SOCKET_CALL(start_socket_wait)
      (&state, mysql_socket.m_psi, PSI_SOCKET_CONNECT, (size_t)0, src_file, src_line);

    /* Instrumented code */
    result= listen(mysql_socket.fd, backlog);

对于back_log值的确定，mysql有2种处理方式。
一种是情况默认情况，会设置50 + (max_connections / 5)且不超过900。具体的代码如下：

int init_common_variables()
{
  umask(((~my_umask) & 0666));
  my_decimal_set_zero(&decimal_zero); // set decimal_zero constant;
  tzset();      // Set tzname

  /* Fix back_log */
  if (back_log == 0 && (back_log= 50 + max_connections / 5) > 900)
      back_log= 900;
}

另外一种情况，也可以手动设置mysqld的启动参数。

static Sys_var_ulong Sys_back_log(
       "back_log", "The number of outstanding connection requests "
       "MySQL can have. This comes into play when the main MySQL thread "
       "gets very many connection requests in a very short time",
       READ_ONLY GLOBAL_VAR(back_log), CMD_LINE(REQUIRED_ARG),
       VALID_RANGE(0, 65535), DEFAULT(0), BLOCK_SIZE(1));

为了保持服务器配置的统一化，我们这次调整了mysqld的启动back-log=2048，调整完成后，重启mysql服务，观察了2天，再未发生半连接丢包的问题。

【问题总结】

全连接队列、半连接队列溢出这种问题很容易发生，但可能报错具有偶然性，很容易被忽视，linux版本的不断进化，TCP的设计也越来越复杂，作为一名合格的DBA，也需要对网络有所了解，才能更好地定位和处理日常的运维问题。