怎樣設計一個運行日志服務

開篇聲明:這篇隨筆只是談談做運行日志服務積累十多年的心得、經驗，無意於說教。所以誰若是有想法，或是不同意，請保留或是說出來，拒絕動粗。此外，凡事沒有最好，願意借用或是借鑒源碼的，可以盡情按需修改，如有需要可以聯系，哥不確定能幫忙。

什么叫運行日志服務？這里說的，其實就是怎么用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源文件，直接移植或是借鑒。
http://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     : [e-mail] (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分鍾找到問題”，“沒必要重現故障”。當然，開發工作量也至少會多出一倍。