MySQL Case-时间问题导致MySQL实例批量宕机

  • 哎呀我的天呐

    2021-08-18 12:44:35
  • MySQL
  • 原创

数据库宕机信息

客户环境多套数据库宕机，error log信息如下：

2021-08-17T13:17:18.033537+08:00 4 [Note] Got an error reading communication packets
2021-08-17T13:17:43.281992+08:00 5 [Note] Got an error reading communication packets
2021-08-17T13:32:21.657931+08:00 8 [Note] Aborted connection 8 to db: 'test' user: 'root' host: '127.0.0.1' (Got an error reading communication packets)
2021-08-17T13:32:27.918403+08:00 0 [Note] InnoDB: page_cleaner: 1000ms intended loop took 5250ms. The settings might not be optimal. (flushed=1465 and evicted=0, during the time.)
2021-08-17T14:24:21.727815+08:00 12 [Note] Aborted connection 12 to db: 'recover' user: 'root' host: 'localhost' (Got timeout reading communication packets)
2021-08-17T14:43:19.642209+08:00 14 [Note] Got an error reading communication packets
2021-08-17T15:43:40.972887+08:00 26 [Note] Got an error reading communication packets
2021-08-17T17:02:02.057400+08:00 0 [Note] InnoDB: page_cleaner: 1000ms intended loop took 10947ms. The settings might not be optimal. (flushed=408 and evicted=0, during the time.)
2021-08-17T17:02:29.974975+08:00 0 [Note] InnoDB: page_cleaner: 1000ms intended loop took 4875ms. The settings might not be optimal. (flushed=328 and evicted=0, during the time.)
2021-08-17T17:03:44.284632+08:00 0 [Note] InnoDB: page_cleaner: 1000ms intended loop took 7881ms. The settings might not be optimal. (flushed=4000 and evicted=0, during the time.)
2021-08-17T17:04:07.271494+08:00 0 [Note] InnoDB: page_cleaner: 1000ms intended loop took 8948ms. The settings might not be optimal. (flushed=4000 and evicted=0, during the time.)
Status information:
Current dir: /data/mysql_data/
Running threads: 2  Stack size: 262144
Current locks:
lock: 0x7556b30:
lock: 0x74ecee0:
lock: 0x7494630:
lock: 0x74d6910:
lock: 0x74bdb70:
lock: 0x74b73f0:
lock: 0x74af850:
lock: 0x211f760:
lock: 0x211f680:
lock: 0x211f5a0:
lock: 0x211f4c0:
lock: 0x211f3e0:
lock: 0x211f300:
lock: 0x211f220:
lock: 0x211f140:
lock: 0x211f060:
lock: 0x211fd80:
lock: 0x211c560:
lock: 0x2120640:
lock: 0x2120560:
lock: 0x2120480:
lock: 0x21203a0:
lock: 0x21202c0:
lock: 0x21201e0:
lock: 0x2120100:
lock: 0x2120020:
lock: 0x211dce0:
lock: 0x211f840:
lock: 0x211e120:
lock: 0x211e040:
lock: 0x211df60:
lock: 0x211de80:
lock: 0x211ddc0:
lock: 0x211ff40:
lock: 0x211fe60:
lock: 0x211e580:
lock: 0x211e4a0:
lock: 0x211e3c0:
lock: 0x211e740:
lock: 0x211bca0:
lock: 0x211fca0:
lock: 0x211cc60:
lock: 0x211c9c0:
lock: 0x211cb80:
lock: 0x211c8e0:
lock: 0x211caa0:
lock: 0x211d200:
lock: 0x211d2c0:
lock: 0x211d380:
lock: 0x211c480:
lock: 0x211c3a0:
lock: 0x211c800:
lock: 0x211c2c0:
lock: 0x211c720:
lock: 0x211c1e0:
lock: 0x211c640:
lock: 0x211cfa0:
lock: 0x211d060:
lock: 0x211d120:
lock: 0x211c100:
lock: 0x211be60:
lock: 0x211c020:
lock: 0x211bd80:
lock: 0x211bf40:
lock: 0x211cd40:
lock: 0x211ce00:
lock: 0x211cec0:
lock: 0x211f920:
lock: 0x211fbc0:
lock: 0x211fae0:
lock: 0x211fa00:
lock: 0x211ed40:
lock: 0x211ec60:
lock: 0x211eb80:
lock: 0x211eaa0:
lock: 0x211e9c0:
lock: 0x211eec0:
lock: 0x211e900:
lock: 0x211e820:
lock: 0x211ef80:
lock: 0x211e660:
lock: 0x211e200:
lock: 0x211e2e0:
lock: 0x211dc00:
lock: 0x211db20:
lock: 0x211d7a0:
lock: 0x211da40:
lock: 0x211d960:
lock: 0x211d6c0:
lock: 0x211d880:
lock: 0x211d460:
lock: 0x211d520:
lock: 0x211d5e0:
lock: 0x211ee00:
Key caches:
default
Buffer_size:       8388608
Block_size:           1024
Division_limit:        100
Age_limit:             300
blocks used:             3
not flushed:             0
w_requests:              0
writes:                  0
r_requests:              6
reads:                   3
handler status:
read_key:           15
read_next:     5050002
read_rnd             0
read_first:         17
write:         5050100
delete               0
update:              0
Table status:
Opened tables:        123
Open tables:          108
Open files:            18
Open streams:           0
Memory status:



  
  
  
  
  
  
  
  
  
  
  
  
  
  
  
  
  
  
  










  
  
  
  
  
  
  
  
  
  
  
  
  
  
  










  
  
  
  
  
  
  
  
  
  
  
  
  
  
  
  
  
  
  
  










  
  
  
  
  
  
  
  
  
  
  
  
  
  
  










  
  
  
  










  










  










  


























