服务器编程心得（五）—— 如何编写高性能日志

一、服务器端日志与客户端日志的区别

在正式讲解之前，我们先来看一个日志类的实现方法，这个日志类也是代表着大多数客户端日志的主流写法:

/**
 *@desc:    程序运行log类,log.h
 *@author:  zhangyl
 *@date:    2017.01.17
 **/
#ifndef __LOG_H__
#define __LOG_H__

#ifdef _ZYL_LOG_
#define LogInfo(...)     Log::GetInstance().AddLog("INFO", __FILE__, __LINE__, __FUNCSIG__, __VA_ARGS__)
#define LogWarning(...)  Log::GetInstance().AddLog("WARNING", __FILE__, __LINE__, __FUNCSIG__, __VA_ARGS__)
#define LogError(...)    Log::GetInstance().AddLog("ERROR", __FILE__, __LINE__, __FUNCSIG__, __VA_ARGS__)
#else
#define LogInfo(...) (void(0))
#define LogError(...) (void(0))
#endif

class Log
{
public:
    static Log& GetInstance();

    bool AddLog(const char* pszLevel, const char* pszFile, int lineNo, const char* pszFuncSig, char* pszFmt, ...);

private:
    Log();
    ~Log();
    Log(const Log&);
    Log& operator=(const Log&);

private:
    FILE*   m_file;

};

#endif //!__LOG_H__
/**
 *@desc:    程序运行log类,log.cpp
 *@author:  zhangyl
 *@date:    2017.01.17
 **/

#include <time.h>
#include <stdio.h>
#include <stdarg.h>
#include "Log.h"

Log& Log::GetInstance()
{
    static Log log;
    return log;
}

bool Log::AddLog(const char* pszLevel, const char* pszFile, int lineNo, const char* pszFuncSig, char* pszFmt, ...)
{
    if (m_file == NULL)
        return false;

    char tmp[8192*10] = { 0 };
    va_list va;                 //定义一个va_list型的变量,这个变量是指向参数的指针.
    va_start(va, pszFmt);           //用va_start宏初始化变量,这个宏的第二个参数是第一个可变参数的前一个参数,是一个固定的参数
    _vsnprintf(tmp, ARRAYSIZE(tmp), pszFmt, va);//注意,不要漏掉前面的_
    va_end(va);

    time_t now = time(NULL);
    struct tm* tmstr = localtime(&now);
    char content[8192 * 10 + 256] = {0};
    sprintf_s(content, ARRAYSIZE(content), "[%04d-%02d-%02d %02d:%02d:%02d][%s][0x%04x][%s:%d %s]%s\r\n",
                tmstr->tm_year + 1900,
                tmstr->tm_mon + 1,
                tmstr->tm_mday,
                tmstr->tm_hour,
                tmstr->tm_min,
                tmstr->tm_sec,
                pszLevel,
                GetCurrentThreadId(),
                pszFile,
                lineNo,
                pszFuncSig,
                tmp);

    if (fwrite(content, strlen(content), 1, m_file) != 1)
        return false;

    fflush(m_file);

    return true;
}

Log::Log()
{
    time_t now = time(NULL);
    struct tm* tmstr = localtime(&now);
    char filename[256];
    sprintf_s(filename, ARRAYSIZE(filename), "%04d%02d%02d%02d%02d%02d.runlog",
                tmstr->tm_year + 1900,
                tmstr->tm_mon + 1,
                tmstr->tm_mday,
                tmstr->tm_hour,
                tmstr->tm_min,
                tmstr->tm_sec);

    m_file = fopen(filename, "at+");
}

Log::~Log()
{
    if (m_file != NULL)
        fclose(m_file);
}

这个Log类的定义和实现代码节选自我的一款12306刷票软件，如果需要使用这个类的话包含Log.h头文件，然后使用宏：LogInfo/LogWarning/LogError这三个宏就可以了。示例如下：

    string strResponse;
    string strCookie = "Cookie: ";
    strCookie += m_strCookies;
    if (!HttpRequest(osURL.str().c_str(), strResponse, true, strCookie.c_str(), NULL, false, 10))
    {
        LogError("QueryTickets2 failed");
        return false;
    }

