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