Events status:
LLA = Last Locked At  LUA = Last Unlocked At
WOC = Waiting On Condition  DL = Data Locked
Event scheduler status:
State      : INITIALIZED
Thread id  : 0
LLA        : n/a:0
LUA        : n/a:0
WOC        : NO
Workers    : 0
Executed   : 0
Data locked: NO
Event queue status:
Element count   : 0
Data locked     : NO
Attempting lock : NO
LLA             : init_queue:103
LUA             : init_queue:111
WOC             : NO
Next activation : never
2021-08-17T17:08:10.123540+08:00 0 [Note] InnoDB: page_cleaner: 1000ms intended loop took 8773ms. The settings might not be optimal. (flushed=0 and evicted=0, during the time.)
2021-08-17T17:08:27.584420+08:00 0 [Note] InnoDB: page_cleaner: 1000ms intended loop took 7896ms. The settings might not be optimal. (flushed=3417 and evicted=0, during the time.)
2021-08-17T17:08:27.871717+08:00 32 [Note] Aborted connection 32 to db: 'test' user: 'root' host: '127.0.0.1' (Got an error reading communication packets)
2021-08-17T17:43:32.012491+08:00 34 [Note] Got an error reading communication packets
2021-08-17T17:45:25.898084+08:00 35 [Note] Got packets out of order
2050-10-10T20:00:05.358937+08:00 36 [Warning] Current time has got past year 2038. Validating current time with 5 iterations before initiating the normal server shutdown process.
2050-10-10T20:00:05.385232+08:00 36 [Warning] Iteration 1: Current time obtained from system is greater than 2038
2050-10-10T20:00:05.385246+08:00 36 [Warning] Iteration 2: Current time obtained from system is greater than 2038
2050-10-10T20:00:05.385250+08:00 36 [Warning] Iteration 3: Current time obtained from system is greater than 2038
2050-10-10T20:00:05.385253+08:00 36 [Warning] Iteration 4: Current time obtained from system is greater than 2038
2050-10-10T20:00:05.385256+08:00 36 [Warning] Iteration 5: Current time obtained from system is greater than 2038
2050-10-10T20:00:05.408669+08:00 36 [ERROR] This MySQL server doesn't support dates later than 2038
2050-10-10T20:00:05.746302+08:00 0 [Note] Giving 0 client threads a chance to die gracefully
2050-10-10T20:00:05.746331+08:00 0 [Note] Shutting down slave threads
2050-10-10T20:00:05.746340+08:00 0 [Note] Forcefully disconnecting 0 remaining clients
2050-10-10T20:00:05.770946+08:00 0 [Note] Event Scheduler: Purging the queue. 0 events
2050-10-10T20:00:05.822777+08:00 0 [Note] Binlog end
2050-10-10T20:00:05.942614+08:00 0 [Note] Shutting down plugin 'ngram'
2050-10-10T20:00:05.948141+08:00 0 [Note] Shutting down plugin 'partition'
2050-10-10T20:00:05.948176+08:00 0 [Note] Shutting down plugin 'BLACKHOLE'
2050-10-10T20:00:05.948187+08:00 0 [Note] Shutting down plugin 'ARCHIVE'
2050-10-10T20:00:05.948192+08:00 0 [Note] Shutting down plugin 'PERFORMANCE_SCHEMA'
2050-10-10T20:00:05.964149+08:00 0 [Note] Shutting down plugin 'MRG_MYISAM'
2050-10-10T20:00:05.964186+08:00 0 [Note] Shutting down plugin 'MyISAM'
2050-10-10T20:00:05.967164+08:00 0 [Note] Shutting down plugin 'INNODB_SYS_VIRTUAL'
2050-10-10T20:00:05.968176+08:00 0 [Note] Shutting down plugin 'INNODB_SYS_DATAFILES'
2050-10-10T20:00:05.968196+08:00 0 [Note] Shutting down plugin 'INNODB_SYS_TABLESPACES'
2050-10-10T20:00:05.968200+08:00 0 [Note] Shutting down plugin 'INNODB_SYS_FOREIGN_COLS'
2050-10-10T20:00:05.968204+08:00 0 [Note] Shutting down plugin 'INNODB_SYS_FOREIGN'
2050-10-10T20:00:05.968207+08:00 0 [Note] Shutting down plugin 'INNODB_SYS_FIELDS'
2050-10-10T20:00:05.968210+08:00 0 [Note] Shutting down plugin 'INNODB_SYS_COLUMNS'
2050-10-10T20:00:05.968214+08:00 0 [Note] Shutting down plugin 'INNODB_SYS_INDEXES'
2050-10-10T20:00:05.968217+08:00 0 [Note] Shutting down plugin 'INNODB_SYS_TABLESTATS'
2050-10-10T20:00:05.968220+08:00 0 [Note] Shutting down plugin 'INNODB_SYS_TABLES'
2050-10-10T20:00:05.968223+08:00 0 [Note] Shutting down plugin 'INNODB_FT_INDEX_TABLE'
2050-10-10T20:00:05.968226+08:00 0 [Note] Shutting down plugin 'INNODB_FT_INDEX_CACHE'
2050-10-10T20:00:05.968229+08:00 0 [Note] Shutting down plugin 'INNODB_FT_CONFIG'
2050-10-10T20:00:05.968232+08:00 0 [Note] Shutting down plugin 'INNODB_FT_BEING_DELETED'
2050-10-10T20:00:05.968235+08:00 0 [Note] Shutting down plugin 'INNODB_FT_DELETED'
2050-10-10T20:00:05.972522+08:00 0 [Note] Shutting down plugin 'INNODB_FT_DEFAULT_STOPWORD'
2050-10-10T20:00:05.972537+08:00 0 [Note] Shutting down plugin 'INNODB_METRICS'
2050-10-10T20:00:05.972545+08:00 0 [Note] Shutting down plugin 'INNODB_TEMP_TABLE_INFO'
2050-10-10T20:00:05.972549+08:00 0 [Note] Shutting down plugin 'INNODB_BUFFER_POOL_STATS'
2050-10-10T20:00:05.972554+08:00 0 [Note] Shutting down plugin 'INNODB_BUFFER_PAGE_LRU'
2050-10-10T20:00:05.972558+08:00 0 [Note] Shutting down plugin 'INNODB_BUFFER_PAGE'
2050-10-10T20:00:05.972562+08:00 0 [Note] Shutting down plugin 'INNODB_CMP_PER_INDEX_RESET'
2050-10-10T20:00:05.972568+08:00 0 [Note] Shutting down plugin 'INNODB_CMP_PER_INDEX'
2050-10-10T20:00:05.972576+08:00 0 [Note] Shutting down plugin 'INNODB_CMPMEM_RESET'
2050-10-10T20:00:05.972580+08:00 0 [Note] Shutting down plugin 'INNODB_CMPMEM'
2050-10-10T20:00:05.972584+08:00 0 [Note] Shutting down plugin 'INNODB_CMP_RESET'
2050-10-10T20:00:05.972588+08:00 0 [Note] Shutting down plugin 'INNODB_CMP'
2050-10-10T20:00:05.972593+08:00 0 [Note] Shutting down plugin 'INNODB_LOCK_WAITS'
2050-10-10T20:00:05.972597+08:00 0 [Note] Shutting down plugin 'INNODB_LOCKS'
2050-10-10T20:00:05.972601+08:00 0 [Note] Shutting down plugin 'INNODB_TRX'
2050-10-10T20:00:05.972606+08:00 0 [Note] Shutting down plugin 'InnoDB'
2050-10-10T20:00:06.009896+08:00 0 [Note] InnoDB: FTS optimize thread exiting.
2050-10-10T20:00:06.010211+08:00 0 [Note] InnoDB: Starting shutdown...
2050-10-10T20:00:06.111955+08:00 0 [Note] InnoDB: Dumping buffer pool(s) to /data/mysql_data/ib_buffer_pool
2050-10-10T20:00:06.135351+08:00 0 [Note] InnoDB: Buffer pool(s) dump completed at 501010 20:00:06
2050-10-10T20:00:27.872226+08:00 0 [Note] InnoDB: Shutdown completed; log sequence number 3757316759
2050-10-10T20:00:27.881295+08:00 0 [Note] InnoDB: Removed temporary tablespace data file: "ibtmp1"
2050-10-10T20:00:27.881333+08:00 0 [Note] Shutting down plugin 'MEMORY'
2050-10-10T20:00:27.883896+08:00 0 [Note] Shutting down plugin 'CSV'
2050-10-10T20:00:27.883923+08:00 0 [Note] Shutting down plugin 'sha256_password'
2050-10-10T20:00:27.883934+08:00 0 [Note] Shutting down plugin 'mysql_native_password'
2050-10-10T20:00:27.907348+08:00 0 [Note] Shutting down plugin 'binlog'
2050-10-10T20:00:27.945216+08:00 0 [Note] /usr/local/mysql/bin/mysqld: Shutdown complete

