【译】C++日志（Logging in C++）

时间：2022-02-04 01:55:57

声明：原创翻译，转载请注明出处！http://www.cnblogs.com/mewmicro/p/6432507.html

注：作者Petru Marginean，2007/09/05

 

日志记录是用于故障排除和维护软件系统的关键技术。Petru提供了一种类型安全，线程安全和可移植的C ++日志框架。

日志记录是用于故障排除和维护软件系统的关键技术。要获取它所提供的信息也十分简单，既不要求具备编程语言的知识，也不需要专用工具。日志是一个判断应用程序是否正常运行的有效手段。良好的日志机制可以有效节省调试时间，并大大提高应用程序的可维护性

在本文中，我将介绍一个简单但非常有用的日志框架，它是类型安全，线程安全（行级），高效，可移植，细粒度，紧凑和灵活的。它能在Sun或其他平台上使用Visual C ++ 7.1，g ++ 3.3.5和CC 5.3编译。完整源代码可以在www.ddj.com/code/下的DDJ October 2007 zip文件中找到。

在本文的第2部分，我会通过提供更多的粒度来增强这种技术。

The First Step 第一步

让我们对Log类中进行第一次刺探。 清单1使用名为“os”的std :: ostringstream成员变量来累积记录的数据。 Get（）成员函数提供对该变量的访问。 所有数据格式化后，Log的析构函数将输出保存为标准错误。 你像这样使用Log类：

Log().Get(logINFO) << "Hello " << username;

执行此代码将创建一个具有 logINFOx 日志记录级别的 Log 对象，获取其 std::stringstream 对象，格式化并累积用户提供的数据，最后使用一次 fprintf() 调用将结果字符串持久化到日志文件中。

为什么在析构期间执行flush？最后两个步骤很重要，它们保证了日志机制的线程安全性。 fprintf() 函数是线程安全的，所以即使这个log对象被不同的线程调用，输出内容也不会混乱。根据gnu.org/software/libc/manual/html_node/Streams-and-Threads.html所述：

Listing One 清单1

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
// Log, version 0.1: a simple logging class
enum TLogLevel {logERROR, logWARNING, logINFO, logDEBUG, logDEBUG1,
logDEBUG2, logDEBUG3, logDEBUG4};
class Log
{
public:
   Log();
   virtual ~Log();
   std::ostringstream& Get(TLogLevel level = logINFO);
public:
   static TLogLevel& ReportingLevel();
protected:
   std::ostringstream os;
private:
   Log(const Log&);
   Log& operator =(const Log&);
private:
   TLogLevel messageLevel;
};
std::ostringstream& Log::Get(TLogLevel level)
{
   os << "- " << NowTime();
   os << " " << ToString(level) << ": ";
   os << std::string(level > logDEBUG ? 0 : level - logDEBUG, '\t');
   messageLevel = level;
   return os;
}
Log::~Log()
{
   if (messageLevel >= Log::ReportingLevel())
   {
      os << std::endl;
      fprintf(stderr, "%s", os.str().c_str());
      fflush(stderr);
   }
}

POSIX标准要求默认情况下流操作是原子的...两个线程同时对同一个流发出操作时的执行结果，应该与这两个流操作被顺序地发出时一样。读取或写入时执行的缓冲区操作不受同一流的其他方法影响。 为此，每个流都有一个内部锁对象，必须（隐式地）在执行任何工作之前获取。

在继续进行更高效实现之前，让我们编写代码，以便与日志记录级别成比例地插入选项卡，并将std :: endl附加到每个文本块。 这使得日志行定向并且容易被人和机器读取。 以下是相关代码：

1
2
3
4
5
6
7
Log::ReportingLevel() = logDEBUG2;
const int count = 3;
Log().Get(logDEBUG) << "A loop with " << count << " iterations";
for (int i = 0; i != count; ++i)
{
   Log().Get(logDEBUG1) << "the counter i = " << i;
}

其输出为：

1
2
3
4
- 22:25:23.643 DEBUG:   A loop with 3 iterations
- 22:25:23.644 DEBUG1:  the counter i = 0
- 22:25:23.645 DEBUG1:  the counter i = 1
- 22:25:23.645 DEBUG1:  the counter i = 2

缩进使日志的可读性更强。越多前置标签意味着越详尽的日志级别。

A Little Trick  一个小技巧

到目前为止，该框架表现出了良好的性价比：它在一个小而易用的包中提供了一些不错的格式化规则（根据日志级别变化的标签和最终的std :: endl）。但是，当前的Log类有一个效率问题：即使当前日志级别并不需要输出，Log对象仍会在内部累积数据 - 只有在销毁期间才能意识到根本不需要输出！ 这个问题足以成为阻碍Log类在生产系统中使用的绊脚石。

当日志级别无需输出时，你可以使用一个小技巧，使代码跟没加日志记录代码时运行的几乎一样快。日志只有在实际产生输出时才有开销; 否则，几乎没有开销（实际上在大多数情况下是不可测量的）。这让你很好地在快速执行和详细的日志记录之间的取得平衡。

让我们将输出检查从析构函数移动到最早的可能时间，也就是在构建Log对象之前。这样，如果日志记录级别表明您应该放弃记录的数据，您甚至不会创建Log对象。

1
2
3
#define LOG(level) \
if (level > Log::ReportingLevel()) ; \
else Log().Get(level)

现在第一个例子的代码应该变为：

1
LOG(logINFO) << "Hello " << username;

并会由预处理器展开为（为了清楚起见，添加了新行）：

1
2
3
4
if (logINFO > Log::ReportingLevel())
;
else
Log().Get(logINFO) << "Hello " << username;

于是，Log类也变得更简单，因为messageLevel成员和析构函数中的测试条件可以移除了：

1
2
3
4
5
6
Log::~Log()
{
   os << std::endl;
   fprintf(stderr, "%s", os.str().c_str());
   fflush(stderr);
}

现在，日志记录变得更加高效了。您可以*地在代码中记录日志，而不必担心效率问题。唯一要记住的是，在频繁执行的代码使用更高的（即更详细的）日志记录级别。

在应用这个技巧后，应该注意避免引入宏相关的错误 - 我们要记住，受到日志级别的影响，日志代码可能不会被执行。虽然，这正是我们所期望的行为，并且也是保证代码高效的实际原因。但是，一如既往，“宏”定义可能引入微妙的错误。比如，在下面这个例子中：

1
LOG(logINFO) << "A number of " << NotifyClients() << " were notified.";

只有当日志级别为logINFO或更低时，才会通知客户端。这可能并非你的本意！正确的代码应该是：

1
2
const int notifiedClients = NotifyClients();
LOG(logINFO) << "A number of " << notifiedClients << " were notified.";

Going Generic 转向泛型

到目前为止，我们的实现存在的另一个问题是，代码是硬编码的，只能输出到stderr，别无他处。如果您的库是GUI应用程序的一部分，则更有效的做法是把日志记录到ASCII文件中。客户端（而不是库）应该指明日志的目的地是哪里。通过在Log中增加参数以允许更改输出目标为FILE *是不难的，但为什么给我们不能让它变得更通用呢？更好的做法是将Log逻辑与底层的输出细节完全分离，它们之间则通过策略类进行通信。使用基于策略的设计是合理的（较运行时多态的方法而言），因为你很可能在早期做设计时就会决定日志策略，而不像日志级别到运行时才会被定义。所以，让我们改变Log类来定义和使用策略。实际上，策略接口非常简单，因为它只对一个简单的sink字符串建模：

1
static void Output(const std::string& msg);

Log类转变为期望执行策略的类模板：

1
2
3
4
5
6
7
8
9
10
template <typename OutputPolicy>
class Log
{
  //...
};
template <typename OutputPolicy>
Log<OutputPolicy>::~Log()
{
  OutputPolicy::Output(msg.str());
}

这几乎是Log类需要做的所有事情。作为OutputPolicy策略的一种实现，您现在可以提供FILE *输出，如清单2所示。

Listing Two 清单2

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
class Output2FILE // implementation of OutputPolicy
{
   public:
   static FILE*& Stream();
   static void Output(const std::string& msg);
};
inline FILE*& Output2FILE::Stream()
{
   static FILE* pStream = stderr;
   return pStream;
}
inline void Output2FILE::Output(const std::string& msg)
{
   FILE* pStream = Stream();
   if (!pStream)
       return
 
   fprintf(pStream, "%s", msg.c_str());
   fflush(pStream);
}
typedef Log<Output2FILE> FILELog;
#define FILE_LOG(level) \
if (level > FILELog::ReportingLevel() || !Output2FILE::Stream()) ; \
else FILELog().Get(messageLevel)

下面的代码展示了如何将默认stderr的输出更改为某个特定文件（为简洁起见，省略了错误检查/处理）：

1
2
3
FILE* pFile = fopen("application.log", "a");
Output2FILE::Stream() = pFile;
FILE_LOG(logINFO) << ...;

多线程应用程序的注意事项：如果不同时设置日志的目标，则Output2FILE策略实现是很好的。另一方面，如果计划在运行时从任意线程动态更改日志记录流，则应该使用平台的线程设置或更便携的包装器（如Boost线程）来进行适当的互锁。清单三显示了如何使用Boost线程。

Lising Three 清单3

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
#include <boost/thread/mutex.hpp>
class Output2FILE
{
public:
    static void Output(const std::string& msg);
    static void SetStream(FILE* pFile);
private:
    static FILE*& StreamImpl();
    static boost::mutex mtx;
};
 
inline FILE*& Output2FILE::StreamImpl()
{
    static FILE* pStream = stderr;
    return pStream;
}
inline void Output2FILE::SetStream(FILE* pFile)
{
    boost::mutex::scoped_lock lock(mtx);
    StreamImpl() = pFile;
}
inline void Output2FILE::Output(const std::string& msg)
{
    boost::mutex::scoped_lock lock(mtx);
    FILE* pStream = StreamImpl();
    if (!pStream)
        return;
    fprintf(pStream, "%s", msg.c_str());
    fflush(pStream);
}

