Implementing dprintf() without __VA_ARGS_

在這篇《Implementing dprintf() with __VA_ARGS__》裡，簡介了如何利用 __VA_ARGS__ 做出好用的 dprintf()，以協助我們僅在測試版裡傾印偵錯訊息。然而，某些老舊但仍然十分活躍的 compilers，如 VC6，並沒有支援 __VA_ARGS__。因為通常來說，為了照顧既有的大量程式，以及一些政治問題，更換 compiler 有時是不可能的。所以我們最好還是來想想，怎樣在不支援 __VA_ARGS__ 的情況下，仍然將 dprintf() 實作出來。

仔細檢視 dprintf_v2() 與 dprintf_v3() 在 #define 時的差別，我們會發現，dprintf_v2() 其實並不是一個真正的 function-like macro，而僅僅只是把 dprintf_v2 這個「名字」給代換成 dprintf_v2_impl。於是，原本跟在後面，屬於 dprintf_v2 的參數，經過 preprocessor 處理之後，變成了跟在 dprintf_v2_impl 的後面。這樣的作法，除了之前提過的，在釋出版裡，剩下來的參數列，不一定有辦法被最佳化去掉之外，還有一個更大的問題就是，沒有辦法於呼叫 dprintf_v2() 時省略 __FILE__ 和 __LINE__，自動於轉換成呼叫 dprintf_v2_impl() 時加上這兩個參數。

也就是說，透過 __VA_ARGS__ 的幫助，我們就可以在 function-like macro 裡，利用 ... 與 __VA_ARGS__，更精細地控制參數的對應關係。相反地，若是在沒有 __VA_ARGS__ 的情況下，我們就只能做到 function 名字的代換，呼叫的參數列，必須原汁原味，無法更動。然而，我們卻希望，能夠自動嵌入 __FILE__ 與 __LINE__ 兩個參數，而這就是不支援 __VA_ARGS__ 所產生的最大問題。

因此，如果我們能夠找到某種方法，不利用 __VA_ARGS__，「夾帶」__FILE__ 與 __LINE__ 使得真正印訊息得函式本體，能夠得到這兩個參數的話，我們就可以避掉這個問題。

使用 C++ 物件承載 __FILE__ 與 __LINE__ 資訊：dprintf_v4.cpp

第一個竄入腦袋裡的解法是，利用 C++ 的物件，承裝 __FILE__ 與 __LINE__ 等額外的資訊。也就是說，利用函數物件 (function object，或稱 functor) 來實作，這一招在 C++ 是很常見的手法。如下：

#include <cstdio>
#include <cstdarg>

class dprintf_v4_impl
{
public:
    dprintf_v4_impl(const char* src_file, size_t src_line)
        : src_file_(src_file)
        , src_line_(src_line)
    {
    }
    void operator()(bool enable, const char* fmt, ...) const
    {
        va_list ap;
        if (enable) {
            fprintf(stderr, "%s (%d): ", src_file_, src_line_);
            va_start(ap, fmt);
            vfprintf(stderr, fmt, ap);
            va_end(ap);
            fprintf(stderr, "\n");
            fflush(stderr);
        }
    }
private:
    const char* src_file_;
    size_t      src_line_;
};

#ifndef NDEBUG
#   define dprintf_v4 dprintf_v4_impl(__FILE__, __LINE__)
#else
#   define dprintf_v4
#endif

int main()
{
    int enable = 1;
    int i = 3;
    dprintf_v4(enable, "i == %d", i);
    return 0;
}

// OUTPUT:
// dprintf_v4.cpp (39): i == 3

首先，dprintf_v4 這個函數名稱，會被代換成 dprintf_v4_impl(__FILE__, __LINE__)，實際上 dprintf_v4_impl 是個 class，所以這會產生一個暫時物件，同時把 __FILE__ 與 __LINE__ 存在暫時物件裡。因為 dprintf_v4_impl 不僅僅只是一個普通的物件，而更是一個 functor，所以在暫時物件 dprintf_v4_impl(__FILE__, __LINE__) 後面還可以再接上括弧與裡面的參數。

也就是說，main() 裡呼叫的 dprintf_v4()，在經過 preprocessing 處理後，就會變成：

   dprintf_v4_impl(__FILE__, __LINE__)(enable, "i == %d", i);
// |---------暫時存在的函式物件--------||--呼叫 operator()()--|

於是 void operator()(bool enable, const char* fmt, ...) 這個 member function 被呼叫，而裡面就是原本 dprintf_v3_impl() 的內容^[1]。

當然，我們也可以不要 overload operator()，而是用如 print() 這樣的成員函式名稱，就變成是 #define dprintf_v4 dprintf_v4(__FILE__, __LINE__).print。不過，這樣就不屌了，哈。

2008-03-12 更新：剛剛看到的，這篇《Getting around the need for a vararg #define just to automatically use __FILE__ and __LINE__ in a TRACE macro》也提出了同樣的技術。

承載 __FILE__ 與 __LINE__ 資訊後回傳 function pointer：dprintf_v5.c

然而，dprintf_v4.cpp 使用 functor 的招式，是 C++ only，沒有辦法在 C 裡面使用。在 C 裡，沒有「物件」這種東西，所以就不會有「隱藏的 this 指標^[2]」，幫助我們將 __FILE__ 與 __LINE__ 資訊，「運送」到最終印出的程式片段。因此，我們必須要想別的辦法，來傳送 __FILE__ 與 __LINE__ 這兩個參數。

