C++日志系统如何设计

Posted 2021-04-30 高性能服务器开发

笔者在写作本章节的时候，并不敢把此章节的标题叫做《高性能日志系统的设计》，之所以不敢加上“高性能”三个字的原因是，第一，我的对于日志系统设计知识和经验都来自于学习和工作经验，我并不是原创者，只是知识的搬运工；第二，目前有许多优秀的、被广泛使用的开源的日志系统，他们给了我很多启发，不敢在此班门弄斧。不管怎样，笔者还是想写一些自己关于对日志系统的理解和经验，让我们开始吧。

为什么需要日志

实际的软件项目产出都有一个流程，即先开发、测试，再发布生产，由于人的因素，既然是软件产品就不可能百分百没有bug或者逻辑错误，对于已经发布了生产的项目，一旦某个时刻产生非预期的结果，我们就需要去定位和排查问题。但是一般正式的生产环境的服务器或者产品是不允许开发人员通过附加调试器去排查问题的，主要有如下可能原因：

1. 在一些大的互联网公司或者部门分工明确的公司，开发部门、测试部分和产品运维部门是分工明确的，软件产品一旦发布到生产环境以后，将全部交由运维部门人员去管理和维护，而原来开发此产品的开发人员不再拥有相关的操作程序的权限。

2. 对于已经上了生产环境的服务，其数据是公司的核心产值所在，一般不允许或者不敢被开发人员随意调试或者操作，以免对公司造成损失。

3. 发布到生产环境的服务，一般为了让程序执行效率更高、文件体积更小，都是去掉调试符号后的版本，不方便也不利于调试。

既然我们无法通过调试器去调试，这个时候我们为了跟踪和回忆当时的程序行为进而定位问题，我们就需要日志系统。

退一步说，即使在开发或者测试环境，我们可以把程序附加到调试器上去调试，但是对于一些特定的程序行为，我们无法通过设置断点，让程序在某个时刻暂停下来进行调试。例如，对于某些网络通信功能，如果暂停时间过长（相对于操作系统的操作来说），通信的对端可能由于彼端没有在规定时间内响应而断开连接，导致程序逻辑无法进入我们想要的执行流中去；再例如，对于一些高频操作（如心跳包、定时器、界面绘制下的某些高频重复行为），可能在少量次数下无法触发我们想要的行为，而通过断点的暂停方式，我们不得不重复操作几十次、上百次甚至更多，这样排查问题效率是非常低下的。对于这类操作，我们可以通过打印日志，将当时的程序行为上下文现场记录下来，然后从日志系统中找到某次不正常的行为的上下文信息。这也是日志的另外一个作用。

本文将从技术和业务上两个方面来介绍日志系统相关的设计与开发，所谓技术上，就是如何从程序开发的角度设计一款功能强大、性能优越、使用方便的日志系统；而业务上，是指我们在使用日志系统时，应该去记录哪些行为和数据，既简洁、不啰嗦，又方便需要时准确快速地定位问题。

日志系统的技术上的实现

日志的最初的原型即将程序运行的状态打印出来，对于C/C++这门语言来说，即可以利用printf、std::cout等控制台输出函数，将日志信息输出到控制台，这类简单的情形我们不在此过多赘述。

对于，实际的商业项目，为了方便排查问题，我们一般不将日志写到控制台，而是输出到文件或者数据库系统。不管哪一种，其思路基本上一致，我们这里以写文件为例来详细介绍。

同步写日志

所谓同步写日志，指的是在输出日志的地方，将日志即时写入到文件中去。根据笔者的经验，这种设计广泛地用于相当数量的客户端软件。笔者曾从事过数年的客户端开发（包括pc、安卓版本），设计过一些功能复杂的金融客户端产品，在这些系统中采用的就是这种同步写日志的方式。之所以使用这种方式其主要原因就是设计简单，而又不会影响用户使用体验。说到这里读者可能有这样一个疑问：一般的客户端软件，一般存在界面，而界面部分所属的逻辑就是程序的主线程，如果采取这种同步写日志的方式，当写日志时，写文件是磁盘IO操作，相比较程序其他部分是CPU操作，前者要慢很多，这样势必造成CPU等待，进而导致主线程“卡”在写文件处，进而造成界面卡顿，从而导致用户使用软件的体验不好。读者的这种顾虑确实是存在的。但是，很多时候我们不用担心这种问题，主要有两个原因：

