MySQL 主从时间字段相差1秒深度揭密_时间戳转换后与数据库差1s-CSDN博客

本文链接：https://blog.csdn.net/postgres20/article/details/127650224

1. 主从数据异常

某实例一个datetime字段主从数据不一致，其它数据暂未发现异常。第一反应，有可能是人为修改，如果有用户有高权限帐号，是可能做到这事的，检查所有帐号权限排除了这种可能。难道有黑客入侵？神经一下绷紧，仔细排查各种系统状态，很快也排除了这种可能。同时分析业务类型，有问题的值都是从机都是比主少一秒，时间戳被改小一秒不能带来任何收益，被非法篡改的可能性基本排除。

2. 初步分析

对比数据发现，从机比主机少一秒的数据经常出现，但从机主从复制状态一直正常，主机binlog中未发现有语句被跳过。对比master上binlog及slave上relaylog, relaylog和master上binlog完全一致，有问题的数据在master上binlog里就已经少一秒了，因此肯定从机状态是正常的，问题出在master上。继续分析发现有问题的数据，发现在master上select出来和binlog中就是差一秒，很是诡异邪门。打开general_log，记录一段时间操作，抓到了大量的时间相差一秒的情况行的前后插入语句，观察发现general_log 和binlog中时间相同，但直接select出来的值多一秒，没有其它多余操作，完全排除非法篡改的情况。至此可以认定，异常数据在innodb引擎中存的数据和binlog中的数据是不一致的，在这里需要说明的是master上binlog格式是mixed，非row格式并不能完全保证binlog数据可靠。继续分析geneal_log,有问题的行是都是通过Prepared Execute方式插入的，尝试联系前端人员复现问题未果后，自己想办法复现。分析问题数据有几个特点：

Prepared Execute 方式插入
部分数据差一秒，非全部
有问题的数据在binlog中都是比innodb中的少一秒
datetime字段未指定精度由于前端大多是通过jdbc方式访问数据库，于是根据上面特征在本地构造jdbc用例操作库，绑定变量，构造prepare execute方式插入数据，当设置预编译模式（useServerPrepStmts=true）复现了bug，复现的java代码如下：

import java.sql.*;
import java.text.SimpleDateFormat;
public class insertData {
	public static void main(String[] args)
	{
		String driver = "com.mysql.jdbc.Driver";
		String url = "jdbc:mysql://127.0.0.1:3306/mydb?useServerPrepStmts=true";
		String user = "u1";
		String password = "123456";
		try 
		{
			Class.forName(driver);
			Connection conn = DriverManager.getConnection(url, user, password);
			if(!conn.isClosed())
				System.out.println("Succeeded connecting to the Database!");
			//String dateStr = "2018-09-25 14:36:45.666";  
			//SimpleDateFormat  form = new SimpleDateFormat ("yyyy-MM-dd HH:mm:ss.SSS");
			//java.util.Date date=form.parse(dateStr);
			//java.sql.Timestamp tmp= new java.sql.Timestamp(date.getTime());
			//System.out.println(tmp);
			long time = System.currentTimeMillis();
			Date date = new Date(time);
    	java.sql.Timestamp tmp= new java.sql.Timestamp(date.getTime());
  		System.out.println(tmp);  		
			//create table test(a datetime);
			PreparedStatement pstmt = conn.prepareStatement("insert into test values(?)");
			pstmt.setTimestamp(1, tmp);
			pstmt.execute();
			conn.close();
		}
		catch(ClassNotFoundException e) 
		{
			System.out.println("Sorry,can`t find the Driver!");
			e.printStackTrace();
		}
		catch(SQLException e) 
		{
			e.printStackTrace();
		} catch(Exception e) 
		{
			e.printStackTrace();
		}
	}
}

用例很简单，取当前时间插入数据库，binlog中有不少时间值少一秒，如下图：

第一个图是java插入数据并打印出原始时间数据，第二个图是数据库中binlog及直接查出的时间数据，显然秒以下精度大于0.5秒的两个时间出现了相差一秒的情况，至此可以初步认定该问题是由于精度引起，如果前端将秒以下精度清零再插入，不会有这问题。

3. 深度挖掘

一、前端参数简介

到此问题似乎已经解决，前端精度清零即可，但是这只是临时方案，为什么精度不清零会有问题？根本原因是什么？精度问题前端页面和入库有不一致可以接受，但是在入库后binlog与innodb存的数据不一致，没有任何提示报错直接导致主从数据不一致，这是不能接受的，必须挖出根本原因，保证数据的可靠性。当用其它方式操作库没有问题，用prepare不用预编译模式（useServerPrepStmts=false）也不会有问题，由此可见触发该问题的关键是是否使用预编译模式。