順著 functor 的思路，我們可以找到 functor 在 C 裡的對應：function pointer。如果我們先執行一個 function，將 __FILE__ 與 __LINE__ 存在「某個地方」，然後這個 function 回傳一個 function pointer，經 preprocessor 代換之後，這個 function pointer 會接上 dprintf 的參數串執行之，此時再將 __FILE__ 與 __LINE__ 取回來。這樣一來，就可以做到「不經過參數列的資訊傳送」。程式寫出來大致如下：

#include <stdio.h>
#include <stdarg.h>

typedef void (*dprintf_v5_fn)(int enable, const char* fmt, ...);

struct file_line_t
{
    const char* file;
    size_t      line;
};
// Global for transporting __FILE__ and __LINE__.
static struct file_line_t g_file_line;

void dprintf_v5_impl(int enable, const char* fmt, ...)
{
    va_list ap;
    if (enable) {
        fprintf(stderr, "%s (%d): ", g_file_line.file, g_file_line.line);
        va_start(ap, fmt);
        vfprintf(stderr, fmt, ap);
        va_end(ap);
        fprintf(stderr, "\n");
        fflush(stderr);
    }
}

dprintf_v5_fn dprintf_v5_front(const char* src_file, size_t src_line)
{
    g_file_line.file = src_file;
    g_file_line.line = src_line;
    return &dprintf_v5_impl;
}

#ifndef NDEBUG
#   define dprintf_v5 (*dprintf_v5_front(__FILE__, __LINE__))
#else
#   define dprintf_v5
#endif

int main()
{
    int enable = 1;
    int i = 3;
    dprintf_v5(enable, "i == %d", i);
    return 0;
}

// OUTPUT:
// dprintf_v5.c (44): i == 3

首先，我們把 dprintf_v5 給 #define 成 (*dprintf_v5_front(__FILE__, __LINE__))，當展開 dprintf_v5 時，會先呼叫 dprintf_v5_front() 把 __FILE__ 與 __LINE__ 存在某個地方，然後 dprintf_v5_front() 會回傳一個指向 dprintf_v5_impl() 的 function pointer。接著，呼叫這個 function pointer 所指到的函式，也就是 dprintf_v5_impl()，dprintf_v5_impl() 會將之前存著的 __FILE__ 與 __LINE__ 取出，最後將訊息頃印出來。

很不幸地，這裡所謂的「某個地方」，是一個全域變數 g_file_line 變數，這也意味著，這樣的寫法，是 non-thread-safe 的。

加上 sleep 以驗證共用錯誤：dprintf_v5mt.c

舉例來說，若 thread1 執行到了 dprintf_v5_front()，把 thread1.c 與 314 存進了 g_file_line，在 thread1 還沒有執行 dprintf_v5_impl() 之前，thread2 也執行到了 dprintf_v5_front()，把 g_file_line 改成了 thread2.c 與 749，然後又切回 thread1 執行 dprintf_v5_impl()，此時就會印出錯誤的 file/line 資訊。且看以下的範例：

#include <stddef.h>
#include <stdio.h>
#include <time.h>
#include <stdarg.h>
#include <pthread.h>

#define ENTER_FUNCTION()                              \
    fprintf(stderr, "thread#%d: %s(): entering...\n", \
            pthread_self(), __FUNCTION__);            \
    /**/

/** Sleep @p s seconds for current thread. */
void thread_sleep(size_t s)
{
    fprintf(stderr, "thread#%d: sleep for %d seconds...\n", pthread_self(), s);
    struct timespec ts = {0}; // reset to all zero
    ts.tv_sec = s;
    nanosleep(&ts, 0);
}

typedef void (*dprintf_v5mt_fn)(int enable, const char* fmt, ...);

struct file_line_t
{
    const char* file;
    size_t      line;
};

static struct file_line_t g_file_line;

void dprintf_v5mt_impl(int enable, const char* fmt, ...)
{
    ENTER_FUNCTION();
    va_list ap;
    if (enable) {
        fprintf(stderr, "thread#%d: %s (%d): ",
                pthread_self(), g_file_line.file, g_file_line.line);
        va_start(ap, fmt);
        vfprintf(stderr, fmt, ap);
        va_end(ap);
        fprintf(stderr, "\n");
        fflush(stderr);
    }
}

dprintf_v5mt_fn dprintf_v5mt_front(const char* src_file, size_t src_line)
{
    ENTER_FUNCTION();
    g_file_line.file = src_file;
    g_file_line.line = src_line;
    thread_sleep(2);
    return &dprintf_v5mt_impl;
}

#ifndef NDEBUG
#   define dprintf_v5mt (*dprintf_v5mt_front(__FILE__, __LINE__))
#else
#   define dprintf_v5mt
#endif

int g_enable = 1;
int g_data   = 3;

void* main_thread(void* param)
{
    ENTER_FUNCTION();
    thread_sleep(1);
    dprintf_v5mt(g_enable, "g_data == %d", g_data); // line 64
    return 0;
}

void* other_thread(void* param)
{
    ENTER_FUNCTION();
    thread_sleep(2);
    dprintf_v5mt(g_enable, "g_data == %d", g_data); // line 72
    return 0;
}

int main()
{
    pthread_t other_thr;
    pthread_create(&other_thr, NULL, other_thread, NULL);
    main_thread(0);
    pthread_join(other_thr, NULL);
    return 0;
}