1. 对于客户端程序，即使在主线程（UI线程）中同步写文件，其单次或者几次磁盘操作累加时间，与人（用户）的可感知时间相比，也是非常小的，也就是说用户根本感觉不到这种同步写文件造成的延迟。当然，这里也给您一个提醒就是，如果在UI线程里面写日志，尤其是在一些高频操作中（如Windows的界面绘制消息WM_PAINT处理逻辑中），一定要控制写日志的长度和次数，否则就会因频繁写文件和一次写入数据过大而对界面造成卡顿。

2. 客户端程序除了UI线程，还有其他与界面无关的工作线程，在这些线程中直接写文件，一般不会对用户的体验产生什么影响。

说了这么多，我们给出一个具体的例子。

日志类的.h文件

 1/**
 2 *@desc:   IULog.h
 3 *@author: zhangyl
 4 *@date:   2014.12.25
 5 */
 6#ifndef __LOG_H__
 7#define __LOG_H__
 8
 9enum LOG_LEVEL
10{
11    LOG_LEVEL_INFO,
12    LOG_LEVEL_WARNING,
13    LOG_LEVEL_ERROR
14};
15
16//注意：如果打印的日志信息中有中文，则格式化字符串要用_T()宏包裹起来，
17#define LOG_INFO(...)     CIULog::Log(LOG_LEVEL_INFO, __FUNCSIG__,__LINE__, __VA_ARGS__)
18#define LOG_WARNING(...)  CIULog::Log(LOG_LEVEL_WARNING, __FUNCSIG__, __LINE__,__VA_ARGS__)
19#define LOG_ERROR(...)    CIULog::Log(LOG_LEVEL_ERROR, __FUNCSIG__,__LINE__, __VA_ARGS__)
20
21class CIULog
22{
23public:
24    static bool Init(bool bToFile, bool bTruncateLongLog, PCTSTR pszLogFileName);
25    static void Uninit();
26
27    static void SetLevel(LOG_LEVEL nLevel);
28
29    //不输出线程ID号和所在函数签名、行号
30    static bool Log(long nLevel, PCTSTR pszFmt, ...);
31    //输出线程ID号和所在函数签名、行号
32    static bool Log(long nLevel, PCSTR pszFunctionSig, int nLineNo, PCTSTR pszFmt, ...);        //注意:pszFunctionSig参数为Ansic版本
33    static bool Log(long nLevel, PCSTR pszFunctionSig, int nLineNo, PCSTR pszFmt, ...);
34private:
35    CIULog() = delete;
36    ~CIULog() = delete;
37
38    CIULog(const CIULog& rhs) = delete;
39    CIULog& operator=(const CIULog& rhs) = delete;
40
41    static void GetTime(char* pszTime, int nTimeStrLength);
42
43private:
44    static bool             m_bToFile;              //日志写入文件还是写到控制台  
45    static HANDLE           m_hLogFile;
46    static bool             m_bTruncateLongLog;     //长日志是否截断
47    static LOG_LEVEL        m_nLogLevel;            //日志级别
48};
49
50#endif // !__LOG_H__

日志的cpp文件（实现文件）

  1/**
  2 *@desc:   IULog.cpp
  3 *@author: zhangyl
  4 *@date:   2014.12.25
  5 */
  6#include "stdafx.h"
  7#include "IULog.h"
  8#include "EncodingUtil.h"
  9#include <tchar.h>
 10
 11#ifndef LOG_OUTPUT
 12#define LOG_OUTPUT
 13#endif
 14
 15#define MAX_LINE_LENGTH 256
 16
 17bool CIULog::m_bToFile = false;
 18bool CIULog::m_bTruncateLongLog = false;
 19HANDLE CIULog::m_hLogFile = INVALID_HANDLE_VALUE;
 20LOG_LEVEL CIULog::m_nLogLevel = LOG_LEVEL_INFO;
 21
 22bool CIULog::Init(bool bToFile, bool bTruncateLongLog, PCTSTR pszLogFileName)
 23{
 24#ifdef LOG_OUTPUT
 25    m_bToFile = bToFile;
 26    m_bTruncateLongLog = bTruncateLongLog;
 27
 28    if (pszLogFileName == NULL || pszLogFileName[0] == NULL)
 29        return FALSE;
 30
 31    TCHAR szHomePath[MAX_PATH] = {0};
 32    ::GetModuleFileName(NULL, szHomePath, MAX_PATH);
 33    for (int i = _tcslen(szHomePath); i >= 0; --i)
 34    {
 35        if (szHomePath[i] == _T('\\'))
 36        {
 37            szHomePath[i] = _T('\0');
 38            break;
 39        }
 40    }
 41
 42    TCHAR szLogDirectory[MAX_PATH] = { 0 };
 43    _stprintf_s(szLogDirectory, _T("%s\\Logs\\"), szHomePath);
 44
 45    DWORD dwAttr = ::GetFileAttributes(szLogDirectory);
 46    if (!((dwAttr != 0xFFFFFFFF) && (dwAttr & FILE_ATTRIBUTE_DIRECTORY)))
 47    {
 48        TCHAR cPath[MAX_PATH] = { 0 };
 49        TCHAR cTmpPath[MAX_PATH] = { 0 };
 50        TCHAR* lpPos = NULL;
 51        TCHAR cTmp = _T('\0');
 52
 53        _tcsncpy_s(cPath, szLogDirectory, MAX_PATH);
 54
 55        for (int i = 0; i < (int)_tcslen(cPath); i++)
 56        {
 57            if (_T('\\') == cPath[i])
 58                cPath[i] = _T('/');
 59        }
 60
 61        lpPos = _tcschr(cPath, _T('/'));
 62        while (lpPos != NULL)
 63        {
 64            if (lpPos == cPath)
 65            {
 66                lpPos++;
 67            }
 68            else
 69            {
 70                cTmp = *lpPos;
 71                *lpPos = _T('\0');
 72                _tcsncpy_s(cTmpPath, cPath, MAX_PATH);
 73                ::CreateDirectory(cTmpPath, NULL);
 74                *lpPos = cTmp;
 75                lpPos++;
 76            }
 77            lpPos = _tcschr(lpPos, _T('/'));
 78        }
 79    }
 80
 81    m_hLogFile = ::CreateFile(pszLogFileName, GENERIC_READ | GENERIC_WRITE, FILE_SHARE_READ, NULL, CREATE_NEW, FILE_ATTRIBUTE_NORMAL, NULL);
 82    if (m_hLogFile == INVALID_HANDLE_VALUE)
 83        return false;
 84
 85#endif // end LOG_OUTPUT
 86
 87    return true;
 88}
 89
 90void CIULog::Uninit()
 91{
 92#ifdef LOG_OUTPUT
 93    if(m_hLogFile != INVALID_HANDLE_VALUE)
 94    {
 95        ::CloseHandle(m_hLogFile);
 96        m_hLogFile = INVALID_HANDLE_VALUE;
 97    }
 98#endif //end LOG_OUTPUT
 99}
