更优化的日志设计 - 快速但全面

• 下载源代码 - 1.76 KB

引言

本文介绍了一种日志设计方法，它实现了文章描述的功能。

• 在没有发生任何事件时，尽可能快地工作。
• 在必要时，记录尽可能多的信息。

这是关于设计的问题，而不是实现。我想明确指出这一点。文章提供的实现非常简单（尽管它包含了很多C++的技巧），只有大约200行代码。此外，在严肃的项目中，不应该直接使用这个实现，而应该根据需求进行修改和调整。例如，您可以添加缓冲、当文件过大时自动重定向到新文件、自动删除旧文件等等。

但我认为这个日志的设计非常有价值。我在我所有的应用程序中都使用类似的日志记录方式，并且它证明非常有效。

日志记录

日志记录是程序中一个非常重要的部分。而且，程序越复杂、越大，拥有适当的日志记录就越重要。在许多情况下（例如调试和崩溃调查），日志几乎是您拥有的唯一信息。很难想象没有日志记录而设计的服务器能够 24/7 运行。

如今存在许多不同的日志系统。有简单的写入文件的包装类（任何人都可以轻松创建），也有更高级的日志记录器，提供缓冲、格式化、过滤、输出选择等选项。还有一个名为“Apache log”（又名 log4cxx）的库，它是一个功能极其丰富的超大日志库。

无论选择哪个库，日志记录都存在以下不可避免的缺点：

• 性能损耗

日志记录很消耗资源。在一些关键代码块（例如内部循环）中进行日志记录，可能会完全扼杀性能。许多日志库会进行缓存（在实际将输出发送到文件/控制台/等之前），这会显著减轻负载。然而

• 它们仍然很消耗资源。即使不写入信息，格式化输出字符串也是一项复杂的操作。此外，在多线程环境中，将内容附加到缓存需要同步（即原子操作），这对性能也有显著影响。
• 缓存可能导致许多糟糕的意外。例如，当程序崩溃时，所有缓存的信息都会丢失。
• 信息/垃圾比率差

通常很难预测问题将在何处发生以及哪些信息对问题调查有用。记录过多会导致性能下降，并且日志会充斥大量无用的垃圾信息。另一方面，在某些地方禁用日志记录是危险的——如果发生问题，您可能会删除非常有价值的信息。

许多日志库支持过滤。也就是说，您可以在代码中放置大量日志语句；然而，它们在运行时可能不会实际被记录。有些库需要重新编译才能工作，有些需要重启程序，还有一些甚至可以在运行时重新配置。通过这种方式，您通常可以使用非常低的日志级别（过滤掉几乎所有内容），在调试时，将日志级别提高。有些库甚至允许为不同的库/类提供不同的过滤选项。

到目前为止，过滤功能很好。但仍然不够好。实际上，这意味着如果第一次发生崩溃（日志级别较低时），您几乎没有任何信息。然后您开始调试：提高日志级别并尝试重现问题。但是有些问题非常难以重现，特别是那些与时序、多线程等相关的问题。此外，提高日志级别后，程序的行为会有所不同——由于日志记录的性能影响，时序可能会改变。实际上，当开启日志记录时，您可能根本无法重现问题。

一箭双雕

现在，让我们来看另一种日志设计。在大多数日志记录器中，在运行时，您使用一种功能：某个函数/宏/运算符用于日志记录。在我们的设计中，我们有三个操作：日志记录、设置所谓的检查点，以及转储所有检查点。以下是这些操作的语法：

// Actual logging.
PUTLOG("This is logged immediately. SomeStr=%s, SomeNum=%d" 
       << szSomeStr << nSomeNum);

// Declaring a checkpoint
CHECKPOINT("This is a checkpoint. SomeNum=%d" << nSomeNum)

// This sends all the checkpoints into the log
Log::PrintCheckpoints();

日志和检查点语句支持类似printf的格式字符串，带有可变数量的参数。唯一的区别是参数用<<而不是逗号分隔。

检查点是一个临时对象，它保存一个已准备好记录但尚未记录的表达式。它存在于声明的作用域（花括号）内。如果一切正常，当退出作用域时，它会被静默删除，并且不会记录任何内容。但是，如果出现问题——您调用Log::PrintCheckpoints，所有检查点都会一次性添加到日志中。

为了弄清楚，让我们看下面的例子：

{
    CHECKPOINT(_T("One"))
    {
        CHECKPOINT(_T("Two"))
        {
            CHECKPOINT(_T("Three"))
            Log::PrintCheckpoints();
        }
        Log::PrintCheckpoints();
    }
    Log::PrintCheckpoints();
}

当第一次调用Log::PrintCheckpoints时（在最内层作用域）——它会看到所有三个检查点。当下次调用时——最内层检查点已经被删除，它只会看到“One”和“Two”。并且，当第三次调用Log::PrintCheckpoints时——只会打印第一个检查点。

在上面的例子中，所有检查点都位于同一个函数中，但这并非强制。检查点可以在不同的函数中声明，它们仍然可见。此外，如果一个函数被递归调用——它的检查点也会被递归看到。换句话说，检查点可见直到它们的生命周期结束。

让我们看另一个例子，这是一个或多或少现实地演示了我们的日志记录：

void SomeWorkerFunc()
{
    CHECKPOINT(_T("WorkerThread=%d") << GetCurrentThreadId())

    // ...
    // eventually process some I/O for client
    pClient->ProcessIo();
    // ...
}

void Client::ProcessIo()
{
    CHECKPOINT(_T("Request from client ID=%u") << m_ID)
    
    // ...
    // eventually decide to send something to the client
    CHECKPOINT(_T("Sending file path=%s") << szSomeFilePath)

    HANDLE hFile = CreateFile(szSomeFilePath, /* ... */);
    ReadFile(/* ... */);
    // ...
}