// OUTPUT:
// thread#134557696: main_thread(): entering...
// thread#134558720: other_thread(): entering...
// thread#134557696: sleep for 1 seconds...
// thread#134558720: sleep for 2 seconds...
// thread#134557696: dprintf_v5mt_front(): entering...
// thread#134557696: sleep for 2 seconds...
// thread#134558720: dprintf_v5mt_front(): entering...
// thread#134558720: sleep for 2 seconds...
// thread#134557696: dprintf_v5mt_impl(): entering...
// thread#134557696: dprintf_v5mt.c (72): g_data == 3
// thread#134558720: dprintf_v5mt_impl(): entering...
// thread#134558720: dprintf_v5mt.c (72): g_data == 3

為了追蹤是哪個 thread 在做事，所以這個範例裡的每一行程式，特地在前面多印出 thread id^[3]，thread#134557697 是 main_thread()，於第 64 行呼叫 dprintf_v5mt()，而 thread#134558720 是 other_thread()，於第 72 行呼叫 dprintf_v5mt()。利用故意加入的 thread_sleep()，從 output 我們看到，thread#134557697 先進入 dprintf_v5mt_front()，此時 g_file_line.line 應該是 64^[4]。然而，在還沒進入 dprintf_v5mt_impl() 之前，另外一個 thread#134558720 也進入了 dprintf_v5mt_front()，因此 g_file_line.line 被改掉了，所以最後印出來的行號，thread#134557696 與 thread#134558720 都顯示成 72，而前者其實是錯的。

使用 mutex 保護 __FILE__ 與 __LINE__ 資訊：dprintf_v6mt.c

為了解決這種共用的問題，理所當然的，要用 mutex 這種東西來保護共用資訊。既然標題裡提到了 VC6，但前面一直用 pthread 當範例，這樣文不對題，是不對的行為。所以，在加入 mutex 機制的同時，我們一併讓程式可以跨 win32/pthread：

#include <stddef.h>
#include <stdio.h>
#include <time.h>
#include <stdarg.h>
#if defined(WIN32)
#   include <windows.h>
#else /* !defined(WIN32) */
#   include <pthread.h>
#endif /* defined(WIN32) */

#if defined(WIN32)
#   define thread_id() GetCurrentThreadId()
#else /* !defined(WIN32) */
#   define thread_id() pthread_self()
#endif /* defined(WIN32) */

#define ENTER_FUNCTION() fprintf(stderr, "thread#%d: %s(): entering...\n", thread_id(), __FUNCTION__);

/** Sleep @p s seconds for current thread. */
void thread_sleep(size_t s)
{
    fprintf(stderr, "thread#%d: sleep for %d seconds...\n", thread_id(), s);
    struct timespec ts = {0};
    ts.tv_sec = s;
    nanosleep(&ts, 0);
}

/** Define mutex type according to current platform. */
#if defined(WIN32)
typedef CRITICAL_SECTION mutex_t;
#else /* !defined(WIN32) */
typedef pthread_mutex_t mutex_t;
#endif /* defined(WIN32) */

/** Initialize mutex object */
void mutex_init(mutex_t* mx)
{
#if defined(WIN32)
    InitializeCriticalSection(mx);
#else /* !defined(WIN32) */
    pthread_mutex_init(mx, NULL);
#endif /* defined(WIN32) */
}

/** Destroy mutex object */
void mutex_destroy(mutex_t* mx)
{
#if defined(WIN32)
    DeleteCriticalSection(mx);
#else /* !defined(WIN32) */
    pthread_mutex_destroy(mx);
#endif /* defined(WIN32) */
}

/** Lock mutex object */
void mutex_lock(mutex_t* mx)
{
#if defined(WIN32)
    EnterCriticalSection(mx);
#else /* !defined(WIN32) */
    pthread_mutex_lock(mx);
#endif /* defined(WIN32) */
}

/** Unlock mutex object */
void mutex_unlock(mutex_t* mx)
{
#if defined(WIN32)
    LeaveCriticalSection(mx);
#else /* !defined(WIN32) */
    pthread_mutex_unlock(mx);
#endif /* defined(WIN32) */
}

typedef void (*dprintf_v6mt_fn)(int enable, const char* fmt, ...);

struct file_line_t
{
    const char* file;
    size_t      line;
};

static struct file_line_t g_file_line;
static mutex_t            g_file_line_mutex; // to protect g_file_line

void dprintf_v6mt_impl(int enable, const char* fmt, ...)
{
    ENTER_FUNCTION();
    va_list ap;
    if (enable) {
        fprintf(stderr, "thread#%d: %s (%d): ", thread_id(), g_file_line.file, g_file_line.line);
        va_start(ap, fmt);
        vfprintf(stderr, fmt, ap);
        va_end(ap);
        fprintf(stderr, "\n");
        fflush(stderr);
    }
    mutex_unlock(&g_file_line_mutex);
}

dprintf_v6mt_fn dprintf_v6mt_front(const char* src_file, size_t src_line)
{
    mutex_lock(&g_file_line_mutex);
    ENTER_FUNCTION();
    g_file_line.file = src_file;
    g_file_line.line = src_line;
    thread_sleep(2);
    return &dprintf_v6mt_impl;
}

#ifndef NDEBUG
#   define dprintf_v6mt (*dprintf_v6mt_front(__FILE__, __LINE__))
#else
#   define dprintf_v6mt
#endif

int g_enable = 1;
int g_data   = 3;

void* main_thread(void* param)
{
    ENTER_FUNCTION();
    thread_sleep(1);
    dprintf_v6mt(g_enable, "g_data == %d", g_data); // line 124
    return 0;
}

void* other_thread(void* param)
{
    ENTER_FUNCTION();
    thread_sleep(2);
    dprintf_v6mt(g_enable, "g_data == %d", g_data); // line 132
    return 0;
}

