想给自己之前的日志库,加一个染色的功能
gcc 有一个自己的特性,叫 __thread,介绍可以看这里,https://gcc.gnu.org/onlinedocs…,是可以用来修饰一个全局变量,从而让这个全局变量在每个线程都有一份拷贝,例子如下:
#include <stdio.h> #include <unistd.h> #include <pthread.h> #include <sys/syscall.h> __thread int n = 0; int ns[] = {1, 2}; void* thread_func(void *arg) { int tid = (int)syscall(__NR_gettid); printf("1, tid = %d, n = %d\n", tid, n); n = *((int*)arg); printf("2, tid = %d, n = %d\n", tid, n); while (1) { printf("3, tid = %d, n = %d\n", tid, n); sleep(1); } } int main() { for (int i = 0; i < sizeof(ns)/sizeof(ns[0]); i++) { pthread_t tid; pthread_create(&tid, NULL, thread_func, &ns[i]); printf("thread %d created\n", tid); } while (1) { sleep(1); } return 0; }
跑起来之后的输出是这样的
thread 1082132800 created thread 1090525504 created 1, tid = 11508, n = 0 2, tid = 11508, n = 1 3, tid = 11508, n = 1 1, tid = 11509, n = 0 2, tid = 11509, n = 2 3, tid = 11509, n = 2 3, tid = 11508, n = 1 3, tid = 11509, n = 2 3, tid = 11508, n = 1 3, tid = 11509, n = 2 3, tid = 11508, n = 1 3, tid = 11509, n = 2
用在日志库中,成为这个样子
#include <net/if.h> #include <arpa/inet.h> #include "logger.h" __thread int m_iLoggerLogTraceOn;// 是否开启染色日志 int Logger::Init(eLogLevel level, const char* pLogFileDir, const char* pLogFileBaseName, uint32_t uiLogFileRollingSize, uint32_t uiMaxCharPerLine, uint32_t uiLogBufferLines) { pthread_mutex_lock(&m_stInitLock); if (m_bInited || level == LOG_LEVEL_OFF) { pthread_mutex_unlock(&m_stInitLock); return 0; }
然后加了一个修改的接口
void Logger::setLogTraceOn(int iTraceOn) { printf("set trace switch to %d\n", iTraceOn); m_iLoggerLogTraceOn = iTraceOn; printf("after set, iLoggerLogTraceOn(%p) is %d, tid is %d\n", &m_iLoggerLogTraceOn, m_iLoggerLogTraceOn, (int)syscall(__NR_gettid)); }
在各个函数处也加了跟踪
void Logger::LogToMem(eLogLevel level, const char* format, ...) { printf("trace on(%p) : %d, tid is %d\n", &m_iLoggerLogTraceOn, m_iLoggerLogTraceOn, (int)syscall(__NR_gettid)); if (m_bInited && (level >= m_eLevel || m_iLoggerLogTraceOn)) { va_list args; va_start(args, format); char *pWritePtr = m_pLogBufferMem+((__sync_add_and_fetch(&m_uiWriteLineCount, 1) % m_uiLogBufferLines) * m_uiMaxCharPerLine); vsnprintf(pWritePtr+1, m_uiMaxCharPerLine-2, format, args); *(pWritePtr) = 1; va_end(args); } }
void Logger::LogToStdout(eLogLevel level, const char* format, ...) { printf("trace on(%p) : %d, tid is %d\n", &m_iLoggerLogTraceOn, m_iLoggerLogTraceOn, (int)syscall(__NR_gettid)); if (m_bInited && (level >= m_eLevel || m_iLoggerLogTraceOn)) { va_list args; va_start(args, format); vprintf(format, args); va_end(args); } }
然后在业务中这么使用
if (pSession->strAppUser == "BAAEB881F489FC59") { Logger::setLogTraceOn(1); LOG_INFO("appuser match, turn logger trace on"); }
然而,跑起来之后是这样的
set trace switch to 1 after set, iLoggerLogTraceOn(0x797bf0) is 1, tid is 9696 [2015-03-26 14:28:20] [INFO][ OnRequestData@ src/BusiObj.cpp,0136] appuser match, turn logger trace on trace on(0x43b0693c) : 0, tid is 9696 trace on(0x43b0693c) : 0, tid is 9696 trace on(0x43b0693c) : 0, tid is 9696 trace on(0x43b0693c) : 0, tid is 9696 trace on(0x43b0693c) : 0, tid is 9696
注意到一个神奇的现象,同一个变量,在同一个线程里面,指针不一样了
考虑到之前做函数耗时测试,和代码覆盖度测试的时候,遇到过由于进程关系复杂(又多进程又线程的)引起的问题,考虑是否由于这个原因引起的问题,于是写了这么一个测试
来看这个:
t2.cpp
#include <stdio.h> #include <unistd.h> #include <sys/syscall.h> __thread int n = 0; extern "C" { void busi(int arg) { printf("1, tid = %d, n = %d\n", (int)syscall(__NR_gettid), n); n = arg; printf("2, tid = %d, n = %d\n", (int)syscall(__NR_gettid), n); while (1) { printf("3, tid = %d, n = %d\n", (int)syscall(__NR_gettid), n); sleep(1); } } }
f1.cpp
#include <stdio.h> #include <stdlib.h> #include <dlfcn.h> #include <pthread.h> #include <unistd.h> int ns[] = {1, 2}; typedef void(*busi_func_ptr_t)(int); busi_func_ptr_t busi_func_ptr ; void* thread_func(void *args) { int arg = *((int*)args); printf("0, arg = %d\n", arg); (*busi_func_ptr)(arg); } int main() { int fork_ret = fork(); if (fork_ret == 0) { void* dll = dlopen("./t2.so", RTLD_LAZY); if (dll == NULL) { printf("%s\n", dlerror()); abort(); } busi_func_ptr = (busi_func_ptr_t)dlsym(dll, "busi"); char *err = dlerror(); if (err != NULL) { printf("%s\n", err); abort(); } for (int i = 0; i < sizeof(ns)/sizeof(ns[0]); i++) { pthread_t tid; pthread_create(&tid, NULL, thread_func, &ns[i]); printf("thread %d created\n", tid); } while (1) { sleep(1); } dlclose(dll); } else { printf("chid proc %d\n", fork_ret); while (1) { sleep(1); } } return 0; }
makefile
all: g++ t2.cpp -O3 -shared -o t2.so -fPIC g++ f1.cpp -O3 -o f1 -ldl -pthread
makefile 带 O3 是为了跟实际情况保持一致
运行输出如下
thread 1082132800 created chid proc 12856 thread 1090525504 created 0, arg = 1 1, tid = 12857, n = 0 2, tid = 12857, n = 1 3, tid = 12857, n = 1 0, arg = 2 1, tid = 12858, n = 0 2, tid = 12858, n = 2 3, tid = 12858, n = 2 3, tid = 12857, n = 1 3, tid = 12858, n = 2 3, tid = 12857, n = 1 3, tid = 12858, n = 2
看起来是没有问题的,又考虑到,我们的日志是先编译成一个静态的 lib.a 的库,然后在编译到 lib.so 的动态库中,最后由框架加载运行的,于是试了一下这么搞
我写了一个 test.cpp
public: //与tcpd的接口 char * OnRequestData(const char * p_pcResData, int p_iResDataLen, int& p_iRetDataLen, int& p_iDataBufLen, const char *p_pcHostIP, const char * p_pcBusiBuf, int& piProcessedDataLen, int fd) { Logger::setLogTraceOn(1); printf("on request123\n"); LOG_DEBUG("on request123"); LOG_ERR("on request123"); Logger::setLogTraceOn(0); printf("on request456\n"); LOG_DEBUG("on request456"); LOG_ERR("on request456"); Logger::setLogTraceOn(1); printf("on request789\n"); LOG_DEBUG("on request789"); LOG_ERR("on request789"); Logger::setLogTraceOn(0); return NULL; } int OnDllDataUpdate(const char * p_pcDataBuf, int p_iDataBufLen) {} bool FreeMemBlock(char * p_pcMemBlock, int p_iMemBlockLen) { return true; } bool InitDllWithCfgFile(const char *p_pcCfgFileName) { printf("%s\n", p_pcCfgFileName); Logger::Init(Logger::LOG_LEVEL_INFO, "./", "stdout"); Logger::setLogTraceOn(1); }
然后把含有日志库的通用组件的静态库和这个 test.cpp 放在同一个目录中,编出一个动态库
g++ test.cpp libcommontool.a -shared -o lib.so -fPIC
然后用 tcpd 去加载这个动态库
这个是 Init 函数打出来的
CALL DLL INIT INTERFACE ./main.cfg set trace switch to 1 after set, iLoggerLogTraceOn(0x51be60) is 1, tid is 15719
这个是 OnRquest 函数打出来的
set trace switch to 1 after set, iLoggerLogTraceOn(0x52f280) is 1, tid is 15721 on request123 trace on(0x4090193c) : 0, tid is 15721 trace on(0x4090193c) : 0, tid is 15721 [2015-03-26 14:49:15][ERROR][ OnRequestData@ test.cpp,0026] on request123 set trace switch to 0 after set, iLoggerLogTraceOn(0x52f280) is 0, tid is 15721 on request456 trace on(0x4090193c) : 0, tid is 15721 trace on(0x4090193c) : 0, tid is 15721 [2015-03-26 14:49:15][ERROR][ OnRequestData@ test.cpp,0030] on request456 set trace switch to 1 after set, iLoggerLogTraceOn(0x52f280) is 1, tid is 15721 on request789 trace on(0x4090193c) : 0, tid is 15721 trace on(0x4090193c) : 0, tid is 15721 [2015-03-26 14:49:15][ERROR][ OnRequestData@ test.cpp,0034] on request789 set trace switch to 0 after set, iLoggerLogTraceOn(0x52f280) is 0, tid is 15721
于是到此就陷入了僵局,查资料说 gcc 在编译动态链接库的时候对全局变量的处理有一些特殊,看到这里,http://blog.csdn.net/zxh821112/article/details/8969541,还有,http://blog.csdn.net/yuyin86/article/details/10239479,http://bbs.chinaunix.net/thread-1620536-1-1.html,和这里,https://www.owent.net/2014/01/cpp%E5%8F%88%E4%B8%80%E5%9D%91-%E5%8A%A8%E6%80%81%E9%93%BE%E6%8E%A5%E5%BA%93%E4%B8%AD%E7%9A%84%E5%85%A8%E5%B1%80%E5%8F%98%E9%87%8F.html,不过这些帖子在讨论,主要是集中在一个动态库被多个进程引用的时候的赋值问题,跟我们这个场景还不太一样
——————
2015-3-26 20:34:46 update http://lists.freebsd.org/piper… 这里有一篇,之前没发现
———————
2015-3-27 11:33:43 update 最后确认是编译器的问题,生产环境的编译器是 4.1.2 的老古董,换一个 gcc 4.8.2 问题就烟消云散了