一、客户端
先来看一个日志类的实现方法,这个日志类也是代表着大多数客户端日志的主流写法:
log.h:
1 #ifndef __LOG_H__
2 #define __LOG_H__
3
4 #include <stdio.h>
5
6 //#ifdef _ZYL_LOG_
7 #define LogInfo(...) Log::GetInstance().AddLog("INFO", __FILE__, __LINE__, __FUNCTION__, __VA_ARGS__)
8 #define LogWarning(...) Log::GetInstance().AddLog("WARNING", __FILE__, __LINE__, __FUNCTION__, __VA_ARGS__)
9 #define LogError(...) Log::GetInstance().AddLog("ERROR", __FILE__, __LINE__, __FUNCTION__, __VA_ARGS__)
//其中,...表示可变参数列表,__VA_ARGS__在预处理中,会被实际的参数集(实参列表)所替换。
10 //#else
11 //#define LogInfo(...) (void(0))
12 //#define LogError(...) (void(0))
13 //#endif
14
15 class Log
16 {
17 public:
18 static Log& GetInstance();
19
20 bool AddLog(const char* pszLevel, const char* pszFile, int lineNo, const char* pszFuncSig, char* pszFmt, ...);
21
22 private:
23 Log();
24 ~Log();
25 Log(const Log&);
26 Log& operator=(const Log&);
27
28 private:
29 FILE* m_file;
30
31 };
32
33 #endif //!__LOG_H__
log.cpp :
1 #include <time.h>
2 #include <stdio.h>
3 #include <stdarg.h>
4 #include <cstring>
5 #include "log.h"
6
7 Log& Log::GetInstance()
8 {
9 static Log log;
10 return log;
11 }
12
13 bool Log::AddLog(const char* pszLevel, const char* pszFile, int lineNo, const char* pszFuncSig, char* pszFmt, ...)
//最后的pszFmt是一个固定的参数,用于表示格式化输出
14 {
15 if (m_file == NULL)
16 return false;
17
18 char tmp[8192*10] = { 0 };
19 va_list va; //定义一个va_list型的变量,这个变量是指向参数的指针.
20 va_start(va, pszFmt); //用va_start宏初始化变量,这个宏的第二个参数是第一个可变参数的前一个参数,是一个固定的参数
21 vsnprintf(tmp, 8192*10, pszFmt, va); //linux环境下为vsnprintf(),vc6环境下为_vsnprintf()
22 va_end(va);
//参数说明: int vsnprintf( char* buffer, std::size_t buf_size, const char* format, va_list vlist ); (C++11 起)
//char *str [out],把生成的格式化的字符串存放在这里.
//size_t size [in], str可接受的最大字符数[1] (非字节数,UNICODE一个字符两个字节),防止产生数组越界.
//const char *format [in], 指定输出格式的字符串,它决定了你需要提供的可变参数的类型、个数和顺序。
//va_list ap [in], va_list变量. va:variable-argument:可变参数
//函数功能:将可变参数格式化输出到一个字符数组。
23
24 time_t now = time(NULL);
25 struct tm* tmstr = localtime(&now);
26 char content[8192 * 10 + 256] = {0};
27 snprintf(content, 8192*10+256, "[%04d-%02d-%02d %02d:%02d:%02d][%s][0x%04x][%s:%d %s]%s\ r\n",
28 tmstr->tm_year + 1900,
29 tmstr->tm_mon + 1,
30 tmstr->tm_mday,
31 tmstr->tm_hour,
32 tmstr->tm_min,
33 tmstr->tm_sec,
34 pszLevel,
35 0,//GetCurrentThreadId(),
36 pszFile,
37 lineNo,
38 pszFuncSig,
39 tmp);
40
41 if (fwrite(content, strlen(content), 1, m_file) != 1)
42 return false;
43
44 fflush(m_file);
45
46 return true;
47 }
48
49 Log::Log()
50 {
51 time_t now = time(NULL);
52 struct tm* tmstr = localtime(&now);
53 char filename[256];
54 snprintf(filename, 256, "%04d%02d%02d%02d%02d%02d.runlog",
55 tmstr->tm_year + 1900,
56 tmstr->tm_mon + 1,
57 tmstr->tm_mday,
58 tmstr->tm_hour,
59 tmstr->tm_min,
60 tmstr->tm_sec);
61
62 m_file = fopen(filename, "at+"); //"a+" = "at+" :打开或新建一个文本文件,可以读,但只允许在文件末尾追写
63 }
64
65 Log::~Log()
66 {
67 if (m_file != NULL)
68 fclose(m_file);
69 }
70
testlog.cpp:
1 #include "log.h"
2
3 int main(){
4 LogInfo("test log info: %d, %c, %s", 1,'2',"3");
5 LogWarning("test log warning");
6 LogError("test log error");
7
8 return 0;
9 }
输出:生成文件 20181213025414.runlog
[2018-12-13 02:54:14][INFO][0x0000][testlog.cpp:4 main]test log info: 1, 2, 3
[2018-12-13 02:54:14][WARNING][0x0000][testlog.cpp:5 main]test log warning
[2018-12-13 02:54:14][ERROR][0x0000][testlog.cpp:6 main]test log error
这个日志类,每次输出一行,一行中输出时间、日志级别、线程id、文件名、行号、函数签名和自定义的错误信息。至此,宏 LogInfo、LogWarning 和 LogError 可以类似prinf使用格式化输出形式将内容输出到日志文件中去。
上述日志的实现虽然通用,但其局限性也只能用于客户端这样对性能和效率要求不高的程序(这里的性能和效率是相对于高并发高性能的服务器程序来说的,也就是说上述日志实现可用于大多数客户端程序,但不能用于高性能高并发的服务器程序)。那么上述程序存在什么问题?问题是效率低!
上述日志类实现,是在调用者线程中直接进行IO操作,相比较于高速的CPU,IO磁盘操作是很慢的,直接在某些工作线程(包括UI线程)写文件,程序执行速度太慢,尤其是当日志数据比较多的时候。这也就是服务器端日志和客户端日志的区别之一,客户端程序日志一般可以在直接在所在的工作线程写日志,因为这点性能和时间损失对大多数客户端程序来说,是可以忽略的,但对于要求高并发(例如并发量达百万级乃至千万级的系统)的服务器程序来说,单位时间内耗在磁盘写操作上的时间就相当可观了。
参考资料:
服务器编程心得(五)—— 如何编写高性能日志
std::vsnprintf
std::snprintf
va_list 、va_start、 va_arg、 va_end 使用说明
二、服务端
作者的做法是参考陈硕的muduo库的做法,使用一个队列,需要写日志时,将日志加入队列中,单独用另外一个专门的日志线程来写日志。
logger.h:
1 #ifndef __LOGGER_H__
2 #define __LOGGER_H__
3
4 #include <string>
5 #include <memory>
6 #include <thread>
7 #include <mutex>
8 #include <condition_variable>
9 #include <list>
10
11 //struct FILE;
12
13 #define LogInfo(...) Logger::GetInstance().AddToQueue("INFO", __FILE__, __LINE__, __PRETT Y_FUNCTION__, __VA_ARGS__)
14 #define LogWarning(...) Logger::GetInstance().AddToQueue("WARNING", __FILE__, __LINE__, __PR ETTY_FUNCTION__, __VA_ARGS__)
15 #define LogError(...) Logger::GetInstance().AddToQueue("ERROR", __FILE__, __LINE__, __PRET TY_FUNCTION__, __VA_ARGS__)
16
17 class Logger
18 {
19 public:
20 static Logger& GetInstance();
21
22 void SetFileName(const char* filename);
23 bool Start();
24 void Stop();
25
26 void AddToQueue(const char* pszLevel, const char* pszFile, int lineNo, const char* pszFuncSi g, char* pszFmt, ...);
27
28 private:
29 Logger() = default;
30 Logger(const Logger& rhs) = delete;
31 Logger& operator =(Logger& rhs) = delete;
32
33 void threadfunc();
34
35
36 private:
37 std::string filename_;
38 FILE* fp_{};
39 std::shared_ptr<std::thread> spthread_;
40 std::mutex mutex_;
41 std::condition_variable cv_; //有新的日志到来的标识
42 bool exit_{false};
43 std::list<std::string> queue_;
44 };
45
46 #endif //!__LOGGER_H__
logger.cpp:
1 #include "logger.h"
2 #include <time.h>
3 #include <stdio.h>
4 #include <string>
5 #include <memory>
6 #include <functional>
7 #include <stdarg.h>
8
9 Logger& Logger::GetInstance()
10 {
11 static Logger logger;
12 return logger;
13 }
14
15 void Logger::SetFileName(const char* filename)
16 {
17 filename_ = filename;
18 }
19
20 bool Logger::Start()
21 {
22 if (filename_.empty())
23 {
24 time_t now = time(NULL);
25 struct tm* t = localtime(&now);
26 char timestr[64] = { 0 };
27 sprintf(timestr, "%04d%02d%02d%02d%02d%02d.imserver.log", t->tm_year + 1900, t->tm_mon + 1, t->tm_mday, t->tm_hour, t->tm_min, t->tm_sec);
28 filename_ = timestr;
29 }
30
31 fp_ = fopen(filename_.c_str(), "wt+");
32 if (fp_ == NULL)
33 return false;
34
35 spthread_.reset(new std::thread(std::bind(&Logger::threadfunc, this)));
36
37 return true;
38 }
39
40 void Logger::Stop()
41 {
42 exit_ = true;
43 cv_.notify_one();
44
45 //阻塞等待线程this结束
46 spthread_->join();
47 }
48
49 void Logger::AddToQueue(const char* pszLevel, const char* pszFile, int lineNo, const char* pszFu ncSig, char* pszFmt, ...)
50 {
51 char msg[256] = { 0 };
52
53 va_list vArgList;
54 va_start(vArgList, pszFmt);
55 vsnprintf(msg, 256, pszFmt, vArgList);
56 va_end(vArgList);
57
58 time_t now = time(NULL);
59 struct tm* tmstr = localtime(&now);
60 char content[512] = { 0 };
61 sprintf(content, "[%04d-%02d-%02d %02d:%02d:%02d][%s][0x%04x][%s:%d %s]%s\n",
62 tmstr->tm_year + 1900,
63 tmstr->tm_mon + 1,
64 tmstr->tm_mday,
65 tmstr->tm_hour,
66 tmstr->tm_min,
67 tmstr->tm_sec,
68 pszLevel,
69 std::this_thread::get_id(),
70 pszFile,
71 lineNo,
72 pszFuncSig,
73 msg);
74 {
75 std::lock_guard<std::mutex> guard(mutex_);
76 queue_.emplace_back(content);
77 }
78
79 cv_.notify_one();
80 }
81
82 void Logger::threadfunc()
83 {
84 if (fp_ == NULL)
85 return;
86
87 while (!exit_)
88 {
89 //写日志
90 std::unique_lock<std::mutex> guard(mutex_);
91 while (queue_.empty())
92 {
93 if (exit_)
94 return;
95
96 cv_.wait(guard);
97 }
98
99 //写日志
100 const std::string& str = queue_.front();
101
102 fwrite((void*)str.c_str(), str.length(), 1, fp_);
103 fflush(fp_);
104 queue_.pop_front();
105 }
106 }
testlogger.cpp:
调用 Logger::GetInstance().Start() 启动日志线程:
1 #include "logger.h"
2 #include "unistd.h"
3
4 int main(){
5 Logger::GetInstance().Start(); //启动日志线程
6
7 LogInfo(" Test LogInfo : %d, %c, %s" , 1, '2', "3");
8
9 sleep(3);
10 Logger::GetInstance().Stop();
11
12 return 0;
13 }
生成日志文件 20181213042114.imserver.log ,内容为:
[2018-12-13 04:21:14][INFO][0x7a85f740][testlogger.cpp:7 int main()] Test LogInfo : 1, 2, 3
三、总结
1、对c++程序而已,最好整个程序(包括主程序和程序库)都使用相同的日志库,程序有一个整体的日志输出,而不要各个组件有各自的日志输出。从这个意义上讲,日志库是一个singleton。
2、c++日志库的前端大体有两种风格:
- C / JAVA 的 printf ( fmt , ... ) 风格,如 log_info("Rechieved %d bytes from %s" , len, getClientName.c_str());
- C++ 的 stream << 风格, 如 LOG_INFO << "Rechieved " << len << " bytes from " << getClientName();
3、对于分布式系统中的服务进程而言,日志的目的地只有一个:本地文件。往网络写日志消息是不靠谱的。以本地文件为日志的目的地,那么日志文件的滚动(rolling)是必需的,这样可以简化日志归档(archive)的实现。
4、日志库不能每条消息都flush硬盘,更不能每条日志都open\close文件,这样性能开销太大。改进方法:定期(默认3秒)将缓冲区内的日志消息 flush 硬盘。但程序奔溃时,后边的日志会丢失。
5、往往写日志的一个常见问题是,万一程序奔溃,那么最后若干条日志往往就丢失了(因为考虑到性能开销问题,日志库不能每条消息都flush硬盘,更不能每条日志都open\close文件)。改进方法:
-
定期将缓冲区内的日志消息 flush 硬盘。这也就需要利用 buffer 对日志消息进行缓存。
- 每条内存中的日志消息都带有cookie(或者叫哨兵值/sentry),其值为某个函数的地址,这样通过core dump 文件中查找cookie就能找到尚未来得及写入磁盘的消息。
6、多线程异步日志(叫“非阻塞日志”似乎更准确)
保证线程安全(即多个线程可以并发写日志)的基础上,考虑性能。简单的做法有二:用一个全局mutex保护IO,或者每个线程单独写一个日志文件。但这两种方法效率堪忧,前者会造成全部线程枪一个锁,后者可能让业务线程阻塞在写磁盘操作上。因此,应该用一个背景线程负责收集日志消息,并写入日志文件,其他业务线程只管往这个“日志线程”发送日志消息,这称为“异步日志”。
(原因:在正常的实时业务处理流程中应该彻底避免磁盘IO,因为线程是复用的,阻塞意味着影响多个客户连接。)
但“异步日志”可能出现日志消息堆积问题(典型的生产速度高于消费速度问题)。而同步日志则无此问题(阻塞IO自然就限制了前端的写入速度)。解决:直接丢掉多余的日志buffer,以腾出内存。
参考资料:
Linux多线程服务端编程:使用moduo C++网络库