int main()
{
    mutex_init(&g_file_line_mutex);

    pthread_t other_thr;
    pthread_create(&other_thr, NULL, other_thread, NULL);
    main_thread(0);
    pthread_join(other_thr, NULL);

    mutex_destroy(&g_file_line_mutex);
    return 0;
}

// OUTPUT:
// thread#134557696: main_thread(): entering...
// thread#134557696: sleep for 1 seconds...
// thread#134558720: other_thread(): entering...
// thread#134558720: sleep for 2 seconds...
// thread#134557696: dprintf_v6mt_front(): entering...
// thread#134557696: sleep for 2 seconds...
// thread#134557696: dprintf_v6mt_impl(): entering...
// thread#134557696: dprintf_v6mt.c (124): g_data == 3
// thread#134558720: dprintf_v6mt_front(): entering...
// thread#134558720: sleep for 2 seconds...
// thread#134558720: dprintf_v6mt_impl(): entering...
// thread#134558720: dprintf_v6mt.c (132): g_data == 3

從程式的 output 我們可以看出，other_thread() 對 dprintf_v6mt() 的呼叫，被延遲了，所以 dprintf_v6mt_front() 一直到 main_thread() 的 dprintf_v6mt_impl() 把除錯訊息印出來之後，才被 other_thread() 執行，所以最後兩個 threads 所印出的程式碼行號，都是正確的。

然而我們也可以感覺得到，整體程式的執行時間變長了，這是因為瓶頸在 g_file_line_mutex，若同時有很多個 thread 都要 lock 這個 mutex，大家就會鎖在這邊，造成效率的低落。當然，範例裡因為故意加入了 thread_sleep()，所以效率的低落特別明顯，實際上在跑的時候，不會有 thread_sleep()，所以對效率的影響，其實很小。由於測試版我們在乎的通常不是效率，因此這點 overhead，是可以被接受的。

C++ 之好，C 難以承受

基本上來說，dprintf_v6mt.c 已經是很好的解法了，然而，我們總是要盡量使用 C++ 的優點的，不是嗎？:-p

為了讓 OS 提供的 thread 相關 API 更好用一些，一般我們會將 API 再包裝過，提供一些更安全、易於管理的機制，組織成一套好用的 thread library。這裡所謂的「OS 提供的 API」，指的是 pthread 與 Win32 SDK 裡如 CreateThread()、_beginthreadex() 之類的函式。這個 thread library，可能有下面四種實作方式：

Implemented in C only, no extra C++ API.
Implemented in C++ only, no extra C API.
Implemented in C, with extra thin C++ wrappers.
Implemented in C++, with extra thin C wrappers.

為了要讓這個 thread library 能夠給純 C 使用，又能夠有 C++ 的 syntax candies^[5]，前兩者基本上我們不考慮。

首先，就「Implemented in C, with extra thin C++ wrappers」這個部分，可能作法如下(基於 dprintf_v6mt.c，跨平台部分先忽略)：

typedef CRITICAL_SECTION mutex_t;

void mutex_init(mutex_t* mx)    { InitializeCriticalSection(mx); }
void mutex_destroy(mutex_t* mx) { DeleteCriticalSection(mx);     }
void mutex_lock(mutex_t* mx)    { EnterCriticalSection(mx);      }
void mutex_unlock(mutex_t* mx)  { LeaveCriticalSection(mx);      }

/** Thin C++ wrappers for extra C++ syntax candies. */
class mutex
{
friend class mutex::guard; // let mutex::guard call lock/unlock().
public:

    class guard
    {
    public:

        guard(mutex& mx) : mx_(mx) { mx_.lock();   }
        ~guard()                   { mx_.unlock(); }

    private:

        mutex_& mx_; // reference to remember which mutex we locked.

    };

    mutex()  { mutex_init(&mx_);    }
    ~mutex() { mutex_destroy(&mx_); }

private:

    void lock()   { mutex_lock(&mx_);   }
    void unlock() { mutex_unlock(&mx_); }

    mutex_t mx_;

};

在這個例子裡，class mutex 實際上並沒有真正做事，而是轉而呼叫 C 版的函式^[6]。不過，善用 C++ 的 RAII 的技巧可以讓程式更安全，我們將 lock() 與 unlock() 藏在了 class mutex 的 private 區塊裡，然後額外提供了 class mutex::guard，用起來像這個樣子：

class account { ... };

static map<string /* name */, account*> g_accounts;       // global account table
static mutex                            g_accounts_mutex; // protect g_accounts.

void create_account(const char* name)
{
    mutex::guard lock(g_accounts_mutex);
    g_accounts.insert(make_pair(string(name), new account(name)));
}

如 pthread 就是典型的 C 介面，而 Boost.Thread，則是典型的 C++ 介面，前者容易成為跨系統通用的 API，後者則能善用 C++ 的好。一般而言，我們會希望使用功能更為強大，使用起來更不容易出錯的 C++ 介面版。

然而，mutex::guard 這個招式，卻是沒有辦法應用在 dprintf_v6mt 上的。因為，mutex::guard 利用 constructor/destructor 執行 lock/unlock，雖然方便，但也限制住了 mutex::guard 的效果只及於同一個 block 中。然而，dprintf_v6mt 卻需要在 dprintf_v6mt_front() 裡 lock，在 dprintf_v6mt_impl() 裡 unlock，不在同一個 block 裡。是故，C++ 的好，在這個情境下，沒辦法給 C 介面的 function 使用。

因此，如果我們選擇使用「Implemented in C, with extra thin C++ wrappers」的方式實作 thread library，在這裡就無法使用好用的 C++ wrappers，只能直接使用 C implementation；而如果我們選擇使用「Implemented in C++, with extra thin C wrappers」的方式實作，就必須改呼叫 thin C wrappers。

不過，就如同之前於《Race condition in C wrapper of mutex class》一文中探討過的，想要擁有 C/C++ 雙介面，有時候問題會更多。因此，最終我的選擇會是，直接使用 C++ 實作 thread library，拋棄容易出問題的 C 介面。但也因為如此，我們就無法使用這個包好的 C++ thread library，必須直接在 dprintf_v6mt 裡呼叫底層 OS 提供的 C APIs，並針對跨平台的需求，包出一組又一組，醜陋的 #ifdef，而這本來是該交由 thread library 解決的事。

避免使用 mutex 造成不必要的效能瓶頸：dprintf_v7mt.cpp

在 dprintf_v6mt.cpp 這個版本裡，我們使用了 mutex 以確保暫時放在全域變數的 __FILE__ 和 __LINE__ 不會因為 race condition 而被其他 thread 改掉。這個作法其實不是那麼地完美，因為 __FILE__ 與 __LINE__ 根本就是自己這個 thread 的資料，與其他 thread 沒有關係，也就是說，不是共享的資料。但不需要共享的資料，卻因為語言機制的缺乏，而不得不放在「大家一起用的空間(全域變數)」，所以導致必須額外付出一個 mutex 的成本，當程式一複雜，總 thread 數一多起來的時候，大家就都會擁塞在這個 mutex 上，對效率影響甚巨。

所以，要改進 dprintf_v6mt.cpp，我們就需要把 thread specific 的資料，改放到 thread 專屬不與其他 thread 共享的空間，這樣一來，就不需要用 mutex 鎖住共享空間，繼而造成效能瓶頸。對於一個 thread 來說，屬於 thread 所獨有的空間，除了 stack 之外，就剩 thread local storage (TLS)，又稱 thread specific data，前者是 Windows programming 的術語，後者是 pthread 的說法。使用 TLS 的方法，也是大同小異，基本上都是這四個介面：

步驟	Win32	Pthread
Allocate TLS space and obtain a key to access it	`TlsAlloc()`	`pthread_key_create()`
Set value to the space with the key	`TlsSetValue()`	`pthread_setspecific()`
Get value from the space with the key	`TlsGetValue()`	`pthread_getspecific()`
Deallocate TLS space with the key	`TlsFree()`	`pthread_key_delete()`

TLS 的使用有一些要注意的地方，尤其是考慮到跨平台的需求。這部份容後再專文介紹^[7]。在這裡我們就先使用 pthread 來實作：

#include <stddef.h>
#include <stdio.h>
#include <time.h>
#include <stdarg.h>
#include <stdlib.h>
#include <pthread.h>

#define ENTER_FUNCTION()                              \
    fprintf(stderr, "thread#%d: %s(): entering...\n", \
            pthread_self(), __FUNCTION__);            \
    /**/

/** Sleep @p s seconds for current thread. */
void thread_sleep(size_t s)
{
    fprintf(stderr, "thread#%d: sleep for %d seconds...\n",
            pthread_self(), s);
    struct timespec ts = {0};
    ts.tv_sec = s;
    nanosleep(&ts, 0);
}

typedef void (*dprintf_v7mt_fn)(int enable, const char* fmt, ...);

#ifndef __cplusplus
typedef struct file_line_t file_line_t;
#endif
struct file_line_t
{
    const char* file;
    size_t      line;
};

void free_file_line(void* value)
{
    file_line_t* fl = (file_line_t*)value;
    free(fl);
}

pthread_key_t g_file_line_key;

void dprintf_v7mt_impl(int enable, const char* fmt, ...)
{
    ENTER_FUNCTION();
    va_list ap;
    if (enable) {
        file_line_t* fl = (file_line_t*)pthread_getspecific(g_file_line_key);
        fprintf(stderr, "thread#%d: %s (%d): ",
                pthread_self(), fl->file, fl->line);
        va_start(ap, fmt);
        vfprintf(stderr, fmt, ap);
        va_end(ap);
        fprintf(stderr, "\n");
        fflush(stderr);
    }
}

dprintf_v7mt_fn dprintf_v7mt_front(const char* src_file, size_t src_line)
{
    ENTER_FUNCTION();
    file_line_t* fl = (file_line_t*)pthread_getspecific(g_file_line_key);
    if (fl == NULL) {
        fl = (file_line_t*)malloc(sizeof(file_line_t));
        pthread_setspecific(g_file_line_key, (void*)fl);
    }
    fl->file = src_file;
    fl->line = src_line;
    thread_sleep(2);
    return &dprintf_v7mt_impl;
}

#ifndef NDEBUG
#   define dprintf_v7mt (*dprintf_v7mt_front(__FILE__, __LINE__))
#else
#   define dprintf_v7mt
#endif

int g_enable = 1;
int g_data   = 3;

void* main_thread(void* param)
{
    ENTER_FUNCTION();
    thread_sleep(1);
    dprintf_v7mt(g_enable, "g_data == %d", g_data); // line 124
    return 0;
}

void* other_thread(void* param)
{
    ENTER_FUNCTION();
    thread_sleep(2);
    dprintf_v7mt(g_enable, "g_data == %d", g_data); // line 132
    return 0;
}

