On Feb 7, 2008, at 1:11 PM, David Roundy wrote: > Thanks for the test case, Zooko, and for pointing out this regression! > Could you rerun your timings when you have pulled this change:
I pulled your latest patches and ran it again and it took around 20 seconds. Way to go! That is within an order of magnitude of Mercurial, which is, IMO, the gold standard of performance for portable (i.e., non- git) decentralized revision control tools. Hm, no it isn't actually within one order of magnitude (base 10) -- here are some timing results and some more strace results: MAIN wonwin-mcbrootles-computer:~$ grep ^real time-darcs109- record.log.txt real 0m9.330s real 0m9.903s MAIN wonwin-mcbrootles-computer:~$ grep ^real time-darcs2pre- record.log.txt real 0m21.069s real 0m20.032s real 0m19.069s MAIN wonwin-mcbrootles-computer:~$ grep ^real time-darcs2pre-hf- record.log.txt real 0m24.494s real 0m23.897s real 0m23.920s MAIN wonwin-mcbrootles-computer:~$ grep ^real time-darcs2pre-d2f- record.log.txt real 0m24.028s real 0m24.099s real 0m23.737s MAIN wonwin-mcbrootles-computer:~$ grep ^real time-hg-commit.log.txt real 0m2.388s real 0m2.028s real 0m2.074s real 0m2.045s Here are strace logs of darcs and hg: https://zooko.com/strace_logs-d2f_vs_hg.tar.bz2 MAIN wonwin-mcbrootles-computer:~$ wc -l hg_commit.strace.log.txt d2f_record.strace.log.txt 59769 hg_commit.strace.log.txt 137595 d2f_record.strace.log.txt HACK zooko-laptop:/tmp$ grep "^ ........... open(" hg_commit.strace.log.txt | wc -l 7934 HACK zooko-laptop:/tmp$ grep "^ ........... open(" d2f_record.strace.log.txt | wc -l 14183 $ find ciphercycles-20070205/ | wc -l 2100 So it looks like darcs is doing almost twice as many open() calls as hg. Next, I chose a filename at random and grepped for that filename in the strace logs: $ grep "aes-128-poly1305-2/estream-c.c" d2f_record.strace.log.txt 0.000065 lstat64("/home/zooko/playground/timing/ ciphercycles-20070205/ciphers/aes-128-poly1305-2/estream-c.c", {st_mode=S_IFREG|0644, st_size=847, ...}) = 0 0.000054 open("/home/zooko/playground/timing/ ciphercycles-20070205/ciphers/aes-128-poly1305-2/estream-c.c", O_RDONLY|O_NOCTTY|O_NONBLOCK|O_LARGEFILE) = 3 0.000151 lstat64("/home/zooko/playground/timing/ ciphercycles-20070205/ciphers/aes-128-poly1305-2/estream-c.c", {st_mode=S_IFREG|0644, st_size=847, ...}) = 0 0.000164 open("/home/zooko/playground/timing/ ciphercycles-20070205/ciphers/aes-128-poly1305-2/estream-c.c", O_RDONLY|O_NOCTTY|O_NONBLOCK|O_LARGEFILE) = 3 $ grep "aes-128-poly1305-2/estream-c.c" hg_commit.strace.log.txt 0.000085 lstat64("/home/zooko/playground/timing/ ciphercycles-20070205/ciphers/aes-128-poly1305-2/estream-c.c", {st_mode=S_IFREG|0644, st_size=847, ...}) = 0 0.000100 open("/home/zooko/playground/timing/ ciphercycles-20070205/ciphers/aes-128-poly1305-2/estream-c.c", O_RDONLY|O_LARGEFILE) = 4 0.000108 open("/home/zooko/playground/timing/.hg/store/data/ ciphercycles-20070205/ciphers/aes-128-poly1305-2/estream-c.c.i", O_RDONLY|O_LARGEFILE) = -1 ENOENT (No such file or directory) 0.000158 lstat64("/home/zooko/playground/timing/.hg/store/data/ ciphercycles-20070205/ciphers/aes-128-poly1305-2/estream-c.c.i", 0xbf8698d8) = -1 ENOENT (No such file or directory) 0.000074 open("/home/zooko/playground/timing/.hg/store/data/ ciphercycles-20070205/ciphers/aes-128-poly1305-2/estream-c.c.i", O_RDWR|O_CREAT|O_APPEND|O_LARGEFILE, 0666) = 4 0.000041 lstat64("/home/zooko/playground/timing/ ciphercycles-20070205/ciphers/aes-128-poly1305-2/estream-c.c", {st_mode=S_IFREG|0644, st_size=847, ...}) = 0 0.000075 lstat64("/home/zooko/playground/timing/ ciphercycles-20070205/ciphers/aes-128-poly1305-2/estream-c.c", {st_mode=S_IFREG|0644, st_size=847, ...}) = 0 0.000076 lstat64("/home/zooko/playground/timing/ ciphercycles-20070205/ciphers/aes-128-poly1305-2/estream-c.c", {st_mode=S_IFREG|0644, st_size=847, ...}) = 0 So darcs is lstat'ing and opening the file twice, where hg is lstating and opening the file once. Digging in further, here are the relevant excerpts of the log from the strace of darcs: 0.000065 lstat64("/home/zooko/playground/timing/ ciphercycles-20070205/ciphers/aes-128-poly1305-2/estream-c.c", {st_mode=S_IFREG|0644, st_size=847, ...}) = 0 ... 0.000054 open("/home/zooko/playground/timing/ ciphercycles-20070205/ciphers/aes-128-poly1305-2/estream-c.c", O_RDONLY|O_NOCTTY|O_NONBLOCK|O_LARGEFILE) = 3 0.000064 fstat64(3, {st_mode=S_IFREG|0644, st_size=847, ...}) = 0 0.000048 fcntl64(3, F_GETFL) = 0x8800 (flags O_RDONLY| O_NONBLOCK|O_LARGEFILE) 0.000033 fcntl64(3, F_SETFL, O_RDONLY|O_NONBLOCK|O_LARGEFILE) = 0 0.000032 ioctl(3, SNDCTL_TMR_TIMEBASE or TCGETS, 0xbfb7f4f4) = -1 ENOTTY (Inappropriate ioctl for device) 0.000039 fstat64(3, {st_mode=S_IFREG|0644, st_size=847, ...}) = 0 0.000048 read(3, "#define ECRYPT_API\n#if TUNINGNUM"..., 8192) = 847 0.000046 close(3) = 0 (That's the entire file -- it is 847 bytes.) ... 0.000151 lstat64("/home/zooko/playground/timing/ ciphercycles-20070205/ciphers/aes-128-poly1305-2/estream-c.c", {st_mode=S_IFREG|0644, st_size=847, ...}) = 0 ... 0.000164 open("/home/zooko/playground/timing/ ciphercycles-20070205/ciphers/aes-128-poly1305-2/estream-c.c", O_RDONLY|O_NOCTTY|O_NONBLOCK|O_LARGEFILE) = 3 0.000106 fstat64(3, {st_mode=S_IFREG|0644, st_size=847, ...}) = 0 0.000098 fcntl64(3, F_GETFL) = 0x8800 (flags O_RDONLY| O_NONBLOCK|O_LARGEFILE) 0.000063 fcntl64(3, F_SETFL, O_RDONLY|O_NONBLOCK|O_LARGEFILE) = 0 0.000063 ioctl(3, SNDCTL_TMR_TIMEBASE or TCGETS, 0xbfb7f4f4) = -1 ENOTTY (Inappropriate ioctl for device) 0.000066 fstat64(3, {st_mode=S_IFREG|0644, st_size=847, ...}) = 0 0.000099 read(3, "#define ECRYPT_API\n#if TUNINGNUM"..., 8192) = 847 0.000427 close(3) = 0 And here are the comparable excerpts from the strace of hg: 0.000085 lstat64("/home/zooko/playground/timing/ ciphercycles-20070205/ciphers/aes-128-poly1305-2/estream-c.c", {st_mode=S_IFREG|0644, st_size=847, ...}) = 0 ... 0.000100 open("/home/zooko/playground/timing/ ciphercycles-20070205/ciphers/aes-128-poly1305-2/estream-c.c", O_RDONLY|O_LARGEFILE) = 4 0.000049 fstat64(4, {st_mode=S_IFREG|0644, st_size=847, ...}) = 0 0.000053 fstat64(4, {st_mode=S_IFREG|0644, st_size=847, ...}) = 0 0.000042 _llseek(4, 0, [0], SEEK_CUR) = 0 0.000027 fstat64(4, {st_mode=S_IFREG|0644, st_size=847, ...}) = 0 0.000042 mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE| MAP_ANONYMOUS, -1, 0) = 0xb7ba5000 0.000029 _llseek(4, 0, [0], SEEK_CUR) = 0 0.000029 read(4, "#define ECRYPT_API\n#if TUNINGNUM"..., 4096) = 847 0.000040 read(4, "", 4096) = 0 0.000027 close(4) = 0 ... 0.000041 lstat64("/home/zooko/playground/timing/ ciphercycles-20070205/ciphers/aes-128-poly1305-2/estream-c.c", {st_mode=S_IFREG|0644, st_size=847, ...}) = 0 0.000075 lstat64("/home/zooko/playground/timing/ ciphercycles-20070205/ciphers/aes-128-poly1305-2/estream-c.c", {st_mode=S_IFREG|0644, st_size=847, ...}) = 0 (Heh -- hg is making a list and checking it twice.) ... 0.000076 lstat64("/home/zooko/playground/timing/ ciphercycles-20070205/ciphers/aes-128-poly1305-2/estream-c.c", {st_mode=S_IFREG|0644, st_size=847, ...}) = 0 Regards, Zooko _______________________________________________ darcs-devel mailing list darcs-devel@darcs.net http://lists.osuosl.org/mailman/listinfo/darcs-devel