[ERROR]ThisMySQLserverdoesn'tsupportdateslaterthan2038

从上述错误可以看出，超过MySQL支持的时间范围，经过确认，宕机的数据库都为vmare上的虚拟机，从下面可以看出，虚拟机时间取自于宿主机，运维人员误更改宿主机系统时间导致

那么我们来看下为什么时间不能超过2038年呢？

千年虫2038年问题

和21世纪初的千年虫（the Millennium bug）问题类似，32位的Unix操作系统和Linux操作系统时间溢出问题又称为 （the Year 2038 problem）。如果你想知道什么是2038问题的话，你需要知道一些技术上的东西。这个bug是由用来写Unix/Linux的C语言引起的，C语言中用 time_t 来代表时间和日期，time_t 是整数（int）型的，它用来记载从1970年1月1日到2000年所经历的秒数。

这个数据是以32位存储的，第一位是符号位，其余的31位用来存数字，而这31位数字可以存储的最大数字为2147483647。

从1970年开始计算，这31位的数字可以表示的秒数最多可以用到2038年01月19日03时14分07秒，当时间到达这个数字的时候系统将会出现问题，到时候数字不会自动增加，而是会变为-2147483648，而这串数字代表的时间是1901年12月13日20时45分52秒，这会导致很多的程序出现问题，甚至崩溃。