int main()
{
    pthread_key_create(&g_file_line_key, &free_file_line);

    pthread_t other_thr;
    pthread_create(&other_thr, NULL, other_thread, NULL);
    main_thread(0);
    pthread_join(other_thr, NULL);

    pthread_key_delete(g_file_line_key);

    return 0;
}

// OUTPUT:
// thread#134557696: main_thread(): entering...
// thread#134557696: sleep for 1 seconds...
// thread#134558720: other_thread(): entering...
// thread#134558720: sleep for 2 seconds...
// thread#134557696: dprintf_v7mt_front(): entering...
// thread#134557696: sleep for 2 seconds...
// thread#134558720: dprintf_v7mt_front(): entering...
// thread#134558720: sleep for 2 seconds...
// thread#134557696: dprintf_v7mt_impl(): entering...
// thread#134557696: dprintf_v7mt.c (85): g_data == 3
// thread#134558720: dprintf_v7mt_impl(): entering...
// thread#134558720: dprintf_v7mt.c (93): g_data == 3

首先，我們先建立一個 TLS 的 key，叫做 g_file_line_key，在 dprintf_v7mt_front() 裡面，將 __FILE__ 與 __LINE__ 存在一個 malloc 出來的資料結構 file_line_t 裡，然後把這個資料結構的位址，存在 g_file_line_key 所代表的 TLS 空間裡。接著，在 dprintf_v7mt_impl() 裡，自 TLS 裡取出指向 file_line_t 結構的指標，得到當初存起來的 __FILE__ 與 __LINE__ 的值，印出。

因為當初在建立 g_file_line_key 時，已經指定使用 free_file_line() 銷毀存在 TLS 裡的值，所以我們可以不必顧慮該如何釋放 file_line_t 結構所佔用的空間。當 g_file_line_key 所對應的值改變，或 g_file_line_key 要被銷毀時，或是 thread 結束時，free_file_line() 都會被呼叫。所以，我們只需要在 dprintf_v7mt_front() 裡面檢查 g_file_line_key 所對應的是不是 NULL，如果事的話，表示這個 thread 尚未建立 file_line_t 結構，便 malloc() 之。這樣一來，就可以整個 thread 只在第一次時為 file_line_t 結構配置記憶體，然後從頭用到尾。

由於是利用 TLS 承載 __FILE__ 與 __LINE__ 資訊，縱使 g_file_line_key 是全域變數，但每個 thread 都會有自己的一份 file_line_t 結構，故 __FILE__ 與 __LINE__ 資訊，並非是所有 threads 共享，故可以避免使用 mutex，繼而避免效能的損失。

把所有東西組裝起來：dprintf.cpp

至此，所有技術上的問題，大致都已經解決了，該取捨的部份，也都做出了選擇。接下來，我們就可以把上面提到的所有技術，整合成一個完整的 dprintf() 實作。基本上，我們有以下幾個可用的版本，他們的優缺點分別如下：

使用 __VA_ARGS__：沒有 run-time overhead，但只有支援 C99 的編譯器可以用^[8]。
使用 C++ 物件：多了一個暫時物件，與 functor 的呼叫，但不會造成 multi-thread 執行的瓶頸。只能在 C++ 裡使用。
使用 mutex 與 function pointer：多呼叫一個 dprintf_front()，且因使用 mutex 而會造成 multi-thread 執行的瓶頸。不限 C++，C 也可以使用。
使用 TLS 與 function pointer：多呼叫一個 dprintf_front()，但因利用 TLS 故不會有 mutex 造成 multi-thread 執行的瓶頸，但理論上仍然會比使用 C++ 物件還要來得慢，端視 TLS 的實作而定。不限 C++，C 也可以使用。

基本上，我們可以使用 TLS 而拋棄 mutex 法。整個取捨的邏輯是：

if (支援 C99) {
    使用 __VA_ARGS__
} else {
    if (is C++) {
        使用 C++ 物件
    } else {
        使用 TLS 搭配 function pointer
    }
}

故，整套組裝起來的 dprintf 實作應為 (僅實作 pthread 版)：

用來輔助驗證的 thread_tool.h：

#ifndef THREAD_TOOL_H_INCLUDED
#define THREAD_TOOL_H_INCLUDED

#include <stdio.h>
#include <stddef.h>

#if defined(__cplusplus)
extern "C" {
#endif

#define ENTER_FUNCTION()                              \
    fprintf(stderr, "thread#%d: %s(): entering...\n", \
            pthread_self(), __FUNCTION__);            \
    /**/

/** Sleep @p s seconds for current thread. */
void thread_sleep(size_t s);

#if defined(__cplusplus)
} // extern "C"
#endif

#endif /* THREAD_TOOL_H_INCLUDED */

與其實作 thread_tool.c，實際上線的系統，不需要用到這裡面的東西：

#include "thread_tool.h"
#include <stdio.h>
#include <pthread.h>

void thread_sleep(size_t s)
{
    fprintf(stderr, "thread#%d: sleep for %d seconds...\n",
            pthread_self(), s);
    struct timespec ts = {0};
    ts.tv_sec = s;
    nanosleep(&ts, 0);
}

我們將最終版本命名為 DPRINTF()，畢竟那是個 macro，全部大寫也有助於提示使用者，這個 macro 在 release 版可能會被 preprocessor 消滅掉。實作分兩部份，宣告放在 dprintf.h：

#ifndef DPRINTF_H_INCLUDED
#define DPRINTF_H_INCLUDED

#include <stddef.h>

