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)
半连接队列长度 = min(应用调用Listen的backlog,somaxconn,tcp_max_syn_backlog)

我们可以用下面的命令,来监控全连接的队列大小,发现值为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,也需要对网络有所了解,才能更好地定位和处理日常的运维问题。

Tags: