Re: [HACKERS] WAL logging problem in 9.4.3?

At Tue, 27 Aug 2019 15:49:32 +0900 (Tokyo Standard Time), Kyotaro Horiguchi <horikyota.ntt@gmail.com> wrote in
<20190827.154932.250364935.horikyota.ntt@gmail.com>
> 128GB shared buffers contain 16M buffers. On my
> perhaps-Windows-Vista-era box, such loop takes 15ms. (Since it
> has only 6GB, the test is ignoring the effect of cache that comes
> from the difference of the buffer size). (attached 1)
...
> For a 16MB file, the cost of write-fsyncing cost is almost the
> same to that of WAL-emitting cost. It was about 200 ms on the
> Vista-era machine with non-performant rotating magnetic disks
> with xfs. (attached 2, 3) Although write-fsyncing of relation
> file makes no lock conflict with other backends, WAL-emitting
> delays other backends' commits at most by that milliseconds.

FWIW, the attached are the programs I used to take the numbers.

testloop.c: to take time to loop over buffers in FlushRelationBuffers

testfile.c: to take time to sync a heap file. (means one file for the size)

testfile2.c: to take time to emit a wal record. (means 16MB per file)

regards.

-- 
Kyotaro Horiguchi
NTT Open Source Software Center
#include <stdio.h>
#include <stdlib.h>
#include <sys/time.h>

typedef struct RelFileNode
{
  unsigned int spc;
  unsigned int db;
  unsigned int rel;
} RelFileNode;

typedef struct Buffer
{
  RelFileNode rnode;
} Buffer;

//#define NBUFFERS ((int)((128.0 * 1024 * 1024 * 1024) / (8.0 * 1024)))
#define NBUFFERS ((int)((32.0 * 1024 * 1024 * 1024) / (8.0 * 1024)))
int main(void) {
  int i;
  RelFileNode t = {1,2,3};
  Buffer *bufs = (Buffer *) malloc(sizeof(Buffer) * NBUFFERS);
  struct timeval st, ed;
  int matches = 0, unmatches = 0;
  Buffer *b;

  for (i = 0 ; i < NBUFFERS ; i++) {
    bufs[i].rnode.spc = random() * 100;
    bufs[i].rnode.db = random() * 100;
    bufs[i].rnode.rel = random() * 10000;
  }

  /* start measuring */
  gettimeofday(&st, NULL);

  b = bufs;
  for (i = 0 ; i < NBUFFERS ; i++) {
    if (b->rnode.spc == t.spc && b->rnode.db == t.db && b->rnode.rel == t.rel)
      matches++;
    else
      unmatches++;

    b++;
  }
  gettimeofday(&ed, NULL);

  printf("%lf ms for %d loops, matches %d, unmatches %d\n",
         (double)((ed.tv_sec - st.tv_sec) * 1000.0 +
                  (ed.tv_usec - st.tv_usec) / 1000.0),
         i, matches, unmatches);

  return 0;
}
#include <stdio.h>
#include <stdlib.h>
#include <unistd.h>
#include <string.h>
#include <sys/time.h>
#include <fcntl.h>

//#define FILE_SIZE (16 * 1024 * 1024)
//#define LOOPS 100

#define FILE_SIZE (64 * 1024)
#define LOOPS 1000

//#define FILE_SIZE (8 * 1024)
//#define LOOPS 1000

//#define FILE_SIZE (1 * 1024)
//#define LOOPS 1000

//#define FILE_SIZE (512)
//#define LOOPS 1000

//#define FILE_SIZE (128)
//#define LOOPS 1000

char buf[FILE_SIZE];
char fname[256];

