怎样设计一个运行日志服务

开篇声明:这篇随笔只是谈谈做运行日志服务积累十多年的心得、经验，无意于说教。所以谁若是有想法，或是不同意，请保留或是说出来，拒绝动粗。此外，凡事没有最好，愿意借用或是借鉴源码的，可以尽情按需修改，如有需要可以联系，哥不确定能帮忙。

什么叫运行日志服务？这里说的，其实就是怎么用printf。十多年前刚开始做项目的时候，哥还是沿用学生时候的做法，在程序需要的地方用printf进行日志打印，有两种做法。

方法 A.

if(!ptr)
{
#ifdef _DEBUG
  printf("%s:%d invalid null ptr\n", __FUNCTION__, __LINE__);
#endif
  return -1;
}

方法 B.

if(!ptr)
{
  if(g_debug)
  {
    printf("%s:%d invalid null ptr\n", __FUNCTION__, __LINE__);
  }
  return -1;
}

我相信，很多人看到这些就觉得眼熟。比如尚在学习编程的，会说“啊，我咋没想到可以用编译宏或是变量控制呢？”，经验丰富的会说“嗯，哥当年就是这么干的！”，当然，也肯定有人说“这样不是挺好么！”。确实，这样也没什么特比不好的，反正最后发布的版本都能屏蔽那些不需要的打印。

哥想说，你这么写程序，不觉得累么？再者，重新编译哦，查个错还要重新编译啊，那能保证客户那边跑的和你查问题的这个版本是一回事么？哥真见过哥超牛气的嵌入式团队，软件就是这么做的，每天大量的时间就这么花在编译上了！方法B好似进步了点，但系统会不会被太多的打印类似？再进一步，运行日志是不是要能够搞进文件呢？

其实，嵌入式系统开发，运行日志远远比一般人能想到的要复杂，当然做linux等程序也不简单。嵌入式系统里，日志输出要关心调用发生时所处的运行栈：

• 内核；
• 应用栈；
• 中断栈；
• SHELL栈。

这几种运行栈下日志输出行为是不同的。应用栈上的日志输出，大多是用来定位程序运行错误，因此提供调用函数名和源文件行号很重要；中断栈是不能进行任何直接输出的，日志输出需要发送给一个日志队列，由日志服务程序打印出来；SHELL栈则主要是用于人机交互，因此一般要屏蔽函数名这些信息，以便输出排版更好看。

既然有这么多行栈，那各搞一套日志打印不就可以了？可以这么做，但不是很合适。比如说，有些函数，可以被同时用于应用程序和SHELL调用，甚至被中断程序调用。对于这些两栖甚至不确定的函数，按这样一个思路，我们唯有删除任何打印。

我们需要一个统一的日志打印接口。这个打印函数，可以让程序员们在需要的时候直接调用，至于程序运行状态这些高深的东西都留给这个打印函数自己来做吧!

此外，我们希望这个日志打印接口，能允许定制输出级别，别只是一股脑儿的打印或是全部不打印。

再者，我们还希望日志打印能针对各个模块，或是运行任务进行输出控制。

最后，如果日志打印能让我们随心所欲的调整输出到哪里去，就太好了！

最后的最后，这玩意得用起来简单，快捷，最好别有什么使用限制！

如果你有这样的需求，且正在寻找解决办法，那不妨下载下面的C源文件，直接移植或是借鉴。
https://files.cnblogs.com/files/hhao020/cshell_prj_re0.003.rar
zTrace.c，zTrace.h，zTraceApi.h，以及zLog.c，salLog.c就是zTrace的全部实现代码了。

 

zTraceApi.h是唯一的应用程序必须包含的头问题，一起来看看zTraceApi.h里有哪些东西。

/*----------------------------------------------------------
File Name  : xxx.h
Description: This file should be included by any products,
             no matter on vxworks or windows.
Author     : hhao020@gmail.com (bug fixing and consulting)
Date       : 2007-05-15
------------------------------------------------------------*/

#ifndef __TRACE_API_H__
#define __TRACE_API_H__

