【译】C++日志(Logging in C++)

摘要:
Petru提供了一个类型安全、线程安全和可移植的C++日志框架。格式化所有数据后,日志析构函数将输出保存为标准错误。您可以这样使用Log类:Log()Get˂˂“Hello”˂˂username;执行此代码将创建一个具有logINFOX日志级别的Log对象,获取其std::stringstream对象,格式化并累加用户提供的数据,最后使用fprintf()调用将结果字符串持久化到日志文件。这个问题足以成为阻碍在生产系统中使用Log类的绊脚石。这样,如果日志记录级别指示您应该丢弃记录的数据,您甚至不会创建Log对象。

声明:原创翻译,转载请注明出处!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
enumTLogLevel {logERROR, logWARNING, logINFO, logDEBUG, logDEBUG1,
logDEBUG2, logDEBUG3, logDEBUG4};
classLog
{
public:
   Log();
   virtual~Log();
   std::ostringstream& Get(TLogLevel level = logINFO);
public:
   staticTLogLevel& ReportingLevel();
protected:
   std::ostringstream os;
private:
   Log(constLog&);
   Log& operator =(constLog&);
private:
   TLogLevel messageLevel;
};
std::ostringstream& Log::Get(TLogLevel level)
{
   os << "- "<< NowTime();
   os << " "<< ToString(level) << ": ";
   os << std::string(level > logDEBUG ? 0 : level - logDEBUG, ' ');
   messageLevel = level;
   returnos;
}
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;
constintcount = 3;
Log().Get(logDEBUG) << "A loop with " << count << " iterations";
for(inti = 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()) ;
elseLog().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
constintnotifiedClients = NotifyClients();
LOG(logINFO) << "A number of "<< notifiedClients << " were notified.";

Going Generic 转向泛型

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

1
staticvoidOutput(conststd::string& msg);

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

1
2
3
4
5
6
7
8
9
10
template<typenameOutputPolicy>
classLog
{
  //...
};
template<typenameOutputPolicy>
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
classOutput2FILE // implementation of OutputPolicy
{
   public:
   staticFILE*& Stream();
   staticvoidOutput(conststd::string& msg);
};
inlineFILE*& Output2FILE::Stream()
{
   staticFILE* pStream = stderr;
   returnpStream;
}
inlinevoidOutput2FILE::Output(conststd::string& msg)
{
   FILE* pStream = Stream();
   if(!pStream)
       return
 
   fprintf(pStream, "%s", msg.c_str());
   fflush(pStream);
}
typedefLog<Output2FILE> FILELog;
#define FILE_LOG(level)
if(level > FILELog::ReportingLevel() || !Output2FILE::Stream()) ;
elseFILELog().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>
classOutput2FILE
{
public:
    staticvoidOutput(conststd::string& msg);
    staticvoidSetStream(FILE* pFile);
private:
    staticFILE*& StreamImpl();
    staticboost::mutex mtx;
};
 
inlineFILE*& Output2FILE::StreamImpl()
{
    staticFILE* pStream = stderr;
    returnpStream;
}
inlinevoidOutput2FILE::SetStream(FILE* pFile)
{
    boost::mutex::scoped_lock lock(mtx);
    StreamImpl() = pFile;
}
inlinevoidOutput2FILE::Output(conststd::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) ;
  elseif(level > FILELog::ReportingLevel() || !Output2FILE::Stream()) ;
   elseFILELog().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++)第1张
Figure 1: Log speed tests. 图1:日志性能测试
 on-DEBUG4off-INFOon-INFO
AVERAGE00:00:28.00200:00:25.10600:00:25.109
STDEV0.00000298380.00000086050.0000014926
Table 1 表1

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


 

Related Article 关联文章

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



免责声明:文章转载自《【译】C++日志(Logging in C++)》仅用于学习参考。如对内容有疑问,请及时联系本站处理。

上篇var和let区别简述doc命令操作数据库(下)下篇

宿迁高防,2C2G15M,22元/月;香港BGP,2C5G5M,25元/月 雨云优惠码:MjYwNzM=

相关文章

Linux系统学习 九、日志、命令、身份鉴别、目录、文件查看、控制台终端、文件属性

一、配置静态IP地址 输入ifconfig后没有配置IP地址,接下来进行手动配置。 输入以下命令进入IP配置文件进行配置 原始内容 进入vi后,输入i进入编辑状态,编辑完成后,按esc键退出编辑状态,输入:wq进行保存退出。 编辑后的内容 重新启动一下 遇到的问题: IP配置完成,重启后,可以和本机ping通,但是无法ping通百度。 原因...

C# 简单日志文本输出

第一种 直接文件IO流写日志文件 usingSystem.IO; public static void WriteLog(stringstrLog) { string sFilePath="d:\"+DateTime.Now.ToString("yyyyMM"); string sFileName = "rizhi" + DateTime.Now....

go-grpc 基本使用

gRPC是什么? gRPC是什么可以用官网的一句话来概括 A high-performance, open-source universal RPC framework 所谓RPC(remote procedure call 远程过程调用)框架实际是提供了一套机制,使得应用程序之间可以进行通信,而且也遵从server/client模型。使用的时候客户端调用...

log4j2

转载自 Blog of 天外的星星: http://www.cnblogs.com/leo-lsw/p/log4j2tutorial.html Log4j 2的好处就不和大家说了,如果你搜了2,说明你对他已经有一定的了解,并且想用它,所以这里直接就上手了。   1. 去官方下载log4j 2,导入jar包,基本上你只需要导入下面两个jar包就可以了(xx是...

Retrofit 打印log时,中文会显示类似%E8%BE%BD字符

https://blog.csdn.net/honghailiang888/article/details/54289632?utm_source=blogxgwz6 参照Android Retrofit2.1.0设置编码格式GBK 的文章。 OkHttpClient.Builder builder = newOkHttpClient().newBuild...

SQL基础(五):SQL函数

一、SQL Aggregate 函数:   SQL Aggregate 函数计算从列中取得的值,返回一个单一的值。 1、AVG() 函数   AVG() 函数返回数值列的平均值。   语法:SELECT AVG(column_name) FROM table_name //从 "access_log" 表的 "count" 列获取平均值: SELECT...