How to ascertain that using the _IONBF macro with the setvbuf function, file operations are slow

Question

I want to have a clear example that actually using the _IONBF macro in the setvbuf function, the writing operations (stream) in a file take place directly, without using the buffer. If I did this experiment in my file system (SSD memory) I would not see any delay in writing as it is a very fast device, but if I did this using a floppy, I would have to see, when I run the program, the command prompt of my terminal, release as soon as writing to the floppy disk ends.

Why does it seem to me that writing still occurs through a buffer?

note: in the program string I made a copy / paste of a very long text (1.44 Mbyte of characters); so if you want to try the experiment (in addition to a floppy drive), you have to fill that string enough to make writing on the device slow.

#include <stdio.h>
#include <string.h>

int main() {
    FILE *fp;
    char string[] = "here goes a very long text .... enough to fill a floppy disk!";

    fp = freopen("/Volumes/FLOPPY/file.txt", "w", stdout);
    setvbuf(fp, NULL, _IONBF, 0);
    printf("%s", string);
    printf("\nEND OF FILE");

    fclose(fp);
    return(0);
}

Answer 1

The printf() function is likely to map your request to a single write() call, not using the buffering, but not slowing down either. If you want to see the effect of not buffering, use single-character I/O:

for (int i = 0; string[i] != '\0'; i++)
    putc(string[i], fp);

With unbuffered I/O, that will show the difference because each call to putc() requires a write() system call because there's only a single byte available to work on.

Note that the code below doesn't work with a string — it works with a byte array (no null terminator). The difference is not important for performance; it does require a modicum of care in handling the data.

The code also uses a regular fopen() rather than using freopen() on stdout. Again, that won't (is extremely unlikely to) make a material difference to performance.

slow11.c

#include <stdio.h>

#define FLOPPY_SIZE (2 * 80 * 18 * 512) // 2 sides, 80 tracks, 18 sectors, 512 bytes

int main(void)
{
    char string[FLOPPY_SIZE];

    for (size_t i = 0; i < FLOPPY_SIZE; i++)
        string[i] = (i % 64) + '0';

    const char filename[] = "floppy.data";
    FILE *fp = fopen(filename, "w");
    setvbuf(fp, NULL, _IONBF, 0);

    for (size_t i = 0; i < FLOPPY_SIZE; i++)
        putc(string[i], fp);

    fclose(fp);

    return(0);
}

slow61.c

I also created a program slow61.c from slow11.c by removing the setvbuf() line.

fast89.c

#include <stdio.h>

#define FLOPPY_SIZE (2 * 80 * 18 * 512) // 2 sides, 80 tracks, 18 sectors, 512 bytes

int main(void)
{
    char string[FLOPPY_SIZE];

    for (size_t i = 0; i < FLOPPY_SIZE; i++)
        string[i] = (i % 64) + '0';

    const char filename[] = "floppy.data";
    FILE *fp = fopen(filename, "w");
    setvbuf(fp, NULL, _IONBF, 0);

    fprintf(fp, "%.*s", FLOPPY_SIZE, string);

    fclose(fp);

    return(0);
}

Sample run times

The timecmd program is a home-brew; the -u option reports times in microseconds (-n for nanoseconds; -m for milliseconds, nothing for whole seconds). It's primarily for long-running programs where it helps to know when the command started so you can guess when it will finish (which is why it reports the start and finish information). You can probably use (POSIX standard) time instead; the output format will be different.