2038年问题不仅比千年虫更隐蔽，而且比之前千年虫问题更具有破坏力，因为千年虫问题只会导致应用层的程序出现问题，比如信用卡支付系统，或者管理系统。而2038这个bug，将会影响系统最底层的时间控制的功能。

要解决这个问题，最简单的方式是扩展Unix时间的长度，用64位数字来表示它。64位二进制数的实际可用位数是63位，最大表示到公历的UTC时间292,277,026,596年12月4日15时30分08秒. 如果那个时候人类文明还存在的话，公元纪年很可能已经因为太难用而被抛弃了. 理想的情况是到2038年，64位系统已经成为主流，从而避免特意去修正这个问题所需要的大量开销。否则，人们就必须把新的64位时间拆分成两部分并分别保存在两个变量里，这是一个麻烦而且效率低下的选择.

8.0.26版本仍然有这个问题

 if (thd->killed == THD::KILL_QUERY) thd->killed = THD::NOT_KILLED;
  thd->set_time();
  if (is_time_t_valid_for_timestamp(thd->query_start_in_secs()) == false) {
    /*
      If the time has gone past 2038 we need to shutdown the server. But
      there is possibility of getting invalid time value on some platforms.
      For example, gettimeofday() might return incorrect value on solaris
      platform. Hence validating the current time with 5 iterations before
      initiating the normal server shutdown process because of time getting
      past 2038.
    */
    const int max_tries = 5;
    LogErr(WARNING_LEVEL, ER_CONFIRMING_THE_FUTURE, max_tries);
    int tries = 0;
    while (++tries <= max_tries) {
      thd->set_time();
      if (is_time_t_valid_for_timestamp(thd->query_start_in_secs()) == true) {
        LogErr(WARNING_LEVEL, ER_BACK_IN_TIME, tries);
        break;
      }
      LogErr(WARNING_LEVEL, ER_FUTURE_DATE, tries);
    }
    if (tries > max_tries) {
      /*
        If the time has got past 2038 we need to shut this server down
        We do this by making sure every command is a shutdown and we
        have enough privileges to shut the server down
        TODO: remove this when we have full 64 bit my_time_t support
      */

从以上这两段注释来看， MySQL 内部变量 my_time_t 不支持 64 位，在到达2038年之后，MySQL 无法执行任何命令，直接关闭。

从mysql_time.h中可以看到TEMESTAMP时间最大值定义为int32

constexpr const int TIMESTAMP_MAX_VALUE =
    std::numeric_limits::max();constexpr const int TIMESTAMP_MIN_VALUE = 1;

时间字段选择

在MySQL中时间字段，timestamp最大值也为2038年，这也是由于timestamp实际存储的是int值，

可以看到在一些开发规范中也是要使用datetime类型。

https://dev.mysql.com/doc/refman/8.0/en/datetime.html


更多文章欢迎关注本人公众号，搜dbachongzi或扫二维码

作者：姚崇 Oracle OCM、 MySQL OCP、Oceanbase OBCA、PingCAP PCTA认证，擅长基于Oracle、 MySQL Performance Turning及多种关系型 NoSQL 数据库。

请使用浏览器的分享功能分享到微信等