Jdbc对prepare的大致处理过程如下： useServerPrepStmts=true时Jdbc对prepare的处理 1）创建PreparedStatement对象，向服务器发送COM_PREPARE命令，并传送带问号的sql. 服务器返回jdbc stmt->id等信息 2）向服务器发送COM_EXECUTE命令,并只传送参数信息。 useServerPrepStmts=false时Jdbc对prepare的处理 1）创建PreparedStatement对象，此时不会和服务器交互。 2）根据参数和PreparedStatement对象拼接完整的SQL，向服务器发送QUERY命令当使用预编译时prepare阶段发带问号语句到后端，执行时只发参数，相同语句后端只需要解析一次。非预编译时，prepare时与后端无交互，执行时拼接完整的SQL发到后端运行，即问号已经在前端被填充好值，每条语句都要解析一次。预编译模式，执行时只发参数，引擎层把传过来的参数值处理落盘，而写入binlog的语句是把参数转换拼接而成。这里引擎层落盘数据和sql层转换拼接还原binlog语句是两个独立的过程，可以提出一个假设：如果sql层和引擎层对精度处理逻辑不一致，innodb引擎层对秒以下做四舍五入，而sql层直接舍弃秒以下精度，那么就可能造成这个问题。

二、binlog语句来处

带着上面的假设分析源码，尝试从源码中继续寻找答案。先找binlog的语句来处，mysql中sql语句都保存在thd->query_string中，但这里的query_string中的参数是问号，它是在函数insert_params_with_log中拼接还原而成, 把时间值转成了字串符填入了sql中的问号，如下：

937	    if (query->replace(param->pos_in_query+length, 1, *res))
(gdb) bt
#0  insert_params_with_log (stmt=0x7f77e8c56280, null_array=0x7f77f7f6600a "", read_pos=0x7f77f7f6601a "", data_end=0x7f77f7f6601a "", query=0x7f7879e29f00) at /data/new56/event/DB/sql/sql_prepare.cc:937
#1  0x000000000081eb0c in Prepared_statement::set_parameters (this=0x7f77e8c56280, expanded_query=0x7f7879e29f00, packet=0x7f77f7f6600e "\v\342\a\v\002\n\005\065\370\334\f", packet_end=0x7f77f7f6601a "")
    at /data/new56/event/DB/sql/sql_prepare.cc:3594
#2  0x000000000081ebeb in Prepared_statement::execute_loop (this=0x7f77e8c56280, expanded_query=0x7f7879e29f00, open_cursor=false, packet=0x7f77f7f6600a "", packet_end=0x7f77f7f6601a "")
    at /data/new56/event/DB/sql/sql_prepare.cc:3655
#3  0x000000000081c845 in mysqld_stmt_execute (thd=0x7f77f7f62000, packet_arg=0x7f77f7f66001 "\001", packet_length=25) at /data/new56/event/DB/sql/sql_prepare.cc:2701
#4  0x00000000007f972a in dispatch_command (command=COM_STMT_EXECUTE, thd=0x7f77f7f62000, packet=0x7f77f7f66001 "\001", packet_length=25) at /data/new56/event/DB/sql/sql_parse.cc:1351
#5  0x00000000007f8931 in do_command (thd=0x7f77f7f62000) at /data/new56/event/DB/sql/sql_parse.cc:1060
#6  0x00000000007be7d1 in do_handle_one_connection (thd_arg=0x7f77f7f62000) at /data/new56/event/DB/sql/sql_connect.cc:998
#7  0x00000000007be2ab in handle_one_connection (arg=0x7f77f7f62000) at /data/new56/event/DB/sql/sql_connect.cc:905
#8  0x0000000000b2f665 in pfs_spawn_thread (arg=0x7f7877ffd920) at /data/new56/event/DB/storage/perfschema/pfs.cc:1860
#9  0x00007f7879b6d9d1 in start_thread () from /lib64/libpthread.so.0
#10 0x00007f78788d68fd in clone () from /lib64/libc.so.6
(gdb) p *query
$1 = {Ptr = 0x7f77e8c15040 "insert into test values(?)", str_length = 26, Alloced_length = 32, alloced = true, str_charset = 0x182f260}
(gdb) n
940	    length+= res->length()-1;
(gdb) p *query
$2 = {Ptr = 0x7f77e8c1c070 "insert into test values('2018-11-02 10:45:17')", str_length = 46, Alloced_length = 48, alloced = true, str_charset = 0x182f260}