#include "zType_Def.h"

#ifdef __cplusplus
extern "C" {
#endif


int z_IamShell();
int z_TaskSelf();
int z_InShell();
int z_InKernal();
int z_InInterrupt();


extern int z_Log2ConsoleCbkSet(int (*fnPrint)(const char *, int));
extern int z_Log2ZcnCbkSet(int (*fnPrint)(const char *, int));
extern int z_Log2FileCbkSet(int (*fnPrint)(const char *, int));
extern int z_Log2MemoryCbkSet(int (*fnPrint)(const char *, int));

extern int z_ShellLog(const char *fmt, ...);
extern int z_IntLog  (const char *fmt, ...);
extern int z_TaskLog (const char *fmt, ...);

extern int z_ShellLogHex(const byte_t *pData, int nLen);
extern int z_IntLogHex  (const byte_t *pData, int nLen);
extern int z_TaskLogHex (const byte_t *pData, int nLen);

extern int z_ShellPrint(const char *fmt, ...);
extern int z_ShellPrintHex(const byte_t *pData, int nLen);


int zTraceTaskLevel();

int zTraceBlockOn();
int zTraceBlockOff();
  
int zTraceServiceInit();

int zTraceLevelReset();
int zTraceLevelSet(int tid, byte_t ucLevel);
int zTraceFlagSet(int tid, int bLogFlag);
int zTraceLevelSetAll(byte_t ucLevel);




int zTraceMemoryReset();
int zTraceMemoryInit(int size);
int zTraceMemoryShow(int detail);



/*Any update to below level should update g_strTraceLevelName as well.*/
#define TraceFatal  0x01  /*fatal errors, not recoverable, and is starting reboot soon*/
#define TraceAlarm  0x02  /*emergent errors, not recoverable, need users' maintence check.*/
#define TraceError  0x04  /*software errors*/
#define TraceWarn   0x08  /*configure errors*/
#define TraceInfo   0x10  /*key processes like message traces, for designer, tester's purpose*/
#define TraceDebug  0x20  /*any other verbose information for designing, debuging intents*/


#define VERBOSE_LINE(fnPrint, level) fnPrint("[%s]:%s %s %d::", _STR(level), __FILE__, __FUNCTION__, __LINE__)
#define zTraceV(level, fmt, arg...) do{ \
  if(zTraceTaskLevel() & _CONS(Trace,level)) {\
    zTraceBlockOn();  \
    VERBOSE_LINE(z_TaskLog, level); \
    z_TaskLog(fmt, ##arg); \
    zTraceBlockOff();  \
  } \
}while(0)
#define zTraceQ(level, fmt, arg...) do{ \
  if(zTraceTaskLevel() & _CONS(Trace,level)) {\
    zTraceBlockOn(); \
    z_TaskLog(fmt, ##arg); \
    zTraceBlockOff(); \
  } \
}while(0)
#define zTraceP(fmt, arg...) do{ \
  zTraceBlockOn(); \
  z_ShellPrint(fmt, ##arg); \
  zTraceBlockOff(); \
}while(0)
#define zTracePV(fmt, arg...) do{ \
  zTraceBlockOn(); \
  VERBOSE_LINE(z_TaskLog, Console); \
  z_ShellPrint(fmt, ##arg); \
  zTraceBlockOff(); \
}while(0)


#define zTraceHexV(level, pData, nLen) do{ \
  if(zTraceTaskLevel() & _CONS(Trace,level)) {\
    zTraceBlockOn(); \
    VERBOSE_LINE(z_TaskLog, level); \
    z_TaskLogHex((pData), nLen); \
    zTraceBlockOff(); \
  } \
}while(0)
#define zTraceHexQ(level, pData, nLen) do{ \
  if(zTraceTaskLevel() & _CONS(Trace,level)) {\
    zTraceBlockOn(); \
    z_TaskLogHex((pData), nLen); \
    zTraceBlockOff(); \
  } \
}while(0)
#define zTraceHexP(pData, nLen) do{  \
  zTraceBlockOn(); \
  z_ShellPrintHex((byte_t*)(pData), nLen); \
  zTraceBlockOff(); \
}while(0)




