disk write performance in golang

Question

In the following code, I write messages to a file using bufio in golang. My disk I/O speed is about 1000M/s. Strangely, when the size of the written file is less than 20G, the writing speed is about 800M~900M per second, a little bit less than the I/O speed. But, when the file size is more than 21G, I found the writing speed is about 200M per second, much less than the I/O speed. I don't know why, anybody can help me? Thank you.

package main

import "fmt"
import (
    "os"
    "time"
    "flag"
    "bufio"
)

func main() {
    var pRound = flag.Int64("round", 3500000, "loop round")
    flag.Parse()

    var message string
    for i := 0; i < 1024; i++ {
        message += "1234567890"
    }
    message += "\n"

    f, err := os.OpenFile("server", os.O_CREATE|os.O_APPEND|os.O_RDWR, 0666)
    if err != nil {
        fmt.Println(err)
        return
    }
    w := bufio.NewWriter(f)

    var i int64 = 0
    round := *pRound
    start := time.Now()
    for i = 0; i < round; i++ {
        w.WriteString(message)
    }
    w.Flush()
    f.Close()
    end := time.Now()

    nanoseconds := end.Sub(start).Nanoseconds()
    speed := 1000000000 * round / nanoseconds

    fmt.Printf("round: %v\n", round)
    fmt.Printf("Nanoseconds: %v\n", nanoseconds)
    fmt.Printf("speed: %v\n", speed)
}

I think I have asked a foolish question. On the response of Vorsprung, I show my C code here. And I test it again in C language. I find the same result with go language. My test result is:

./a.out 10000
seconds: 7
milliseconds: 260910
total: 10485760000 Bytes
total: 10000 M
total: 9.76562 G
speed: 1377.24 M/s


./a.out 20000
seconds: 24
milliseconds: 7249
total: 20971520000 Bytes
total: 20000 M
total: 19.5312 G
speed: 833.082 M/s


./a.out 30000
seconds: 80
milliseconds: 518970
total: 31457280000 Bytes
total: 30000 M
total: 29.2969 G
speed: 372.583 M/s



./a.out 40000
seconds: 134
milliseconds: 615910
total: 41943040000 Bytes
total: 40000 M
total: 39.0625 G
speed: 297.142 M/s

The following is my C code:

#include <fcntl.h>
#include <errno.h>
#include <limits.h>
#include <sys/uio.h>
#include <time.h>
#include <sys/time.h>
#include <iostream>
#include <string.h>
#include <stdlib.h>

int main(int argc, char* argv[]) {
  if (argc != 2) {
    std::cout << "usage: " << argv[0] << " round" << std::endl;
    return -1;
  }
  int round = atoi(argv[1]);

  int fd = open("file.data", O_CREAT | O_APPEND | O_RDWR, 0666);
  if (fd == -1) {
    std::cout << "open file error: " << strerror(errno) << std::endl;
    return -1;
  }

  struct iovec vec[IOV_MAX];
  int len = 1024;
  for (int i = 0; i < IOV_MAX; i++) {
    vec[i].iov_base = new char[len];
    vec[i].iov_len = len;

    char *buf = NULL;
    for (int j = 0; j < len - 1; j++) {
      buf = (char*)vec[i].iov_base;
      buf[j] = j % 10 + '1';
    }
    buf[len - 1] = '\n';
  }

  timeval tv1;
  gettimeofday(&tv1, NULL);
  for (int i = 0; i < round; i++) {
    writev(fd, vec, IOV_MAX);
  }

  close(fd);

  timeval tv2;
  gettimeofday(&tv2, NULL);

  for (int i = 0; i < IOV_MAX; i++) {
     char* buf = (char*)vec[i].iov_base;
     delete[] buf;
  }

  std::cout << "seconds: " << tv2.tv_sec - tv1.tv_sec << std::endl;
  std::cout << "milliseconds: " << tv2.tv_usec - tv1.tv_usec << std::endl;
  int64_t total = int64_t(len) * IOV_MAX * round;
  float t = (tv2.tv_sec - tv1.tv_sec) * 1000000.0 + (tv2.tv_usec - tv1.tv_usec);
  float speed = 1000000.0 * total / t / 1024 / 1024;
  std::cout << "total: " << total << " Bytes" << std::endl;
  std::cout << "total: " << total / 1024.0 / 1024.0 << " M" << std::endl;
  std::cout << "total: " << total / 1024.0 / 1024.0 / 1024.0 << " G" << std::endl;
  std::cout << "speed: " << speed << " M/s" << std::endl;
  return 0;
}