#if defined(__cplusplus)
extern "C" {
#endif

void dprintf_c99(const char* src_file, size_t src_line,
                 int enable, const char* fmt, ...);

typedef void (*dprintf_fn)(int enable, const char* fmt, ...);

void dprintf_tls(int enable, const char* fmt, ...);
dprintf_fn dprintf_front(const char* src_file, size_t src_line);

#if defined(__cplusplus)
} // extern "C"
#endif

#if defined(__cplusplus)
class dprintf_cpp
{
public:
    dprintf_cpp(const char* src_file, size_t src_line);
    void operator()(bool enable, const char* fmt, ...) const;
private:
    const char* src_file_;
    size_t      src_line_;
};
#endif

#ifndef NDEBUG
#   if (__STDC_VERSION__ >= 199901L) // support C99
#       define DPRINTF(enable, ...) \
               dprintf_c99(__FILE__, __LINE__, enable, __VA_ARGS__)
#   else
#       if defined(__cplusplus) // is C++
#           define DPRINTF \
                   dprintf_cpp(__FILE__, __LINE__)
#       else
#           define DPRINTF \
                   (*dprintf_front(__FILE__, __LINE__))
        #endif
#   endif
#else
#   define DPRINTF(enable, ...) // define to nothing in release mode
#endif

#endif // DPRINTF_H_INCLUDED

實作放在 dprintf.cpp。由於使用者可能與三種實作的任何一種連結，故三種實作都必須放進產出的目的檔裡，不可以用 preprocessor 藏起來。因為其中一種實作使用 C++，故 dprintf.cpp 是個 C++ 原始碼檔案：

#include "dprintf.h"
#include "thread_tool.h"
#include <stdio.h>
#include <stdlib.h>
#include <stdarg.h>
#include <pthread.h>

static
void dprintf_impl(const char* src_file, size_t src_line,
                  int enable, const char* fmt, va_list ap)
{
    ENTER_FUNCTION();
    if (enable) {
        fprintf(stderr, "%s (%d): ", src_file, src_line);
        vfprintf(stderr, fmt, ap);
        fprintf(stderr, "\n");
        fflush(stderr);
    }
}

void dprintf_c99(const char* src_file, size_t src_line,
                 int enable, const char* fmt, ...)
{
    va_list ap;
    va_start(ap, fmt);
    dprintf_impl(src_file, src_line, enable, fmt, ap);
    va_end(ap);
}

dprintf_cpp::dprintf_cpp(const char* src_file, size_t src_line)
    : src_file_(src_file)
    , src_line_(src_line)
{
}

void dprintf_cpp::operator()(bool enable, const char* fmt, ...) const
{
    ENTER_FUNCTION();
    va_list ap;
    va_start(ap, fmt);
    dprintf_impl(src_file_, src_line_, enable, fmt, ap);
    va_end(ap);
}

struct file_line_t
{
    const char* file;
    size_t      line;
};

void free_file_line(void* value)
{
    ENTER_FUNCTION();
    file_line_t* fl = reinterpret_cast<file_line_t*>(value);
    if (fl) {
        free(fl);
    }
}

typedef void (*cleanup_fn)(void* value);

template <class T>
class TlsCell
{
public:

    TlsCell(cleanup_fn cleanup = 0)
    {
        pthread_key_create(&key_, cleanup);
    }

    ~TlsCell()
    {
        pthread_key_delete(key_);
    }

    void set(T* value)
    {
        pthread_setspecific(key_, reinterpret_cast<void*>(value));
    }

    T* get()
    {
        return reinterpret_cast<T*>(pthread_getspecific(key_));
    }

private:

    pthread_key_t key_;

};

TlsCell<file_line_t> g_file_line_tls(free_file_line);

void dprintf_tls(int enable, const char* fmt, ...)
{
    ENTER_FUNCTION();
    va_list ap;
    file_line_t* fl = g_file_line_tls.get();
    va_start(ap, fmt);
    dprintf_impl(fl->file, fl->line, enable, fmt, ap);
    va_end(ap);
}

dprintf_fn dprintf_front(const char* src_file, size_t src_line)
{
    ENTER_FUNCTION();
    file_line_t* fl = g_file_line_tls.get();
    if (fl == NULL) {
        fl = reinterpret_cast<file_line_t*>(malloc(sizeof(file_line_t)));
        g_file_line_tls.set(fl);
    }
    fl->file = src_file;
    fl->line = src_line;
    thread_sleep(2);
    return &dprintf_tls;
}

由於 TLS 的 key 需要事先 create，事後 delete，因此將這些動作用一個叫 TlsCell 的 template class 包裝起來，這樣就不需要讓使用者自行呼叫 pthread_key_create() 與 pthread_key_delete() 了。

為了測試 DPRINTF() 的效果，我們準備了這個測試程式標準版：

#include "dprintf.h"
#include "thread_tool.h"
#include <pthread.h>

int g_enable = 1;
int g_data   = 3;

void* main_thread(void* param)
{
    ENTER_FUNCTION();
    thread_sleep(1);
    DPRINTF(g_enable, "g_data == %d", g_data);
    return 0;
}

void* other_thread(void* param)
{
    ENTER_FUNCTION();
    thread_sleep(2);
    DPRINTF(g_enable, "g_data == %d", g_data);
    return 0;
}

int main()
{
    pthread_t other_thr;
    pthread_create(&other_thr, NULL, other_thread, NULL);
    main_thread(0);
    pthread_join(other_thr, NULL);

    return 0;
}