100
101void CIULog::SetLevel(LOG_LEVEL nLevel)
102{
103    m_nLogLevel = nLevel;
104}
105
106bool CIULog::Log(long nLevel, PCTSTR pszFmt, ...)
107{
108#ifdef LOG_OUTPUT
109    if (nLevel < m_nLogLevel)
110        return false;
111
112    char szTime[64] = { 0 };
113    GetTime(szTime,ARRAYSIZE(szTime));
114    std::string strDebugInfo(szTime);
115
116    std::string strLevel("[INFO]");
117    if (nLevel == LOG_LEVEL_WARNING)
118        strLevel = "[Warning]";
119    else if (nLevel == LOG_LEVEL_ERROR)
120        strLevel = "[Error]";
121
122    strDebugInfo += strLevel;
123
124    //当前线程信息
125    char szThreadID[32] = { 0 };
126    DWORD dwThreadID = ::GetCurrentThreadId();
127    sprintf_s(szThreadID, ARRAYSIZE(szThreadID), "[ThreadID: %u]", dwThreadID);  
128    strDebugInfo += szThreadID;
129
130    //log正文
131    std::wstring strLogMsg;
132    va_list ap;
133    va_start(ap, pszFmt);
134    int nLogMsgLength = _vsctprintf(pszFmt, ap);
135    //容量必须算上最后一个\0
136    if ((int)strLogMsg.capacity() < nLogMsgLength + 1)
137    {
138        strLogMsg.resize(nLogMsgLength + 1);
139    }
140    _vstprintf_s((TCHAR*)strLogMsg.data(), strLogMsg.capacity(), pszFmt, ap);
141    va_end(ap);
142
143    //string内容正确但length不对，恢复一下其length
144    std::wstring strMsgFormal;
145    strMsgFormal.append(strLogMsg.c_str(), nLogMsgLength);
146
147    //如果日志开启截断，长日志只取前MAX_LINE_LENGTH个字符
148    if (m_bTruncateLongLog)
149        strMsgFormal = strMsgFormal.substr(0, MAX_LINE_LENGTH);
150
151    std::string strLogMsgAscii;
152    strLogMsgAscii = EncodeUtil::UnicodeToAnsi(strMsgFormal);
153
154    strDebugInfo += strLogMsgAscii;
155    strDebugInfo += "\r\n";
156
157    if(m_bToFile)
158    {
159        if(m_hLogFile == INVALID_HANDLE_VALUE)
160            return false;
161
162        ::SetFilePointer(m_hLogFile, 0, NULL, FILE_END);
163        DWORD dwBytesWritten = 0;       
164        ::WriteFile(m_hLogFile, strDebugInfo.c_str(), strDebugInfo.length(), &dwBytesWritten, NULL);
165        ::FlushFileBuffers(m_hLogFile);
166        return true;
167    }
168
169    ::OutputDebugStringA(strDebugInfo.c_str());
170
171#endif // end LOG_OUTPUT
172
173    return true;
174}
175
176bool CIULog::Log(long nLevel, PCSTR pszFunctionSig, int nLineNo, PCTSTR pszFmt, ...)
177{
178#ifdef LOG_OUTPUT
179    if (nLevel < m_nLogLevel)
180        return false;
181
182    //时间
183    char szTime[64] = { 0 };
184    GetTime(szTime, ARRAYSIZE(szTime));
185    std::string strDebugInfo(szTime);
186
187    //错误级别
188    std::string strLevel("[INFO]");
189    if (nLevel == LOG_LEVEL_WARNING)
190        strLevel = "[Warning]";
191    else if (nLevel == LOG_LEVEL_ERROR)
192        strLevel = "[Error]";
193
194    strDebugInfo += strLevel;
195
196    //当前线程信息
197    char szThreadID[32] = {0};
198    DWORD dwThreadID = ::GetCurrentThreadId();
199    sprintf_s(szThreadID, ARRAYSIZE(szThreadID), "[ThreadID: %u]", dwThreadID);
200    strDebugInfo += szThreadID;
201
202    //函数签名
203    char szFuncSig[512] = { 0 };
204    sprintf_s(szFuncSig, "[%s:%d]", pszFunctionSig, nLineNo);
205    strDebugInfo += szFuncSig;
206
207    //log正文
208    std::wstring strLogMsg;
209    va_list ap;
210    va_start(ap, pszFmt);
211    int nLogMsgLength = _vsctprintf(pszFmt, ap);
212    //容量必须算上最后一个\0 
213    if ((int)strLogMsg.capacity() < nLogMsgLength + 1)
214    {
215        strLogMsg.resize(nLogMsgLength + 1);
216    }
217    _vstprintf_s((TCHAR*)strLogMsg.data(), strLogMsg.capacity(), pszFmt, ap);
218    va_end(ap);
219
220    //string内容正确但length不对，恢复一下其length
221    std::wstring strMsgFormal;
222    strMsgFormal.append(strLogMsg.c_str(), nLogMsgLength);
223
224    //如果日志开启截断，长日志只取前MAX_LINE_LENGTH个字符
225    if (m_bTruncateLongLog)
226        strMsgFormal = strMsgFormal.substr(0, MAX_LINE_LENGTH);
227
228    std::string strLogMsgAscii;
229    strLogMsgAscii = EncodeUtil::UnicodeToAnsi(strMsgFormal);
230
231    strDebugInfo += strLogMsgAscii;
232    strDebugInfo += "\r\n";
233
234    if(m_bToFile)
235    {
236        if(m_hLogFile == INVALID_HANDLE_VALUE)
237            return false;
238
239        ::SetFilePointer(m_hLogFile, 0, NULL, FILE_END);
240        DWORD dwBytesWritten = 0;
241        ::WriteFile(m_hLogFile, strDebugInfo.c_str(), strDebugInfo.length(), &dwBytesWritten, NULL);
242        ::FlushFileBuffers(m_hLogFile);
243        return true;
244    }
245
246    ::OutputDebugStringA(strDebugInfo.c_str());
247
248#endif // end LOG_OUTPUT
249
250    return true;
251}
252
253bool CIULog::Log(long nLevel, PCSTR pszFunctionSig, int nLineNo, PCSTR pszFmt, ...)
254{
255#ifdef LOG_OUTPUT
256    if (nLevel < m_nLogLevel)
257        return false;
258
259    //时间
260    char szTime[64] = { 0 };
261    GetTime(szTime, ARRAYSIZE(szTime));
262    std::string strDebugInfo(szTime);
263
264    //错误级别
265    std::string strLevel("[INFO]");
266    if (nLevel == LOG_LEVEL_WARNING)
267        strLevel = "[Warning]";
268    else if (nLevel == LOG_LEVEL_ERROR)
269        strLevel = "[Error]";
270
271    strDebugInfo += strLevel;
272
273    //当前线程信息
274    char szThreadID[32] = {0};
275    DWORD dwThreadID = ::GetCurrentThreadId();
276    sprintf_s(szThreadID, ARRAYSIZE(szThreadID), "[ThreadID: %u]", dwThreadID);
277    strDebugInfo += szThreadID;
278
279    //函数签名
280    char szFuncSig[512] = { 0 };
281    sprintf_s(szFuncSig, "[%s:%d]", pszFunctionSig, nLineNo);
282    strDebugInfo += szFuncSig;
283
284    //日志正文
285    std::string strLogMsg;
286    va_list ap;
287    va_start(ap, pszFmt);
288    int nLogMsgLength = _vscprintf(pszFmt, ap);
289    //容量必须算上最后一个\0
290    if ((int)strLogMsg.capacity() < nLogMsgLength + 1)
291    {
292        strLogMsg.resize(nLogMsgLength + 1);
293    }
294    vsprintf_s((char*)strLogMsg.data(), strLogMsg.capacity(), pszFmt, ap);
295    va_end(ap);
296
297    //string内容正确但length不对，恢复一下其length
298    std::string strMsgFormal;
299    strMsgFormal.append(strLogMsg.c_str(), nLogMsgLength);
300
301    //如果日志开启截断，长日志只取前MAX_LINE_LENGTH个字符
302    if (m_bTruncateLongLog)
303        strMsgFormal = strMsgFormal.substr(0, MAX_LINE_LENGTH);
304
305    strDebugInfo += strMsgFormal;
306    strDebugInfo += "\r\n";
307
308    if(m_bToFile)
309    {
310        if(m_hLogFile == INVALID_HANDLE_VALUE)
311            return false;
312
313        ::SetFilePointer(m_hLogFile, 0, NULL, FILE_END);
314        DWORD dwBytesWritten = 0;
315        ::WriteFile(m_hLogFile, strDebugInfo.c_str(), strDebugInfo.length(), &dwBytesWritten, NULL);
316        ::FlushFileBuffers(m_hLogFile);
317        return true;
318    }
319
320    ::OutputDebugStringA(strDebugInfo.c_str());
321
322#endif // end LOG_OUTPUT
323
324    return true;
325}
326
327void CIULog::GetTime(char* pszTime, int nTimeStrLength)
328{
329    SYSTEMTIME st = {0};
330    ::GetLocalTime(&st);
331    sprintf_s(pszTime, nTimeStrLength, "[%04d-%02d-%02d %02d:%02d:%02d:%04d]", st.wYear, st.wMonth, st.wDay, st.wHour, st.wMinute, st.wSecond, st.wMilliseconds);
332}

