由于线上服务端程序，需要大量写入日志，将来入数据库库，以便做数据分析或者对账之用，可是发现日志打开后服务器变慢了，对外并发响应数量也减少了。于是分析了下日志写入函数fprintf。其写日志文件的顺序是：程序写入用户地址空间内核从用户地址空间缓冲区复制到内核文件缓冲区内核文件缓冲区满的情况下再放入内核io队列，等待写入到硬盘上。写文件其实不是直接写到硬盘，那样的话一堆程序都同时并发往硬盘上写，硬盘能累吐血。所以文件其实是先写到内存，满员后再写到硬盘，当然这是内核完成的，我们用户程序只要使用系统调用就行了。这样可以减少写硬盘的次数，一次批量多写些内容进去。
一个程序使用系统调用的次数会很大程度上影响系统的性能,因为在执行系统时，会从用户代码切换执行内核代码，然后返回用户代码。优化手段就是尽量减少系统调用次数。
以上这种缓存的思想是很OK的，那么我们的问题在哪里呢？我们的问题其实就是一次性写入的日志很大，通常会超过系统默认的用户地址空间文件缓冲区大小4096字节，刚好就是一个页的大小，应该是为了方便拷贝到内核而设的单位，我们往往一行日志就写了5000多字节，有的甚至1M字节。所以每次写一行日志都会触发系统调用。而我们的服务器程序写日志很频繁，每秒都有几次写这种大型日志的操作，写小日志的操作就更多了。当然可以分不同的文件写到多个日志文件中，缓解单个文件缓冲区的压力，不过这好像么有治本。
在服务器设计上的思想，我是尽可能的用空间换时间，因为用户很挑剔啊，时间上人家可不愿意多等几秒。当然不要无限制的滥用空间，内存和硬盘也很宝贵的。
我们的办法就是在写日志文件的时候，使用setvbuf函数设置自己的缓冲区，尽量在内存够用的情况下，设置大些。我设置了10*4096个字节，这样fprintf函数内部使用系统调用的频率就少了，减少了不少次从用户态拷贝小数据到内核态转换的时间开销，转为积累大数据，一次性拷贝，只一次系统调用就搞定。接下来看示例

调大缓冲区

/**
 * 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字节。

    printf("循环%d条，数据总量%ld：\n", LOOP_CNT, (long)LOOP_CNT* 4108);
    
    FILE *pFile;
    struct stat sysbuf;
    stat("1.txt", &sysbuf);
    printf("系统默认文件缓冲区大小 = %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个字节的i和换行。
    }
    fclose (pFile);
    gettimeofday(&end,NULL); // 结束计时
    // 计算耗时
    timeuse = 1000000*(end.tv_sec - start.tv_sec) + end.tv_usec - start.tv_usec; 
    timeuse /= 1000000; 
    printf("默认缓冲区写文件，用时:%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字节。

    printf("循环%d条，数据总量%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("自定义缓冲区 = %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("自定义缓冲区写文件，用时:%f\n", timeuse);
    
    return 0;
}

在一个5400转硬盘的虚拟机上，分别编译运行，查看结果，其中st_blocks代表该文件使用了多少个块。
一开始测试我犯了个严重的错误，就是将两段代码编译好的程序一起运行，或者两次运行间隔时间不长。后来通过在windows的资源管理器中查看实时磁盘IO，发现写入1.txt的程序虽然已经退出了，但是磁盘还在写入，说明这会是内核在往磁盘中写入呢。而我此时启动另一个测试程序对2.txt做写入操作，会响测试1.txt效果，应该等1.txt完全写入完成，磁盘io不再进行时候再启动对2.txt的操作。

循环10000条，数据总量41080000：
系统默认文件缓冲区大小 = 4096 byte,总共802344块
默认缓冲区写文件，用时:0.468300
循环10000条，数据总量41080000：
自定义缓冲区 = 40960 byte
自定义缓冲区写文件，用时:0.155844

循环100000条，数据总量410800000：
系统默认文件缓冲区大小 = 4096 byte,总共8023438块
默认缓冲区写文件，用时:4.686463
循环100000条，数据总量410800000：
自定义缓冲区 = 40960 byte
自定义缓冲区写文件，用时:1.543402

循环1000000条，数据总量4108000000：
系统默认文件缓冲区大小 = 4096 byte,总共2642816块
默认缓冲区写文件，用时:47.181843
循环1000000条，数据总量4108000000：
自定义缓冲区 = 40960 byte
自定义缓冲区写文件，用时:28.394735

在写入100000条之前，还有着2倍多的速率差异。
等到写入次数达到1000000条的时候，两者的时间差缩小到了1倍以内，此时的日志文件4.16G。再加大测试的话，内核的IO队列该不够用。
在windows下查看了下虚拟机的写入速率，依然自定义缓存方式要快一些，以下是速率峰值时候的截图
1.用系统默认缓存

这里写图片描述

最高到74M/s
2.自定义缓存峰值

这里写图片描述
最高到115M/s
从每次测试的结果看，自定义缓冲区后，写入相同字节的内容，自定义缓冲区明显要比系统默认少一倍以上的时间。当然这是测试，实际项目可根据情况自行调节缓冲区大小。
不过这样做的坏处显而易见，断电就抓瞎了，大量的的缓存还没写到磁盘呢！

调等缓冲区

当然，我们还要测试下设置成和系统默认4096，也就是一个页大小的单位

循环1000000条，数据总量4108000000：
系统默认文件缓冲区大小 = 4096 byte,总共79633800块
默认缓冲区写文件，用时:48.648003
循环1000000条，数据总量4108000000：
自定义缓冲区 = 4096 byte
自定义缓冲区写文件，用时:49.252640

用时几乎相当，还多了1秒，呵呵。

调小缓冲区

再看看，缩小缓冲区的结果，设为1024字节

循环1000000条，数据总量4108000000：
系统默认文件缓冲区大小 = 4096 byte,总共8023438块
默认缓冲区写文件，用时:49.945450
循环1000000条，数据总量4108000000：
自定义缓冲区 = 1024 byte
自定义缓冲区写文件，用时:102.239960

这次看到缓冲区缩小后，明显用时更多了，竟然超过1倍多的时间。

思考

FILE结构里本身带有一个缓冲。而内核在操作IO的时候会还有一个缓冲区，内核将缓冲区写到磁盘也不是直接写，而是放到其IO队列中等待写入。加大文件缓冲区，也只是加大了用户态的缓冲区，而内核态缓冲区是没有变的，所以当用户态缓冲区超过4096一个页大小的时候，它从用户地址空间拷贝到内核地址空间时候，应该是切分了好几页，分别加入内核IO的队列中，准备写入到磁盘上。

---

创建于2014-03-04深圳腾讯，更新于2016-07-06杭州。