FFLIB C++ 异步&类型安全&printf风格的日志库
摘要
C++程序的调试一般有调试器、printf、日志文件三种。Linux下的调试器为gdb，关于gdb的使用甚至可以单独用一本书来说明，但是本章并不会过度讨论gdb，读者可以寻找相关的资料阅读。Gdb是C++程序调试中非常重要的调试手段，其有如下特点：
- l 通过增加断点，可以观察重点代码的执行
- l 若程序出现segmentation fault，gdb可以输出调用堆栈，方便找到bug之所在
- l 有些逻辑代码段非常不容易触发，可以在gdb环境下通过加断点、修改内存来强制进入特定的代码段
- l 但是gdb不能用于生产环境，在几百上千在线的服务器程序上执行gdb的attach操作，是不可能接受的
Gdb绝对是调试期的利器，另外一个调试期使用的既简单又实用的方法是printf，就是使用c库的函数printf输出变量到控制台。其优点是直观，可以完整的、清晰的观察程序的运行过程，而不需像gdb一样暂停程序。另外printf也只能用于开发调试环境，上线时服务器程序都是在后台运行的，printf将会失去作用。更重要的是因为gdb和printf都不会将数据存储，历史数据或历史操作都会在重启程序后消失。日志文件可以弥补gdb和printf的不足，我们需要一个具有如下功能的日志组件：
- l 用于调试可以显示、记录变量、数据，即能支持像printf一样可以实时的在控制台输出显示，又能将记录存储文件，方便搜索查看历史记录
- l 日志应该拥有良好的格式，即方便开发和运维人员的阅读，又要包含足够多的信息，例如事件记录时间、线程id、事件类型，事件的严重级别
- l 日志文件应该被良好的组织，一方面日志应该按照每天单独文件夹分类，另一方面日志日志文件并应该过大，否则使用编辑器打开、搜索将会非常困难。日志内容也应该组织分类，比如数据库的操作日志和用户做任务的日志应该有明确的标志，这样可以对日志文件进行grep等进行过滤分类查看。
- l 日志文件必须非常容易配置，当调试时期望看到尽可能多的内容，但是不关心的内容需要被过滤掉，比如调试用户任务模块时，可以不显示数据库相关日志。在上线后，运维只关心报错信息，比警告级别低的日志需要被屏蔽。在调试时，开发人员经常会盯着控制台的输出，相比于普通级别日志内容，错误级别的日志更应该引起开发注意力，所以重要级别的日志在控制台输出时应该有彩色高亮显示。
- l 日志组件必须有高效的性能，一方面调用者期望日志组件调用后立即返回不影响逻辑层的效率，另一方面写文件属于io操作，比起内存操作慢的多得多。所以要求日志的接口调用是异步的，日志组件单独开启线程执行写文件操作，只有如此才能尽最大程度满足程序的实时性。
下面来探讨一下日志 的实现。
实现类
定义log_t类来封装对于日志配置、格式化、输出的操作。log_t主要的功能有：
- l 支持对日志级别的配置
- l 支持对日志类别的配置
- l 支持配置日志内容是否输出到文件和控制台
- l 格式化日志
class log_t { public: log_t(int level_, const string& all_class_, const string& path_, const string& file_, bool print_file_, bool print_screen_); virtual ~log_t(); void mod_level(int level_, bool flag_); void mod_class(const string& class_, bool flag_); void mod_print_file(bool flag_); void mod_print_screen(bool flag_); bool is_level_enabled(int level_); const char* find_class_name(const char* class_); void log_content(int level_, const char* str_class_, const string& content_); };
接口log_content 负责格式化和输出日志内容，其主要实现代码如下：
void log_t::log_content(int level_, const char* str_class_, const string& content_) { struct timeval curtm; gettimeofday(&curtm, NULL); struct tm tm_val = *localtime(&(curtm.tv_sec)); char log_buff[512]; ::snprintf(log_buff, sizeof(log_buff), "%02d:%02d:%02d.%03ld %s [%ld] [%s] ", tm_val.tm_hour, tm_val.tm_min, tm_val.tm_sec, curtm.tv_usec/1000, g_log_level_desp[level_], gettid(), str_class_); if (m_enable_file && check_and_create_dir(&tm_val)) { m_file << log_buff << content_ << endl; m_file.flush(); } if (m_enable_screen) { printf("%s%s%s%s\n", g_log_color_head[level_], log_buff, content_.c_str(), g_log_color_tail[level_]); } }
其执行的主要过程如下:
- l 格式化时间，包括调用时的时分秒以及毫秒，为什么没有年月日呢？日志目录已经安装每天一个文件夹分类了，故这里省略了年月日信息。
- l 增加日志级别信息，日志级别对应一个字符串描述，如debug级别日志每一行会包含DEBUG字符串。
- l 记录线程id，这里并没有直接使用::pthread_self() 获取线程id，而是获取线程在系统中分配的“TID”,要知道线程和进程在内核中都有唯一的id，可以通过top进行查看，top -H –p [pid] 可以查看进程内的所有线程的运行负载情况，如果某个线程运行负载很高，我们需要知道到底是那一部分逻辑是热点，通过搜索日志，可以知道该线程负责了哪块逻辑，从而能够发现问题。
- l 记录日志类别
- l 若配置允许输出屏幕，那么利用printf输出，不同的日志级别会有不同的显示颜色，如printf("\033[1;33mDEBUG\033[0m")， DEBUG 会以黄色输出。
- l 若配置允许输出文件，那么flush到文件中，若日期发生变化，重新创建日期目录，保证每一天一个文件夹，若单个文件内容超过5000行，会创建新的文件，避免文件内容过大，最终目录机构如下
异步操作
为了保证日志接口尽可能的快，日志接口都是异步完成的其。时序图如下：
对于用户层而言，调用日志组件接口的开销为日志内容格式化和拷贝字符串到队列，而相对开销较大的写文件、输出屏幕操作则有日志线程完成，这样可以最大程度的保证用户层的高效运行。
我们定义log_service_t封装异步操作，对于格式化和输出，log_service_t仍然通过log_t实现，log_service_t的职责有四：
- l 封装异步接口，外部直接调用log_service_t的接口，一般log_service_t一单件模式使用
- l Log_service_t接口模板函数，利用C++的泛型能力确保类型安全，比如当%s参数本应该是user.name()时，却手误写成user，log_service_t的接口保证在编译器就能报错。
- l Log_service_t创建日志线程和日志任务队列，
- l Log_service_t在初始化的时候接受配置日志组件的参数，同时它也支持在运行期修改参数，并且线程安全。
关键代码如下：
class log_service_t { public: log_service_t(); ~log_service_t(); int start(const string& opt_); int stop(); LOG_IMPL_MACRO(async_logdebug, LOG_DEBUG); LOG_IMPL_MACRO(async_logtrace, LOG_TRACE); LOG_IMPL_MACRO(async_loginfo, LOG_INFO); LOG_IMPL_MACRO(async_logwarn, LOG_WARN); LOG_IMPL_MACRO(async_logerror, LOG_ERROR); LOG_IMPL_MACRO(async_logfatal, LOG_FATAL); };
由于各个日志级别的接口代码都是相似的，使用了LOG_IMPL_MACRO简化代码，LOG_IMPL_MACRO定义为：
#define LOG_IMPL_NONE_ARG(func, LOG_LEVEL) \ inline void func(const char* class_, const char* fmt_) \ { \ if (m_log->is_level_enabled(LOG_LEVEL)) \ { \ const char* class_name_str = m_log->find_class_name(class_); \ if (class_name_str) \ { \ m_task_queue.produce(task_binder_t::gen(&log_t::log_content, m_log, LOG_LEVEL, \ class_name_str, string(fmt_))); \ } \ } \ } #define LOG_IMPL_ARG1(func, LOG_LEVEL) \ template <typename ARG1> \ inline void func(const char* class_, const char* fmt_, const ARG1& arg1_) \ { \ if (m_log->is_level_enabled(LOG_LEVEL)) \ { \ const char* class_name_str = m_log->find_class_name(class_); \ if (class_name_str) \ { \ str_format_t dest(fmt_); \ dest.append(arg1_); \ m_task_queue.produce(task_binder_t::gen(&log_t::log_content, m_log, LOG_LEVEL, \ class_name_str, dest.gen_result())); \ } \ } \ } #define LOG_IMPL_MACRO(async_logdebug, LOG_DEBUG) \ LOG_IMPL_NONE_ARG(async_logdebug, LOG_DEBUG) \ LOG_IMPL_ARG1(async_logdebug, LOG_DEBUG) \ LOG_IMPL_ARG2(async_logdebug, LOG_DEBUG) \ LOG_IMPL_ARG3(async_logdebug, LOG_DEBUG) \ LOG_IMPL_ARG4(async_logdebug, LOG_DEBUG) \ LOG_IMPL_ARG5(async_logdebug, LOG_DEBUG) \ LOG_IMPL_ARG6(async_logdebug, LOG_DEBUG)
受篇幅所限，没有附上所有宏展开的代码，log_service_t初始化的代码如下：
int log_service_t::start(const string& opt_) { if (m_log) return 0; int level = 2; string path = "./log"; string filename = "log"; bool print_file = true; bool print_screen = false; arg_helper_t arg(opt_); if (!arg.get_option_value("-log_level").empty()) level = ::atoi(arg.get_option_value("-log_level").c_str()); if (!arg.get_option_value("-log_path").empty()) path = arg.get_option_value("-log_level"); if (!arg.get_option_value("-log_filename").empty()) path = arg.get_option_value("-log_filename"); if (arg.get_option_value("-log_print_file") == "false" || arg.get_option_value("-log_print_file") == "0") { print_file = false; } if (arg.get_option_value("-log_print_screen") == "true" || arg.get_option_value("-log_print_screen") == "1") { print_screen = true; } m_log = new log_t(level, arg.get_option_value("-log_class"), path, filename, print_file, print_screen); m_thread.create_thread(task_binder_t::gen(&task_queue_t::run, &m_task_queue), 1); return 0; }
代码很简单，也很直观，需要对读者解释的是，初始化接口start的参数为字符串，这样做的好处是可以从配置文件中读入日志配置参数后直接传给log_service_t的start接口，而用户层完全不需要关心日志配置语法的细节。Start函数创建log_t实例后，创建单独线程执行任务队列，而任务队列中的所有任务就是写日志内容或输出日志内容。
格式化
关于格式化输出，使用使用了模板函数和多态机制保证了绝对的类型安全，这也是相对于sprintf的巨大优越点。class str_format_t 是用来格式化字符串的工具类，它使用sprintf的格式化语法，但是额外提供了排错和纠错功能：
- l 使用sprintf格式化语法，最基本的格式化参数都支持如%d,%u,%ld,%lu,%s,%c,%x,%p,%f甚至形如%04d设置字符串宽度的语法也是支持的
- l str_format_t 类型安全，格式化参数支持整型、浮点数、字符串cost char*、指针、string,若赋值其他类型参数，则编译不能通过。
- l str_format_t 拥有自动纠错功能，使用sprintf的时候除了类型不安全导致出错外，最常见的就是sprintf的格式化参数与赋值的参数个数不一致，如sprintf(buff, “%s,%s”, 100);这样的代码编译能够通过只有运行期才能发现出错，str_format_t 可以容忍这样的失误，当模板字符串中%比赋值的参数多时，str_format_t自动忽略多余的%，若%比后边的值参数少时，值参数自动追加到字符串尾部，这样最大程度的避免了出错和信息丢失。
关于基本类型的格式化模板函数：
template<typename T>
void append(T content_)
{
if (move_to_next_wildcard())
{
if (m_fmt_type.type == 'x')
{
char buff[64];
snprintf(buff, sizeof(buff), "0x%x", (unsigned int)content_);
m_num_buff = buff;
}
else
{
m_strstream << content_;
m_strstream >> m_num_buff;
}
int width = m_fmt_type.min_len > m_num_buff.length()? m_fmt_type.min_len - m_num_buff.length(): 0;
for (; width > 0; -- width)
{
m_result += m_fmt_type.fill_char;
}
}
else
{
m_strstream << content_;
m_strstream >> m_num_buff;
}
m_result += m_num_buff;
m_strstream.clear();//! clear error bit,not content
m_num_buff.clear();
}
关于字符串的特化函数：
void str_format_t::append(const string& str_) { if (move_to_next_wildcard()) { int width = m_fmt_type.min_len > str_.length()? m_fmt_type.min_len -str_.length(): 0; for (; width > 0; -- width) { m_result += m_fmt_type.fill_char; } } m_result += str_; }
move_to_next_wildcard 每次尝试移动到下一个%所在的位置，然后用值参数替换%的格式化。move_to_next_wildcard的整个开销是遍历字符串的开销：
bool str_format_t::move_to_next_wildcard() { m_fmt_type.clear(); char tmp = '\0'; for (; cur_format_index < m_fmt_len; ++ cur_format_index) { tmp = m_fmt[cur_format_index]; if (tmp != '%') { m_result += tmp; continue; } char next = m_fmt[cur_format_index + 1]; if (next == '%') { cur_format_index += 1; m_result += next; continue; } //! 支持多种格式化 %c %s, %d, %ld, %u, %lu, %x, %X, 找到格式化的类型 //for (++cur_format_index; cur_format_index < m_fmt_len; ++ cur_format_index) for (unsigned int i = 1 ; i <= 5; ++i) { char cur = m_fmt[cur_format_index + i]; if (cur == '\0' || cur == '%') { break; } else if (cur == 'c' || cur == 'd' || cur == 'u' || cur == 'x' || cur == 'f' || cur == 's') { m_fmt_type.type = cur; m_fmt_type.min_len = ::atoi(m_fmt + cur_format_index + 1); cur_format_index = cur_format_index + i + 1; if (next == '0') { m_fmt_type.fill_char = next; } return true; } else if (cur == 'l') { char c_num = m_fmt[cur_format_index + i + 1]; if ('d' == c_num || 'u' == c_num) { m_fmt_type.type = c_num; m_fmt_type.min_len = ::atoi(m_fmt + cur_format_index + 1); cur_format_index = cur_format_index + i + 2; if (next == '0') { m_fmt_type.fill_char = next; } return true; } } } m_result += tmp; } return false; }
配置
最基本的log_service_t的start接口提供了初始化日志组件时的配置，配置参数:
enum log_level_e { LOG_FATAL = 0, LOG_ERROR, LOG_WARN, LOG_INFO, LOG_TRACE, LOG_DEBUG, LOG_LEVEL_NUM };
- l -log_level 配置日志级别，0-5代表不同的日志级别，枚举定义如下：
- l -log_path 配置日志文件存储的根目录
- l -log_filename 配置文件名称
- l -log_print_file" 配置日志是否输出到文件
- l log_print_screen 配置日志是否输出到屏幕
- l - log_class 配置哪些日志类别是开启的，只有 开启的类别日志才会被记录
这其中除了log_path和log_filename不需要运行期配置外，其他的配置都有运行期修改的需求，比如运行期某个类别的日志被关闭了，但是为了跟踪某问题必须开启，如果不能动态修改日志配置往往会是开发人员面对问题时束手无策。对于-log_print_file 和-log_print_screen 都是用bool记录的，-log_level 是整型记录的，都是直接支持运行期修改的。有的读者可能指出日志不是有单独线程吗，而且使用线程组件的用户层也可能是多线程的，不就设计到了多线程竞争了吗？在明白此答案之前，先让我们缕一缕log中的结构：
- l 日志的接口会被多线程调用
- l 异步日志接口会访问日志的配置，判断该日志类别或级别是否已开启，由于只有读取操作，不需要加锁。
- l 日志格式化后投递到队列，队列是线程安全的，只有日志线程会从任务队列中消费任务。
- l 运行修改日志配置的操作会投递到日志线程完成，保证任一时刻只有一个线程修改日志配置
对于-log_print_file 、-log_print_screen 和-log_level 都是多线程读取访问，某一时刻一个线程修改，并且三者都是基本类型的，不存在内存地址变化的问题，这样日志线程修改后会立即生效。但是对于-log_class，被开启的日志类别都被保存到set<string> 的结构中，多线程对其执行find操作是安全的，这个stl的多线程特性是明确支持的。但是若对set<string> 在运行期执行insert或erase后会使set<string>中的迭代器失效，被坏的情况是会引起读操作的线程崩溃，所以在运行期绝对不能对老的日志类别容器进行修改。难道日志类别就没办法运行期修改了吗？脑筋急转弯一下，既然不能修改老的，为什么不创建一个新的，然后用新的替换老的？为了使用这个方法，需要一些小技巧：
l 使用一个指针引用当前日志级别的容器，度线程总是获取该指针，然后执行find操作find_class_name 根据类别字符串去容器中查找是否存在。这里使用了原子操作ATOMIC_FETCH，在gcc的环境下可以把它定义为：
#define ATOMIC_FETCH(src_ptr) __sync_add_and_fetch(src_ptr, 0) typedef set<string> str_set_t; typedef vector<str_set_t*> ptr_vt_t; str_set_t* m_enable_class_set; const char* log_t::find_class_name(const char* class_) { str_set_t* pset = ATOMIC_FETCH(&m_enable_class_set); str_set_t::iterator it = pset->find(class_); if (it != pset->end()) { return (*it).c_str(); } return NULL; }
l find_class_name对于存储日志类别的容器指针使用了原子操作，所以要保证指针对应的数据永远不被修改，即使有新的配置产生时，老的配置仍然不会被销毁，利用数据冗余保证无锁操作的线程安全，最后将新配置容器的指针替换老配置的指针即可，同样使用原子操作完成
#define ATOMIC_SET(src_ptr, v) (void)__sync_bool_compare_and_swap(src_ptr, *(src_ptr), v) void log_t::mod_class(const string& class_, bool flag_) { str_set_t* pset = new str_set_t(m_enable_class_set->begin(), m_enable_class_set->end()); if (flag_) { pset->insert(class_); } else { pset->erase(class_); } m_class_set_history.push_back(pset); ATOMIC_SET(&m_enable_class_set, pset); }
总结以上无锁编程的技巧有：
l 对于stl的对象的多线程读操作是安全的
l 对于指针可以使用原子操作进行读取、更新、比较等操作
l 老的容器被保存而不是销毁，从而保证了获取了老数据的线程仍然能够工作正常，日志的类别字符串只有十几顶多几十个，这里做数据冗余的内存开销是可以忽略的。
使用
日志的异步接口是由log_service_t定义的，前边介绍log_service_t的时候也提到了log_service_t一般是被单件使用的，如果每次调用singleton_t<log_service_t>::instance().async_logdebug(“XX”, “OhNice”);代码太长了，使用宏封装单件的操作：
#define LOG singleton_t<log_service_t>::instance() #define LOGDEBUG(content) singleton_t<log_service_t>::instance().async_logdebug content #define LOGTRACE(content) singleton_t<log_service_t>::instance().async_logtrace content #define LOGINFO(content) singleton_t<log_service_t>::instance().async_loginfo content #define LOGWARN(content) singleton_t<log_service_t>::instance().async_logwarn content #define LOGERROR(content) singleton_t<log_service_t>::instance().async_logerror content #define LOGFATAL(content) singleton_t<log_service_t>::instance().async_logfatal content
使用宏的好处是，比如logtrace可能会被到处使用了，而有可能其只在调试器有用，那么在release版本时候可以把宏LOGTRACE定义成空操作，当然若日志级别不开启的情况下，调用LOGTRACE的开销是很小的，一般情况可以忽略其影响。
使用示例：
int main(int argc, char* argv[]) { LOG.start("-log_path ./log -log_filename log -log_class FF,XX -log_print_screen true -log_print_file true -log_level 6"); LOGDEBUG(("XX", "FFFFF")); LOGTRACE(("XX", "FFFFF")); LOGINFO(("XX", "FFFFF")); LOGWARN(("XX", "FFFFF")); LOGERROR(("XX", "FFFFF")); LOGFATAL(("XX", "FFFFF")); LOG.mod_class("TT", true); sleep(1); LOGFATAL(("TT", "FFFFF")); LOGFATAL(("FF", "DSDFFFFF%s", string("SFWEGGGGGGGGG"))); LOG.stop(); return 0; }
总结：
- l 日志组件需要尽可能的快从而对于调用者的影响降到最低，使用异步接口可以使日志接口调用后立即返回
- l 日志的文件组织需要较好的被分类，目录首先按照时间分类，每天生成一个目录存储当天的日志，并且日志文件对大小做了上限，超过限制会重新创建新的文件，保证单个日志文件不会过大
- l 日志组件被设计成printf的格式化风格，但是增加了类型安全和参数纠错，不支持的类型会在编译期发现，值参数数目过多会被追加到字符串尾部，过少则忽略相应的%。
- l 日志组件是线程安全的，对于日志的配置虽然是多线程无锁访问的，仍然支持运行期动态的修改配置，其中使用了原子操作既保证了无锁编程的高效，又满足了多线程的稳定。
- 源码：https://github.com/fanchy/fflib
