FFLIB C++ 异步&类型安全&printf风格的日志库

FFLIB C++ 异步&类型安全&printf风格的日志库

摘要

C++程序的调试一般有调试器、printf、日志文件三种。Linux下的调试器为gdb,关于gdb的使用甚至可以单独用一本书来说明,但是本章并不会过度讨论gdb,读者可以寻找相关的资料阅读。Gdb是C++程序调试中非常重要的调试手段,其有如下特点:

  • 通过增加断点,可以观察重点代码的执行
  • 若程序出现segmentation fault,gdb可以输出调用堆栈,方便找到bug之所在
  • 有些逻辑代码段非常不容易触发,可以在gdb环境下通过加断点、修改内存来强制进入特定的代码段
  • 但是gdb不能用于生产环境,在几百上千在线的服务器程序上执行gdb的attach操作,是不可能接受的Gdb绝对是调试期的利器,另外一个调试期使用的既简单又实用的方法是printf,就是使用c库的函数printf输出变量到控制台。其优点是直观,可以完整的、清晰的观察程序的运行过程,而不需像gdb一样暂停程序。另外printf也只能用于开发调试环境,上线时服务器程序都是在后台运行的,printf将会失去作用。更重要的是因为gdb和printf都不会将数据存储,历史数据或历史操作都会在重启程序后消失。日志文件可以弥补gdb和printf的不足,我们需要一个具有如下功能的日志组件:

  • 用于调试可以显示、记录变量、数据,即能支持像printf一样可以实时的在控制台输出显示,又能将记录存储文件,方便搜索查看历史记录

  • 日志应该拥有良好的格式,即方便开发和运维人员的阅读,又要包含足够多的信息,例如事件记录时间、线程id、事件类型,事件的严重级别
  • 日志文件应该被良好的组织,一方面日志应该按照每天单独文件夹分类,另一方面日志日志文件并应该过大,否则使用编辑器打开、搜索将会非常困难。日志内容也应该组织分类,比如数据库的操作日志和用户做任务的日志应该有明确的标志,这样可以对日志文件进行grep等进行过滤分类查看。
  • 日志文件必须非常容易配置,当调试时期望看到尽可能多的内容,但是不关心的内容需要被过滤掉,比如调试用户任务模块时,可以不显示数据库相关日志。在上线后,运维只关心报错信息,比警告级别低的日志需要被屏蔽。在调试时,开发人员经常会盯着控制台的输出,相比于普通级别日志内容,错误级别的日志更应该引起开发注意力,所以重要级别的日志在控制台输出时应该有彩色高亮显示。
  • 日志组件必须有高效的性能,一方面调用者期望日志组件调用后立即返回不影响逻辑层的效率,另一方面写文件属于io操作,比起内存操作慢的多得多。所以要求日志的接口调用是异步的,日志组件单独开启线程执行写文件操作,只有如此才能尽最大程度满足程序的实时性。
    下面来探讨一下日志 的实现。

实现类

定义log_t类来封装对于日志配置、格式化、输出的操作。log_t主要的功能有:

  • 支持对日志级别的配置
  • 支持对日志类别的配置
  • 支持配置日志内容是否输出到文件和控制台
  • 格式化日志
    1
    2
    3
    4
    5
    6
    7
    8
    9
    10
    11
    12
    13
    14
    15
    16
    17
    18
    19
    20
    21
    22
    23
    24
    25
    26
    27
    28
    29
    30
    31
    32
    33
    34
    35
    36
    37
    38
    39
    40
    41
    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_]);
    }
    }

其执行的主要过程如下:

  • 格式化时间,包括调用时的时分秒以及毫秒,为什么没有年月日呢?日志目录已经安装每天一个文件夹分类了,故这里省略了年月日信息。
  • 增加日志级别信息,日志级别对应一个字符串描述,如debug级别日志每一行会包含DEBUG字符串。
  • 记录线程id,这里并没有直接使用::pthread_self() 获取线程id,而是获取线程在系统中分配的“TID”,要知道线程和进程在内核中都有唯一的id,可以通过top进行查看,top -H –p [pid] 可以查看进程内的所有线程的运行负载情况,如果某个线程运行负载很高,我们需要知道到底是那一部分逻辑是热点,通过搜索日志,可以知道该线程负责了哪块逻辑,从而能够发现问题。
  • 记录日志类别
  • 若配置允许输出屏幕,那么利用printf输出,不同的日志级别会有不同的显示颜色,如printf(“\033[1;33mDEBUG\033[0m”), DEBUG 会以黄色输出。
  • 若配置允许输出文件,那么flush到文件中,若日期发生变化,重新创建日期目录,保证每一天一个文件夹,若单个文件内容超过5000行,会创建新的文件,避免文件内容过大,最终目录机构如下
    Alt text

异步操作

为了保证日志接口尽可能的快,日志接口都是异步完成的其。时序图如下:
Alt text

对于用户层而言,调用日志组件接口的开销为日志内容格式化和拷贝字符串到队列,而相对开销较大的写文件、输出屏幕操作则有日志线程完成,这样可以最大程度的保证用户层的高效运行。

我们定义log_service_t封装异步操作,对于格式化和输出,log_service_t仍然通过log_t实现,log_service_t的职责有四:

  • 封装异步接口,外部直接调用log_service_t的接口,一般log_service_t一单件模式使用
  • Log_service_t接口模板函数,利用C++的泛型能力确保类型安全,比如当%s参数本应该是user.name()时,却手误写成user,log_service_t的接口保证在编译器就能报错。
  • Log_service_t创建日志线程和日志任务队列,
  • Log_service_t在初始化的时候接受配置日志组件的参数,同时它也支持在运行期修改参数,并且线程安全。

关键代码如下:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
75
76
77
78
79
80
81
82
83
84
85
86
87
88
89
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的格式化语法,但是额外提供了排错和纠错功能:

  • 使用sprintf格式化语法,最基本的格式化参数都支持如%d,%u,%ld,%lu,%s,%c,%x,%p,%f甚至形如%04d设置字符串宽度的语法也是支持的
  • str_format_t 类型安全,格式化参数支持整型、浮点数、字符串cost char*、指针、string,若赋值其他类型参数,则编译不能通过。
  • str_format_t 拥有自动纠错功能,使用sprintf的时候除了类型不安全导致出错外,最常见的就是sprintf的格式化参数与赋值的参数个数不一致,如sprintf(buff, “%s,%s”, 100);这样的代码编译能够通过只有运行期才能发现出错,str_format_t 可以容忍这样的失误,当模板字符串中%比赋值的参数多时,str_format_t自动忽略多余的%,若%比后边的值参数少时,值参数自动追加到字符串尾部,这样最大程度的避免了出错和信息丢失。
    关于基本类型的格式化模板函数:
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
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();
}

关于字符串的特化函数:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
75
76
77
78
79
80
81
82
83
84
85
86
87
88
89
90
91
92
93
94
95
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
};
  • -log_level 配置日志级别,0-5代表不同的日志级别,枚举定义如下:
  • -log_path 配置日志文件存储的根目录
  • -log_filename 配置文件名称
  • -log_print_file” 配置日志是否输出到文件
  • log_print_screen 配置日志是否输出到屏幕
    • log_class 配置哪些日志类别是开启的,只有 开启的类别日志才会被记录

