由于線上服務端程序，需要大量寫入日志，將來入數(shù)據(jù)庫庫，以便做數(shù)據(jù)分析或者對賬之用，可是發(fā)現(xiàn)日志打開后服務器變慢了，對外并發(fā)響應數(shù)量也減少了。于是分析了下日志寫入函數(shù)fprintf。其寫日志文件的順序是：程序寫入用戶地址空間?內核從用戶地址空間緩沖區(qū)復制到內核文件緩沖區(qū)?內核文件緩沖區(qū)滿的情況下再放入內核io隊列，等待寫入到硬盤上。寫文件其實不是直接寫到硬盤，那樣的話一堆程序都同時并發(fā)往硬盤上寫，硬盤能累吐血。所以文件其實是先寫到內存，滿員后再寫到硬盤，當然這是內核完成的，我們用戶程序只要使用系統(tǒng)調用就行了。這樣可以減少寫硬盤的次數(shù)，一次批量多寫些內容進去。
一個程序使用系統(tǒng)調用的次數(shù)會很大程度上影響系統(tǒng)的性能,因為在執(zhí)行系統(tǒng)時，會從用戶代碼切換執(zhí)行內核代碼，然后返回用戶代碼。優(yōu)化手段就是盡量減少系統(tǒng)調用次數(shù)。
以上這種緩存的思想是很OK的，那么我們的問題在哪里呢？我們的問題其實就是一次性寫入的日志很大，通常會超過系統(tǒng)默認的用戶地址空間文件緩沖區(qū)大小4096字節(jié)，剛好就是一個頁的大小，應該是為了方便拷貝到內核而設的單位，我們往往一行日志就寫了5000多字節(jié)，有的甚至1M字節(jié)。所以每次寫一行日志都會觸發(fā)系統(tǒng)調用。而我們的服務器程序寫日志很頻繁，每秒都有幾次寫這種大型日志的操作，寫小日志的操作就更多了。當然可以分不同的文件寫到多個日志文件中，緩解單個文件緩沖區(qū)的壓力，不過這好像么有治本。
在服務器設計上的思想，我是盡可能的用空間換時間，因為用戶很挑剔啊，時間上人家可不愿意多等幾秒。當然不要無限制的濫用空間，內存和硬盤也很寶貴的。
我們的辦法就是在寫日志文件的時候，使用setvbuf函數(shù)設置自己的緩沖區(qū)，盡量在內存夠用的情況下，設置大些。我設置了10*4096個字節(jié)，這樣fprintf函數(shù)內部使用系統(tǒng)調用的頻率就少了，減少了不少次從用戶態(tài)拷貝小數(shù)據(jù)到內核態(tài)轉換的時間開銷，轉為積累大數(shù)據(jù)，一次性拷貝，只一次系統(tǒng)調用就搞定。接下來看示例

調大緩沖區(qū)

/**
 * test1.c
 * gcc test1.c -o test1
 */
#include <stdio.h>
#include <sys/stat.h>
#include <sys/time.h> 

#define BUF_SIZE 40960
#define LOOP_CNT 1000000

int main () 
{
    int i = 0;
    struct timeval start, end; // 計時用的結構
    float timeuse; // 耗時，s為單位

    char test_fmt[4108];
    for(i = 0; i < 4108; i++){
        test_fmt[i] = 'A';
    } // 總共4108字節(jié)。

    printf("循環(huán)%d條，數(shù)據(jù)總量%ld：\n", LOOP_CNT, (long)LOOP_CNT* 4108);
    
    FILE *pFile;
    struct stat sysbuf;
    stat("1.txt", &sysbuf);
    printf("系統(tǒng)默認文件緩沖區(qū)大小 = %d byte,總共%d塊\n", (int)sysbuf.st_blksize, (int)sysbuf.st_blocks);
    pFile=fopen ("1.txt","w");
    gettimeofday(&start,NULL); // 開始計時
    for (i = 0; i < LOOP_CNT; i++){
        fprintf(pFile, test_fmt, i); // 每行128個A，總共4096個A，再加上末尾不到10個字節(jié)的i和換行。
    }
    fclose (pFile);
    gettimeofday(&end,NULL); // 結束計時
    // 計算耗時
    timeuse = 1000000*(end.tv_sec - start.tv_sec) + end.tv_usec - start.tv_usec; 
    timeuse /= 1000000; 
    printf("默認緩沖區(qū)寫文件，用時:%f\n", timeuse);
    
    return 0;
}

/**
 * test2.c
 * gcc test2.c -o test2
 */
#include <stdio.h>
#include <sys/stat.h>
#include <sys/time.h> 

#define BUF_SIZE 40960
#define LOOP_CNT 1000000