不用说，互锁的日志记录将会更慢，但是未使用的日志记录将以最快的速度运行。 这是因为宏中的测试是不同步的 - 一个良性的竞争条件，没有伤害，假设整数被原子地分配（在大多数平台上是公平的假设）。

Compile-Time Plateau Logging Level 编译期日志级别阈值

在某些使用场景中，您可能会发现应用程序的资源占用率超出了预期，或者，即便未输出日志语句的运行时分支判断开销也变得不可忽略。为此，我们可以使用预处理器符号FILELOG_MAX_LEVEL来（在编译期）消除一些日志：

1
2
3
4
5
6
7
#ifndef FILELOG_MAX_LEVEL
#define FILELOG_MAX_LEVEL logDEBUG4
#endif
#define FILE_LOG(level) \
  if (level > FILELOG_MAX_LEVEL) ;\
  else if (level > FILELog::ReportingLevel() || !Output2FILE::Stream()) ; \
   else FILELog().Get(level)

这段代码的有趣之处在于它结合了两个测试。如果你把一个编译期常量传给FILE_LOG，那么第一条测试分支比较的就是两个编译期常量，测试结果在编译期就能确定，任何优化器都可以根据测试结果丢弃生成代码中的死分支。这是种十分常见的优化方式，多数情况下你都可以放心地在你的代码中使用。第二个测试分支如前所述检查运行时日志记录级别。于是，FILELOG_MAX_LEVEL就在原来动态日志级别范围中引入了一个静态阈值：任何高于该静态阈值的日志记录代码都被简单粗暴地丢弃。实际效果展示如下：

1
2
3
4
5
6
7
8
9
bash-3.2$ g++ main.cpp
bash-3.2$ ./a.exe DEBUG1
- 22:25:23.643 DEBUG:   A loop with 3 iterations
- 22:25:23.644 DEBUG1:  the counter i = 0
- 22:25:23.645 DEBUG1:  the counter i = 1
- 22:25:23.645 DEBUG1:  the counter i = 2
bash-3.2$ g++ main.cpp -DFILELOG_MAX_LEVEL=3
bash-3.2$ ./a.exe DEBUG1
- 22:25:31.972 DEBUG:   A loop with 3 iterations

Final Tips on Using Log 日志使用的终极建议

我一直都在使用一项有趣的技术，那就是通过对比日志文件差异来比较每次运行过程。这项技术在您不知道程序出错的原因，以及为什么运行相同代码却获得不同结果时尤其有用：

在不同的平台上（Linux vs. Windows）。在同一平台的不同版本上（RHEL3 vs. RHEL4）。使用不同的编译器设置时（调试 vs. 优化）。

只需将启用最详细的日志级别（要知道，因为日志记录很轻量，你的代码中已经有很多logDEBUGx的日志语句），在两个不同的上下文中运行应用程序，从日志文件中删除时间戳（例如，使用sed程序），并比较两个输出。即便输出文件可能很大，但它们之间的差异也可以很小。不过两者间的差别往往包含大量的有效信息，这也是我们关注的重点。

使用此日志框架的另一个好处是将多个不同应用程序（或单个应用程序的多个实例）的日志记录组合在一起。只需在多个应用程序中以append模式打开相同的文件，就可以看到从各进程交错记录的日志了！结果日志文件仍然有意义（至少在一个合规的操作系统上），因为日志行具有原子性。

我做了一些测试，以实际测量运行时机制的速度（相对于编译期）。结果证明是非常好的。我以三个不同的配置运行相同的代码：

    off-INFO 日志在编译期被禁用，作为测量基准。on-INFO 日志在编译期启用，在运行时禁用（使用INFO详细信息级别）。 on-DEBUG4 在运行时和编译时启用日志（使用DEBUG4级别的详细信息）。

每种配置下都运行多次（20）次（以消除可能的随机错误）。图1和表1展示了实验结果。如您所见，运行时性能（25.109秒）与编译期（25.106秒）（译者注：原文中写的是25.109秒，应该是笔误）相当。这意味着只有当你真正要输出日志记录时才会产生开销。

【译】C++日志（Logging in C++）
Figure 1: Log speed tests. 图1：日志性能测试
  on-DEBUG4 off-INFO on-INFO
AVERAGE 00:00:28.002 00:00:25.106 00:00:25.109
STDEV 0.0000029838 0.0000008605 0.0000014926
Table 1 表1

我发现，在实践中除时间戳和日志级别外最好还应该记录输出日志线程的线程号。当读取来自多线程应用程序的日志文件时，这会是一个十分有效的帮助。

 

Related Article 关联文章

第二篇文章地址：http://www.drdobbs.com/cpp/logging-in-c-part-2/221900468

相关文章