int main(void) {
  int i, j;
  int fd = -1;
  struct timeval st, ed;
  double accum = 0.0;
  int bufperfile = (int)((16.0 * 1024 * 1024) / FILE_SIZE);

  for (i = 0 ; i < LOOPS ; i++) {
    snprintf(fname, 256, "test%03d.file", i);
    unlink(fname); // ignore errors
  }

  for (i = 0 ; i < LOOPS ; i++) {
    for (j = 0 ; j < FILE_SIZE ; j++)
      buf[j] = random()* 256;

    if (i % bufperfile == 0) {
      if (fd >= 0)
        close(fd);

      snprintf(fname, 256, "test%03d.file", i / bufperfile);
      fd = open(fname, O_CREAT | O_RDWR, 0644);
      if (fd < 0) {
        fprintf(stderr, "open error: %m\n");
        exit(1);
      }
      memset(buf, 0, sizeof(buf));
      if (write(fd, buf, sizeof(buf)) < 0) {
        fprintf(stderr, "init write error: %m\n");
        exit(1);
      }
      if (fsync(fd) < 0) {
        fprintf(stderr, "init fsync error: %m\n");
        exit(1);
      }
      if (lseek(fd, 0, SEEK_SET) < 0) {
        fprintf(stderr, "init lseek error: %m\n");
        exit(1);
      }
      
    }

    gettimeofday(&st, NULL);
    if (write(fd, buf, FILE_SIZE) < 0) {
      fprintf(stderr, "write error: %m\n");
      exit(1);
    }
    if (fdatasync(fd) < 0) {
      fprintf(stderr, "fdatasync error: %m\n");
      exit(1);
    }
    gettimeofday(&ed, NULL);

    accum += (double)((ed.tv_sec - st.tv_sec) * 1000.0 +
                      (ed.tv_usec - st.tv_usec) / 1000.0);
  }

  printf("%.2lf ms for %d %dkB-records (%d MB), %.2lf ms per %dkB)\n",
         accum, i, FILE_SIZE / 1024, i * FILE_SIZE, accum / i, FILE_SIZE / 1024);

  return 0;
}

#include <stdio.h>
#include <stdlib.h>
#include <unistd.h>
#include <sys/time.h>
#include <fcntl.h>

//#define FILE_SIZE (16 * 1024 * 1024)
//#define LOOPS 100

//#define FILE_SIZE (8 * 1024)
//#define LOOPS 1000

//#define FILE_SIZE (1 * 1024)
//#define LOOPS 1000

//#define FILE_SIZE (512)
//#define LOOPS 1000

#define FILE_SIZE (128)
#define LOOPS 1000

char buf[FILE_SIZE];

int main(void) {
  int i;
  int fd = -1;
  double accum = 0.0;
  struct timeval st, ed;

  for (i = 0 ; i < LOOPS ; i++) {
    char fname[256];
    snprintf(fname, 256, "test%03d.file", i);
    unlink(fname); // ignore errors
  }

  for (i = 0 ; i < LOOPS ; i++) {
    char fname[256];
    int j;

    snprintf(fname, 256, "test%03d.file", i);

    for (j = 0 ; j < FILE_SIZE ; j++)
      buf[j] = random()* 256;

    if (fd >= 0)
      close(fd);

    gettimeofday(&st, NULL);
    fd = open(fname, O_CREAT | O_RDWR, 0644);
    if (fd < 0) {
      fprintf(stderr, "open error: %m\n");
      exit(1);
    }

    if (write(fd, buf, FILE_SIZE) < 0) {
      fprintf(stderr, "write error: %m\n");
      exit(1);
    }
    if (fdatasync(fd) < 0) {
      fprintf(stderr, "fdatasync error: %m\n");
      exit(1);
    }

    if (lseek(fd, 0, SEEK_SET) < 0) {
      fprintf(stderr, "lseek error: %m\n");
      exit(1);
    }
    gettimeofday(&ed, NULL);

    accum += (double)((ed.tv_sec - st.tv_sec) * 1000.0 +
                      (ed.tv_usec - st.tv_usec) / 1000.0);
  }

  printf("%.2lf ms for %d %dkB-files (%d MB), %.2lf ms per %dkB)\n",
         accum, i, FILE_SIZE / 1024, i * FILE_SIZE, accum / i, FILE_SIZE / 1024);

  return 0;
}