int main () 
{
    int i = 0;
    struct timeval start, end; // 計時用的結構
    float timeuse; // 耗時，s為單位

    char test_fmt[4108];
    for(i = 0; i < 4108; i++){
        test_fmt[i] = 'A';
    } // 總共4108字節(jié)。

    printf("循環(huán)%d條，數(shù)據(jù)總量%ld：\n", LOOP_CNT, (long)LOOP_CNT* 4108);
    
    FILE *pFile1;
    pFile1=fopen ("2.txt","w"); 
    char buf[BUF_SIZE];
    setvbuf ( pFile1 , buf, _IOFBF , BUF_SIZE );
    printf("自定義緩沖區(qū) = %d byte\n", BUF_SIZE);
    gettimeofday(&start,NULL); // 開始計時
    for (i = 0; i < LOOP_CNT; i++){
        fprintf(pFile1, test_fmt, i);
    }
    fclose (pFile1);
    gettimeofday(&end,NULL); // 結束計時
    // 計算耗時
    timeuse = 1000000*(end.tv_sec - start.tv_sec) + end.tv_usec - start.tv_usec; 
    timeuse /= 1000000; 
    printf("自定義緩沖區(qū)寫文件，用時:%f\n", timeuse);
    
    return 0;
}

在一個5400轉硬盤的虛擬機上，分別編譯運行，查看結果，其中st_blocks代表該文件使用了多少個塊。
一開始測試我犯了個嚴重的錯誤，就是將兩段代碼編譯好的程序一起運行，或者兩次運行間隔時間不長。后來通過在windows的資源管理器中查看實時磁盤IO，發(fā)現(xiàn)寫入1.txt的程序雖然已經退出了，但是磁盤還在寫入，說明這會是內核在往磁盤中寫入呢。而我此時啟動另一個測試程序對2.txt做寫入操作，會響測試1.txt效果，應該等1.txt完全寫入完成，磁盤io不再進行時候再啟動對2.txt的操作。

循環(huán)10000條，數(shù)據(jù)總量41080000：
系統(tǒng)默認文件緩沖區(qū)大小 = 4096 byte,總共802344塊
默認緩沖區(qū)寫文件，用時:0.468300
循環(huán)10000條，數(shù)據(jù)總量41080000：
自定義緩沖區(qū) = 40960 byte
自定義緩沖區(qū)寫文件，用時:0.155844

循環(huán)100000條，數(shù)據(jù)總量410800000：
系統(tǒng)默認文件緩沖區(qū)大小 = 4096 byte,總共8023438塊
默認緩沖區(qū)寫文件，用時:4.686463
循環(huán)100000條，數(shù)據(jù)總量410800000：
自定義緩沖區(qū) = 40960 byte
自定義緩沖區(qū)寫文件，用時:1.543402

循環(huán)1000000條，數(shù)據(jù)總量4108000000：
系統(tǒng)默認文件緩沖區(qū)大小 = 4096 byte,總共2642816塊
默認緩沖區(qū)寫文件，用時:47.181843
循環(huán)1000000條，數(shù)據(jù)總量4108000000：
自定義緩沖區(qū) = 40960 byte
自定義緩沖區(qū)寫文件，用時:28.394735

在寫入100000條之前，還有著2倍多的速率差異。
等到寫入次數(shù)達到1000000條的時候，兩者的時間差縮小到了1倍以內，此時的日志文件4.16G。再加大測試的話，內核的IO隊列該不夠用。
在windows下查看了下虛擬機的寫入速率，依然自定義緩存方式要快一些，以下是速率峰值時候的截圖
1.用系統(tǒng)默認緩存

這里寫圖片描述

最高到74M/s
2.自定義緩存峰值

這里寫圖片描述

調等緩沖區(qū)

當然，我們還要測試下設置成和系統(tǒng)默認4096，也就是一個頁大小的單位

循環(huán)1000000條，數(shù)據(jù)總量4108000000：
系統(tǒng)默認文件緩沖區(qū)大小 = 4096 byte,總共79633800塊
默認緩沖區(qū)寫文件，用時:48.648003
循環(huán)1000000條，數(shù)據(jù)總量4108000000：
自定義緩沖區(qū) = 4096 byte
自定義緩沖區(qū)寫文件，用時:49.252640

用時幾乎相當，還多了1秒，呵呵。

調小緩沖區(qū)

再看看，縮小緩沖區(qū)的結果，設為1024字節(jié)

循環(huán)1000000條，數(shù)據(jù)總量4108000000：
系統(tǒng)默認文件緩沖區(qū)大小 = 4096 byte,總共8023438塊
默認緩沖區(qū)寫文件，用時:49.945450
循環(huán)1000000條，數(shù)據(jù)總量4108000000：
自定義緩沖區(qū) = 1024 byte
自定義緩沖區(qū)寫文件，用時:102.239960

這次看到緩沖區(qū)縮小后，明顯用時更多了，竟然超過1倍多的時間。

思考

FILE結構里本身帶有一個緩沖。而內核在操作IO的時候會還有一個緩沖區(qū)，內核將緩沖區(qū)寫到磁盤也不是直接寫，而是放到其IO隊列中等待寫入。加大文件緩沖區(qū)，也只是加大了用戶態(tài)的緩沖區(qū)，而內核態(tài)緩沖區(qū)是沒有變的，所以當用戶態(tài)緩沖區(qū)超過4096一個頁大小的時候，它從用戶地址空間拷貝到內核地址空間時候，應該是切分了好幾頁，分別加入內核IO的隊列中，準備寫入到磁盤上。

創(chuàng)建于2014-03-04深圳騰訊，更新于2016-07-06杭州。