#define zTraceFatal(fmt, arg...)    zTraceV(Fatal,  fmt, ##arg)
#define zTraceAlarm(fmt, arg...)    zTraceV(Alarm,  fmt, ##arg)
#define zTraceError(fmt, arg...)    zTraceV(Error,  fmt, ##arg)
#define zTraceWarn( fmt, arg...)    zTraceV(Warn,   fmt, ##arg)
#define zTraceInfo( fmt, arg...)    zTraceV(Info,   fmt, ##arg)
#define zTraceDebug(fmt, arg...)    zTraceV(Debug,  fmt, ##arg)

#define zTraceFatalQ(fmt, arg...)   zTraceQ(Fatal , fmt, ##arg)
#define zTraceAlarmQ(fmt, arg...)   zTraceQ(Alarm , fmt, ##arg)
#define zTraceErrorQ(fmt, arg...)   zTraceQ(Error , fmt, ##arg)
#define zTraceWarnQ( fmt, arg...)   zTraceQ(Warn  , fmt, ##arg)
#define zTraceInfoQ( fmt, arg...)   zTraceQ(Info,   fmt, ##arg)
#define zTraceDebugQ(fmt, arg...)   zTraceQ(Debug , fmt, ##arg)

#define zTraceHexFatal(pData, nLen)    zTraceHexV(Fatal,  (byte_t*)(pData), nLen)
#define zTraceHexAlarm(pData, nLen)    zTraceHexV(Alarm,  (byte_t*)(pData), nLen)
#define zTraceHexError(pData, nLen)    zTraceHexV(Error,  (byte_t*)(pData), nLen)
#define zTraceHexWarn( pData, nLen)    zTraceHexV(Warn,   (byte_t*)(pData), nLen)
#define zTraceHexInfo( pData, nLen)    zTraceHexV(Info,   (byte_t*)(pData), nLen)
#define zTraceHexDebug(pData, nLen)    zTraceHexV(Debug,  (byte_t*)(pData), nLen)

#define zTraceHexFatalQ(pData, nLen)   zTraceHexQ(Fatal , (byte_t*)(pData), nLen)
#define zTraceHexAlarmQ(pData, nLen)   zTraceHexQ(Alarm , (byte_t*)(pData), nLen)
#define zTraceHexErrorQ(pData, nLen)   zTraceHexQ(Error , (byte_t*)(pData), nLen)
#define zTraceHexWarnQ( pData, nLen)   zTraceHexQ(Warn  , (byte_t*)(pData), nLen)
#define zTraceHexInfoQ( pData, nLen)   zTraceHexQ(Info,   (byte_t*)(pData), nLen)
#define zTraceHexDebugQ(pData, nLen)   zTraceHexQ(Debug , (byte_t*)(pData), nLen)






#define PRINT_THREAD_INFO(tid) do{ printf("%s: %d\n", _STR(tid), (int)tid); }while(0)
#define PRINT_THREAD_LIST(tlist, n) do{ \
  int i; \
  for(i=0; i<n; i++) printf("%s[%d]: %d\n", _STR(tlist), i, (int)tlist[i]); \
}while(0)



#ifdef __cplusplus
}
#endif


#endif /*__TRACE_API_H__*/

 

首先，是几个判断当前运行状态的函数，shell，kernal，interrupt三种，如果这三种状态都不是，那就是应用程序。紧接着的，是z_Log2xxx函数，用来做最终输出的，包括console，file，memory等多个选项。然后是z_xxxLog/z_ShellPrintxxx函数，这个是封装前的几个打印函数，他们会调用前面的z_Log2xxx。再往下，是一组互斥量操作，内存日志支持函数，以及日志打印级别定义和操作。

对于一般使用者来说，这些都不需要理解，因为它们对用户是透明的。

输出级别定义后，是一些相对具体的日志输出接口，是些宏定义。这里有选择的讲一讲。

#define VERBOSE_LINE(fnPrint, level) fnPrint("[%s]:%s %s %d::", _STR(level), __FILE__, __FUNCTION__, __LINE__)

