为什么数据库启动时，开始的几行错误日志时间戳是UTC时区,而非本地时间？

最新推荐文章于 2023-12-18 17:24:45 发布

sunashe

最新推荐文章于 2023-12-18 17:24:45 发布

阅读量773

点赞数 1

欢迎转载，但请注明出处。

本文链接：https://blog.csdn.net/sun_ashe/article/details/86711077

版权

一、问题

数据库参数

log_timestamps=system

这个参数控制写入错误日志/普通日志/满日志的时区，而当设置为system时，日志应该为本地系统时区。

但是数据库启动时，前几行日志的时间可能跟系统时间不一致。

二、错误日志

2019-01-30T04:48:31.838813Z 0 [Warning] option 'table_open_cache_instances': unsigned value 128 adjusted to 64
2019-01-30T04:48:31.841289Z 0 [Warning] Could not increase number of max_open_files to more than 10240 (request: 65535)
2019-01-30T04:48:31.841326Z 0 [Warning] Changed limits: table_open_cache: 2615 (requested 4096)
2019-01-30T12:48:36.787386+08:00 0 [Warning] 'NO_AUTO_CREATE_USER' sql mode was not set.
2019-01-30T12:48:36.787555+08:00 0 [Warning] Insecure configuration for --secure-file-priv: Current value does not restrict location of generated files. Consider setting it to a valid, non-empty path.
2019-01-30T12:48:36.787698+08:00 0 [Note] /data/mysql-server/sql/mysqld (mysqld 5.7.18-debug-log) starting as process 22960 ...

可以看出前三行日志的时间是UTC时间，而非根据参数设定的那样，遵照系统时间。

这其实是因为数据库启动时，要进行配置读取，参数校验，而这个过程是区分先后顺序的。mysqld定义了一系列需要提前进行初始化和赋值的参数，见vector<my_option> all_early_options。比如说控制performance_schema是否开启的参数performance_schema

// sys_var.cc
static Sys_var_mybool Sys_pfs_enabled(
       "performance_schema",
       "Enable the performance schema.",
       READ_ONLY GLOBAL_VAR(pfs_param.m_enabled),
       CMD_LINE(OPT_ARG), DEFAULT(TRUE),
       PFS_TRAILING_PROPERTIES);

然而，控制日志文件中时间时区的参数，log_timestamps不属于提前初始化的参数，这就导致了，如果在初始化比它靠前的参数时，需要打印日志（比如说配置了不合理的参数，如上日志内容），则使用的是UTC时间，并且此时可能还没有初始化错误日志文件，只存放在缓存中，等到初始化错误日志后，再输出到文件。下面是日志组件初始化的过程。

mysqld 在日志组件初始化之前的日志

比如说下面这个warn日志,来看下它是怎么被记录的

2019-01-30T04:48:31.838813Z 0 [Warning] option 'table_open_cache_instances': unsigned value 128 adjusted to 64

代码如下

if (error_log_buffering)
  {
    // Logfile not open yet, buffer messages for now.
    if (buffered_messages == NULL)
      buffered_messages= new (std::nothrow) std::string();
    std::ostringstream s;
    s << my_timestamp << " " << thread_id;
    if (level == ERROR_LEVEL)
      s << " [ERROR] ";
    else if (level == WARNING_LEVEL)
      s << " [Warning] ";
    else
      s << " [Note] ";
    s << buffer << std::endl;
    buffered_messages->append(s.str());
  }

将这些内容存放在static std::string *buffered_messages中。
my_timestamp是调用函数make_iso8601_timestamp(my_timestamp)来获取的

// 判断log_timestamps设置
  if (opt_log_timestamps == 0)
    gmtime_r(&seconds, &my_tm);
  else
  {
    localtime_r(&seconds, &my_tm);

此时log_timestamps是没有通过配置文件赋值的，还是默认值，所以获得的timestamp值，是UTC时间，而非配置中指定的log_timestamps=system.

mysqld 日志组件初始化过程

main
    mysqld_main(int, char**)
        init_server_components()
            open_error_log(char const*)
                flush_error_log_messages()

函数flush_error_log_messages()如下，将上面说的缓存的日志进行落盘。

void flush_error_log_messages()
{
  if (buffered_messages && !buffered_messages->empty())
  {
    fprintf(stderr, "%s", buffered_messages->c_str());
    fflush(stderr);
    delete buffered_messages;
    buffered_messages= NULL;
  }
  error_log_buffering= false;
}