您當前位置：首頁 > 互聯網 > 多線程下寫日志

多線程下寫日志

來源：程序員人生發布時間：2014-11-20 08:09:00 閱讀次數：2843次

鄙人最近遇到了1個奇特的線上事故，記錄1下，以備記憶。

鄙人所在的部門負責給公司提供各種基礎庫，即基礎架構部門。最近某別的部門用本部門提供的支持多線程版本的日志庫后，出現這樣1個奇特的現象：當磁盤被日志寫滿以后，他們的數據文件的頭部被寫上了最新的日志！就是說，別的部門的程序的數據文件被日志數據給污染了。

這里先不介紹這個事故的緣由。先說下這個日志庫的寫日志進程，其流程大致以下：

step1 如果log的fd為⑴，就重新通過C函數open再打開1個log_fd；

step2 寫log內容，即ssize_t size = write(log_fd, buf, len);

step3 如果size等于len，則轉step 7，否則繼續step 8；

step4 對log_fd加mutex鎖；

step5 close(log_fd)；

step6 log_fd賦值為⑴；

step7 解鎖；

step8 return。

然后用戶進程的邏輯大致為：

logic1 當有新數據的時候，通過C函數open打開1個data_fd；

logic2 write(data_fd, data, data_len);

logic3 close(data_fd)。

假定這樣1個場景：有線程A先寫了1條日志，線程B緊隨其后也來寫1條日志，線程C正常進行數據文件寫操作。通過假定1下情況，在磁盤滿的時候可能復現這個bug。假定程序運行進程是：

進程1 線程A履行到step6，此時log_fd為3，線程A給log_fd賦值為⑴；

進程2 線程B履行到step2，此時log_fd依然為3，但其實線程A已將fd為3的文件關閉掉了，所以線程B持有的這個log_fd此時為非法描寫符；

進程3 線程C履行到logic2，由于線程A已將fd 3歸還給os，所以os此時把3給了data_fd，即data_fd為3。

如果這個假定成立，那末在進程線程B的log內容1定會寫到數據文件中。

為了驗證這個情況，先在公司的linuxhttp://www.vxbq.cn/server/建立了1個loop文件系統，簡歷步驟以下：

1 dd if=/dev/zero of=/home/alex/100.img bs=1M count=100 # 在這1步建立1個容量為100M的loop裝備
2 mkfs.ext2 100.img # 將loop裝備格式化為ext2格式
3 mount 100.img /home/alex/vfs -o loop -n # 簡歷loop裝備，將/home/alex/vfs目錄映照到這個loop裝備上

由于裝備的容量非常小，上面的bug就很容易重現，重現邏輯很簡單，首先設置log的文件目錄是/home/alex/vfs，然后啟動1000個線程，每一個線程的邏輯函數以下:

void* thread_func(void *arg) { char log_file_name[32]; sprintf(log_file_name, "/tmp/%d", (int)(int_ptr)(arg)); //data file name for (int idx = 0; idx < 10000; idx++) { int fd = open(log_file_name, O_CREAT | O_APPEND | O_RDWR, 0666); log_debug("1234567890qwertyuiopasdfghjklzxcvbnmQWERhello, %d", (int)(int_ptr)(arg)); close(fd); } pthread_exit(NULL); return NULL; } #define MAX_THEAD_NUM 1000 int main() { // set log path: /home/alex/vfs/ pthread_t id[MAX_THEAD_NUM]; for (int idx = 0; idx < MAX_THEAD_NUM; idx++) { pthread_create(id + idx, NULL, thread_func, (void*)(intptr_t)(idx)); } for (idx = 0; idx < thread_num; idx++) { pthread_join(id[idx], NULL); } return 0; }

上面的線程函在循環里不斷的打開關閉數據文件，即其大小為0。程序運行終了后，數據文件的大小若不為0，就可以驗證上面的假定。

運行以上測試程序后，視察到大量的數據文件的大小不為0，其內容為log內容。其實這個事故還算榮幸，若用戶的數據不是輸出到磁盤，而是通過tcp socket發送到別的機器，那末這個bug會致使tcp的流內容稀里糊涂的亂掉，那問題就更不容易清查了。

驗證了假定，問題就很容易解決了。解決方法有兩種：

第1種方法，對fd加援用計數。即線程每獲得1個新的log_fd時候，要增加1次援用次數；如果出現write失敗的情況，要減小1次援用次數，當援用次數為0的時候，再close掉log_fd；

第2種方法，使用tls（thread local storage）情勢的log file。即每一個線程都打開同1個log file，open函數的“mode參數”為“O_CREAT | O_APPEND | O_RDWR”，當寫失敗的時候，各自close各自的log_fd。

終究我采取了第2種解決方法，很好地解決了問題。如果你有更好的方法，歡迎評論。

此記，謝絕轉載。

生活不易，碼農辛苦
如果您覺得本網站對您的學習有所幫助,可以手機掃描二維碼進行捐贈
程序員人生