On Thu, Jul 22, 2004 at 02:27:49PM EDT, Nicolas Rachinsky wrote: > * David Yitzchak Cohen <lists+mutt_users@xxxxxxxxxxxxxx> [2004-07-22 12:50 > -0400]: > > On Thu, Jul 22, 2004 at 10:11:41AM EDT, Nicolas Rachinsky wrote: > > Even with your own box, though, notice how much time is wasted (a) > > in systemcalls and (b) in actual disk I/O. The second open, BTW, > > wouldn't be half as fast if you didn't have 1GB of RAM. (Try 192MB, > > and then we can talk ... hehe. . .) > > Can't try this easily, sorry. NP ... just keep in mind that my inbox is twice the size of my total RAM, while your test mailbox is not even a third of your total RAM. In other words, for me, the first and second opens of a mailbox take virtually identical time. > > Your benchmarks are quoted below in their entirety, for ease of reference. > > > > The following commands were executed on a mbox and maildir containing > > > the same 22959 mails with a total size of 300MB. > > > > > > /usr/bin/time -h -l mutt -F /dev/null -f big.mbox -e 'push x' > > > 10.01s real 2.47s user 0.65s sys > > > 2263 block input operations > > > 0 block output operations > > > > > > /usr/bin/time -h -l mutt -F /dev/null -f big.mbox -e 'push x' > > > 3.12s real 2.42s user 0.35s sys > > > 0 block input operations > > > 0 block output operations > > > > > > > > > > > > /usr/bin/time -h -l mutt -F /dev/null -f big.maildir -e 'push x' > > > 19.51s real 2.42s user 1.99s sys > > > 23598 block input operations > > > 0 block output operations > > > > > > /usr/bin/time -h -l mutt -F /dev/null -f big.maildir -e 'push x' > > > 3.46s real 2.28s user 0.86s sys > > > 0 block input operations > > > 0 block output operations > > > > > > > > > > > > /usr/bin/time -h -l mutt -F /dev/null -f big.maildir -e 'set > > > maildir_cache=cache' -e 'push x' > > > 6.54s real 3.16s user 1.49s sys > > > 2 block input operations > > > 744 block output operations > > > > > > > > > > > > /usr/bin/time -h -l mutt -F /dev/null -f big.maildir -e 'set > > > maildir_cache=cache' -e 'push x' > > > 1.43s real 0.79s user 0.36s sys > > > 0 block input operations > > > 12 block output operations > > > > > > > > > /usr/bin/time -h -l mutt -F /dev/null -f big.maildir -e 'set > > > maildir_cache=cache' -e 'push x' > > > 1.40s real 0.79s user 0.37s sys > > > 0 block input operations > > > 12 block output operations > > > > > > > > > > > > /usr/bin/time -h -l mutt -F /dev/null -f big.maildir -e 'set > > > maildir_cache=cache' -e 'unset maildir_cache_verify' -e 'push x' > > > 1.20s real 0.72s user 0.25s sys > > > 0 block input operations > > > 12 block output operations > > > > > > > > > I removed all except the interessting lines from the time output. > After removing cache the same with another Mailbox containing now > 68244 emails with a total size of 300MB. Okay, now you've got me beat for mail compactness. Let's see what happens: > /usr/bin/time -h -l mutt -F /dev/null -f small.mbox -e 'push x' > 25.82s real 14.87s user 1.81s sys > 4859 block input operations > 0 block output operations Okay, my previous assertion that mbox load time is mostly proportional to mailbox size is clearly totally bogus. I'm guessing the Content-Length header is probably to blame. If you still have the small.mbox lying around, I'd be awfully interested in the results of running the tests on the results after a "egrep -v '^Content-[Ll]ength:'" :-) > /usr/bin/time -h -l mutt -F /dev/null -f small.mbox -e 'push x' > 16.91s real 14.63s user 1.16s sys > 0 block input operations > 0 block output operations Well, in case you forgot, you have 1GB of RAM. You can guess where every last bit of that mbox went after the first time you fetched it ;-) > /usr/bin/time -h -l mutt -F /dev/null -f small.maildir -e 'push x' > 39.63s real 8.73s user 7.21s sys > 68963 block input operations > 0 block output operations It's impressive that maildir is able to keep from falling below 50% of the mbox speed even with >64K mails in a directory (You're on reiserfs, I assume?). Note, though, the syscall time there. We're talking about massive amounts of work being done by your kernel, servicing about 17 times as many read(2)s as the mbox. Also worth noting is the time spent idling while waiting on the disk. The mbox waits for only about 9 seconds, while maildir winds up waiting for almost 24! Clearly, you wouldn't want several users banging away on maildirs at the same time on your system. . . > /usr/bin/time -h -l mutt -F /dev/null -f small.maildir -e 'push x' > 36.66s real 8.61s user 6.52s sys > 68253 block input operations > 0 block output operations Now, isn't that interesting? 1GB of RAM was barely able to cache anything between your opens. (Maybe a cron job or something happened between the two opens? I wasn't expecting the second open to be _that_ bad. . .) Assuming it's not a fluke, somebody on your FS team needs to be blamed: it looks to me like the only thing that was still cached was the directory index itself (and maybe the permission structs in the inode tables). With a whole gigabyte of RAM, I think you have the right to expect better. The system was waiting for a whopping 21 seconds of disk time, to access data that could've easily been cached if Linux only cared enough to :-( > /usr/bin/time -h -l mutt -F /dev/null -f small.maildir -e 'set > maildir_cache=cache' -e 'push x' > 49.13s real 11.19s user 8.64s sys > 68260 block input operations > 644 block output operations Well, yeah, that's to be expected - you're doing a full maildir open, plus concurrent I/O with a cache file. You're simply seeing the penalty for concurrent I/O on an already maxed-out disk system (and the extra user time is obviously just Mutt's headercache calculations). > /usr/bin/time -h -l mutt -F /dev/null -f small.maildir -e 'set > maildir_cache=cache' -e 'push x' > 4.49s real 2.48s user 1.36s sys > 5 block input operations > 12 block output operations This is where maildir with the headercache really shines vs. mbox: we're comparing to a 17-second mbox open in the best-case scenario, or a 26-second mbox open in the worst case ... while maildir+headercache takes only 4.5 seconds (which should marginally improve even further next time, due to OS caching). (Remember, the headercache doesn't self-destruct just because you decided to open a memory-guzzling program for a few minutes between Mutt uses. The mbox cache obviously does.) > /usr/bin/time -h -l mutt -F /dev/null -f small.maildir -e 'set > maildir_cache=cache' -e 'push x' > 4.45s real 2.46s user 1.39s sys > 2 block input operations > 12 block output operations LOL ... I spoke too early ;-) > /usr/bin/time -h -l mutt -F /dev/null -f small.maildir -e 'set > maildir_cache=cache' -e 'unset maildir_cache_verify' -e 'push x' > 3.87s real 2.35s user 0.84s sys > 1 block input operations > 12 block output operations I'm not sure what's happening there, exactly. > BTW: > 136M cache When was that number obtained? I'd expect buffers+cache to be about 300MB after the first mbox read. > And now a third folder, containing 18 emails with a total size of 310MB. Our prediction here is obviously that maildir will trounce mbox, even without the headercache. > /usr/bin/time -h -l mutt -F /dev/null -f monster.mbox -e 'push x' > 0.40s real 0.01s user 0.01s sys > 47 block input operations > 0 block output operations There's no way on Earth that your system can read 310MB off the disk in less than 0.4 seconds! > /usr/bin/time -h -l mutt -F /dev/null -f monster.mbox -e 'push x' > 0.03s real 0.01s user 0.01s sys > 0 block input operations > 0 block output operations I guess it must've taken 0.37 seconds for the physical disk reads :-) > /usr/bin/time -h -l mutt -F /dev/null -f monster.maildir -e 'push x' > 0.16s real 0.01s user 0.00s sys > 39 block input operations > 0 block output operations Why am I not surprised? Maildir here basically amounts to reading the first block or two from each file in a directory - certainly much quicker than hunting through a 310MB file looking for 18 message start points ;-) > /usr/bin/time -h -l mutt -F /dev/null -f monster.maildir -e 'push x' > 0.02s real 0.01s user 0.00s sys > 0 block input operations > 0 block output operations ...and this time, the OS caches everything, too :-) > /usr/bin/time -h -l mutt -F /dev/null -f monster.maildir -e 'set > maildir_cache=cache' -e 'push x' > 0.05s real 0.01s user 0.01s sys > 1 block input operations > 25 block output operations > > > /usr/bin/time -h -l mutt -F /dev/null -f monster.maildir -e 'set > maildir_cache=cache' -e 'push x' > 0.02s real 0.01s user 0.00s sys > 0 block input operations > 12 block output operations > > > /usr/bin/time -h -l mutt -F /dev/null -f monster.maildir -e 'set > maildir_cache=cache' -e 'push x' > 0.03s real 0.01s user 0.00s sys > 0 block input operations > 12 block output operations > > > /usr/bin/time -h -l mutt -F /dev/null -f monster.maildir -e 'set > maildir_cache=cache' -e 'unset maildir_cache_verify' -e 'push x' > 0.02s real 0.01s user 0.00s sys > 0 block input operations > 12 block output operations Those results are more or less to be expected. > The same mbox, but with Content-Length Headers removed: You read my mind ;-) > /usr/bin/time -h -l mutt -F /dev/null -f monster2 -e 'push x' > 13.06s real 1.33s user 1.16s sys > 5001 block input operations > 0 block output operations Well, we now know it takes your system about 13 seconds to read (310MB-sizeof(last_email_body)) off the disk. $ echo $((310/18*17)) #assuming the last email's average size 289 $ echo $((2890/13)) 222 22.2MBps is pretty damn good for real-world disk performance :-) > /usr/bin/time -h -l mutt -F /dev/null -f monster2 -e 'push x' > 2.04s real 1.27s user 0.75s sys > 0 block input operations > 0 block output operations ...and your 1GB of RAM just eats everything right up, of course :-) - Dave > > > PS: > > > Mutt 1.5.6i (2004-02-01) > > > Copyright (C) 1996-2002 Michael R. Elkins and others. > > > Mutt comes with ABSOLUTELY NO WARRANTY; for details type `mutt -vv'. > > > Mutt is free software, and you are welcome to redistribute it > > > under certain conditions; type `mutt -vv' for details. > > > > > > System: FreeBSD 4.10-RELEASE-p2 (i386) [using ncurses 5.1] [using > > > libiconv 1.9] [using libidn 0.5.2 (compiled with 0.5.2)] > > > Compile options: > > > -DOMAIN > > > -DEBUG > > > -HOMESPOOL +USE_SETGID +USE_DOTLOCK +DL_STANDALONE > > > -USE_FCNTL +USE_FLOCK > > > +USE_POP +USE_IMAP +IMAP_EDIT_THREADS -USE_GSS +USE_SSL -USE_SASL > > > -USE_SASL2 > > > +HAVE_REGCOMP -USE_GNU_REGEX +COMPRESSED > > > +HAVE_COLOR +HAVE_START_COLOR +HAVE_TYPEAHEAD +HAVE_BKGDSET > > > +HAVE_CURS_SET +HAVE_META +HAVE_RESIZETERM > > > +CRYPT_BACKEND_CLASSIC_PGP +CRYPT_BACKEND_CLASSIC_SMIME > > > -CRYPT_BACKEND_GPGME -BUFFY_SIZE -EXACT_ADDRESS -SUN_ATTACHMENT > > > +ENABLE_NLS -LOCALES_HACK -HAVE_WC_FUNCS +HAVE_LANGINFO_CODESET > > > +HAVE_LANGINFO_YESEXPR > > > +HAVE_ICONV -ICONV_NONTRANS +HAVE_LIBIDN +HAVE_GETSID > > > +HAVE_GETADDRINFO +USE_HCACHE > > > -ISPELL > > > SENDMAIL="/usr/sbin/sendmail" > > > MAILPATH="/var/mail" > > > PKGDATADIR="/usr/local/share/mutt" > > > SYSCONFDIR="/usr/local/etc" > > > EXECSHELL="/bin/sh" > > > -MIXMASTER > > > To contact the developers, please mail to <mutt-dev@xxxxxxxx>. > > > To report a bug, please use the flea(1) utility. > > > > > > patch-1.5.6.dw.multiple-crypt-hook.2 > > > patch-1.5.6.dw.confirm-crypt-hook.1 > > > patch-1.5.6.dw.crypt-autoselectkey.1 > > > patch-1.5.6.dw.pgp-menu-traditional.2 > > > patch-1.5.6.dw.maildir-mtime.1 > > > patch-1.5.6.dshaw.extend_timeout > > > maildir-header-cache.18 > > > patch-1.5.6.eh.thread_subject.1 > > > patch-1.5.5.1.cd.trash_folder.3.4 > > > patch-1.5.1.nr.indicator_not_bright > > > 1.3.26.bj.current_shortcut.1-nr > > > rr.compressed > > > 1.3.28.nr.threadcomplete > > > patch-1.5.0.ats.date_conditional.1 > > > dgc.deepif.1 > > > > > > ----- > > > > > > FreeBSD pc5.i.0x5.de 4.10-RELEASE-p2 FreeBSD 4.10-RELEASE-p2 #0: Fri Jul > > > 2 09:03:30 CEST 2004 > > > nicolas@xxxxxxxxxxxx:/scratch/obj/usr/exported/src/sys/PC5 i386 > > > > > > ----- > > > > > > CPU: AMD Athlon(TM) XP 2000+ (1666.74-MHz 686-class CPU) > > > > > > 1GB RAM > > > > > > ----- > > > > > > FFS with softupdates on a Vinum RAID1 on > > > ad0: 152627MB <SAMSUNG SV1604N> [310101/16/63] at ata0-master UDMA100 > > > ad6: 156334MB <Maxtor 6Y160P0> [317632/16/63] at ata3-master UDMA133 -- Uncle Cosmo, why do they call this a word processor? It's simple, Skyler. You've seen what food processors do to food, right? Please visit this link: http://rotter.net/israel
Attachment:
pgpq0HfBJk4HB.pgp
Description: PGP signature