將這個標準版測試程式，內容不便，分別存成檔名不同的三個檔案：main_c99.c、main_cpp.cpp 與 main_tls.c。分別用不同的方法編譯出 main_c99、main_cpp 與 main_tls 三支測試程式：

編譯 main_c99 與執行結果：

SHELL> gcc -std=c99 -o main_c99.o -c main_c99.c
SHELL> g++ -o main_c99 main_c99.o thread_tool.o dprintf.o
SHELL> ./main_c99
thread#134557696: main_thread(): entering...
thread#134557696: sleep for 1 seconds...
thread#134558720: other_thread(): entering...
thread#134558720: sleep for 2 seconds...
thread#134557696: dprintf_impl(): entering...
main_c99.c (12): g_data == 3
thread#134558720: dprintf_impl(): entering...
main_c99.c (20): g_data == 3

編譯 main_cpp 與執行結果：

SHELL> g++ -o main_cpp.o -c main_cpp.cpp
SHELL> g++ -o main_cpp main_cpp.o thread_tool.o dprintf.o
SHELL> ./main_cpp
thread#134557696: main_thread(): entering...
thread#134557696: sleep for 1 seconds...
thread#134558720: other_thread(): entering...
thread#134558720: sleep for 2 seconds...
thread#134557696: operator()(): entering...
thread#134557696: dprintf_impl(): entering...
main_cpp.cpp (12): g_data == 3
thread#134558720: operator()(): entering...
thread#134558720: dprintf_impl(): entering...
main_cpp.cpp (20): g_data == 3

編譯 main_tls 與執行結果：

SHELL> gcc -o main_tls.o -c main_tls.c
SHELL> g++ -o main_tls main_tls.o thread_tool.o dprintf.o
SHELL> ./main_tls
thread#134557696: main_thread(): entering...
thread#134557696: sleep for 1 seconds...
thread#134558720: other_thread(): entering...
thread#134558720: sleep for 2 seconds...
thread#134557696: dprintf_front(): entering...
thread#134557696: sleep for 2 seconds...
thread#134558720: dprintf_front(): entering...
thread#134558720: sleep for 2 seconds...
thread#134557696: dprintf_tls(): entering...
thread#134557696: dprintf_impl(): entering...
main_tls.c (12): g_data == 3
thread#134558720: dprintf_tls(): entering...
thread#134558720: dprintf_impl(): entering...
main_tls.c (20): g_data == 3
thread#134558720: free_file_line(): entering...

從執行結果看來，這三種方法，都能夠正確的運作。我們總算將 dprintf() 搞定。

參考資料 (2008-01-23 新增)

Boost.Thread: Rationale for the Lock Design - Explains why the mutex lock concept in Boost.Thread is not thread-safe.

即使是 C++ 的 member function，還是可以使用 <stdarg.h>，寫成不定參數個數的形式。 ↩
在 C++ 裡，呼叫 non-static member function 時，實際上除了函式的參數之外，還有一個「隱藏的 this 指標」參數，讓 member function 裡能夠使用霧漸得內容。 ↩
使用 pthread_self() 取得。 ↩
由於都是在同一個檔案，所以雖然 g_file_line.file 也會被影響到，不過因為值都一樣，所以會看不出來，故這邊我們就不看了。 ↩
很奇怪的是，wikipedia 竟然沒有 syntax candy 這個條目。 ↩
現在 C 版本看起來很簡單，實際上，加上跨平台的部分之後，會變複雜一些，而其他 thread 相關的部分，會更複雜。 ↩
寫文章就等於是在整理筆記。 ↩
連 GCC 也得額外加上 -std=c99 參數才能夠使用。 ↩

5 Comments

Lemon

Posted January 17, 2009 at 1:00 am | Permalink

那個...請教一下:
mutex::guard lock(g_accounts_mutex);
這行, 為什麼不單純的呼叫
g_accounts_mutex.lock();
就好了?

因為目前我理解的只是省掉了呼叫 g_accounts_mutex.unlock();
的步驟而已, 而我以為是可以防止 g_accounts_mutex.lock()
被重覆呼叫.
是不是我理解錯了?
jeffhung

Posted January 17, 2009 at 10:57 am | Permalink

Lemon,

如果在程式裡面任何一點 throw/return/break 了出來，那 g_accounts_mutex.unlock() 可能會沒被呼叫到，最後輕則導致 dead lock，重則什麼事情都有可能發生。

利用這種技巧，可以保證一定會 unlock，我們就不用花費心思去確認，所有的執行路徑都有 unlock。
av

Posted January 19, 2009 at 12:15 pm | Permalink

這也是與使用 smart pointer 類似的原理，以確保 clean up 的 code 一會被 run 到.
fr3@K

Posted January 3, 2010 at 9:56 pm | Permalink

提供一個 micro optimization...

紀錄 line number 可用 const char*. 然後把 dprintf_v4 改成:
#define dprintf_v4 dprintf_v4_impl(__FILE__, #__LINE__)

印字串總是比印數字更有效率.
jeffhung

Posted January 4, 2010 at 9:17 am | Permalink

Hi fr3@K,

這招厲害。:-)

不過實務上，我把 file 與 line 以及其它資訊如 thread-id 甚至 back trace 等，一起包在一個叫 trace_info 的結構裡。這樣不僅 dprintf 可用，logging 或其它程式組件也可使用；更重要的是，這東西在 run-time (at least in debug-mode) 也很有用。

JeffHung.Blog

Implementing dprintf() without __VA_ARGS__

Random Posts

Similar Posts

5 Comments

Post a Comment

RSS Feeds

Recent Comments

Categories

Archives

Monthly Populars