可以看到，在937行把问号做了替换，还原了sql语句，而问号里的值在上面 param->set_param_func函数中获取，set_param_func在此实际调用的是set_param_datetime，代码如下：

static void set_param_datetime(Item_param *param, uchar **pos, ulong len)
{
  MYSQL_TIME tm;
  ulong length= get_param_length(pos, len);//前端发过来的参数长度

  if (length >= 4)
  {//下面把前端发过来的参数转成MYSQL_TIME时间
    uchar *to= *pos;

    tm.neg=    0;
    /*
     前端发过来时间格式数字内存转的字符串:20181101125510124566，代表的时间为2018年11月01日12点55分10秒124566微秒
     分别用2字节存年，月日时分秒均用1个字节存，微秒4字节，一共2+1+1+1+1+1+4=11字节，前端发过来的时间
     格式就是按这个方式把数据堆在一起，下面的逻辑就是把时间还原出来   
    */
    tm.year=   (uint) sint2korr(to);
    /*
     sint2korr(A) (int16) (((int16) ((uchar) (A)[0])) + ((int16) ((int16) (A)[1]) << 8))
     把两个字节所表示的整数还原出来，下面sint4korr把四字节表示的整数还原出来
    */
    tm.month=  (uint) to[2]; //0~255之间值一个字节可以存放
    tm.day=    (uint) to[3];
    if (length > 4)
    {
      tm.hour=   (uint) to[4];
      tm.minute= (uint) to[5];
      tm.second= (uint) to[6];
    }
    else
      tm.hour= tm.minute= tm.second= 0;

    tm.second_part= (length > 7) ? (ulong) sint4korr(to+7) : 0;
  }
  else
    set_zero_time(&tm, MYSQL_TIMESTAMP_DATETIME);

  /*
   此时打印时间是带精度的：
   (gdb) p tm
   $9 = {year = 2018, month = 11, day = 2, hour = 10, minute = 45, second = 17, second_part = 908000, neg = 0 '\000', time_type = 32632}
  */
  param->set_time(&tm, MYSQL_TIMESTAMP_DATETIME,
                  MAX_DATETIME_FULL_WIDTH * MY_CHARSET_BIN_MB_MAXLEN);
  *pos+= length;
}

至此，在set_param_datetime中把前端传过来的时间参数转成了tm时间，并在param->set_time设置到了value中，param->set_time函数如下：

void Item_param::set_time(MYSQL_TIME *tm, timestamp_type time_type,
                          uint32 max_length_arg)
{ 
  DBUG_ENTER("Item_param::set_time");

  value.time= *tm;           //保存时间
  value.time.time_type= time_type;

  if (check_datetime_range(&value.time))
  {
    make_truncated_value_warning(ErrConvString(&value.time,
                                               MY_MIN(decimals,
                                                      DATETIME_MAX_DECIMALS)),
                                 time_type);
    set_zero_time(&value.time, MYSQL_TIMESTAMP_ERROR);
  }

  state= TIME_VALUE;
  maybe_null= 0;
  max_length= max_length_arg;
  decimals= 0;            //精度设为0,不管原来值是多少，一律清0，关键点=================
  DBUG_VOID_RETURN;
}

再回到 insert_params_with_log函数，在上面的937行上面两行调用 param->query_val_str 函数把tm时间转成了时间值字符串：

const String *Item_param::query_val_str(THD *thd, String* str) const
{
  switch (state) {  //state值为TIME_VALUE
  case INT_VALUE:
    str->set_int(value.integer, unsigned_flag, &my_charset_bin);
    break;
  case REAL_VALUE:
    str->set_real(value.real, NOT_FIXED_DEC, &my_charset_bin);
    break;
  case DECIMAL_VALUE:
    if (my_decimal2string(E_DEC_FATAL_ERROR, &decimal_value,
                          0, 0, 0, str) > 1)
      return &my_null_string;
    break;
  case TIME_VALUE://==========>进入
    {
      char *buf, *ptr;
      str->length(0);
      /*
        TODO: in case of error we need to notify replication
        that binary log contains wrong statement 
      */
      if (str->reserve(MAX_DATE_STRING_REP_LENGTH+3))
        break; 

      /* Create date string inplace */
      buf= str->c_ptr_quick();
      ptr= buf;
      *ptr++= '\'';
      /*
        这里decimals在前面set_time中被设置成了0，MY_MIN(decimals, DATETIME_MAX_DECIMALS)为
        取小值，因此 my_TIME_to_str(&value.time, ptr,MY_MIN(decimals, DATETIME_MAX_DECIMALS))
        等价于my_TIME_to_str(&value.time, ptr,0) ，传入的精度位数为0，my_TIME_to_str函数是把时间
        转成字符串，如果精度为0直接忽略秒以下值
      */
      ptr+= (uint) my_TIME_to_str(&value.time, ptr,
                                  MY_MIN(decimals, DATETIME_MAX_DECIMALS));
      *ptr++= '\'';
      str->length((uint32) (ptr - buf));
      break;
    }
  case STRING_VALUE:
  case LONG_DATA_VALUE:
    {
      str->length(0);
      append_query_string(thd, value.cs_info.character_set_client, &str_value,
                          str);
      break;
    }
  case NULL_VALUE:
    return &my_null_string;
  default:
    DBUG_ASSERT(0);
  }
  return str;
}