这个日志类，每次输出一行，一行中输出时间、日志级别、线程id、文件名、行号、函数签名和自定义的错误信息，演示如下：

[2017-02-16 17:30:08][INFO][0x0e7c][f:\mycode\hack12306\12306demo\client12306.cpp:1401 bool __thiscall Client12306::HttpRequest(const char *,class std::basic_string<char,struct std::char_traits<char>,class std::allocator<char> > &,bool,const char *,const char *,bool,int)]http response: {"validateMessagesShowId":"_validatorMessage","status":true,"httpstatus":200,"data":{"loginAddress":"10.1.232.219","otherMsg":"","loginCheck":"Y"},"messages":[],"validateMessages":{}}

[2017-02-16 17:30:08][INFO][0x0e7c][f:\mycode\hack12306\12306demo\client12306.cpp:1379 bool __thiscall Client12306::HttpRequest(const char *,class std::basic_string<char,struct std::char_traits<char>,class std::allocator<char> > &,bool,const char *,const char *,bool,int)]http post: url=https://kyfw.12306.cn:443/otn/login/userLogin, headers=Cookie: JSESSIONID=0A01D965C45FE88A1FB289F288BD96C255E3547783; BIGipServerotn=1708720394.50210.0000; , postdata=_json_att=

[2017-02-16 17:30:08][INFO][0x0e7c][f:\mycode\hack12306\12306demo\client12306.cpp:1401 bool __thiscall Client12306::HttpRequest(const char *,class std::basic_string<char,struct std::char_traits<char>,class std::allocator<char> > &,bool,const char *,const char *,bool,int)]http response: 

[2017-02-16 17:30:08][INFO][0x0e7c][f:\mycode\hack12306\12306demo\client12306.cpp:1379 bool __thiscall Client12306::HttpRequest(const char *,class std::basic_string<char,struct std::char_traits<char>,class std::allocator<char> > &,bool,const char *,const char *,bool,int)]http post: url=https://kyfw.12306.cn:443/otn/index/initMy12306, headers=Cookie: JSESSIONID=0A01D965C45FE88A1FB289F288BD96C255E3547783; BIGipServerotn=1708720394.50210.0000; , postdata=

上文中也说了，以上示例是我曾经写的一款客户端程序的日志，注意“客户端”这个重要的关键字。因为上述日志的实现虽然通用，但其局限性也只能用于客户端这样对性能和效率要求不高的程序（这里的性能和效率是相对于高并发高性能的服务器程序来说的，也就是说上述日志实现可用于大多数客户端程序，但不能用于高性能高并发的服务器程序）。那么上述程序存在什么问题？问题是效率低！
不知道读者有没有注意上，上述日志类实现，是在调用者线程中直接进行IO操作，相比较于高速的CPU，IO磁盘操作是很慢的，直接在某些工作线程（包括UI线程）写文件，程序执行速度太慢，尤其是当日志数据比较多的时候。
这也就是服务器端日志和客户端日志的区别之一，客户端程序日志一般可以在直接在所在的工作线程写日志，因为这点性能和时间损失对大多数客户端程序来说，是可以忽略的，但对于要求高并发（例如并发量达百万级乃至千万级的系统）的服务器程序来说，单位时间内耗在磁盘写操作上的时间就相当可观了。我目前的做法是参考陈硕的muduo库的做法，使用一个队列，需要写日志时，将日志加入队列中，另外一个专门的日志线程来写日志，我给出下我的具体实现代码，如果需要查看muduo库的做法，请参考陈硕的书《Linux多线程服务端编程：使用muduo C++网络库》关于日志章节。注意：以下是纯C++11代码：

/**
 * 日志类头文件, Logger.h
 * zhangyl 2017.02.28
 **/

#ifndef __LOGGER_H__
#define __LOGGER_H__

#include <string>
#include <memory>
#include <thread>
#include <mutex>
#include <condition_variable>
#include <list>

//struct FILE;

