[rrd-developers] Use of madvise / msync kills performance for me
Tobias Oetiker
tobi at oetiker.ch
Thu Jun 26 07:30:03 CEST 2008
Hi Marcus,
Have you tried compiling rrrdtool without mmapping ? Note that
removing msync is BAD. Have a look at the manual page.
msync() flushes changes made to the in-core copy of a
file that was mapped into memory using mmap(2) back to disk.
Without use of this call there is no guarantee that changes
are written back before munmap(2) is called.
Obviously it will be faster without this call, but then again,
the price (potential file corruption) might be a bit high.
Why some of the madvise calls are are taking so long is unclear to
me. You might want to try only to drop the WILLNEED calls only and not
the RANDOM since it is crucial in preserving cache memory ...
My guess is that the WILLNEED calls actually cause data to be read
which saves you time later on, your trace does not give absolute
time, it would be interesting to see that too.
cheers
tobi
Yesterday Marcus Reid wrote:
> 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 ----
>
> _______________________________________________
> rrd-developers mailing list
> rrd-developers at lists.oetiker.ch
> https://lists.oetiker.ch/cgi-bin/listinfo/rrd-developers
>
>
--
Tobi Oetiker, OETIKER+PARTNER AG, Aarweg 15 CH-4600 Olten
http://it.oetiker.ch tobi at oetiker.ch ++41 62 775 9902
More information about the rrd-developers
mailing list