这其中除了log_path和log_filename不需要运行期配置外,其他的配置都有运行期修改的需求,比如运行期某个类别的日志被关闭了,但是为了跟踪某问题必须开启,如果不能动态修改日志配置往往会是开发人员面对问题时束手无策。对于-log_print_file 和-log_print_screen 都是用bool记录的,-log_level 是整型记录的,都是直接支持运行期修改的。有的读者可能指出日志不是有单独线程吗,而且使用线程组件的用户层也可能是多线程的,不就设计到了多线程竞争了吗?在明白此答案之前,先让我们缕一缕log中的结构:

  • 日志的接口会被多线程调用
  • 异步日志接口会访问日志的配置,判断该日志类别或级别是否已开启,由于只有读取操作,不需要加锁。
  • 日志格式化后投递到队列,队列是线程安全的,只有日志线程会从任务队列中消费任务。
  • 运行修改日志配置的操作会投递到日志线程完成,保证任一时刻只有一个线程修改日志配置
    对于-log_print_file 、-log_print_screen 和-log_level 都是多线程读取访问,某一时刻一个线程修改,并且三者都是基本类型的,不存在内存地址变化的问题,这样日志线程修改后会立即生效。但是对于-log_class,被开启的日志类别都被保存到set 的结构中,多线程对其执行find操作是安全的,这个stl的多线程特性是明确支持的。但是若对set 在运行期执行insert或erase后会使set中的迭代器失效,被坏的情况是会引起读操作的线程崩溃,所以在运行期绝对不能对老的日志类别容器进行修改。难道日志类别就没办法运行期修改了吗?脑筋急转弯一下,既然不能修改老的,为什么不创建一个新的,然后用新的替换老的?为了使用这个方法,需要一些小技巧:
  • 使用一个指针引用当前日志级别的容器,度线程总是获取该指针,然后执行find操作find_class_name 根据类别字符串去容器中查找是否存在。这里使用了原子操作ATOMIC_FETCH,在gcc的环境下可以把它定义为:
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
#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;
}

// 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);
}

总结以上无锁编程的技巧有:

  • 对于stl的对象的多线程读操作是安全的
  • 对于指针可以使用原子操作进行读取、更新、比较等操作
  • 老的容器被保存而不是销毁,从而保证了获取了老数据的线程仍然能够工作正常,日志的类别字符串只有十几顶多几十个,这里做数据冗余的内存开销是可以忽略的。

使用日志的异步接口是由log_service_t定义的,前边介绍log_service_t的时候也提到了log_service_t一般是被单件使用的,如果每次调用singleton_t<log_service_t>::instance().async_logdebug(“XX”, “OhNice”);代码太长了,使用宏封装单件的操作:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
#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;
}

总结:

  • 日志组件需要尽可能的快从而对于调用者的影响降到最低,使用异步接口可以使日志接口调用后立即返回
  • 日志的文件组织需要较好的被分类,目录首先按照时间分类,每天生成一个目录存储当天的日志,并且日志文件对大小做了上限,超过限制会重新创建新的文件,保证单个日志文件不会过大
  • 日志组件被设计成printf的格式化风格,但是增加了类型安全和参数纠错,不支持的类型会在编译期发现,值参数数目过多会被追加到字符串尾部,过少则忽略相应的%。
  • 日志组件是线程安全的,对于日志的配置虽然是多线程无锁访问的,仍然支持运行期动态的修改配置,其中使用了原子操作既保证了无锁编程的高效,又满足了多线程的稳定。
  • 源码:https://github.com/fanchy/fflib