摘要
C++程序的調試一般有調試器、printf、日志文件三種。Linux下的調試器為gdb，關於gdb的使用甚至可以單獨用一本書來說明，但是本章並不會過度討論gdb，讀者可以尋找相關的資料閱讀。Gdb是C++程序調試中非常重要的調試手段，其有如下特點：
- l 通過增加斷點，可以觀察重點代碼的執行
- l 若程序出現segmentation fault，gdb可以輸出調用堆棧，方便找到bug之所在
- l 有些邏輯代碼段非常不容易觸發，可以在gdb環境下通過加斷點、修改內存來強制進入特定的代碼段
- l 但是gdb不能用於生產環境，在幾百上千在線的服務器程序上執行gdb的attach操作，是不可能接受的
Gdb絕對是調試期的利器，另外一個調試期使用的既簡單又實用的方法是printf，就是使用c庫的函數printf輸出變量到控制台。其優點是直觀，可以完整的、清晰的觀察程序的運行過程，而不需像gdb一樣暫停程序。另外printf也只能用於開發調試環境，上線時服務器程序都是在后台運行的，printf將會失去作用。更重要的是因為gdb和printf都不會將數據存儲，歷史數據或歷史操作都會在重啟程序后消失。日志文件可以彌補gdb和printf的不足，我們需要一個具有如下功能的日志組件：
- l 用於調試可以顯示、記錄變量、數據，即能支持像printf一樣可以實時的在控制台輸出顯示，又能將記錄存儲文件，方便搜索查看歷史記錄
- l 日志應該擁有良好的格式，即方便開發和運維人員的閱讀，又要包含足夠多的信息，例如事件記錄時間、線程id、事件類型，事件的嚴重級別
- l 日志文件應該被良好的組織，一方面日志應該按照每天單獨文件夾分類，另一方面日志日志文件並應該過大，否則使用編輯器打開、搜索將會非常困難。日志內容也應該組織分類，比如數據庫的操作日志和用戶做任務的日志應該有明確的標志，這樣可以對日志文件進行grep等進行過濾分類查看。
- l 日志文件必須非常容易配置，當調試時期望看到盡可能多的內容，但是不關心的內容需要被過濾掉，比如調試用戶任務模塊時，可以不顯示數據庫相關日志。在上線后，運維只關心報錯信息，比警告級別低的日志需要被屏蔽。在調試時，開發人員經常會盯着控制台的輸出，相比於普通級別日志內容，錯誤級別的日志更應該引起開發注意力，所以重要級別的日志在控制台輸出時應該有彩色高亮顯示。
- l 日志組件必須有高效的性能，一方面調用者期望日志組件調用后立即返回不影響邏輯層的效率，另一方面寫文件屬於io操作，比起內存操作慢的多得多。所以要求日志的接口調用是異步的，日志組件單獨開啟線程執行寫文件操作，只有如此才能盡最大程度滿足程序的實時性。
下面來探討一下日志 的實現。
實現類
定義log_t類來封裝對於日志配置、格式化、輸出的操作。log_t主要的功能有：
- l 支持對日志級別的配置
- l 支持對日志類別的配置
- l 支持配置日志內容是否輸出到文件和控制台
- l 格式化日志
class log_t { public: log_t(int level_, const string& all_class_, const string& path_, const string& file_, bool print_file_, bool print_screen_); virtual ~log_t(); void mod_level(int level_, bool flag_); void mod_class(const string& class_, bool flag_); void mod_print_file(bool flag_); void mod_print_screen(bool flag_); bool is_level_enabled(int level_); const char* find_class_name(const char* class_); void log_content(int level_, const char* str_class_, const string& content_); };
接口log_content 負責格式化和輸出日志內容，其主要實現代碼如下：
void log_t::log_content(int level_, const char* str_class_, const string& content_) { struct timeval curtm; gettimeofday(&curtm, NULL); struct tm tm_val = *localtime(&(curtm.tv_sec)); char log_buff[512]; ::snprintf(log_buff, sizeof(log_buff), "%02d:%02d:%02d.%03ld %s [%ld] [%s] ", tm_val.tm_hour, tm_val.tm_min, tm_val.tm_sec, curtm.tv_usec/1000, g_log_level_desp[level_], gettid(), str_class_); if (m_enable_file && check_and_create_dir(&tm_val)) { m_file << log_buff << content_ << endl; m_file.flush(); } if (m_enable_screen) { printf("%s%s%s%s\n", g_log_color_head[level_], log_buff, content_.c_str(), g_log_color_tail[level_]); } }
其執行的主要過程如下:
- l 格式化時間，包括調用時的時分秒以及毫秒，為什么沒有年月日呢？日志目錄已經安裝每天一個文件夾分類了，故這里省略了年月日信息。
- l 增加日志級別信息，日志級別對應一個字符串描述，如debug級別日志每一行會包含DEBUG字符串。
- l 記錄線程id，這里並沒有直接使用::pthread_self() 獲取線程id，而是獲取線程在系統中分配的“TID”,要知道線程和進程在內核中都有唯一的id，可以通過top進行查看，top -H –p [pid] 可以查看進程內的所有線程的運行負載情況，如果某個線程運行負載很高，我們需要知道到底是那一部分邏輯是熱點，通過搜索日志，可以知道該線程負責了哪塊邏輯，從而能夠發現問題。
- l 記錄日志類別
- l 若配置允許輸出屏幕，那么利用printf輸出，不同的日志級別會有不同的顯示顏色，如printf("\033[1;33mDEBUG\033[0m")， DEBUG 會以黃色輸出。
- l 若配置允許輸出文件，那么flush到文件中，若日期發生變化，重新創建日期目錄，保證每一天一個文件夾，若單個文件內容超過5000行，會創建新的文件，避免文件內容過大，最終目錄機構如下
異步操作
為了保證日志接口盡可能的快，日志接口都是異步完成的其。時序圖如下：
對於用戶層而言，調用日志組件接口的開銷為日志內容格式化和拷貝字符串到隊列，而相對開銷較大的寫文件、輸出屏幕操作則有日志線程完成，這樣可以最大程度的保證用戶層的高效運行。
我們定義log_service_t封裝異步操作，對於格式化和輸出，log_service_t仍然通過log_t實現，log_service_t的職責有四：
- l 封裝異步接口，外部直接調用log_service_t的接口，一般log_service_t一單件模式使用
- l Log_service_t接口模板函數，利用C++的泛型能力確保類型安全，比如當%s參數本應該是user.name()時，卻手誤寫成user，log_service_t的接口保證在編譯器就能報錯。
- l Log_service_t創建日志線程和日志任務隊列，
- l Log_service_t在初始化的時候接受配置日志組件的參數，同時它也支持在運行期修改參數，並且線程安全。
關鍵代碼如下：
class log_service_t { public: log_service_t(); ~log_service_t(); int start(const string& opt_); int stop(); LOG_IMPL_MACRO(async_logdebug, LOG_DEBUG); LOG_IMPL_MACRO(async_logtrace, LOG_TRACE); LOG_IMPL_MACRO(async_loginfo, LOG_INFO); LOG_IMPL_MACRO(async_logwarn, LOG_WARN); LOG_IMPL_MACRO(async_logerror, LOG_ERROR); LOG_IMPL_MACRO(async_logfatal, LOG_FATAL); };
由於各個日志級別的接口代碼都是相似的，使用了LOG_IMPL_MACRO簡化代碼，LOG_IMPL_MACRO定義為：
#define LOG_IMPL_NONE_ARG(func, LOG_LEVEL) \ inline void func(const char* class_, const char* fmt_) \ { \ if (m_log->is_level_enabled(LOG_LEVEL)) \ { \ const char* class_name_str = m_log->find_class_name(class_); \ if (class_name_str) \ { \ m_task_queue.produce(task_binder_t::gen(&log_t::log_content, m_log, LOG_LEVEL, \ class_name_str, string(fmt_))); \ } \ } \ } #define LOG_IMPL_ARG1(func, LOG_LEVEL) \ template <typename ARG1> \ inline void func(const char* class_, const char* fmt_, const ARG1& arg1_) \ { \ if (m_log->is_level_enabled(LOG_LEVEL)) \ { \ const char* class_name_str = m_log->find_class_name(class_); \ if (class_name_str) \ { \ str_format_t dest(fmt_); \ dest.append(arg1_); \ m_task_queue.produce(task_binder_t::gen(&log_t::log_content, m_log, LOG_LEVEL, \ class_name_str, dest.gen_result())); \ } \ } \ } #define LOG_IMPL_MACRO(async_logdebug, LOG_DEBUG) \ LOG_IMPL_NONE_ARG(async_logdebug, LOG_DEBUG) \ LOG_IMPL_ARG1(async_logdebug, LOG_DEBUG) \ LOG_IMPL_ARG2(async_logdebug, LOG_DEBUG) \ LOG_IMPL_ARG3(async_logdebug, LOG_DEBUG) \ LOG_IMPL_ARG4(async_logdebug, LOG_DEBUG) \ LOG_IMPL_ARG5(async_logdebug, LOG_DEBUG) \ LOG_IMPL_ARG6(async_logdebug, LOG_DEBUG)
受篇幅所限，沒有附上所有宏展開的代碼，log_service_t初始化的代碼如下：
int log_service_t::start(const string& opt_) { if (m_log) return 0; int level = 2; string path = "./log"; string filename = "log"; bool print_file = true; bool print_screen = false; arg_helper_t arg(opt_); if (!arg.get_option_value("-log_level").empty()) level = ::atoi(arg.get_option_value("-log_level").c_str()); if (!arg.get_option_value("-log_path").empty()) path = arg.get_option_value("-log_level"); if (!arg.get_option_value("-log_filename").empty()) path = arg.get_option_value("-log_filename"); if (arg.get_option_value("-log_print_file") == "false" || arg.get_option_value("-log_print_file") == "0") { print_file = false; } if (arg.get_option_value("-log_print_screen") == "true" || arg.get_option_value("-log_print_screen") == "1") { print_screen = true; } m_log = new log_t(level, arg.get_option_value("-log_class"), path, filename, print_file, print_screen); m_thread.create_thread(task_binder_t::gen(&task_queue_t::run, &m_task_queue), 1); return 0; }
代碼很簡單，也很直觀，需要對讀者解釋的是，初始化接口start的參數為字符串，這樣做的好處是可以從配置文件中讀入日志配置參數后直接傳給log_service_t的start接口，而用戶層完全不需要關心日志配置語法的細節。Start函數創建log_t實例后，創建單獨線程執行任務隊列，而任務隊列中的所有任務就是寫日志內容或輸出日志內容。
格式化
關於格式化輸出，使用使用了模板函數和多態機制保證了絕對的類型安全，這也是相對於sprintf的巨大優越點。class str_format_t 是用來格式化字符串的工具類，它使用sprintf的格式化語法，但是額外提供了排錯和糾錯功能：
- l 使用sprintf格式化語法，最基本的格式化參數都支持如%d,%u,%ld,%lu,%s,%c,%x,%p,%f甚至形如%04d設置字符串寬度的語法也是支持的
- l str_format_t 類型安全，格式化參數支持整型、浮點數、字符串cost char*、指針、string,若賦值其他類型參數，則編譯不能通過。
- l str_format_t 擁有自動糾錯功能，使用sprintf的時候除了類型不安全導致出錯外，最常見的就是sprintf的格式化參數與賦值的參數個數不一致，如sprintf(buff, “%s,%s”, 100);這樣的代碼編譯能夠通過只有運行期才能發現出錯，str_format_t 可以容忍這樣的失誤，當模板字符串中%比賦值的參數多時，str_format_t自動忽略多余的%，若%比后邊的值參數少時，值參數自動追加到字符串尾部，這樣最大程度的避免了出錯和信息丟失。
關於基本類型的格式化模板函數：
template<typename T>
void append(T content_)
{
if (move_to_next_wildcard())
{
if (m_fmt_type.type == 'x')
{
char buff[64];
snprintf(buff, sizeof(buff), "0x%x", (unsigned int)content_);
m_num_buff = buff;
}
else
{
m_strstream << content_;
m_strstream >> m_num_buff;
}
int width = m_fmt_type.min_len > m_num_buff.length()? m_fmt_type.min_len - m_num_buff.length(): 0;
for (; width > 0; -- width)
{
m_result += m_fmt_type.fill_char;
}
}
else
{
m_strstream << content_;
m_strstream >> m_num_buff;
}
m_result += m_num_buff;
m_strstream.clear();//! clear error bit,not content
m_num_buff.clear();
}
關於字符串的特化函數：
void str_format_t::append(const string& str_) { if (move_to_next_wildcard()) { int width = m_fmt_type.min_len > str_.length()? m_fmt_type.min_len -str_.length(): 0; for (; width > 0; -- width) { m_result += m_fmt_type.fill_char; } } m_result += str_; }
move_to_next_wildcard 每次嘗試移動到下一個%所在的位置，然后用值參數替換%的格式化。move_to_next_wildcard的整個開銷是遍歷字符串的開銷：
bool str_format_t::move_to_next_wildcard() { m_fmt_type.clear(); char tmp = '\0'; for (; cur_format_index < m_fmt_len; ++ cur_format_index) { tmp = m_fmt[cur_format_index]; if (tmp != '%') { m_result += tmp; continue; } char next = m_fmt[cur_format_index + 1]; if (next == '%') { cur_format_index += 1; m_result += next; continue; } //! 支持多種格式化 %c %s, %d, %ld, %u, %lu, %x, %X, 找到格式化的類型 //for (++cur_format_index; cur_format_index < m_fmt_len; ++ cur_format_index) for (unsigned int i = 1 ; i <= 5; ++i) { char cur = m_fmt[cur_format_index + i]; if (cur == '\0' || cur == '%') { break; } else if (cur == 'c' || cur == 'd' || cur == 'u' || cur == 'x' || cur == 'f' || cur == 's') { m_fmt_type.type = cur; m_fmt_type.min_len = ::atoi(m_fmt + cur_format_index + 1); cur_format_index = cur_format_index + i + 1; if (next == '0') { m_fmt_type.fill_char = next; } return true; } else if (cur == 'l') { char c_num = m_fmt[cur_format_index + i + 1]; if ('d' == c_num || 'u' == c_num) { m_fmt_type.type = c_num; m_fmt_type.min_len = ::atoi(m_fmt + cur_format_index + 1); cur_format_index = cur_format_index + i + 2; if (next == '0') { m_fmt_type.fill_char = next; } return true; } } } m_result += tmp; } return false; }
配置
最基本的log_service_t的start接口提供了初始化日志組件時的配置，配置參數:
enum log_level_e { LOG_FATAL = 0, LOG_ERROR, LOG_WARN, LOG_INFO, LOG_TRACE, LOG_DEBUG, LOG_LEVEL_NUM };
- l -log_level 配置日志級別，0-5代表不同的日志級別，枚舉定義如下：
- l -log_path 配置日志文件存儲的根目錄
- l -log_filename 配置文件名稱
- l -log_print_file" 配置日志是否輸出到文件
- l log_print_screen 配置日志是否輸出到屏幕
- l - log_class 配置哪些日志類別是開啟的，只有 開啟的類別日志才會被記錄
這其中除了log_path和log_filename不需要運行期配置外，其他的配置都有運行期修改的需求，比如運行期某個類別的日志被關閉了，但是為了跟蹤某問題必須開啟，如果不能動態修改日志配置往往會是開發人員面對問題時束手無策。對於-log_print_file 和-log_print_screen 都是用bool記錄的，-log_level 是整型記錄的，都是直接支持運行期修改的。有的讀者可能指出日志不是有單獨線程嗎，而且使用線程組件的用戶層也可能是多線程的，不就設計到了多線程競爭了嗎？在明白此答案之前，先讓我們縷一縷log中的結構：
- l 日志的接口會被多線程調用
- l 異步日志接口會訪問日志的配置，判斷該日志類別或級別是否已開啟，由於只有讀取操作，不需要加鎖。
- l 日志格式化后投遞到隊列，隊列是線程安全的，只有日志線程會從任務隊列中消費任務。
- l 運行修改日志配置的操作會投遞到日志線程完成，保證任一時刻只有一個線程修改日志配置
對於-log_print_file 、-log_print_screen 和-log_level 都是多線程讀取訪問，某一時刻一個線程修改，並且三者都是基本類型的，不存在內存地址變化的問題，這樣日志線程修改后會立即生效。但是對於-log_class，被開啟的日志類別都被保存到set<string> 的結構中，多線程對其執行find操作是安全的，這個stl的多線程特性是明確支持的。但是若對set<string> 在運行期執行insert或erase后會使set<string>中的迭代器失效，被壞的情況是會引起讀操作的線程崩潰，所以在運行期絕對不能對老的日志類別容器進行修改。難道日志類別就沒辦法運行期修改了嗎？腦筋急轉彎一下，既然不能修改老的，為什么不創建一個新的，然后用新的替換老的？為了使用這個方法，需要一些小技巧：
l 使用一個指針引用當前日志級別的容器，度線程總是獲取該指針，然后執行find操作find_class_name 根據類別字符串去容器中查找是否存在。這里使用了原子操作ATOMIC_FETCH，在gcc的環境下可以把它定義為：
#define ATOMIC_FETCH(src_ptr) __sync_add_and_fetch(src_ptr, 0) typedef set<string> str_set_t; typedef vector<str_set_t*> ptr_vt_t; str_set_t* m_enable_class_set; const char* log_t::find_class_name(const char* class_) { str_set_t* pset = ATOMIC_FETCH(&m_enable_class_set); str_set_t::iterator it = pset->find(class_); if (it != pset->end()) { return (*it).c_str(); } return NULL; }
l find_class_name對於存儲日志類別的容器指針使用了原子操作，所以要保證指針對應的數據永遠不被修改，即使有新的配置產生時，老的配置仍然不會被銷毀，利用數據冗余保證無鎖操作的線程安全，最后將新配置容器的指針替換老配置的指針即可，同樣使用原子操作完成
#define ATOMIC_SET(src_ptr, v) (void)__sync_bool_compare_and_swap(src_ptr, *(src_ptr), v) void log_t::mod_class(const string& class_, bool flag_) { str_set_t* pset = new str_set_t(m_enable_class_set->begin(), m_enable_class_set->end()); if (flag_) { pset->insert(class_); } else { pset->erase(class_); } m_class_set_history.push_back(pset); ATOMIC_SET(&m_enable_class_set, pset); }
總結以上無鎖編程的技巧有：
l 對於stl的對象的多線程讀操作是安全的
l 對於指針可以使用原子操作進行讀取、更新、比較等操作
l 老的容器被保存而不是銷毀，從而保證了獲取了老數據的線程仍然能夠工作正常，日志的類別字符串只有十幾頂多幾十個，這里做數據冗余的內存開銷是可以忽略的。
使用
日志的異步接口是由log_service_t定義的，前邊介紹log_service_t的時候也提到了log_service_t一般是被單件使用的，如果每次調用singleton_t<log_service_t>::instance().async_logdebug(“XX”, “OhNice”);代碼太長了，使用宏封裝單件的操作：
#define LOG singleton_t<log_service_t>::instance() #define LOGDEBUG(content) singleton_t<log_service_t>::instance().async_logdebug content #define LOGTRACE(content) singleton_t<log_service_t>::instance().async_logtrace content #define LOGINFO(content) singleton_t<log_service_t>::instance().async_loginfo content #define LOGWARN(content) singleton_t<log_service_t>::instance().async_logwarn content #define LOGERROR(content) singleton_t<log_service_t>::instance().async_logerror content #define LOGFATAL(content) singleton_t<log_service_t>::instance().async_logfatal content
使用宏的好處是，比如logtrace可能會被到處使用了，而有可能其只在調試器有用，那么在release版本時候可以把宏LOGTRACE定義成空操作，當然若日志級別不開啟的情況下，調用LOGTRACE的開銷是很小的，一般情況可以忽略其影響。
使用示例：
int main(int argc, char* argv[]) { LOG.start("-log_path ./log -log_filename log -log_class FF,XX -log_print_screen true -log_print_file true -log_level 6"); LOGDEBUG(("XX", "FFFFF")); LOGTRACE(("XX", "FFFFF")); LOGINFO(("XX", "FFFFF")); LOGWARN(("XX", "FFFFF")); LOGERROR(("XX", "FFFFF")); LOGFATAL(("XX", "FFFFF")); LOG.mod_class("TT", true); sleep(1); LOGFATAL(("TT", "FFFFF")); LOGFATAL(("FF", "DSDFFFFF%s", string("SFWEGGGGGGGGG"))); LOG.stop(); return 0; }
總結：
- l 日志組件需要盡可能的快從而對於調用者的影響降到最低，使用異步接口可以使日志接口調用后立即返回
- l 日志的文件組織需要較好的被分類，目錄首先按照時間分類，每天生成一個目錄存儲當天的日志，並且日志文件對大小做了上限，超過限制會重新創建新的文件，保證單個日志文件不會過大
- l 日志組件被設計成printf的格式化風格，但是增加了類型安全和參數糾錯，不支持的類型會在編譯期發現，值參數數目過多會被追加到字符串尾部，過少則忽略相應的%。
- l 日志組件是線程安全的，對於日志的配置雖然是多線程無鎖訪問的，仍然支持運行期動態的修改配置，其中使用了原子操作既保證了無鎖編程的高效，又滿足了多線程的穩定。
- 源碼：https://github.com/fanchy/fflib