[rrd-developers] Use of madvise / msync kills performance for me

[Marcus Reid]

Hello,

I'm using py-rrdtool 0.2.1 and rrdtool 1.3.0 under FreeBSD 7.0-STABLE,
and for me madvise and msync really hurts performance.  There might be
a more efficient way of doing things, but for every update the .rrd
file is opened, mapped into memory, written to, and then closed.  Here
is a kdump of an update before commenting out the madvise/msync
code:

   65074 python   0.000009 CALL  open(0x831a1b4,O_RDWR,<unused>0)
   65074 python   0.000013 NAMI  "rg2.rrd"
   65074 python   0.000024 RET   open 7
   65074 python   0.000007 CALL  fstat(0x7,0xbfbfe428)
   65074 python   0.000011 RET   fstat 0
   65074 python   0.000008 CALL  mmap(0,0x453b7618,PROT_READ|PROT_WRITE,MAP_SHARED,0x7,0,0)
   65074 python   0.000018 RET   mmap 679235584/0x287c5000
   65074 python   0.000007 CALL  madvise(0x287c5000,0x453b7618,_MADV_RANDOM)
   65074 python   0.000008 RET   madvise 0
   65074 python   0.000006 CALL  madvise(0x287c5000,0x70,_MADV_WILLNEED)
   65074 python   0.027455 RET   madvise 0
   65074 python   0.000058 CALL  madvise(0x287c5000,0x1c20,_MADV_WILLNEED)
   65074 python   0.016904 RET   madvise 0
   65074 python   0.000179 CALL  madvise(0x287c6000,0x1950,_MADV_WILLNEED)
   65074 python   0.008629 RET   madvise 0
   65074 python   0.000040 CALL  madvise(0x287c8000,0x8,_MADV_WILLNEED)
   65074 python   0.004173 RET   madvise 0
   65074 python   0.000048 CALL  gettimeofday(0xbfbfe554,0)
   65074 python   0.000009 RET   gettimeofday 0
   65074 python   0.000012 CALL  fcntl(0x7,<invalid=12>,0xbfbfe478)
   65074 python   0.000024 RET   fcntl 0
   65074 python   0.006084 CALL  msync(0x287c5000,0x453b7618,MS_ASYNC)
   65074 python   0.106284 RET   msync 0
   65074 python   0.000483 CALL  munmap(0x287c5000,0x453b7618)
   65074 python   0.000356 RET   munmap 0
   65074 python   0.000012 CALL  close(0x7)
   65074 python   0.000046 RET   close 0
   65074 python   0.000173 CALL  __sysctl(0xbfbfe388,0x2,0xbfbfe394,0xbfbfe398,0,0)
   65074 python   0.000016 RET   __sysctl 0

The third column is seconds elapsed relative to last call.

Here's the same thing after applying the following diff to rrd_open.c .  For
some reason there's still some madvise calls going on, but not quite the same
and it takes less time.  Note the absence of the tenth of a second taken up
by msync().

   96372 python   0.000011 CALL  open(0x831aa34,O_RDWR,<unused>0)
   96372 python   0.000016 NAMI  "rg2.rrd"
   96372 python   0.000025 RET   open 7
   96372 python   0.000009 CALL  fstat(0x7,0xbfbfe428)
   96372 python   0.000014 RET   fstat 0
   96372 python   0.000010 CALL  mmap(0,0x453b7618,PROT_READ|PROT_WRITE,MAP_SHARED,0x7,0,0)
   96372 python   0.000021 RET   mmap 679235584/0x287c5000
   96372 python   0.000101 CALL  madvise(0x287c5000,0x1c20,_MADV_WILLNEED)
   96372 python   0.000013 RET   madvise 0
   96372 python   0.000010 CALL  madvise(0x287c6000,0x1950,_MADV_WILLNEED)
   96372 python   0.000010 RET   madvise 0
   96372 python   0.000009 CALL  madvise(0x287c8000,0x8,_MADV_WILLNEED)
   96372 python   0.000009 RET   madvise 0
   96372 python   0.000010 CALL  gettimeofday(0xbfbfe554,0)
   96372 python   0.000009 RET   gettimeofday 0
   96372 python   0.000011 CALL  fcntl(0x7,<invalid=12>,0xbfbfe478)
   96372 python   0.000016 RET   fcntl 0
   96372 python   0.002024 CALL  munmap(0x287c5000,0x453b7618)
   96372 python   0.000366 RET   munmap 0
   96372 python   0.000016 CALL  close(0x7)
   96372 python   0.000046 RET   close 0
   96372 python   0.000108 CALL  __sysctl(0xbfbfe388,0x2,0xbfbfe394,0xbfbfe398,0,0)
   96372 python   0.000017 RET   __sysctl 0

The rate of updates fluctuates a bit, but the OS seems to do a much better
job of managing the IO without interference.

Marcus


*** src/rrd_open.c.orig Tue Jun 10 23:12:55 2008
--- src/rrd_open.c      Wed Jun 25 21:43:54 2008
***************
*** 175,191 ****
  #endif
      if (rdwr & RRD_CREAT)
          goto out_done;
- #ifdef USE_MADVISE
-     if (rdwr & RRD_COPY) {
-         /* We will read everything in a moment (copying) */
-         madvise(data, rrd_file->file_len, MADV_WILLNEED | MADV_SEQUENTIAL);
-     } else {
-         /* We do not need to read anything in for the moment */
-         madvise(data, rrd_file->file_len, MADV_RANDOM);
-         /* the stat_head will be needed soonish, so hint accordingly */
-         madvise(data, sizeof(stat_head_t), MADV_WILLNEED | MADV_RANDOM);
-     }
- #endif
  
      __rrd_read(rrd->stat_head, stat_head_t,
                 1);
--- 175,180 ----
***************
*** 388,396 ****
      int       ret;
  
  #ifdef HAVE_MMAP
-     ret = msync(rrd_file->file_start, rrd_file->file_len, MS_ASYNC);
-     if (ret != 0)
-         rrd_set_error("msync rrd_file: %s", rrd_strerror(errno));
      ret = munmap(rrd_file->file_start, rrd_file->file_len);
      if (ret != 0)
          rrd_set_error("munmap rrd_file: %s", rrd_strerror(errno));
--- 377,382 ----