#define LogInfo(...)        Logger::GetInstance().AddToQueue("INFO", __FILE__, __LINE__, __PRETTY_FUNCTION__, __VA_ARGS__)
#define LogWarning(...)     Logger::GetInstance().AddToQueue("WARNING", __FILE__, __LINE__, __PRETTY_FUNCTION__, __VA_ARGS__)
#define LogError(...)       Logger::GetInstance().AddToQueue("ERROR", __FILE__, __LINE__, __PRETTY_FUNCTION__, __VA_ARGS__)

class Logger
{
public:
    static Logger& GetInstance();

    void SetFileName(const char* filename);
    bool Start();
    void Stop();

    void AddToQueue(const char* pszLevel, const char* pszFile, int lineNo, const char* pszFuncSig, char* pszFmt, ...);

private:
    Logger() = default;
    Logger(const Logger& rhs) = delete;
    Logger& operator =(Logger& rhs) = delete;

    void threadfunc();

private:
    std::string                     filename_;
    FILE*                           fp_{};
    std::shared_ptr<std::thread>    spthread_;
    std::mutex                      mutex_;
    std::condition_variable         cv_;            //有新的日志到来的标识
    bool                            exit_{false};
    std::list<std::string>          queue_;
};

#endif //!__LOGGER_H__
/**
 * 日志类实现文件, Logger.cpp
 * zhangyl 2017.02.28
 **/

#include "Logger.h"
#include <time.h>
#include <stdio.h>
#include <memory>
#include <stdarg.h>

Logger& Logger::GetInstance()
{
    static Logger logger;
    return logger;
}

void Logger::SetFileName(const char* filename)
{
    filename_ = filename;
}

bool Logger::Start()
{
    if (filename_.empty())
    {
        time_t now = time(NULL);
        struct tm* t = localtime(&now);
        char timestr[64] = { 0 };
        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);
        filename_ = timestr;
    }

    fp_ = fopen(filename_.c_str(), "wt+");
    if (fp_ == NULL)
        return false;

    spthread_.reset(new std::thread(std::bind(&Logger::threadfunc, this)));

    return true;
}

void Logger::Stop()
{
    exit_ = true;
    cv_.notify_one();

    //等待时间线程结束
    spthread_->join();
}

void Logger::AddToQueue(const char* pszLevel, const char* pszFile, int lineNo, const char* pszFuncSig, char* pszFmt, ...)
{
    char msg[256] = { 0 };

    va_list vArgList;
    va_start(vArgList, pszFmt);
    vsnprintf(msg, 256, pszFmt, vArgList);
    va_end(vArgList);

    time_t now = time(NULL);
    struct tm* tmstr = localtime(&now);
    char content[512] = { 0 };
    sprintf(content, "[%04d-%02d-%02d %02d:%02d:%02d][%s][0x%04x][%s:%d %s]%s\n",
                tmstr->tm_year + 1900,
                tmstr->tm_mon + 1,
                tmstr->tm_mday,
                tmstr->tm_hour,
                tmstr->tm_min,
                tmstr->tm_sec,
                pszLevel,
                std::this_thread::get_id(),
                pszFile,
                lineNo,
                pszFuncSig,
                msg);

    {
        std::lock_guard<std::mutex> guard(mutex_);
        queue_.emplace_back(content);
    }

    cv_.notify_one();
}

void Logger::threadfunc()
{
    if (fp_ == NULL)
        return;

    while (!exit_)
    {
        //写日志
        std::unique_lock<std::mutex> guard(mutex_);
        while (queue_.empty())
        {
            if (exit_)
                return;

            cv_.wait(guard);
        }

        //写日志
        const std::string& str = queue_.front();

        fwrite((void*)str.c_str(), str.length(), 1, fp_);
        fflush(fp_);
        queue_.pop_front();
    }
}

以上代码只是个简化版的实现，使用std::list来作为队列，使用条件变量来作为新日志到来的触发条件。当然，由于使用了两个固定长度的数组，大小是256和512，如果日志数据太长，会导致数组溢出，这个可以根据实际需求增大缓冲区或者改用动态长度的string类型。使用这两个文件只要包含Logger.h，然后使用如下一行代码启动日志线程就可以了：

