www.digitalmars.com         C & C++   DMDScript  

digitalmars.D.bugs - [Issue 8219] New: File.writeln is slow

reply d-bugmail puremagic.com writes:
http://d.puremagic.com/issues/show_bug.cgi?id=8219

           Summary: File.writeln is slow
           Product: D
           Version: D2
          Platform: All
        OS/Version: All
            Status: NEW
          Severity: enhancement
          Priority: P2
         Component: Phobos
        AssignedTo: nobody puremagic.com
        ReportedBy: bearophile_hugs eml.cc



A little benchmark to show the low performance of the
std.stdio.File().writeln() with numbers. The programs accept N from the command
line, and just save a textual file (opened as binary file) that contains
numbers from 0 to N-1. 

The write1 program is the basic one that uses File.writeln(). The successive
programs are for comparison.

The write2 program is equally basic, but it uses C functions, using the same D
compiler and compilation arguments, and it's almost 12 times faster.

The write3 program is a basic Java program, it's more than 17 times faster than
write1.

The write4 is a test to write a very fast D program, it's more than 30 times
faster than write2 (it's not the fastest possible program because the DMD
compiler is currently not able to perform the small dividend optimization. GCC
and Clang are able to replace the small dividend with some faster operations).


DMD 2.060alpha, Windows, -O -release -inline
Java 1.7.0_03-b05

Timings, N = 2_000_000, best of 3, seconds:
  write1: 9.67
  write2: 0.83 
  write3: 0.56 (Java)
  write4: 0.32

- - - - - - - - - - - - - - - - - - - - - - - - -

// write1
import std.stdio, std.conv;

void main(string[] args) {
    auto f = File("numbers.txt", "wb");
    foreach (i; 0 .. args[1].to!int())
        f.writeln(i);
    f.close();
}

- - - - - - - - - - - - - - - - - - - - - - - - -

// write2
import core.stdc.stdio, std.conv;

void main(string[] args) {
    auto f = fopen("numbers.txt", "wb");
    foreach (i; 0 .. args[1].to!int())
        fprintf(f, "%d\n", i);
    fclose(f);
}

- - - - - - - - - - - - - - - - - - - - - - - - -

// write3
import java.io.BufferedWriter;
import java.io.FileWriter;
import java.io.IOException;

class write3 {
    public static void main(String args[]) {
        if (args.length != 1)
            System.exit(-1);
        int count = Integer.parseInt(args[0]);

        try {
            BufferedWriter bw = new BufferedWriter(new
FileWriter("numbers.txt"));

            for (int i = 0; i < count; i++) {
                bw.write(i);
                bw.write("\n");
            }

            bw.close();
        } catch (IOException e) {
            System.exit(-2);
        }
    }
}

- - - - - - - - - - - - - - - - - - - - - - - - -

// write4
import core.stdc.stdio, std.conv, std.typetuple;

void saveNumbers(uint buf_size)(FILE* f, in uint n, in uint start) nothrow {
    __gshared static char[buf_size] buffer = void;
    __gshared static immutable string digits = "0123456789";
    char* ptr = buffer.ptr;

    foreach (k; start .. start + n) {
        uint v = k;
        if (v >= 0 && v < 10) {
            *ptr = digits[v];
            ptr++;
        } else {
            if (v < 0) {
                v = -v;
                *ptr = '-';
                ptr++;
            }

            char* start_ptr = ptr;

            foreach (_; TypeTuple!(0,1,2,3,4,5,6,7,8,9)) {
                // DMD doesn't know how to perform a fast division
                // or modulus when the quotient is a small integer
                *ptr = (v % 10) + '0';
                v /= 10;
                ptr++;
                if (!v) break;
            }

            immutable size_t i = ptr - start_ptr;
            for (size_t j = 0; j < i / 2; ++j) {
                immutable aux = start_ptr[j];
                start_ptr[j] = start_ptr[i - j - 1];
                start_ptr[i - j - 1] = aux;
            }
        }
        *ptr = '\n';
        ptr++;
    }

    *ptr = '\0';
    fputs(buffer.ptr, f);
}

void main(in string[] args) {
    auto f = fopen("numbers.txt", "wb");
    if (args.length != 2 || f == null) return;
    immutable uint N = to!uint(args[1]);

    enum uint max_int_len = 12;
    enum uint buf_size = 1_000_000;
    enum uint M = buf_size / max_int_len;

    uint count;
    foreach (_0; 0 .. N / M) {
        saveNumbers!buf_size(f, M, count);
        count += M;
    }
    saveNumbers!buf_size(f, N % M, count);

    fclose(f);
}

- - - - - - - - - - - - - - - - - - - - - - - - -

-- 
Configure issuemail: http://d.puremagic.com/issues/userprefs.cgi?tab=email
------- You are receiving this mail because: -------
Jun 11 2012
next sibling parent d-bugmail puremagic.com writes:
http://d.puremagic.com/issues/show_bug.cgi?id=8219


Denis Shelomovskij <verylonglogin.reg gmail.com> changed:

           What    |Removed                     |Added
----------------------------------------------------------------------------
                 CC|                            |verylonglogin.reg gmail.com



