thr3ads.net - freebsd stable - Performance of madvise / msync [Jun 2008]

If this information is useful, please help other people find it:
Share via:

Marcus Reid

2008-Jun-27 00:11 UTC

Performance of madvise / msync

Hi,

I'm using py-rrdtool 0.2.1 with rrdtool 1.3.0 under 7.0-STABLE, and
there's a couple of things about this new version of rrdtool that
hurt performance under FreeBSD, but apparently help on whatever they
tested on.

For every update, the database file is opened, mapped into memory,
madvise() is called, contents are modified, msync() is called, and
the file is unmapped and closed:

   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

Here's a similar update without the calls to madvise and 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

As you can see, it's quite a bit faster.

I know that msync is necessary under Linux but obsolete under FreeBSD, but
it's still funny that it takes a tenth of a second to return even with
MS_ASYNC specified.

Also, why is it that the madvise() calls take so much longer when the
program does a couple of its own madvise() calls?  Was madvise() never
intended to be run so frequently and is therefore a little slower than
it could be?

Here's the diff between the code for the first kdump above and the
second one.

*** 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 ----

Thanks,

Marcus

Matthew Dillon

2008-Jun-27 00:48 UTC

head link

Performance of madvise / msync

:   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.006084 CALL  msync(0x287c5000,0x453b7618,MS_ASYNC)
:   65074 python   0.106284 RET   msync 0
:...
:As you can see, it's quite a bit faster.
:
:I know that msync is necessary under Linux but obsolete under FreeBSD, but
:it's still funny that it takes a tenth of a second to return even with
:MS_ASYNC specified.
:
:Also, why is it that the madvise() calls take so much longer when the
:program does a couple of its own madvise() calls?  Was madvise() never
:intended to be run so frequently and is therefore a little slower than
:it could be?
:
:Here's the diff between the code for the first kdump above and the
:second one.

     Those times are way way too large, even with other running threads
     in the system.  madvise() should not take that long unless it is
     being forced to wait on a busied page, and neither should msync().
     madvise() doesn't even do any I/O (or shouldn't anyhow).

     Try removing just the msync() but keep the madvise() calls and see
     if the madvise() calls continue to take horrendous amounts of time.
     Then try the vise-versa.

     It kinda feels like a prior msync() is initiating physical I/O on
     pages and a later mmap/madvise or page fault is being forced to
     wait on the prior pages for the I/O to finish.

     The size_t argument to msync() (0x453b7618) is highly questionable.
     It could be ktrace reporting the wrong value, but maybe not.
     On any sort of random writing test, particularly if multiple threads
     are involved, specifying a size that large could result in very large
     latencies.

					-Matt

Apparently Analagous Threads

Search for more reasonably related threads

freebsd stable - Jun 2008 - Performance of madvise / msync

Performance of madvise / msync

Performance of madvise / msync

Apparently Analagous Threads