Logger::GetInstance().Start();

生成日志，使用头文件里面定义的三个宏LogInfo、LogWarning、LogError，当然你也可以扩展自己的日志级别。

二、日志里面应该写些什么？

我开始在试着去写日志的时候，也走了不少弯路，无论是客户端还是服务器端，日志写的内容倒是不少，但都是些废话，虽然也报出故障，但对解决实际问题时毫无作用。尤其是在服务器上生产环境以后，出现很多问题，问题也暴露出来了，但是由于日志含有的当时现场的环境信息太少，只能看到错误，却没法追踪问题，更别说解决问题了。我们来看两个具体的例子：

CIULog::Log(LOG_WARNING, __FUNCSIG__, _T("Be cautious! Unhandled net data! req_ans_command=%d."), header.cmd);

这条日志记录，只打印出一条警告信息和命令号（cmd），对具体产生这个警告的输入参数和当时的环境也没进行任何记录，即使产生问题，事后也无法追踪。再看一条


    if (!HttpRequest(osURL.str().c_str(), strResponse, true, strCookie.c_str(), NULL, false, 10))
    {
        LogError("QueryTickets1 failed");
        return false;
    }

这条日志，因为http请求报了个简单的错误，至于产生错误的参数和原因一概没有交待，这种日志如果在生产环境上出现如何去排查呢？出错原因可能是设置的参数非法，这是外部原因，可以解决的，甚至是交互双方的一端传过来的，需要对方去纠正；也可能是当时的网络故障，这个也可以解决，也不算是程序的bug，不需要解决；也可能是的bug引起的，这个需要程序作者去解决。另外，如果是服务器程序，甚至应该在错误中交待下产生日志的用户id、操作类型等信息，这样事后才能便于定位位置，进行重现等。
总结起来，日志记录应该尽量详细，能反映出当时出错的现场情节、产生的环境等。比如一个注册请求失败，至少要描述出当时注册的用户名、密码、用户状态（比如是否已经注册）、请求的注册地址等等。因为日志报错不一定是程序bug，可能是用户非法请求。日志详细了，请不用担心服务器的磁盘空间，因为相比较定位错误，这点磁盘空间还是值得的，实在不行可以定期清理日志嘛。

另外一点是，可以将错误日志、运行状态日志等分开，甚至可以将程序记录日志与业务本身日志分开，这样排查故障时优先查看是否有错误日志文件产生，再去错误日志里面去找，而不用在一堆日志中筛选错误日志。我的很多项目在生产环境也是这么做的。

以上是关于日志的一些个人心得吧，如有一些说的不对的地方，欢迎指正。

原文地址：http://blog.51cto.com/6956264/2125751

时间： 2024-10-09 11:58:12

服务器编程心得（五）—— 如何编写高性能日志的相关文章

服务器编程心得（四）—— 如何将socket设置为非阻塞模式

