Writing to a file many times with fprint is very slow

[hotgluebanjo]

Not sure if this is a real issue or if I'm doing something wrong, but something like this takes about 21 seconds:

package slow_example

import "core:fmt"
import "core:os"

main :: proc() {
    f, _ := os.open("test.txt", os.O_CREATE)
    defer os.close(f)
    for _ in 0..<5000 {
        fmt.fprintln(f, "test")
    }
}

Run with:

odin run test.odin -file

Whereas C takes about 30 milliseconds for what I think is the equivalent example.

#include <stdio.h>

int main() {
    FILE *file = fopen("test.txt", "w");
    for (int i = 0; i < 5000; i++) {
        fprintf(file, "test\n");
    }
    fclose(file);
}

Rust and Python are close to C. Optimizing doesn't help.

Only tested on Windows. Both nightly and stable do this. Anyone have any idea?

[z64]

@hotgluebanjo This only takes a few ms on my Linux machine, but I can guess that the reason is the same on windows:

If we observe the syscall trace, C will buffer the writes into chunks:

openat(AT_FDCWD, "test.txt", O_WRONLY|O_CREAT|O_TRUNC, 0666) = 3
newfstatat(3, "", {st_mode=S_IFREG|0644, st_size=0, ...}, AT_EMPTY_PATH) = 0
write(3, "testtesttesttesttesttesttesttest"..., 4096) = 4096
write(3, "testtesttesttesttesttesttesttest"..., 4096) = 4096
write(3, "testtesttesttesttesttesttesttest"..., 4096) = 4096
write(3, "testtesttesttesttesttesttesttest"..., 4096) = 4096
write(3, "testtesttesttesttesttesttesttest"..., 3616) = 3616
close(3)                                = 0

Odin (by default) will not do so, issuing a write() each time; twice in fact, per "test", when using println():

open("test.txt", O_RDWR|O_CREAT, 000)   = 3
write(3, "test", 4)                     = 4
write(3, "\n", 1)                       = 1
write(3, "test", 4)                     = 4
write(3, "\n", 1)                       = 1
write(3, "test", 4)                     = 4
write(3, "\n", 1)                       = 1
write(3, "test", 4)                     = 4
write(3, "\n", 1)                       = 1
write(3, "test", 4)                     = 4
write(3, "\n", 1)                       = 1
write(3, "test", 4)                     = 4
write(3, "\n", 1)                       = 1
write(3, "test", 4)                     = 4
write(3, "\n", 1)                       = 1
write(3, "test", 4)                     = 4
write(3, "\n", 1)                       = 1
write(3, "test", 4)                     = 4

..... many calls ....

write(3, "\n", 1)                       = 1
write(3, "test", 4)                     = 4
write(3, "\n", 1)                       = 1
write(3, "test", 4)                     = 4
write(3, "\n", 1)                       = 1
close(3)                                = 0

You can do the same buffering in Odin, and you should get similar results as C, etc.:

import "core:fmt"
import "core:os"
import "core:bufio"

main :: proc() {
    f, _ := os.open("test.txt", os.O_CREATE)
    stream := os.stream_from_handle(f)
    defer os.close(f)

    w: bufio.Writer
    bufio.writer_init(&w, {stream}, 4096)
    defer bufio.writer_flush(&w)

    for _ in 0..<5000 {
        bufio.writer_write_string(&w, "test\n")
    }
}

Which will run much faster (microseconds), with a similar syscall profile:

open("test.txt", O_RDWR|O_CREAT, 000)   = 3
write(3, "test\ntest\ntest\ntest\ntest\ntest\nte"..., 4096) = 4096
write(3, "est\ntest\ntest\ntest\ntest\ntest\ntes"..., 4096) = 4096
write(3, "st\ntest\ntest\ntest\ntest\ntest\ntest"..., 4096) = 4096
write(3, "t\ntest\ntest\ntest\ntest\ntest\ntest\n"..., 4096) = 4096
write(3, "\ntest\ntest\ntest\ntest\ntest\ntest\nt"..., 4096) = 4096
write(3, "test\ntest\ntest\ntest\ntest\ntest\nte"..., 4096) = 4096
write(3, "est\ntest\ntest\ntest\ntest\ntest\ntes"..., 424) = 424
close(3)                                = 0

I would give that a try, then we can maybe investigate further if there is still a significant difference 😺

[z64]

I would also be careful, if you're timing odin run test.odin -file, that will include the time to compile your program! The Odin compiler is much slower than other C compilers, so to give a fair chase, I would make sure you are timing the built executable test.exe.

[hotgluebanjo]

Ah! That makes sense. I did a quick test and it's identical to C for me. I had looked around a bit for a buffered writer but probably missed that one. Now I know.

I would also be careful, if you're timing odin run test.odin -file, that will include the time to compile your program!

I should have mentioned that that time was of the standalone executable. Not sure why I put odin run actually. But relative to a 21-second running time, time spent compiling is pretty negligible anyway.

Thanks for the help!