上述代码中根据日志级别定义了三个宏LOG_INFO、LOG_WARNING、LOG_ERROR，如果要使用该日志模块，只需要在程序启动处的地方调用CIULog::Init函数初始化日志：

1SYSTEMTIME st = {0};
2::GetLocalTime(&st);
3TCHAR szLogFileName[MAX_PATH] = {0};
4_stprintf_s(szLogFileName, MAX_PATH, _T("%s\\Logs\\%04d%02d%02d%02d%02d%02d.log"), g_szHomePath, st.wYear, st.wMonth, st.wDay, st.wHour, st.wMinute, st.wSecond);
5CIULog::Init(true, false, szLogFileName);

当然，最佳的做法，在程序退出的地方，调用CIULog::Uninit回收日志模块相关的资源：

1CIULog::Uninit();

在做好这些准备工作以后，如果你想在程序的某个地方写一条日志，只需要这样写：

1LOG_INFO("Request logon: Account=%s, Password=*****, Status=%d, LoginType=%d.", pLoginRequest->m_szAccountName, pLoginRequest->m_szPassword, pLoginRequest->m_nStatus, (long)pLoginRequest->m_nLoginType);
2LOG_WARN("Some warning...");
3LOG_ERROR("Recv data error, errorNO=%d.", ::WSAGetLastError());