$ for i in 1 2 3 4 5 6 7 8 9 0; do timecmd -u -- fast89; timecmd -u slow61; timecmd -u slow11; done
2020-03-01 07:58:05.964614 [PID 14492] fast89
2020-03-01 07:58:05.978391 [PID 14492; status 0x0000]  -  0.013777s
2020-03-01 07:58:05.986902 [PID 14494] slow61
2020-03-01 07:58:06.058328 [PID 14494; status 0x0000]  -  0.071426s
2020-03-01 07:58:06.066949 [PID 14496] slow11
2020-03-01 07:58:09.788096 [PID 14496; status 0x0000]  -  3.721147s
2020-03-01 07:58:09.795178 [PID 14498] fast89
2020-03-01 07:58:09.806464 [PID 14498; status 0x0000]  -  0.011286s
2020-03-01 07:58:09.813784 [PID 14500] slow61
2020-03-01 07:58:09.882777 [PID 14500; status 0x0000]  -  0.068993s
2020-03-01 07:58:09.890567 [PID 14502] slow11
2020-03-01 07:58:13.689083 [PID 14502; status 0x0000]  -  3.798516s
2020-03-01 07:58:13.696225 [PID 14504] fast89
2020-03-01 07:58:13.708219 [PID 14504; status 0x0000]  -  0.011994s
2020-03-01 07:58:13.715447 [PID 14506] slow61
2020-03-01 07:58:13.784190 [PID 14506; status 0x0000]  -  0.068743s
2020-03-01 07:58:13.791485 [PID 14508] slow11
2020-03-01 07:58:17.495425 [PID 14508; status 0x0000]  -  3.703940s
2020-03-01 07:58:17.502710 [PID 14510] fast89
2020-03-01 07:58:17.514147 [PID 14510; status 0x0000]  -  0.011437s
2020-03-01 07:58:17.521541 [PID 14512] slow61
2020-03-01 07:58:17.589657 [PID 14512; status 0x0000]  -  0.068116s
2020-03-01 07:58:17.596818 [PID 14514] slow11
2020-03-01 07:58:21.253654 [PID 14514; status 0x0000]  -  3.656836s
2020-03-01 07:58:21.260930 [PID 14516] fast89
2020-03-01 07:58:21.272169 [PID 14516; status 0x0000]  -  0.011239s
2020-03-01 07:58:21.279587 [PID 14518] slow61
2020-03-01 07:58:21.348507 [PID 14518; status 0x0000]  -  0.068920s
2020-03-01 07:58:21.355832 [PID 14520] slow11
2020-03-01 07:58:25.041571 [PID 14520; status 0x0000]  -  3.685739s
2020-03-01 07:58:25.048497 [PID 14522] fast89
2020-03-01 07:58:25.059680 [PID 14522; status 0x0000]  -  0.011183s
2020-03-01 07:58:25.066855 [PID 14524] slow61
2020-03-01 07:58:25.135246 [PID 14524; status 0x0000]  -  0.068391s
2020-03-01 07:58:25.142421 [PID 14526] slow11
2020-03-01 07:58:28.853268 [PID 14526; status 0x0000]  -  3.710847s
2020-03-01 07:58:28.860497 [PID 14528] fast89
2020-03-01 07:58:28.872152 [PID 14528; status 0x0000]  -  0.011655s
2020-03-01 07:58:28.879254 [PID 14530] slow61
2020-03-01 07:58:28.947534 [PID 14530; status 0x0000]  -  0.068280s
2020-03-01 07:58:28.955126 [PID 14532] slow11
2020-03-01 07:58:33.236459 [PID 14532; status 0x0000]  -  4.281333s
2020-03-01 07:58:33.243709 [PID 14534] fast89
2020-03-01 07:58:33.260364 [PID 14534; status 0x0000]  -  0.016655s
2020-03-01 07:58:33.267575 [PID 14536] slow61
2020-03-01 07:58:33.336602 [PID 14536; status 0x0000]  -  0.069027s
2020-03-01 07:58:33.344791 [PID 14538] slow11
2020-03-01 07:58:37.065292 [PID 14538; status 0x0000]  -  3.720501s
2020-03-01 07:58:37.072215 [PID 14540] fast89
2020-03-01 07:58:37.083717 [PID 14540; status 0x0000]  -  0.011502s
2020-03-01 07:58:37.090785 [PID 14542] slow61
2020-03-01 07:58:37.158659 [PID 14542; status 0x0000]  -  0.067874s
2020-03-01 07:58:37.165790 [PID 14544] slow11
2020-03-01 07:58:41.024668 [PID 14544; status 0x0000]  -  3.858878s
2020-03-01 07:58:41.032007 [PID 14566] fast89
2020-03-01 07:58:41.043518 [PID 14566; status 0x0000]  -  0.011511s
2020-03-01 07:58:41.053114 [PID 14568] slow61
2020-03-01 07:58:41.128938 [PID 14568; status 0x0000]  -  0.075824s
2020-03-01 07:58:41.136826 [PID 14570] slow11
2020-03-01 07:58:44.971013 [PID 14570; status 0x0000]  -  3.834187s
$

It doesn't take much skill to see that the slow11 code takes about 300 times as long as the fast89 code, nor that the non-buffering is the key factor since slow61 is only about 6-7 times as slow as fast89.

Testing on a MacBook Pro running macOS Mojave 10.14.6 with SSD and using GCC 9.2.0.