void ReadFile(/* ... */)
{
    CHECKPOINT(_T("Attempt to read %u bytes", dwBytes)
    TestSysCall(ReadFile(hFile, pBuf, dwBytes, /* ... */));
}

void TestSysCall(BOOL bVal)
{
    if (!bVal)
    {
        PUTLOG(_T("Error=%u") << GetLastError());
        Log::PrintCheckpoints();
        
        throw SomeException;
    }
}

在此示例中，如果一切正常，则不会记录任何内容。但是，如果ReadFile失败，则以下内容将被写入日志：

Error=187
Attempt to read 2048 bytes
Sending file path path=C:\Data\SomeFile.bin
Request from client ID=22487
WorkerThread=3047

注意：此处唯一报告错误的是TestSysCall函数。它没有任何关于其发生上下文的信息，它也不知道错误源自何处。它只拥有（并记录）错误代码。

是否可能在没有检查点的情况下用传统的日志记录实现这种行为？理论上可以。但这需要大量的日志代码，看起来很笨拙，并且会使程序完全难以阅读。代码看起来会像这样：

// ...
HANDLE hFile = CreateFile(szSomeFilePath, /* ... */);
if (INVALID_HANDLE_VALUE == hFile)
{
    Log(_T("Couldn't open file=%s when attempted to send" 
           " it to the cleint ID=%u, in thread=%s. Error=%u")
        << szSomeFilePath << m_ID 
        << GetCurrentThreadId() << GetLastError());
    throw SomeExc;
}

// ...
if (!ReadFile(hFile, /* ... */))
{
    Log(_T("Couldn't read %u bytes from file=%s when attempted" 
           " to send it to the cleint ID=%u, in thread=%s. Error=%u")
        << szSomeFilePath << dwBytes << m_ID 
        << GetCurrentThreadId() << GetLastError());
    throw SomeExc;
}

// ...

也就是说，在这种情况下，您必须将所有上下文信息传递给所有函数，并在所有日志语句中打印它们。您将无法使用通用的（不带上下文的）函数进行常见操作，如 I/O、错误检查等。

事实上，没有人真的这样做。相反，人们要么不记录大部分上下文信息，要么在真正需要之前就记录它们（我们已经讨论了这种方法的缺点）。

当您使用检查点时，情况就会改变。现在，您不必犹豫提供尽可能多的信息，这些信息实际上只会在需要时才被记录。

实现细节

PUTLOG

让我们从PUTLOG宏开始。它将一个表达式作为参数，并立即记录该表达式。

• 表达式的第一个元素必须是一个格式字符串。根据多字节/Unicode编译器选项，字符串应该是多字节或Unicode。使用_T()宏来自动使用正确的字符串是值得的。
• 随后的参数必须根据格式字符串的内容指定。如果不需要参数——则不应指定任何参数。
• 参数必须用<<运算符分隔（您可能已经注意到了）。
• 该表达式仅被评估一次。如果表达式的评估有副作用（例如：它可能包含具有副作用的函数调用），这一点很重要。

正如我一开始所说，日志的实现非常粗糙，不应直接使用。它不支持过滤。也就是说，表达式总是被评估并记录。也没有选择要写入哪个日志的可能性（如果您可能希望有多个日志输出用于不同内容）。您可能会注意到，到目前为止，我们还没有看到任何日志初始化方法，也没有指定要将哪个文件记录到的地方。这是因为此实现不向文件写入任何内容！它只是将格式化后的字符串发送到调试输出。

您应仅将此实现视为一个骨架。如果您喜欢这个想法——那么就去做吧，并根据您的需求进行调整。例如，如果您想添加对多个日志对象支持，您应该重新定义PUTLOG宏以接受一个额外的参数——日志对象。此外，您可以支持过滤：运行时过滤选项（存储在指定的日志对象中）或编译时定义日志宏。但是，您必须小心：当不记录时，您可以选择评估或不评估给定的表达式。当然，最好不要评估它（提高性能）；然而，要小心副作用。

CHECKPOINT

现在来到主菜：CHECKPOINT宏。在决定如何设计和实现检查点时，存在一定的自由度。我的实现的关键目标是：

• 它必须尽可能轻便和快速。
• 使用方便。

也就是说，如果不方便，您将不想使用它。如果它沉重而缓慢——您可能想使用它，但最好不要使用。

为了理解CHECKPOINT到底做什么，我们首先需要认识到传统日志记录在执行时执行的步骤。假设我们记录以下内容：

PUTLOG(_T("My name is %s, Elapsed time=%d") 
          << GetMyName() << TimeNow() - nTimeStart);

在此示例中，执行了以下步骤：

1. 评估日志记录表达式。调用GetName和TimeNow。计算时间减去nTimeStart的值。
2. 格式化日志字符串。这意味着分配一个缓冲区，并调用printf类函数的变体来构建最终字符串。
3. 可选地，可以对最终字符串进行一些装饰（开头的时间戳，结尾的换行符）。
4. 将字符串发送到输出（文件、控制台等）。

CHECKPOINT宏将日志表达式作为参数。该表达式立即被评估，但最终的日志字符串不会被格式化，也不会发出任何内容。这意味着，上面链条的第一个步骤被执行。

CHECKPOINT(_T("My name is %s, Elapsed time=%d") 
              << GetMyName() << TimeNow() - nTimeStart);

在此示例中，GetName和TimeNow立即被调用，并计算出时间减去nTimeStart的值。仅此而已。所有剩余的步骤都会被推迟，直到检查点实际被记录。这会产生以下影响：

• 性能极佳。如果日志表达式不包含繁重的内容（如函数调用）——表达式的评估非常快。
• 由于实际日志字符串的格式化被推迟——表达式中的所有参数必须保持有效。

最后一句话是什么意思？简单地说——GetMyName和TimeNow的返回值必须在检查点生命周期结束之前保持有效。例如，GetMyName可能返回一个指向某个字符串的指针，然后该字符串最终被删除/修改，而检查点仍然存在。这必须避免。

另一种变体：GetMyName返回的不是指向字符串的原始指针，而是通过值返回一个C++字符串对象（例如CString、std::string或其他对象）。返回的对象是临时的，其生命周期仅限于该语句。在PUTLOG中使用这种东西没有问题，因为日志字符串会立即被格式化，但在CHECKPOINT中使用它将导致灾难性的后果。

是否有可能在没有这些缺点的情况下实现CHECKPOINT？是的，但您需要为此付出代价。一种变体是立即格式化日志字符串。另一种方法——定义CHECKPOINT，使其立即复制所有指定的字符串。

是否值得付出代价？绝对不值得，太昂贵了。当前的实现只在初始化时消耗少量 CPU 周期，并在清理时消耗少量周期，这在 99% 的情况下可以忽略不计，即使在最关键的代码块中也是如此。而复制字符串则涉及堆操作，会消耗数百到数千个周期。这将使使用检查点变得毫无价值。毕竟，在大多数情况下，这方面的考虑都是不相关的。大多数时候，检查点（至少对我来说）要么完全没有参数，要么只有几个基本参数。而且，如果您确实想使用一个可能过期的字符串——请自行复制。

深入技术细节

日志表达式（由PUTLOG和CHECKPOINT解析）被转换为一个Record结构，该结构定义如下：

template <size_t nSize>
struct Record {
    PCTSTR m_szFmt;
    int m_pParams[nSize / sizeof(int)];
};

m_szFmt是格式字符串，m_pParams——是格式化最终日志字符串所需的所有参数，以printf类函数识别的方式打包。

注意：Record是一个模板结构，其模板参数是格式化所需的打包参数的大小。实际的格式化参数在运行时放入其中，但容纳它们所需的大小在编译时确定。这是如何实现的？嗯，这是激烈的C++模板魔法。我将这个任务留给您，亲爱的读者，请您从代码中摸索出来。如果我现在告诉您编译和工作原理——我可能会破坏您从本文中获得的最美妙的乐趣。

PUTLOG宏构建这样的记录并立即记录它。而CHECKPOINT宏执行以下操作：

• 构建记录。
• 声明一个Checkpoint类的临时对象，该对象包装上述记录。该对象在构造函数（ctor）中“注册”自己，并在析构函数（dtor）中“注销”自己。

“注册”和“注销”是什么意思？让我们看看代码。Checkpoint定义如下：

struct Checkpoint {

    __declspec(thread) static Checkpoint* s_pTop;
    Checkpoint* m_pPrev;
    // ...

    template <size_t>
    Checkpoint(/* ... */); // register
    ~Checkpoint(); // unregister
};

s_pTop指向最近“注册”的检查点，并且每个检查点的m_pPrev成员指向它替换的那个。就这样，检查点形成了一种堆栈。

注意：s_pTop变量声明为__declspec(thread)语义。这意味着它通过TLS访问。（那些不熟悉的人：TLS - 是“线程局部存储”。它就像一个全局变量；然而，它对每个线程都是唯一的。）通过TLS访问变量非常快。从性能的角度来看，这与访问普通变量相当。

如果您的部分代码位于DLL中，则不能使用__declspec(thread)。在这种情况下——您必须显式访问TLS（通过TlsGetValue/TlsSetValue）。您还必须确保在EXE和所有DLL中使用相同的TLS索引；否则，您将获得多个检查点链，而每个模块中只有一个可见。

异常处理和检查点

在上面的例子中，当程序检测到问题时，会显式调用Log::PrintCheckpoints。特别地，在其中一个案例中，我们在抛出异常之前调用了它。但是，我们不能保证该函数会在每次抛出异常之前被调用。有时，我们将不得不调用一些第三方代码（如STL、MFC、boost等），它们不了解我们的日志系统，而它们只会抛出异常。此外，异常可能由操作系统/硬件隐式引发（例如访问冲突）。顺便说一句，在这种情况下，倾倒所有信息最为重要，但遗憾的是，我们没有机会倾倒检查点。

在异常被抛出并捕获之后——倾倒检查点是不可能的。因为它们已经不存在了。回想一下，检查点存在直到它们的生命周期结束，并且在异常被捕获后，堆栈已经被展开，所有自动（在堆栈上）的变量都被销毁。

幸运的是，有一个解决方案。有一种可能在异常被抛出之后、在它被捕获并展开堆栈之前执行某些操作。这可以通过使用SEH（结构化异常处理）来实现。那些不熟悉SEH的人——有很多在线文档，我推荐阅读它们。我还推荐阅读关于异常处理模型的文章。

为了实现这一目标，我们应该替换或包装传统的try/catch块，使用__try/__except块。您应该这样做：

/////////////////////////////////
// traditional exc handling block
try {
    DoSomething();
catch (/* ... */) {
    Log::PrintCheckpoints(); // Oops! There's nothing there
}

/////////////////////////////////
// Now putting the __try/__except in the middle:
try {
    DoSomethingGuarded();
catch (/* ... */) {
    // Checkpoints already dumped
    // Now - handle the exception
}

void DoSomethingGuarded()
{
    __try {
        DoSomething();
    } __except (Log::PrintCheckpoints(), EXCEPTION_CONTINUE_SEARCH) {
        // never get there
    }
}

/////////////////////////////////
// Use only __try/__except, omit the traditional try/catch
__try {
    DoSomething();
} __except (Log::PrintCheckpoints(), EXCEPTION_EXECUTE_HANDLER) {
    // Checkpoints are already dumped.
    // Now - handle the exception
}

对于不熟悉SEH的人来说，上面的内容可能看起来很复杂。但实际上它并不复杂。传统的C++异常处理机制（至少在MSVC中）是通过SEH实现的。然而，与SEH不同的是，C++异常处理机制是被隐藏的。为了“揭示”它，必须使用纯SEH。

结论

我使用这种日志记录方式已经很长时间了（很多年了），并且它被证明非常有效。我讨厌用缓慢而笨重的东西来臃肿程序，我非常崇尚极简主义。尤其是在必须从硬件榨取最大性能的高性能程序方面。而且，我个人觉得这种日志记录恰到好处。

实际上，当我了解到SEH并开始使用它时，我“发明”了这种日志记录方式。它明显优于C++异常处理，此外，正如发现的，C++异常是基于SEH实现的，因此SEH实际上涵盖了所有异常和崩溃处理。SEH最显著的优点之一是，在发生异常时，您有机会在堆栈展开发生之前执行操作。这对于调试非常有价值，因为此时整个堆栈，包括引发异常的代码，仍然有效，并且包含非常有价值的信息。

在某个时候，我开始在堆栈上添加一些“装饰”，因为原始堆栈可读性不高。这些装饰只是一个单独的字符串。最终，我想在这些字符串中添加一些运行时参数，但是字符串格式化很耗费资源。此外，格式化字符串的长度在编译时未知，因此在运行时，它应该在堆上分配（否则，日志字符串可能会被截断），这会极大地降低性能。通过这种方式，我开始使用“延迟”格式化。有一天，我意识到检查点不仅对崩溃调查有用，实际上可以完全取代传统的日志记录。只需将所有日志语句转换为检查点。这将抛弃大部分垃圾信息，因为不再需要到处传递所有上下文信息。而且，只在必要时记录检查点：发生异常时（在被视为异常的情况下），以及按需在几个地方。

顺便说一句，最近，我与Apache Log（又名log4cxx）有一些经验，这是一个庞大且非常流行的日志库，拥有巨大的选项和功能。我感到惊讶：它不仅支持传统日志记录，还创建了与我所做的工作类似的东西！它被称为NDC——“嵌套诊断上下文”，这是一个每个线程的字符串LIFO队列（堆栈），您可以对其进行推/弹操作，它们会自动附加到每个日志消息中。

然而，他们只做了一部分工作，这使得他们的NDC的使用非常有限，在我看来。这个机制极其重要，要快速且方便，而log4cxx的NDC在这两方面都表现不佳。从性能角度来看，它很糟糕——它使用大量的堆操作、字符串复制等。而且，从使用便利性的角度来看，它太笨拙了——它只接受字符串。此外，它允许不可控的字符串推/弹：特别是，您可能在某处推送一个字符串，而在退出作用域时没有将其弹回。这显然会导致混乱。必须使用RAII包装器来防止这种情况。否则，您的“嵌套诊断上下文”可能包含不再是实际的信息。此外，所有NDC字符串都会自动附加到每个日志消息中，这并不是您想要的。

我和一些真正钦佩log4cxx的人谈过。我问NDC的主要用途是什么。他们告诉我一些关于线程的事情。也就是说，在多线程应用程序中，不同的线程记录到同一个文件中，所有内容都会混杂在一起。NDC有助于区分消息来自何处。

但这太荒谬了。人们根本没有意识到这个想法的巨大潜力。我的所作所为，或多或少，应该是NDC最明显的用途。只是NDC必须快速且轻量级，而它不是。

正如我之前所说——提供的实现是一个骨架。它不执行实际的日志记录。如果适用于您的情况，您可以将其作为支持过滤、缓冲等的其他日志系统的包装器来使用。

我将感激评论，无论是积极的还是消极的。欢迎新的想法和批评。