1. windows平台上无论利用socket()函数还是WSASocket()函数创建的socket都是阻塞模式的: SOCKET WSAAPI socket( _In_ int af, _In_ int type, _In_ int protocol ); SOCKET WSASocket( _In_ int af, _In_ int type, _In_ int protocol, _In_ LPWSAPROTOCOL_INFO lpProtocolInfo, _In_ GROUP g,

服务器端编程心得（六）—— 关于网络编程的一些实用技巧和细节

这些年,接触了形形色色的项目,写了不少网络编程的代码,从windows到linux,跌进了不少坑,由于网络编程涉及很多细节和技巧,一直想写篇文章来总结下这方面的心得与经验,希望对来者有一点帮助,那就善莫大焉了. 本文涉及的平台包括windows和linux,下面开始啦. 一.非阻塞的的connect()函数如何编写 我们知道用connect()函数默认是阻塞的,直到三次握手建立之后,或者实在连不上超时返回,期间程序执行流一直阻塞在那里.那么如何利用connect()函数编写非阻塞的连接代码呢?

服务器端编程心得（三）—— 一个服务器程序的架构介绍

本文将介绍我曾经做过的一个项目的服务器架构和服务器编程的一些重要细节. 一.程序运行环境 操作系统:centos 7.0 编译器:gcc/g++ 4.8.3     cmake 2.8.11 mysql数据库:5.5.47 项目代码管理工具:VS2013 二.程序结构 该程序总共有17个线程,其中分为9个数据库工作线程D和一个日志线程L,6个普通工作线程W,一个主线程M.(以下会用这些字母来代指这些线程) (一).数据库工作线程的用途 9个数据库工作线程在线程启动之初,与mysql建立连接,也就

服务器编程的一点心得

由于水平有限,以下仅仅是个人的一些心得,希望对新人有一点参考作用.另外由于时间关系,写得有点杂,有些点可能并不是跟服务器编程强相关的. 性能相关 1.     应用各种pool. a)       Mempool 比如为了提高内存分配效率,可以使用Mem pool.当对应的场景简单时,可以自己定制私有的内存池管理.当内存池设计相对复杂的时候,可以考虑直接使用jemalloc.tcmalloc. b)      Socket pool 比如dns解析一般是基于udp协议,为了提高性能,避免反复创建

linux高性能服务器编程

<Linux高性能服务器编程>:当当网.亚马逊 目录: 第一章:tcp/ip协议族 第二章:ip协议族 第三章:tcp协议详解 第四章:tcp/ip通信案例:访问Internet 第五章:linux网络编程基础API 第六章:高级IO函数 第七章:linux服务器程序规范 第八章:高性能服务器框架 第九章:IO复用 第十章:信号 第十一章:定时器 第十二章:高性能IO框架库libevent 第十三章:多进程编程 第十四章:多线程编程 第十五章:进程池和线程池 第十六章:服务器调制.调试和测试

Linux高性能服务器编程——定时器

 定时器 服务器程序通常管理着众多定时事件,因此有效组织这些定时事件,使之能在预期的时间点被触发且不影响服务器的主要逻辑,对于服务器的性能有着至关重要的影响.位置我们要将每个定时事件封装成定时器,并使用某种容器类型的数据结构,比如链表.排序链表和时间轮将所有定时器串联起来,以实现对定时事件的统一管理. Linux提供三种定时方法: 1.socket选项SO_RECVTIMEO和SO_SNDTIMEO. 2.SIGALRM信号 3.I/O复用系统调用的超时参数 socket选项SO_RCVTI

Linux 高性能服务器编程——高级I/O函数

重定向dup和dup2函数 [cpp] view plaincopyprint? #include <unistd.h> int dup(int file_descriptor); int dup2(int file_descriptor_one, int file_descriptor_two); dup创建一个新的文件描述符, 此描述符和原有的file_descriptor指向相同的文件.管道或者网络连接. dup返回的文件描述符总是取系统当前可用的最小整数值. dup2函数通过使用参数f

Linux高性能服务器编程——信号及应用

 信号 信号是由用户.系统或者进程发送给目标进程的信息,以通知目标进程某个状态的改变或系统异常.Linux信号可由如下条件产生: 对于前台进程,用户可以通过输入特殊的终端字符来给它发送信号.比如输入Ctrl+C通常会给进程发送一个终端信号. 2.系统异常 系统状态变化 运行kill命令或调用kill函数 Linux信号概述 发送信号 Linux下,一个进程给其他进程发送信号的API是kill函数.其定义如下: #include <sys/types.h> #include <sign

Linux高性能服务器编程——多进程编程

多进程编程 多进程编程包括如下内容: 复制进程影映像的fork系统调用和替换进程映像的exec系列系统调用. 僵尸进程以及如何避免僵尸进程 进程间通信(Inter-Process Communication,IPC)最简单的方式:管道 3种进程间通信方式:信号量,消息队列和共享内存 fork系统调用 #include<unistd.h> pid_tfork(void); 该函数的每次都用都返回两次,在父进程中返回的是子进程的PID,在子进程中返回的是0.该返回值是后续代码判断当前进程是父进程还