在my_TIME_to_str中又是直接调用my_datetime_to_str把时间转成的字符串逻辑如下：

//l_time 待转的时间
//to 存转换后的时间字符串
//dec 精度
int my_datetime_to_str(const MYSQL_TIME *l_time, char *to, uint dec)  
{
  int len= TIME_to_datetime_str(to, l_time); //TIME_to_datetime_str仅转换年月日时分秒
  if (dec) //精度不为0则进入把精度转换处理
    len+= my_useconds_to_str(to + len, l_time->second_part, dec);
  else  //精度为0则直接舍弃秒以下精度。前面已经将精度置为0，这种场景下，每次都走这个else逻辑分支，直接忽略秒以下精度
    to[len]= '\0';
  return len;
}

整个逻辑可以非常清楚的看到，sql层在处理这种情况传过来的时间参数时，直接把时间的秒以下精度丢掉生成一个时间字符串，给binlog和general log还原问号生成sql语句，因此binlog中的sql语句时间是直接忽略精度，非四舍五入的。

三、InnoDB引擎时间去处

上面已经证明了猜测的一半，sql层还原语句直接丢弃了秒以下的精度。而从结果上来看，innodb层应该是做了四舍五入，究竟是不是这么做的呢？可以继续跟踪。在row_insert_for_mysql函数打断点，往回追踪，最终是在函数 my_datetime_round中处理的时间，如果没有指定精度，会根据传过来的实际参数值是否有秒以下精度来做四舍五入，大于0.5秒的会向前取整加一秒，有兴趣的同学可以跟踪看一下，这里不再细述。

总结

真实原因和猜测的一样，sql层和引擎层处理精度逻辑不一样，一个直接舍弃，一个四舍五入，造成了相差一秒的情况，有的时候，合理的假设往往能做到有的放矢，避免乱碰乱撞，达到事半功倍的效果。知道了根本原因要修复也比较简单，即可以都舍去，也可以都四舍五入，逻辑保持一致即可。下载最新版官方代码复现时发现官方已经修复了这个问题，5.6 & 6.7都已经修复，都使用了四舍五入的逻辑，因此用户可以使用新版本避免这个问题。当然如果不想手工改代码修复，又不想升级最新版本，以下几个方法也可以避免这个问题：

前端时间类型秒以下精度清0，前端取到的时间是有微秒精度的，清零之后再发到后台。
使用binlog用row模式。
不用预解编译定变量模式（useServerPrepStmts=false）。

后续

mysql 官方5.7.18、5.6.36 修复了该bug。附官方commit说明：


SHA-1: 6b3d07f3343a1fe7039cfc5fb8b6da092ccde793

* BUG#25187670: BACKPORT BUG#19894382 TO 5.6 AND 5.7.

Backport from mysql-trunk to mysql-5.6 and mysql-5.7.

Bug#19894382 SERVER SIDE PREPARED STATEMENTS LEADS TO POTENTIAL
             OFF-BY-SECOND TIMESTAMP ON SLAVE

For temporal type input parameter (as time, timestamp and
datetime) of server side prepared statement, the fractional
second part is ignored while preparing the query string.
Executing such query string at slave is resulting in a time
value difference between master and server.

For server prepared statement, the parameters passed for
execution are parsed and Item_param objects are created for
it. While preparing Item_param for temporal types time,
timestamp and datetime, precision for fractional second part's
(Item_param::decimals) is set to "0" always. Because of which
while preparing query string with param values, fractional second
value is ignored. So execution of such prepared statements uses
correct values but query string formed is incorrect. Hence
difference in temporal type value is observed on usage of query
string.
Fix:
--------
If temporal types time, timestamp and datetime has fractional
second part then setting microseconds (6 digit) precision for
the Item_param.