定义额外调试信息，我们不想总是去敲入__FUNCTION__，__LINE__，用这个宏定义来解决。

zTraceV和zTraceQ是所有程序日志使用的；zTraceP和zTracePV则是用来给SHELL用的，且只用在明确的提示信息输出，比如在ShowTaskName()函数里使用。SHELL的运行错误等内容，同样是调用zTraceV或是zTraceQ。TraceHex是个额外的封装，按16进制方式，输出buff内容。这里的V表示包含刚刚那个verbose调试信息，而Q则表示不包含。

zTraceV和zTraceQ都需要提供level。以前哥是把它们做成函数的，但后来发现，有时候用户会传进非法的level；再就是，函数会造成不必要的开销，即便level判断不需要打印，也会造成相当大的运行开销。因此，现在它们被改成了宏，如此一来，level判断在生成打印函数的堆栈信息前，就做了判断，避免了不必要的堆栈变化。

对于使用者来说，这些也都还是透明的。只有再下面的定义，才是他们要关心和使用的。哥给出的zTrace，分5个级别：zTraceFatal，zTraceAlarm，zTraceError，zTraceWarn，zTraceInfo，和zTraceDebug。针对不同的需求，有分为V，Q，Hex，HexQ四个类别。编程的时候，大约95%的情况下，我们只用那5个基本接口（默认Verbose模式）。
下面是个样例：

int   DataBlockFreeCount(void* pool)
{
  zDataPool_t *pPool = (zDataPool_t *)pool;
  if(!pool)
  {
    zTraceWarn("Bad input null pool.\n");
    return -1;
  }

  return pPool->freeCount;
}

注意了，level是个bit位，每个level都是独立的。这里哥用的是warn，而不是其它level。建议是，系统初始化代码里，多用fatal，因为那会出错了就意味着系统没法运行；alarm级别多用在系统性错误，表示系统已经没法服务了；error级别则不要随便用于运行错误，只能用于编码错误；warn级别用于业务或是一般程序运行错误；info级别专供输出主要业务逻辑，比如接口消息的输出，用于定位业务故障；debug级别就是开放给程序员用的，想用就用吧！

info级别其实可以被扩展成msginfo和runinfo的，那样可能更好用。另外，level可以定义成32bits的，那样的话，应用程序可以把info级别扩展成若干个feature相关的level。

在程序设计中，除了专供中断等需要频繁调用高效处理场合使用的代码，zTrace没什么限制。而且，zTrace不需要使用前做初始化(g_zTraceLock编译初始化成unlock)，因此程序可以在任何时间使用。

如何做到让zTrace根据模块或是线程来定制日志输出级别？在zTrace编程大家看到的样子前，我是用模块号来定制输出的。但那么做，就需要在zTrace的参数里提供模块号。这么做挺好的，可以把一个任务切割成几个不同的功能模块来定制日志级别；缺点是，很多函数是公用的，而且应用中，常常看到打印后，却不知道到底是哪个任务打印的。于是，慢慢的，就演进到现在的样子：根据线程来决定级别。

为避免不必要的CPU开销，zTrace首先判断是否使用common的level配置；只有在调试状态（这时候，性能不再重要），才会出现定制的level。当然，针对线程的定制level也并不是那么可怕，只不过微微多占用点CPU罢了。

在结束前，哥建议使用者多利用zTraceLevelSet函数。比如，以前我做电话交换系统，会在消息入口处，对将主、被叫电话号码同跟踪列表进行比对，当发现需要跟踪时，会使用zTraceLevelSet置日志info级别，而处理完消息后，则重置成默认级别。之前我讲状态机编程的时候，提到了FsmTrace。在使用中，FsmTrace一样需要选择性的trace，那是通过traceId来控制的。

好了，差不多讲完了。zTrace虽好，但仍需配合其它手段使用，比如EOS等，绝不可偏废。做任何系统，都应该目标“5分钟找到问题”，“没必要重现故障”。当然，开发工作量也至少会多出一倍。