Now my diskio.go test result show here. because I don't know how to comment a easy-reading result in comment, I show it here.

time ./diskio -size=4
written: 4294967296B 26237051975ns 4.29GB 26.24s 163.70MB/s
real    0m26.980s
user    0m0.397s
sys     0m4.874s


time ./diskio -size=8
written: 8589934592B 57803019028ns 8.59GB 57.80s 148.61MB/s
real    0m59.192s
user    0m0.813s
sys     0m9.607s



time ./diskio -size=10
written: 10737418240B 68331989999ns 10.74GB 68.33s 157.14MB/s
real    1m10.288s
user    0m0.946s
sys     0m12.024s




time ./diskio -size=20
written: 21474836480B 141169506440ns 21.47GB 141.17s 152.12MB/s
real    2m25.037s
user    0m1.881s
sys     0m24.029s


time ./diskio -size=30
written: 32212254720B 203807569664ns 32.21GB 203.81s 158.05MB/s
real    3m29.345s
user    0m2.925s
sys     0m33.528s

diskio.go comes from https://stackoverflow.com/a/47889346/5616809

I think I get the answer, the testing result is caused by the disk buffer reason. I tested my disk speed using hdparm commend, and I got this:

hdparm -Tt /dev/sde1
/dev/sde1:
Timing cached reads:   18166 MB in  2.00 seconds = 9093.93 MB/sec
Timing buffered disk reads: 584 MB in  3.01 seconds = 194.18 MB/sec

So maybe my program is writting bytes to buffer when file size is less than about 18166M. After that the program is writting to the disk, so it's speed is slower.

Answer 1

Your issue is not reproducible. Your code has bugs.

We would expect that disk write time would be affected by a number of factors: the program, other programs, the operating system, hardware, and so on.

Boot a standalone, dedicated machine, and run the diskio.go program. What results do you get? For example, on my machine:

$ go build diskio.go
$ time ./diskio -size=32
written: 34359738368B 154333936544ns 34.36GB 154.33s 222.63MB/s
real    2m35.323s
user    0m6.418s
sys     0m41.994s
$ time ./diskio -size=16
written: 17179869184B 77901269159ns 17.18GB 77.90s 220.53MB/s
real    1m18.746s
user    0m2.849s
sys     0m21.721s
$ time ./diskio -size=8
written: 8589934592B 38940248134ns 8.59GB 38.94s 220.59MB/s
real    0m39.625s
user    0m1.719s
sys     0m12.493s
$ time ./diskio -size=1
written: 1073741824B 4738082404ns 1.07GB 4.74s 226.62MB/s
real    0m4.851s
user    0m0.069s
sys     0m0.755s
$ 

As expected, little time is spent in the program, more time is spent in the operating system, a lot of time is spent waiting on the disk. There is no precipitous change in write speed.

diskio.go:

package main

import (
    "bufio"
    "flag"
    "fmt"
    "os"
    "time"
)

func writeFile(fSize int64) error {
    fName := `/home/peter/diskio` // test file
    defer os.Remove(fName)
    f, err := os.Create(fName)
    if err != nil {
        return err
    }
    const defaultBufSize = 4096
    buf := make([]byte, defaultBufSize)
    buf[len(buf)-1] = '\n'
    w := bufio.NewWriterSize(f, len(buf))

    start := time.Now()
    written := int64(0)
    for i := int64(0); i < fSize; i += int64(len(buf)) {
        nn, err := w.Write(buf)
        written += int64(nn)
        if err != nil {
            return err
        }
    }
    err = w.Flush()
    if err != nil {
        return err
    }
    err = f.Sync()
    if err != nil {
        return err
    }
    since := time.Since(start)

    err = f.Close()
    if err != nil {
        return err
    }
    fmt.Printf("written: %dB %dns %.2fGB %.2fs %.2fMB/s\n",
        written, since,
        float64(written)/1000000000, float64(since)/float64(time.Second),
        (float64(written)/1000000)/(float64(since)/float64(time.Second)),
    )
    return nil
}

var size = flag.Int("size", 8, "file size in GiB")

func main() {
    flag.Parse()
    fSize := int64(*size) * (1024 * 1024 * 1024)
    err := writeFile(fSize)
    if err != nil {
        fmt.Fprintln(os.Stderr, fSize, err)
    }
}

Playground: https://play.golang.org/p/vnjnpgMzsV