20:35:29 MSD ---
Looks like Marco Righele was the first with this issue:
http://forum.dlang.org/thread/mailman.257.1281550251.13841.digitalmars-d puremagic.com

Fix added to
https://github.com/D-Programming-Language/phobos/pull/778

From commit message:
There is absolutely no need to explicitly flush a stream on new line because it
is expected only for console output which is line buffered or unbuffered by
default.

P.S.
I have no idea how such performance killer was added but with a fix of this
issue we will finally get non-“considered out-dated” file IO suitable for
simple programs with text output.

-- 
Configure issuemail: http://d.puremagic.com/issues/userprefs.cgi?tab=email
------- You are receiving this mail because: -------
Sep 11 2012
prev sibling next sibling parent d-bugmail puremagic.com writes:
http://d.puremagic.com/issues/show_bug.cgi?id=8219




Commit pushed to master at https://github.com/D-Programming-Language/phobos

https://github.com/D-Programming-Language/phobos/commit/e281d8deaa8e6adbc42ee5f6dd69d303a7d67b58
Fix Issue 8219 - File.writeln is slow

There is absolutely no need to explicitly flush a stream on new line because it
is expected only for console output which is line buffered or unbuffered by
default.

-- 
Configure issuemail: http://d.puremagic.com/issues/userprefs.cgi?tab=email
------- You are receiving this mail because: -------
Oct 04 2012
prev sibling next sibling parent d-bugmail puremagic.com writes:
http://d.puremagic.com/issues/show_bug.cgi?id=8219




Now the runtime for the write1 D benchmark is 1.12 seconds, it's a significant
improvement.

When N = 10_000_000 the D version takes about 5.61 seconds, while the Java
program takes (including the start of the JVM) about 2.33 seconds, so it's
about 2.4 times faster.

Do you want me/suggest me to close this issue?

-- 
Configure issuemail: http://d.puremagic.com/issues/userprefs.cgi?tab=email
------- You are receiving this mail because: -------
Oct 04 2012
prev sibling next sibling parent d-bugmail puremagic.com writes:
http://d.puremagic.com/issues/show_bug.cgi?id=8219


Andrei Alexandrescu <andrei metalanguage.com> changed:

           What    |Removed                     |Added
----------------------------------------------------------------------------
                 CC|                            |andrei metalanguage.com



11:08:53 PDT ---
Let's keep this open, we should achieve parity with the best out there. Thanks
bearophile and Denis for your work on this.

-- 
Configure issuemail: http://d.puremagic.com/issues/userprefs.cgi?tab=email
------- You are receiving this mail because: -------
Oct 04 2012
prev sibling next sibling parent d-bugmail puremagic.com writes:
http://d.puremagic.com/issues/show_bug.cgi?id=8219




14:44:55 PDT ---
bearophile, I committed
https://github.com/D-Programming-Language/phobos/commit/28e1c98d69a0258992068f4410bdd62c46f5474a
could you please compare again against everything?

-- 
Configure issuemail: http://d.puremagic.com/issues/userprefs.cgi?tab=email
------- You are receiving this mail because: -------
Oct 04 2012
prev sibling next sibling parent d-bugmail puremagic.com writes:
http://d.puremagic.com/issues/show_bug.cgi?id=8219







 could you please compare again against everything?


I have re-compiled druntime and Phobos (but not dmd, because in the meantime it
has not changed), and my run-time for the write1 with N=2_000_000 is about the
same. The run-time with N=10_000_000 seems a little lower, 5.55 seconds (but
changes with similar magnitude are sometimes just noise, so it's not
significant).

Those timings are just one data point (32 bit Windows, Core 2). If we you want
to optimize textual output, then probably more data points are needed, with a
Core i7, on 64 bits, and on a Linux. And probably a profiling is useful.

-------------------

The optimization stages of GCC and Clang contain an algorithm that turn small
dividend (division and modulus) operations in a faster combination of simpler
operations. This is handy in all kind of code, and it's also quite useful in
code like:

auto c = cast(uint) (v % 10);
v /= 10;

Some info:
http://www.hackersdelight.org/divcMore.pdf

-- 
Configure issuemail: http://d.puremagic.com/issues/userprefs.cgi?tab=email
------- You are receiving this mail because: -------
Oct 04 2012
prev sibling next sibling parent d-bugmail puremagic.com writes:
http://d.puremagic.com/issues/show_bug.cgi?id=8219






 could you please compare again against everything?


Andrei, unfortunately I think there is a bug in your code, this prints "1-":


import std.stdio: writeln;
void main() {
    writeln(-1);
}


I think Phobos needs more unittests :-(

-- 
Configure issuemail: http://d.puremagic.com/issues/userprefs.cgi?tab=email
------- You are receiving this mail because: -------
Oct 06 2012
prev sibling parent d-bugmail puremagic.com writes:
http://d.puremagic.com/issues/show_bug.cgi?id=8219




19:52:20 PDT ---
Thanks, Brad fixed it (and added a unittest). I'm not that bright.

-- 
Configure issuemail: http://d.puremagic.com/issues/userprefs.cgi?tab=email
------- You are receiving this mail because: -------
Oct 06 2012