High disk write and I/O after enabling Query History

[jpastuszek]

I get a very high disk write and I/O write operations after enabling query history (even if using very high threshold so no queries are logged to the history table), using:

call sys.querylog_enable(10000);

I have a constant rate of inserts to the DB (around 30 records/s). This generates around 1.5 MB/s write about 40 I/O write operation per second to the main storage.

The moment I enabled the query history log (even with a high threshold) I get ~100MB/s write rate and ~1000 I/O write operations per second to the storage all the time.

This makes the feature not very useful in my use-case as it will have a significant impact on performance. I was also hoping to use it as a "slow query log" by giving a relatively high threshold value.

I had a look at system call count (with strace) and with the log disabled a typical 10 second work load looks like:

  72012 clock_gettime
   6063 poll
   3852 futex
   1074 write
    802 read
    728 rt_sigprocmask
    364 clone
     18 fdatasync
     10 lseek
      4 mremap

but with it enabled it looks like:

  57100 clock_gettime
  23442 write
  23336 read
   4923 poll
   3318 futex
    624 rt_sigprocmask
    312 clone
     42 rename
     42 close
     35 lseek
     28 openat
     28 open
     28 munmap
     28 mmap
     28 getdents
     28 fstat
     27 fdatasync
     14 unlink
     14 rmdir
     14 mkdir
     14 fcntl
      2 mremap

Looking at the opens and write what it does is:

openat(AT_FDCWD, "/var/lib/monetdb/data/default/logs/bat/DELETE_ME", O_RDONLY|O_NONBLOCK|O_DIRECTORY|O_CLOEXEC) = 30
getdents(30, /* 3 entries */, 32768)    = 80
unlink("/var/lib/monetdb/data/default/logs/bat/DELETE_ME/BBP.dir") = 0
getdents(30, /* 0 entries */, 32768)    = 0
close(30)                               = 0
rmdir("/var/lib/monetdb/data/default/logs/bat/DELETE_ME") = 0
clock_gettime(CLOCK_REALTIME, {1637340440, 451079009}) = 0
rename("/var/lib/monetdb/data/default/logs/bat/BBP.dir", "/var/lib/monetdb/data/default/logs/bat/BACKUP/BBP.dir") = 0

and

openat(AT_FDCWD, "/var/lib/monetdb/data/default/logs/bat/BACKUP/SUBCOMMIT", O_RDONLY|O_NONBLOCK|O_DIRECTORY|O_CLOEXEC) = -1 ENOENT (No such file o
r directory)
mkdir("/var/lib/monetdb/data/default/logs/bat/BACKUP/SUBCOMMIT", 0777) = 0
clock_gettime(CLOCK_REALTIME, {1637340441, 481343818}) = 0
rename("/var/lib/monetdb/data/default/logs/bat/BACKUP/BBP.dir", "/var/lib/monetdb/data/default/logs/bat/BACKUP/SUBCOMMIT/BBP.dir") = 0
open("/var/lib/monetdb/data/default/logs/bat/BBP.dir", O_WRONLY|O_CREAT|O_CLOEXEC, 0666) = 30
fcntl(30, F_GETFL)                      = 0x8001 (flags O_WRONLY|O_LARGEFILE)
open("/var/lib/monetdb/data/default/logs/bat/BACKUP/SUBCOMMIT/BBP.dir", O_RDONLY) = 31
fstat(31, {st_mode=S_IFREG|0600, st_size=6583714, ...}) = 0
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f7f931b1000
read(31, "BBP.dir, GDKversion 25124\n8 8 16"..., 4096) = 4096
fstat(30, {st_mode=S_IFREG|0600, st_size=0, ...}) = 0
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f7f931b0000
read(31, "4096 0 9223372036854775808 92233"..., 4096) = 4096
write(30, "BBP.dir, GDKversion 25124\n8 8 16"..., 4096) = 4096
read(31, "0 1153 0 0 0 0 92233720368547758"..., 4096) = 4096
write(30, "4096 0 9223372036854775808 92233"..., 4096) = 4096
read(31, " 1048576 0 str 2 1 0 0 0 0 0 922"..., 4096) = 4096
write(30, "0 1153 0 0 0 0 92233720368547758"..., 4096) = 4096
read(31, "036854775808 11371 16384 0\n171 3"..., 4096) = 4096
write(30, " 1048576 0 str 2 1 0 0 0 0 0 922"..., 4096) = 4096
read(31, "362 40448 0 int 4 0 0 0 0 0 0 92"..., 4096) = 4096
write(30, "036854775808 11371 16384 0\n171 3"..., 4096) = 4096
read(31, "5808 0 2048 0 922337203685477580"..., 4096) = 4096
write(30, "362 40448 0 int 4 0 0 0 0 0 0 92"..., 4096) = 4096
read(31, "0 0 9223372036854775808 2 1024 0"..., 4096) = 4096
write(30, "5808 0 2048 0 922337203685477580"..., 4096) = 4096
read(31, "4 32 tmp_460 04/460 2 10 1024 0 "..., 4096) = 4096
write(30, "0 0 9223372036854775808 2 1024 0"..., 4096) = 4096
read(31, " 1490871 1572864 0 str 4 1 2048 "..., 4096) = 4096
write(30, "4 32 tmp_460 04/460 2 10 1024 0 "..., 4096) = 4096

and many more writes.

So this looks like it is re-writing (updating?) the bat/BBP.dir like 3 times per second with the query log feature enabled. That would explain the I/O load as the size of the BBP.dir file is 6.3M on my system.

This is on MonetDB Jul2021-SP1 release.

[yzchang]

Hai Jakub,

This is more or less expected and independent of the MonetDB version. Query history stores the information persistently, which effectively turns every transaction into an update, my least favourite part about this feature.

Improving query history has been on our todo list for a long time, but so far, we haven't received sufficient request to increase its priority.

If you only need to look back for a short time, you can use sys.queue(), which only keeps a transient list of N most recently finished queries and the ongoing queries.