日志的使用方式:
LOG_INFO << "AAA";
LOG_INFO是一个宏,展开后为:
muduo::Logger(__FILE__, __LINE__).stream() << "AAA";
构造了一个匿名对象Logger,在这个对象构造的时候其实已经写入了文件名和行号。
匿名对象调用.stream()函数拿到一个LogStream对象,由这个LogStream对象重载<<将“AAA”写入LogStream的数据成员FixBuffer对象的data_缓冲区内。
匿名对象在这条语句执行完毕以后会被销毁,因此会调用~muduo::Logger()函数将日志消息输出至目的地(标准输出或者磁盘的日志文件);
日志的流程:
Logger——Impl——LogStream——operator<<——LogStream的FixBuffer内——g_output——g_flush
异步日志及流程图:
由于磁盘IO是移动磁头的方式来记录文件的,其速度与CPU运行速度并不在一个数量级上。因此业务线程中应该避免进行磁盘IO以防止业务得不到及时的处理。
在多线程程序中,业务线程应该专注于其业务逻辑的运算,用另外一个独立的线程来将日志消息写入磁盘。
在muduo的日志系统中,分为前端和后端。前端是业务线程产生一条条的日志消息。后端是日志线程,将日志消息写入文件。
业务线程有多个,日志线程只有一个。这是一个典型地多生产者单消费者模型。
一、3秒超时将日志写入磁盘
多个线程会互斥地往A缓冲区写数据。
二、A缓存区被写满
三、A缓冲区被写满,由于某些原因日志线程没有及时唤醒
有可能是日志线程没有及时分配到时间片,所以条件变量notify()的时候并没有及时将日志线程备用的两个缓冲区拿来给前端顶替A和B缓冲区的位置;
这个时候就在互斥锁内分配内存。不过这种情况很少发生。
总结:
高性能日志系统其高性能所在:
1.业务线程与日志线程独立,保证了业务线程能及时处理业务。
2.多个线程其实是争用一个全局锁往缓冲区A拷贝写数据。这了拷贝数据是否是性能杀手,引用作者的一段话:
这个传递指针的方案似乎会更加高效,但是据我测试,直接拷贝日志数据的做法比传递指针快3倍(在每条消息不大于4KB的时候),估计是内存分配开销所致。因此muduo日志库只提供了这一种异步日志机制。这再次说明“性能”不能凭感觉说了算,一定要有典型场景的测试数据作为支撑。
虽然加锁的临界区足够小,但是如果线程数据较多,依旧会是性能瓶颈。
3.四缓冲机制避免了在临界区分配空间的时间消耗(见上图分析)。
4.将Buffers_的数据写磁盘是先进行swap交换到一个临时变量上,待互斥锁释放以后才进行磁盘IO操作。减少在临界区操作的时间,提升性能。
5.在缓冲区的移动上使用了std::move,避免了不必要的内存拷贝。
代码分析:
Logger类:
class Logger { public: enum LogLevel { TRACE, DEBUG, INFO, WARN, ERROR, FATAL, NUM_LOG_LEVELS, }; // compile time calculation of basename of source file class SourceFile { public: template<int N> SourceFile(const char (&arr)[N]): data_(arr), size_(N-1) { const char* slash = strrchr(data_, '/'); // builtin function if (slash) { data_ = slash + 1; size_ -= static_cast<int>(data_ - arr); } } explicit SourceFile(const char* filename): data_(filename) { const char* slash = strrchr(filename, '/'); if (slash) { data_ = slash + 1; } size_ = static_cast<int>(strlen(data_)); } const char* data_; int size_; }; Logger(SourceFile file, int line); Logger(SourceFile file, int line, LogLevel level); Logger(SourceFile file, int line, LogLevel level, const char* func); Logger(SourceFile file, int line, bool toAbort); ~Logger(); //返回内部类对象的数据成员LogStream对象。 LogStream& stream() { return impl_.stream_; } static LogLevel logLevel(); static void setLogLevel(LogLevel level); typedef void (*OutputFunc)(const char* msg, int len); typedef void (*FlushFunc)(); static void setOutput(OutputFunc); static void setFlush(FlushFunc); static void setTimeZone(const TimeZone& tz); private: class Impl { public: typedef Logger::LogLevel LogLevel; Impl(LogLevel level, int old_errno, const SourceFile& file, int line); void formatTime(); void finish(); Timestamp time_; //LogStream对象会重载<<运算符,将日志消息写到他的数据成员FixBuffer内 LogStream stream_; LogLevel level_; int line_; SourceFile basename_; }; Impl impl_; };
LogStream:
LogStream主要是重载了<<运算符,将各种类型当作字符串类型存入缓冲区内;
class LogStream : noncopyable { typedef LogStream self; public: typedef detail::FixedBuffer<detail::kSmallBuffer> Buffer; //将bool类型当作字符串0或者1存入缓冲区 self& operator<<(bool v) { buffer_.append(v ? "1" : "0", 1); return *this; } self& operator<<(short); self& operator<<(unsigned short); self& operator<<(int); self& operator<<(unsigned int); self& operator<<(long); self& operator<<(unsigned long); self& operator<<(long long); self& operator<<(unsigned long long); self& operator<<(const void*); self& operator<<(float v) { *this << static_cast<double>(v); return *this; } self& operator<<(double); // self& operator<<(long double); self& operator<<(char v) { buffer_.append(&v, 1); return *this; } // self& operator<<(signed char); // self& operator<<(unsigned char); self& operator<<(const char* str) { if (str) { buffer_.append(str, strlen(str)); } else { buffer_.append("(null)", 6); } return *this; } self& operator<<(const unsigned char* str) { return operator<<(reinterpret_cast<const char*>(str)); } self& operator<<(const string& v) { buffer_.append(v.c_str(), v.size()); return *this; } self& operator<<(const StringPiece& v) { buffer_.append(v.data(), v.size()); return *this; } self& operator<<(const Buffer& v) { *this << v.toStringPiece(); return *this; } void append(const char* data, int len) { buffer_.append(data, len); } const Buffer& buffer() const { return buffer_; } void resetBuffer() { buffer_.reset(); } private: void staticCheck(); template<typename T> void formatInteger(T); //日志消息会存入到这个FixedBuffer对象的数据成员中; //typedef detail::FixedBuffer<detail::kSmallBuffer> Buffer; //detail::kSmallBuffe为4000个字节 Buffer buffer_; static const int kMaxNumericSize = 32; };
LogStream的主要数据成员就是:FixBuffer对象,一条日志消息会暂时存在FixBuffer对象的数据成员data_内;
//非类型模板: //typedef detail::FixedBuffer<detail::kSmallBuffer> Buffer; //detail::kSmallBuffer传入了一个值,用于设置char data_[SIZE]的大小; template<int SIZE> class FixedBuffer : noncopyable { public: FixedBuffer(): cur_(data_) { setCookie(cookieStart); } ~FixedBuffer() { setCookie(cookieEnd); } void append(const char* /*restrict*/ buf, size_t len) { // FIXME: append partially if (implicit_cast<size_t>(avail()) > len) { //这里做了一次拷贝,将日志消息从栈内存拷到了类对象的空间上。 //这里其实是汇集数据的作用,方便后续将数据输出。 memcpy(cur_, buf, len); cur_ += len; } } const char* data() const { return data_; } int length() const { return static_cast<int>(cur_ - data_); } // write to data_ directly char* current() { return cur_; } int avail() const { return static_cast<int>(end() - cur_); } void add(size_t len) { cur_ += len; } void reset() { cur_ = data_; } void bzero() { memZero(data_, sizeof data_); } // for used by GDB const char* debugString(); void setCookie(void (*cookie)()) { cookie_ = cookie; } // for used by unit test string toString() const { return string(data_, length()); } StringPiece toStringPiece() const { return StringPiece(data_, length()); } private: const char* end() const { return data_ + sizeof data_; } // Must be outline function for cookies. static void cookieStart(); static void cookieEnd(); void (*cookie_)(); //存日志消息的数据成员; char data_[SIZE]; char* cur_; };
匿名对象执行析构函数:
Logger::~Logger() { //最后往这条日志消息里面插入:-文件名:行数 impl_.finish(); //这里拿到了数据的引用,并没有拷贝复制 const LogStream::Buffer& buf(stream().buffer()); //buf.data()返回的是数据成员data_数组的首地址; //g_output和g_flush都是一个可调用对象 //typedef void (*OutputFunc)(const char* msg, int len); //typedef void (*FlushFunc)(); g_output(buf.data(), buf.length()); if (impl_.level_ == FATAL) { g_flush(); abort(); } }
不同的调用对象直接导致了日志消息的输出的目的地。
例如默认的:
//将buffer内的数据输出到标准输出 void defaultOutput(const char* msg, int len) { size_t n = fwrite(msg, 1, len, stdout); //FIXME check n (void)n; }
//将数据刷新到标准输出 void defaultFlush() { fflush(stdout); }
在异步日志中,将日志消息输出到日志线程中,由日志线程将数据输出到磁盘的日志文件中。
异步日志:
使用方法:
muduo::AsyncLogging* g_asyncLog = NULL; void asyncOutput(const char *msg, int len) { //将日志消息数据存入异步日志类对象的缓冲区内 g_asyncLog->append(msg, len); } //创建一个异步日志类对象,超过kRollSize后会滚动日志 muduo::AsyncLogging log(::basename(name), kRollSize); //异步日志启动 log.start(); //设置Logger类的全局变量g_output为asynOutput,析构的时候调用asyncOutput对象 muduo::Logger::setOutput(asyncOutput);
先新建异步日志对象并运行起来,这样是为了??(创建好缓冲区吗??)
再设置Logger对象析构时调用的函数asyncOutput;
AsyncLogging类:
数据成员:
private: //日志线程会运行这个函数用于将日志消息写入磁盘的日志文件;与业务线程分开; void threadFunc(); typedef muduo::detail::FixedBuffer<muduo::detail::kLargeBuffer> Buffer; typedef std::vector<std::unique_ptr<Buffer>> BufferVector; //容器内元素的类型 typedef BufferVector::value_type BufferPtr; //条件变量等待超时的时间,用于3秒超时将日志消息的数据写入磁盘 const int flushInterval_; //日志线程是否在运行; std::atomic<bool> running_; const string basename_; //rollSize_大小后滚动日志 const off_t rollSize_; //用于创建日志线程 muduo::Thread thread_; //用于确保日志线程已经启动 muduo::CountDownLatch latch_; //与条件变量一起用的互斥器,用于对缓冲区加锁。各个业务线程互斥写入下面两个缓冲区 muduo::MutexLock mutex_; muduo::Condition cond_ GUARDED_BY(mutex_); //当前缓冲区和业务缓冲区供前端(业务线程)将数据存放的地方 BufferPtr currentBuffer_ GUARDED_BY(mutex_); BufferPtr nextBuffer_ GUARDED_BY(mutex_); //在这里的都是即将要写入磁盘日志文件的数据; BufferVector buffers_ GUARDED_BY(mutex_);
AsyncLogging类对象内有两个缓冲区数据成员:currentBuffer和nextBuffer;
每个线程在调用void asyncOutput(const char * msg, int len)的时候会调用AsyncLogging对象的append()成员函数,在append()函数内会加锁将日志消息写入到currentBuffer内。