关于CIULog这个日志模块类，如果读者要想实际运行查看效果，可以从链接（https://github.com/baloonwj/flamingo/tree/master/flamingoclient）下载完整的项目代码来运行。该日志输出效果如下：

 1[2018-11-09 23:52:54:0826][INFO][ThreadID: 7252][bool __thiscall CIUSocket::Login(const char *,const char *,int,int,int,class std::basic_string<char,struct std::char_traits<char>,class std::allocator<char> > &):1107]Request logon: Account=zhangy, Password=*****, Status=76283204, LoginType=1.
 2[2018-11-09 23:52:56:0352][INFO][ThreadID: 5828][void __thiscall CIUSocket::SendThreadProc(void):794]Recv data thread start...
 3[2018-11-09 23:52:56:0385][INFO][ThreadID: 6032][void __thiscall CSendMsgThread::HandleUserBasicInfo(const class CUserBasicInfoRequest *):298]Request to get userinfo.
 4[2018-11-09 23:52:56:0355][INFO][ThreadID: 7140][void __thiscall CIUSocket::RecvThreadProc(void):842]Recv data thread start...
 5[2018-11-09 23:52:57:0254][INFO][ThreadID: 7220][int __thiscall CRecvMsgThread::HandleFriendListInfo(const class std::basic_string<char,struct std::char_traits<char>,class std::allocator<char> > &):593]Recv user basic info, info count=1:
 6[2018-11-09 23:52:57:0685][INFO][ThreadID: 6032][void __thiscall CSendMsgThread::HandleGroupBasicInfo(const class CGroupBasicInfoRequest *):336]Request to get group members, groupid=268435457.
 7[2018-11-09 23:52:57:0809][INFO][ThreadID: 8184][bool __thiscall CIUSocket::ConnectToImgServer(int):428]Connect to img server:120.55.94.78, port:20002 successfully.
 8[2018-11-09 23:52:58:0048][INFO][ThreadID: 6032][void __thiscall CSendMsgThread::HandleGroupBasicInfo(const class CGroupBasicInfoRequest *):336]Request to get group members, groupid=268435458.
 9[2018-11-09 23:52:58:0084][INFO][ThreadID: 7220][int __thiscall CRecvMsgThread::HandleGroupBasicInfo(const class std::basic_string<char,struct std::char_traits<char>,class std::allocator<char> > &):671]Recv group member info, groupid=268435457, info count=29:
10[2018-11-09 23:52:58:0500][Error][ThreadID: 8184][long __thiscall CImageTaskThread::DownloadImage(const char *,const wchar_t *,int,struct HWND__ *,void *):568]Download img failed: read filesize error, filesize=0, img name=be19574dcdd11fb9a96cf00f7e5f0e66
11[2018-11-09 23:52:58:0943][INFO][ThreadID: 6032][void __thiscall CSendMsgThread::HandleGroupBasicInfo(const class CGroupBasicInfoRequest *):336]Request to get group members, groupid=268435485.
12[2018-11-09 23:52:59:0310][INFO][ThreadID: 7220][int __thiscall CRecvMsgThread::HandleGroupBasicInfo(const class std::basic_string<char,struct std::char_traits<char>,class std::allocator<char> > &):671]Recv group member info, groupid=268435458, info count=7:
13[2018-11-09 23:52:59:0508][Error][ThreadID: 8184][long __thiscall CImageTaskThread::DownloadImage(const char *,const wchar_t *,int,struct HWND__ *,void *):619]Failed to download image: F:\mycode\flamingoX\flamingoclient\Source\..\Bin\Users\zhangy\UserThumb\15.png.

多线程同步写日志出现的问题一

从上面的日志输出来看，这种同步的日志输出方式，也存在时间顺序不正确的问题（时间戳大的日志比时间戳小的日志靠前）。这是由于多线程同时写日志到同一个文件时，产生日志的时间和实际写入磁盘的时间不是一个原子操作。下图解释了该现象出现的根源：

多线程写同一个日志文件出现先产生的日志后写入到文件中的现象

好在这种时间顺序不正确只会出现在不同线程之间，对于同一个线程的不同时间的日志记录顺序肯定是正确的。所以这种日期错乱现象，并不影响我们使用日志。

多线程同步写日志出现的问题二

多线程同时写入同一个日志文件还有一个问题，就是假设线程A写某一个时刻追加日志内容为“AAAAA”，线程B在同一时刻追加日志内容为“BBBBB”，线程C在同一时刻追加日志内容为“CCCCC”，那么最终的日志文件中的内容会不会出现“AABBCCABCAACCBB”这种格式？

在类Unix系统上（包括linux），同一个进程内针对同一个FILE*的操作是线程安全的，也就是说，在这类操作系统上得到的日志结果A、B、C各个字母组一定是连续在一起，也就是说最终得到的日志内容可能是“AAAAACCCCCBBBBB”或“AAAAABBBBBCCCCC”等这种连续的格式，绝不会出现A、B、C字母相间的现象。

而在Windows系统上，对于FILE*的操作并不是线程安全的。但是笔者做了大量实验，在Windows系统上也没有出现这种A、B、C字母相间的现象。（关于这个问题的讨论，可以参考这里：https://www.zhihu.com/question/40472431）

加上这种同步日志的实现方式，一般用于低频写日志的软件系统中（如客户端软件），所以，我们可以认为这种多线程同时写日志到一个文件中是可行的。

全部章节内容，我放在我的知识星球中去了。很多人可能不熟悉知识星球，这是一个知识付费社区。我的知识星球的主题是“小方说服务器开发”，星球有如下内容：

1. 你平常技术上或者生活上有什么困惑之类的问题，你在里面提问很多前辈可以给你详尽的回答。

2. 分享一些内部的源码或者教程或资料（这些内容不方便对外公开），这些内容一般对外部收费，对内部免费。

3. 不定期做一些只针对星球成员的技术分享活动。

值此双11狂欢节之际，给大家送一波福利——原价200元的知识星球，现在只需要111元，时长调整为一年，即一年111元。加入三天内如不满意，无条件全额退款。一星期后将恢复原价，如有兴趣的小伙伴尽快加入。加入方式，微信扫描下面的二维码即可加入：