Error Log是MySQL的一个非常重要的日志,主要用来记录mysqld的启动和关闭,以及mysqld启动,关闭以及运行期间的诊断信息。本文主要对Error Log的初始化以及写入过程做一个详细的介绍。以下介绍基于MySQL 8.0.28。
初始化
日志服务的初始化代码调用堆栈如下:
- mysqld_main
- init_error_log
//初始化日志子系统
- log_builtins_init
//初始化filter
- log_builtins_filter_init
//启用log_sink_buffer
- log_builtins_error_stack
- init_server_components
- setup_error_log
//打开指定的error log文件,同时将stdout和stderr重定向到该文件
//这里设置stderr禁用buffer
- open_error_log
//设置log_error_stage_current为LOG_ERROR_STAGE_BUFFERING_UNIPLEX
- log_error_stage_set
//激活log_error_services中设置的所有日志组件,将之前内置的buffer日志组件缓冲
//的数据写入pfs和新启动的日志组件,同时终止内置buffer日志组件。
- setup_error_log_components
//启用配置的日志组件,禁用log_sink_buffer
- log_builtins_error_stack
//构造新的日志组件实例
- log_service_instance_new
- log_service_imp::open
//设置log_error_stage_current为LOG_ERROR_STAGE_EXTERNAL_SERVICES_AVAILABLE
- log_error_stage_set
//这里将模式切换为LOG_BUFFER_PROCESS_AND_DISCARD从而清空全局的logline,链表log_sink_buffer失效了
- flush_error_log_message
//将log_sink_buffer缓存的日志写到配置的日志服务中
- log_sink_buffer_flush
整个初始化过程可以分为两个阶段,以配置的日志组件启动为界,启动前称为阶段1,启动后称为阶段2。
阶段1
log_line
介绍这部分前先介绍一下日志项(log_line),error log的中记录的一条日志就是一个日志项,MySQL中用log_line这个结构体来表示日志项,一个日志项是由若干个field构成的,比如如下一条日志,是由时间戳,线程id,日志级别,错误码,子系统,这些field组成,在MySQL中用log_item来表示field。
在阶段1,会进行各种锁的初始化,具体各个锁的作用会在下面的文章中进行介绍。内置规则集(ruleset)的初始化,以及启用log_sink_buffer日志组件。
在阶段1,日志项会先被缓存起来,然后后续再flush(写入)到日志文件中,这个工作是通过内置的日志组件(log_sink_buffer)来做的。这是因为此时命令行的配置项(option)还没有被处理,还不清楚日志的格式,日志文件的位置等信息;即便处理完命令行后,可能日志组件还是没有被加载,仍需要将日志项缓存起来。
log_sink_buffer会通过一个全局链表将所有的log_line串起来,链表的头尾分别用两个指针log_line_buffer_start和log_line_buffer_tail来记录。这个全局链表是通过THR_LOCK_log_buffered来保护的。
当有日志项产生时, log_sink_buffer将日志项通过全局链表缓存起来,当遇到比较严重(ERROR_LEVEL/SYSTEM_LEVEL)的日志项,或者超过了log_sink_buffer的时间窗口,或此时的日志记录所处的阶段为LOG_ERROR_STAGE_BUFFERING_UNIPLEX(一般在配置的日志组件启用之前都是这个状态,所以日志项都直接输出),log_sink_buffer也会将相应日志输出,因为用一个错误的格式输出日志比什么都不输出要强。这部分逻辑在log_sink_buffer函数中,其中log_sink_buffer最终是通过log_write_errstream完成日志的输出的,代码如下:
void log_write_errstream(const char *buffer, size_t length) {
DBUG_TRACE;
DBUG_PRINT("enter", ("buffer: %s", buffer));
/*
This must work even if the mutex has not been initialized yet.
At that point we should still be single threaded so that it is
safe to write without mutex.
*/
if (error_log_initialized) mysql_mutex_lock(&LOCK_error_log);
fprintf(stderr, "%.*s\n", (int)length, buffer);
fflush(stderr);
if (error_log_initialized) mysql_mutex_unlock(&LOCK_error_log);
}
可以看到log_sink_buffer是将日志项写在标准错误流的。根据log_error变量,决定是否使用文件记录错误日志。如果使用文件,标准错误流和标准输出流在启动过程中已经被重定向到了error log文件中,同时设置了标准错误流是unbuffered,即日志项不缓存直接写入文件中,这部分代码在open_error_log中。由上面代码也可以看到,输出日志项是受LOCK_error_log保护的;如果不使用文件,则将错误日志直接记录在标准错误流中。
在阶段1,log_sink_buffer的写入对于日志项的全局链表是无损的,他是通过如下7步来做的:
-
获取 THR_LOCK_log_buffered锁
-
将全局链表转为(steal)局部链表,同时将全局链表置为空
-
释放 THR_LOCK_log_buffered锁
-
写入日志项
-
获取 THR_LOCK_log_buffered锁
-
将局部链表和全局链表合并
-
释放 THR_LOCK_log_buffered锁
这样做的好处是可以减少持有THR_LOCK_log_buffered锁的时间。
阶段2
这部分开始前,先介绍几个基本概念。
logging stack
所有设置的日志组件构成了日志组件栈。这个日志组件栈是通过THR_LOCK_log_stack来保护的。当产生一个日志项后,这个日志项会依次被日志组件栈中的日志组件所处理。日志组件栈的设置通过变量log_error_services指定的。
日志组件栈是通过全局链表来管理的,链表头是全局变量log_service_instances。同时有一个全局静态hash(log_service_cache)用来存储日志组件的相关信息。
构建logging stack的逻辑在log_builtins_error_stack函数中。该函数的主要有两个功能:1 检查日志组件栈的设置是否合理;2 设置日志组件栈。使用方法是先调用一次log_builtins_error_stack检查日志组件栈是否合理,然后在调用log_builtins_error_stack设置日志组件栈。
检查日志组件栈设置,检查了该日志组件是否存在,是否多次设置了单例组件(组件只能在日志组件栈中出现一次)以及日志组件栈的最后一个组件是否为sink类型。
该函数会根据传入的配置参数,依次检查相应的配置组件的sce(日志组件信息缓存)是否在log_service_cache中,如果不在,构建相应sce添加到log_service_cache中,增加相应组件sce的请求数。如果是进行日志组件的设置,会构建日志组件实例并打开,将该日志组件实例添加到全局log_service_instances链表中。最后检查log_service_cache,将没有opened的组件从中移除。这个过程是在THR_LOCK_log_stack X锁保护下进行的。
日志组件的类型
日志组件有三种类型:sources:产生日志信息,filter:过滤日志信息,sink:输出日志信息。我们常使用的是后面两种。日志组件是通过component的方式实现的。
filter
filter的作用就是根据定义好的规则来对日志项进行相应处理。
其中过滤规则包括一系列的过滤条件,目前已有的过滤条件如下:
typedef enum enum_log_filter_cond {
LOG_FILTER_COND_NONE = 0, /**< not set / unconditional */
LOG_FILTER_COND_EQ = 1, /**< equal */
LOG_FILTER_COND_NE = 2, /**< not equal */
LOG_FILTER_COND_LT = 3, /**< less than */
LOG_FILTER_COND_LE = 4, /**< less or equal */
LOG_FILTER_COND_GE = 5, /**< greater or equal */
LOG_FILTER_COND_GT = 6, /**< greater than */
LOG_FILTER_COND_PRESENT = 7, /**< field present */
LOG_FILTER_COND_ABSENT = 8, /**< field absent */
} log_filter_cond;
如果满足过滤条件,要进行相应的动作,对日志项进行处理,
typedef enum enum_log_filter_verb {
LOG_FILTER_UNDEF = 0, /**< not set */
LOG_FILTER_DROP = 1, /**< drop this log event */
LOG_FILTER_THROTTLE = 2, /**< rate-limit this line class */
LOG_FILTER_ITEM_SET = 3, /**< add field */
LOG_FILTER_ITEM_DEL = 4, /**< remove field */
LOG_FILTER_RETURN = 8, /**< stop filtering, run (next filter or) sinks */
LOG_FILTER_CHAIN_AND = 4096, /**< no verb yet, part of a condition chain */
LOG_FILTER_CHAIN_OR = 4097 /**< no verb yet, part of a condition chain */
} log_filter_verb;
每个filter组件会定义若干规则,MySQL中用log_filter_rule表示,每个log_filter_rule有一个读写锁rule_lock,用来保护这个rule内部状态(比如这个规则被触发了多少次等等)。这些规则构成了一个规则集,MySQL中用log_filter_ruleset表示,log_filter_ruleset也有一个读写锁ruleset_lock,当应用规则集的到日志项时使用读锁,更改规则集的时候用写锁。规则是作用于日志项的field的,如果满足规则指定的条件,则对该field进行相应的动作。应用内置filter(log_filter_internal)是在log_builtins_filter_run函数中,其中找到规则对应的日志项的field是通过log_line_index_by_item函数来进行的,判断是否满足条件的逻辑在log_filter_try_match中,对该field采用相应动作在log_filter_try_apply中。
内置filter使用的是默认规则。默认规则是在log_builtins_filter_set_defaults函数中加载的,加载到了全局变量log_filter_builtin_rules中。默认规则只有三条,日志项的级别为SYSTEM_LEVEL和ERROR_LEVEL的不被过滤,直接写日志;级别大于log_error_verbosity的,丢弃不记录;删除所有日志项的source line这个filed。
阶段2
阶段2主要进行3个工作:
构造logging stack,这部分的逻辑在log_builtins_error_stack中,在构造logging stack时,将日志组件实例化,并打开了日志组件对应的写入文件。
设置stage为LOG_ERROR_STAGE_EXTERNAL_SERVICES_AVAILABLE,从而使得log_sink_buffer失效。
将通过log_sink_buffer记录的日志项写入到配置的日志组件中,同时将记录日志项的全局链表清空,这部分逻辑在flush_error_log_messages函数中。
日志的写入
日志的写入逻辑是在log_line_submit函数中,在这个函数中会先在日志项中添加一些field,如时间戳,线程id等等;在完成了filed的添加后会调用日志组件对日志项进行处理。
在配置的日志组件启动前(阶段1),是通过log_sink_buffer记录日志的,log_sink_buffer的逻辑已经在阶段1详细介绍过。
在阶段2,log_line_submit会依次调用配置的日志组件(顺序由系统变量log_error_services指定),对日志项进行处理。其中log_filter_internal使用的是默认规则,log_sink_internal是也是通过log_write_errstream来写入的。其他的日志组件服务通过log_service_imp::run接口来调用。
flush error logs
flush error logs命令会执行两步操作,关闭错误日志文件,然后重新打开。具体调用堆栈如下:
- mysql_execute_command
- handle_reload_request
- reopen_error_log
- fropen
对于非内置日志组件,通过log_service_imp::flush接口来调用日志组件提供的服务。对于内置日志组件,通过open_error_log函数来完成日志组件的关闭和重新打开。
bool reopen_error_log() {
bool result = false;
assert(error_log_initialized);
// reload all error logging services
log_builtins_error_stack_flush();
if (error_log_file) {
mysql_mutex_lock(&LOCK_error_log);
result = open_error_log(error_log_file, true);
mysql_mutex_unlock(&LOCK_error_log);
if (result)
my_error(ER_DA_CANT_OPEN_ERROR_LOG, MYF(0), error_log_file, ".",
""); /* purecov: inspected */
#ifdef WITH_XENGINE_STORAGE_ENGINE
else if (mysql_reinit_xengine_log())
sql_print_error("Failed to re-initialize logger in XEngine: %s", error_log_file);
#endif
}
return result;
}
代码详解
笔者在上面的文章中,对Error Log的初始化和写入做了基本的介绍。笔者在下面的文章中,对初始化和写入过程中比较重要的函数做了更进一步的讲解,感兴趣的读者可以继续阅读。下面提到的函数,在上面的文章中基本都有出现,读者可以结合上面的介绍,了解这些函数所处的位置和具体的作用。
log_builtins_error_stack
//获取THR_LOCK_log_stack锁
mysql_rwlock_wrlock(&THR_LOCK_log_stack);
//如果要重新配置日志服务,则释放之前配置的日志服务
if (!check_only) {
log_sink_pfs_source = nullptr;
log_service_instance_release_all();
}
while ((len = log_builtins_stack_get_service_from_var(&start, &end, &delim)) >
0){
...
//如果当前日志组件没有配置,则为该组件构造信息缓存(sce),并
//将该sce添加到全局hash表log_service_cache中
if (it == log_service_cache->end()) {
...
}else
//如果日志组件已经配置,则获取该组件的缓存
sce = it->second.get();
//增加该日志组件的请求数
sce->requested++;
//如果只是检查配置是否合理,则只进行信息统计
if (check_only) {...}
//
else if ((sce->requested == 1) ||
!(sce->chistics & LOG_SERVICE_SINGLETON)){
//构造该日志组件的实例,并将该日志组件添加到全局日志链表中
//同时记录第一个log-parser(可以解析日志的组件,不仅可以写,还可以读)
//第一个支持向pfs表写入的sinker,以及filter的数量
...
}else{
//构造组件实例失败
rr = LOG_ERROR_STACK_SERVICE_INSTANCE_OOM; /* purecov: inspected */
goto done;
}
//循环处理下一个日志组件
start = end;
}
done:
//从日志组件全局链表移除不在使用的组件
...
//得到支持pfs的日志组件
if (!check_only) {
log_sink_pfs_source = (log_sink_pfs_parser != nullptr)
? log_sink_pfs_parser
: log_sink_pfs_buffer;
}
...
log_sink_buffer_flush
//获得锁THR_LOCK_log_buffered
if (log_builtins_inited && (mode != LOG_BUFFER_REPORT_AND_KEEP))
mysql_mutex_lock(&THR_LOCK_log_buffered);
//清空全局logline链表
local_head = log_line_buffer_start; // save list head
log_line_buffer_start = nullptr; // empty public list
log_line_buffer_tail = &log_line_buffer_start; // adjust tail of public list
//释放锁
if (log_builtins_inited && (mode != LOG_BUFFER_REPORT_AND_KEEP))
mysql_mutex_unlock(&THR_LOCK_log_buffered);
//如果是buffer mode,从上次处理的logline后接着继续处理
if (mode == LOG_BUFFER_REPORT_AND_KEEP) {
if (log_sink_buffer_latest_event_shown != nullptr) {
local_tail = log_sink_buffer_latest_event_shown;
llp = local_tail->next;
}
} else {
log_sink_buffer_latest_event_shown = nullptr;
}
//循环向日志文件中写logline
while (llp != nullptr) {
//如果不是在丢弃日志项模式下
if (mode != LOG_BUFFER_DISCARD_ONLY) {
//处理时间戳(如果缓冲这条logline的时候已经记录了时间戳,则用此时间戳,否则
//使用当前时间作为时间戳)
...
//如果在buffer mode模式下,说明配置的日志服务还未启动,此时使用内置的日志服务
if (log_sink_buffer_is_buffered_mode(log_service_instances)){
//LOG_BUFFER_REPORT_AND_KEEP代表先使用内置日志服务,后续配置的日志服务
//启动后还要使用配置的日志服务
if (mode == LOG_BUFFER_REPORT_AND_KEEP) {
//复制构建临时logline
...
//根据规则过滤logline
if (log_filter_builtin_rules != nullptr)
log_builtins_filter_run(log_filter_builtin_rules, &temp_line);
//使用内置服务将logline写入日志
log_sink_trad(nullptr, &temp_line);
//释放临时logline
log_line_item_free_all(&temp_line);
//记录已经处理的位置,方便下次直接从改位置后开始处理
log_sink_buffer_latest_event_shown = llp;
//logline链表指针移动,循环处理
local_tail = llp;
llp = llp->next;
continue;
}else{
//否则处于LOG_BUFFER_PROCESS_AND_DISCARD模式下,此时说明出现了严重
//的错误,已经在进行shundown了
//仍旧使用内置日志服务进行日志过滤并打印
}else {
//说明配置的日志服务已经启动,向配置的日志服务提交日志项
log_line_submit(&llp->ll);
goto kv_freed;
}
}
//销毁logline
log_line_item_free_all(&local_head->ll);
kv_freed:
//移动指针处理下一条logline,并释放保存当前logline的logbuffer
local_head = local_head->next;
my_free(llp);
llp = local_head;
}
//加锁
if (log_builtins_inited && (mode != LOG_BUFFER_REPORT_AND_KEEP))
mysql_mutex_lock(&THR_LOCK_log_buffered);
//如果local_head不为空,将局部Logbuffer的链表和全局的合并
....
//放锁
if (log_builtins_inited && (mode != LOG_BUFFER_REPORT_AND_KEEP))
mysql_mutex_unlock(&THR_LOCK_log_buffered);
日志的写入
#define LogErr(severity, ecode, ...) \
LogEvent() \
.prio(severity) \
.errcode(ecode) \
.subsys(LOG_SUBSYSTEM_TAG) \
.source_line(__LINE__) \
.source_file(MY_BASENAME) \
.function(__FUNCTION__) \
.lookup(ecode, ##__VA_ARGS__)
可以看到LogEvent是用流接口模式设计的,这种设计模式的特点就是通常采取方法瀑布调用 (具体来说是方法链式调用)来转发一系列对象方法调用的上下文 。这个对象定义了三个私有成员变量,和各种方法。
private:
log_line *ll; //日志项的集合
char *msg;
const char *msg_tag;
log_line的定义如下
typedef struct _log_line {
log_item_type_mask seen; ///< bit field flagging item-types contained
log_item_iter iter; ///< iterator over key/value pairs
log_item output_buffer; ///< buffer a service can return its output in
int count; ///< number of key/value pairs ("log items")
log_item item[LOG_ITEM_MAX]; ///< log items
} log_line;
log_line是一系列日志项的集合,日志项对应的类型是log_item定义如下,log_item是由key/value构成的
typedef struct _log_item {
log_item_type type;
log_item_class item_class;
log_item_key key;
log_item_data data;
uint32 alloc;
} log_item;
其中key就是c的风格的string
typedef const char *log_item_key;
data的具体定义如下
typedef union _log_item_data {
longlong data_integer;
double data_float;
MYSQL_LEX_CSTRING data_string;
MYSQL_LEX_STRING data_buffer;
} log_item_data;
其中存储数据的data_string和缓存数据的data_buffer都是自定义的一个记录长度的字符串
struct MYSQL_LEX_CSTRING {
const char *str;
size_t length;
};
struct MYSQL_LEX_STRING {
char *str;
size_t length;
};
iter的定义如下:
/**
Iterator over the key/value pairs of a log_line.
At present, only one iter may exist per log_line.
*/
typedef struct _log_item_iter {
struct _log_line *ll; ///< log_line this is the iter for
int index; ///< index of current key/value pair
} log_item_iter;
LogEvent在通过链式调用,设置了各种信息后,最后要通过lookup函数来构建最后输出的字符串。可以看到这块用到了可变参数,从而允许根据自定义的错误模板来输出错误信息,errorcode用来寻找在messages_to_error_log.txt或者messages_to_clients.txt定义的错误模板。
LogEvent &lookup(longlong errcode, ...) {
va_list args;
va_start(args, errcode);
set_message_by_errcode(errcode, args);
va_end(args);
return *this;
}
可以看到lookup函数主要是调用set_message_by_errcode,这个函数是用来设置error code以及组装最终的输出的,函数定义如下:
inline void LogEvent::set_message_by_errcode(longlong errcode, va_list ap) {
const char *fmt = error_msg_by_errcode((int)errcode);
if ((fmt == nullptr) || (*fmt == '\0')) fmt = "invalid error code";
//设置error code
set_errcode(errcode);
//组装输出的信息
set_message(fmt, ap);
}
其中Log_event::~Log_event用来发送event,同时在处理后自动销毁。从下面可见,依次调用了submit,exit和free。
~LogEvent() {
if (ll != nullptr) {
log_line_submit(this->ll);
//释放日志项(logline)
log_line_exit(ll);
//释放msg
log_free(msg);
}
}
log_line_submit函数见log_builtins.cc文件。该函数主要完成日志项的提交,过滤和写入。
//log_line_submit先是添加了额外的日志项
/* auto-add a prio item */
...
//如果日志项有内容
if (ll->count > 0){
//如果内置日志服务还没启动,构造log_sink_buffer,这个log_sink_buffer
//用一个global的链表把log_line记录下来
//当超过设定的时间窗口,或者只有单个sink或文件时,或者log_line是
//ERROR_LEVEL/SYSTEM_LEVEL时将log_line flush到日志文件中
if (!log_builtins_inited)
log_sink_buffer(nullptr, ll);
//如果内置日志服务启动了,调用所有配置的日志服务
else{
//加stack锁,因为下面要循环调用所有日志服务
mysql_rwlock_rdlock(&THR_LOCK_log_stack);
//日志服务组件有三类,sources:添加日志信息
//filter:过滤日志信息,sink:将日志信息写入日志
/*
Call all configured log-services (sources, filters, sinks)
on this log-event.
sources:
Add info from other log item sources,
e.g. that supplied by the client on connect using mysql_options4();
filters:
Remove or modify entries
sinks:
Write logs
*/
//循环调用每项日志服务
while ((lsi != nullptr) && ((sce = lsi->sce) != nullptr)) {
...
//先调用缓冲日志服务
if (sce->chistics & LOG_SERVICE_BUFFER)
log_sink_buffer(lsi->instance, ll);
//然后调用可加载(loadble)服务
else if (!(sce->chistics & LOG_SERVICE_BUILTIN)) {
SERVICE_TYPE(log_service) * ls;
ls = reinterpret_cast<SERVICE_TYPE(log_service) *>(sce->service);
if (ls != nullptr) ls->run(lsi->instance, ll);
}
//调用内置filter
else if (log_service_has_characteristics(
sce, (LOG_SERVICE_BUILTIN | LOG_SERVICE_FILTER)))
log_builtins_filter_run(log_filter_builtin_rules, ll);
//调用内置sink
else if (log_service_has_characteristics(
sce, (LOG_SERVICE_BUILTIN | LOG_SERVICE_SINK)))
//内置sink直接调用log_sink_trad写日志
log_sink_trad(lsi->instance, ll);
lsi = lsi->next;
}
...
//写入performance_schema.error_log
log_sink_perfschema(nullptr, ll);
//释放THR_LOCK_log_stack锁
mysql_rwlock_unlock(&THR_LOCK_log_stack);
}
//释放日志项
log_line_item_free_all(ll);
}
总结
MySQL官方提供了一些日志组件,但是一般来说,使用的比较广泛的是默认的日志组件,默认日志组件是有一些缺陷的,如默认的sinker没有提供buffer的能力,每条日志直接写入文件,对于记录大量日志的情况,很可能成为性能瓶颈,对于默认的filter,其过滤规则也只有三条,不能提供更具个性化的过滤能力。但是MySQL采用component的形式实现日志组件,从而提供了良好的扩展性,我们可以方便的实现自己的日志组件,来满足自己的需求。